Timeout waiting for LSP after quitting and garbage output for all toml files since 22.12

[illode]

Summary

Since the update, any toml file will hang after quitting, then output Error: Timed out waiting for language servers to shutdown. Doesn't seem to happen for other formats.

Also, sometimes after quitting the next shell prompt will be pre-filled with a bunch of escape sequence garbage like: 35;93;71M35;109;71M35;119;71M35;129;71M35;139;71M35;148;72M35;155;73M. The exact garbage changes. I can't remember if this bug was introduced in 22.12 or not.

Both tested on two machines with both zsh (customized) and bash (distro default) and two terminal emulators.

Reproduction Steps

1. Open toml file. Neither the contents matter, nor whether it exists or not. helix qwe.toml
2. Quit with :q or :q!. No changes need to be made.

UI will freeze for a second or two, then print the error. Trying this repeatedly will eventually lead to the garbage output, but it can take a lot of attempts (>50).

Helix log

helix -vvv qwe.toml log
This is with both garbage in prompt and hang.

~/.cache/helix/helix.log

2022-12-15T11:20:44.661 helix_loader [DEBUG] Located configuration folders: []
2022-12-15T11:20:44.669 helix_view::clipboard [INFO] Using wl-copy+wl-paste to interact with the system and selection (primary) clipboard
2022-12-15T11:20:44.671 mio::poll [TRACE] registering event source with poller: token=Token(0), interests=READABLE | WRITABLE
2022-12-15T11:20:44.671 mio::poll [TRACE] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE
2022-12-15T11:20:44.671 mio::poll [TRACE] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE
2022-12-15T11:20:44.671 helix_view::editor [DEBUG] editor status: Loaded 1 files.
2022-12-15T11:20:44.671 mio::poll [TRACE] registering event source with poller: token=Token(3), interests=READABLE | WRITABLE
2022-12-15T11:20:44.671 mio::poll [TRACE] registering event source with poller: token=Token(4), interests=READABLE | WRITABLE
2022-12-15T11:20:44.671 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"initialize","params":{"capabilities":{"textDocument":{"codeAction":{"codeActionLiteralSupport":{"codeActionKind":{"valueSet":["","quickfix","refactor","refactor.extract","refactor.inline","refactor.rewrite","source","source.organizeImports"]}}},"completion":{"completionItem":{"insertReplaceSupport":true,"resolveSupport":{"properties":["documentation","detail","additionalTextEdits"]},"snippetSupport":false},"completionItemKind":{}},"hover":{"contentFormat":["markdown"]},"publishDiagnostics":{},"rename":{"dynamicRegistration":false,"honorsChangeAnnotations":false,"prepareSupport":false},"signatureHelp":{"signatureInformation":{"activeParameterSupport":true,"documentationFormat":["markdown"],"parameterInformation":{"labelOffsetSupport":true}}}},"window":{"workDoneProgress":true},"workspace":{"applyEdit":true,"configuration":true,"didChangeConfiguration":{"dynamicRegistration":false},"executeCommand":{"dynamicRegistration":false},"symbol":{"dynamicRegistration":false},"workspaceFolders":true}},"processId":157798,"rootPath":"/home/dominik","rootUri":"file:///home/dominik","workspaceFolders":[{"name":"dominik","uri":"file:///home/dominik"}]},"id":0}
2022-12-15T11:20:44.671 mio::poll [TRACE] registering event source with poller: token=Token(0), interests=READABLE
2022-12-15T11:20:44.671 mio::poll [TRACE] registering event source with poller: token=Token(1), interests=READABLE
2022-12-15T11:20:44.671 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"initialize\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"textDocument/foldingRange\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"textDocument/documentSymbol\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"textDocument/formatting\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"textDocument/completion\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"textDocument/hover\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"textDocument/documentLink\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"textDocument/semanticTokens/full\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"textDocument/prepareRename\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"textDocument/rename\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered notification handler method=\"initialized\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered notification handler method=\"textDocument/didOpen\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered notification handler method=\"textDocument/didChange\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered notification handler method=\"textDocument/didSave\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered notification handler method=\"textDocument/didClose\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered notification handler method=\"workspace/didChangeConfiguration\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered notification handler method=\"workspace/didChangeWorkspaceFolders\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"taplo/convertToJson\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"taplo/convertToToml\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"taplo/listSchemas\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered request handler method=\"taplo/associatedSchema\"\n"
2022-12-15T11:20:44.697 helix_lsp::transport [ERROR] err <- " INFO taplo: registered notification handler method=\"taplo/associateSchema\"\n"
2022-12-15T11:20:44.723 helix_lsp::transport [ERROR] err <- " INFO taplo: LSP server listening transport=\"stdio\"\n"
2022-12-15T11:20:44.954 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","id":0,"result":{"capabilities":{"textDocumentSync":1,"hoverProvider":true,"completionProvider":{"resolveProvider":false,"triggerCharacters":[".","=","[","{",",","\""]},"documentSymbolProvider":true,"documentFormattingProvider":true,"renameProvider":{"prepareProvider":true},"documentLinkProvider":{},"foldingRangeProvider":true,"workspace":{"workspaceFolders":{"supported":true,"changeNotifications":true}},"semanticTokensProvider":{"workDoneProgress":false,"legend":{"tokenTypes":["tomlArrayKey","tomlTableKey"],"tokenModifiers":["readonly"]},"range":false,"full":true}},"serverInfo":{"name":"Taplo","version":"0.6.0"}}}
2022-12-15T11:20:44.954 helix_lsp::transport [INFO] <- {"capabilities":{"completionProvider":{"resolveProvider":false,"triggerCharacters":[".","=","[","{",",","\""]},"documentFormattingProvider":true,"documentLinkProvider":{},"documentSymbolProvider":true,"foldingRangeProvider":true,"hoverProvider":true,"renameProvider":{"prepareProvider":true},"semanticTokensProvider":{"full":true,"legend":{"tokenModifiers":["readonly"],"tokenTypes":["tomlArrayKey","tomlTableKey"]},"range":false,"workDoneProgress":false},"textDocumentSync":1,"workspace":{"workspaceFolders":{"changeNotifications":true,"supported":true}}},"serverInfo":{"name":"Taplo","version":"0.6.0"}}
2022-12-15T11:20:44.954 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"initialized","params":{}}
2022-12-15T11:20:44.954 helix_term::application [DEBUG] received editor event: LanguageServerMessage((0, Notification(Notification { jsonrpc: None, method: "initialized", params: None })))
2022-12-15T11:20:44.954 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didOpen","params":{"textDocument":{"languageId":"toml","text":"\n","uri":"file:///home/dominik/qwe.toml","version":0}}}
2022-12-15T11:20:44.954 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-12-15T11:20:44.954 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/dominik/qwe.toml","diagnostics":[]}}
2022-12-15T11:20:44.954 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/dominik/qwe.toml","diagnostics":[]}}
2022-12-15T11:20:44.954 helix_term::application [DEBUG] received editor event: LanguageServerMessage((0, Notification(Notification { jsonrpc: Some(V2), method: "textDocument/publishDiagnostics", params: Map({"diagnostics": Array [], "uri": String("file:///home/dominik/qwe.toml")}) })))
2022-12-15T11:20:44.954 helix_term::application [DEBUG] received editor event: LanguageServerMessage((0, Notification(Notification { jsonrpc: Some(V2), method: "textDocument/publishDiagnostics", params: Map({"diagnostics": Array [], "uri": String("file:///home/dominik/qwe.toml")}) })))
2022-12-15T11:20:44.956 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/dominik/qwe.toml","diagnostics":[]}}
2022-12-15T11:20:44.956 helix_term::application [DEBUG] received editor event: LanguageServerMessage((0, Notification(Notification { jsonrpc: Some(V2), method: "textDocument/publishDiagnostics", params: Map({"diagnostics": Array [], "uri": String("file:///home/dominik/qwe.toml")}) })))
2022-12-15T11:20:44.956 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"workspace/configuration","id":0,"params":{"items":[{"section":"evenBetterToml"},{"scopeUri":"file:///home/dominik","section":"evenBetterToml"}]}}
2022-12-15T11:20:44.957 helix_term::application [DEBUG] received editor event: LanguageServerMessage((0, MethodCall(MethodCall { jsonrpc: Some(V2), method: "workspace/configuration", params: Map({"items": Array [Object {"section": String("evenBetterToml")}, Object {"scopeUri": String("file:///home/dominik"), "section": String("evenBetterToml")}]}), id: Num(0) })))
2022-12-15T11:20:44.957 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","result":[null,null],"id":0}
2022-12-15T11:20:45.071 helix_term::application [DEBUG] received editor event: IdleTimer
2022-12-15T11:20:47.342 helix_term::commands::typed [DEBUG] quitting...
2022-12-15T11:20:47.342 helix_view::document [DEBUG] id 1 modified - last saved: 0, current: 0
2022-12-15T11:20:47.342 helix_term::job [DEBUG] waiting on jobs...
2022-12-15T11:20:47.342 helix_term::job [DEBUG] waiting on jobs...
2022-12-15T11:20:47.342 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"shutdown","params":null,"id":1}
2022-12-15T11:20:50.344 helix_term::application [ERROR] Timed out waiting for language servers to shutdown
2022-12-15T11:20:50.345 mio::poll [TRACE] deregistering event source from poller
2022-12-15T11:20:50.346 mio::poll [TRACE] deregistering event source from poller
2022-12-15T11:20:50.346 mio::poll [TRACE] deregistering event source from poller
2022-12-15T11:20:50.346 mio::poll [TRACE] deregistering event source from poller
2022-12-15T11:20:50.346 mio::poll [TRACE] deregistering event source from poller

