Crash: protocol Jason.Encoder not implemented for ElixirLS.LanguageServer.Protocol.DocumentSymbol

[thetamind]

(Protocol.UndefinedError) protocol Jason.Encoder not implemented for %ElixirLS.LanguageServer.Protocol.DocumentSymbol

Environment

• Elixir & Erlang versions (elixir --version):

Erlang/OTP 23 [erts-11.0] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [dtrace]

Elixir 1.11.0-dev (b028ac8) (compiled with Erlang/OTP 23)

• Operating system: macOS High Sierra 10.13.6
• Editor or IDE name (e.g. Emacs/VSCode): VSCode 1.44.2
• LSP Client name:
  • If using VSCode, are you using "ElixirLS: Elixir support and debugger"? Yes, jakebecker.elixir-ls v0.4.0

Troubleshooting

• Restart your editor (which will restart ElixirLS) sometimes fixes issues
• Stop your editor, remove the entire .elixir_ls directory, then restart your editor
  • NOTE: This will cause you to have to re-run the dialyzer build for your project

Reproduction steps

I could not trigger the error with a simple file in a empty mix project, but I could in a new Phoenix project.

1. mix phx.new hello # Phoenix 1.5.1
2. cd hello
3. code .
4. In VSCode open lib/hello/repo.ex
5. Wait for ElixirLS to finish working (to show not a race condition...)
6. At the end of defmodule Hello.Repo do press enter to insert new line
7. ElixirLS has crashed. See Output panel.

defmodule Hello.Repo do

  use Ecto.Repo,
    otp_app: :hello,
    adapter: Ecto.Adapters.Postgres
end

Logs

Full log.

[Trace - 5:06:14 p.m.] Sending request 'textDocument/documentSymbol - (4)'.
[Trace - 5:06:14 p.m.] Received notification 'window/logMessage'.

17:06:14.940 [error] GenServer ElixirLS.LanguageServer.Server terminating
** (Protocol.UndefinedError) protocol Jason.Encoder not implemented for %ElixirLS.LanguageServer.Protocol.DocumentSymbol{children: [], kind: 2, name: "Hello.Repo", range: %{end: %{character: 0, line: 0}, start: %{character: 0, line: 0}}, selectionRange: %{end: %{character: 0, line: 0}, start: %{character: 0, line: 0}}} of type ElixirLS.LanguageServer.Protocol.DocumentSymbol (a struct), Jason.Encoder protocol must always be explicitly implemented.
[...]
This protocol is implemented for the following type(s): Ecto.Association.NotLoaded, Ecto.Schema.Metadata, Date, BitString, Jason.Fragment, Any, Map, NaiveDateTime, List, Integer, Time, DateTime, Decimal, Atom, Float
    lib/jason.ex:150: Jason.encode!/2
    (elixir_ls_utils 0.4.0) lib/wire_protocol.ex:9: ElixirLS.Utils.WireProtocol.send/1
    (language_server 0.4.0) lib/language_server/server.ex:94: ElixirLS.LanguageServer.Server.handle_call/3
    (stdlib 3.13) gen_server.erl:706: :gen_server.try_handle_call/4
    (stdlib 3.13) gen_server.erl:735: :gen_server.handle_msg/6
    (stdlib 3.13) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
