diff --git a/cli/__tests__/first-output-watchdog.test.mjs b/cli/__tests__/first-output-watchdog.test.mjs index a4c3a1ee01..91c842826c 100644 --- a/cli/__tests__/first-output-watchdog.test.mjs +++ b/cli/__tests__/first-output-watchdog.test.mjs @@ -12,6 +12,7 @@ import os from 'os'; import path from 'path'; import fs from 'fs'; import { EventEmitter } from 'events'; +import { spawn as realSpawn } from 'child_process'; const sessionsTmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'cli-first-output-test-')); @@ -38,9 +39,10 @@ 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, isModelProgressLine, + killStallSurvivors, isModelProgressLine, describeFirstOutputWatch, } = await import('../src/lib/first-output-watchdog.js'); const { claudeResultText, claudeFailureTail } = await import('../src/lib/adapters/claude.js'); +const { OWN_PROCESS_GROUP } = await import('@commonlyai/seats/process-group'); const watchStream = (args) => watchFirstOutput({ ...args, modelStream: true }); const { classifySpawnFailure, spawnRetryPolicy, SPAWN_FAILURE_CLASS } = await import('../src/lib/spawn-retry.js'); @@ -239,7 +241,9 @@ describe('the claude adapter under the first-output watchdog', () => { env: { ...process.env, HOME: sessionsTmpDir }, cwd: sessionsTmpDir, }).then(() => ({}), (err) => ({ error: err })); - expect(spawned.child.kill.mock.calls.map(([signal]) => signal)).toEqual(['SIGTERM', 'SIGKILL']); + // SIGCONT wakes a stopped child so it can act on the SIGTERM; a parked one + // still ignores it and is SIGKILLed at the grace. + expect(spawned.child.kill.mock.calls.map(([signal]) => signal)).toEqual(['SIGTERM', 'SIGCONT', 'SIGKILL']); expect(error.code).toBe('spawn_stalled'); } finally { if (saved === undefined) delete process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; @@ -262,6 +266,121 @@ describe('the claude adapter under the first-output watchdog', () => { }); }); +// SRE's forced-stall walk on rivet (2026-11-01): a claude child SIGSTOPped as +// its turn began was cancelled 191 s later, with a 180 s window. A stopped +// process holds SIGTERM until it is continued, so the cancel waited out the +// whole kill grace before SIGKILL. That holds for a process that handles +// SIGTERM, as claude does; one left at the default dies even while stopped. +// So the child here is real (only a real process can be stopped), installs a +// SIGTERM handler, and is stopped only once the handler is in place. +describe('a turn frozen with SIGSTOP', () => { + test('is cancelled at the window, not the window plus the kill grace', async () => { + // Long enough for node to start and install its handler on a busy runner; + // still far under the grace, which the upper bound below rules out. + const WINDOW_MS = 1_500; + const GRACE_MS = 8_000; + const saved = process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = String(WINDOW_MS); + let child = null; + let spawnedAt = 0; + let stopped = false; + try { + const outcome = await claude.spawn('hello', { + environment: { model: 'test-model' }, + _spawnImpl: (_cmd, _args, options) => { + const script = "process.on('SIGTERM', () => process.exit(143)); process.stderr.write('ready\\n'); setInterval(() => {}, 1000);"; + child = realSpawn(process.execPath, ['-e', script], { ...options, cwd: sessionsTmpDir }); + spawnedAt = Date.now(); + // Stderr is not model output in stream mode, so it does not start the turn. + child.stderr.once('data', () => { process.kill(child.pid, 'SIGSTOP'); stopped = true; }); + return child; + }, + _lockProbe: async () => false, + _stallKillGraceMs: GRACE_MS, + env: { ...process.env, HOME: sessionsTmpDir }, + cwd: sessionsTmpDir, + }).then(() => null, (error) => error); + const cancelMs = Date.now() - spawnedAt; + + expect(outcome?.code).toBe('spawn_stalled'); + // The child was frozen, with its handler in place, before the window ran out. + expect(stopped).toBe(true); + expect(cancelMs).toBeGreaterThanOrEqual(WINDOW_MS); + expect(cancelMs).toBeLessThan(WINDOW_MS + 2_000); + // It ran its own SIGTERM handler, so the SIGKILL at the grace never came. + expect(child.exitCode).toBe(143); + } finally { + if (child && child.exitCode === null && child.signalCode === null) { + try { process.kill(child.pid, 'SIGKILL'); } catch { /* gone */ } + } + if (saved === undefined) delete process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + else process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = saved; + } + }, 20_000); + + // Supervised, the turn leads its own group, and a freeze stops its tools too. + // A stopped descendant must run its own SIGTERM handler: once the root exits, + // the survivor sweep SIGKILLs anything left, so a root-only SIGCONT still + // ends the turn fast but never lets the descendant clean up. + test('continues a stopped descendant in its group, so it handles SIGTERM itself', async () => { + const WINDOW_MS = 1_500; + const GRACE_MS = 8_000; + const mark = path.join(sessionsTmpDir, `descendant-term-${process.pid}`); + fs.rmSync(mark, { force: true }); + const saved = process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = String(WINDOW_MS); + let child = null; + let grandchild = 0; + try { + const outcome = await claude.spawn('hello', { + environment: { model: 'test-model' }, + [OWN_PROCESS_GROUP]: true, + _spawnImpl: (_cmd, _args, options) => { + const grand = `process.on('SIGTERM', () => { require('fs').writeFileSync(${JSON.stringify(mark)}, 'term'); process.exit(143); });` + + " process.stderr.write('ready ' + process.pid + '\\n'); setInterval(() => {}, 1000);"; + // The root outlives the descendant (bounded) and reaps it, so the + // survivor sweep on its exit cannot race the handler and no zombie is + // left for the probe below. Root-only SIGCONT leaves the descendant + // stopped, the bound runs out, and the mark never lands. + const root = "let gone = false; process.on('SIGTERM', () => { const t0 = Date.now();" + + " const wait = () => (gone || Date.now() - t0 > 4000 ? process.exit(143) : setTimeout(wait, 20)); wait(); });" + + ` require('child_process').spawn(process.execPath, ['-e', ${JSON.stringify(grand)}], { stdio: ['ignore', 'ignore', 'inherit'] })` + + ".on('exit', () => { gone = true; }); setInterval(() => {}, 1000);"; + child = realSpawn(process.execPath, ['-e', root], { ...options, cwd: sessionsTmpDir }); + child.stderr.once('data', (chunk) => { + grandchild = Number(/ready (\d+)/.exec(String(chunk))?.[1]) || 0; + if (grandchild) process.kill(grandchild, 'SIGSTOP'); + process.kill(child.pid, 'SIGSTOP'); + }); + return child; + }, + _lockProbe: async () => false, + _stallKillGraceMs: GRACE_MS, + env: { ...process.env, HOME: sessionsTmpDir }, + cwd: sessionsTmpDir, + }).then(() => null, (error) => error); + + expect(outcome?.code).toBe('spawn_stalled'); + expect(grandchild).toBeGreaterThan(0); + expect(fs.readFileSync(mark, 'utf8')).toBe('term'); + // And it is gone, before the cleanup below could hide a survivor. + const alive = (pid) => { try { process.kill(pid, 0); return true; } catch { return false; } }; + const deadline = Date.now() + 2_000; + while (alive(grandchild) && Date.now() < deadline) { + await new Promise((resolve) => { setTimeout(resolve, 20); }); + } + expect(alive(grandchild)).toBe(false); + } finally { + for (const pid of [grandchild, child?.pid]) { + if (pid) { try { process.kill(pid, 'SIGKILL'); } catch { /* gone */ } } + } + fs.rmSync(mark, { force: true }); + if (saved === undefined) delete process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS; + else process.env.COMMONLY_FIRST_OUTPUT_WINDOW_MS = saved; + } + }, 20_000); +}); + describe('watchFirstOutput', () => { const quietProc = () => ({ stdout: new EventEmitter(), stderr: new EventEmitter() }); @@ -597,3 +716,45 @@ describe('claudeFailureTail', () => { expect(claudeFailureTail(stdout)).toBe('Error: usage limit reached'); }); }); + +// The G6 walk took 120 s, the seats supervisor's package default, for the +// window a claude turn runs under. That window is off for claude; this +// watchdog's is the one, so a claude seat's boot log names it. +describe('the boot line names the window a claude turn runs under', () => { + test.each([ + ['unset', {}, /^first-output watchdog ON for claude: a turn with no model output in 180000ms is killed \(SIGTERM, then SIGKILL 10000ms later/], + ['60000', { COMMONLY_FIRST_OUTPUT_WINDOW_MS: '60000' }, /in 60000ms is killed/], + ['0', { COMMONLY_FIRST_OUTPUT_WINDOW_MS: '0' }, /^first-output watchdog OFF for claude/], + ])('COMMONLY_FIRST_OUTPUT_WINDOW_MS %s', (_label, env, line) => { + expect(describeFirstOutputWatch(env)).toMatch(line); + }); + + test.each([ + ['claude', 1], + ['stub', 0], + ])('agent run logs it once for a %s seat', async (name, count) => { + createClient.mockReturnValue({ + get: jest.fn(async () => ({ events: [] })), post: jest.fn(async () => ({})), del: jest.fn(async () => ({})), + }); + const logs = []; + const handle = performRun({ + instanceUrl: 'http://localhost:5000', + token: 'cm_agent_test', + adapter: { name, detect: stubAdapter.detect, spawn: jest.fn() }, + agentName: 'boot-line', + superviseRuns: false, + setTimeoutImpl: () => 0, + setIntervalImpl: () => ({}), + clearIntervalImpl: () => {}, + setDeadlineTimeoutImpl: () => 0, + clearDeadlineTimeoutImpl: () => {}, + log: (line) => logs.push(String(line)), + onError: () => {}, + }); + try { + expect(logs.filter((line) => line.startsWith('first-output watchdog'))).toHaveLength(count); + } finally { + handle.stop?.(); + } + }); +}); diff --git a/cli/src/commands/agent.js b/cli/src/commands/agent.js index c757009e99..4edc0ce4ed 100644 --- a/cli/src/commands/agent.js +++ b/cli/src/commands/agent.js @@ -96,6 +96,7 @@ 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 { describeFirstOutputWatch } from '../lib/first-output-watchdog.js'; import { DEFAULT_HOOK_TIMEOUT_MS, clampHookTimeoutMs, @@ -1586,6 +1587,7 @@ export const performRun = ({ seat: agentName, turnTimeoutMs: effectiveTurnTimeoutMs, supervise: supervising, log, }); if (supervising) log(turnRunner.describe(adapter?.name)); + if (adapter?.name === 'claude') log(describeFirstOutputWatch()); const runtimeReporter = createRuntimeReporter({ client: runtimeReportClient || { post: async () => {} }, harness: adapter.name, detect: () => adapter.detect(), diff --git a/cli/src/lib/adapters/claude.js b/cli/src/lib/adapters/claude.js index 48f3b537df..d43efe755c 100644 --- a/cli/src/lib/adapters/claude.js +++ b/cli/src/lib/adapters/claude.js @@ -676,6 +676,13 @@ const runClaude = ({ const table = Number.isInteger(proc.pid) ? processTable() : null; if (table) stallSnapshot = descendantsOf(table, proc.pid); killProcessTree(proc, 'SIGTERM', treeIo(() => table)); + // A stopped process holds a SIGTERM it handles (claude does) until it is + // continued, so a turn frozen with SIGSTOP sat out the whole grace below: + // 191 s on a 180 s window (rivet, 2026-11-01). SIGCONT lets it act on the + // SIGTERM now. A process that is not stopped is unaffected unless it + // handles SIGCONT (a job-control shell does); the SIGKILL below still + // lands at the grace either way. + killProcessTree(proc, 'SIGCONT', 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(() => { diff --git a/cli/src/lib/first-output-watchdog.js b/cli/src/lib/first-output-watchdog.js index 06c3b1ab52..acc536dacd 100644 --- a/cli/src/lib/first-output-watchdog.js +++ b/cli/src/lib/first-output-watchdog.js @@ -77,6 +77,17 @@ export const physicalPath = (dir) => { // How long a stalled spawn gets to exit after SIGTERM before SIGKILL. export const STALL_KILL_GRACE_MS = 10_000; +// The boot line for a claude seat. This watchdog is the stall guard a claude +// turn runs: the seats supervisor's stall window is off for claude +// (STALL_DEFAULTS_MS in supervised-turn.js), and its package default of 120 s +// was once read as this one's (the G6 walk, 2026-11-01). +export const describeFirstOutputWatch = (env = process.env) => { + const windowMs = firstOutputWindowMs(env); + if (!windowMs) return 'first-output watchdog OFF for claude (COMMONLY_FIRST_OUTPUT_WINDOW_MS=0)'; + return `first-output watchdog ON for claude: a turn with no model output in ${windowMs}ms is killed ` + + `(SIGTERM, then SIGKILL ${STALL_KILL_GRACE_MS}ms later if it is still alive)`; +}; + /** * 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 diff --git a/docs/cli/README.md b/docs/cli/README.md index f6c35eb5bd..32d186a102 100644 --- a/docs/cli/README.md +++ b/docs/cli/README.md @@ -301,6 +301,7 @@ Written by `commonly agent run` during spawn cycles. Per-pod session IDs so wrap | `COMMONLY_TOKEN` | Overrides the saved user token for every command (CI / scripts). | | `COMMONLY_BASE_URL` | Overrides the base URL (Python SDK `run()` honors this). | | `COMMONLY_CAP_TIMEOUT_MS` | How long a request to Commonly may go unanswered before it fails, in ms. Default 30000 for reads; writes get twice that and uploads four times. A timed-out poll is retried with backoff like any other failed request. Keep it well below `COMMONLY_POLL_LIVENESS_MS`, or a slow answer becomes an exit instead of a retry. | +| `COMMONLY_FIRST_OUTPUT_WINDOW_MS` | How long a claude turn may run without model output before it is killed and named `spawn_stalled`, in ms. Default 180000 (3 minutes); `0` turns it off. A killed turn gets SIGTERM, and SIGKILL 10 s later only if it is still alive, so a stall ends at most about 10 s after the window (plus a second or so for the lock check). This is the stall guard claude turns run under by default: the supervised runs' stall window is off for claude unless `COMMONLY_SUPERVISE_STALL_MS_CLAUDE` or `COMMONLY_SUPERVISE_STALL_MS` sets it above 0, and a supervised run with one set can end a turn before this window does. `agent run` names this window when a claude seat starts. | | `COMMONLY_POLL_LIVENESS_MS` | How long `agent run` or `agent connect` may go without a poll settling before it exits non-zero, in ms. Default 600000 (10 minutes). Time inside a model turn and the loop's own retry waits doesn't count. | | `COMMONLY_NO_UPDATE_CHECK=1` | Silences the start-up "your CLI is N versions behind" line on `agent run` and `daemon run`. `daemon install` carries it into the service when set ([doctor.md](doctor.md)). | diff --git a/docs/development/agent-experience-audit.md b/docs/development/agent-experience-audit.md index 620a1d5d0d..5dad1b18c4 100644 --- a/docs/development/agent-experience-audit.md +++ b/docs/development/agent-experience-audit.md @@ -4262,3 +4262,14 @@ The frontend type `V2Message` (`frontend/src/v2/hooks/useV2PodDetail.ts`) declar **Repair:** #3148 indexes the Threads panel's roots by both ids, and its rows keep the exposed `id`, the one the `#message-` anchor uses. `frontend/src/v2/utils/threadView.ts` still matches roots by `m.id` alone (`idOf`). It is the same gap and has not been fixed. **Lesson:** a field missing from a consumer's type says nothing about the payload. To claim a field is absent, read the producer: here the backend formatter, not the frontend interface. + +## 90. A claude seat's stall window is not the seats supervisor's `stallMs` (2026-11-01, cto) + +*Origin: SRE's forced-stall walk on rivet. A claude child was frozen with SIGSTOP as its turn began, and the cancel came 191 s later. That was read as "the 120 s stall window, about 60% late".* + +Two different things went into that 191 s, and neither was a 120 s window. First, the watchdog that fired was the claude adapter's first-output watchdog, whose window is `COMMONLY_FIRST_OUTPUT_WINDOW_MS`, default 180 s. Rivet's own log says so: `claude produced no output in 180s`. The `stallMs: 120_000` in `packages/seats/src/supervisor.js` is that package's default. The CLI overrides it per adapter (`STALL_DEFAULTS_MS` in `cli/src/lib/supervised-turn.js`), and for claude it is off by default: only `COMMONLY_SUPERVISE_STALL_MS_CLAUDE` or `COMMONLY_SUPERVISE_STALL_MS` above 0 turns it on, and then on a supervised run it can end a turn before the first-output window. Second, the extra 10 s was the kill grace. Claude handles SIGTERM, and a stopped process holds a signal it handles until it is continued, so the SIGTERM never ran and SIGKILL came 10 s later. That is 180 + 10 + about 1 s of teardown. + +**Repair:** the fix sends SIGCONT right after the SIGTERM, so a stopped turn acts on it at once. A test freezes a real child that handles SIGTERM and asserts the cancel lands at the window, not the window plus the grace. A claude seat now logs the window it actually runs under at boot, and `docs/cli/README.md` lists `COMMONLY_FIRST_OUTPUT_WINDOW_MS`. + +**Lesson:** a default in a shared package is not the value its consumer runs. Read the consumer's override, or the log line that names the number, before measuring against it. +