x/tools/cmd/gopls: CL 185438 results in CheckPackageHandles error

[myitcv]

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

$ go version
go version devel +61bb56ad63 Mon Aug 12 23:12:29 2019 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.0.0-20190813214143-62ee03427e21
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.1.4-0.20190813214143-62ee03427e21

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

What did you do?

In govim we handle changes to (generated) files not loaded in the editing change via a file watcher (whilst we await #31553)

As of CL 185438 this test now fails. The gopls log is as follows:

[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"7.384747ms for GOROOT=/home/myitcv/gos GOPATH=/home/myitcv/gostuff GO111MODULE=on PWD=/tmp/go-test-script045282391/script-complete_watched go \"list\" \"-m\" \"-json\" \"all\", stderr: \u003c\u003c\u003e\u003e\n"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"7.897766ms for GOROOT=/home/myitcv/gos GOPATH=/home/myitcv/gostuff GO111MODULE=on PWD=/tmp/go-test-script045282391/script-complete_watched go \"list\" \"-e\" \"-json\" \"-compiled=true\" \"-test=true\" \"-export=false\" \"-deps=true\" \"-find=false\" \"--\" \"builtin\", stderr: \u003c\u003c\u003e\u003e\n"}


[Trace - 12:53:24 PM] Received response 'initialize - (1)' in 0ms.
Params: {"capabilities":{"textDocumentSync":{"openClose":true,"change":2,"save":{}},"hoverProvider":true,"completionProvider":{"triggerCharacters":["."]},"signatureHelpProvider":{"triggerCharacters":["(",","]},"definitionProvider":true,"referencesProvider":true,"documentHighlightProvider":true,"documentSymbolProvider":true,"codeActionProvider":true,"documentFormattingProvider":true,"renameProvider":true,"documentLinkProvider":{},"typeDefinitionProvider":true,"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":"workspace/didChangeWorkspaceFolders"}}},"custom":null}


[Trace - 12:53:24 PM] Sending notification 'initialize' in 10ms.
Params: {"processId":0,"rootUri":"file:///tmp/go-test-script045282391/script-complete_watched","capabilities":{"workspace":{"workspaceEdit":{},"didChangeConfiguration":{"dynamicRegistration":true},"didChangeWatchedFiles":{},"symbol":{"symbolKind":{}},"executeCommand":{},"configuration":true},"textDocument":{"synchronization":{},"completion":{"completionItem":{},"completionItemKind":{}},"hover":{"contentFormat":["plaintext"]},"signatureHelp":{"signatureInformation":{"parameterInformation":{}}},"references":{},"documentHighlight":{},"documentSymbol":{"symbolKind":{}},"formatting":{},"rangeFormatting":{},"onTypeFormatting":{},"definition":{},"codeAction":{"codeActionLiteralSupport":{"codeActionKind":{"valueSet":null}}},"codeLens":{},"documentLink":{},"rename":{},"publishDiagnostics":{},"implementation":{},"typeDefinition":{},"colorProvider":{},"foldingRange":{},"declaration":{},"selectionRange":{}},"window":{}},"initializationOptions":{"incrementalSync":true,"noDocsOnHover":true},"workspaceFolders":null}


[Trace - 12:53:24 PM] Sending response 'client/registerCapability - (1)' in 0ms.
Params: {}


[Trace - 12:53:24 PM] Received notification 'client/registerCapability' in 1ms.
Params: {"registrations":[{"id":"workspace/didChangeConfiguration","method":"workspace/didChangeConfiguration"},{"id":"workspace/didChangeWorkspaceFolders","method":"workspace/didChangeWorkspaceFolders"}]}


[Trace - 12:53:24 PM] Sending response 'workspace/configuration - (2)' in 0ms.
Params: [{"hoverKind":"FullDocumentation"},null]


[Trace - 12:53:24 PM] Received notification 'workspace/configuration' in 0ms.
Params: {"items":[{"scopeUri":"file:///tmp/go-test-script045282391/script-complete_watched","section":"gopls"},{"scopeUri":"file:///tmp/go-test-script045282391/script-complete_watched","section":"script-complete_watched"}]}


