x/tools/cmd/gopls: data race on (*Server).client

[pwaller]

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

$ go version
go version devel +4b3f04c63b Thu Jan 10 18:15:48 2019 +0000 linux/amd64

Does this issue reproduce with the latest release?

Yes, I am testing on 7f7074d (master at time of writing) with the recent patch for URI escaping applied.

git fetch https://go.googlesource.com/tools refs/changes/77/161077/2 && git cherry-pick FETCH_HEAD

What did you do?

Compile gopls with -race. Use cmd/gopls/forward. Use vscode-go. I am working out of my $GOPATH using modules, and have GO111MODULE=on.

I then did some development using vscode and observed the crash. Afraid I don't have a precise sequence to reproduce, but I wasn't doing anything fancy beyond just using the editor to edit code and perhaps jump to definition.

What did you expect to see?

Things working as normal.

What did you see instead?

The race detector reports warnings and then some time later I also encounter a panic with a nil pointer dereference. I'm including the nil dereference since these may be related?

Nil pointer dereference panic:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x8e7976]

goroutine 20 [running]:
golang.org/x/tools/internal/lsp/cmd.(*Server).Run.func1(0xc004582700, 0xc004582440, 0xffffffffffffffff, 0xc0045568e8, 0x8, 0x0, 0x0)
	/home/pwaller/.local/src/golang.org/x/tools/internal/lsp/cmd/server.go:104 +0x306
golang.org/x/tools/internal/jsonrpc2.(*Conn).run(0xc0001a7e30, 0xa77d00, 0xc0000bc010, 0x0, 0x0)
	/home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:332 +0x895
golang.org/x/tools/internal/jsonrpc2.NewConn.func4(0xc0001a7e30, 0xa77d00, 0xc0000bc010)
	/home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:110 +0x51
created by golang.org/x/tools/internal/jsonrpc2.NewConn
	/home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:109 +0x261

Data race warnings:

==================
WARNING: DATA RACE
Read at 0x00c00010e640 by goroutine 9:
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:29 +0x11b

Previous write at 0x00c00010e640 by goroutine 7:
  golang.org/x/tools/internal/lsp.RunServerOnPort.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:51 +0xfc

Goroutine 9 (running) created at:
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:23 +0x14e
  golang.org/x/tools/internal/lsp.(*server).DidOpen()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:176 +0xae
  golang.org/x/tools/internal/lsp/protocol.serverHandler.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/server.go:147 +0x1e37
  golang.org/x/tools/internal/jsonrpc2.(*Conn).run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:321 +0xa39
  golang.org/x/tools/internal/jsonrpc2.NewConn.func4()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:110 +0x50

Goroutine 7 (running) created at:
  golang.org/x/tools/internal/lsp.RunServerOnPort()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:48 +0x2a7
  golang.org/x/tools/internal/lsp/cmd.(*Server).Run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/cmd/server.go:113 +0x1f5
  golang.org/x/tools/internal/tool.Main.func2()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:130 +0xb6
  golang.org/x/tools/internal/tool.Main()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:131 +0x29f
  golang.org/x/tools/internal/lsp/cmd.(*Application).Run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/cmd/cmd.go:67 +0x546
  golang.org/x/tools/internal/tool.Main.func2()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:130 +0xb6
  golang.org/x/tools/internal/tool.Main()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:131 +0x29f
  main.main()
      /home/pwaller/.local/src/golang.org/x/tools/cmd/gopls/main.go:20 +0x128
==================
==================
WARNING: DATA RACE
Read at 0x00c000102098 by goroutine 9:
  golang.org/x/tools/internal/lsp/protocol.(*clientDispatcher).PublishDiagnostics()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/client.go:188 +0x3e
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:29 +0x15b

Previous write at 0x00c000102098 by goroutine 7:
  golang.org/x/tools/internal/lsp/protocol.RunServer()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/protocol.go:27 +0x1a6
  golang.org/x/tools/internal/lsp.RunServerOnPort.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:49 +0xb7

Goroutine 9 (running) created at:
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:23 +0x14e
  golang.org/x/tools/internal/lsp.(*server).DidOpen()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:176 +0xae
  golang.org/x/tools/internal/lsp/protocol.serverHandler.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/server.go:147 +0x1e37
  golang.org/x/tools/internal/jsonrpc2.(*Conn).run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:321 +0xa39
  golang.org/x/tools/internal/jsonrpc2.NewConn.func4()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:110 +0x50

