diff --git a/docs/activity-trace.md b/docs/activity-trace.md index 088fc156..09b114e9 100644 --- a/docs/activity-trace.md +++ b/docs/activity-trace.md @@ -168,7 +168,8 @@ no `sent`. | `cat` | Fires when | Key fields | |---|---|---| | `recv.*` | An IPC event arrives (`cli-busy-state`, `terminal-notification`, `session-forked`, `session-detected`, `process-exited`, `subagent-spawned`, `subagent-completed`) | per event | -| `recv.subagent-spawned` | …with `applied` telling whether it changed anything. `applied:false` + `reason:"heartbeat-for-untracked-agent"` is a heartbeat deliberately dropped | `agentId`, `applied`, `bootstrap`, `heartbeat`, `from` | +| `recv.subagent-spawned` | `noteSubagentActivity()` recorded a sighting — the single write path into `activeSubagentsByParent`, whichever of the three sources called it. `applied` tells whether it changed anything; `applied:false` + `reason:"heartbeat-for-untracked-agent"` is a heartbeat deliberately dropped **before** reaching `noteSubagentActivity` (still traced, from `onSubagentSpawned`, so it never gets a `source`) | `agentId`, `applied`, `source` (`local-ipc` / `remote-watch` / `local-transcript`), `bootstrap`, `heartbeat` (both `local-ipc`-only), `from` | +| `recv.subagent-completed` | An agent left `activeSubagentsByParent`, however that was discovered — `via` says how: `ipc` (the real `subagent-completed` event, local-ipc only), `ttl` (`pruneStaleSubagents`'s 60s sweep — the only "completed" `remote-watch`/`local-transcript` ever get, since neither source has a completed IPC of its own), or `parent-cleared` (`clearActiveSubagentsFor`, on a parent PTY exit or a remote session marked stopped) | `agentId`, `from`, `via` | | `store.mutate` | A state store changes | `map`, `op`, `from`, `to`, `fn`, `via` | | `store.skip` | A write was **refused** by a guard | `map`, `reason`, `fn` | | `store.purge` | State dropped because the PTY is gone | `reason`, `busy`, `ready`, `attention` | diff --git a/public/local-transcript-adapter.js b/public/local-transcript-adapter.js index f71d6244..bbec636d 100644 --- a/public/local-transcript-adapter.js +++ b/public/local-transcript-adapter.js @@ -108,7 +108,7 @@ function onLocalTranscriptSubagentActivity(payload) { // per-(parent, agentId) running set for the child row's own dot — see .ai/contexts/subagent-observability.md const agentId = payload.agentId; if (typeof agentId === 'string' && agentId && typeof noteSubagentActivity === 'function') { - noteSubagentActivity(parentSessionId, agentId); + noteSubagentActivity(parentSessionId, agentId, 'local-transcript'); } } diff --git a/public/remote-activity-ui.js b/public/remote-activity-ui.js index 8c0dbd48..998beec1 100644 --- a/public/remote-activity-ui.js +++ b/public/remote-activity-ui.js @@ -147,7 +147,7 @@ function onRemoteActivityEvent(payload) { // per-(parent, agentId) running set for the child row's own dot — see .ai/contexts/subagent-observability.md const agentId = payload.agentId; if (typeof agentId === 'string' && agentId && typeof noteSubagentActivity === 'function') { - noteSubagentActivity(parentSessionId, agentId); + noteSubagentActivity(parentSessionId, agentId, 'remote-watch'); } return; } diff --git a/public/sidebar.js b/public/sidebar.js index df07822a..4ebec99e 100644 --- a/public/sidebar.js +++ b/public/sidebar.js @@ -179,7 +179,11 @@ function pruneStaleSubagents() { const cutoff = Date.now() - SUBAGENT_LIVE_TTL_MS; for (const [parentId, map] of activeSubagentsByParent) { for (const [agentId, lastSeenAt] of map) { - if (lastSeenAt < cutoff) map.delete(agentId); + if (lastSeenAt < cutoff) { + // see docs/activity-trace.md (recv.subagent-completed via:ttl) + if (window.ATRACE) window.atrace('recv.subagent-completed', parentId, { map: 'activeSubagentsByParent', op: 'delete', agentId, from: lastSeenAt, to: null, via: 'ttl', fn: 'pruneStaleSubagents' }); + map.delete(agentId); + } } if (map.size === 0) activeSubagentsByParent.delete(parentId); } @@ -227,6 +231,8 @@ function clearActiveSubagentsFor(parentSessionId) { if (window.ATRACE) window.atrace('store.mutate', parentSessionId, { map: 'activeSubagentsByParent', op: 'delete-parent', from: map.size, to: 0, agentIds, fn: 'clearActiveSubagentsFor' }); activeSubagentsByParent.delete(parentSessionId); for (const agentId of agentIds) { + // see docs/activity-trace.md (recv.subagent-completed via:parent-cleared) + if (window.ATRACE) window.atrace('recv.subagent-completed', parentSessionId, { map: 'activeSubagentsByParent', op: 'delete', agentId, from: map.get(agentId) ?? null, to: null, via: 'parent-cleared', fn: 'clearActiveSubagentsFor' }); reflectSubagentRunningState(parentSessionId, agentId); } } @@ -268,14 +274,16 @@ function reflectSubagentRunningState(parentSessionId, agentId) { if (window.ATRACE) window.atrace('class.subagent', parentSessionId, { agentId, running, childEl: el ? el.id : null, caretEl: caret ? caret.id : null, parentEl: parentEl ? parentEl.id : null, 'has-busy-agents': parentHasActiveSubagent(parentSessionId), fn: 'reflectSubagentRunningState' }); } -// single write path into activeSubagentsByParent — see .ai/contexts/subagent-observability.md -function noteSubagentActivity(parentSessionId, agentId) { +// single write path into activeSubagentsByParent, sole emitter of recv.subagent-spawned — see docs/activity-trace.md +function noteSubagentActivity(parentSessionId, agentId, source, extra) { let map = activeSubagentsByParent.get(parentSessionId); + const from = map ? (map.get(agentId) ?? null) : null; if (!map) { map = new Map(); activeSubagentsByParent.set(parentSessionId, map); } map.set(agentId, Date.now()); + if (window.ATRACE) window.atrace('recv.subagent-spawned', parentSessionId, { map: 'activeSubagentsByParent', op: 'set', agentId, from, applied: true, source: source || 'local-ipc', fn: 'noteSubagentActivity', ...(extra || {}) }); scheduleSubagentTtlTick(); reflectSubagentRunningState(parentSessionId, agentId); } @@ -294,8 +302,7 @@ function noteSubagentActivity(parentSessionId, agentId) { if (window.ATRACE) window.atrace('recv.subagent-spawned', parentSessionId, { map: 'activeSubagentsByParent', op: 'ignore', agentId, heartbeat: true, applied: false, reason: 'heartbeat-for-untracked-agent', fn: 'onSubagentSpawned' }); return; } - if (window.ATRACE) window.atrace('recv.subagent-spawned', parentSessionId, { map: 'activeSubagentsByParent', op: 'set', agentId, from: map ? (map.get(agentId) ?? null) : null, applied: true, bootstrap: !!payload._bootstrap, heartbeat: !!_heartbeat, fn: 'onSubagentSpawned' }); - noteSubagentActivity(parentSessionId, agentId); + noteSubagentActivity(parentSessionId, agentId, 'local-ipc', { bootstrap: !!payload._bootstrap, heartbeat: !!_heartbeat }); }); } @@ -304,7 +311,7 @@ function noteSubagentActivity(parentSessionId, agentId) { const { parentSessionId, agentId } = payload || {}; if (!parentSessionId || !agentId) return; const map = activeSubagentsByParent.get(parentSessionId); - if (window.ATRACE) window.atrace('recv.subagent-completed', parentSessionId, { map: 'activeSubagentsByParent', op: 'delete', agentId, from: map ? (map.get(agentId) ?? null) : null, to: null, fn: 'onSubagentCompleted' }); + if (window.ATRACE) window.atrace('recv.subagent-completed', parentSessionId, { map: 'activeSubagentsByParent', op: 'delete', agentId, from: map ? (map.get(agentId) ?? null) : null, to: null, via: 'ipc', fn: 'onSubagentCompleted' }); if (map) { map.delete(agentId); if (map.size === 0) activeSubagentsByParent.delete(parentSessionId); diff --git a/test/dom-sidebar-subagent-running-parity.test.js b/test/dom-sidebar-subagent-running-parity.test.js index 87f5ac9e..06c88521 100644 --- a/test/dom-sidebar-subagent-running-parity.test.js +++ b/test/dom-sidebar-subagent-running-parity.test.js @@ -254,3 +254,123 @@ test('(6) an unattached remote parent icon, once painted by the remote adapter, ctx.destroy(); } }); + +// Issue #291 — noteSubagentActivity() is the single write path into +// activeSubagentsByParent AND the single place that traces +// recv.subagent-spawned, so every source gets one trace line tagged with +// where it came from, and the local-ipc handler (which used to trace its +// own "applied" line before calling noteSubagentActivity) does not double it. +// See docs/activity-trace.md. + +test('(7) recv.subagent-spawned tags source:"local-ipc", exactly once', () => { + const ctx = setupSidebarDom(); + try { + ctx.sidebar.renderProjects([projectWithLocalSubagent()], true); + const sent = []; + ctx.window.ATRACE = true; + ctx.window.atrace = (cat, sid, fields) => sent.push({ cat, sid, fields }); + + ctx.emitSubagentSpawned({ parentSessionId: 's-top-1', agentId: 'agent-1' }); + + const events = sent.filter(e => e.cat === 'recv.subagent-spawned'); + assert.equal(events.length, 1, 'not traced twice now that the handler no longer traces its own copy'); + assert.equal(events[0].fields.source, 'local-ipc'); + } finally { + ctx.destroy(); + } +}); + +test('(8) recv.subagent-spawned tags source:"remote-watch"', () => { + const ctx = setupSidebarDom(); + try { + ctx.sidebar.renderProjects([projectWithRemoteSubagent()], true); + const sent = []; + ctx.window.ATRACE = true; + ctx.window.atrace = (cat, sid, fields) => sent.push({ cat, sid, fields }); + + ctx.window.onRemoteActivityEvent({ alias: 'vps', parentSessionId: 'r-top-1', agentId: 'agent-1', at: Date.now(), kind: 'subagent' }); + + const events = sent.filter(e => e.cat === 'recv.subagent-spawned'); + assert.equal(events.length, 1); + assert.equal(events[0].fields.source, 'remote-watch'); + } finally { + ctx.destroy(); + } +}); + +test('(9) recv.subagent-spawned tags source:"local-transcript"', () => { + const ctx = setupSidebarDom(); + try { + ctx.sidebar.renderProjects([projectWithLocalTranscriptSubagent()], true); + const sent = []; + ctx.window.ATRACE = true; + ctx.window.atrace = (cat, sid, fields) => sent.push({ cat, sid, fields }); + + ctx.emitSessionTranscriptActivity({ parentSessionId: 'l-top-1', agentId: 'agent-1', at: Date.now(), kind: 'subagent' }); + + const events = sent.filter(e => e.cat === 'recv.subagent-spawned'); + assert.equal(events.length, 1); + assert.equal(events[0].fields.source, 'local-transcript'); + } finally { + ctx.destroy(); + } +}); + +test('(10) recv.subagent-completed via:"ipc" for the direct completed IPC', () => { + const ctx = setupSidebarDom(); + try { + ctx.sidebar.renderProjects([projectWithLocalSubagent()], true); + ctx.emitSubagentSpawned({ parentSessionId: 's-top-1', agentId: 'agent-1' }); + const sent = []; + ctx.window.ATRACE = true; + ctx.window.atrace = (cat, sid, fields) => sent.push({ cat, sid, fields }); + + ctx.emitSubagentCompleted({ parentSessionId: 's-top-1', agentId: 'agent-1' }); + + const ev = sent.find(e => e.cat === 'recv.subagent-completed'); + assert.ok(ev); + assert.equal(ev.fields.via, 'ipc'); + } finally { + ctx.destroy(); + } +}); + +test('(11) recv.subagent-completed via:"parent-cleared" from clearActiveSubagentsFor', () => { + const ctx = setupSidebarDom(); + try { + ctx.sidebar.renderProjects([projectWithLocalSubagent()], true); + ctx.emitSubagentSpawned({ parentSessionId: 's-top-1', agentId: 'agent-1' }); + const sent = []; + ctx.window.ATRACE = true; + ctx.window.atrace = (cat, sid, fields) => sent.push({ cat, sid, fields }); + + ctx.window.clearActiveSubagentsFor('s-top-1'); + + const ev = sent.find(e => e.cat === 'recv.subagent-completed'); + assert.ok(ev); + assert.equal(ev.fields.via, 'parent-cleared'); + } finally { + ctx.destroy(); + } +}); + +test('(12) recv.subagent-completed via:"ttl" — the only completion remote-watch ever gets', () => { + const ctx = setupSidebarDom(); + try { + ctx.sidebar.renderProjects([projectWithRemoteSubagent()], true); + ctx.window.onRemoteActivityEvent({ alias: 'vps', parentSessionId: 'r-top-1', agentId: 'agent-1', at: Date.now(), kind: 'subagent' }); + const sent = []; + ctx.window.ATRACE = true; + ctx.window.atrace = (cat, sid, fields) => sent.push({ cat, sid, fields }); + + const t0 = ctx.window.Date.now(); + ctx.window.Date.now = () => t0 + 61000; // past the 60s TTL + ctx.sidebar.renderProjects([projectWithRemoteSubagent()], false); + + const ev = sent.find(e => e.cat === 'recv.subagent-completed'); + assert.ok(ev, 'the TTL prune traces the completion since remote-watch never sends one itself'); + assert.equal(ev.fields.via, 'ttl'); + } finally { + ctx.destroy(); + } +});