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

[rsc]

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!

[bradfitz]

@tombergan, does this ring any bells?

[tombergan]

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]

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

[gopherbot]

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

[bradfitz]

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

[bradfitz]

... as part of TestNoBodyOnChunked304Response.

[gopherbot]

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

[bradfitz]

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?