tcp-info icon indicating copy to clipboard operation
tcp-info copied to clipboard

eventsocket unit tests flaky

Open stephen-soltesz opened this issue 5 years ago • 0 comments

Before merging https://github.com/m-lab/tcp-info/pull/113 one of the travis builds failed as a result of test hanging in github.com/m-lab/tcp-info/eventsocket.

However, this can occur on earlier versions as late as v1.3.0.

Running the tcp-info unit tests repeatedly will eventually hang on these tests.

while go test -timeout 2m -count=1 -v ./... ; do echo $? ; done

After timeout, the test panics and dumps a stack trace, like below:

=== RUN   TestClient
2019/12/20 18:32:56 Adding new TCP event client &{{0xc0000c6500}}
panic: test timed out after 10m0s

goroutine 5 [running]:
testing.(*M).startAlarm.func1()
        /golang/src/testing/testing.go:1392 +0xdf
created by time.goFunc
        /golang/src/time/sleep.go:168 +0x44

goroutine 1 [chan receive]:
testing.(*T).Run(0xc0000c8100, 0x624772, 0xa, 0x62f8b8, 0x483fb6)
        /golang/src/testing/testing.go:961 +0x377
testing.runTests.func1(0xc0000c8000)
        /golang/src/testing/testing.go:1204 +0x78
testing.tRunner(0xc0000c8000, 0xc00004cdc0)
        /golang/src/testing/testing.go:909 +0xc9
testing.runTests(0xc0000a6060, 0x7ad420, 0x4, 0x4, 0x0)
        /golang/src/testing/testing.go:1202 +0x2a7
testing.(*M).Run(0xc0000c6000, 0x0)
        /golang/src/testing/testing.go:1119 +0x176
main.main()
        _testmain.go:50 +0x135

goroutine 20 [semacquire]:
sync.runtime_Semacquire(0xc0000ce078)
        /golang/src/runtime/sema.go:56 +0x42
sync.(*WaitGroup).Wait(0xc0000ce070)
        /golang/src/sync/waitgroup.go:130 +0x64
github.com/m-lab/tcp-info/eventsocket.TestClient(0xc0000c8100)
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/client_test.go:62 +0x66d
testing.tRunner(0xc0000c8100, 0x62f8b8)
        /golang/src/testing/testing.go:909 +0xc9
created by testing.(*T).Run
        /golang/src/testing/testing.go:960 +0x350

goroutine 21 [IO wait]:
internal/poll.runtime_pollWait(0x7ffbfc5d2f98, 0x72, 0x0)
        /golang/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc0000c6098, 0x72, 0x0, 0x0, 0x623b1d)
        /golang/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
        /golang/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Accept(0xc0000c6080, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
        /golang/src/internal/poll/fd_unix.go:384 +0x1f8
net.(*netFD).accept(0xc0000c6080, 0x5aac8e, 0x0, 0x0)
        /golang/src/net/fd_unix.go:238 +0x42
net.(*UnixListener).accept(0xc00008e810, 0xc000098038, 0x5d2560, 0x65e390)
        /golang/src/net/unixsock_posix.go:162 +0x32
net.(*UnixListener).Accept(0xc00008e810, 0x0, 0x0, 0x0, 0x0)
        /golang/src/net/unixsock.go:260 +0x47
github.com/m-lab/tcp-info/eventsocket.(*server).Serve(0xc0000ba0a0, 0x664e80, 0xc00009c6c0, 0x0, 0x0)
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/server.go:152 +0x1d1
created by github.com/m-lab/tcp-info/eventsocket.TestClient
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/client_test.go:40 +0x2ac

goroutine 22 [IO wait]:
internal/poll.runtime_pollWait(0x7ffbfc5d2ec8, 0x72, 0xffffffffffffffff)
        /golang/src/runtime/netpoll.go:184 +0x55
internal/poll.(*pollDesc).wait(0xc0000c6298, 0x72, 0x1000, 0x1000, 0xffffffffffffffff)
        /golang/src/internal/poll/fd_poll_runtime.go:87 +0x45
internal/poll.(*pollDesc).waitRead(...)
        /golang/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0000c6280, 0xc0000e4000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /golang/src/internal/poll/fd_unix.go:169 +0x1cf
net.(*netFD).Read(0xc0000c6280, 0xc0000e4000, 0x1000, 0x1000, 0xc00004ece8, 0x44706c, 0x1000)
        /golang/src/net/fd_unix.go:202 +0x4f
net.(*conn).Read(0xc000098030, 0xc0000e4000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /golang/src/net/net.go:184 +0x68
bufio.(*Scanner).Scan(0xc00004eed8, 0x666480)
        /golang/src/bufio/scan.go:213 +0xa4
github.com/m-lab/tcp-info/eventsocket.MustRun(0x664e80, 0xc00009c800, 0xc0000d0080, 0x32, 0x662ec0, 0xc0000ce060)
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/client.go:48 +0x276
github.com/m-lab/tcp-info/eventsocket.TestClient.func1(0x664e80, 0xc00009c680, 0xc000096030, 0x23, 0xc0000ce060, 0xc0000942b0)
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/client_test.go:47 +0x99
created by github.com/m-lab/tcp-info/eventsocket.TestClient
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/client_test.go:46 +0x386

goroutine 23 [chan receive]:
github.com/m-lab/tcp-info/eventsocket.MustRun.func1(0x664e80, 0xc00009c800, 0x666480, 0xc000098030)
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/client.go:42 +0x48
created by github.com/m-lab/tcp-info/eventsocket.MustRun
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/client.go:39 +0x1d0

goroutine 24 [chan receive]:
github.com/m-lab/tcp-info/eventsocket.(*server).notifyClients(0xc0000ba0a0, 0x664e80, 0xc00009c840)
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/server.go:99 +0xdb
created by github.com/m-lab/tcp-info/eventsocket.(*server).Serve
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/server.go:135 +0x11e

goroutine 25 [chan receive]:
github.com/m-lab/tcp-info/eventsocket.(*server).Serve.func1(0x664e80, 0xc00009c840, 0xc0000ba0a0)
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/server.go:143 +0x4c
created by github.com/m-lab/tcp-info/eventsocket.(*server).Serve
        /home/soltesz/src/github.com/m-lab/tcp-info/eventsocket/server.go:142 +0x174
FAIL    github.com/m-lab/tcp-info/eventsocket   600.033s


stephen-soltesz avatar Dec 20 '19 23:12 stephen-soltesz