Regression: "data did not match any variant of untagged enum RawMessage"

[jez]

• Did you upgrade to latest plugin version?
• Did you upgrade to/compile latest binary? Run shell command
• (Neovim users only) Did you check output of :checkhealth LanguageClient?
• Did you check troubleshooting?

Describe the bug

I had been using an older (stable) version, but wanted to upgrade to get floating window support. Upgrading made LanguageClient-neovim fail to initialize specifically when working with Sorbet.

I bisected the bug (using make release and git bisect locally) to isolate the issue to this commit to LanguageClient-neovim: 815e44a which bumps jsonrpc-core from version 12 to 13.

Environment

• neovim/vim version (nvim --version or vim --version): NVIM v0.4.2
• This plugin version (git rev-parse --short HEAD): 4fd272b

To Reproduce

Steps to reproduce the behavior:

vimrc:

let g:LanguageClient_loggingLevel = 'INFO'
let g:LanguageClient_loggingFile = '/tmp/languageclient-neovim.log'
let g:LanguageClient_serverCommands = {}
let g:LanguageClient_serverCommands.ruby = ['bundle', 'exec', 'srb', 'tc', '--lsp', '--debug-log-file=/tmp/sorbet-nvim.log', '.']

project:

# Install Sorbet into an empty folder
mkdir -p ~/foo
cd ~/foo
echo "source 'https://rubygems.org'" > Gemfile
echo "gem 'sorbet'" >> Gemfile
bundle install

# Verify that we installed Sorbet correctly (should see a help message)
bundle exec srb tc -h

# Open vim to trigger the initialization handshake
touch empty.rb
nvim empty.rb

Current behavior

/tmp/languageclient-neovim.log

