From c13f4ac451df7a5ff284cc70bf87364550c4bc06 Mon Sep 17 00:00:00 2001 From: Patrick Yang <266918795+patriyang@users.noreply.github.com> Date: Fri, 7 Aug 2026 01:22:30 -0400 Subject: [PATCH 1/2] Report measured elapsed time when the turn-stall watchdog fires MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The stall message was built from the configured budget alone — `no activity for 900s` came from `Math.round(stallTimeoutMs / 1000)`, never from a measurement. When two concurrent turns logged their 900s idle stall ~21 minutes after their last recorded activity, the log could not say whether unlogged notifications had silently rearmed the timer or the timer itself had overslept, because it asserted an elapsed it never observed. Record the wall-clock instant and running count of every rearm, plus the instant each timer was armed, and append them to the stall message: Codex turn stalled (idle): no activity for 900s [budget 900s; measured 1260s since the last of 42 activity events at 2026-08-06T08:15:50.129Z; timer fired 360s late]. Interrupting and aborting the turn. That separates the two cases next time. A `last activity at` later than the final entry in the job log means silent rearms; one that matches the log alongside a large "fired late" means the timer was delayed (system sleep, App Nap, event-loop starvation). Watchdog behaviour is unchanged — same budgets, same interrupt path. This is observability only; whether the timer needs to survive system sleep is the question the instrumentation exists to answer. The leading clause is byte-identical to before so existing assertions and the rendered failure message stay stable. Closes #90 Co-Authored-By: Claude Opus 5 (1M context) --- .claude-plugin/marketplace.json | 4 +- package-lock.json | 4 +- package.json | 2 +- plugins/codex/.claude-plugin/plugin.json | 2 +- plugins/codex/scripts/lib/codex.mjs | 84 +++++++++++++++++++++--- tests/runtime.test.mjs | 63 ++++++++++++++++++ 6 files changed, 143 insertions(+), 16 deletions(-) diff --git a/.claude-plugin/marketplace.json b/.claude-plugin/marketplace.json index 016dedc80..03af6b846 100644 --- a/.claude-plugin/marketplace.json +++ b/.claude-plugin/marketplace.json @@ -5,13 +5,13 @@ }, "metadata": { "description": "Codex plugins to use in Claude Code for delegation and code review.", - "version": "1.0.37" + "version": "1.0.38" }, "plugins": [ { "name": "codex", "description": "Use Codex from Claude Code to review code or delegate tasks.", - "version": "1.0.37", + "version": "1.0.38", "author": { "name": "OpenAI" }, diff --git a/package-lock.json b/package-lock.json index c800e1779..89d5ab90a 100644 --- a/package-lock.json +++ b/package-lock.json @@ -1,12 +1,12 @@ { "name": "@openai/codex-plugin-cc", - "version": "1.0.37", + "version": "1.0.38", "lockfileVersion": 3, "requires": true, "packages": { "": { "name": "@openai/codex-plugin-cc", - "version": "1.0.37", + "version": "1.0.38", "license": "Apache-2.0", "devDependencies": { "@types/node": "^25.5.0", diff --git a/package.json b/package.json index ea05cbc06..e51e6332a 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "@openai/codex-plugin-cc", - "version": "1.0.37", + "version": "1.0.38", "private": true, "type": "module", "description": "Use Codex from Claude Code to review code or delegate tasks.", diff --git a/plugins/codex/.claude-plugin/plugin.json b/plugins/codex/.claude-plugin/plugin.json index 0de326a56..483f78bb5 100644 --- a/plugins/codex/.claude-plugin/plugin.json +++ b/plugins/codex/.claude-plugin/plugin.json @@ -1,6 +1,6 @@ { "name": "codex", - "version": "1.0.37", + "version": "1.0.38", "description": "Use Codex from Claude Code to review code or delegate tasks.", "author": { "name": "OpenAI" diff --git a/plugins/codex/scripts/lib/codex.mjs b/plugins/codex/scripts/lib/codex.mjs index d240f2a4b..e2c333efb 100644 --- a/plugins/codex/scripts/lib/codex.mjs +++ b/plugins/codex/scripts/lib/codex.mjs @@ -26,9 +26,11 @@ * activeSubagentTurns: Set, * completionTimer: ReturnType | null, * activityTimer: ReturnType | null, + * lastActivityAt: number | null, + * activityCount: number, * stallCleanup: Promise | null, * stalled: boolean, - * activeTools: Map | null }>, + * activeTools: Map | null, armedAt: number | null }>, * lastAgentMessage: string, * reviewText: string, * reasoningSummary: string[], @@ -416,6 +418,8 @@ function createTurnCaptureState(threadId, options = {}) { activeSubagentTurns: new Set(), completionTimer: null, activityTimer: null, + lastActivityAt: null, + activityCount: 0, stallCleanup: null, stalled: false, activeTools: new Map(), @@ -479,12 +483,20 @@ function trackToolStart(state, client, threadId, item, label, maxInFlightMs) { } const key = activeToolKey(threadId, item?.id); removeActiveTool(state, key); - const entry = { threadId: threadId ?? null, itemId: item?.id ?? null, toolClass: cls, label, deadlineTimer: null }; + const entry = { + threadId: threadId ?? null, + itemId: item?.id ?? null, + toolClass: cls, + label, + deadlineTimer: null, + armedAt: null + }; state.activeTools.set(key, entry); if (cls === "quick" && !state.completed && maxInFlightMs > 0 && Number.isFinite(maxInFlightMs)) { + entry.armedAt = Date.now(); entry.deadlineTimer = setTimeout(() => { entry.deadlineTimer = null; - state.stallCleanup = handleStall(state, client, maxInFlightMs, "tool-max", entry.label); + state.stallCleanup = handleStall(state, client, maxInFlightMs, "tool-max", entry.label, entry.armedAt); }, maxInFlightMs); entry.deadlineTimer.unref?.(); } @@ -643,21 +655,69 @@ async function interruptTurnWithTimeout(client, threadId, turnId) { } } -async function handleStall(state, client, stallTimeoutMs, stallMode, itemLabel = null) { +function formatStallDuration(ms) { + if (!Number.isFinite(ms)) { + return null; + } + if (ms < 1000) { + return `${Math.max(0, Math.round(ms))}ms`; + } + return `${Math.round(ms / 1000)}s`; +} + +async function handleStall(state, client, stallTimeoutMs, stallMode, itemLabel = null, armedAt = null) { if (state.completed) { return; } state.stalled = true; - const seconds = Math.round(stallTimeoutMs / 1000); + const now = Date.now(); + const budgetSeconds = Math.round(stallTimeoutMs / 1000); + const measuredMs = + stallMode === "tool-max" + ? Number.isFinite(armedAt) + ? now - armedAt + : null + : Number.isFinite(state.lastActivityAt) + ? now - state.lastActivityAt + : null; + const lateMs = Number.isFinite(armedAt) && Number.isFinite(stallTimeoutMs) + ? now - (armedAt + stallTimeoutMs) + : null; const labels = itemLabel ? [itemLabel] : activeToolLabels(state); const itemDetail = labels.length ? ` while "${labels.join(", ")}" was in flight` : ""; const modeDetail = stallMode === "tool" ? "tool-in-flight" : stallMode === "tool-max" ? "tool-max-duration" : "idle"; const reason = stallMode === "tool-max" - ? `in flight for ${seconds}s without completing (exceeded max tool duration)` - : `no activity for ${seconds}s`; - const message = `Codex turn stalled (${modeDetail}): ${reason}${itemDetail}. Interrupting and aborting the turn.`; + ? `in flight for ${budgetSeconds}s without completing (exceeded max tool duration)` + : `no activity for ${budgetSeconds}s`; + const detailParts = []; + const budget = formatStallDuration(stallTimeoutMs); + if (budget) { + detailParts.push(`budget ${budget}`); + } + if (Number.isFinite(measuredMs)) { + if (stallMode === "tool-max") { + detailParts.push(`measured ${formatStallDuration(measuredMs)} since the tool deadline was armed`); + } else { + let activityDetail = `measured ${formatStallDuration(measuredMs)} since the last of ${state.activityCount} activity events`; + if (Number.isFinite(state.lastActivityAt)) { + activityDetail += ` at ${new Date(state.lastActivityAt).toISOString()}`; + } + detailParts.push(activityDetail); + } + } + if (stallMode === "tool-max") { + detailParts.push(`${state.activityCount} activity events`); + if (Number.isFinite(state.lastActivityAt)) { + detailParts.push(`last activity at ${new Date(state.lastActivityAt).toISOString()}`); + } + } + if (Number.isFinite(lateMs) && lateMs > 1000) { + detailParts.push(`timer fired ${formatStallDuration(lateMs)} late`); + } + const detail = detailParts.length ? ` [${detailParts.join("; ")}]` : ""; + const message = `Codex turn stalled (${modeDetail}): ${reason}${itemDetail}${detail}. Interrupting and aborting the turn.`; state.error ??= { message }; emitLogEvent(state.onProgress, { message, @@ -682,6 +742,9 @@ function bumpActivity(state, client, stallTimeouts) { return; } + state.lastActivityAt = Date.now(); + state.activityCount += 1; + // A single global inactivity timer covers the whole turn. Use the short tool budget while any // quick tool is in flight; otherwise (only long tools, or none) fall back to the generous turn // backstop, since long tools (shell commands, subagent collaborations) can run long and silent. @@ -690,9 +753,10 @@ function bumpActivity(state, client, stallTimeouts) { clearActivityTimer(state); if (stallTimeoutMs > 0 && Number.isFinite(stallTimeoutMs)) { + const armedAt = Date.now(); state.activityTimer = setTimeout(() => { - state.activityTimer = null; - state.stallCleanup = handleStall(state, client, stallTimeoutMs, stallMode); + clearActivityTimer(state); + state.stallCleanup = handleStall(state, client, stallTimeoutMs, stallMode, null, armedAt); }, stallTimeoutMs); state.activityTimer.unref?.(); } diff --git a/tests/runtime.test.mjs b/tests/runtime.test.mjs index 14e3e768d..c548fce7a 100644 --- a/tests/runtime.test.mjs +++ b/tests/runtime.test.mjs @@ -18,6 +18,7 @@ import { } from "../plugins/codex/scripts/lib/broker-lifecycle.mjs"; import { parseBrokerEndpoint } from "../plugins/codex/scripts/lib/broker-endpoint.mjs"; import { CodexAppServerClient } from "../plugins/codex/scripts/lib/app-server.mjs"; +import { runAppServerTurn } from "../plugins/codex/scripts/lib/codex.mjs"; import { getProcessStartTime } from "../plugins/codex/scripts/lib/process.mjs"; import { resolveClaudeSessionPath, @@ -3087,6 +3088,68 @@ test("task watchdog lets idle reasoning exceed tool budget and stalls at turn ba assert.match(storedPayload.storedJob.rendered, /Codex turn stalled \(idle\)/i); }); +test("in-process idle watchdog reports measured oversleep and late firing", async (t) => { + const repo = makeTempDir(); + const binDir = makeTempDir(); + installFakeCodex(binDir, "idle-hung-turn"); + initGitRepo(repo); + + const stallTimeoutMs = 100; + const toolStallTimeoutMs = 50; + const previousPath = process.env.PATH; + const previousTurnStallTimeout = process.env.CODEX_TURN_STALL_TIMEOUT_MS; + const previousToolStallTimeout = process.env.CODEX_TOOL_STALL_TIMEOUT_MS; + process.env.PATH = buildEnv(binDir).PATH; + process.env.CODEX_TURN_STALL_TIMEOUT_MS = String(stallTimeoutMs); + process.env.CODEX_TOOL_STALL_TIMEOUT_MS = String(toolStallTimeoutMs); + t.after(() => { + if (previousPath === undefined) { + delete process.env.PATH; + } else { + process.env.PATH = previousPath; + } + if (previousTurnStallTimeout === undefined) { + delete process.env.CODEX_TURN_STALL_TIMEOUT_MS; + } else { + process.env.CODEX_TURN_STALL_TIMEOUT_MS = previousTurnStallTimeout; + } + if (previousToolStallTimeout === undefined) { + delete process.env.CODEX_TOOL_STALL_TIMEOUT_MS; + } else { + process.env.CODEX_TOOL_STALL_TIMEOUT_MS = previousToolStallTimeout; + } + }); + + let blockTimer = null; + t.after(() => clearTimeout(blockTimer)); + + const result = await runAppServerTurn(repo, { + prompt: "think without tools", + sandbox: "read-only", + onProgress: (update) => { + const message = typeof update === "string" ? update : update?.message; + if (!blockTimer && message?.startsWith("Turn started")) { + blockTimer = setTimeout(() => { + const blockUntil = Date.now() + 1500; + while (Date.now() < blockUntil) { + // Deliberately starve the event loop past the watchdog deadline. + } + }, 50); + } + } + }); + + const failureMessage = result.error?.message ?? ""; + assert.notEqual(result.status, 0); + assert.match(failureMessage, /Codex turn stalled \(idle\)/); + const measured = failureMessage.match(/measured (\d+)(ms|s)/); + assert.ok(measured, failureMessage); + const measuredMs = Number(measured[1]) * (measured[2] === "s" ? 1000 : 1); + assert.ok(measuredMs > stallTimeoutMs * 2, failureMessage); + assert.match(failureMessage, /since the last of \d+ activity events at \d{4}-\d{2}-\d{2}T[^ ]+Z/); + assert.match(failureMessage, /timer fired (\d+)(ms|s) late/); +}); + test("review rejects focus text because it is native-review only", () => { const repo = makeTempDir(); const binDir = makeTempDir(); From b92e62d155f321d14a005a7971048e3fe28b8225 Mon Sep 17 00:00:00 2001 From: Patrick Yang <266918795+patriyang@users.noreply.github.com> Date: Fri, 7 Aug 2026 01:27:47 -0400 Subject: [PATCH 2/2] Record why the stall timings use the wall clock The deep review weighed switching these measurements to a monotonic clock. Doing so would defeat the purpose: setTimeout already runs on loop time, so a monotonic measurement agrees with the budget by construction and reports nothing. The divergence between the two clocks is the signal. Co-Authored-By: Claude Opus 5 (1M context) --- plugins/codex/scripts/lib/codex.mjs | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/plugins/codex/scripts/lib/codex.mjs b/plugins/codex/scripts/lib/codex.mjs index e2c333efb..b4c30624a 100644 --- a/plugins/codex/scripts/lib/codex.mjs +++ b/plugins/codex/scripts/lib/codex.mjs @@ -665,6 +665,10 @@ function formatStallDuration(ms) { return `${Math.round(ms / 1000)}s`; } +// Timings below are deliberately wall-clock (`Date.now`), not monotonic. `setTimeout` runs on loop +// time, which stops while the machine sleeps, so a monotonic measurement would always agree with the +// budget and hide the very overshoot this reports. The gap between the two clocks is the diagnostic: +// wall-clock elapsed far above the budget means the timer lost time it could not observe. async function handleStall(state, client, stallTimeoutMs, stallMode, itemLabel = null, armedAt = null) { if (state.completed) { return;