diff --git a/.ai/contexts/subagent-observability.md b/.ai/contexts/subagent-observability.md index 4f8049c7..653e3e43 100644 --- a/.ai/contexts/subagent-observability.md +++ b/.ai/contexts/subagent-observability.md @@ -91,9 +91,17 @@ re-sees the entire history of the session**. `detectSubagentTransitions()` only rescans when the `subagents/` dir mtime moves — which is exactly what happens when a *new* subagent starts. Two rules keep that rescan quiet: -- **A first sighting is only a spawn if the file is fresh.** An unknown file - whose mtime is already older than `BOOTSTRAP_LIVE_MS` (60 s) is recorded - silently as `completed: true`, with no `readSubagentMeta()` and no IPC. +- **Bootstrap never announces anything.** Every file present at a session's + first scan is recorded silently as `completed: true`, whatever its mtime. + Switchboard owns the PTYs its subagents run in — one set per Electron + process — so they all died with the previous process, and a restored session + gets a brand-new PTY whose agents write *after* bootstrap and are picked up + by the normal path. Nothing on disk at that moment can be live. The silence + is unconditional; the *verdict* is not (next bullet). +- **After bootstrap, a first sighting is only a spawn if the file is fresh.** + An unknown file whose mtime is already older than `FRESH_SIGHTING_MS` (60 s) + is recorded silently as `completed: true`, with no `readSubagentMeta()` and + no IPC. - **That verdict is an assumption, and it is reversible.** A stale first sighting is *not* proof the agent finished. `detectSubagentTransitions()` runs only from `flushChanges()`, whose debounce (`main.js`) is shared across @@ -104,9 +112,17 @@ when a *new* subagent starts. Two rules keep that rescan quiet: it is rehabilitated** — `completed` returns to false and the withheld `subagent-spawned` is emitted (logged `[subagent-spawn-late]`). The window closes once the file has been seen motionless for a full `STABLE_MS`, after - which the entry is frozen and costs nothing. At bootstrap no window is - opened: the PTY belongs to Switchboard, so nothing it spawned can be - mid-flight before that session's first flush. + which the entry is frozen and costs nothing. **At bootstrap the window is + opened only for files whose mtime is fresh** — the handful that could + conceivably still be running. Everything older is frozen outright: a window + over the whole history would cost one `statSync` per historical file per + flush, exactly what the dir-mtime cache exists to avoid, and a file minutes + old cannot be the agent in question anyway. The narrow window is what keeps + the startup rule falsifiable: if the PTY-ownership argument above is ever + wrong (an orphaned process surviving a hard kill and still writing), the + agent is announced late instead of staying invisible for the whole session. + Silence at startup must not become a permanent blind spot — a visible late + spawn beats a silent disappearance. - **`knownSubagents` forgets an agent only when its file leaves the disk.** The earlier GC dropped completed entries after 5 minutes; because the file stayed, the next rescan rediscovered it as unknown and announced a spawn. That was the @@ -133,6 +149,16 @@ Guaranteed: a static historical file never produces a spawn (it does not move, so it never enters the rehabilitation branch), and an agent still writing is always picked up — late at worst, never lost. +Also guaranteed since 2026-08-22: **a restart is quiet**. Bootstrap used to +treat any file younger than 60 s as a live agent and emit a synthetic +`subagent-spawned` (`payload._bootstrap`). An agent that finished less than a +minute before the app was restarted therefore came back as a ghost — purple +activity glyph on the parent, green dot on the subagent group header — until +the 30 s stability window declared it complete. Observed 2026-08-22; the +synthetic bootstrap spawn is gone and `_bootstrap` is no longer emitted (the +renderer still tolerates the field). What replaced it is silence plus a +recheck window on recent files, not an irreversible verdict. + Not guaranteed: an agent that goes quiet for longer than `STABLE_MS` mid-run — a long tool call, say — can be declared finished while it is still alive. That is not new and not specific to the age filter: the 30 s stability window has diff --git a/docs/activity-trace.md b/docs/activity-trace.md index d6b7827a..de01fc2f 100644 --- a/docs/activity-trace.md +++ b/docs/activity-trace.md @@ -93,7 +93,7 @@ no `sent`. | `osc.progress` | Every OSC 9;4 progress level (except `4;0`) | `level`, `payload`, `was`, `decision` | | `osc.notify` | Every non-progress OSC 9 | `message`, `sent` | | `busy.emit` | A `cli-busy-state` event leaves main | `busy`, `via` (`osc0` / `osc9.4`), `sent` | -| `subagent.spawned` | `subagent-spawned` is sent | `agentId`, `kind` (`spawn` / `bootstrap` / `heartbeat`), `subagentType`, `ageMs`, `sent` | +| `subagent.spawned` | `subagent-spawned` is sent | `agentId`, `kind` (`spawn` / `heartbeat`), `subagentType`, `ageMs`, `sent` | | `subagent.assumed-finished` | An unknown transcript is recorded as already finished, **silently** — no IPC | `agentId`, `ageMs`, `bootstrap`, `recheck` | | `subagent.rehabilitated` | An assumed-finished entry grew inside its recheck window: the withheld spawn is released | `agentId`, `withheldForMs`, `subagentType`, `sent` | | `subagent.completed` | `subagent-completed` is sent | `agentId`, `stableForMs`, `reason`, `sent` | diff --git a/session-transitions.js b/session-transitions.js index 8bdaeb4c..246a9d25 100644 --- a/session-transitions.js +++ b/session-transitions.js @@ -71,8 +71,8 @@ function detectSubagentTransitions(sessionId, session, folderPath) { // First walk for this session: pre-populate knownSubagents with every // existing file silently so we don't flood the renderer with spawn/complete // events for agents that already finished before Switchboard started watching. - // Files modified in the last 60s get a normal lifecycle; older ones are - // recorded as already-completed without IPC. + // No file present at this point can belong to a live agent, whatever its + // mtime — see .ai/contexts/subagent-observability.md if (isBootstrap) { session.knownSubagents = new Map(); } @@ -80,7 +80,7 @@ function detectSubagentTransitions(sessionId, session, folderPath) { const mainWindow = getMainWindow(); const now = Date.now(); const STABLE_MS = 30000; // 30 seconds of no mtime advance → completed - const BOOTSTRAP_LIVE_MS = 60000; // file modified in last 60s = still alive at boot + const FRESH_SIGHTING_MS = 60000; // post-bootstrap: first sighting counts as live if newer than this // Re-emit subagent-spawned (idempotent on the renderer side — it just // refreshes the entry's last-seen timestamp) at most every HEARTBEAT_MS // while an agent's file keeps growing. Without this, the renderer's 60s @@ -114,12 +114,20 @@ function detectSubagentTransitions(sessionId, session, folderPath) { const mtimeMs = stat.mtimeMs; if (!known) { - // A stale file is assumed finished and recorded silently. At bootstrap - // that is certain; afterwards the sighting may simply be late, so the - // entry keeps a recheck window instead of being frozen. + // A file that cannot be live is recorded as finished, silently. At + // bootstrap that covers every file: Switchboard owns the PTYs, so + // nothing it spawned outlived the previous process. Afterwards only a + // stale mtime says so, and the sighting may simply be late. + // + // Either way the verdict stays reversible while the file could + // conceivably be alive — a recheck window rehabilitates it if it grows. + // Only a plainly historical file seen at bootstrap is frozen outright, + // which is what keeps startup free of a per-file statSync. // See .ai/contexts/subagent-observability.md - const looksAlive = (now - mtimeMs) < BOOTSTRAP_LIVE_MS; + const isFresh = (now - mtimeMs) < FRESH_SIGHTING_MS; + const looksAlive = !isBootstrap && isFresh; if (!looksAlive) { + const recheck = !isBootstrap || isFresh; session.knownSubagents.set(agentId, { mtimeMs, completed: true, @@ -127,14 +135,13 @@ function detectSubagentTransitions(sessionId, session, folderPath) { subagentType: null, description: null, _lastHeartbeatAt: now, - _recheckStart: isBootstrap ? null : now, + _recheckStart: recheck ? now : null, }); - if (TRACE) trace('subagent.assumed-finished', sessionId, { agentId, ageMs: now - mtimeMs, bootstrap: isBootstrap, recheck: !isBootstrap }); + if (TRACE) trace('subagent.assumed-finished', sessionId, { agentId, ageMs: now - mtimeMs, bootstrap: isBootstrap, recheck }); continue; } - // First sighting of a live file: a synthetic spawn at bootstrap - // (_bootstrap), a genuine one afterwards. + // First sighting of a live file — always post-bootstrap, so a genuine spawn. const meta = readSubagentMeta(filePath) || {}; session.knownSubagents.set(agentId, { mtimeMs, @@ -144,17 +151,15 @@ function detectSubagentTransitions(sessionId, session, folderPath) { description: meta.description || null, _lastHeartbeatAt: now, }); - log.info(`[subagent-spawn${isBootstrap ? '-bootstrap' : ''}] parent=${sessionId} agentId=${agentId} type=${meta.agentType || 'unknown'}`); - if (TRACE) trace('subagent.spawned', sessionId, { agentId, kind: isBootstrap ? 'bootstrap' : 'spawn', subagentType: meta.agentType || null, ageMs: now - mtimeMs, sent: !!(mainWindow && !mainWindow.isDestroyed()) }); + log.info(`[subagent-spawn] parent=${sessionId} agentId=${agentId} type=${meta.agentType || 'unknown'}`); + if (TRACE) trace('subagent.spawned', sessionId, { agentId, kind: 'spawn', subagentType: meta.agentType || null, ageMs: now - mtimeMs, sent: !!(mainWindow && !mainWindow.isDestroyed()) }); if (mainWindow && !mainWindow.isDestroyed()) { - const payload = { + mainWindow.webContents.send('subagent-spawned', { parentSessionId: sessionId, agentId, subagentType: meta.agentType || null, description: meta.description || null, - }; - if (isBootstrap) payload._bootstrap = true; - mainWindow.webContents.send('subagent-spawned', payload); + }); } } else if (known.completed) { // Inside the recheck window of an assumed-finished entry. A file that diff --git a/test/session-transitions.test.js b/test/session-transitions.test.js index 2413fffc..d8258c0a 100644 --- a/test/session-transitions.test.js +++ b/test/session-transitions.test.js @@ -56,33 +56,32 @@ function seedAgents(folder, sessionId, agents) { return subDir; } -test('bootstrap call with 5 pre-existing subagents: old agents silent, fresh agents get synthetic spawn', () => { - // Updated for Fix 2: looksAlive bootstrap files now emit subagent-spawned - // with _bootstrap:true so the renderer can track their lifecycle. Old - // agents (>60s) stay silent to avoid flooding on startup. +test('bootstrap is silent whatever the mtimes: every pre-existing file is recorded as finished', () => { + // Switchboard owns the PTYs it spawns subagents from. They all die with the + // process, so no file present at a session's first scan can belong to a live + // agent — however recently it was written. const events = setupModule(); const tmp = mkTmp(); try { const sessionId = 'parent-session'; - // 3 fresh (looksAlive) + 2 old (completed-at-boot) seedAgents(tmp, sessionId, [ - { id: 'a1', ageMs: 120_000 }, // 2 min old — silent - { id: 'a2', ageMs: 120_000 }, // 2 min old — silent - { id: 'a3', ageMs: 5_000 }, // fresh — gets synthetic spawn - { id: 'a4', ageMs: 5_000 }, // fresh — gets synthetic spawn - { id: 'a5', ageMs: 5_000 }, // fresh — gets synthetic spawn + { id: 'a1', ageMs: 120_000 }, + { id: 'a2', ageMs: 120_000 }, + { id: 'a3', ageMs: 5_000 }, + { id: 'a4', ageMs: 5_000 }, + { id: 'a5', ageMs: 0 }, ]); const session = {}; // knownSubagents undefined → bootstrap detectSubagentTransitions(sessionId, session, tmp); - assert.equal(events.length, 3, 'exactly 3 synthetic spawns for fresh bootstrap agents'); - for (const ev of events) { - assert.equal(ev.channel, 'subagent-spawned'); - assert.equal(ev.payload._bootstrap, true, 'bootstrap spawn must carry _bootstrap flag'); - } + assert.equal(events.length, 0, `bootstrap must emit nothing, got ${JSON.stringify(events)}`); assert.ok(session.knownSubagents instanceof Map); assert.equal(session.knownSubagents.size, 5); + for (const [agentId, entry] of session.knownSubagents) { + assert.equal(entry.completed, true, `${agentId} must be recorded as finished`); + assert.ok(entry._completedAt, `${agentId} must carry _completedAt`); + } } finally { cleanup(tmp); } @@ -108,26 +107,115 @@ test('bootstrap marks an old-mtime agent (>60s) as completed: true', () => { } }); -test('bootstrap marks a fresh-mtime agent as completed: false and emits synthetic spawn', () => { - // Fix 2: fresh bootstrap files now emit subagent-spawned with _bootstrap:true. +test('bootstrap marks a just-written agent as completed too, and stays silent', () => { + // The ghost this fixes: an agent that finished seconds before the app was + // restarted used to be announced as a live spawn, lighting the parent's + // activity glyph for a full STABLE_MS. const events = setupModule(); const tmp = mkTmp(); try { const sessionId = 'parent'; - seedAgents(tmp, sessionId, [{ id: 'fresh', ageMs: 5_000 }]); // 5s old, well under 60s + seedAgents(tmp, sessionId, [{ id: 'fresh' }]); // mtime = now const session = {}; detectSubagentTransitions(sessionId, session, tmp); - assert.equal(events.length, 1, 'bootstrap emits exactly 1 synthetic spawn for fresh agent'); - assert.equal(events[0].channel, 'subagent-spawned'); - assert.equal(events[0].payload._bootstrap, true); - assert.equal(events[0].payload.agentId, 'fresh'); + assert.equal(events.length, 0, 'a just-written file at bootstrap must not emit a spawn'); const entry = session.knownSubagents.get('fresh'); assert.ok(entry); - assert.equal(entry.completed, false); - assert.equal(entry._completedAt, null); + assert.equal(entry.completed, true); + assert.ok(entry._completedAt, 'expected _completedAt to be stamped'); + } finally { + cleanup(tmp); + } +}); + +test('bootstrap opens no recheck window for history files, but keeps one for recent ones', () => { + // A window over the whole history would mean one statSync per file per + // flush, which the dir-mtime cache exists to avoid — and a file minutes old + // cannot be the live agent anyway. A recent file is the only one that could + // conceivably still be running, so it stays reversible: silent now, but + // rehabilitated if it grows. Freezing it would trade a visible ghost for an + // agent invisible for the whole session. + const events = setupModule(); + const tmp = mkTmp(); + try { + const sessionId = 'parent'; + seedAgents(tmp, sessionId, [{ id: 'history', ageMs: 300_000 }, { id: 'recent' }]); + + const session = {}; + detectSubagentTransitions(sessionId, session, tmp); + + assert.equal(events.length, 0, 'bootstrap stays silent either way'); + assert.equal(session.knownSubagents.get('history')._recheckStart, null, + 'a plainly historical file is frozen outright'); + assert.ok(session.knownSubagents.get('recent')._recheckStart, + 'a recent file keeps a recheck window'); + } finally { + cleanup(tmp); + } +}); + +test('bootstrap is reversible: a recent file that then grows is a live agent after all', (t) => { + // The whole fix rests on "Switchboard owns the PTYs, so nothing survives a + // restart". If that ever fails — an orphaned process still writing, say — + // the agent must not vanish for the session. It is silent until it proves + // itself, then announced. + const events = setupModule(); + const tmp = mkTmp(); + try { + const sessionId = 'parent'; + const subDir = seedAgents(tmp, sessionId, [{ id: 'survivor' }]); + const filePath = path.join(subDir, 'agent-survivor.jsonl'); + t.mock.timers.enable({ apis: ['Date'], now: Date.now() }); + + const session = {}; + detectSubagentTransitions(sessionId, session, tmp); + assert.equal(events.length, 0, 'nothing announced at bootstrap'); + assert.equal(session.knownSubagents.get('survivor').completed, true, 'assumed finished for now'); + + // It is still writing. + t.mock.timers.tick(1_000); + setMtime(filePath, Date.now()); + detectSubagentTransitions(sessionId, session, tmp); + + const spawns = events.filter(e => e.channel === 'subagent-spawned'); + assert.equal(spawns.length, 1, `growth must produce exactly one spawn, got ${spawns.length}`); + assert.equal(spawns[0].payload.agentId, 'survivor'); + assert.ok(!spawns[0].payload._heartbeat, 'it is a spawn, not a heartbeat'); + assert.equal(session.knownSubagents.get('survivor').completed, false, 'the assumption is undone'); + + // And from there the normal lifecycle applies. + detectSubagentTransitions(sessionId, session, tmp); + t.mock.timers.tick(31_000); + detectSubagentTransitions(sessionId, session, tmp); + assert.equal(events.filter(e => e.channel === 'subagent-completed').length, 1); + } finally { + t.mock.timers.reset(); + cleanup(tmp); + } +}); + +test('bootstrap window closes: a recent file that never moves is never announced', (t) => { + // The ghost stays fixed: silence at bootstrap, and silence for good once the + // window has elapsed without the file moving. + const events = setupModule(); + const tmp = mkTmp(); + try { + const sessionId = 'parent'; + seedAgents(tmp, sessionId, [{ id: 'justfinished' }]); + t.mock.timers.enable({ apis: ['Date'], now: Date.now() }); + + const session = {}; + detectSubagentTransitions(sessionId, session, tmp); + detectSubagentTransitions(sessionId, session, tmp); + t.mock.timers.tick(31_000); + detectSubagentTransitions(sessionId, session, tmp); + + assert.equal(events.length, 0, 'a finished agent seen at startup is never announced'); + assert.ok(!session.knownSubagents.get('justfinished')._recheckStart, 'window closed'); } finally { + t.mock.timers.reset(); cleanup(tmp); } }); @@ -159,7 +247,6 @@ test('post-bootstrap: a brand-new agent file emits exactly one subagent-spawned }); test('post-bootstrap with no new agents emits no additional events (IPC-flood regression)', () => { - // Fix 2: bootstrap for fresh (ageMs:0) agents now emits synthetic spawns. // The regression guard is that *subsequent* flushes with no new files must // not re-emit — the event count must not increase after the first call. const events = setupModule(); @@ -175,7 +262,7 @@ test('post-bootstrap with no new agents emits no additional events (IPC-flood re ]); const session = {}; - // Bootstrap absorbs all three silently (all old → no synthetic spawns) + // Bootstrap absorbs all three silently detectSubagentTransitions(sessionId, session, tmp); assert.equal(events.length, 0, 'old-agent bootstrap must be silent'); @@ -195,26 +282,28 @@ test('completion: agent with stable mtime for >30s emits subagent-completed (dri const tmp = mkTmp(); try { const sessionId = 'parent'; - // Create the agent file aged >60s so bootstrap records it as not-yet-completed - // (i.e. looksAlive=false path is too old — we want an agent that is first spotted - // post-bootstrap so its full lifecycle plays out). - // Seed with ageMs=0 so looksAlive=true; bootstrap will emit synthetic spawn. - const subDir = seedAgents(tmp, sessionId, [{ id: 'slow', ageMs: 0 }]); + const subDir = path.join(tmp, sessionId, 'subagents'); + fs.mkdirSync(subDir, { recursive: true }); const filePath = path.join(subDir, 'agent-slow.jsonl'); - // Call 1: bootstrap — knownSubagents is created, synthetic spawn emitted, - // agent entry stored with completed:false and no _stableStart yet. const session = {}; // Enable fake Date with now=realNow so _stableStart gets a non-zero truthy value // (the stability timer check uses !known._stableStart which would be truthy for 0/epoch). t.mock.timers.enable({ apis: ['Date'], now: Date.now() }); + // Call 1: bootstrap on an empty dir. A live entry can only be created + // afterwards — bootstrap never announces a spawn. + detectSubagentTransitions(sessionId, session, tmp); + + // Call 2: the agent starts, and is announced. + seedAgents(tmp, sessionId, [{ id: 'slow' }]); + setMtime(filePath, Date.now()); + setMtime(subDir, Date.now()); detectSubagentTransitions(sessionId, session, tmp); - // Bootstrap emits one synthetic spawn for this fresh agent assert.equal(events.filter(e => e.channel === 'subagent-spawned').length, 1); assert.equal(session.knownSubagents.get('slow').completed, false); - // Call 2: mtime unchanged from call 1 → _stableStart is set to "now" + // Call 3: mtime unchanged from the spawn → _stableStart is set to "now" detectSubagentTransitions(sessionId, session, tmp); assert.equal(session.knownSubagents.get('slow').completed, false); @@ -248,8 +337,23 @@ test('heartbeat: a subagent whose file keeps growing re-emits subagent-spawned ( const tmp = mkTmp(); try { const sessionId = 'parent'; - const subDir = seedAgents(tmp, sessionId, [{ id: 'longrun', ageMs: 0 }]); + const subDir = path.join(tmp, sessionId, 'subagents'); + fs.mkdirSync(subDir, { recursive: true }); const filePath = path.join(subDir, 'agent-longrun.jsonl'); + const heartbeats = () => events.filter(e => e.channel === 'subagent-spawned' && e.payload._heartbeat); + + t.mock.timers.enable({ apis: ['Date'], now: Date.now() }); + + // Bootstrap on an empty dir, then the agent starts: spawn, and the + // heartbeat clock starts with it. + const session = {}; + detectSubagentTransitions(sessionId, session, tmp); + seedAgents(tmp, sessionId, [{ id: 'longrun' }]); + setMtime(subDir, Date.now()); + detectSubagentTransitions(sessionId, session, tmp); + assert.equal(events.filter(e => e.channel === 'subagent-spawned').length, 1, 'one real spawn'); + assert.equal(heartbeats().length, 0, 'no heartbeat at spawn'); + const realBaseMs = fs.statSync(filePath).mtimeMs; let bump = 0; const bumpMtime = () => { @@ -257,14 +361,6 @@ test('heartbeat: a subagent whose file keeps growing re-emits subagent-spawned ( const d = new Date(realBaseMs + bump * 2000); fs.utimesSync(filePath, d, d); }; - const heartbeats = () => events.filter(e => e.channel === 'subagent-spawned' && e.payload._heartbeat); - - t.mock.timers.enable({ apis: ['Date'], now: Date.now() }); - - // Call 1: bootstrap — synthetic spawn, heartbeat clock starts. - const session = {}; - detectSubagentTransitions(sessionId, session, tmp); - assert.equal(heartbeats().length, 0, 'no heartbeat at bootstrap'); // 25s later the file has grown → past the 20s throttle → heartbeat. t.mock.timers.tick(25_000); @@ -356,9 +452,8 @@ test('concurrent monitoring: detectSubagentTransitions for 2 distinct sessions e const bHasNewWorker = spawnedForB.some(e => e.payload.agentId === 'a-worker-new'); assert.ok(!bHasNewWorker, 'sessB must not receive spawn events for sessA agents'); - // Fresh workers from bootstrap emit with _bootstrap:true; the new post-bootstrap - // agent for sessA must NOT carry _bootstrap:true - assert.ok(!newWorkerEvent.payload._bootstrap, 'post-bootstrap spawn must not carry _bootstrap flag'); + // Bootstrap announces nothing, so every spawn recorded here is a real one. + assert.ok(!newWorkerEvent.payload._bootstrap, 'no spawn carries a _bootstrap flag any more'); } finally { cleanup(tmp); } @@ -435,7 +530,7 @@ test('post-GC volume: 30 historical agent files plus 1 new one emit exactly one const subDir = seedAgents(tmp, sessionId, olds); t.mock.timers.enable({ apis: ['Date'], now: Date.now() }); - // Bootstrap absorbs all 30 silently (all older than BOOTSTRAP_LIVE_MS). + // Bootstrap absorbs all 30 silently (all older than FRESH_SIGHTING_MS). const session = {}; detectSubagentTransitions(sessionId, session, tmp); assert.equal(events.length, 0, 'bootstrap of old files must be silent'); @@ -488,7 +583,7 @@ test('post-bootstrap: an unknown file with an old mtime is recorded as finished, test('late sighting: a stale file that then grows is a live agent — the withheld spawn is emitted', (t) => { // detectSubagentTransitions only runs from flushChanges, whose debounce is // shared across PROJECTS_DIR and has no maxWait: a burst of parallel - // subagent writes can push the first flush past BOOTSTRAP_LIVE_MS. The age + // subagent writes can push the first flush past FRESH_SIGHTING_MS. The age // filter must be reversible, or a genuinely live agent discovered late would // be silently written off for the rest of the session. const events = setupModule();