net/http: TestTransportGCRequest failures

[gopherbot]

#!watchflakes
post <- pkg == "net/http" && test == "TestTransportGCRequest" && date < "2023-08-25"

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

— watchflakes

[gopherbot]

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

— watchflakes

[bcmills]

It appears this test was last updated in https://go.dev/cl/438137 (attn @neild).

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

[bcmills]

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

[neild]

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.

[bcmills]

runtime.GC should 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. 😅)

[gopherbot]

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

— watchflakes

[gopherbot]

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

— watchflakes

[gopherbot]

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)

— watchflakes

[bcmills]

The -race failures are #58168. The freebsd-riscv64-unmatched failure looks real. I still think we should remove the arbitrary timeout.

[gopherbot]

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

— watchflakes

[gopherbot]

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

— watchflakes