x/tools/gopls: unimported completions only returned on second call to Completion

[myitcv]

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

$ go version
go version devel +2b50ab2aee Tue Mar 2 06:38:07 2021 +0000 linux/amd64
$ go list -m golang.org/x/tools
golang.org/x/tools v0.1.1-0.20210227203037-f5a4005dda57
$ go list -m golang.org/x/tools/gopls
golang.org/x/tools/gopls v0.0.0-20210227203037-f5a4005dda57

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=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/myitcv/.cache/go-build"
GOENV="/home/myitcv/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/myitcv/gostuff/pkg/mod"
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"
GOVCS=""
GOVERSION="devel +2b50ab2aee Tue Mar 2 06:38:07 2021 +0000"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/myitcv/.vim/plugged/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-build1538164450=/tmp/go-build -gno-record-gcc-switches"

What did you do?

Start by adding github.com/kr/pretty to your module cache:

cd $(mktemp -d)
go mod init blah.com
go get github.com/kr/pretty

Then separately create the following setup:

-- go.mod --
module blah.com

go 1.16
-- main.go --
package main

func main() {

}

Edit main.go as follows:

package main

func main() {
        pretty.Spr_
}

and trigger completion with the cursor in the position shown by _.

What did you expect to see?

Unimported completion results that include github.com/kr/pretty.

What did you see instead?

No results. I only see results if I trigger a second completion request.

Logs:

• gopls.log
• govim.log

---

cc @stamblerre

FYI @leitzler

[stamblerre]

Pulling out the relevant pieces of the log:

[Trace - 16:21:38.391 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"version":12,"uri":"file:///home/myitcv/gostuff/src/github.com/myitcv/playground/main.go"},"contentChanges":[{"range":{"start":{"line":3,"character":0},"end":{"line":4,"character":0}},"text":"\tpretty.Spr\n"}]}


[Trace - 16:21:38.852 PM] Sending request 'textDocument/completion - (2)'.
Params: {"context":{"triggerKind":0},"textDocument":{"uri":"file:///home/myitcv/gostuff/src/github.com/myitcv/playground/main.go"},"position":{"line":3,"character":11}}


[Trace - 16:21:38.953 PM] Received response 'textDocument/completion - (2)' in 101ms.
Result: {"isIncomplete":true,"items":[]}


[Trace - 16:21:39.778 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"version":13,"uri":"file:///home/myitcv/gostuff/src/github.com/myitcv/playground/main.go"},"contentChanges":[{"range":{"start":{"line":3,"character":0},"end":{"line":4,"character":0}},"text":"\tpretty.Spr\n"}]}


[Trace - 16:21:40.562 PM] Sending request 'textDocument/completion - (3)'.
Params: {"context":{"triggerKind":0},"textDocument":{"uri":"file:///home/myitcv/gostuff/src/github.com/myitcv/playground/main.go"},"position":{"line":3,"character":11}}


[Trace - 16:21:40.665 PM] Received response 'textDocument/completion - (3)' in 102ms.
Result: {"isIncomplete":true,"items":[{"label":"Sprint","kind":6,"detail":"(from \"github.com/kylelemons/godebug/pretty\")","preselect":true,"sortText":"00000","filterText":"Sprint","insertTextFormat":1,"textEdit":{"range":{"start":{"line":3,"character":8},"end":{"line":3,"character":11}},"newText":"Sprint"},"additionalTextEdits":[{"range":{"start":{"line":1,"character":0},"end":{"line":1,"character":0}},"newText":"\nimport \"github.com/kylelemons/godebug/pretty\"\n"}]},{"label":"Sprint","kind":6,"detail":"(from \"github.com/kr/pretty\")","sortText":"00001","filterText":"Sprint","insertTextFormat":1,"textEdit":{"range":{"start":{"line":3,"character":8},"end":{"line":3,"character":11}},"newText":"Sprint"},"additionalTextEdits":[{"range":{"start":{"line":1,"character":0},"end":{"line":1,"character":0}},"newText":"\nimport \"github.com/kr/pretty\"\n"}]},{"label":"Sprint","kind":6,"detail":"(from \"github.com/niemeyer/pretty\")","sortText":"00002","filterText":"Sprint","insertTextFormat":1,"textEdit":{"range":{"start":{"line":3,"character":8},"end":{"line":3,"character":11}},"newText":"Sprint"},"additionalTextEdits":[{"range":{"start":{"line":1,"character":0},"end":{"line":1,"character":0}},"newText":"\nimport \"github.com/niemeyer/pretty\"\n"}]},{"label":"Sprintf","kind":6,"detail":"(from \"github.com/kr/pretty\")","sortText":"00003","filterText":"Sprintf","insertTextFormat":1,"textEdit":{"range":{"start":{"line":3,"character":8},"end":{"line":3,"character":11}},"newText":"Sprintf"},"additionalTextEdits":[{"range":{"start":{"line":1,"character":0},"end":{"line":1,"character":0}},"newText":"\nimport \"github.com/kr/pretty\"\n"}]},{"label":"Sprintf","kind":6,"detail":"(from \"github.com/niemeyer/pretty\")","sortText":"00004","filterText":"Sprintf","insertTextFormat":1,"textEdit":{"range":{"start":{"line":3,"character":8},"end":{"line":3,"character":11}},"newText":"Sprintf"},"additionalTextEdits":[{"range":{"start":{"line":1,"character":0},"end":{"line":1,"character":0}},"newText":"\nimport \"github.com/niemeyer/pretty\"\n"}]}]}

I'm seeing what looks like 2 of the same didChange notification. Is it possible that's related here? Maybe it's possible that the incoming didChange notification caused the first request to be canceled?

/cc @heschik

[heschi]

The completion request took 101ms which almost certainly means it timed out while scanning the filesystem. I don't see a reason to think there's a bug offhand.

[myitcv]

I'm not sure I follow that logic, because the second call took 102ms.

That said I'm fairly sure there is some sort of issue here, not least because I'm using -remote with the following flags:

-remote=auto;$ID -remote.listen.timeout=0

(for some $ID)

The first completion request fairly consistently (90%+) fails every time I open a new Vim+govim instance, despite the fact that instance should be connecting to the same remote daemon. So I would expect the "unimported cache" (or whatever it is called) to be warm.

[heschi]

Calls to completion will be prone to slowness while the disk is being scanned, but that doesn't mean they can't return results. The second one happened to find some packages that matched before the scan was done.

There is not, and has never been, an attempt to share the goimports cache across workspaces. Rob has filed #44863 for that. I don't see anything else to do here, so closing.

[myitcv]

There is not, and has never been, an attempt to share the goimports cache across workspaces.

Thanks, in the context of #44863 and the discussion we had around that I now understand the current behaviour.