Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

net/http: TestHijackAfterCloseNotifier failures #56275

Closed
gopherbot opened this issue Oct 17, 2022 · 15 comments
Closed

net/http: TestHijackAfterCloseNotifier failures #56275

gopherbot opened this issue Oct 17, 2022 · 15 comments
Labels
NeedsFix The path to resolution is known, but the work has not been done. Testing An issue that has been verified to require only test changes, not just a test failure.
Milestone
Go1.21

Comments

@gopherbot
Copy link

gopherbot commented Oct 17, 2022 •
edited by bcmills 

#!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 gopherbot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Oct 17, 2022
@gopherbot
Copy link
Author

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

@seankhliao seankhliao added this to the Unplanned milestone Nov 19, 2022
@bcmills
Copy link
Contributor

bcmills commented Dec 7, 2022 •
edited

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
Copy link
Author

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
Copy link
Author

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

This comment was marked as off-topic.

Sign in to view
@gopherbot
Copy link
Author

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
Copy link
Contributor

neild commented Apr 6, 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.

@bcmills
Copy link
Contributor

bcmills commented Apr 6, 2023

@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
Copy link
Contributor

bcmills commented Apr 6, 2023

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
Copy link
Contributor

bcmills commented Apr 6, 2023 •
edited

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
Copy link
Contributor

neild commented Apr 6, 2023

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
Copy link
Contributor

bcmills commented Apr 7, 2023 •
edited

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

@bcmills
Copy link
Contributor

bcmills commented Apr 7, 2023 •
edited

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)

@gopherbot
Copy link
Author

Change https://go.dev/cl/483116 mentions this issue: net/http: wait forever for write results in tests

@neild
Copy link
Contributor

neild commented Apr 7, 2023

Aha! Nice catch.

Perhaps we should just disable the maxWriteWaitBeforeConnReuse timeout in tests.

@dmitshur dmitshur modified the milestones: Unplanned, Go1.21 May 24, 2023
@dmitshur dmitshur added NeedsFix The path to resolution is known, but the work has not been done. Testing An issue that has been verified to require only test changes, not just a test failure. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels May 24, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
NeedsFix The path to resolution is known, but the work has not been done. Testing An issue that has been verified to require only test changes, not just a test failure.
Projects
Test Flakes
Status: Done
Milestone
Go1.21
Development

No branches or pull requests
5 participants
@neild @dmitshur @bcmills @gopherbot @seankhliao