x/tools/gopls: "no ParseGoHandle for file.go" error from CodeAction

[myitcv]

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

$ go version
go version devel +d2de9bd59c Thu Jan 16 04:02:37 2020 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20200116181651-872a348c3885
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.1.8-0.20200116181651-872a348c3885

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
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/myitcv/.cache/go-build"
GOENV="/home/myitcv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/myitcv/gostuff"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/myitcv/gos"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/myitcv/gos/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
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-build746032130=/tmp/go-build -gno-record-gcc-switches"

What did you do?

This looks very similar to #35638.

govim has a test that starts with the following setup:

-- go.mod --
module mod.com

go 1.12
-- main.go --
package main

func main() {
}

We then create a new buffer in Vim called const.go which is initially empty. No file exists on disk at this point.

Then we populate the buffer with:

  
package main

Note the leading blank line.

Then we save const.go. This triggers CodeAction (to fix imports) followed by (assuming there was no error from the previous step) Formatting.

However we are seeing an error from the call to CodeAction:

2020-01-16T19:52:05.304899_#16: gopls.CodeAction() return; err: getting file for AllImportsFixes: no ParseGoHandle for file:///artefacts/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go; res:

gopls.log

For some reason this is only triggering in our -race tests. But still, worth flagging because this looks, from the logs, like a genuine error.

Related to #35694

What did you expect to see?

No error from CodeAction, then the call to Formatting to succeed.

What did you see instead?

As above.

---

cc @stamblerre

FYI @leitzler

[myitcv]

To add a bit of colour, contrasting between a run of this test that succeeds and fails.

Here is a section of the gopls.log file when the test passes:

[Trace - 20:07:56.762 PM] Sending request 'textDocument/codeAction - (2)'.
Params: {"textDocument":{"uri":"file:///tmp/blah/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go"},"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"context":{"diagnostics":null}}


[Trace - 20:07:56.806 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/16 20:07:56 using the -modfile flag is disabled\n\tdirectory = file:///tmp/blah/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package"}


[Trace - 20:07:56.923 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/16 20:07:56 go/packages.Load\n\tquery = [./... builtin]\n\tpackages = 2"}


[Trace - 20:07:57.164 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/16 20:07:57 go/packages.Load\n\tquery = [file=/tmp/blah/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go]\n\tpackages = 1"}


[Trace - 20:07:57.164 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/16 20:07:57 go/packages.Load\n\tpackage = mod.com\n\tfiles = [/tmp/blah/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/main.go /tmp/blah/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go]"}


[Trace - 20:07:57.175 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/16 20:07:57 go/packages.Load\n\tquery = [./...]\n\tpackages = 1"}


[Trace - 20:07:57.180 PM] Received response 'textDocument/codeAction - (2)' in 417ms.
Result: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"documentChanges":[{"textDocument":{"version":2,"uri":"file:///tmp/blah/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go"},"edits":[{"range":{"start":{"line":0,"character":0},"end":{"line":1,"character":0}},"newText":""}]}]}}]

success.log

Now the failure case:

[Trace - 19:52:05.241 PM] Sending request 'textDocument/codeAction - (2)'.
Params: {"textDocument":{"uri":"file:///artefacts/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go"},"range":{"start":{"line":0,"character":0},"end":{"line":0,"character":0}},"context":{"diagnostics":null}}


[Error - 19:52:05.303 PM] Received #2 getting file for AllImportsFixes: no ParseGoHandle for file:///artefacts/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go


[Trace - 19:52:05.303 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/16 19:52:05 go/packages.Load\n\tquery = [file=/artefacts/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go]\n\tpackages = 1"}


[Trace - 19:52:05.304 PM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/01/16 19:52:05 go/packages.Load\n\tpackage = mod.com\n\tfiles = [/artefacts/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/main.go /artefacts/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go]"}


[Trace - 19:52:05.312 PM] Sending notification 'textDocument/didSave'.
Params: {"textDocument":{"version":2,"uri":"file:///artefacts/govim/cmd/govim-race/scenario_default/script-format_on_save_new_file_existing_package/const.go"}}

fail.log

Notice in the failure case there are no go/packages calls attempted before a failure is returned. Whereas in the success case, the call to CodeAction appears to trigger a call.

This could of course be a coincidence and the success/failure might be entirely a function of the CodeAction call racing with something that has previously been triggered (as a result of the DidChange) but not yet completed.

[myitcv]

Further context, this test failure appears to have been introduced as a result of our upgrade from 473961ec to 872a348c (which we did in order to pick up https://go-review.googlesource.com/c/tools/+/215057). But I stress "appears" in that first sentence, because I can't be 100% sure it wasn't there before. But given we're seeing it fail roughly 50% of the time now in race tests, the evidence points that way.

This is actually incorrect.

[stamblerre]

Ok, I was able to reproduce this locally. You're right that this seems exactly like the earlier bug. @heschik will not be pleased...

Writing down the repro steps here so that I can figure out how to do it again.

$ export GOVIM_TESTSCRIPT_WORKDIR_ROOT=$(mktemp -d)
$ export VIM_FLAVOR=vim
$ go test ./cmd/govim -gopls $(which gopls) -run=TestScripts/scenario_default/format_on_save_new_file_existing_package -race
$ code $GOVIM_TESTSCRIPT_WORKDIR_ROOT/govim/cmd/govim/scenario_default/script-format_on_save_new_file_existing_package/_tmp/gopls.log

[gopherbot]

Change https://golang.org/cl/215318 mentions this issue: internal/lsp: invalidate directories if we have no direct IDs