From 793173789a25b86c873f7fcc527d700776fa4637 Mon Sep 17 00:00:00 2001 From: Jean-Philippe Sirois Date: Wed, 12 Aug 2026 16:48:38 -0300 Subject: [PATCH] feat(remote): report why the relay connection died The persistent analyzer's connection to the relay breaks and reconnects every 65 seconds or so, and neither side says why. capnweb reports every death as the same "WebSocket connection failed", which cannot distinguish the server reaping us as a half-open client from an ordinary close. The socket is now constructed here rather than opened by capnweb from a URL, so its close frame reaches the log. A close with code 1006 and no reason is a terminate; anything else is not. watchEventLoopLag warns when the loop stops turning for more than five seconds. The relay's pong is answered by the transport on that same loop, and the server terminates any client that misses one 30-second heartbeat, so a stall here looks exactly like a dead process from the outside. Nothing in the logs currently distinguishes the two. It runs only on the persistent path; a CI session is over in seconds. Neither line changes behaviour. Both exist to answer a question the current logs cannot. Co-Authored-By: Claude --- src/main.ts | 4 ++++ src/remote/api-client.ts | 13 +++++++++++- src/remote/event-loop-lag.ts | 39 ++++++++++++++++++++++++++++++++++++ 3 files changed, 55 insertions(+), 1 deletion(-) create mode 100644 src/remote/event-loop-lag.ts diff --git a/src/main.ts b/src/main.ts index 04d26b6..22cee0d 100644 --- a/src/main.ts +++ b/src/main.ts @@ -26,6 +26,7 @@ import { resolveVerdict } from "./gate/policy.ts"; import { DEFAULT_CONFIG } from "./config.ts"; import { ApiClient } from "./remote/api-client.ts"; import { Remote } from "./remote/remote.ts"; +import { watchEventLoopLag } from "./remote/event-loop-lag.ts"; import { ConnectionManager } from "./sync/connection-manager.ts"; import { PgbadgerSource } from "./sql/pgbadger.ts"; import { baselineNotFoundMessage } from "./reporters/baseline-notice.ts"; @@ -438,6 +439,9 @@ async function runOutsideCI() { { disableQueryLoader: false }, sourceDb, ); + // Only the persistent analyzer holds a connection long enough for a stall to + // cost it one; a CI run's session is over in seconds. + watchEventLoopLag(); ApiClient.connectWithReconnect(env.SITE_API_ENDPOINT, env.TOKEN, { kind: "persistent" }, remote); const server = await createServer( env.HOST, diff --git a/src/remote/api-client.ts b/src/remote/api-client.ts index 8b1a6ff..60080a6 100644 --- a/src/remote/api-client.ts +++ b/src/remote/api-client.ts @@ -93,7 +93,18 @@ export class ApiClient extends RpcTarget implements ClientApi { static async connect(endpoint: string, token: string, mode: ConnectionMode, remote: Remote, onBroken: (err: unknown) => void): Promise { const wsEndpoint = `${endpoint}/relay`.replace(/^http/, "ws"); - const unauthenticated = newWebSocketRpcSession(wsEndpoint); + // Own the socket rather than letting capnweb open it from the URL, so the + // close frame is visible. capnweb reports every death as the same + // "WebSocket connection failed", which cannot distinguish the server + // reaping us as a half-open client (1006, no reason) from a normal close. + const socket = new WebSocket(wsEndpoint); + socket.addEventListener("close", (event) => { + log.info( + `Relay socket closed: code=${event.code} reason="${event.reason}" clean=${event.wasClean}`, + this.#name, + ); + }); + const unauthenticated = newWebSocketRpcSession(socket); const api = await unauthenticated.authenticate(token, new this(remote), mode) as unknown as RpcStub; let broken = false; const triggerBroken = (err: unknown) => { diff --git a/src/remote/event-loop-lag.ts b/src/remote/event-loop-lag.ts new file mode 100644 index 0000000..e1d4511 --- /dev/null +++ b/src/remote/event-loop-lag.ts @@ -0,0 +1,39 @@ +import { log } from "../log.ts"; + +const TICK_MS = 1_000; +const DEFAULT_THRESHOLD_MS = 5_000; + +/** + * Warns when the event loop stops turning. + * + * The relay's pong is answered by the transport, on this same loop, and the + * server reaps any client that misses one 30-second heartbeat. So a stall here + * is indistinguishable — from the server's side — from a process that has died, + * and it is the difference between a connection that lasts and one that is + * terminated every minute. Nothing else in the analyzer's logs shows it: the + * connection simply reports itself broken, with no hint that this process was + * the one that went quiet. + * + * Cheap by construction: one timer, one subtraction per second, and it never + * holds the process open. + */ +export function watchEventLoopLag( + thresholdMs: number = DEFAULT_THRESHOLD_MS, +): () => void { + let previousTick = Date.now(); + const timer = setInterval(() => { + const now = Date.now(); + // Anything beyond the interval itself is time the loop owed this timer and + // could not pay, which is time it could not have answered a ping in either. + const lag = now - previousTick - TICK_MS; + previousTick = now; + if (lag >= thresholdMs) { + log.warn( + `Event loop stalled for ${(lag / 1000).toFixed(1)}s — the relay could not answer a heartbeat while it was blocked`, + "event-loop", + ); + } + }, TICK_MS); + timer.unref(); + return () => clearInterval(timer); +}