LSP log is flooded with "Unmatched cancel notification for request id"

[sakhnik]

Describe the bug Great plugin, works like a charm with LSP! It's just annoying to see the log is flooded with error messages.

[ERROR][2023-09-28 18:41:05] .../vim/lsp/rpc.lua:734    "rpc"   "jdtls" "stderr"        "вер. 28, 2023 6:41:05 ПП org.eclipse.lsp4j.jsonrpc.RemoteEndpoint handleCancellation\nWARNING: Unmatched cancel notification for request id 14\n"
[ERROR][2023-09-28 18:41:05] .../vim/lsp/rpc.lua:734    "rpc"   "jdtls" "stderr"        "вер. 28, 2023 6:41:05 ПП org.eclipse.lsp4j.jsonrpc.RemoteEndpoint handleCancellation\nWARNING: Unmatched cancel notification for request id 15\n"
[ERROR][2023-09-28 18:41:05] .../vim/lsp/rpc.lua:734    "rpc"   "jdtls" "stderr"        "вер. 28, 2023 6:41:05 ПП org.eclipse.lsp4j.jsonrpc.RemoteEndpoint handleCancellation\nWARNING: Unmatched cancel notification for request id 16\n"

When I increased the log level to DEBUG, it can be seen that every single RPC request gets cancelled even after successful response:

[DEBUG][2023-09-28 18:41:05] .../vim/lsp/rpc.lua:284    "rpc.send"      {  id = 15,  jsonrpc = "2.0",  method = "textDocument/documentHighlight",  params = {    position = {      character = 15,      line = 36    },    textDocument = {      uri = "file:///w/project/plugin/model/LayoutManager.java"    }  }}
[DEBUG][2023-09-28 18:41:05] .../vim/lsp/rpc.lua:387    "rpc.receive"   {  id = 15,  jsonrpc = "2.0",  result = { {      kind = 3,      range = {
      ["end"] = {          character = 30,          line = 35        },        start = {          character = 19,          line = 35        }     }    }, {      kind = 2,      range = {        ["end"] = {          character = 24,          line = 36        },        start = {          character = 13,          line = 36        }      }    }, {      kind = 2,      range = {        ["end"] = {          character = 23,          line = 39        },        start = {          character = 12,          line = 39        }      }    } }}
[DEBUG][2023-09-28 18:41:06] .../vim/lsp/rpc.lua:284    "rpc.send"      {  jsonrpc = "2.0",  method = "$/cancelRequest",  params = {    id = 15  }}

I captured the stack traceback:

    /usr/share/nvim/runtime/lua/vim/lsp.lua:1479: in function 'can\cel_request'
    /usr/share/nvim/runtime/lua/vim/lsp.lua:1981: in function </usr/share/nvim/runtime/lua/vim/lsp.lua:1978>
    [C]: in function 'pcal\l'
    ...qs/start/vim-illuminate/lua/illuminate/providers/lsp.lua:62: in function <...qs/start/vim-illuminate/lua/illuminate/providers/lsp.lua:58>\
    [C]: in function 'pcall'
    ...pack/paqs/start/vim-illuminate/lua/illuminate/engine.lua:113: in function 'refresh_references'
    ...pack/paqs/\start/vim-illuminate/lua/illuminate/engine.lua:50: in function <...pack/paqs/start/vim-illuminate/lua/illuminate/engine.lua:49>"

It looks like the requests that succeeded shouldn't be cancelled.

To Reproduce It should be reproducible with any LSP server complaining on the completed request being cancelled like jdtls It may be challenging to setup jdtls:

$ mkdir /tmp/test
$ cd /tmp/test
# Make sure java 17 is activated, for instance, with sdkman! (https://sdkman.io/): `sdk install java 17.0.8-zulu`
$ gradle init     # create a new java app, suppose named `app`
$ git clone https://github.com/sakhnik/nvim-config nvim
$ XDG_CONFIG_HOME=/tmp/test XDG_DATA_HOME=/tmp/test XDG_CACHE_HOME=/tmp/test nvim
<wait until plugins are installed>
:MasonInstall jdtls
:find **.*java<tab><tab><tab><cr>
:cd app

Navigate around to have the illuminate do its job. Then examine the log with LspLog

Note Omitting a minimal init.vim/init.lua/.vimrc will likely result in the issue being closed without explanation. Sorry, it's hassly Java. But I'm open to assisting in experimenting, and testing.

Output from :IlluminateDebug

buf_should_illuminate 1 true                                                                                                                       
config {                                                                                                                                           
  case_insensitive_regex = false,                                                                                                                  
  delay = 100,                                                                                                                                     
  filetype_overrides = {},                                                                                                                         
  filetypes_allowlist = {},                                                                                                                        
  filetypes_denylist = { "dirbuf", "dirvish", "fugitive" },                                                                                        
  min_count_to_highlight = 1,                                                                                                                      
  modes_allowlist = {},                                                                                                                            
  modes_denylist = {},                                                                                                                             
  providers = { "lsp", "treesitter" },                                                                                                             
  providers_regex_syntax_allowlist = {},                                                                                                           
  providers_regex_syntax_denylist = {},                                                                                                            
  under_cursor = true                                                                                                                              
}                                                                                                                                                  
started true                                                                                                                                       
provider table: 0x7ffaadf1d230 lsp                                                                                                                 
`termguicolors` true

Expected behavior No error message "Unmatched cancel notification..." in the LSP log

Screenshots

Additional context

[RRethy]

@sakhnik Can you try out #182, branch fix-181-2? I'll use it for the next week to make sure it doesn't break existing users, see if it fixes the log issue.

[sakhnik]

@RRethy, the frequency of cancellations has decreased noticeably. Yet there still are some messages in the log. I've prepared a Docker image with a reproduction package if that could be useful. I'm also running it on a public server for a couple of days: ssh -p 2222 guest@iryska.com.ua (the password is the same as the username). You can login there, cd app; nvim, find and open App.java and jdtls will kick in a few seconds later. illuminate-bug.tgz

[RRethy]

I pushed another change to that branch.

[sakhnik]

This one is much more reliable. I've only had one occurrence of the message since update. Thanks!

[RRethy]

Will probably merge in a few days if I see no issues.