x/tools/gopls: extremely long background refresh for goimports

[fkarakas]

Please direct general questions to:

• #vscode channel in Gophers Slack

Please review the documentation before filing an issue.
Helpful pages include:

• GOPATH
• Module Support
• Go Language Server
• Debugging
  • Set "trace": "log" and share the resulting logs in the debug console when logging an issue.

Please answer these questions before submitting your issue. Thanks!

What version of Go, VS Code & VS Code Go extension are you using?

• Run go version to get version of Go
• Run gopls -v version to get version of Gopls if you are using the language server.
• Run code -v or code-insiders -v to get version of VS Code or VS Code Insiders
• Check your installed extensions to get the version of the VS Code Go extension
• Run go env to get the go development environment details

Share the Go related settings you have added/edited

Run Preferences: Open Settings (JSON) command to open your settings.json file.
Share all the settings with the go. or ["go"] or gopls prefixes.

Describe the bug

A clear and concise description of what the bug.
A clear and concise description of what you expected to happen.

Steps to reproduce the behavior:

1. Go to '...'
2. Click on '....'
3. See error

Screenshots or recordings

If applicable, add screenshots or recordings to help explain your problem.

When saving a file, the popup stays for ever and i can't save the file:

Saving 'scheduler_test.go': Getting code actions from ''Go'' (configure).

After 15 mins perhaps, the file is saved

[fkarakas]

latest version of everything, everuthing up2date, macos catalina

[stamblerre]

Have you taken a look at golang/vscode-go#236? Do you have any of those other extensions installed?

[fkarakas]

Hello Rebecca,
I have Back & forth, docker ad go extensions.
I took a look at golang/vscode-go#236 but what is the solution ? waiting for a gopls fix ? there should be a "pin comment" in github issue to pin the solution :)

[stamblerre]

The first comment explains the different steps to try--this issue doesn't have one concrete solution, but can be caused by various issues. I would recommend trying to disable your other extensions to see if they are the cause. If that doesn't help, then please share a gopls log by following the instructions here: https://github.com/golang/tools/blob/master/gopls/doc/troubleshooting.md#capturing-logs.

[fkarakas]

[Trace - 03:13:44.152 AM] Received response 'textDocument/codeLens - (6030)' in 83807ms.
Result: null


[Trace - 03:13:44.152 AM] Received response 'textDocument/codeAction - (6031)' in 83808ms.
Result: null


[Trace - 03:13:44.153 AM] Received response 'textDocument/codeAction - (6032)' in 83785ms.
Result: null


[Trace - 03:13:44.153 AM] Received response 'textDocument/documentSymbol - (6033)' in 83711ms.
Result: [{"name":"Event","detail":"interface{...}","kind":11,"range":{"start":{"line":12,"character":5},"end":{"line":14,"character":1}},"selectionRange":{"start":{"line":12,"character":5},"end":{"line":12,"character":10}},"children":[{"name":"String","kind":6,"range":{"start":{"line":13,"character":1},"end":{"line":13,"character":16}},"selectionRange":{"start":{"line":13,"character":1},"end":{"line":13,"character":7}}}]},{"name":"Error","detail":"interface{...}","kind":11,"range":{"start":{"line":16,"character":5},"end":{"line":18,"character":1}},"selectionRange":{"start":{"line":16,"character":5},"end":{"line":16,"character":10}},"children":[{"name":"Event","kind":11,"range":{"start":{"line":17,"character":1},"end":{"line":17,"character":6}},"selectionRange":{"start":{"line":17,"character":1},"end":{"line":17,"character":6}}}]},{"name":"Scheduler","detail":"struct{...}","kind":23,"range":{"start":{"line":20,"character":5},"end":{"line":24,"character":1}},"selectionRange":{"start":{"line":20,"character":5},"end":{"line":20,"character":14}},"children":[{"name":"Timers","detail":"struct{...}","kind":8,"range":{"start":{"line":21,"character":1},"end":{"line":21,"character":14}},"selectionRange":{"start":{"line":21,"character":1},"end":{"line":21,"character":14}}},{"name":"Store","detail":"interface{...}","kind":8,"range":{"start":{"line":22,"character":1},"end":{"line":22,"character":12}},"selectionRange":{"start":{"line":22,"character":1},"end":{"line":22,"character":12}}},{"name":"events","detail":"chan Event","kind":8,"range":{"start":{"line":23,"character":1},"end":{"line":23,"character":18}},"selectionRange":{"start":{"line":23,"character":1},"end":{"line":23,"character":7}}}]},{"name":"NewScheduler","detail":"(store store.Store)","kind":12,"range":{"start":{"line":26,"character":0},"end":{"line":35,"character":1}},"selectionRange":{"start":{"line":26,"character":5},"end":{"line":26,"character":17}}},{"name":"(Scheduler).Events","detail":"()","kind":6,"range":{"start":{"line":37,"character":0},"end":{"line":39,"character":1}},"selectionRange":{"start":{"line":37,"character":21},"end":{"line":37,"character":27}}},{"name":"(Scheduler).Close","detail":"()","kind":6,"range":{"start":{"line":41,"character":0},"end":{"line":44,"character":1}},"selectionRange":{"start":{"line":41,"character":21},"end":{"line":41,"character":26}}},{"name":"(Scheduler).OldEventsHandler","detail":"(since time.Time, input \u003c-chan store.Event)","kind":6,"range":{"start":{"line":77,"character":0},"end":{"line":191,"character":1}},"selectionRange":{"start":{"line":77,"character":21},"end":{"line":77,"character":37}}},{"name":"(Scheduler).addToTimers","detail":"(s schedule.Schedule)","kind":6,"range":{"start":{"line":279,"character":0},"end":{"line":287,"character":1}},"selectionRange":{"start":{"line":279,"character":21},"end":{"line":279,"character":32}}},{"name":"(Scheduler).Start","detail":"(since time.Time)","kind":6,"range":{"start":{"line":289,"character":0},"end":{"line":382,"character":1}},"selectionRange":{"start":{"line":289,"character":21},"end":{"line":289,"character":26}}}]


