Spaces:
Running
watchdog: off-thread event-loop stall detector
Browse filesIncidents where the main thread wedged on synchronous work (the FUSE/SQLite
class of bug) left no diagnostic trail: in-process HTTP dies with the loop, and
main-thread timers can't fire to log anything until/unless it recovers — which
it sometimes never does. The run logs just went silent.
Add a worker thread with its OWN event loop that watches a heartbeat the main
thread stamps into shared memory. When the heartbeat goes stale it logs the
stall to stderr (→ the Space's run logs) in real time: how long, what the main
thread was doing (a breadcrumb set at each build phase), and process RSS (read
from the worker, so it's available even while main is frozen). A 30s baseline
"ok" line means a gap in the logs is itself the alarm.
Breadcrumbs (mark/tracked, save+restore so they nest) wrap the trace build, the
opencode/hermes SQLite reads, and the usage build — the known-heavy paths.
Fail-safe: worker is unref'd and error-swallowing, mark() is a no-op if the
worker never started, and AM_NO_WATCHDOG=1 disables it.
Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
- server/src/index.js +5 -0
- server/src/traces.js +15 -3
- server/src/usage.js +6 -1
- server/src/watchdog-worker.js +51 -0
- server/src/watchdog.js +68 -0
|
@@ -19,6 +19,7 @@ import { buildUsage } from './usage.js';
|
|
| 19 |
import { buildTraces, traceDigests, digestFor } from './traces.js';
|
| 20 |
import { initPush, publicKey, deviceCount, addSubscription, removeSubscription, sendToAll } from './push.js';
|
| 21 |
import { startVisibilityWatch, isPublic, visibility } from './visibility.js';
|
|
|
|
| 22 |
|
| 23 |
ensureDirs();
|
| 24 |
refreshVersions();
|
|
@@ -1106,6 +1107,10 @@ generateEnvSkill(loadSecretNotes()); // keep the environment skill current on bo
|
|
| 1106 |
// (skeletons + stale-while-revalidate), so nothing is lost but the boot risk.
|
| 1107 |
setTimeout(() => { traceDigests().catch(() => {}); }, 4000);
|
| 1108 |
|
|
|
|
|
|
|
|
|
|
|
|
|
| 1109 |
server.listen(PORT, () => {
|
| 1110 |
console.log(`Agent Manager :${PORT} tmux=${USE_TMUX} data=${DATA_DIR}`);
|
| 1111 |
console.log('⚠ No authentication: this app trusts whoever can reach it.');
|
|
|
|
| 19 |
import { buildTraces, traceDigests, digestFor } from './traces.js';
|
| 20 |
import { initPush, publicKey, deviceCount, addSubscription, removeSubscription, sendToAll } from './push.js';
|
| 21 |
import { startVisibilityWatch, isPublic, visibility } from './visibility.js';
|
| 22 |
+
import { startWatchdog } from './watchdog.js';
|
| 23 |
|
| 24 |
ensureDirs();
|
| 25 |
refreshVersions();
|
|
|
|
| 1107 |
// (skeletons + stale-while-revalidate), so nothing is lost but the boot risk.
|
| 1108 |
setTimeout(() => { traceDigests().catch(() => {}); }, 4000);
|
| 1109 |
|
| 1110 |
+
// Off-thread stall detector — must start early so it's watching before the
|
| 1111 |
+
// first heavy build. Logs any event-loop wedge to the run logs (see watchdog.js).
|
| 1112 |
+
startWatchdog();
|
| 1113 |
+
|
| 1114 |
server.listen(PORT, () => {
|
| 1115 |
console.log(`Agent Manager :${PORT} tmux=${USE_TMUX} data=${DATA_DIR}`);
|
| 1116 |
console.log('⚠ No authentication: this app trusts whoever can reach it.');
|
|
@@ -3,6 +3,7 @@ import fsp from 'node:fs/promises';
|
|
| 3 |
import path from 'node:path';
|
| 4 |
import * as store from './sessions.js';
|
| 5 |
import { WORKSPACES_DIR } from './config.js';
|
|
|
|
| 6 |
|
| 7 |
// Workspace-wide trace analytics: parse every Claude transcript and Codex
|
| 8 |
// rollout on the Space into per-conversation stats (turns, tool calls, web
|
|
@@ -343,7 +344,10 @@ function readOpencode() {
|
|
| 343 |
if (ocMemo.key && Date.now() - ck.hotMs < 8_000) return ocMemo.rows;
|
| 344 |
const key = ck.key;
|
| 345 |
let db;
|
| 346 |
-
|
|
|
|
|
|
|
|
|
|
| 347 |
const rows = [];
|
| 348 |
try {
|
| 349 |
const sessions = db.prepare('select * from session').all();
|
|
@@ -399,6 +403,7 @@ function readOpencode() {
|
|
| 399 |
}
|
| 400 |
} catch { /* torn read / schema drift: keep previous */ } finally {
|
| 401 |
try { db.close(); } catch {}
|
|
|
|
| 402 |
}
|
| 403 |
ocMemo = { key, rows };
|
| 404 |
return rows;
|
|
@@ -436,7 +441,8 @@ function readHermes() {
|
|
| 436 |
if (hermesMemo.key === ck.key) return hermesMemo.rows;
|
| 437 |
if (hermesMemo.key && Date.now() - ck.hotMs < 8_000) return hermesMemo.rows;
|
| 438 |
let db;
|
| 439 |
-
|
|
|
|
| 440 |
const rows = [];
|
| 441 |
try {
|
| 442 |
const sessions = db.prepare('select * from sessions').all();
|
|
@@ -492,6 +498,7 @@ function readHermes() {
|
|
| 492 |
}
|
| 493 |
} catch { /* torn read / schema drift: keep previous */ } finally {
|
| 494 |
try { db.close(); } catch {}
|
|
|
|
| 495 |
}
|
| 496 |
hermesMemo = { key: ck.key, rows };
|
| 497 |
return rows;
|
|
@@ -599,7 +606,12 @@ async function codexFilesUncached() {
|
|
| 599 |
|
| 600 |
const UUID_RE = /([0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12})(?:\.jsonl)?$/;
|
| 601 |
|
| 602 |
-
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
| 603 |
const sessions = store.list();
|
| 604 |
const byClaudeUuid = new Map(sessions.filter((s) => s.cli === 'claude' && s.sessionUuid).map((s) => [s.sessionUuid, s]));
|
| 605 |
const byCodexId = new Map(sessions.filter((s) => s.codexSessionId).map((s) => [s.codexSessionId, s]));
|
|
|
|
| 3 |
import path from 'node:path';
|
| 4 |
import * as store from './sessions.js';
|
| 5 |
import { WORKSPACES_DIR } from './config.js';
|
| 6 |
+
import { mark, tracked, PHASE } from './watchdog.js';
|
| 7 |
|
| 8 |
// Workspace-wide trace analytics: parse every Claude transcript and Codex
|
| 9 |
// rollout on the Space into per-conversation stats (turns, tool calls, web
|
|
|
|
| 344 |
if (ocMemo.key && Date.now() - ck.hotMs < 8_000) return ocMemo.rows;
|
| 345 |
const key = ck.key;
|
| 346 |
let db;
|
| 347 |
+
// Synchronous DB read — the historically wedge-prone spot. Breadcrumb it so a
|
| 348 |
+
// stall while it runs is attributed (see watchdog.js).
|
| 349 |
+
const ocPhase = mark(PHASE.readOpencode);
|
| 350 |
+
try { db = new DatabaseSync(p, { readOnly: true }); } catch { mark(ocPhase); return ocMemo.rows; }
|
| 351 |
const rows = [];
|
| 352 |
try {
|
| 353 |
const sessions = db.prepare('select * from session').all();
|
|
|
|
| 403 |
}
|
| 404 |
} catch { /* torn read / schema drift: keep previous */ } finally {
|
| 405 |
try { db.close(); } catch {}
|
| 406 |
+
mark(ocPhase);
|
| 407 |
}
|
| 408 |
ocMemo = { key, rows };
|
| 409 |
return rows;
|
|
|
|
| 441 |
if (hermesMemo.key === ck.key) return hermesMemo.rows;
|
| 442 |
if (hermesMemo.key && Date.now() - ck.hotMs < 8_000) return hermesMemo.rows;
|
| 443 |
let db;
|
| 444 |
+
const hermesPhase = mark(PHASE.readHermes);
|
| 445 |
+
try { db = new DatabaseSync(p, { readOnly: true }); } catch { mark(hermesPhase); return hermesMemo.rows; }
|
| 446 |
const rows = [];
|
| 447 |
try {
|
| 448 |
const sessions = db.prepare('select * from sessions').all();
|
|
|
|
| 498 |
}
|
| 499 |
} catch { /* torn read / schema drift: keep previous */ } finally {
|
| 500 |
try { db.close(); } catch {}
|
| 501 |
+
mark(hermesPhase);
|
| 502 |
}
|
| 503 |
hermesMemo = { key: ck.key, rows };
|
| 504 |
return rows;
|
|
|
|
| 606 |
|
| 607 |
const UUID_RE = /([0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12})(?:\.jsonl)?$/;
|
| 608 |
|
| 609 |
+
// Breadcrumb the whole build so a wedge anywhere in it is attributed to
|
| 610 |
+
// 'buildTraces' (the db reads narrow it further to their own phase). tracked()
|
| 611 |
+
// restores the prior breadcrumb even if the build throws.
|
| 612 |
+
function build() { return tracked(PHASE.buildTraces, buildImpl); }
|
| 613 |
+
|
| 614 |
+
async function buildImpl() {
|
| 615 |
const sessions = store.list();
|
| 616 |
const byClaudeUuid = new Map(sessions.filter((s) => s.cli === 'claude' && s.sessionUuid).map((s) => [s.sessionUuid, s]));
|
| 617 |
const byCodexId = new Map(sessions.filter((s) => s.codexSessionId).map((s) => [s.codexSessionId, s]));
|
|
@@ -3,6 +3,7 @@ import fsp from 'node:fs/promises';
|
|
| 3 |
import path from 'node:path';
|
| 4 |
import { execFile as execFileCb } from 'node:child_process';
|
| 5 |
import { promisify } from 'node:util';
|
|
|
|
| 6 |
|
| 7 |
const execFile = promisify(execFileCb);
|
| 8 |
|
|
@@ -239,7 +240,11 @@ async function debugInfo() {
|
|
| 239 |
};
|
| 240 |
}
|
| 241 |
|
| 242 |
-
export
|
|
|
|
|
|
|
|
|
|
|
|
|
| 243 |
// `only` narrows to one provider so the Usage page can fetch each in
|
| 244 |
// parallel and render whichever answers first — one slow/hung provider
|
| 245 |
// (ccusage has a 20s timeout) no longer blocks the rest.
|
|
|
|
| 3 |
import path from 'node:path';
|
| 4 |
import { execFile as execFileCb } from 'node:child_process';
|
| 5 |
import { promisify } from 'node:util';
|
| 6 |
+
import { tracked, PHASE } from './watchdog.js';
|
| 7 |
|
| 8 |
const execFile = promisify(execFileCb);
|
| 9 |
|
|
|
|
| 240 |
};
|
| 241 |
}
|
| 242 |
|
| 243 |
+
export function buildUsage(debug = false, only = null) {
|
| 244 |
+
return tracked(PHASE.buildUsage, () => buildUsageImpl(debug, only));
|
| 245 |
+
}
|
| 246 |
+
|
| 247 |
+
async function buildUsageImpl(debug = false, only = null) {
|
| 248 |
// `only` narrows to one provider so the Usage page can fetch each in
|
| 249 |
// parallel and render whichever answers first — one slow/hung provider
|
| 250 |
// (ccusage has a 20s timeout) no longer blocks the rest.
|
|
@@ -0,0 +1,51 @@
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
| 1 |
+
import { workerData } from 'node:worker_threads';
|
| 2 |
+
|
| 3 |
+
// Runs on its own event loop, so it keeps ticking while the MAIN thread is
|
| 4 |
+
// blocked. Reads the heartbeat + phase the main thread writes to shared memory
|
| 5 |
+
// and logs to stderr — the one channel that survives a wedge (the Space's run
|
| 6 |
+
// logs). See watchdog.js for the contract.
|
| 7 |
+
|
| 8 |
+
const { sab, beatMs, stallMs, phases } = workerData;
|
| 9 |
+
const hb = new BigInt64Array(sab, 0, 1);
|
| 10 |
+
const meta = new Int32Array(sab, 8, 2);
|
| 11 |
+
|
| 12 |
+
const mb = (b) => Math.round(b / 1048576);
|
| 13 |
+
const phaseName = (c) => phases[c] || `#${c}`;
|
| 14 |
+
const now = () => Date.now();
|
| 15 |
+
|
| 16 |
+
let stalling = false;
|
| 17 |
+
let stallStart = 0;
|
| 18 |
+
let lastStallLog = 0;
|
| 19 |
+
let maxLag = 0;
|
| 20 |
+
let lastOk = now();
|
| 21 |
+
|
| 22 |
+
setInterval(() => {
|
| 23 |
+
const t = now();
|
| 24 |
+
const last = Number(Atomics.load(hb, 0));
|
| 25 |
+
const age = t - last;
|
| 26 |
+
if (age > maxLag) maxLag = age;
|
| 27 |
+
|
| 28 |
+
if (age > stallMs) {
|
| 29 |
+
// Loop is stuck. Log on onset, then at most every 10s while it stays stuck,
|
| 30 |
+
// so a long wedge leaves a trail without flooding.
|
| 31 |
+
if (!stalling) { stalling = true; stallStart = last; lastStallLog = 0; }
|
| 32 |
+
if (lastStallLog === 0 || t - lastStallLog >= 10000) {
|
| 33 |
+
lastStallLog = t;
|
| 34 |
+
console.error(`[watchdog] main loop STALLED ${Math.round(age / 1000)}s`
|
| 35 |
+
+ ` — activity=${phaseName(Atomics.load(meta, 0))} rss=${mb(process.memoryUsage().rss)}MB`);
|
| 36 |
+
}
|
| 37 |
+
return;
|
| 38 |
+
}
|
| 39 |
+
|
| 40 |
+
if (stalling) {
|
| 41 |
+
stalling = false;
|
| 42 |
+
console.error(`[watchdog] main loop recovered after ~${Math.round((t - stallStart) / 1000)}s`);
|
| 43 |
+
}
|
| 44 |
+
// Baseline heartbeat every 30s: a steady "ok" line means alive; a GAP in
|
| 45 |
+
// these lines is itself the alarm, and rss/maxLag give a cheap trend.
|
| 46 |
+
if (t - lastOk >= 30000) {
|
| 47 |
+
lastOk = t;
|
| 48 |
+
console.error(`[watchdog] ok rss=${mb(process.memoryUsage().rss)}MB maxLag=${maxLag}ms`);
|
| 49 |
+
maxLag = 0;
|
| 50 |
+
}
|
| 51 |
+
}, beatMs);
|
|
@@ -0,0 +1,68 @@
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
|
| 1 |
+
import { Worker } from 'node:worker_threads';
|
| 2 |
+
|
| 3 |
+
// Observability that survives a BLOCKED event loop. When the main thread wedges
|
| 4 |
+
// on synchronous work (the FUSE/SQLite class of bug), in-process HTTP dies and
|
| 5 |
+
// main-thread timers can't fire — so nothing gets logged until/unless the loop
|
| 6 |
+
// recovers, and it may never. A worker thread has its OWN event loop and keeps
|
| 7 |
+
// watching regardless: it reports the stall to stderr (→ the Space's run logs)
|
| 8 |
+
// in real time, with the last activity breadcrumb and current RSS, so an
|
| 9 |
+
// incident is a labelled event instead of a sudden silence.
|
| 10 |
+
//
|
| 11 |
+
// Mechanism: the main thread stamps the time into a SharedArrayBuffer every
|
| 12 |
+
// beat and records a small integer "current activity" code; the worker reads
|
| 13 |
+
// both and, when the stamp goes stale, reports how long the loop has been
|
| 14 |
+
// unresponsive, what it was doing, and process memory (RSS is process-wide, so
|
| 15 |
+
// the worker can read it even while the main thread is frozen).
|
| 16 |
+
|
| 17 |
+
// Activity breadcrumbs. The worker maps code → name (order defines the code).
|
| 18 |
+
export const PHASE = {
|
| 19 |
+
idle: 0,
|
| 20 |
+
buildTraces: 1,
|
| 21 |
+
readOpencode: 2,
|
| 22 |
+
readHermes: 3,
|
| 23 |
+
buildUsage: 4,
|
| 24 |
+
};
|
| 25 |
+
const PHASE_NAMES = Object.keys(PHASE);
|
| 26 |
+
|
| 27 |
+
const BEAT_MS = 1000;
|
| 28 |
+
const STALL_MS = 5000; // report once the loop has missed ~5 beats
|
| 29 |
+
|
| 30 |
+
let shared = null; // { hb: BigInt64Array, meta: Int32Array }
|
| 31 |
+
let worker = null;
|
| 32 |
+
|
| 33 |
+
export function startWatchdog() {
|
| 34 |
+
if (worker || process.env.AM_NO_WATCHDOG) return;
|
| 35 |
+
// BigInt64 for the heartbeat (Atomics needs an integer view; ms-since-epoch
|
| 36 |
+
// overflows Int32), Int32 for the phase code — 8-byte aligned so both are
|
| 37 |
+
// valid Atomics targets.
|
| 38 |
+
const sab = new SharedArrayBuffer(16);
|
| 39 |
+
const hb = new BigInt64Array(sab, 0, 1);
|
| 40 |
+
const meta = new Int32Array(sab, 8, 2);
|
| 41 |
+
Atomics.store(hb, 0, BigInt(Date.now()));
|
| 42 |
+
shared = { hb, meta };
|
| 43 |
+
const beat = setInterval(() => Atomics.store(hb, 0, BigInt(Date.now())), BEAT_MS);
|
| 44 |
+
if (beat.unref) beat.unref();
|
| 45 |
+
try {
|
| 46 |
+
worker = new Worker(new URL('./watchdog-worker.js', import.meta.url), {
|
| 47 |
+
workerData: { sab, beatMs: BEAT_MS, stallMs: STALL_MS, phases: PHASE_NAMES },
|
| 48 |
+
});
|
| 49 |
+
worker.unref();
|
| 50 |
+
worker.on('error', () => {}); // the watchdog must never take down the app
|
| 51 |
+
} catch { worker = null; }
|
| 52 |
+
}
|
| 53 |
+
|
| 54 |
+
// Cheap breadcrumb: record what the main thread is about to do, so a stall
|
| 55 |
+
// report can name the culprit. Returns the PREVIOUS code so callers can restore
|
| 56 |
+
// it — breadcrumbs then nest correctly (a build that dips into a db read shows
|
| 57 |
+
// the read while it runs, the build again after). A safe no-op (returns idle)
|
| 58 |
+
// before startWatchdog() runs.
|
| 59 |
+
export function mark(code) {
|
| 60 |
+
return shared ? Atomics.exchange(shared.meta, 0, code | 0) : PHASE.idle;
|
| 61 |
+
}
|
| 62 |
+
|
| 63 |
+
// Run fn under a breadcrumb, restoring the previous one even on throw. Works for
|
| 64 |
+
// sync or async fn; the breadcrumb is what the worker reports if fn wedges.
|
| 65 |
+
export async function tracked(code, fn) {
|
| 66 |
+
const prev = mark(code);
|
| 67 |
+
try { return await fn(); } finally { mark(prev); }
|
| 68 |
+
}
|