net/http: BenchmarkClientServerParallelTLS64 sometimes reports an error

[erifan]

Please answer these questions before submitting your issue. Thanks!

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

go version devel +cc155eb

Does this issue reproduce with the latest release?

Yes.

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

GOARCH="arm64"
GOBIN=""
GOCACHE="/home/*/.cache/go-build"
GOEXE=""
GOHOSTARCH="arm64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/username/go"
GORACE=""
GOROOT="/home/username/go-temp"
GOTMPDIR=""
GOTOOLDIR="/home/username/go-temp/pkg/tool/linux_arm64"
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 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build212786936=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I found this error in the log of our daily job (cd /src ; go test -count 3 -timeout 180m -run=^$ -bench=. ... ).

Running the command "go test -bench BenchmarkClientServerParallelTLS64" alone can also reproduce this error, but the error sometimes appears, sometimes does not appear, you may need to run it several times.

What did you expect to see?

PASS

What did you see instead?

I have seen two kinds of error messages. When executing command "go test -bench BenchmarkClientServerParallelTLS64" , the error message appears:

goos: linux
goarch: arm64
pkg: net/http
BenchmarkClientServerParallel4-32 30000 37850 ns/op 12324 B/op 88 allocs/op
BenchmarkClientServerParallel64-32 10000 307570 ns/op 13278 B/op 96 allocs/op
BenchmarkClientServerParallelTLS4-32 20000 112708 ns/op 41859 B/op 433 allocs/op
BenchmarkClientServerParallelTLS64-32 2018/03/25 13:47:49 http: TLS handshake error from 127.0.0.1:58119: read tcp 127.0.0.1:34212->127.0.0.1:58119: use of closed network connection
20000 106537 ns/op 43259 B/op 454 allocs/op
PASS
ok net/http 47.081s

When running all the benchmarks ( cd /src ; go test -count 3 -timeout 180m -run=^$ -bench=. ... ) , in addition to the above error, another error may also occur., namely:
15:10:47 BenchmarkClientServerParallelTLS64-64 Build timed out (after 10 minutes). Marking the build as aborted.
15:20:47 Build was aborted

I do not understand what the problem is. How did it come about? Can anyone explain it to me, thank you!

[erifan]

Hi, does anyone know the problem?

[mengzhuo]

I can confirm this bug in my box
Linux hikey13 4.15-hikey #1 SMP PREEMPT Sat Mar 10 22:41:04 UTC 2018 aarch64 GNU/Linux

goos: linux                                                                         
goarch: arm64                                                                       
pkg: net/http                                                                       
BenchmarkClientServerParallelTLS64-8    2018/03/29 14:04:27 http: TLS handshake erro
r from 127.0.0.1:49120: read tcp 127.0.0.1:33467->127.0.0.1:49120: use of closed net
work connection                                                                     
2018/03/29 14:04:27 http: TLS handshake error from 127.0.0.1:49090: read tcp 127.0.0
.1:33467->127.0.0.1:49090: use of closed network connection                         
2018/03/29 14:04:27 http: TLS handshake error from 127.0.0.1:49180: read tcp 127.0.0
.1:33467->127.0.0.1:49180: use of closed network connection                         
2018/03/29 14:04:27 http: TLS handshake error from 127.0.0.1:49042: read tcp 127.0.0
.1:33467->127.0.0.1:49042: use of closed network connection                         
    2000            798913 ns/op           60430 B/op        604 allocs/op          
PASS                                                                                
ok      net/http        3.318s                                                      

[erifan]

@mengzhuo Yes, the issue also exists on x86.

[mengzhuo]

@erifan I found it's related to #9661
Lots tcp connections are in TIME_WAIT status after benchmarks. TCP connection start without SO_REUSEPORT nor SO_REUSEADDR will cause this issue.

[erifan]

@mengzhuo I'm not sure, the error message comes from tlsConn.Handshake(), I don't know why there is a connection at this stage after the server is closed.

[erifan]

@FiloSottile Hi, do you know the cause of this problem? I have been investigating this issue for some time, but I still do not understand it. Can you give me some suggestions? Thanks!

[erifan]

This is the other error information I've observed.

