net/http: Possible HTTP/2 busy loop regression in Go 1.17.3

[lwithers]

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

$ go version
go version go1.17.3 linux/amd64

Does this issue reproduce with the latest release?

Go 1.17.3 is currently the latest release. The same binary compiled with Go 1.17.2 does not have the same issue.

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

go env Output

$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/lwithers/.cache/go-build"
GOENV="/home/lwithers/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/lwithers/go/pkg/mod"
GONOPROXY=""
GONOSUMDB="github.com/lampkicking,go.internal.yoti.com,dev.go.internal.yoti.com"
GOOS="linux"
GOPATH="/home/lwithers/go"
GOPRIVATE=""
GOPROXY="https://athens.internal.yoti.com"
GOROOT="/opt/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/opt/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.3"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="0"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build390959389=/tmp/go-build -gno-record-gcc-switches"

The issue

Wtih some of our production binaries, we have seen quiescent CPU usages between 67%–100% of one core, even though the binary is idle. We have not yet found a small reproducer. This issue was found on binaries that were recompiled without changes (i.e. identical source, identical go.mod) with Go 1.17.3 — it does not occur if we compile the same input with Go 1.17.2 or any earlier version that we have used.

Looking at pprof we see:

pprof.human-attribute-server.samples.cpu.003.pb.gz

Looking at the update to the HTTP/2 bundle in Go1.17.3, we see a new func (cs *http2clientStream) writeRequest which has the following loop at the end:

        for {
                select {
                case <-cs.peerClosed:
                        return nil
                case <-respHeaderTimer:
                        return http2errTimeout
                case <-respHeaderRecv:
                        respHeaderTimer = nil // keep waiting for END_STREAM
                case <-cs.abort:
                        return cs.abortErr
                case <-ctx.Done():
                        return ctx.Err()
                case <-cs.reqCancel:
                        return http2errRequestCanceled
                }
        }

The line number of this in h2_bundle.go matches the line number in the profile.

Without knowing much at all about the design or operation of the HTTP/2 code, it would seem that if the channel respHeaderRecv (which is earlier set to cs.respHeaderRecv) is closed, that this function would busy-wait. And indeed, the CL updating the bundle in Go 1.17.3 does introduce a new close(cs.respHeaderRecv) on line 8692. I'm not 100% clear if that is the issue, but it's as far as I got without familiarising myself with the HTTP/2 codebase.

[seankhliao]

cc @neild

[lwithers]

We have found a reproducer, please find attached. It is related to some of the settings on the http.Client.Transport object:

https://play.golang.org/p/pNqYAo3WnX4

[gopherbot]

Change https://golang.org/cl/364574 mentions this issue: http2: avoid busy loop when ResponseHeaderTimeout is set

[neild]

Thats an unpleasant bug. Thanks for the nice analysis.

[neild]

@gopherbot Please open backport issues for 1.16 and 1.17.

[gopherbot]

Backport issue(s) opened: #49623 (for 1.16), #49624 (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.

[gopherbot]

Change https://golang.org/cl/368377 mentions this issue: [internal-branch.go1.17-vendor] http2: avoid busy loop when ResponseHeaderTimeout is set

[gopherbot]

Change https://golang.org/cl/368376 mentions this issue: [internal-branch.go1.16-vendor] http2: avoid busy loop when ResponseHeaderTimeout is set