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

x/net/http2: Blocked Write on single connection causes all future calls to block indefinitely #33425

prashantv opened this issue Aug 2, 2019 · 16 comments


Copy link

@prashantv prashantv commented Aug 2, 2019

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

$ go version
go version go1.12.7 linux/amd64

Does this issue reproduce with the latest release?


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

go env Output
$ go env
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build705930436=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Used the HTTP/2 library to make calls as a client. One of the backends stalled and stopped reading from the TCP connection (although it was still running and the TCP connection was active).

This caused the TCP write buffer on the client to fill up.

What did you expect to see?

I expected that all future calls to the blocked server would timeout eventually, and that calls to any other server would not be affected.

What did you see instead?

All calls on the transport are blocked forever, including calls to working backends. Stack traces should the calls are blocked on a mutex, so any timeouts are ignored.



The repro sets up 2 "backends":
stuckURL: Accepts a TCP connection and does not read from the connection, to simulate a stuck backend
normal1URL: Echoes the request body back to the caller.

  1. A call is made to stuckURL with a payload that never completes. This causes the TCP write buffer to fill up, and the Write to block, while holding the *ClientConn.wmu (write lock on the connection). We sleep a second to make sure the TCP buffer fills up, and the write is blocked.
Stack trace
goroutine 44 [IO wait]:
internal/poll.runtime_pollWait(0x7f74ab342b98, 0x77, 0xffffffffffffffff)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/runtime/netpoll.go:182 +0x56
internal/poll.(*pollDesc).wait(0xc000144598, 0x77, 0x4000, 0x4800, 0xffffffffffffffff)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/internal/poll/fd_poll_runtime.go:87 +0x9b
internal/poll.(*FD).Write(0xc000144580, 0xc0001f2000, 0x4009, 0x4800, 0x0, 0x0, 0x0)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/internal/poll/fd_unix.go:276 +0x26e
net.(*netFD).Write(0xc000144580, 0xc0001f2000, 0x4009, 0x4800, 0x3, 0x3, 0xc0001aadaa)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/fd_unix.go:220 +0x4f
net.(*conn).Write(0xc00013c0a0, 0xc0001f2000, 0x4009, 0x4800, 0x0, 0x0, 0x0)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/net.go:189 +0x69, 0xc00013c0a0, 0xc000195058, 0xc0001f2000, 0x4009, 0x4800, 0x4009, 0x0, 0x0)
	/home/prashant/go/src/ +0x68
