crypto/tls: tls deadlock at handshake stage during my concurrent tests

[leslie-qiwa]

Please answer these questions before submitting your issue. Thanks!

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

go version go1.10.3 linux/amd64

Does this issue reproduce with the latest release?

yes.

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/go"
GORACE=""
GOROOT="/usr/local/go"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
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 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build222663646=/tmp/go-build -gno-record-gcc-switches"

What did you do?

We have a https server, and https clients, which uses http.Client::Get to do standard http rest.

What did you expect to see?

Normal result.

What did you see instead?

We saw 1 deadlock whose trace is similar at server side. I noticed https://go-review.googlesource.com/c/go/+/90155, which seems like related. So wonder to know if it can solve my issues, or mine are new ones.

part of stack traces:

net/http.(*Transport).getConn(0xc4200ed2c0, 0xc4209cb140, 0x0, 0xc420e96990, 0x5, 0xc420d22621, 0xf, 0x0, 0x0, 0x0)
/usr/local/go/src/net/http/transport.go:962 +0x558
net/http.(*Transport).RoundTrip(0xc4200ed2c0, 0xc420af7000, 0xc4200ed2c0, 0x0, 0x0)
/usr/local/go/src/net/http/transport.go:409 +0x632
net/http.send(0xc420af7000, 0x11d6d80, 0xc4200ed2c0, 0x0, 0x0, 0x0, 0xc420646f60, 0xf8, 0xc4212d4be8, 0x1)
/usr/local/go/src/net/http/client.go:252 +0x185
net/http.(*Client).send(0xc4203aab10, 0xc420af7000, 0x0, 0x0, 0x0, 0xc420646f60, 0x0, 0x1, 0x412a78)
/usr/local/go/src/net/http/client.go:176 +0xfa
net/http.(*Client).Do(0xc4203aab10, 0xc420af7000, 0xc420e96990, 0x27, 0x0)
/usr/local/go/src/net/http/client.go:615 +0x28d
net/http.(*Client).Get(0xc4203aab10, 0xc420e96990, 0x27, 0x2, 0x2, 0xc420e96990)
/usr/local/go/src/net/http/client.go:396 +0x9d

goroutine 75459 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7fba8b5a6440, 0x72, 0xc4217c5868)
/usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc4203ce318, 0x72, 0xffffffffffffff00, 0x11d8460, 0x1bdf0a0)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc4203ce318, 0xc420dbf800, 0x400, 0x400)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc4203ce300, 0xc420dbf800, 0x400, 0x400, 0x0, 0x0, 0x0)
/usr/local/go/src/internal/poll/fd_unix.go:157 +0x17d
net.(*netFD).Read(0xc4203ce300, 0xc420dbf800, 0x400, 0x400, 0xd, 0xd, 0xc422188c0d)
/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc4232ceaa0, 0xc420dbf800, 0x400, 0x400, 0x0, 0x0, 0x0)
/usr/local/go/src/net/net.go:176 +0x6a
crypto/tls.(*block).readFromUntil(0xc420947e00, 0x7fba8b62e000, 0xc4232ceaa0, 0x5, 0xc4232ceaa0, 0xc4217c5a40)
/usr/local/go/src/crypto/tls/conn.go:493 +0x96
crypto/tls.(*Conn).readRecord(0xc420663c00, 0x214, 0x0, 0x0)
/usr/local/go/src/crypto/tls/conn.go:595 +0xe0
crypto/tls.(*clientHandshakeState).readFinished(0xc421abfe70, 0xc420663cf5, 0xc, 0xc, 0x0, 0x0)
/usr/local/go/src/crypto/tls/handshake_client.go:634 +0x53
crypto/tls.(*clientHandshakeState).handshake(0xc4217c5e70, 0xc420596dc0, 0x0)
/usr/local/go/src/crypto/tls/handshake_client.go:263 +0x590
crypto/tls.(*Conn).clientHandshake(0xc420663c00, 0x1136db0, 0xc420663d20)
/usr/local/go/src/crypto/tls/handshake_client.go:168 +0x38c
crypto/tls.(*Conn).Handshake(0xc420663c00, 0x0, 0x0)
/usr/local/go/src/crypto/tls/conn.go:1329 +0x185
net/http.(*persistConn).addTLS.func2(0x0, 0xc420663c00, 0x0, 0xc420b094a0)
/usr/local/go/src/net/http/transport.go:1068 +0x42
created by net/http.(*persistConn).addTLS
/usr/local/go/src/net/http/transport.go:1064 +0x19f

goroutine 75630 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7fba8b60e3b8, 0x72, 0xc4218914d0)
/usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc420ac0098, 0x72, 0xffffffffffffff00, 0x11d8460, 0x1bdf0a0)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc420ac0098, 0xc423cf9400, 0x400, 0x400)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc420ac0080, 0xc423cf9400, 0x400, 0x400, 0x0, 0x0, 0x0)
/usr/local/go/src/internal/poll/fd_unix.go:157 +0x17d
net.(*netFD).Read(0xc420ac0080, 0xc423cf9400, 0x400, 0x400, 0x423e77b792e2712b, 0x3c020140860d0000, 0x403050100100401)
/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc4226cda58, 0xc423cf9400, 0x400, 0x400, 0x0, 0x0, 0x0)
/usr/local/go/src/net/net.go:176 +0x6a
crypto/tls.(*block).readFromUntil(0xc4235f28d0, 0x7fba8b62e000, 0xc4226cda58, 0x5, 0xc4226cda58, 0x474200)
/usr/local/go/src/crypto/tls/conn.go:493 +0x96
crypto/tls.(*Conn).readRecord(0xc423a28700, 0xc423cf9c16, 0x29b, 0x400)
/usr/local/go/src/crypto/tls/conn.go:595 +0xe0
crypto/tls.(*Conn).readHandshake(0xc423a28700, 0x29b, 0x0, 0x0, 0x4)
/usr/local/go/src/crypto/tls/conn.go:965 +0x8d
crypto/tls.(*serverHandshakeState).doFullHandshake(0xc421891c50, 0xc420ea7c00, 0x0)
/usr/local/go/src/crypto/tls/handshake_server.go:450 +0x548
crypto/tls.(*Conn).serverHandshake(0xc423a28700, 0x1136db0, 0xc423a28820)
/usr/local/go/src/crypto/tls/handshake_server.go:85 +0x2f7
crypto/tls.(*Conn).Handshake(0xc423a28700, 0x0, 0x0)
/usr/local/go/src/crypto/tls/conn.go:1331 +0x24e
net/http.(*conn).serve(0xc4208fd860, 0x11e1d40, 0xc4235f2870)
/usr/local/go/src/net/http/server.go:1742 +0x18f
created by net/http.(*Server).Serve
/usr/local/go/src/net/http/server.go:2795 +0x27b

