diff --git a/.agents/skills/verify-diff-lifecycle/covered.lock b/.agents/skills/verify-diff-lifecycle/covered.lock index f596a9e5e..a8215d5f0 100644 --- a/.agents/skills/verify-diff-lifecycle/covered.lock +++ b/.agents/skills/verify-diff-lifecycle/covered.lock @@ -139,7 +139,7 @@ file lua/claudecode/logger.lua 17b404dda41c3591 == lua/claudecode/selection.lua file lua/claudecode/selection.lua 4d6678af786fa69f == lua/claudecode/server/client.lua -file lua/claudecode/server/client.lua 4304e6496b5c4f32 +file lua/claudecode/server/client.lua d630d84ea8ce44a7 block create_client 24fa2a266b76e6ad == lua/claudecode/server/frame.lua file lua/claudecode/server/frame.lua 3c50766875878d56 @@ -161,7 +161,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 63cbb8922056279a +file lua/claudecode/server/tcp.lua 0cfb4b3ed4c138a1 == 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 a45f262aa..5868a67bc 100644 --- a/lua/claudecode/server/README.md +++ b/lua/claudecode/server/README.md @@ -41,7 +41,7 @@ Layers, top to bottom: ### Connection, handshake, and frames -- `client.create_client(tcp_handle, keepalive_timeout?)`, `process_data(...)`, `send_message`, `send_ping`, `close_client`, `abandon_close_frame`, `is_client_alive(client, timeout=30000)`, `sample_write_progress(client)`, `is_client_reading(client)`, and `get_client_info` [server/client.lua:M.process_data] +- `client.create_client(tcp_handle, keepalive_timeout?)`, `process_data(...)`, `send_message`, `send_ping`, `close_client`, `abandon_close_frame`, `sample_write_progress(client)`, `is_client_reading(client)`, and `get_client_info` [server/client.lua:M.process_data] - `handshake.process_handshake(request, expected_auth_token) -> ok, response, headers?` [server/handshake.lua:M.process_handshake] - `handshake.validate_upgrade_request`, `create_handshake_response`, `parse_request_line`, `is_websocket_endpoint`, `create_error_response`, and `extract_http_request` [server/handshake.lua:M.validate_upgrade_request] - `frame.OPCODE`: `CONTINUATION 0x0`, `TEXT 0x1`, `BINARY 0x2`, `CLOSE 0x8`, `PING 0x9`, `PONG 0xA` [server/frame.lua:M.OPCODE] @@ -77,9 +77,9 @@ 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 two ticks in a row find no pong within `interval * 2`. The first such tick pings again and sets `client.pong_overdue`, because a tick that Neovim runs late after a block can come before the loop has read the pong of the last ping. The next tick finds that pong, or drops the client. A tick that finds a pong clears `pong_overdue`. 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 [server/tcp.lua:M.start_ping_timer] [server/tcp.lua:drop_client] -- A Claude that answers each ping but never reads would keep that queue, which is Neovim's memory, without limit, so the server also closes a connected client that answers and whose write queue made no progress at two ticks in a row. Each tick calls `is_client_reading` for each connected client, which calls `sample_write_progress`: it compares `queued_bytes - get_write_queue_size()` with its value at the last progress, and an empty queue counts as progress. A tick that finds progress clears `client.write_stalled`. The first tick that finds none sets it. The second asks for a confirmation, and a confirmation that still finds no progress drops the client: the Close frame carries 1011 "Not reading", `on_disconnect` gets 1006 "Write queue stalled", and the server logs `Closed client_: not reading for s, KB queued` at info level. The confirmation runs right after the next poll. libuv reports that a socket is writable again only in a poll phase, so a tick that Neovim runs after a main-loop block inside an I/O callback can find no progress although Claude read during the block, whether the tick is late or on time. `after_next_poll` arms a check handle, which libuv runs right after each poll phase in every version, and an idle handle, which keeps that poll from waiting for a timer or a socket. The check callback closes both handles, removes them from `server.pending_polls`, and judges the queue once more: progress clears `write_stalled`, and no progress drops the client. A client that left or started to leave in the meantime, because the poll read its EOF, a read error, its Close frame or a protocol error, is skipped without a log line. `stop_server` closes the handles of a confirmation that has not run, which `server.pending_polls` lists. If libuv cannot create a handle, the tick leaves the client for the next tick. The look is a sample at one moment, not proof. libuv takes its snapshot of the ready sockets when a poll starts, so a callback that blocks inside that poll, after the snapshot, hides what Claude reads during the block from the check callback that follows. A client that was stalled for the whole window and resumes during such a block is dropped. That is a deadline race, as with any timeout: the client was stalled when the window ended, and what it read afterwards is not reported yet. Verifier probes closed a reader that resumed 0.1 s into a 0.5 s to 1.5 s block inside the confirming poll, on Neovim 0.12.3 and 0.8.0, at 3 s, 5 s and 30 s intervals. A block after the tick and before that poll, or in a scheduled callback, keeps the reader. The bound is two to three ticks after the last progress, which is 60 s to 90 s at the default interval, plus the delay of late ticks, each of which comes at most `interval * 1.5` after the tick before it. A tick that comes more than `interval * 1.5` after the tick before it counts as a wake from sleep. A wake tick starts a fresh stall window: it clears the count and judges nothing, so it delays the drop by one tick when the count was clear, and by two ticks when the wake tick takes the place of the confirming tick. The next two ticks always count, wake ticks or not, because wake ticks that come again and again are a loop that stays blocked, not sleeps. So whatever the pattern of late ticks, a stalled client is closed at the second tick after a fresh window started. A wake tick three or more ticks after the last fresh start starts a new window. The bound is never the size of the queue, so a Claude that reads slowly, or is sent one message of tens of MB, stays connected while libuv writes any of it. libuv writes more only after the kernel reports the socket writable again, which took 1.2 to 1.5 MB of reading on a Linux loopback socket with default buffers (measured), so a Claude that reads less than about 1.4 MB per window counts as stalled while a backlog exists, and one that reads just faster than that still lets the queue grow as long as Neovim queues more than it reads. `write` queues a frame of more than 1 MiB in pieces of 1 MiB, because libuv on Windows lowers the queue only when a whole write request is done, so a large frame shows its progress per piece there too, and the callback of the last piece reports the frame. [server/tcp.lua:M.start_ping_timer] [server/tcp.lua:confirm_stall] [server/tcp.lua:after_next_poll] [server/tcp.lua:M.stop_server] [server/client.lua:M.is_client_reading] [server/client.lua:M.sample_write_progress] [server/client.lua:write] -- On one tick the pong rule runs first. A client without a pong gets the second chance or the keepalive drop whatever its write queue shows, and only a client that answered is confirmed for a stall. A pong that arrives while the queue is stalled does not save the client: the next tick clears `pong_overdue`, and then asks for the confirmation. Every connected client is sampled on every tick except one that starts a fresh stall window, answering or not, so "two ticks in a row" means consecutive ticks. A tick gap above `interval * 1.5` counts as a wake from sleep and resets `last_pong` of each connected client, and its own alive check finds the fresh pong and clears `pong_overdue`. A wake tick that starts a fresh stall window also resets `last_drain`, clears `write_stalled`, and does not sample the queue. `last_drain` feeds only the `not reading for s` of the log line, so the reset keeps the sleep out of it. A wake tick within two ticks after the start of a fresh window resets `last_pong` only, and counts like any tick. 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] +- A ping timer tick pings every connected client and never closes one for a missing answer. `client.ping_unanswered_since` holds the loop time of the oldest ping sent since bytes were last read from the client. The read callback clears it on any bytes, not only a pong: Claude shows it is alive by writing anything, and a pong that waits behind more unread data than the socket holds is not in the first poll after a block. The tick calls `vim.loop.update_time()` before it reads the clock, because libuv caches the loop time when a pass of the main loop starts and runs the timers of the pass with it, and a callback that ran before the tick in the pass can have blocked since, or the machine can have slept in it. A stale time would hide a wake and would stamp a ping older than it is. Each tick that pinged a client arms `after_next_poll` (below), and its callback runs `judge_silence` after the next poll. libuv runs the check handle right after the poll phase that reads the sockets, so every byte that reached a socket before the loop time of the check was read. The check closes each client that the tick pinged when its oldest ping is `interval * 2.5` old, but only if its loop time is at most `interval * 1.5` after the tick. After a longer block Neovim and Claude can have slept together (a suspended machine), and Claude has had no time to answer. A tick cannot decide this, because libuv can run a tick before it reads the pong that Claude sent: after a block in a check callback or an I/O read callback, and, with libuv 1.44 (bundled in Neovim 0.8), after a block in any callback. libuv 1.44 also runs the timers again at the end of a pass, so two ticks can run with no read between them. `vim.schedule` cannot decide it either, because Neovim runs its callbacks between two passes, so it can run one before the read. Drop bound: a block of the main loop, of any length and in any callback, does not close a Claude that writes something within `interval * 2.5` (75 s by default) of each ping. A tick never closes a client, a check judges only after a poll within `interval * 1.5` of its tick, and any bytes clear the stamp. A client that writes data but never answers a ping is not closed by this rule: it is alive, and the plugin does not judge what it writes (the stall rule below closes it when it stops reading, but only once the kernel's socket buffers are full and libuv's write queue backs up, because a queue that is empty counts as progress). A block longer than `interval * 1.5` restarts the count: the next tick sees the gap, takes it for a wake and clears every stamp. So a block delays the close of a silent Claude, and a run of such blocks can postpone it. Without a long block, a Claude that sends nothing is closed at the first read of its socket after the third tick that follows its first unanswered ping, which is 90 s by default after that ping. 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 check 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 [server/tcp.lua:M.start_ping_timer] [server/tcp.lua:judge_silence] [server/tcp.lua:drop_client] +- A Claude that answers each ping but never reads would keep that queue, which is Neovim's memory, without limit, so the server also closes a connected client that answers and whose write queue made no progress at two ticks in a row. Each tick calls `is_client_reading` for each connected client, which calls `sample_write_progress`: it compares `queued_bytes - get_write_queue_size()` with its value at the last progress, and an empty queue counts as progress. A tick that finds progress clears `client.write_stalled`. The first tick that finds none sets it. The second asks for a confirmation, and a confirmation that still finds no progress drops the client: the Close frame carries 1011 "Not reading", `on_disconnect` gets 1006 "Write queue stalled", and the server logs `Closed client_: not reading for s, KB queued` at info level. The confirmation runs right after the next poll. libuv reports that a socket is writable again only in a poll phase, so a tick that Neovim runs after a main-loop block inside an I/O callback can find no progress although Claude read during the block, whether the tick is late or on time. `after_next_poll` arms a check handle, which libuv runs right after each poll phase in every version, and an idle handle, which keeps that poll from waiting for a timer or a socket. The check callback closes both handles, removes them from `server.pending_polls`, and judges the queue once more: progress clears `write_stalled`, and no progress drops the client. A client that left or started to leave in the meantime, because the poll read its EOF, a read error, its Close frame or a protocol error, is skipped without a log line. `stop_server` closes the handles of a confirmation that has not run, which `server.pending_polls` lists. If libuv cannot create a handle, the tick leaves the client for the next tick. The look is a sample at one moment, not proof. libuv takes its snapshot of the ready sockets when a poll starts, so a callback that blocks inside that poll, after the snapshot, hides what Claude reads during the block from the check callback that follows. A client that was stalled for the whole window and resumes during such a block is dropped. That is a deadline race, as with any timeout: the client was stalled when the window ended, and what it read afterwards is not reported yet. Verifier probes closed a reader that resumed 0.1 s into a 0.5 s to 1.5 s block inside the confirming poll, on Neovim 0.12.3 and 0.8.0, at 3 s, 5 s and 30 s intervals. A block after the tick and before that poll, or in a scheduled callback, keeps the reader. The bound is two to three ticks after the last progress, which is 60 s to 90 s at the default interval, plus the delay of late ticks, each of which comes at most `interval * 1.5` after the tick before it. A tick that comes more than `interval * 1.5` after the tick before it counts as a wake from sleep. A wake tick starts a fresh stall window: it clears the count and judges nothing, so it delays the drop by one tick when the count was clear, and by two ticks when the wake tick takes the place of the confirming tick. The next two ticks always count, wake ticks or not, because wake ticks that come again and again are a loop that stays blocked, not sleeps. So whatever the pattern of late ticks, a stalled client is closed at the second tick after a fresh window started. A wake tick three or more ticks after the last fresh start starts a new window. The bound is never the size of the queue, so a Claude that reads slowly, or is sent one message of tens of MB, stays connected while libuv writes any of it. libuv writes more only after the kernel reports the socket writable again, which took 1.2 to 1.5 MB of reading on a Linux loopback socket with default buffers (measured), so a Claude that reads less than about 1.4 MB per window counts as stalled while a backlog exists, and one that reads just faster than that still lets the queue grow as long as Neovim queues more than it reads. `write` queues a frame of more than 1 MiB in pieces of 1 MiB, because libuv on Windows lowers the queue only when a whole write request is done, so a large frame shows its progress per piece there too, and the callback of the last piece reports the frame. [server/tcp.lua:M.start_ping_timer] [server/tcp.lua:judge_stall] [server/tcp.lua:after_next_poll] [server/tcp.lua:M.stop_server] [server/client.lua:M.is_client_reading] [server/client.lua:M.sample_write_progress] [server/client.lua:write] +- On one tick a client counts as answered when no ping of it waited for `interval * 2`. Only a client that answered is confirmed for a stall. A client that did not answer is dropped by the keepalive check above, whatever its write queue shows. A client that answers while its queue is stalled is not saved: its bytes clear the stamp, the next tick finds it answered, and then asks for the confirmation. Every connected client is sampled on every tick except one that starts a fresh stall window, answering or not, so "two ticks in a row" means consecutive ticks. A tick gap above `interval * 1.5` counts as a wake from sleep and clears `ping_unanswered_since` of each connected client. A wake tick that starts a fresh stall window also resets `last_drain`, clears `write_stalled`, and does not sample the queue. `last_drain` feeds only the `not reading for s` of the log line, so the reset keeps the sleep out of it. A wake tick within two ticks after the start of a fresh window clears the stamps only, and counts like any tick. A client that is not connected is not pinged, so a main loop that blocks during the handshake does not count against it [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] @@ -101,8 +101,8 @@ Layers, top to bottom: - `client.create_client` increments `_G.claudecode_clients_created` [server/client.lua:M.create_client] - `tcp.lua` seeds `math.randomseed` once per process. `init.lua` calls `math.random` at load. Both change the global PRNG [server/tcp.lua:ensure_rng_seeded] - `client.process_data` writes handshake, PONG, and Close frames to the socket. It runs `on_message` and `on_close` through `vim.schedule`. It calls `on_error` directly after a failed handshake write, and after it queues the Close frame for a protocol error [server/client.lua:M.process_data] [server/client.lua:M.close_client] -- The ping timer writes ping frames and closes clients that timed out or stopped reading [server/tcp.lua:M.start_ping_timer] -- A tick that finds the second stalled tick in a row creates a `vim.loop` check handle and an idle handle for one confirmation. The check callback closes them, and `stop_server` closes those that did not run [server/tcp.lua:after_next_poll] [server/tcp.lua:M.stop_server] +- The ping timer writes ping frames. The check handle that each tick arms closes clients that timed out or stopped reading [server/tcp.lua:M.start_ping_timer] [server/tcp.lua:after_next_poll] +- Each tick that pinged a client creates one `vim.loop` check handle and one idle handle, and the judgement of every client of that tick, keepalive and stall, shares that pair. The check callback closes them, and `stop_server` closes those that did not run [server/tcp.lua:after_next_poll] [server/tcp.lua:M.stop_server] - `close_client` starts a repeating `vim.loop` timer for the Close frame of a client that has `keepalive_timeout`. It runs until the frame is written, the socket closes, or the deadline closes the socket [server/client.lua:M.close_client] [server/client.lua:start_close_timer] - `handshake.lua`, `frame.lua`, and `utils.lua` do no I/O [server/handshake.lua:M] - `mock.lua` opens no sockets and keeps its clients and messages in its own `M.state` tables. Its `mcp.tool.invoke` handler calls the real `tools.handle_invoke`, so a simulated tool call has that tool's real side effects (for example `saveDocument` writes the file) [server/mock.lua:M.register_handlers] [server/mock.lua:M.state] diff --git a/lua/claudecode/server/client.lua b/lua/claudecode/server/client.lua index a168d4193..02080ceba 100644 --- a/lua/claudecode/server/client.lua +++ b/lua/claudecode/server/client.lua @@ -36,7 +36,7 @@ local CLOSE_REASONS = { ---@field drained_bytes integer The bytes libuv had written to the socket when `sample_write_progress` last saw progress ---@field last_drain number Timestamp of the last `sample_write_progress` check that found the write queue empty or smaller ---@field write_stalled boolean|nil True after a ping tick found no write progress. The next such tick asks for a look after the next poll, and only that look drops the client ----@field pong_overdue boolean|nil True after a ping timer tick found no pong for two intervals. The next such tick drops the client +---@field ping_unanswered_since number|nil Loop time of the oldest ping sent since bytes were last read from the client ---Create a new WebSocket client ---@param tcp_handle table The vim.loop TCP handle @@ -277,9 +277,6 @@ function M.process_data(client, data, on_message, on_close, on_error, auth_token end client.handshake_complete = true client.state = "connected" - -- The keepalive window starts now. The ping timer ignores a client that is not connected, so the main loop can - -- block between the accept and this point for longer than the timeout, and no ping reached this client yet. - client.last_pong = vim.loop.now() logger.debug("client", "WebSocket connection established for client:", client.id) if on_open then on_open(client) @@ -467,21 +464,6 @@ function M.abandon_close_frame(client) stop_close_timer(client) end ----Check if a client connection is alive ----@param client WebSocketClient The client object ----@param timeout number Timeout in milliseconds (default: 30000) ----@return boolean alive True if the client is considered alive -function M.is_client_alive(client, timeout) - timeout = timeout or 30000 -- 30 seconds default - - if client.state ~= "connected" then - return false - end - - local now = vim.loop.now() - return (now - client.last_pong) < timeout -end - ---Check whether libuv wrote a byte of the write queue of a client since the last check that saw progress, or the queue ---is empty. A client that reads slowly makes progress, and so does one that is sent a single large message, however big. ---@param client WebSocketClient The client object diff --git a/lua/claudecode/server/tcp.lua b/lua/claudecode/server/tcp.lua index 639d4d93c..cd1b8756b 100644 --- a/lua/claudecode/server/tcp.lua +++ b/lua/claudecode/server/tcp.lua @@ -217,6 +217,10 @@ function M._handle_new_connection(server) return end + -- Any bytes show that Claude is alive and writing. A pong can wait behind more unread data than the socket holds, + -- and one poll does not reach it, so the keepalive does not wait for the pong itself. + client.ping_unanswered_since = nil + -- Process incoming data client_manager.process_data(client, data, function(cl, message) server.on_message(cl, message) @@ -430,30 +434,54 @@ local function close_pending_polls(server) end end ----Drop a client that answered its ping and whose write queue made no progress at two ticks in a row, unless the next ----poll shows progress. A Claude whose reader is stuck can still answer each ping, so only its write queue shows it. ----The queue is Neovim's memory: it goes with the client. The tick can run before libuv reported the bytes that Claude ----read during a block, so the stall is judged once more right after the next poll, and only that judgement drops. +---Drop a client that answered its ping and whose write queue made no progress at two ticks in a row, unless the poll +---that just ran shows progress. A Claude whose reader is stuck can still answer each ping, so only its write queue +---shows it. The queue is Neovim's memory: it goes with the client. The tick can run before libuv reported the bytes +---that Claude read during a block, so the stall is judged once more right after the next poll, and only that judgement +---drops. ---@param server TCPServer The server object ---@param client WebSocketClient The client whose queue made no progress at two ticks in a row -local function confirm_stall(server, client) - after_next_poll(server, function() - if server.clients[client.id] ~= client or client.state ~= "connected" then - return - end - if client_manager.sample_write_progress(client) then - client.write_stalled = nil - return +local function judge_stall(server, client) + if server.clients[client.id] ~= client or client.state ~= "connected" then + return + end + if client_manager.sample_write_progress(client) then + client.write_stalled = nil + return + end + local time_since_drain = math.floor((vim.loop.now() - client.last_drain) / 1000) + local queued_kb = math.floor(client.tcp_handle:get_write_queue_size() / 1024) + require("claudecode.logger").one_line( + "info", + "server", + string.format("Closed %s: not reading for %ds, %d KB queued", client.id, time_since_drain, queued_kb) + ) + drop_client(server, client, "Not reading", "Write queue stalled") +end + +---Drop each of `clients` that sent nothing since its oldest ping, for `limit` ms. It runs right after the poll phase that +---reads the sockets [after_next_poll], so every byte that reached a socket before the loop time of the check has been +---read. A timer tick cannot judge: libuv can run it before it reads the pong that Claude sent. That happens after a +---block in a check callback or an I/O read callback, and, with libuv 1.44 (bundled in Neovim 0.8), after a block in any +---callback. libuv 1.44 also runs the timers again at the end of a pass, so two ticks can run with no read between them. +---`vim.schedule` is no help either: Neovim runs its callbacks between two passes, so it can run one before the read. +---@param server TCPServer The server object +---@param clients WebSocketClient[] The clients that the ping timer pinged in one tick +---@param limit number Age in milliseconds of the oldest unanswered ping at which a client is dropped +local function judge_silence(server, clients, limit) + local now = vim.loop.now() + for _, client in ipairs(clients) do + local since = client.ping_unanswered_since + if server.clients[client.id] == client and client.state == "connected" and since and now - since >= limit then + -- Client connection timed out - log at INFO level (this is expected behavior) + require("claudecode.logger").one_line( + "info", + "server", + string.format("Closed %s: no reply for %ds", client.id, math.floor((now - since) / 1000)) + ) + drop_client(server, client, "Keepalive timeout", "Connection timeout") end - local time_since_drain = math.floor((vim.loop.now() - client.last_drain) / 1000) - local queued_kb = math.floor(client.tcp_handle:get_write_queue_size() / 1024) - require("claudecode.logger").one_line( - "info", - "server", - string.format("Closed %s: not reading for %ds, %d KB queued", client.id, time_since_drain, queued_kb) - ) - drop_client(server, client, "Not reading", "Write queue stalled") - end) + end end ---Stop the TCP server @@ -475,7 +503,13 @@ function M.stop_server(server) end end ----Start a periodic ping task to keep connections alive +---Start a periodic ping task to keep connections alive. +---A tick pings every connected client and never drops one. A client whose oldest ping is `interval * 2.5` old is dropped +---at the first read of its socket after a tick [judge_silence], if the loop ran that read within `interval * 1.5` of the +---tick. A block longer than that restarts the count (the next tick is a wake). Any bytes read from a client clear its +---stamp, so a Claude that sends anything, also a large message before its pong, is not dropped. A Claude that sends +---nothing is dropped after the third tick that follows its first unanswered ping: the half interval keeps timer jitter +---from moving the drop. A client that answered is also judged for a stall of its write queue [judge_stall]. ---@param server TCPServer The server object ---@param interval number Ping interval in milliseconds (default: 30000) ---@return table? timer The timer handle, or nil if creation failed @@ -497,6 +531,10 @@ function M.start_ping_timer(server, interval) server.keepalive_timeout = timeout timer:start(interval, interval, function() + -- libuv caches the loop time when a pass starts and runs the timers of the pass with it. A callback that ran before + -- this tick in the pass can have blocked since, or the machine can have slept in it. Read the clock again: a stale + -- `now` hides a wake, and a ping stamped with it looks older than it is. + vim.loop.update_time() local now = vim.loop.now() local elapsed = now - last_run @@ -514,8 +552,8 @@ function M.start_ping_timer(server, interval) end if is_wake_from_sleep then - -- After system sleep/wake, reset all client pong and write-progress timestamps to prevent false timeouts - -- This gives clients a fresh keepalive window since the time jump isn't their fault + -- After system sleep/wake, forget the pings that went unanswered and reset the write-progress timestamps to + -- prevent false timeouts. This gives clients a fresh keepalive window since the time jump isn't their fault require("claudecode.logger").debug( "server", string.format( @@ -525,8 +563,7 @@ function M.start_ping_timer(server, interval) ) for _, client in pairs(server.clients) do if client.state == "connected" then - -- The alive check below finds the fresh pong and clears `pong_overdue`. - client.last_pong = now + client.ping_unanswered_since = nil if fresh_start then client.last_drain = now client.write_stalled = nil @@ -535,40 +572,44 @@ function M.start_ping_timer(server, interval) end end + local pinged, stalled = {}, {} for _, client in pairs(server.clients) do if client.state == "connected" then -- Every tick samples the write queue, so that "two ticks in a row" are consecutive ticks, whether the client -- answered or not. A tick that starts a fresh stall window does not. local reading = fresh_start or client_manager.is_client_reading(client) - -- Check if client is alive (local connections, so use standard timeout) - if client_manager.is_client_alive(client, timeout) then - client.pong_overdue = nil - client_manager.send_ping(client, "ping") - -- Only a client that answered is dropped for a stall, and only after the next poll confirms it. - if not reading then - confirm_stall(server, client) - end - elseif not client.pong_overdue then - -- A tick that Neovim runs late after a block can come before the loop has read the pong of the last ping. - -- 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. A client without a pong gets this second chance whatever its write queue - -- shows: the stall rule above judges only a client that answered. - client.pong_overdue = true - client_manager.send_ping(client, "ping") - else - -- Client connection timed out - log at INFO level (this is expected behavior) - local time_since_pong = math.floor((now - client.last_pong) / 1000) - require("claudecode.logger").one_line( - "info", - "server", - string.format("Closed %s: no reply for %ds", client.id, time_since_pong) - ) - drop_client(server, client, "Keepalive timeout", "Connection timeout") + -- A client answered if no ping of it waited for the whole window (local connections, so use standard timeout) + local since = client.ping_unanswered_since + local answered = since == nil or now - since < timeout + client_manager.send_ping(client, "ping") + client.ping_unanswered_since = since or now + table.insert(pinged, client) + -- Only a client that answered is dropped for a stall, and only after the next poll confirms it. A client that + -- did not answer is dropped by the keepalive judgement, whatever its write queue shows. + if answered and not reading then + table.insert(stalled, client) end end end last_run = now + + if #pinged > 0 then + local tick_time = now + -- Neither judgement happens at the tick: see `judge_silence` and `judge_stall`. If libuv cannot create the handles, + -- the clients wait for the next tick. + after_next_poll(server, function() + -- The keepalive judges only if the poll came at most `interval * 1.5` after the tick. After a longer block Neovim + -- and Claude can have slept together, and Claude has had no time to answer: the next tick finds the same gap, + -- takes it for a wake and starts over. + if vim.loop.now() - tick_time <= interval * 1.5 then + judge_silence(server, pinged, interval * 2.5) + end + for _, client in ipairs(stalled) do + judge_stall(server, client) + end + end) + end end) return timer diff --git a/tests/mocks/vim.lua b/tests/mocks/vim.lua index dda6e3267..f42497c16 100644 --- a/tests/mocks/vim.lua +++ b/tests/mocks/vim.lua @@ -1305,6 +1305,7 @@ local vim = { now = function() return os.time() * 1000 end, + update_time = function() end, timer_stop = function(timer) return true end, diff --git a/tests/unit/server/connection_lifecycle_spec.lua b/tests/unit/server/connection_lifecycle_spec.lua index 2f1d57de8..67f2c0c0c 100644 --- a/tests/unit/server/connection_lifecycle_spec.lua +++ b/tests/unit/server/connection_lifecycle_spec.lua @@ -1,7 +1,8 @@ --- A client that the plugin is done with must leave the server promptly, be reported once and have its socket closed, --- and a Claude that answers pings must never be dropped. These tests run the real tcp.lua and client.lua against a --- socket that works like libuv's: a write callback runs only when the test calls `done` (a Claude that does not read ---- never completes a write), and a second close of a handle is an error. +--- never completes a write), and a second close of a handle is an error. A check handle runs right after a poll, as in +--- libuv. require("tests.busted_setup") describe("The lifecycle of a WebSocket connection", function() @@ -30,8 +31,11 @@ describe("The lifecycle of a WebSocket connection", function() new_timer = vim.loop.new_timer, new_check = vim.loop.new_check, new_idle = vim.loop.new_idle, + update_time = vim.loop.update_time, valid_utf8 = utils.valid_utf8, } + -- The loop time and the time of the world are the same here, unless a test caches the loop time by itself. + vim.loop.update_time = function() end -- `send_message` scans each outbound text with `utils.valid_utf8`, byte by byte in Lua. Under luacov every byte costs -- a line hook, so the multi-MiB messages of these tests took minutes in CI. They check how a message is queued and -- when its client is dropped, not its encoding: `send_utf8_spec.lua` tests that. @@ -104,7 +108,7 @@ describe("The lifecycle of a WebSocket connection", function() after_each(function() vim.schedule, vim.loop.now, vim.loop.new_timer = saved.schedule, saved.now, saved.new_timer - vim.loop.new_check, vim.loop.new_idle = saved.new_check, saved.new_idle + vim.loop.new_check, vim.loop.new_idle, vim.loop.update_time = saved.new_check, saved.new_idle, saved.update_time utils.valid_utf8 = saved.valid_utf8 end) @@ -172,6 +176,16 @@ describe("The lifecycle of a WebSocket connection", function() end end + ---Forget the check and idle handles made so far, to follow the ones that the next ticks make. + local function forget_handles() + for index in pairs(checks) do + checks[index] = nil + end + for index in pairs(idles) do + idles[index] = nil + end + end + ---Start the ping timer on the server, and return the function that runs on each tick. ---One poll phase of the loop: libuv polls its sockets (`during` runs, and reports what Claude read), then the armed ---check callbacks run. @@ -252,18 +266,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, at the second tick that finds no pong", function() + it("still drops a client that never answers, at the poll after the fourth tick", function() local tick = start_ping_timer() local client, writes, handle = connect_and_upgrade() + for _ = 1, 3 do + clock = clock + interval + tick() -- the first ping, and two intervals more + assert.is_not_nil(server.clients[client.id], "the client was dropped before its ping was 2.5 intervals old") + assert.equals(frame.OPCODE.PING, parse(writes[#writes]).opcode) + 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 + tick() -- the first ping is 3 intervals old: the poll after this tick drops the client assert.is_nil(server.clients[client.id]) assert.spy(callbacks.on_disconnect).was_called_with(client, 1006, "Connection timeout") @@ -272,39 +286,460 @@ 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() + -- A tick never drops a client for a missing answer. After a tick, libuv polls its sockets, and a check handle runs + -- right after that poll: only there is a client judged, so a pong that reached the socket was read first. + describe("when a Claude never answers a ping", function() + it("drops it at the first read after the fourth tick, and not at the tick", function() + local tick, raw_tick = start_ping_timer() local client, writes, handle = connect_and_upgrade() - local pong = frame.create_frame(frame.OPCODE.PONG, "ping", true, true) - -- A Claude answers a ping after it read it, so libuv has written the pings queued for it by then. - local function claude_pongs() - handle.drain(math.huge) - handle._read_cb(nil, pong) + + for _ = 1, 3 do + clock = clock + interval + tick() -- the first ping, then 1 and 2 intervals old + assert.is_not_nil(server.clients[client.id], "the client was dropped before its ping was 2.5 intervals old") end + clock = clock + interval + raw_tick() -- the first ping is 3 intervals old, and Neovim did not read the socket since this tick + assert.is_not_nil(server.clients[client.id], "a tick dropped the client before the socket was read") + assert.spy(callbacks.on_disconnect).was_not_called() + poll() + + assert.is_nil(server.clients[client.id]) + assert.spy(callbacks.on_disconnect).was_called_with(client, 1006, "Connection timeout") + assert.equals(1011, close_status(writes[#writes])) + assert.is_true(handle:is_closing()) + end) + + it("counts the time from the first ping that went unanswered, after Claude answered before", function() + local tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() clock = clock + interval tick() - claude_pongs() + handle._read_cb(nil, frame.create_frame(frame.OPCODE.PONG, "", true, true)) -- Claude answers the first ping + for _ = 1, 4 do + clock = clock + interval + assert.is_not_nil(server.clients[client.id]) + handle.drain(math.huge) -- Claude reads the pings, and does not answer them + tick() + end + + assert.is_nil(server.clients[client.id], "the ping of the second tick was unanswered for 3 intervals") + end) + + it("drops it at the first read after a late tick that finds its ping 2.5 intervals old", function() + local tick = start_ping_timer() + local client = connect_and_upgrade() + clock = clock + interval - tick() -- Neovim blocks right after this ping, before it reads the pong, for 1.3 intervals + tick() + clock = clock + 1.3 * interval + tick() -- the first ping is 1.3 intervals old + assert.is_not_nil(server.clients[client.id]) clock = clock + 1.3 * interval + tick() -- the first ping is 2.6 intervals old: the third tick is not needed + + assert.is_nil(server.clients[client.id]) + end) + + it("drops it at the poll that follows a block of 1.4 intervals between the tick and the poll", function() + local tick, raw_tick = start_ping_timer() + local client = connect_and_upgrade() + + for _ = 1, 3 do + clock = clock + interval + tick() + end + clock = clock + interval + raw_tick() + clock = clock + 1.4 * interval + poll() + + assert.is_nil(server.clients[client.id], "the check skipped a poll that came within 1.5 intervals of its tick") + end) + + -- The gap skip is pinned to the millisecond from both sides, as the wake threshold of a tick is: a poll exactly 1.5 + -- intervals after its tick judges, and one 1 ms later does not. + it("judges at a poll exactly 1.5 intervals after its tick", function() + local tick, raw_tick = start_ping_timer() + local client = connect_and_upgrade() + + for _ = 1, 3 do + clock = clock + interval + tick() + end + clock = clock + interval + raw_tick() + clock = clock + 1.5 * interval + poll() + + assert.is_nil(server.clients[client.id], "the check skipped a poll at exactly 1.5 intervals after its tick") + end) + + it("judges nothing at a poll 1 ms above 1.5 intervals after its tick", function() + local tick, raw_tick = start_ping_timer() + local client = connect_and_upgrade() + + for _ = 1, 3 do + clock = clock + interval + tick() + end + clock = clock + interval + raw_tick() + clock = clock + 1.5 * interval + 1 + poll() + + assert.is_not_nil(server.clients[client.id], "the check judged a poll more than 1.5 intervals after its tick") + end) + + it("drops a client whose oldest ping is exactly 2.5 intervals old at its poll", function() + local tick, raw_tick = start_ping_timer() + local client = connect_and_upgrade() + + for _ = 1, 2 do + clock = clock + interval + tick() + end + clock = clock + interval + raw_tick() -- the third tick: the first ping is 2 intervals old + clock = clock + 0.5 * interval -- the poll comes within 1.5 intervals of its tick + poll() + + assert.is_nil(server.clients[client.id], "a ping exactly 2.5 intervals old was not judged") + end) + + it("restarts the count when a block makes the next tick a wake", function() + local tick = start_ping_timer() + local client = connect_and_upgrade() + + for _ = 1, 2 do + clock = clock + interval + tick() + end + clock = clock + 2 * interval -- a block of 2 intervals: the next tick sees a gap above 1.5 intervals + for _ = 1, 3 do + tick() -- the first of these is the wake and stamps afresh, the others age that stamp + assert.is_not_nil(server.clients[client.id], "the count did not restart") + clock = clock + interval + end tick() - assert.is_not_nil(server.clients[client.id], "the client was dropped by a late tick") + assert.is_nil(server.clients[client.id], "a silent Claude was not dropped 3 ticks after the wake") + end) + + it("is dropped by the keepalive, and its Close frame says so, although its write queue stalled", function() + local tick = start_ping_timer() + local client, writes = connect_and_upgrade() + tcp.send_to_client(server, client.id, string.rep("x", 262144)) + + for _ = 1, 4 do + clock = clock + interval + tick() + end + + assert.is_nil(server.clients[client.id]) + assert.spy(callbacks.on_disconnect).was_called_with(client, 1006, "Connection timeout") + assert.equals("Keepalive timeout", parse(writes[#writes]).payload:sub(3)) + end) + end) + + describe("when the main loop blocks before the pongs of a Claude that answers every ping are read", function() + -- libuv runs timers before it reads sockets, and Neovim 0.8 (libuv 1.44) runs the timers a second time at the end + -- of a pass, after the check handles. A tick that Neovim runs late after a block finds the pongs of the last pings + -- unread, and two late ticks can run with no read between them. + local pong + + before_each(function() + pong = frame.create_frame(frame.OPCODE.PONG, "", true, true) + end) + + ---Claude read the pings queued for it, answered, and the poll reads its answers. + local function claude_answers(handle, data) + return function() + handle.drain(math.huge) + handle._read_cb(nil, data or pong) + end + end + + it("does not drop it when two late ticks run with no read between them", function() + local tick, raw_tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() + + clock = clock + interval + tick() -- Claude answers after this poll + clock = clock + interval + raw_tick() + poll(claude_answers(handle)) + clock = clock + interval + tick() -- ping 3 + -- A check callback blocks for 1.3 intervals right after the ping. The timers run again at the end of the pass, and + -- a vim.schedule callback blocks for 1.3 intervals before the next pass reads the socket. + clock = clock + 1.3 * interval + raw_tick() + clock = clock + 1.3 * interval + raw_tick() + assert.is_not_nil(server.clients[client.id], "a late tick dropped the client") + + poll(claude_answers(handle, pong .. pong .. pong)) + + assert.is_not_nil(server.clients[client.id], "the check of a late tick dropped the client") + assert.spy(callbacks.on_disconnect).was_not_called() + end) + + it("does not drop it however many late ticks run with no read between them", function() + local _, raw_tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() + + for _ = 1, 20 do + clock = clock + 1.3 * interval + raw_tick() + end + assert.is_not_nil(server.clients[client.id], "a late tick dropped the client") + poll(claude_answers(handle, pong .. pong .. pong)) + + assert.is_not_nil(server.clients[client.id], "the check of a late tick dropped the client") assert.spy(callbacks.on_disconnect).was_not_called() - claude_pongs() -- the loop reads the pong after the late tick + end) + + it("does not drop a Claude whose pong waits in the socket when its ping is 3 intervals old", function() + local tick, raw_tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() + clock = clock + interval + tick() -- Claude answers after this poll + for _ = 1, 2 do + clock = clock + interval + tick() + end + clock = clock + interval + raw_tick() -- the ping of the first tick is 3 intervals old, and its pong was not read yet + poll(claude_answers(handle)) + + assert.is_not_nil(server.clients[client.id], "the check ran before the pong was read") + assert.spy(callbacks.on_disconnect).was_not_called() + end) + + -- A machine that sleeps between a tick and its poll stops Neovim and Claude together. When they wake, the loop polls + -- before Claude answers, and the ping looks as old as the sleep. A block that long is a wake, as it is for a tick. + it("judges nothing when the loop blocked for longer than 1.5 intervals between the tick and its poll", function() + local tick, raw_tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() + tick() - clock = clock + 1.3 * interval -- a second late tick, again with the pong unread + clock = clock + interval + raw_tick() + clock = clock + 3 * interval -- a callback blocks before the poll, or the machine sleeps + poll() -- Claude has not answered yet + + assert.is_not_nil(server.clients[client.id], "the check judged a ping that the block made look old") + poll(claude_answers(handle)) + assert.is_not_nil(server.clients[client.id]) + assert.spy(callbacks.on_disconnect).was_not_called() + end) + + -- Claude writes while Neovim is blocked, and one poll reads only what the socket holds: the first part of a large + -- message. The pong waits behind it, so the poll does not reach it. Any bytes show that Claude is alive. + it( + "does not drop a Claude that sends a large message before its pong, whichever block comes before the poll", + function() + local tick, raw_tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() + local big = frame.create_frame(frame.OPCODE.TEXT, string.rep("x", 300000), true, true) + + clock = clock + interval + tick() + clock = clock + 1.4 * interval + raw_tick() -- the ping of the first tick is 1.4 intervals old, and its pong waits behind the large message + clock = clock + 1.4 * interval + -- The poll reads the first part: the ping is 2.8 intervals old, within the gap of the tick. + poll(claude_answers(handle, big:sub(1, 65536))) + + assert.is_not_nil(server.clients[client.id], "the check dropped a Claude that was sending") + poll(claude_answers(handle, big:sub(65537) .. pong)) + assert.is_not_nil(server.clients[client.id]) + assert.spy(callbacks.on_disconnect).was_not_called() + end + ) + + it("does not drop a client that writes data but never answers a ping", function() + local tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() + local request = frame.create_frame(frame.OPCODE.TEXT, "{}", true, true) + + for _ = 1, 8 do + clock = clock + interval + handle.drain(math.huge) -- it reads what the plugin writes + handle._read_cb(nil, request) + tick() + end + + assert.is_not_nil(server.clients[client.id], "a client that writes is alive") + assert.spy(callbacks.on_disconnect).was_not_called() + end) + + ---Cache the loop time as libuv does: it is the time of the world only when `refresh` runs, at the start of a pass + ---and after a poll. + local function cache_loop_time() + local cached = clock + vim.loop.now = function() + return cached + end + vim.loop.update_time = function() + cached = clock + end + return function() + cached = clock + end + end + + it( + "judges a silent Claude with the loop time of the poll, not with a time read after a callback blocked", + function() + local refresh = cache_loop_time() + local tick, raw_tick = start_ping_timer() + local client = connect_and_upgrade() + + for _ = 1, 3 do + clock = clock + interval + refresh() + tick() + end + clock = clock + interval + refresh() + raw_tick() + poll(function() + refresh() -- the poll returned + clock = clock + 3 * interval -- a callback that runs before the check handles blocks after the poll + end) + + assert.is_nil(server.clients[client.id], "the check took the time after the block for the time of the poll") + end + ) + + it("keeps a Claude whose pong reaches the socket while a callback blocks between the poll and the check", function() + local refresh = cache_loop_time() + local _, raw_tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() + + clock = clock + interval + refresh() + raw_tick() + poll(function() + refresh() -- the poll returned before Claude's pong arrived, and read nothing + clock = clock + 3 * interval -- a younger check callback or an I/O callback blocks; the pong arrives meanwhile + end) + assert.is_not_nil(server.clients[client.id], "the check judged with a time read after the block") + poll(claude_answers(handle)) + + assert.is_not_nil(server.clients[client.id]) + assert.spy(callbacks.on_disconnect).was_not_called() + end) + + -- libuv runs the timers of a pass with the loop time of the start of the pass. A timer callback that runs before the + -- ping timer can block for longer than 1.5 intervals, or the machine can sleep in it. The cached time then hides the + -- wake, and the pings that went unanswered before it would look old at the check, which has no gap to skip. + it("takes a tick for a wake when a callback before it in the pass blocked, though the loop time is old", function() + local refresh = cache_loop_time() + local tick, raw_tick = start_ping_timer() + local client = connect_and_upgrade() + + for _ = 1, 2 do + clock = clock + interval + refresh() + tick() + end + clock = clock + interval + refresh() + clock = clock + 2 * interval -- a timer callback that runs before the ping timer blocks, or the machine sleeps + raw_tick() -- the cached loop time shows one interval since the last tick, the clock three + poll() -- Claude has had no time to answer + + assert.is_not_nil(server.clients[client.id], "the tick did not see the wake, and the check judged an old ping") + end) + + it( + "ages a ping from when it was sent, though a callback of the pass blocked for half an interval before", + function() + local refresh = cache_loop_time() + local tick, raw_tick = start_ping_timer() + local client = connect_and_upgrade() + + clock = clock + interval + refresh() + clock = clock + 0.5 * interval -- a timer that ran before the ping timer in this pass blocked: the loop time is old + raw_tick() + poll(refresh) + for _ = 1, 2 do + clock = clock + interval + refresh() + tick() + end + assert.is_not_nil(server.clients[client.id], "the ping was aged from the loop time that the block left behind") + + clock = clock + interval + refresh() + tick() + assert.is_nil(server.clients[client.id]) + end + ) + + it("forgets the pings that went unanswered when Neovim wakes from sleep", function() + local tick, raw_tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() + + for _ = 1, 2 do + clock = clock + interval + tick() + end + clock = clock + 10 * interval -- the machine slept: Claude slept too, and answers once it is awake tick() + assert.is_not_nil(server.clients[client.id], "the wake was not forgiven") + poll(claude_answers(handle)) + + assert.is_not_nil(server.clients[client.id]) + assert.is_not_nil(raw_tick) + end) + end) + + describe("when a client leaves between a tick and the check that follows it", function() + ---Three ticks with a poll after each, then a fourth that no poll follows. Claude never answered: the oldest ping is 3 + ---intervals old at the fourth tick, and the check of that tick is the next to run. + local function tick_four_times(tick, raw_tick) + for _ = 1, 3 do + clock = clock + interval + tick() + end + clock = clock + interval + raw_tick() + end - assert.is_not_nil(server.clients[client.id], "the first late tick counted against the second one") + it("does not report a client that hung up, and logs nothing about it", function() + local one_line = spy.on(require("claudecode.logger"), "one_line") + local tick, raw_tick = start_ping_timer() + local client, _, handle = connect_and_upgrade() + tick_four_times(tick, raw_tick) + + handle._read_cb(nil, nil) -- Claude hangs up before the pass reads anything else + assert.spy(callbacks.on_disconnect).was_called(1) + assert.spy(callbacks.on_disconnect).was_called_with(client, 1006, "EOF") + poll() + + assert.spy(callbacks.on_disconnect).was_called(1) + assert.spy(one_line).was_not_called() + one_line:revert() + end) + + it("does not drop a client that is closing", function() + local tick, raw_tick = start_ping_timer() + local client, writes = connect_and_upgrade() + tick_four_times(tick, raw_tick) + require("claudecode.server.client").close_client(client, 1001, "going away") -- the Close frame waits to be written + assert.equals("closing", client.state) + local written = #writes + poll() + + assert.equals(written, #writes, "a Close frame followed the Close frame that was queued") assert.spy(callbacks.on_disconnect).was_not_called() - assert.equals(frame.OPCODE.PING, parse(writes[#writes]).opcode) end) end) @@ -399,7 +834,7 @@ describe("The lifecycle of a WebSocket connection", function() local client, writes, handle = connect_and_upgrade() tcp.send_to_client(server, client.id, string.rep("x", 262144)) - for _ = 1, 3 do + for _ = 1, 4 do clock = clock + interval tick() end @@ -563,40 +998,29 @@ describe("The lifecycle of a WebSocket connection", function() handle._read_cb(nil, frame.create_frame(frame.OPCODE.PONG, "", true, true)) end - ---Start a client whose queue never drains, which answers the first tick and the third, and not the second. + ---Start a client whose queue never drains, which answers the first tick and not the following two. local function stalled_client_that_misses_a_pong() local tick = start_ping_timer() local client, writes, handle = connect_and_upgrade() tcp.send_to_client(server, client.id, reply) pong(handle) clock = clock + interval - tick() -- the 101 reply was written: that is progress, and the last one + tick() -- the 101 reply was written: that is progress, and the last one; the ping is stamped clock = clock + interval - tick() -- no pong for two intervals: the second chance + tick() -- no pong for 1 interval and no progress: the first tick that counts return tick, client, writes, handle end - it("gives a silent client its second chance although its queue stalled too, then drops it for the pong", function() - local client_manager = require("claudecode.server.client") - local tick = start_ping_timer() - local client, writes, handle = connect_and_upgrade() - tcp.send_to_client(server, client.id, reply) - -- No pong for two intervals and no byte written for two ticks: both rules find this client dead at the first tick. - client.last_pong = clock - 2 * interval - client.last_drain = clock - 3 * interval - client.drained_bytes = client.queued_bytes - handle:get_write_queue_size() - client.write_stalled = true -- the tick before found no progress either - assert.is_false(client_manager.is_client_alive(client, 2 * interval)) - assert.is_false(client_manager.is_client_reading(client)) - - tick() - - assert.is_not_nil(server.clients[client.id], "the stall skipped the second chance of the pong rule") - assert.is_true(client.pong_overdue) - assert.equals(frame.OPCODE.PING, parse(writes[#writes]).opcode) + it("leaves a silent client to the keepalive although its queue stalled too, and drops it for the pong", function() + local tick, client, writes, handle = stalled_client_that_misses_a_pong() + assert.is_true(client.write_stalled) + assert.is_not_nil(client.ping_unanswered_since) clock = clock + interval - tick() + tick() -- the oldest ping is 2 intervals old: the client did not answer, so the stall is not judged + assert.is_not_nil(server.clients[client.id], "the stall dropped a client that did not answer") + clock = clock + interval + tick() -- the oldest ping is 3 intervals old: the keepalive drops it assert.is_nil(server.clients[client.id]) assert.spy(callbacks.on_disconnect).was_called(1) @@ -608,50 +1032,43 @@ describe("The lifecycle of a WebSocket connection", function() it("drops a client for the stall when its pong arrives, because the pong does not save a stalled queue", function() local tick, client, writes, handle = stalled_client_that_misses_a_pong() - assert.is_true(client.pong_overdue) + assert.is_true(client.write_stalled) pong(handle) -- the late pong is read, but nothing of the queue is written + assert.is_nil(client.ping_unanswered_since, "the pong did not clear the stamp") clock = clock + interval tick() - assert.is_nil(client.pong_overdue, "the tick that found the pong kept the flag") assert.is_nil(server.clients[client.id]) assert.spy(callbacks.on_disconnect).was_called(1) assert.spy(callbacks.on_disconnect).was_called_with(client, 1006, "Write queue stalled") assert.equals("Not reading", parse(writes[#writes]).payload:sub(3)) end) - it("keeps a client whose pong arrives while its queue drains, and clears the flag", function() - local tick = start_ping_timer() - local client, _, handle = connect_and_upgrade() - tcp.send_to_client(server, client.id, reply) - pong(handle) - clock = clock + interval - tick() - clock = clock + interval - tick() -- no pong: the second chance - assert.is_true(client.pong_overdue) + it("keeps a client whose pong arrives while its queue drains, and clears the count", function() + local tick, client, _, handle = stalled_client_that_misses_a_pong() + assert.is_true(client.write_stalled) handle.drain(1024) -- Claude reads a little, and answers pong(handle) clock = clock + interval tick() - assert.is_nil(client.pong_overdue) + assert.is_nil(client.write_stalled) assert.is_not_nil(server.clients[client.id]) assert.spy(callbacks.on_disconnect).was_not_called() end) - it("clears both flags and restarts the stall window when the machine wakes from sleep", function() + it("forgets the unanswered pings and restarts the stall window when the machine wakes from sleep", function() local tick, client, _, handle = stalled_client_that_misses_a_pong() - assert.is_true(client.pong_overdue) assert.is_true(client.write_stalled) clock = clock + 600000 -- the machine slept for ten minutes, and the timer runs first when it wakes tick() - assert.is_nil(client.pong_overdue, "the wake kept the flag") assert.is_nil(client.write_stalled, "the wake kept the stall count") assert.is_not_nil(server.clients[client.id], "the sleep counted against the client") + assert.is_not_nil(client.ping_unanswered_since, "the tick that woke did not ping") + assert.equals(clock, client.ping_unanswered_since, "the wake kept a ping that went unanswered before the sleep") pong(handle) clock = clock + interval @@ -747,6 +1164,37 @@ describe("The lifecycle of a WebSocket connection", function() assert.equals("Not reading", parse(writes[#writes]).payload:sub(3)) end) + it("drops a stalled client although every poll comes 1.6 intervals after its tick", function() + local _, raw_tick, client, handle = stalled_client() + + clock = clock + 1.6 * interval + for _ = 1, 9 do + handle._read_cb(nil, pong) -- Claude answers, and does not read + raw_tick() + clock = clock + 1.6 * interval -- a callback blocks between the tick and its poll + poll() + if not server.clients[client.id] then + break + end + end + + assert.is_nil(server.clients[client.id], "a stalled client stayed while every poll came late") + assert.spy(callbacks.on_disconnect).was_called_with(client, 1006, "Write queue stalled") + end) + + it("judges a stall for a client whose last ping is inside the window and not answered yet", function() + local tick, raw_tick, client, handle = stalled_client() + answer_and(tick, 1)(handle) -- the first tick that counts + assert.is_true(client.write_stalled) + + clock = clock + interval + raw_tick() -- the ping of the last tick waits for Claude: it is one interval old, inside the window of two + poll() + + assert.is_nil(server.clients[client.id], "a client that has two intervals to answer was not judged for a stall") + assert.spy(callbacks.on_disconnect).was_called_with(client, 1006, "Write queue stalled") + end) + it("does not ask for a confirmation at the first tick without progress", function() local tick, _, client, handle = stalled_client() @@ -754,7 +1202,7 @@ describe("The lifecycle of a WebSocket connection", function() assert.is_true(client.write_stalled) assert.is_not_nil(server.clients[client.id]) - assert.equals(0, #checks, "the first tick armed a check handle") + assert.spy(callbacks.on_disconnect).was_not_called() end) it("clears the count when a tick finds progress", function() @@ -804,12 +1252,14 @@ describe("The lifecycle of a WebSocket connection", function() assert.is_true(client.write_stalled) handle._read_cb(nil, pong) + forget_handles() clock = clock + 1.5 * interval + 1 tick() + poll() -- the poll after the tick: a confirmation would find no progress and drop the client assert.is_nil(client.write_stalled, "a gap above 1.5 intervals kept the count") assert.is_not_nil(server.clients[client.id], "a gap above 1.5 intervals counted against the client") - assert.equals(0, #checks, "a wake tick asked for a confirmation") + assert.spy(callbacks.on_disconnect).was_not_called() end) it("judges only the clients that answered at the tick", function() @@ -817,14 +1267,14 @@ describe("The lifecycle of a WebSocket connection", function() answer_and(tick, 1)(handle) assert.is_true(client.write_stalled) - -- No pong for two intervals: the pong rule gives its second chance, and the stall rule leaves the client alone. - client.last_pong = clock - 2 * interval + -- No pong for two intervals: the keepalive is not due yet, and the stall rule leaves the client alone. + client.ping_unanswered_since = clock - 2 * interval + interval clock = clock + interval tick() - assert.is_not_nil(server.clients[client.id]) - assert.is_true(client.pong_overdue) - assert.equals(0, #checks, "a client that did not answer was confirmed for a stall") + assert.is_not_nil(server.clients[client.id], "a client that did not answer was confirmed for a stall") + assert.is_not_nil(client.ping_unanswered_since) + assert.spy(callbacks.on_disconnect).was_not_called() end) it("makes no stall judgement at the tick that finds the machine woken from sleep, and clears the count", function() @@ -837,7 +1287,7 @@ describe("The lifecycle of a WebSocket connection", function() assert.is_nil(client.write_stalled, "the wake kept the count") assert.is_not_nil(server.clients[client.id], "the sleep counted against the client") - assert.equals(0, #checks) + assert.spy(callbacks.on_disconnect).was_not_called() end) it("counts the two ticks after a wake tick, so that a run of wake ticks keeps no stalled client", function() @@ -918,6 +1368,7 @@ describe("The lifecycle of a WebSocket connection", function() local function pending_confirmation() local tick, raw_tick, client, handle, writes = stalled_client() answer_and(tick, 1)(handle) + forget_handles() answer_and(raw_tick, 1)(handle) assert.equals(1, #checks) assert.equals(1, #idles) @@ -1062,6 +1513,7 @@ describe("The lifecycle of a WebSocket connection", function() end local tick, raw_tick, client, handle = stalled_client() answer_and(tick, 1)(handle) + forget_handles() answer_and(raw_tick, 1)(handle) diff --git a/tests/unit/server/log_lines_spec.lua b/tests/unit/server/log_lines_spec.lua index 0feaf2300..7223cca7f 100644 --- a/tests/unit/server/log_lines_spec.lua +++ b/tests/unit/server/log_lines_spec.lua @@ -21,6 +21,7 @@ describe("Server lines on the command line", function() lines = {} saved.notify, saved.echo, saved.new_timer, saved.new_tcp = vim.notify, vim.api.nvim_echo, vim.loop.new_timer, vim.loop.new_tcp + saved.new_check, saved.update_time, saved.now = vim.loop.new_check, vim.loop.update_time, vim.loop.now vim.notify = function(msg, level) table.insert(lines, { text = msg, level = level }) end @@ -37,6 +38,7 @@ describe("Server lines on the command line", function() end vim.notify, vim.api.nvim_echo, vim.loop.new_timer, vim.loop.new_tcp = saved.notify, saved.echo, saved.new_timer, saved.new_tcp + vim.loop.new_check, vim.loop.update_time, vim.loop.now = saved.new_check, saved.update_time, saved.now end) local function start() @@ -220,6 +222,7 @@ describe("Server lines on the command line", function() it("shows a keepalive timeout as one info line", function() local tick + local checks, clock = {}, 1000000 vim.loop.new_timer = function() return { start = function(_, _, _, callback) @@ -229,18 +232,38 @@ describe("Server lines on the command line", function() close = function() end, } end + vim.loop.new_check = function() + return { + start = function(_, callback) + table.insert(checks, callback) + end, + stop = function() end, + close = function() end, + } + end + vim.loop.update_time = function() end + vim.loop.now = function() + return clock + end local client = connect(start()) client.tcp_handle._read_cb(nil, upgrade(token)) assert.equals("connected", client.state) 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() + for round = 1, 4 do + clock = clock + 30000 + tick() -- a tick pings and logs nothing: the timeout is decided at the check, after libuv read the socket + assert.same({}, lines) + if round < 4 then + table.remove(checks)() + assert.same({}, lines) + end + end + table.remove(checks)() local line = only_line() assert.equals(vim.log.levels.INFO, line.level) assert_contains(line.text, client.id) + assert_contains(line.text, "no reply for 90s") end) end) diff --git a/tests/unit/server/tcp_spec.lua b/tests/unit/server/tcp_spec.lua index 5ae0409b6..7f107b0e2 100644 --- a/tests/unit/server/tcp_spec.lua +++ b/tests/unit/server/tcp_spec.lua @@ -5,15 +5,23 @@ local client_manager = require("claudecode.server.client") describe("TCP server disconnect handling", function() local tcp local original_process_data + local original_loop before_each(function() package.loaded["claudecode.server.tcp"] = nil tcp = require("claudecode.server.tcp") original_process_data = client_manager.process_data + original_loop = {} + for _, name in ipairs({ "new_timer", "new_check", "update_time", "now" }) do + original_loop[name] = vim.loop[name] + end end) after_each(function() client_manager.process_data = original_process_data + for name, fn in pairs(original_loop) do + vim.loop[name] = fn + end end) describe("find_available_port", function() @@ -313,7 +321,8 @@ describe("TCP server disconnect handling", function() it("closes a client that stopped answering pings with 1011, and reports 1006 to on_disconnect", function() local frame = require("claudecode.server.frame") local tick - local new_timer = vim.loop.new_timer + local checks = {} + local clock = 1000000 vim.loop.new_timer = function() return { start = function(_, _, _, callback) @@ -323,6 +332,20 @@ describe("TCP server disconnect handling", function() close = function() end, } end + -- A check handle runs after the poll that reads the sockets. Neovim runs the callback of the ping timer's check once. + vim.loop.new_check = function() + return { + start = function(self, callback) + table.insert(checks, callback) + end, + stop = function() end, + close = function() end, + } + end + vim.loop.update_time = function() end + vim.loop.now = function() + return clock + end local writes = {} local handle = { closed = false } function handle:write(data, callback) @@ -341,17 +364,25 @@ describe("TCP server disconnect handling", function() return 0 end local client = client_manager.create_client(handle) - client.state, client.handshake_complete, client.last_pong = "connected", true, vim.loop.now() - 61000 + client.state, client.handshake_complete = "connected", true local server = { clients = { [client.id] = client }, on_disconnect = spy.new(function() end) } 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() + for round = 1, 4 do + clock = clock + 30000 + tick() -- a tick pings and never drops: it can run before libuv reads the pong of the last ping + assert.is_not_nil(server.clients[client.id]) + assert.equals(frame.OPCODE.PING, assert(frame.parse_frame(writes[#writes])).opcode) + assert.equals(1, #checks) + if round < 4 then + table.remove(checks)() -- libuv read the socket, and Claude did not answer + assert.is_not_nil(server.clients[client.id]) + end + end + -- The oldest ping is 3 intervals old, and libuv read the socket: Claude did not answer. + table.remove(checks)() - local close = assert(frame.parse_frame(writes[2])) + local close = assert(frame.parse_frame(writes[#writes])) 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")