go: net/http: TestHijackAfterCloseNotifier failures

#!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

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 15 (9 by maintainers)

Most upvoted comments

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.)

+2
bcmills on Apr 7, 2023

That same race seems to account for a large number of net/http test flakes, including:

And a couple of additional failures that have not yet been reported by watchflakes.

Also related are:

~/go-review/src$ go test net/http -test.timeout=30m
--- FAIL: TestClientRedirectEatsBody_h1 (0.36s)
    --- FAIL: TestClientRedirectEatsBody_h1/h1 (0.36s)
        client_test.go:1400: server saw different client ports before & after the redirect
--- FAIL: TestKeepAliveFinalChunkWithEOF (0.36s)
    --- FAIL: TestKeepAliveFinalChunkWithEOF/h1 (0.36s)
        serve_test.go:1233: connection not reused
--- FAIL: TestHijackAfterCloseNotifier (0.30s)
    --- FAIL: TestHijackAfterCloseNotifier/h1 (0.30s)
        serve_test.go:3330: addr1, addr2 = "127.0.0.1:37070", "127.0.0.1:37074"; want same
--- FAIL: TestServerConnState (0.36s)
    --- FAIL: TestServerConnState/h1 (0.36s)
        serve_test.go:4124: unexpected conn in state new
        serve_test.go:4124: unexpected conn in state active
        serve_test.go:4124: unexpected conn in state closed
        serve_test.go:4165: Request(s) produced unexpected state sequence.
            Got:  [new active idle closed]
            Want: [new active idle active closed]
        serve_test.go:4124: unexpected conn in state new
        serve_test.go:4124: unexpected conn in state active
        serve_test.go:4170: Request(s) produced unexpected state sequence.
            Got:  [new active idle closed]
            Want: [new active idle active closed]
        serve_test.go:4124: unexpected conn in state closed
--- FAIL: TestHandlerSetsBodyNil (0.36s)
    --- FAIL: TestHandlerSetsBodyNil/h1 (0.35s)
        serve_test.go:4590: Failed to reuse connections between requests: 127.0.0.1:50782 vs 127.0.0.1:50790
--- FAIL: TestServerIdleTimeout (0.36s)
    --- FAIL: TestServerIdleTimeout/h1 (0.36s)
        serve_test.go:5374: did requests on different connections
--- FAIL: TestServerSetKeepAlivesEnabledClosesConns (0.35s)
    --- FAIL: TestServerSetKeepAlivesEnabledClosesConns/h1 (0.35s)
        serve_test.go:5427: server reported requests from "127.0.0.1:42814" and "127.0.0.1:42816"; expected same connection
        serve_test.go:5435: found 0 idle conns ([]); want 1
--- FAIL: TestTransportKeepAlives (0.36s)
    --- FAIL: TestTransportKeepAlives/h1 (0.36s)
        transport_test.go:193: error in disableKeepAlive=false. unexpected bodiesDiffer=true; body1="127.0.0.1:45346, *net.TCPConn 0xc0004c0090"; body2="127.0.0.1:45354, *net.TCPConn 0xc000a04000"
--- FAIL: TestTransportConnectionCloseOnResponse (0.37s)
    --- FAIL: TestTransportConnectionCloseOnResponse/h1 (0.36s)
        transport_test.go:240: error in connectionClose=false. unexpected bodiesDiffer=true; body1="127.0.0.1:54042, *net.TCPConn 0xc00030a008"; body2="127.0.0.1:54044, *net.TCPConn 0xc00007a040"
--- FAIL: TestTransportConnectionCloseOnRequest (0.36s)
    --- FAIL: TestTransportConnectionCloseOnRequest/h1 (0.36s)
        transport_test.go:308: for Request.Close=false: server saw 2 unique connections, wanted 1

            bodies were: "127.0.0.1:40092, *net.TCPConn 0xc000a04000" and "127.0.0.1:40102, *net.TCPConn 0xc00030a008"
