Solargraph::FileNotFoundError on start up

[jebw]

I'm working on a solargraph client for gnome-builder.

I'm getting a Solargraph::FileNotFoundError on start up when trying to open the solargraph codebase, always with the same file (bin/solargraph). Files are loaded in a random order but it always bin/solargraph which fails.

The client is trying to walk the various documents in the codebase and calling textDocument/documentSymbols for each of them. The error from bin/solargraph is triggered when solargraph tries to look up the file in Dispatch#library_for, other files are using explicit_library_for but bin/solargraph is using implicit_library_for - and the sources list is empty (race between threads maybe?)

Is this expected behaviour? Any pointers for debugging this?

[castwide]

Are you still having a problem with this? A race condition is definitely possible, but I haven't been able to reproduce it in VS Code. It opens 'bin/solargraph' and works as expected. I might be able to help if you can provide me with a stack trace and possibly some sample code that triggers it.

[jebw]

Just updated to master and I'm still seeing this consistently

Solargraph is getting launched from a git checkout, only change is to set the LOG_LEVEL to DEBUG

Solargraph is launched as below

ruby -I/home/jebw/Projects/solargraph/lib /home/jebw/Projects/solargraph/bin/solargraph stdio

{"jsonrpc":"2.0","id":17,"result":[{"name":"Solargraph","containerName":"","kind":2,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":4,"character":0},"end":{"line":221,"character":3}}},"deprecated":false},{"name":"Shell","containerName":"Solargraph","kind":5,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":5,"character":2},"end":{"line":220,"character":5}}},"deprecated":false},{"name":"version","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":11,"character":4},"end":{"line":13,"character":7}}},"deprecated":false},{"name":"socket","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":18,"character":4},"end":{"line":32,"character":7}}},"deprecated":false},{"name":"stdio","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":35,"character":4},"end":{"line":47,"character":7}}},"deprecated":false},{"name":"config","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":51,"character":4},"end":{"line":71,"character":7}}},"deprecated":false},{"name":"download_core","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":74,"character":4},"end":{"line":84,"character":7}}},"deprecated":false},{"name":"list_cores","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":87,"character":4},"end":{"line":89,"character":7}}},"deprecated":false},{"name":"available_cores","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":92,"character":4},"end":{"line":94,"character":7}}},"deprecated":false},{"name":"clear","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":103,"character":4},"end":{"line":106,"character":7}}},"deprecated":false},{"name":"uncache","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":111,"character":4},"end":{"line":119,"character":7}}},"deprecated":false},{"name":"reporters","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":122,"character":4},"end":{"line":124,"character":7}}},"deprecated":false},{"name":"typecheck","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":135,"character":4},"end":{"line":156,"character":7}}},"deprecated":false},{"name":"scan","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":167,"character":4},"end":{"line":187,"character":7}}},"deprecated":false},{"name":"bundle","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":192,"character":4},"end":{"line":194,"character":7}}},"deprecated":false},{"name":"rdoc","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":197,"character":4},"end":{"line":201,"character":7}}},"deprecated":false},{"name":"pin_description","containerName":"Solargraph::Shell","kind":6,"location":{"uri":"file:///home/jebw/Projects/solargraph/lib/solargraph/shell.rb","range":{"start":{"line":207,"character":4},"end":{"line":219,"character":7}}},"deprecated":false}]}
[INFO] Server received textDocument/documentSymbol
[DEBUG] {"method"=>"textDocument/documentSymbol", "jsonrpc"=>"2.0", "id"=>18, "params"=>{"textDocument"=>{"uri"=>"file:///home/jebw/Projects/solargraph/solargraph.gemspec"}}}
[WARN] Error processing request: [Solargraph::FileNotFoundError] Host could not find file:///home/jebw/Projects/solargraph/solargraph.gemspec
[WARN] /home/jebw/Projects/solargraph/lib/solargraph/language_server/host/sources.rb:114:in `find'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/host/dispatch.rb:84:in `block in implicit_library_for'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/host/dispatch.rb:82:in `each'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/host/dispatch.rb:82:in `implicit_library_for'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/host/dispatch.rb:42:in `library_for'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/host.rb:561:in `document_symbols'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/message/text_document/document_symbol.rb:7:in `process'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/host.rb:101:in `receive'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/transport/adapter.rb:44:in `process'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/transport/adapter.rb:17:in `block in opening'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/transport/data_reader.rb:59:in `parse_message_from_buffer'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/transport/data_reader.rb:35:in `block in receive'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/transport/data_reader.rb:30:in `each_char'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/transport/data_reader.rb:30:in `receive'
/home/jebw/Projects/solargraph/lib/solargraph/language_server/transport/adapter.rb:27:in `receiving'
/home/jebw/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/client.rb:63:in `tick'
/home/jebw/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/server/stdio.rb:18:in `update'
/home/jebw/.rbenv/versions/2.6.6/lib/ruby/2.6.0/observer.rb:197:in `block in notify_observers'
/home/jebw/.rbenv/versions/2.6.6/lib/ruby/2.6.0/observer.rb:196:in `each'
/home/jebw/.rbenv/versions/2.6.6/lib/ruby/2.6.0/observer.rb:196:in `notify_observers'
/home/jebw/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/client.rb:121:in `read_input'
/home/jebw/.rbenv/versions/2.6.6/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/client.rb:102:in `block in run_input_thread'
[INFO] Sending response to textDocument/documentSymbol
[DEBUG] Content-Length: 170

