From 3202a01dbc0d218b30cfc1d34e46c5b7a3ede36e Mon Sep 17 00:00:00 2001 From: Lily Shen <115414357+lilyshen0722@users.noreply.github.com> Date: Sun, 25 Oct 2026 21:16:01 -0700 Subject: [PATCH 1/8] feat(cli): supervised turn runner on main behind COMMONLY_SUPERVISE_RUNS, no relay The seat runner's supervised turn (stall window, cancel grace, process-group kill, wall backstop, named failures) now runs on main when COMMONLY_SUPERVISE_RUNS=1, so canary seats can run a main build. Flag unset is pinned byte for byte against main's own agent.js. The provider relay is left out entirely. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013ENddpGzhE7S8qjDSYAMuu --- .../fixtures/run-loop-flag-off.golden.json | 268 ++++++++++++ cli/__tests__/seat-log-baseline.test.mjs | 43 ++ cli/__tests__/supervise-runs-flag.test.mjs | 339 +++++++++++++++ cli/__tests__/supervised-turn.test.mjs | 392 ++++++++++++++++++ cli/scripts/seat-log-baseline.mjs | 185 +++++++++ cli/src/commands/agent.js | 26 +- cli/src/lib/supervised-turn.js | 340 +++++++++++++++ 7 files changed, 1591 insertions(+), 2 deletions(-) create mode 100644 cli/__tests__/fixtures/run-loop-flag-off.golden.json create mode 100644 cli/__tests__/seat-log-baseline.test.mjs create mode 100644 cli/__tests__/supervise-runs-flag.test.mjs create mode 100644 cli/__tests__/supervised-turn.test.mjs create mode 100644 cli/scripts/seat-log-baseline.mjs create mode 100644 cli/src/lib/supervised-turn.js diff --git a/cli/__tests__/fixtures/run-loop-flag-off.golden.json b/cli/__tests__/fixtures/run-loop-flag-off.golden.json new file mode 100644 index 0000000000..8675dc7461 --- /dev/null +++ b/cli/__tests__/fixtures/run-loop-flag-off.golden.json @@ -0,0 +1,268 @@ +{ + "success": { + "spawns": [ + { + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 1\n@rhea docs gate: #2250, wording only\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "ctx": { + "agentName": "rhea", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/rhea", + "env": "", + "environment": null, + "instanceUrl": "http://localhost:5000", + "memoryLongTerm": "", + "memoryWithheld": false, + "metadata": { + "event": "batch-evt-1" + }, + "onSkillsLinked": "[function]", + "onSpawn": "", + "providerKey": "", + "runtimeToken": "cm_agent_test", + "sessionId": null, + "skillMountDir": "/commonly-agents/rhea", + "timeoutMs": 900000 + } + } + ], + "acks": [ + { + "id": "evt-1", + "result": { + "outcome": "posted" + } + } + ], + "posts": [ + { + "content": "docs gate: PASS" + } + ], + "releases": [ + { + "route": "/api/agents/runtime/messages/1/claim", + "body": { + "outcome": "completed" + } + } + ], + "otherPosts": [ + "/api/agents/runtime/spawn-credentials/revoke-orphans", + "/api/agents/runtime/messages/1/claim", + "/api/agents/runtime/spawn-credentials" + ], + "errors": [], + "logs": [ + "cascade: cap=3 grace=2 reset=600000ms (defaults)", + "spawn credential boot sweep found no orphans", + "[inbox.batch] spawning stub", + "spawn credential response carried no token — spawning with the seat token", + "spawning with the seat token (spawn credential unavailable)", + "[inbox.batch] posted 15 bytes as 1 message (single)" + ], + "scheduled": [ + 3000 + ] + }, + "refusalInMixedBatch": { + "spawns": [ + { + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 2 new events in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/2: chat.mention — message 2\n@rhea security gate: #2249, flagged-content-here\n\nEvent 2/2: chat.mention — message 3\n@rhea docs gate: #2251, typo fix\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "ctx": { + "agentName": "rhea", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/rhea", + "env": "", + "environment": null, + "instanceUrl": "http://localhost:5000", + "memoryLongTerm": "", + "memoryWithheld": false, + "metadata": { + "event": "batch-evt-2" + }, + "onSkillsLinked": "[function]", + "onSpawn": "", + "providerKey": "", + "runtimeToken": "cm_agent_test", + "sessionId": null, + "skillMountDir": "/commonly-agents/rhea", + "timeoutMs": 900000 + } + }, + { + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 2\n@rhea security gate: #2249, flagged-content-here\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "ctx": { + "agentName": "rhea", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/rhea", + "env": "", + "environment": null, + "instanceUrl": "http://localhost:5000", + "memoryLongTerm": "", + "memoryWithheld": false, + "metadata": { + "event": "batch-evt-2" + }, + "onSkillsLinked": "[function]", + "onSpawn": "", + "providerKey": "", + "runtimeToken": "cm_agent_test", + "sessionId": null, + "skillMountDir": "/commonly-agents/rhea", + "timeoutMs": 900000 + } + }, + { + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 3\n@rhea docs gate: #2251, typo fix\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "ctx": { + "agentName": "rhea", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/rhea", + "env": "", + "environment": null, + "instanceUrl": "http://localhost:5000", + "memoryLongTerm": "", + "memoryWithheld": false, + "metadata": { + "event": "batch-evt-3" + }, + "onSkillsLinked": "[function]", + "onSpawn": "", + "providerKey": "", + "runtimeToken": "cm_agent_test", + "sessionId": null, + "skillMountDir": "/commonly-agents/rhea", + "timeoutMs": 900000 + } + } + ], + "acks": [ + { + "id": "evt-2", + "result": { + "outcome": "error", + "reason": "provider-refused", + "details": { + "failureClass": "content_refused", + "handoff": null, + "noticePosted": true + } + } + }, + { + "id": "evt-3", + "result": { + "outcome": "posted" + } + } + ], + "posts": [ + { + "content": "docs gate: PASS" + }, + { + "content": "The model provider refused the content of #2249 (no head named) (message 2 from growth-ops), so I could not read it and will not retry it. It needs another reader." + } + ], + "releases": [ + { + "route": "/api/agents/runtime/messages/2/claim", + "body": { + "outcome": "refused", + "reason": "upstream-refused" + } + }, + { + "route": "/api/agents/runtime/messages/3/claim", + "body": { + "outcome": "completed" + } + } + ], + "otherPosts": [ + "/api/agents/runtime/spawn-credentials/revoke-orphans", + "/api/agents/runtime/messages/2/claim", + "/api/agents/runtime/messages/3/claim", + "/api/agents/runtime/spawn-credentials", + "/api/agents/runtime/spawn-credentials", + "/api/agents/runtime/spawn-credentials" + ], + "errors": [], + "logs": [ + "cascade: cap=3 grace=2 reset=600000ms (defaults)", + "spawn credential boot sweep found no orphans", + "[inbox.batch] spawning stub", + "spawn credential response carried no token — spawning with the seat token", + "spawning with the seat token (spawn credential unavailable)", + "[inbox.batch] the model provider refused this batch's content (content_refused); running its 2 items one at a time so only a refused item is refused", + "[inbox.batch] spawning stub", + "spawn credential response carried no token — spawning with the seat token", + "spawning with the seat token (spawn credential unavailable)", + "[inbox.batch] spawning stub", + "spawn credential response carried no token — spawning with the seat token", + "spawning with the seat token (spawn credential unavailable)", + "[inbox.batch] posted 15 bytes as 1 message (single)", + "[chat.mention] the model provider refused the content of event evt-2 (content_refused) — acked as refused, not retried", + "[inbox.batch] refusal notice posted" + ], + "scheduled": [ + 3000 + ] + }, + "runtimeFailure": { + "spawns": [ + { + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 4\n@rhea docs gate: #2252\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "ctx": { + "agentName": "rhea", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/rhea", + "env": "", + "environment": null, + "instanceUrl": "http://localhost:5000", + "memoryLongTerm": "", + "memoryWithheld": false, + "metadata": { + "event": "batch-evt-4" + }, + "onSkillsLinked": "[function]", + "onSpawn": "", + "providerKey": "", + "runtimeToken": "cm_agent_test", + "sessionId": null, + "skillMountDir": "/commonly-agents/rhea", + "timeoutMs": 900000 + } + } + ], + "acks": [], + "posts": [], + "releases": [ + { + "route": "/api/agents/runtime/messages/4/claim" + } + ], + "otherPosts": [ + "/api/agents/runtime/spawn-credentials/revoke-orphans", + "/api/agents/runtime/messages/4/claim", + "/api/agents/runtime/spawn-credentials" + ], + "errors": [ + { + "code": "agent_spawn_retry_scheduled", + "message": "inbox batch processing failed (runtime; 1 consecutive) — retrying 1 held event in 5s: runtime unavailable", + "failureClass": "runtime" + } + ], + "logs": [ + "cascade: cap=3 grace=2 reset=600000ms (defaults)", + "spawn credential boot sweep found no orphans", + "[inbox.batch] spawning stub", + "spawn credential response carried no token — spawning with the seat token", + "spawning with the seat token (spawn credential unavailable)" + ], + "scheduled": [ + 5000 + ] + } +} diff --git a/cli/__tests__/seat-log-baseline.test.mjs b/cli/__tests__/seat-log-baseline.test.mjs new file mode 100644 index 0000000000..f98306ad6b --- /dev/null +++ b/cli/__tests__/seat-log-baseline.test.mjs @@ -0,0 +1,43 @@ +import { baseline, render } from '../scripts/seat-log-baseline.mjs'; + +const L = (ts, msg, seat = 'nib') => `2026-10-24T${ts}Z [${seat}] ${msg}`; +const LOG = [ + L('00:00:00.000', 'polling https://api.commonly.me for events (ctrl+c to stop)'), + L('01:00:00.000', '[inbox.batch] spawning codex'), + L('01:00:00.400', 'spawn credential minted (6adbd35b8522fc8abce9b7b6, granted 9 tools)'), + L('01:00:30.000', 'spawn credential revoked (6adbd35b8522fc8abce9b7b6)'), + L('01:00:30.300', '[inbox.batch] agent posted via tool this turn — not echoing CLI output'), + L('02:00:00.000', '[inbox.batch] spawning codex'), + L('02:45:00.000', 'spawn credential revoked (6adbd35b8522fc8abce9b7b7)'), + L('02:45:00.100', 'inbox batch processing failed (runtime; 1 consecutive) — 1 events remain unacked; retry scheduled, next probe in 5.6s: codex timed out after 2700000ms SECRET-STDERR-TEXT'), + ' SECRET-HTML', + L('03:00:00.000', '[chat.mention] spawning codex'), + L('03:00:05.000', 'inbox batch processing failed (runtime; 1 consecutive) — 1 events remain unacked: codex exited with code 7: SECRET-STDERR-TEXT'), + L('04:00:00.000', '[inbox.batch] spawning claude'), + L('04:01:00.000', 'stopping after the current turn...'), + L('04:02:00.000', 'fetch failed'), + L('05:00:00.000', '[inbox.batch] spawning claude', 'quire'), + L('06:00:00.000', '[inbox.batch] spawning codex'), +].join('\n'); + +test('turns, durations, timeouts, exits, restarts, and an open turn, from timestamps and fixed phrases', () => { + const r = baseline(LOG, { seat: 'nib', untilMs: Date.parse('2026-10-24T07:00:00Z'), hours: 48 }); + expect(r.byAdapter.codex).toMatchObject({ + turns: 4, ok: 1, failed: 2, timeouts: 1, exits: { 7: 1 }, errors: 0, open: 1, atOrOverTimeout: 1, + outcomes: { posted_via_tool: 1 }, + }); + expect(r.byAdapter.codex.durationMs).toEqual({ p50: 30_000, p90: 2_700_100, p99: 2_700_100, max: 2_700_100, n: 3 }); + expect(r.byAdapter.claude).toMatchObject({ turns: 1, cutByRestart: 1 }); + expect(r.counts).toMatchObject({ untimestamped: 1, pollErrors: 1, restarts: 1, otherSeatLines: 1 }); + const out = `${render(r)}\n${JSON.stringify(r)}`; + expect(out).not.toMatch(/SECRET/); + expect(out).toMatch(/the log cannot tell/); +}); + +test('the window bounds which turns count', () => { + const r = baseline(LOG, { seat: 'nib', untilMs: Date.parse('2026-10-24T02:30:00Z'), hours: 2 }); + expect(r.byAdapter.codex.turns).toBe(2); + expect(r.byAdapter.codex.ok).toBe(1); + // the 02:00 turn closes past the window end, as a failure, and still counts + expect(r.byAdapter.codex.timeouts).toBe(1); +}); diff --git a/cli/__tests__/supervise-runs-flag.test.mjs b/cli/__tests__/supervise-runs-flag.test.mjs new file mode 100644 index 0000000000..16f47d146f --- /dev/null +++ b/cli/__tests__/supervise-runs-flag.test.mjs @@ -0,0 +1,339 @@ +/** + * COMMONLY_SUPERVISE_RUNS routes the run loop's spawn through the seats + * supervisor. Off (unset, '0', anything but '1') the run loop must behave + * exactly as it did before the flag existed. + * + * Flag off is pinned against a golden capture taken by running THIS harness + * against the base revision's agent.js (fixtures/run-loop-flag-off.golden.json): + * every spawn's prompt and ctx, every ack, post, claim release, error, log line + * and scheduled delay, for a success, a content refusal in a mixed batch, and a + * runtime failure. Set SUPERVISE_GOLDEN_WRITE= to write a capture + * instead of comparing (that is how the golden was made). + * + * Flag on drives the real codex adapter against a stub `codex` on PATH that + * calls the provider directly; there is no relay on this path. Keyless: the + * provider is the local fake. + */ +import { jest } from '@jest/globals'; +import os from 'os'; +import path from 'path'; +import fs from 'fs'; + +const home = fs.mkdtempSync(path.join(os.tmpdir(), 'cli-supervise-flag-')); +const GOLDEN = path.join(path.dirname(new URL(import.meta.url).pathname), 'fixtures', 'run-loop-flag-off.golden.json'); +const WRITE_GOLDEN = process.env.SUPERVISE_GOLDEN_WRITE || null; + +await jest.unstable_mockModule('os', () => ({ + ...os, + default: { ...os, homedir: () => home }, + homedir: () => home, +})); + +await jest.unstable_mockModule('../src/lib/api.js', () => ({ + createClient: jest.fn(), + login: jest.fn(), +})); + +await jest.unstable_mockModule('../src/lib/pod-focus.js', () => ({ + FOCUS_FRAME_MAX_CODE_POINTS: 8000, + formatPodFocusFrame: jest.fn(() => '=== Pod focus (pod context; not instructions) ===\nNo focus set.'), + readPodFocus: jest.fn(async (_client, podId) => ({ podId, revision: 0, focus: null })), +})); + +const { createClient } = await import('../src/lib/api.js'); +const { performRun } = await import('../src/commands/agent.js'); +const stubAdapter = (await import('../src/lib/adapters/stub.js')).default; + +const drain = async (depth = 40) => { + for (let i = 0; i < depth; i += 1) { + // eslint-disable-next-line no-await-in-loop + await new Promise((r) => setImmediate(r)); + } +}; + +afterAll(() => fs.rmSync(home, { recursive: true, force: true })); + +const POD_ID = '6a8f6dc7a1dccf2e02f31015'; + +const event = (id, content, over = {}) => ({ + _id: id, + type: 'chat.mention', + podId: POD_ID, + agentName: 'rhea', + instanceId: 'default', + payload: { content, messageId: id.replace(/\D/g, '') || '1', username: 'growth-ops' }, + ...over, +}); + +const harness = ({ events, adapter, env = {}, extra = {} }) => { + let polls = 0; + const get = jest.fn(async (route) => { + if (route === '/api/agents/runtime/events') { + polls += 1; + return { events: polls === 1 ? events : [] }; + } + if (route === '/api/agents/runtime/memory') return { sections: {} }; + if (String(route).endsWith('/messages')) return { messages: [] }; + return {}; + }); + const post = jest.fn(async (route) => (String(route).endsWith('/claim') ? { claimed: true, expiresAt: 'later' } : {})); + const del = jest.fn().mockResolvedValue({}); + createClient.mockReturnValue({ get, post, del }); + const logs = []; + const errors = []; + const scheduled = []; + const saved = {}; + for (const [key, value] of Object.entries(env)) { + saved[key] = process.env[key]; + if (value === undefined) delete process.env[key]; else process.env[key] = value; + } + let handle; + try { + handle = performRun({ + instanceUrl: 'http://localhost:5000', + token: 'cm_agent_test', + adapter, + agentName: 'rhea', + retryJitterRatio: 0, + claimYieldDelayMs: 0, + sleepImpl: async () => {}, + log: (line) => logs.push(String(line)), + onError: (err) => errors.push({ code: err.code ?? null, message: err.message, failureClass: err.failureClass ?? null }), + setTimeoutImpl: (callback, delayMs) => { scheduled.push({ callback, delayMs }); return 0; }, + ...extra, + }); + } finally { + for (const [key, value] of Object.entries(saved)) { + if (value === undefined) delete process.env[key]; else process.env[key] = value; + } + } + const calls = () => post.mock.calls.map(([route, body]) => ({ route: String(route), body })); + return { + handle, + logs, + errors, + scheduled, + acks: () => calls().filter((c) => c.route.endsWith('/ack')).map((c) => ({ id: c.route.split('/').at(-2), result: c.body.result })), + posts: () => calls().filter((c) => c.route.endsWith(`/pods/${POD_ID}/messages`)).map((c) => c.body), + releases: () => del.mock.calls.filter(([r]) => String(r).endsWith('/claim')).map(([r, b]) => ({ route: String(r), body: b })), + otherPosts: () => calls().filter((c) => !c.route.endsWith('/ack') && !c.route.endsWith(`/pods/${POD_ID}/messages`)).map((c) => c.route), + }; +}; + +// ── flag off: byte-identical to the base revision ─────────────────────────── + +const ctxShape = (ctx) => Object.fromEntries(Object.keys(ctx).sort().map((key) => { + const value = ctx[key]; + if (typeof value === 'function') return [key, '[function]']; + if (key === 'env') return [key, value === process.env ? '' : '']; + if (key === 'metadata') return [key, { event: value?.event?._id ?? null }]; + return [key, value === undefined ? '' : value]; +})); + +const normalise = (value) => JSON.parse(JSON.stringify(value, (_key, v) => ( + typeof v === 'string' ? v.split(home).join('').split(os.tmpdir()).join('') : v +))); + +const SCENARIOS = { + success: { + events: [event('evt-1', '@rhea docs gate: #2250, wording only')], + spawn: async () => ({ text: 'docs gate: PASS' }), + }, + refusalInMixedBatch: { + events: [ + event('evt-2', '@rhea security gate: #2249, flagged-content-here'), + event('evt-3', '@rhea docs gate: #2251, typo fix'), + ], + spawn: async (prompt) => { + if (prompt.includes('flagged-content-here')) { + throw new Error('codex turn failed: This content was flagged for possible cybersecurity risk.'); + } + return { text: 'docs gate: PASS' }; + }, + }, + runtimeFailure: { + events: [event('evt-4', '@rhea docs gate: #2252')], + spawn: async () => { throw new Error('runtime unavailable'); }, + }, +}; + +const capture = async (env) => { + const out = {}; + for (const [name, scenario] of Object.entries(SCENARIOS)) { + fs.rmSync(path.join(home, '.commonly'), { recursive: true, force: true }); + const spawns = []; + const adapter = { + name: 'stub', + detect: stubAdapter.detect, + spawn: async (prompt, ctx) => { + spawns.push({ prompt, ctx: ctxShape(ctx) }); + return scenario.spawn(prompt, ctx); + }, + }; + const run = harness({ events: scenario.events, adapter, env }); + // eslint-disable-next-line no-await-in-loop + await drain(); + run.handle.stop(); + // eslint-disable-next-line no-await-in-loop + await drain(5); + out[name] = normalise({ + spawns, + acks: run.acks(), + posts: run.posts(), + releases: run.releases(), + otherPosts: run.otherPosts(), + errors: run.errors, + logs: run.logs, + scheduled: run.scheduled.map((s) => s.delayMs), + }); + } + return out; +}; + +describe('COMMONLY_SUPERVISE_RUNS off', () => { + const variants = WRITE_GOLDEN + ? [['unset', undefined]] + : [['unset', undefined], ["'0'", '0'], ["'true' (only '1' turns it on)", 'true'], ["''", '']]; + + test.each(variants)('flag %s: the run loop matches the base revision exactly', async (_label, value) => { + const got = await capture({ COMMONLY_SUPERVISE_RUNS: value }); + if (WRITE_GOLDEN) { + fs.writeFileSync(WRITE_GOLDEN, `${JSON.stringify(got, null, 2)}\n`); + return; + } + const golden = JSON.parse(fs.readFileSync(GOLDEN, 'utf8')); + expect(got).toEqual(golden); + // Supervision leaves no trace store behind when it is off. + expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); + }); + + if (!WRITE_GOLDEN) { + test('the golden is not vacuous: it holds a posted turn, a refused ack and a scheduled retry', () => { + const golden = JSON.parse(fs.readFileSync(GOLDEN, 'utf8')); + expect(golden.success.posts.length).toBeGreaterThan(0); + expect(golden.success.spawns[0].ctx).toHaveProperty('runtimeToken'); + expect(golden.refusalInMixedBatch.acks.map((a) => a.result.reason)).toContain('provider-refused'); + expect(golden.runtimeFailure.errors.map((e) => e.code)).toContain('agent_spawn_retry_scheduled'); + }); + + test('the explicit superviseRuns=false option also keeps the plain path, even with the env set', async () => { + const spawns = []; + const adapter = { + name: 'stub', + detect: stubAdapter.detect, + spawn: async (prompt, ctx) => { spawns.push(ctxShape(ctx)); return { text: 'ok' }; }, + }; + fs.rmSync(path.join(home, '.commonly'), { recursive: true, force: true }); + const run = harness({ + events: [event('evt-5', '@rhea hi')], adapter, env: { COMMONLY_SUPERVISE_RUNS: '1' }, extra: { superviseRuns: false }, + }); + await drain(); + run.handle.stop(); + expect(spawns).toHaveLength(1); + expect(spawns[0]).not.toHaveProperty('signal'); + expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); + }); + } +}); + +// ── flag on: a codex run on the supervised path ───────────────────────────── + +const STUB_CODEX = `#!/usr/bin/env node +// A stand-in for codex exec: one Chat Completions call straight to the +// provider, exit 0. Writes only the reply file codex would. +import { writeFileSync } from 'node:fs'; +const args = process.argv.slice(2); +let out = null; +for (let i = 0; i < args.length; i += 1) if (args[i] === '-o') out = args[i + 1]; +const prompt = args.at(-1); +const res = await fetch(process.env.STUB_CODEX_DIRECT_BASE.replace(/\\/+$/, '') + '/chat/completions', { + method: 'POST', + headers: { 'content-type': 'application/json', authorization: 'Bearer ' + process.env.FAKE_PROVIDER_KEY }, + body: JSON.stringify({ model: 'm', messages: [{ role: 'user', content: prompt }] }), +}); +process.stdout.write(JSON.stringify({ type: 'thread.started', thread_id: 'thread-stub-1' }) + '\\n'); +if (!res.ok) { process.stderr.write('model request failed: HTTP ' + res.status + '\\n'); process.exit(1); } +const text = (await res.json()).choices[0].message.content; +writeFileSync(out, text); +process.stdout.write(JSON.stringify({ type: 'turn.completed' }) + '\\n'); +`; + +const filesUnder = (dir) => { + const found = []; + const walk = (p) => { + let stat; + try { stat = fs.lstatSync(p); } catch { return; } + if (stat.isSymbolicLink()) return; + if (stat.isDirectory()) { for (const name of fs.readdirSync(p)) walk(path.join(p, name)); } else found.push(p); + }; + walk(dir); + return found; +}; + +describe('COMMONLY_SUPERVISE_RUNS=1 with the real codex adapter', () => { + // Each turn spawns a real child and makes real loopback calls; under a + // parallel suite on a loaded host that takes longer than jest's 5 s default. + jest.setTimeout(60_000); + const CANARY_KEY = 'sk-canary-run-loop-4c1d9e7a'; + + test('a clean reply is posted, the metric line says supervised and ok, and nothing else reaches disk', async () => { + const { startFakeProvider } = await import('../../packages/seats/test-support/fake-provider.js'); + const codex = (await import('../src/lib/adapters/codex.js')).default; + const provider = await startFakeProvider({ defaultReply: 'review: PASS' }); + fs.rmSync(path.join(home, '.commonly'), { recursive: true, force: true }); + const codexHome = path.join(home, '.codex'); + const bin = path.join(home, 'bin'); + fs.rmSync(codexHome, { recursive: true, force: true }); + fs.mkdirSync(codexHome, { recursive: true }); + fs.mkdirSync(bin, { recursive: true }); + fs.writeFileSync(path.join(codexHome, 'config.toml'), ''); + fs.writeFileSync(path.join(bin, 'codex'), STUB_CODEX, { mode: 0o755 }); + const workspace = fs.mkdtempSync(path.join(home, 'ws-')); + const env = { + COMMONLY_SUPERVISE_RUNS: '1', + CODEX_HOME: codexHome, + FAKE_PROVIDER_KEY: CANARY_KEY, + STUB_CODEX_DIRECT_BASE: provider.baseURL, + PATH: `${bin}${path.delimiter}${path.dirname(process.execPath)}${path.delimiter}${process.env.PATH}`, + }; + // The env must stay set while the turn runs: the adapter reads it at spawn. + const saved = Object.fromEntries(Object.keys(env).map((k) => [k, process.env[k]])); + Object.assign(process.env, env); + try { + const run = harness({ + events: [event('evt-9', '@rhea review #2249')], + adapter: codex, + extra: { environment: { model: 'gpt-test' }, workspacePath: workspace }, + }); + const deadline = Date.now() + 30_000; + while (Date.now() < deadline && run.acks().length === 0) { + // eslint-disable-next-line no-await-in-loop + await new Promise((r) => setTimeout(r, 25)); + } + run.handle.stop(); + await drain(5); + expect({ errors: run.errors, logs: run.logs.filter((l) => /supervised/.test(l)) }).toEqual({ + errors: [], logs: [expect.stringMatching(/^supervised runs ON for codex: stall=900000ms, .*trace=memory/)], + }); + expect(run.acks()[0].result).toEqual({ outcome: 'posted' }); + expect(run.posts().map((p) => p.content)).toContain('review: PASS'); + expect(provider.requests.map((r) => r.authorization)).toEqual(['present']); + expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); + const lines = fs.readFileSync(path.join(home, '.commonly', 'state', 'seats-canary', 'rhea.jsonl'), 'utf8') + .split('\n').filter(Boolean).map((line) => JSON.parse(line)); + expect(lines).toEqual([expect.objectContaining({ + path: 'supervised', adapter: 'codex', outcome: 'ok', failure: null, + stallMs: 15 * 60 * 1000, exitCode: 0, exitObserved: true, killed: false, + })]); + // The reply was posted, and is in no file the run left: no record writer. + for (const file of filesUnder(home)) { + const text = fs.readFileSync(file, 'utf8'); + expect({ file, reply: text.includes('review: PASS'), auth: text.includes(CANARY_KEY) }) + .toEqual({ file, reply: false, auth: false }); + } + } finally { + for (const [k, v] of Object.entries(saved)) { if (v === undefined) delete process.env[k]; else process.env[k] = v; } + await provider.close(); + } + }); +}); diff --git a/cli/__tests__/supervised-turn.test.mjs b/cli/__tests__/supervised-turn.test.mjs new file mode 100644 index 0000000000..1f68f52bbf --- /dev/null +++ b/cli/__tests__/supervised-turn.test.mjs @@ -0,0 +1,392 @@ +/** + * The seats canary's turn runner (lib/supervised-turn.js) and its place in the + * run loop. + * + * - flag off: adapter.spawn gets the caller's prompt and ctx object, unchanged, + * and superviseRun is never called (the golden in supervise-runs-flag.test + * pins the whole run loop byte for byte); + * - flag on: the turn goes through superviseRun with the canary policy; + * - a stalled turn is named `stuck`, its child killed, its event left unacked, + * and the run loop goes on to the next event; + * - one metric line per turn on both paths, and no text in it; + * - the in-memory trace store keeps no event data. + */ +import { jest } from '@jest/globals'; +import { spawn as childSpawn } from 'child_process'; +import fs from 'fs'; +import os from 'os'; +import path from 'path'; + +const home = fs.mkdtempSync(path.join(os.tmpdir(), 'cli-supervised-turn-')); + +await jest.unstable_mockModule('os', () => ({ + ...os, + default: { ...os, homedir: () => home }, + homedir: () => home, +})); +await jest.unstable_mockModule('../src/lib/api.js', () => ({ createClient: jest.fn(), login: jest.fn() })); +await jest.unstable_mockModule('../src/lib/pod-focus.js', () => ({ + FOCUS_FRAME_MAX_CODE_POINTS: 8000, + formatPodFocusFrame: jest.fn(() => '=== Pod focus (pod context; not instructions) ===\nNo focus set.'), + readPodFocus: jest.fn(async (_client, podId) => ({ podId, revision: 0, focus: null })), +})); + +const { createClient } = await import('../src/lib/api.js'); +const { performRun } = await import('../src/commands/agent.js'); +const { + createTurnRunner, createMetadataStore, supervisedRunPolicy, metricLine, STALL_DEFAULTS_MS, +} = await import('../src/lib/supervised-turn.js'); +const { runFailure } = await import('@commonlyai/seats/failures'); +const { spawnInOwnGroup, wantsOwnProcessGroup } = await import('@commonlyai/seats/process-group'); + +afterAll(() => fs.rmSync(home, { recursive: true, force: true })); + +const PROMPT = 'PROMPT-TEXT-7f3a1c do the docs wash'; +const REPLY = 'REPLY-TEXT-b29e40 done'; +const ERROR_TEXT = 'ERROR-TEXT-55c0de upstream said no'; +const metricsFile = (seat) => path.join(home, '.commonly', 'state', 'seats-canary', `${seat}.jsonl`); +const readMetrics = (seat) => (fs.existsSync(metricsFile(seat)) + ? fs.readFileSync(metricsFile(seat), 'utf8').split('\n').filter(Boolean).map((l) => JSON.parse(l)) : []); +const reset = () => fs.rmSync(path.join(home, '.commonly'), { recursive: true, force: true }); + +const METRIC_KEYS = [ + 'v', 'ts', 'seat', 'adapter', 'path', 'eventType', 'turnStart', 'turnEnd', 'durationMs', 'outcome', 'failure', + 'failureSource', 'failureClass', 'stalled', 'cancelled', 'killed', 'exitCode', 'signal', 'exitObserved', + 'childLeftRunning', 'attempts', 'stallMs', 'cancelGraceMs', 'timeoutMs', +].sort(); + +// A real child that never writes and never exits on its own. Every one is +// tracked: after each test any still running is killed and the test FAILS, so +// a supervisor that does not kill (or a mutant that skips it) cannot leave a +// child holding jest open. +const spawned = new Set(); +const silentChild = () => { + const child = childSpawn(process.execPath, ['-e', 'setInterval(() => {}, 1000)'], { stdio: ['ignore', 'pipe', 'pipe'] }); + spawned.add(child); + return child; +}; +// A zombie (exited, not yet reaped by whoever adopted it) is not running. +const isZombie = (pid) => { + try { return /^\d+ \(.*\) Z /.test(fs.readFileSync(`/proc/${pid}/stat`, 'utf8')); } catch { return false; } +}; +const isRunning = (pid) => { + try { process.kill(pid, 0); } catch (e) { return e.code !== 'ESRCH'; } + return !isZombie(pid); +}; +const strayPids = new Set(); +afterEach(async () => { + const strays = [...strayPids].filter(isRunning); + strayPids.clear(); + for (const pid of strays) { try { process.kill(pid, 'SIGKILL'); } catch { /* gone */ } } + expect(strays.map((pid) => `grandchild ${pid} outlived its test`)).toEqual([]); + const leaked = [...spawned].filter((child) => child.exitCode === null && child.signalCode === null); + spawned.clear(); + for (const child of leaked) child.kill('SIGKILL'); + await Promise.all(leaked.map((child) => new Promise((resolve) => { + if (child.exitCode !== null || child.signalCode !== null) resolve(); else child.once('exit', resolve); + }))); + expect(leaked.map((child) => `child ${child.pid} outlived its test`)).toEqual([]); +}); + +describe('policy defaults', () => { + test('codex stalls at 15 min, claude has no stall window, both get grace 15 s and the wall past the turn budget', () => { + expect(STALL_DEFAULTS_MS).toEqual({ codex: 900_000, claude: 0 }); + expect(supervisedRunPolicy(2_700_000, { adapterName: 'codex', env: {} })) + .toEqual({ stallMs: 900_000, cancelGraceMs: 15_000, timeoutMs: 2_760_000 }); + expect(supervisedRunPolicy(2_700_000, { adapterName: 'claude', env: {} }).stallMs).toBe(0); + expect(supervisedRunPolicy(1000, { adapterName: 'stub', env: {} }).stallMs).toBe(0); + }); + + test('env overrides, most specific first; a bad value is ignored with a warning', () => { + const env = { COMMONLY_SUPERVISE_STALL_MS: '600000', COMMONLY_SUPERVISE_STALL_MS_CLAUDE: '1800000' }; + expect(supervisedRunPolicy(10, { adapterName: 'codex', env }).stallMs).toBe(600_000); + expect(supervisedRunPolicy(10, { adapterName: 'claude', env }).stallMs).toBe(1_800_000); + const warnings = []; + expect(supervisedRunPolicy(10, { + adapterName: 'codex', env: { COMMONLY_SUPERVISE_STALL_MS_CODEX: '-5', COMMONLY_SUPERVISE_CANCEL_GRACE_MS: '2000' }, warnings, + })).toEqual({ stallMs: 900_000, cancelGraceMs: 2000, timeoutMs: 60_010 }); + expect(warnings).toEqual([expect.stringContaining('COMMONLY_SUPERVISE_STALL_MS_CODEX ignored')]); + }); +}); + +describe('the turn runner', () => { + beforeEach(reset); + + test('flag off: adapter.spawn gets the same prompt and the same ctx object, and superviseRun is not called', async () => { + const superviseRun = jest.fn(); + const spawn = jest.fn(async () => ({ text: REPLY })); + const ctx = { cwd: '/w', env: process.env, timeoutMs: 5 }; + const runner = createTurnRunner({ seat: 'quire', turnTimeoutMs: 5, supervise: false, superviseRun, env: {} }); + await expect(runner.run({ name: 'claude', spawn }, PROMPT, ctx, { eventType: 'chat.mention' })).resolves.toEqual({ text: REPLY }); + expect(spawn).toHaveBeenCalledTimes(1); + expect(spawn.mock.calls[0][0]).toBe(PROMPT); + expect(spawn.mock.calls[0][1]).toBe(ctx); + expect(Object.keys(ctx)).toEqual(['cwd', 'env', 'timeoutMs']); + expect(superviseRun).not.toHaveBeenCalled(); + }); + + test('flag on: the turn goes through superviseRun with the canary policy and a no-record store, and no relay', async () => { + const superviseRun = jest.fn(async ({ store }) => { + store.startRun({}).emit('run.settled', { outcome: 'ok' }); + return { outcome: 'ok', attempts: 1, result: { text: REPLY } }; + }); + const spawn = jest.fn(); + const runner = createTurnRunner({ seat: 'nib', turnTimeoutMs: 2_700_000, supervise: true, superviseRun, env: {} }); + await expect(runner.run({ name: 'codex', spawn }, PROMPT, { cwd: '/w' }, { eventType: 'inbox.batch' })) + .resolves.toEqual({ text: REPLY }); + expect(spawn).not.toHaveBeenCalled(); + expect(superviseRun).toHaveBeenCalledTimes(1); + const args = superviseRun.mock.calls[0][0]; + expect(args.prompt).toBe(PROMPT); + expect(args.policy).toEqual({ stallMs: 900_000, cancelGraceMs: 15_000, timeoutMs: 2_760_000 }); + expect(args).not.toHaveProperty('relay'); + expect(typeof args.ctx.onSpawn).toBe('function'); + expect(args.label).toBe('inbox.batch'); + }); + + test('a stalled real child is named stuck, killed, and thrown; the metric line says so', async () => { + // Under a mutant that never supervises, run() never settles: race it so the test fails, not hangs. + const within = (promise, ms) => Promise.race([promise, new Promise((_, reject) => { + setTimeout(() => reject(new Error(`no settle in ${ms}ms`)), ms).unref(); + })]); + const env = { COMMONLY_SUPERVISE_STALL_MS: '60', COMMONLY_SUPERVISE_CANCEL_GRACE_MS: '40' }; + const logs = []; + let pid; + const adapter = { + name: 'codex', + // Ignores the abort, so the supervisor has to kill. + spawn: (_prompt, ctx) => new Promise(() => { + const child = silentChild(); + pid = child.pid; + child.once('spawn', () => ctx.onSpawn({}, child)); + }), + }; + const runner = createTurnRunner({ seat: 'nib', turnTimeoutMs: 60_000, supervise: true, env, log: (l) => logs.push(l) }); + const error = await within(runner.run(adapter, PROMPT, {}, { eventType: 'chat.mention' }), 5000).catch((e) => e); + expect(error.kind).toBe('stuck'); + expect(isRunning(pid)).toBe(false); + expect(logs).toEqual([expect.stringMatching(/^\[chat\.mention\] supervised turn failed: stuck \(child killed\)$/)]); + expect(readMetrics('nib')).toEqual([expect.objectContaining({ + path: 'supervised', outcome: 'failed', failure: 'stuck', failureSource: 'supervisor', stalled: true, + cancelled: true, killed: true, signal: 'SIGKILL', exitObserved: true, childLeftRunning: false, stallMs: 60, + })]); + }); + + test('a stalled child in its own group is killed with its grandchild (group kill on the canary path)', async () => { + const env = { COMMONLY_SUPERVISE_STALL_MS: '500', COMMONLY_SUPERVISE_CANCEL_GRACE_MS: '40' }; + // The CLI stand-in starts a grandchild in a group of its own (as codex does + // for MCP servers), reports its pid on stderr, then goes quiet. + const script = "const c=require('child_process').spawn(process.execPath,['-e','setInterval(()=>{},1000)'],{detached:true,stdio:'ignore'});" + + "process.stderr.write(c.pid+'\\n');setInterval(()=>{},1000);"; + let child; + let ownGroup; + let grandchild = null; + const adapter = { + name: 'codex', + spawn: (_prompt, ctx) => new Promise(() => { + ownGroup = wantsOwnProcessGroup(ctx); + child = spawnInOwnGroup(childSpawn, process.execPath, ['-e', script], { stdio: ['ignore', 'pipe', 'pipe'] }, { ownGroup }); + spawned.add(child); + child.stderr.on('data', (chunk) => { + grandchild = Number(String(chunk).trim()); + strayPids.add(grandchild); + }); + child.once('spawn', () => ctx.onSpawn({}, child)); + }), + }; + const runner = createTurnRunner({ seat: 'nib', turnTimeoutMs: 60_000, supervise: true, env }); + const error = await runner.run(adapter, PROMPT, {}, { eventType: 'chat.mention' }).catch((e) => e); + expect(error.kind).toBe('stuck'); + expect(ownGroup).toBe(process.platform !== 'win32'); + expect(Number.isInteger(grandchild)).toBe(true); + const deadline = Date.now() + 2000; + while ((isRunning(child.pid) || isRunning(grandchild)) && Date.now() < deadline) { + // eslint-disable-next-line no-await-in-loop + await new Promise((r) => setTimeout(r, 20)); + } + expect(isRunning(child.pid)).toBe(false); + expect(isRunning(grandchild)).toBe(false); + }, 15_000); + + test('one metric line per turn on both paths, and none of them carries text', async () => { + const env = { COMMONLY_SUPERVISE_STALL_MS: '0' }; + const ok = { name: 'codex', spawn: async () => ({ text: REPLY }) }; + const bad = { name: 'codex', spawn: async () => { throw new Error(`codex exited with code 3: ${ERROR_TEXT}`); } }; + const named = { name: 'codex', spawn: async () => { throw runFailure('exited', ERROR_TEXT); } }; + const plain = createTurnRunner({ seat: 'nib', turnTimeoutMs: 1000, supervise: false, env }); + const supervised = createTurnRunner({ seat: 'nib', turnTimeoutMs: 1000, supervise: true, env }); + await plain.run(ok, PROMPT, {}, { eventType: 'chat.mention' }); + await plain.run(bad, PROMPT, {}, { eventType: 'chat.mention' }).catch(() => {}); + await supervised.run(ok, PROMPT, {}, { eventType: 'inbox.batch' }); + await supervised.run(bad, PROMPT, {}, { eventType: 'inbox.batch' }).catch(() => {}); + await supervised.run(named, PROMPT, {}, { eventType: 'inbox.batch' }).catch(() => {}); + + const lines = readMetrics('nib'); + expect(lines.map((l) => [l.path, l.outcome, l.failure])).toEqual([ + ['legacy', 'ok', null], + ['legacy', 'failed', 'adapter_exit'], + ['supervised', 'ok', null], + ['supervised', 'failed', 'adapter_exit'], + ['supervised', 'failed', 'exited'], + ]); + expect(lines[1].exitCode).toBe(3); + for (const line of lines) { + expect(Object.keys(line).sort()).toEqual(METRIC_KEYS); + for (const value of Object.values(line)) { + expect(['string', 'number', 'boolean'].includes(typeof value) || value === null).toBe(true); + } + } + const raw = fs.readFileSync(metricsFile('nib'), 'utf8'); + for (const text of [PROMPT, REPLY, ERROR_TEXT, 'PROMPT-TEXT', 'REPLY-TEXT', 'ERROR-TEXT']) expect(raw).not.toContain(text); + }); + + test('metricLine drops anything it does not list', () => { + const line = metricLine({ + seat: 'nib', adapter: 'codex', path: 'legacy', startMs: 0, endMs: 5, ok: true, text: REPLY, prompt: PROMPT, detail: ERROR_TEXT, + }); + expect(Object.keys(line).sort()).toEqual(METRIC_KEYS); + expect(JSON.stringify(line)).not.toMatch(/TEXT-/); + }); + + test('a metrics write failure never fails a turn, and is said once', async () => { + const blocker = path.join(home, 'not-a-dir'); + fs.writeFileSync(blocker, ''); + const logs = []; + const runner = createTurnRunner({ + seat: 'nib', turnTimeoutMs: 1000, supervise: false, env: { COMMONLY_SEATS_CANARY_DIR: path.join(blocker, 'x') }, log: (l) => logs.push(l), + }); + const adapter = { name: 'codex', spawn: async () => ({ text: REPLY }) }; + await expect(runner.run(adapter, PROMPT, {}, {})).resolves.toEqual({ text: REPLY }); + await runner.run(adapter, PROMPT, {}, {}); + expect(logs).toEqual([expect.stringMatching(/^turn metrics not written/)]); + }); +}); + +describe('the metadata store', () => { + test('keeps type, time and the recovery action, never event data', () => { + const run = createMetadataStore().startRun({}); + run.emit('agent.message_chunk', { text: REPLY }); + run.emit('liveness.recovery', { action: 'kill', attempt: 1 }); + run.emit('run.settled', { outcome: 'failed', failure: { kind: 'stuck', detail: ERROR_TEXT } }); + expect(run.emit('usage', {})).toBeNull(); + expect(JSON.stringify(run.events())).not.toMatch(/TEXT-/); + expect(run.events().map(({ type, action }) => [type, action ?? null])) + .toEqual([['agent.message_chunk', null], ['liveness.recovery', 'kill'], ['run.settled', null]]); + expect(() => run.emit('not.a.type', {})).toThrow(/unknown trace event type/); + }); +}); + +// ── in the run loop ───────────────────────────────────────────────────────── + +const POD = '6a8f6dc7a1dccf2e02f31015'; +const event = (id) => ({ + _id: id, type: 'chat.mention', podId: POD, agentName: 'nib', instanceId: 'default', + payload: { content: `@nib ${PROMPT} (${id})`, messageId: id.replace(/\D/g, '') || '1', username: 'growth-ops' }, +}); + +const loop = ({ batches, adapter, superviseRuns, env = {} }) => { + let polls = 0; + const get = jest.fn(async (route) => { + if (route === '/api/agents/runtime/events') { polls += 1; return { events: batches[polls - 1] || [] }; } + if (route === '/api/agents/runtime/memory') return { sections: {} }; + if (String(route).endsWith('/messages')) return { messages: [] }; + return {}; + }); + const post = jest.fn(async (route) => (String(route).endsWith('/claim') ? { claimed: true, expiresAt: 'later' } : {})); + createClient.mockReturnValue({ get, post, del: jest.fn().mockResolvedValue({}) }); + const saved = Object.fromEntries(Object.keys(env).map((k) => [k, process.env[k]])); + Object.assign(process.env, env); + const logs = []; + const errors = []; + const scheduled = []; + const handle = performRun({ + instanceUrl: 'http://localhost:5000', + token: 'cm_agent_test', + adapter, + agentName: 'nib', + environment: { model: 'gpt-test' }, + retryJitterRatio: 0, + claimYieldDelayMs: 0, + sleepImpl: async () => {}, + superviseRuns, + log: (line) => logs.push(String(line)), + onError: (err) => errors.push(err), + setTimeoutImpl: (callback, delayMs) => { scheduled.push({ callback, delayMs }); return 0; }, + }); + const restore = () => { for (const [k, v] of Object.entries(saved)) { if (v === undefined) delete process.env[k]; else process.env[k] = v; } }; + const acks = () => post.mock.calls.filter(([r]) => String(r).endsWith('/ack')).map(([r, b]) => ({ id: String(r).split('/').at(-2), result: b.result })); + return { handle, logs, errors, scheduled, acks, restore }; +}; + +const until = async (predicate, ms = 10_000) => { + const deadline = Date.now() + ms; + while (!predicate() && Date.now() < deadline) { + // eslint-disable-next-line no-await-in-loop + await new Promise((r) => setTimeout(r, 10)); + } + if (!predicate()) throw new Error('condition not met in time'); +}; + +describe('the run loop', () => { + jest.setTimeout(30_000); + beforeEach(() => { jest.clearAllMocks(); reset(); }); + + test.each([[false, 'legacy'], [true, 'supervised']])('superviseRuns=%s routes the spawn on the %s path', async (superviseRuns, pathName) => { + const ctxs = []; + const adapter = { name: 'codex', detect: async () => null, spawn: async (_p, ctx) => { ctxs.push(ctx); return { text: REPLY }; } }; + const run = loop({ batches: [[event('evt-1')]], adapter, superviseRuns, env: {} }); + try { + await until(() => run.acks().length === 1); + } finally { run.handle.stop(); run.restore(); } + // Only superviseRun hands an adapter a cancel signal and a trace hook. + expect('signal' in ctxs[0]).toBe(superviseRuns); + expect('trace' in ctxs[0]).toBe(superviseRuns); + expect(readMetrics('nib').map((l) => l.path)).toEqual([pathName]); + expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); + }); + + test('a stalled turn is named stuck in the log, surfaces like any failed turn, and its held event is retried', async () => { + let first = true; + let pid; + const adapter = { + name: 'codex', + detect: async () => null, + spawn: (_p, ctx) => { + if (!first) return Promise.resolve({ text: REPLY }); + first = false; + return new Promise(() => { + const child = silentChild(); + pid = child.pid; + child.once('spawn', () => ctx.onSpawn({}, child)); + }); + }, + }; + const run = loop({ + batches: [[event('evt-a')], [event('evt-b')]], + adapter, + superviseRuns: true, + env: { COMMONLY_SUPERVISE_STALL_MS: '60', COMMONLY_SUPERVISE_CANCEL_GRACE_MS: '40' }, + }); + try { + await until(() => run.errors.length === 1 && run.scheduled.length === 1); + // The run loop takes a single event or an inbox batch; either way the + // turn is named in the seat log and surfaces through onError. + expect(run.logs).toEqual(expect.arrayContaining([ + expect.stringMatching(/^\[(chat\.mention|inbox\.batch)\] supervised turn failed: stuck \(child killed\)$/), + ])); + expect(run.errors[0]).toMatchObject({ code: 'agent_spawn_retry_scheduled', eventId: 'evt-a' }); + expect(run.errors[0].message).toMatch(/retrying 1 held event in \d+s: stuck: no progress signal/); + expect(run.acks()).toEqual([]); + expect(isRunning(pid)).toBe(false); + // The retry re-runs the held event (it is still claimed by this runner, + // so no poll could return it); the next poll's event is served too. + run.scheduled.shift().callback(); + await until(() => ['evt-a', 'evt-b'].every((id) => run.acks().some((a) => a.id === id))); + expect(run.acks().filter((a) => a.id === 'evt-a')).toEqual([{ id: 'evt-a', result: { outcome: 'posted' } }]); + } finally { run.handle.stop(); run.restore(); } + const turns = readMetrics('nib').map((l) => [l.path, l.outcome, l.failure, l.killed]); + expect(turns[0]).toEqual(['supervised', 'failed', 'stuck', true]); + expect(turns.slice(1).length).toBeGreaterThan(0); + for (const turn of turns.slice(1)) expect(turn).toEqual(['supervised', 'ok', null, false]); + }); +}); diff --git a/cli/scripts/seat-log-baseline.mjs b/cli/scripts/seat-log-baseline.mjs new file mode 100644 index 0000000000..3aa1cba418 --- /dev/null +++ b/cli/scripts/seat-log-baseline.mjs @@ -0,0 +1,185 @@ +#!/usr/bin/env node +/** + * Offline baseline of a seat's turns, from its wrapper log + * (~/.commonly/logs/.log), for the window before the seats canary + * switch, to compare against ~/.commonly/state/seats-canary/.jsonl. + * + * node cli/scripts/seat-log-baseline.mjs [--until ] [--hours 48] + * [--log ] [--timeout-ms 2700000] [--json] + * + * Reads only timestamps and the wrapper's own fixed phrases. It never prints a + * line's free text: a failure line's tail (the CLI's stderr) is reduced to a + * name (adapter_timeout | adapter_exit | adapter_error), and lines with + * no timestamp (raw stderr, HTML error pages) are counted, not shown. + * + * A turn opens at "[] spawning " and closes at the first of: + * - "spawn credential revoked" (the spawn returned; the outcome line follows) + * - "processing failed" (the spawn threw; failed) + * - a restart ("stopping after the current turn" / "polling … for events") + * or the next "spawning" (no close seen; counted as unclosed) + * A turn still open at the end of the window is "open", not a hang. + */ +import fs from 'fs'; +import os from 'os'; +import path from 'path'; + +export const LIMITS = [ + 'exit codes and signals of turns that succeeded (the log names a code only when a turn failed)', + 'whether a kill fired, and whether a child outlived its turn (the old path logs neither)', + 'quiet gaps inside a turn: the log has no mid-turn liveness, so a stall cannot be told from long work; only the 45-minute timeout shows', + 'in-band provider refusals the CLI swallowed (refusal_dropped): an exit 0 with an empty or refused reply reads as an ordinary turn', + 'turns cut by a restart: the end time is the restart, not the child\'s exit, and the outcome is unknown', + 'whether "posted via tool" posted the right thing, or why a NO_REPLY was chosen', + 'anything before the log was rotated or after it stopped being written', +]; + +const LINE_RE = /^(\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d(?:\.\d+)?Z) \[([^\]]+)\] (.*)$/; +const SPAWN_RE = /^\[([A-Za-z0-9._-]{1,40})\] spawning ([a-z0-9-]{1,32})$/; + +const outcomeOf = (msg) => { + if (/no wrapper-post \(NO_REPLY\)/.test(msg)) return 'no_reply'; + if (/no wrapper-post \(empty output\)/.test(msg)) return 'empty_output'; + if (/agent posted via tool/.test(msg) || /posted via tool, then/.test(msg)) return 'posted_via_tool'; + if (/\bposted \d+ bytes\b/.test(msg)) return 'wrapper_posted'; + if (/routed private response/.test(msg)) return 'private_response'; + if (/server skipped the post/.test(msg)) return 'server_skipped'; + if (/wrapper delivery refused/.test(msg)) return 'delivery_refused'; + return null; +}; + +const failureOf = (msg) => { + const timeout = /\btimed out after (\d+)ms\b/.exec(msg); + if (timeout) return { name: 'adapter_timeout', timeoutMs: Number(timeout[1]) }; + const exit = /\bexited with code (-?\d+)\b/.exec(msg); + if (exit) return { name: 'adapter_exit', exitCode: Number(exit[1]) }; + return { name: 'adapter_error' }; +}; + +const pct = (sorted, p) => (sorted.length ? sorted[Math.min(sorted.length - 1, Math.ceil((p / 100) * sorted.length) - 1)] : null); + +export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeoutMs = 2_700_000 } = {}) => { + const fromMs = untilMs - hours * 3_600_000; + const turns = []; + let open = null; + const counts = { untimestamped: 0, pollErrors: 0, restarts: 0, otherSeatLines: 0 }; + const close = (turn, fields) => { Object.assign(turn, fields); turns.push(turn); }; + + for (const line of text.split('\n')) { + if (!line) continue; + const m = LINE_RE.exec(line); + if (!m) { counts.untimestamped += 1; continue; } + const [, ts, who, msg] = m; + const at = Date.parse(ts); + if (seat && who !== seat) { counts.otherSeatLines += 1; continue; } + if (at < fromMs || at > untilMs) { + // A turn that opened inside the window may close just past it; let it. + if (!(open && at > untilMs)) continue; + } + const spawn = SPAWN_RE.exec(msg); + if (spawn) { + if (open) close(open, { endMs: at, ended: 'unclosed' }); + if (at > untilMs) { open = null; break; } + open = { startMs: at, eventType: spawn[1], adapter: spawn[2] }; + continue; + } + if (/^stopping after the current turn/.test(msg) || /^polling \S+ for events/.test(msg)) { + if (at <= untilMs) counts.restarts += /^polling/.test(msg) ? 1 : 0; + if (open) { close(open, { endMs: at, ended: 'restart' }); open = null; } + continue; + } + if (/^(fetch failed|poll failed|HTTP \d{3}\b)/.test(msg)) { if (at <= untilMs) counts.pollErrors += 1; continue; } + if (!open) continue; + if (/processing failed/.test(msg)) { + close(open, { endMs: at, ended: 'failed', ...failureOf(msg) }); + open = null; + continue; + } + if (/^spawn credential revoked\b/.test(msg)) { open.revokedMs = at; continue; } + const outcome = outcomeOf(msg); + if (outcome && open.revokedMs !== undefined) { + close(open, { endMs: open.revokedMs, ended: 'ok', outcome }); + open = null; + } + } + if (open) { + if (open.revokedMs !== undefined) close(open, { endMs: open.revokedMs, ended: 'ok', outcome: 'unknown' }); + else close(open, { endMs: null, ended: 'open' }); + } + + const byAdapter = {}; + for (const t of turns) { + const a = (byAdapter[t.adapter] ||= { + turns: 0, ok: 0, failed: 0, timeouts: 0, exits: {}, errors: 0, unclosed: 0, cutByRestart: 0, open: 0, + atOrOverTimeout: 0, outcomes: {}, durations: [], + }); + a.turns += 1; + if (t.endMs !== null) t.durationMs = t.endMs - t.startMs; + if (t.ended === 'ok') { a.ok += 1; a.outcomes[t.outcome] = (a.outcomes[t.outcome] || 0) + 1; } + if (t.ended === 'failed') { + a.failed += 1; + if (t.name === 'adapter_timeout') a.timeouts += 1; + else if (t.name === 'adapter_exit') a.exits[t.exitCode] = (a.exits[t.exitCode] || 0) + 1; + else a.errors += 1; + } + if (t.ended === 'unclosed') a.unclosed += 1; + if (t.ended === 'restart') a.cutByRestart += 1; + if (t.ended === 'open') a.open += 1; + if (t.durationMs !== undefined) { + a.durations.push(t.durationMs); + if (t.durationMs >= timeoutMs) a.atOrOverTimeout += 1; + } + } + for (const a of Object.values(byAdapter)) { + const d = a.durations.sort((x, y) => x - y); + a.durationMs = d.length ? { p50: pct(d, 50), p90: pct(d, 90), p99: pct(d, 99), max: d[d.length - 1], n: d.length } : null; + delete a.durations; + } + return { + seat: seat || null, + window: { from: new Date(fromMs).toISOString(), until: new Date(untilMs).toISOString(), hours }, + turnTimeoutMs: timeoutMs, + byAdapter, + counts, + cannotTell: LIMITS, + }; +}; + +const fmtMs = (ms) => (ms === null || ms === undefined ? '-' : ms >= 60_000 ? `${(ms / 60_000).toFixed(1)}m` : `${(ms / 1000).toFixed(1)}s`); + +export const render = (r) => { + const out = [`seat ${r.seat}: ${r.window.from} → ${r.window.until} (${r.window.hours}h), turn budget ${fmtMs(r.turnTimeoutMs)}`]; + const adapters = Object.entries(r.byAdapter); + if (!adapters.length) out.push(' no turns in the window'); + for (const [name, a] of adapters) { + out.push(` ${name}: ${a.turns} turns, ${a.ok} ok, ${a.failed} failed` + + ` (${a.timeouts} timed out, exits ${JSON.stringify(a.exits)}, ${a.errors} other)` + + `, ${a.cutByRestart} cut by restart, ${a.unclosed} unclosed, ${a.open} still open at the window end`); + out.push(` reached the turn budget: ${a.atOrOverTimeout}`); + if (a.durationMs) out.push(` duration p50 ${fmtMs(a.durationMs.p50)} p90 ${fmtMs(a.durationMs.p90)} p99 ${fmtMs(a.durationMs.p99)} max ${fmtMs(a.durationMs.max)} (n=${a.durationMs.n})`); + out.push(` outcomes ${JSON.stringify(a.outcomes)}`); + } + out.push(` restarts ${r.counts.restarts}, poll errors ${r.counts.pollErrors}, untimestamped lines (whole log) ${r.counts.untimestamped}`); + out.push(' the log cannot tell:'); + for (const l of r.cannotTell) out.push(` - ${l}`); + return out.join('\n'); +}; + +const main = (argv) => { + const args = [...argv]; + const seat = args.shift(); + if (!seat || seat.startsWith('-')) { + process.stderr.write('usage: seat-log-baseline.mjs [--until ] [--hours 48] [--log ] [--timeout-ms 2700000] [--json]\n'); + return 2; + } + const opt = (name, fallback) => { const i = args.indexOf(name); return i >= 0 ? args[i + 1] : fallback; }; + const untilMs = opt('--until') ? Date.parse(opt('--until')) : Date.now(); + if (Number.isNaN(untilMs)) { process.stderr.write('--until is not a date\n'); return 2; } + const logPath = opt('--log', path.join(os.homedir(), '.commonly', 'logs', `${seat}.log`)); + const result = baseline(fs.readFileSync(logPath, 'utf8'), { + seat, untilMs, hours: Number(opt('--hours', 48)), timeoutMs: Number(opt('--timeout-ms', 2_700_000)), + }); + process.stdout.write(`${args.includes('--json') ? JSON.stringify(result, null, 2) : render(result)}\n`); + return 0; +}; + +if (import.meta.url === `file://${process.argv[1]}`) process.exitCode = main(process.argv.slice(2)); diff --git a/cli/src/commands/agent.js b/cli/src/commands/agent.js index d6325b1c65..e0685413cb 100644 --- a/cli/src/commands/agent.js +++ b/cli/src/commands/agent.js @@ -91,6 +91,7 @@ import { prepareMcpBeforeFirstPoll } from '../lib/mcp-first-run.js'; import { createSeatStop } from '../lib/seat-stop.js'; import { detectSeatbelt } from '../lib/sandbox/seatbelt.js'; import { describeUpstreamRefusal } from '../lib/upstream-refusal.js'; +import { createTurnRunner, supervisedRunPolicy } from '../lib/supervised-turn.js'; import { DEFAULT_HOOK_TIMEOUT_MS, clampHookTimeoutMs, @@ -1384,6 +1385,11 @@ const extractPrompt = (event) => { * Every enforcement failure fails OPEN — a kernel without the claim route or * an unreachable upload endpoint must never produce a silent agent (#887). */ +// The supervisor's policy for a run-loop spawn: lib/supervised-turn.js has the +// stall windows per adapter (codex 15 min, claude off) and their evidence, the +// cancel grace, and the wall-clock backstop past the adapter's own timeout. +export { supervisedRunPolicy }; + export const performRun = ({ instanceUrl, token, @@ -1431,6 +1437,12 @@ export const performRun = ({ resolveOwnProviderKey = null, runtimeReportClient = null, refusalHandoff = null, + // Off unless COMMONLY_SUPERVISE_RUNS=1: each spawn runs under the seats + // supervisor (stall window, wall-clock backstop, a named failure on every + // settle). The CLI still talks to its provider directly. Off, the spawn path + // is the plain adapter call it has always been. Either way one metadata line + // per turn goes to ~/.commonly/state/seats-canary/.jsonl. + superviseRuns = process.env.COMMONLY_SUPERVISE_RUNS === '1', }) => { reportRuntime = reportRuntime && WALKED_HARNESSES.includes(adapter?.name); if (environment?.provider !== undefined && !adapter?.supportsProvider) { @@ -1440,6 +1452,12 @@ export const performRun = ({ const effectiveTurnTimeoutMs = Number.isFinite(requestedTurnTimeout) && requestedTurnTimeout > 0 ? Math.min(requestedTurnTimeout, 2_147_483_647) : 15 * 60 * 1000; const client = createClient({ instance: instanceUrl, token }); + // The supervised run keeps its trace in memory, metadata only; no record of + // a run is written to disk on either path (lib/supervised-turn.js). + const turnRunner = createTurnRunner({ + seat: agentName, turnTimeoutMs: effectiveTurnTimeoutMs, supervise: superviseRuns, log, + }); + if (superviseRuns) log(turnRunner.describe(adapter?.name)); const runtimeReporter = createRuntimeReporter({ client: runtimeReportClient || { post: async () => {} }, harness: adapter.name, detect: () => adapter.detect(), @@ -2076,7 +2094,8 @@ export const performRun = ({ reason: 'own-key-requires-scoped-spawn' }; } } - result = await adapter.spawn(frameDecisionForkRule(promptForSpawn), { + const spawnPrompt = frameDecisionForkRule(promptForSpawn); + const spawnCtx = { onSpawn: reportRuntime ? (controls) => { observedSpawn = true; return runtimeReporter.spawn(controls); @@ -2108,7 +2127,10 @@ export const performRun = ({ instanceUrl, agentName, metadata: { event }, - }); + }; + // Supervised or plain, a failure is thrown exactly as the adapter's own + // would be, so the run loop's classification and retry apply unchanged. + result = await turnRunner.run(adapter, spawnPrompt, spawnCtx, { eventType: event.type }); spawnCompleted = true; } finally { try { diff --git a/cli/src/lib/supervised-turn.js b/cli/src/lib/supervised-turn.js new file mode 100644 index 0000000000..4731945229 --- /dev/null +++ b/cli/src/lib/supervised-turn.js @@ -0,0 +1,340 @@ +/** + * One model turn of `commonly agent run`, on one of two paths, and one + * metadata line per turn on BOTH so they can be compared (the seats canary). + * + * COMMONLY_SUPERVISE_RUNS=1 (read by performRun as `superviseRuns`) + * the turn runs under `superviseRun` from @commonlyai/seats: a stall + * window, a wall-clock backstop, and a guarantee the turn settles with a + * named failure. No provider relay: the CLI talks to its provider directly, + * exactly as on the plain path. + * anything else + * the plain path: `adapter.spawn(prompt, ctx)` with the caller's ctx object + * untouched. Only the metric line is new. + * + * NO RECORD WRITER. The supervisor needs a trace store. The one here + * (createMetadataStore) is in memory, lives for one turn, and keeps event type + * names, times and the recovery action word. It drops every event's data, so + * no agent text, prompt, reply, failure detail or credential is kept, and + * nothing is written to disk (CTO's redact blocker on #2701). + * + * Metrics: ~/.commonly/state/seats-canary/.jsonl (COMMONLY_SEATS_CANARY_DIR + * overrides the directory). Whitelisted fields only; see metricLine. + */ +import { appendFileSync, mkdirSync } from 'fs'; +import { homedir } from 'os'; +import { dirname, join } from 'path'; +import { superviseRun as defaultSuperviseRun } from '@commonlyai/seats/supervisor'; +import { isEventType } from '@commonlyai/seats/trace/events'; +import { failureKindOf } from '@commonlyai/seats/failures'; +import { classifySpawnFailure } from './spawn-retry.js'; + +const MAX_TIMER_MS = 2_147_483_647; + +/** + * Stall windows per adapter, in ms; 0 is off. Unlisted adapters: off. + * + * codex: `codex exec --json` writes a JSONL event per item, so its stdout is a + * real progress signal, and the quiet stretch is the longest single item (a + * reasoning step or one shell command). Measured 2026-10-25 from per-turn + * timestamp gaps in this host's October codex rollouts (~/.codex/sessions): + * 9,703 turns, max quiet gap 162 s, p99 53 s; 9 turns would have tripped the + * package default of 120 s. 15 min is 5.5x the worst gap seen and still + * 30 min inside the seats' 45 min turn budget. + * claude: the adapter runs `claude -p --output-format text`, which writes + * nothing to stdout until the reply is done. A healthy 14-minute quire turn + * (in its log) is 14 minutes of silence to the supervisor, so any window + * under the turn budget would be a turn-length cap, not a liveness check. + * Off; claude is guarded by the wall-clock backstop and the cancel ladder. + */ +export const STALL_DEFAULTS_MS = Object.freeze({ codex: 15 * 60 * 1000, claude: 0 }); +// How long after the supervisor's abort before it SIGKILLs the child's tree +// (process-group.js). The claude and codex adapters do not act on the abort, +// so on a stall the child is alive at the kill and its whole tree goes with it: +// a SIGTERM to the CLI alone would let it exit first and orphan the MCP +// servers it started in groups of their own, which the tree kill then skips. +// An adapter that honours ctx.signal gets this long to settle. +export const CANCEL_GRACE_MS = 15_000; +// The wall clock sits past the adapter's own timeout, so the adapter's timeout +// (the same SIGTERM and error as on the plain path) fires first; the +// supervisor's only settles a child that outlived it. +export const WALL_BACKSTOP_MS = 60_000; +// After a failed turn, how long to wait for the child's exit status before +// writing the metric line anyway (the kill lands just before settle). +const EXIT_WAIT_MS = 3_000; + +const envName = (prefix, adapterName) => `${prefix}_${String(adapterName || '').toUpperCase().replace(/[^A-Z0-9]/g, '_')}`; + +const envMs = (env, name, warnings) => { + const raw = env?.[name]; + if (raw === undefined || raw === '') return undefined; + const value = Number(raw); + if (!Number.isInteger(value) || value < 0) { + warnings.push(`${name} ignored (want a non-negative integer of ms)`); + return undefined; + } + return Math.min(value, MAX_TIMER_MS); +}; + +/** + * The supervisor policy for one adapter's turn. Env overrides, most specific + * first: COMMONLY_SUPERVISE_STALL_MS_, COMMONLY_SUPERVISE_STALL_MS, + * COMMONLY_SUPERVISE_CANCEL_GRACE_MS, COMMONLY_SUPERVISE_WALL_BACKSTOP_MS. + * 0 turns a window off. No retries: the run loop keeps those. + */ +export const supervisedRunPolicy = (turnTimeoutMs, { adapterName = null, env = process.env, warnings = [] } = {}) => { + const stallMs = envMs(env, envName('COMMONLY_SUPERVISE_STALL_MS', adapterName), warnings) + ?? envMs(env, 'COMMONLY_SUPERVISE_STALL_MS', warnings) + ?? STALL_DEFAULTS_MS[adapterName] ?? 0; + const cancelGraceMs = envMs(env, 'COMMONLY_SUPERVISE_CANCEL_GRACE_MS', warnings) ?? CANCEL_GRACE_MS; + const backstopMs = envMs(env, 'COMMONLY_SUPERVISE_WALL_BACKSTOP_MS', warnings) ?? WALL_BACKSTOP_MS; + return { + stallMs, + cancelGraceMs, + timeoutMs: Math.min(Number(turnTimeoutMs) + backstopMs, MAX_TIMER_MS), + }; +}; + +/** + * A trace store that keeps no agent text and writes nothing. superviseRun + * calls startRun once per turn; each event keeps { type, at, action? }. + */ +export const createMetadataStore = ({ now = Date.now } = {}) => { + let current = null; + let seq = 0; + return { + startRun({ runId } = {}) { + seq += 1; + const events = []; + let settled = false; + current = { + runId: runId || `turn-${now().toString(36)}-${seq}`, + emit(type, data) { + if (!isEventType(type)) throw new Error(`unknown trace event type: ${type}`); + if (settled) return null; + const entry = { type, at: now() }; + if (type === 'liveness.recovery' && typeof data?.action === 'string') entry.action = data.action; + events.push(entry); + if (type === 'run.settled') settled = true; + return entry; + }, + get settled() { return settled; }, + events: () => events.map((entry) => ({ ...entry })), + }; + return current; + }, + lastRun: () => current, + }; +}; + +export const metricsPathFor = (seat, env = process.env) => { + const dir = env?.COMMONLY_SEATS_CANARY_DIR || join(homedir(), '.commonly', 'state', 'seats-canary'); + const safe = String(seat || 'unknown').replace(/[^A-Za-z0-9_.-]/g, '_').slice(0, 64) || 'unknown'; + return join(dir, `${safe}.jsonl`); +}; + +/** A failure's name, never its text. RunFailure kinds are the supervisor's words. */ +export const failureNameOf = (error) => { + const kind = failureKindOf(error) || (typeof error?.kind === 'string' && /^[a-z_]{1,40}$/.test(error.kind) ? error.kind : null); + if (kind) return { name: kind, source: 'supervisor' }; + const message = String(error?.message ?? error ?? ''); + if (/\btimed out after \d+ms\b/.test(message)) return { name: 'adapter_timeout', source: 'adapter' }; + if (/\bexited with code\b/.test(message)) return { name: 'adapter_exit', source: 'adapter' }; + return { name: 'adapter_error', source: 'adapter' }; +}; + +const failureClassOf = (error) => { + try { return classifySpawnFailure(error); } catch { return null; } +}; + +const inferredExitCode = (error) => { + const match = /\bexited with code (-?\d+)\b/.exec(String(error?.message ?? '')); + return match ? Number(match[1]) : null; +}; + +const EVENT_TYPE_RE = /^[A-Za-z0-9._-]{1,40}$/; +const iso = (ms) => new Date(ms).toISOString(); +const int = (value) => (Number.isInteger(value) ? value : null); + +/** + * The metric line. Every field is listed here, each a number, boolean, null or + * a short fixed word; nothing from the prompt, the reply, a failure's detail or + * the environment can reach it. + */ +export const metricLine = (f) => ({ + v: 1, + ts: iso(f.endMs), + seat: String(f.seat || 'unknown').replace(/[^A-Za-z0-9_.-]/g, '_').slice(0, 64), + adapter: String(f.adapter || 'unknown').replace(/[^A-Za-z0-9_.-]/g, '_').slice(0, 32), + path: f.path === 'supervised' ? 'supervised' : 'legacy', + eventType: EVENT_TYPE_RE.test(String(f.eventType || '')) ? f.eventType : null, + turnStart: iso(f.startMs), + turnEnd: iso(f.endMs), + durationMs: Math.max(0, f.endMs - f.startMs), + outcome: f.ok ? 'ok' : 'failed', + failure: f.ok ? null : (f.failureName || 'adapter_error'), + failureSource: f.ok ? null : (f.failureSource || null), + failureClass: f.ok || typeof f.failureClass !== 'string' ? null : f.failureClass, + stalled: !!f.stalled, + cancelled: !!f.cancelled, + killed: !!f.killed, + exitCode: int(f.exitCode), + signal: typeof f.signal === 'string' && /^SIG[A-Z0-9]+$/.test(f.signal) ? f.signal : null, + exitObserved: !!f.exitObserved, + childLeftRunning: typeof f.childLeftRunning === 'boolean' ? f.childLeftRunning : null, + attempts: int(f.attempts), + stallMs: int(f.policy?.stallMs), + cancelGraceMs: int(f.policy?.cancelGraceMs), + timeoutMs: int(f.policy?.timeoutMs), +}); + +const isChild = (value) => !!value && typeof value.once === 'function' && typeof value.kill === 'function'; +const isAlive = (child) => !!child && child.exitCode === null && child.signalCode === null; + +const waitForExit = (child, ms) => new Promise((resolve) => { + if (!isAlive(child)) { resolve(); return; } + const timer = setTimeout(resolve, ms); + timer.unref?.(); + child.once('exit', () => { clearTimeout(timer); resolve(); }); +}); + +/** + * @param {object} args + * @param {string} args.seat agent name; names the metrics file + * @param {number} args.turnTimeoutMs the run loop's effective turn budget + * @param {boolean} args.supervise performRun's superviseRuns + * @param {(line: string) => void} [args.log] + * @param {object} [args.env] + * @param {Function} [args.superviseRun] injectable for tests + */ +export const createTurnRunner = ({ + seat, + turnTimeoutMs, + supervise = false, + log = () => {}, + env = process.env, + now = Date.now, + superviseRun = defaultSuperviseRun, +} = {}) => { + const metricsPath = metricsPathFor(seat, env); + let metricsWarned = false; + + const record = (fields) => { + try { + mkdirSync(dirname(metricsPath), { recursive: true, mode: 0o700 }); + appendFileSync(metricsPath, `${JSON.stringify(metricLine({ seat, ...fields }))}\n`, { mode: 0o600 }); + } catch (error) { + // Metrics never fail a turn. Said once per process, not per turn. + if (!metricsWarned) { + metricsWarned = true; + log(`turn metrics not written (${error?.code || 'error'}); turns are unaffected`); + } + } + }; + + /** The boot line for the supervised path; the plain path logs nothing new. */ + const describe = (adapterName) => { + const warnings = []; + const policy = supervisedRunPolicy(turnTimeoutMs, { adapterName, env, warnings }); + return `supervised runs ON for ${adapterName}: stall=${policy.stallMs ? `${policy.stallMs}ms` : 'off'}, ` + + `cancel grace=${policy.cancelGraceMs}ms, wall=${policy.timeoutMs}ms, ` + + 'trace=memory (no record written); ' + + `metrics → ${metricsPath}${warnings.length ? `; ${warnings.join('; ')}` : ''}`; + }; + + const runPlain = async (adapter, prompt, ctx, eventType) => { + const startMs = now(); + try { + const result = await adapter.spawn(prompt, ctx); + // claude and codex resolve only on exit 0. + record({ adapter: adapter?.name, path: 'legacy', eventType, startMs, endMs: now(), ok: true, exitCode: 0 }); + return result; + } catch (error) { + const { name, source } = failureNameOf(error); + record({ + adapter: adapter?.name, + path: 'legacy', + eventType, + startMs, + endMs: now(), + ok: false, + failureName: name, + failureSource: source, + failureClass: failureClassOf(error), + exitCode: inferredExitCode(error), + }); + throw error; + } + }; + + const runSupervised = async (adapter, prompt, ctx, eventType) => { + const startMs = now(); + const policy = supervisedRunPolicy(turnTimeoutMs, { adapterName: adapter?.name, env }); + const store = createMetadataStore({ now }); + let child = null; + let exit = null; + const callerOnSpawn = ctx?.onSpawn; + const onSpawn = (...args) => { + const proc = args.find(isChild); + if (proc) { + child = proc; + exit = null; + proc.once('exit', (code, signal) => { if (child === proc) exit = { code, signal }; }); + } + return typeof callerOnSpawn === 'function' ? callerOnSpawn(...args) : undefined; + }; + + const supervised = await superviseRun({ + adapter, + prompt, + ctx: { ...ctx, onSpawn }, + store, + policy, + label: EVENT_TYPE_RE.test(String(eventType || '')) ? eventType : undefined, + }); + + const ok = !supervised.failure; + if (!ok) await waitForExit(child, EXIT_WAIT_MS); + const events = store.lastRun()?.events() || []; + const recovered = (action) => events.some((e) => e.type === 'liveness.recovery' && e.action === action); + const killed = recovered('kill'); + const named = ok ? null : failureNameOf(supervised.failure); + record({ + adapter: adapter?.name, + path: 'supervised', + eventType, + startMs, + endMs: now(), + ok, + failureName: named?.name, + failureSource: named?.source, + failureClass: ok ? null : failureClassOf(supervised.failure), + stalled: events.some((e) => e.type === 'liveness.stalled'), + cancelled: recovered('cancel'), + killed, + exitCode: exit ? exit.code : null, + signal: exit ? exit.signal : null, + exitObserved: !!exit, + childLeftRunning: child ? isAlive(child) : null, + attempts: supervised.attempts, + policy, + }); + if (ok) return supervised.result; + if (named.source === 'supervisor') { + // The name goes in the seat log. The throw takes the road a plain-path + // failure takes: unacked, the run loop's retry policy, onError. + log(`[${eventType}] supervised turn failed: ${named.name}${killed ? ' (child killed)' : ''}` + + `${isAlive(child) ? ' (child still running)' : ''}`); + } + throw supervised.failure; + }; + + return { + supervise, + metricsPath, + describe, + /** One model turn. Same contract as adapter.spawn(prompt, ctx). */ + run(adapter, prompt, ctx, { eventType } = {}) { + return supervise ? runSupervised(adapter, prompt, ctx, eventType) : runPlain(adapter, prompt, ctx, eventType); + }, + }; +}; From 2a331fc7e5e8bf1668e1690c7fc0cfc67a3db7bc Mon Sep 17 00:00:00 2001 From: Lily Shen <115414357+lilyshen0722@users.noreply.github.com> Date: Sun, 25 Oct 2026 21:26:24 -0700 Subject: [PATCH 2/8] fix(cli): the seat-log baseline closes seat-token turns at their outcome A turn that spawned on the seat token mints no spawn credential, so no "spawn credential revoked" line is logged; a failed revoke logs a different line. The baseline waited for the revoked line and reported both as open. The outcome line now closes a turn, ending it at the revoke when there was one. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013ENddpGzhE7S8qjDSYAMuu --- cli/__tests__/seat-log-baseline.test.mjs | 14 ++++++++++++++ cli/scripts/seat-log-baseline.mjs | 8 +++++--- 2 files changed, 19 insertions(+), 3 deletions(-) diff --git a/cli/__tests__/seat-log-baseline.test.mjs b/cli/__tests__/seat-log-baseline.test.mjs index f98306ad6b..931b780096 100644 --- a/cli/__tests__/seat-log-baseline.test.mjs +++ b/cli/__tests__/seat-log-baseline.test.mjs @@ -41,3 +41,17 @@ test('the window bounds which turns count', () => { // the 02:00 turn closes past the window end, as a failure, and still counts expect(r.byAdapter.codex.timeouts).toBe(1); }); + +test('a turn on the seat token, and one whose revoke failed, still close as ok', () => { + const log = [ + L('01:00:00.000', '[inbox.batch] spawning codex'), + L('01:00:00.200', 'spawn credential unavailable (HTTP 503) — spawning with the seat token'), + L('01:00:20.000', '[inbox.batch] agent posted via tool this turn — not echoing CLI output'), + L('02:00:00.000', '[inbox.batch] spawning codex'), + L('02:00:40.000', 'spawn credential revoke failed (6adbd35b8522fc8abce9b7b8, 503) — the boot sweep will collect it'), + L('02:00:40.500', '[inbox.batch] no wrapper-post (NO_REPLY)'), + ].join('\n'); + const r = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T03:00:00Z'), hours: 4 }); + expect(r.byAdapter.codex).toMatchObject({ turns: 2, ok: 2, open: 0, outcomes: { posted_via_tool: 1, no_reply: 1 } }); + expect(r.byAdapter.codex.durationMs.max).toBe(40_000); +}); diff --git a/cli/scripts/seat-log-baseline.mjs b/cli/scripts/seat-log-baseline.mjs index 3aa1cba418..5dea660486 100644 --- a/cli/scripts/seat-log-baseline.mjs +++ b/cli/scripts/seat-log-baseline.mjs @@ -94,10 +94,12 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout open = null; continue; } - if (/^spawn credential revoked\b/.test(msg)) { open.revokedMs = at; continue; } + // The child's end, when the turn minted a credential. A seat-token turn + // mints none and logs neither line, so its outcome line is its end. + if (/^spawn credential (revoked|revoke failed)\b/.test(msg)) { open.revokedMs = at; continue; } const outcome = outcomeOf(msg); - if (outcome && open.revokedMs !== undefined) { - close(open, { endMs: open.revokedMs, ended: 'ok', outcome }); + if (outcome) { + close(open, { endMs: open.revokedMs ?? at, ended: 'ok', outcome }); open = null; } } From 377b1203aa17b36a5631c68165d88c1ff62642c8 Mon Sep 17 00:00:00 2001 From: Lily Shen <115414357+lilyshen0722@users.noreply.github.com> Date: Sun, 25 Oct 2026 21:39:44 -0700 Subject: [PATCH 3/8] fix(cli): the seat-log baseline treats a malformed option as a usage error A missing or non-numeric --log, --hours, --timeout-ms or --until value crashed with a stack trace or produced a report computed from NaN. Each is now a status-2 usage error, as an unparseable --until already was. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013ENddpGzhE7S8qjDSYAMuu --- cli/__tests__/seat-log-baseline.test.mjs | 36 +++++++++++++++++++++++- cli/scripts/seat-log-baseline.mjs | 36 ++++++++++++++++++------ 2 files changed, 62 insertions(+), 10 deletions(-) diff --git a/cli/__tests__/seat-log-baseline.test.mjs b/cli/__tests__/seat-log-baseline.test.mjs index 931b780096..4185532482 100644 --- a/cli/__tests__/seat-log-baseline.test.mjs +++ b/cli/__tests__/seat-log-baseline.test.mjs @@ -1,4 +1,8 @@ -import { baseline, render } from '../scripts/seat-log-baseline.mjs'; +import { mkdtempSync, rmSync, writeFileSync } from 'fs'; +import { tmpdir } from 'os'; +import { join } from 'path'; + +import { baseline, main, render } from '../scripts/seat-log-baseline.mjs'; const L = (ts, msg, seat = 'nib') => `2026-10-24T${ts}Z [${seat}] ${msg}`; const LOG = [ @@ -55,3 +59,33 @@ test('a turn on the seat token, and one whose revoke failed, still close as ok', expect(r.byAdapter.codex).toMatchObject({ turns: 2, ok: 2, open: 0, outcomes: { posted_via_tool: 1, no_reply: 1 } }); expect(r.byAdapter.codex.durationMs.max).toBe(40_000); }); + +test('a malformed option is a usage error, not a stack trace or a NaN report', () => { + const dir = mkdtempSync(join(tmpdir(), 'seat-log-baseline-')); + try { + const log = join(dir, 'nib.log'); + writeFileSync(log, LOG); + const run = (...args) => { + const out = []; + const err = []; + const status = main(['nib', ...args], { stdout: { write: (t) => out.push(t) }, stderr: { write: (t) => err.push(t) } }); + return { status, out: out.join(''), err: err.join('') }; + }; + for (const [args, message] of [ + [['--log'], '--log needs a value'], + [['--log', '--json'], '--log needs a value'], + [['--log', log, '--hours'], '--hours must be a positive number'], + [['--log', log, '--hours', 'abc'], '--hours must be a positive number'], + [['--log', log, '--timeout-ms', 'x'], '--timeout-ms must be a positive number'], + [['--log', log, '--until'], '--until needs a value'], + [['--log', log, '--until', 'yesterday'], '--until is not a date'], + ]) { + expect(run(...args)).toEqual({ status: 2, out: '', err: `${message}\n` }); + } + const ok = run('--log', log, '--until', '2026-10-24T07:00:00Z', '--hours', '48', '--json'); + expect(ok.status).toBe(0); + expect(JSON.parse(ok.out).byAdapter.codex.turns).toBe(4); + } finally { + rmSync(dir, { recursive: true, force: true }); + } +}); diff --git a/cli/scripts/seat-log-baseline.mjs b/cli/scripts/seat-log-baseline.mjs index 5dea660486..75b803a049 100644 --- a/cli/scripts/seat-log-baseline.mjs +++ b/cli/scripts/seat-log-baseline.mjs @@ -166,21 +166,39 @@ export const render = (r) => { return out.join('\n'); }; -const main = (argv) => { +export const main = (argv, { stdout = process.stdout, stderr = process.stderr } = {}) => { const args = [...argv]; const seat = args.shift(); if (!seat || seat.startsWith('-')) { - process.stderr.write('usage: seat-log-baseline.mjs [--until ] [--hours 48] [--log ] [--timeout-ms 2700000] [--json]\n'); + stderr.write('usage: seat-log-baseline.mjs [--until ] [--hours 48] [--log ] [--timeout-ms 2700000] [--json]\n'); return 2; } - const opt = (name, fallback) => { const i = args.indexOf(name); return i >= 0 ? args[i + 1] : fallback; }; - const untilMs = opt('--until') ? Date.parse(opt('--until')) : Date.now(); - if (Number.isNaN(untilMs)) { process.stderr.write('--until is not a date\n'); return 2; } + // A malformed option is a usage error (status 2), never a stack trace or a + // report computed from NaN. + const usage = (message) => { stderr.write(`${message}\n`); return 2; }; + const opt = (name, fallback) => { + const i = args.indexOf(name); + if (i < 0) return fallback; + const value = args[i + 1]; + return value === undefined || value.startsWith('--') ? null : value; + }; + const num = (name, fallback) => { + const value = opt(name, fallback); + const n = value === null ? NaN : Number(value); + return Number.isFinite(n) && n > 0 ? n : null; + }; + const until = opt('--until'); + if (until === null) return usage('--until needs a value'); + const untilMs = until === undefined ? Date.now() : Date.parse(until); + if (Number.isNaN(untilMs)) return usage('--until is not a date'); const logPath = opt('--log', path.join(os.homedir(), '.commonly', 'logs', `${seat}.log`)); - const result = baseline(fs.readFileSync(logPath, 'utf8'), { - seat, untilMs, hours: Number(opt('--hours', 48)), timeoutMs: Number(opt('--timeout-ms', 2_700_000)), - }); - process.stdout.write(`${args.includes('--json') ? JSON.stringify(result, null, 2) : render(result)}\n`); + if (logPath === null) return usage('--log needs a value'); + const hours = num('--hours', 48); + if (hours === null) return usage('--hours must be a positive number'); + const timeoutMs = num('--timeout-ms', 2_700_000); + if (timeoutMs === null) return usage('--timeout-ms must be a positive number'); + const result = baseline(fs.readFileSync(logPath, 'utf8'), { seat, untilMs, hours, timeoutMs }); + stdout.write(`${args.includes('--json') ? JSON.stringify(result, null, 2) : render(result)}\n`); return 0; }; From 96e9ac447570af03801926775d62d81a3b889636 Mon Sep 17 00:00:00 2001 From: Lily Shen <115414357+lilyshen0722@users.noreply.github.com> Date: Sun, 25 Oct 2026 21:47:20 -0700 Subject: [PATCH 4/8] fix(cli): seat-log baseline takes only an ISO --until and an in-range window Date.parse accepted "Oct 24 2026", rolled 2026-02-31 into March and read a zone-less timestamp as host-local time, so a wrong --until produced a report instead of a usage error. A --hours large enough to push the window start past the Date range threw from toISOString. Both are now status 2. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013ENddpGzhE7S8qjDSYAMuu --- cli/__tests__/seat-log-baseline.test.mjs | 7 ++++++- cli/scripts/seat-log-baseline.mjs | 18 ++++++++++++++++-- 2 files changed, 22 insertions(+), 3 deletions(-) diff --git a/cli/__tests__/seat-log-baseline.test.mjs b/cli/__tests__/seat-log-baseline.test.mjs index 4185532482..5905c26c6b 100644 --- a/cli/__tests__/seat-log-baseline.test.mjs +++ b/cli/__tests__/seat-log-baseline.test.mjs @@ -78,7 +78,12 @@ test('a malformed option is a usage error, not a stack trace or a NaN report', ( [['--log', log, '--hours', 'abc'], '--hours must be a positive number'], [['--log', log, '--timeout-ms', 'x'], '--timeout-ms must be a positive number'], [['--log', log, '--until'], '--until needs a value'], - [['--log', log, '--until', 'yesterday'], '--until is not a date'], + [['--log', log, '--until', 'yesterday'], '--until is not an ISO date'], + [['--log', log, '--until', 'Oct 24 2026'], '--until is not an ISO date'], + [['--log', log, '--until', '2026-02-31T00:00:00Z'], '--until is not an ISO date'], + // No zone: Date.parse would read it as host-local time. + [['--log', log, '--until', '2026-10-24T07:00:00'], '--until is not an ISO date'], + [['--log', log, '--hours', '1000000000000'], '--hours puts the window start outside the supported date range'], ]) { expect(run(...args)).toEqual({ status: 2, out: '', err: `${message}\n` }); } diff --git a/cli/scripts/seat-log-baseline.mjs b/cli/scripts/seat-log-baseline.mjs index 75b803a049..f079c0f775 100644 --- a/cli/scripts/seat-log-baseline.mjs +++ b/cli/scripts/seat-log-baseline.mjs @@ -166,6 +166,17 @@ export const render = (r) => { return out.join('\n'); }; +// Date.parse accepts "Oct 24 2026" and rolls 2026-02-31 into March, so the +// documented ISO form is checked here, and the date must survive a round trip. +const ISO_DATE = /^(\d{4}-\d{2}-\d{2})(?:T\d{2}:\d{2}(?::\d{2}(?:\.\d{1,3})?)?(?:Z|[+-]\d{2}:\d{2}))?$/; +const parseIsoDate = (value) => { + const match = ISO_DATE.exec(value); + if (!match) return null; + const ms = Date.parse(value); + if (Number.isNaN(ms)) return null; + return new Date(Date.parse(match[1])).toISOString().slice(0, 10) === match[1] ? ms : null; +}; + export const main = (argv, { stdout = process.stdout, stderr = process.stderr } = {}) => { const args = [...argv]; const seat = args.shift(); @@ -189,12 +200,15 @@ export const main = (argv, { stdout = process.stdout, stderr = process.stderr } }; const until = opt('--until'); if (until === null) return usage('--until needs a value'); - const untilMs = until === undefined ? Date.now() : Date.parse(until); - if (Number.isNaN(untilMs)) return usage('--until is not a date'); + const untilMs = until === undefined ? Date.now() : parseIsoDate(until); + if (untilMs === null) return usage('--until is not an ISO date'); const logPath = opt('--log', path.join(os.homedir(), '.commonly', 'logs', `${seat}.log`)); if (logPath === null) return usage('--log needs a value'); const hours = num('--hours', 48); if (hours === null) return usage('--hours must be a positive number'); + if (Number.isNaN(new Date(untilMs - hours * 3_600_000).getTime())) { + return usage('--hours puts the window start outside the supported date range'); + } const timeoutMs = num('--timeout-ms', 2_700_000); if (timeoutMs === null) return usage('--timeout-ms must be a positive number'); const result = baseline(fs.readFileSync(logPath, 'utf8'), { seat, untilMs, hours, timeoutMs }); From b3b0ddda009992e90f2feac104138eb43df0afa7 Mon Sep 17 00:00:00 2001 From: Lily Shen <115414357+lilyshen0722@users.noreply.github.com> Date: Sun, 25 Oct 2026 21:57:26 -0700 Subject: [PATCH 5/8] fix(cli): seat-log baseline closes ask turns and does not count a refused spawn as a turn An agent.ask turn ends with "routed private response", "response already routed by agent tool" or "no private response (...)"; the last two were not recognised, so those turns read as unclosed. "spawning" is logged before the credential lease, so a refused lease left an open turn for a child that never ran; it is now counted as a refused spawn instead. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013ENddpGzhE7S8qjDSYAMuu --- cli/__tests__/seat-log-baseline.test.mjs | 21 +++++++++++++++++++++ cli/scripts/seat-log-baseline.mjs | 16 +++++++++++++--- 2 files changed, 34 insertions(+), 3 deletions(-) diff --git a/cli/__tests__/seat-log-baseline.test.mjs b/cli/__tests__/seat-log-baseline.test.mjs index 5905c26c6b..9f3a474b0d 100644 --- a/cli/__tests__/seat-log-baseline.test.mjs +++ b/cli/__tests__/seat-log-baseline.test.mjs @@ -38,6 +38,27 @@ test('turns, durations, timeouts, exits, restarts, and an open turn, from timest expect(out).toMatch(/the log cannot tell/); }); +test('ask outcomes close a turn, and a refused spawn credential is not a turn', () => { + const log = [ + L('01:00:00.000', '[agent.ask] spawning codex'), + L('01:00:10.000', '[agent.ask] routed private response (42 bytes)'), + L('02:00:00.000', '[agent.ask] spawning codex'), + L('02:00:10.000', '[agent.ask] response already routed by agent tool'), + L('03:00:00.000', '[agent.ask] spawning codex'), + L('03:00:10.000', '[agent.ask] no private response (empty output)'), + L('04:00:00.000', '[inbox.batch] spawning codex'), + L('04:00:00.300', 'spawn credential refused (HTTP 403) — not spawning'), + L('05:00:00.000', '[inbox.batch] spawning codex'), + L('05:00:20.000', '[inbox.batch] no wrapper-post (NO_REPLY)'), + ].join('\n'); + const r = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T06:00:00Z'), hours: 8 }); + expect(r.byAdapter.codex).toMatchObject({ + turns: 4, ok: 4, open: 0, unclosed: 0, outcomes: { private_response: 2, no_private_response: 1, no_reply: 1 }, + }); + expect(r.counts.spawnRefused).toBe(1); + expect(render(r)).toMatch(/spawns refused a credential 1/); +}); + test('the window bounds which turns count', () => { const r = baseline(LOG, { seat: 'nib', untilMs: Date.parse('2026-10-24T02:30:00Z'), hours: 2 }); expect(r.byAdapter.codex.turns).toBe(2); diff --git a/cli/scripts/seat-log-baseline.mjs b/cli/scripts/seat-log-baseline.mjs index f079c0f775..ad3457c9bd 100644 --- a/cli/scripts/seat-log-baseline.mjs +++ b/cli/scripts/seat-log-baseline.mjs @@ -17,6 +17,8 @@ * - "processing failed" (the spawn threw; failed) * - a restart ("stopping after the current turn" / "polling … for events") * or the next "spawning" (no close seen; counted as unclosed) + * A "spawn credential refused" after "spawning" means the child never ran: it + * is counted as a refused spawn, not a turn. * A turn still open at the end of the window is "open", not a hang. */ import fs from 'fs'; @@ -41,7 +43,8 @@ const outcomeOf = (msg) => { if (/no wrapper-post \(empty output\)/.test(msg)) return 'empty_output'; if (/agent posted via tool/.test(msg) || /posted via tool, then/.test(msg)) return 'posted_via_tool'; if (/\bposted \d+ bytes\b/.test(msg)) return 'wrapper_posted'; - if (/routed private response/.test(msg)) return 'private_response'; + if (/routed private response/.test(msg) || /response already routed by agent tool/.test(msg)) return 'private_response'; + if (/\bno private response\b/.test(msg)) return 'no_private_response'; if (/server skipped the post/.test(msg)) return 'server_skipped'; if (/wrapper delivery refused/.test(msg)) return 'delivery_refused'; return null; @@ -61,7 +64,7 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout const fromMs = untilMs - hours * 3_600_000; const turns = []; let open = null; - const counts = { untimestamped: 0, pollErrors: 0, restarts: 0, otherSeatLines: 0 }; + const counts = { untimestamped: 0, pollErrors: 0, restarts: 0, otherSeatLines: 0, spawnRefused: 0 }; const close = (turn, fields) => { Object.assign(turn, fields); turns.push(turn); }; for (const line of text.split('\n')) { @@ -97,6 +100,13 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout // The child's end, when the turn minted a credential. A seat-token turn // mints none and logs neither line, so its outcome line is its end. if (/^spawn credential (revoked|revoke failed)\b/.test(msg)) { open.revokedMs = at; continue; } + // "spawning" is logged before the credential lease, so a refused lease + // follows it: the child never ran, and there is no turn to time. + if (/^spawn credential refused\b/.test(msg)) { + if (open.startMs >= fromMs && open.startMs <= untilMs) counts.spawnRefused += 1; + open = null; + continue; + } const outcome = outcomeOf(msg); if (outcome) { close(open, { endMs: open.revokedMs ?? at, ended: 'ok', outcome }); @@ -160,7 +170,7 @@ export const render = (r) => { if (a.durationMs) out.push(` duration p50 ${fmtMs(a.durationMs.p50)} p90 ${fmtMs(a.durationMs.p90)} p99 ${fmtMs(a.durationMs.p99)} max ${fmtMs(a.durationMs.max)} (n=${a.durationMs.n})`); out.push(` outcomes ${JSON.stringify(a.outcomes)}`); } - out.push(` restarts ${r.counts.restarts}, poll errors ${r.counts.pollErrors}, untimestamped lines (whole log) ${r.counts.untimestamped}`); + out.push(` restarts ${r.counts.restarts}, poll errors ${r.counts.pollErrors}, spawns refused a credential ${r.counts.spawnRefused}, untimestamped lines (whole log) ${r.counts.untimestamped}`); out.push(' the log cannot tell:'); for (const l of r.cannotTell) out.push(` - ${l}`); return out.join('\n'); From 9aabf34b91f5b2a69147117ff775ee1301ce8a11 Mon Sep 17 00:00:00 2001 From: Lily Shen <115414357+lilyshen0722@users.noreply.github.com> Date: Sun, 25 Oct 2026 22:13:28 -0700 Subject: [PATCH 6/8] fix(cli): seat-log baseline counts restarts after the first start, and names lease failures and lost replies The first "polling" line in a log is the seat's first start, not a restart. A credential lease that failed before the child ran is not a turn. A turn whose model answered and whose reply every delivery rung refused now reads as reply_delivery_error, not an adapter error. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013ENddpGzhE7S8qjDSYAMuu --- cli/__tests__/seat-log-baseline.test.mjs | 21 ++++++++++++++- cli/scripts/seat-log-baseline.mjs | 33 ++++++++++++++++-------- 2 files changed, 42 insertions(+), 12 deletions(-) diff --git a/cli/__tests__/seat-log-baseline.test.mjs b/cli/__tests__/seat-log-baseline.test.mjs index 9f3a474b0d..1074cdf645 100644 --- a/cli/__tests__/seat-log-baseline.test.mjs +++ b/cli/__tests__/seat-log-baseline.test.mjs @@ -32,7 +32,7 @@ test('turns, durations, timeouts, exits, restarts, and an open turn, from timest }); expect(r.byAdapter.codex.durationMs).toEqual({ p50: 30_000, p90: 2_700_100, p99: 2_700_100, max: 2_700_100, n: 3 }); expect(r.byAdapter.claude).toMatchObject({ turns: 1, cutByRestart: 1 }); - expect(r.counts).toMatchObject({ untimestamped: 1, pollErrors: 1, restarts: 1, otherSeatLines: 1 }); + expect(r.counts).toMatchObject({ untimestamped: 1, pollErrors: 1, restarts: 0, otherSeatLines: 1 }); const out = `${render(r)}\n${JSON.stringify(r)}`; expect(out).not.toMatch(/SECRET/); expect(out).toMatch(/the log cannot tell/); @@ -59,6 +59,25 @@ test('ask outcomes close a turn, and a refused spawn credential is not a turn', expect(render(r)).toMatch(/spawns refused a credential 1/); }); +test('a first start is not a restart, a failed lease is not a turn, and a lost reply is not an adapter error', () => { + const log = [ + L('00:00:00.000', 'polling https://api.commonly.me for events (ctrl+c to stop)'), + L('01:00:00.000', '[inbox.batch] spawning codex'), + L('01:00:00.200', 'spawn credential lease failed (socket hang up) — not spawning'), + L('01:00:00.300', 'inbox batch processing failed (runtime; 1 consecutive) — 1 events remain unacked: socket hang up'), + L('02:00:00.000', '[chat.mention] spawning codex'), + L('02:00:30.000', '[chat.mention] ERROR reply NOT delivered to pod p1 — 120 bytes lost, 1 event left unacked for retry: HTTP 502'), + L('02:00:30.100', 'chat.mention processing failed (runtime; 1 consecutive): HTTP 502'), + L('03:00:00.000', 'polling https://api.commonly.me for events (ctrl+c to stop)'), + ].join('\n'); + const inWindow = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T04:00:00Z'), hours: 8 }); + expect(inWindow.counts).toMatchObject({ restarts: 1, leaseFailed: 1, spawnRefused: 0 }); + expect(inWindow.byAdapter.codex).toMatchObject({ turns: 1, failed: 1, replyLost: 1, errors: 0 }); + // The start before the window still makes the 03:00 line a restart. + const late = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T04:00:00Z'), hours: 1.5 }); + expect(late.counts.restarts).toBe(1); +}); + test('the window bounds which turns count', () => { const r = baseline(LOG, { seat: 'nib', untilMs: Date.parse('2026-10-24T02:30:00Z'), hours: 2 }); expect(r.byAdapter.codex.turns).toBe(2); diff --git a/cli/scripts/seat-log-baseline.mjs b/cli/scripts/seat-log-baseline.mjs index ad3457c9bd..8525cdbc42 100644 --- a/cli/scripts/seat-log-baseline.mjs +++ b/cli/scripts/seat-log-baseline.mjs @@ -17,8 +17,8 @@ * - "processing failed" (the spawn threw; failed) * - a restart ("stopping after the current turn" / "polling … for events") * or the next "spawning" (no close seen; counted as unclosed) - * A "spawn credential refused" after "spawning" means the child never ran: it - * is counted as a refused spawn, not a turn. + * A "spawn credential refused" or "lease failed" after "spawning" means the + * child never ran: it is counted as such, not as a turn. * A turn still open at the end of the window is "open", not a hang. */ import fs from 'fs'; @@ -64,7 +64,10 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout const fromMs = untilMs - hours * 3_600_000; const turns = []; let open = null; - const counts = { untimestamped: 0, pollErrors: 0, restarts: 0, otherSeatLines: 0, spawnRefused: 0 }; + const counts = { untimestamped: 0, pollErrors: 0, restarts: 0, otherSeatLines: 0, spawnRefused: 0, leaseFailed: 0 }; + // The first "polling" line in the log is the seat's first start, not a + // restart; one before the window still makes the next one a restart. + let polledBefore = false; const close = (turn, fields) => { Object.assign(turn, fields); turns.push(turn); }; for (const line of text.split('\n')) { @@ -74,6 +77,9 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout const [, ts, who, msg] = m; const at = Date.parse(ts); if (seat && who !== seat) { counts.otherSeatLines += 1; continue; } + const polling = /^polling \S+ for events/.test(msg); + const restarted = polling && polledBefore; + if (polling) polledBefore = true; if (at < fromMs || at > untilMs) { // A turn that opened inside the window may close just past it; let it. if (!(open && at > untilMs)) continue; @@ -85,15 +91,18 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout open = { startMs: at, eventType: spawn[1], adapter: spawn[2] }; continue; } - if (/^stopping after the current turn/.test(msg) || /^polling \S+ for events/.test(msg)) { - if (at <= untilMs) counts.restarts += /^polling/.test(msg) ? 1 : 0; + if (/^stopping after the current turn/.test(msg) || polling) { + if (at <= untilMs && restarted) counts.restarts += 1; if (open) { close(open, { endMs: at, ended: 'restart' }); open = null; } continue; } if (/^(fetch failed|poll failed|HTTP \d{3}\b)/.test(msg)) { if (at <= untilMs) counts.pollErrors += 1; continue; } if (!open) continue; + // The model answered and every delivery rung threw; the processing + // failure that follows is the reply's, not the adapter's. + if (/\bERROR reply NOT delivered\b/.test(msg)) { open.replyLost = true; continue; } if (/processing failed/.test(msg)) { - close(open, { endMs: at, ended: 'failed', ...failureOf(msg) }); + close(open, { endMs: at, ended: 'failed', ...(open.replyLost ? { name: 'reply_delivery_error' } : failureOf(msg)) }); open = null; continue; } @@ -102,8 +111,9 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout if (/^spawn credential (revoked|revoke failed)\b/.test(msg)) { open.revokedMs = at; continue; } // "spawning" is logged before the credential lease, so a refused lease // follows it: the child never ran, and there is no turn to time. - if (/^spawn credential refused\b/.test(msg)) { - if (open.startMs >= fromMs && open.startMs <= untilMs) counts.spawnRefused += 1; + const notSpawned = /^spawn credential (refused|lease failed)\b/.exec(msg); + if (notSpawned) { + if (open.startMs >= fromMs && open.startMs <= untilMs) counts[notSpawned[1] === 'refused' ? 'spawnRefused' : 'leaseFailed'] += 1; open = null; continue; } @@ -121,7 +131,7 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout const byAdapter = {}; for (const t of turns) { const a = (byAdapter[t.adapter] ||= { - turns: 0, ok: 0, failed: 0, timeouts: 0, exits: {}, errors: 0, unclosed: 0, cutByRestart: 0, open: 0, + turns: 0, ok: 0, failed: 0, timeouts: 0, exits: {}, replyLost: 0, errors: 0, unclosed: 0, cutByRestart: 0, open: 0, atOrOverTimeout: 0, outcomes: {}, durations: [], }); a.turns += 1; @@ -131,6 +141,7 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout a.failed += 1; if (t.name === 'adapter_timeout') a.timeouts += 1; else if (t.name === 'adapter_exit') a.exits[t.exitCode] = (a.exits[t.exitCode] || 0) + 1; + else if (t.name === 'reply_delivery_error') a.replyLost += 1; else a.errors += 1; } if (t.ended === 'unclosed') a.unclosed += 1; @@ -164,13 +175,13 @@ export const render = (r) => { if (!adapters.length) out.push(' no turns in the window'); for (const [name, a] of adapters) { out.push(` ${name}: ${a.turns} turns, ${a.ok} ok, ${a.failed} failed` - + ` (${a.timeouts} timed out, exits ${JSON.stringify(a.exits)}, ${a.errors} other)` + + ` (${a.timeouts} timed out, exits ${JSON.stringify(a.exits)}, ${a.replyLost} replies not delivered, ${a.errors} other)` + `, ${a.cutByRestart} cut by restart, ${a.unclosed} unclosed, ${a.open} still open at the window end`); out.push(` reached the turn budget: ${a.atOrOverTimeout}`); if (a.durationMs) out.push(` duration p50 ${fmtMs(a.durationMs.p50)} p90 ${fmtMs(a.durationMs.p90)} p99 ${fmtMs(a.durationMs.p99)} max ${fmtMs(a.durationMs.max)} (n=${a.durationMs.n})`); out.push(` outcomes ${JSON.stringify(a.outcomes)}`); } - out.push(` restarts ${r.counts.restarts}, poll errors ${r.counts.pollErrors}, spawns refused a credential ${r.counts.spawnRefused}, untimestamped lines (whole log) ${r.counts.untimestamped}`); + out.push(` restarts ${r.counts.restarts}, poll errors ${r.counts.pollErrors}, spawns refused a credential ${r.counts.spawnRefused}, credential lease failures ${r.counts.leaseFailed}, untimestamped lines (whole log) ${r.counts.untimestamped}`); out.push(' the log cannot tell:'); for (const l of r.cannotTell) out.push(` - ${l}`); return out.join('\n'); From 9f1bcc8ad1236b77d3d66dc02641bbba821952d3 Mon Sep 17 00:00:00 2001 From: Lily Shen <115414357+lilyshen0722@users.noreply.github.com> Date: Sun, 25 Oct 2026 23:59:57 -0700 Subject: [PATCH 7/8] fix(cli): a canary turn is ok only once its reply reached the pod MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The supervised path wrote its metric line when the spawn resolved, so a reply every delivery rung refused, or one suppressed because the claim was lost mid-turn, counted as ok. The line is now written after delivery settles, with outcome delivered, silent, reply_lost, claim_lost, server_skipped, server_refused or upstream_refused; ok is true only for delivered and silent. A spawn that threw is still `failed` at once. The seat-log baseline maps the same outcomes, recognising the "stood down — claim lost mid-turn" line. With COMMONLY_SUPERVISE_RUNS off, nothing is written at all. Run-loop tests drive a lease lost mid-turn and a reply every rung refused, and read each turn back from the canary and from the baseline over the run's own log. Answers CodeRabbit review 5647380486: the real-child stall window is 300 ms, a runner test covers unsafe seat names and event labels, and the baseline is tested through its CLI entrypoint. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013ENddpGzhE7S8qjDSYAMuu --- cli/__tests__/seat-log-baseline.test.mjs | 60 +++++- cli/__tests__/supervise-runs-flag.test.mjs | 12 +- cli/__tests__/supervised-turn.test.mjs | 208 +++++++++++++++++---- cli/scripts/seat-log-baseline.mjs | 48 +++-- cli/src/commands/agent.js | 51 +++-- cli/src/lib/supervised-turn.js | 145 +++++++------- 6 files changed, 384 insertions(+), 140 deletions(-) diff --git a/cli/__tests__/seat-log-baseline.test.mjs b/cli/__tests__/seat-log-baseline.test.mjs index 1074cdf645..919147de4a 100644 --- a/cli/__tests__/seat-log-baseline.test.mjs +++ b/cli/__tests__/seat-log-baseline.test.mjs @@ -1,6 +1,8 @@ +import { spawnSync } from 'child_process'; import { mkdtempSync, rmSync, writeFileSync } from 'fs'; import { tmpdir } from 'os'; -import { join } from 'path'; +import { dirname, join } from 'path'; +import { fileURLToPath } from 'url'; import { baseline, main, render } from '../scripts/seat-log-baseline.mjs'; @@ -28,7 +30,7 @@ test('turns, durations, timeouts, exits, restarts, and an open turn, from timest const r = baseline(LOG, { seat: 'nib', untilMs: Date.parse('2026-10-24T07:00:00Z'), hours: 48 }); expect(r.byAdapter.codex).toMatchObject({ turns: 4, ok: 1, failed: 2, timeouts: 1, exits: { 7: 1 }, errors: 0, open: 1, atOrOverTimeout: 1, - outcomes: { posted_via_tool: 1 }, + outcomes: { delivered: 1, failed: 2 }, }); expect(r.byAdapter.codex.durationMs).toEqual({ p50: 30_000, p90: 2_700_100, p99: 2_700_100, max: 2_700_100, n: 3 }); expect(r.byAdapter.claude).toMatchObject({ turns: 1, cutByRestart: 1 }); @@ -53,7 +55,7 @@ test('ask outcomes close a turn, and a refused spawn credential is not a turn', ].join('\n'); const r = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T06:00:00Z'), hours: 8 }); expect(r.byAdapter.codex).toMatchObject({ - turns: 4, ok: 4, open: 0, unclosed: 0, outcomes: { private_response: 2, no_private_response: 1, no_reply: 1 }, + turns: 4, ok: 4, open: 0, unclosed: 0, outcomes: { delivered: 2, silent: 2 }, }); expect(r.counts.spawnRefused).toBe(1); expect(render(r)).toMatch(/spawns refused a credential 1/); @@ -72,12 +74,38 @@ test('a first start is not a restart, a failed lease is not a turn, and a lost r ].join('\n'); const inWindow = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T04:00:00Z'), hours: 8 }); expect(inWindow.counts).toMatchObject({ restarts: 1, leaseFailed: 1, spawnRefused: 0 }); - expect(inWindow.byAdapter.codex).toMatchObject({ turns: 1, failed: 1, replyLost: 1, errors: 0 }); + // The model answered, so the spawn did not fail; the turn is still not ok. + expect(inWindow.byAdapter.codex).toMatchObject({ turns: 1, ok: 0, failed: 0, errors: 0, outcomes: { reply_lost: 1 } }); // The start before the window still makes the 03:00 line a restart. const late = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T04:00:00Z'), hours: 1.5 }); expect(late.counts.restarts).toBe(1); }); +test('a turn is ok only when it was delivered or silent: a lost claim, a skip, a refusal and a refused route are not', () => { + const log = [ + L('01:00:00.000', '[chat.mention] spawning codex'), + L('01:00:05.000', '[chat.mention] claim on message 42 lost mid-turn to peer — standing down at post time'), + L('01:00:10.000', '[chat.mention] stood down — claim lost mid-turn to peer; reply suppressed (120 bytes not posted)'), + L('02:00:00.000', '[chat.mention] spawning codex'), + L('02:00:10.000', '[chat.mention] upstream refused 429 — nothing posted this turn'), + L('03:00:00.000', '[agent.ask] spawning codex'), + L('03:00:10.000', '[agent.ask] upstream refused 403: route closed — no private response'), + L('04:00:00.000', '[chat.mention] spawning codex'), + L('04:00:10.000', '[chat.mention] server skipped the post: duplicate (10 min window) — nothing reached the pod'), + L('05:00:00.000', '[chat.mention] spawning codex'), + L('05:00:10.000', '[chat.mention] wrapper delivery refused after 0/1 message (run_cap): stop'), + L('06:00:00.000', '[chat.mention] spawning codex'), + L('06:00:10.000', '[chat.mention] posted 120 bytes as 1 message (single)'), + ].join('\n'); + const r = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T07:00:00Z'), hours: 8 }); + expect(r.byAdapter.codex).toMatchObject({ + turns: 6, + ok: 1, + failed: 0, + outcomes: { claim_lost: 1, upstream_refused: 2, server_skipped: 1, server_refused: 1, delivered: 1 }, + }); +}); + test('the window bounds which turns count', () => { const r = baseline(LOG, { seat: 'nib', untilMs: Date.parse('2026-10-24T02:30:00Z'), hours: 2 }); expect(r.byAdapter.codex.turns).toBe(2); @@ -96,7 +124,7 @@ test('a turn on the seat token, and one whose revoke failed, still close as ok', L('02:00:40.500', '[inbox.batch] no wrapper-post (NO_REPLY)'), ].join('\n'); const r = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T03:00:00Z'), hours: 4 }); - expect(r.byAdapter.codex).toMatchObject({ turns: 2, ok: 2, open: 0, outcomes: { posted_via_tool: 1, no_reply: 1 } }); + expect(r.byAdapter.codex).toMatchObject({ turns: 2, ok: 2, open: 0, outcomes: { delivered: 1, silent: 1 } }); expect(r.byAdapter.codex.durationMs.max).toBe(40_000); }); @@ -134,3 +162,25 @@ test('a malformed option is a usage error, not a stack trace or a NaN report', ( rmSync(dir, { recursive: true, force: true }); } }); + +test('run as a script, it reads the log it is given and prints no free text', () => { + const dir = mkdtempSync(join(tmpdir(), 'seat-log-baseline-')); + try { + const log = join(dir, 'nib.log'); + writeFileSync(log, LOG); + const script = join(dirname(fileURLToPath(import.meta.url)), '..', 'scripts', 'seat-log-baseline.mjs'); + const args = ['nib', '--log', log, '--until', '2026-10-24T07:00:00Z', '--hours', '48']; + const json = spawnSync(process.execPath, [script, ...args, '--json'], { encoding: 'utf8' }); + expect({ status: json.status, stderr: json.stderr }).toEqual({ status: 0, stderr: '' }); + const r = JSON.parse(json.stdout); + expect(r.seat).toBe('nib'); + expect(r.byAdapter.codex).toMatchObject({ turns: 4, ok: 1, failed: 2 }); + expect(r.counts).toMatchObject({ untimestamped: 1, otherSeatLines: 1 }); + const text = spawnSync(process.execPath, [script, ...args], { encoding: 'utf8' }); + expect(text.status).toBe(0); + expect(text.stdout).toMatch(/codex: 4 turns, 1 ok \(delivered or silent\), 2 spawns failed/); + expect(`${json.stdout}${text.stdout}`).not.toMatch(/SECRET/); + } finally { + rmSync(dir, { recursive: true, force: true }); + } +}); diff --git a/cli/__tests__/supervise-runs-flag.test.mjs b/cli/__tests__/supervise-runs-flag.test.mjs index 16f47d146f..ed1c4abacc 100644 --- a/cli/__tests__/supervise-runs-flag.test.mjs +++ b/cli/__tests__/supervise-runs-flag.test.mjs @@ -170,7 +170,9 @@ const capture = async (env) => { return scenario.spawn(prompt, ctx); }, }; - const run = harness({ events: scenario.events, adapter, env }); + // The turn budget is read from the host env; an operator's override must + // not change what the golden pins. + const run = harness({ events: scenario.events, adapter, env: { COMMONLY_AGENT_RUN_TIMEOUT_MS: undefined, ...env } }); // eslint-disable-next-line no-await-in-loop await drain(); run.handle.stop(); @@ -203,8 +205,9 @@ describe('COMMONLY_SUPERVISE_RUNS off', () => { } const golden = JSON.parse(fs.readFileSync(GOLDEN, 'utf8')); expect(got).toEqual(golden); - // Supervision leaves no trace store behind when it is off. + // Off, nothing is written: no trace store, and no canary line. expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); + expect(fs.existsSync(path.join(home, '.commonly', 'state', 'seats-canary'))).toBe(false); }); if (!WRITE_GOLDEN) { @@ -232,6 +235,7 @@ describe('COMMONLY_SUPERVISE_RUNS off', () => { expect(spawns).toHaveLength(1); expect(spawns[0]).not.toHaveProperty('signal'); expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); + expect(fs.existsSync(path.join(home, '.commonly', 'state', 'seats-canary'))).toBe(false); }); } }); @@ -276,7 +280,7 @@ describe('COMMONLY_SUPERVISE_RUNS=1 with the real codex adapter', () => { jest.setTimeout(60_000); const CANARY_KEY = 'sk-canary-run-loop-4c1d9e7a'; - test('a clean reply is posted, the metric line says supervised and ok, and nothing else reaches disk', async () => { + test('a clean reply is posted, the metric line says supervised and delivered, and nothing else reaches disk', async () => { const { startFakeProvider } = await import('../../packages/seats/test-support/fake-provider.js'); const codex = (await import('../src/lib/adapters/codex.js')).default; const provider = await startFakeProvider({ defaultReply: 'review: PASS' }); @@ -322,7 +326,7 @@ describe('COMMONLY_SUPERVISE_RUNS=1 with the real codex adapter', () => { const lines = fs.readFileSync(path.join(home, '.commonly', 'state', 'seats-canary', 'rhea.jsonl'), 'utf8') .split('\n').filter(Boolean).map((line) => JSON.parse(line)); expect(lines).toEqual([expect.objectContaining({ - path: 'supervised', adapter: 'codex', outcome: 'ok', failure: null, + path: 'supervised', adapter: 'codex', outcome: 'delivered', ok: true, failure: null, stallMs: 15 * 60 * 1000, exitCode: 0, exitObserved: true, killed: false, })]); // The reply was posted, and is in no file the run left: no record writer. diff --git a/cli/__tests__/supervised-turn.test.mjs b/cli/__tests__/supervised-turn.test.mjs index 1f68f52bbf..1097c46bf9 100644 --- a/cli/__tests__/supervised-turn.test.mjs +++ b/cli/__tests__/supervised-turn.test.mjs @@ -8,7 +8,8 @@ * - flag on: the turn goes through superviseRun with the canary policy; * - a stalled turn is named `stuck`, its child killed, its event left unacked, * and the run loop goes on to the next event; - * - one metric line per turn on both paths, and no text in it; + * - flag on, one metric line per turn, written once delivery settles, and no + * text in it; flag off, nothing written at all; * - the in-memory trace store keeps no event data. */ import { jest } from '@jest/globals'; @@ -32,9 +33,10 @@ await jest.unstable_mockModule('../src/lib/pod-focus.js', () => ({ })); const { createClient } = await import('../src/lib/api.js'); +const { baseline } = await import('../scripts/seat-log-baseline.mjs'); const { performRun } = await import('../src/commands/agent.js'); const { - createTurnRunner, createMetadataStore, supervisedRunPolicy, metricLine, STALL_DEFAULTS_MS, + createTurnRunner, createMetadataStore, supervisedRunPolicy, metricLine, STALL_DEFAULTS_MS, TURN_OUTCOMES, } = await import('../src/lib/supervised-turn.js'); const { runFailure } = await import('@commonlyai/seats/failures'); const { spawnInOwnGroup, wantsOwnProcessGroup } = await import('@commonlyai/seats/process-group'); @@ -50,7 +52,7 @@ const readMetrics = (seat) => (fs.existsSync(metricsFile(seat)) const reset = () => fs.rmSync(path.join(home, '.commonly'), { recursive: true, force: true }); const METRIC_KEYS = [ - 'v', 'ts', 'seat', 'adapter', 'path', 'eventType', 'turnStart', 'turnEnd', 'durationMs', 'outcome', 'failure', + 'v', 'ts', 'seat', 'adapter', 'path', 'eventType', 'turnStart', 'turnEnd', 'durationMs', 'outcome', 'ok', 'failure', 'failureSource', 'failureClass', 'stalled', 'cancelled', 'killed', 'exitCode', 'signal', 'exitObserved', 'childLeftRunning', 'attempts', 'stallMs', 'cancelGraceMs', 'timeoutMs', ].sort(); @@ -109,6 +111,12 @@ describe('policy defaults', () => { }); }); +// One turn through the runner, as the run loop drives it. +const turnOf = (runner, adapter, ctx = {}, { eventType = 'chat.mention', outcome = 'delivered' } = {}) => { + const turn = runner.begin({ eventType }); + return turn.run(adapter, PROMPT, ctx).then((result) => { turn.finish(outcome); return result; }); +}; + describe('the turn runner', () => { beforeEach(reset); @@ -117,12 +125,14 @@ describe('the turn runner', () => { const spawn = jest.fn(async () => ({ text: REPLY })); const ctx = { cwd: '/w', env: process.env, timeoutMs: 5 }; const runner = createTurnRunner({ seat: 'quire', turnTimeoutMs: 5, supervise: false, superviseRun, env: {} }); - await expect(runner.run({ name: 'claude', spawn }, PROMPT, ctx, { eventType: 'chat.mention' })).resolves.toEqual({ text: REPLY }); + await expect(turnOf(runner, { name: 'claude', spawn }, ctx)).resolves.toEqual({ text: REPLY }); expect(spawn).toHaveBeenCalledTimes(1); expect(spawn.mock.calls[0][0]).toBe(PROMPT); expect(spawn.mock.calls[0][1]).toBe(ctx); expect(Object.keys(ctx)).toEqual(['cwd', 'env', 'timeoutMs']); expect(superviseRun).not.toHaveBeenCalled(); + // Nothing is written with the flag off, not even the directory. + expect(fs.existsSync(path.join(home, '.commonly'))).toBe(false); }); test('flag on: the turn goes through superviseRun with the canary policy and a no-record store, and no relay', async () => { @@ -132,7 +142,7 @@ describe('the turn runner', () => { }); const spawn = jest.fn(); const runner = createTurnRunner({ seat: 'nib', turnTimeoutMs: 2_700_000, supervise: true, superviseRun, env: {} }); - await expect(runner.run({ name: 'codex', spawn }, PROMPT, { cwd: '/w' }, { eventType: 'inbox.batch' })) + await expect(turnOf(runner, { name: 'codex', spawn }, { cwd: '/w' }, { eventType: 'inbox.batch' })) .resolves.toEqual({ text: REPLY }); expect(spawn).not.toHaveBeenCalled(); expect(superviseRun).toHaveBeenCalledTimes(1); @@ -149,7 +159,8 @@ describe('the turn runner', () => { const within = (promise, ms) => Promise.race([promise, new Promise((_, reject) => { setTimeout(() => reject(new Error(`no settle in ${ms}ms`)), ms).unref(); })]); - const env = { COMMONLY_SUPERVISE_STALL_MS: '60', COMMONLY_SUPERVISE_CANCEL_GRACE_MS: '40' }; + // 300 ms, not less: a loaded CI host must not count the child's own start as a stall. + const env = { COMMONLY_SUPERVISE_STALL_MS: '300', COMMONLY_SUPERVISE_CANCEL_GRACE_MS: '40' }; const logs = []; let pid; const adapter = { @@ -162,13 +173,13 @@ describe('the turn runner', () => { }), }; const runner = createTurnRunner({ seat: 'nib', turnTimeoutMs: 60_000, supervise: true, env, log: (l) => logs.push(l) }); - const error = await within(runner.run(adapter, PROMPT, {}, { eventType: 'chat.mention' }), 5000).catch((e) => e); + const error = await within(turnOf(runner, adapter), 5000).catch((e) => e); expect(error.kind).toBe('stuck'); expect(isRunning(pid)).toBe(false); expect(logs).toEqual([expect.stringMatching(/^\[chat\.mention\] supervised turn failed: stuck \(child killed\)$/)]); expect(readMetrics('nib')).toEqual([expect.objectContaining({ - path: 'supervised', outcome: 'failed', failure: 'stuck', failureSource: 'supervisor', stalled: true, - cancelled: true, killed: true, signal: 'SIGKILL', exitObserved: true, childLeftRunning: false, stallMs: 60, + path: 'supervised', outcome: 'failed', ok: false, failure: 'stuck', failureSource: 'supervisor', stalled: true, + cancelled: true, killed: true, signal: 'SIGKILL', exitObserved: true, childLeftRunning: false, stallMs: 300, })]); }); @@ -195,7 +206,7 @@ describe('the turn runner', () => { }), }; const runner = createTurnRunner({ seat: 'nib', turnTimeoutMs: 60_000, supervise: true, env }); - const error = await runner.run(adapter, PROMPT, {}, { eventType: 'chat.mention' }).catch((e) => e); + const error = await turnOf(runner, adapter).catch((e) => e); expect(error.kind).toBe('stuck'); expect(ownGroup).toBe(process.platform !== 'win32'); expect(Number.isInteger(grandchild)).toBe(true); @@ -208,28 +219,44 @@ describe('the turn runner', () => { expect(isRunning(grandchild)).toBe(false); }, 15_000); - test('one metric line per turn on both paths, and none of them carries text', async () => { + test('flag on, one line per turn once delivery settles; flag off, none; and no line carries text', async () => { const env = { COMMONLY_SUPERVISE_STALL_MS: '0' }; const ok = { name: 'codex', spawn: async () => ({ text: REPLY }) }; const bad = { name: 'codex', spawn: async () => { throw new Error(`codex exited with code 3: ${ERROR_TEXT}`); } }; const named = { name: 'codex', spawn: async () => { throw runFailure('exited', ERROR_TEXT); } }; const plain = createTurnRunner({ seat: 'nib', turnTimeoutMs: 1000, supervise: false, env }); const supervised = createTurnRunner({ seat: 'nib', turnTimeoutMs: 1000, supervise: true, env }); - await plain.run(ok, PROMPT, {}, { eventType: 'chat.mention' }); - await plain.run(bad, PROMPT, {}, { eventType: 'chat.mention' }).catch(() => {}); - await supervised.run(ok, PROMPT, {}, { eventType: 'inbox.batch' }); - await supervised.run(bad, PROMPT, {}, { eventType: 'inbox.batch' }).catch(() => {}); - await supervised.run(named, PROMPT, {}, { eventType: 'inbox.batch' }).catch(() => {}); + await turnOf(plain, ok); + await turnOf(plain, bad).catch(() => {}); + expect(readMetrics('nib')).toEqual([]); + + // A spawn that resolved writes nothing until the run loop says what + // became of the reply, and only the first finish counts. + const held = supervised.begin({ eventType: 'inbox.batch' }); + await held.run(ok, PROMPT, {}); + expect(readMetrics('nib')).toEqual([]); + held.finish('reply_lost'); + held.finish('delivered'); + for (const outcome of ['delivered', 'silent', 'claim_lost']) { + // eslint-disable-next-line no-await-in-loop + await turnOf(supervised, ok, {}, { eventType: 'inbox.batch', outcome }); + } + // A failed spawn is written at once; a finish after it adds nothing. + for (const adapter of [bad, named]) { + const turn = supervised.begin({ eventType: 'inbox.batch' }); + // eslint-disable-next-line no-await-in-loop + await turn.run(adapter, PROMPT, {}).catch(() => turn.finish('reply_lost')); + } const lines = readMetrics('nib'); - expect(lines.map((l) => [l.path, l.outcome, l.failure])).toEqual([ - ['legacy', 'ok', null], - ['legacy', 'failed', 'adapter_exit'], - ['supervised', 'ok', null], - ['supervised', 'failed', 'adapter_exit'], - ['supervised', 'failed', 'exited'], + expect(lines.map((l) => [l.path, l.outcome, l.ok, l.failure])).toEqual([ + ['supervised', 'reply_lost', false, null], + ['supervised', 'delivered', true, null], + ['supervised', 'silent', true, null], + ['supervised', 'claim_lost', false, null], + ['supervised', 'failed', false, 'adapter_exit'], + ['supervised', 'failed', false, 'exited'], ]); - expect(lines[1].exitCode).toBe(3); for (const line of lines) { expect(Object.keys(line).sort()).toEqual(METRIC_KEYS); for (const value of Object.values(line)) { @@ -240,12 +267,38 @@ describe('the turn runner', () => { for (const text of [PROMPT, REPLY, ERROR_TEXT, 'PROMPT-TEXT', 'REPLY-TEXT', 'ERROR-TEXT']) expect(raw).not.toContain(text); }); - test('metricLine drops anything it does not list', () => { + test('the seat name cannot leave the canary directory, and a bad event label is dropped', async () => { + const dir = path.join(home, 'canary'); + const ok = { name: 'codex', spawn: async () => ({ text: REPLY }) }; + for (const seat of ['../../etc/x', 'a'.repeat(200)]) { + const runner = createTurnRunner({ + seat, turnTimeoutMs: 1000, supervise: true, env: { COMMONLY_SUPERVISE_STALL_MS: '0', COMMONLY_SEATS_CANARY_DIR: dir }, + }); + expect(path.dirname(runner.metricsPath)).toBe(dir); + // eslint-disable-next-line no-await-in-loop + await turnOf(runner, ok, {}, { eventType: 'chat mention\nforged: true' }); + } + const files = fs.readdirSync(dir); + expect(files).toHaveLength(2); + for (const file of files) { + expect(file).toMatch(/^[A-Za-z0-9_.-]{1,64}\.jsonl$/); + const [line] = fs.readFileSync(path.join(dir, file), 'utf8').split('\n').filter(Boolean).map((l) => JSON.parse(l)); + expect(line.eventType).toBeNull(); + expect(line.seat).toMatch(/^[A-Za-z0-9_.-]{1,64}$/); + } + expect(fs.existsSync(path.join(home, 'etc'))).toBe(false); + }); + + test('metricLine drops anything it does not list, and an outcome it does not know is unknown, not ok', () => { const line = metricLine({ - seat: 'nib', adapter: 'codex', path: 'legacy', startMs: 0, endMs: 5, ok: true, text: REPLY, prompt: PROMPT, detail: ERROR_TEXT, + seat: 'nib', adapter: 'codex', path: 'supervised', startMs: 0, endMs: 5, outcome: 'delivered', text: REPLY, prompt: PROMPT, detail: ERROR_TEXT, }); expect(Object.keys(line).sort()).toEqual(METRIC_KEYS); + expect(line).toMatchObject({ outcome: 'delivered', ok: true }); expect(JSON.stringify(line)).not.toMatch(/TEXT-/); + expect(metricLine({ startMs: 0, endMs: 5, outcome: REPLY })).toMatchObject({ outcome: 'unknown', ok: false }); + expect(metricLine({ startMs: 0, endMs: 5 })).toMatchObject({ outcome: 'unknown', ok: false }); + expect(TURN_OUTCOMES.filter((o) => metricLine({ startMs: 0, endMs: 5, outcome: o }).ok)).toEqual(['delivered', 'silent']); }); test('a metrics write failure never fails a turn, and is said once', async () => { @@ -253,11 +306,15 @@ describe('the turn runner', () => { fs.writeFileSync(blocker, ''); const logs = []; const runner = createTurnRunner({ - seat: 'nib', turnTimeoutMs: 1000, supervise: false, env: { COMMONLY_SEATS_CANARY_DIR: path.join(blocker, 'x') }, log: (l) => logs.push(l), + seat: 'nib', + turnTimeoutMs: 1000, + supervise: true, + env: { COMMONLY_SUPERVISE_STALL_MS: '0', COMMONLY_SEATS_CANARY_DIR: path.join(blocker, 'x') }, + log: (l) => logs.push(l), }); const adapter = { name: 'codex', spawn: async () => ({ text: REPLY }) }; - await expect(runner.run(adapter, PROMPT, {}, {})).resolves.toEqual({ text: REPLY }); - await runner.run(adapter, PROMPT, {}, {}); + await expect(turnOf(runner, adapter)).resolves.toEqual({ text: REPLY }); + await turnOf(runner, adapter); expect(logs).toEqual([expect.stringMatching(/^turn metrics not written/)]); }); }); @@ -284,7 +341,12 @@ const event = (id) => ({ payload: { content: `@nib ${PROMPT} (${id})`, messageId: id.replace(/\D/g, '') || '1', username: 'growth-ops' }, }); -const loop = ({ batches, adapter, superviseRuns, env = {} }) => { +const CLAIM_RENEW_MS = 45_000; // the default 90 s lease renews at half-life +const claimed = { claimed: true, expiresAt: 'later' }; + +const loop = ({ + batches, adapter, superviseRuns, env = {}, postImpl = async (route) => (String(route).endsWith('/claim') ? claimed : {}), +}) => { let polls = 0; const get = jest.fn(async (route) => { if (route === '/api/agents/runtime/events') { polls += 1; return { events: batches[polls - 1] || [] }; } @@ -292,13 +354,15 @@ const loop = ({ batches, adapter, superviseRuns, env = {} }) => { if (String(route).endsWith('/messages')) return { messages: [] }; return {}; }); - const post = jest.fn(async (route) => (String(route).endsWith('/claim') ? { claimed: true, expiresAt: 'later' } : {})); + const post = jest.fn(postImpl); createClient.mockReturnValue({ get, post, del: jest.fn().mockResolvedValue({}) }); const saved = Object.fromEntries(Object.keys(env).map((k) => [k, process.env[k]])); Object.assign(process.env, env); const logs = []; const errors = []; const scheduled = []; + const intervals = []; + const seatLines = []; const handle = performRun({ instanceUrl: 'http://localhost:5000', token: 'cm_agent_test', @@ -309,13 +373,20 @@ const loop = ({ batches, adapter, superviseRuns, env = {} }) => { claimYieldDelayMs: 0, sleepImpl: async () => {}, superviseRuns, - log: (line) => logs.push(String(line)), - onError: (err) => errors.push(err), + log: (line) => { logs.push(String(line)); seatLines.push(String(line)); }, + // `commonly agent run` stamps onError into the same seat log as log(). + onError: (err) => { errors.push(err); seatLines.push(err.message); }, setTimeoutImpl: (callback, delayMs) => { scheduled.push({ callback, delayMs }); return 0; }, + setIntervalImpl: (callback, delayMs) => { intervals.push({ callback, delayMs }); return intervals.length; }, + clearIntervalImpl: () => {}, }); const restore = () => { for (const [k, v] of Object.entries(saved)) { if (v === undefined) delete process.env[k]; else process.env[k] = v; } }; const acks = () => post.mock.calls.filter(([r]) => String(r).endsWith('/ack')).map(([r, b]) => ({ id: String(r).split('/').at(-2), result: b.result })); - return { handle, logs, errors, scheduled, acks, restore }; + // The claim keeper's renewal ticks, fired by hand (mid-turn, from a spawn). + const renewClaims = () => Promise.all(intervals.filter((i) => i.delayMs === CLAIM_RENEW_MS).map((i) => i.callback())); + // The run's log as the seat log has it, for the baseline. + const seatLog = () => seatLines.map((line, i) => `2026-10-26T00:00:${String(i).padStart(2, '0')}.000Z [nib] ${line}`).join('\n'); + return { handle, logs, errors, scheduled, acks, restore, post, renewClaims, seatLog }; }; const until = async (predicate, ms = 10_000) => { @@ -341,7 +412,9 @@ describe('the run loop', () => { // Only superviseRun hands an adapter a cancel signal and a trace hook. expect('signal' in ctxs[0]).toBe(superviseRuns); expect('trace' in ctxs[0]).toBe(superviseRuns); - expect(readMetrics('nib').map((l) => l.path)).toEqual([pathName]); + // Flag off writes no canary line at all; flag on writes one once the reply is posted. + expect(readMetrics('nib').map((l) => [l.path, l.outcome, l.ok])).toEqual(superviseRuns ? [[pathName, 'delivered', true]] : []); + expect(fs.existsSync(path.join(home, '.commonly', 'state', 'seats-canary'))).toBe(superviseRuns); expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); }); @@ -365,7 +438,7 @@ describe('the run loop', () => { batches: [[event('evt-a')], [event('evt-b')]], adapter, superviseRuns: true, - env: { COMMONLY_SUPERVISE_STALL_MS: '60', COMMONLY_SUPERVISE_CANCEL_GRACE_MS: '40' }, + env: { COMMONLY_SUPERVISE_STALL_MS: '300', COMMONLY_SUPERVISE_CANCEL_GRACE_MS: '40' }, }); try { await until(() => run.errors.length === 1 && run.scheduled.length === 1); @@ -387,6 +460,69 @@ describe('the run loop', () => { const turns = readMetrics('nib').map((l) => [l.path, l.outcome, l.failure, l.killed]); expect(turns[0]).toEqual(['supervised', 'failed', 'stuck', true]); expect(turns.slice(1).length).toBeGreaterThan(0); - for (const turn of turns.slice(1)) expect(turn).toEqual(['supervised', 'ok', null, false]); + for (const turn of turns.slice(1)) expect(turn).toEqual(['supervised', 'delivered', null, false]); + }); + + // A turn is ok only once its outcome reached the pod. Each case below runs + // the real run loop with the flag on, then reads the same turn back two + // ways: the canary line, and the seat-log baseline over the run's own log. + const baselineOf = (run) => baseline(run.seatLog(), { seat: 'nib', untilMs: Date.parse('2026-10-26T01:00:00Z'), hours: 2 }); + + test('a lease lost mid-turn is claim_lost, not ok: the reply is not posted, in the canary and the baseline alike', async () => { + const renewals = { n: 0 }; + let run; + const adapter = { + name: 'codex', + detect: async () => null, + spawn: async () => { await run.renewClaims(); return { text: REPLY }; }, + }; + run = loop({ + batches: [[event('evt-1')]], + adapter, + superviseRuns: true, + env: { COMMONLY_SUPERVISE_STALL_MS: '0' }, + postImpl: async (route) => { + if (!String(route).endsWith('/claim')) return {}; + renewals.n += 1; + // Acquired, then a peer holds it at the first renewal. + return renewals.n === 1 ? claimed : { claimed: false, claimedBy: 'peer' }; + }, + }); + try { + await until(() => readMetrics('nib').length === 1); + } finally { run.handle.stop(); run.restore(); } + expect(renewals.n).toBeGreaterThan(1); + expect(run.logs).toEqual(expect.arrayContaining([expect.stringMatching(/stood down — claim lost mid-turn to peer; reply suppressed/)])); + expect(run.post.mock.calls.filter(([r]) => String(r).endsWith('/messages'))).toEqual([]); + expect(readMetrics('nib')).toEqual([expect.objectContaining({ path: 'supervised', outcome: 'claim_lost', ok: false, failure: null })]); + expect(baselineOf(run).byAdapter.codex).toMatchObject({ turns: 1, ok: 0, failed: 0, outcomes: { claim_lost: 1 } }); + }); + + test('a reply every delivery rung refused is reply_lost, not ok: the event stays unacked, in the canary and the baseline alike', async () => { + const adapter = { name: 'codex', detect: async () => null, spawn: async () => ({ text: REPLY }) }; + const rungs = []; + const run = loop({ + batches: [[event('evt-1')]], + adapter, + superviseRuns: true, + env: { COMMONLY_SUPERVISE_STALL_MS: '0' }, + postImpl: async (route) => { + const r = String(route); + if (r.endsWith('/claim')) return claimed; + if (r.includes('/messages') || r.includes('/upload')) { + rungs.push(r); + throw Object.assign(new Error('HTTP 502'), { status: 502 }); + } + return {}; + }, + }); + try { + await until(() => readMetrics('nib').length === 1 && run.errors.length === 1); + } finally { run.handle.stop(); run.restore(); } + expect(rungs.length).toBeGreaterThan(0); + expect(run.logs).toEqual(expect.arrayContaining([expect.stringMatching(/ERROR reply NOT delivered to pod/)])); + expect(run.acks()).toEqual([]); + expect(readMetrics('nib')).toEqual([expect.objectContaining({ path: 'supervised', outcome: 'reply_lost', ok: false, failure: null })]); + expect(baselineOf(run).byAdapter.codex).toMatchObject({ turns: 1, ok: 0, failed: 0, errors: 0, outcomes: { reply_lost: 1 } }); }); }); diff --git a/cli/scripts/seat-log-baseline.mjs b/cli/scripts/seat-log-baseline.mjs index 8525cdbc42..490a868778 100644 --- a/cli/scripts/seat-log-baseline.mjs +++ b/cli/scripts/seat-log-baseline.mjs @@ -13,13 +13,18 @@ * no timestamp (raw stderr, HTML error pages) are counted, not shown. * * A turn opens at "[] spawning " and closes at the first of: - * - "spawn credential revoked" (the spawn returned; the outcome line follows) - * - "processing failed" (the spawn threw; failed) + * - an outcome line (what became of the reply; see outcomeOf) + * - "processing failed" (the spawn threw: failed; or, after + * "ERROR reply NOT delivered": reply_lost) * - a restart ("stopping after the current turn" / "polling … for events") * or the next "spawning" (no close seen; counted as unclosed) * A "spawn credential refused" or "lease failed" after "spawning" means the * child never ran: it is counted as such, not as a turn. * A turn still open at the end of the window is "open", not a hang. + * + * Outcomes use the canary's words (TURN_OUTCOMES in + * src/lib/supervised-turn.js), so a log and a canary file compare event for + * event: a turn is ok only when it was delivered or silent. */ import fs from 'fs'; import os from 'os'; @@ -38,15 +43,20 @@ export const LIMITS = [ const LINE_RE = /^(\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d(?:\.\d+)?Z) \[([^\]]+)\] (.*)$/; const SPAWN_RE = /^\[([A-Za-z0-9._-]{1,40})\] spawning ([a-z0-9-]{1,32})$/; +const OK_OUTCOMES = ['delivered', 'silent']; + +// Each phrase the run loop logs once delivery settles, in the order it checks +// them, mapped to the canary's outcome. An upstream refusal is matched first: +// it also ends in "nothing posted" or "no private response". const outcomeOf = (msg) => { - if (/no wrapper-post \(NO_REPLY\)/.test(msg)) return 'no_reply'; - if (/no wrapper-post \(empty output\)/.test(msg)) return 'empty_output'; - if (/agent posted via tool/.test(msg) || /posted via tool, then/.test(msg)) return 'posted_via_tool'; - if (/\bposted \d+ bytes\b/.test(msg)) return 'wrapper_posted'; - if (/routed private response/.test(msg) || /response already routed by agent tool/.test(msg)) return 'private_response'; - if (/\bno private response\b/.test(msg)) return 'no_private_response'; + if (/^\[[^\]]+\] upstream refused \d{3}\b/.test(msg)) return 'upstream_refused'; + if (/agent posted via tool/.test(msg) || /posted via tool, then/.test(msg)) return 'delivered'; + if (/\bposted \d+ bytes\b/.test(msg)) return 'delivered'; + if (/routed private response/.test(msg) || /response already routed by agent tool/.test(msg)) return 'delivered'; + if (/no wrapper-post \(/.test(msg) || /\bno private response\b/.test(msg)) return 'silent'; + if (/stood down — claim lost mid-turn/.test(msg)) return 'claim_lost'; if (/server skipped the post/.test(msg)) return 'server_skipped'; - if (/wrapper delivery refused/.test(msg)) return 'delivery_refused'; + if (/wrapper delivery refused/.test(msg)) return 'server_refused'; return null; }; @@ -102,7 +112,8 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout // failure that follows is the reply's, not the adapter's. if (/\bERROR reply NOT delivered\b/.test(msg)) { open.replyLost = true; continue; } if (/processing failed/.test(msg)) { - close(open, { endMs: at, ended: 'failed', ...(open.replyLost ? { name: 'reply_delivery_error' } : failureOf(msg)) }); + if (open.replyLost) close(open, { endMs: open.revokedMs ?? at, ended: 'settled', outcome: 'reply_lost' }); + else close(open, { endMs: at, ended: 'failed', ...failureOf(msg) }); open = null; continue; } @@ -119,29 +130,32 @@ export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeout } const outcome = outcomeOf(msg); if (outcome) { - close(open, { endMs: open.revokedMs ?? at, ended: 'ok', outcome }); + close(open, { endMs: open.revokedMs ?? at, ended: 'settled', outcome }); open = null; } } if (open) { - if (open.revokedMs !== undefined) close(open, { endMs: open.revokedMs, ended: 'ok', outcome: 'unknown' }); + if (open.revokedMs !== undefined) close(open, { endMs: open.revokedMs, ended: 'settled', outcome: 'unknown' }); else close(open, { endMs: null, ended: 'open' }); } const byAdapter = {}; for (const t of turns) { const a = (byAdapter[t.adapter] ||= { - turns: 0, ok: 0, failed: 0, timeouts: 0, exits: {}, replyLost: 0, errors: 0, unclosed: 0, cutByRestart: 0, open: 0, + turns: 0, ok: 0, failed: 0, timeouts: 0, exits: {}, errors: 0, unclosed: 0, cutByRestart: 0, open: 0, atOrOverTimeout: 0, outcomes: {}, durations: [], }); a.turns += 1; if (t.endMs !== null) t.durationMs = t.endMs - t.startMs; - if (t.ended === 'ok') { a.ok += 1; a.outcomes[t.outcome] = (a.outcomes[t.outcome] || 0) + 1; } + if (t.ended === 'settled') { + if (OK_OUTCOMES.includes(t.outcome)) a.ok += 1; + a.outcomes[t.outcome] = (a.outcomes[t.outcome] || 0) + 1; + } if (t.ended === 'failed') { a.failed += 1; + a.outcomes.failed = (a.outcomes.failed || 0) + 1; if (t.name === 'adapter_timeout') a.timeouts += 1; else if (t.name === 'adapter_exit') a.exits[t.exitCode] = (a.exits[t.exitCode] || 0) + 1; - else if (t.name === 'reply_delivery_error') a.replyLost += 1; else a.errors += 1; } if (t.ended === 'unclosed') a.unclosed += 1; @@ -174,8 +188,8 @@ export const render = (r) => { const adapters = Object.entries(r.byAdapter); if (!adapters.length) out.push(' no turns in the window'); for (const [name, a] of adapters) { - out.push(` ${name}: ${a.turns} turns, ${a.ok} ok, ${a.failed} failed` - + ` (${a.timeouts} timed out, exits ${JSON.stringify(a.exits)}, ${a.replyLost} replies not delivered, ${a.errors} other)` + out.push(` ${name}: ${a.turns} turns, ${a.ok} ok (delivered or silent), ${a.failed} spawns failed` + + ` (${a.timeouts} timed out, exits ${JSON.stringify(a.exits)}, ${a.errors} other)` + `, ${a.cutByRestart} cut by restart, ${a.unclosed} unclosed, ${a.open} still open at the window end`); out.push(` reached the turn budget: ${a.atOrOverTimeout}`); if (a.durationMs) out.push(` duration p50 ${fmtMs(a.durationMs.p50)} p90 ${fmtMs(a.durationMs.p90)} p99 ${fmtMs(a.durationMs.p99)} max ${fmtMs(a.durationMs.max)} (n=${a.durationMs.n})`); diff --git a/cli/src/commands/agent.js b/cli/src/commands/agent.js index e0685413cb..bf43fee6f8 100644 --- a/cli/src/commands/agent.js +++ b/cli/src/commands/agent.js @@ -1357,6 +1357,11 @@ const extractPrompt = (event) => { return null; }; +// The supervisor's policy for a run-loop spawn: lib/supervised-turn.js has the +// stall windows per adapter (codex 15 min, claude off) and their evidence, the +// cancel grace, and the wall-clock backstop past the adapter's own timeout. +export { supervisedRunPolicy }; + /** * Start the run loop. Polls /events, spawns the adapter per event, posts the * result into the pod, acks. @@ -1385,11 +1390,6 @@ const extractPrompt = (event) => { * Every enforcement failure fails OPEN — a kernel without the claim route or * an unreachable upload endpoint must never produce a silent agent (#887). */ -// The supervisor's policy for a run-loop spawn: lib/supervised-turn.js has the -// stall windows per adapter (codex 15 min, claude off) and their evidence, the -// cancel grace, and the wall-clock backstop past the adapter's own timeout. -export { supervisedRunPolicy }; - export const performRun = ({ instanceUrl, token, @@ -1439,9 +1439,10 @@ export const performRun = ({ refusalHandoff = null, // Off unless COMMONLY_SUPERVISE_RUNS=1: each spawn runs under the seats // supervisor (stall window, wall-clock backstop, a named failure on every - // settle). The CLI still talks to its provider directly. Off, the spawn path - // is the plain adapter call it has always been. Either way one metadata line - // per turn goes to ~/.commonly/state/seats-canary/.jsonl. + // settle). The CLI still talks to its provider directly, and one metadata + // line per turn goes to ~/.commonly/state/seats-canary/.jsonl once + // delivery settles. Off, the spawn path is the plain adapter call it has + // always been, and nothing is written. superviseRuns = process.env.COMMONLY_SUPERVISE_RUNS === '1', }) => { reportRuntime = reportRuntime && WALKED_HARNESSES.includes(adapter?.name); @@ -1453,7 +1454,7 @@ export const performRun = ({ ? Math.min(requestedTurnTimeout, 2_147_483_647) : 15 * 60 * 1000; const client = createClient({ instance: instanceUrl, token }); // The supervised run keeps its trace in memory, metadata only; no record of - // a run is written to disk on either path (lib/supervised-turn.js). + // a run is written to disk (lib/supervised-turn.js). const turnRunner = createTurnRunner({ seat: agentName, turnTimeoutMs: effectiveTurnTimeoutMs, supervise: superviseRuns, log, }); @@ -1870,8 +1871,21 @@ export const performRun = ({ // The spawn → post-decision half of a turn, split out so the claim release // above is a plain finally instead of threading through every return path. - const runTurn = async ({ - event, eventPodId, prompt, preSpawnIds, snapshotMessages, claimKeeper, trigger, + // With superviseRuns, the turn's canary line is written once delivery has + // settled; anything thrown after a spawn that resolved means the reply never + // reached the pod. Off, `turn` writes nothing. + const runTurn = async (args) => { + const turn = turnRunner.begin({ eventType: args.event.type }); + try { + return await runTurnBody({ ...args, turn }); + } catch (error) { + turn.finish('reply_lost'); + throw error; + } + }; + + const runTurnBody = async ({ + event, eventPodId, prompt, preSpawnIds, snapshotMessages, claimKeeper, trigger, turn, }) => { const placement = await placeTurn(); // A workspace turn placed public (its pod turned public, or its pods could @@ -2130,7 +2144,7 @@ export const performRun = ({ }; // Supervised or plain, a failure is thrown exactly as the adapter's own // would be, so the run loop's classification and retry apply unchanged. - result = await turnRunner.run(adapter, spawnPrompt, spawnCtx, { eventType: event.type }); + result = await turn.run(adapter, spawnPrompt, spawnCtx); spawnCompleted = true; } finally { try { @@ -2213,6 +2227,9 @@ export const performRun = ({ const upstream = result.upstream || null; let delivered = agentPostedItself; let deliveryRefusal = null; + // What became of the reply, for the canary line (lib/supervised-turn.js + // TURN_OUTCOMES). A throw below is reply_lost, finished by runTurn. + let turnOutcome; if (event.type === 'agent.ask') { if (silentReply) { @@ -2222,6 +2239,7 @@ export const performRun = ({ // having nothing to say. if (upstream) log(`[${event.type}] ${describeUpstreamRefusal(upstream)} — no private response`); else log(`[${event.type}] no private response (${reason})`); + turnOutcome = upstream ? 'upstream_refused' : 'silent'; } else { try { await client.post( @@ -2229,6 +2247,7 @@ export const performRun = ({ { content: replyText }, ); delivered = true; + turnOutcome = 'delivered'; log(`[${event.type}] routed private response (${Buffer.byteLength(replyText)} bytes)`); } catch (err) { // A tool-capable agent may have called commonly_respond_to_ask @@ -2237,6 +2256,7 @@ export const performRun = ({ // the model forever. if (err?.status === 409 && err?.body?.code === 'already_responded') { delivered = true; + turnOutcome = 'delivered'; log(`[${event.type}] response already routed by agent tool`); } else { throw err; @@ -2264,6 +2284,7 @@ export const performRun = ({ // Report the two cases distinctly. `posted` is the load-bearing word: a // reader scanning for whether a seat is contributing must not have to // infer it from the absence of a different line. + turnOutcome = agentPostedItself ? 'delivered' : upstream ? 'upstream_refused' : 'silent'; if (agentPostedItself) { log( `[${event.type}] posted via tool, then ${reason} — no echo needed ` @@ -2282,6 +2303,7 @@ export const performRun = ({ // Name the message that caused the suppression. A silently dropped reply // is invisible to everyone; #757 went unnoticed precisely because this // line said only "posted via tool" with no way to tell whose post it saw. + turnOutcome = 'delivered'; log( `[${event.type}] agent posted via tool this turn — not echoing CLI output ` + `(avoids double-post; matched message ${suppressedBy.id} by ${suppressedBy.author} ` @@ -2291,6 +2313,7 @@ export const performRun = ({ // ADR-018 D3: the lease lapsed mid-turn and a peer re-won the message — // that peer owns the conversation now, so posting would recreate the // two-agents-one-message crossing the claim exists to prevent. + turnOutcome = 'claim_lost'; log( `[${event.type}] stood down — claim lost mid-turn to ${claimKeeper.getHolder()}; ` + `reply suppressed (${Buffer.byteLength(replyText)} bytes not posted)`, @@ -2333,6 +2356,7 @@ export const performRun = ({ // it like a refusal: re-posting the same text inside the window would // only be skipped again. deliveryRefusal = delivery; + turnOutcome = 'server_skipped'; const windowMinutes = delivery.duplicate?.dedupeWindowMinutes; const detail = [ windowMinutes ? `${windowMinutes} min window` : null, @@ -2358,6 +2382,7 @@ export const performRun = ({ // guidance expressly says not to retry unchanged), while preserving // the refusal and its partial-post count for the seat and event ledger. deliveryRefusal = delivery; + turnOutcome = 'server_refused'; const guidance = delivery.guidance || 'The server refused this message; do not retry it unchanged.'; const detail = `after ${delivery.messages}/${delivery.attemptedMessages} message${delivery.attemptedMessages === 1 ? '' : 's'}`; log(`[${event.type}] wrapper delivery refused ${detail} (${delivery.reason}): ${guidance}`); @@ -2373,12 +2398,14 @@ export const performRun = ({ )); } else { delivered = true; + turnOutcome = 'delivered'; log( `[${event.type}] posted ${Buffer.byteLength(replyText)} bytes as ` + `${delivery.messages} message${delivery.messages === 1 ? '' : 's'} (${delivery.mode})`, ); } } + turn.finish(turnOutcome); if (result.memorySummary && !memoryWithheld) { try { await syncBack(client, { summary: result.memorySummary }); diff --git a/cli/src/lib/supervised-turn.js b/cli/src/lib/supervised-turn.js index 4731945229..2553ab3a4e 100644 --- a/cli/src/lib/supervised-turn.js +++ b/cli/src/lib/supervised-turn.js @@ -1,6 +1,7 @@ /** - * One model turn of `commonly agent run`, on one of two paths, and one - * metadata line per turn on BOTH so they can be compared (the seats canary). + * One model turn of `commonly agent run`, on one of two paths. The supervised + * path also writes one metadata line per turn (the seats canary), once the + * turn's outcome has reached the pod or failed to. * * COMMONLY_SUPERVISE_RUNS=1 (read by performRun as `superviseRuns`) * the turn runs under `superviseRun` from @commonlyai/seats: a stall @@ -9,7 +10,13 @@ * exactly as on the plain path. * anything else * the plain path: `adapter.spawn(prompt, ctx)` with the caller's ctx object - * untouched. Only the metric line is new. + * untouched, and nothing written: the flag-off run loop is main's. + * + * A turn is ok only when its outcome reached the pod: the reply was delivered + * or the agent chose silence. The run loop names the outcome after delivery + * settles (turn.finish); a spawn that threw is `failed` at once. The + * seat-log baseline (scripts/seat-log-baseline.mjs) maps a log to the same + * outcomes, so the two can be compared event for event. * * NO RECORD WRITER. The supervisor needs a trace store. The one here * (createMetadataStore) is in memory, lives for one turn, and keeps event type @@ -146,10 +153,17 @@ const failureClassOf = (error) => { try { return classifySpawnFailure(error); } catch { return null; } }; -const inferredExitCode = (error) => { - const match = /\bexited with code (-?\d+)\b/.exec(String(error?.message ?? '')); - return match ? Number(match[1]) : null; -}; +// What happened to a turn, named by the run loop once delivery settles. +export const TURN_OUTCOMES = Object.freeze([ + 'delivered', // the reply reached the pod (wrapper post, the agent's own post, or an ask response) + 'silent', // NO_REPLY, a heartbeat control word, or empty output: nothing to post + 'reply_lost', // the model answered and every delivery rung threw + 'claim_lost', // the lease lapsed mid-turn and a peer owns the message; reply suppressed + 'server_skipped', // the server answered and created nothing (a duplicate, a kept heartbeat) + 'server_refused', // the server refused the post (a run cap) + 'upstream_refused', // the model route refused; the CLI exited with nothing to say +]); +export const OK_OUTCOMES = Object.freeze(['delivered', 'silent']); const EVENT_TYPE_RE = /^[A-Za-z0-9._-]{1,40}$/; const iso = (ms) => new Date(ms).toISOString(); @@ -160,32 +174,37 @@ const int = (value) => (Number.isInteger(value) ? value : null); * a short fixed word; nothing from the prompt, the reply, a failure's detail or * the environment can reach it. */ -export const metricLine = (f) => ({ - v: 1, - ts: iso(f.endMs), - seat: String(f.seat || 'unknown').replace(/[^A-Za-z0-9_.-]/g, '_').slice(0, 64), - adapter: String(f.adapter || 'unknown').replace(/[^A-Za-z0-9_.-]/g, '_').slice(0, 32), - path: f.path === 'supervised' ? 'supervised' : 'legacy', - eventType: EVENT_TYPE_RE.test(String(f.eventType || '')) ? f.eventType : null, - turnStart: iso(f.startMs), - turnEnd: iso(f.endMs), - durationMs: Math.max(0, f.endMs - f.startMs), - outcome: f.ok ? 'ok' : 'failed', - failure: f.ok ? null : (f.failureName || 'adapter_error'), - failureSource: f.ok ? null : (f.failureSource || null), - failureClass: f.ok || typeof f.failureClass !== 'string' ? null : f.failureClass, - stalled: !!f.stalled, - cancelled: !!f.cancelled, - killed: !!f.killed, - exitCode: int(f.exitCode), - signal: typeof f.signal === 'string' && /^SIG[A-Z0-9]+$/.test(f.signal) ? f.signal : null, - exitObserved: !!f.exitObserved, - childLeftRunning: typeof f.childLeftRunning === 'boolean' ? f.childLeftRunning : null, - attempts: int(f.attempts), - stallMs: int(f.policy?.stallMs), - cancelGraceMs: int(f.policy?.cancelGraceMs), - timeoutMs: int(f.policy?.timeoutMs), -}); +export const metricLine = (f) => { + const failed = f.outcome === 'failed'; + const outcome = failed || TURN_OUTCOMES.includes(f.outcome) ? f.outcome : 'unknown'; + return { + v: 1, + ts: iso(f.settledMs ?? f.endMs), + seat: String(f.seat || 'unknown').replace(/[^A-Za-z0-9_.-]/g, '_').slice(0, 64), + adapter: String(f.adapter || 'unknown').replace(/[^A-Za-z0-9_.-]/g, '_').slice(0, 32), + path: f.path === 'supervised' ? 'supervised' : 'legacy', + eventType: EVENT_TYPE_RE.test(String(f.eventType || '')) ? f.eventType : null, + turnStart: iso(f.startMs), + turnEnd: iso(f.endMs), + durationMs: Math.max(0, f.endMs - f.startMs), + outcome, + ok: OK_OUTCOMES.includes(outcome), + failure: failed ? (f.failureName || 'adapter_error') : null, + failureSource: failed ? (f.failureSource || null) : null, + failureClass: failed && typeof f.failureClass === 'string' ? f.failureClass : null, + stalled: !!f.stalled, + cancelled: !!f.cancelled, + killed: !!f.killed, + exitCode: int(f.exitCode), + signal: typeof f.signal === 'string' && /^SIG[A-Z0-9]+$/.test(f.signal) ? f.signal : null, + exitObserved: !!f.exitObserved, + childLeftRunning: typeof f.childLeftRunning === 'boolean' ? f.childLeftRunning : null, + attempts: int(f.attempts), + stallMs: int(f.policy?.stallMs), + cancelGraceMs: int(f.policy?.cancelGraceMs), + timeoutMs: int(f.policy?.timeoutMs), + }; +}; const isChild = (value) => !!value && typeof value.once === 'function' && typeof value.kill === 'function'; const isAlive = (child) => !!child && child.exitCode === null && child.signalCode === null; @@ -241,32 +260,7 @@ export const createTurnRunner = ({ + `metrics → ${metricsPath}${warnings.length ? `; ${warnings.join('; ')}` : ''}`; }; - const runPlain = async (adapter, prompt, ctx, eventType) => { - const startMs = now(); - try { - const result = await adapter.spawn(prompt, ctx); - // claude and codex resolve only on exit 0. - record({ adapter: adapter?.name, path: 'legacy', eventType, startMs, endMs: now(), ok: true, exitCode: 0 }); - return result; - } catch (error) { - const { name, source } = failureNameOf(error); - record({ - adapter: adapter?.name, - path: 'legacy', - eventType, - startMs, - endMs: now(), - ok: false, - failureName: name, - failureSource: source, - failureClass: failureClassOf(error), - exitCode: inferredExitCode(error), - }); - throw error; - } - }; - - const runSupervised = async (adapter, prompt, ctx, eventType) => { + const runSupervised = async (adapter, prompt, ctx, eventType, hold) => { const startMs = now(); const policy = supervisedRunPolicy(turnTimeoutMs, { adapterName: adapter?.name, env }); const store = createMetadataStore({ now }); @@ -298,13 +292,13 @@ export const createTurnRunner = ({ const recovered = (action) => events.some((e) => e.type === 'liveness.recovery' && e.action === action); const killed = recovered('kill'); const named = ok ? null : failureNameOf(supervised.failure); - record({ + const fields = { adapter: adapter?.name, path: 'supervised', eventType, startMs, endMs: now(), - ok, + outcome: ok ? undefined : 'failed', failureName: named?.name, failureSource: named?.source, failureClass: ok ? null : failureClassOf(supervised.failure), @@ -317,8 +311,11 @@ export const createTurnRunner = ({ childLeftRunning: child ? isAlive(child) : null, attempts: supervised.attempts, policy, - }); - if (ok) return supervised.result; + }; + // A spawn that resolved is not yet an ok turn: the line waits for the run + // loop to say what became of the reply. + if (ok) { hold(fields); return supervised.result; } + record(fields); if (named.source === 'supervisor') { // The name goes in the seat log. The throw takes the road a plain-path // failure takes: unacked, the run loop's retry policy, onError. @@ -332,9 +329,25 @@ export const createTurnRunner = ({ supervise, metricsPath, describe, - /** One model turn. Same contract as adapter.spawn(prompt, ctx). */ - run(adapter, prompt, ctx, { eventType } = {}) { - return supervise ? runSupervised(adapter, prompt, ctx, eventType) : runPlain(adapter, prompt, ctx, eventType); + /** + * One model turn. `run` has adapter.spawn's contract; `finish(outcome)` + * writes the line once delivery has settled. Only the first finish counts, + * and a finish with no spawned turn behind it writes nothing. + */ + begin({ eventType } = {}) { + let held = null; + let done = false; + return { + run(adapter, prompt, ctx) { + if (!supervise) return adapter.spawn(prompt, ctx); + return runSupervised(adapter, prompt, ctx, eventType, (fields) => { held = fields; }); + }, + finish(outcome) { + if (done || !held) return; + done = true; + record({ ...held, outcome, settledMs: now() }); + }, + }; }, }; }; From af846fa094a19598e79e1081120c2a2ebed1a17a Mon Sep 17 00:00:00 2001 From: Lily Shen <115414357+lilyshen0722@users.noreply.github.com> Date: Sat, 31 Oct 2026 04:33:57 -0700 Subject: [PATCH 8/8] chore(cli): name the supervised turn's metadata a turn log; drop the operator baseline script The per-turn metadata line moves to ~/.commonly/state/turns/.jsonl (COMMONLY_TURN_LOG_DIR overrides it). The seat-log baseline was an operator tool for comparing one host's logs, not part of the CLI, so it leaves the repo along with its test. Test fixtures use synthetic agent names and ids. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01N4VWLC9MiWprFWXFNjJSnr --- .../fixtures/run-loop-flag-off.golden.json | 42 +-- cli/__tests__/seat-log-baseline.test.mjs | 186 ------------- cli/__tests__/supervise-runs-flag.test.mjs | 30 +-- cli/__tests__/supervised-turn.test.mjs | 86 +++--- cli/scripts/seat-log-baseline.mjs | 254 ------------------ cli/src/commands/agent.js | 6 +- cli/src/lib/supervised-turn.js | 18 +- 7 files changed, 86 insertions(+), 536 deletions(-) delete mode 100644 cli/__tests__/seat-log-baseline.test.mjs delete mode 100644 cli/scripts/seat-log-baseline.mjs diff --git a/cli/__tests__/fixtures/run-loop-flag-off.golden.json b/cli/__tests__/fixtures/run-loop-flag-off.golden.json index 8675dc7461..af2a9f85f2 100644 --- a/cli/__tests__/fixtures/run-loop-flag-off.golden.json +++ b/cli/__tests__/fixtures/run-loop-flag-off.golden.json @@ -2,11 +2,11 @@ "success": { "spawns": [ { - "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 1\n@rhea docs gate: #2250, wording only\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 1\n@echo docs gate: #0050, wording only\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", "ctx": { - "agentName": "rhea", + "agentName": "echo", "commitAttributionEnv": null, - "cwd": "/commonly-agents/rhea", + "cwd": "/commonly-agents/echo", "env": "", "environment": null, "instanceUrl": "http://localhost:5000", @@ -20,7 +20,7 @@ "providerKey": "", "runtimeToken": "cm_agent_test", "sessionId": null, - "skillMountDir": "/commonly-agents/rhea", + "skillMountDir": "/commonly-agents/echo", "timeoutMs": 900000 } } @@ -67,11 +67,11 @@ "refusalInMixedBatch": { "spawns": [ { - "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 2 new events in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/2: chat.mention — message 2\n@rhea security gate: #2249, flagged-content-here\n\nEvent 2/2: chat.mention — message 3\n@rhea docs gate: #2251, typo fix\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 2 new events in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/2: chat.mention — message 2\n@echo security gate: #0049, flagged-content-here\n\nEvent 2/2: chat.mention — message 3\n@echo docs gate: #0051, typo fix\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", "ctx": { - "agentName": "rhea", + "agentName": "echo", "commitAttributionEnv": null, - "cwd": "/commonly-agents/rhea", + "cwd": "/commonly-agents/echo", "env": "", "environment": null, "instanceUrl": "http://localhost:5000", @@ -85,16 +85,16 @@ "providerKey": "", "runtimeToken": "cm_agent_test", "sessionId": null, - "skillMountDir": "/commonly-agents/rhea", + "skillMountDir": "/commonly-agents/echo", "timeoutMs": 900000 } }, { - "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 2\n@rhea security gate: #2249, flagged-content-here\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 2\n@echo security gate: #0049, flagged-content-here\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", "ctx": { - "agentName": "rhea", + "agentName": "echo", "commitAttributionEnv": null, - "cwd": "/commonly-agents/rhea", + "cwd": "/commonly-agents/echo", "env": "", "environment": null, "instanceUrl": "http://localhost:5000", @@ -108,16 +108,16 @@ "providerKey": "", "runtimeToken": "cm_agent_test", "sessionId": null, - "skillMountDir": "/commonly-agents/rhea", + "skillMountDir": "/commonly-agents/echo", "timeoutMs": 900000 } }, { - "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 3\n@rhea docs gate: #2251, typo fix\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 3\n@echo docs gate: #0051, typo fix\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", "ctx": { - "agentName": "rhea", + "agentName": "echo", "commitAttributionEnv": null, - "cwd": "/commonly-agents/rhea", + "cwd": "/commonly-agents/echo", "env": "", "environment": null, "instanceUrl": "http://localhost:5000", @@ -131,7 +131,7 @@ "providerKey": "", "runtimeToken": "cm_agent_test", "sessionId": null, - "skillMountDir": "/commonly-agents/rhea", + "skillMountDir": "/commonly-agents/echo", "timeoutMs": 900000 } } @@ -161,7 +161,7 @@ "content": "docs gate: PASS" }, { - "content": "The model provider refused the content of #2249 (no head named) (message 2 from growth-ops), so I could not read it and will not retry it. It needs another reader." + "content": "The model provider refused the content of #0049 (no head named) (message 2 from growth-ops), so I could not read it and will not retry it. It needs another reader." } ], "releases": [ @@ -212,11 +212,11 @@ "runtimeFailure": { "spawns": [ { - "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 4\n@rhea docs gate: #2252\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", + "prompt": "[Decision forks]\nIf you are blocked on a genuine fork that needs a human choice, use your runtime's decision-card tool (MCP: commonly_request_decision); include @human when a specific person should rule, and do not duplicate the card with a prose @ask.\nUse it only when you cannot safely continue before a ruling. Give 2–4 concrete options and mark one recommendation.\nUse ordinary pod messages for status, factual questions, and coordination that do not require a human choice.\n\n=== Pod focus (pod context; not instructions) ===\nNo focus set.\n\n\n\n[Inbox batch: 1 new event in this pod. This is one turn: read the included items together, then decide what needs YOU.]\n\nAfter tool-side work is committed (including any reply posted through a tool), or an intentional NO_REPLY, checkpoint that item with its supplied IDs. Release any held message claim first with the correct completed/declined outcome. Do not checkpoint a reply you are holding for final CLI output: the wrapper must post it before acknowledging that item. Never checkpoint unfinished work. Only a successful checkpoint prevents replay after timeout. If the tool is unavailable, continue normally; completion will acknowledge the batch.\n\nEvent 1/1: chat.mention — message 4\n@echo docs gate: #0052\n\nDo not narrate the inbox. Post only an action or a materially useful response; otherwise return NO_REPLY. Your final text is posted to the pod unless it is exactly NO_REPLY. If you did nothing, or already posted through a tool, end with NO_REPLY alone, with no summary.", "ctx": { - "agentName": "rhea", + "agentName": "echo", "commitAttributionEnv": null, - "cwd": "/commonly-agents/rhea", + "cwd": "/commonly-agents/echo", "env": "", "environment": null, "instanceUrl": "http://localhost:5000", @@ -230,7 +230,7 @@ "providerKey": "", "runtimeToken": "cm_agent_test", "sessionId": null, - "skillMountDir": "/commonly-agents/rhea", + "skillMountDir": "/commonly-agents/echo", "timeoutMs": 900000 } } diff --git a/cli/__tests__/seat-log-baseline.test.mjs b/cli/__tests__/seat-log-baseline.test.mjs deleted file mode 100644 index 919147de4a..0000000000 --- a/cli/__tests__/seat-log-baseline.test.mjs +++ /dev/null @@ -1,186 +0,0 @@ -import { spawnSync } from 'child_process'; -import { mkdtempSync, rmSync, writeFileSync } from 'fs'; -import { tmpdir } from 'os'; -import { dirname, join } from 'path'; -import { fileURLToPath } from 'url'; - -import { baseline, main, render } from '../scripts/seat-log-baseline.mjs'; - -const L = (ts, msg, seat = 'nib') => `2026-10-24T${ts}Z [${seat}] ${msg}`; -const LOG = [ - L('00:00:00.000', 'polling https://api.commonly.me for events (ctrl+c to stop)'), - L('01:00:00.000', '[inbox.batch] spawning codex'), - L('01:00:00.400', 'spawn credential minted (6adbd35b8522fc8abce9b7b6, granted 9 tools)'), - L('01:00:30.000', 'spawn credential revoked (6adbd35b8522fc8abce9b7b6)'), - L('01:00:30.300', '[inbox.batch] agent posted via tool this turn — not echoing CLI output'), - L('02:00:00.000', '[inbox.batch] spawning codex'), - L('02:45:00.000', 'spawn credential revoked (6adbd35b8522fc8abce9b7b7)'), - L('02:45:00.100', 'inbox batch processing failed (runtime; 1 consecutive) — 1 events remain unacked; retry scheduled, next probe in 5.6s: codex timed out after 2700000ms SECRET-STDERR-TEXT'), - ' SECRET-HTML', - L('03:00:00.000', '[chat.mention] spawning codex'), - L('03:00:05.000', 'inbox batch processing failed (runtime; 1 consecutive) — 1 events remain unacked: codex exited with code 7: SECRET-STDERR-TEXT'), - L('04:00:00.000', '[inbox.batch] spawning claude'), - L('04:01:00.000', 'stopping after the current turn...'), - L('04:02:00.000', 'fetch failed'), - L('05:00:00.000', '[inbox.batch] spawning claude', 'quire'), - L('06:00:00.000', '[inbox.batch] spawning codex'), -].join('\n'); - -test('turns, durations, timeouts, exits, restarts, and an open turn, from timestamps and fixed phrases', () => { - const r = baseline(LOG, { seat: 'nib', untilMs: Date.parse('2026-10-24T07:00:00Z'), hours: 48 }); - expect(r.byAdapter.codex).toMatchObject({ - turns: 4, ok: 1, failed: 2, timeouts: 1, exits: { 7: 1 }, errors: 0, open: 1, atOrOverTimeout: 1, - outcomes: { delivered: 1, failed: 2 }, - }); - expect(r.byAdapter.codex.durationMs).toEqual({ p50: 30_000, p90: 2_700_100, p99: 2_700_100, max: 2_700_100, n: 3 }); - expect(r.byAdapter.claude).toMatchObject({ turns: 1, cutByRestart: 1 }); - expect(r.counts).toMatchObject({ untimestamped: 1, pollErrors: 1, restarts: 0, otherSeatLines: 1 }); - const out = `${render(r)}\n${JSON.stringify(r)}`; - expect(out).not.toMatch(/SECRET/); - expect(out).toMatch(/the log cannot tell/); -}); - -test('ask outcomes close a turn, and a refused spawn credential is not a turn', () => { - const log = [ - L('01:00:00.000', '[agent.ask] spawning codex'), - L('01:00:10.000', '[agent.ask] routed private response (42 bytes)'), - L('02:00:00.000', '[agent.ask] spawning codex'), - L('02:00:10.000', '[agent.ask] response already routed by agent tool'), - L('03:00:00.000', '[agent.ask] spawning codex'), - L('03:00:10.000', '[agent.ask] no private response (empty output)'), - L('04:00:00.000', '[inbox.batch] spawning codex'), - L('04:00:00.300', 'spawn credential refused (HTTP 403) — not spawning'), - L('05:00:00.000', '[inbox.batch] spawning codex'), - L('05:00:20.000', '[inbox.batch] no wrapper-post (NO_REPLY)'), - ].join('\n'); - const r = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T06:00:00Z'), hours: 8 }); - expect(r.byAdapter.codex).toMatchObject({ - turns: 4, ok: 4, open: 0, unclosed: 0, outcomes: { delivered: 2, silent: 2 }, - }); - expect(r.counts.spawnRefused).toBe(1); - expect(render(r)).toMatch(/spawns refused a credential 1/); -}); - -test('a first start is not a restart, a failed lease is not a turn, and a lost reply is not an adapter error', () => { - const log = [ - L('00:00:00.000', 'polling https://api.commonly.me for events (ctrl+c to stop)'), - L('01:00:00.000', '[inbox.batch] spawning codex'), - L('01:00:00.200', 'spawn credential lease failed (socket hang up) — not spawning'), - L('01:00:00.300', 'inbox batch processing failed (runtime; 1 consecutive) — 1 events remain unacked: socket hang up'), - L('02:00:00.000', '[chat.mention] spawning codex'), - L('02:00:30.000', '[chat.mention] ERROR reply NOT delivered to pod p1 — 120 bytes lost, 1 event left unacked for retry: HTTP 502'), - L('02:00:30.100', 'chat.mention processing failed (runtime; 1 consecutive): HTTP 502'), - L('03:00:00.000', 'polling https://api.commonly.me for events (ctrl+c to stop)'), - ].join('\n'); - const inWindow = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T04:00:00Z'), hours: 8 }); - expect(inWindow.counts).toMatchObject({ restarts: 1, leaseFailed: 1, spawnRefused: 0 }); - // The model answered, so the spawn did not fail; the turn is still not ok. - expect(inWindow.byAdapter.codex).toMatchObject({ turns: 1, ok: 0, failed: 0, errors: 0, outcomes: { reply_lost: 1 } }); - // The start before the window still makes the 03:00 line a restart. - const late = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T04:00:00Z'), hours: 1.5 }); - expect(late.counts.restarts).toBe(1); -}); - -test('a turn is ok only when it was delivered or silent: a lost claim, a skip, a refusal and a refused route are not', () => { - const log = [ - L('01:00:00.000', '[chat.mention] spawning codex'), - L('01:00:05.000', '[chat.mention] claim on message 42 lost mid-turn to peer — standing down at post time'), - L('01:00:10.000', '[chat.mention] stood down — claim lost mid-turn to peer; reply suppressed (120 bytes not posted)'), - L('02:00:00.000', '[chat.mention] spawning codex'), - L('02:00:10.000', '[chat.mention] upstream refused 429 — nothing posted this turn'), - L('03:00:00.000', '[agent.ask] spawning codex'), - L('03:00:10.000', '[agent.ask] upstream refused 403: route closed — no private response'), - L('04:00:00.000', '[chat.mention] spawning codex'), - L('04:00:10.000', '[chat.mention] server skipped the post: duplicate (10 min window) — nothing reached the pod'), - L('05:00:00.000', '[chat.mention] spawning codex'), - L('05:00:10.000', '[chat.mention] wrapper delivery refused after 0/1 message (run_cap): stop'), - L('06:00:00.000', '[chat.mention] spawning codex'), - L('06:00:10.000', '[chat.mention] posted 120 bytes as 1 message (single)'), - ].join('\n'); - const r = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T07:00:00Z'), hours: 8 }); - expect(r.byAdapter.codex).toMatchObject({ - turns: 6, - ok: 1, - failed: 0, - outcomes: { claim_lost: 1, upstream_refused: 2, server_skipped: 1, server_refused: 1, delivered: 1 }, - }); -}); - -test('the window bounds which turns count', () => { - const r = baseline(LOG, { seat: 'nib', untilMs: Date.parse('2026-10-24T02:30:00Z'), hours: 2 }); - expect(r.byAdapter.codex.turns).toBe(2); - expect(r.byAdapter.codex.ok).toBe(1); - // the 02:00 turn closes past the window end, as a failure, and still counts - expect(r.byAdapter.codex.timeouts).toBe(1); -}); - -test('a turn on the seat token, and one whose revoke failed, still close as ok', () => { - const log = [ - L('01:00:00.000', '[inbox.batch] spawning codex'), - L('01:00:00.200', 'spawn credential unavailable (HTTP 503) — spawning with the seat token'), - L('01:00:20.000', '[inbox.batch] agent posted via tool this turn — not echoing CLI output'), - L('02:00:00.000', '[inbox.batch] spawning codex'), - L('02:00:40.000', 'spawn credential revoke failed (6adbd35b8522fc8abce9b7b8, 503) — the boot sweep will collect it'), - L('02:00:40.500', '[inbox.batch] no wrapper-post (NO_REPLY)'), - ].join('\n'); - const r = baseline(log, { seat: 'nib', untilMs: Date.parse('2026-10-24T03:00:00Z'), hours: 4 }); - expect(r.byAdapter.codex).toMatchObject({ turns: 2, ok: 2, open: 0, outcomes: { delivered: 1, silent: 1 } }); - expect(r.byAdapter.codex.durationMs.max).toBe(40_000); -}); - -test('a malformed option is a usage error, not a stack trace or a NaN report', () => { - const dir = mkdtempSync(join(tmpdir(), 'seat-log-baseline-')); - try { - const log = join(dir, 'nib.log'); - writeFileSync(log, LOG); - const run = (...args) => { - const out = []; - const err = []; - const status = main(['nib', ...args], { stdout: { write: (t) => out.push(t) }, stderr: { write: (t) => err.push(t) } }); - return { status, out: out.join(''), err: err.join('') }; - }; - for (const [args, message] of [ - [['--log'], '--log needs a value'], - [['--log', '--json'], '--log needs a value'], - [['--log', log, '--hours'], '--hours must be a positive number'], - [['--log', log, '--hours', 'abc'], '--hours must be a positive number'], - [['--log', log, '--timeout-ms', 'x'], '--timeout-ms must be a positive number'], - [['--log', log, '--until'], '--until needs a value'], - [['--log', log, '--until', 'yesterday'], '--until is not an ISO date'], - [['--log', log, '--until', 'Oct 24 2026'], '--until is not an ISO date'], - [['--log', log, '--until', '2026-02-31T00:00:00Z'], '--until is not an ISO date'], - // No zone: Date.parse would read it as host-local time. - [['--log', log, '--until', '2026-10-24T07:00:00'], '--until is not an ISO date'], - [['--log', log, '--hours', '1000000000000'], '--hours puts the window start outside the supported date range'], - ]) { - expect(run(...args)).toEqual({ status: 2, out: '', err: `${message}\n` }); - } - const ok = run('--log', log, '--until', '2026-10-24T07:00:00Z', '--hours', '48', '--json'); - expect(ok.status).toBe(0); - expect(JSON.parse(ok.out).byAdapter.codex.turns).toBe(4); - } finally { - rmSync(dir, { recursive: true, force: true }); - } -}); - -test('run as a script, it reads the log it is given and prints no free text', () => { - const dir = mkdtempSync(join(tmpdir(), 'seat-log-baseline-')); - try { - const log = join(dir, 'nib.log'); - writeFileSync(log, LOG); - const script = join(dirname(fileURLToPath(import.meta.url)), '..', 'scripts', 'seat-log-baseline.mjs'); - const args = ['nib', '--log', log, '--until', '2026-10-24T07:00:00Z', '--hours', '48']; - const json = spawnSync(process.execPath, [script, ...args, '--json'], { encoding: 'utf8' }); - expect({ status: json.status, stderr: json.stderr }).toEqual({ status: 0, stderr: '' }); - const r = JSON.parse(json.stdout); - expect(r.seat).toBe('nib'); - expect(r.byAdapter.codex).toMatchObject({ turns: 4, ok: 1, failed: 2 }); - expect(r.counts).toMatchObject({ untimestamped: 1, otherSeatLines: 1 }); - const text = spawnSync(process.execPath, [script, ...args], { encoding: 'utf8' }); - expect(text.status).toBe(0); - expect(text.stdout).toMatch(/codex: 4 turns, 1 ok \(delivered or silent\), 2 spawns failed/); - expect(`${json.stdout}${text.stdout}`).not.toMatch(/SECRET/); - } finally { - rmSync(dir, { recursive: true, force: true }); - } -}); diff --git a/cli/__tests__/supervise-runs-flag.test.mjs b/cli/__tests__/supervise-runs-flag.test.mjs index ed1c4abacc..c1e16a87cc 100644 --- a/cli/__tests__/supervise-runs-flag.test.mjs +++ b/cli/__tests__/supervise-runs-flag.test.mjs @@ -59,7 +59,7 @@ const event = (id, content, over = {}) => ({ _id: id, type: 'chat.mention', podId: POD_ID, - agentName: 'rhea', + agentName: 'echo', instanceId: 'default', payload: { content, messageId: id.replace(/\D/g, '') || '1', username: 'growth-ops' }, ...over, @@ -93,7 +93,7 @@ const harness = ({ events, adapter, env = {}, extra = {} }) => { instanceUrl: 'http://localhost:5000', token: 'cm_agent_test', adapter, - agentName: 'rhea', + agentName: 'echo', retryJitterRatio: 0, claimYieldDelayMs: 0, sleepImpl: async () => {}, @@ -136,13 +136,13 @@ const normalise = (value) => JSON.parse(JSON.stringify(value, (_key, v) => ( const SCENARIOS = { success: { - events: [event('evt-1', '@rhea docs gate: #2250, wording only')], + events: [event('evt-1', '@echo docs gate: #0050, wording only')], spawn: async () => ({ text: 'docs gate: PASS' }), }, refusalInMixedBatch: { events: [ - event('evt-2', '@rhea security gate: #2249, flagged-content-here'), - event('evt-3', '@rhea docs gate: #2251, typo fix'), + event('evt-2', '@echo security gate: #0049, flagged-content-here'), + event('evt-3', '@echo docs gate: #0051, typo fix'), ], spawn: async (prompt) => { if (prompt.includes('flagged-content-here')) { @@ -152,7 +152,7 @@ const SCENARIOS = { }, }, runtimeFailure: { - events: [event('evt-4', '@rhea docs gate: #2252')], + events: [event('evt-4', '@echo docs gate: #0052')], spawn: async () => { throw new Error('runtime unavailable'); }, }, }; @@ -205,9 +205,9 @@ describe('COMMONLY_SUPERVISE_RUNS off', () => { } const golden = JSON.parse(fs.readFileSync(GOLDEN, 'utf8')); expect(got).toEqual(golden); - // Off, nothing is written: no trace store, and no canary line. + // Off, nothing is written: no trace store, and no turn line. expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); - expect(fs.existsSync(path.join(home, '.commonly', 'state', 'seats-canary'))).toBe(false); + expect(fs.existsSync(path.join(home, '.commonly', 'state', 'turns'))).toBe(false); }); if (!WRITE_GOLDEN) { @@ -228,14 +228,14 @@ describe('COMMONLY_SUPERVISE_RUNS off', () => { }; fs.rmSync(path.join(home, '.commonly'), { recursive: true, force: true }); const run = harness({ - events: [event('evt-5', '@rhea hi')], adapter, env: { COMMONLY_SUPERVISE_RUNS: '1' }, extra: { superviseRuns: false }, + events: [event('evt-5', '@echo hi')], adapter, env: { COMMONLY_SUPERVISE_RUNS: '1' }, extra: { superviseRuns: false }, }); await drain(); run.handle.stop(); expect(spawns).toHaveLength(1); expect(spawns[0]).not.toHaveProperty('signal'); expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); - expect(fs.existsSync(path.join(home, '.commonly', 'state', 'seats-canary'))).toBe(false); + expect(fs.existsSync(path.join(home, '.commonly', 'state', 'turns'))).toBe(false); }); } }); @@ -278,7 +278,7 @@ describe('COMMONLY_SUPERVISE_RUNS=1 with the real codex adapter', () => { // Each turn spawns a real child and makes real loopback calls; under a // parallel suite on a loaded host that takes longer than jest's 5 s default. jest.setTimeout(60_000); - const CANARY_KEY = 'sk-canary-run-loop-4c1d9e7a'; + const TURN_KEY = 'sk-turn-run-loop-4c1d9e7a'; test('a clean reply is posted, the metric line says supervised and delivered, and nothing else reaches disk', async () => { const { startFakeProvider } = await import('../../packages/seats/test-support/fake-provider.js'); @@ -296,7 +296,7 @@ describe('COMMONLY_SUPERVISE_RUNS=1 with the real codex adapter', () => { const env = { COMMONLY_SUPERVISE_RUNS: '1', CODEX_HOME: codexHome, - FAKE_PROVIDER_KEY: CANARY_KEY, + FAKE_PROVIDER_KEY: TURN_KEY, STUB_CODEX_DIRECT_BASE: provider.baseURL, PATH: `${bin}${path.delimiter}${path.dirname(process.execPath)}${path.delimiter}${process.env.PATH}`, }; @@ -305,7 +305,7 @@ describe('COMMONLY_SUPERVISE_RUNS=1 with the real codex adapter', () => { Object.assign(process.env, env); try { const run = harness({ - events: [event('evt-9', '@rhea review #2249')], + events: [event('evt-9', '@echo review #0049')], adapter: codex, extra: { environment: { model: 'gpt-test' }, workspacePath: workspace }, }); @@ -323,7 +323,7 @@ describe('COMMONLY_SUPERVISE_RUNS=1 with the real codex adapter', () => { expect(run.posts().map((p) => p.content)).toContain('review: PASS'); expect(provider.requests.map((r) => r.authorization)).toEqual(['present']); expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); - const lines = fs.readFileSync(path.join(home, '.commonly', 'state', 'seats-canary', 'rhea.jsonl'), 'utf8') + const lines = fs.readFileSync(path.join(home, '.commonly', 'state', 'turns', 'echo.jsonl'), 'utf8') .split('\n').filter(Boolean).map((line) => JSON.parse(line)); expect(lines).toEqual([expect.objectContaining({ path: 'supervised', adapter: 'codex', outcome: 'delivered', ok: true, failure: null, @@ -332,7 +332,7 @@ describe('COMMONLY_SUPERVISE_RUNS=1 with the real codex adapter', () => { // The reply was posted, and is in no file the run left: no record writer. for (const file of filesUnder(home)) { const text = fs.readFileSync(file, 'utf8'); - expect({ file, reply: text.includes('review: PASS'), auth: text.includes(CANARY_KEY) }) + expect({ file, reply: text.includes('review: PASS'), auth: text.includes(TURN_KEY) }) .toEqual({ file, reply: false, auth: false }); } } finally { diff --git a/cli/__tests__/supervised-turn.test.mjs b/cli/__tests__/supervised-turn.test.mjs index 1097c46bf9..c8a9e02ba2 100644 --- a/cli/__tests__/supervised-turn.test.mjs +++ b/cli/__tests__/supervised-turn.test.mjs @@ -1,11 +1,11 @@ /** - * The seats canary's turn runner (lib/supervised-turn.js) and its place in the + * The supervised turn runner (lib/supervised-turn.js) and its place in the * run loop. * * - flag off: adapter.spawn gets the caller's prompt and ctx object, unchanged, * and superviseRun is never called (the golden in supervise-runs-flag.test * pins the whole run loop byte for byte); - * - flag on: the turn goes through superviseRun with the canary policy; + * - flag on: the turn goes through superviseRun with the turn log policy; * - a stalled turn is named `stuck`, its child killed, its event left unacked, * and the run loop goes on to the next event; * - flag on, one metric line per turn, written once delivery settles, and no @@ -33,7 +33,6 @@ await jest.unstable_mockModule('../src/lib/pod-focus.js', () => ({ })); const { createClient } = await import('../src/lib/api.js'); -const { baseline } = await import('../scripts/seat-log-baseline.mjs'); const { performRun } = await import('../src/commands/agent.js'); const { createTurnRunner, createMetadataStore, supervisedRunPolicy, metricLine, STALL_DEFAULTS_MS, TURN_OUTCOMES, @@ -46,7 +45,7 @@ afterAll(() => fs.rmSync(home, { recursive: true, force: true })); const PROMPT = 'PROMPT-TEXT-7f3a1c do the docs wash'; const REPLY = 'REPLY-TEXT-b29e40 done'; const ERROR_TEXT = 'ERROR-TEXT-55c0de upstream said no'; -const metricsFile = (seat) => path.join(home, '.commonly', 'state', 'seats-canary', `${seat}.jsonl`); +const metricsFile = (seat) => path.join(home, '.commonly', 'state', 'turns', `${seat}.jsonl`); const readMetrics = (seat) => (fs.existsSync(metricsFile(seat)) ? fs.readFileSync(metricsFile(seat), 'utf8').split('\n').filter(Boolean).map((l) => JSON.parse(l)) : []); const reset = () => fs.rmSync(path.join(home, '.commonly'), { recursive: true, force: true }); @@ -124,7 +123,7 @@ describe('the turn runner', () => { const superviseRun = jest.fn(); const spawn = jest.fn(async () => ({ text: REPLY })); const ctx = { cwd: '/w', env: process.env, timeoutMs: 5 }; - const runner = createTurnRunner({ seat: 'quire', turnTimeoutMs: 5, supervise: false, superviseRun, env: {} }); + const runner = createTurnRunner({ seat: 'delta', turnTimeoutMs: 5, supervise: false, superviseRun, env: {} }); await expect(turnOf(runner, { name: 'claude', spawn }, ctx)).resolves.toEqual({ text: REPLY }); expect(spawn).toHaveBeenCalledTimes(1); expect(spawn.mock.calls[0][0]).toBe(PROMPT); @@ -135,13 +134,13 @@ describe('the turn runner', () => { expect(fs.existsSync(path.join(home, '.commonly'))).toBe(false); }); - test('flag on: the turn goes through superviseRun with the canary policy and a no-record store, and no relay', async () => { + test('flag on: the turn goes through superviseRun with the turn log policy and a no-record store, and no relay', async () => { const superviseRun = jest.fn(async ({ store }) => { store.startRun({}).emit('run.settled', { outcome: 'ok' }); return { outcome: 'ok', attempts: 1, result: { text: REPLY } }; }); const spawn = jest.fn(); - const runner = createTurnRunner({ seat: 'nib', turnTimeoutMs: 2_700_000, supervise: true, superviseRun, env: {} }); + const runner = createTurnRunner({ seat: 'delta', turnTimeoutMs: 2_700_000, supervise: true, superviseRun, env: {} }); await expect(turnOf(runner, { name: 'codex', spawn }, { cwd: '/w' }, { eventType: 'inbox.batch' })) .resolves.toEqual({ text: REPLY }); expect(spawn).not.toHaveBeenCalled(); @@ -172,18 +171,18 @@ describe('the turn runner', () => { child.once('spawn', () => ctx.onSpawn({}, child)); }), }; - const runner = createTurnRunner({ seat: 'nib', turnTimeoutMs: 60_000, supervise: true, env, log: (l) => logs.push(l) }); + const runner = createTurnRunner({ seat: 'delta', turnTimeoutMs: 60_000, supervise: true, env, log: (l) => logs.push(l) }); const error = await within(turnOf(runner, adapter), 5000).catch((e) => e); expect(error.kind).toBe('stuck'); expect(isRunning(pid)).toBe(false); expect(logs).toEqual([expect.stringMatching(/^\[chat\.mention\] supervised turn failed: stuck \(child killed\)$/)]); - expect(readMetrics('nib')).toEqual([expect.objectContaining({ + expect(readMetrics('delta')).toEqual([expect.objectContaining({ path: 'supervised', outcome: 'failed', ok: false, failure: 'stuck', failureSource: 'supervisor', stalled: true, cancelled: true, killed: true, signal: 'SIGKILL', exitObserved: true, childLeftRunning: false, stallMs: 300, })]); }); - test('a stalled child in its own group is killed with its grandchild (group kill on the canary path)', async () => { + test('a stalled child in its own group is killed with its grandchild (group kill on the turn log path)', async () => { const env = { COMMONLY_SUPERVISE_STALL_MS: '500', COMMONLY_SUPERVISE_CANCEL_GRACE_MS: '40' }; // The CLI stand-in starts a grandchild in a group of its own (as codex does // for MCP servers), reports its pid on stderr, then goes quiet. @@ -205,7 +204,7 @@ describe('the turn runner', () => { child.once('spawn', () => ctx.onSpawn({}, child)); }), }; - const runner = createTurnRunner({ seat: 'nib', turnTimeoutMs: 60_000, supervise: true, env }); + const runner = createTurnRunner({ seat: 'delta', turnTimeoutMs: 60_000, supervise: true, env }); const error = await turnOf(runner, adapter).catch((e) => e); expect(error.kind).toBe('stuck'); expect(ownGroup).toBe(process.platform !== 'win32'); @@ -224,17 +223,17 @@ describe('the turn runner', () => { const ok = { name: 'codex', spawn: async () => ({ text: REPLY }) }; const bad = { name: 'codex', spawn: async () => { throw new Error(`codex exited with code 3: ${ERROR_TEXT}`); } }; const named = { name: 'codex', spawn: async () => { throw runFailure('exited', ERROR_TEXT); } }; - const plain = createTurnRunner({ seat: 'nib', turnTimeoutMs: 1000, supervise: false, env }); - const supervised = createTurnRunner({ seat: 'nib', turnTimeoutMs: 1000, supervise: true, env }); + const plain = createTurnRunner({ seat: 'delta', turnTimeoutMs: 1000, supervise: false, env }); + const supervised = createTurnRunner({ seat: 'delta', turnTimeoutMs: 1000, supervise: true, env }); await turnOf(plain, ok); await turnOf(plain, bad).catch(() => {}); - expect(readMetrics('nib')).toEqual([]); + expect(readMetrics('delta')).toEqual([]); // A spawn that resolved writes nothing until the run loop says what // became of the reply, and only the first finish counts. const held = supervised.begin({ eventType: 'inbox.batch' }); await held.run(ok, PROMPT, {}); - expect(readMetrics('nib')).toEqual([]); + expect(readMetrics('delta')).toEqual([]); held.finish('reply_lost'); held.finish('delivered'); for (const outcome of ['delivered', 'silent', 'claim_lost']) { @@ -248,7 +247,7 @@ describe('the turn runner', () => { await turn.run(adapter, PROMPT, {}).catch(() => turn.finish('reply_lost')); } - const lines = readMetrics('nib'); + const lines = readMetrics('delta'); expect(lines.map((l) => [l.path, l.outcome, l.ok, l.failure])).toEqual([ ['supervised', 'reply_lost', false, null], ['supervised', 'delivered', true, null], @@ -263,16 +262,16 @@ describe('the turn runner', () => { expect(['string', 'number', 'boolean'].includes(typeof value) || value === null).toBe(true); } } - const raw = fs.readFileSync(metricsFile('nib'), 'utf8'); + const raw = fs.readFileSync(metricsFile('delta'), 'utf8'); for (const text of [PROMPT, REPLY, ERROR_TEXT, 'PROMPT-TEXT', 'REPLY-TEXT', 'ERROR-TEXT']) expect(raw).not.toContain(text); }); - test('the seat name cannot leave the canary directory, and a bad event label is dropped', async () => { - const dir = path.join(home, 'canary'); + test('the seat name cannot leave the turn log directory, and a bad event label is dropped', async () => { + const dir = path.join(home, 'turn-log'); const ok = { name: 'codex', spawn: async () => ({ text: REPLY }) }; for (const seat of ['../../etc/x', 'a'.repeat(200)]) { const runner = createTurnRunner({ - seat, turnTimeoutMs: 1000, supervise: true, env: { COMMONLY_SUPERVISE_STALL_MS: '0', COMMONLY_SEATS_CANARY_DIR: dir }, + seat, turnTimeoutMs: 1000, supervise: true, env: { COMMONLY_SUPERVISE_STALL_MS: '0', COMMONLY_TURN_LOG_DIR: dir }, }); expect(path.dirname(runner.metricsPath)).toBe(dir); // eslint-disable-next-line no-await-in-loop @@ -291,7 +290,7 @@ describe('the turn runner', () => { test('metricLine drops anything it does not list, and an outcome it does not know is unknown, not ok', () => { const line = metricLine({ - seat: 'nib', adapter: 'codex', path: 'supervised', startMs: 0, endMs: 5, outcome: 'delivered', text: REPLY, prompt: PROMPT, detail: ERROR_TEXT, + seat: 'delta', adapter: 'codex', path: 'supervised', startMs: 0, endMs: 5, outcome: 'delivered', text: REPLY, prompt: PROMPT, detail: ERROR_TEXT, }); expect(Object.keys(line).sort()).toEqual(METRIC_KEYS); expect(line).toMatchObject({ outcome: 'delivered', ok: true }); @@ -306,10 +305,10 @@ describe('the turn runner', () => { fs.writeFileSync(blocker, ''); const logs = []; const runner = createTurnRunner({ - seat: 'nib', + seat: 'delta', turnTimeoutMs: 1000, supervise: true, - env: { COMMONLY_SUPERVISE_STALL_MS: '0', COMMONLY_SEATS_CANARY_DIR: path.join(blocker, 'x') }, + env: { COMMONLY_SUPERVISE_STALL_MS: '0', COMMONLY_TURN_LOG_DIR: path.join(blocker, 'x') }, log: (l) => logs.push(l), }); const adapter = { name: 'codex', spawn: async () => ({ text: REPLY }) }; @@ -337,8 +336,8 @@ describe('the metadata store', () => { const POD = '6a8f6dc7a1dccf2e02f31015'; const event = (id) => ({ - _id: id, type: 'chat.mention', podId: POD, agentName: 'nib', instanceId: 'default', - payload: { content: `@nib ${PROMPT} (${id})`, messageId: id.replace(/\D/g, '') || '1', username: 'growth-ops' }, + _id: id, type: 'chat.mention', podId: POD, agentName: 'delta', instanceId: 'default', + payload: { content: `@delta ${PROMPT} (${id})`, messageId: id.replace(/\D/g, '') || '1', username: 'growth-ops' }, }); const CLAIM_RENEW_MS = 45_000; // the default 90 s lease renews at half-life @@ -362,20 +361,19 @@ const loop = ({ const errors = []; const scheduled = []; const intervals = []; - const seatLines = []; const handle = performRun({ instanceUrl: 'http://localhost:5000', token: 'cm_agent_test', adapter, - agentName: 'nib', + agentName: 'delta', environment: { model: 'gpt-test' }, retryJitterRatio: 0, claimYieldDelayMs: 0, sleepImpl: async () => {}, superviseRuns, - log: (line) => { logs.push(String(line)); seatLines.push(String(line)); }, + log: (line) => { logs.push(String(line)); }, // `commonly agent run` stamps onError into the same seat log as log(). - onError: (err) => { errors.push(err); seatLines.push(err.message); }, + onError: (err) => { errors.push(err); }, setTimeoutImpl: (callback, delayMs) => { scheduled.push({ callback, delayMs }); return 0; }, setIntervalImpl: (callback, delayMs) => { intervals.push({ callback, delayMs }); return intervals.length; }, clearIntervalImpl: () => {}, @@ -384,9 +382,7 @@ const loop = ({ const acks = () => post.mock.calls.filter(([r]) => String(r).endsWith('/ack')).map(([r, b]) => ({ id: String(r).split('/').at(-2), result: b.result })); // The claim keeper's renewal ticks, fired by hand (mid-turn, from a spawn). const renewClaims = () => Promise.all(intervals.filter((i) => i.delayMs === CLAIM_RENEW_MS).map((i) => i.callback())); - // The run's log as the seat log has it, for the baseline. - const seatLog = () => seatLines.map((line, i) => `2026-10-26T00:00:${String(i).padStart(2, '0')}.000Z [nib] ${line}`).join('\n'); - return { handle, logs, errors, scheduled, acks, restore, post, renewClaims, seatLog }; + return { handle, logs, errors, scheduled, acks, restore, post, renewClaims }; }; const until = async (predicate, ms = 10_000) => { @@ -412,9 +408,9 @@ describe('the run loop', () => { // Only superviseRun hands an adapter a cancel signal and a trace hook. expect('signal' in ctxs[0]).toBe(superviseRuns); expect('trace' in ctxs[0]).toBe(superviseRuns); - // Flag off writes no canary line at all; flag on writes one once the reply is posted. - expect(readMetrics('nib').map((l) => [l.path, l.outcome, l.ok])).toEqual(superviseRuns ? [[pathName, 'delivered', true]] : []); - expect(fs.existsSync(path.join(home, '.commonly', 'state', 'seats-canary'))).toBe(superviseRuns); + // Flag off writes no turn line at all; flag on writes one once the reply is posted. + expect(readMetrics('delta').map((l) => [l.path, l.outcome, l.ok])).toEqual(superviseRuns ? [[pathName, 'delivered', true]] : []); + expect(fs.existsSync(path.join(home, '.commonly', 'state', 'turns'))).toBe(superviseRuns); expect(fs.existsSync(path.join(home, '.commonly', 'traces'))).toBe(false); }); @@ -457,18 +453,16 @@ describe('the run loop', () => { await until(() => ['evt-a', 'evt-b'].every((id) => run.acks().some((a) => a.id === id))); expect(run.acks().filter((a) => a.id === 'evt-a')).toEqual([{ id: 'evt-a', result: { outcome: 'posted' } }]); } finally { run.handle.stop(); run.restore(); } - const turns = readMetrics('nib').map((l) => [l.path, l.outcome, l.failure, l.killed]); + const turns = readMetrics('delta').map((l) => [l.path, l.outcome, l.failure, l.killed]); expect(turns[0]).toEqual(['supervised', 'failed', 'stuck', true]); expect(turns.slice(1).length).toBeGreaterThan(0); for (const turn of turns.slice(1)) expect(turn).toEqual(['supervised', 'delivered', null, false]); }); // A turn is ok only once its outcome reached the pod. Each case below runs - // the real run loop with the flag on, then reads the same turn back two - // ways: the canary line, and the seat-log baseline over the run's own log. - const baselineOf = (run) => baseline(run.seatLog(), { seat: 'nib', untilMs: Date.parse('2026-10-26T01:00:00Z'), hours: 2 }); + // the real run loop with the flag on, then reads the turn back from its turn line. - test('a lease lost mid-turn is claim_lost, not ok: the reply is not posted, in the canary and the baseline alike', async () => { + test('a lease lost mid-turn is claim_lost, not ok: the reply is not posted', async () => { const renewals = { n: 0 }; let run; const adapter = { @@ -489,16 +483,15 @@ describe('the run loop', () => { }, }); try { - await until(() => readMetrics('nib').length === 1); + await until(() => readMetrics('delta').length === 1); } finally { run.handle.stop(); run.restore(); } expect(renewals.n).toBeGreaterThan(1); expect(run.logs).toEqual(expect.arrayContaining([expect.stringMatching(/stood down — claim lost mid-turn to peer; reply suppressed/)])); expect(run.post.mock.calls.filter(([r]) => String(r).endsWith('/messages'))).toEqual([]); - expect(readMetrics('nib')).toEqual([expect.objectContaining({ path: 'supervised', outcome: 'claim_lost', ok: false, failure: null })]); - expect(baselineOf(run).byAdapter.codex).toMatchObject({ turns: 1, ok: 0, failed: 0, outcomes: { claim_lost: 1 } }); + expect(readMetrics('delta')).toEqual([expect.objectContaining({ path: 'supervised', outcome: 'claim_lost', ok: false, failure: null })]); }); - test('a reply every delivery rung refused is reply_lost, not ok: the event stays unacked, in the canary and the baseline alike', async () => { + test('a reply every delivery rung refused is reply_lost, not ok: the event stays unacked', async () => { const adapter = { name: 'codex', detect: async () => null, spawn: async () => ({ text: REPLY }) }; const rungs = []; const run = loop({ @@ -517,12 +510,11 @@ describe('the run loop', () => { }, }); try { - await until(() => readMetrics('nib').length === 1 && run.errors.length === 1); + await until(() => readMetrics('delta').length === 1 && run.errors.length === 1); } finally { run.handle.stop(); run.restore(); } expect(rungs.length).toBeGreaterThan(0); expect(run.logs).toEqual(expect.arrayContaining([expect.stringMatching(/ERROR reply NOT delivered to pod/)])); expect(run.acks()).toEqual([]); - expect(readMetrics('nib')).toEqual([expect.objectContaining({ path: 'supervised', outcome: 'reply_lost', ok: false, failure: null })]); - expect(baselineOf(run).byAdapter.codex).toMatchObject({ turns: 1, ok: 0, failed: 0, errors: 0, outcomes: { reply_lost: 1 } }); + expect(readMetrics('delta')).toEqual([expect.objectContaining({ path: 'supervised', outcome: 'reply_lost', ok: false, failure: null })]); }); }); diff --git a/cli/scripts/seat-log-baseline.mjs b/cli/scripts/seat-log-baseline.mjs deleted file mode 100644 index 490a868778..0000000000 --- a/cli/scripts/seat-log-baseline.mjs +++ /dev/null @@ -1,254 +0,0 @@ -#!/usr/bin/env node -/** - * Offline baseline of a seat's turns, from its wrapper log - * (~/.commonly/logs/.log), for the window before the seats canary - * switch, to compare against ~/.commonly/state/seats-canary/.jsonl. - * - * node cli/scripts/seat-log-baseline.mjs [--until ] [--hours 48] - * [--log ] [--timeout-ms 2700000] [--json] - * - * Reads only timestamps and the wrapper's own fixed phrases. It never prints a - * line's free text: a failure line's tail (the CLI's stderr) is reduced to a - * name (adapter_timeout | adapter_exit | adapter_error), and lines with - * no timestamp (raw stderr, HTML error pages) are counted, not shown. - * - * A turn opens at "[] spawning " and closes at the first of: - * - an outcome line (what became of the reply; see outcomeOf) - * - "processing failed" (the spawn threw: failed; or, after - * "ERROR reply NOT delivered": reply_lost) - * - a restart ("stopping after the current turn" / "polling … for events") - * or the next "spawning" (no close seen; counted as unclosed) - * A "spawn credential refused" or "lease failed" after "spawning" means the - * child never ran: it is counted as such, not as a turn. - * A turn still open at the end of the window is "open", not a hang. - * - * Outcomes use the canary's words (TURN_OUTCOMES in - * src/lib/supervised-turn.js), so a log and a canary file compare event for - * event: a turn is ok only when it was delivered or silent. - */ -import fs from 'fs'; -import os from 'os'; -import path from 'path'; - -export const LIMITS = [ - 'exit codes and signals of turns that succeeded (the log names a code only when a turn failed)', - 'whether a kill fired, and whether a child outlived its turn (the old path logs neither)', - 'quiet gaps inside a turn: the log has no mid-turn liveness, so a stall cannot be told from long work; only the 45-minute timeout shows', - 'in-band provider refusals the CLI swallowed (refusal_dropped): an exit 0 with an empty or refused reply reads as an ordinary turn', - 'turns cut by a restart: the end time is the restart, not the child\'s exit, and the outcome is unknown', - 'whether "posted via tool" posted the right thing, or why a NO_REPLY was chosen', - 'anything before the log was rotated or after it stopped being written', -]; - -const LINE_RE = /^(\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d(?:\.\d+)?Z) \[([^\]]+)\] (.*)$/; -const SPAWN_RE = /^\[([A-Za-z0-9._-]{1,40})\] spawning ([a-z0-9-]{1,32})$/; - -const OK_OUTCOMES = ['delivered', 'silent']; - -// Each phrase the run loop logs once delivery settles, in the order it checks -// them, mapped to the canary's outcome. An upstream refusal is matched first: -// it also ends in "nothing posted" or "no private response". -const outcomeOf = (msg) => { - if (/^\[[^\]]+\] upstream refused \d{3}\b/.test(msg)) return 'upstream_refused'; - if (/agent posted via tool/.test(msg) || /posted via tool, then/.test(msg)) return 'delivered'; - if (/\bposted \d+ bytes\b/.test(msg)) return 'delivered'; - if (/routed private response/.test(msg) || /response already routed by agent tool/.test(msg)) return 'delivered'; - if (/no wrapper-post \(/.test(msg) || /\bno private response\b/.test(msg)) return 'silent'; - if (/stood down — claim lost mid-turn/.test(msg)) return 'claim_lost'; - if (/server skipped the post/.test(msg)) return 'server_skipped'; - if (/wrapper delivery refused/.test(msg)) return 'server_refused'; - return null; -}; - -const failureOf = (msg) => { - const timeout = /\btimed out after (\d+)ms\b/.exec(msg); - if (timeout) return { name: 'adapter_timeout', timeoutMs: Number(timeout[1]) }; - const exit = /\bexited with code (-?\d+)\b/.exec(msg); - if (exit) return { name: 'adapter_exit', exitCode: Number(exit[1]) }; - return { name: 'adapter_error' }; -}; - -const pct = (sorted, p) => (sorted.length ? sorted[Math.min(sorted.length - 1, Math.ceil((p / 100) * sorted.length) - 1)] : null); - -export const baseline = (text, { seat, untilMs = Date.now(), hours = 48, timeoutMs = 2_700_000 } = {}) => { - const fromMs = untilMs - hours * 3_600_000; - const turns = []; - let open = null; - const counts = { untimestamped: 0, pollErrors: 0, restarts: 0, otherSeatLines: 0, spawnRefused: 0, leaseFailed: 0 }; - // The first "polling" line in the log is the seat's first start, not a - // restart; one before the window still makes the next one a restart. - let polledBefore = false; - const close = (turn, fields) => { Object.assign(turn, fields); turns.push(turn); }; - - for (const line of text.split('\n')) { - if (!line) continue; - const m = LINE_RE.exec(line); - if (!m) { counts.untimestamped += 1; continue; } - const [, ts, who, msg] = m; - const at = Date.parse(ts); - if (seat && who !== seat) { counts.otherSeatLines += 1; continue; } - const polling = /^polling \S+ for events/.test(msg); - const restarted = polling && polledBefore; - if (polling) polledBefore = true; - if (at < fromMs || at > untilMs) { - // A turn that opened inside the window may close just past it; let it. - if (!(open && at > untilMs)) continue; - } - const spawn = SPAWN_RE.exec(msg); - if (spawn) { - if (open) close(open, { endMs: at, ended: 'unclosed' }); - if (at > untilMs) { open = null; break; } - open = { startMs: at, eventType: spawn[1], adapter: spawn[2] }; - continue; - } - if (/^stopping after the current turn/.test(msg) || polling) { - if (at <= untilMs && restarted) counts.restarts += 1; - if (open) { close(open, { endMs: at, ended: 'restart' }); open = null; } - continue; - } - if (/^(fetch failed|poll failed|HTTP \d{3}\b)/.test(msg)) { if (at <= untilMs) counts.pollErrors += 1; continue; } - if (!open) continue; - // The model answered and every delivery rung threw; the processing - // failure that follows is the reply's, not the adapter's. - if (/\bERROR reply NOT delivered\b/.test(msg)) { open.replyLost = true; continue; } - if (/processing failed/.test(msg)) { - if (open.replyLost) close(open, { endMs: open.revokedMs ?? at, ended: 'settled', outcome: 'reply_lost' }); - else close(open, { endMs: at, ended: 'failed', ...failureOf(msg) }); - open = null; - continue; - } - // The child's end, when the turn minted a credential. A seat-token turn - // mints none and logs neither line, so its outcome line is its end. - if (/^spawn credential (revoked|revoke failed)\b/.test(msg)) { open.revokedMs = at; continue; } - // "spawning" is logged before the credential lease, so a refused lease - // follows it: the child never ran, and there is no turn to time. - const notSpawned = /^spawn credential (refused|lease failed)\b/.exec(msg); - if (notSpawned) { - if (open.startMs >= fromMs && open.startMs <= untilMs) counts[notSpawned[1] === 'refused' ? 'spawnRefused' : 'leaseFailed'] += 1; - open = null; - continue; - } - const outcome = outcomeOf(msg); - if (outcome) { - close(open, { endMs: open.revokedMs ?? at, ended: 'settled', outcome }); - open = null; - } - } - if (open) { - if (open.revokedMs !== undefined) close(open, { endMs: open.revokedMs, ended: 'settled', outcome: 'unknown' }); - else close(open, { endMs: null, ended: 'open' }); - } - - const byAdapter = {}; - for (const t of turns) { - const a = (byAdapter[t.adapter] ||= { - turns: 0, ok: 0, failed: 0, timeouts: 0, exits: {}, errors: 0, unclosed: 0, cutByRestart: 0, open: 0, - atOrOverTimeout: 0, outcomes: {}, durations: [], - }); - a.turns += 1; - if (t.endMs !== null) t.durationMs = t.endMs - t.startMs; - if (t.ended === 'settled') { - if (OK_OUTCOMES.includes(t.outcome)) a.ok += 1; - a.outcomes[t.outcome] = (a.outcomes[t.outcome] || 0) + 1; - } - if (t.ended === 'failed') { - a.failed += 1; - a.outcomes.failed = (a.outcomes.failed || 0) + 1; - if (t.name === 'adapter_timeout') a.timeouts += 1; - else if (t.name === 'adapter_exit') a.exits[t.exitCode] = (a.exits[t.exitCode] || 0) + 1; - else a.errors += 1; - } - if (t.ended === 'unclosed') a.unclosed += 1; - if (t.ended === 'restart') a.cutByRestart += 1; - if (t.ended === 'open') a.open += 1; - if (t.durationMs !== undefined) { - a.durations.push(t.durationMs); - if (t.durationMs >= timeoutMs) a.atOrOverTimeout += 1; - } - } - for (const a of Object.values(byAdapter)) { - const d = a.durations.sort((x, y) => x - y); - a.durationMs = d.length ? { p50: pct(d, 50), p90: pct(d, 90), p99: pct(d, 99), max: d[d.length - 1], n: d.length } : null; - delete a.durations; - } - return { - seat: seat || null, - window: { from: new Date(fromMs).toISOString(), until: new Date(untilMs).toISOString(), hours }, - turnTimeoutMs: timeoutMs, - byAdapter, - counts, - cannotTell: LIMITS, - }; -}; - -const fmtMs = (ms) => (ms === null || ms === undefined ? '-' : ms >= 60_000 ? `${(ms / 60_000).toFixed(1)}m` : `${(ms / 1000).toFixed(1)}s`); - -export const render = (r) => { - const out = [`seat ${r.seat}: ${r.window.from} → ${r.window.until} (${r.window.hours}h), turn budget ${fmtMs(r.turnTimeoutMs)}`]; - const adapters = Object.entries(r.byAdapter); - if (!adapters.length) out.push(' no turns in the window'); - for (const [name, a] of adapters) { - out.push(` ${name}: ${a.turns} turns, ${a.ok} ok (delivered or silent), ${a.failed} spawns failed` - + ` (${a.timeouts} timed out, exits ${JSON.stringify(a.exits)}, ${a.errors} other)` - + `, ${a.cutByRestart} cut by restart, ${a.unclosed} unclosed, ${a.open} still open at the window end`); - out.push(` reached the turn budget: ${a.atOrOverTimeout}`); - if (a.durationMs) out.push(` duration p50 ${fmtMs(a.durationMs.p50)} p90 ${fmtMs(a.durationMs.p90)} p99 ${fmtMs(a.durationMs.p99)} max ${fmtMs(a.durationMs.max)} (n=${a.durationMs.n})`); - out.push(` outcomes ${JSON.stringify(a.outcomes)}`); - } - out.push(` restarts ${r.counts.restarts}, poll errors ${r.counts.pollErrors}, spawns refused a credential ${r.counts.spawnRefused}, credential lease failures ${r.counts.leaseFailed}, untimestamped lines (whole log) ${r.counts.untimestamped}`); - out.push(' the log cannot tell:'); - for (const l of r.cannotTell) out.push(` - ${l}`); - return out.join('\n'); -}; - -// Date.parse accepts "Oct 24 2026" and rolls 2026-02-31 into March, so the -// documented ISO form is checked here, and the date must survive a round trip. -const ISO_DATE = /^(\d{4}-\d{2}-\d{2})(?:T\d{2}:\d{2}(?::\d{2}(?:\.\d{1,3})?)?(?:Z|[+-]\d{2}:\d{2}))?$/; -const parseIsoDate = (value) => { - const match = ISO_DATE.exec(value); - if (!match) return null; - const ms = Date.parse(value); - if (Number.isNaN(ms)) return null; - return new Date(Date.parse(match[1])).toISOString().slice(0, 10) === match[1] ? ms : null; -}; - -export const main = (argv, { stdout = process.stdout, stderr = process.stderr } = {}) => { - const args = [...argv]; - const seat = args.shift(); - if (!seat || seat.startsWith('-')) { - stderr.write('usage: seat-log-baseline.mjs [--until ] [--hours 48] [--log ] [--timeout-ms 2700000] [--json]\n'); - return 2; - } - // A malformed option is a usage error (status 2), never a stack trace or a - // report computed from NaN. - const usage = (message) => { stderr.write(`${message}\n`); return 2; }; - const opt = (name, fallback) => { - const i = args.indexOf(name); - if (i < 0) return fallback; - const value = args[i + 1]; - return value === undefined || value.startsWith('--') ? null : value; - }; - const num = (name, fallback) => { - const value = opt(name, fallback); - const n = value === null ? NaN : Number(value); - return Number.isFinite(n) && n > 0 ? n : null; - }; - const until = opt('--until'); - if (until === null) return usage('--until needs a value'); - const untilMs = until === undefined ? Date.now() : parseIsoDate(until); - if (untilMs === null) return usage('--until is not an ISO date'); - const logPath = opt('--log', path.join(os.homedir(), '.commonly', 'logs', `${seat}.log`)); - if (logPath === null) return usage('--log needs a value'); - const hours = num('--hours', 48); - if (hours === null) return usage('--hours must be a positive number'); - if (Number.isNaN(new Date(untilMs - hours * 3_600_000).getTime())) { - return usage('--hours puts the window start outside the supported date range'); - } - const timeoutMs = num('--timeout-ms', 2_700_000); - if (timeoutMs === null) return usage('--timeout-ms must be a positive number'); - const result = baseline(fs.readFileSync(logPath, 'utf8'), { seat, untilMs, hours, timeoutMs }); - stdout.write(`${args.includes('--json') ? JSON.stringify(result, null, 2) : render(result)}\n`); - return 0; -}; - -if (import.meta.url === `file://${process.argv[1]}`) process.exitCode = main(process.argv.slice(2)); diff --git a/cli/src/commands/agent.js b/cli/src/commands/agent.js index bf43fee6f8..8ea421e9e2 100644 --- a/cli/src/commands/agent.js +++ b/cli/src/commands/agent.js @@ -1440,7 +1440,7 @@ export const performRun = ({ // Off unless COMMONLY_SUPERVISE_RUNS=1: each spawn runs under the seats // supervisor (stall window, wall-clock backstop, a named failure on every // settle). The CLI still talks to its provider directly, and one metadata - // line per turn goes to ~/.commonly/state/seats-canary/.jsonl once + // line per turn goes to ~/.commonly/state/turns/.jsonl once // delivery settles. Off, the spawn path is the plain adapter call it has // always been, and nothing is written. superviseRuns = process.env.COMMONLY_SUPERVISE_RUNS === '1', @@ -1871,7 +1871,7 @@ export const performRun = ({ // The spawn → post-decision half of a turn, split out so the claim release // above is a plain finally instead of threading through every return path. - // With superviseRuns, the turn's canary line is written once delivery has + // With superviseRuns, the turn's log line is written once delivery has // settled; anything thrown after a spawn that resolved means the reply never // reached the pod. Off, `turn` writes nothing. const runTurn = async (args) => { @@ -2227,7 +2227,7 @@ export const performRun = ({ const upstream = result.upstream || null; let delivered = agentPostedItself; let deliveryRefusal = null; - // What became of the reply, for the canary line (lib/supervised-turn.js + // What became of the reply, for the turn line (lib/supervised-turn.js // TURN_OUTCOMES). A throw below is reply_lost, finished by runTurn. let turnOutcome; diff --git a/cli/src/lib/supervised-turn.js b/cli/src/lib/supervised-turn.js index 2553ab3a4e..651286a34b 100644 --- a/cli/src/lib/supervised-turn.js +++ b/cli/src/lib/supervised-turn.js @@ -1,6 +1,6 @@ /** * One model turn of `commonly agent run`, on one of two paths. The supervised - * path also writes one metadata line per turn (the seats canary), once the + * path also writes one metadata line per turn (the turn log), once the * turn's outcome has reached the pod or failed to. * * COMMONLY_SUPERVISE_RUNS=1 (read by performRun as `superviseRuns`) @@ -14,17 +14,15 @@ * * A turn is ok only when its outcome reached the pod: the reply was delivered * or the agent chose silence. The run loop names the outcome after delivery - * settles (turn.finish); a spawn that threw is `failed` at once. The - * seat-log baseline (scripts/seat-log-baseline.mjs) maps a log to the same - * outcomes, so the two can be compared event for event. + * settles (turn.finish); a spawn that threw is `failed` at once. * * NO RECORD WRITER. The supervisor needs a trace store. The one here * (createMetadataStore) is in memory, lives for one turn, and keeps event type * names, times and the recovery action word. It drops every event's data, so * no agent text, prompt, reply, failure detail or credential is kept, and - * nothing is written to disk (CTO's redact blocker on #2701). + * nothing is written to disk (a redaction review on #2701). * - * Metrics: ~/.commonly/state/seats-canary/.jsonl (COMMONLY_SEATS_CANARY_DIR + * Metrics: ~/.commonly/state/turns/.jsonl (COMMONLY_TURN_LOG_DIR * overrides the directory). Whitelisted fields only; see metricLine. */ import { appendFileSync, mkdirSync } from 'fs'; @@ -43,13 +41,13 @@ const MAX_TIMER_MS = 2_147_483_647; * codex: `codex exec --json` writes a JSONL event per item, so its stdout is a * real progress signal, and the quiet stretch is the longest single item (a * reasoning step or one shell command). Measured 2026-10-25 from per-turn - * timestamp gaps in this host's October codex rollouts (~/.codex/sessions): + * timestamp gaps in October codex rollouts on one host (~/.codex/sessions): * 9,703 turns, max quiet gap 162 s, p99 53 s; 9 turns would have tripped the * package default of 120 s. 15 min is 5.5x the worst gap seen and still * 30 min inside the seats' 45 min turn budget. * claude: the adapter runs `claude -p --output-format text`, which writes - * nothing to stdout until the reply is done. A healthy 14-minute quire turn - * (in its log) is 14 minutes of silence to the supervisor, so any window + * nothing to stdout until the reply is done. A healthy 14-minute claude turn + * is 14 minutes of silence to the supervisor, so any window * under the turn budget would be a turn-length cap, not a liveness check. * Off; claude is guarded by the wall-clock backstop and the cancel ladder. */ @@ -134,7 +132,7 @@ export const createMetadataStore = ({ now = Date.now } = {}) => { }; export const metricsPathFor = (seat, env = process.env) => { - const dir = env?.COMMONLY_SEATS_CANARY_DIR || join(homedir(), '.commonly', 'state', 'seats-canary'); + const dir = env?.COMMONLY_TURN_LOG_DIR || join(homedir(), '.commonly', 'state', 'turns'); const safe = String(seat || 'unknown').replace(/[^A-Za-z0-9_.-]/g, '_').slice(0, 64) || 'unknown'; return join(dir, `${safe}.jsonl`); };