x/tools/gopls: rapid changes cause errors, context cancellation

[stamblerre]

Forked from #32667 (comment).

I'm seeing this in a module context. In my situation, there are a number of relatively rapid changes to certain files (a code generator is the source of the changes, but the changes are notified to gopls via didChange notifications).

I first see a number of lines like:

unable to check package for file:///path/to/file.go: context canceled

I also see a number of lines like:

failed to deliver diagnostic for file:///path/to/file.go (will retry): context canceled

Then I see a number of lines like:

unable to check package for file:///path/to/file.go: loadParseTypeCheck: no package found for /path/to/file.go

I also see a number of lines like:

file:///path/to/file.go is not part of a package

I don't yet have a repro for this.

---

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

$ go version
go version go1.12.6 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20190618233249-04b924abaa25
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.0.0-20190618233249-04b924abaa25

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GOARCH="amd64"
GOBIN="/home/myitcv/gostuff/src/github.com/myitcv/govim/cmd/govim/.bin"
GOCACHE="/home/myitcv/.cache/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/home/myitcv/gostuff"
GOPROXY=""
GORACE=""
GOROOT="/home/myitcv/gos"
GOTMPDIR=""
GOTOOLDIR="/home/myitcv/gos/pkg/tool/linux_amd64"
GCCGO="gccgo"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/myitcv/gostuff/src/github.com/myitcv/govim/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build453321011=/tmp/go-build -gno-record-gcc-switches"

FWIW this was also an issue with:

golang.org/x/tools v0.0.0-20190612231717-10539ce30318
golang.org/x/tools/gopls v0.1.0

[myitcv]

Per discussions with @stamblerre and @ianthehat on Slack, I suspect the issue here is something along the lines of:

• lots of didOpen/didChange notifications because of the code generation
• gopls cancels the handling/something of one/more of these notifications because of #reasons (hence the context canceled messages)
• this leaves gopls in a bad state for the file in question
• we get the subsequent error messages:

/path/to/file is not part of a package

[muirdm]

This change fixed a similar issue. Are you still seeing this failure?

[myitcv]

I still see the errors mentioned in #32899 (comment) as of fb37f6b. The tricky thing is, this is very much a timing related issue... so I can't reproduce it reliably.

I can't test much beyond that because https://go-review.googlesource.com/c/tools/+/184257 appears to have introduced some sort of bug/issue whereby trying to call goimports (i.e. the code action) after the steps above causes gopls to hang (or it was hung up before I tried to call it, not sure).

Stack trace of that hang:

https://gist.github.com/myitcv/9d1f257c32e1cddde1589c63d34c9a0e

[stamblerre]

Oh, I expect you are seeing the issues fixed by @muirrn here: https://go-review.googlesource.com/c/tools/+/184880.

[myitcv]

Thanks, yes that did fix the hang. I'll monitor 504de27 and feedback here if I do/don't see any occurrences of the context cancellation issue.

[stamblerre]

@myitcv: Any updates here? Can we close this issue?

[ereslibre]

Hello!

I'm using gopls at revision 128824a23e7c038a341252700f1001ad29ef1988 and I'm consistently seeing this issue. I can reproduce on the Kubernetes codebase almost everytime, and when restarting gopls it happens again when I interact after some seconds. It happens specially when going back and forth (I'm using lsp-mode on emacs), so if I somewhat in a fast fashion do M-., M-,, and M-. again I get GetAST: unable to check package for file:///path/to/existing/go/file.go: no packages found for file:///path/to/existing/go/file.go.

~/p/g/s/g/x/tools (master) > gopls version
golang.org/x/tools/cmd/gopls v0.1.3-cmd.gopls
    golang.org/x/tools@(devel)

I'm fairly new to gopls, so please tell me if there's a way I can be more helpful :)

[stamblerre]

@ereslibre: To confirm my understanding, does gopls work fine on this codebase until you send a large number of commands? Could you share a specific repro case for this?

[ereslibre]

@ereslibre: To confirm my understanding, does gopls work fine on this codebase until you send a large number of commands? Could you share a specific repro case for this?

I tried with master and I couldn't easily reproduce, so I will point to a way I can reproduce 100% with a couple of keystrokes.

If you checkout https://github.com/ereslibre/kubernetes, the ping-on-long-running-commands branch, I do the following:

• Open /staging/src/k8s.io/kubectl/pkg/cmd/logs/logs.go (I do C-c p f with projectile and kubectl logs.go)
• Navigate to line 380; visit StreamWithPing (M-.)
• Go back (M-,)
• Try to visit StreamWithPing again (M-.)

Error: GetAST: unable to check package for...
If I restart gopls with M-x lsp-restart-workspace, same thing, I can visit it once, go back, and when visiting again it will fail again.

Sorry, is the best I have :(

[ereslibre]

Murphy's law, now I can go back and forth without any issue after the last restart.

Edit: I still get it sometimes, I just cannot understand the pattern. If I can use gopls with some flags that can output some information when that happens I can provide those logs.

Edit: starting from a clean slate always gives me this issue the first time; after a restart sometimes I get it and sometimes I don't, I have to navigate a little more to trigger it.

[stamblerre]

I was actually able to reproduce this issue myself in VSCode. Thanks for sharing the info - I will file a separate issue (#33551) because this sounds like a specific issue with the Kubernetes repository.

[ereslibre]

Thanks a lot @stamblerre!

[myitcv]

@stamblerre - I'm definitely seeing issues with 6d4652c779c4. Whether it's related to this issue or not, gopls simply dies. I'll try and take a look today.

[myitcv]

Turns out that issue was unrelated. Also looks (from a very unscientific couple of attempts to try and repro the issue) like things are "fixed" (just tested against 6d4652c)

Will close for now; we can always re-open if this rears its head again.