search

sourcegraph / go-langserver

Go language server to add Go support to editors and other tools that use the Language Server Protocol (LSP)
https://sourcegraph.com
MIT License
1.17k stars 89 forks source link

Prevent deadlock in reading notifications for integration test #303

Closed keegancsmith closed 6 years ago

keegancsmith commented 6 years ago

Sweet, reproduced on the first try. Looks like a deadlock in the go runtime, which is rather strange. Might be something unique to the travis CI environment.

$ ./ci-run-tests.sh
?       github.com/sourcegraph/go-langserver    [no test files]
SIGABRT: abort
PC=0x4587d1 m=0 sigcode=0
goroutine 0 [idle]:
runtime.futex(0xb099c8, 0x0, 0x0, 0x0, 0x7fff00000000, 0x430f18, 0x0, 0x0, 0x7fff6352bb48, 0x4108cb, ...)
    /usr/local/go/src/runtime/sys_linux_amd64.s:530 +0x21
runtime.futexsleep(0xb099c8, 0x7fff00000000, 0xffffffffffffffff)
    /usr/local/go/src/runtime/os_linux.go:45 +0x4b
runtime.notesleep(0xb099c8)
    /usr/local/go/src/runtime/lock_futex.go:151 +0x9b
runtime.stoplockedm()
    /usr/local/go/src/runtime/proc.go:2101 +0x8c
runtime.schedule()
    /usr/local/go/src/runtime/proc.go:2493 +0x2da
runtime.park_m(0xc420225380)
    /usr/local/go/src/runtime/proc.go:2604 +0xb6
runtime.mcall(0x0)
    /usr/local/go/src/runtime/asm_amd64.s:351 +0x5b
goroutine 1 [semacquire, 5 minutes]:
sync.runtime_Semacquire(0xc42062afec)
    /usr/local/go/src/runtime/sema.go:56 +0x39
sync.(*WaitGroup).Wait(0xc42062afe0)
    /usr/local/go/src/sync/waitgroup.go:129 +0x72
cmd/go/internal/work.(*Builder).Do(0xc420234e60, 0xc4205c32c0)
    /usr/local/go/src/cmd/go/internal/work/exec.go:173 +0x3b0
cmd/go/internal/test.runTest(0xaff700, 0xc42001e160, 0x3, 0x3)
    /usr/local/go/src/cmd/go/internal/test/test.go:760 +0x100f
main.main()
    /usr/local/go/src/cmd/go/main.go:140 +0x7e1
goroutine 5 [syscall, 5 minutes]:
os/signal.signal_recv(0x0)
    /usr/local/go/src/runtime/sigqueue.go:139 +0xa6
os/signal.loop()
    /usr/local/go/src/os/signal/signal_unix.go:22 +0x22
created by os/signal.init.0
    /usr/local/go/src/os/signal/signal_unix.go:28 +0x41
goroutine 7 [select, 4 minutes]:
cmd/go/internal/work.(*Builder).Do.func2(0xc42062afe0, 0xc420234e60, 0xc42035e0e0)
    /usr/local/go/src/cmd/go/internal/work/exec.go:154 +0x161
created by cmd/go/internal/work.(*Builder).Do
    /usr/local/go/src/cmd/go/internal/work/exec.go:151 +0x38c
goroutine 8 [select, 4 minutes]:
cmd/go/internal/test.(*runCache).builderRunTest(0xc420667e00, 0xc420234e60, 0xc42038d2c0, 0x0, 0x0)
    /usr/local/go/src/cmd/go/internal/test/test.go:1282 +0xfe0
cmd/go/internal/test.(*runCache).(cmd/go/internal/test.builderRunTest)-fm(0xc420234e60, 0xc42038d2c0, 0x5b3cb3, 0xc420234ed0)
    /usr/local/go/src/cmd/go/internal/test/test.go:998 +0x3e
cmd/go/internal/work.(*Builder).Do.func1(0xc42038d2c0)
    /usr/local/go/src/cmd/go/internal/work/exec.go:106 +0x72
cmd/go/internal/work.(*Builder).Do.func2(0xc42062afe0, 0xc420234e60, 0xc42035e0e0)
    /usr/local/go/src/cmd/go/internal/work/exec.go:164 +0xbb
created by cmd/go/internal/work.(*Builder).Do
    /usr/local/go/src/cmd/go/internal/work/exec.go:151 +0x38c
goroutine 82 [select, 4 minutes, locked to thread]:
runtime.gopark(0x8d9540, 0x0, 0x8aad5c, 0x6, 0x18, 0x1)
    /usr/local/go/src/runtime/proc.go:291 +0x11a
