Solargraph: Hangs on macOS on certain textDocument/completion request

[tallytarik]

Hi,

First off, thanks so much for your work on Solargraph - it's incredible.

That said, there's been an issue that I've been experiencing for some time. While I'm working on a project in VS Code, after an indeterminate amount of time the Solargraph process will hang. It'll be stuck using 100% CPU, and it doesn't recover.

The only way to work around it has been to force-kill the ruby solargraph process, and restart VSCode to get it to spawn a new server.

Unfortunately I don't have a reproducible case, because it seems to happen randomly. It happens on every Ruby project that I've worked on, noting that they're all Rails projects. If I'm working on a project long enough, Solargraph will hang.

I took some time to try debugging the process today, and managed to get it to provide a backtrace:

[INFO] Server received textDocument/completion
[DEBUG] {"jsonrpc"=>"2.0", "id"=>132, "method"=>"textDocument/completion", "params"=>{"textDocument"=>{"uri"=>"file:///Users/user/project/redacted-file-1.rb"}, "position"=>{"line"=>15, "character"=>68}, "context"=>{"triggerKind"=>1}}}
[INFO] Cataloging /Users/user/project
[INFO] Catalog complete (68701 pins)
[INFO] Cataloging /Users/user/project
[INFO] Catalog complete (68701 pins)
[INFO] Cataloging /Users/user/project
[INFO] Catalog complete (68701 pins)
[INFO] Diagnosing file:///Users/user/project/redacted-file-1.rb
.rubocop.yml: Metrics/LineLength has the wrong namespace - should be Layout
[INFO] Server sent textDocument/publishDiagnostics
[DEBUG] ** redacted diagnostic response **

** Process hung at this point
** Started debugging the process here **
** Managed to kill the hung thread, which gave the following backtrace **

