Skip to content

Report measured elapsed time when the turn-stall watchdog fires - #91

Merged
patriyang merged 2 commits into
mainfrom
fix/90-stall-watchdog-instrumentation
Aug 7, 2026
Merged

Report measured elapsed time when the turn-stall watchdog fires#91
patriyang merged 2 commits into
mainfrom
fix/90-stall-watchdog-instrumentation

Conversation

@patriyang

Copy link
Copy Markdown
Owner

Problem

handleStall built its message from the configured budget and nothing else — no activity for 900s came straight from Math.round(stallTimeoutMs / 1000). It never measured how much time had actually passed since the last rearm, so the log asserted an elapsed it had not observed.

That is what made #90 unresolvable. Two concurrent turns logged their 900s idle stall roughly 21 minutes after their last recorded activity, both within a second of each other, and the logs could not distinguish:

  1. unlogged notifications silently rearming the timer (watchdog correct, observability lacking), from
  2. the timers genuinely oversleeping (system sleep, macOS App Nap, event-loop starvation).

Reproduced first

In-process, with a 1000ms budget and the event loop blocked 1500ms past the armed deadline:

[+454ms] Turn started (turn_1).
[+3003ms] Codex turn stalled (idle): no activity for 1s. Interrupting and aborting the turn.

The timer was armed at ~+454ms and fired 2549ms after the last activity — a 155% overshoot — and the message still reported the budget.

Change

Record the wall-clock instant and running count of every rearm, plus the instant each timer was armed, and append them to the existing 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.

Applied to the incident in #90, that separates the two cases directly: a last activity at later than the final job-log entry means silent rearms; one that matches the log alongside a large "fired late" means the timer was delayed. ISO-8601 so it diffs against job-log and rollout timestamps without conversion.

The same harness after the change:

[+3049ms] Codex turn stalled (idle): no activity for 1s [budget 1s; measured 3s since the
last of 3 activity events at 2026-08-07T04:57:35.860Z; timer fired 2s late].
Interrupting and aborting the turn.

The tool-max deadline gets the same treatment via a per-tool armedAt, since it arms once at tool start and is never rearmed.

Scope

Observability only — same budgets, same interrupt path, same completeTurn call. Deliberately not switching the watchdog to a polling or wall-clock-checked rearm loop: whether the timer needs to survive system sleep is precisely the question this instrumentation exists to answer, and #90 asks to instrument rather than guess.

The leading clause is byte-identical to before, so the existing assertions on Codex turn stalled (<mode>) and the tests/render.test.mjs fixture string stay stable.

Testing

  • New in-process regression test starves the event loop past the armed deadline and asserts the reported measurement. Red-green verified: against baseline codex.mjs it fails in 2.1s with AssertionError: Codex turn stalled (idle): no activity for 0s.; it passes with the change.
  • Full suite: 304 passed, 0 failed.

Plugin version bumped 1.0.37 → 1.0.38 for the version guard.

Closes #90

🤖 Generated with Claude Code

patriyang and others added 2 commits August 7, 2026 01:22
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) <noreply@anthropic.com>
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) <noreply@anthropic.com>
@patriyang
patriyang merged commit 5d67be7 into main Aug 7, 2026
3 checks passed
@patriyang
patriyang deleted the fix/90-stall-watchdog-instrumentation branch August 7, 2026 05:40
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Idle turn-stall watchdog fired ~6 minutes late on two concurrent turns

1 participant