net/http: TestTransportGCRequest failures
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
Issue created automatically to collect these failures.
Example (log):
1 second passes in backend, proxygone= false
2022/11/17 00:14:51 http2: server: error reading preface from client 127.0.0.1:38531: bogus greeting "CONNECT golang.fake.tld:"
2022/11/17 00:14:51 http2: server: error reading preface from client 127.0.0.1:38538: bogus greeting "CONNECT golang.fake.tld:"
2022/11/17 00:14:53 http: TLS handshake error from 127.0.0.1:38595: EOF
2022/11/17 00:14:54 http: TLS handshake error from 127.0.0.1:38601: EOF
2022/11/17 00:15:01 http: TLS handshake error from 127.0.0.1:38682: write tcp 127.0.0.1:38673->127.0.0.1:38682: use of closed network connection
2022/11/17 00:15:01 http: TLS handshake error from 127.0.0.1:38681: write tcp 127.0.0.1:38673->127.0.0.1:38681: use of closed network connection
2022/11/17 00:15:02 http: TLS handshake error from 127.0.0.1:38691: read tcp 127.0.0.1:38690->127.0.0.1:38691: use of closed network connection
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (7.10s)
--- FAIL: TestTransportGCRequest/h2/Body (5.32s)
clientserver_test.go:1171: never saw GC of request
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39016: read tcp 127.0.0.1:39015->127.0.0.1:39016: read: connection reset by peer
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39017: read tcp 127.0.0.1:39015->127.0.0.1:39017: read: connection reset by peer
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39024: read tcp 127.0.0.1:39023->127.0.0.1:39024: read: connection reset by peer
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39026: read tcp 127.0.0.1:39023->127.0.0.1:39026: read: connection reset by peer
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39025: read tcp 127.0.0.1:39023->127.0.0.1:39025: read: connection reset by peer
2022/11/17 00:15:21 http: TLS handshake error from 127.0.0.1:39180: write tcp 127.0.0.1:39179->127.0.0.1:39180: i/o timeout
2022/11/17 00:15:21 http: TLS handshake error from 127.0.0.1:39178: write tcp 127.0.0.1:39177->127.0.0.1:39178: i/o timeout
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2022-11-16 15:10 freebsd-riscv64-unmatched go@70f585f0 net/http.TestTransportGCRequest (log)
1 second passes in backend, proxygone= false
2022/11/17 00:14:51 http2: server: error reading preface from client 127.0.0.1:38531: bogus greeting "CONNECT golang.fake.tld:"
2022/11/17 00:14:51 http2: server: error reading preface from client 127.0.0.1:38538: bogus greeting "CONNECT golang.fake.tld:"
2022/11/17 00:14:53 http: TLS handshake error from 127.0.0.1:38595: EOF
2022/11/17 00:14:54 http: TLS handshake error from 127.0.0.1:38601: EOF
2022/11/17 00:15:01 http: TLS handshake error from 127.0.0.1:38682: write tcp 127.0.0.1:38673->127.0.0.1:38682: use of closed network connection
2022/11/17 00:15:01 http: TLS handshake error from 127.0.0.1:38681: write tcp 127.0.0.1:38673->127.0.0.1:38681: use of closed network connection
2022/11/17 00:15:02 http: TLS handshake error from 127.0.0.1:38691: read tcp 127.0.0.1:38690->127.0.0.1:38691: use of closed network connection
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (7.10s)
--- FAIL: TestTransportGCRequest/h2/Body (5.32s)
clientserver_test.go:1171: never saw GC of request
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39016: read tcp 127.0.0.1:39015->127.0.0.1:39016: read: connection reset by peer
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39017: read tcp 127.0.0.1:39015->127.0.0.1:39017: read: connection reset by peer
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39024: read tcp 127.0.0.1:39023->127.0.0.1:39024: read: connection reset by peer
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39026: read tcp 127.0.0.1:39023->127.0.0.1:39026: read: connection reset by peer
2022/11/17 00:15:18 http: TLS handshake error from 127.0.0.1:39025: read tcp 127.0.0.1:39023->127.0.0.1:39025: read: connection reset by peer
2022/11/17 00:15:21 http: TLS handshake error from 127.0.0.1:39180: write tcp 127.0.0.1:39179->127.0.0.1:39180: i/o timeout
2022/11/17 00:15:21 http: TLS handshake error from 127.0.0.1:39178: write tcp 127.0.0.1:39177->127.0.0.1:39178: i/o timeout
It appears this test was last updated in https://go.dev/cl/438137 (attn @neild).
This doesn't seem likely to be caused by https://go.dev/cl/438137, which refactored the way the test is invoked and its name but not the content of the test.
The test sends an HTTP request, waits 100ms, calls runtime.GC, waits 4900ms, and fails if the request has not been finalized. Possibly a sufficiently slow builder could result in the request not being GCd within the time limit?
I'm currently unable to create a freebsd-riscv64-unmatched gomote to test. Going to leave this alone for now to collect more data.
“sufficiently slow builder” seems plausible.
Would it make sense to remove the arbitrary 5s timeout? If the request is truly pinned by a reachable Transport, letting the test run to its deadline should detect that bug equally well.
Dropping the timeout might be reasonable. Although I'm a bit confused why it would be necessary, since runtime.GC should block until the GC is complete, by which point finalizers should have run, no?
Let's see if any other flakes show up, and on what builders.
runtime.GCshould block until the GC is complete, by which point finalizers should have run, no?
Finalizers aren't guaranteed to run at any given point relative to the GC cycle; IIRC they only start running at the end of the cycle in which the object becomes unreachable. And sometimes they can take arbitrarily many cycles to clear — for example, a chain of N objects with a finalizer set at each link of the chain will have N GC cycles of latency before the last finalizer can run.
So in general a test that uses finalizers to check for leaks has to be prepared for arbitrary latency.
Making matters even worse, if the allocation is small enough to fit into the tiny allocator, its finalizer might not ever run if some unrelated tiny allocation pins the block. (But wouldn't expect an http.Request to fit into the tiny allocator, so that's probably not the problem here. 😅)
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2022-12-01 18:11 freebsd-riscv64-unmatched go@36b87f27 net/http.TestTransportGCRequest (log)
1 second passes in backend, proxygone= false
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (6.61s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.32s)
clientserver_test.go:1184: never saw GC of request
--- FAIL: TestTransportGCRequest/h2 (8.36s)
--- FAIL: TestTransportGCRequest/h2/NoBody (7.07s)
clientserver_test.go:1184: never saw GC of request
2022-12-05 20:45 freebsd-riscv64-unmatched go@a5b10be4 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (6.50s)
--- FAIL: TestTransportGCRequest/h2/Body (5.33s)
clientserver_test.go:1184: never saw GC of request
2022-12-07 16:09 freebsd-riscv64-unmatched go@7ed50cfd net/http.TestTransportGCRequest (log)
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (6.28s)
--- FAIL: TestTransportGCRequest/h1/Body (5.36s)
clientserver_test.go:1184: never saw GC of request
2022-12-14 19:12 freebsd-riscv64-unmatched go@ffefcd36 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (6.41s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.26s)
clientserver_test.go:1184: never saw GC of request
2022-12-21 03:49 freebsd-riscv64-unmatched go@78fc8107 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (9.88s)
--- FAIL: TestTransportGCRequest/h2/NoBody (6.68s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-01-21 21:08 freebsd-riscv64-unmatched go@ba913774 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (7.92s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.34s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-01-20 05:01 freebsd-riscv64-unmatched go@8354f6b5 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (8.01s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.93s)
clientserver_test.go:1184: never saw GC of request
--- FAIL: TestTransportGCRequest/h2 (9.75s)
--- FAIL: TestTransportGCRequest/h2/NoBody (6.13s)
clientserver_test.go:1184: never saw GC of request
1 second passes in backend, proxygone= false
2023-02-01 19:47 linux-amd64-race go@ab0f0459 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
2023-02-01 21:30 darwin-amd64-race go@4b7f7eef net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.01s)
The -race failures are #58168. The freebsd-riscv64-unmatched failure looks real. I still think we should remove the arbitrary timeout.
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-03-24 00:44 darwin-amd64-nocgo go@d633f4b9 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (8.86s)
--- FAIL: TestTransportGCRequest/h1/Body (8.05s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-04-06 22:46 freebsd-riscv64-unmatched go@4f4a9c7f net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (7.77s)
--- FAIL: TestTransportGCRequest/h2/NoBody (7.26s)
clientserver_test.go:1184: never saw GC of request
--- FAIL: TestTransportGCRequest/h1 (9.36s)
--- FAIL: TestTransportGCRequest/h1/NoBody (6.02s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-05-09 18:03 freebsd-riscv64-unmatched go@fffddce5 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (7.63s)
--- FAIL: TestTransportGCRequest/h2/NoBody (6.46s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-04-18 16:26 freebsd-riscv64-unmatched go@c9d5df08 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (7.17s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.40s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-05-24 00:48 darwin-amd64-13 go@e4d95d0d net/http.TestTransportGCRequest (log)
2023/05/23 21:14:43 httptest.Server blocked in Close after 5 seconds, waiting for connections:
*net.TCPConn 0xc000d1c200 127.0.0.1:50286 in state active
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (18.17s)
--- FAIL: TestTransportGCRequest/h1/Body (17.92s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-05-30 19:27 linux-s390x-ibm-race go@348fd638 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (7.15s)
--- FAIL: TestTransportGCRequest/h2/Body (5.43s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-05-31 22:48 freebsd-riscv64-unmatched go@1079a5c0 net/http.TestTransportGCRequest (log)
1 second passes in backend, proxygone= false
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (7.68s)
--- FAIL: TestTransportGCRequest/h2/Body (5.56s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-06-13 03:06 linux-s390x-ibm-race go@b0e1707f net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (11.44s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.86s)
clientserver_test.go:210: server log: timeout waiting for SETTINGS frames from 127.0.0.1:53882
clientserver_test.go:1166: Post "https://127.0.0.1:42741": unexpected EOF
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-05-31 15:17 netbsd-arm64-bsiegert go@125c2cac net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (6.50s)
--- FAIL: TestTransportGCRequest/h2/Body (6.22s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-06-28 02:41 linux-s390x-ibm-race go@a3093eca net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (9.46s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.63s)
clientserver_test.go:1184: never saw GC of request
--- FAIL: TestTransportGCRequest/h2 (9.67s)
--- FAIL: TestTransportGCRequest/h2/NoBody (6.30s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-07-19 11:55 linux-s390x-ibm-race go@5fe3f0a2 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (10.15s)
--- FAIL: TestTransportGCRequest/h1/NoBody (6.75s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-07-20 16:57 linux-s390x-ibm-race go@2b82d70f net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (12.20s)
--- FAIL: TestTransportGCRequest/h2/NoBody (6.22s)
clientserver_test.go:1184: never saw GC of request
--- FAIL: TestTransportGCRequest/h1 (16.30s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.83s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-07-31 18:33 linux-s390x-ibm go@bac4e2f2 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (8.16s)
--- FAIL: TestTransportGCRequest/h1/Body (6.05s)
clientserver_test.go:1184: never saw GC of request
--- FAIL: TestTransportGCRequest/h2 (8.15s)
--- FAIL: TestTransportGCRequest/h2/Body (6.01s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-08-07 18:49 linux-s390x-ibm go@78af0bbc net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (7.84s)
--- FAIL: TestTransportGCRequest/h2/Body (5.78s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-08-12 03:56 linux-s390x-ibm go@ac64a362 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (9.34s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.51s)
clientserver_test.go:1184: never saw GC of request
2023-08-12 03:56 linux-s390x-ibm-race go@ac64a362 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (6.70s)
--- FAIL: TestTransportGCRequest/h2/Body (5.44s)
clientserver_test.go:1184: never saw GC of request
2023-08-14 15:41 linux-s390x-ibm-race go@c6ee8e31 net/http.TestTransportGCRequest (log)
1 second passes in backend, proxygone= false
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (11.66s)
--- FAIL: TestTransportGCRequest/h2/Body (7.30s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-08-21 21:48 linux-s390x-ibm-race go@47645420 net/http.TestTransportGCRequest (log)
1 second passes in backend, proxygone= false
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (12.30s)
--- FAIL: TestTransportGCRequest/h1/NoBody (9.40s)
clientserver_test.go:1184: never saw GC of request
--- FAIL: TestTransportGCRequest/h2 (19.88s)
--- FAIL: TestTransportGCRequest/h2/NoBody (11.12s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-08-23 19:03 freebsd-riscv64-unmatched go@738d2d90 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (7.19s)
--- FAIL: TestTransportGCRequest/h1/NoBody (5.92s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-08-22 19:18 linux-s390x-ibm go@fbcf43c6 net/http.TestTransportGCRequest (log)
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h1 (7.18s)
--- FAIL: TestTransportGCRequest/h1/Body (6.16s)
clientserver_test.go:1184: never saw GC of request
--- FAIL: TestTransportGCRequest/h2 (6.46s)
--- FAIL: TestTransportGCRequest/h2/Body (5.42s)
clientserver_test.go:1184: never saw GC of request
Found new dashboard test flakes for:
#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest"
2023-08-22 19:18 linux-s390x-ibm go@88a6df72 net/http.TestTransportGCRequest (log)
1 second passes in backend, proxygone= false
--- FAIL: TestTransportGCRequest (0.00s)
--- FAIL: TestTransportGCRequest/h2 (9.11s)
--- FAIL: TestTransportGCRequest/h2/NoBody (7.45s)
clientserver_test.go:1184: never saw GC of request
Change https://go.dev/cl/522615 mentions this issue: net/http: remove arbitrary timeout from TestTransportGCRequest