Platform

Arch Linux

Terminal Emulator

Konsole and Alacritty

Helix Version

helix 22.12

[pascalkuthe]

This is a known issue #4468 (comment) and an upstream problem

[pascalkuthe]

The garbage output are the escape codes for mouse events send by the emulator that are not intercepted by helix anymore. Once helix properly shuts down we stop requesting mouse events from the emulator. Not sure if we can do anything about that... Maybe we can execute some of the shutdown code earlier?

[illode]

Ah, I skimmed that and somehow missed the last bullet point for taplo. The delay is noticeably worse in the 22.12 than 22.08, though. Do you have a link to the issue upstream, if it exists?

And yeah, I see if I spin my mouse while it's hanging it absolutely fills the prompt with garbage.

[pascalkuthe]

This issue did not exist in 22.08 because we did not wait for LSPs to shutdown at all and just killed the process. We really don't want to do that. I don't think there is an upstream issue about this yet (or did I miss anything you found @the-mikedavis?)

[gabydd]

tamasfe/taplo#354 Micheal Davis actually has a pr to fix it

[illode]

I'm just disabling the LSP by adding the following to languages.toml until it's fixed upstream since the delay is a nuisance:

[[language]]
name = "toml"
language-server = { command = ""}

[metafates]

This issue did not exist in 22.08 because we did not wait for LSPs to shutdown at all and just killed the process. We really don't want to do that.

Can we have another :quit command (or config field) then that would behave like it was before? Something like :quit-force or quit-unsafe (I believe you would come up with better naming :P)? I personally find this issue very frustrating... :(

[the-mikedavis]

This is a tricky case to deal with genically with a change in Helix. It's in your best interest to shut down language servers gracefully: a hypothetical language server could be building some database for a project and a hard kill might cause some corruption or lost work.

If you're building from source you can tune this timeout down:

helix/helix-view/src/editor.rs

Line 1366 in ba3c24a

Duration::from_millis(timeout.unwrap_or(3000)),

It's currently 3s which makes the shutdown take a while. We could set a timeout lower as a special case for Application::close I suppose but it's a balance between allowing language servers to terminate gracefully and closing the editor quickly.

[sicher]

Would it be possible to give some immediate feedback to the user that the editor is quitting, a status line "Shutting down language servers..." or something?

[jzskca]

tamasfe/taplo#354 Micheal Davis actually has a pr to fix it

This seems to be fixed in Taplo 0.8.1 now that this PR has been merged.