runtime.selectgo(0xc42004e750, 0xc4206627e0)
    /usr/local/go/src/runtime/select.go:392 +0xe50
runtime.ensureSigM.func1()
    /usr/local/go/src/runtime/signal_unix.go:549 +0x1f4
runtime.goexit()
    /usr/local/go/src/runtime/asm_amd64.s:2361 +0x1
goroutine 83 [chan receive, 4 minutes]:
cmd/go/internal/base.processSignals.func1(0xc4206626c0)
    /usr/local/go/src/cmd/go/internal/base/signal.go:21 +0x34
created by cmd/go/internal/base.processSignals
    /usr/local/go/src/cmd/go/internal/base/signal.go:20 +0x93
goroutine 85 [IO wait, 4 minutes]:
internal/poll.runtime_pollWait(0x7fb1c8642c50, 0x72, 0xc4206184e8)
    /usr/local/go/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc420250608, 0x72, 0xffffffffffffff01, 0x911660, 0xac95b0)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:85 +0x9b
internal/poll.(*pollDesc).waitRead(0xc420250608, 0xc42030ae01, 0xf0d, 0xf0d)
    /usr/local/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc4202505f0, 0xc42030aef3, 0xf0d, 0xf0d, 0x0, 0x0, 0x0)
    /usr/local/go/src/internal/poll/fd_unix.go:157 +0x17d
os.(*File).read(0xc4201f6050, 0xc42030aef3, 0xf0d, 0xf0d, 0xaf, 0x0, 0x0)
    /usr/local/go/src/os/file_unix.go:226 +0x4e
os.(*File).Read(0xc4201f6050, 0xc42030aef3, 0xf0d, 0xf0d, 0xaf, 0x0, 0x0)
    /usr/local/go/src/os/file.go:107 +0x6a
bytes.(*Buffer).ReadFrom(0xc4200c4000, 0x910b60, 0xc4201f6050, 0x7fb1c868d7d0, 0xc4200c4000, 0xa0a2e656c696601)
    /usr/local/go/src/bytes/buffer.go:205 +0xa0
io.copyBuffer(0x9102c0, 0xc4200c4000, 0x910b60, 0xc4201f6050, 0x0, 0x0, 0x0, 0x660a, 0x0, 0x0)
    /usr/local/go/src/io/io.go:386 +0x31a
io.Copy(0x9102c0, 0xc4200c4000, 0x910b60, 0xc4201f6050, 0x0, 0x0, 0x0)
    /usr/local/go/src/io/io.go:362 +0x5a
os/exec.(*Cmd).writerDescriptor.func1(0x0, 0x0)
    /usr/local/go/src/os/exec/exec.go:275 +0x4d
os/exec.(*Cmd).Start.func1(0xc420615600, 0xc420566160)
    /usr/local/go/src/os/exec/exec.go:396 +0x27
created by os/exec.(*Cmd).Start
    /usr/local/go/src/os/exec/exec.go:395 +0x5df