15:22:49 BenchmarkClientServerParallel64-96 2000 668230 ns/op 21286 B/op 124 allocs/op
15:22:51 BenchmarkClientServerParallel64-96 3000 418305 ns/op 20977 B/op 122 allocs/op
15:22:52 BenchmarkClientServerParallelTLS4-96 2000 897250 ns/op 65399 B/op 620 allocs/op
15:22:55 BenchmarkClientServerParallelTLS4-96 2018/04/08 14:22:58 http: TLS handshake error from 127.0.0.1:38978: read tcp 127.0.0.1:39659->127.0.0.1:38978: use of closed network connection
15:22:58 2000 878092 ns/op 43781 B/op 417 allocs/op
15:22:58 BenchmarkClientServerParallelTLS4-96 1000 1015730 ns/op 72051 B/op 693 allocs/op
15:22:59 BenchmarkClientServerParallelTLS64-96 5000 345304 ns/op 78196 B/op 755 allocs/op
15:23:04 BenchmarkClientServerParallelTLS64-96 5000 211130 ns/op 71296 B/op 683 allocs/op
15:23:08 BenchmarkClientServerParallelTLS64-96 10000 1616486 ns/op 74765 B/op 731 allocs/op
15:23:27 BenchmarkServer-96 5000 313404 ns/op 2273 B/op 20 allocs/op
15:23:29 BenchmarkServer-96 5000 315469 ns/op 2273 B/op 20 allocs/op
15:23:32 BenchmarkServer-96 5000 308680 ns/op 2257 B/op 20 allocs/op
15:23:36 --- FAIL: BenchmarkClient
15:23:36 main_test.go:140: Test appears to have leaked a timing out dial:
15:23:36 internal/poll.runtime_pollWait(0xfffe56cf8750, 0x77, 0xfffe56cf8758)
15:23:36 /home/root/ci-scripts/golang/src/runtime/netpoll.go:173 +0x3c
15:23:36 internal/poll.(*pollDesc).wait(0x4011bab598, 0x77, 0x4016f55400, 0x4016f55438, 0x4014bbba01)
15:23:36 /home/root/ci-scripts/golang/src/internal/poll/fd_poll_runtime.go:85 +0x90
15:23:36 internal/poll.(*pollDesc).waitWrite(0x4011bab598, 0x4011bab500, 0x0, 0x0)
15:23:36 /home/root/ci-scripts/golang/src/internal/poll/fd_poll_runtime.go:94 +0x30
15:23:36 internal/poll.(*FD).WaitWrite(0x4011bab580, 0x40001b0010, 0x40001b0010)
15:23:36 /home/root/ci-scripts/golang/src/internal/poll/fd_unix.go:446 +0x2c
15:23:36 net.(*netFD).connect(0x4011bab580, 0x8a4200, 0x40001b0010, 0x0, 0x0, 0x89fee0, 0x4014bbbac0, 0x0, 0x0, 0x0, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/fd_unix.go:152 +0x1e0
15:23:36 net.(*netFD).dial(0x4011bab580, 0x8a4200, 0x40001b0010, 0x8a4f20, 0x0, 0x8a4f20, 0x400c7e3c50, 0x5895e8, 0x401514bbf0)
15:23:36 /home/root/ci-scripts/golang/src/net/sock_posix.go:142 +0x98
15:23:36 net.socket(0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x2, 0x1, 0x0, 0x0, 0x8a4f20, 0x0, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/sock_posix.go:93 +0x124
15:23:36 net.internetSocket(0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x8a4f20, 0x0, 0x8a4f20, 0x400c7e3c50, 0x1, 0x0, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/ipsock_posix.go:141 +0xbc
15:23:36 net.doDialTCP(0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x0, 0x400c7e3c50, 0x0, 0x0, 0x0)
15:23:36 /home/root/ci-scripts/golang/src/net/tcpsock_posix.go:62 +0x78
15:23:36 net.dialTCP(0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x0, 0x400c7e3c50, 0x177502b8388f53, 0x221c2526, 0x40001b0010)
15:23:36 /home/root/ci-scripts/golang/src/net/tcpsock_posix.go:58 +0xb0
15:23:36 net.dialSingle(0x8a4200, 0x40001b0010, 0x4011bab500, 0x8a1d00, 0x400c7e3c50, 0x0, 0x0, 0x0, 0x0)
15:23:36 /home/root/ci-scripts/golang/src/net/dial.go:547 +0x2e0
15:23:36 net.dialSerial(0x8a4200, 0x40001b0010, 0x4011bab500, 0x4007084530, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
15:23:36 /home/root/ci-scripts/golang/src/net/dial.go:515 +0x188
15:23:36 net.(*Dialer).DialContext(0xad7480, 0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x40091395e0, 0xf, 0x0, 0x0, 0x0, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/dial.go:397 +0x4f0
15:23:36 net/http.(*Transport).dial(0x400c19c2d0, 0x8a4200, 0x40001b0010, 0x830ae7, 0x3, 0x40091395e0, 0xf, 0x474a38, 0x400fb8e900, 0x200000003, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/http/transport.go:906 +0x124
15:23:36 net/http.(*Transport).dialConn(0x400c19c2d0, 0x8a4200, 0x40001b0010, 0x0, 0x40001ec700, 0x5, 0x40091395e0, 0xf, 0x40056d9c00, 0x4003398101, ...)
15:23:36 /home/root/ci-scripts/golang/src/net/http/transport.go:1119 +0x23c
15:23:36 net/http.(*Transport).getConn.func4(0x400c19c2d0, 0x8a4200, 0x40001b0010, 0x40045d0a80, 0x40085acae0)
15:23:36 /home/root/ci-scripts/golang/src/net/http/transport.go:956 +0x44
15:23:36 created by net/http.(*Transport).getConn
15:23:36 /home/root/ci-scripts/golang/src/net/http/transport.go:955 +0x26c

[mmcloughlin]

Looks like this is still an issue. Besides being a bug with this specific benchmark, it's a slight annoyance since it corrupts standard library benchmark output, therefore it does not parse correctly with standard tools (golang.org/x/perf/storage/benchfmt). For some reason the error log is also going to stdout rather than stderr. Easy to work around, but it would be nice if we could clean this up.

$ go test -run 'none^' -bench . -benchtime 10ms net/http
goos: linux
goarch: amd64
pkg: net/http
BenchmarkCookieString-8                      	   23854	       539 ns/op	     176 B/op	       1 allocs/op
...
BenchmarkClientServerParallel64-8            	     532	     77916 ns/op	   12270 B/op	      86 allocs/op
BenchmarkClientServerParallelTLS4-8          	2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57680: read tcp 127.0.0.1:40263->127.0.0.1:57680: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57672: read tcp 127.0.0.1:40263->127.0.0.1:57672: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57626: read tcp 127.0.0.1:40263->127.0.0.1:57626: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57660: write tcp 127.0.0.1:40263->127.0.0.1:57660: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57690: read tcp 127.0.0.1:40263->127.0.0.1:57690: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57658: read tcp 127.0.0.1:40263->127.0.0.1:57658: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57644: write tcp 127.0.0.1:40263->127.0.0.1:57644: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:57654: write tcp 127.0.0.1:40263->127.0.0.1:57654: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42360: read tcp 127.0.0.1:33587->127.0.0.1:42360: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42436: read tcp 127.0.0.1:33587->127.0.0.1:42436: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42440: read tcp 127.0.0.1:33587->127.0.0.1:42440: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42448: read tcp 127.0.0.1:33587->127.0.0.1:42448: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42424: read tcp 127.0.0.1:33587->127.0.0.1:42424: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42442: read tcp 127.0.0.1:33587->127.0.0.1:42442: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42420: read tcp 127.0.0.1:33587->127.0.0.1:42420: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42444: read tcp 127.0.0.1:33587->127.0.0.1:42444: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42446: read tcp 127.0.0.1:33587->127.0.0.1:42446: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42422: write tcp 127.0.0.1:33587->127.0.0.1:42422: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:42438: write tcp 127.0.0.1:33587->127.0.0.1:42438: use of closed network connection
      54	    196088 ns/op	  104960 B/op	    1317 allocs/op
BenchmarkClientServerParallelTLS64-8         	2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:60164: write tcp 127.0.0.1:37981->127.0.0.1:60164: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:60166: write tcp 127.0.0.1:37981->127.0.0.1:60166: use of closed network connection
2020/05/02 14:14:00 http: TLS handshake error from 127.0.0.1:36562: read tcp 127.0.0.1:39223->127.0.0.1:36562: use of closed network connection
      63	    253756 ns/op	  115646 B/op	    1459 allocs/op
BenchmarkServer-8                            	     156	     73795 ns/op	    2495 B/op	      20 allocs/op
...