net/http: TestHijackAfterCloseNotifier failures

[gopherbot]

#!watchflakes
post <- pkg == "net/http" && test == "TestHijackAfterCloseNotifier" && `want same`

Issue created automatically to collect these failures.

Example (log):

2022/10/17 02:06:33 http: TLS handshake error from 127.0.0.1:21860: EOF
2022/10/17 02:06:35 http: TLS handshake error from 127.0.0.1:46518: write tcp 127.0.0.1:45680->127.0.0.1:46518: i/o timeout
2022/10/17 02:06:35 http: TLS handshake error from 127.0.0.1:2197: write tcp 127.0.0.1:13625->127.0.0.1:2197: i/o timeout
2022/10/17 02:06:36 http: TLS handshake error from 127.0.0.1:45371: write tcp 127.0.0.1:38635->127.0.0.1:45371: i/o timeout
2022/10/17 02:06:36 http: TLS handshake error from 127.0.0.1:45248: write tcp 127.0.0.1:11478->127.0.0.1:45248: i/o timeout
2022/10/17 02:06:36 http2: server: error reading preface from client 127.0.0.1:16541: bogus greeting "CONNECT golang.fake.tld:"
2022/10/17 02:06:37 http2: server: error reading preface from client 127.0.0.1:20393: bogus greeting "CONNECT golang.fake.tld:"
--- FAIL: TestHijackAfterCloseNotifier (0.00s)
    --- FAIL: TestHijackAfterCloseNotifier/h1 (0.13s)
        serve_test.go:3324: addr1, addr2 = "127.0.0.1:43885", "127.0.0.1:44395"; want same
2022/10/17 02:06:51 http: TLS handshake error from 127.0.0.1:34478: EOF
2022/10/17 02:06:51 http: TLS handshake error from 127.0.0.1:16556: EOF
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:24764: write tcp 127.0.0.1:42504->127.0.0.1:24764: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:17591: write tcp 127.0.0.1:42504->127.0.0.1:17591: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:7383: write tcp 127.0.0.1:32294->127.0.0.1:7383: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:6079: write tcp 127.0.0.1:32294->127.0.0.1:6079: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:22550: read tcp 127.0.0.1:32294->127.0.0.1:22550: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:26024: write tcp 127.0.0.1:32294->127.0.0.1:26024: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:47350: write tcp 127.0.0.1:32294->127.0.0.1:47350: use of closed network connection
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:20490: EOF
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:28231: EOF
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:14732: read tcp 127.0.0.1:41602->127.0.0.1:14732: read: connection reset by peer
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:13282: read tcp 127.0.0.1:41602->127.0.0.1:13282: read: connection reset by peer
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:20888: read tcp 127.0.0.1:41602->127.0.0.1:20888: read: connection reset by peer
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:44183: read tcp 127.0.0.1:22518->127.0.0.1:44183: read: connection reset by peer
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:22949: read tcp 127.0.0.1:22518->127.0.0.1:22949: read: connection reset by peer

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHijackAfterCloseNotifier"

2022-10-14 12:48 openbsd-arm64-jsing go@5fde02e3 net/http.TestHijackAfterCloseNotifier (log)

2022/10/17 02:06:33 http: TLS handshake error from 127.0.0.1:21860: EOF
2022/10/17 02:06:35 http: TLS handshake error from 127.0.0.1:46518: write tcp 127.0.0.1:45680->127.0.0.1:46518: i/o timeout
2022/10/17 02:06:35 http: TLS handshake error from 127.0.0.1:2197: write tcp 127.0.0.1:13625->127.0.0.1:2197: i/o timeout
2022/10/17 02:06:36 http: TLS handshake error from 127.0.0.1:45371: write tcp 127.0.0.1:38635->127.0.0.1:45371: i/o timeout
2022/10/17 02:06:36 http: TLS handshake error from 127.0.0.1:45248: write tcp 127.0.0.1:11478->127.0.0.1:45248: i/o timeout
2022/10/17 02:06:36 http2: server: error reading preface from client 127.0.0.1:16541: bogus greeting "CONNECT golang.fake.tld:"
2022/10/17 02:06:37 http2: server: error reading preface from client 127.0.0.1:20393: bogus greeting "CONNECT golang.fake.tld:"
--- FAIL: TestHijackAfterCloseNotifier (0.00s)
    --- FAIL: TestHijackAfterCloseNotifier/h1 (0.13s)
        serve_test.go:3324: addr1, addr2 = "127.0.0.1:43885", "127.0.0.1:44395"; want same
