Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
165 changes: 163 additions & 2 deletions cli/__tests__/first-output-watchdog.test.mjs
Original file line number Diff line number Diff line change
Expand Up @@ -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-'));

Expand All @@ -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');

Expand Down Expand Up @@ -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;
Expand All @@ -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() });

Expand Down Expand Up @@ -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?.();
}
});
});
2 changes: 2 additions & 0 deletions cli/src/commands/agent.js
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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(),
Expand Down
7 changes: 7 additions & 0 deletions cli/src/lib/adapters/claude.js
Original file line number Diff line number Diff line change
Expand Up @@ -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(() => {
Expand Down
11 changes: 11 additions & 0 deletions cli/src/lib/first-output-watchdog.js
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
1 change: 1 addition & 0 deletions docs/cli/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)). |

Expand Down
11 changes: 11 additions & 0 deletions docs/development/agent-experience-audit.md
Original file line number Diff line number Diff line change
Expand Up @@ -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-<id>` 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.

Loading