[Trace - 12:53:24 PM] Sending notification 'initialized' in 51ms.
Params: {}


[Trace - 12:53:24 PM] Sending notification 'textDocument/didOpen' in 34ms.
Params: {"textDocument":{"uri":"file:///tmp/go-test-script045282391/script-complete_watched/main.go","languageId":"go","version":0,"text":"package main\n\nimport \"fmt\"\n\nfunc main() {\n\tfmt.Println()\n}\n"}}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"Build info\n----------\ngolang.org/x/tools/gopls v0.1.3\n    golang.org/x/tools/[email protected] h1:ZabWS3brJtZJBNZbJhOAP1z/gKKLkR0uEP5qai6EgZM=\n    golang.org/x/[email protected] h1:8gQV6CLnAEikrhgkHFbMAEhagSSnXWGV915qUMm9mrU=\n    golang.org/x/[email protected] h1:71n+srv0xxBVyaIgyKgmdlN7KOcKG8M7Ex6nin1EnOM=\n    golang.org/x/[email protected] h1:9zdDQZ7Thm29KFXgAX/+yaf3eVbP7djjWp/dXAppNCc=\n\nGo info\n-------\ngo version devel +61bb56ad63 Mon Aug 12 23:12:29 2019 +0000 linux/amd64\n\nGO111MODULE=\"on\"\nGOARCH=\"amd64\"\nGOBIN=\"\"\nGOCACHE=\"/home/myitcv/.cache/go-build\"\nGOENV=\"/home/myitcv/.config/go/env\"\nGOEXE=\"\"\nGOFLAGS=\"\"\nGOHOSTARCH=\"amd64\"\nGOHOSTOS=\"linux\"\nGONOPROXY=\"\"\nGONOSUMDB=\"\"\nGOOS=\"linux\"\nGOPATH=\"/home/myitcv/gostuff\"\nGOPRIVATE=\"\"\nGOPROXY=\"https://proxy.golang.org,direct\"\nGOROOT=\"/home/myitcv/gos\"\nGOSUMDB=\"sum.golang.org\"\nGOTMPDIR=\"\"\nGOTOOLDIR=\"/home/myitcv/gos/pkg/tool/linux_amd64\"\nGCCGO=\"gccgo\"\nAR=\"ar\"\nCC=\"gcc\"\nCXX=\"g++\"\nCGO_ENABLED=\"1\"\nGOMOD=\"/home/myitcv/gostuff/src/github.com/myitcv/govim/go.mod\"\nCGO_CFLAGS=\"-g -O2\"\nCGO_CPPFLAGS=\"\"\nCGO_CXXFLAGS=\"-g -O2\"\nCGO_FFLAGS=\"-g -O2\"\nCGO_LDFLAGS=\"-g -O2\"\nPKG_CONFIG=\"pkg-config\"\nGOGCCFLAGS=\"-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build141748545=/tmp/go-build -gno-record-gcc-switches\"\n"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"5.515563ms for GOROOT=/home/myitcv/gos GOPATH=/home/myitcv/gostuff GO111MODULE=on PWD=/tmp/go-test-script045282391/script-complete_watched go \"list\" \"-m\" \"-json\" \"all\", stderr: \u003c\u003c\u003e\u003e\n"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"69.457516ms for GOROOT=/home/myitcv/gos GOPATH=/home/myitcv/gostuff GO111MODULE=on PWD=/tmp/go-test-script045282391/script-complete_watched go \"list\" \"-e\" \"-json\" \"-compiled=true\" \"-test=true\" \"-export=false\" \"-deps=true\" \"-find=false\" \"--\" \"/tmp/go-test-script045282391/script-complete_watched\", stderr: \u003c\u003c\u003e\u003e\n"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"go/packages.Load\n\tpackage = mod.com\n\tfiles = [/tmp/go-test-script045282391/script-complete_watched/main.go]"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"go/packages.Load\n\tpackages = 1"}


