x/tools/cmd/gopls: import organization fails on certain packages

[atombender]

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

$ go version
go version go1.11.5 darwin/amd64

Does this issue reproduce with the latest release?

N/A, I think.

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

go env Output

$ go env
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/alex/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/alex/.go"
GOPROXY=""
GORACE=""
GOROOT="/usr/local/opt/go/libexec"
GOTMPDIR=""
GOTOOLDIR="/usr/local/opt/go/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/alex/Projects/Transparensee/enclosure-core/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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/qs/wpmg19r12_9_nz7pvvs2_82r0000gn/T/go-build353164800=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

What did you expect to see?

Saved file in VSCode that contains a reference to a struct in a different package, within the same module. I expected the import to be added to import.

What did you see instead?

Nothing was added. This usually works, but there appears to be some packages that just don't work with import organization. This works fine with Go's standard library packages as well as third-party packages.

The file is a skeleton main.go, where I added site := models.Site{}. The models package is a package inside the same module.

I don't know much about gopls and how to report diagnostics, but here's the log file with RPC logging enabled: gopls.log.

[stamblerre]

Does running goimports manually on the file work as intended?

[atombender]

@stamblerre Yes.

[m15ch4]

Same behavior here.

~ go version
go version go1.12.1 darwin/amd64

[andybons]

• Is the file formatted correctly and it's just that the missing import isn't added?
• Is there a go.mod file present in the directory? Does adding one solve the issue?

[atombender]

Is the file formatted correctly and it's just that the missing import isn't added?

Yes. Also, gopls works fine for some files. It's inconsistent.

Is there a go.mod file present in the directory? Does adding one solve the issue?

I can reproduce the problem both in the root (where go.mod is) and in a sub-folder.

[andybons]

Got it. Thank you.

[stamblerre]

@atombender: Are you able to offer the contents of the Go file and the go.mod file for us to try to repro, or are they private?

[atombender]

As I said, it's just a skeleton file with just an empty main. I can see if I can reduce it to something I can share, but I'm doubtful. Is there any extra logging I can turn on?

[stamblerre]

I did see the main file in the logs you attached, but I was more curious about the go.mod file - maybe it's something to do with the dependency you are adding.

Also, just checking, is the file saved on disk? If the file isn't saved yet, gopls won't work at all.

[atombender]

Yes, it's saved. Everything being imported is within the same Go module. I haven't noticed any patterns to the problem. I'll see if I can create a minimally reproducible case here now.

More logging might be useful. After using gopls for a few days in VSCode I've eventually disabled it because it's completely unstable. I frequently get no autocompletions, no reformatting on save, gopls crashing, gopls having to restarted to unclog it, etc. Not sure how much of this is VSCode or gopls itself. The sudden lack of automatic reformatting always trips me up, because it's unclear if it's taking time or it's just stopped working. I've never found anything useful in the log when these things happen.

[peterbourgon]

For the record, my experience with gopls + VSCode on Mac mirrors @atombender; several times a day, I notice that auto-importing and autocompletion have stopped working. Restarting VSCode (and, therefore, gopls) typically solves the issue for awhile. I'd happily run it in some diagnostic mode and report back, if it helps.

edit: I'm on go version go1.12.4 darwin/amd64, in a project using modules, with a go.mod and go.sum, outside of GOPATH.

edit 2: It may also be worth noting the project vendors via go mod vendor.

[stamblerre]

We will try to add some more logging to understand better why this happens. I've never had this happen, but there seem to be quite a few people reporting that gopls stops working in certain projects.

[OneOfOne]

I can confirm that as well, even in non-go mod repos.

[ericrenard]

Same issue for me with both modules or non-modules projects. Restarting vscode does the trick.

[natefinch]

Same issue for me... but restarting doesn't fix it. Nothing seems to fix it. Import organization only works like 5% of the time for me.

[stamblerre]

For those who are having this experience, can you attach your gopls logs to this issue? For VSCode users, they can be found by going to "View: Debug Console" -> "Output" -> "Tasks" -> "gopls".

[freeformz]

If those logs include a "no room in queue" output that correlates to roughly when the problem started, then it's likely related to #32368. If so please update and report back.

[atombender]

@freeformz Not in my case. Log is in original issue.

[stamblerre]

@atombender: When you see the diagnostic from the language server that your package is not imported, can you hover over the error and see a "Quick Fix" suggestion? And if so, does it offer you the "Organize All Imports" quick fix?

[ericrenard]

If those logs include a "no room in queue" output that correlates to roughly when the problem started, then it's likely related to #32368. If so please update and report back.

I updated yesterday and still got the no room in queue bug :

[Error - 1:47:00 PM] Request textDocument/documentSymbol failed.
Message: no room in queue
Code: -32000
[Error - 1:47:03 PM] Request textDocument/hover failed.
Message: no object for ident sections
Code: 0
[Error - 1:47:03 PM] Request textDocument/hover failed.
Message: no object for ident sections
Code: 0
[Error - 1:47:04 PM] Request textDocument/hover failed.
Message: no identifier found
Code: 0

[ericrenard]

