crypto/tls: Conn.Close doesn't unblock stuck conn.Read #23518

dingdexin · 2018-01-23T11:00:30Z

Please answer these questions before submitting your issue. Thanks!

What did you do?

I write a tcp server using "crypto/tls", it listen on a port. just like this:

for {
conn, err := netListen.Accept()
if nil != err {
continue
}
go handleConnection(conn)
}

In handleConnection, a separate go routine recvFromTcp is created for TCP reading operation, and timeout judgement is made in the main goroutine. When 30 seconds can't get the TCP client's message, it will close the connection.

I use telnet to connect the server, and after 30 seconds the server-side determines the timeout, and the recvFromTcp group is stuck in Read when the Conn's Close () is called. Two go routine can't quit

What did you expect to see?

tcp server using "crypto/tls" , listen on a port ,when I run telnet on wondows, Server-side timeout judgment, one goroutine call Close() of net.Conn, conn.Read in another goroutine will return err immediately。

What did you see instead?

when one goroutine call Close() of net.Conn,conn.Read in another goroutine is blocked in Read。

System details

call Close in one goroutine:

#	0x43fe1c	sync.runtime_SemacquireMutex+0x3c	/usr/local/go/src/runtime/sema.go:71
#	0x472a7d	sync.(*Mutex).Lock+0xed			/usr/local/go/src/sync/mutex.go:134
#	0x60bc5b	crypto/tls.(*Conn).Close+0x6b		/usr/local/go/src/crypto/tls/conn.go:1208
#	0x7e4df9	main.handleConnection.func1+0x59	 
#	0x7d981d	main.handleConnection+0x81d

another goroutine is blocked in Read of net.Conn:

#	0x429456	internal/poll.runtime_pollWait+0x56			/usr/local/go/src/runtime/netpoll.go:173
#	0x49253d	internal/poll.(*pollDesc).wait+0xad			/usr/local/go/src/internal/poll/fd_poll_runtime.go:85
#	0x4925bc	internal/poll.(*pollDesc).waitRead+0x3c			/usr/local/go/src/internal/poll/fd_poll_runtime.go:90
#	0x493359	internal/poll.(*FD).Read+0x189				/usr/local/go/src/internal/poll/fd_unix.go:125
#	0x5afc51	net.(*netFD).Read+0x51					/usr/local/go/src/net/fd_unix.go:202
#	0x5c21ec	net.(*conn).Read+0x6c					/usr/local/go/src/net/net.go:176
#	0x6077b4	crypto/tls.(*block).readFromUntil+0x94			/usr/local/go/src/crypto/tls/conn.go:488
#	0x607d1f	crypto/tls.(*Conn).readRecord+0xdf			/usr/local/go/src/crypto/tls/conn.go:590
#	0x60a68c	crypto/tls.(*Conn).readHandshake+0x8c			/usr/local/go/src/crypto/tls/conn.go:943
#	0x61a31d	crypto/tls.(*serverHandshakeState).readClientHello+0x4d	/usr/local/go/src/crypto/tls/handshake_server.go:116
#	0x619e5d	crypto/tls.(*Conn).serverHandshake+0xad			/usr/local/go/src/crypto/tls/handshake_server.go:48
#	0x60c1ee	crypto/tls.(*Conn).Handshake+0x27e			/usr/local/go/src/crypto/tls/conn.go:1309
#	0x60b7b2	crypto/tls.(*Conn).Read+0x52				/usr/local/go/src/crypto/tls/conn.go:1117
#	0x7d7e0c	main.recvFromTcp+0x48c

go version go1.9 linux/amd64
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/teld/gocode:/home/teld/gocode/fes/simctrl:/home/teld/gocode/fes/setgetctrl:/home/teld/gocode/fes/prot_tcp_protobuf:/home/teld/gocode/fes/prot_tcp_protobuf_monitor"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build436166746=/tmp/go-build -gno-record-gcc-switches"
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"
GOROOT/bin/go version: go version go1.9 linux/amd64
GOROOT/bin/go tool compile -V: compile version go1.9
uname -sr: Linux 3.10.0-514.26.2.el7.x86_64
/lib64/libc.so.6: GNU C Library (GNU libc) stable release version 2.17, by Roland McGrath et al.
gdb --version: GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-94.el7

