Clojure crashing the editor

HiiGHoVuTi commented 2 years ago

Summary

The bug is really simple, the helix-lsp-client seems to crash when editing clojure code. At first the editing works and at some point it crashes and from then on, it is impossible to re-open the file without the editor crashing.

Reproduction Steps

I'm in a default lein project.

I tried this:

hx src/project/core.clj
go around changing some code

I expected this to happen:

being able to use helix to edit clojure files

Instead, this happened:

after some time editing the file, the editor crashes. When trying to re-open the file, it crashes immediately.

Helix log

~/.cache/helix/helix.log

``` Caused by: channel closed) 2022-08-11T10:46:32.297 helix_term::application [ERROR] Language Server: Method not found client/registerCapability 2022-08-11T10:53:21.546 helix_lsp::client [WARN] language server failed to terminate gracefully - failed to parse: invalid type: map, expected unit 2022-08-11T10:54:14.728 helix_lsp::transport [ERROR] err: <- Other(failed to send a message to server Caused by: channel closed) 2022-08-11T10:55:26.963 helix_lsp::transport [ERROR] err: <- StreamClosed 2022-08-11T10:55:26.963 helix_lsp::transport [ERROR] err: <- StreamClosed 2022-08-11T10:56:30.952 helix_lsp::transport [ERROR] err: <- Other(failed to send a message to server Caused by: channel closed) 2022-08-11T10:57:14.206 helix_lsp::transport [ERROR] err: <- Other(failed to send a message to server Caused by: channel closed) ``` or sometimes ``` Caused by: channel closed) 2022-08-11T11:11:55.481 helix_view::editor [ERROR] Failed to initialize the LSP for `source.clojure` { cannot find binary path } 2022-08-11T11:12:00.294 helix_view::editor [ERROR] Failed to initialize the LSP for `source.clojure` { cannot find binary path } ``` (`clojure-lsp` is in my path and it's found sometimes) on top of that, the instantaneous crash when I open the file doesn't produce any logs !

Rust stack trace

Here are the rust logs, since they were provided too: ``` thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', /build/81fl2hx743wzi1fr8zmak81ggyahvz9m-source/helix-term/src/application.rs:513:81 stack backtrace: 0: 0x55eff7d2d494 - ::fmt::h9c2a9d2774d81873 1: 0x55eff756b76c - core::fmt::write::hba4337c43d992f49 2: 0x55eff7d26e75 - std::io::Write::write_fmt::heb73de6e02cfabed 3: 0x55eff7d2f33e - std::panicking::default_hook::{{closure}}::hc9a76eed0b18f82b 4: 0x55eff7d2f06d - std::panicking::default_hook::h2e88d02087fae196 5: 0x55eff7bb8c6c - helix_term::application::Application::run::{{closure}}::{{closure}}::h2a171355ca53c72c 6: 0x55eff7d2f9cb - std::panicking::rust_panic_with_hook::habfdcc2e90f9fd4c 7: 0x55eff7d2f7cc - std::panicking::begin_panic_handler::{{closure}}::he054b2a83a51d2cd 8: 0x55eff7d2d9c4 - std::sys_common::backtrace::__rust_end_short_backtrace::ha48b94ab49b30915 9: 0x55eff7d2f55d - rust_begin_unwind 10: 0x55eff74ead53 - core::panicking::panic_fmt::h366d3a309ae17c94 11: 0x55eff74eac1d - core::panicking::panic::h8705e81f284be8a5 12: 0x55eff7be8085 - core::ops::function::impls:: for &mut F>::call_mut::h8c3d620290629383 13: 0x55eff7ba79ae - as alloc::vec::spec_from_iter::SpecFromIter>::from_iter::ha0789922cc9bb92c 14: 0x55eff7bb6eb6 - helix_term::application::Application::event_loop_until_idle::{{closure}}::h8be88e44471bed39 15: 0x55eff7bd30bb - as core::future::future::Future>::poll::h00641bb03ff36fdd 16: 0x55eff7bab4a2 - std::thread::local::LocalKey::with::h4a2650524fd0402e 17: 0x55eff7b93688 - tokio::park::thread::CachedParkThread::block_on::h23825ea45ad693b3 18: 0x55eff7bf48b8 - tokio::runtime::thread_pool::ThreadPool::block_on::h7d48bcf67d5258ff 19: 0x55eff7bcfd83 - tokio::runtime::Runtime::block_on::hab8dd3ba388c1c22 20: 0x55eff7b8b936 - hx::main::h8012874220ecbbec 21: 0x55eff7b8ba63 - std::sys_common::backtrace::__rust_begin_short_backtrace::h8b4ea23ef8b6946e 22: 0x55eff7bab19d - std::rt::lang_start::{{closure}}::hc01c98d73647ef30 23: 0x55eff7d2170b - std::rt::lang_start_internal::h9c06694362b5b80c 24: 0x55eff7b8ba42 - main 25: 0x7fd6da83b237 - __libc_start_call_main 26: 0x7fd6da83b2f5 - __libc_start_main_impl 27: 0x55eff7520ef1 - _start 28: 0x0 - ```

Platform

Linux (NixOS)

Terminal Emulator

wezterm

Helix Version

helix 22.05 (d192d59)

the-mikedavis commented 2 years ago

I tried poking around in a clojure project for a while but I couldn't reproduce this with the clojure-lsp from nixpkgs unstable:

clojure-lsp 2022.07.24-18.25.43
clj-kondo 2022.06.23-SNAPSHOT

The panic comes from the handling of LSP PublishDiagnostics here: https://github.com/helix-editor/helix/blob/80dde577b0287410cc5a7af79e6737425f95abff/helix-term/src/application.rs#L513

which looks like it can be None if the language server's capabilities are not set up yet, although I'm not sure what series of events could lead to that.

Can you reproduce this running in verbose mode (hx -v) and post the log? Verbose mode will spit out the messages between the language server and helix.

HiiGHoVuTi commented 2 years ago

and here are some logs:

2022-08-11T16:26:43.597 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"$/progress","params":{"token":"clojure-lsp","value":{"kind":"report","message":"Analyzing external classpath","percentage":43}}}
2022-08-11T16:26:43.600 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"$/progress","params":{"token":"clojure-lsp","value":{"kind":"report","message":"Analyzing external classpath","percentage":43}}}
2022-08-11T16:26:43.601 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"$/progress","params":{"token":"clojure-lsp","value":{"kind":"report","message":"Analyzing external classpath","percentage":44}}}
2022-08-11T16:26:43.798 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"$/progress","params":{"token":"clojure-lsp","value":{"kind":"report","message":"Resolving config paths","percentage":45}}}
2022-08-11T16:26:43.798 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"$/progress","params":{"token":"clojure-lsp","value":{"kind":"report","message":"Analyzing project files","percentage":50}}}
2022-08-11T16:26:43.799 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"$/progress","params":{"token":"clojure-lsp","value":{"kind":"report","message":"Analyzing project files","percentage":74}}}
2022-08-11T16:26:43.800 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"$/progress","params":{"token":"clojure-lsp","value":{"kind":"report","message":"Analyzing project files","percentage":99}}}
2022-08-11T16:26:43.805 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"$/progress","params":{"token":"clojure-lsp","value":{"kind":"end","message":"Project analyzed"}}}
2022-08-11T16:26:43.806 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/maxime/tmp/t/test/t/core_test.clj","diagnostics":[{"range":{"start":{"line":1,"character":33},"end":{"line":1,"character":37}},"severity":2,"code":"refer-all","source":"clj-kondo","message":"use alias or :refer [deftest is testing]","tags":[]},{"range":{"start":{"line":2,"character":27},"end":{"line":2,"character":31}},"severity":2,"code":"refer-all","source":"clj-kondo","message":"use alias or :refer","tags":[]}]}}
2022-08-11T16:26:43.806 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","id":0,"result":{"capabilities":{"textDocumentSync":{"openClose":true,"change":1,"save":{"includeText":true}},"hoverProvider":true,"completionProvider":{"resolveProvider":true,"triggerCharacters":[":","/"]},"signatureHelpProvider":{"triggerCharacters":[]},"definitionProvider":true,"implementationProvider":true,"referencesProvider":true,"documentHighlightProvider":true,"documentSymbolProvider":true,"workspaceSymbolProvider":true,"codeActionProvider":{"codeActionKinds":["quickfix","refactor","refactor.extract","refactor.inline","refactor.rewrite","source","source.organizeImports"]},"codeLensProvider":{"resolveProvider":true},"documentFormattingProvider":true,"documentRangeFormattingProvider":true,"renameProvider":{"prepareProvider":true},"declarationProvider":true,"executeCommandProvider":{"commands":["add-import-to-namespace","add-missing-import","add-missing-libspec","add-require-suggestion","change-coll","clean-ns","create-function","create-test","cycle-coll","cycle-privacy","demote-fn","destructure-keys","drag-backward","drag-forward","expand-let","extract-function","extract-to-def","inline-symbol","introduce-let","move-coll-entry-down","move-coll-entry-up","move-form","move-to-let","promote-fn","resolve-macro-as","sort-map","suppress-diagnostic","thread-first","thread-first-all","thread-last","thread-last-all","unwind-all","unwind-thread"]},"workspace":{"fileOperations":{"willRename":{"filters":[{"pattern":{"glob":"**/*.{clj,cljs,cljc,cljd,edn,bb,clj_kondo}","matches":"file"},"scheme":"file"}]}}},"callHierarchyProvider":true,"linkedEditingRangeProvider":true,"semanticTokensProvider":{"legend":{"tokenTypes":["namespace","type","function","macro","keyword","class","variable","method","event"],"tokenModifiers":["definition","defaultLibrary","implementation"]},"range":true,"full":true},"experimental":{"testTree":true,"cursorInfo":true,"serverInfo":true,"clojuredocs":true}}}}
2022-08-11T16:26:43.806 helix_lsp::transport [INFO] <- {"capabilities":{"callHierarchyProvider":true,"codeActionProvider":{"codeActionKinds":["quickfix","refactor","refactor.extract","refactor.inline","refactor.rewrite","source","source.organizeImports"]},"codeLensProvider":{"resolveProvider":true},"completionProvider":{"resolveProvider":true,"triggerCharacters":[":","/"]},"declarationProvider":true,"definitionProvider":true,"documentFormattingProvider":true,"documentHighlightProvider":true,"documentRangeFormattingProvider":true,"documentSymbolProvider":true,"executeCommandProvider":{"commands":["add-import-to-namespace","add-missing-import","add-missing-libspec","add-require-suggestion","change-coll","clean-ns","create-function","create-test","cycle-coll","cycle-privacy","demote-fn","destructure-keys","drag-backward","drag-forward","expand-let","extract-function","extract-to-def","inline-symbol","introduce-let","move-coll-entry-down","move-coll-entry-up","move-form","move-to-let","promote-fn","resolve-macro-as","sort-map","suppress-diagnostic","thread-first","thread-first-all","thread-last","thread-last-all","unwind-all","unwind-thread"]},"experimental":{"clojuredocs":true,"cursorInfo":true,"serverInfo":true,"testTree":true},"hoverProvider":true,"implementationProvider":true,"linkedEditingRangeProvider":true,"referencesProvider":true,"renameProvider":{"prepareProvider":true},"semanticTokensProvider":{"full":true,"legend":{"tokenModifiers":["definition","defaultLibrary","implementation"],"tokenTypes":["namespace","type","function","macro","keyword","class","variable","method","event"]},"range":true},"signatureHelpProvider":{"triggerCharacters":[]},"textDocumentSync":{"change":1,"openClose":true,"save":{"includeText":true}},"workspace":{"fileOperations":{"willRename":{"filters":[{"pattern":{"glob":"**/*.{clj,cljs,cljc,cljd,edn,bb,clj_kondo}","matches":"file"},"scheme":"file"}]}}},"workspaceSymbolProvider":true}}
2022-08-11T16:26:43.806 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{"uri":"file:///home/maxime/tmp/t/src/t/core.clj","diagnostics":[{"range":{"start":{"line":2,"character":6},"end":{"line":2,"character":9}},"severity":3,"code":"clojure-lsp/unused-public-var","source":"clojure-lsp","message":"Unused public var \u0027t.core/foo\u0027","tags":[1]}]}}
2022-08-11T16:26:43.806 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"initialized","params":{}}
2022-08-11T16:26:43.807 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","id":"1","method":"client/registerCapability","params":{"registrations":[{"id":"id","method":"workspace/didChangeWatchedFiles","registerOptions":{"watchers":[{"globPattern":"**/*.{clj,cljs,cljc,cljd,edn,bb,clj_kondo}"}]}}]}}

HiiGHoVuTi commented 2 years ago

retrying without -v on a new project gave me this interesting line:

2022-08-11T16:32:24.778 helix_term::application [ERROR] Timed out waiting for language servers to shutdown

which is the only line logged before crashing

the-mikedavis commented 2 years ago

Ah, these two lines are interesting:

2022-08-11T16:26:43.806 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics",...
2022-08-11T16:26:43.806 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","id":0,"result":{"capabilities":...

Looks like clojure-lsp is sending a textDocument/publishDiagnostics before the initializeResult which is invalid according to the LSP spec. If you have a reliable reproduction case you can share (they would probably want an example project that exhibits the behavior), it would be good to report this upstream to clojure-lsp. I haven't been able to reproduce oddly.

That being said, we've been trying to be more defensive about spec violations: we should discard messages and not panic when the server breaks spec. I've opened a PR to log and discard the textDocument/publishDiagnostic if it's received before the language server is initialized: #3403. Could you give that a try and see if that prevents the panic?

HiiGHoVuTi commented 2 years ago

Today I cannot reproduce this bug, even though I changed nothing in my setup (unless there was a sneaky update?). Your diagnostic makes sense with what I was experiencing, so I hope it won't happen to other people (or future me). If I come across it again I'll upgrade and file an issue to clojure-lsp.

helix-editor / helix