bufio.(*Writer).Write(0xc000130480, 0xc0001f2000, 0x4009, 0x4800, 0xc000034070, 0xc000034000, 0x0)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/bufio/bufio.go:622 +0x145*Framer).endWrite(0xc0001ea000, 0x0, 0x0)
	/home/prashant/go/src/ +0xab*Framer).WriteDataPadded(0xc0001ea000, 0x3, 0xc0001ee000, 0x4000, 0x4000, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/prashant/go/src/ +0x25d*Framer).WriteData(...)
	/home/prashant/go/src/*clientStream).writeRequestBody(0xc000154640, 0x7f74ab343070, 0xc000138600, 0x7f74ab343090, 0xc000138600, 0x0, 0x0)
	/home/prashant/go/src/ +0x337*Transport).getBodyWriterState.func1()
	/home/prashant/go/src/ +0xc2
created by
	/home/prashant/go/src/ +0xa3

  1. Another call to stuckURL is made, which is blocked in roundTrip trying to get the *ClientConn.wmu (since (1) holds this lock), and with the * lock held.
Stack trace

goroutine 46 [semacquire]:
sync.runtime_SemacquireMutex(0xc000195054, 0x40de00)
/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/runtime/sema.go:71 +0x3d
/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/sync/mutex.go:134 +0x109*ClientConn).roundTrip(0xc000194f00, 0xc000204100, 0x0, 0x0, 0x0, 0x0)
/home/prashant/go/src/ +0x467*Transport).RoundTripOpt(0xc00013a4e0, 0xc000204100, 0xc000118000, 0xc0001164b0, 0xc00013e03c, 0xc00013e040)
/home/prashant/go/src/ +0x172*Transport).RoundTrip(0xc00013a4e0, 0xc000204100, 0xc00013a4e0, 0xbf490e456743e889, 0xe34199ec9)
/home/prashant/go/src/ +0x3a
net/http.send(0xc000204000, 0x93f060, 0xc00013a4e0, 0xbf490e456743e889, 0xe34199ec9, 0xc6c560, 0xc00011c050, 0xbf490e456743e889, 0x1, 0x0)
/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:250 +0x461
net/http.(*Client).send(0xc000134db0, 0xc000204000, 0xbf490e456743e889, 0xe34199ec9, 0xc6c560, 0xc00011c050, 0x0, 0x1, 0xc000020a80)
/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:174 +0xfb
net/http.(*Client).do(0xc000134db0, 0xc000204000, 0x0, 0x0, 0x0)
/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:641 +0x279
net/http.(*Client).Get(0xc000134db0, 0xc000136180, 0x16, 0x8b330c, 0xf, 0x93f020)
/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:398 +0x9e
created by
/home/prashant/go/src/ +0x402

  1. Another call to stuckURL grabs the connection pool lock, *, then iterates over all connections to that address to check the idleState() which tries to grab * This blocks since (2) is already holding this lock.
Stack trace
goroutine 45 [semacquire]:
sync.runtime_SemacquireMutex(0xc000194f54, 0xc00013e000)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/runtime/sema.go:71 +0x3d
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/sync/mutex.go:134 +0x109*ClientConn).idleState(0xc000194f00, 0xc000130000)
	/home/prashant/go/src/ +0x41*clientConnPool).getClientConn(0xc000134fc0, 0xc000204300, 0xc00013e080, 0xf, 0xc00013a501, 0xc0001a5a18, 0x7c1030, 0xc00013a4e0)
	/home/prashant/go/src/ +0xeb*clientConnPool).GetClientConn(0xc000134fc0, 0xc000204300, 0xc00013e080, 0xf, 0xc00013e080, 0xf, 0x2)
	/home/prashant/go/src/ +0x4e*Transport).RoundTripOpt(0xc00013a4e0, 0xc000204300, 0xc000118100, 0xc0001165d0, 0xc00013e06c, 0xc00013e070)
	/home/prashant/go/src/ +0x105*Transport).RoundTrip(0xc00013a4e0, 0xc000204300, 0xc00013a4e0, 0xbf490e456749078a, 0xe341ebd66)
	/home/prashant/go/src/ +0x3a
net/http.send(0xc000204200, 0x93f060, 0xc00013a4e0, 0xbf490e456749078a, 0xe341ebd66, 0xc6c560, 0xc00011c080, 0xbf490e456749078a, 0x1, 0x0)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:250 +0x461
net/http.(*Client).send(0xc000134db0, 0xc000204200, 0xbf490e456749078a, 0xe341ebd66, 0xc6c560, 0xc00011c080, 0x0, 0x1, 0xc000020a80)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:174 +0xfb
net/http.(*Client).do(0xc000134db0, 0xc000204200, 0x0, 0x0, 0x0)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:641 +0x279
net/http.(*Client).Get(0xc000134db0, 0xc000136180, 0x16, 0x8b330c, 0xf, 0x93f020)
	/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:398 +0x9e
created by
	/home/prashant/go/src/ +0x402
  1. Now any calls made using the same *clientConnPool (e.g., any call through the same client/transport) block on trying to get *
Stack trace
3 @ 0x430b8f 0x440d79 0x440d4f 0x440aed 0x4663d9 0x78e6c6 0x78e62e 0x7a8b85 0x7a86ba 0x6af511 0x6aef0b 0x6b0519 0x6b004e 0x6b003b 0x45d481
#	0x440aec	sync.runtime_SemacquireMutex+0x3c										/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/runtime/sema.go:71
#	0x4663d8	sync.(*Mutex).Lock+0x108											/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/sync/mutex.go:134
#	0x78e6c5*clientConnPool).getClientConn+0x65	/home/prashant/go/src/
#	0x78e62d*clientConnPool).GetClientConn+0x4d	/home/prashant/go/src/
#	0x7a8b84*Transport).RoundTripOpt+0x104		/home/prashant/go/src/
#	0x7a86b9*Transport).RoundTrip+0x39		/home/prashant/go/src/
#	0x6af510	net/http.send+0x460												/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:250
#	0x6aef0a	net/http.(*Client).send+0xfa											/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:174
#	0x6b0518	net/http.(*Client).do+0x278											/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:641
#	0x6b004d	net/http.(*Client).Do+0x9d											/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:509
#	0x6b003a	net/http.(*Client).Get+0x8a											/home/prashant/.gimme/versions/go1.12.7.linux.amd64/src/net/http/client.go:398

I've reduced the size of TCP read/write buffers to trigger the issue more quickly.

The repro includs a flag for controlling steps 2/3. Setting the --num-stuck-calls to 2 or higher will reproduce the issue (the echo calls will fail), while 0 or 1 will cause the test to pass.

@prashantv prashantv changed the title x/net/http2: Blocked Write on single connection causes all calls on the transport to fail x/net/http2: Blocked Write on single connection causes all future calls to block indefinitely Aug 2, 2019
Copy link

@katiehockman katiehockman commented Aug 5, 2019

Copy link
Contributor Author

@prashantv prashantv commented Aug 19, 2019

Any other information I can provide to help speed up any investigation? I've seen some outages in production caused by this issue, and want to help get a fix out.

@ianlancetaylor ianlancetaylor added this to the Go1.14 milestone Aug 19, 2019
@rsc rsc modified the milestones: Go1.14, Backlog Oct 9, 2019
Copy link
Contributor Author

@prashantv prashantv commented Oct 18, 2019

Anything we can help contribute to help with this? Since a single bad backend can deadlock the whole transport, the impact if quite large for us.

Copy link

@bradfitz bradfitz commented Oct 18, 2019

Is this a dup of #32388?

Copy link
Contributor Author

@prashantv prashantv commented Oct 21, 2019

It looks similar to #32388, but I don't see any mention of the *ClientConn.wmu in that bug, and the stacks are different (though that could be because of different versions). The underlying cause of this issue is definitely due to the wmu.

I took the in-review change and applied it to my repro, and it didn't seem to help. Presumably, there's more changes required.

# Ensure the patch is applied:

$ git status
On branch master
Your branch is up to date with 'origin/master'.

Changes not staged for commit:
  (use "git add <file>..." to update what will be committed)
  (use "git checkout -- <file>..." to discard changes in working directory)

        modified:   vendor/
        modified:   vendor/

no changes added to commit (use "git add" and/or "git commit -a")
$ git diff | head
diff --git a/vendor/ b/vendor/
index c0c80d8..70e4f14 100644
--- a/vendor/
+++ b/vendor/
@@ -814,23 +814,25 @@ func (cc *ClientConn) Shutdown(ctx context.Context) error {

 func (cc *ClientConn) sendGoAway() error {
-       defer
-       cc.wmu.Lock()

# Run the test which hangs with and without the fix:
$ go test . -v -timeout 10s -count 1
Listening on :9999
=== RUN   TestSendLargeUnreadPayload
Making request 0
^CFAIL       4.997s

The deadlock is caused by:

  • *clientStream.writeRequestBody holds the *ClientConn.wmu while writing. When writes are stalled, this lock is held indefinitely.
  • *ClientConn.roundTrip holds the * while trying to get the *ClientConn.wmu:
1016   cc.wmu.Lock()
  • *clientConnPool.getClientConn holds the * while checking the idle state for each connection:
 88   for _, cc := range p.conns[addr] {
 89     if st := cc.idleState(); st.canTakeNewRequest {

And getting the idleState requires the *

 717 func (cc *ClientConn) idleState() clientConnIdleState {

So the blocked *ClientConn.wmu causes the * to be held waiting for the wmu on the next call, which then blocks clientConnPool.getClientConn to block as well, blocking the whole transport.

Copy link

@fraenkel fraenkel commented Oct 22, 2019

The mentioned change doesn't fix anything because its incomplete. All of these problems are all the same with no good solution because eventually the write lock will become the issue that backs up to the mu given the relationship that exists between them.

Copy link
Contributor Author

@prashantv prashantv commented Oct 22, 2019

Yeah, I dug through the code and was unable to find any easy way to fix the issue. I think the main issue is that idleState() used by the pool requires *, which is involved in the write path. If the state could be maintained as a cached value, that might help but given the number of conditions, it doesn't seem easy.

In this scenario, it'd be nice to know if the lock was held since we can skip any connection with the lock held (probably safe to assume it's not usable right now). To prototype this idea, I used a huge hack that lets me check whether a lock is held, and return a clientConnIdleState{false, false} if so.

+type fakeMutex struct {
+       mu     sync.Mutex
+       locked int32
+func (m *fakeMutex) Locked() bool {
+       return atomic.LoadInt32(&m.locked) > 0
+func (m *fakeMutex) Lock() {
+       atomic.StoreInt32(&m.locked, 1)
+func (m *fakeMutex) Unlock() {
+       atomic.StoreInt32(&m.locked, 0)
 // Transport is an HTTP/2 Transport.
 // A Transport internally caches connections to servers. It is safe
@@ -210,7 +229,7 @@ type ClientConn struct {
        idleTimeout time.Duration // or 0 for never
        idleTimer   *time.Timer

-       mu              sync.Mutex // guards following
+       mu              fakeMutex  // guards following
        cond            *sync.Cond // hold mu; broadcast on flow/closed changes
        flow            flow       // our conn-level flow control quota (cs.flow is per stream)
        inflow          flow       // peer's conn-level flow control
@@ -715,6 +734,10 @@ type clientConnIdleState struct {

 func (cc *ClientConn) idleState() clientConnIdleState {
+       if {
+               return clientConnIdleState{false, false}
+       }

With this change, my repro above passes everytime. A less hacky of my approach can be done using a channel with size 1 (blocking write to Lock, blocking read to Unlock, non-blocking write to check if it's locked). This would allow the idleState function to return even if the connection is blocked. Thoughts?

Copy link

@fraenkel fraenkel commented Oct 22, 2019

@prashantv While your solution fixes idleState it breaks everything else that relies on the read mutex.
The solution is dictated by the problem we are trying to solve. Almost all the reports are regarding the Write blocking which is difficult to solve.
I can easily add one more mutex to my code to disconnect the read/write mutex during new connections and that might solve a majority of the cases. But I know it won't solve the write issue everyone keeps reporting.

Copy link
Contributor Author

@prashantv prashantv commented Oct 22, 2019

@prashantv While your solution fixes idleState it breaks everything else that relies on the read mutex.

Can you expand on what's broken by this? The * is currently a *sync.Mutex, and my change adds a way for idleState() to check if the mutex is locked or about to get locked before it calls .Lock(). Before accessing data protected by the lock, we still call Lock() which is exactly the same since it still uses a *sync.Mutex to Lock / Unlock.

The only thing that's affected is calls to *ClientConn.idleState, of which there's only one -- which is from *clientConnPool.getClientConn, and that's where we need to avoid grabbing the lock.

In fact, I've run the HTTP2 tests multiple times with my change without issues:

$ go test -v -race -count 1  
ok  83.645s

Pushed a branch with my change if you want to test it:

My change is still a hack, so it doesn't fully solve the problem (it's still possible that *clientConnPool will think that the *ClientConn is safe to lock, but then is beaten to the lock by another goroutine, but it seems to help significantly, without breaking other parts of the library.

Copy link

@fraenkel fraenkel commented Oct 23, 2019

Here is a simple issue that you have:
if 2 routines both perform a Lock(), locked = 1 and one blocks on the mutex. When Unlock() is invoked, the second routine will execute but locked = 0.

Copy link
Contributor Author

@prashantv prashantv commented Oct 23, 2019

if 2 routines both perform a Lock(), locked = 1 and one blocks on the mutex. When Unlock() is invoked, the second routine will execute but locked = 0.

My mistake, I meant to set locked = 1 while holding the lock. Once that's flipped, apart from not fixing the issue 100%, are there other things that are broken? You mentioned "everything that relies on read mutex", not exactly sure what you meant by "read mutex".

I want to understand if the problem being solved (Making idleState() not block trying to get * is the right problem to focus on. The above is still just an example solution, but it suffers from a race since the check for Locked() and Lock() are not atomic. However that can be solved using a channel based lock:

This uses a channel to implement a lock that supports a TryLock method. It's likely a little slower, but I didn't see any noticeable difference when I ran the benchmarks.

Copy link

@fraenkel fraenkel commented Oct 23, 2019

And eventually the channel can be blocked. You can't just short circuit idleStateLocked, it actually computes the answer. Returning an incorrect value will break other guarantees.
As I already stated, my patch attempted to break the read/write mutex and did so up until I hit the one place where control needs to transfer sequentially from the read lock to the write lock. I haven't determined a good way to accomplish this once the write side is blocked.
Any solution must fix the write blocking issue which then allows us to disentangle the read/write mutex overlaps.

Copy link
Contributor Author

@prashantv prashantv commented Oct 23, 2019

break other guraantees

I assume the guarantee you mean is that we'll end up with more connections than required, since my idleState() implementation assumes that a connection cannot be used if the lock is held. This means that any call started while there's any pending operation on a connection will end up triggering a new connection.

Looking at the change linked to the other issue, I'm not sure if there's a clear path to fixing the underlying locking issues. I can try to investigate that approach, but in the meantime, we're stuck with deadlocks. Is there a short-term workaround? E.g., write deadlines?

A workaround (even if it triggers more connections than necessary) would be preferable to a deadlock in production.

Copy link

@fraenkel fraenkel commented Oct 25, 2019

The only solution I can think of right now is to build your own client pool which tracks outstanding requests per client. Don't share the transport.
You might actually be able to build a Transport that does pooling instead.

Copy link

@jaricftw jaricftw commented Jun 3, 2020

Alternatively, how do we like the idea of per-backend/address lock, instead of a shared lock for the entire client connection pool? A proof-of-concept:, which ensures a single stuck backend won't block requests to other backends.

Copy link

@fraenkel fraenkel commented Jun 3, 2020

@jaricftw That doesn't fix the actual issue. While there are multiple logical client connections, we only have one physical connection. The data protected is about all clients not individual ones.

Please see #32388. I submitted 2 patches which should resolve this issue.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
7 participants