Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[error] Bad RPC call to node nextls-runtime => LSP Exited => :timeout #467

Closed
teamon opened this issue May 11, 2024 · 6 comments · Fixed by #478 or #479
Closed

[error] Bad RPC call to node nextls-runtime => LSP Exited => :timeout #467

teamon opened this issue May 11, 2024 · 6 comments · Fixed by #478 or #479

Comments

@teamon
Copy link

teamon commented May 11, 2024

This happened a few times on a different occasions but now it happens every time I restart vscode.

The relevant log lines seems to be these:

14:44:03.388 [info] Loading 160 CA(s) from :otp store
...
14:44:06.385 [info] Booting runtime for XXX.
...
14:44:06.604 [info] Connected to node nextls-runtime-1715431446385794000@MacBook-XXX
...
14:44:06.623 [error] Bad RPC call to node nextls-runtime-1715431446385794000@MacBook-XXX: {:EXIT, {:badarg, [{:ets, :lookup, [:elixir_config, :parser_options], [error_info: %{cause: :id, module: :erl_stdlib_errors}]}, {:elixir_config, :get, 1, [file: ~c"src/elixir_config.erl", line: 21]}, {:elixir_compiler, :string, 3, [file: ~c"src/elixir_compiler.erl", line: 7]}, {Module.ParallelChecker, :verify, 1, [file: ~c"lib/module/parallel_checker.ex", line: 112]}, {Code, :compile_file, 1, []}]}}
...
14:44:06.625 [info] The runtime for XXX has successfully shut down.
...
14:44:24.628 [error] LSP Exited.
....
Last message received: handle_request %{"id" => 12, "jsonrpc" => "2.0", "method" => "textDocument/formatting", "params" => %{"options" => %{"insertFinalNewline" => true, "insertSpaces" => true, "tabSize" => 2, "trimFinalNewlines" => true, "trimTrailingWhitespace" => true}, "textDocument" => %{"uri" => "file:///Users/teamon/code/XXX/test/XXX_test.exs"}}}

