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..af2a9f85f2 --- /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@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": "echo", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/echo", + "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/echo", + "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@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": "echo", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/echo", + "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/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@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": "echo", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/echo", + "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/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@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": "echo", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/echo", + "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/echo", + "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 #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": [ + { + "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@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": "echo", + "commitAttributionEnv": null, + "cwd": "/commonly-agents/echo", + "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/echo", + "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__/supervise-runs-flag.test.mjs b/cli/__tests__/supervise-runs-flag.test.mjs new file mode 100644 index 0000000000..c1e16a87cc --- /dev/null +++ b/cli/__tests__/supervise-runs-flag.test.mjs @@ -0,0 +1,343 @@ +/** + * 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: 'echo', + 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: 'echo', + 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', '@echo docs gate: #0050, wording only')], + spawn: async () => ({ text: 'docs gate: PASS' }), + }, + refusalInMixedBatch: { + events: [ + 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')) { + throw new Error('codex turn failed: This content was flagged for possible cybersecurity risk.'); + } + return { text: 'docs gate: PASS' }; + }, + }, + runtimeFailure: { + events: [event('evt-4', '@echo docs gate: #0052')], + 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); + }, + }; + // 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(); + // 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); + // 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', 'turns'))).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', '@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', 'turns'))).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 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'); + 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: TURN_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', '@echo review #0049')], + 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', '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, + 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(TURN_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..c8a9e02ba2 --- /dev/null +++ b/cli/__tests__/supervised-turn.test.mjs @@ -0,0 +1,520 @@ +/** + * 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 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 + * text in it; flag off, nothing written at all; + * - 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, 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'); + +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', '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 }); + +const METRIC_KEYS = [ + '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(); + +// 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')]); + }); +}); + +// 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); + + 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: '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); + 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 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: '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(); + 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(); + })]); + // 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 = { + 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: '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('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 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. + 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: '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'); + 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('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: '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('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('delta')).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('delta'); + 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'], + ]); + 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('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 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_TURN_LOG_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: '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 }); + 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 () => { + const blocker = path.join(home, 'not-a-dir'); + fs.writeFileSync(blocker, ''); + const logs = []; + const runner = createTurnRunner({ + seat: 'delta', + turnTimeoutMs: 1000, + supervise: true, + 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 }) }; + await expect(turnOf(runner, adapter)).resolves.toEqual({ text: REPLY }); + await turnOf(runner, adapter); + 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: '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 +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] || [] }; } + if (route === '/api/agents/runtime/memory') return { sections: {} }; + if (String(route).endsWith('/messages')) return { messages: [] }; + return {}; + }); + 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 handle = performRun({ + instanceUrl: 'http://localhost:5000', + token: 'cm_agent_test', + adapter, + agentName: 'delta', + environment: { model: 'gpt-test' }, + retryJitterRatio: 0, + claimYieldDelayMs: 0, + sleepImpl: async () => {}, + superviseRuns, + log: (line) => { logs.push(String(line)); }, + // `commonly agent run` stamps onError into the same seat log as log(). + 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: () => {}, + }); + 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 })); + // 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())); + return { handle, logs, errors, scheduled, acks, restore, post, renewClaims }; +}; + +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); + // 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); + }); + + 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: '300', 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('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 turn back from its turn line. + + 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 = { + 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('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('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', 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('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('delta')).toEqual([expect.objectContaining({ path: 'supervised', outcome: 'reply_lost', ok: false, failure: null })]); + }); +}); diff --git a/cli/src/commands/agent.js b/cli/src/commands/agent.js index d6325b1c65..8ea421e9e2 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, @@ -1356,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. @@ -1431,6 +1437,13 @@ 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, and one metadata + // 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', }) => { reportRuntime = reportRuntime && WALKED_HARNESSES.includes(adapter?.name); if (environment?.provider !== undefined && !adapter?.supportsProvider) { @@ -1440,6 +1453,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 (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(), @@ -1852,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 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) => { + 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 @@ -2076,7 +2108,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 +2141,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 turn.run(adapter, spawnPrompt, spawnCtx); spawnCompleted = true; } finally { try { @@ -2191,6 +2227,9 @@ export const performRun = ({ const upstream = result.upstream || null; let delivered = agentPostedItself; let deliveryRefusal = null; + // 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; if (event.type === 'agent.ask') { if (silentReply) { @@ -2200,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( @@ -2207,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 @@ -2215,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; @@ -2242,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 ` @@ -2260,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} ` @@ -2269,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)`, @@ -2311,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, @@ -2336,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}`); @@ -2351,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 new file mode 100644 index 0000000000..651286a34b --- /dev/null +++ b/cli/src/lib/supervised-turn.js @@ -0,0 +1,351 @@ +/** + * One model turn of `commonly agent run`, on one of two paths. The supervised + * 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`) + * 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, 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. + * + * 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 (a redaction review on #2701). + * + * Metrics: ~/.commonly/state/turns/.jsonl (COMMONLY_TURN_LOG_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 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 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. + */ +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_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`); +}; + +/** 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; } +}; + +// 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(); +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) => { + 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; + +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 runSupervised = async (adapter, prompt, ctx, eventType, hold) => { + 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); + const fields = { + adapter: adapter?.name, + path: 'supervised', + eventType, + startMs, + endMs: now(), + outcome: ok ? undefined : 'failed', + 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, + }; + // 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. + 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. `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() }); + }, + }; + }, + }; +};