net/http: TestHandlerPanic hangs

[dvyukov]

parent: 15771:0adf91947752 tip
darwin/amd64

$ while ./http.test -test.v -test.cpu=1,2,3,4,5,6,7,8 -test.run=HandlerPanic; do true;
done;

eventually hangs with (even after increasing the timeout to 10sec):
=== RUN TestHandlerPanic-2
--- PASS: TestHandlerPanic-2 (0.00 seconds)
=== RUN TestHandlerPanicWithHijack-2
--- PASS: TestHandlerPanicWithHijack-2 (0.00 seconds)
=== RUN TestHandlerPanicNil-3
--- PASS: TestHandlerPanicNil-3 (0.00 seconds)
=== RUN TestHandlerPanic-3
--- PASS: TestHandlerPanic-3 (18.86 seconds)
serve_test.go:1067:     expected server handler to log an error

The stack dump is:
goroutine 48 [running]:
testing.func·004(0x5cdfa8, 0x5cd100)
    /Users/dvyukov/src/go2/src/pkg/testing/testing.go:310 +0xb3
net/http_test.testHandlerPanic(0xc20016fea0, 0x374200, 0x230720, 0xc2000a0ed0,
0xc2000a0ed0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1067 +0x337
net/http_test.TestHandlerPanic(0xc20016fea0, 0xc22f54c30a)
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1000 +0x62
testing.tRunner(0xc20016fea0, 0x5104c0, 0x0, 0x0)
    /Users/dvyukov/src/go2/src/pkg/testing/testing.go:315 +0x6c
created by testing.RunTests
    /Users/dvyukov/src/go2/src/pkg/testing/testing.go:430 +0x875

goroutine 1 [chan receive]:
testing.RunTests(0x2000, 0x50fb60, 0x8f, 0x8f, 0x5c3f01, ...)
    /Users/dvyukov/src/go2/src/pkg/testing/testing.go:431 +0x898
testing.Main(0x2000, 0x50fb60, 0x8f, 0x8f, 0x5092f8, ...)
    /Users/dvyukov/src/go2/src/pkg/testing/testing.go:327 +0x8a
main.main()
    net/http/_test/_testmain.go:349 +0x9a

goroutine 49 [runnable]:
net.(*pollServer).WaitRead(0xc20013c6f0, 0xc20011edd0, 0xc200000c60, 0x23, 0xc200000c01,
...)
    /Users/dvyukov/src/go2/src/pkg/net/fd_unix.go:244 +0x63
net.(*netFD).accept(0xc20011edd0, 0x15d290, 0x0, 0xc200000c60, 0x23, ...)
    /Users/dvyukov/src/go2/src/pkg/net/fd_unix.go:631 +0x171
net.(*TCPListener).AcceptTCP(0xc2000b73d0, 0xc20018af00, 0x0, 0x0, 0xc0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/tcpsock_posix.go:232 +0x57
net.(*TCPListener).Accept(0xc2000b73d0, 0x0, 0x0, 0x0, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/tcpsock_posix.go:242 +0x49
net/http/httptest.(*historyListener).Accept(0xc20013c840, 0x0, 0x0, 0x0, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/http/httptest/server.go:48 +0x54
net/http.(*Server).Serve(0xc20016d8c0, 0xc200095980, 0xc20013c840, 0x0, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/http/server.go:1316 +0x85
created by net/http/httptest.(*Server).Start
    /Users/dvyukov/src/go2/src/pkg/net/http/httptest/server.go:109 +0x21a

goroutine 4 [syscall]:
syscall.Syscall6()
    /Users/dvyukov/src/go2/src/pkg/syscall/asm_darwin_amd64.s:38 +0x5
syscall.kevent(0x6, 0x0, 0x0, 0xc200096c08, 0xa, ...)
    /Users/dvyukov/src/go2/src/pkg/syscall/zsyscall_darwin_amd64.go:199 +0x83
syscall.Kevent(0x6, 0x0, 0x0, 0x0, 0xc200096c08, ...)
    /Users/dvyukov/src/go2/src/pkg/syscall/syscall_bsd.go:554 +0x9b
net.(*pollster).WaitFD(0xc200096c00, 0xc200000db0, 0x0, 0x0, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/fd_darwin.go:101 +0x187
net.(*pollServer).Run(0xc200000db0, 0x0)
    /Users/dvyukov/src/go2/src/pkg/net/fd_unix.go:212 +0x10a
created by net.newPollServer
    /Users/dvyukov/src/go2/src/pkg/net/newpollserver_unix.go:33 +0x2d5

goroutine 24 [syscall]:
syscall.Syscall6()
    /Users/dvyukov/src/go2/src/pkg/syscall/asm_darwin_amd64.s:38 +0x5
syscall.kevent(0x9, 0x0, 0x0, 0xc20014d008, 0xa, ...)
    /Users/dvyukov/src/go2/src/pkg/syscall/zsyscall_darwin_amd64.go:199 +0x83
syscall.Kevent(0x9, 0x0, 0x0, 0x0, 0xc20014d008, ...)
    /Users/dvyukov/src/go2/src/pkg/syscall/syscall_bsd.go:554 +0x9b
net.(*pollster).WaitFD(0xc20014d000, 0xc20013c6f0, 0x0, 0x0, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/fd_darwin.go:101 +0x187
net.(*pollServer).Run(0xc20013c6f0, 0x0)
    /Users/dvyukov/src/go2/src/pkg/net/fd_unix.go:212 +0x10a
created by net.newPollServer
    /Users/dvyukov/src/go2/src/pkg/net/newpollserver_unix.go:33 +0x2d5

goroutine 6 [semacquire]:
sync.runtime_Semacquire(0xc2000b73a0, 0xc2000b73a0)
    /Users/dvyukov/src/go2/src/pkg/runtime/zsema_darwin_amd64.c:165 +0x2e
sync.(*Cond).Wait(0xc2000c0030, 0x0)
    /Users/dvyukov/src/go2/src/pkg/sync/cond.go:73 +0x95
io.(*pipe).read(0xc2000c0000, 0xc2000fa000, 0x1000, 0x1000, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/io/pipe.go:52 +0x1f2
io.(*PipeReader).Read(0xc2000b7330, 0xc2000fa000, 0x1000, 0x1000, 0x1000, ...)
    /Users/dvyukov/src/go2/src/pkg/io/pipe.go:130 +0x5d
net/http_test.func·063(0xc2000b7328, 0xc2000b7318, 0xc2000b7398, 0x0, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1046 +0x68
created by net/http_test.testHandlerPanic
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1052 +0x20c

goroutine 26 [semacquire]:
sync.runtime_Semacquire(0xc2000b7898, 0xc2000b7898)
    /Users/dvyukov/src/go2/src/pkg/runtime/zsema_darwin_amd64.c:165 +0x2e
sync.(*Cond).Wait(0xc2001400f0, 0xc2000a01c0)
    /Users/dvyukov/src/go2/src/pkg/sync/cond.go:73 +0x95
io.(*pipe).read(0xc2001400c0, 0xc20014e000, 0x1000, 0x1000, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/io/pipe.go:52 +0x1f2
io.(*PipeReader).Read(0xc2000b7828, 0xc20014e000, 0x1000, 0x1000, 0x1000, ...)
    /Users/dvyukov/src/go2/src/pkg/io/pipe.go:130 +0x5d
net/http_test.func·063(0xc2000b7820, 0xc2000b7810, 0xc2000b7890, 0x0, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1046 +0x68
created by net/http_test.testHandlerPanic
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1052 +0x20c

goroutine 44 [semacquire]:
sync.runtime_Semacquire(0xc2000b7de8, 0xc2000b7de8)
    /Users/dvyukov/src/go2/src/pkg/runtime/zsema_darwin_amd64.c:165 +0x2e
sync.(*Cond).Wait(0xc200140030, 0xc200000000)
    /Users/dvyukov/src/go2/src/pkg/sync/cond.go:73 +0x95
io.(*pipe).read(0xc200140000, 0xc200110000, 0x1000, 0x1000, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/io/pipe.go:52 +0x1f2
io.(*PipeReader).Read(0xc2000b7ca0, 0xc200110000, 0x1000, 0x1000, 0x1000, ...)
    /Users/dvyukov/src/go2/src/pkg/io/pipe.go:130 +0x5d
net/http_test.func·063(0xc2000b7ca8, 0xc2000b7cb8, 0xc2000b7098, 0x0, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1046 +0x68
created by net/http_test.testHandlerPanic
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1052 +0x20c

goroutine 50 [semacquire]:
sync.runtime_Semacquire(0xc2000b7dd0, 0xc2000b7dd0)
    /Users/dvyukov/src/go2/src/pkg/runtime/zsema_darwin_amd64.c:165 +0x2e
sync.(*Cond).Wait(0xc200165f30, 0xc2000a01c0)
    /Users/dvyukov/src/go2/src/pkg/sync/cond.go:73 +0x95
io.(*pipe).read(0xc200165f00, 0xc20011f000, 0x1000, 0x1000, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/io/pipe.go:52 +0x1f2
io.(*PipeReader).Read(0xc2000b7388, 0xc20011f000, 0x1000, 0x1000, 0x1000, ...)
    /Users/dvyukov/src/go2/src/pkg/io/pipe.go:130 +0x5d
net/http_test.func·063(0xc2000b7380, 0xc2000b7370, 0xc2000b73f8, 0x0, 0x0, ...)
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1046 +0x68
created by net/http_test.testHandlerPanic
    /Users/dvyukov/src/go2/src/pkg/net/http/serve_test.go:1052 +0x20c

[bradfitz]

Comment 1:

I can't reproduce this.
I looked at the test code and it seems fine, too.  There's a 5 second timeout, which
seems like tons of time.  But maybe try making it longer?
I get an unrelated crash after running this for awhile, though:
=== RUN TestHandlerPanic
--- PASS: TestHandlerPanic (0.00 seconds)
=== RUN TestHandlerPanic-2
--- PASS: TestHandlerPanic-2 (0.00 seconds)
=== RUN TestHandlerPanic-3
--- PASS: TestHandlerPanic-3 (0.00 seconds)
=== RUN TestHandlerPanic-4
--- PASS: TestHandlerPanic-4 (0.00 seconds)
=== RUN TestHandlerPanic-5
--- PASS: TestHandlerPanic-5 (0.00 seconds)
=== RUN TestHandlerPanic-6
--- PASS: TestHandlerPanic-6 (0.00 seconds)
panic: httptest: failed to listen on a port: listen tcp6 [::1]:0: address already in use
[recovered]
        panic: httptest: failed to listen on a port: listen tcp6 [::1]:0: address already in use
goroutine 38 [running]:
testing.func·004(0x7fba8c9bffa8, 0x7fba8c9bf100)
        /usr/local/google/home/bradfitz/go/src/pkg/testing/testing.go:310 +0xb3
net/http/httptest.newLocalListener(0x1, 0x405db2)
        /usr/local/google/home/bradfitz/go/src/pkg/net/http/httptest/server.go:68 +0x36b
net/http/httptest.NewUnstartedServer(0xc200000c30, 0xc20012ab90, 0xc20012abc0,
0xc20012ab90, 0x486d0e, ...)
        /usr/local/google/home/bradfitz/go/src/pkg/net/http/httptest/server.go:96 +0x1c
net/http/httptest.NewServer(0xc200000c30, 0xc20012ab90, 0xc2000b4778, 0xc2000b4780,
0xc20009dd20, ...)
        /usr/local/google/home/bradfitz/go/src/pkg/net/http/httptest/server.go:83 +0x2f
net/http_test.testHandlerPanic(0xc200128f30, 0x772100, 0x62faf8, 0xc20009dd10,
0xc20009dd10, ...)
        /usr/local/google/home/bradfitz/go/src/pkg/net/http/serve_test.go:1037 +0x18e
net/http_test.TestHandlerPanic(0xc200128f30, 0xc235ac4201)
        /usr/local/google/home/bradfitz/go/src/pkg/net/http/serve_test.go:1000 +0x62
testing.tRunner(0xc200128f30, 0x913c88, 0x0, 0x0)
        /usr/local/google/home/bradfitz/go/src/pkg/testing/testing.go:315 +0x6c
created by testing.RunTests
        /usr/local/google/home/bradfitz/go/src/pkg/testing/testing.go:430 +0x875

[dvyukov]

Comment 2:

Can't reproduce now as well...

Status changed to Invalid.