[WARN] Error processing request: [SystemStackError] stack level too deep
[WARN] /Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/api_map.rb:547:in `cache'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/api_map.rb:238:in `qualify'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/api_map.rb:516:in `super_and_sub?'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/api_map.rb:348:in `get_complex_type_methods'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/source_map/clip.rb:47:in `complete'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/library.rb:160:in `completions_at'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/host.rb:494:in `completions_at'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/message/text_document/completion.rb:12:in `process'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/host.rb:101:in `receive'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/adapter.rb:44:in `process'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/adapter.rb:17:in `block in opening'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/data_reader.rb:57:in `parse_message_from_buffer'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/data_reader.rb:35:in `block in receive'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/data_reader.rb:30:in `each_char'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/data_reader.rb:30:in `receive'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/adapter.rb:27:in `receiving'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/client.rb:63:in `tick'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/server/tcpip.rb:76:in `update'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/2.6.0/observer.rb:197:in `block in notify_observers'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/2.6.0/observer.rb:196:in `each'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/2.6.0/observer.rb:196:in `notify_observers'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/client.rb:121:in `read_input'
/Users/user/.rbenv/versions/2.6.5/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/completion
[DEBUG] Content-Length: 102

{"jsonrpc":"2.0","id":132,"error":{"code":-32603,"message":"[SystemStackError] stack level too deep"}}

** Process continued as normal here **

So it looks like it hung on a textDocument/completion request trying to call @mutex.synchronize.

Unfortunately, that's where my debugging foo ends. If there's anything I can do to help figure this out, please let me know! I'm currently running Solargraph separately so I can attach to the process to grab backtraces, in case it happens again, so I'll let you know if I have more.

[tallytarik]

Ok, actually, following the above it looks like I can reproduce it. It's hanging on textDocument/completion with a certain variable.

Another backtrace:

[INFO] Server received textDocument/completion
[DEBUG] {"jsonrpc"=>"2.0", "id"=>48, "method"=>"textDocument/completion", "params"=>{"textDocument"=>{"uri"=>"file:///Users/user/project/redacted-file-1.rb"}, "position"=>{"line"=>15, "character"=>67}, "context"=>{"triggerKind"=>2, "triggerCharacter"=>"."}}}
[INFO] Cataloging /Users/user/project
[INFO] Catalog complete (68702 pins)
[INFO] Cataloging /Users/user/project
[INFO] Catalog complete (68702 pins)
[INFO] Cataloging /Users/user/project
[INFO] Catalog complete (68702 pins)
[INFO] Diagnosing file:///Users/user/project/redacted-file-1.rb
.rubocop.yml: Metrics/LineLength has the wrong namespace - should be Layout
[INFO] Server sent textDocument/publishDiagnostics
[DEBUG] {:uri=>"file:///Users/user/project/redacted-file-1.rb", :diagnostics=>[** redacted **]}

** Process hung at this point
** Started debugging the process here **
** Managed to kill the hung thread, which gave the following backtrace **

[WARN] Error processing request: [SystemStackError] stack level too deep
[WARN] /Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/api_map/cache.rb:30:in `get_qualified_namespace'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/api_map.rb:238:in `qualify'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/api_map.rb:516:in `super_and_sub?'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/api_map.rb:348:in `get_complex_type_methods'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/source_map/clip.rb:47:in `complete'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/library.rb:160:in `completions_at'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/host.rb:494:in `completions_at'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/message/text_document/completion.rb:12:in `process'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/host.rb:101:in `receive'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/adapter.rb:44:in `process'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/adapter.rb:17:in `block in opening'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/data_reader.rb:57:in `parse_message_from_buffer'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/data_reader.rb:35:in `block in receive'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/data_reader.rb:30:in `each_char'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/data_reader.rb:30:in `receive'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/solargraph-0.38.5/lib/solargraph/language_server/transport/adapter.rb:27:in `receiving'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/client.rb:63:in `tick'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/server/tcpip.rb:76:in `update'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/2.6.0/observer.rb:197:in `block in notify_observers'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/2.6.0/observer.rb:196:in `each'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/2.6.0/observer.rb:196:in `notify_observers'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/client.rb:121:in `read_input'
/Users/user/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/backport-1.1.2/lib/backport/client.rb:102:in `block in run_input_thread'

Sadly I can't provide the entire project because it's proprietary, and huge.

For context, I was typing in a Rails controller function, and it hung on typing @my_model_variable., where @my_model_variable was an instance of a Rails model in my project.

As soon as I have a moment I'll try to trim down my project to a simple reproducible case.

[castwide]

Thanks a lot for all your effort looking for a root cause. This looks very similar to the problem reported in https://github.com/castwide/solargraph/issues/288

If you can reduce the problem to a reproducible case, I'd appreciate it. In the meantime, I'll try to reproduce it running toy Rails projects on MacOS.

[tallytarik]

Sorry for the late reply, I've just gotten around to creating a test case.

It was actually very simple. It's almost a bare Rails project with one generated model/controller.

See here: https://github.com/tallytarik/solargraph-rails-hang

I can reliably cause Solargraph to hang by doing this:

1. Open app/controllers/servers/application_controller.rb
2. At the end of line 6, within the #server method, hit enter to start a new line
3. Type Server.
4. Solargraph hangs on typing the dot character

For reference, I'm using VSCode on macOS Catalina.

Hope that helps. Let me know if I can provide anything else!

[castwide]

Very helpful, thanks a lot. I cloned the repo and was able to reproduce the error on Windows. I'm still not sure of the root cause, but this gives me a good place to start looking.

[castwide]

The problem turned out to be name collisions in the class inheritance tree. Under certain circumstances, a subclass with a base name that matches the superclass (e.g., class Servers::ApplicationController < ApplicationController) would cause an infinite loop.

There's a fix in the master branch. I expect to release it in v0.38.6 in the next couple days.

[tallytarik]

Awesome work! I've just switched to the master branch, so will let you know if I have any issues.

[castwide]

Released in v0.38.6.