The text was updated successfully, but these errors were encountered:

dingdexin · 2018-01-24T03:26:19Z

my tls server go code like this:

package main

import (
"crypto/tls"
"flag"
"fmt"
"net"
"net/http"
_ "net/http/pprof"
"os"
"runtime"
"runtime/pprof"
"strconv"
"sync/atomic"
"time"
)

var clientNum int32 = 0
var cpuprofile = flag.String("cpuprofile", "", "write cpu profile to file")

func main() {
cert, _ := tls.LoadX509KeyPair("server.pem", "server.key")

config := &tls.Config{Certificates: []tls.Certificate{cert}}
netListen, _ := tls.Listen("tcp", ":"+strconv.Itoa(3001), config)
if *cpuprofile != "" {
	f, err := os.Create(*cpuprofile)
	if nil != err {
		Log(err)
	}
	pprof.StartCPUProfile(f)

}
go func() {
	http.ListenAndServe(":3000", nil)
}()
defer pprof.StopCPUProfile()

go monitor()
Log("Waiting for clients")

for {
	conn, err := netListen.Accept()
	if err != nil {
		continue
	}

	Log(conn.RemoteAddr().String(), " tcp connect success", clientNum)
	go handleConnection(conn)
	atomic.AddInt32(&clientNum, 1)

}

}

func handleConnection(conn net.Conn) {

go func() { // This is an analog active shutdown
	time.Sleep(5 * time.Second)
	Log("before close")
	conn.Close() //blocked here
	Log("after close")
}()
buffer := make([]byte, 1024)
for {
	_, err := conn.Read(buffer) //blocked here
	if err != nil {
		Log(conn.RemoteAddr().String(), " connection error: ", err)
		return
	}
	fmt.Println("recv ", buffer)

}

}

func Log(v ...interface{}) {
fmt.Println(v...)
}

func CheckError(err error) {
if err != nil {
fmt.Fprintf(os.Stderr, "Fatal error: %s", err.Error())
os.Exit(1)
}
}

func monitor() {
for {

	Log("go routine num:", runtime.NumGoroutine())

	time.Sleep(time.Second * 5)
}

}
I recorded the screen, see the appendix，thank you!
kk 2018-01-24 11-18-16.zip

dingdexin · 2018-01-24T03:27:28Z

If the telnet client is actively closed, there is no problem

minaevmike · 2018-01-25T15:31:19Z

Hi. I think the problem is some think like that:

