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

Jump to bottom

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

Closed
leslie-qiwa opened this issue Aug 21, 2018 · 5 comments
Closed

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

leslie-qiwa opened this issue Aug 21, 2018 · 5 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Milestone
Go1.12

Comments

@leslie-qiwa
Copy link

leslie-qiwa commented Aug 21, 2018 •
edited

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
Copy link
Contributor

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

@ianlancetaylor ianlancetaylor changed the title tls deadlock at handshake stage during my concurrent tests crypto/tls: tls deadlock at handshake stage during my concurrent tests Aug 22, 2018
@ianlancetaylor ianlancetaylor added WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Aug 22, 2018
@ianlancetaylor ianlancetaylor added this to the Go1.12 milestone Aug 22, 2018
@leslie-qiwa
Copy link
Author

leslie-qiwa commented Aug 22, 2018 •
edited

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
Copy link
Author

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
Copy link
Author

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
Copy link
Author

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

@golang golang locked and limited conversation to collaborators Aug 29, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
Go1.12
Development

No branches or pull requests
3 participants
@ianlancetaylor @gopherbot @leslie-qiwa