[Trace - 03:13:44.157 AM] Received notification 'textDocument/publishDiagnostics'.
Params: {"uri":"file:///Users/fkarakas/go/src/github.com/etf1/kafka-scheduler/scheduler/scheduler.go","version":1868,"diagnostics":[]}


[Trace - 03:13:44.162 AM] Received response 'textDocument/documentLink - (6034)' in 83148ms.
Result: [{"range":{"start":{"line":3,"character":2},"end":{"line":3,"character":5}},"target":"https://pkg.go.dev/fmt?utm_source=gopls"},{"range":{"start":{"line":4,"character":2},"end":{"line":4,"character":6}},"target":"https://pkg.go.dev/sort?utm_source=gopls"},{"range":{"start":{"line":5,"character":2},"end":{"line":5,"character":6}},"target":"https://pkg.go.dev/time?utm_source=gopls"},{"range":{"start":{"line":7,"character":2},"end":{"line":7,"character":49}},"target":"https://pkg.go.dev/github.com/etf1/kafka-scheduler/internal/timers?utm_source=gopls"},{"range":{"start":{"line":8,"character":2},"end":{"line":8,"character":42}},"target":"https://pkg.go.dev/github.com/etf1/kafka-scheduler/schedule?utm_source=gopls"},{"range":{"start":{"line":9,"character":2},"end":{"line":9,"character":39}},"target":"https://pkg.go.dev/github.com/etf1/kafka-scheduler/store?utm_source=gopls"},{"range":{"start":{"line":196,"character":10},"end":{"line":196,"character":18}},"target":"https://time.Now"},{"range":{"start":{"line":212,"character":16},"end":{"line":212,"character":32}},"target":"https://sch.Store.Events"},{"range":{"start":{"line":231,"character":22},"end":{"line":231,"character":26}},"target":"https://s.ID"},{"range":{"start":{"line":233,"character":29},"end":{"line":233,"character":33}},"target":"https://s.ID"},{"range":{"start":{"line":234,"character":23},"end":{"line":234,"character":27}},"target":"https://s.ID"},{"range":{"start":{"line":239,"character":15},"end":{"line":239,"character":19}},"target":"https://s.ID"},{"range":{"start":{"line":244,"character":116},"end":{"line":244,"character":124}},"target":"https://time.Now"},{"range":{"start":{"line":244,"character":139},"end":{"line":244,"character":147}},"target":"https://time.Now"},{"range":{"start":{"line":244,"character":172},"end":{"line":244,"character":180}},"target":"https://time.Now"},{"range":{"start":{"line":249,"character":34},"end":{"line":249,"character":42}},"target":"https://time.Now"},{"range":{"start":{"line":249,"character":95},"end":{"line":249,"character":103}},"target":"https://time.Now"},{"range":{"start":{"line":298,"character":25},"end":{"line":298,"character":33}},"target":"https://time.Now"},{"range":{"start":{"line":299,"character":4},"end":{"line":299,"character":14}},"target":"https://sch.events"},{"range":{"start":{"line":314,"character":20},"end":{"line":314,"character":28}},"target":"https://time.Now"},{"range":{"start":{"line":315,"character":5},"end":{"line":315,"character":15}},"target":"https://sch.events"}]