#######
LanguageClient 0.1.154 4fd272b0dbf96d7a4fd5d9d840780638f514aa7c
#######
16:36:27 INFO writer-None src/rpcclient.rs:215 => None {"jsonrpc":"2.0","method":"eval","params":["[!!get(g:, 'LanguageClient_autoStart', 1), s:GetVar('LanguageClient_serverCommands', {}), get(g:, 'LanguageClient_selectionUI', v:null), get(g:, 'LanguageClient_trace', v:null), expand(get(g:, 'LanguageClient_settingsPath', '.vim/settings.json')), !!get(g:, 'LanguageClient_loadSettings', 1), get(g:, 'LanguageClient_rootMarkers', v:null), get(g:, 'LanguageClient_changeThrottle', v:null), get(g:, 'LanguageClient_waitOutputTimeout', v:null), !!get(g:, 'LanguageClient_diagnosticsEnable', 1), get(g:, 'LanguageClient_diagnosticsList', 'Quickfix'), get(g:, 'LanguageClient_diagnosticsDisplay', {}), get(g:, 'LanguageClient_windowLogMessageLevel', 'Warning'), get(g:, 'LanguageClient_hoverPreview', 'Auto'), get(g:, 'LanguageClient_completionPreferTextEdit', 0), has('nvim')]"],"id":3}
16:36:27 INFO reader-None src/rpcclient.rs:169 <= None {"method": "languageClient/handleCursorMoved", "jsonrpc": "2.0", "params": {"bufnr": 1, "viewport": {"end": 10, "start": 0}, "languageId": "ruby", "buftype": "", "position": {"character": 2, "line": 9}, "filename": "/Users/jez/sandbox/foo/editor.rb"}}
16:36:27 INFO unnamed src/language_server_protocol.rs:2282 Begin languageClient/handleCursorMoved
16:36:27 INFO reader-None src/rpcclient.rs:169 <= None {"id": 3, "jsonrpc": "2.0", "result": [1, {"ruby": ["sorbet", "--lsp", "--enable-experimental-lsp-autocomplete", "--debug-log-file=/tmp/sorbet-nvim.log", "."]}, null, null, ".vim/settings.json", 1, null, null, null, 1, "Quickfix", {"1": {"name": "Error", "signText": "✘", "texthl": "ALEError", "signTexthl": "Error"}, "2": {"name": "Warning", "signText": "▲", "texthl": "ALEWarning", "signTexthl": "Todo"}, "3": {"name": "Information", "signText": "✘", "texthl": "ALEError", "signTexthl": "Error"}, "4": {"name": "Hint", "signText": "➤", "texthl": "ALEWarning", "signTexthl": "Todo"}}, "Warning", "Auto", 0, 1]}
16:36:27 INFO writer-None src/rpcclient.rs:215 => None {"jsonrpc":"2.0","method":"eval","params":["[get(g:, 'LanguageClient_diagnosticsSignsMax', v:null), get(g:, 'LanguageClient_diagnosticsMaxSeverity', 'Hint'), get(g:, 'LanguageClient_documentHighlightDisplay', {}), !!s:GetVar('LanguageClient_selectionUI_autoOpen', 1), s:useVirtualText(), !!s:GetVar('LanguageClient_echoProjectRoot', 1)]"],"id":4}
16:36:27 INFO reader-None src/rpcclient.rs:169 <= None {"id": 4, "jsonrpc": "2.0", "result": [null, "Hint", {}, 1, 1, 1]}
16:36:27 INFO writer-None src/rpcclient.rs:215 => None {"jsonrpc":"2.0","method":"eval","params":["get(g:, 'loaded_fzf')"],"id":5}
16:36:27 INFO reader-None src/rpcclient.rs:169 <= None {"id": 5, "jsonrpc": "2.0", "result": 1}
16:36:27 INFO unnamed src/language_server_protocol.rs:235 End sync settings
16:36:27 INFO unnamed src/language_server_protocol.rs:2835 settings synced
16:36:27 WARN unnamed src/utils.rs:77 Unknown project type. Fallback to use dir as project root: Ok("/Users/jez/sandbox/foo")
16:36:27 INFO unnamed src/language_server_protocol.rs:2861 Project root: /Users/jez/sandbox/foo
16:36:27 INFO writer-None src/rpcclient.rs:215 => None {"jsonrpc":"2.0","method":"s:EchomsgEllipsis","params":["Project root: /Users/jez/sandbox/foo"]}
16:36:27 INFO unnamed src/language_server_protocol.rs:2938 End languageClient/startServer
16:36:27 INFO unnamed src/language_server_protocol.rs:254 Defining signs
16:36:27 INFO unnamed src/language_server_protocol.rs:929 Begin initialize
16:36:27 INFO writer-None src/rpcclient.rs:215 => None {"jsonrpc":"2.0","method":"s:command","params":["sign define LanguageClientWarning text=▲ texthl=Todo","sign define LanguageClientError text=✘ texthl=Error","sign define LanguageClientHint text=➤ texthl=Todo","sign define LanguageClientInformation text=✘ texthl=Error"]}
16:36:27 INFO writer-None src/rpcclient.rs:215 => None {"jsonrpc":"2.0","method":"eval","params":["s:hasSnippetSupport()"],"id":6}
16:36:27 INFO reader-None src/rpcclient.rs:169 <= None {"id": 6, "jsonrpc": "2.0", "result": 0}
16:36:27 WARN unnamed src/language_server_protocol.rs:941 Failed to get initializationOptions: Failed to read file (/Users/jez/sandbox/foo/.vim/settings.json): No such file or directory (os error 2)
16:36:27 INFO writer-Some("ruby") src/rpcclient.rs:215 => Some("ruby") {"jsonrpc":"2.0","method":"initialize","params":{"capabilities":{"textDocument":{"colorProvider":null,"completion":{"completionItem":{"snippetSupport":false}},"declaration":{"linkSupport":true},"definition":{"linkSupport":true},"implementation":{"linkSupport":true},"publishDiagnostics":{"relatedInformation":true},"signatureHelp":{"signatureInformation":{"parameterInformation":{"labelOffsetSupport":true}}},"typeDefinition":{"linkSupport":true}},"workspace":{"applyEdit":true,"didChangeWatchedFiles":{"dynamicRegistration":true}}},"processId":64169,"rootPath":"/Users/jez/sandbox/foo","rootUri":"file:///Users/jez/sandbox/foo","trace":"off"},"id":1}
16:36:27 INFO reader-Some("ruby") src/rpcclient.rs:169 <= Some("ruby") {"jsonrpc":"2.0","id":1,"requestMethod":"initialize","result":{"capabilities":{"textDocumentSync":1,"hoverProvider":true,"completionProvider":{"triggerCharacters":["."]},"definitionProvider":true,"typeDefinitionProvider":true,"referencesProvider":true,"documentSymbolProvider":false,"workspaceSymbolProvider":false}}}
16:36:27 ERROR reader-Some("ruby") src/rpcclient.rs:174 Failed to deserialize output: data did not match any variant of untagged enum RawMessage

 Message: {"jsonrpc":"2.0","id":1,"requestMethod":"initialize","result":{"capabilities":{"textDocumentSync":1,"hoverProvider":true,"completionProvider":{"triggerCharacters":["."]},"definitionProvider":true,"typeDefinitionProvider":true,"referencesProvider":true,"documentSymbolProvider":false,"workspaceSymbolProvider":false}}}