--- FAIL: TestTransportIdleCacheKeys (0.31s)
    --- FAIL: TestTransportIdleCacheKeys/h1 (0.30s)
        transport_test.go:413: After Get expected 1 idle conn cache keys; got 0
--- FAIL: TestTransportReadToEndReusesConn (0.57s)
    --- FAIL: TestTransportReadToEndReusesConn/h1 (0.56s)
        transport_test.go:470: for /content-length/, server saw 3 distinct client addresses; want 1
        transport_test.go:470: for /chunked/, server saw 3 distinct client addresses; want 1
--- FAIL: TestTransportMaxPerHostIdleConns (0.30s)
    --- FAIL: TestTransportMaxPerHostIdleConns/h1 (0.30s)
        transport_test.go:540: after first response, expected 1 idle conn cache keys; got 0
--- FAIL: TestTransportMaxConnsPerHost (1.58s)
    --- FAIL: TestTransportMaxConnsPerHost/h1 (0.76s)
        transport_test.go:699: round 1: too many dials: 10 != 1
        transport_test.go:702: round 1: too many get connections: 10 != 1
    --- FAIL: TestTransportMaxConnsPerHost/https1 (0.80s)
        transport_test.go:699: round 1: too many dials: 10 != 1
        transport_test.go:702: round 1: too many get connections: 10 != 1
        transport_test.go:705: round 1: too many tls handshakes: 10 != 1
--- FAIL: TestTransportServerClosingUnexpectedly (0.41s)
    --- FAIL: TestTransportServerClosingUnexpectedly/h1 (0.41s)
        transport_test.go:832: expected body1 and body2 to be equal
--- FAIL: TestTransportHeadChunkedResponse (0.36s)
    --- FAIL: TestTransportHeadChunkedResponse/h1 (0.36s)
        transport_test.go:962: ip/ports differed between head requests: "127.0.0.1:43408" vs "127.0.0.1:53478"
panic: test timed out after 30m0s
running tests:
        TestTransportSocketLateBinding (28m1s)
        TestTransportSocketLateBinding/h1 (28m1s)

goroutine 27929 [running]:
testing.(*M).startAlarm.func1()
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:2260 +0x3b9
created by time.goFunc
        /usr/local/google/home/bcmills/go-review/src/time/sleep.go:176 +0x2d

goroutine 1 [chan receive, 28 minutes]:
testing.(*T).Run(0xc0001921a0, {0x8c925a?, 0x20?}, 0x904838)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1649 +0x3c8
testing.runTests.func1(0xc37840?)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:2055 +0x3e
testing.tRunner(0xc0001921a0, 0xc0000e1c30)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1595 +0xff
testing.runTests(0xc0000c2c80?, {0xc31820, 0x1fc, 0x1fc}, {0x40d849?, 0xc0000e1d40?, 0xc36ce0?})
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:2053 +0x445
testing.(*M).Run(0xc0000c2c80)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1925 +0x636
net/http_test.TestMain(0x46b87a?)
        /usr/local/google/home/bcmills/go-review/src/net/http/main_test.go:23 +0x13
main.main()
        _testmain.go:1127 +0x1c6

goroutine 33 [chan receive, 29 minutes]:
testing.(*T).Parallel(0xc00027f380)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1403 +0x205
net/http.TestCmdGoNoHTTPServer(0xc00027f380)
        /usr/local/google/home/bcmills/go-review/src/net/http/http_test.go:85 +0x2a
testing.tRunner(0xc00027f380, 0x903318)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1595 +0xff
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1648 +0x3ad

goroutine 34 [chan receive, 29 minutes]:
testing.(*T).Parallel(0xc00027f520)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1403 +0x205
net/http.TestOmitHTTP2(0xc00027f520)
        /usr/local/google/home/bcmills/go-review/src/net/http/http_test.go:119 +0x87
testing.tRunner(0xc00027f520, 0x903398)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1595 +0xff
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1648 +0x3ad

