net/http: TestServerEmptyBodyRace_h2 flakes with "connection reset by peer" #22540

rsc · 2017-11-02T04:13:17Z

I'm seeing lots of flaky tests in net/http. They all fail with a message like:

2017/11/02 00:10:29 Dialing 127.0.0.1:50066
2017/11/02 00:10:30 Dialing 127.0.0.1:50070
2017/11/02 00:10:30 Unsolicited response received on idle HTTP channel starting with "0\r\n\r\n"; err=<nil>

On my Mac just now:

2017/11/02 00:10:29 Dialing 127.0.0.1:50066
2017/11/02 00:10:30 Dialing 127.0.0.1:50070
2017/11/02 00:10:30 Unsolicited response received on idle HTTP channel starting with "0\r\n\r\n"; err=<nil>
--- FAIL: TestServerEmptyBodyRace_h2 (0.01s)
	serve_test.go:4157: Get https://127.0.0.1:50756: read tcp 127.0.0.1:50757->127.0.0.1:50756: read: connection reset by peer
	serve_test.go:4170: handler ran 19 times; want 20
FAIL
FAIL	net/http	5.178s

linux-386 build dashboard:

2017/11/02 03:56:34 Dialing 127.0.0.1:45529
2017/11/02 03:56:34 Dialing 127.0.0.1:41134
2017/11/02 03:56:34 Unsolicited response received on idle HTTP channel starting with "0\r\n\r\n"; err=<nil>
--- FAIL: TestCloseIdleConnections_h2 (0.22s)
	clientserver_test.go:1304: didn't close connection
FAIL
FAIL	net/http	3.058s

I had a trybot failure with this earlier this evening too.

Not sure what's going on.

Welcome back, @bradfitz!

The text was updated successfully, but these errors were encountered:

bradfitz · 2017-11-02T04:21:09Z

@tombergan, does this ring any bells?

tombergan · 2017-11-02T15:45:11Z

TestCloseIdleConnections_h2 is #22413.

I believe those "Dialing... Unsolicited response" messages are printed by tests that were running concurrently with the flakey tests. The "Unsolicited response" message is H1 while the flakey tests are H2. Further, I don't see those messages when I repro the second flake with go test -run TestCloseIdleConnections_h2 -count 100000 net/http.

I can't repro TestServerEmptyBodyRace_h2 on my linux workstation. It looks like Russ has filed an issue for that flake at least twice before, both times on a Mac and both times with the same error message: #18541 and #17713.

bradfitz · 2017-11-02T19:13:43Z

The "Dialing" log spam was introduced by f5cd386 for HTTPS proxy support (@bemasc). I'll send a CL for that first.

gopherbot · 2017-11-02T19:18:31Z

Change https://golang.org/cl/75531 mentions this issue: net/http: remove some log spam in test, add missing error detail

Updates #22540 Change-Id: I26e79c25652976fac6f2e5a7afb4fd1240996d74 Reviewed-on: https://go-review.googlesource.com/75531 Reviewed-by: Tom Bergan <tombergan@google.com> Run-TryBot: Tom Bergan <tombergan@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org>

bradfitz · 2017-11-02T21:06:28Z

More digging. The "Unsolicited" log spam was added by 2da8a16 (@benburkert), also recently.

bradfitz · 2017-11-02T21:06:45Z

... as part of TestNoBodyOnChunked304Response.

gopherbot · 2017-11-02T21:12:30Z

Change https://golang.org/cl/75593 mentions this issue: net/http: quiet some log spam in TestNoBodyOnChunked304Response

Updates #22540 Change-Id: I63e8c4874f8a774e9c47affc856aadf8c35ca23b Reviewed-on: https://go-review.googlesource.com/75593 Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Tom Bergan <tombergan@google.com>

bradfitz · 2018-01-04T22:56:54Z

I was able to reproduce this on my Mac (10.13.2) with,

go test -short -count=3000 -run=TestServerEmptyBodyRace

and started to look into it, but when I ran that command again, it hung for a few seconds and then spewed out:

--- FAIL: TestServerEmptyBodyRace_h2 (0.11s)
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4150: Get https://127.0.0.1:64315: dial tcp 127.0.0.1:64315: connect: can't assign requested address
        serve_test.go:4163: handler ran 0 times; want 20
--- FAIL: TestServerEmptyBodyRace_h1 (0.11s)
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4150: Get http://127.0.0.1:64314: dial tcp 127.0.0.1:64314: connect: can't assign requested address
        serve_test.go:4163: handler ran 5 times; want 20
....

Does Darwin's TCP stack not recycle local port numbers as quickly as Linux, I guess? Do I need to wait 3 minutes or so before I'm allowed to run a test again?

fraenkel · 2018-08-25T19:24:53Z

When I run go test -short -count=3000 -run=TestServerEmptyBodyRace
There are 59289 connections in time-wait.
TestServerEmptyBodyRace_h1 creates 58737
TestServerEmptyBodyRace_h2 creates 172