Might not be related but it also doesn't work most of the time when adding a new file.
For example, I add a new file with simply package x and a struct def, gopls output :

[Error - 8:03:36 PM] unable to check package for [filename]: parse: no package found for [filename]
[Error - 8:03:36 PM] Request textDocument/hover failed.
Message: no AST for [filename]
Code: 0

Once vscode is restarted, new file is correctly recognized.

[stamblerre]

@ericrenard: Do you mind filing separate issues for these cases? I think it will be easiest to help everyone debug their cases in separate issues - even when the bugs seem similar, they are often unrelated.

[atombender]

Here's a log from a current editing session where imports aren't being reorganized. In this case, it refuses to remove unused imports after I commented out a section of code, and it's not adding a third-party import (gorm, which is github.com/jinzhu/gorm) that I'm using in this project.

• gopls.log.gz
• main.go.gz

In this case, the "quick fix" button fixes the unused imports, whereas the "quick fix" on the "Undeclared name: gorm" error shows "No code actions available".

goimports is not having any issues on this file.

[stamblerre]

Can you try adding

 "editor.codeActionsOnSaveTimeout": 3000

to your VSCode configuration? The default value is 750ms, so it might not need to be as large as 3000. This seems to have mitigated a few goimports-related issues for users on Slack.

[atombender]

@stamblerre That didn't help, unfortunately.

I can reproduce this consistently in my project. I have a main.go which is in a sub-folder. If I remove all its imports and save, almost none are automatically put back (the only one is gopkg.in/yaml.v2, curiously). Log: gopls-1.log.gz.

If I then undo to put back all the imports, and save, all the errors remain, even though the imports are back, and the log starts getting no room in queue errors. Log: gopls-2.log.gz.

I can tar up the project and email it to you privately if that would help?

[atombender]

@stamblerre Thanks, but I'm not seeing anything different with that setting. Gopls is still trying to format and resolve imports, and I can see things like fixImports in the log output.

[stamblerre]

Oh, I'm sorry, I forgot to mention that you would also want to set the "editor.codeActionsOnSave" setting to false. You may also have to make sure that your "go.formatTool" is set to goimports rather than gofmt.

[atombender]

editor.codeActionsOnSave is supposed to be an object. Did you mean "editor.codeActionsOnSave": {"source.organizeImports": false}?

[atombender]

That can't be right, that disables format-on-save altogether, even Format Document stops working. I have:

  "go.formatTool": "goimports",
  "editor.formatOnSave": true,
  "editor.codeActionsOnSave": {
    "source.organizeImports": true
  },
  "editor.codeActionsOnSaveTimeout": 30000
  "go.useLanguageServer": true,
  "go.languageServerExperimentalFeatures": {
    "diagnostics": true,
    "format": false
  },
  "go.languageServerFlags": [
    "-trace"
  ]

[stamblerre]

Yes, my apologies, I did mean "source.organizeImports" should be set to false. With this configuration, I am able to get goimports working through the VSCode-Go extension, rather than through gopls:

