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

[dingdexin]

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

[dingdexin]

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]

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

[minaevmike]

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]

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