Goroutine 7 (running) created at:
  golang.org/x/tools/internal/lsp.RunServerOnPort()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:48 +0x2a7
  golang.org/x/tools/internal/lsp/cmd.(*Server).Run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/cmd/server.go:113 +0x1f5
  golang.org/x/tools/internal/tool.Main.func2()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:130 +0xb6
  golang.org/x/tools/internal/tool.Main()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:131 +0x29f
  golang.org/x/tools/internal/lsp/cmd.(*Application).Run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/cmd/cmd.go:67 +0x546
  golang.org/x/tools/internal/tool.Main.func2()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:130 +0xb6
  golang.org/x/tools/internal/tool.Main()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:131 +0x29f
  main.main()
      /home/pwaller/.local/src/golang.org/x/tools/cmd/gopls/main.go:20 +0x128
==================
==================
WARNING: DATA RACE
Write at 0x00c00010e668 by goroutine 8:
  golang.org/x/tools/internal/lsp.(*server).setContent()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:44 +0x128
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:20 +0xea
  golang.org/x/tools/internal/lsp.(*server).DidOpen()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:176 +0xae
  golang.org/x/tools/internal/lsp/protocol.serverHandler.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/server.go:147 +0x1e37
  golang.org/x/tools/internal/jsonrpc2.(*Conn).run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:321 +0xa39
  golang.org/x/tools/internal/jsonrpc2.NewConn.func4()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:110 +0x50

Previous read at 0x00c00010e668 by goroutine 9:
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:31 +0x218

Goroutine 8 (running) created at:
  golang.org/x/tools/internal/jsonrpc2.NewConn()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:109 +0x260
  golang.org/x/tools/internal/lsp/protocol.RunServer()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/protocol.go:26 +0x179
  golang.org/x/tools/internal/lsp.RunServerOnPort.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:49 +0xb7

Goroutine 9 (running) created at:
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:23 +0x14e
  golang.org/x/tools/internal/lsp.(*server).DidOpen()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:176 +0xae
  golang.org/x/tools/internal/lsp/protocol.serverHandler.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/server.go:147 +0x1e37
  golang.org/x/tools/internal/jsonrpc2.(*Conn).run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:321 +0xa39
  golang.org/x/tools/internal/jsonrpc2.NewConn.func4()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:110 +0x50
==================

/cc @stamblerre

[gopherbot]

Change https://golang.org/cl/161220 mentions this issue: internal/lsp/cmd: some minor clean-up and fixes

[pwaller]

I just had another go and the race is still present after 40960b6.

I think I understand the race and the nil pointer dereference.

1. The client field of the server is set once the connection is constructed:

   • RunServer
   • RunServerOnPort

2. The s.client field of the server is used during request handling for PublishDiagnostics.

The problem AIUI is that (2) can happen before (1), currently. The reason is that protocol.RunServer constructs the client (the return value) only after calling jsonrpc2.NewConn. The consequence is that messages are being processed before the client field is set, and this field is used to run PublishDiagnostics.

Solving this looks a little tricky. It seems designed with interfaces in such a way that it is difficult to construct the client and server simultaneously and have them know about each other before beginning to handle messages.

One potential approach that comes to mind would be to build something out of channels, so that PublishDiagnostics resulted in request/response channels being used internally, usiong a goroutine reading off that channel only once the client has been constructed. This would cause PublishDiagnostics to naturally block until the goroutine handling the client was ready, and reduce the possibility of a race.

[stamblerre]

Thanks for the report and for diagnosing the issue! Adding @ianthehat on this for a decision.

[pwaller]

Ping @ianthehat.

I've upgraded gopls recently for the memory improvements in #30309, but now this is not just a race but regularly crashing the server. I am using the -remote feature.

Here is a stack trace captured from current gotools master.

==================
WARNING: DATA RACE
Read at 0x00c00007ad40 by goroutine 9:
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:33 +0x16e

Previous write at 0x00c00007ad40 by goroutine 7:
  golang.org/x/tools/internal/lsp.RunServerOnAddress.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:57 +0xdd

Goroutine 9 (running) created at:
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:23 +0x183
  golang.org/x/tools/internal/lsp.(*server).DidOpen()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:184 +0xae
  golang.org/x/tools/internal/lsp/protocol.serverHandler.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/server.go:144 +0x1d94
  golang.org/x/tools/internal/jsonrpc2.(*Conn).run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:315 +0x940
  golang.org/x/tools/internal/jsonrpc2.NewConn.func4()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:107 +0x50

