Report measured elapsed time when the turn-stall watchdog fires

.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"
       },

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.",

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"

plugins/codex/scripts/lib/codex.mjs

@@ -26,9 +26,11 @@
  *   activeSubagentTurns: Set<string>,
  *   completionTimer: ReturnType<typeof setTimeout> | null,
  *   activityTimer: ReturnType<typeof setTimeout> | null,
+ *   lastActivityAt: number | null,
+ *   activityCount: number,
  *   stallCleanup: Promise<void> | null,
  *   stalled: boolean,
- *   activeTools: Map<string, { threadId: string | null, itemId: string | null, toolClass: string, label: string, deadlineTimer: ReturnType<typeof setTimeout> | null }>,
+ *   activeTools: Map<string, { threadId: string | null, itemId: string | null, toolClass: string, label: string, deadlineTimer: ReturnType<typeof setTimeout> | 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,73 @@ 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`;
+}
+
+// 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;
   }
 
   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 +746,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 +757,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?.();
   }

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();