goroutine 35 [chan receive, 29 minutes]:
testing.(*T).Parallel(0xc00027f6c0)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1403 +0x205
net/http.TestOmitHTTP2Vet(0xc00027f6c0)
        /usr/local/google/home/bcmills/go-review/src/net/http/http_test.go:131 +0x25
testing.tRunner(0xc00027f6c0, 0x903390)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1595 +0xff
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1648 +0x3ad

goroutine 101 [chan receive, 29 minutes]:
testing.(*T).Parallel(0xc000103520)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1403 +0x205
net/http.TestRequestWriteTransport(0xc000103520)
        /usr/local/google/home/bcmills/go-review/src/net/http/requestwrite_test.go:668 +0x2a
testing.tRunner(0xc000103520, 0x903448)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1595 +0xff
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1648 +0x3ad

goroutine 106 [chan receive, 29 minutes]:
testing.(*T).Parallel(0xc0004a4680)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1403 +0x205
net/http.TestReadResponseCloseInMiddle(0xc0004a4680)
        /usr/local/google/home/bcmills/go-review/src/net/http/response_test.go:647 +0x2a
testing.tRunner(0xc0004a4680, 0x9033e0)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1595 +0xff
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1648 +0x3ad

goroutine 7887 [chan receive, 29 minutes]:
testing.(*T).Parallel(0xc0003f96c0)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1403 +0x205
net/http_test.TestConsumingBodyOnNextConn(0xc0003f96c0)
        /usr/local/google/home/bcmills/go-review/src/net/http/serve_test.go:167 +0x3e
testing.tRunner(0xc0003f96c0, 0x903990)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1595 +0xff
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1648 +0x3ad

goroutine 27886 [chan receive, 28 minutes]:
testing.(*T).Run(0xc0011a8680, {0x8b40bf?, 0x3f?}, 0xc000c56300)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1649 +0x3c8
net/http_test.run[...](0xc0011a8680, 0x9054a0, {0x0, 0x0, 0x48984f})
        /usr/local/google/home/bcmills/go-review/src/net/http/clientserver_test.go:82 +0x26f
net/http_test.TestTransportSocketLateBinding(0xc0011a84e0?)
        /usr/local/google/home/bcmills/go-review/src/net/http/transport_test.go:2802 +0x2b
testing.tRunner(0xc0011a8680, 0x904838)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1595 +0xff
created by testing.(*T).Run in goroutine 1
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1648 +0x3ad

goroutine 27887 [select, 28 minutes]:
net/http.(*Transport).getConn(0xc0000f63c0, 0xc0000250c0, {{}, 0x0, {0xc00050a400, 0x4}, {0xc00051c1c0, 0xf}, 0x0})
        /usr/local/google/home/bcmills/go-review/src/net/http/transport.go:1389 +0x5c5
net/http.(*Transport).roundTrip(0xc0000f63c0, 0xc000200500)
        /usr/local/google/home/bcmills/go-review/src/net/http/transport.go:591 +0x73a
net/http.(*Transport).RoundTrip(0xc00045d940?, 0x97f340?)
        /usr/local/google/home/bcmills/go-review/src/net/http/roundtrip.go:17 +0x13
net/http.send(0xc000200500, {0x97f340, 0xc0000f63c0}, {0x1?, 0xc00050a411?, 0x0?})
        /usr/local/google/home/bcmills/go-review/src/net/http/client.go:257 +0x606
net/http.(*Client).send(0xc000c564e0, 0xc000200500, {0xc0000dfbc8?, 0x5face5?, 0x0?})
        /usr/local/google/home/bcmills/go-review/src/net/http/client.go:181 +0x96
net/http.(*Client).do(0xc000c564e0, 0xc000200500)
        /usr/local/google/home/bcmills/go-review/src/net/http/client.go:721 +0x928
net/http.(*Client).Do(...)
        /usr/local/google/home/bcmills/go-review/src/net/http/client.go:587