Goroutine 7 (running) created at:
  golang.org/x/tools/internal/lsp.RunServerOnAddress()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:55 +0x1b8
  golang.org/x/tools/internal/lsp.RunServerOnPort()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:38 +0xd2
  golang.org/x/tools/internal/lsp/cmd.(*Serve).Run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/cmd/serve.go:126 +0x6a4
  golang.org/x/tools/internal/tool.Main.func2()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:130 +0xb6
  golang.org/x/tools/internal/tool.Main()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:131 +0x29f
  golang.org/x/tools/internal/lsp/cmd.(*Application).Run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/cmd/cmd.go:75 +0x614
  golang.org/x/tools/internal/tool.Main.func2()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:130 +0xb6
  golang.org/x/tools/internal/tool.Main()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:131 +0x29f
  main.main()
      /home/pwaller/.local/src/golang.org/x/tools/cmd/gopls/main.go:20 +0x133
==================
==================
WARNING: DATA RACE
Read at 0x00c0000100e8 by goroutine 9:
  golang.org/x/tools/internal/lsp/protocol.(*clientDispatcher).PublishDiagnostics()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/client.go:186 +0x3e
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:33 +0x1ab

Previous write at 0x00c0000100e8 by goroutine 7:
  golang.org/x/tools/internal/lsp/protocol.RunServer()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/protocol.go:27 +0x1a6
  golang.org/x/tools/internal/lsp.RunServerOnAddress.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:56 +0xac

Goroutine 9 (running) created at:
  golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:23 +0x183
  golang.org/x/tools/internal/lsp.(*server).DidOpen()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:184 +0xae
  golang.org/x/tools/internal/lsp/protocol.serverHandler.func1()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/protocol/server.go:144 +0x1d94
  golang.org/x/tools/internal/jsonrpc2.(*Conn).run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:315 +0x940
  golang.org/x/tools/internal/jsonrpc2.NewConn.func4()
      /home/pwaller/.local/src/golang.org/x/tools/internal/jsonrpc2/jsonrpc2.go:107 +0x50

Goroutine 7 (running) created at:
  golang.org/x/tools/internal/lsp.RunServerOnAddress()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:55 +0x1b8
  golang.org/x/tools/internal/lsp.RunServerOnPort()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/server.go:38 +0xd2
  golang.org/x/tools/internal/lsp/cmd.(*Serve).Run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/cmd/serve.go:126 +0x6a4
  golang.org/x/tools/internal/tool.Main.func2()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:130 +0xb6
  golang.org/x/tools/internal/tool.Main()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:131 +0x29f
  golang.org/x/tools/internal/lsp/cmd.(*Application).Run()
      /home/pwaller/.local/src/golang.org/x/tools/internal/lsp/cmd/cmd.go:75 +0x614
  golang.org/x/tools/internal/tool.Main.func2()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:130 +0xb6
  golang.org/x/tools/internal/tool.Main()
      /home/pwaller/.local/src/golang.org/x/tools/internal/tool/tool.go:131 +0x29f
  main.main()
      /home/pwaller/.local/src/golang.org/x/tools/cmd/gopls/main.go:20 +0x133
==================
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x8926dc]

goroutine 2334 [running]:
golang.org/x/tools/internal/lsp/source.Diagnostics(0xaf6b00, 0xc00931bb00, 0xaf6c80, 0xc004cfca80, 0xc0092f2f00, 0x3a, 0xc005f8c460, 0xc0090a0000, 0x0)
	/home/pwaller/.local/src/golang.org/x/tools/internal/lsp/source/diagnostics.go:64 +0xec
golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose.func1(0xc00007ad40, 0xc0092f2f00, 0x3a)
	/home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:28 +0x107
created by golang.org/x/tools/internal/lsp.(*server).cacheAndDiagnose
	/home/pwaller/.local/src/golang.org/x/tools/internal/lsp/diagnostics.go:23 +0x184

[stamblerre]

@pwaller: does gopls consistently crash for you if you don't compile with -race? I think the nil pointer you are seeing may be unrelated.

[ianthehat]

Using -remote is not a supported way of running gopls, it's very experimental but I added it specifically to allow us to debug this race condition (along with other things of that nature)
I am working on a fix for race conditions, but I am trying to get to the point where I have a unit test that reliably produces them first.
Unfortunately I have not had much time for actual coding recently, hopefully this week I will get a bit more time.