net/http: HTTP/2 client retains an extra connection when client conn not usable path is reached

[bcmills]

#!watchflakes
post <- pkg == "net/http" && test == "TestTransportIdleConnTimeout" && `unexpected number of idle conns`

After CL 477196, TestTransportIdleConnTimeout/h2 occasionally fails with an extra connection (https://build.golang.org/log/3ad51e846979ee007b5a6bcae73ea5f5917d6a85):

--- FAIL: TestTransportIdleConnTimeout (0.06s)
    --- FAIL: TestTransportIdleConnTimeout/h2 (0.05s)
        transport_test.go:5073: req 1: unexpected number of idle conns: ["127.0.0.1:39145" "127.0.0.1:39145"]
FAIL
FAIL	net/http	55.461s

This failure mode seems exclusive to the h2 subtest — the HTTP/1 test does not seem to be affected.

I tried playing with the time.Sleep(timeout / 2) call in the doReq loop, and found that the failures are correlated to the Sleep: a longer sleep produces a higher probability of an extra connection.

I added some debug logging, and found that in a successful run each request makes two GetClientConn calls from (*Transport).roundTrip:

• The first call is from transport.go:549 via (*http2noDialH2RoundTripper).RoundTrip, and returns http2ErrNoCachedConn which becomes ErrSkipAltProtocol.
• The second call is from transport.go:591, and successfully calls ReserveNewRequest on a cached connection.

In a failing run, during the second doReq call the ReserveNewRequest path is taken first, and RoundTrip on it fails with http2: client conn not usable. The retry hits the http2ErrNoCachedConn path, and the rest of the request falls through to the secondary path as usual. It appears that something about the extra retry causes an additional connection to be added to the pool.

(attn @neild)

[gopherbot]

Change https://go.dev/cl/477876 mentions this issue: http2: log the correct error when retrying in (*Transport).RoundTripOpt

[gopherbot]

Change https://go.dev/cl/477856 mentions this issue: net/http: retry TestTransportIdleConnTimeout if an extra conn is seen in HTTP/2 mode

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestTransportIdleConnTimeout" && `unexpected number of idle conns`

2023-03-20 22:54 linux-amd64-longtest-race go@b98c1b22 net/http.TestTransportIdleConnTimeout (log)

--- FAIL: TestTransportIdleConnTimeout (0.05s)
    --- FAIL: TestTransportIdleConnTimeout/h2 (0.04s)
        transport_test.go:5073: req 1: unexpected number of idle conns: ["127.0.0.1:43911" "127.0.0.1:43911"]
2023/03/20 23:22:10 Unsolicited response received on idle HTTP channel starting with "HTTP/1.1 204 No Content\r\nConnection: close\r\n\r\n"; err=<nil>

— watchflakes

[gopherbot]

Found new dashboard test flakes for:

#!watchflakes
post <- pkg == "net/http" && test == "TestTransportIdleConnTimeout" && `unexpected number of idle conns`

2023-03-22 18:50 linux-amd64-longtest-race go@09f1ddb1 net/http.TestTransportIdleConnTimeout (log)

--- FAIL: TestTransportIdleConnTimeout (0.07s)
    --- FAIL: TestTransportIdleConnTimeout/h2 (0.06s)
        transport_test.go:5073: req 2: unexpected number of idle conns: ["127.0.0.1:33677" "127.0.0.1:33677"]

— watchflakes