feat(observability): event-loop lag monitoring for Redis leases (F8) (#137)

.changeset/feat-f8-event-loop-lag-observability.md

@@ -0,0 +1,26 @@
+---
+"sql-fs-api": minor
+---
+
+feat(observability): event-loop lag monitoring for the Redis leases (F8).
+
+The exec-lock writer lease, the RW-lock writer flag, and the RW-lock reader ZSET
+scores are all kept alive by `setTimeout` heartbeats that silently assume timers
+fire on schedule. A long event-loop stall (a V8 GC pause or a pathological
+synchronous bash stretch) can fire a renewal past the lease, voiding it — Lock 3
+keeps Postgres consistent, so this was always an observability gap, not a
+correctness bug, but nothing measured it.
+
+New `src/api/event-loop-monitor.ts` (purely observational, no behavior change):
+
+- A `perf_hooks.monitorEventLoopDelay` histogram started at boot, sampled every
+  `EVENT_LOOP_MONITOR_INTERVAL_MS` (default 10s) and logged as
+  `event:"event_loop_lag"` (`p50Ms`/`p99Ms`/`maxMs`/`meanMs`), then reset.
+- Per-heartbeat gap measurement wired into all three lease sites: each heartbeat
+  reports actual-minus-expected fire time as `event:"heartbeat_gap"` at
+  `severity:"warn"` (gap > renewMs) or `"critical"` (gap > leaseMs), tagged with
+  the lock kind (`exec`/`rw-writer`/`rw-reader`) and key.
+
+Alert thresholds are documented in DEVELOPER.md ("Lock observability"). End-to-end
+smoke tests reproduce a >lease stall on each lease and assert the critical
+heartbeat_gap fires (with a no-stall control proving no false positives).

CLAUDE.md

@@ -219,6 +219,7 @@ const TABLE = Object.assign(Object.create(null) as Record<string, string>, {
 | `REDIS_RWLOCK_READER_LEASE_MS` | No (default: 60000) | TTL (ms) for reader entries in the distributed RW lock ZSET. Bounds the time a writer must wait for a crashed reader to be reaped. |
 | `REDIS_PATH_SNAPSHOT_ENABLED` | No (default: false) | Set to `true` to enable the Redis path snapshot cache. When enabled, cold-start pathCache is loaded from Redis instead of a full Postgres `loadAllPaths` scan. Requires `REDIS_URL`. |
 | `REDIS_PATH_SNAPSHOT_TTL_MS` | No (default: 3600000) | TTL for path snapshot entries (ms, default 1h). |
+| `EVENT_LOOP_MONITOR_INTERVAL_MS` | No (default: 10000) | Sampling interval (ms) for the F8 event-loop lag monitor. Each window logs `event:"event_loop_lag"` (`p50Ms`/`p99Ms`/`maxMs`/`meanMs`) then resets the histogram. Purely observational; pairs with per-heartbeat `event:"heartbeat_gap"` warn/critical events that flag a stall eating into a Redis lease (see DEVELOPER.md "Lock observability"). |
 | `JUST_BASH_DEFENSE_IN_DEPTH` | No (default: `false`) | Enables just-bash's defense-in-depth security layer (monkey-patches `setTimeout`, `eval`, `Function`, dynamic `import`, etc. for the duration of `bash.exec`). All Postgres I/O is wrapped in `DefenseInDepthBox.runTrustedAsync` to remain compatible. |
 | `JUST_BASH_DEFENSE_AUDIT_MODE` | No (default: `true`) | When `JUST_BASH_DEFENSE_IN_DEPTH=true`, controls whether violations throw (`false`) or are logged only (`true`). Recommended `true` for initial rollout, then flip to `false` once logs are clean. |
 | `BLOB_GC_MIN_AGE_MS` | No (default: 10800000) | Grace window (ms, default 3h) before an orphan blob becomes collectible by `pnpm db:gc`. Orphans whose `last_referenced_at` is newer than this are kept; the `ON CONFLICT DO UPDATE` row lock on blob writes is the actual dedup re-adoption race guard — this window is churn/margin control. Rows with NULL `last_referenced_at` (legacy, pre-migration-0006) are treated as ancient and always collectible. Override per-run with `--min-age-ms`. |

DEVELOPER.md

@@ -202,6 +202,19 @@ Bypassing the lock to write directly to `SqlFs` from elsewhere in the codebase w
 | `DELETE /sandboxes/:id` races an active exec | drains via exclusive acquire | blocks (routed through lock) | backstop |
 | Admin/test route bypasses `withSession` | — | — | still catches |
 
+### Lock observability — event-loop lag (F8)
+
+Every lease above (the exec-lock writer lease, the RW-lock writer flag, and the RW-lock reader ZSET scores) is kept alive by a `setTimeout` heartbeat that renews well before expiry (`renewMs` 20s < `leaseMs` 60s). They all assume the timer fires roughly on schedule. The GC-pause failure mode in the table above is exactly a violation of that assumption: when the event loop stalls longer than the lease, the renewal fires too late, Redis has already expired the key / reaped the reader entry, and the next renew returns 0 → `LockLostError`. Lock 3 keeps the DB consistent, so this is an **observability** concern, not a correctness one — but until F8 nothing measured how close the process ran to the lease floor.
+
+`src/api/event-loop-monitor.ts` is purely observational and emits two structured log events:
+
+| Event | Emitted by | Fields | Meaning / alert threshold |
+|---|---|---|---|
+| `event_loop_lag` | boot sampler (`startEventLoopMonitor`, every `EVENT_LOOP_MONITOR_INTERVAL_MS`, default 10s) | `p50Ms`, `p99Ms`, `maxMs`, `meanMs`, `windowMs` | Process-wide event-loop delay from `perf_hooks.monitorEventLoopDelay`. **Page** when `p99Ms`/`maxMs` approaches `renewMs` (~20s) — the lease margin is being eaten. |
+| `heartbeat_gap` | each heartbeat callback (`recordHeartbeatGap`) | `severity`, `lock` (`exec`\|`rw-writer`\|`rw-reader`), `key`, `gapMs`, `renewMs`, `leaseMs` | Actual-minus-expected fire time for one heartbeat. `severity:"warn"` at `gapMs > renewMs` (a full interval late); `severity:"critical"` at `gapMs > leaseMs` (the lease almost certainly lapsed). Silent below `renewMs`. |
+
+`warn`/`critical` go to `console.warn`/`console.error` respectively; the sampler logs at `console.log`. A `critical` `heartbeat_gap` for `exec`/`rw-writer` is the breadcrumb that explains a subsequent `LockLostError`; for `rw-reader` it flags the window during which a writer could have reaped the stale reader entry and entered mid-read. `eventLoopLagSnapshot()` exposes the live histogram for a future health endpoint without perturbing the windowed log.
+
 ---
 
 ## ReadOnly Safety Model

src/api/distributed-lock.ts

@@ -15,6 +15,7 @@ import {
 	DEFAULT_ACQUIRE_ERROR_BUDGET_MS,
 	getRedisCircuitBreaker,
 } from "../redis/circuit-breaker.js";
+import { recordHeartbeatGap } from "./event-loop-monitor.js";
 
 const RELEASE_SCRIPT = `
 if redis.call("get", KEYS[1]) == ARGV[1] then
@@ -192,8 +193,13 @@ export async function withDistributedLock<T>(
 	const renewRetryMs = Math.max(50, Math.floor(renewMs / 4));
 	const scheduleRenew = (delayMs: number): void => {
 		if (stopped) return;
+		// F8: capture when this tick is *expected* to fire so the callback can
+		// measure event-loop lag (a GC pause / sync stall that delays renewal past
+		// the lease is otherwise silent until LockLostError surfaces post-hoc).
+		const expectedFireAt = Date.now() + delayMs;
 		renewTimer = setTimeout(async () => {
 			if (stopped) return;
+			recordHeartbeatGap({ lock: "exec", key, expectedFireAt, renewMs, leaseMs });
 			// Cap renewal command wait so a stalled Redis can't block release.
 			let outcome: "renewed" | "ownership_lost" | "transient";
 			// L1: track and clear the race timeout so a won race doesn't leave a

src/api/distributed-rw-lock.ts

@@ -19,6 +19,7 @@ import {
 } from "../redis/circuit-breaker.js";
 export { LockAcquireTimeoutError, LockLostError } from "./distributed-lock.js";
 import { LockAcquireTimeoutError, LockLostError, jitteredDelayMs } from "./distributed-lock.js";
+import { recordHeartbeatGap } from "./event-loop-monitor.js";
 
 // ── Lua scripts ──────────────────────────────────────────────────────────────
 
@@ -222,8 +223,12 @@ function startSharedHeartbeat(
 
 	const schedule = (delayMs: number): void => {
 		if (stopped) return;
+		// F8: a stall that delays this tick past the reader lease lets a writer
+		// enter mid-read; measure the gap (readerLeaseMs is the reader's "lease").
+		const expectedFireAt = Date.now() + delayMs;
 		timer = setTimeout(async () => {
 			if (stopped) return;
+			recordHeartbeatGap({ lock: "rw-reader", key: keys.readers, expectedFireAt, renewMs, leaseMs: readerLeaseMs });
 			let outcome: "renewed" | "ownership_lost" | "transient";
 			let raceTimeout: ReturnType<typeof setTimeout> | undefined; // L1: clear on settle
 			try {
@@ -349,8 +354,12 @@ function startExclusiveHeartbeat(
 
 	const schedule = (delayMs: number): void => {
 		if (stopped) return;
+		// F8: a stall that delays this tick past the writer lease lets a peer
+		// replica acquire the flag while we believe we still hold it; measure it.
+		const expectedFireAt = Date.now() + delayMs;
 		timer = setTimeout(async () => {
 			if (stopped) return;
+			recordHeartbeatGap({ lock: "rw-writer", key: keys.writer, expectedFireAt, renewMs, leaseMs });
 			let outcome: "renewed" | "ownership_lost" | "transient";
 			let raceTimeout: ReturnType<typeof setTimeout> | undefined; // L1: clear on settle
 			try {

src/api/event-loop-monitor.ts

@@ -0,0 +1,182 @@
+/**
+ * F8: Event-loop lag observability (purely observational — no behavior change).
+ *
+ * The three Redis leases — the exec-lock writer lease (`distributed-lock.ts`),
+ * the RW-lock writer flag (`distributed-rw-lock.ts` exclusive heartbeat), and the
+ * RW-lock reader ZSET scores (shared heartbeat) — each keep themselves alive with
+ * a `setTimeout`-driven heartbeat that renews well before expiry (`renewMs` <
+ * `leaseMs`). They silently assume the timer fires roughly on schedule. A long
+ * event-loop stall (a V8 GC pause, a pathological synchronous bash stretch, or —
+ * only when `REDIS_PATH_SNAPSHOT_ENABLED=true` — the in-lock msgpack encode) fires
+ * the renewal late; by then Redis has already expired the key / reaped the ZSET
+ * entry, another replica can step in, and the next renew returns 0 →
+ * `LockLostError`. Lock 3 (PG advisory + per-tx serialization, see DEVELOPER.md)
+ * prevents any DB corruption, so this is an *observability* gap, not a correctness
+ * bug: nothing measured how close the process ran to the lease floor.
+ *
+ * This module measures it, two ways:
+ *  - {@link startEventLoopMonitor}/{@link stopEventLoopMonitor}: a
+ *    `perf_hooks.monitorEventLoopDelay` histogram, sampled on an interval and
+ *    logged as `event:"event_loop_lag"` (p50/p99/max ms), then reset each window.
+ *  - {@link recordHeartbeatGap}: called from each heartbeat callback with the time
+ *    the timer was *expected* to fire; emits `event:"heartbeat_gap"` at severity
+ *    `"warn"` (gap > renewMs — a full renewal interval late) or `"critical"`
+ *    (gap > leaseMs — the lease almost certainly lapsed). No-op below renewMs and
+ *    safe to call when the monitor was never started (unit tests / no-Redis runs).
+ */
+
+import { type IntervalHistogram, monitorEventLoopDelay } from "node:perf_hooks";
+
+const NS_PER_MS = 1_000_000;
+
+/** Default interval (ms) between event-loop-lag samples. Override via `EVENT_LOOP_MONITOR_INTERVAL_MS`. */
+export const DEFAULT_SAMPLE_INTERVAL_MS = 10_000;
+/** Default histogram resolution (ms) — how often perf_hooks records a delay reading. */
+export const DEFAULT_RESOLUTION_MS = 20;
+
+/** Which lease a heartbeat gap belongs to, for alert routing. */
+export type HeartbeatLockKind = "exec" | "rw-writer" | "rw-reader";
+
+/** Severity of a single heartbeat gap relative to the renew/lease windows. */
+export type HeartbeatGapSeverity = "ok" | "warn" | "critical";
+
+export interface EventLoopLagSnapshot {
+	readonly p50Ms: number;
+	readonly p99Ms: number;
+	readonly maxMs: number;
+	readonly meanMs: number;
+}
+
+export interface EventLoopMonitorOptions {
+	/** Sampling/log interval (ms). Each window is logged, then the histogram is reset. */
+	readonly sampleIntervalMs?: number;
+	/** perf_hooks histogram resolution (ms). */
+	readonly resolutionMs?: number;
+	/** Injectable log sink (defaults to `console.log`). Tests pass a collector. */
+	readonly log?: (line: string) => void;
+}
+
+interface MonitorState {
+	readonly histogram: IntervalHistogram;
+	readonly timer: ReturnType<typeof setInterval>;
+}
+
+let state: MonitorState | undefined;
+
+function toMs(ns: number): number {
+	// perf_hooks reports nanoseconds; round to whole ms for log readability.
+	return Math.round(ns / NS_PER_MS);
+}
+
+function readSnapshot(h: IntervalHistogram): EventLoopLagSnapshot {
+	return {
+		p50Ms: toMs(h.percentile(50)),
+		p99Ms: toMs(h.percentile(99)),
+		maxMs: toMs(h.max),
+		meanMs: toMs(h.mean),
+	};
+}
+
+/**
+ * Start the process-wide event-loop-delay monitor. Idempotent: a second call
+ * while already running is a no-op. The sampling timer is `unref()`'d so it never
+ * keeps the process alive past shutdown.
+ */
+export function startEventLoopMonitor(opts: EventLoopMonitorOptions = {}): void {
+	if (state !== undefined) return;
+	const sampleIntervalMs = opts.sampleIntervalMs ?? DEFAULT_SAMPLE_INTERVAL_MS;
+	const resolutionMs = opts.resolutionMs ?? DEFAULT_RESOLUTION_MS;
+	const log = opts.log ?? ((line: string): void => console.log(line));
+
+	const histogram = monitorEventLoopDelay({ resolution: resolutionMs });
+	histogram.enable();
+
+	const timer = setInterval(() => {
+		const snapshot = readSnapshot(histogram);
+		histogram.reset();
+		log(JSON.stringify({ event: "event_loop_lag", ...snapshot, windowMs: sampleIntervalMs }));
+	}, sampleIntervalMs);
+	if (typeof timer.unref === "function") timer.unref();
+
+	state = { histogram, timer };
+}
+
+/** Stop the monitor and disable the histogram. Idempotent. */
+export function stopEventLoopMonitor(): void {
+	if (state === undefined) return;
+	clearInterval(state.timer);
+	state.histogram.disable();
+	state = undefined;
+}
+
+/**
+ * Current event-loop-delay snapshot, or `undefined` when the monitor is not
+ * running. Reads the live histogram WITHOUT resetting it (the sampler owns the
+ * reset), so a health endpoint can poll it without perturbing the windowed log.
+ */
+export function eventLoopLagSnapshot(): EventLoopLagSnapshot | undefined {
+	if (state === undefined) return undefined;
+	return readSnapshot(state.histogram);
+}
+
+/**
+ * Classify a heartbeat gap. Pure — exported for direct unit testing.
+ *  - `gap > leaseMs`  → "critical" (the lease has almost certainly lapsed)
+ *  - `gap > renewMs`  → "warn"     (a full renewal interval late)
+ *  - otherwise        → "ok"       (within normal jitter)
+ */
+export function classifyHeartbeatGap(gapMs: number, renewMs: number, leaseMs: number): HeartbeatGapSeverity {
+	if (gapMs > leaseMs) return "critical";
+	if (gapMs > renewMs) return "warn";
+	return "ok";
+}
+
+export interface HeartbeatGapInput {
+	readonly lock: HeartbeatLockKind;
+	readonly key: string;
+	/** `Date.now()` value at which this heartbeat timer was scheduled to fire. */
+	readonly expectedFireAt: number;
+	readonly renewMs: number;
+	readonly leaseMs: number;
+	/** Observed fire time (ms). Defaults to `Date.now()`; injectable for tests. */
+	readonly nowMs?: number;
+	/** Injectable log sink. Defaults to `console.warn` (warn) / `console.error` (critical). */
+	readonly log?: (line: string) => void;
+}
+
+/**
+ * Record one heartbeat's actual-vs-expected fire gap. Emits an `event:
+ * "heartbeat_gap"` structured line at "warn" or "critical" severity; below the
+ * renew window it is a silent no-op (the common case — every healthy tick).
+ *
+ * Returns the classified severity so callers/tests can branch without re-deriving
+ * it. This function never throws and never depends on {@link startEventLoopMonitor}.
+ */
+export function recordHeartbeatGap(input: HeartbeatGapInput): HeartbeatGapSeverity {
+	const now = input.nowMs ?? Date.now();
+	const gapMs = now - input.expectedFireAt;
+	const severity = classifyHeartbeatGap(gapMs, input.renewMs, input.leaseMs);
+	if (severity === "ok") return "ok";
+	const line = JSON.stringify({
+		event: "heartbeat_gap",
+		severity,
+		lock: input.lock,
+		key: input.key,
+		gapMs,
+		renewMs: input.renewMs,
+		leaseMs: input.leaseMs,
+	});
+	if (input.log !== undefined) {
+		input.log(line);
+	} else if (severity === "critical") {
+		console.error(line);
+	} else {
+		console.warn(line);
+	}
+	return severity;
+}
+
+/** Test hook: force the monitor back to the not-started state. */
+export function resetEventLoopMonitorForTest(): void {
+	stopEventLoopMonitor();
+}

src/api/server.ts

@@ -17,6 +17,7 @@ import { RedisPathSnapshot } from "../sql-fs/redis-path-snapshot.js";
 import type { SandboxListEntry, SandboxMeta } from "../sql-fs/types.js";
 import { type AuthVariables, createAuthMiddleware, loadStaticMcpAuthConfig } from "./auth.js";
 import { clientSafeErrorMessage, mapFsErrorToStatus } from "./errors.js";
+import { DEFAULT_SAMPLE_INTERVAL_MS, startEventLoopMonitor, stopEventLoopMonitor } from "./event-loop-monitor.js";
 import { mcpOptionsResponse, withMcpCors } from "./mcp-cors.js";
 import { handleMcpRequest, shutdownMcp, startMcpSessionSweeper } from "./mcp/server.js";
 import { runMigrations } from "./migrations.js";
@@ -302,11 +303,19 @@ if (isMain) {
 		sessionManager.startReaper();
 		startMcpSessionSweeper();
 
+		// F8: process-wide event-loop-lag monitor. Purely observational — surfaces
+		// the GC-pause / sync-stall class that can silently void a Redis lease
+		// (see event-loop-monitor.ts). The sampling timer is unref()'d internally.
+		startEventLoopMonitor({
+			sampleIntervalMs: parsePositiveInt("EVENT_LOOP_MONITOR_INTERVAL_MS", DEFAULT_SAMPLE_INTERVAL_MS),
+		});
+
 		let shuttingDown = false;
 		const shutdown = (): void => {
 			if (shuttingDown) return;
 			shuttingDown = true;
 			console.log(JSON.stringify({ event: "shutdown_begin" }));
+			stopEventLoopMonitor();
 			// Force-exit guard so a hung Postgres or Redis cleanup cannot keep
 			// the process alive past the orchestrator's grace period.
 			const forceExit = setTimeout(() => {