net/http: TestRequestLimit/h2 becomes significantly more expensive and slower after x/net@v0.23.0

[dmitshur]

#!watchflakes
post <-  pkg == "net/http" && test ~ `TestRequestLimit` && status == "ABORT"

I've initially observed this on various builders, most often linux-386 ones, but it seems to reproduce on darwin/arm64 too.

At tip without x/net@v0.23.0 (e.g., commit 61a3ee5), TestRequestLimit/h2 consistently passes in under a second:

$ go test -count=1 net/http -v -run=^TestRequestLimit$
=== RUN   TestRequestLimit
=== RUN   TestRequestLimit/h1
=== RUN   TestRequestLimit/h2
--- PASS: TestRequestLimit (0.14s)
    --- PASS: TestRequestLimit/h1 (0.06s)
    --- PASS: TestRequestLimit/h2 (0.08s)
PASS
ok  	net/http	0.491s
$ go test -count=1 net/http -run=^TestRequestLimit$
ok  	net/http	0.442s
$ go test -count=1 net/http -run=^TestRequestLimit$
ok  	net/http	0.395s
$ go test -count=1 net/http -run=^TestRequestLimit$
ok  	net/http	0.425s

When x/net@v0.23.0 is pulled in (e.g., CL 576295), it takes anywhere between 15 seconds and 200+ seconds:

$ go test -count=1 net/http -v -run=^TestRequestLimit$
=== RUN   TestRequestLimit
=== RUN   TestRequestLimit/h1
=== RUN   TestRequestLimit/h2
--- PASS: TestRequestLimit (14.94s)
    --- PASS: TestRequestLimit/h1 (0.06s)
    --- PASS: TestRequestLimit/h2 (14.88s)
PASS
ok  	net/http	15.327s
$ go test -count=1 net/http -v -run=^TestRequestLimit$
=== RUN   TestRequestLimit
=== RUN   TestRequestLimit/h1
=== RUN   TestRequestLimit/h2
--- PASS: TestRequestLimit (266.59s)
    --- PASS: TestRequestLimit/h1 (0.06s)
    --- PASS: TestRequestLimit/h2 (266.52s)
PASS
ok  	net/http	266.886s
$ go test -count=1 net/http -v -run=^TestRequestLimit$
=== RUN   TestRequestLimit
=== RUN   TestRequestLimit/h1
=== RUN   TestRequestLimit/h2
--- PASS: TestRequestLimit (205.00s)
    --- PASS: TestRequestLimit/h1 (0.05s)
    --- PASS: TestRequestLimit/h2 (204.95s)
PASS
ok  	net/http	205.313s

I'm seeing around 125% CPU usage while this one test runs. This seems to cause it to exceed the 180 second timeout on some builders, especially when running all other tests and not just this one.

CC @neild.

[neild]

The root cause of this is an unfortunate side-effect of the fix for #65051. It's arguably a bug in that fix.

When the HTTP/2 server rejects a connection due to a bad request, it sends a GOAWAY frame and closes the connection. The GOAWAY includes the ID of the most recent request processed by the server. The problem is that the GOAWAY sent by the server in this case includes the ID of the previous request, not the one which caused us to close the connection.

When the HTTP/2 client gets a GOAWAY with an error for a connection where it has sent only one request, it should assume that there's something wrong with that request and not retry it, even if the GOAWAY doesn't indicate that this request was seen by the server. It does not. This is #60636.

The interaction of these two behaviors means that in TestRequestLimit, requests get sent, rejected, and retried repeatedly.

One half of the fix will be to make the GOAWAY sent when rejecting a request correctly indicate that the server saw that request. The other will be to finally fix #60636, if I can figure out a good way to do so. (It's tricky, because the retry behavior is spread between net/http and x/net/http, and the interactions between the two sides are complicated.)

[gopherbot]

Change https://go.dev/cl/576756 mentions this issue: http2: send correct LastStreamID in stream-caused GOAWAY

[MadhavJivrajani]

Thank you for the RCA and the potential fix @neil, I really appreciate the detailed write-up! ♥️

[MadhavJivrajani]

@neild @dmitshur 👋🏼

Hey folks, thank you for tracking this. I'm trying to understand the process better here, and apologies if I've missed reading about this somewhere, would the bug fix in https://go.dev/cl/576756 warrant another patch release for it? Or would this then be included whenever the next one happens to be planned in the future? Thanks!

[gopherbot]

Change https://go.dev/cl/576895 mentions this issue: http2: don't retry the first request on a connection on GOAWAY error

[neild]

@gopherbot please open backport issues. This is a bug/deficiency in a previous cherrypick, so we should backport the fix as well.

[gopherbot]

Backport issue(s) opened: #66697 (for 1.21), #66698 (for 1.22).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://go.dev/wiki/MinorReleases.

[neild]

@MadhavJivrajani I don't believe this warrants an off-schedule minor release, but I do think we should backport https://go.dev/cl/576756 into the next minor releases.