Error: Error("data did not match any variant of untagged enum RawMessage", line: 0, column: 0)

/tmp/sorbet-nvim.log

Heads up I'm a Sorbet developer. If you need any help reading this log I'm happy to explain.
The important lines are the Read: and Write: lines. Those are lines that the language server process has read from stdin and written to stdout.

[2019-09-23 16:36:27.253] [consoleAndFile] [debug] Running sorbet version 0.4.0 (non-release) with arguments: sorbet --lsp --enable-experimental-lsp-autocomplete --debug-log-file=/tmp/sorbet-nvim.log .
[2019-09-23 16:36:27.253] [consoleAndFile] [debug] Creating 8 worker threads
[2019-09-23 16:36:27.254] [consoleAndFile] [debug] Worker threads created
[2019-09-23 16:36:27.260] [consoleAndFile] [debug] Unpickler::UnPickler: 5.68586ms
[2019-09-23 16:36:27.264] [consoleAndFile] [debug] readFiles: 4.54016ms
[2019-09-23 16:36:27.281] [consoleAndFile] [debug] readSymbols: 15.7838ms
[2019-09-23 16:36:27.282] [consoleAndFile] [debug] unpickleGS: 22.1477ms
[2019-09-23 16:36:27.282] [consoleAndFile] [debug] read_global_state.binary: 28.0529ms
[2019-09-23 16:36:27.282] [consoleAndFile] [debug] Starting sorbet version 0.4.0 (non-release) in LSP server mode. Talk ‘\r\n’-separated JSON-RPC to me. More details at https://microsoft.github.io/language-server-protocol/specification.If you're developing an LSP extension to some editor, make sure to run sorbet with `-v` flag,it will enable outputing the LSP session to stderr(`Write: ` and `Read: ` log lines)
[2019-09-23 16:36:27.282] [consoleAndFile] [debug] Starting monitoring path . with watchman for files with extensions rb,rbi. Subscription id: ruby-typer-64177
[2019-09-23 16:36:27.282] [consoleAndFile] [debug] Read: {"jsonrpc":"2.0","method":"initialize","params":{"capabilities":{"textDocument":{"colorProvider":null,"completion":{"completionItem":{"snippetSupport":false}},"declaration":{"linkSupport":true},"definition":{"linkSupport":true},"implementation":{"linkSupport":true},"publishDiagnostics":{"relatedInformation":true},"signatureHelp":{"signatureInformation":{"parameterInformation":{"labelOffsetSupport":true}}},"typeDefinition":{"linkSupport":true}},"workspace":{"applyEdit":true,"didChangeWatchedFiles":{"dynamicRegistration":true}}},"processId":64169,"rootPath":"/Users/jez/sandbox/foo","rootUri":"file:///Users/jez/sandbox/foo","trace":"off"},"id":1}
[2019-09-23 16:36:27.284] [consoleAndFile] [debug] getNewRequest: 1.39295ms
[2019-09-23 16:36:27.284] [consoleAndFile] [debug] idle: 1.56914ms
[2019-09-23 16:36:27.284] [consoleAndFile] [debug] Write: {"jsonrpc":"2.0","id":1,"requestMethod":"initialize","result":{"capabilities":{"textDocumentSync":1,"hoverProvider":true,"completionProvider":{"triggerCharacters":["."]},"definitionProvider":true,"typeDefinitionProvider":true,"referencesProvider":true,"documentSymbolProvider":false,"workspaceSymbolProvider":false}}}

