Refactored server failure on multifile projects

[clason]

This may be premature, but I just tested the refactored version of texlab (macOS Catalina, neovim with vim-lsp). There seems to be something wrong with the workspace detection: While hover, complete, and gotoDefinition seem to work for bibtex and the current tex file, I don't get any result on these for labels from different files. Here's a (hopefully relevant) part of the vim-lsp log for calling hover on a label defined in a different subfile:

Sat Apr 11 10:30:53 2020:["--->", 5, "texlab", {"method": "textDocument/hover", "on_notification": "---       funcref---", "params": {"textDocument": {"uri": "file:///XXX"},       "position": {"character": 45, "line": 6}}}]
Sat Apr 11 10:30:53 2020:["<---", 5, {"method": "workspace/configuration", "jsonrpc": "2.0", "id": 34,        "params": {"items": [{"section": "latex"}]}}]
Sat Apr 11 10:30:53 2020:["--->", 5, "texlab", {"id": 34, "result": [null]}]
Sat Apr 11 10:30:53 2020:["<---", 5, {"method": "workspace/configuration", "jsonrpc": "2.0", "id": 35,        "params": {"items": [{"section": "bibtex"}]}}]
Sat Apr 11 10:30:53 2020:["--->", 5, "texlab", {"id": 35, "result": [{"formatting": {"lineLength": 0}}]}]
Sat Apr 11 10:30:53 2020:["<---(stderr)", 5, "texlab", ["thread 'main' panicked at 'index out of bounds: the  len is 347 but the index is 1490', /private/tmp/rust-20200323-19534-npgehr/rustc-1.42.0-src/src/libcore/slice/mod.rs:2791:10", "note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace", ""]]

EDIT: and I just found this at the top of the log:

Sat Apr 11 10:30:47 2020:["Starting server", "texlab", ["/Users/clason/.cache/nvim/nvim_lsp/texlab"]]
Sat Apr 11 10:30:47 2020:[{"response": {"data": {"__data__": "vim-lsp", "lsp_id": 5, "server_name":           "texlab"}, "message": "started lsp server successfully"}}]
Sat Apr 11 10:30:47 2020:[{"response": {"error": {"data": {"lsp_id": 5, "__error__": "vim-lsp",               "server_name": "texlab"}, "code": 0, "message": "ignore initialization lsp server due to empty root_uri"}}}]

Also, texlab seems to be noticeable slower than before, but I can't quantify that?

EDIT 2: Same under Linux.

[pfoerster]

Thanks for the report.

Sat Apr 11 10:30:53 2020:["<---(stderr)", 5, "texlab", ["thread 'main' panicked at 'index out of bounds: the len is 347 but the index is 1490', /private/tmp/rust-20200323-19534-npgehr/rustc-1.42.0-src/src/libcore/slice/mod.rs:2791:10", "note: run with RUST_BACKTRACE=1 environment variable to display a backtrace", ""]]

Can you try to run texlab with RUST_BACKTRACE = 1? I cannot reproduce this on my machine.

There seems to be something wrong with the workspace detection:

Can you try setting latex.rootDirectory to null? This one should be the only visible change to the workspace detection algorithm.

Also, texlab seems to be noticeable slower than before, but I can't quantify that?

I haven't tested the performance that much yet with a release build, but I will add some benchmarks to find the regressions. I have still some optimizations left to try out so I think we will get to the level of the old performance pretty easily.

[pfoerster]

Sat Apr 11 10:30:47 2020:[{"response": {"error": {"data": {"lsp_id": 5, "error": "vim-lsp", "server_name": "texlab"}, "code": 0, "message": "ignore initialization lsp server due to empty root_uri"}}}]

This one seems to be odd. According to the LSP spec, the client has to specify the rootUri and not the server. I just looked at the source code of vim-lsp and they seem to expect a rootUri inside the serverInfo object.

[clason]

This one seems to be odd. According to the LSP spec, the client has to specify the rootUri and not the server. I just looked at the source code of vim-lsp and they seem to expect a rootUri inside the serverInfo object.

You are of course right; it just seemed related; texlab was working fine without specifying this before. (But I just checked, the error has always been there.)