2022/10/17 02:06:51 http: TLS handshake error from 127.0.0.1:34478: EOF
2022/10/17 02:06:51 http: TLS handshake error from 127.0.0.1:16556: EOF
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:24764: write tcp 127.0.0.1:42504->127.0.0.1:24764: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:17591: write tcp 127.0.0.1:42504->127.0.0.1:17591: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:7383: write tcp 127.0.0.1:32294->127.0.0.1:7383: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:6079: write tcp 127.0.0.1:32294->127.0.0.1:6079: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:22550: read tcp 127.0.0.1:32294->127.0.0.1:22550: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:26024: write tcp 127.0.0.1:32294->127.0.0.1:26024: use of closed network connection
2022/10/17 02:07:00 http: TLS handshake error from 127.0.0.1:47350: write tcp 127.0.0.1:32294->127.0.0.1:47350: use of closed network connection
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:20490: EOF
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:28231: EOF
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:14732: read tcp 127.0.0.1:41602->127.0.0.1:14732: read: connection reset by peer
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:13282: read tcp 127.0.0.1:41602->127.0.0.1:13282: read: connection reset by peer
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:20888: read tcp 127.0.0.1:41602->127.0.0.1:20888: read: connection reset by peer
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:44183: read tcp 127.0.0.1:22518->127.0.0.1:44183: read: connection reset by peer
2022/10/17 02:07:06 http: TLS handshake error from 127.0.0.1:22949: read tcp 127.0.0.1:22518->127.0.0.1:22949: read: connection reset by peer

— watchflakes

[bcmills]

greplogs -l -e 'FAIL: TestHijackAfterCloseNotifier' --since=2022-10-17
2022-12-06T18:32:51-dfd13ce/darwin-amd64-race
2022-11-22T01:42:49-1521199/darwin-amd64-aws-race
2022-11-17T03:47:35-fee0ab8/darwin-amd64-12-aws
2022-11-15T22:52:03-8477562/darwin-amd64-11-aws
2022-11-02T18:15:21-581a822/darwin-amd64-10_14-aws

The -aws builders were skipped until recently (configured in #55166, which I have since updated), but I'm not sure why watchflakes didn't post the one from the darwin-amd64-race builder.

(attn @neild)

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHijackAfterCloseNotifier"

2022-12-06 18:32 darwin-amd64-race go@dfd13ce5 net/http.TestHijackAfterCloseNotifier (log)

--- FAIL: TestHijackAfterCloseNotifier (0.04s)
    --- FAIL: TestHijackAfterCloseNotifier/h1 (0.26s)
        serve_test.go:3389: addr1, addr2 = "127.0.0.1:53065", "127.0.0.1:53067"; want same

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHijackAfterCloseNotifier"

2022-12-21 03:49 darwin-amd64-race go@78fc8107 net/http.TestHijackAfterCloseNotifier (log)

--- FAIL: TestHijackAfterCloseNotifier (0.01s)
    --- FAIL: TestHijackAfterCloseNotifier/h1 (0.06s)
        serve_test.go:3389: addr1, addr2 = "127.0.0.1:53576", "127.0.0.1:53580"; want same

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHijackAfterCloseNotifier"

2023-02-01 19:47 linux-amd64-race go@ab0f0459 net/http.TestHijackAfterCloseNotifier (log)

--- FAIL: TestHijackAfterCloseNotifier (0.00s)

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestHijackAfterCloseNotifier" && `want same`

2023-04-04 07:16 darwin-amd64-12_0 go@56e900d9 net/http.TestHijackAfterCloseNotifier (log)

--- FAIL: TestHijackAfterCloseNotifier (0.00s)
    --- FAIL: TestHijackAfterCloseNotifier/h1 (0.09s)
        serve_test.go:3330: addr1, addr2 = "127.0.0.1:50780", "127.0.0.1:50781"; want same

— watchflakes

[neild]

No-update update: Looked at this for a bit. Could not replicate on darwin-amd64-race builder. Could not find a plausible explanation for the flake. Admitting defeat for the moment.

[bcmills]

@neild, I wonder if the cluster of darwin bugs might be a test in some other package (perhaps net, perhaps something else) dialing a local server port after it has been closed.

If so, then in order to reproduce it you might have to run the net/http test in the same go test invocation as whatever other package is doing the dialing.

[bcmills]

Hmm, or it could be a timing issue (which could be harder to reproduce in isolation because of differences in CPU/disk/network/syscall load).

For example, in TestHijackAfterCloseNotifier, it could be that the client isn't returning the idle connection from the first call to the idle pool quickly enough for it to be visible when the second call dials its connection.

[bcmills]

Hmm. I guess the “stray dial” theory doesn't apply in this case, because both client requests are getting an X-Addr header in the reply — a stray dial would hit the bogus plan panic, which would not set that header.

[neild]

The client returns the idle connection to the pool before returning from RoundTrip, exactly to ensure that a followup request picks it up:
https://go.googlesource.com/go/+/refs/tags/go1.20/src/net/http/transport.go#2159

Maybe something is happening that causes that first connection to close before it gets reused?

[bcmills]

Ah, that's the clue! The call to tryPutIdleConn only occurs if pc.wroteRequest() returns true.

I can reproduce this failure mode on Linux by injecting time.Sleep(100 * time.Millisecond) before the send to pc.writeErrCh here:
https://cs.opensource.google/go/go/+/master:src/net/http/transport.go;l=2440;drc=d633f4b996dadb6b72c2c43d35092738b7c19e7f

(Why 100ms? Because it's somewhat longer than maxWriteWaitBeforeConnReuse, which is 50ms.)