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.

Sign up for GitHub

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

Jump to bottom

net/http: build test sometimes fails #17733

Closed
YoshikiShibata opened this issue Nov 2, 2016 · 3 comments
Closed

net/http: build test sometimes fails #17733

YoshikiShibata opened this issue Nov 2, 2016 · 3 comments
Labels
FrozenDueToAge help wanted Testing An issue that has been verified to require only test changes, not just a test failure.
Milestone
Go1.8

Comments

@YoshikiShibata
Copy link

Please answer these questions before submitting your issue. Thanks!

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

go version devel +c57a443 Tue Nov 1 23:47:31 2016 +0000 linux/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/yoshiki/gocode:/home/yoshiki/gpl_exercises:/home/yoshiki/oak"
GORACE=""
GOROOT="/home/yoshiki/go"
GOTOOLDIR="/home/yoshiki/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build983223135=/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?

If possible, provide a recipe for reproducing the error.
A complete runnable program is good.
A link on play.golang.org is best.

Just rebuild by running src/all.bash after git pull

What did you expect to see?

All tests passed. I tried 3 times and all tests passed only once.

What did you see instead?

ok net 1.394s
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
2016/11/02 09:08:05 httptest.Server blocked in Close after 5 seconds, waiting for connections:
*tls.Conn 0xc42008a000 127.0.0.1:60608 in state active
1 second passes in backend, proxygone= false
1 second passes in backend, proxygone= false
goroutine 3198 [running]:
net/http_test.testTransportAndServerSharedBodyRace.func5.1()
/home/yoshiki/go/src/net/http/serve_test.go:3383 +0x9b
created by time.goFunc
/home/yoshiki/go/src/time/sleep.go:164 +0x44

goroutine 1 [chan receive]:
testing.(*T).Run(0xc4200ee180, 0x8b1c2d, 0x27, 0x8c0fd0, 0xc4200add01)
/home/yoshiki/go/src/testing/testing.go:684 +0x2ee
testing.runTests.func1(0xc4200ee180)
/home/yoshiki/go/src/testing/testing.go:839 +0x67
testing.tRunner(0xc4200ee180, 0xc4200ade10)
/home/yoshiki/go/src/testing/testing.go:646 +0x85
testing.runTests(0x8bfb90, 0xadb8a0, 0x19d, 0x19d, 0x0)
/home/yoshiki/go/src/testing/testing.go:845 +0x29d
testing.(*M).Run(0xc42003ef28, 0xc420074058)
/home/yoshiki/go/src/testing/testing.go:780 +0x90
net/http_test.TestMain(0xc4200adf28)
/home/yoshiki/go/src/net/http/main_test.go:19 +0x2b
main.main()
net/http/_test/_testmain.go:928 +0xc6

goroutine 17 [syscall, locked to thread]:
runtime.goexit()
/home/yoshiki/go/src/runtime/asm_amd64.s:2184 +0x1

goroutine 2043 [chan receive]:
testing.(*T).Parallel(0xc420111740)
/home/yoshiki/go/src/testing/testing.go:585 +0x14f
net/http_test.setParallel(0xc420111740)
/home/yoshiki/go/src/net/http/main_test.go:87 +0x43
net/http_test.TestServerTimeouts(0xc420111740)
/home/yoshiki/go/src/net/http/serve_test.go:462 +0x43
testing.tRunner(0xc420111740, 0x8c0df8)
/home/yoshiki/go/src/testing/testing.go:646 +0x85
created by testing.(*T).Run
/home/yoshiki/go/src/testing/testing.go:683 +0x2c4