Can you try setting latex.rootDirectory to null? This one should be the only visible change to the workspace detection algorithm.

Then I get no hover definition found. I'm using

                \ 'workspace_config': {
                \       'bibtex': {'formatting': {'lineLength': 0}},
                \       'latex': {'rootDirectory': 'null'},
                \ },

maybe that's not the right way?

Can you try to run texlab with RUST_BACKTRACE = 1? I cannot reproduce this on my machine.

Sure! How would I do that (from vim-lsp)?

[pfoerster]

Sure! How would I do that (from vim-lsp)?

It is just an environment variable so it should get passed down to texlab if you run RUST_BACKTRACE = 1 nvim ....

maybe that's not the right way?

This seems to be the right way.

Maybe, I will try to use the old issues as test cases to find a reproducing example so I can fix this regression.

[clason]

Backtrace:

Sat Apr 11 11:53:00 2020:["<---(stderr)", 5, "texlab", ["thread 'main' panicked at 'index out of bounds: the  len is 347 but the index is 1402', /private/tmp/rust-20200323-19534-npgehr/rustc-1.42.0-src/src/libcore/slice/mod.rs:2791:10", ""]]
Sat Apr 11 11:53:00 2020:["<---(stderr)", 5, "texlab", ["stack backtrace:", ""]]
Sat Apr 11 11:53:00 2020:["<---(stderr)", 5, "texlab", ["   0: <std::sys_common::backtrace::_print::          DisplayBacktrace as core"]]
Sat Apr 11 11:53:00 2020:["<---(stderr)", 5, "texlab", ["::fmt::Display>::fmt", "   1: core::fmt::write", "   2: std::io::Write::write_fmt", "   3: std::panicking::default_hook::{{closure}}", "   4: std::panicking::     rust_panic_with_hook", "   5: rust_begin_unwind", "   6: core::panicking::panic_fmt", "   7: core::panicking::panic_bounds_check", "   8: texlab::outline::OutlineContext::parse", "   9: <std::future::GenFuture<T> as     core::future::future::Future>::poll", "  10: <std::future::GenFuture<T> as core::future::future::Future>::    poll", "  11: <std::future::GenFuture<T> as core::future::future::Future>::poll", "  12: <texlab::server::    LatexLspServer<C> as texlab::jsonrpc::server::RequestHandler>::handle_request::{{closure}}", "  13: <std::    future::GenFuture<T> as core::future::future::Future>::poll", "  14: tokio::task::core::Core<T>::poll", "     15: tokio::task::raw::poll", "  16: texlab::main", "  17: std::rt::lang_start::{{closure}}", "  18: main",    "note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.", ""]]

(this is without latex.rootDirectory; there's no panick if I specify it).

I tried a minimal example, but that worked fine. So there has to be some minimal complexity (maybe it needs bibtex?)

[clason]

In the log, I see references to rootPath (which is set correctly) rather than rootDirectory?

[clason]

This example has the same issue: #23 (comment)
(try typing -- or completing -- \ref{sec:1} in test2.tex and hovering).

Here's the full log when doing that (ignore the vimscript errors, look for the "hover" method):
vim-lsp.log

The labels sec:2 and eq:2 are treated correctly.

(This example works if I omit the latex.rootDirectory, though.)

[pfoerster]

This example has the same issue: #23 (comment)
(try typing -- or completing -- \ref{sec:1} in test2.tex and hovering).

From which directory are you calling nvim? Is it the same directory, which contains the TeX files?
If no, then I think that I found the error.

Backtrace:
Sat Apr 11 11:53:00 2020:["<---(stderr)", 5, "texlab", ["thread 'main' panicked at 'index out of bounds: the len is 347 but the index is 1402', /private/tmp/rust-20200323-19534-npgehr/rustc-1.42.0-src/src/libcore/slice/mod.rs:2791:10", ""]]
Sat Apr 11 11:53:00 2020:["<---(stderr)", 5, "texlab", ["stack backtrace:", ""]]
Sat Apr 11 11:53:00 2020:["<---(stderr)", 5, "texlab", [" 0: <std::sys_common::backtrace::_print:: DisplayBacktrace as core"]]
Sat Apr 11 11:53:00 2020:["<---(stderr)", 5, "texlab", ["::fmt::Display>::fmt", " 1: core::fmt:

Can you run the same thing with a debug build, please? The compiler seems to have optimized the faulty function and the line numbers away.

[clason]

From which directory are you calling nvim? Is it the same directory, which contains the TeX files?
If no, then I think that I found the error.

Yes, from the same directory.

[clason]

Sat Apr 11 14:32:16 2020:["--->", 5, "texlab", {"id": 9, "result": [{"formatting": {"lineLength": 0}}]}]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["thread 'main' panicked at 'index out of bounds: the len is 347 but the index is 1402', /private/tmp/rust-20200323-19534-npgehr/rustc-1.42.0-src/src/libcore/slice/mod.rs:2791:10", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["stack backtrace:", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["   0: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["   1: core::fmt::write", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["   2: std::io::Write::write_fmt", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["   3: std::panicking::default_hook::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["   4: std::panicking::default_hook", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["   5: std::panicking::rust_panic_with_hook", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["   6: rust_begin_unwind", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["   7: core::panicking::panic_fmt", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["   8: core::panicking::panic_bounds_check", "   9: <usize as core::slice::SliceIndex<[T]>>::index", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  10: core::slice::<impl core::ops::index::Index<I> for [T]>::index", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  11: <alloc::vec::Vec<T> as core::ops::index::Index<I>>::index", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  12: <petgraph::graph_impl::Graph<N,E,Ty,Ix> as core::ops::index::Index<petgraph::graph_impl::NodeIndex<Ix>>>::index", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  13: texlab::syntax::latex::analysis::Environment::range", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  14: texlab::outline::OutlineContext::find_theorem", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  15: texlab::outline::OutlineContext::parse::{{closure}}", "  16: core::option::Option<T>::or_else", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  17: texlab::outline::OutlineContext::parse", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  18: <texlab::hover::latex::label::LatexLabelHoverProvider as texlab::feature::FeatureProvider>::execute::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  19: <std::future::GenFuture<T> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  20: <core::pin::Pin<P> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  21: std::future::poll_with_tls_context", "  22: <texlab::feature::ChoiceProvider<P,O> as texlab::feature::FeatureProvider>::execute::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  23: <std::future::GenFuture<T> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  24: <core::pin::Pin<P> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  25: std::future::poll_with_tls_context", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  26: <texlab::hover::HoverProvider as texlab::feature::FeatureProvider>::execute::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  27: <std::future::GenFuture<T> as core::future::future::Future>::poll", "  28: <core::pin::Pin<P> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  29: std::future::poll_with_tls_context", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  30: texlab::server::LatexLspServer<C>::hover::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  31: <std::future::GenFuture<T> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  32: std::future::poll_with_tls_context", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  33: <texlab::server::LatexLspServer<C> as texlab::jsonrpc::server::RequestHandler>::handle_request::{{closure}}::{{closure}}::{{closure}}", "  34: <std::future::GenFuture<T> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  35: std::future::poll_with_tls_context", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  36: texlab::jsonrpc::server::handle_request::{{closure}}::{{closure}}::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  37: <std::future::GenFuture<T> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  38: std::future::poll_with_tls_context", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  39: texlab::jsonrpc::server::handle_request::{{closure}}", "  40: <std::future::GenFuture<T> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  41: std::future::poll_with_tls_context", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  42: <texlab::server::LatexLspServer<C> as texlab::jsonrpc::server::RequestHandler>::handle_request::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  43: <std::future::GenFuture<T> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  44: <core::pin::Pin<P> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  45: std::future::poll_with_tls_context", "  46: texlab::jsonrpc::MessageHandler<S,C>::handle::{{closure}}::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  47: <std::future::GenFuture<T> as core::future::future::Future>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  48: tokio::task::core::Core<T>::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  49: tokio::task::harness::Harness<T,S>::poll::{{closure}}::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  50: core::ops::function::FnOnce::call_once", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  51: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  52: std::panicking::try::do_call", "  53: __rust_maybe_catch_panic", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  54: std::panicking::try", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  55: std::panic::catch_unwind", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  56: tokio::task::harness::Harness<T,S>::poll::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  57: tokio::loom::std::causal_cell::CausalCell<T>::with_mut", "  58: tokio::"]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["task::harness::Harness<T,S>::poll", "  59: tokio::task::raw::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  60: tokio::task::raw::RawTask::poll", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  61: tokio::task::Task<S>::run", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  62: tokio::runtime::basic_scheduler::SchedulerPriv::tick", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  63: tokio::runtime::basic_scheduler::BasicScheduler<P>::block_on", "  64: tokio::runtime::Runtime::block_on::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  65: tokio::runtime::context::enter", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  66: tokio::runtime::handle::Handle::enter", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  67: tokio::runtime::Runtime::block_on", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  68: texlab::main", "  69: std::rt::lang_start::{{closure}}", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  70: std::panicking::try::do_call", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  71: __rust_maybe_catch_panic", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  72: std::rt::lang_start_internal", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["  73: std::rt::lang_start", "  74: main", ""]]
Sat Apr 11 14:32:17 2020:["<---(stderr)", 5, "texlab", ["note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.", ""]]
Sat Apr 11 14:33:02 2020:["s:on_text_document_did_save()", 1]
Sat Apr 11 14:33:02 2020:["s:on_text_document_did_close()", 1]

[pfoerster]

Thanks. The crash should be fixed with bf97694.

[clason]

Great, that fixes the not working hover/gotoDefinition as well! Thanks!

[pfoerster]

Great, that fixes the not working hover/gotoDefinition as well! Thanks!

Did it fix the workspace detection issue as well?

Also, texlab seems to be noticeable slower than before, but I can't quantify that?

I benchmarked the completion and the initial performance seems to be roughly the same. With 7eb1adc, the new version should be a bit faster than the old version (at least for the comletion of commands).

[clason]

I think yes, because that seemed to have been the underlying issue that prevented hover from working. I also now get many more completion candidates in my multi-file projects (I haven't fully checked, but now it seems to be all of them, where previously candidates from some other files were missing)...

...however, that has made completion significantly slower than before (which is hardly surprising since now it seems to be checking much more files). Would it be possible to implement some caching for this (I did not notice any such effects)?

(How can I check whether the workspace detection is working as intended, by the way?)

[pfoerster]

I think yes, because that seemed to have been the underlying issue that prevented hover from working. I also now get many more completion candidates in my multi-file projects (I haven't fully checked, but now it seems to be all of them, where previously candidates from some other files were missing)...

This is good to hear. I fixed a lot of small errors in the workspace detection algorithm (in addititon to that, it now works with URIs mostly instead of paths like the old version so it should work with remote files too).

...however, that has made completion significantly slower than before (which is hardly surprising since now it seems to be checking much more files). Would it be possible to implement some caching for this (I did not notice any such effects)?

Caching is a bit difficult because the LSP type definition crate we are using does not support returning borrowed data. Almost all the during completion is spent allocating the CompletionItems and serializing them to JSON. I will try patching it to see whether it noticably affects the performance (there is a open issue at their repository: gluon-lang/lsp-types#20). Before 7eb1adc, texlab used to allocate every completion item and then truncate the list to 50 items at maximum (sendings more items cause VSCode to lag severely or even crash because their completion list does not seem to be virtualized). Now, the truncation is done before allocating the completion items.

(How can I check whether the workspace detection is working as intended, by the way?)

You can try triggering the completion for a command, which is provided by a package in a different file. If the command shows up in the list, then the files are considered to be in the same workspace. In addition to that, I can easily add a log statement, which displays all files that are considered when executing an operation.

[clason]

You can try triggering the completion for a command, which is provided by a package in a different file. If the command shows up in the list, then the files are considered to be in the same workspace.

Yes, that works -- I get completion of commands from all manner of \usepackages (but this seemed to be working before already?)

In addition to that, I can easily add a log statement, which displays all files that are considered when executing an operation.

If you think it's helpful, I can try that locally. Otherwise I'd consider the workspace detection fixed.

I understand the caching issue. If there's anything I can do to profile this (easily) on my project, let me know! (Otherwise, my "stress test" project is an expanded version of https://arxiv.org/abs/2001.00216, for which you can download the sources if you're interested.)