net/http: HTTP/2 response body Close method sometimes returns spurious context cancelation error (1.17.3 regression) #49366

cespare · 2021-11-04T23:00:29Z

What version of Go are you using (`go version`)?

Go 1.17.3

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (`go env`)?

linux/amd64

What did you do?

Use an http.Client with (any) Timeout set
Make an HTTP/2 request
Read the body
Close the body

Demo code:

package main

import (
	"io"
	"log"
	"net/http"
	"time"
)

func main() {
	client := &http.Client{Timeout: time.Minute}
	for i := 0; i < 20; i++ {
		resp, err := client.Get("https://google.com")
		if err != nil {
			log.Fatal(err)
		}
		if _, err := io.Copy(io.Discard, resp.Body); err != nil {
			log.Fatal(err)
		}
		if err := resp.Body.Close(); err != nil {
			log.Fatalf("[i=%d] body close error: %s", i, err)
		}
	}
}

(I'm pinging google.com as an easy way to get an HTTP/2 request going.)

What did you expect to see?

No error, at least not on the resp.Body.Close() call.

What did you see instead?

For example:

2021/11/04 15:49:08 [i=0] body close error: context canceled

Sometimes it takes a few iterations to hit an error.

This is HTTP/2-specific: with GODEBUG=http2client=0 it does not reproduce.

This does not occur in Go 1.17.2 but it started happening with 1.17.3.

I realize it's weird to be checking the resp.Body.Close error in the first place. This came up in the context of twirp; I'm going to send a PR to them to stop checking the error. Even so, I don't think we should get this error in the client. It's especially confusing because we get the error immediately (so it's not related to the 1 minute timeout specifically).

I bisected on master to 7109323, which is CL 353870. The original x/net/http2 CL is CL 353390 and it was backported for Go 1.17.3 as CL 357683.

/cc @neild @bradfitz @nightlyone @fraenkel

The text was updated successfully, but these errors were encountered:

neild · 2021-11-05T00:22:20Z

resp.Body.Close wants to wait until the request stream has been finalized. (This ensures that, among other things, if we immediately send another request, the previous request no longer counts against the connection's concurrency limit.)

Finalizing the stream (in cleanupWriteRequest) can write to the network (sending a stream reset. Network writes can take an arbitrarily long amount of time, so resp.Body.Close waits until the cleanup happens or until the request is canceled, whichever happens first.

A http.Client with a non-zero timeout wraps the response body in a *http.cancelTimerBody. The cancelTimerBody cancels the request context after reading any error, including io.EOF, from the response body.

So if you read the full response, the request context is always canceled before resp.Body.Close is called.

I'm not immediately certain what the right fix is: resp.Body.Close waits for the stream cleanup because we have tests which expect that all stream state is cleaned up after the response body is closed. This seems like a reasonable assumption, and a good property to preserve. But we don't want to block indefinitely, so there needs to be some bound on how long resp.Body.Close will take. The context lifetime seems like the perfect bound, but we apparently can't use it.

cespare · 2021-11-05T00:43:54Z

Naive suggestion from someone without context:

If cancelTimerBody.Close would return context.Canceled and it had previously called stop, then could it know that the latter caused the former and return nil as a special case?

neild · 2021-11-05T00:58:14Z

That fixes the problem where we return context.Canceled instead of nil, but it doesn't fix the problem where we want to wait for the request to be cleaned up before returning from Close.

cespare · 2021-11-05T23:31:05Z

@neild I'm not sure I'm following you. Altering whether the function returns nil or context.Canceled doesn't change how long the function waits before returning.

Or are you saying that the problem I'm noticing is a symptom of a deeper problem, which is that resp.Body.Close doesn't wait for stream cleanup as intended if there's a timeout set?

neild · 2021-11-06T06:29:26Z

Yes, that's right: resp.Body.Close is supposed to be waiting for stream cleanup, but it's returning immediately when the body has been completely read.

gburt · 2021-11-06T20:28:20Z

This just hit us too; sorry for the +1 post. We reverted to the previous Go version because it's not feasible to change every instance where we check such errors (and not clear that's the right thing to do anyway). This feels like a pretty serious regression.

gopherbot · 2021-11-08T19:27:09Z

Change https://golang.org/cl/362354 mentions this issue: http2: avoid spurious context cancelation error from Response.Body.Close

gopherbot · 2021-11-08T19:28:54Z

Change https://golang.org/cl/361919 mentions this issue: net/http: do not cancel request context on response body read

chrisntb · 2021-11-12T05:40:33Z

We also saw this error in our logs when we upgraded to 1.17.3. We downgraded the log to warn level after seeing this issue to remove the noise.

nicolaasuni · 2021-11-12T14:37:56Z

This issue is serious for me as I have a case when the entire body is lost before being processed.
This is happening when using httputil.DumpResponse to log the response body before returning it.
For example: https://github.com/nexmoinc/gosrvlib/blob/main/pkg/httpclient/client.go#L95 but with the body param set to true.
For now I solved by adding a Context Timeout.

When a request has a deadline set, the net/http package can cancel the request context after reading an error (including io.EOF) from the response body. Avoid returning a spurious error from transportResponseBody if the request context is canceled. For golang/go#49366. Change-Id: I645466a1d6e405bdf17b3cc087204e4622a140eb Reviewed-on: https://go-review.googlesource.com/c/net/+/362354 Trust: Damien Neil <dneil@google.com> Run-TryBot: Damien Neil <dneil@google.com> TryBot-Result: Go Bot <gobot@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

neild · 2021-11-12T20:23:46Z

@gopherbot Please open backport issues for 1.16 and 1.17

gopherbot · 2021-11-12T20:29:12Z

Backport issue(s) opened: #49558 (for 1.16), #49559 (for 1.17).

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

becasue of this bug golang/go#49366 Signed-off-by: Krasi Georgiev <8903888+krasi-georgiev@users.noreply.github.com>

gopherbot · 2021-12-01T19:40:50Z

Change https://golang.org/cl/368084 mentions this issue: [release-branch.go1.16] net/http: do not cancel request context on response body read

gopherbot · 2021-12-01T19:40:53Z

Change https://golang.org/cl/368085 mentions this issue: [release-branch.go1.17] net/http: do not cancel request context on response body read

…sponse body read When sending a Request with a non-context deadline, we create a context with a timeout. This context is canceled when closing the response body, and also if a read from the response body returns an error (including io.EOF). Cancelling the context in Response.Body.Read interferes with the HTTP/2 client cleaning up after a request is completed, and is unnecessary: The user should always close the body, the impact from not canceling the context is minor (the context timer leaks until it fires). Fixes #49559. For #49366. Change-Id: Ieaed866116916261d9079f71d8fea7a7b303b8fb Reviewed-on: https://go-review.googlesource.com/c/go/+/361919 Trust: Damien Neil <dneil@google.com> Run-TryBot: Damien Neil <dneil@google.com> TryBot-Result: Go Bot <gobot@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org> (cherry picked from commit 76fbd61) Reviewed-on: https://go-review.googlesource.com/c/go/+/368085 Reviewed-by: Michael Knyszek <mknyszek@google.com>

…sponse body read When sending a Request with a non-context deadline, we create a context with a timeout. This context is canceled when closing the response body, and also if a read from the response body returns an error (including io.EOF). Cancelling the context in Response.Body.Read interferes with the HTTP/2 client cleaning up after a request is completed, and is unnecessary: The user should always close the body, the impact from not canceling the context is minor (the context timer leaks until it fires). For #49366. Fixes #49558. Change-Id: Ieaed866116916261d9079f71d8fea7a7b303b8fb Reviewed-on: https://go-review.googlesource.com/c/go/+/361919 Trust: Damien Neil <dneil@google.com> Run-TryBot: Damien Neil <dneil@google.com> TryBot-Result: Go Bot <gobot@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org> (cherry picked from commit 76fbd61) Reviewed-on: https://go-review.googlesource.com/c/go/+/368084 Reviewed-by: Michael Knyszek <mknyszek@google.com>

Workaround for golang/go#49366

When a request has a deadline set, the net/http package can cancel the request context after reading an error (including io.EOF) from the response body. Avoid returning a spurious error from transportResponseBody if the request context is canceled. For golang/go#49366. Change-Id: I645466a1d6e405bdf17b3cc087204e4622a140eb Reviewed-on: https://go-review.googlesource.com/c/net/+/362354 Trust: Damien Neil <dneil@google.com> Run-TryBot: Damien Neil <dneil@google.com> TryBot-Result: Go Bot <gobot@golang.org> Reviewed-by: Brad Fitzpatrick <bradfitz@golang.org>

cespare mentioned this issue Nov 4, 2021

Don't check the response body close error in the client twitchtv/twirp#336

Merged

thanm added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 5, 2021

rhysh mentioned this issue Nov 11, 2021

net/http: 1.17.3 setting http.Client.Timeout returns context cancelled on Body.Close #49517

Closed

CarsonHoffman mentioned this issue Nov 12, 2021

error closing resp body bwmarrin/discordgo#1028

Closed

gopherbot closed this as completed in 76fbd61 Nov 12, 2021

krasi-georgiev added a commit to cryptoriums/flashbot that referenced this issue Nov 13, 2021

pinning the golang version

5e6312c

becasue of this bug golang/go#49366 Signed-off-by: Krasi Georgiev <8903888+krasi-georgiev@users.noreply.github.com>

krasi-georgiev mentioned this issue Nov 13, 2021

closing flashbot reply body: context canceled cryptoriums/flashbot#4

Closed

mikhailshilkov mentioned this issue Nov 23, 2021

Disable response body dump pulumi/pulumi-google-native#238

Merged

marefr mentioned this issue Nov 24, 2021

'Failed to close response body' error after upgrade golang net/http grafana/grafana#41924

Closed

bep mentioned this issue Dec 2, 2021

Add a remote retry for resources.Get gohugoio/hugo#9231

Merged

bep added a commit to bep/hugo that referenced this issue Dec 2, 2021

resources: Add timeout to the HTTP request in Get

6573ba1

Workaround for golang/go#49366

bep added a commit to bep/hugo that referenced this issue Dec 2, 2021

resources: Add timeout to the HTTP request in Get

94c2873

Workaround for golang/go#49366

bep added a commit to bep/hugo that referenced this issue Dec 2, 2021

resources: Add timeout to the HTTP request in Get

cb46d10

Workaround for golang/go#49366

bep added a commit to gohugoio/hugo that referenced this issue Dec 2, 2021

resources: Add timeout to the HTTP request in Get

93572e5

Workaround for golang/go#49366

nanmu42 mentioned this issue Dec 5, 2021

CI: httputil.DumpResponse() is unstable under go 1.17.3 and HTTP/2 nanmu42/etherscan-api#64

Closed

bep mentioned this issue Dec 9, 2021

Add a way for the user to control errors in resources.Get gohugoio/hugo#9259

Closed

golang locked and limited conversation to collaborators Dec 1, 2022

gopherbot added the FrozenDueToAge label Dec 1, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http: HTTP/2 response body Close method sometimes returns spurious context cancelation error (1.17.3 regression) #49366

net/http: HTTP/2 response body Close method sometimes returns spurious context cancelation error (1.17.3 regression) #49366

cespare commented Nov 4, 2021

neild commented Nov 5, 2021

cespare commented Nov 5, 2021

neild commented Nov 5, 2021

cespare commented Nov 5, 2021

neild commented Nov 6, 2021

gburt commented Nov 6, 2021

gopherbot commented Nov 8, 2021

gopherbot commented Nov 8, 2021

chrisntb commented Nov 12, 2021

nicolaasuni commented Nov 12, 2021 •

edited

neild commented Nov 12, 2021

gopherbot commented Nov 12, 2021

gopherbot commented Dec 1, 2021

gopherbot commented Dec 1, 2021

net/http: HTTP/2 response body Close method sometimes returns spurious context cancelation error (1.17.3 regression) #49366

net/http: HTTP/2 response body Close method sometimes returns spurious context cancelation error (1.17.3 regression) #49366

Comments

cespare commented Nov 4, 2021

What version of Go are you using (go version)?

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

What did you do?

What did you expect to see?

What did you see instead?

neild commented Nov 5, 2021

cespare commented Nov 5, 2021

neild commented Nov 5, 2021

cespare commented Nov 5, 2021

neild commented Nov 6, 2021

gburt commented Nov 6, 2021

gopherbot commented Nov 8, 2021

gopherbot commented Nov 8, 2021

chrisntb commented Nov 12, 2021

nicolaasuni commented Nov 12, 2021 • edited

neild commented Nov 12, 2021

gopherbot commented Nov 12, 2021

gopherbot commented Dec 1, 2021

gopherbot commented Dec 1, 2021

What version of Go are you using (`go version`)?

What operating system and processor architecture are you using (`go env`)?

nicolaasuni commented Nov 12, 2021 •

edited