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: HTTP/2 client retains an extra connection when client conn not usable path is reached #59155

Closed
bcmills opened this issue Mar 20, 2023 · 4 comments
Closed

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

bcmills opened this issue Mar 20, 2023 · 4 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@bcmills
Copy link
Contributor

bcmills commented Mar 20, 2023 •
edited 

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

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)
@bcmills bcmills added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Mar 20, 2023
@bcmills bcmills added this to the Backlog milestone Mar 20, 2023
@bcmills bcmills changed the title net/http: HTTP/2 idle connections are sometimes not reused net/http: HTTP/2 client dials an extra connection when 'client conn not usable' path is reached Mar 20, 2023
@gopherbot
Copy link

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

gopherbot pushed a commit to golang/net that referenced this issue Mar 20, 2023
@gopherbot
http2: log the correct error when retrying in (*Transport).RoundTripOpt
6960703 
On the shouldRetryRequest path, err is invariantly nil, and therefore
meaningless to log with vlogf. Instead, log the original error returned
by the call to cc.RoundTrip.

For golang/go#59155.

Change-Id: I82c00a6033d0e92c28a5ccf60a87eec1c8b41886
Reviewed-on: https://go-review.googlesource.com/c/net/+/477876
TryBot-Result: Gopher Robot <gobot@golang.org>
Run-TryBot: Bryan Mills <bcmills@google.com>
Auto-Submit: Bryan Mills <bcmills@google.com>
Reviewed-by: Damien Neil <dneil@google.com>
@bcmills bcmills changed the title net/http: HTTP/2 client dials an extra connection when 'client conn not usable' path is reached net/http: HTTP/2 client retains an extra connection when 'client conn not usable' path is reached Mar 20, 2023
@bcmills bcmills changed the title net/http: HTTP/2 client retains an extra connection when 'client conn not usable' path is reached net/http: HTTP/2 client retains an extra connection when client conn not usable path is reached Mar 20, 2023
@gopherbot
Copy link

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

@gopherbot
Copy link

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

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

@golang golang locked and limited conversation to collaborators Mar 21, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
Test Flakes
Status: Done
Milestone
Backlog
Development

No branches or pull requests
2 participants
@bcmills @gopherbot