you are trying to connet to tls server via telnet(telnet doesn't support tls)
i am not common with tls package. But seem that server waiting for tls handshake, but there is no any data for it.
i don't know is it expected behavior or not. There are some words about using Write() and Close() concurently https://github.com/golang/go/blob/master/src/crypto/tls/conn.go#L1219 . May be this case must be decribed too?
also you can use conn.SetReadDeadline(time.Now().Add(5 *time.Second))

seems it's a deadlock:

1 @ 0x4575ed 0x4576ce 0x469f48 0x469cbd 0x4a6eec 0x684e2e 0x858fae 0x4892e1
#	0x469cbc	sync.runtime_SemacquireMutex+0x3c	/usr/local/go/src/runtime/sema.go:71
#	0x4a6eeb	sync.(*Mutex).Lock+0x14b		/usr/local/go/src/sync/mutex.go:134
#	0x684e2d	crypto/tls.(*Conn).Close+0x9d		/usr/local/go/src/crypto/tls/conn.go:1208
#	0x858fad	main.handleConnection.func1+0xad	a.go:62

1 @ 0x4575ed 0x45262a 0x451bee 0x54ad4b 0x54adfb 0x54c06d 0x600636 0x619a68 0x63ff9a 0x67e45d 0x67ed82 0x682b7d 0x69da83 0x69d323 0x6857a5 0x6845b5 0x858b54 0x4892e1
#	0x451bed	internal/poll.runtime_pollWait+0x5d			/usr/local/go/src/runtime/netpoll.go:173
#	0x54ad4a	internal/poll.(*pollDesc).wait+0xfa			/usr/local/go/src/internal/poll/fd_poll_runtime.go:85
#	0x54adfa	internal/poll.(*pollDesc).waitRead+0x4a			/usr/local/go/src/internal/poll/fd_poll_runtime.go:90
#	0x54c06c	internal/poll.(*FD).Read+0x23c				/usr/local/go/src/internal/poll/fd_unix.go:125
#	0x600635	net.(*netFD).Read+0x65					/usr/local/go/src/net/fd_unix.go:202
#	0x619a67	net.(*conn).Read+0x87					/usr/local/go/src/net/net.go:176
#	0x63ff99	net.(*TCPConn).Read+0x69				<autogenerated>:1
#	0x67e45c	crypto/tls.(*block).readFromUntil+0x11c			/usr/local/go/src/crypto/tls/conn.go:488
#	0x67ed81	crypto/tls.(*Conn).readRecord+0x141			/usr/local/go/src/crypto/tls/conn.go:590
#	0x682b7c	crypto/tls.(*Conn).readHandshake+0xfc			/usr/local/go/src/crypto/tls/conn.go:943
#	0x69da82	crypto/tls.(*serverHandshakeState).readClientHello+0x72	/usr/local/go/src/crypto/tls/handshake_server.go:116
#	0x69d322	crypto/tls.(*Conn).serverHandshake+0x122		/usr/local/go/src/crypto/tls/handshake_server.go:48
#	0x6857a4	crypto/tls.(*Conn).Handshake+0x4e4			/usr/local/go/src/crypto/tls/conn.go:1309
#	0x6845b4	crypto/tls.(*Conn).Read+0x74				/usr/local/go/src/crypto/tls/conn.go:1117

While we are making handshake handshakeMutex is locked. And in close method we are trying lock it again to check handshakeComplete. May be working with handshakeComplete variable can be atomic?

gopherbot · 2018-01-26T09:33:43Z

Change https://golang.org/cl/90155 mentions this issue: crypto/tls: fix deadlock when Read and Close called concurrently.

The existing implementation of TLS connection has a deadlock. It occurs when client connects to TLS server and doesn't send data for handshake, so server calls Close on this connection. This is because server reads data under locked mutex, while Close method tries to lock the same mutex. Fixes golang#23518 Change-Id: I4fb0a2a770f3d911036bfd9a7da7cc41c1b27e19 Reviewed-on: https://go-review.googlesource.com/90155 Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org> TryBot-Result: Gobot Gobot <gobot@golang.org> Reviewed-by: Filippo Valsorda <filippo@golang.org>

bradfitz changed the title ~~Non TLS client connect TLS server,and server call net.Conn Close(), then crypto/tls.(*Conn).Read blocked~~ crypto/tls: Conn.Close doesn't unblock stuck conn.Read Jan 23, 2018

bradfitz added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Jan 23, 2018

bradfitz added this to the Go1.11 milestone Jan 23, 2018

gopherbot closed this as completed in e5b1340 Jul 25, 2018

golang locked and limited conversation to collaborators Jul 25, 2019

gopherbot added the FrozenDueToAge label Jul 25, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

crypto/tls: Conn.Close doesn't unblock stuck conn.Read #23518

crypto/tls: Conn.Close doesn't unblock stuck conn.Read #23518

dingdexin commented Jan 23, 2018 •

edited by bradfitz

dingdexin commented Jan 24, 2018 •

edited

dingdexin commented Jan 24, 2018

minaevmike commented Jan 25, 2018 •

edited

gopherbot commented Jan 26, 2018

Navigation Menu

crypto/tls: Conn.Close doesn't unblock stuck conn.Read #23518

crypto/tls: Conn.Close doesn't unblock stuck conn.Read #23518

Comments

dingdexin commented Jan 23, 2018 • edited by bradfitz

What did you do?

What did you expect to see?

What did you see instead?

System details

dingdexin commented Jan 24, 2018 • edited

dingdexin commented Jan 24, 2018

minaevmike commented Jan 25, 2018 • edited

gopherbot commented Jan 26, 2018

dingdexin commented Jan 23, 2018 •

edited by bradfitz

dingdexin commented Jan 24, 2018 •

edited

minaevmike commented Jan 25, 2018 •

edited