Bundler auto_install prints to STDOUT and breaks connection

[a-lavis]

Description

Reproduction steps:

1. Use the rbenv version manager
2. Open a Ruby file in VSCode with the Ruby LSP extension installed
3. See the below error:

Here's the output from the VSCode extension:

2024-06-04 08:01:10.831 [info] (kickstarter) Ruby LSP> Running bundle install for the custom bundle. This may take a while...
Ruby LSP> Command: (bundle check || bundle install) 1>&2

2024-06-04 08:01:11.342 [info] (kickstarter) Resolving dependencies...

2024-06-04 08:01:12.020 [info] (kickstarter) The Gemfile's dependencies are satisfied

2024-06-04 08:01:14.725 [info] (kickstarter) Initializing Ruby LSP v0.17.1...

2024-06-04 08:01:14.752 [info] (kickstarter) [Error - 8:01:14 AM] Client Ruby LSP: connection to server is erroring.
Header must provide a Content-Length property.
{"resolving dependencies...\ncontent-length":"1599"}
Shutting down server.
2024-06-04 08:01:14.753 [info] (kickstarter) [Error - 8:01:14 AM] Stopping server failed
2024-06-04 08:01:14.753 [info] (kickstarter) Error: Client is not running and can't be stopped. It's current state is: starting
    at ws.shutdown (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:41:8468)
    at ws.stop (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:41:8047)
    at ws.stop (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:44:38355)
    at ws.handleConnectionError (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:43:63)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)

I originally posted this thread in slack, then I posted this comment in a different issue, but @vinistock recommended I start a new issue.

[a-lavis]

I just tried:

rails new foo
cd foo
code .

and the Ruby LSP works. So it must be specific to the repo I'm working in - going to investigate to see if I can figure out why,

[a-lavis]

Not sure what changed, but I'm getting a slightly different error now:

2024-06-04 20:46:35.050 [info] (kickstarter) Ruby LSP> Running bundle install for the custom bundle. This may take a while...
Ruby LSP> Command: (bundle check || bundle install) 1>&2

2024-06-04 20:46:35.566 [info] (kickstarter) Resolving dependencies...

2024-06-04 20:46:36.242 [info] (kickstarter) The Gemfile's dependencies are satisfied

2024-06-04 20:46:38.802 [info] (kickstarter) Initializing Ruby LSP v0.17.1...

2024-06-04 20:46:38.828 [info] (kickstarter) [Error - 8:46:38 PM] Client Ruby LSP: connection to server is erroring.
Header must provide a Content-Length property.
{"resolving dependencies...\ncontent-length":"1599"}
Shutting down server.
2024-06-04 20:46:38.828 [info] (kickstarter) [Error - 8:46:38 PM] Stopping server failed
2024-06-04 20:46:38.828 [info] (kickstarter) Error: Client is not running and can't be stopped. It's current state is: starting
    at ws.shutdown (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:41:8468)
    at ws.stop (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:41:8047)
    at ws.stop (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:44:38355)
    at ws.handleConnectionError (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:43:63)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