goroutine 75631 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7fba8b609910, 0x72, 0xc423237728)
/usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc420ac0118, 0x72, 0xffffffffffffff00, 0x11d8460, 0x1bdf0a0)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc420ac0118, 0xc420dffc00, 0x400, 0x400)
/usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc420ac0100, 0xc420dffc00, 0x400, 0x400, 0x0, 0x0, 0x0)
/usr/local/go/src/internal/poll/fd_unix.go:157 +0x17d
net.(*netFD).Read(0xc420ac0100, 0xc420dffc00, 0x400, 0x400, 0xc420dffc00, 0x0, 0x400)
/usr/local/go/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc4226cda60, 0xc420dffc00, 0x400, 0x400, 0x0, 0x0, 0x0)
/usr/local/go/src/net/net.go:176 +0x6a
crypto/tls.(*block).readFromUntil(0xc420a6e0c0, 0x7fba8b62e000, 0xc4226cda60, 0x5, 0xc4226cda60, 0x1)
/usr/local/go/src/crypto/tls/conn.go:493 +0x96
crypto/tls.(*Conn).readRecord(0xc423a28a80, 0xc816b83b67535216, 0x1b64fd2efb275d6b, 0x80aee4ac23607b07)
/usr/local/go/src/crypto/tls/conn.go:595 +0xe0
crypto/tls.(*Conn).readHandshake(0xc423a28a80, 0x0, 0xb, 0xc42284c330, 0x0)
/usr/local/go/src/crypto/tls/conn.go:965 +0x8d
crypto/tls.(*serverHandshakeState).readClientHello(0xc423237c50, 0xc423237c40, 0x5, 0x3)
/usr/local/go/src/crypto/tls/handshake_server.go:116 +0x4e
crypto/tls.(*Conn).serverHandshake(0xc423a28a80, 0x1136db0, 0xc423a28ba0)
/usr/local/go/src/crypto/tls/handshake_server.go:48 +0xae
crypto/tls.(*Conn).Handshake(0xc423a28a80, 0x0, 0x0)
/usr/local/go/src/crypto/tls/conn.go:1331 +0x24e
net/http.(*conn).serve(0xc4208fd900, 0x11e1d40, 0xc420a6e090)
/usr/local/go/src/net/http/server.go:1742 +0x18f
created by net/http.(*Server).Serve
/usr/local/go/src/net/http/server.go:2795 +0x27b

goroutine 70522 [chan receive, 9 minutes]:
net/http.(*persistConn).addTLS(0xc42076b680, 0xc420d22621, 0x9, 0x0, 0xc420d2262b, 0x5)
/usr/local/go/src/net/http/transport.go:1074 +0x1c8
net/http.(*Transport).dialConn(0xc4200ed2c0, 0x11e1cc0, 0xc420036178, 0x0, 0xc420e96990, 0x5, 0xc420d22621, 0xf, 0x10dfd96, 0xf, ...)
/usr/local/go/src/net/http/transport.go:1153 +0x14c3
net/http.(*Transport).getConn.func4(0xc4200ed2c0, 0x11e1cc0, 0xc420036178, 0xc4209cb170, 0xc4203faae0)
/usr/local/go/src/net/http/transport.go:957 +0x78
created by net/http.(*Transport).getConn
/usr/local/go/src/net/http/transport.go:956 +0x363

*** Test killed with quit: ran too long (10m0s).

[ianlancetaylor]

Can you try your test with the Go 1.11 release candidate?

[leslie-qiwa]

BTW, thanks for your attention, and quick reply!!! Just download 1.11rc1 source codes, complied and installed. Seems like still able to reproduce.

[leslie-qiwa]

Seems like one deadlock is in our side. I've updated description. So far, I haven't reproduce this deadlock using 1.11rc1. Will continue try and share update.

[leslie-qiwa]

Just update description, and remove some stack traces. From netstat result, Seems like for some reason, server established two connections with one client. This is why in stack trace, handshake_server shows two read: readClientHello and doFullHandshake . Guess server sends back different result to client through the two connections, and client is confused, then read at unexpected places. Just wild guess.

tcp        0    563 127.0.0.1:56614         127.0.0.1:10000         ESTABLISHED 4244/my.test
tcp6       0      0 :::10000                :::*                    LISTEN      4244/my.test
tcp6       0      0 127.0.0.1:10000         127.0.0.1:56614         ESTABLISHED 4244/my.test
tcp6       0    668 127.0.0.1:10000         127.0.0.1:56614         ESTABLISHED 4244/my.test

[leslie-qiwa]

Seems like this is OS related issue. Closed for now.