TestStreamsInSentOrder sometimes deadlocks

[ssgelm]

We are having a problem in Debian when building the martian where TestStreamsInSentOrder occasionally deadlocks. There's a little more info at https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=923819 but tl;dr in a small but consistent number of builds TestStreamsInSentOrder runs for 10 minutes until it is killed. It looks this test was previously flaky and fixed in #265. Is it possible there are still issues? I'm also doing some investigation on my end to see what I can find. A log of the failure is below.

=== RUN   TestStreamsInSentOrder
SIGQUIT: quit
PC=0x45e770 m=0 sigcode=0

goroutine 0 [idle]:
runtime.epollwait(0x7fff00000004, 0x7fff30199818, 0xffffffff00000080, 0x7fff00000001, 0xffffffff00000001, 0x1, 0x0, 0xda5f5e3000000005, 0x7f17, 0x0, ...)
	/usr/lib/go-1.11/src/runtime/sys_linux_amd64.s:671 +0x20
runtime.netpoll(0xc000028501, 0xc000028501)
	/usr/lib/go-1.11/src/runtime/netpoll_epoll.go:71 +0x132
runtime.findrunnable(0xc000026000, 0x0)
	/usr/lib/go-1.11/src/runtime/proc.go:2469 +0x51c
runtime.schedule()
	/usr/lib/go-1.11/src/runtime/proc.go:2613 +0x13a
runtime.park_m(0xc000001800)
	/usr/lib/go-1.11/src/runtime/proc.go:2676 +0xae
runtime.mcall(0x0)
	/usr/lib/go-1.11/src/runtime/asm_amd64.s:299 +0x5b

goroutine 1 [chan receive, 9 minutes]:
testing.(*T).Run(0xc00010c100, 0x72cf41, 0x16, 0x73d830, 0x478386)
	/usr/lib/go-1.11/src/testing/testing.go:879 +0x383
testing.runTests.func1(0xc00010c000)
	/usr/lib/go-1.11/src/testing/testing.go:1119 +0x78
testing.tRunner(0xc00010c000, 0xc0000a5e08)
	/usr/lib/go-1.11/src/testing/testing.go:827 +0xbf
testing.runTests(0xc00008e320, 0x967200, 0x8, 0x8, 0x40d3ff)
	/usr/lib/go-1.11/src/testing/testing.go:1117 +0x2aa
testing.(*M).Run(0xc00010a000, 0x0)
	/usr/lib/go-1.11/src/testing/testing.go:1034 +0x165
main.main()
	_testmain.go:56 +0x13d

goroutine 19 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7f17da5f5e30, 0x72, 0xc000046b80)
	/usr/lib/go-1.11/src/runtime/netpoll.go:173 +0x66
internal/poll.(*pollDesc).wait(0xc00010a318, 0x72, 0xffffffffffffff00, 0x776bc0, 0x934560)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:85 +0x9a
internal/poll.(*pollDesc).waitRead(0xc00010a318, 0xc00013c000, 0x1000, 0x1000)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc00010a300, 0xc00013c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/internal/poll/fd_unix.go:169 +0x179
net.(*netFD).Read(0xc00010a300, 0xc00013c000, 0x1000, 0x1000, 0xc0004d9630, 0x40, 0x50)
	/usr/lib/go-1.11/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc00008a058, 0xc00013c000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/net.go:177 +0x68
bufio.(*Reader).fill(0xc00006a4e0)
	/usr/lib/go-1.11/src/bufio/bufio.go:100 +0x10f
bufio.(*Reader).ReadByte(0xc00006a4e0, 0xc0002cd630, 0x0, 0xf)
	/usr/lib/go-1.11/src/bufio/bufio.go:242 +0x39
golang.org/x/net/websocket.hybiFrameReaderFactory.NewFrameReader(0xc00006a4e0, 0x73e108, 0xc0001ae028, 0xc000464000, 0xc000046e90)
	/<<BUILDDIR>>/golang-github-google-martian-2.1.0+git20181219.d0b5ad3/obj-x86_64-linux-gnu/src/golang.org/x/net/websocket/hybi.go:123 +0x60
golang.org/x/net/websocket.Codec.Receive(0x73d868, 0x73d870, 0xc0001ae000, 0x6a3c40, 0xc0004ed520, 0x0, 0x0)
	/<<BUILDDIR>>/golang-github-google-martian-2.1.0+git20181219.d0b5ad3/obj-x86_64-linux-gnu/src/golang.org/x/net/websocket/websocket.go:341 +0xaf
github.com/google/martian/marbl.TestStreamsInSentOrder(0xc00010c100)
	/<<BUILDDIR>>/golang-github-google-martian-2.1.0+git20181219.d0b5ad3/obj-x86_64-linux-gnu/src/github.com/google/martian/marbl/handler_test.go:55 +0x32a
testing.tRunner(0xc00010c100, 0x73d830)
	/usr/lib/go-1.11/src/testing/testing.go:827 +0xbf