goroutine 86 [syscall, 4 minutes]:
syscall.Syscall6(0xf7, 0x1, 0xa0a, 0xc420618dd0, 0x1000004, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/local/go/src/syscall/asm_linux_amd64.s:44 +0x5
os.(*Process).blockUntilWaitable(0xc4202cedb0, 0x6e756f6620656220, 0x656874206e692064, 0x45534e4543494c20)
    /usr/local/go/src/os/wait_waitid.go:31 +0x98
os.(*Process).wait(0xc4202cedb0, 0x74726f706d690a0a, 0x74796222090a2820, 0x726522090a227365)
    /usr/local/go/src/os/exec_unix.go:22 +0x3c
os.(*Process).Wait(0xc4202cedb0, 0x90a22736f22090a, 0x69662f6874617022, 0xa2268746170656c)
    /usr/local/go/src/os/exec.go:123 +0x2b
os/exec.(*Cmd).Wait(0xc420615600, 0x6170206568742064, 0x616e206567616b63)
    /usr/local/go/src/os/exec/exec.go:461 +0x5c
cmd/go/internal/test.(*runCache).builderRunTest.func1(0xc4202461e0, 0xc420615600)
    /usr/local/go/src/cmd/go/internal/test/test.go:1279 +0x2b
created by cmd/go/internal/test.(*runCache).builderRunTest
    /usr/local/go/src/cmd/go/internal/test/test.go:1278 +0xf1a
keegancsmith commented 6 years ago

I realised that go test probably has a child. So I actually need to sigabrt the actual test process. Maybe I am overengineering and should just try out the timeout flag.

keegancsmith commented 6 years ago

Ok, so it seems to be a deadlock in the update diagnostics test.

=== RUN   TestIntegration_FileSystem_Diagnostics
panic: test timed out after 5m0s

goroutine 109 [running]:
testing.(*M).startAlarm.func1()
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/testing/testing.go:1240 +0x146
created by time.goFunc
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/time/sleep.go:172 +0x52

goroutine 1 [chan receive, 4 minutes]:
testing.(*T).Run(0xc4202a4000, 0xdf37e3, 0x26, 0xe06a70, 0xc4200f3c01)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/testing/testing.go:825 +0x597
testing.runTests.func1(0xc4202a4000)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/testing/testing.go:1063 +0xa5
testing.tRunner(0xc4202a4000, 0xc4200f3db0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/testing/testing.go:777 +0x16e
testing.runTests(0xc42000dd00, 0x1241de0, 0x11, 0x11, 0xc420270280)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/testing/testing.go:1061 +0x4e2
testing.(*M).Run(0xc420270280, 0x0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/testing/testing.go:978 +0x2ce
main.main()
        _testmain.go:76 +0x22b

goroutine 94 [IO wait, 4 minutes]:
internal/poll.runtime_pollWait(0x7fee66b42f00, 0x72, 0xc42005ec98)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/runtime/netpoll.go:173 +0x5e
internal/poll.(*pollDesc).wait(0xc420270018, 0x72, 0xc4201b6100, 0x0, 0x0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/internal/poll/fd_poll_runtime.go:85 +0xe5
internal/poll.(*pollDesc).waitRead(0xc420270018, 0xffffffffffffff00, 0x0, 0x0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/internal/poll/fd_poll_runtime.go:90 +0x4b
internal/poll.(*FD).Accept(0xc420270000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/internal/poll/fd_unix.go:372 +0x2e2
net.(*netFD).accept(0xc420270000, 0xc42005ee58, 0xc42005ee60, 0x18)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/net/fd_unix.go:238 +0x53
net.(*TCPListener).accept(0xc42000e050, 0xea2580, 0xc4200a8050, 0x0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/net/tcpsock_posix.go:136 +0x4e
net.(*TCPListener).Accept(0xc42000e050, 0xc4200a8050, 0xea07c0, 0xc4203780c0, 0xe9af40)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/net/tcpsock.go:259 +0x50
github.com/sourcegraph/go-langserver/langserver.serve(0xea2580, 0xc4200a8050, 0xea14c0, 0xc42000e050, 0xe9af40, 0xc42042c100, 0x0, 0x0, 0x0, 0x56bfec, ...)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/langserver_test.go:1277 +0xfb
github.com/sourcegraph/go-langserver/langserver.startServer.func1(0xea14c0, 0xc42000e050, 0xe9af40, 0xc42042c100, 0xea79a0, 0xc4202ac000)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/langserver_test.go:1264 +0xa6
created by github.com/sourcegraph/go-langserver/langserver.startServer
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/langserver_test.go:1263 +0x1e3

goroutine 3 [chan receive, 4 minutes]:
github.com/sourcegraph/go-langserver/langserver/internal/gocode.new_file_reader.func1(0xc42000e018)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/internal/gocode/utils.go:229 +0x93
created by github.com/sourcegraph/go-langserver/langserver/internal/gocode.new_file_reader
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/internal/gocode/utils.go:226 +0xae

goroutine 93 [select, 4 minutes]:
github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2.(*Conn).Call(0xc420270300, 0xea2580, 0xc4200a8050, 0xdd3ccf, 0x14, 0xd1cb20, 0xc4200a05a0, 0x0, 0x0, 0x0, ...)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2/jsonrpc2.go:426 +0x388
github.com/sourcegraph/go-langserver/langserver.callFn.func1(0xdd3ccf, 0x14, 0xd1cb20, 0xc4200a05a0)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/integration_test.go:393 +0xc2
github.com/sourcegraph/go-langserver/langserver.TestIntegration_FileSystem_Diagnostics.func1(0xea2580, 0xc4200a8050, 0xc420418c00, 0x40, 0xc420270300, 0xc420034360)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/integration_test.go:268 +0xa23
github.com/sourcegraph/go-langserver/langserver.integrationTest(0xc4202ac000, 0xc42033dcf8, 0xc42033dd28, 0xc42033dce0)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/integration_test.go:388 +0xe4a
github.com/sourcegraph/go-langserver/langserver.TestIntegration_FileSystem_Diagnostics(0xc4202ac000)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/integration_test.go:207 +0x384
testing.tRunner(0xc4202ac000, 0xe06a70)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/testing/testing.go:777 +0x16e
created by testing.(*T).Run
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/testing/testing.go:824 +0x565

goroutine 96 [chan send, 4 minutes]:
github.com/sourcegraph/go-langserver/langserver.integrationTest.func1(0xea2580, 0xc4200a8050, 0xc420270300, 0xc4204494a0, 0x12b, 0xc4203374a0, 0xc42040d124, 0x438eca)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/integration_test.go:360 +0x56
github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2.(*HandlerWithErrorConfigurer).Handle(0xc42042c130, 0xea2580, 0xc4200a8050, 0xc420270300, 0xc4204494a0)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2/handler_with_error.go:21 +0x98
github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2.(*Conn).readMessages(0xc420270300, 0xea2580, 0xc4200a8050)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2/jsonrpc2.go:511 +0x132
created by github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2.NewConn
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2/jsonrpc2.go:328 +0x213

goroutine 95 [IO wait, 4 minutes]:
internal/poll.runtime_pollWait(0x7fee66b42af0, 0x72, 0x120a648)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/runtime/netpoll.go:173 +0x5e
internal/poll.(*pollDesc).wait(0xc420270198, 0x72, 0xe9b500, 0x120a648, 0xffffffffffffffff)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/internal/poll/fd_poll_runtime.go:85 +0xe5
internal/poll.(*pollDesc).waitRead(0xc420270198, 0xc42027b000, 0x1000, 0x1000)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/internal/poll/fd_poll_runtime.go:90 +0x4b
internal/poll.(*FD).Read(0xc420270180, 0xc42027b000, 0x1000, 0x1000, 0x0, 0x0, 0x0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/internal/poll/fd_unix.go:157 +0x22a
net.(*netFD).Read(0xc420270180, 0xc42027b000, 0x1000, 0x1000, 0xc420378080, 0xc420421950, 0x8bd84d)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/net/fd_unix.go:202 +0x66
net.(*conn).Read(0xc42000e070, 0xc42027b000, 0x1000, 0x1000, 0xc4203780f0, 0x0, 0x0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/net/net.go:176 +0x85
bufio.(*Reader).fill(0xc4203b2000)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/bufio/bufio.go:100 +0x1a0
bufio.(*Reader).ReadSlice(0xc4203b2000, 0x7fee66c4e00d, 0x0, 0x0, 0x4, 0x40, 0x0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/bufio/bufio.go:341 +0x4b
bufio.(*Reader).ReadBytes(0xc4203b2000, 0xc420378d0d, 0x0, 0x0, 0x0, 0x0, 0xc4203cf108)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/bufio/bufio.go:419 +0x83
bufio.(*Reader).ReadString(0xc4203b2000, 0xcf8d0d, 0xc42042c610, 0x465b54, 0x4159b0, 0x0)
        /home/travis/.gimme/versions/go1.10.3.linux.amd64/src/bufio/bufio.go:459 +0x46
github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2.VSCodeObjectCodec.ReadObject(0xc4203b2000, 0xcf8d00, 0xc42042c680, 0xc420055000, 0xc4203ccaf0)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2/stream.go:136 +0x5d
github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2.(*bufferedObjectStream).ReadObject(0xc4203780c0, 0xcf8d00, 0xc42042c680, 0xc420270200, 0xc4203ccaf0)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2/stream.go:63 +0x87
github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2.(*Conn).readMessages(0xc420270200, 0xea2580, 0xc4200a8050)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2/jsonrpc2.go:501 +0x1df
created by github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2.NewConn
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/vendor/github.com/sourcegraph/jsonrpc2/jsonrpc2.go:328 +0x213

goroutine 114 [chan receive, 4 minutes]:
github.com/sourcegraph/go-langserver/langserver.(*HandlerCommon).InitTracer.func1(0xc420270200, 0xc42042c1c0)
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/tracing.go:37 +0x5c
created by github.com/sourcegraph/go-langserver/langserver.(*HandlerCommon).InitTracer
        /home/travis/gopath/src/github.com/sourcegraph/go-langserver/langserver/tracing.go:36 +0x41e
FAIL    github.com/sourcegraph/go-langserver/langserver 300.444s
lloiser commented 6 years ago

interesting that this fixes the deadlock. I had clearly some problems with a buffered channel... I will try it on my machine later.