LSP: _changetracking.lua:154: Invalid buffer id: (race condition in 'initialize' RPC?)

[sapient-cogbag]

Problem

Problem

When using a system to automatically attach buffers to a language server that reinitializes itself, or responds to the initialize RPC query slowly, or something similar, if one of those buffers becomes invalid then the _on_attach method of LSP Clients produces an invalid buffer-number error.

This problem is compounded if for one reason or another the initialize query is repeatedly responded to or multiple buffers attached to a client become invalid over time (for example, if significant numbers of ephemeral preview buffers are attached to a language server and then removed in short succession), as all of these invalid buffers are provided to _on_attach on what I assume are repeated initialize responses from the LSP server, every time, creating a large error log spam which greatly interferes with typing >.<

While this is most acute when using a system that happens to attach and invalidate ephemeral buffers, it is (again, as far as I can tell) a race condition that should apply in any case where an LSP server reinitializes itself after any of it's attached buffers are rendered invalid. However, in practice it seems extremely difficult to reproduce....

Error executing vim.schedule lua callback: /usr/share/nvim/runtime/lua/vim/lsp/_changetracking.lua:154: Invalid buffer id: 44                                                                     
stack traceback:                                                                                                                                                                                  
        [C]: in function 'nvim_buf_get_name'                                                                                                                                                      
        /usr/share/nvim/runtime/lua/vim/lsp/_changetracking.lua:154: in function 'init'                                                                                                           
        /usr/share/nvim/runtime/lua/vim/lsp/client.lua:915: in function '_text_document_did_open_handler'                                                                                         
        /usr/share/nvim/runtime/lua/vim/lsp/client.lua:950: in function '_on_attach'                                                                                                              
        /usr/share/nvim/runtime/lua/vim/lsp/client.lua:623: in function ''                                                                                                                        
        vim/_editor.lua: in function <vim/_editor.lua:0> 

Originating Code Path

runtime/lua/vim/lsp/client.lua:608 - this is inside a callback passed to rpc.request with method initialize

    -- If server is being restarted, make sure to re-attach to any previously attached buffers.
    -- Save which buffers before on_init in case new buffers are attached.
    local reattach_bufs = vim.deepcopy(self.attached_buffers) -- <=== This is the source of the invalid bufnrs 

    self:_run_callbacks(self._on_init_cbs, lsp.client_errors.ON_INIT_CALLBACK_ERROR, self, result)

    for buf in pairs(reattach_bufs) do
      self:_on_attach(buf) -- <==== this is the source of the error(s) when the bufnr is invalid, which we will traverse into
    end

runtime/lua/vim/lsp/client.lua:938 - this is the actual _on_attach method. The error comes from inside _text_document_did_open_handler method

--- @package
--- Runs the on_attach function from the client's config if it was defined.
--- @param bufnr integer Buffer number
function Client:_on_attach(bufnr)
  self:_text_document_did_open_handler(bufnr) -- <=== Source of error. 

  lsp._set_defaults(self, bufnr)

  api.nvim_exec_autocmds('LspAttach', {
    buffer = bufnr,
    modeline = false,
    data = { client_id = self.id },
  })

runtime/lua/vim/lsp/client.lua:902

--- @package
--- Default handler for the 'textDocument/didOpen' LSP notification.
---
--- @param bufnr integer Number of the buffer, or 0 for current
function Client:_text_document_did_open_handler(bufnr)
  changetracking.init(self, bufnr)  -- <=== Error comes from here. Note that further down there is some kind of bufnr validation
  if not vim.tbl_get(self.server_capabilities, 'textDocumentSync', 'openClose') then
    return
  end
  if not api.nvim_buf_is_loaded(bufnr) then
    return
  end
  local filetype = vim.bo[bufnr].filetype

runtime/lua/vim/lsp/_changetracking.lua:149, inside the M.init module function.

  local buf_state = state.buffers[bufnr]
  if buf_state then
    buf_state.refs = buf_state.refs + 1
  else
    buf_state = {
      name = api.nvim_buf_get_name(bufnr), -- <=== The real source of the error ^.^
      lines = {},
      lines_tmp = {},
      pending_changes = {},
      needs_flush = false,
      refs = 1,
    }
    state.buffers[bufnr] = buf_state

Steps to reproduce using "nvim -u minimal_init.lua"

I could not get a minimal reproduction, unfortunately. I spent many many hours trying. However, minimal reproductions of race conditions are rather difficult. In particular, I've failed to get a minimal config to get an invalid bufnr into the attached_buffers of any LSP server, even though I know it is possible because my custom LSP setup (which is a bit of an abomination at this point...) has a status command which I modified to report on that (among other things like listing files with each language server client, filtering by language, etc.)

My final failed attempt at minimal_init.lua

local pattern = 'lua'
local cmd = { 'lua-language-server' }
-- Add files/folders here that indicate the root of a project
local root_markers = { '.git', '.editorconfig' }
-- Change to table with settings if required
local settings = vim.empty_dict()

-- LSP that we want to directly attach to
local client_id = nil

-- Files to open
--
-- First is the one put in a buffer to immediately wipe it out, second is to induce a re-initialize
local bufhidewipe_file = "dummy-lua.lua"
local reinit_trigger_file = "dummy-lua-two.lua"

-- Start the LSP with the bufnr, using the filename as the location...
--
-- Bufnr may not actually be a standard buffer constructed from something like `:edit` ^.^
local function do_start(bufnr, fname)
	local match = vim.fs.find(root_markers, { path = fname, upward = true })[1]
	local root_dir = match and vim.fn.fnamemodify(match, ':p:h') or nil
	return vim.lsp.start({
		name = 'lua-language-server',
		cmd = cmd,
		root_dir = root_dir,
		settings = settings,	
	}, { bufnr = bufnr })
end

--[[
vim.api.nvim_create_autocmd('FileType', {
	pattern = pattern,
	callback = function(args)
		client_id = do_start(0, args.file)
	end
})]]--



-- Open a file and heuristically locate it's buffer number
--
-- Note that this will totally break with duplicate files in different current working directories :p
-- It's just intended to be a very quick method of getting buffer numbers to work with :)
--
-- Optionally, specify `preview = true` to open in the preview window....
local function open_buffer_via_name(filename, preview)
	-- Open file in split.
	if not preview then
		vim.cmd.vsplit(filename)
	else
		vim.cmd.pedit(filename)
	end
	-- We need to find the bufnr for this buffer... can't find a way to actually directly create/edit a buffer in a way that gets the bufnr >.<
	local test_bufnr = nil
	for _, bufnr in ipairs(vim.api.nvim_list_bufs()) do
		local name = vim.api.nvim_buf_get_name(bufnr)
		-- Plain search
		if string.find(name, filename, 1, true) ~= nil then
			test_bufnr = bufnr
		end
	end
	return test_bufnr
end

-- Load a file into a scratch buffer. Will still have the filename as the name. Returns the bufnr
-- also allows you to set a filetype. Also reads contents from the file in question into the buffer.
--
-- This sets the scratch buffer's `bufhidden` option to `wipe`, which will wipe the buffer when it's not in a window
-- Importantly, this doesn't trigger autocommands! :p (i think this might be related).
--
-- It also creates a window (to prevent immediate wipe).
--
-- Returns the scratch buffer id as well as the scratch window id. The important thing is to destroy the buffer by hiding
-- the window and not deleting it directly ^.^

-- is in fzf-lua, which suggests this may be related to lsp??
local function open_scratch_buffer_via_name(filename, set_filetype)
	-- Read data into the buffer.
	--
	-- We read before creating the buffer so if there are errors no extranuous buffers
	-- are left hanging around :p
	local filelines = {}
	for l in io.lines(filename) do
		-- one-based indices 🤢
		filelines[#filelines + 1] = l
	end
	local scratch_buffer = vim.api.nvim_create_buf(false, true)
	vim.api.nvim_buf_set_lines(scratch_buffer, 0, 1, false, filelines)
	vim.api.nvim_buf_set_name(scratch_buffer, filename)
	-- This is probably the important bit. FZF sets `bufhidden=wipe` which does NOT CALL AUTOCMDS
	vim.api.nvim_set_option_value("bufhidden", "wipe", { buf = scratch_buffer })
	vim.api.nvim_set_option_value("filetype", set_filetype, { buf = scratch_buffer })

	-- Create the window. Doesn't need to be float or anything :p
	-- Automatically enter it.
	local scratch_window = vim.api.nvim_open_win(scratch_buffer, true, {
		relative = "cursor",
		row = 0,
		col = 0,
		height = 40,
		width = 30,
		noautocmd = true,
		border = "rounded"
	})
	return scratch_buffer, scratch_window
end


vim.api.nvim_create_user_command("ReproduceRaceCondition", function(args) 
	local bufhidewipe_bufnr, bufhidewipe_win_id = open_scratch_buffer_via_name(bufhidewipe_file, "lua")
	local ephemeral_client_id = do_start(bufhidewipe_bufnr, bufhidewipe_file)
	vim.defer_fn(function()
		vim.api.nvim_win_close(bufhidewipe_win_id, true)
		--[[vim.defer_fn(function() 
			local client = vim.lsp.get_client_by_id(ephemeral_client_id)
			client:stop()
		end)]]

		vim.defer_fn(function()
			local nonephemeral_bufnr = open_buffer_via_name(bufhidewipe_file, false)
			vim.lsp.buf_attach_client(nonephemeral_bufnr, ephemeral_client_id)
		end, 100)
	end, 50)
end, {
	nargs = 0
})

Folder Arrangement

Just placing minimal_init.lua in a folder with an empty .editorfile, and dummy-lua.lua (the .editorfile is for lsp sharing) will get the configuration i was using while writing this failed minimal config.

Actual Setup Behaviour

It's probably worth noting that the actual setup I have is more complex than this in certain ways that may be relevant. Importantly, the main LSP servers that I see in my listing (:LspStatus) command with invalid bufnrs is marksman (the markdown LSP I use).

My suspicion is that somehow the autocmd I have that automatically produces a popup when typing (which is constantly being refreshed) manages to trigger this race condition. But it also seems to occur more after I use preview windows with fzf-lua if they are scrolled through very rapidly (I use no plugins for the popup/documentation aspect, so it's not an fzf-lua thing). However, this is not marksman stuff, even if I havent seen it in any kind of :LspStatus listing yet :/

Logs

I have looked in logs, but there doesn't seem to be much useful there (though there are a signifcant number of errors from marksman and a few from my lua-language-server in some of the other earlier loglines. Still:

[START][2024-04-30 00:08:27] LSP logging initiated
[ERROR][2024-04-30 00:08:27] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:08:26 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:26:00] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:26:00 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:26:36] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:26:35 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:27:09] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:27:09 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:27:17] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:27:17 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:28:13] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:28:13 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:35:52] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:35:51 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:35:52] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:35:52 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:35:54] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:35:54 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:35:55] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:35:54 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:35:55] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:35:54 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:35:55] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:35:54 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:35:57] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:35:56 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:35:58] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:35:57 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:36:24] ...m/lsp/client.lua:980	"LSP[marksman]"	"on_error"	{  code = "ON_EXIT_CALLBACK_ERROR",  err = "vim/_editor.lua:0: E5560: Vimscript function must not be called in a lua loop callback"}
[ERROR][2024-04-30 00:36:24] ...m/lsp/client.lua:980	"LSP[marksman]"	"on_error"	{  code = "ON_EXIT_CALLBACK_ERROR",  err = "vim/_editor.lua:0: E5560: Vimscript function must not be called in a lua loop callback"}
[ERROR][2024-04-30 00:36:24] ...m/lsp/client.lua:980	"LSP[marksman]"	"on_error"	{  code = "ON_EXIT_CALLBACK_ERROR",  err = "vim/_editor.lua:0: E5560: Vimscript function must not be called in a lua loop callback"}
[ERROR][2024-04-30 00:36:24] ...m/lsp/client.lua:980	"LSP[marksman]"	"on_error"	{  code = "ON_EXIT_CALLBACK_ERROR",  err = "vim/_editor.lua:0: E5560: Vimscript function must not be called in a lua loop callback"}
[ERROR][2024-04-30 00:36:24] ...m/lsp/client.lua:980	"LSP[marksman]"	"on_error"	{  code = "ON_EXIT_CALLBACK_ERROR",  err = "vim/_editor.lua:0: E5560: Vimscript function must not be called in a lua loop callback"}
[ERROR][2024-04-30 00:36:24] ...m/lsp/client.lua:980	"LSP[marksman]"	"on_error"	{  code = "ON_EXIT_CALLBACK_ERROR",  err = "vim/_editor.lua:0: E5560: Vimscript function must not be called in a lua loop callback"}
[ERROR][2024-04-30 00:36:24] ...m/lsp/client.lua:980	"LSP[marksman]"	"on_error"	{  code = "ON_EXIT_CALLBACK_ERROR",  err = "vim/_editor.lua:0: E5560: Vimscript function must not be called in a lua loop callback"}
[ERROR][2024-04-30 00:36:24] ...m/lsp/client.lua:980	"LSP[marksman]"	"on_error"	{  code = "ON_EXIT_CALLBACK_ERROR",  err = "vim/_editor.lua:0: E5560: Vimscript function must not be called in a lua loop callback"}
[ERROR][2024-04-30 00:36:40] ...m/lsp/client.lua:980	"LSP[rust-analyzer]"	"on_error"	{  code = "ON_EXIT_CALLBACK_ERROR",  err = "vim/_editor.lua:0: E5560: Vimscript function must not be called in a lua loop callback"}
[ERROR][2024-04-30 00:36:59] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:36:59 INF] <LSP Entry> Starting Marksman LSP server: {}\n"
[ERROR][2024-04-30 00:36:59] .../vim/lsp/rpc.lua:752	"rpc"	"/usr/bin/marksman"	"stderr"	"[00:36:59 INF] <LSP Entry> Starting Marksman LSP server: {}\n"

