Repository: autozimu/LanguageClient-neovim (language: rust)

Issue:
Regression: "data did not match any variant of untagged enum RawMessage"
- [x] Did you upgrade to latest plugin version?
- [x] Did you upgrade to/compile latest binary? Run shell command
- [x] (Neovim users only) Did you check output of `:checkhealth LanguageClient`?
- [x] Did you check [troubleshooting]?

[troubleshooting]: https://github.com/autozimu/LanguageClient-neovim/blob/next/INSTALL.md#6-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: 815e44a69ab45295e44e4deeb97f5acf0906efe4 which bumps `jsonrpc-core` from version 12 to 13.

[Sorbet]: https://sorbet.org

## 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:

```vim
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:

```bash
# 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: 815e44a69ab45295e44e4deeb97f5acf0906efe4

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.




Discussion / hints:

Fix patch:
diff --git a/Cargo.lock b/Cargo.lock
index 6a07e2192..12be0c758 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -300,7 +300,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 
 [[package]]
 name = "jsonrpc-core"
-version = "13.0.0"
+version = "12.0.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 dependencies = [
  "futures 0.1.28 (registry+https://github.com/rust-lang/crates.io-index)",
@@ -328,7 +328,7 @@ dependencies = [
  "failure 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)",
  "glob 0.3.0 (registry+https://github.com/rust-lang/crates.io-index)",
  "itertools 0.8.0 (registry+https://github.com/rust-lang/crates.io-index)",
- "jsonrpc-core 13.0.0 (registry+https://github.com/rust-lang/crates.io-index)",
+ "jsonrpc-core 12.0.0 (registry+https://github.com/rust-lang/crates.io-index)",
  "log 0.4.8 (registry+https://github.com/rust-lang/crates.io-index)",
  "log4rs 0.8.3 (registry+https://github.com/rust-lang/crates.io-index)",
  "lsp-types 0.60.0 (registry+https://github.com/rust-lang/crates.io-index)",
@@ -966,7 +966,7 @@ dependencies = [
 "checksum iovec 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)" = "dbe6e417e7d0975db6512b90796e8ce223145ac4e33c377e4a42882a0e88bb08"
 "checksum itertools 0.8.0 (registry+https://github.com/rust-lang/crates.io-index)" = "5b8467d9c1cebe26feb08c640139247fac215782d35371ade9a2136ed6085358"
 "checksum itoa 0.4.4 (registry+https://github.com/rust-lang/crates.io-index)" = "501266b7edd0174f8530248f87f99c88fbe60ca4ef3dd486835b8d8d53136f7f"
-"checksum jsonrpc-core 13.0.0 (registry+https://github.com/rust-lang/crates.io-index)" = "34d379861584fe4e3678f6ae9ee60b41726df2989578c1dc0f90190dfc92dbe0"
+"checksum jsonrpc-core 12.0.0 (registry+https://github.com/rust-lang/crates.io-index)" = "288dca7f9713710a29e485076b9340156cb701edb46a881f5d0c31aa4f5b9143"
 "checksum kernel32-sys 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)" = "7507624b29483431c0ba2d82aece8ca6cdba9382bff4ddd0f7490560c056098d"
 "checksum lazy_static 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)" = "bc5729f27f159ddd61f4df6228e827e86643d4d3e7c32183cb30a1c08f604a14"
 "checksum lazycell 1.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "b294d6fa9ee409a054354afc4352b0b9ef7ca222c69b8812cbea9e7d2bf3783f"
diff --git a/Cargo.toml b/Cargo.toml
index 61e6e9f82..0bfcc440c 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -28,7 +28,7 @@ serde_json = "1"
 
 crossbeam-channel = "0.3"
 
-jsonrpc-core = "13"
+jsonrpc-core = "12"
 lsp-types = "0.60"
 url = "2"
 pathdiff = "0"


Test patch: