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

crypto/tls: handshake cause goroutine blocking In some cases? #36255

Closed
aaaaa123ad opened this issue Dec 23, 2019 · 4 comments
Closed

crypto/tls: handshake cause goroutine blocking In some cases? #36255

aaaaa123ad opened this issue Dec 23, 2019 · 4 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

Comments

@aaaaa123ad
Copy link

aaaaa123ad commented Dec 23, 2019

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

$ go version
go version go1.13.3 linux/amd64

Does this issue reproduce with the latest release?

yes

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

go env Output
$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/root/go"
GOPRIVATE=""
GOPROXY="direct"
GOROOT="/usr/lib/golang"
GOSUMDB="off"
GOTMPDIR=""
GOTOOLDIR="/usr/lib/golang/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
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-build531877332=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I make a https server using golang。Server waited a long time in tls handshake phase,becouse
many clients didn't send hello to server。One day later, my server goroutine count Increase to a huge number(hundreds thousand level)。

I try different frameworks or library(net/http,fasthttp,gin) and set the readtimeout,but didn't solve this problem.

goroutine 627 [IO wait, 36 minutes]:
internal/poll.runtime_pollWait(0x7f6d0fc44728, 0x72, 0xffffffffffffffff)
C:/Go1.13/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc000223898, 0x72, 0x200, 0x205, 0xffffffffffffffff)
C:/Go1.13/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
C:/Go1.13/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc000223880, 0xc000334480, 0x205, 0x205, 0x0, 0x0, 0x0)
C:/Go1.13/src/internal/poll/fd_unix.go:169 +0x1cf
net.(*netFD).Read(0xc000223880, 0xc000334480, 0x205, 0x205, 0x203000, 0x42e7c1, 0xb98f38)
C:/Go1.13/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc00000e898, 0xc000334480, 0x205, 0x205, 0x0, 0x0, 0x0)
C:/Go1.13/src/net/net.go:184 +0x68
crypto/tls.(*atLeastReader).Read(0xc0002a9ce0, 0xc000334480, 0x205, 0x205, 0xc000334480, 0x0, 0xc000551450)
C:/Go1.13/src/crypto/tls/conn.go:782 +0x60
bytes.(*Buffer).ReadFrom(0xc000508958, 0xc60fc0, 0xc0002a9ce0, 0x40a1d5, 0xab40a0, 0xb3daa0)
C:/Go1.13/src/bytes/buffer.go:204 +0xb4
crypto/tls.(*Conn).readFromUntil(0xc000508700, 0xc61e80, 0xc00000e898, 0x5, 0xc00000e898, 0x0)
C:/Go1.13/src/crypto/tls/conn.go:804 +0xec
crypto/tls.(*Conn).readRecordOrCCS(0xc000508700, 0x100, 0xc61180, 0xc00001e050)
C:/Go1.13/src/crypto/tls/conn.go:609 +0x17c
crypto/tls.(*Conn).readRecord(...)
C:/Go1.13/src/crypto/tls/conn.go:577
crypto/tls.(*Conn).readHandshake(0xc000508700, 0x0, 0x0, 0xc61180, 0xc00001e050)
C:/Go1.13/src/crypto/tls/conn.go:995 +0x6d
crypto/tls.(*Conn).readClientHello(0xc000508700, 0x0, 0xc61180, 0xc00001e050)
C:/Go1.13/src/crypto/tls/handshake_server.go:135 +0x40
crypto/tls.(*Conn).serverHandshake(0xc000508700, 0x0, 0x0)
C:/Go1.13/src/crypto/tls/handshake_server.go:43 +0x70
crypto/tls.(*Conn).Handshake(0xc000508700, 0x0, 0x0)
C:/Go1.13/src/crypto/tls/conn.go:1366 +0x23a
github.com/valyala/fasthttp.(*Server).getNextProto(0xc000180e00, 0xc76040, 0xc000508700, 0x0, 0x0, 0xc61180, 0xc00001e050)
C:/Users/Administrator/go/src/github.com/valyala/fasthttp/server.go:1338 +0xbf
github.com/valyala/fasthttp.(*Server).serveConn(0xc000180e00, 0xc76040, 0xc000508700, 0x0, 0x0)
C:/Users/Administrator/go/src/github.com/valyala/fasthttp/server.go:1843 +0xbf
github.com/valyala/fasthttp.(*workerPool).workerFunc(0xc0001df180, 0xc0002a8780)
C:/Users/Administrator/go/src/github.com/valyala/fasthttp/workerpool.go:223 +0xc0
github.com/valyala/fasthttp.(*workerPool).getCh.func1(0xc0001df180, 0xc0002a8780, 0xa511a0, 0xc0002a8780)
C:/Users/Administrator/go/src/github.com/valyala/fasthttp/workerpool.go:195 +0x35
created by github.com/valyala/fasthttp.(*workerPool).getCh
C:/Users/Administrator/go/src/github.com/valyala/fasthttp/workerpool.go:194 +0x101

What did you expect to see?

I hope the handshake timeout could be add in crypto/tls。

@aaaaa123ad aaaaa123ad changed the title crypto/tls: crypto/tls: handshake cause goroutine leak In some cases? Dec 23, 2019
@aaaaa123ad aaaaa123ad changed the title crypto/tls: handshake cause goroutine leak In some cases? crypto/tls: handshake cause goroutine block In some cases? Dec 23, 2019
@aaaaa123ad aaaaa123ad changed the title crypto/tls: handshake cause goroutine block In some cases? crypto/tls: handshake cause goroutine blocking In some cases? Dec 23, 2019
@networkimprov
Copy link

Maybe you're running into this? #31224

If not, could you provide a small, complete program which reproduces your problem, and tell us how you built and ran it?

@aaaaa123ad
Copy link
Author

aaaaa123ad commented Dec 25, 2019

Maybe you're running into this? #31224

If not, could you provide a small, complete program which reproduces your problem, and tell us how you built and ran it?

The client written by others uses mbedtls to connect to the server.But I can use golang to write a simple server and client to simulate

Server:

package main

import (
	"fmt"
	"net/http"
	_ "net/http/pprof"
)

func main() {
	http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
		fmt.Fprint(w,"hello")
	})
	go func() {
		http.ListenAndServe("0.0.0.0:8787", nil)
	}()
	http.ListenAndServeTLS(":12121","server.pem","server.key",nil)

}

Client:

package main

import (
	"crypto/tls"
	"log"
	"net"
)

func ClientTest()  {
	rawConn, err := net.Dial("tcp", "127.0.0.1:12121")
	if err != nil {
		log.Println("error :",err.Error())
		return
	}
	conn:=tls.Client(rawConn,&tls.Config{})

        //handshake  didn't work for some reason or client bug
	select {

	}
	//handshake
	conn.Handshake()
	//.....other operation
}
func main()  {
	for i:=0;i<500;i++{
		go ClientTest()
	}
	select {

	}
}

http://127.0.0.1:8787/debug/pprof:

/debug/pprof/

Types of profiles available:
CountProfile
2allocs
0block
0cmdline
505goroutine
2heap
0mutex
0profile
7threadcreate
0trace
full goroutine stack dump

http://127.0.0.1:8787/debug/pprof/goroutine?debug=2:

///....................some fragment.........  server is  under the environment of Windows
goroutine 501 [IO wait]:
internal/poll.runtime_pollWait(0x330ee354, 0x72, 0x7db7d0)
	C:/Go1.13/src/runtime/netpoll.go:184 +0x4b
internal/poll.(*pollDesc).wait(0x131c785c, 0x72, 0x9c4100, 0x0, 0x0)
	C:/Go1.13/src/internal/poll/fd_poll_runtime.go:87 +0x37
internal/poll.(*ioSrv).ExecIO(0xa015f8, 0x131c7774, 0x77a430, 0x0, 0x0, 0x0)
	C:/Go1.13/src/internal/poll/fd_windows.go:228 +0xef
internal/poll.(*FD).Read(0x131c7760, 0x13201b00, 0x205, 0x205, 0x0, 0x0, 0x0)
	C:/Go1.13/src/internal/poll/fd_windows.go:527 +0x10a
net.(*netFD).Read(0x131c7760, 0x13201b00, 0x205, 0x205, 0x0, 0x281fcf5, 0x76)
	C:/Go1.13/src/net/fd_windows.go:152 +0x3f
net.(*conn).Read(0x12c41d28, 0x13201b00, 0x205, 0x205, 0x0, 0x0, 0x0)
	C:/Go1.13/src/net/net.go:184 +0x56
crypto/tls.(*atLeastReader).Read(0x130f4750, 0x13201b00, 0x205, 0x205, 0x0, 0x13201b00, 0x0)
	C:/Go1.13/src/crypto/tls/conn.go:782 +0x61
bytes.(*Buffer).ReadFrom(0x13212d60, 0x7da7f0, 0x130f4750, 0x0, 0x4088c9, 0x70e760, 0x74dc80)
	C:/Go1.13/src/bytes/buffer.go:204 +0x95
crypto/tls.(*Conn).readFromUntil(0x13212c00, 0x32f21008, 0x12c41d28, 0x5, 0x12c41d28, 0x0)
	C:/Go1.13/src/crypto/tls/conn.go:804 +0xcb
crypto/tls.(*Conn).readRecordOrCCS(0x13212c00, 0x0, 0x0, 0x27e8a38)
	C:/Go1.13/src/crypto/tls/conn.go:609 +0x114
crypto/tls.(*Conn).readRecord(...)
	C:/Go1.13/src/crypto/tls/conn.go:577
crypto/tls.(*Conn).readHandshake(0x13212c00, 0x23ba98, 0x20, 0x0, 0x200)
	C:/Go1.13/src/crypto/tls/conn.go:995 +0x4b
crypto/tls.(*Conn).readClientHello(0x13212c00, 0x12cbec80, 0x84, 0xffffffff)
	C:/Go1.13/src/crypto/tls/handshake_server.go:135 +0x25
crypto/tls.(*Conn).serverHandshake(0x13212c00, 0x0, 0x330ea480)
	C:/Go1.13/src/crypto/tls/handshake_server.go:43 +0x6f
crypto/tls.(*Conn).Handshake(0x13212c00, 0x0, 0x0)
	C:/Go1.13/src/crypto/tls/conn.go:1366 +0x1d7
net/http.(*conn).serve(0x12fc7500, 0x7de740, 0x12c38800)
	C:/Go1.13/src/net/http/server.go:1783 +0x1a2
created by net/http.(*Server).Serve
	C:/Go1.13/src/net/http/server.go:2928 +0x30d

//.....................hidden.........

@toothrot
Copy link
Contributor

toothrot commented Jan 7, 2020

@aaaaa123ad Are you checking the error that got returned from the handshake? In this scenario, I'd expect an error similar to:

tls: either ServerName or InsecureSkipVerify must be specified in the tls.Config

Also, I am not quite sure I understand what the point of the empty select {} is in ClientTest. It seems like you're opening a connection and blocking indefinitely before doing a handshake, which could be why you have so many goroutines blocking on your server.

@toothrot toothrot added 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. labels Jan 7, 2020
@toothrot toothrot added this to the Backlog milestone Jan 7, 2020
@gopherbot
Copy link

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.)

@golang golang locked and limited conversation to collaborators Feb 6, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
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
Development

No branches or pull requests

4 participants