fix(cli): stop the live token counter from silently freezing mid-run - #971
Conversation
…alue
A fresh-user dogfood on 0.6.7 (skillsbench edit-pdf, prime-agent,
deepseek-v4-flash, Daytona) watched the footer climb to 56.8k tokens and
then hold that exact figure for 20m39s of a 26.5-minute run whose final
trusted total was 1,697,038 — 3.3% of the truth, rendered as if it were
current, while the same row's tool-call counter climbed 26 -> 53. Users
read that number to decide whether to kill a run, so a frozen-but-plausible
value is worse than no value.
The gateway tail read 24KB per `dd bs=1 skip=<offset>` per transient exec.
Two syscalls per byte transferred, one full Daytona round trip (create
session, run, poll on a 1s interval, fetch logs, delete) per 24KB window,
under a 10s per-read deadline. That ceiling sits at the same order as the
rate a full-message DeepSeek log grows at — and, decisively, a single failed
read cost the whole poll with the offset unmoved: `timeout` killing the
command (rc 124) and the poll deadline raising both landed on "return
nothing", which the caller could not distinguish from a drained log. Silent,
permanent, debug-level.
Read shape: byte-ranged `dd iflag=skip_bytes,count_bytes,fullblock bs=64K`,
512KB per read over 8 reads/tick (was 24KB over 64), and the command now
emits `<size>\n<base64>` so one round trip carries both the payload and the
log's size. Userland floor is unchanged in kind — `base64 -w 0` on the same
line already requires GNU coreutils; skip_bytes/count_bytes need 8.11+.
Falling behind is now a fact, not a silence. The size lets an empty read be
classified as drained (offset == EOF) or as a lag, raising reads are caught
at the read site so they still reach the lag accounting, every behind poll
logs the byte lag at debug, and a tail that stops advancing altogether
raises one latched WARNING. The counter itself is left alone: it is a
cumulative lower bound at all times, and blanking it would just hand the
cell to the equally lagging ACP signal.
Also fixes the phase label running backwards at the end of a run
("verifying…" at 24:04, then "running agent…" at 24:49/25:35/26:20).
cleanup() calls disconnect(), whose unguarded rewind to "installed"
relabelled the whole teardown stretch and transiently blanked
Rollout.result, which is gated on the same terminal phases; and "executed"
mapped to "verifying…" even though verify() has marked its own entry since
PR #957, so the only stretch rendering under it is the inside of
disconnect(). The between-scenes rewind is preserved.
GitHub Actions
Inactive
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 7ea2be2cd1
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| logger.warning( | ||
| "Live token counter has stalled: the model-gateway log tail " | ||
| "has not advanced past byte %d in %d polls (%s bytes behind). " | ||
| "The live token/cost figures now UNDERCOUNT this run; the " | ||
| "final totals, imported from the full log, are unaffected.", |
There was a problem hiding this comment.
In the TTY CLI path, main.py wraps the evaluation in live_session, whose quiet_root_logging replaces the root handlers with _WarningBuffer and replays warnings only after Evaluation.run() exits. Consequently, when callback reads fail and this warning fires, the user continues seeing the frozen token figure for the remainder of the run and receives the warning only after it is too late to use it to decide whether to stop the run; expose the stalled state in the dashboard or route this warning through a live-safe output path.
Useful? React with 👍 / 👎.
| assert rollout._phase == "verifying" | ||
|
|
||
|
|
||
| def test_phase_labels_never_walk_backwards_through_a_run(): |
There was a problem hiding this comment.
This regression test and the following disconnect regression test describe previously shipped failures only in comments and have no docstrings identifying the PR or commit they guard. Add durable provenance in each test's docstring as required by the repository convention.
AGENTS.md reference: AGENTS.md:L16-L17
Useful? React with 👍 / 👎.
1 participant
A fresh-user dogfood of the released 0.6.7 (skillsbench edit-pdf, prime-agent, deepseek-v4-flash, Daytona, 26.5 min) measured the footer climbing normally —
4.5k → 9.5k → … → 56.8k tokens— and then freezing at 56.8k for 20 min 39 s while the same row's tool-call counter kept climbing 26 → 53. The true total was 1,697,038 tokens: the displayed figure was 3.3% of truth, and it looked authoritative. That contradictsdocs/reference/cli.md's promise that spend is visible mid-run, and it's the number users watch to decide whether to kill a run.Mechanism — three causes, and the stated hypothesis was only partly right
The suspected cause was the per-tick byte budget. On the evidence that predicts a lagging counter, not a zero-progress one: at 24 KB per round trip the reader could have moved 12–29 MB during the freeze against a ~6–7 MB log. It moved 0 bytes.
The hard flatline came from the read path:
_read_callback_chunkreturned barebytes, sob""meant both "drained" and "the read failed" — the callerbreaks either way with the offset unmoved, so a failing read repeats identically every tick, forever, logged only at debug. Both failure shapes are reachable (timeout 10 bash -c→ rc 124 →b"";_poll_responseraising on the same deadline → swallowed by a blanketexcept).dd bs=1made tripping that 10 s deadline plausible: 24,576 read + 24,576 write syscalls per window (measured ~27 ms/24 KB vs ~6 ms seeked).Fix
_CallbackChunk(data, size); a failed read is no longer indistinguishable from EOF.stat -c %s F; dd iflag=skip_bytes,count_bytes,fullblock bs=64K skip=<off> count=<limit> | base64 -w 0, one command per read viaexec_transient. Budget 512 KB × 8 reads/tick (was 24 KB × 64) — ~20× per round trip with 8× fewer round trips; timeout 10 s → 20 s.verifying…→running agent…at 24:49+):cleanup()→disconnect()unconditionally reset_phaseto"installed"after verify had reached"verified"; terminal phases are now sticky, and"executed"maps torunning agent…(the only window rendering under it is insidedisconnect()).Verification
The author flagged one honest gap — the new command had never run against real GNU coreutils. I closed it against a live Daytona sandbox: coreutils 9.7; a 500 KB ranged read from a mid-file offset returned rc 0 with a byte-exact slice (sha256 verified); a past-EOF read returned rc 0 with an empty payload — the drained signal, not an error.
Unit side: the regression drives a log growing at ~2× the per-tick budget and requires the counter to advance every tick and converge on the true total (102 round trips against a 121 bound); both failure shapes are covered; each fix was mutation-checked (invert drained/failed → 2 fail; drop the phase guard → 1 fails; restore the
"executed"label → 1 fails).Still not done: a full end-to-end Daytona re-measurement of the dogfood scenario. The wire behavior of the new command is now confirmed, but the 26-minute run was not repeated.
Gates: ruff format/check, ty clean; target files 82 passed;
-k cli400;-k "evaluation or eval_run or rollout"312;-k "session or acp"353; full suite 5398 passed (only the three known host-specific failures).