fix(codex): count raw child output as activity (#9632)
## Thinking Path > - Paperclip is the open source control plane teams use to manage AI agents and their work > - The Codex local adapter supervises CLI child processes and terminates genuinely silent runs > - The existing inactivity timer only recognized parsed JSONL stdout events as activity > - Long verification commands can emit ordinary stdout or stderr while producing no JSONL, so healthy children could be killed > - This pull request makes the watchdog observe raw child-process output before filtering or parsing > - The benefit is that long typecheck, build, and test phases survive while truly silent children remain bounded ## Linked Issues or Issue Description - **Bug:** The Codex output-inactivity watchdog could terminate healthy runs during long verification phases because non-JSON stdout and stderr did not reset its timer. - **Expected:** Any bytes emitted by the child process count as output activity; only a child with no stdout or stderr for the configured interval is terminated. - **Reproduction:** Configure a short `outputInactivityTimeoutMs`, run a Codex child that periodically emits plain-text verification progress without JSONL events, and observe the old monitor firing despite continued output. - **Deployment mode:** Local `codex_local` adapter execution. - Related implementation: #5017 - Related recovery behavior: #8680 ## What Changed - Reset the Codex inactivity monitor on every non-empty stdout or stderr chunk before stderr noise filtering. - Track raw output chunk and byte counts in monitor diagnostics while retaining parsed JSONL event counts. - Add regression coverage for more than 21 simulated minutes of non-JSON verification output and retain silent-child termination coverage. - Document that `outputInactivityTimeoutMs` observes raw child output and that `null` still disables the monitor. ## Verification - `/srv/paperclip/home/paperclipai/paperclip/node_modules/.bin/vitest run packages/adapters/codex-local/src/server/output-inactivity-monitor.test.ts packages/adapters/codex-local/src/server/output-inactivity-monitor.integration.test.ts` - `/srv/paperclip/home/paperclipai/paperclip/node_modules/.bin/tsc -p packages/adapters/codex-local/tsconfig.json --noEmit` ## Risks - Low risk: the monitor becomes more conservative and may allow a noisy-but-stuck child to run longer, but the configured hard timeout and platform silent-run safety net remain unchanged. - No schema, API, migration, or UI changes. > For core feature work, check [`ROADMAP.md`](ROADMAP.md) first and discuss it in `#dev` before opening the PR. Feature PRs that overlap with planned core work may need to be redirected — check the roadmap first. See `CONTRIBUTING.md`. ## Model Used - OpenAI Codex CLI coding agent; runtime model ID and context-window size were not exposed to the agent. Used repository/tool access, code execution, and focused test verification. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [x] All Paperclip CI gates are green - [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge --------- Co-authored-by: Paperclip <noreply@paperclip.ing>
This commit is contained in:
Dotta
GitHub
parent
8eff54bc47
commit
df2404d443
|
|
@ -95,7 +95,7 @@ Core fields:
|
|||
Operational fields:
|
||||
- timeoutSec (number, optional): run timeout in seconds
|
||||
- graceSec (number, optional): SIGTERM grace period in seconds
|
||||
- outputInactivityTimeoutMs (number | null, optional): inactivity monitor around the codex child. Resets on every parsed JSONL event from stdout. Defaults to 7 * 60_000 ms when unset or non-positive. Set to \`null\` to disable the monitor entirely (only do this for known-slow tasks; the platform-level 1h silent-run safety net still applies). On fire, the adapter sends SIGTERM to the process group, waits 5s, then SIGKILL, and surfaces the run as failed with errorMessage "monitor: no codex output for {N}m {S}s".
|
||||
- outputInactivityTimeoutMs (number | null, optional): inactivity monitor around the codex child. Resets whenever the child emits stdout or stderr bytes, including non-JSON progress from long-running verification commands. Defaults to 7 * 60_000 ms when unset or non-positive. Set to \`null\` to disable the monitor entirely (only do this for known-slow tasks; the platform-level 1h silent-run safety net still applies). On fire, the adapter sends SIGTERM to the process group, waits 5s, then SIGKILL, and surfaces the run as failed with errorMessage "monitor: no codex output for {N}m {S}s".
|
||||
- agentCommand (string, optional): ACP server command override used only when engine="acp"; defaults to the package-local codex-acp binary
|
||||
- mode (string, optional): ACP session mode when engine="acp"; persistent or oneshot
|
||||
- nonInteractivePermissions (string, optional): ACP non-interactive permission fallback when engine="acp"; deny or fail
|
||||
|
|
|
|||
|
|
@ -1037,6 +1037,7 @@ export async function execute(ctx: AdapterExecutionContext): Promise<AdapterExec
|
|||
const logLine =
|
||||
`[paperclip] adapter.invoke ${message}; ` +
|
||||
`timeoutMs=${monitorResolution.timeoutMs} elapsedSinceLastEventMs=${monitorElapsedMs} ` +
|
||||
`outputChunkCount=${state.outputChunkCount} outputBytes=${state.outputBytes} ` +
|
||||
`parsedEvents=${state.parsedEventCount} (timeout=${timeoutSecLabel}s elapsed=${elapsedSec}s); ` +
|
||||
`terminating codex child via SIGTERM (5s grace, then SIGKILL).\n`;
|
||||
// Issue the log without awaiting on the kill hot path, but capture
|
||||
|
|
@ -1078,8 +1079,8 @@ export async function execute(ctx: AdapterExecutionContext): Promise<AdapterExec
|
|||
onSpawn: wrappedOnSpawn,
|
||||
onRuntimeProgress: ctx.onRuntimeProgress,
|
||||
onLog: async (stream, chunk) => {
|
||||
monitor?.noteOutputChunk(stream, chunk);
|
||||
if (stream === "stdout") {
|
||||
monitor?.noteStdoutChunk(chunk);
|
||||
await onLog(stream, chunk);
|
||||
return;
|
||||
}
|
||||
|
|
|
|||
|
|
@ -72,9 +72,7 @@ describe("codex inactivity monitor (integration: real subprocess)", () => {
|
|||
},
|
||||
onLog: async (stream, chunk) => {
|
||||
logs.push({ stream, chunk });
|
||||
if (stream === "stdout") {
|
||||
monitor.noteStdoutChunk(chunk);
|
||||
}
|
||||
monitor.noteOutputChunk(stream, chunk);
|
||||
},
|
||||
});
|
||||
|
||||
|
|
|
|||
|
|
@ -121,7 +121,7 @@ describe("createCodexOutputInactivityMonitor (acceptance criteria 1: fires)", ()
|
|||
|
||||
// One event right after spawn.
|
||||
clock.advance(50);
|
||||
monitor.noteStdoutChunk('{"type":"thread.started","thread_id":"abc"}\n');
|
||||
monitor.noteOutputChunk("stdout", '{"type":"thread.started","thread_id":"abc"}\n');
|
||||
expect(fires).toHaveLength(0);
|
||||
expect(monitor.state().parsedEventCount).toBe(1);
|
||||
|
||||
|
|
@ -157,7 +157,7 @@ describe("createCodexOutputInactivityMonitor (acceptance criteria 1: fires)", ()
|
|||
monitor.stop();
|
||||
});
|
||||
|
||||
it("ignores non-JSON lines when resetting the timer", () => {
|
||||
it("resets on non-JSON stdout bytes", () => {
|
||||
const clock = new FakeClock();
|
||||
let fireCount = 0;
|
||||
const monitor = createCodexOutputInactivityMonitor({
|
||||
|
|
@ -169,17 +169,52 @@ describe("createCodexOutputInactivityMonitor (acceptance criteria 1: fires)", ()
|
|||
fireCount += 1;
|
||||
},
|
||||
});
|
||||
// Plain stderr-ish text should NOT reset the monitor.
|
||||
clock.advance(500);
|
||||
monitor.noteStdoutChunk("loading model...\n");
|
||||
expect(monitor.state().parsedEventCount).toBe(0);
|
||||
clock.advance(600);
|
||||
monitor.noteOutputChunk("stdout", "loading model...\n");
|
||||
expect(monitor.state()).toMatchObject({
|
||||
outputChunkCount: 1,
|
||||
outputBytes: Buffer.byteLength("loading model...\n", "utf8"),
|
||||
parsedEventCount: 0,
|
||||
});
|
||||
clock.advance(999);
|
||||
expect(fireCount).toBe(0);
|
||||
clock.advance(1);
|
||||
expect(fireCount).toBe(1);
|
||||
monitor.stop();
|
||||
});
|
||||
});
|
||||
|
||||
describe("createCodexOutputInactivityMonitor (acceptance criteria 2: does not fire)", () => {
|
||||
it("keeps long verification alive while non-JSON stdout and stderr bytes continue", () => {
|
||||
const clock = new FakeClock();
|
||||
let fireCount = 0;
|
||||
const timeoutMs = 7 * 60 * 1000;
|
||||
const monitor = createCodexOutputInactivityMonitor({
|
||||
timeoutMs,
|
||||
now: () => clock.now(),
|
||||
setTimer: (cb, ms) => clock.setTimer(cb, ms),
|
||||
clearTimer: (handle) => clock.clearTimer(handle),
|
||||
onFire: () => {
|
||||
fireCount += 1;
|
||||
},
|
||||
});
|
||||
|
||||
clock.advance(timeoutMs - 1_000);
|
||||
monitor.noteOutputChunk("stdout", "packages/server: typecheck passed\n");
|
||||
clock.advance(timeoutMs - 1_000);
|
||||
monitor.noteOutputChunk("stderr", "packages/ui: build still running\n");
|
||||
clock.advance(timeoutMs - 1_000);
|
||||
monitor.noteOutputChunk("stdout", "packages/ui: build passed\n");
|
||||
|
||||
expect(fireCount).toBe(0);
|
||||
expect(monitor.state()).toMatchObject({
|
||||
outputChunkCount: 3,
|
||||
parsedEventCount: 0,
|
||||
fired: false,
|
||||
});
|
||||
monitor.stop();
|
||||
});
|
||||
|
||||
it("does not fire when events arrive every (threshold - 1s)", () => {
|
||||
const clock = new FakeClock();
|
||||
let fireCount = 0;
|
||||
|
|
@ -197,7 +232,7 @@ describe("createCodexOutputInactivityMonitor (acceptance criteria 2: does not fi
|
|||
// Pump events at threshold-1s intervals for 12 cycles (~84 minutes).
|
||||
for (let i = 0; i < 12; i += 1) {
|
||||
clock.advance(timeoutMs - 1_000);
|
||||
monitor.noteStdoutChunk(`{"type":"item.completed","item":{"type":"agent_message","text":"tick ${i}"}}\n`);
|
||||
monitor.noteOutputChunk("stdout", `{"type":"item.completed","item":{"type":"agent_message","text":"tick ${i}"}}\n`);
|
||||
expect(fireCount).toBe(0);
|
||||
}
|
||||
|
||||
|
|
@ -223,7 +258,8 @@ describe("createCodexOutputInactivityMonitor (acceptance criteria 2: does not fi
|
|||
},
|
||||
});
|
||||
clock.advance(500);
|
||||
monitor.noteStdoutChunk(
|
||||
monitor.noteOutputChunk(
|
||||
"stdout",
|
||||
'{"type":"thread.started","thread_id":"a"}\n{"type":"item.completed","item":{"type":"agent_message","text":"hi"}}\n',
|
||||
);
|
||||
expect(monitor.state().parsedEventCount).toBe(2);
|
||||
|
|
|
|||
|
|
@ -31,6 +31,8 @@ export interface CodexOutputInactivityMonitorState {
|
|||
spawnedAt: number;
|
||||
lastEventAt: number;
|
||||
firedAt: number | null;
|
||||
outputChunkCount: number;
|
||||
outputBytes: number;
|
||||
parsedEventCount: number;
|
||||
}
|
||||
|
||||
|
|
@ -48,7 +50,7 @@ export interface CodexOutputInactivityMonitorOptions {
|
|||
}
|
||||
|
||||
export interface CodexOutputInactivityMonitorHandle {
|
||||
noteStdoutChunk(chunk: string): void;
|
||||
noteOutputChunk(stream: "stdout" | "stderr", chunk: string): void;
|
||||
/** Returns the current state without stopping the timer. */
|
||||
state(): CodexOutputInactivityMonitorState;
|
||||
/** Cancels any pending timer and returns the final state. */
|
||||
|
|
@ -80,6 +82,8 @@ export function createCodexOutputInactivityMonitor(
|
|||
spawnedAt,
|
||||
lastEventAt: spawnedAt,
|
||||
firedAt: null,
|
||||
outputChunkCount: 0,
|
||||
outputBytes: 0,
|
||||
parsedEventCount: 0,
|
||||
};
|
||||
let timerHandle: unknown = null;
|
||||
|
|
@ -102,19 +106,19 @@ export function createCodexOutputInactivityMonitor(
|
|||
arm();
|
||||
|
||||
return {
|
||||
noteStdoutChunk(chunk: string) {
|
||||
if (stopped || state.fired) return;
|
||||
let sawHeartbeat = false;
|
||||
for (const rawLine of chunk.split(/\r?\n/)) {
|
||||
if (isHeartbeatLine(rawLine)) {
|
||||
sawHeartbeat = true;
|
||||
state.parsedEventCount += 1;
|
||||
noteOutputChunk(stream: "stdout" | "stderr", chunk: string) {
|
||||
if (stopped || state.fired || chunk.length === 0) return;
|
||||
state.outputChunkCount += 1;
|
||||
state.outputBytes += Buffer.byteLength(chunk, "utf8");
|
||||
if (stream === "stdout") {
|
||||
for (const rawLine of chunk.split(/\r?\n/)) {
|
||||
if (isHeartbeatLine(rawLine)) {
|
||||
state.parsedEventCount += 1;
|
||||
}
|
||||
}
|
||||
}
|
||||
if (sawHeartbeat) {
|
||||
state.lastEventAt = now();
|
||||
arm();
|
||||
}
|
||||
state.lastEventAt = now();
|
||||
arm();
|
||||
},
|
||||
state() {
|
||||
return { ...state };
|
||||
|
|
|
|||
Loading…
Reference in New Issue