mcauto · 2018-11-27T09:49:33Z

Same here

Code

transport := &http.Transport{
		Dial: (&net.Dialer{
			Timeout: p.timeout,
		}).Dial,
		TLSHandshakeTimeout: p.timeout,
		IdleConnTimeout:     time.Second,
		TLSClientConfig:     &tls.Config{InsecureSkipVerify: true},
	}

	client := &http.Client{
		Transport: transport,
		Timeout:   p.timeout,
	}
        response, _ := client.Get(addr)

Result

2018/11/27 09:38:02 Unsolicited response received on idle HTTP channel starting with "\r\n"; err=<nil>
2018/11/27 09:38:02 Unsolicited response received on idle HTTP channel starting with "DY></HTML>\r\n\r\n"; err=<nil>
2018/11/27 09:38:02 Unsolicited response received on idle HTTP channel starting with "\r\n"; err=<nil>
2018/11/27 09:38:02 Unsolicited response received on idle HTTP channel starting with "\r\n"; err=<nil>

I use go version go1.9.4 linux/amd64

bcmills · 2019-10-21T13:08:53Z

Same failure mode on netbsd-amd64-8_0, but without the Unsolicited response messages:
https://build.golang.org/log/c005ed3a705dd49a49c1c529e7cc7491bd3a6728

gopherbot · 2020-10-13T01:14:29Z

Change https://golang.org/cl/261698 mentions this issue: net/http: deflake TestServerEmptyBodyRace_h1, or at least try

rsc added this to the Go1.10 milestone Nov 2, 2017

bradfitz added the NeedsFix The path to resolution is known, but the work has not been done. label Nov 2, 2017

tombergan changed the title ~~net/http: flaky "unsolicited response received on idle HTTP channel" HTTP/2 failures~~ net/http: TestServerEmptyBodyRace_h2 flakes on Mac with "connection reset by peer" Nov 27, 2017

andybons mentioned this issue Jan 24, 2018

all: Go 1.10 release status #23541

Closed

bradfitz modified the milestones: Go1.10, Go1.11 Feb 14, 2018

bradfitz added Testing An issue that has been verified to require only test changes, not just a test failure. help wanted labels Feb 14, 2018

andybons modified the milestones: Go1.11, Go1.11.1 Aug 25, 2018

FiloSottile modified the milestones: Go1.11.1, Go1.12 Aug 31, 2018

andybons modified the milestones: Go1.12, Go1.13 Feb 12, 2019

andybons modified the milestones: Go1.13, Go1.14 Jul 8, 2019

bcmills mentioned this issue Aug 12, 2019

net/http: flaky tests on macOS #33585

Closed

rsc removed this from the Go1.14 milestone Oct 9, 2019

rsc added this to the Backlog milestone Oct 9, 2019

bcmills changed the title ~~net/http: TestServerEmptyBodyRace_h2 flakes on Mac with "connection reset by peer"~~ net/http: TestServerEmptyBodyRace_h2 flakes with "connection reset by peer" Oct 21, 2019

dmitshur modified the milestones: Backlog, Go1.16 Oct 13, 2020

gopherbot closed this as completed in 59202c4 Oct 16, 2020

golang locked and limited conversation to collaborators Oct 16, 2021

gopherbot added the FrozenDueToAge label Oct 16, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: TestServerEmptyBodyRace_h2 flakes with "connection reset by peer" #22540

net/http: TestServerEmptyBodyRace_h2 flakes with "connection reset by peer" #22540

rsc commented Nov 2, 2017

bradfitz commented Nov 2, 2017

tombergan commented Nov 2, 2017

bradfitz commented Nov 2, 2017

gopherbot commented Nov 2, 2017

bradfitz commented Nov 2, 2017

bradfitz commented Nov 2, 2017

gopherbot commented Nov 2, 2017

bradfitz commented Jan 4, 2018

fraenkel commented Aug 25, 2018

mcauto commented Nov 27, 2018

bcmills commented Oct 21, 2019

gopherbot commented Oct 13, 2020

net/http: TestServerEmptyBodyRace_h2 flakes with "connection reset by peer" #22540

net/http: TestServerEmptyBodyRace_h2 flakes with "connection reset by peer" #22540

Comments

rsc commented Nov 2, 2017

bradfitz commented Nov 2, 2017

tombergan commented Nov 2, 2017

bradfitz commented Nov 2, 2017

gopherbot commented Nov 2, 2017

bradfitz commented Nov 2, 2017

bradfitz commented Nov 2, 2017

gopherbot commented Nov 2, 2017

bradfitz commented Jan 4, 2018

fraenkel commented Aug 25, 2018

mcauto commented Nov 27, 2018

bcmills commented Oct 21, 2019

gopherbot commented Oct 13, 2020