[Trace - 12:53:24 PM] Received notification 'textDocument/publishDiagnostics' in 0ms.
Params: {"uri":"file:///tmp/go-test-script045282391/script-complete_watched/main.go","diagnostics":[]}


[Trace - 12:53:24 PM] Sending notification 'textDocument/didOpen' in 1ms.
Params: {"textDocument":{"uri":"file:///tmp/go-test-script045282391/script-complete_watched/const.go","languageId":"go","version":0,"text":"package main\n\nconst (\n\tConst1 = 1\n\tConst2 = 2\n)\n"}}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"6.938578ms for GOROOT=/home/myitcv/gos GOPATH=/home/myitcv/gostuff GO111MODULE=on PWD=/tmp/go-test-script045282391/script-complete_watched go \"list\" \"-m\" \"-json\" \"all\", stderr: \u003c\u003c\u003e\u003e\n"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"72.56106ms for GOROOT=/home/myitcv/gos GOPATH=/home/myitcv/gostuff GO111MODULE=on PWD=/tmp/go-test-script045282391/script-complete_watched go \"list\" \"-e\" \"-json\" \"-compiled=true\" \"-test=true\" \"-export=false\" \"-deps=true\" \"-find=false\" \"--\" \"/tmp/go-test-script045282391/script-complete_watched\", stderr: \u003c\u003c\u003e\u003e\n"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"go/packages.Load\n\tpackage = mod.com\n\tfiles = [/tmp/go-test-script045282391/script-complete_watched/const.go /tmp/go-test-script045282391/script-complete_watched/main.go]"}


[Trace - 12:53:24 PM] Sending notification 'textDocument/didChange' in 86ms.
Params: {"textDocument":{"version":1,"uri":"file:///tmp/go-test-script045282391/script-complete_watched/const.go"},"contentChanges":[{"text":"package main\n\nconst (\n\tConst1 = 1\n\tConst2 = 2\n)\n"}]}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":3,"message":"go/packages.Load\n\tpackages = 1"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":1,"message":"failed to compute diagnostics: no CheckPackageHandles for file:///tmp/go-test-script045282391/script-complete_watched/const.go\n\tfile = file:///tmp/go-test-script045282391/script-complete_watched/const.go"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":1,"message":"failed to check package: context canceled"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":1,"message":"failed to compute diagnostics: no CheckPackageHandles for file:///tmp/go-test-script045282391/script-complete_watched/const.go\n\tfile = file:///tmp/go-test-script045282391/script-complete_watched/const.go"}


[Trace - 12:53:24 PM] Received notification 'window/logMessage' in 0ms.
Params: {"type":1,"message":"failed to check package: context canceled"}

What did you expect to see?

The test passing.

What did you see instead?

The test fails.

---

cc @stamblerre @ianthehat

[myitcv]

For reference, the test in question is https://github.com/myitcv/govim/blob/master/cmd/govim/testdata/complete_watched.txt

[myitcv]

Still seeing this with 547ecf7. This is in effect a blocker for govim using a later version of gopls/x/tools.

@ianthehat I known Rebecca is away this week. Is there anything more I can provide to help with investigating this?

[myitcv]

For the record, still seeing this in 95c3470.

[stamblerre]

@myitcv: Can you share the logs for the most recent failures? I added a bit more logging to try and track this down.

[myitcv]

@stamblerre https://gist.github.com/myitcv/496a0c9eb05f28ffc5f559e421a44abe, against 95c3470

[myitcv]

@stamblerre - based on our discussion on the golang-tools call the other day, I've marked this as milestone "gopls v1.0" because:

• it's currently a blocker for us upgrading govim to a later version of gopls
• my understanding was that the fix to this bug essentially falls under the heading of "the big rewrite"

Please do say if I've got things wrong/misunderstood on either point.

[myitcv]

This was fixed in https://go-review.googlesource.com/c/tools/+/192719.

Thanks to @muirrn and @stamblerre for tracking this down.