(trace): subagent activity is traced from its single write path, with its source

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` |

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');
   }
 }
 

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;
   }

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);

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();
+  }
+});