From a6783acfdb175bf7c340dff91cde83dc0f0151da Mon Sep 17 00:00:00 2001 From: Jean-Baptiste Date: Mon, 24 Aug 2026 00:12:38 +0200 Subject: [PATCH] fix(subagent): give the liveness signal a clock and make completion reversible MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit detectSubagentTransitions() owns spawn, heartbeat and completion, but it only ran from the projects watcher's debounced flush. A function that runs when a file changes cannot see that a file stopped changing: agent a9be19fb0a7e0e504 last wrote at 23:42:18 and its completion was logged at 23:52:55 — 10 min 37 s for a 30 s stability window — because the folder went quiet and no flush ran. The same window also fires wrongly. Agents a8e8c25f42a65b026 and a19dcbbb23270de85 were declared complete at 23:56:53 and 00:00:27 while still writing minutes later: a tool call longer than the window reads as a finished agent. That verdict was irreversible — the entry carried no recheck window, so it hit the completed fast path forever and the agent could never light up again. A stability completion now keeps a recheck window, so renewed growth rehabilitates it and re-emits the spawn. That is what makes the tick safe: adding a clock makes false completions more frequent, not less. Rather than let such an agent oscillate, its stability window widens on each rehabilitation along a capped ladder (30 s, 2 min, MAX_STABLE_MS) so it converges. An assumed-finished entry is deliberately excluded: it carries no evidence of long silences, and widening it would slow the normal case. Widening needs one companion change. A wider window lets an agent stay silent past the renderer's TTL without completing, and the renderer refuses a heartbeat for an agent it no longer tracks — on its own the widening would trade a blink for a permanent blackout. The growth branch therefore emits a real spawn instead of a heartbeat once the agent has been unseen that long. That agreement between the main process and the two views was three separate 60000 literals held together by a comment; shortening one alone silently recreates the blackout. public/subagent-timing.js is now the single definition, using the dual-mode pattern of public/shortcuts.js: classic script for the renderer, module.exports for require(). Both renderer safety nets had the same shape of bug — pruneStaleGridSubagents() ran only from wrapInGridCard() and pruneStaleSubagents() only from renderProjects(), so a stale entry survived exactly in the idle case the TTL exists to cover. Each view now arms a one-shot timer at the oldest entry's deadline, refreshes only the entries the prune removed, and stops when its map is empty (ADR 0002: no steady-state cost). Not changed: the watcher debounce has no maxWait, but the log shows completions emitted while three transcripts were being written, so starvation under write load is refuted and nothing was added for it. --- .ai/contexts/subagent-observability.md | 169 +++++- eslint.config.js | 23 + public/grid-view.js | 30 +- public/index.html | 1 + public/sidebar.js | 30 +- public/subagent-timing.js | 9 + session-transitions.js | 65 ++- test/dom-grid-sidebar-prune-collision.test.js | 2 +- test/dom-grid-subagent-pills.test.js | 2 +- test/dom-setup.js | 1 + test/dom-subagent-transcript.test.js | 1 + test/dom-subagent-ttl-tick.test.js | 282 ++++++++++ test/session-transitions.test.js | 8 + test/subagent-settle-tick.test.js | 504 ++++++++++++++++++ test/terminal-manager-harness.js | 2 +- test/terminal-manager-lifecycle.test.js | 2 +- 16 files changed, 1117 insertions(+), 14 deletions(-) create mode 100644 public/subagent-timing.js create mode 100644 test/dom-subagent-ttl-tick.test.js create mode 100644 test/subagent-settle-tick.test.js diff --git a/.ai/contexts/subagent-observability.md b/.ai/contexts/subagent-observability.md index 9cf905a8..135898e6 100644 --- a/.ai/contexts/subagent-observability.md +++ b/.ai/contexts/subagent-observability.md @@ -66,7 +66,8 @@ This is the **#1 fork-specific feature** (upstream PR #47 still pending). It per `.running` from this Map on every render, so the state survives a full sidebar rebuild; the IPC handlers only fast-path the visual toggle between rebuilds (`reflectSubagentRunningState`). -- **Why a TTL** (`SUBAGENT_LIVE_TTL_MS` = 60s, mirroring grid-view's): +- **Why a TTL** (`SUBAGENT_LIVE_TTL_MS` = 60s, shared with grid-view — see + "One TTL, one definition" below): `detectSubagentTransitions()` only polls subagents of `!exited` sessions — if the parent's PTY dies before a subagent goes 30s quiet, the matching `subagent-completed` never fires and the entry would be stuck forever. @@ -140,6 +141,20 @@ when a *new* subagent starts. Two rules keep that rescan quiet: re-added it, at the cost of a `statSync` and a `readSubagentMeta()` each. The map is now bounded by the directory's own file count. +The settle tick reopens this question, because the predicate that arms it counts +completed-but-still-falsifiable entries — which is exactly what bootstrap leaves +behind for a *recent* file. So the periodic sweep now rescans the very entries +PR #147 was about, with no watcher event involved. It does not wake the ghost: +those entries are recorded `completed: true`, and the rehabilitation branch fires +only on an mtime that actually moved. That is pinned by execution, not by +reading — `test/subagent-settle-tick.test.js` drives the tick past the close of +the window on a bootstrap file and asserts no IPC is ever emitted, and a sibling +test grows the file mid-window to check the late spawn is still emitted, once. +Neutralising the mtime-growth condition makes the first test report +`the tick must never announce a bootstrap file, got +["subagent-spawned","subagent-completed","subagent-spawned"]` — the ghost, now +oscillating on a clock. + Renderer side, `subagent-spawned` doubles as the still-alive heartbeat (`payload._heartbeat`). **A heartbeat refreshes an agent already tracked; it never creates an entry** — in `public/sidebar.js` and `public/grid-view.js` @@ -175,6 +190,158 @@ an agent tracked from its first line. The renderer's 60 s TTL has the same shape. Anything that needs true liveness would have to come from the parent process, not from mtime. +## The liveness signal needs a clock of its own (measured 2026-08-23/24) + +`detectSubagentTransitions()` owns three signals — spawn, heartbeat, completion — +and until now it ran from exactly one place: the projects watcher's debounced +flush (`main.js:startProjectsWatcher`, `setTimeout(flushChanges, 500)` re-armed +on every `fs.watch` event over `PROJECTS_DIR`). A function that only runs when a +file changes cannot detect that a file **stopped** changing. Three symptoms, +all measured in `~/AppData/Roaming/switchboard/logs/main.log`: + +- **Completion arrives minutes late.** Agent `a9be19fb0a7e0e504`: last transcript + write 23:42:18, `[subagent-complete]` logged **23:52:55** — 10 min 37 s for a + 30 s stability window. The parent was `waiting for your input` (OSC 9 at + 23:43:35), so nothing wrote in the folder and no flush ran. The event fired at + the moment activity resumed, which is what the user saw as "the indicators + went dark when the parent came back". +- **Completion also arrives *wrongly*.** Agents `a8e8c25f42a65b026` and + `a19dcbbb23270de85` were declared complete at 23:56:53 and 00:00:27 while + still writing at 00:02:00 and 00:01:45. A tool call longer than `STABLE_MS` + is indistinguishable from a finished agent — a documented limitation, but the + verdict was **irreversible**: the completion branch set `completed = true` + without a `_recheckStart`, so the entry hit the + `if (known.completed && !known._recheckStart) continue` fast path forever and + the agent could never light up again. `LIVE_RECHECK_MS` (5 min) now keeps a + stability completion falsifiable exactly like an assumed-finished one; renewed + growth rehabilitates it and re-emits the spawn (`[subagent-spawn-late]`). + This is load-bearing for the tick below: giving the stability clock a clock + makes false completions *more* frequent, not less, so reversibility is the + half that makes the pair safe. + + **The window widens on each rehabilitation** — `STABLE_LADDER_MS` + (30 s -> 2 min -> `MAX_STABLE_MS` = 5 min, capped by name, carried on the + entry as `_stableMs`). An agent that has already gone quiet for longer than + its window is an agent whose silences are long; widening converges instead of + letting it oscillate complete -> rehabilitated -> complete, one visible blink + per cycle. The widening is deliberately **not** applied to the other + rehabilitation case: an *assumed*-finished entry (bootstrap, or a stale first + sighting) was never declared finished by the stability timer and carries no + evidence of long silences, so widening it would slow the normal case for + nothing. `_recheckMs` is the discriminator — it is set only on a stability + completion. Getting that wrong is caught by the two pre-existing bootstrap + reversibility tests. + + **Widening required one companion change.** A wider window means an agent can + stay silent past the renderer's 60 s TTL without being completed — and the + renderer refuses a heartbeat for an agent it no longer tracks, by design. On + its own the widening would therefore have traded a blink for a permanent + blackout: exactly the bug being fixed, since before this branch the + completion/rehabilitation pair was the *only* path that re-lit a TTL-pruned + entry. So when the growth branch finds the agent unseen for at least + `SUBAGENT_LIVE_TTL_MS` it emits a **real spawn instead of a heartbeat**. That is + safe in all three cases the no-resurrect guard defends against: a completed + entry never reaches the growth branch, a TTL-pruned one is precisely what we + want to revive on fresh evidence of growth, and a dead parent never gets + scanned at all (`detectSubagentTransitions` runs only for `!exited` + sessions). +- **Heartbeats stop too**, and the renderer's 60 s TTL then evicts a live agent. + Combined with "a heartbeat never resurrects an untracked agent", that eviction + is permanent as well. + +The settle tick (`SETTLE_TICK_MS`, `armSubagentSettleTick`) re-runs the scan for +sessions that still hold a non-completed entry, independent of the watcher. It +arms only when something is unsettled, re-arms from its own sweep, and stops on +its own once every tracked agent has both completed **and** closed its recheck +window — no idle cost when no subagent is running. `unref()` keeps it out of the +way of process shutdown and of tests. + +A completed-but-still-falsifiable entry counts as unsettled on purpose: without +that, in a silent folder its window could only ever close on a write to some +*other* file in the same folder, so the "generous but bounded" promise above +would not hold. Note that arming is guarded in two places — in +`armSubagentSettleTick` and again in the sweep — so a test that only drains +timers cannot tell the two apart; `test/subagent-settle-tick.test.js` scans a +settled session directly and asserts nothing gets armed. + +**Refuted, so it does not get fixed here**: the debounce being *starved* by a +flood of writes (re-armed faster than 500 ms while several transcripts append). +The log disproves it — completions were emitted at 23:56:53 and 00:00:27 while +three transcripts were being written, so the flush was running normally under +load. No `maxWait` was added. + +### One TTL, one definition + +The main process and both renderer views must agree on the liveness TTL, and +the failure is silent and one-directional: shorten the renderer's TTL alone and +there is a band of durations in which the renderer has already pruned the entry +while the main process is still sending heartbeats the renderer refuses — the +permanent blackout this branch exists to fix, reintroduced with nothing to +catch it. (Diverging the other way is harmless.) + +It used to be three independent `60000` literals held together by a comment. +`public/subagent-timing.js` is now the single definition, following the +dual-mode pattern already used by `public/shortcuts.js` and +`public/terminal-manager.js`: a classic ` + diff --git a/public/sidebar.js b/public/sidebar.js index f2e96e0d..a19f4ea3 100644 --- a/public/sidebar.js +++ b/public/sidebar.js @@ -92,7 +92,6 @@ function subagentTypeColor(type) { // then evicts agents that went silent without evicting one that merely runs // longer than a minute. const activeSubagentsByParent = new Map(); -const SUBAGENT_LIVE_TTL_MS = 60000; function isSubagentActive(parentSessionId, agentId) { const map = activeSubagentsByParent.get(parentSessionId); @@ -115,6 +114,34 @@ function pruneStaleSubagents() { if (window.ATRACE) window.atrace('subagents.prune', null, { map: 'activeSubagentsByParent', cutoff, parents: activeSubagentsByParent.size, agents: [...activeSubagentsByParent.values()].reduce((n, m) => n + m.size, 0), fn: 'pruneStaleSubagents' }); } +let subagentTtlTimer = null; + +function scheduleSubagentTtlTick() { + if (subagentTtlTimer) return; + let oldest = Infinity; + for (const map of activeSubagentsByParent.values()) { + for (const lastSeenAt of map.values()) { + if (lastSeenAt < oldest) oldest = lastSeenAt; + } + } + if (oldest === Infinity) return; + const delay = Math.max(1, oldest + SUBAGENT_LIVE_TTL_MS + 1 - Date.now()); + subagentTtlTimer = setTimeout(runSubagentTtlTick, delay); +} + +function runSubagentTtlTick() { + subagentTtlTimer = null; + const tracked = []; + for (const [parentId, map] of activeSubagentsByParent) { + for (const agentId of map.keys()) tracked.push([parentId, agentId]); + } + pruneStaleSubagents(); + for (const [parentId, agentId] of tracked) { + if (!isSubagentActive(parentId, agentId)) reflectSubagentRunningState(parentId, agentId); + } + scheduleSubagentTtlTick(); +} + // Drop all live-subagent state for a parent whose PTY just stopped, and sync // the DOM immediately. Called from app.js's updateRunningIndicators(): // stop-session kills the PTY without emitting subagent-completed, and @@ -180,6 +207,7 @@ function reflectSubagentRunningState(parentSessionId, agentId) { } if (window.ATRACE) window.atrace('recv.subagent-spawned', parentSessionId, { map: 'activeSubagentsByParent', op: 'set', agentId, from: map.get(agentId) ?? null, applied: true, bootstrap: !!payload._bootstrap, heartbeat: !!_heartbeat, fn: 'onSubagentSpawned' }); map.set(agentId, Date.now()); + scheduleSubagentTtlTick(); reflectSubagentRunningState(parentSessionId, agentId); }); } diff --git a/public/subagent-timing.js b/public/subagent-timing.js new file mode 100644 index 00000000..998651c5 --- /dev/null +++ b/public/subagent-timing.js @@ -0,0 +1,9 @@ +// Shared subagent liveness timings. +// Classic