net/http: http2 round tripper nil pointer dereference causes panic causing deadlock

[niallnsec]

Go version

go version go1.22.0 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/user/Library/Caches/go-build'
GOENV='/Users/user/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/user/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/user/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/opt/homebrew/Cellar/go/1.22.0/libexec'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/opt/homebrew/Cellar/go/1.22.0/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.0'
GCCGO='gccgo'
AR='ar'
CC='cc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/0_/clg6377n50x2gd3388rp147w0000gn/T/go-build4212135828=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

Issue occurs intermittently in a highly concurrent program making HTTP requests using Go's http.Client. The issue manifests as a deadlock in the program.

What did you see happen?

goroutine 2270 gp=0xc0003e01c0 m=nil [sync.Mutex.Lock, 180 minutes]:
runtime.gopark(0x2?, 0x0?, 0xb0?, 0x89?, 0x4500c6?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/proc.go:402 +0xce fp=0xc000048880 sp=0xc000048860 pc=0x43e76e
runtime.goparkunlock(...)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/proc.go:408
runtime.semacquire1(0xc000002354, 0x0, 0x3, 0x1, 0x15)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/sema.go:160 +0x225 fp=0xc0000488e8 sp=0xc000048880 pc=0x450c05
sync.runtime_SemacquireMutex(0x4?, 0x0?, 0xd5d8c0?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/sema.go:77 +0x25 fp=0xc000048920 sp=0xc0000488e8 pc=0x46d6e5
sync.(*Mutex).lockSlow(0xc000002350)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/sync/mutex.go:171 +0x15d fp=0xc000048970 sp=0xc000048920 pc=0x47a6dd
sync.(*Mutex).Lock(...)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/sync/mutex.go:90
net/http.(*http2clientStream).abortStream(0xc000048a68?, {0xf98f60, 0x1578700})
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:7438 +0x5d fp=0xc0000489c0 sp=0xc000048970 pc=0x65851d
net/http.(*http2ClientConn).RoundTrip(0xc000002300, 0xc000db4c60)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:8340 +0x4f9 fp=0xc000048b00 sp=0xc0000489c0 pc=0x65c9b9
net/http.(*http2Transport).RoundTripOpt(0xc0004c2750, 0xc000db4c60, {0xf0?})
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:7591 +0x1b1 fp=0xc000048c30 sp=0xc000048b00 pc=0x659131
net/http.(*http2Transport).RoundTrip(...)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:7540
net/http.http2noDialH2RoundTripper.RoundTrip({0xc00025f040?}, 0xc000db4c60?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:10167 +0x1a fp=0xc000048c70 sp=0xc000048c30 pc=0x666f1a
net/http.(*Transport).roundTrip(0xc00025f040, 0xc000db4c60)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/transport.go:553 +0x39c fp=0xc000048e98 sp=0xc000048c70 pc=0x68dedc
net/http.(*Transport).RoundTrip(0xc000db4c60?, 0xf98de0?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/roundtrip.go:17 +0x13 fp=0xc000048eb8 sp=0xc000048e98 pc=0x673813
net/http.send(0xc000db4b40, {0xf98de0, 0xc00025f040}, {0x1?, 0x496233?, 0x1510f40?})
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/client.go:259 +0x5e4 fp=0xc000049098 sp=0xc000048eb8 pc=0x6381a4
net/http.(*Client).send(0xc0009e88d0, 0xc000db4b40, {0x8?, 0xc000049180?, 0x1510f40?})
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/client.go:180 +0x98 fp=0xc000049110 sp=0xc000049098 pc=0x637a58
net/http.(*Client).do(0xc0009e88d0, 0xc000db4b40)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/client.go:724 +0x8dc fp=0xc000049300 sp=0xc000049110 pc=0x639d3c
net/http.(*Client).Do(...)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/client.go:590
<PRIVATE CODE>

goroutine 2377 gp=0xc000318700 m=nil [sync.Mutex.Lock, 180 minutes]:
runtime.gopark(0xd94b80?, 0xc000b87b60?, 0x60?, 0x92?, 0x23?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/proc.go:402 +0xce fp=0xc00001c968 sp=0xc00001c948 pc=0x43e76e
runtime.goparkunlock(...)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/proc.go:408
runtime.semacquire1(0xc000002354, 0x0, 0x3, 0x1, 0x15)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/sema.go:160 +0x225 fp=0xc00001c9d0 sp=0xc00001c968 pc=0x450c05
sync.runtime_SemacquireMutex(0xc000618a90?, 0xa0?, 0xc0009e8c98?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/sema.go:77 +0x25 fp=0xc00001ca08 sp=0xc00001c9d0 pc=0x46d6e5
sync.(*Mutex).lockSlow(0xc000002350)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/sync/mutex.go:171 +0x15d fp=0xc00001ca58 sp=0xc00001ca08 pc=0x47a6dd
sync.(*Mutex).Lock(...)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/sync/mutex.go:90
net/http.(*http2clientConnReadLoop).cleanup(0xc000318700?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:9241 +0x145 fp=0xc00001cb70 sp=0xc00001ca58 pc=0x6618e5
net/http.(*http2ClientConn).readLoop.deferwrap1()
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:9197 +0x25 fp=0xc00001cb88 sp=0xc00001cb70 pc=0x661685
panic({0xd9e2a0?, 0x14ac430?})
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/panic.go:770 +0x132 fp=0xc00001cc38 sp=0xc00001cb88 pc=0x43acf2
runtime.panicmem(...)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/panic.go:261
runtime.sigpanic()
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/signal_unix.go:881 +0x378 fp=0xc00001cc98 sp=0xc00001cc38 pc=0x4537f8
net/http.(*http2pipe).Write(0xb100000000000009?, {0xc0001a0340?, 0xc0000de6e0?, 0xc00001cde0?})
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:3751 +0x176 fp=0xc00001cd20 sp=0xc00001cc98 pc=0x648e56
net/http.(*http2clientConnReadLoop).processData(0xc00001cfa8, 0xc000dbff20)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:9748 +0x21e fp=0xc00001cdf0 sp=0xc00001cd20 pc=0x66485e
net/http.(*http2clientConnReadLoop).run(0xc00001cfa8)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:9337 +0x446 fp=0xc00001cf60 sp=0xc00001cdf0 pc=0x662306
net/http.(*http2ClientConn).readLoop(0xc000002300)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:9198 +0x65 fp=0xc00001cfc8 sp=0xc00001cf60 pc=0x661565
net/http.(*http2Transport).newClientConn.gowrap1()
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:7848 +0x25 fp=0xc00001cfe0 sp=0xc00001cfc8 pc=0x65adc5
runtime.goexit({})
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/asm_amd64.s:1695 +0x1 fp=0xc00001cfe8 sp=0xc00001cfe0 pc=0x4712e1
created by net/http.(*http2Transport).newClientConn in goroutine 2376
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:7848 +0xca6

goroutine 2672 gp=0xc00081b500 m=nil [sync.Mutex.Lock, 180 minutes]:
runtime.gopark(0xf98f60?, 0x1578700?, 0x40?, 0xe5?, 0xc000002300?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/proc.go:402 +0xce fp=0xc001070e30 sp=0xc001070e10 pc=0x43e76e
runtime.goparkunlock(...)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/proc.go:408
runtime.semacquire1(0xc000002354, 0x0, 0x3, 0x1, 0x15)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/sema.go:160 +0x225 fp=0xc001070e98 sp=0xc001070e30 pc=0x450c05
sync.runtime_SemacquireMutex(0xc0008f36e0?, 0x80?, 0x0?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/sema.go:77 +0x25 fp=0xc001070ed0 sp=0xc001070e98 pc=0x46d6e5
sync.(*Mutex).lockSlow(0xc000002350)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/sync/mutex.go:171 +0x15d fp=0xc001070f20 sp=0xc001070ed0 pc=0x47a6dd
sync.(*Mutex).Lock(...)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/sync/mutex.go:90
net/http.(*http2clientStream).cleanupWriteRequest(0xc0008ee600, {0xf98f60, 0x1578700})
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:8568 +0x85 fp=0xc001070f98 sp=0xc001070f20 pc=0x65e0a5
net/http.(*http2clientStream).doRequest(0xc0008ee600, 0xc0008a87e0?)
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:8354 +0x28 fp=0xc001070fc0 sp=0xc001070f98 pc=0x65cd88
net/http.(*http2ClientConn).RoundTrip.gowrap1()
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:8259 +0x25 fp=0xc001070fe0 sp=0xc001070fc0 pc=0x65cd25
runtime.goexit({})
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/runtime/asm_amd64.s:1695 +0x1 fp=0xc001070fe8 sp=0xc001070fe0 pc=0x4712e1
created by net/http.(*http2ClientConn).RoundTrip in goroutine 2270
	/opt/homebrew/Cellar/go/1.22.0/libexec/src/net/http/h2_bundle.go:8259 +0x2ed

Looking specifically at the stack for goroutine 2377 it appears that there is a panic here:

go/src/net/http/h2_bundle.go

Line 3751 in 6cbe522

return p.b.Write(d)

which occurs as a result of p.b being nil. It looks like the deadlock occurs because as the stack unwinds and the deferred functions are called, cleanup() attempts to acquire a mutex which is already held further up the stack here:

go/src/net/http/h2_bundle.go

Line 9733 in 6cbe522

cc.mu.Lock()

What did you expect to see?

The HTTP2 round tripper should not panic and cause a deadlock.

[panjf2000]

The client would set up separate goroutines for reading and writing, this can happen in theory when some error occurred in the write goroutine and it closed the the pipe while the read goroutine reading it. That's my guess for this, could you provide a reproducible demo for us to diagnose more deeply?

[panjf2000]

CC @neild

[niallnsec]

@panjf2000 The scenario you are proposing makes a lot of sense with what I am seeing.

I wish I could provide a reproducible example, so far I have not been able to recreate it locally, but it inevitably appears on production systems after some time. I am still trying to put something together to trigger the issue locally for debugging though.

If it helps, the environment that my code is running has the following features:

• Approx 32 concurrent goroutines making HTTP requests (each uses its own instance of http.Client)
• HTTP requests are all GET or HEAD
• Each goroutine will be spawning its own worker routines making many simultaneous HTTP requests to a single server.
• The host machines CPU is under stress, typical load average is 15.
• The application makes requests to servers across the internet, frequently coming across servers which do not implement the HTTP and HTTP2 protocols properly. Lots of output like the following accumulates over time:

2024/02/19 22:44:18 protocol error: received DATA after END_STREAM
2024/02/19 22:44:20 protocol error: received DATA after END_STREAM
2024/02/19 22:44:33 protocol error: received DATA on a HEAD request
2024/02/19 22:44:49 Unsolicited response received on idle HTTP channel starting with "<!DOCTYPE html>\r\n"; err=<nil>
2024/02/19 22:47:03 protocol error: received DATA after END_STREAM
2024/02/19 22:47:04 Unsolicited response received on idle HTTP channel starting with "0\r\n\r\n"; err=<nil>
2024/02/19 22:47:20 protocol error: received DATA before a HEADERS frame
2024/02/19 22:48:57 protocol error: received DATA on a HEAD request
2024/02/19 22:48:58 protocol error: received DATA on a HEAD request
2024/02/19 22:49:48 Transport: unhandled response frame type *http.http2UnknownFrame

So far, I have not correlated these kinds of protocol errors with the times at which the deadlock occurs, so I doubt it is related but thought it worth mentioning.

I am in the process of adding additional instrumentation to my application in production in order to collect more details, I will report back if I find anything interesting or manage to recreate the issue locally.

[panjf2000]

The client would set up separate goroutines for reading and writing, this can happen in theory when some error occurred in the write goroutine and it closed the the pipe while the read goroutine reading it. That's my guess for this, could you provide a reproducible demo for us to diagnose more deeply?

After a deeper look at the source code, my previous assumption may not stand. If that was the case, the pipe.Write would have returned from here:

go/src/net/http/h2_bundle.go

Lines 3748 to 3750 in 83da21f

	if p.err != nil || p.breakErr != nil {
	return 0, http2errClosedPipeWrite
	}

However, I'm pretty sure that this issue had something to do with the fact that pipe.setBuffer was never invoked in clientConnReadLoop.handleResponse which is inside clientConnReadLoop.processHeaders. There are some cases that might cause handleResponse to miss the call to pipe.setBuffer without returning a non-nil error (or maybe some irregular frames from the remote, just like those logs you provided), I'm unable to determine which one is the root cause that is responsible for this issue before I get some more exhaustive info from your production environment. But I think we can fix this issue by checking if the pipe is initialized before writing on it, which is also a good thing in general.

[gopherbot]

Change https://go.dev/cl/566675 mentions this issue: http2: prevent uninitialized pipe from being written

[gopherbot]

Change https://go.dev/cl/567175 mentions this issue: http2: reject DATA frames after 1xx and before final headers

[neild]

One possible path for this (possibly the only path? I haven't found any others): Server sends a 1xx response, followed by a DATA frame. processData checks to see if the request has begun, but it checks cs.firstByte (have we received any frames for the stream, including a 1xx header) rather than cs.pastHeaders (have we received headers for the stream).

https://go.googlesource.com/net/+/refs/tags/v0.21.0/http2/transport.go#2687

[gopherbot]

Change https://go.dev/cl/569819 mentions this issue: net/http: update bundled x/net/http2

[niallnsec]

I've been running in production with the patch from https://go.dev/cl/566675 applied to the stdlib for about 8 days now and many million HTTP requests later I have not seen the deadlock issue pop up at all, so that appears to fix the issue.

I am not sure about the patch in https://go.dev/cl/567175 but if needed I can apply it as well (either on its own or with the other one) to test it.

[neild]

@niallnsec Thanks, that gives me some added confidence that we've correctly identified the root cause.

Historically, we haven't backported HTTP/2 fixes that can be applied by importing golang.org/x/net/http2 and using ConfigureServer to swap out the bundled implementation. I think that for clear bugs with no workaround short of using an entirely different package, we should be a bit more aggressive about backports, though, so:

@gopherbot please open backport issues. This is an HTTP/2 bug with no good workaround.