x/tools/gopls: format_on_save_new_file (govim) test flaky

[myitcv]

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

$ go version
go version devel +73d213708e Sat Jan 25 16:34:18 2020 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20200124220429-8fe064f891f2
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.1.8-0.20200124220429-8fe064f891f2

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-build728174989=/tmp/go-build -gno-record-gcc-switches"

What did you do?

As a follow up to #34103 (comment), we are seeing some errors being logged by gopls when we are not expecting any.

As background, in govim/govim#661 we are looking to enable an automatic check at the end of each integration test, a check that asserts we have received no errors/warnings from gopls (this check will not be in place for tests where we are expecting errors/warnings).

For example we have a test that ensures CodeAction and Formatting work on a buffer that does not yet exist on disk.

In the test we sometimes see the following error message:

[Trace - 02:34:55.311 AM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2020/01/26 02:34:55 diagnose: could not generate diagnostics for package: no parsed files for package command-line-arguments, expected: [/artefacts/govim/cmd/govim/scenario_default/script-format_on_save_new_file/main.go], errors: [successfully parsed but no token.File for file:///artefacts/govim/cmd/govim/scenario_default/script-format_on_save_new_file/main.go (/artefacts/govim/cmd/govim/scenario_default/script-format_on_save_new_file/main.go:1:2: expected ';', found 'EOF' (and 2 more errors))], list errors: []\n\tpackage = command-line-arguments"}

The gopls log file for this test run is: gopls.log

It is true that no files exist, but this test is run within the context of a main module.

What did you expect to see?

No errors logged.

What did you see instead?

As above.

Tentatively marking as v0.3.0. I will also add further instances of logged errors as CI finds them.

---

cc @stamblerre

FYI @leitzler

[myitcv]

We also see instances of:

[Trace - 03:17:35.586 AM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2020/01/26 03:17:35 diagnose: no workspace packages: go [list -f {{context.GOARCH}} {{context.Compiler}} -- unsafe]: exit status 1: go: updates to go.mod needed, but contents have changed\n\n\tdirectory = 0xa932b0"}

gopls log file: gopls.log

[myitcv]

We also see instances of:

[Trace - 03:24:05.751 AM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"2020/01/26 03:24:05 publishReports: failed to deliver diagnostic: context canceled\n\tfile = \u003cnil\u003e"}

gopls log file: gopls.log

[stamblerre]

Going through the 3 log statements here:

(1) I expect that this is logged by the initial workspace load and its attempt to run diagnostics on the workspace before all of files get created via textDocument/didChange. I'll mail a CL to add snapshot IDs to more of the log statements, but I would guess that this would be for snapshot 0, in which case I think it's a valid log statement, since at that point there is no content for that file.

(2) The second one I am unsure of, since it's a go list error that I'm not familiar with. Does the go.mod file already exist on disk in this test? Also, maybe @jayconrod or @bcmills can give more insight on the meaning of the go: updates to go.mod needed, but contents have changed error message?

(3) I will mail a CL for this.

[gopherbot]

Change https://golang.org/cl/216497 mentions this issue: internal/lsp: log snapshot IDs, don't log context cancellation

[myitcv]

Thanks. By way of response for (1):

but I would guess that this would be for snapshot 0, in which case I think it's a valid log statement, since at that point there is no content for that file.

But in this test, main.go never exists on disk until after the calls to CodeAction and Formatting. This error appears as the call to CodeAction is being handled.

[jayconrod]

go: updates to go.mod needed, but contents have changed

When the go command updates go.mod, it re-reads the file and verifies that the contents are identical to what they were when it started. It prints this error if go.mod was modified while the go command was running (between the first and second read).

So it sounds like multiple processes are racing to modify go.mod. Is that expected? What else is running?

[stamblerre]

Responding to (2)

Thanks for the explanation, @jayconrod. For that test, it does seem like there is a race, between the initial workspace diagnostics and the textDocument/definition. The request comes in before the initial workspace load is complete, so two go list requests probably end up running simultaneously, causing this error message.

This is a genuine error, so it should be logged. I'm a bit torn on how to handle it correctly - on one hand, it makes sense for all requests to wait on the initial workspace load to complete, but on the other hand, it's a better user experience if all language features work without any start-up delay. @heschik, what do you think?

---

Responding to (1)

But in this test, main.go never exists on disk until after the calls to CodeAction and Formatting. This error appears as the call to CodeAction is being handled.

The log messages aren't necessarily in order, and diagnostics happen asynchronously so this isn't necessarily part of handling code actions. https://golang.org/cl/216497 added logging of snapshot IDs for diagnostics, so we can use that to confirm my suspicion that this log message happens during the initial workspace load.

[gopherbot]

Change https://golang.org/cl/216543 mentions this issue: internal/lsp/cache: handle go.mod conflicts in go list

[stamblerre]

I believe that https://golang.org/cl/216637 will also deal with the errors that were logged in (1). Closing this issue as I believe all of the cases have been addressed. Please open a new issue if you see an unexpected error.

[myitcv]

Is it ok if we keep this open until that CL is merged and the issues are confirmed fixed?

[gopherbot]

Change https://golang.org/cl/216637 mentions this issue: internal/lsp: recover from a view initialization failure

[myitcv]

@stamblerre

An update, testing against CL 216637:

(1) - still seeing these, so I attach a passing and failing log with verbose enabled:

• fail.log
• pass.log

Hopefully this gives you the snapshot information you now need?

(2) what we can/should do in this case is actually fix the govim tests that are triggering these failures (by ensuring the go.mod file is stable for the test) and then create a specific test where go.mod is expected to change and assert against that as required depending on how you and @heschik conclude. I will look to fix things on the govim side, assuming this "fix" can be applied to all tests (there are some tests where we need to change go.mod, so this might not be totally foolproof - again, we could skip asserting here for now)

(3) we haven't seen any more instances of this. Thank you!

(4) we have also started seeing an instance of:

Params: {"type":1,"message":"2020/01/28 09:06:17 diagnose: no workspace packages: no metadata for [command-line-arguments]\n\tsnapshot = 3\n\tdirectory = 0xea3c40"}

• fail.log
• pass.log

[heschi]

Did my CL not fix (2)?

[stamblerre]

(1) The log message occurs for snapshot 1, which is created by this didOpen:

[Trace - 11:31:01.249 AM] Sending notification 'textDocument/didOpen'.
Params: {"textDocument":{"uri":"file:///tmp/blah/govim/cmd/govim/scenario_default/script-format_on_save_new_file/main.go","languageId":"go","version":1,"text":"\n"}}

This error message therefore makes sense, since we weren't able to load anything about the package. I think that the flakiness here is related to timing - in the "pass" case, the diagnostics for snapshot 1 get canceled by the subsequent didChange and creation of snapshot 2. In the fail case, the diagnostics for snapshot 1 complete before diagnostics for snapshot 2 begin. I think we can therefore consider (1) resolved.

(4) I think this is similar to the cases that you are seeing in the other tests. It's again another valid error, so the real issue is figuring out what's causing this flakiness.

[myitcv]

(1) ah @stamblerre that sounds very plausible indeed. We should fix this on the govim side to expect the diagnostics after open before making the change. That way we can then assert that this test should include errors. Thank you very much for tracking that down.

(2) Didn't appear to, @heschik. We were testing against https://go-review.googlesource.com/c/tools/+/216637/4 (note, specific patchset). But that does appear to include your CL 216543.

(4) understood, thanks.

[stamblerre]

I don't know that you can assert against the errors for (1) one way or another. Depending on the context, the diagnostics may or may not be canceled.

[heschi]

#36772 (comment): Okay. I don't understand how that's possible; I'll need another log to investigate further.