** (MatchError) no match of right hand side value: :timeout
    (next_ls 0.21.4) lib/next_ls.ex:522: NextLS.handle_request/2
    (gen_lsp 0.8.1) lib/gen_lsp.ex:277: anonymous fn/2 in GenLSP.loop/3
    (telemetry 1.2.1) /Users/runner/work/next-ls/next-ls/deps/telemetry/src/telemetry.erl:321: :telemetry.span/3
    (gen_lsp 0.8.1) lib/gen_lsp.ex:276: anonymous fn/6 in GenLSP.loop/3
    (gen_lsp 0.8.1) lib/gen_lsp.ex:397: GenLSP.attempt/4
    (stdlib 5.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3

Removing .elixir-tools and restarting everything fixes the problem.

Full log

14:44:03.388 [info] Loading 160 CA(s) from :otp store

14:44:03.499 id=0 [debug] handled request client -> server initialize in 75ms

14:44:03.504 [debug] sent notification server -> client window/logMessage

14:44:03.509 id=101 [debug] sent request server -> client client/registerCapability

14:44:03.509 [debug] sent notification server -> client window/logMessage

14:44:03.509 [info] [extension] Credo disabled

14:44:06.365 [debug] sent notification server -> client window/logMessage

14:44:06.368 id=34 [debug] sent request server -> client window/workDoneProgress/create

14:44:06.372 [debug] sent notification server -> client $/progress

14:44:06.381 [debug] sent notification server -> client window/logMessage

14:44:06.381 [info] Beginning DB migration...

14:44:06.385 [debug] sent notification server -> client window/logMessage

14:44:06.385 [info] Database is on the latest version: 7

14:44:06.385 [debug] sent notification server -> client window/logMessage

14:44:06.385 [info] Finished DB migration...

14:44:06.385 [debug] sent notification server -> client window/logMessage

14:44:06.385 [info] Booting runtime for XXX.

- elixir: /Users/teamon/.cache/elixir-tools/nextls/elixir/1-17-1/bin/elixir
- zombie wrapper script: /Users/teamon/Library/Application Support/.burrito/next_ls_erts-14.2.1_0.21.4/lib/next_ls-0.21.4/priv/cmd
- working_dir: /Users/teamon/code/XXX
- command: /Users/teamon/.cache/elixir-tools/nextls/elixir/1-17-1/bin/elixir --no-halt --sname nextls-runtime-1715431446385794000 --cookie GXTH2ADWMKCQRWYYE4MOOIJM4C745XQZF26XPQZZXM3OHLNEPRGA==== -S mix loadpaths --no-compile

Environment: 

LSP=nextls
NEXTLS_PARENT_PID=g1h3Km5leHQtbHMtMTcxNTQzMTQ0MzM5OTYzODcwOUBNYWNCb29rLVByby1CRgAAAQ8AAAAAZj9oFA==
MIX_ENV=dev
MIX_TARGET=host
MIX_BUILD_ROOT=.elixir-tools/_build
ROOTDIR=false
BINDIR=false
RELEASE_ROOT=false
RELEASE_SYS_CONFIG=false
PATH=/Users/teamon/.cache/elixir-tools/nextls/elixir/1-17-1/bin:/Users/teamon/Library/Application Support/.burrito/next_ls_erts-14.2.1_0.21.4/bin:/Users/teamon/bin:/Users/teamon/.asdf/shims:/opt/homebrew/opt/asdf/libexec/bin:/opt/homebrew/bin:/opt/homebrew/sbin:/usr/local/bin:/System/Cryptexes/App/usr/bin:/usr/bin:/bin:/usr/sbin:/sbin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/local/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/bin:/var/run/com.apple.security.cryptexd/codex.system/bootstrap/usr/appleinternal/bin:/Library/Apple/usr/bin:/Applications/Wireshark.app/Contents/MacOS:/opt/homebrew/opt/fzf/bin
MIX_HOME=/Users/teamon/.cache/elixir-tools/nextls/elixir/1-17-1/.mix


14:44:06.386 [debug] handled notification client -> server initialized in 2884ms

14:44:06.389 [debug] handled notification client -> server textDocument/didOpen in 2ms

14:44:06.405 id=1 [debug] handled request client -> server textDocument/documentSymbol in 16ms

14:44:06.418 id=2 [debug] handled request client -> server textDocument/codeAction in 13ms

14:44:06.423 id=3 [debug] handled request client -> server textDocument/documentSymbol in 4ms

14:44:06.424 [debug] handled notification client -> server $/cancelRequest in 1ms

14:44:06.424 [debug] handled notification client -> server $/cancelRequest in 15µs

14:44:06.424 [debug] handled notification client -> server $/cancelRequest in 10µs

14:44:06.604 [debug] sent notification server -> client window/logMessage

14:44:06.604 [info] Connected to node nextls-runtime-1715431446385794000@MacBook-XXX

14:44:06.623 [debug] sent notification server -> client $/progress

14:44:06.623 [debug] sent notification server -> client window/logMessage

14:44:06.623 [error] Bad RPC call to node nextls-runtime-1715431446385794000@MacBook-XXX: {:EXIT, {:badarg, [{:ets, :lookup, [:elixir_config, :parser_options], [error_info: %{cause: :id, module: :erl_stdlib_errors}]}, {:elixir_config, :get, 1, [file: ~c"src/elixir_config.erl", line: 21]}, {:elixir_compiler, :string, 3, [file: ~c"src/elixir_compiler.erl", line: 7]}, {Module.ParallelChecker, :verify, 1, [file: ~c"lib/module/parallel_checker.ex", line: 112]}, {Code, :compile_file, 1, []}]}}

14:44:06.624 [debug] sent notification server -> client window/logMessage

14:44:06.625 [debug] sent notification server -> client window/logMessage

14:44:06.625 [info] The runtime for XXX has successfully shut down.

14:44:10.302 id=4 [debug] handled request client -> server textDocument/codeAction in 242µs

14:44:10.308 id=5 [debug] handled request client -> server textDocument/documentSymbol in 6ms

14:44:10.550 id=6 [debug] handled request client -> server textDocument/codeAction in 126µs

14:44:10.607 id=7 [debug] handled request client -> server textDocument/documentSymbol in 5ms

14:44:22.832 id=8 [debug] handled request client -> server textDocument/codeAction in 256µs

14:44:23.081 id=9 [debug] handled request client -> server textDocument/codeAction in 151µs

14:44:23.137 id=10 [debug] handled request client -> server textDocument/documentSymbol in 4ms

14:44:23.378 id=11 [debug] handled request client -> server textDocument/codeAction in 223µs

14:44:24.628 [debug] sent notification server -> client window/logMessage

14:44:24.628 [error] LSP Exited.

Last message received: handle_request %{"id" => 12, "jsonrpc" => "2.0", "method" => "textDocument/formatting", "params" => %{"options" => %{"insertFinalNewline" => true, "insertSpaces" => true, "tabSize" => 2, "trimFinalNewlines" => true, "trimTrailingWhitespace" => true}, "textDocument" => %{"uri" => "file:///Users/teamon/code/XXX/test/XXX_test.exs"}}}

** (MatchError) no match of right hand side value: :timeout
    (next_ls 0.21.4) lib/next_ls.ex:522: NextLS.handle_request/2
    (gen_lsp 0.8.1) lib/gen_lsp.ex:277: anonymous fn/2 in GenLSP.loop/3
    (telemetry 1.2.1) /Users/runner/work/next-ls/next-ls/deps/telemetry/src/telemetry.erl:321: :telemetry.span/3
    (gen_lsp 0.8.1) lib/gen_lsp.ex:276: anonymous fn/6 in GenLSP.loop/3
    (gen_lsp 0.8.1) lib/gen_lsp.ex:397: GenLSP.attempt/4
    (stdlib 5.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3




14:44:24.628 [debug] sent notification server -> client window/logMessage

14:44:24.628 [error] LSP Exited.

Last message received: handle_request %{"id" => 11, "jsonrpc" => "2.0", "method" => "textDocument/codeAction", "params" => %{"context" => %{"diagnostics" => [], "triggerKind" => 2}, "range" => %{"end" => %{"character" => 48, "line" => 787}, "start" => %{"character" => 48, "line" => 787}}, "textDocument" => %{"uri" => "file:///Users/teamon/code/XXX/test/XXX_test.exs"}}}

** (MatchError) no match of right hand side value: :timeout
    (next_ls 0.21.4) lib/next_ls.ex:522: NextLS.handle_request/2
    (gen_lsp 0.8.1) lib/gen_lsp.ex:277: anonymous fn/2 in GenLSP.loop/3
    (telemetry 1.2.1) /Users/runner/work/next-ls/next-ls/deps/telemetry/src/telemetry.erl:321: :telemetry.span/3
    (gen_lsp 0.8.1) lib/gen_lsp.ex:276: anonymous fn/6 in GenLSP.loop/3
    (gen_lsp 0.8.1) lib/gen_lsp.ex:397: GenLSP.attempt/4
    (stdlib 5.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3

@mhanberg
Copy link
Collaborator

i haven't actually seen that error in a prod build, only in tests

14:44:06.623 [error] Bad RPC call to node nextls-runtime-1715431446385794000@MacBook-XXX: {:EXIT, {:badarg, [{:ets, :lookup, [:elixir_config, :parser_options], [error_info: %{cause: :id, module: :erl_stdlib_errors}]}, {:elixir_config, :get, 1, [file: ~c"src/elixir_config.erl", line: 21]}, {:elixir_compiler, :string, 3, [file: ~c"src/elixir_compiler.erl", line: 7]}, {Module.ParallelChecker, :verify, 1, [file: ~c"lib/module/parallel_checker.ex", line: 112]}, {Code, :compile_file, 1, []}]}}

i think its a weird timing issue, will investigate further, thank you for the report!

@teamon
Copy link
Author

teamon commented May 15, 2024

I'm constantly hitting this issue now. I've run next-ls locally over tcp but there are no logs or errors in its output.

Is there any way I could debug this locally?

mhanberg added a commit that referenced this issue May 15, 2024
Frequently we'd see the following error in tests, and some users were
seeing in production:

```
[error] Bad RPC call to node nextls-runtime-1715431446385794000@MacBook-XXX: {:EXIT, {:badarg, [{:ets, :lookup, [:elixir_config, :parser_options], [error_info: %{cause: :id, module: :erl_stdlib_errors}]}, {:elixir_config, :get, 1, [file: ~c"src/elixir_config.erl", line: 21]}, {:elixir_compiler, :string, 3, [file: ~c"src/elixir_compiler.erl", line: 7]}, {Module.ParallelChecker, :verify, 1, [file: ~c"lib/module/parallel_checker.ex", line: 112]}, {Code, :compile_file, 1, []}]}}
```

I believe that this is caused by an internal ETS table not being booted
yet, so we not await on it being present on the project node.

Closes #467
@mhanberg
Copy link
Collaborator

@teamon I think this should fix it: #478

@teamon
Copy link
Author

teamon commented May 15, 2024

I'll give it a try, thanks!

mhanberg added a commit that referenced this issue May 15, 2024
Frequently we'd see the following error in tests, and some users were
seeing in production:

```
[error] Bad RPC call to node nextls-runtime-1715431446385794000@MacBook-XXX: {:EXIT, {:badarg, [{:ets, :lookup, [:elixir_config, :parser_options], [error_info: %{cause: :id, module: :erl_stdlib_errors}]}, {:elixir_config, :get, 1, [file: ~c"src/elixir_config.erl", line: 21]}, {:elixir_compiler, :string, 3, [file: ~c"src/elixir_compiler.erl", line: 7]}, {Module.ParallelChecker, :verify, 1, [file: ~c"lib/module/parallel_checker.ex", line: 112]}, {Code, :compile_file, 1, []}]}}
```

I believe that this is caused by an internal ETS table not being booted
yet, so we not await on it being present on the project node.

Closes #467
mhanberg added a commit that referenced this issue May 15, 2024
Frequently we'd see the following error in tests, and some users were
seeing in production:

```
[error] Bad RPC call to node nextls-runtime-1715431446385794000@MacBook
-XXX: {:EXIT, {:badarg, [{:ets, :lookup, [:elixir_config,
:parser_options], [error_info: %{cause: :id, module: :erl_stdlib_errors}]
}, {:elixir_config, :get, 1, [file: ~c"src/elixir_config.erl", line: 21]}
, {:elixir_compiler, :string, 3, [file: ~c"src/elixir_compiler.erl", line
: 7]}, {Module.ParallelChecker, :verify, 1, [file: ~c"lib/module/parallel
_checker.ex", line: 112]}, {Code, :compile_file, 1, []}]}}
```

I believe that this is caused by an internal ETS table not being booted
yet, so we not await on it being present on the project node.

Closes #467
mhanberg added a commit that referenced this issue May 15, 2024
Frequently we'd see the following error in tests, and some users were
seeing in production:

```
[error] Bad RPC call to node nextls-runtime-1715431446385794000@MacBook
-XXX: {:EXIT, {:badarg, [{:ets, :lookup, [:elixir_config,
:parser_options], [error_info: %{cause: :id, module: :erl_stdlib_errors}]
}, {:elixir_config, :get, 1, [file: ~c"src/elixir_config.erl", line: 21]}
, {:elixir_compiler, :string, 3, [file: ~c"src/elixir_compiler.erl", line
: 7]}, {Module.ParallelChecker, :verify, 1, [file: ~c"lib/module/parallel
_checker.ex", line: 112]}, {Code, :compile_file, 1, []}]}}
```

I believe that this is caused by an internal ETS table not being booted
yet, so we not await on it being present on the project node.

Closes #467
mhanberg added a commit that referenced this issue May 15, 2024
Frequently we'd see the following error in tests, and some users were
seeing in production:

```
[error] Bad RPC call to node nextls-runtime-1715431446385794000@MacBook
-XXX: {:EXIT, {:badarg, [{:ets, :lookup, [:elixir_config,
:parser_options], [error_info: %{cause: :id, module: :erl_stdlib_errors}]
}, {:elixir_config, :get, 1, [file: ~c"src/elixir_config.erl", line: 21]}
, {:elixir_compiler, :string, 3, [file: ~c"src/elixir_compiler.erl", line
: 7]}, {Module.ParallelChecker, :verify, 1, [file: ~c"lib/module/parallel
_checker.ex", line: 112]}, {Code, :compile_file, 1, []}]}}
```

I believe that this is caused by an internal ETS table not being booted
yet, so we not await on it being present on the project node.

Closes #467
@mhanberg
Copy link
Collaborator

last release got botched, re-doing it now

@mhanberg
Copy link
Collaborator

should be fixed now

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment