From 851794a4dca7d2bdec710c9a67d33f86b893d3c3 Mon Sep 17 00:00:00 2001 From: Thomas Kosiewski Date: Tue, 10 Nov 2026 19:28:08 +0000 Subject: [PATCH] fix(server): do not drop a live Claude on a late keepalive tick libuv runs timers before it reads sockets. A ping timer tick that Neovim runs late after a block of 1.0 to 1.5 intervals is not a wake (the wake reset needs more than 1.5 intervals), and it finds the pong of the last ping still unread: now - last_pong is about 2.3 intervals, above the timeout, so the client was dropped with 1011 although it answers every ping. The first tick that finds no pong for two intervals now pings again and sets client.pong_overdue. The next tick finds the pong that was read in between, or drops the client. A pong clears pong_overdue at the next tick. A client that never answers is dropped one tick later than before. --- .../skills/verify-diff-lifecycle/covered.lock | 4 +- lua/claudecode/server/README.md | 2 +- lua/claudecode/server/client.lua | 1 + lua/claudecode/server/tcp.lua | 7 +++ .../unit/server/connection_lifecycle_spec.lua | 45 ++++++++++++++++--- tests/unit/server/log_lines_spec.lua | 2 + tests/unit/server/tcp_spec.lua | 5 ++- 7 files changed, 57 insertions(+), 9 deletions(-) diff --git a/.agents/skills/verify-diff-lifecycle/covered.lock b/.agents/skills/verify-diff-lifecycle/covered.lock index 393628771..e2132697f 100644 --- a/.agents/skills/verify-diff-lifecycle/covered.lock +++ b/.agents/skills/verify-diff-lifecycle/covered.lock @@ -135,7 +135,7 @@ file lua/claudecode/logger.lua 17b404dda41c3591 == lua/claudecode/selection.lua file lua/claudecode/selection.lua 0fa651cc95e0af0d == lua/claudecode/server/client.lua -file lua/claudecode/server/client.lua 3454ff62e057b632 +file lua/claudecode/server/client.lua 5789c6ff18045f9f block create_client 647b7523dea26af6 == lua/claudecode/server/frame.lua file lua/claudecode/server/frame.lua 3c50766875878d56 @@ -157,7 +157,7 @@ site lua/claudecode/server/init.lua: if not _G.claude_deferred_responses then @ == lua/claudecode/server/mock.lua file lua/claudecode/server/mock.lua def1248d2793d559 == lua/claudecode/server/tcp.lua -file lua/claudecode/server/tcp.lua a291c2d0f65ef167 +file lua/claudecode/server/tcp.lua f1f9833b4322b1ae == lua/claudecode/server/utils.lua file lua/claudecode/server/utils.lua 2915ae87b48f04ca == lua/claudecode/terminal.lua diff --git a/lua/claudecode/server/README.md b/lua/claudecode/server/README.md index 1e480faed..8622c5aa4 100644 --- a/lua/claudecode/server/README.md +++ b/lua/claudecode/server/README.md @@ -77,7 +77,7 @@ Layers, top to bottom: - When the JSON decodes to a non-table value (for example a number or a boolean), `_handle_message` replies -32600 with `"id": null`. It does not raise [server/init.lua:M._handle_message] - A message with a truthy `id` is a request. Any other message is a notification. A valid notification never gets a response. The -32700 and -32600 checks run before the `id` check, so a malformed notification gets an error reply [server/init.lua:M._handle_message] - A deferred response is keyed by `tostring(coroutine)` in `_G.claude_deferred_responses`. A result with neither `content` nor `error` becomes -32603 [server/init.lua:M._setup_deferred_response] -- The ping timer closes a connected client when no pong arrived within `interval * 2`: its Close frame carries 1011 "Keepalive timeout" (RFC 6455 reserves 1006, so no Close frame carries it), `on_disconnect` gets 1006 "Connection timeout", and the timer logs `Closed client_: no reply for s` at info level. A peer that stopped reading does not get that Close frame. Once its receive window is full, every write to it (replies, pings, and the Close frame) waits in libuv's queue, and closing the socket drops the queue. Until the timeout, the queued replies stay in memory. A tick gap above `interval * 1.5` counts as a wake from sleep and resets `last_pong` of each connected client. The 101 write callback sets `last_pong` again, so the keepalive window starts when the client is connected, not at the accept. A main loop that blocks during the handshake then does not count against the client [server/tcp.lua:M.start_ping_timer] [server/client.lua:M.process_data] +- The ping timer closes a connected client when two ticks in a row find no pong within `interval * 2`. The first such tick pings again and sets `client.pong_overdue`, because libuv runs timers before it reads sockets, so a tick that Neovim runs late after a block finds the pong of the last ping still unread. The next tick finds that pong, or drops the client. A pong clears `pong_overdue` at the next tick. The Close frame of a dropped client carries 1011 "Keepalive timeout" (RFC 6455 reserves 1006, so no Close frame carries it), `on_disconnect` gets 1006 "Connection timeout", and the timer logs `Closed client_: no reply for s` at info level. A peer that stopped reading does not get that Close frame. Once its receive window is full, every write to it (replies, pings, and the Close frame) waits in libuv's queue, and closing the socket drops the queue. Until the timeout, the queued replies stay in memory. A tick gap above `interval * 1.5` counts as a wake from sleep and resets `last_pong` of each connected client. The 101 write callback sets `last_pong` again, so the keepalive window starts when the client is connected, not at the accept. A main loop that blocks during the handshake then does not count against the client [server/tcp.lua:M.start_ping_timer] [server/client.lua:M.process_data] - `_disconnect_client` is idempotent: `on_disconnect` fires once per client id. A client that already left the server (it stopped before a scheduled `on_close` or an EOF ran) gets its socket closed there, unless the write callback of its Close frame will close it [server/tcp.lua:M._disconnect_client] - A client's read error or protocol error reaches the server only as its `on_disconnect` reason (`Client read error: …` or `Client error: …`), which `init.lua` logs at debug level. `on_error` carries only the server's own failures (listen, accept, and creating a client handle or the ping timer), which `init.lua` logs at error level [server/tcp.lua:M._handle_new_connection] [server/init.lua:M.start] - A rejected handshake logs `Rejected client_: ` at warn level, with the reason from the body of the error response. Once the error response is written, `on_error` removes the client from the server and closes its socket [server/client.lua:M.process_data] diff --git a/lua/claudecode/server/client.lua b/lua/claudecode/server/client.lua index d1781ac2b..742612882 100644 --- a/lua/claudecode/server/client.lua +++ b/lua/claudecode/server/client.lua @@ -30,6 +30,7 @@ local CLOSE_REASONS = { ---@field close_pending boolean|nil True while a Close frame waits to be written: its write callback closes the socket ---@field last_ping number Timestamp of last ping sent ---@field last_pong number Timestamp of last pong received +---@field pong_overdue boolean|nil True after a ping timer tick found no pong for two intervals. The next such tick drops the client ---Create a new WebSocket client ---@param tcp_handle table The vim.loop TCP handle diff --git a/lua/claudecode/server/tcp.lua b/lua/claudecode/server/tcp.lua index 5de4954fc..c4fc11573 100644 --- a/lua/claudecode/server/tcp.lua +++ b/lua/claudecode/server/tcp.lua @@ -424,6 +424,13 @@ function M.start_ping_timer(server, interval) if client.state == "connected" then -- Check if client is alive (local connections, so use standard timeout) if client_manager.is_client_alive(client, interval * 2) then + client.pong_overdue = nil + client_manager.send_ping(client, "ping") + elseif not client.pong_overdue then + -- libuv runs timers before it reads sockets, so a tick that Neovim runs late after a block finds the pong of + -- the last ping still unread. The first tick that finds no pong for two intervals pings again. The next one + -- finds the pong that was read in between, or drops the client. + client.pong_overdue = true client_manager.send_ping(client, "ping") else -- Client connection timed out - log at INFO level (this is expected behavior) diff --git a/tests/unit/server/connection_lifecycle_spec.lua b/tests/unit/server/connection_lifecycle_spec.lua index 09528d8cd..33f59cd9f 100644 --- a/tests/unit/server/connection_lifecycle_spec.lua +++ b/tests/unit/server/connection_lifecycle_spec.lua @@ -140,14 +140,18 @@ describe("The lifecycle of a WebSocket connection", function() assert.equals(frame.OPCODE.PING, parse(writes[2]).opcode) end) - it("still drops a client that never answers after it was connected", function() + it("still drops a client that never answers, at the second tick that finds no pong", function() local tick = start_ping_timer() local client, writes, handle = connect_and_upgrade() - for _ = 1, 3 do - clock = clock + interval - tick() - end + clock = clock + interval + tick() -- the client is 1 interval old: a ping + clock = clock + interval + tick() -- no pong for 2 intervals: the first such tick pings again and does not drop + assert.is_not_nil(server.clients[client.id], "the client was dropped at the first tick that found no pong") + assert.equals(frame.OPCODE.PING, parse(writes[#writes]).opcode) + clock = clock + interval + tick() -- still no pong: the second such tick drops the client assert.is_nil(server.clients[client.id]) assert.spy(callbacks.on_disconnect).was_called_with(client, 1006, "Connection timeout") @@ -156,6 +160,37 @@ describe("The lifecycle of a WebSocket connection", function() end) end) + describe("when the ping timer runs late, below the wake threshold, with Claude's pong still unread", function() + -- libuv runs timers before it reads sockets. A tick that Neovim runs late after a block finds the pong of the last ping + -- still in the socket, so its last_pong is a whole interval older than the tick before it. A block of up to 1.5 + -- intervals is not a wake, so last_pong is not reset. + it("does not drop a Claude that answers every ping, and forgets the late tick once Claude answers", function() + local tick = start_ping_timer() + local client, writes, handle = connect_and_upgrade() + local pong = frame.create_frame(frame.OPCODE.PONG, "ping", true, true) + + clock = clock + interval + tick() + handle._read_cb(nil, pong) + clock = clock + interval + tick() -- Neovim blocks right after this ping, before it reads the pong, for 1.3 intervals + clock = clock + 1.3 * interval + tick() + + assert.is_not_nil(server.clients[client.id], "the client was dropped by a late tick") + assert.spy(callbacks.on_disconnect).was_not_called() + handle._read_cb(nil, pong) -- the loop reads the pong after the late tick + clock = clock + interval + tick() + clock = clock + 1.3 * interval -- a second late tick, again with the pong unread + tick() + + assert.is_not_nil(server.clients[client.id], "the first late tick counted against the second one") + assert.spy(callbacks.on_disconnect).was_not_called() + assert.equals(frame.OPCODE.PING, parse(writes[#writes]).opcode) + end) + end) + describe("when Claude stops reading, a large message fills its window and Claude breaks the protocol", function() local cases = { { diff --git a/tests/unit/server/log_lines_spec.lua b/tests/unit/server/log_lines_spec.lua index 779c59e4b..0feaf2300 100644 --- a/tests/unit/server/log_lines_spec.lua +++ b/tests/unit/server/log_lines_spec.lua @@ -235,6 +235,8 @@ describe("Server lines on the command line", function() lines = {} client.last_pong = vim.loop.now() - 61000 + tick() -- the first tick that finds no pong pings again and logs nothing + assert.same({}, lines) tick() local line = only_line() diff --git a/tests/unit/server/tcp_spec.lua b/tests/unit/server/tcp_spec.lua index c6ae9d8cb..8141106a2 100644 --- a/tests/unit/server/tcp_spec.lua +++ b/tests/unit/server/tcp_spec.lua @@ -343,9 +343,12 @@ describe("TCP server disconnect handling", function() tcp.start_ping_timer(server, 30000) vim.loop.new_timer = new_timer + tick() -- the first tick that finds no pong pings again: a late tick finds the pong of the last ping unread + assert.equals(frame.OPCODE.PING, assert(frame.parse_frame(writes[1])).opcode) + assert.is_not_nil(server.clients[client.id]) tick() - local close = assert(frame.parse_frame(writes[1])) + local close = assert(frame.parse_frame(writes[2])) assert.equals(frame.OPCODE.CLOSE, close.opcode) assert.equals(1011, close.payload:byte(1) * 256 + close.payload:byte(2)) assert.spy(server.on_disconnect).was_called_with(client, 1006, "Connection timeout")