net/http.(*Client).Get(0xc000c568a0?, {0xc00050a400?, 0x8b40bf?})
        /usr/local/google/home/bcmills/go-review/src/net/http/client.go:485 +0x5f
net/http_test.testTransportSocketLateBinding(0xc0011a8820, {0x8b40bf, 0x2})
        /usr/local/google/home/bcmills/go-review/src/net/http/transport_test.go:2871 +0x4b5
net/http_test.run[...].func1()
        /usr/local/google/home/bcmills/go-review/src/net/http/clientserver_test.go:90 +0xf6
testing.tRunner(0xc0011a8820, 0xc000c56300)
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1595 +0xff
created by testing.(*T).Run in goroutine 27886
        /usr/local/google/home/bcmills/go-review/src/testing/testing.go:1648 +0x3ad

goroutine 27888 [IO wait, 28 minutes]:
internal/poll.runtime_pollWait(0x7fbbfd4b89a0, 0x72)
        /usr/local/google/home/bcmills/go-review/src/runtime/netpoll.go:306 +0x85
internal/poll.(*pollDesc).wait(0xc000e2e100?, 0x4?, 0x0)
        /usr/local/google/home/bcmills/go-review/src/internal/poll/fd_poll_runtime.go:84 +0x27
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/google/home/bcmills/go-review/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc000e2e100)
        /usr/local/google/home/bcmills/go-review/src/internal/poll/fd_unix.go:614 +0x2ac
net.(*netFD).accept(0xc000e2e100)
        /usr/local/google/home/bcmills/go-review/src/net/fd_unix.go:172 +0x29
net.(*TCPListener).accept(0xc000132160)
        /usr/local/google/home/bcmills/go-review/src/net/tcpsock_posix.go:152 +0x1e
net.(*TCPListener).Accept(0xc000132160)
        /usr/local/google/home/bcmills/go-review/src/net/tcpsock.go:299 +0x30
net/http.(*Server).Serve(0xc0002ea000, {0x9824c0, 0xc000132160})
        /usr/local/google/home/bcmills/go-review/src/net/http/server.go:3051 +0x366
net/http/httptest.(*Server).goServe.func1()
        /usr/local/google/home/bcmills/go-review/src/net/http/httptest/server.go:310 +0x65
created by net/http/httptest.(*Server).goServe in goroutine 27887
        /usr/local/google/home/bcmills/go-review/src/net/http/httptest/server.go:308 +0x65

goroutine 27958 [select, 28 minutes]:
net/http_test.testTransportSocketLateBinding.func3({0x8b42db, 0x3}, {0xc00051c1c0, 0xf})
        /usr/local/google/home/bcmills/go-review/src/net/http/transport_test.go:2821 +0x9e
net/http.(*Transport).dial(0x0?, {0x982f60?, 0xc660b0?}, {0x8b42db?, 0xc0001dd000?}, {0xc00051c1c0?, 0x1000?})
        /usr/local/google/home/bcmills/go-review/src/net/http/transport.go:1186 +0x57
net/http.(*Transport).dialConn(0xc0000f63c0, {0x982f60, 0xc660b0}, {{}, 0x0, {0xc00050a400, 0x4}, {0xc00051c1c0, 0xf}, 0x0})
        /usr/local/google/home/bcmills/go-review/src/net/http/transport.go:1621 +0x7e8
net/http.(*Transport).dialConnFor(0x6e1aa5?, 0xc0003a0370)
        /usr/local/google/home/bcmills/go-review/src/net/http/transport.go:1463 +0xa5
created by net/http.(*Transport).queueForDial in goroutine 27887
        /usr/local/google/home/bcmills/go-review/src/net/http/transport.go:1432 +0x3d5
FAIL    net/http        1800.018s
FAIL

(CC @paulzhol)

+1
bcmills on Apr 7, 2023

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.

+1
neild on Apr 6, 2023
Read more comments on GitHub
← go: net/http: TestClientTimeout* failures with "missing timeout substring" on Windows
go: net/http: TestRetryRequestsOnError failures with "use of closed network connection" →