Last message (from #PID<0.366.0>): {:request_finished, 4, {:ok, [%ElixirLS.LanguageServer.Protocol.DocumentSymbol{children: [], kind: 2, name: "Hello.Repo", range: %{end: %{character: 0, line: 0}, start: %{character: 0, line: 0}}, selectionRange: %{end: %{character: 0, line: 0}, start: %{character: 0, line: 0}}}]}}
State: %ElixirLS.LanguageServer.Server{analysis_ready?: true, awaiting_contracts: [{{#PID<0.325.0>, #Reference<0.3225323319.1372323841.96827>}, "file:///Users/thetamind/Projects/tmp/phoenix_hello/lib/hello/repo.ex"}], build_diagnostics: [], build_ref: #Reference<0.3225323319.1372323842.93752>, build_running?: false, client_capabilities: %{"textDocument" => %{"codeAction" => %{"codeActionLiteralSupport" => %{"codeActionKind" => %{"valueSet" => ["", "quickfix", "refactor", "refactor.extract", "refactor.inline", "refactor.rewrite", "source", "source.organizeImports"]}}, "dynamicRegistration" => true, "isPreferredSupport" => true}, "codeLens" => %{"dynamicRegistration" => true}, "colorProvider" => %{"dynamicRegistration" => true}, "completion" => %{"completionItem" => %{"commitCharactersSupport" => true, "deprecatedSupport" => true, "documentationFormat" => ["markdown", "plaintext"], "preselectSupport" => true, "snippetSupport" => true, "tagSupport" => %{"valueSet" => [1]}}, "completionItemKind" => %{"valueSet" => [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]}, "contextSupport" => true, "dynamicRegistration" => true}, "declaration" => %{"dynamicRegistration" => true, "linkSupport" => true}, "definition" => %{"dynamicRegistration" => true, "linkSupport" => true}, "documentHighlight" => %{"dynamicRegistration" => true}, "documentLink" => %{"dynamicRegistration" => true, "tooltipSupport" => true}, "documentSymbol" => %{"dynamicRegistration" => true, "hierarchicalDocumentSymbolSupport" => true, "symbolKind" => %{"valueSet" => [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]}}, "foldingRange" => %{"dynamicRegistration" => true, "lineFoldingOnly" => true, "rangeLimit" => 5000}, "formatting" => %{"dynamicRegistration" => true}, "hover" => %{"contentFormat" => ["markdown", "plaintext"], "dynamicRegistration" => true}, "implementation" => %{"dynamicRegistration" => true, "linkSupport" => true}, "onTypeFormatting" => %{"dynamicRegistration" => true}, "publishDiagnostics" => %{"relatedInformation" => true, "tagSupport" => %{"valueSet" => [1, 2]}, "versionSupport" => false}, "rangeFormatting" => %{"dynamicRegistration" => true}, "references" => %{"dynamicRegistration" => true}, "rename" => %{"dynamicRegistration" => true, "prepareSupport" => true}, "selectionRange" => %{"dynamicRegistration" => true}, "signatureHelp" => %{"contextSupport" => true, "dynamicRegistration" => true, "signatureInformation" => %{"documentationFormat" => ["markdown", "plaintext"], "parameterInformation" => %{"labelOffsetSupport" => true}}}, "synchronization" => %{"didSave" => true, "dynamicRegistration" => true, "willSave" => true, "willSaveWaitUntil" => true}, "typeDefinition" => %{"dynamicRegistration" => true, "linkSupport" => true}}, "window" => %{"workDoneProgress" => true}, "workspace" => %{"applyEdit" => true, "configuration" => true, "didChangeConfiguration" => %{"dynamicRegistration" => true}, "didChangeWatchedFiles" => %{"dynamicRegistration" => true}, "executeCommand" => %{"dynamicRegistration" => true}, "symbol" => %{"dynamicRegistration" => true, "symbolKind" => %{"valueSet" => [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]}}, "workspaceEdit" => %{"documentChanges" => true, "failureHandling" => "textOnlyTransactional", "resourceOperations" => ["create", "rename", "delete"]}, "workspaceFolders" => true}}, dialyzer_diagnostics: [%Mix.Task.Compiler.Diagnostic{compiler_name: "ElixirLS Dialyzer", details: {:warn_failing_call, {'lib/hello_web/gettext.ex', 23, {HelloWeb.Gettext, :handle_missing_bindings, 2}}, {:call, [Logger, :__do_log__, '(_@3::any(),binary(),\#{\'application\':=\'hello\', \'file\':=[46 | 47 | 95 | 98 | 101 | 103 | 104 | 105 | 108 | 111 | 116 | 119 | 120,...], \'line\':=23, \'mfa\':={\'Elixir.HelloWeb.Gettext\',\'handle_missing_bindings\',2}})', [2], :only_sig, '(any(),fun(() -> any()),map())', 'no_return()', {false, :none}]}}, file: "/Users/thetamind/Projects/tmp/phoenix_hello/lib/hello_web/gettext.ex", message: "The call 'Elixir.Logger':'__do_log__'\n         (_@3 :: any(),\n          binary(),\n          \#{'application' := 'hello',\n            'file' :=\n                [46 | 47 | 95 | 98 | 101 | 103 | 104 | 105 | 108 | 111 |\n                 116 | 119 | 120,\n                 ...],\n            'line' := 23,\n            'mfa' :=\n                {'Elixir.HelloWeb.Gettext', 'handle_missing_bindings',\n                 2}}) will never return since it differs in the 2nd argument from the success typing arguments: \n         (any(),\n          fun(() -> any()),\n          map())", position: 23, severity: :warning}], dialyzer_sup: #PID<0.118.0>, load_all_modules?: false, needs_build?: false, project_dir: "/Users/thetamind/Projects/tmp/phoenix_hello", received_shutdown?: false, requests: %{3 => #PID<0.325.0>, 4 => #PID<0.366.0>}, root_uri: "file:///Users/thetamind/Projects/tmp/phoenix_hello", settings: %{"dialyzerEnabled" => true, "dialyzerFormat" => "dialyzer", "dialyzerWarnOpts" => [], "fetchDeps" => true, "mixEnv" => "test", "projectDir" => "", "suggestSpecs" => true, "trace" => %{"server" => "messages"}}, source_files: %{"file:///Users/thetamind/Projects/tmp/phoenix_hello/lib/hello/repo.ex" => %ElixirLS.LanguageServer.SourceFile{dirty?: true, text: "defmodule Hello.Repo do\n  \n  use Ecto.Repo,\n    otp_app: :hello,\n    adapter: Ecto.Adapters.Postgres\nend\n", version: 3}}}
Client #PID<0.366.0> is alive

    (stdlib 3.13) gen.erl:208: :gen.do_call/4
    (elixir 1.11.0-dev) lib/gen_server.ex:1020: GenServer.call/3
[Trace - 5:06:14 p.m.] Received notification 'window/showMessage'.
[Info  - 5:06:19 p.m.] Connection to server got closed. Server will restart.
[Error - 5:06:19 p.m.] Request textDocument/codeLens failed.

[cboggs]

I'm seeing an identical failure with the 0.4.0 release. I've not had a chance to do a git bisect yet, but will try this evening if I have some time. :-)

[axelson]

Does this only affect Elixir 1.11.0-dev or can you reproduce it on a released version of Elixir? I wasn't able to reproduce it on 1.10.3 running on Erlang 22.3.2, although I wouldn't expect the document symbol code path to be that dependent on the Elixir version.

[thetamind]

Based on my testing Elixir 1.11.0-dev is affected and not 1.10.3. Erlang 23.0 or 22.3.4 didn't make a difference.

But I've been asdf switching and restarting VSCode a bunch so I'm not 100% sure.

[cboggs]

Can confirm that elixir 1.10.3 with OTP 22 is working fine. :-)

[thetamind]

Let's focus on the error. The DocumentSymbol struct is created successfully and ready to be encoded but Jason.encode! fails because the derived encoder cannot be found for the protocol Jason.Encoder. Project structs are included in the implementation list but ElixirLS structs are missing.

I think this might be a conflict with the Jason shipped with the extension and Jason in the Phoenix project. See related discussion about vendoring Jason or changing packaging approach.

I added a second log which includes the Mix project compilation with warnings. It includes fragments from several runs so I'm not sure of exact reproduction steps.

Highlights

1. Jason modules from extension being clobbered by Jason in project (same version 1.2.1).

==> jason
Compiling 8 files (.ex)
[Warn  - 12:12:40 PM] warning: redefining module Jason (current version loaded from /Users/thetamind/.vscode/extensions/jakebecker.elixir-ls-0.4.0/elixir-ls-release/jason-1.2.1.ez/jason-1.2.1/ebin/Elixir.Jason.beam)
  lib/jason.ex:1
[...]
Generated jason app

2. ElixirLS Dialyzer fails with duplicate protocol modules found between my asdf Elixir install and the build within the .elixir_ls/build folder. (I didn't see this very often but I've been testing with Dialyzer off)

[...]
==> live_view_studio
Compiling 23 files (.ex)
Generated live_view_studio app
[Info  - 12:14:23 PM] Compile took 125501 milliseconds
Compiling with Mix env test
[Info  - 12:14:24 PM] Compile took 492 milliseconds
[Info  - 12:14:24 PM] [ElixirLS Dialyzer] Checking for stale beam files
[Info  - 12:14:31 PM] [ElixirLS Dialyzer] Found 940 changed files in 6958 milliseconds

12:15:35.436 [error] Task #PID<0.120.0> started from #PID<0.119.0> terminating
** (stop) {:nocatch, {:dialyzer_error, 'Analysis failed with error:\nDuplicate modules: [["/Users/thetamind/.asdf/installs/elixir/master-otp-23/bin/../lib/elixir/ebin/Elixir.String.Chars.beam",\n                     "/Users/thetamind/Projects/pragmatic-studio/pragstudio-liveview-code/live_view_studio/.elixir_ls/build/test/lib/live_view_studio/consolidated/Elixir.String.Chars.beam"],\n                    ["/Users/thetamind/.asdf/installs/elixir/master-otp-23/bin/../lib/elixir/ebin/Elixir.Inspect.beam",\n                     "/Users/thetamind/Projects/pragmatic-studio/pragstudio-liveview-code/live_view_studio/.elixir_ls/build/test/lib/live_view_studio/consolidated/Elixir.Inspect.beam"],\n                    ["/Users/thetamind/.asdf/installs/elixir/master-otp-23/bin/../lib/elixir/ebin/Elixir.Enumerable.beam",\n                     "/Users/thetamind/Projects/pragmatic-studio/pragstudio-liveview-code/live_view_studio/.elixir_ls/build/test/lib/live_view_studio/consolidated/Elixir.Enumerable.beam"],\n                    ["/Users/thetamind/.asdf/installs/elixir/master-otp-23/bin/../lib/elixir/ebin/Elixir.List.Chars.beam",\n                     "/Users/thetamind/Projects/pragmatic-studio/pragstudio-liveview-code/live_view_studio/.elixir_ls/build/test/lib/live_view_studio/consolidated/Elixir.List.Chars.beam"],\n                    ["/Users/thetamind/.asdf/installs/elixir/master-otp-23/bin/../lib/elixir/ebin/Elixir.Collectable.beam",\n                     "/Users/thetamind/Projects/pragmatic-studio/pragstudio-liveview-code/live_view_studio/.elixir_ls/build/test/lib/live_view_studio/consolidated/Elixir.Collectable.beam"]]\nLast messages in the log cache:\n  Reading files and computing callgraph... '}}
    (dialyzer 4.2) dialyzer_cl.erl:699: :dialyzer_cl.cl_error/2
    (dialyzer 4.2) dialyzer_cl.erl:401: :dialyzer_cl.do_analysis/4
    (dialyzer 4.2) dialyzer.erl:160: :dialyzer.run/1
    (language_server 0.4.0) lib/language_server/dialyzer/manifest.ex:137: ElixirLS.LanguageServer.Dialyzer.Manifest.build_elixir_plt/0
    (language_server 0.4.0) lib/language_server/dialyzer/manifest.ex:14: anonymous fn/1 in ElixirLS.LanguageServer.Dialyzer.Manifest.build_new_manifest/0
    (elixir 1.11.0-dev) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (stdlib 3.13) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
Function: #Function<1.65931225/0 in ElixirLS.LanguageServer.Dialyzer.Manifest.build_new_manifest/0>
    Args: []

3. ElixirLS crashes with (Protocol.UndefinedError) protocol Jason.Encoder not implemented for ElixirLS.LanguageServer.Protocol.{DocumentSymbol, Location}.
The implemented protocol list for Jason.Encoder includes Ecto from the Phoenix project but nothing from the extension (ElixirLS.LanguageServer.Protocol.*).

** (Protocol.UndefinedError) protocol Jason.Encoder not implemented for %ElixirLS.LanguageServer.Protocol.DocumentSymbol{...} of type ElixirLS.LanguageServer.Protocol.DocumentSymbol (a struct), Jason.Encoder protocol must always be explicitly implemented.
[...]
This protocol is implemented for the following type(s): Ecto.Association.NotLoaded, Ecto.Schema.Metadata, Date, BitString, Jason.Fragment, Any, Map, NaiveDateTime, List, Integer, Time, DateTime, Decimal, Atom, Float
    lib/jason.ex:150: Jason.encode!/2
    (elixir_ls_utils 0.4.0) lib/wire_protocol.ex:9: ElixirLS.Utils.WireProtocol.send/1
    (language_server 0.4.0) lib/language_server/server.ex:94: ElixirLS.LanguageServer.Server.handle_call/3
    (stdlib 3.13) gen_server.erl:706: :gen_server.try_handle_call/4
    (stdlib 3.13) gen_server.erl:735: :gen_server.handle_msg/6
    (stdlib 3.13) proc_lib.erl:226: :proc_lib.init_p_do_apply/3

This hints that the (consolidated?) protocol implementation from the extension is not being found. Docs state protocols are consolidated in the test Mix env. Poor fix might be to adjust elixirc_paths to include .elixr_ls or consolidate_protocols: false?

I've been using the VSCode BEAMdasm extension to examine which beam files include the Jason.Encoder implementation.

[axelson]

Thanks for the research, I'm pretty sure that you are correct that this error is related to protocol consolidation with multiple versions of Jason clobbering each other. I think the most straightforward fix for right now would be to vendor Jason.

[axelson]

@thetamind can you try out #258 and see if that fixes the issue for you?