[jebw]

I can push the integration code somewhere if you're interested but the actual LSP support is all in C and provided by Gnome-Builder itself, I've just got some python to spawn Solargraph and forward on requests (plugins have to be python or C)

It normally seems to be the bin/ file which fails but I'm guessing thats because thats the first file it tries to index

[castwide]

Thanks for following up. This made me think of another possibility. Your client might be sending the textDocument/documentSymbol request before the server is finished initializing. That could raise Solargraph::FileNotFoundError because the workspace hasn't been mapped yet. On my computers, it usually takes about 5 seconds to initialize when opening the Solargraph codebase in VS Code.

If that's the case, it sounds like a bit of a problem on both sides. The LSP specification prohibits clients from sending additional requests before the server responds to the initialize request (see https://microsoft.github.io/language-server-protocol/specification#initialize), but the server should probably respond with a more precise error message.

[castwide]

I'll go ahead and update the server to send a proper ServerNotInitialized error. Even if that's not the root cause of this issue, it's the right thing in general.

[jebw]

That sounds very likely to be the probably cause - this maybe an issue with how Gnome-builder implements LSP. Most existing plugins for builder are for compiled languages and probably have much faster startups, so it maybe they also have the same theoretical race condition on start up but the timing means they never hit it.

I can probably implement something in the plugin to observe when init has completed, and only send other requests after that.

Slightly separate to the above - my observation of Gnome-Builder is that its trying to start/restart the LSP server whenever I switch between files - which sounds different to how VSCode handles it? Does that just start the server when the project is opened?

[jebw]

I found I could hook when the initialization completes, and it is completing before the FileNotFound errors, suggesting that isn't the source of the problem?

I've got a longer debug file with the LSP messages going back and forth and a bunch of my debug output if that helps?

[castwide]

Slightly separate to the above - my observation of Gnome-Builder is that its trying to start/restart the LSP server whenever I switch between files - which sounds different to how VSCode handles it? Does that just start the server when the project is opened?

Yes, VS Code starts one persistent instance of the server and uses it for requests on all files.

I've got a longer debug file with the LSP messages going back and forth and a bunch of my debug output if that helps?

Oh yeah, that might help a lot.

[jebw]

dump.log

:point_up:

[castwide]

Thanks! I think I found the problem.

When Solargraph initializes, it maps all the .rb files in your workspace except a few common "non-library" directories, like spec and .bundle. If you open a workspace file that hasn't been mapped, Solargraph will temporarily add it to Sources in response to a textDocument/didOpen event. This ensures that you still get code intelligence when you're working with a file that wouldn't normally be mapped.

In your case, the client requests textDocument/documentSymbol on bin/solargraph without a preceding textDocument/didOpen. Since the file's not in Sources, it raises Solargraph::FileNotFoundError.

I think we can remove this limitation altogether. In the current gem (especially when using Ruby 2.6+), generating a Source from a file is fast enough that we should be able to do it on demand. There used to be memory concerns about having too many files open at once, but the Source and SourceMap implementations are much more efficient now. Clients that report textDocument/didOpen events would still work the same.

I'll look into updating Dispatch and/or Sources so it can handle this use case.

[castwide]

Correction: Your client is sending the textDocument/didOpen event, but it gets sent for multiple files, and Solargraph only tracks one "open" file at a time. (In VS Code, the "open" file is the one whose editor tab currently has focus.)

It's a slightly different issue, but it's still a limitation we should be able to remove.