2024-06-04 20:46:38.829 [info] (kickstarter) [Error - 8:46:38 PM] Client Ruby LSP: connection to server is erroring.
Header must provide a Content-Length property.
{"{\"id\"":"0,\"result\":{\"capabilities\":{\"positionEncoding\":\"utf-16\",\"textDocumentSync\":{\"openClose\":true,\"change\":2},\"completionProvider\":{\"triggerCharacters\":[\"/\",\"\\\"\",\"'\",\":\",\"@\"],\"resolveProvider\":true,\"completionItem\":{\"labelDetailsSupport\":true}},\"hoverProvider\":{},\"signatureHelpProvider\":{\"triggerCharacters\":[\"(\",\" \",\",\"]},\"definitionProvider\":true,\"documentHighlightProvider\":true,\"documentSymbolProvider\":{\"symbolKind\":{\"value_set\":[1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26]},\"hierarchicalDocumentSymbolSupport\":true},\"codeActionProvider\":{\"resolveProvider\":true},\"codeLensProvider\":{},\"documentLinkProvider\":{},\"documentFormattingProvider\":true,\"documentOnTypeFormattingProvider\":{\"firstTriggerCharacter\":\"{\",\"moreTriggerCharacter\":[\"\\n\",\"|\",\"d\"]},\"foldingRangeProvider\":{\"lineFoldingOnly\":true},\"selectionRangeProvider\":true,\"semanticTokensProvider\":{\"documentSelector\":[{\"language\":\"ruby\"}],\"legend\":{\"tokenTypes\":[\"namespace\",\"type\",\"class\",\"enum\",\"interface\",\"struct\",\"typeParameter\",\"parameter\",\"variable\",\"property\",\"enumMember\",\"event\",\"function\",\"method\",\"macro\",\"keyword\",\"modifier\",\"comment\",\"string\",\"number\",\"regexp\",\"operator\",\"decorator\"],\"tokenModifiers\":[\"declaration\",\"definition\",\"readonly\",\"static\",\"deprecated\",\"abstract\",\"async\",\"modification\",\"documentation\",\"default_library\"]},\"range\":true,\"full\":{\"delta\":false}},\"inlayHintProvider\":{},\"diagnosticProvider\":{\"interFileDependencies\":false,\"workspaceDiagnostics\":false},\"workspaceSymbolProvider\":true},\"serverInfo\":{\"name\":\"Ruby LSP\",\"version\":\"0.17.1\"},\"formatter\":\"rubocop\"},\"jsonrpc\":\"2.0\"}Content-Length: 242"}
Shutting down server.
2024-06-04 20:46:38.829 [info] (kickstarter) [Error - 8:46:38 PM] Stopping server failed
2024-06-04 20:46:38.829 [info] (kickstarter) Error: Client is not running and can't be stopped. It's current state is: starting
    at ws.shutdown (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:41:8468)
    at ws.stop (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:41:8047)
    at ws.stop (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:44:38355)
    at ws.handleConnectionError (/Users/aidanlavis/.vscode/extensions/shopify.ruby-lsp-0.7.1/out/extension.js:43:63)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)

[a-lavis]

aha I figured it out!

I ran this yesterday:

bundle config auto_install true

this created a .bundle/config file.

If I delete the .bundle folder, then Ruby LSP works perfectly! If I run bundle config auto_install true again it breaks again.

[Earlopain]

auto_install resets bundler state here: https://github.com/rubygems/rubygems/blob/a15e2cb599e1415d0e9577eb7ca2d0df985a4c38/bundler/lib/bundler.rb#L183-L190

That includes the ui log level set previously. Probably a bundler bug? That seems unexpected

[vinistock]

Good find. That certainly explains why it's not respecting the UI level.

I'm not sure if it's intentional or not. If they want to keep the code that way, we will need to turn off auto install before launching the server.

[Earlopain]

Let's see https://github.com/rubygems/rubygems/issues/7769. Though, even if it does get fixed, probably needs a bundler version check to disable auto_install on affected versions

[Earlopain]

@a-lavis what's your bundler/gem version (bundler -v/gem -v)? I'm having trouble coming up with a reproducable test case for the rubygems repo. I may have missed something in how this all works together

[a-lavis]

@Earlopain

Some additional context from the slack thread that didn't make it into this GitHub issue (sorry!) is that it only seems to fail when running on my repo - a fresh rails repo works fine, regardless of whether auto_install turned on or not.

For my repo:

> bundler -v
Bundler version 2.5.3
> gem -v
3.5.11

For a fresh rails app:

> bundler -v
Bundler version 2.5.11
> gem -v
3.5.11

I tried updating my repo to use 2.5.11:

> bundler -v
Bundler version 2.5.11
> gem -v
3.5.11

And then I also tried using the latest version of bundler:

> bundler -v
Bundler version 2.5.13
> gem -v
3.5.11

and I'm still seeing the error.

[a-lavis]

Given that it works fine for a fresh rails repo and it only fails on my (closed source) repo, I think this is going to be pretty hard to reproduce.

Feel free to close this issue if you all want to - I've been perfectly happy just not using auto_install while I'm working! That said if you all want to continue looking into the issue I'm happy to answer any questions you might have about the repo.

Thanks for all your hard work on the LSP, its a joy to use!

[jlahtinen]

I have the same problem with custom manager (it just uses rvm use x) (for reasons). I am using jfrog as gem source. Does that make any difference?

[Earlopain]

It would be very helpful if you could try to make a minimal reproduction for this. I haven't had a chance to look into it myself again but last time I couldn't verify my assumption about an issue with bundler itself.