[Error - Received] 03:13:44.162 AM #6035 JSON RPC cancelled


[Error - Received] 03:13:44.162 AM #6036 JSON RPC cancelled


[Trace - 03:13:44.164 AM] Sending request 'textDocument/formatting - (6037)'.
Params: {"textDocument":{"uri":"file:///Users/fkarakas/go/src/github.com/etf1/kafka-scheduler/scheduler/scheduler.go"},"options":{"tabSize":4,"insertSpaces":false}}


[Trace - 03:13:44.168 AM] Received response 'textDocument/formatting - (6037)' in 3ms.
Result: []


[Trace - 03:13:44.230 AM] Sending notification 'textDocument/didSave'.
Params: {"textDocument":{"uri":"file:///Users/fkarakas/go/src/github.com/etf1/kafka-scheduler/scheduler/scheduler.go","version":1868}}


[Trace - 03:13:44.307 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/11/25 03:13:44 background refresh finished after 1m20.476054334s\n"}


[Info  - 3:13:44 AM] 2020/11/25 03:13:44 background refresh finished after 1m20.476054334s

[Trace - 03:13:44.559 AM] Sending request 'textDocument/codeAction - (6038)'.
Params: {"textDocument":{"uri":"file:///Users/fkarakas/go/src/github.com/etf1/kafka-scheduler/scheduler/scheduler.go"},"range":{"start":{"line":363,"character":33},"end":{"line":363,"character":33}},"context":{"diagnostics":[]}}


[Trace - 03:13:44.559 AM] Received response 'textDocument/codeAction - (6038)' in 0ms.
Result: null


[Trace - 03:13:44.638 AM] Sending notification 'workspace/didChangeWatchedFiles'.
Params: {"changes":[{"uri":"file:///Users/fkarakas/go/src/github.com/etf1/kafka-scheduler/scheduler/scheduler.go","type":2}]}

[fkarakas]

it happens time to time, not every time i save a file, previously is last traces when the "slow" action occured, if it can helps...

[stamblerre]

I do see the slow code action request there, but it looks like this is a partial log, so I can't get a full understanding of the issue. Can you please share the complete log (starting from the top, you should see an "initialize" request) the next time this happens?

[fkarakas]

gopls_server_logs.txt

[stamblerre]

I'm actually still not seeing the initialize request in that log. Maybe you could run gopls -rpc.trace -v check path/to/file.go?

[fkarakas]

gopls -rpc.trace -v check ./scheduler/scheduler_test.go
2020/11/25 23:26:45 Info:2020/11/25 23:26:45 go env for /Users/fkarakas/go/src/github.com/etf1/kafka-scheduler
(root /Users/fkarakas/go/src/github.com/etf1/kafka-scheduler)
(go version go version go1.15.5 darwin/amd64)
(valid build configuration = true)
(build flags: [])
GOFLAGS=
GOPATH=/Users/fkarakas/go
GONOPROXY=go.etf1.tf1.fr/*
GOROOT=/usr/local/Cellar/go/1.15.5/libexec
GONOSUMDB=go.etf1.tf1.fr/*
GOPRIVATE=go.etf1.tf1.fr/*
GOPROXY=https://proxy.golang.org,direct
GOCACHE=/Users/fkarakas/Library/Caches/go-build
GOINSECURE=
GOSUMDB=sum.golang.org
GO111MODULE=
GOMODCACHE=/Users/fkarakas/go/pkg/mod
GOMOD=/Users/fkarakas/go/src/github.com/etf1/kafka-scheduler/go.mod

2020/11/25 23:26:46 Info:2020/11/25 23:26:46 go/packages.Load
	snapshot=0
	directory=/Users/fkarakas/go/src/github.com/etf1/kafka-scheduler
	query=[builtin github.com/etf1/kafka-scheduler/...]
	packages=24

it send me back just that.
I never close my vscode maybe the reason ?

[stamblerre]

That looks correct, thanks for sharing that. To confirm, you are also opening VS Code with the root path of /Users/fkarakas/go/src/github.com/etf1/kafka-scheduler?

[fkarakas]

usually i do it from the terminal (iterm):

cd <my_project_root>
code .

in this case :

cd /Users/fkarakas/go/src/github.com/etf1/kafka-scheduler
code .

[stamblerre]

Ok great, thanks for the confirmation. So it looks like your gopls configuration is correct. Have you confirmed that this problem still happens even when all of your other extensions are disabled?

[fkarakas]

i will tell you, i have juste GO extension in my vscode right now, i uninstalled everything else. Thnaks.

[hyangah]

I don't know the reason yet either. It looks like it worked ok till the codeAction requests 11777 and 11778.

[Trace - 23:05:53.865 PM] Sending request 'textDocument/codeAction - (11777)'.
Params: {"textDocument":{"uri":"file:///Users/fkarakas/go/src/github.com/etf1/kafka-scheduler/scheduler/scheduler_test.go"},"range":{"start":{"line":270,"character":22},"end":{"line":270,"character":22}},"context":{"diagnostics":[]}}


[Trace - 23:05:53.865 PM] Sending request 'textDocument/codeAction - (11778)'.
Params: {"textDocument":{"uri":"file:///Users/fkarakas/go/src/github.com/etf1/kafka-scheduler/scheduler/scheduler_test.go"},"range":{"start":{"line":228,"character":31},"end":{"line":228,"character":31}},"context":{"diagnostics":[{"range":{"start":{"line":228,"character":30},"end":{"line":228,"character":35}},"message":"undeclared name: n","severity":1,"source":"compiler"}]}}


[Trace - 23:05:54.072 PM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/fkarakas/go/src/github.com/etf1/kafka-scheduler/scheduler/scheduler_test.go","version":361},"contentChanges":[{"range":{"start":{"line":228,"character":31},"end":{"line":228,"character":31}},"rangeLength":0,"text":"o"}]}


[Trace - 23:05:54.072 PM] Sending notification '$/cancelRequest'.
Params: {"id":11777}


[Trace - 23:05:54.072 PM] Sending notification '$/cancelRequest'.
Params: {"id":11778}

I see vscode is often issuing two of the same or similar kind of messages on the same file in parallel so I guess the same file was open side-by-side. @stamblerre Is there any useful http debug endpoint for @fkarakas to look into to check what gopls is up to? (for example, is it deadlocked? is there any stuck go commands? ...)

"go.languageServerFlags": [
  "serve",
  "-rpc.trace",
  "--debug=localhost:6060",
],

[fkarakas]

Hi @hyangah, still the same issue after disabling all plugins (except go ;) ), to day i reached my record:

[Trace - 04:18:06.078 AM] Received notification 'window/logMessage'.
Params: {"type":3,"message":"2020/11/27 04:18:06 background refresh finished after 7m48.938930833s\n"}
[Info  - 4:18:06 AM] 2020/11/27 04:18:06 background refresh finished after 7m48.938930833s

no file open on the side,
gopls_server.log

[stamblerre]

Thanks for sharing that. /cc'ing @heschik for input on why the background refresh might take so long

[heschi]

There are hundreds of background refreshes in this log, and all but the last take less than 200ms. I don't know what happened at 4:10 AM, and there are no clues that I can find in the logs. But I see no reason to think the refresh is the cause of the problem, or a more significant symptom than all the cancelled requests at that time. I don't think logs are going to help here.

[stamblerre]

@fkarakas: Do you see this issue frequently? Do you know what you are doing when you see it usually? (For example, are you refactoring code, moving files, etc.?)

[fkarakas]

hello, it happens one or twice a day. My coworkers also got time to time this issue. One told me that after "formatting" its macbook, the issue was gone... another one reinstalled vscode from scratch, so i don't know if it can be helpful

I am not moving file, refactoring yes, changing function parameter name etc ...
last time i remember changing "fmt.Printf(..." to "log.Printf(..." and got the issue with a persistent error (l is undefined) but i dont know if it related.

Sorry to bother you with that, i don't really know if is my setup or really touchy corner case between vcode and gopls ?
Perhaps you have a kind of test which can emulate constant refactoring of code and checking response time ?
i will try to make a clean and resintall my vscode as described in this discussion : https://stackoverflow.com/a/47561948

[stamblerre]

OK, please let us know if the problem persists or things improve. It's hard to understand how the problem here since it's not easily reproducible, so I think the best path forward would be if you can find a case where you can reproduce an issue consistently. When you see these errors again, I'd recommend checking your computer's Activity Monitor to see if gopls or another program is causing really high CPU or memory usage that might be causing issues.

As a workaround, when gopls gets into a bad state, the easiest thing might be to use the Go: Restart Language Server command in VS Code through the Command Palette (Ctrl+Shift+P).

[stamblerre]

Closing this issue, as it's been in the Waiting for Info state for over a month.