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); +}