goroutine 3016 [IO wait]:
net.runtime_pollWait(0x7f3761c4dbe8, 0x72, 0x9)
/home/yoshiki/go/src/runtime/netpoll.go:164 +0x59
net.(*pollDesc).wait(0xc42038c148, 0x72, 0xa9fe20, 0xa9b5a0)
/home/yoshiki/go/src/net/fd_poll_runtime.go:75 +0x38
net.(*pollDesc).waitRead(0xc42038c148, 0xc42004e000, 0x8000)
/home/yoshiki/go/src/net/fd_poll_runtime.go:80 +0x34
net.(*netFD).Read(0xc42038c0e0, 0xc42004e000, 0x8000, 0x8000, 0x0, 0xa9fe20, 0xa9b5a0)
/home/yoshiki/go/src/net/fd_unix.go:250 +0x1b7
net.(*conn).Read(0xc42037a000, 0xc42004e000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
/home/yoshiki/go/src/net/net.go:180 +0x70
crypto/tls.(*block).readFromUntil(0xc4204966f0, 0x7f3761c4e398, 0xc42037a000, 0x5, 0xc42037a000, 0x0)
/home/yoshiki/go/src/crypto/tls/conn.go:488 +0x98
crypto/tls.(*Conn).readRecord(0xc42008a000, 0x8c1a17, 0xc42008a120, 0x2)
/home/yoshiki/go/src/crypto/tls/conn.go:590 +0xc4
crypto/tls.(*Conn).Read(0xc42008a000, 0xc420110038, 0x9, 0x9, 0x0, 0x0, 0x0)
/home/yoshiki/go/src/crypto/tls/conn.go:1134 +0x116
io.ReadAtLeast(0xa9d320, 0xc42008a000, 0xc420110038, 0x9, 0x9, 0x9, 0x0, 0xc4202f14f0, 0x0)
/home/yoshiki/go/src/io/io.go:307 +0xa9
io.ReadFull(0xa9d320, 0xc42008a000, 0xc420110038, 0x9, 0x9, 0xc4204a8d00, 0xc421820ee0, 0xc420273260)
/home/yoshiki/go/src/io/io.go:325 +0x58
net/http.http2readFrameHeader(0xc420110038, 0x9, 0x9, 0xa9d320, 0xc42008a000, 0x0, 0x0, 0x2, 0xc421820f44)
/home/yoshiki/go/src/net/http/h2_bundle.go:781 +0x7b
net/http.(*http2Framer).ReadFrame(0xc420110000, 0xc420273260, 0x0, 0x1, 0x0)
/home/yoshiki/go/src/net/http/h2_bundle.go:1003 +0xa7
net/http.(*http2serverConn).readFrames(0xc420427340)
/home/yoshiki/go/src/net/http/h2_bundle.go:3415 +0xab
created by net/http.(*http2serverConn).serve
/home/yoshiki/go/src/net/http/h2_bundle.go:3516 +0x303

goroutine 3006 [semacquire]:
sync.runtime_notifyListWait(0xc42030c5d0, 0x6)
/home/yoshiki/go/src/runtime/sema.go:297 +0x10b
sync.(*Cond).Wait(0xc42030c5c0)
/home/yoshiki/go/src/sync/cond.go:57 +0x80
net/http.(*http2clientStream).awaitFlowControl(0xc4201f2140, 0x1, 0x0, 0x0, 0x0)
/home/yoshiki/go/src/net/http/h2_bundle.go:6218 +0x11f
net/http.(*http2clientStream).writeRequestBody(0xc4201f2140, 0x7f3761b75300, 0xc4201f7ce0, 0x7f3761c68250, 0xc4201f7ce0, 0x0, 0x0)
/home/yoshiki/go/src/net/http/h2_bundle.go:6136 +0x23c
net/http.(*http2Transport).getBodyWriterState.func1()
/home/yoshiki/go/src/net/http/h2_bundle.go:7171 +0xa1
created by net/http.http2bodyWriterState.scheduleBodyWrite
/home/yoshiki/go/src/net/http/h2_bundle.go:7215 +0x8e

goroutine 3020 [semacquire]:
sync.runtime_notifyListWait(0xc42010ac98, 0xc40000000c)
/home/yoshiki/go/src/runtime/sema.go:297 +0x10b
sync.(*Cond).Wait(0xc42010ac88)
/home/yoshiki/go/src/sync/cond.go:57 +0x80
net/http.(*http2pipe).Read(0xc42010ac80, 0xc4201b2000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
/home/yoshiki/go/src/net/http/h2_bundle.go:2811 +0xd9
net/http.(*http2requestBody).Read(0xc420496bd0, 0xc4201b2000, 0x8000, 0x8000, 0x4000, 0x0, 0x0)
/home/yoshiki/go/src/net/http/h2_bundle.go:4699 +0x9e
io.(*LimitedReader).Read(0xc420388a20, 0xc4201b2000, 0x8000, 0x8000, 0x4000, 0x0, 0x0)
/home/yoshiki/go/src/io/io.go:435 +0x6c
io.copyBuffer(0x7f3761c4e598, 0xc42037a008, 0xa9d5a0, 0xc420388a20, 0xc4201b2000, 0x8000, 0x8000, 0x84ef00, 0x7f3761b75301, 0xc420388a20)
/home/yoshiki/go/src/io/io.go:390 +0x147
io.Copy(0x7f3761c4e598, 0xc42037a008, 0xa9d5a0, 0xc420388a20, 0x83abc0, 0x837680, 0xc4204a8d00)
/home/yoshiki/go/src/io/io.go:360 +0x68
io.CopyN(0x7f3761c4e598, 0xc42037a008, 0x7f3761b75300, 0xc420496bd0, 0x100000, 0xc420374758, 0x473a03, 0xc420263350)
/home/yoshiki/go/src/io/io.go:336 +0x90
net/http_test.testTransportAndServerSharedBodyRace.func2.1(0xaa2fe0, 0xc42037a008, 0xc42051e400, 0xc4202735c0)
/home/yoshiki/go/src/net/http/serve_test.go:3323 +0xcc
created by net/http_test.testTransportAndServerSharedBodyRace.func2
/home/yoshiki/go/src/net/http/serve_test.go:3325 +0x106

goroutine 3013 [select]:
net/http.(*http2serverConn).serve(0xc420427340)
/home/yoshiki/go/src/net/http/h2_bundle.go:3522 +0xa3e
net/http.(*http2Server).ServeConn(0xc4201f6090, 0xaa54a0, 0xc42008a000, 0xc4202fdd20)
/home/yoshiki/go/src/net/http/h2_bundle.go:3169 +0x7df
net/http.http2ConfigureServer.func1(0xc4203c0000, 0xc42008a000, 0xa9f460, 0xc4204b61b0)
/home/yoshiki/go/src/net/http/h2_bundle.go:3050 +0x8f
net/http.(*conn).serve(0xc4202b7d60, 0xaa3a20, 0xc4201f6d20)
/home/yoshiki/go/src/net/http/server.go:1709 +0x102f
created by net/http.(*Server).Serve
/home/yoshiki/go/src/net/http/server.go:2608 +0x2ce

goroutine 3005 [IO wait]:
net.runtime_pollWait(0x7f3761c4da68, 0x72, 0x8)
/home/yoshiki/go/src/runtime/netpoll.go:164 +0x59
net.(*pollDesc).wait(0xc42001b3a8, 0x72, 0xa9fe20, 0xa9b5a0)
/home/yoshiki/go/src/net/fd_poll_runtime.go:75 +0x38
net.(*pollDesc).waitRead(0xc42001b3a8, 0xc42182c000, 0x8000)
/home/yoshiki/go/src/net/fd_poll_runtime.go:80 +0x34
net.(*netFD).Read(0xc42001b340, 0xc42182c000, 0x8000, 0x8000, 0x0, 0xa9fe20, 0xa9b5a0)
/home/yoshiki/go/src/net/fd_unix.go:250 +0x1b7
net.(*conn).Read(0xc4202e2088, 0xc42182c000, 0x8000, 0x8000, 0x0, 0x0, 0x0)
/home/yoshiki/go/src/net/net.go:180 +0x70
crypto/tls.(*block).readFromUntil(0xc420114000, 0x7f3761c4e398, 0xc4202e2088, 0x5, 0xc4202e2088, 0x0)
/home/yoshiki/go/src/crypto/tls/conn.go:488 +0x98
crypto/tls.(*Conn).readRecord(0xc42046d880, 0x8c1a17, 0xc42046d9a0, 0x0)
/home/yoshiki/go/src/crypto/tls/conn.go:590 +0xc4
crypto/tls.(*Conn).Read(0xc42046d880, 0xc420327000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
/home/yoshiki/go/src/crypto/tls/conn.go:1134 +0x116
bufio.(*Reader).Read(0xc420380360, 0xc4200ee278, 0x9, 0x9, 0x20, 0x30, 0xc42017a540)
/home/yoshiki/go/src/bufio/bufio.go:213 +0x312
io.ReadAtLeast(0xa9d020, 0xc420380360, 0xc4200ee278, 0x9, 0x9, 0x9, 0x0, 0x0, 0x0)
/home/yoshiki/go/src/io/io.go:307 +0xa9
io.ReadFull(0xa9d020, 0xc420380360, 0xc4200ee278, 0x9, 0x9, 0xc420021300, 0xc420069860, 0xc42032fc00)
/home/yoshiki/go/src/io/io.go:325 +0x58
net/http.http2readFrameHeader(0xc4200ee278, 0x9, 0x9, 0xa9d020, 0xc420380360, 0x0, 0xc400000000, 0x1, 0xc420069860)
/home/yoshiki/go/src/net/http/h2_bundle.go:781 +0x7b
net/http.(*http2Framer).ReadFrame(0xc4200ee240, 0xc42017a540, 0x0, 0x0, 0x0)
/home/yoshiki/go/src/net/http/h2_bundle.go:1003 +0xa7
net/http.(*http2clientConnReadLoop).run(0xc420045fb0, 0x8bfe10, 0xc42029dfb0)
/home/yoshiki/go/src/net/http/h2_bundle.go:6486 +0x88
net/http.(*http2ClientConn).readLoop(0xc420531860)
/home/yoshiki/go/src/net/http/h2_bundle.go:6415 +0xa6
created by net/http.(*http2Transport).newClientConn
/home/yoshiki/go/src/net/http/h2_bundle.go:5756 +0x74d

goroutine 3018 [select]:
net/http_test.testTransportAndServerSharedBodyRace.func2(0xaa2fe0, 0xc42037a008, 0xc42051e400)
/home/yoshiki/go/src/net/http/serve_test.go:3329 +0x248
net/http.HandlerFunc.ServeHTTP(0xc420248060, 0xaa2fe0, 0xc42037a008, 0xc42051e400)
/home/yoshiki/go/src/net/http/server.go:1895 +0x44
net/http.serverHandler.ServeHTTP(0xc4203c0000, 0xaa2fe0, 0xc42037a008, 0xc42051e400)
/home/yoshiki/go/src/net/http/server.go:2508 +0x92
net/http.initNPNRequest.ServeHTTP(0xc42008a000, 0xc4203c0000, 0xaa2fe0, 0xc42037a008, 0xc42051e400)
/home/yoshiki/go/src/net/http/server.go:3028 +0x93
net/http.(*initNPNRequest).ServeHTTP(0xc4204b61b0, 0xaa2fe0, 0xc42037a008, 0xc42051e400)
:318 +0x74
net/http.(Handler).ServeHTTP-fm(0xaa2fe0, 0xc42037a008, 0xc42051e400)
/home/yoshiki/go/src/net/http/h2_bundle.go:4263 +0x4d
net/http.(*http2serverConn).runHandler(0xc420427340, 0xc42037a008, 0xc42051e400, 0xc4203889e0)
/home/yoshiki/go/src/net/http/h2_bundle.go:4541 +0x89
created by net/http.(*http2serverConn).processHeaders
/home/yoshiki/go/src/net/http/h2_bundle.go:4275 +0x43f

goroutine 3019 [chan receive]:
net/http.(*http2responseWriter).CloseNotify.func1(0xc42010ac00, 0xc42038c4d0)
/home/yoshiki/go/src/net/http/h2_bundle.go:4942 +0x47
created by net/http.(*http2responseWriter).CloseNotify
/home/yoshiki/go/src/net/http/h2_bundle.go:4944 +0xda

goroutine 3137 [semacquire]:
sync.runtime_Semacquire(0xc42031c1bc)
/home/yoshiki/go/src/runtime/sema.go:47 +0x34
sync.(*WaitGroup).Wait(0xc42031c1b0)
/home/yoshiki/go/src/sync/waitgroup.go:131 +0x73
net/http/httptest.(*Server).Close(0xc42031c180)
/home/yoshiki/go/src/net/http/httptest/server.go:190 +0x22f
net/http_test.(*clientServerTest).close(0xc42013c040)
/home/yoshiki/go/src/net/http/clientserver_test.go:44 +0x41
net/http_test.testTransportAndServerSharedBodyRace(0xc420180180, 0xc437392d01)
/home/yoshiki/go/src/net/http/serve_test.go:3404 +0x560
net/http_test.TestTransportAndServerSharedBodyRace_h2(0xc420180180)
/home/yoshiki/go/src/net/http/serve_test.go:3301 +0x30
testing.tRunner(0xc420180180, 0x8c0fd0)
/home/yoshiki/go/src/testing/testing.go:646 +0x85
created by testing.(*T).Run
/home/yoshiki/go/src/testing/testing.go:683 +0x2c4

goroutine 2194 [chan receive]:
testing.(*T).Parallel(0xc420180fc0)
/home/yoshiki/go/src/testing/testing.go:585 +0x14f
net/http_test.setParallel(0xc420180fc0)
/home/yoshiki/go/src/net/http/main_test.go:87 +0x43
net/http_test.TestTLSHandshakeTimeout(0xc420180fc0)
/home/yoshiki/go/src/net/http/serve_test.go:1026 +0x43
testing.tRunner(0xc420180fc0, 0x8c0ee0)
/home/yoshiki/go/src/testing/testing.go:646 +0x85
created by testing.(*T).Run
/home/yoshiki/go/src/testing/testing.go:683 +0x2c4
2016/11/02 09:08:07 Timeout.
FAIL net/http 11.879s
@bradfitz bradfitz self-assigned this Nov 2, 2016
@bradfitz bradfitz added the Testing An issue that has been verified to require only test changes, not just a test failure. label Nov 2, 2016
@bradfitz bradfitz added this to the Go1.8 milestone Nov 2, 2016
@bradfitz
Copy link
Contributor

bradfitz commented Nov 2, 2016

Thanks. This looks like the stack that @crawshaw emailed me about earlier today too.

Will look.

(Help wanted, though, if anybody has cycles.)

@gopherbot
Copy link

CL https://golang.org/cl/32583 mentions this issue.

gopherbot pushed a commit to golang/net that referenced this issue Nov 3, 2016
@bradfitz
http2: fix over-aggressive ignoring of frames while in "go away" mode
569280f 
https://golang.org/cl/31727 made many of the Server Frame processors
ignore incoming frames if the connection was in shutdown mode.

The idea was that it's pointless to do work if we're about to hang up
on them in 250ms anyway for violating a protocol error.

But as of https://golang.org/cl/32412 (graceful shutdown) we can also
be in "go away" mode for ErrCodeNo, which just means to nicely tell
them to GOAWAY and because they did nothing wrong, we don't hang up in
250ms (the value of which gave the peer time to read the error before
the TCP close), but instead we keep the conn open until it's idle.

The combination of the two CLs made TestTransportAndServerSharedBodyRace_h2
flaky, since it was never seeing RST_STREAM on cancelation of requests,
and then Handlers would block forever.

Updates golang/go#17733 (fixes after bundle into std)

Change-Id: I67491c1d7124bc3cb554f9246ea7683f20b6a4e3
Reviewed-on: https://go-review.googlesource.com/32583
Run-TryBot: Brad Fitzpatrick <bradfitz@golang.org>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: David Crawshaw <crawshaw@golang.org>
@gopherbot
Copy link

CL https://golang.org/cl/32584 mentions this issue.

@golang golang locked and limited conversation to collaborators Nov 3, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge help wanted Testing An issue that has been verified to require only test changes, not just a test failure.
Projects
None yet
Milestone
Go1.8
Development

No branches or pull requests
3 participants
@bradfitz @YoshikiShibata @gopherbot