"go.formatTool": "goimports", // or "goreturns", depending on your preference
"go.languageServerExperimentalFeatures": {
    "format": false,
},
"[go]": {
    "editor.formatOnSave": true,
    "editor.codeActionsOnSave": {
        "source.organizeImports": false,
},

[atombender]

Same as what I had, but I reloaded the window again (which I'd already done) and it suddenly worked, for some reason, thanks!

Also, for some reason for the Format Document action to work I need "editor.defaultFormatter": "ms-vscode.Go", which (if it's not set) appears twice in the list of suggested formatters.

[atombender]

No, with these settings I'm still seeing import processing in the log, and considerable slowness:

2019/06/19 15:36:32 fixImports(filename="/Users/alex/Projects/Transparensee/enclosure-core/src/api/builder_picks.go"), abs="/Users/alex/Projects/Transparensee/enclosure-core/src/api/builder_picks.go", srcDir="/Users/alex/Projects/Transparensee/enclosure-core/src/api" ...
2019/06/19 15:36:32 16.822328ms for GOROOT=/usr/local/opt/go/libexec GOPATH=/Users/alex/.go GO111MODULE= GOPROXY= PWD=/ go [go env GOMOD]
2019/06/19 15:36:44 scanning /usr/local/opt/go/libexec/src
2019/06/19 15:36:44 scanned /usr/local/opt/go/libexec/src
[...]
[Trace - 3:36:44 PM] Received response 'textDocument/codeAction - (55)' in 59849ms.
Params: {}

Also seeing lines like [{"title":"Organize Imports","kind":"source.organizeImports", .... Surely these shouldn't happen with these settings?

As you can imagine, dealing with 60-second delays when saving a file and waiting for formatting to happen is painful.

Killing gopls doesn't help. I went to a different, small file with no compilation errors and tried saving there, no format-on-save. Maybe something is stuck in VScode. Maybe some internal queue of requests? Reloading the window brings back format-on-save, so something is getting stuck.

[atombender]

Right now, it looks like fixImports(...) appears on roughly every code change. I get outdated error markers when editing that take 30-60 seconds to update.

Inserting some debug information, imports.Process is called with FormatOnly: false in its options. Surely that should be true. It's because lsp/source/format.go calls Process with no options.

Turning the fixImports function into a no-op fixes my import slowness, but it seems I have to turn "source.organizeImports": true in VSCode on again to get goimports to be invoked.

[atombender]

Sorry about spamming this issue, but there's definitely something funky going on with the VSCode Go extension. I had a file where imports were not being added, as usual. I'm running gopls with the fixImports disabled altogether now, so goimports should be formatting. Yet while VSCode was formatting my code, it was not reorganizing the imports. Running goimports manually on the command line worked fine, and super fast. So I reloaded the VSCode window, re-saved the file, and boom, imports automatically added.

The goimports run is not logged to the output panel, so this is difficult to diagnose. I've now added a wrapper script for goimports that logs its activity now, so I can see if it is even being invoked. I'll keep an eye on this problem.

In the meantime, I've noticed messages like this:

[Trace - 7:02:07 PM] Received notification 'window/logMessage'.
Params: {"type":1,"message":"unable to check package for file:///Users/alex/Projects/Transparensee/enclosure-core/src/api/sitecache/sitecache.go: go/packages.Load: no packages found for /Users/alex/Projects/Transparensee/enclosure-core/src/api/sitecache/sitecache.go"}

The file in question is a new file in a new folder that I created in VSCode, inside another package. In this new file, Gopls was completely nonfunctional until I restarted it.

[atombender]

Update: I can confirm that after a while, VSCode just stops invoking goimports on changes. If I go to a different open VSCode window and save something, goimports is invoked. So it's clearly something stuck within a single window process. Reloading the window gets it unstuck. I don't see anything in any of VSCode's log files.

[atombender]

Update: Watching the log with some patience, the above problem seems to actually be caused by Gopls blocking VSCode's execution of goimports. On saving a file, I will see log messages like this:

[Trace - 9:24:19 PM] Received response 'textDocument/codeAction - (19)' in 1342ms.
Params: [{"title":"Organize Imports","kind":"source.organizeImports","edit":{"changes":{"file:///Users/alex/Projects/Transparensee/enclosure-core/src/models/utils_test.go":[{"range":{"start":{"line":12,"character":0},"end":{"line":13,"character":0}},"newText":""},{"range":{"start":{"line":13,"character":0},"end":{"line":14,"character":0}},"newText":""},{"range":{"start":{"line":14,"character":0},"end":{"line":15,"character":0}},"newText":""},{"range":{"start":{"line":15,"character":0},"end":{"line":16,"character":0}},"newText":""},{"range":{"start":{"line":16,"character":0},"end":{"line":16,"character":0}},"newText":"\t\tStreetAddress: ptrutils.String(\"123 Some Way\"),\n"},{"range":{"start":{"line":16,"character":0},"end":{"line":16,"character":0}},"newText":"\t\tState:         ptrutils.String(\"NY\"),\n"},{"range":{"start":{"line":16,"character":0},"end":{"line":16,"character":0}},"newText":"\t\tCounty:        ptrutils.String(\"Kings County\"),\n"},{"range":{"start":{"line":16,"character":0},"end":{"line":16,"character":0}},"newText":"\t\tZipCode:       ptrutils.String(\"10012\"),\n"}]}}}]

(As I said before, I commented out the import organization code in Gopls to avoid the weird long stalls, so it shouldn't be doing anything here.)

But goimports isn't being invoked... until much later. Waiting for it, I see a lot of slow actions (Received response 'textDocument/codeAction - (17)' in 5887ms), and a lot of Sending notification '$/cancelRequest'. Eventually, after maybe a minute, goimports is suddenly invoked again.

It's as if Gopls is building up a queue of changes and choking on them. And this isn't like I'm a particularly fast typer or anything. It happens constantly.

[stamblerre]

It seems like gopls is still doing the import organization, based on the fact that it's still sending those responses. The only thing it does in a code action is imports. Can you try changing the codeAction function in internal/lsp/code_action.go to just return nil, nil?

[atombender]

I didn't realize there were two code paths to import organization. Will try that, thanks.

[atombender]

Still seeing the same weirdness where VSCode just stops invoking goimports after a while. I can report that as a VSCode bug.

[gopherbot]

Change https://golang.org/cl/183718 mentions this issue: internal/jsonrpc2: change the concurrency strategy

[atombender]

@ianthehat How does this fix relate to this issue?

[ianthehat]

This issue seems to cover multiple bugs that have some symptoms in common. Most of the things in it seem to be related to gopls ceasing to communicate with the editor client, often with the no room in queue message, which should be fixed.

[atombender]

That's just part of it, I think. I'd leave this issue open for now. It also relates to with the currently very slow import organization code that apparently is being rewritten.

[stamblerre]

Re-opened to track the imports-related issues. This may be a duplicate of #32360.

[atombender]

@stamblerre You said you re-opened, but it's still closed.

[suzmue]

This issue is outdated due to the latest changes to gopls and imports.

To track issues relating to slow import organization, please follow #32750.