(I don't know what exactly is causing the loop callback error and it seems to sometimes not appear... I think it is not related since it seems to only occur after the first epoch reload I do, whereas the actual issue I'm reporting occurs all of the time - and yes, I have an epoch system for reloading my config... it's about 10x as horrifying as it sounds especially because I was rushing at the time :p)

:LspStatus (my version) - probably not useful, but putting it here anyway in case it is potentially useful in figuring out the underlying causes

Client ID [1] did not have a client!                                                                                                                                                              
marksman [ID: 112]                                                                                                                                                                                
 Status:                                                                                                                                                                                          
  - Running                                                                                                                                                                                       
 Root Directory (config):                                                                                                                                                                         
  - (none)                                                                                                                                                                                        
 Workspace Directories (initial config):                                                                                                                                                          
  - (none)                                                                                                                                                                                        
 Workspace Directories (live):                                                                                                                                                                    
  - (none)                                                                                                                                                                                        
 Attached Buffers                                                                                                                                                                                 
  - [228] [INVALID BUFFER]                                                                                                                                                                        
rust-analyzer [ID: 111]                                                                                                                                                                           
 Status:                                                                                                                                                                                          
  - Running                                                                                                                                                                                       
 Root Directory (config):                                                                                                                                                                         
  - [anon]/sapient/self/limg                                                                                                                                                           
 Workspace Directories (initial config):                                                                                                                                                          
  - (none)                                                                                                                                                                                        
 Workspace Directories (live):                                                                                                                                                                    
  - file://[anon]/sapient/self/limg                                                                                                                                                    
 Attached Buffers                                                                                                                                                                                 
  - [1] [anon]/sapient/self/limg/src/lib.rs                                                                                                                                            
  - [27] [anon]/sapient/self/limg/src/bin/limg.rs                                                                                                                                      
  - [118] [anon]/sapient/self/limg/src/semantic_region.rs (current)                                                                                                                    
  - [72] [anon]/sapient/self/limg/src/locator.rs                                                                                                                                       
marksman [ID: 113]                                                                                                                                                                                
 Status:                                                                                                                                                                                          
  - Running                                                                                                                                                                                       
 Root Directory (config):                                                                                                                                                                         
  - (none)                                                                                                                                                                                        
 Workspace Directories (initial config):                                                                                                                                                          
  - (none)                                                                                                                                                                                        
 Workspace Directories (live):                                                                                                                                                                    
  - (none)                                                                                                                                                                                        
 Attached Buffers                                                                                                                                                                                 
  - [229] [INVALID BUFFER]                                                                                                                                                                        

Expected behavior

Handle invalid buffers gracefully in whatever way is most conceptually in line with how the LSP infrastructure is meant to work - I don't know the best place to put the fix, even if it is extremely simple (just a check with vim.api.nvim_buf_is_valid ^.^). It may also not be worth doing as it seems to be quite hard to produce without some pretty weird config stuff, although it might just be that I didn't put the language servers under enough pressure in my many attempts at minimal_init.lua?

It might be related to the todo in runtime/vim/lsp.lua:70 relating to resolve_bufnr on scratch buffers, but I really just don't know

From a practical perspective, fixing this issue could probably occur in two locations - the rpc.request call, and deep in the _changetracker init method - and it would be a very simple check.

Neovim version (nvim -v)

NVIM v0.10.0-dev-2995+ga1550dbf0a (but applies in all versions with relevant code)

Language server name/version

lua-language-server (3.8.3-1), marksman (2023_12_09-1), rust-analyzer (1.79.0-nightly), presumably others

Operating system/version

Arch Linux

Log file

No response

[justinmk]

From a practical perspective, fixing this issue could probably occur in two locations - the rpc.request call, and deep in the _changetracker init method - and it would be a very simple check.

Something like that.

Possibly related: #27383