diff --git a/cli/__tests__/first-output-watchdog.test.mjs b/cli/__tests__/first-output-watchdog.test.mjs new file mode 100644 index 0000000000..3b33546163 --- /dev/null +++ b/cli/__tests__/first-output-watchdog.test.mjs @@ -0,0 +1,426 @@ +/** + * first-output-watchdog.test.mjs — a spawn that never starts is killed early. + * + * Seen 2026-10-30: with the Mac's console locked, every launchd seat's + * `claude -p` turn wrote nothing for the full 45-minute run timeout, then was + * respawned into the same hang. A healthy turn writes its transcript within a + * second, so a spawn with no transcript row, stdout or stderr inside the + * window is killed, named, backed off, and its claim released. + */ +import { jest } from '@jest/globals'; +import os from 'os'; +import path from 'path'; +import fs from 'fs'; +import { EventEmitter } from 'events'; + +const sessionsTmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'cli-first-output-test-')); + +await jest.unstable_mockModule('os', () => ({ + ...os, + default: { ...os, homedir: () => sessionsTmpDir }, + homedir: () => sessionsTmpDir, +})); + +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 claude = (await import('../src/lib/adapters/claude.js')).default; +const { + consoleLocked, spawnStalledError, watchFirstOutput, firstOutputWindowMs, DEFAULT_FIRST_OUTPUT_WINDOW_MS, physicalPath, + killStallSurvivors, +} = await import('../src/lib/first-output-watchdog.js'); +const { classifySpawnFailure, spawnRetryPolicy, SPAWN_FAILURE_CLASS } = await import('../src/lib/spawn-retry.js'); + +afterAll(() => fs.rmSync(sessionsTmpDir, { recursive: true, force: true })); + +// A child that closes with 143 once killed, and otherwise does whatever +// `script` makes it do. +const fakeChild = (script = () => {}) => { + const proc = new EventEmitter(); + proc.stdout = new EventEmitter(); + proc.stderr = new EventEmitter(); + proc.kill = jest.fn(() => { setImmediate(() => proc.emit('close', 143)); }); + setImmediate(() => script(proc)); + return proc; +}; + +// The child is made inside the spawn seam, so its script cannot run before +// the adapter has attached its listeners. +const spawnClaude = (script, { windowMs, locked = true } = {}) => { + const saved = process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = String(windowMs); + const spawned = {}; + const result = claude.spawn('hello', { + environment: { model: 'test-model' }, + _spawnImpl: () => { + spawned.child = fakeChild(script); + return spawned.child; + }, + _lockProbe: async () => locked, + env: { ...process.env, HOME: sessionsTmpDir }, + cwd: sessionsTmpDir, + }).then((value) => ({ value, child: spawned.child }), (error) => ({ error, child: spawned.child })); + return result.finally(() => { + if (saved === undefined) delete process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + else process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = saved; + }); +}; + +describe('the claude adapter under the first-output watchdog', () => { + test('a spawn that never writes is killed with the reason, not left to the run timeout', async () => { + const { error, child } = await spawnClaude(undefined, { windowMs: 50, locked: true }); + expect(child.kill).toHaveBeenCalledWith('SIGTERM'); + expect(error.code).toBe('spawn_stalled'); + expect(error.message).toBe('claude produced no output in 0s (console locked); killed before the run timeout'); + expect(classifySpawnFailure(error)).toBe(SPAWN_FAILURE_CLASS.STALLED); + }); + + test('a missing transcript alone does not kill: the path may be wrong, so it takes a locked console', async () => { + const { value, error, child } = await spawnClaude((proc) => { + setTimeout(() => { + proc.stdout.emit('data', Buffer.from('done quietly')); + proc.emit('close', 0); + }, 150); + }, { windowMs: 50, locked: false }); + expect(error).toBeUndefined(); + expect(child.kill).not.toHaveBeenCalled(); + expect(value.text).toBe('done quietly'); + }); + + test('a descendant still alive when the stalled spawn closes is SIGKILLed', async () => { + const saved = process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = '50'; + const kill = jest.fn(); + const started = 'Thu Oct 30 06:59:59 2026'; + try { + const { error } = await claude.spawn('hello', { + environment: { model: 'test-model' }, + _spawnImpl: () => { + const proc = fakeChild(); + proc.pid = 4242; + // The spawn exits on SIGTERM; its child does not. + proc.kill = jest.fn((signal) => { + if (signal === 'SIGTERM') setImmediate(() => proc.emit('close', null)); + }); + return proc; + }, + _lockProbe: async () => true, + _stallKillGraceMs: 60_000, + _processTable: () => [{ pid: 4243, ppid: 4242, started }], + // By close it has been reparented to launchd. + _survivorIo: { read: (pid) => (pid === 4243 ? { pid, ppid: 1, started } : null), kill }, + env: { ...process.env, HOME: sessionsTmpDir }, + cwd: sessionsTmpDir, + }).then(() => ({}), (err) => ({ error: err })); + expect(error.code).toBe('spawn_stalled'); + expect(kill).toHaveBeenCalledWith(4243, 'SIGKILL'); + } finally { + if (saved === undefined) delete process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + else process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = saved; + } + }); + + test('a stall SIGTERMs the live tree, and a survivor holding the pipe is SIGKILLed when the spawn exits', async () => { + const saved = process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = '50'; + const started = 'Thu Oct 30 06:59:59 2026'; + const spawned = {}; + let rootAlive = true; + // The descendant ignores SIGTERM and holds the inherited stdout, so close + // fires only once it is SIGKILLed. + const survivorKill = jest.fn((pid, signal) => { + if (pid === 4243 && signal === 'SIGKILL') setImmediate(() => spawned.child.emit('close', null)); + }); + const treeKill = jest.spyOn(process, 'kill').mockImplementation(() => true); + try { + const { error } = await claude.spawn('hello', { + environment: { model: 'test-model' }, + _spawnImpl: () => { + const proc = fakeChild(); + Object.assign(proc, { pid: 4242, exitCode: null, signalCode: null }); + proc.kill = jest.fn((signal) => { + if (signal !== 'SIGTERM') return; + setImmediate(() => { + rootAlive = false; + proc.signalCode = 'SIGTERM'; + proc.emit('exit', null, 'SIGTERM'); + }); + }); + spawned.child = proc; + return proc; + }, + _lockProbe: async () => true, + _stallKillGraceMs: 60_000, + _processTable: () => [{ pid: 4243, ppid: 4242, started }], + _survivorIo: { + read: (pid) => (pid === 4243 ? { pid, ppid: rootAlive ? 4242 : 1, started } : null), + kill: survivorKill, + }, + env: { ...process.env, HOME: sessionsTmpDir }, + cwd: sessionsTmpDir, + }).then(() => ({}), (err) => ({ error: err })); + expect(error.code).toBe('spawn_stalled'); + // The first signal reached the descendant, not only the root. + expect(treeKill).toHaveBeenCalledWith(4243, 'SIGTERM'); + expect(spawned.child.kill).toHaveBeenCalledWith('SIGTERM'); + expect(survivorKill).toHaveBeenCalledWith(4243, 'SIGKILL'); + } finally { + treeKill.mockRestore(); + if (saved === undefined) delete process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + else process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = saved; + } + }); + + test('a spawn that ignores SIGTERM gets SIGKILL after the grace', async () => { + const spawned = {}; + const saved = process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = '50'; + try { + const { error } = await claude.spawn('hello', { + environment: { model: 'test-model' }, + _spawnImpl: () => { + const proc = fakeChild(); + // Parked: SIGTERM does nothing, only SIGKILL ends it. + proc.kill = jest.fn((signal) => { + if (signal === 'SIGKILL') setImmediate(() => proc.emit('close', null)); + }); + spawned.child = proc; + return proc; + }, + _lockProbe: async () => true, + _stallKillGraceMs: 30, + env: { ...process.env, HOME: sessionsTmpDir }, + cwd: sessionsTmpDir, + }).then(() => ({}), (err) => ({ error: err })); + expect(spawned.child.kill.mock.calls.map(([signal]) => signal)).toEqual(['SIGTERM', 'SIGKILL']); + expect(error.code).toBe('spawn_stalled'); + } finally { + if (saved === undefined) delete process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + else process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = saved; + } + }); + + test('a slow spawn that is talking is not killed', async () => { + const { value, error, child } = await spawnClaude((proc) => { + proc.stderr.emit('data', Buffer.from('warming up')); + setTimeout(() => { + proc.stdout.emit('data', Buffer.from('the answer')); + proc.emit('close', 0); + }, 150); + }, { windowMs: 50 }); + expect(error).toBeUndefined(); + expect(child.kill).not.toHaveBeenCalled(); + expect(value.text).toBe('the answer'); + }); +}); + +describe('watchFirstOutput', () => { + const quietProc = () => ({ stdout: new EventEmitter(), stderr: new EventEmitter() }); + + test('a growing transcript counts as started, since claude writes stdout only at the end', async () => { + const transcript = path.join(sessionsTmpDir, 'session.jsonl'); + fs.writeFileSync(transcript, '{"type":"queue-operation"}\n'); + const onStall = jest.fn(); + let fire; + watchFirstOutput({ + proc: quietProc(), windowMs: 1000, transcriptPath: transcript, onStall, + lockProbe: async () => true, setTimeoutImpl: (cb) => { fire = cb; return 0; }, clearTimeoutImpl: () => {}, + }); + fs.appendFileSync(transcript, '{"type":"user"}\n'); + await fire(); + expect(onStall).not.toHaveBeenCalled(); + }); + + test('a resumed transcript that does not grow is a stall', async () => { + const transcript = path.join(sessionsTmpDir, 'resumed.jsonl'); + fs.writeFileSync(transcript, '{"type":"assistant"}\n'); + const onStall = jest.fn(); + let fire; + watchFirstOutput({ + proc: quietProc(), windowMs: 1000, transcriptPath: transcript, onStall, + lockProbe: async () => null, setTimeoutImpl: (cb) => { fire = cb; return 0; }, clearTimeoutImpl: () => {}, + }); + await fire(); + expect(onStall).toHaveBeenCalledWith('no transcript, stdout or stderr'); + }); + + test('a transcript created empty is not a start', async () => { + const transcript = path.join(sessionsTmpDir, 'created-empty.jsonl'); + fs.rmSync(transcript, { force: true }); + const onStall = jest.fn(); + let fire; + watchFirstOutput({ + proc: quietProc(), windowMs: 1000, transcriptPath: transcript, onStall, + lockProbe: async () => null, setTimeoutImpl: (cb) => { fire = cb; return 0; }, clearTimeoutImpl: () => {}, + }); + fs.writeFileSync(transcript, ''); + await fire(); + expect(onStall).toHaveBeenCalledWith('no transcript, stdout or stderr'); + }); + + test('a missing transcript is a stall only on a locked console', async () => { + const transcript = path.join(sessionsTmpDir, 'never-written.jsonl'); + fs.rmSync(transcript, { force: true }); + for (const [locked, expected] of [[false, 0], [null, 0], [true, 1]]) { + const onStall = jest.fn(); + let fire; + watchFirstOutput({ + proc: quietProc(), windowMs: 1000, transcriptPath: transcript, onStall, + lockProbe: async () => locked, setTimeoutImpl: (cb) => { fire = cb; return 0; }, clearTimeoutImpl: () => {}, + }); + // eslint-disable-next-line no-await-in-loop + await fire(); + expect(onStall).toHaveBeenCalledTimes(expected); + } + }); + + test('a descendant that outlived the stalled spawn is SIGKILLed, even reparented; a reused pid is not', () => { + const snapshot = [ + { pid: 501, ppid: 400, started: 'Thu Oct 30 06:59:59 2026' }, // survived, now under launchd + { pid: 502, ppid: 400, started: 'Thu Oct 30 06:59:59 2026' }, // exited + { pid: 503, ppid: 501, started: 'Thu Oct 30 07:00:01 2026' }, // pid reused since + ]; + const now = { + 501: { pid: 501, ppid: 1, started: 'Thu Oct 30 06:59:59 2026' }, + 503: { pid: 503, ppid: 1, started: 'Thu Oct 30 07:05:00 2026' }, + }; + const kill = jest.fn(); + const killed = killStallSurvivors(snapshot, { read: (pid) => now[pid] || null, kill }); + expect(killed).toEqual([501]); + expect(kill).toHaveBeenCalledWith(501, 'SIGKILL'); + expect(kill).toHaveBeenCalledTimes(1); + }); + + test('the transcript is looked for under the physical cwd', () => { + const link = path.join(sessionsTmpDir, 'linked-cwd'); + fs.rmSync(link, { force: true }); + fs.symlinkSync(os.tmpdir(), link); + expect(physicalPath(link)).toBe(fs.realpathSync(os.tmpdir())); + expect(physicalPath(path.join(sessionsTmpDir, 'absent'))).toBe(path.join(sessionsTmpDir, 'absent')); + }); + + test('a window of 0 turns it off', () => { + expect(firstOutputWindowMs({ COMMONLY_FIRST_OUTPUT_WINDOW_MS: '0' })).toBe(0); + expect(firstOutputWindowMs({ COMMONLY_FIRST_OUTPUT_WINDOW_MS: 'soon' })).toBe(DEFAULT_FIRST_OUTPUT_WINDOW_MS); + expect(firstOutputWindowMs({})).toBe(180_000); + }); +}); + +describe('consoleLocked', () => { + const ioreg = (stdout, error = null) => (_cmd, _args, _opts, cb) => cb(error, stdout); + + test('reads IOConsoleLocked from ioreg on darwin', async () => { + await expect(consoleLocked({ platform: 'darwin', execFileImpl: ioreg(' "IOConsoleLocked" = Yes\n') })).resolves.toBe(true); + await expect(consoleLocked({ platform: 'darwin', execFileImpl: ioreg(' "IOConsoleLocked" = No\n') })).resolves.toBe(false); + await expect(consoleLocked({ platform: 'darwin', execFileImpl: ioreg('', new Error('no ioreg')) })).resolves.toBeNull(); + await expect(consoleLocked({ platform: 'linux' })).resolves.toBeNull(); + }); +}); + +describe('the stall backoff', () => { + test('opens the circuit at once and waits 2, 4, 8, then 15 minutes', () => { + const error = spawnStalledError({ label: 'claude', windowMs: 180_000, reason: 'console locked' }); + const delays = [1, 2, 3, 4, 5].map((consecutiveFailures) => spawnRetryPolicy({ error, consecutiveFailures })); + expect(delays.every((retry) => retry.circuitOpen && retry.failureClass === 'stalled')).toBe(true); + expect(delays.map((retry) => retry.delayMs / 60_000)).toEqual([2, 4, 8, 15, 15]); + }); +}); + +// ── the run loop ──────────────────────────────────────────────────────────── + +const drainMicrotasks = async () => { + for (let i = 0; i < 40; i += 1) { + // eslint-disable-next-line no-await-in-loop + await new Promise((r) => setImmediate(r)); + } +}; + +describe('performRun — a stalled turn', () => { + test('releases its claim, backs off with the reason, and resumes when the probe answers', async () => { + fs.rmSync(path.join(sessionsTmpDir, '.commonly'), { recursive: true, force: true }); + const pages = [[{ + _id: 'evt-a', + type: 'chat.mention', + podId: 'pod-abc', + agentName: 'my-stub', + instanceId: 'default', + payload: { content: 'are you there?', deliveryId: 'nonce-evt-a', messageId: 'msg-1' }, + }]]; + const acks = []; + const claimCalls = []; + const get = jest.fn(async (route) => { + if (route === '/api/agents/runtime/events') return { events: pages.length ? pages.shift() : [] }; + if (route.endsWith('/messages')) return { messages: [] }; + if (route.endsWith('/memory')) return { sections: {} }; + return {}; + }); + const post = jest.fn(async (route, body) => { + const ack = String(route).match(/\/events\/([^/]+)\/ack$/); + if (ack) acks.push(ack[1]); + if (String(route).endsWith('/claim')) { + claimCalls.push('acquire'); + return { claimed: true }; + } + if (String(route).endsWith('/events/renew')) { + return { renewed: body.events.map((entry) => entry.eventId).filter((id) => !acks.includes(id)) }; + } + return {}; + }); + const del = jest.fn(async (route) => { + if (String(route).endsWith('/claim')) claimCalls.push('release'); + return {}; + }); + createClient.mockReturnValue({ get, post, del }); + + const spawn = jest.fn() + .mockRejectedValueOnce(spawnStalledError({ label: 'claude', windowMs: 180_000, reason: 'console locked' })) + .mockResolvedValueOnce({ text: 'yes, back now' }); + const scheduled = []; + const errors = []; + const handle = performRun({ + instanceUrl: 'http://localhost:5000', + token: 'cm_agent_test', + adapter: { name: 'stub', detect: stubAdapter.detect, spawn }, + agentName: 'my-stub', + retryJitterRatio: 0, + setTimeoutImpl: (callback, delayMs) => { scheduled.push({ callback, delayMs }); return 0; }, + setIntervalImpl: () => ({}), + clearIntervalImpl: () => {}, + setDeadlineTimeoutImpl: () => 0, + clearDeadlineTimeoutImpl: () => {}, + log: () => {}, + onError: (error) => errors.push(error), + }); + try { + await drainMicrotasks(); + expect(spawn).toHaveBeenCalledTimes(1); + // The stalled turn gave its claim back rather than sitting on it. + expect(claimCalls).toEqual(['acquire', 'release']); + expect(acks).toEqual([]); + const report = errors.find((error) => error.code === 'agent_spawn_retry_scheduled'); + expect(report).toMatchObject({ failureClass: 'stalled', circuitOpen: true, retryAfterMs: 120_000, heldCount: 1 }); + expect(report.message).toContain('console locked'); + + // The probe after the backoff talks, so the run resumes and acks. + const next = scheduled.shift(); + expect(next.delayMs).toBe(120_000); + next.callback(); + await drainMicrotasks(); + expect(spawn).toHaveBeenCalledTimes(2); + expect(acks).toEqual(['evt-a']); + } finally { + handle.stop?.(); + } + }); +}); diff --git a/cli/src/lib/adapters/claude.js b/cli/src/lib/adapters/claude.js index f1f0c71fc3..a793bffec3 100644 --- a/cli/src/lib/adapters/claude.js +++ b/cli/src/lib/adapters/claude.js @@ -1,6 +1,11 @@ import { claudeRuntimeInventory } from '../native-runtime-inventory.js'; import { observeSpawn, controlsFromArguments } from '../runtime-observation.js'; -import { spawnInOwnGroup, wantsOwnProcessGroup } from '@commonlyai/seats/process-group'; +import { + firstOutputWindowMs, killStallSurvivors, physicalPath, spawnStalledError, STALL_KILL_GRACE_MS, watchFirstOutput, +} from '../first-output-watchdog.js'; +import { + descendantsOf, killProcessTree, readProcessTable, spawnInOwnGroup, wantsOwnProcessGroup, +} from '@commonlyai/seats/process-group'; /** * claude adapter — wraps the local `claude` CLI as a Commonly agent. * @@ -88,7 +93,7 @@ import { prepareMcpSpawn, PUBLIC_MCP_UNAVAILABLE_CODE, publicMcpUnavailableError, selectedMcpVersionDir, } from '../mcp-home.js'; import { buildMemoryPreamble, ROW_SLICING_CUE } from '../memory-bridge.js'; -import { claudeConfigDirFor, claudeContextTokens } from '../session-recycle.js'; +import { claudeConfigDirFor, claudeContextTokens, claudeTranscriptPath } from '../session-recycle.js'; import { skillsAsText } from '../skill-prompt.js'; import { adapterFailure, spawnCredentials } from '../upstream-refusal.js'; @@ -484,7 +489,11 @@ const publicSkillPromptArgs = async (skillSources) => { // `ownGroup` is set only under the run supervisor, which kills the child's // whole group; unsupervised, the spawn options are exactly what they were. -const runClaude = ({ cmd, args, cwd, env, timeoutMs, credentials = [], spawnImpl = childSpawn, onSpawn, controls = {}, ownGroup = false }) => new Promise((resolve, reject) => { +const runClaude = ({ + cmd, args, cwd, env, timeoutMs, credentials = [], spawnImpl = childSpawn, onSpawn, controls = {}, ownGroup = false, + transcriptPath = null, firstOutputMs = firstOutputWindowMs(), lockProbe, stallKillGraceMs = STALL_KILL_GRACE_MS, + processTable = readProcessTable, survivorIo, +}) => new Promise((resolve, reject) => { const proc = spawnInOwnGroup(spawnImpl, cmd, args, { cwd, env, @@ -499,15 +508,57 @@ const runClaude = ({ cmd, args, cwd, env, timeoutMs, credentials = [], spawnImpl timedOut = true; proc.kill('SIGTERM'); }, timeoutMs); + // A turn that never starts is killed long before the run timeout. + let stalled = null; + let stallKill = null; + let stallSnapshot = []; + // SIGKILL snapshotted descendants that are still alive. Safe to repeat. It + // runs when the spawn exits, at the grace deadline and on close: a survivor + // still holding the spawn's stdout or stderr keeps close from ever firing, + // and once the spawn is reaped killProcessTree can no longer reach it. + const sweepStallSurvivors = () => { + if (stalled) killStallSurvivors(stallSnapshot, survivorIo); + }; + const treeIo = (table) => ({ table, ...(survivorIo?.read ? { read: survivorIo.read } : {}) }); + const watchdog = watchFirstOutput({ + proc, + windowMs: firstOutputMs, + transcriptPath, + lockProbe, + onStall: (reason) => { + stalled = spawnStalledError({ label: 'claude', windowMs: firstOutputMs, reason }); + // Snapshot the descendants first: once the spawn exits they are + // reparented and can no longer be found from it. + const table = Number.isInteger(proc.pid) ? processTable() : null; + if (table) stallSnapshot = descendantsOf(table, proc.pid); + killProcessTree(proc, 'SIGTERM', treeIo(() => table)); + // A process parked in a system call may not act on SIGTERM. SIGKILL the + // child, its group when it leads one, and its descendants. + stallKill = setTimeout(() => { + killProcessTree(proc, 'SIGKILL', treeIo(processTable)); + sweepStallSurvivors(); + }, stallKillGraceMs); + stallKill.unref?.(); + }, + }); + proc.on('exit', sweepStallSurvivors); proc.stdout?.on('data', (chunk) => { stdout += chunk.toString(); }); proc.stderr?.on('data', (chunk) => { stderr += chunk.toString(); }); proc.on('error', (err) => { clearTimeout(timer); + clearTimeout(stallKill); + watchdog.stop(); reject(err); }); proc.on('close', (code) => { clearTimeout(timer); + clearTimeout(stallKill); + watchdog.stop(); + if (stalled) { + sweepStallSurvivors(); + return reject(stalled); + } if (timedOut) return reject(new Error(`claude timed out after ${timeoutMs}ms`)); if (code !== 0) { // Report stdout too, not just stderr. In `-p` mode claude writes terminal @@ -1200,6 +1251,13 @@ export default { credentials: spawnCredentials(spawnCtx), spawnImpl: ctx._spawnImpl, onSpawn: ctx.onSpawn, controls: controlsFromArguments(modelArgs, { modelFlag: '--model', effortFlag: '--effort' }), // test seam only — do not use in production ownGroup: wantsOwnProcessGroup(ctx), + transcriptPath: claudeTranscriptPath({ + cwd: physicalPath(ctx.cwd), sessionId, configDir: claudeConfigDirFor({ ...env, HOME: childHome || env?.HOME }), + }), + lockProbe: ctx._lockProbe, // test seams only + stallKillGraceMs: ctx._stallKillGraceMs, + processTable: ctx._processTable, + survivorIo: ctx._survivorIo, }); // TASK-440: the context this turn left, read from the transcript the // child wrote under its own env (an isolated HOME for public seats). @@ -1256,6 +1314,14 @@ export default { credentials: spawnCredentials(retryCtx), spawnImpl: ctx._spawnImpl, onSpawn: ctx.onSpawn, controls: controlsFromArguments(modelArgs, { modelFlag: '--model', effortFlag: '--effort' }), ownGroup: wantsOwnProcessGroup(ctx), + transcriptPath: claudeTranscriptPath({ + cwd: physicalPath(ctx.cwd), sessionId: freshId, + configDir: claudeConfigDirFor({ ...retry.env, HOME: retry.childHome || retry.env?.HOME }), + }), + lockProbe: ctx._lockProbe, + stallKillGraceMs: ctx._stallKillGraceMs, + processTable: ctx._processTable, + survivorIo: ctx._survivorIo, }); const contextTokens = claudeContextTokens({ cwd: ctx.cwd, sessionId: freshId, diff --git a/cli/src/lib/first-output-watchdog.js b/cli/src/lib/first-output-watchdog.js new file mode 100644 index 0000000000..2677bf88d2 --- /dev/null +++ b/cli/src/lib/first-output-watchdog.js @@ -0,0 +1,141 @@ +/** + * First-output watchdog for a seat's model CLI spawn. + * + * On 2026-10-30 every launchd seat's `claude -p` turn parked while the Mac's + * console was locked: no transcript row, no stdout, no stderr, for the full + * 45-minute run timeout. Each one held its delivery the whole time, the retry + * respawned it into the same hang, and the log said only "claude timed out + * after 2700000ms", which names nothing. + * + * The signal is not stdout. A seat runs `claude -p --output-format text`, + * which writes stdout once, at the end, so a healthy 20-minute turn has zero + * stdout bytes for 20 minutes. What a healthy turn does write is its session + * transcript: measured on the dart seat, the first row landed 0.7 s after the + * spawn, and the hung spawns that night wrote no row at all. So a spawn counts + * as started when it writes any stdout or stderr byte OR its transcript grows. + * A spawn that does neither inside the window is killed with a reason. When + * the transcript is missing altogether, the path may simply be wrong, so the + * spawn is killed only if the console is also locked. + */ +import { realpathSync, statSync } from 'fs'; +import { readProcess } from '@commonlyai/seats/process-group'; + +export const DEFAULT_FIRST_OUTPUT_WINDOW_MS = 180_000; + +// 0 turns the watchdog off; anything unparseable keeps the default. +export const firstOutputWindowMs = (env = process.env) => { + const raw = env?.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + if (raw === undefined || raw === '') return DEFAULT_FIRST_OUTPUT_WINDOW_MS; + const parsed = Number(raw); + return Number.isFinite(parsed) && parsed >= 0 ? parsed : DEFAULT_FIRST_OUTPUT_WINDOW_MS; +}; + +export const SPAWN_STALLED_CODE = 'spawn_stalled'; + +// The message carries the class word spawn-retry.js matches, so the stall gets +// its own backoff rather than RUNTIME's 5-second retry. +export const spawnStalledError = ({ label, windowMs, reason }) => { + const error = new Error( + `${label} produced no output in ${Math.round(windowMs / 1000)}s (${reason}); killed before the run timeout`, + ); + error.code = SPAWN_STALLED_CODE; + error.stallReason = reason; + return error; +}; + +// `ioreg -n Root -d1` prints `"IOConsoleLocked" = Yes` while the screen is +// locked. True, false, or null when it cannot tell (not darwin, ioreg failed). +// child_process is loaded on demand: suites that mock it with only `spawn` +// would otherwise fail to import every adapter that uses this module. +export const consoleLocked = async ({ platform = process.platform, execFileImpl } = {}) => { + if (platform !== 'darwin') return null; + const run = execFileImpl || (await import('child_process')).execFile; + if (typeof run !== 'function') return null; + return new Promise((resolve) => { + run('/usr/sbin/ioreg', ['-n', 'Root', '-d1'], { timeout: 5000 }, (error, stdout) => { + if (error) return resolve(null); + const match = String(stdout).match(/"IOConsoleLocked"\s*=\s*(Yes|No)/); + return resolve(match ? match[1] === 'Yes' : null); + }); + }); +}; + +// Claude names its project folder after process.cwd(), which on macOS is the +// physical path (/tmp is /private/tmp), so the transcript is looked for there. +export const physicalPath = (dir) => { + if (!dir) return dir; + try { + return realpathSync(dir); + } catch { + return dir; + } +}; + +// How long a stalled spawn gets to exit after SIGTERM before SIGKILL. +export const STALL_KILL_GRACE_MS = 10_000; + +/** + * SIGKILL each snapshotted descendant of a stalled spawn that is still alive + * once the spawn itself has exited. Its parent may have exited, so it may now + * belong to launchd: only the pid and start time are matched, which still + * rules out a reused pid. Returns the pids signalled. + */ +export const killStallSurvivors = (snapshot, { read = readProcess, kill = process.kill.bind(process) } = {}) => { + const killed = []; + for (const row of snapshot || []) { + const now = read(row.pid); + if (!now || now.started !== row.started) continue; + try { kill(row.pid, 'SIGKILL'); killed.push(row.pid); } catch { /* gone */ } + } + return killed; +}; + +const sizeOf = (file) => { + if (!file) return -1; + try { + return statSync(file).size; + } catch { + return -1; + } +}; + +/** + * Watch `proc` for its first sign of life. Returns `{ stop }`; call it when the + * process closes. `onStall(reason)` fires at most once, after the caller should + * kill the process. + */ +export const watchFirstOutput = ({ + proc, + windowMs, + transcriptPath = null, + onStall, + lockProbe = consoleLocked, + setTimeoutImpl = setTimeout, + clearTimeoutImpl = clearTimeout, +}) => { + if (!windowMs) return { stop: () => {} }; + let started = false; + let stopped = false; + const markStarted = () => { started = true; }; + proc.stdout?.on('data', markStarted); + proc.stderr?.on('data', markStarted); + // A missing file counts as empty, so creating an empty one is not growth. + const baseline = Math.max(0, sizeOf(transcriptPath)); + const timer = setTimeoutImpl(async () => { + const size = sizeOf(transcriptPath); + if (started || size > baseline) return; + const locked = await lockProbe().catch(() => null); + if (stopped) return; + // No transcript where one was expected may only mean the path is wrong, so + // that alone never kills a turn: it takes a locked console as well. + if (size < 0 && locked !== true) return; + onStall(locked ? 'console locked' : 'no transcript, stdout or stderr'); + }, windowMs); + timer?.unref?.(); + return { + stop: () => { + stopped = true; + clearTimeoutImpl(timer); + }, + }; +}; diff --git a/cli/src/lib/spawn-retry.js b/cli/src/lib/spawn-retry.js index 67ee47ca0a..527850e395 100644 --- a/cli/src/lib/spawn-retry.js +++ b/cli/src/lib/spawn-retry.js @@ -16,8 +16,16 @@ export const SPAWN_FAILURE_CLASS = Object.freeze({ RATE_LIMIT: 'rate_limit', CONFIGURATION: 'configuration', RUNTIME: 'runtime', + // The spawn never started: no transcript row, stdout or stderr inside the + // first-output window (lib/first-output-watchdog.js). A host condition such as + // a locked console, so the circuit opens at once and the probe waits. + STALLED: 'stalled', }); +// A stalled probe costs one first-output window, so the wait starts short and +// doubles to the usual ceiling: 2, 4, 8, then 15 minutes. +export const SPAWN_STALL_RETRY_BASE_MS = 2 * 60 * 1000; + export const SPAWN_CIRCUIT_THRESHOLD = 3; // Base ceiling before the stable per-agent 0–20% anti-herd offset. export const SPAWN_RETRY_MAX_MS = 15 * 60 * 1000; @@ -116,6 +124,7 @@ export const classifySpawnFailure = (error) => { // First: the refusal text carries none of the words below today, but a // refusal must never be read as a transient condition and retried. if (CONTENT_REFUSED_RE.test(text)) return SPAWN_FAILURE_CLASS.CONTENT_REFUSED; + if (error?.code === 'spawn_stalled') return SPAWN_FAILURE_CLASS.STALLED; // Provider APIs commonly report an exhausted account quota as HTTP 429. // Prefer the more specific body/message over the generic status code so a // hard quota failure gets the long cooldown rather than a one-minute probe. @@ -194,6 +203,17 @@ export const spawnRetryPolicy = ({ }; } + if (failureClass === SPAWN_FAILURE_CLASS.STALLED) { + return { + failureClass, + circuitOpen: true, + delayMs: applyJitter( + Math.min(SPAWN_RETRY_MAX_MS, SPAWN_STALL_RETRY_BASE_MS * (2 ** (failureCount - 1))), + jitterRatio, + ), + }; + } + if (failureClass === SPAWN_FAILURE_CLASS.RATE_LIMIT) { return { failureClass,