Behavior change in saving files with 1.43?

[hyangah]

Multiple users of the Go extension reported issues related to file saving recently,
and it seems like most are correlated to the recent VS Code upgrade (v1.43).
We keep debugging but I want to check if there is any known change or open issue
related to the problem we are experiencing now.

• High CPU utilization at almost every save vscode-go#3110: High CPU utilization at almost every save

There can be other issues related to our language server but all the users said the problem started after VS code upgrade. One of the lsp rpc traces from a user showed that multiple requests (textDocument/didChange, textDocument/codeAction, textDocument/formatting) on a file were issued repeatedly during save and they were identical.

[Trace - 09:40:17.999 AM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/username/go/src/github.com/username/change-request/cmd/main.go","version":5},"contentChanges":[{"range":{"start":{"line":3,"character":0},"end":{"line":12,"character":56}},"rangeLength":259,"text":"\t\"fmt\"\n\t\"strconv\"\n\t\"time\"\n\n\t\"github.com/aws/aws-sdk-go/aws\"\n\t\"github.com/aws/aws-sdk-go/aws/session\"\n\t\"github.com/aws/aws-sdk-go/service/s3\"\n\n\t\"github.com/username/change-request/internal/tracking\"\n\t\"github.com/username/change-request/internal/wavefront\""}]}

[Trace - 09:40:17.999 AM] Sending request 'textDocument/codeAction - (50)'.
Params: {"textDocument":{"uri":"file:///Users/username/go/src/github.com/username/change-request/cmd/main.go"},"range":{"start":{"line":0,"character":0},"end":{"line":91,"character":0}},"context":{"diagnostics":[],"only":["source.organizeImports"]}}

[Trace - 09:40:18.003 AM] Received response 'textDocument/codeAction - (50)' in 4ms.
Result: {}

[Trace - 09:40:18.005 AM] Sending request 'textDocument/formatting - (51)'.
Params: {"textDocument":{"uri":"file:///Users/username/go/src/github.com/username/change-request/cmd/main.go"},"options":{"tabSize":4,"insertSpaces":false}}

[Trace - 09:40:18.008 AM] Received response 'textDocument/formatting - (51)' in 2ms.
Result: []

[Trace - 09:40:18.014 AM] Sending notification 'textDocument/didChange'.
Params: {"textDocument":{"uri":"file:///Users/username/go/src/github.com/username/change-request/cmd/main.go","version":6},"contentChanges":[{"range":{"start":{"line":3,"character":0},"end":{"line":12,"character":56}},"rangeLength":259,"text":"\t\"fmt\"\n\t\"strconv\"\n\t\"time\"\n\n\t\"github.com/aws/aws-sdk-go/aws\"\n\t\"github.com/aws/aws-sdk-go/aws/session\"\n\t\"github.com/aws/aws-sdk-go/service/s3\"\n\n\t\"github.com/username/change-request/internal/tracking\"\n\t\"github.com/username/change-request/internal/wavefront\""}]}

[Trace - 09:40:18.014 AM] Sending request 'textDocument/codeAction - (52)'.
Params: {"textDocument":{"uri":"file:///Users/username/go/src/github.com/username/change-request/cmd/main.go"},"range":{"start":{"line":0,"character":0},"end":{"line":91,"character":0}},"context":{"diagnostics":[],"only":["source.organizeImports"]}}

[Trace - 09:40:18.017 AM] Received response 'textDocument/codeAction - (52)' in 3ms.
Result: {}

[Trace - 09:40:18.018 AM] Sending request 'textDocument/formatting - (53)'.
Params: {"textDocument":{"uri":"file:///Users/username/go/src/github.com/username/change-request/cmd/main.go"},"options":{"tabSize":4,"insertSpaces":false}}

[Trace - 09:40:18.020 AM] Received response 'textDocument/formatting - (53)' in 1ms.
Result: []

Notice that our language server's response to formatting and code action requests are empty - because there is nothing to modify.

After exchanging this sequence of rpcs multiple times, the VS Code window crashed. See microsoft/vscode-go#3110 (comment) for the full log.

• Cannot save files after upgrade to v1.43 - line added and removed in loop vscode-go#3109: Repeated code formatting until eventually VS code crashed

It turned out this issue was caused by other extension interfering during save. I don't have the trace to share, but from the video the user shared with us, I am suspecting VS Code is sending formatting requests to both extensions repeatedly. This problem started to occur with 1.43 upgrade as well.

[jrieken]

We keep debugging but I want to check if there is any known change or open issue
related to the problem we are experiencing now.

Nothing has changed in how we or when we save. For 1.42 we have removed the timeout for "format on save" and "code actions on save" operations, instead we now show progress. With 1.43 we have improved the UI, showing what extension is slowing down save and how to disable that (e.g disable format on save and such). Unfortunately, go appears as one of the main actors in slowing down save (due to format and/or code actions). I do not know why that is but I can confirm that we are saving just as before

[hyangah]

@jrieken Thank you - the UI popup message change is the only one I remembered as well (during 1.43) and I don't think that's related either. It's a new issue with 1.43, and flooding the language server with the identical request sequences is something we've never seen in 1.42.

Is there any way to trace back why an LSP rpc was triggered? Or any extra tracing or debugging technique we can give a shot to inspect vscode-side?

[jrieken]

You would have have to debug the extension side, e.g the driver of the LSP. Potential causes I can think of

• formatter and code actions providers are registered multiple times?
• a save participant calls save during save-handling?

Can you extract a simple sample (with LSP) that shows/reproduces this?