created by testing.(*T).Run
	/usr/lib/go-1.11/src/testing/testing.go:878 +0x35c

goroutine 21 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7f17da5f5f00, 0x72, 0x0)
	/usr/lib/go-1.11/src/runtime/netpoll.go:173 +0x66
internal/poll.(*pollDesc).wait(0xc00010a118, 0x72, 0xc00005e000, 0x0, 0x0)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:85 +0x9a
internal/poll.(*pollDesc).waitRead(0xc00010a118, 0xffffffffffffff00, 0x0, 0x0)
	/usr/lib/go-1.11/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Accept(0xc00010a100, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/usr/lib/go-1.11/src/internal/poll/fd_unix.go:384 +0x1a0
net.(*netFD).accept(0xc00010a100, 0xc00013a140, 0x3f26326a14b63c0c, 0x44c488)
	/usr/lib/go-1.11/src/net/fd_unix.go:238 +0x42
net.(*TCPListener).accept(0xc00008a050, 0x5c7e7212, 0xc00004be78, 0x478386)
	/usr/lib/go-1.11/src/net/tcpsock_posix.go:139 +0x2e
net.(*TCPListener).Accept(0xc00008a050, 0xc00004bec8, 0x18, 0xc000070600, 0x645b85)
	/usr/lib/go-1.11/src/net/tcpsock.go:260 +0x47
net/http.(*Server).Serve(0xc000136000, 0x778ca0, 0xc00008a050, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/http/server.go:2826 +0x22f
net/http.Serve(0x778ca0, 0xc00008a050, 0x775d00, 0xc00008e460, 0x0, 0x0)
	/usr/lib/go-1.11/src/net/http/server.go:2423 +0x6e
created by github.com/google/martian/marbl.TestStreamsInSentOrder
	/<<BUILDDIR>>/golang-github-google-martian-2.1.0+git20181219.d0b5ad3/obj-x86_64-linux-gnu/src/github.com/google/martian/marbl/handler_test.go:38 +0x163

goroutine 4 [chan receive, 9 minutes]:
github.com/google/martian/marbl.(*Handler).streamLogs(0xc00008e460, 0xc00010e240)
	/<<BUILDDIR>>/golang-github-google-martian-2.1.0+git20181219.d0b5ad3/obj-x86_64-linux-gnu/src/github.com/google/martian/marbl/handler.go:77 +0x19d
github.com/google/martian/marbl.(*Handler).streamLogs-fm(0xc00010e240)
	/<<BUILDDIR>>/golang-github-google-martian-2.1.0+git20181219.d0b5ad3/obj-x86_64-linux-gnu/src/github.com/google/martian/marbl/handler.go:61 +0x34
golang.org/x/net/websocket.Server.serveWebSocket(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/<<BUILDDIR>>/golang-github-google-martian-2.1.0+git20181219.d0b5ad3/obj-x86_64-linux-gnu/src/golang.org/x/net/websocket/server.go:89 +0x17e
golang.org/x/net/websocket.Server.ServeHTTP(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/<<BUILDDIR>>/golang-github-google-martian-2.1.0+git20181219.d0b5ad3/obj-x86_64-linux-gnu/src/golang.org/x/net/websocket/server.go:70 +0x6a
github.com/google/martian/marbl.(*Handler).ServeHTTP(0xc00008e460, 0x778ee0, 0xc000146000, 0xc00010c800)
	/<<BUILDDIR>>/golang-github-google-martian-2.1.0+git20181219.d0b5ad3/obj-x86_64-linux-gnu/src/github.com/google/martian/marbl/handler.go:61 +0xd1
net/http.serverHandler.ServeHTTP(0xc000136000, 0x778ee0, 0xc000146000, 0xc00010c800)
	/usr/lib/go-1.11/src/net/http/server.go:2741 +0xab
net/http.(*conn).serve(0xc000140000, 0x779120, 0xc00008ca40)
	/usr/lib/go-1.11/src/net/http/server.go:1847 +0x646
created by net/http.(*Server).Serve
	/usr/lib/go-1.11/src/net/http/server.go:2851 +0x2f5

rax    0xfffffffffffffffc
rbx    0xffffffff
rcx    0x45e770
rdx    0x80
rdi    0x4
rsi    0x7fff30199818
rbp    0x7fff30199e18
rsp    0x7fff301997d8
r8     0x0
r9     0x3
r10    0xffffffff
r11    0x246
r12    0xffffffffffffffff
r13    0x6a
r14    0x69
r15    0x200
rip    0x45e770
rflags 0x246
cs     0x33
fs     0x0
gs     0x0
*** Test killed with quit: ran too long (10m0s).
FAIL	github.com/google/martian/marbl	600.017s

[ssgelm]

In fact, I was just able to reproduce on my first try by running:

go get github.com/google/martian
go test -v github.com/google/martian/marbl

Looks like maybe it's still flaky?

[hueich]

@ssgelm This issue should now be fixed by #290. Feel free to reopen if that doesn't fix it.