Diagnosis

The Sorbet language server sends an additional field in it's initialize response message: requestMethod. This is not mentioned in the LSP spec; it's an implementation detail that makes it easier for us to generate typed C++ bindings to the spec.

I bisected the issue back to this commit: 815e44a

If I manually revert that commit on master (i.e., downgrade the version of jsonrpc-core from 13 back to 12), everything works as expected.

[autozimu]

It seems like the fix would imply this project would be stuck with a particular version of jsonrpc indefinitely.

Is there any other way Sorbet can pass on this information?

[jez]

Is there any other way Sorbet can pass on this information?

The serialization/deserialization library that Sorbet is using is a C++ library that makes it hard to work with untagged unions. Sorbet adds the requestMethod field to make serde easier.

Notably, VS Code ignores extra fields just fine. I can't find anywhere in the spec where it says one way or another whether extra fields are allowed or not.

I'm not super familiar with the library that LanguageClient-neovim is using, but is there an option to have it ignore extra fields when it's attempting to deserialize? In general I've found that it's a nice feature to have (it means that adding a field to the API is not a backwards incompatible change) so I wouldn't be surprised if the Rust library that LanguageClient-neovim uses has a config option for that somewhere.

Ultimately, it's up to you what you'd like to do. Sorbet only officially supports VS Code (for exactly reasons like this—that each LSP client is different in it's own way) so the Sorbet team isn't directly affected.

[jez]

It seems like the fix would imply this project would be stuck with a particular version of jsonrpc indefinitely.

It looks like the most recent upgrade to jsonrpc-core 15 by @martskins in #1099 doesn't have this problem.
So probably it was a bug in jsonrpc-core 13 that has since been fixed.
Thanks for upgrading martskins.

[martskins]

To be honest I'm a little surprised that it fixes it! I wasn't aware of this issue and updated that library but that version seems to include deny_unknown_fields so if anything I would expect it to break it again 🤔 .

We can roll back that dependency upgrade like we did before though. But if it's confirmed that it's working even better.

EDIT: In any case, I'll try to investigate whether additional fields are supported by the protocol or not, but in the meantime, let me know if this breaks again for you.

[jez]

I spoke too soon; I had not rebuilt bin/languageclient after pulling.
This is still an issue. The steps to reproduce above still reproduce the issue on any commit after #1099.

[martskins]

@jez If removing that field from the payload is difficult from your side I suppose we could remove the field from the payload ourselves. We already have something similar for a javascript language server. This one is a little more expensive because we'd have to use a regex, but it could be done.

And sorry for breaking that, wasn't aware of the issue.

[martskins]

I think this should solve this issue and allow us to upgrade: #1115

[jez]

For what it's worth, I'm experimenting with reworking this in Sorbet so that it's less trouble for LanguageClient-neovim

https://github.com/sorbet/sorbet/compare/jez-undiscriminated-union

I still think that the fact that VS Code allows the field means that we should allow it too.

But it seems that jsonrpc-core upstream did not want to maintain "non-strict" parsing of JSON RPC messages:

paritytech/jsonrpc#448

^ this is the commit introduced after version 12 that caused the problem noted in the original report.

[martskins]

Yeah unfortunately that part of the protocol is open to interpretation. Removing that regex would be nice, but at least it's working as expected now. 👍