crypto/tls: handleRenegotiation blocking forever

[JamieAP]

Please answer these questions before submitting your issue. Thanks!

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

1.9.2 on alpine 3.7

Does this issue reproduce with the latest release?

Yes, on 1.10-rc and 1.9.1

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

/ # go env
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/root/go"
GORACE=""
GOROOT="/usr/lib/go"
GOTOOLDIR="/usr/lib/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build855250625=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

Attempt an HTTP/1.1 request over a TLS 1.2 connection using mutual auth (client & server certs).

What did you expect to see?

The handleshake to be successful and request to complete.

What did you see instead?

crypto/tls.(*Conn).handleRenegotiation seems to get stuck:

goroutine 89 [IO wait, 8 minutes]:
internal/poll.runtime_pollWait(0x7f8d90cccbb0, 0x72, 0x0)
	/usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc4201dd798, 0x72, 0xffffffffffffff00, 0xad4960, 0xad03b0)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc4201dd798, 0xc420246000, 0x2000, 0x2000)
	/usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc4201dd780, 0xc420246000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
	/usr/local/go/src/internal/poll/fd_unix.go:126 +0x18a
net.(*netFD).Read(0xc4201dd780, 0xc420246000, 0x2000, 0x2000, 0x7f8d90ccecb8, 0x4565a0, 0x7f8d90d28d90)
	/usr/local/go/src/net/fd_unix.go:202 +0x52
net.(*conn).Read(0xc420194190, 0xc420246000, 0x2000, 0x2000, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/net.go:176 +0x6d
crypto/tls.(*block).readFromUntil(0xc42014ad80, 0x7f8d90cd2b00, 0xc420194190, 0x5, 0xc420194190, 0x30)
	/usr/local/go/src/crypto/tls/conn.go:488 +0x95
crypto/tls.(*Conn).readRecord(0xc420030e00, 0x14, 0x303, 0xc4201dd798)
	/usr/local/go/src/crypto/tls/conn.go:590 +0xe0
crypto/tls.(*clientHandshakeState).readFinished(0xc420273918, 0xc420030ef5, 0xc, 0xc, 0x0, 0x0)
	/usr/local/go/src/crypto/tls/handshake_client.go:584 +0x53
crypto/tls.(*Conn).clientHandshake(0xc420030e00, 0x8ba610, 0xc420030e14)
	/usr/local/go/src/crypto/tls/handshake_client.go:244 +0x10aa
crypto/tls.(*Conn).handleRenegotiation(0xc420030e00, 0x0, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:1108 +0xf4
crypto/tls.(*Conn).Read(0xc420030e00, 0xc420221000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/local/go/src/crypto/tls/conn.go:1141 +0x149
net/http.(*persistConn).Read(0xc420090fc0, 0xc420221000, 0x1000, 0x1000, 0x0, 0x3, 0xc42054ab68)
	/usr/local/go/src/net/http/transport.go:1391 +0x140
bufio.(*Reader).fill(0xc4201ff140)
	/usr/local/go/src/bufio/bufio.go:97 +0x11a
bufio.(*Reader).Peek(0xc4201ff140, 0x1, 0xc4201a20c0, 0xc420028c80, 0xc4201968f0, 0xc420028bf0, 0x10)
	/usr/local/go/src/bufio/bufio.go:129 +0x3a
net/http.(*persistConn).readLoop(0xc420090fc0)
	/usr/local/go/src/net/http/transport.go:1539 +0x185
created by net/http.(*Transport).dialConn
	/usr/local/go/src/net/http/transport.go:1186 +0xa2e

My transport is configured as such: https://gist.github.com/JamieAP/24325d34d4d6cafbef6ffefd835a1063

Curl doesn't seem to have any issues with the TLS reneg: https://gist.github.com/JamieAP/deb70ba1bb28b6acaad77c4077b64bba

What's more, the issue with underlying connection seems to also prevent the http.Transport acting on its timeout:

goroutine 77 [semacquire, 3 minutes]:
sync.runtime_SemacquireMutex(0xc4201b0a98, 0x0)
	/usr/local/go/src/runtime/sema.go:71 +0x3d
sync.(*Mutex).Lock(0xc4201b0a94)
	/usr/local/go/src/sync/mutex.go:134 +0x108
crypto/tls.(*Conn).Close(0xc4201b0a80, 0xc420572df0, 0xc420572df0)
	/usr/local/go/src/crypto/tls/conn.go:1230 +0x6c
net/http.(*persistConn).closeLocked(0xc420216120, 0x8d4a80, 0xc42001ca30)
	/usr/local/go/src/net/http/transport.go:2128 +0xb4
net/http.(*persistConn).cancelRequest(0xc420216120, 0x8d4a80, 0xc42001ca30)
	/usr/local/go/src/net/http/transport.go:1501 +0xa6
net/http.(*persistConn).(net/http.cancelRequest)-fm(0x8d4a80, 0xc42001ca30)
	/usr/local/go/src/net/http/transport.go:1954 +0x3e
net/http.(*Transport).cancelRequest(0xc42021c0f0, 0xc4202d8700, 0x8d4a80, 0xc42001ca30)
	/usr/local/go/src/net/http/transport.go:569 +0xd1
net/http.(*Transport).CancelRequest(0xc42021c0f0, 0xc4202d8700)
	/usr/local/go/src/net/http/transport.go:559 +0x41
net/http.(*persistConn).roundTrip(0xc420216120, 0xc420162960, 0x0, 0x0, 0x0)
	/usr/local/go/src/net/http/transport.go:2073 +0x84c
net/http.(*Transport).RoundTrip(0xc42021c0f0, 0xc4202d8700, 0xc42021c0f0, 0xbe90479e1251fedc, 0x323300e6af)
	/usr/local/go/src/net/http/transport.go:422 +0x8cb
net/http.send(0xc4202d8600, 0x8d4f60, 0xc42021c0f0, 0xbe90479e1251fedc, 0x323300e6af, 0xafff60, 0xc4201fa028, 0xbe90479e1251fedc, 0xc420573540, 0x1)
	/usr/local/go/src/net/http/client.go:252 +0x185
net/http.(*Client).send(0xc420162690, 0xc4202d8600, 0xbe90479e1251fedc, 0x323300e6af, 0xafff60, 0xc4201fa028, 0x0, 0x1, 0xc4205735e0)
	/usr/local/go/src/net/http/client.go:176 +0xfa
net/http.(*Client).Do(0xc420162690, 0xc4202d8600, 0xc420573860, 0xc, 0xc)
	/usr/local/go/src/net/http/client.go:615 +0x28d
github.com/utilitywarehouse/xx-xx-auth-proxy/internal/client.xxClient.MakeRequest(0xc420162690, 0xc42002209c, 0x17, 0xc420024354, 0x4, 0xc42002431d, 0x2, 0xc42002234d, 0x7, 0xc42002261f, ...)
	/go/src/github.com/utilitywarehouse/xx-xx-auth-proxy/internal/client/client.go:111 +0x618
github.com/utilitywarehouse/xx-xx-auth-proxy/internal/handler.handleAsyncRequest.func1(0x8d8f80, 0xc4204a8000, 0xc4202d8500)
	/go/src/github.com/utilitywarehouse/xx-xx-auth-proxy/internal/handler/handler.go:100 +0x254
net/http.HandlerFunc.ServeHTTP(0xc420174bf0, 0x8d8f80, 0xc4204a8000, 0xc4202d8500)
	/usr/local/go/src/net/http/server.go:1947 +0x44
github.com/gorilla/mux.(*Router).ServeHTTP(0xc4201be690, 0x8d8f80, 0xc4204a8000, 0xc4202d8500)
	/go/src/github.com/gorilla/mux/mux.go:159 +0xed
net/http.serverHandler.ServeHTTP(0xc4201ac340, 0x8d8f80, 0xc4204a8000, 0xc4202d8100)
	/usr/local/go/src/net/http/server.go:2694 +0xbc
net/http.(*conn).serve(0xc4202d4000, 0x8d9540, 0xc420234040)
	/usr/local/go/src/net/http/server.go:1830 +0x648
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2795 +0x27b

[titanous]

Can you provide an example server that triggers this issue?

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)