From 308ba575d2b32d13d12cd41761c6022b8f9a1633 Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 19:17:12 -0700 Subject: [PATCH 01/17] fix(escalation,adapters): pause a no-work dev session ahead of the budget; journal transcript idle stretches (#727, #680) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A dev CLI parked on a permission dialog, a login or a dead-on-arrival window ended stalled/crashed/timeout and `decide_dev` RETRYed into the identical wall until `max_dev_attempts` was spent. The tmux adapter now stamps `SessionResult.produced_work` (appended, default True) on every non-completed exit: True on a Stop, on a missing pane log, or on pane growth observed on a tick later than FIRST_FRAME_S (30 s) after the wait loop started and before the first stall wake nudge; False otherwise. `decide_dev` PAUSEs a False result after the env-fault arm and ahead of the budget (`no_work_pause_reason`), so re-arm restores the attempt. The flag rides `dev-decision` and, when False, every role's `session-end`. The #261 byte floor is deliberately not the predicate: the #727 capture is a 1,930-byte dialog rendered once, which clears it. Separately, the adapter stats the live transcript's (mtime_ns, size) on the heartbeat cadence, stamps `transcript_idle_s` on heartbeat.json, and — through the run journal the engine now attaches to every adapter it owns (`CodingCLIAdapter.journal`, including a sweep's distinct triage adapter) — writes one `session-idle` / `session-active` pair per stretch when the age crosses `dev_stall_grace_s`; 0 disables the pair. The TUI agent line shows the open stretch as `· idle `. Observability only: nothing bounds the stretch. `stall_deadline`, `last_activity`, the pane-growth re-arm, the nudge budget, `_log_activity_key`, `_produced_work` and PROOF_OF_WORK_MIN_LOG_BYTES are untouched; the pre-change stall suite passes unmodified. Related to #727 and #680. --- CHANGELOG.md | 18 + README.md | 2 +- docs/FEATURES.md | 4 +- docs/tui-guide.md | 6 +- src/bmad_loop/adapters/base.py | 31 +- src/bmad_loop/adapters/generic.py | 205 +++++++++- src/bmad_loop/data/settings/core.toml | 2 +- src/bmad_loop/engine.py | 19 + src/bmad_loop/escalation.py | 33 ++ src/bmad_loop/policy.py | 9 +- src/bmad_loop/sweep.py | 4 + src/bmad_loop/tui/data.py | 54 ++- src/bmad_loop/tui/widgets.py | 22 ++ tests/test_engine.py | 53 +++ tests/test_escalation.py | 70 ++++ tests/test_generic_tmux.py | 522 +++++++++++++++++++++++++- tests/test_portability_guard.py | 24 ++ tests/test_stories_e2e.py | 47 ++- tests/test_sweep.py | 14 + tests/test_tui_app.py | 46 +++ tests/test_tui_data.py | 70 ++++ 21 files changed, 1236 insertions(+), 19 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0785b006b..1367ecd20 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,24 @@ breaking changes may land in a minor release. ## [Unreleased] +### Added + +- Journal a session's idle stretches (#680). The tmux adapter stats the live transcript + on the heartbeat cadence, stamps `transcript_idle_s` on `heartbeat.json`, and — with + the engine's journal attached (`CodingCLIAdapter.journal`) — writes one `session-idle` + when the age crosses `limits.dev_stall_grace_s` and one `session-active` when the + transcript moves again; `0` disables the pair. The TUI agent line shows the open + stretch as `· idle `. Observability only: nothing bounds the stretch. + +### Fixed + +- Pause a dev session that produced no work instead of retrying into the same wall + (#727). `SessionResult.produced_work` is `false` when no turn ended and the pane + never changed after its first frame before any wake nudge (a permission dialog, a + login, a dead-on-arrival window); `decide_dev` pauses ahead of the budget as an + environment fault does, `dev-decision` and `session-end` carry the flag, and re-arm + resets the attempt. + ## [0.12.0] — 2026-09-20 ### Added diff --git a/README.md b/README.md index 31d673194..09c3ed96b 100644 --- a/README.md +++ b/README.md @@ -423,7 +423,7 @@ session_timeout_min = 90 git_timeout_s = 120 # bound on any single git subprocess; exceeding it pauses/degrades, never crashes the run teardown_grace_s = 20 # verified session teardown: poll a killed session up to this long, then force-kill its pane pids and re-kill; 0 = one best-effort kill stop_without_result_nudges = 1 # times to re-prompt a session that stopped with no result.json -dev_stall_grace_s = 600 # silence grace armed at dev/review launch; transport activity or fresh Stop/idle evidence re-arms it; 0 = no launch timer, but a result-less turn end still fails fast +dev_stall_grace_s = 600 # silence grace armed at dev/review launch; transport activity or fresh Stop/idle evidence re-arms it; 0 = no launch timer, but a result-less turn end still fails fast. Also the transcript-idle notice threshold (journal session-idle/session-active, TUI `idle `); 0 disables the notice dev_stall_nudges = 2 # best-effort wake nudges per silent grace; fresh Stop/idle evidence restores this budget; 0 = stall on grace expiry dev_stall_nudges_cap = 6 # total never-restored nudge bound per dev/review session; an accepted nudge does not guarantee a wake; 0 = stall on first grace expiry workflow_stall_nudges_cap = 3 # same monotonic cap for an injected plugin-workflow session that finished but never wrote its completion marker diff --git a/docs/FEATURES.md b/docs/FEATURES.md index 5d83c30a0..7648625c2 100644 --- a/docs/FEATURES.md +++ b/docs/FEATURES.md @@ -74,6 +74,8 @@ See [README.md](../README.md) for the narrative overview and [setup-guide.md](se - Typed escalations: `CRITICAL` pauses the run + notifies (desktop + `ATTENTION` file); `PREFERENCE` is journaled and continues. A story's escalation trail is append-only and deliberately survives a re-arm (it is the run-dir audit a later resolve cycle reads), so a second `bmad-loop resolve` used to re-present every CRITICAL the story ever raised, interleaved with the new ones and with nothing marking which was which — against a resolve skill whose contract is singular. An interactive resolve session that records a `resolution.json` now **watermarks** the trail at its current length, and every later cycle hands the agent only the escalations recorded since; how many earlier ones were withheld is printed to your terminal, never added to the agent's `context.json`. When that filtered list contains entries, the resolve skill presents them newest-first under the existing globally de-duplicated contract. When a new pause precedes any newer recorded escalation and the filtered list is empty, the skill presents `paused_reason` as the available current-pause evidence and discloses that no newer recorded detail exists; it does not read below the watermark, recover an older artifact entry, or synthesize an escalation object. The watermark moves only on a gesture that actually accepted a resolution — a resolve session that exited without writing one, `resolve --no-interactive`, and the TUI's Re-arm button all leave it where it stands. Leaving a watermark is not clearing it: a watermark already standing still filters on those paths, which show everything recorded since the last accepted resolution rather than the whole trail. That is where the bias is deliberate, and it is a claim about which GESTURES move the watermark: one that accepted nothing never moves it. Within a cycle that DID accept a resolution the watermark covers everything that cycle PRESENTED — it is stamped at the trail's length, not at the entries individually answered — so answering one of five escalations shown together retires all five. A task's watermark is reported as the `esc-upto` column of `bmad-loop diagnose`'s markdown task table, and as `escalations_resolved_upto` under `--json` (that is the key to grep in a support bundle), which is what explains a short or empty `context.json` escalation list on a bug report. - A rejected dev attempt notifies too, with its reason (#640). RETRY was the only dev outcome that rejected an attempt silently, and it is the one that discards a completed implementation — the non-fixable leg resets the tree to baseline. The notice fires once per rejected attempt in an uninterrupted run (so ordinarily at most `max_dev_attempts` per story) and has no suppression knob of its own; it follows `[notify]` like every other notice. One attempt can raise it twice: the notice precedes the rollback, so a host that dies in between replays that verdict on resume and announces it again — treat the count as a floor on attempts rejected, not an exact tally. The reason is reduced to its first line and capped, with a `[…]` marker when it was trimmed, because a `Decision.reason` routinely carries a verify-output tail that would otherwise spill into `ATTENTION` and a desktop bubble; the untruncated reason stays in the `dev-decision` journal entry. It fires above the fixable/non-fixable split, so on a leg that goes on to pause for manual recovery the operator sees both notices. - Environment faults pause without burning budget (#194): a session whose coding CLI never reached the API — a verify command whose _environment_ is broken (`sh` reports rc `126`/`127`; on Windows a missing tool is caught by its `is not recognized` message or by resolving the command's leading token, and a command naming a file `cmd` cannot execute — a `.sh`, or any extension outside `PATHEXT`, which cmd hands to the file association and which exits `0` without running anything — is a fault rather than a silent rc `0` pass, #302; and on either OS a verify command whose child could not be started at all — most often because the directory it was to run in is missing, is a file, or cannot be searched, but any spawn-time `OSError` counts — is translated into the same fault instead of crashing the run, since no exit code exists to classify) **or** a session whose log matches the profile's `env_fault_patterns` (an `API Error … Connection refused`-class transport failure, or a provider quota/usage-limit refusal, that idled out the session clock) — pauses the run with the matched evidence instead of charging the attempt and deferring the story as if its code were broken. Re-arm restores the budget. Patterns are per-profile: `claude` seeds three, reproducing only complete error sentences its CLI was captured printing (connection loss, and the two captured provider 5xx refusals — statuses enumerated, never ranged, so an uncaptured `503` stays prose), so a story that merely writes _about_ a provider error cannot trip them (#507); `opencode` seeds a provider quota/rate-limit and connection pair (#323), matched against the `opencode serve` process's own stdout, which the model cannot write to; the other four profiles ship none. Each adapter matches them against the log named by its `ENV_FAULT_LOG_SUFFIX` — the tmux pane capture `logs/.log`, or `.server.out` (the `opencode serve` process's own stdout) for `opencode-http`, never that adapter's model-written transcript. A pattern is only sound against a log the model cannot write to; where that does not hold — the pane capture — the pattern has to reproduce a whole captured sentence, because an error token plus a cause on the same line is precisely the shape a story writing about the error emits, and that framing is what the guard now refuses (#507). A usage-limit / quota cause stays unseeded on the pane-capture profiles for the same evidentiary reason: no captured line exists for them (#323). Extend or disable them in a project profile overlay. +- A session that never did anything pauses instead of retrying (#727). A dev CLI parked on a permission dialog, a login, or a dead-on-arrival window ends `stalled`/`crashed`/`timeout`, and all three used to RETRY while budget lasted — a fresh session into the identical wall, `max_dev_attempts` burned without a line of work. The tmux adapter now stamps `produced_work` on every non-completed result: `true` when a `Stop` arrived (a turn ended), when there is no pane log to read (opencode-http, "unknown never blocks"), or when the pane log changed on a tick more than 30 s (`FIRST_FRAME_S`) after the wait loop started and before the first stall wake nudge went out; `false` otherwise. The first frame is excluded because a parked CLI paints exactly once — the #727 capture is a 1,930-byte dialog, which clears the #261 read-back gate's 256-byte floor, so that floor is deliberately not the predicate — and post-nudge growth is excluded because the nudge's `Enter` confirms the dialog's default and the pane grows with the echo and exit text, the loop's own keystrokes. `decide_dev` PAUSEs a `produced_work=false` result ahead of the budget, exactly as an environment fault does (`no work produced: dev session (no turn ended and the pane never changed after its first frame — the CLI is likely waiting on a human: a permission prompt, a login, a confirmation; the attempt is not charged)`), the env-fault arm outranks it, the `#489` lost-session suffix survives inside it, and re-arm resets `attempt` to `0`. The flag rides `dev-decision` beside `session_vanished` and, when `false`, every role's `session-end`. Two deliberate costs, both toward today's behavior: a CLI slower than 30 s to paint at all retries as before, and a session that woke only after a nudge and then never ended a turn pauses for the operator instead of retrying. The review, fix and sweep deciders are unchanged, and `stall_deadline`, its pane-growth re-arm and the nudge budget are untouched. +- An idle session is visible while it sits (#680). A session idling inside a tool call (`sleep 590; cat …`) keeps its pane log growing through spinner repaints, so the stall re-arm — correctly — never fires and nothing separated it from a working session but `session_timeout_min`. The adapter now stats the live transcript's `(mtime_ns, size)` on the heartbeat cadence from the first hook event that names it (a stat, never parsed usage, so it works for `usage_parser = "none"`), stamps the age on `heartbeat.json` as `transcript_idle_s` (`null` before a transcript is known), and — when the run's journal is attached, which the engine does for every adapter it owns — journals one `session-idle` (`task_id`, `idle_s`, `since_ts`, `threshold_s`) when the age crosses `limits.dev_stall_grace_s` and one `session-active` (`task_id`, `idle_s`) when the transcript moves again; a later stretch emits a fresh pair. The threshold is the stall grace on purpose — the event fires exactly when the session _would_ have stalled had its pane not kept repainting, so the two records are directly comparable — and `0` disables the events with no new knob. The TUI's agent line shows the open stretch as `· idle `. Observability only: nothing bounds the stretch, and the session is neither nudged, stalled nor killed for it. - A session the multiplexer lost says so (#489). Sessions complete on a hook `Stop` or on window death, and a window is gone whether the CLI exited or something destroyed the whole mux session out from under the run — an external reaper, a concurrent prune or `bmad-loop stop`, an operator `kill-session`, a server crash, the host sleeping. Both are `crashed`, so the retry/defer reason an operator reads said only `dev session crashed` — pointing at the agent when the host was at fault. The crash verdict now asks whether the _session_ still exists and, when it does not, says so in the reason (`… session crashed: the multiplexer no longer reports the session, so the window's disappearance is not evidence the CLI exited`), as `session_vanished` on `dev-decision` and `fix-decision` either way, beside the routing each fed, on every role's `session-end` journal entry when it is true (the convention `env_fault` already uses there), and as a `session-vanished` breadcrumb in `session-lifecycle.jsonl`. The repair path carries it the same way: when fix attempts are exhausted the defer names the lost session instead of blaming the tree for repairs that never ran. The wording states what the evidence _withdraws_, not what it proves: `has_session` maps every nonzero backend result to False, so a negative lookup is "the backend did not confirm it" rather than proof the session is gone — enough to stop an operator reading window death as a CLI exit, not enough to name a destroyer. It composes with an environment-fault pause instead of being swallowed by it. A session reaped _after_ flushing its result still scores `completed` and is not diagnosed — it produced something. Diagnosis only — the routing is unchanged, and a retry re-creates the session. - CRITICAL resolution: `bmad-loop resolve ` opens an interactive resolve agent seeded with the escalation + frozen spec; you disambiguate, it re-arms the story (`escalated → pending`, spec reset to `ready-for-dev`) and resumes. `--no-interactive` skips to re-arm if you fixed the spec yourself. The re-arm advances the story's baseline in the **code tree** and is honest when it cannot: a failed advance is narrowed to typed git @@ -239,7 +241,7 @@ Result` section. Every other spec keeps warn-and-continue, and the record says w - Every run is a resumable on-disk state machine: `bmad-loop resume ` continues from a gate, escalation, or interruption. - A graceful stop (`stop --graceful` / TUI `S`) is resumable too: unlike a hard stop killed mid-item, it lets the in-flight item finish through commit and finalizes cleanly, ending as a `stopped` run that `resume` picks up at the next item. - Every `state.json` publication is serialized by one advisory lock per run, keyed on the resolved run directory plus the logical `state.json` name and stored under the user state root rather than in git. Ignoring a final-component `state.json` symlink keeps that identity stable when atomic publication replaces the directory entry; alternate spellings of the run directory still converge. Multi-step control mutations (`resolve`, `resume`, code-root restamping, and stop's external fallback) hold that same lock from their authoritative read through atomic publication, so a waiter reloads the state its predecessor left instead of overwriting it from a stale snapshot. A fresh run or sweep likewise holds it from its initial state save through trusted-digest and PID publication, preventing an explicit-id resume from observing resumable state before the composer is live. Readers remain lock-free because publication is atomic. Stop does not hold the lock while it requests, signals, polls, or kills: a live engine must be able to publish its own stopped state; only the fallback's final reload/check/write is serialized. That final check preserves an engine that finished during delivery and retries against any newer live engine generation a concurrent resume published. POSIX lock acquisition blocks, while Windows can surface an `OSError` after its bounded wait; either failure aborts the mutation rather than writing unlocked. Two callers acquire without waiting instead: `clean`, sweeping many runs, and the TUI's re-arm, which runs on the dashboard's message loop where a blocking POSIX acquisition would freeze the whole UI for as long as the holder kept the lock. Both report the contended run rather than queueing behind it. -- All run state in `.bmad-loop/runs//` (gitignored): `state.json` (which records `repo_root`, the git root code work happens in, so an out-of-process re-arm reads back the tree the run measured, #716 — resume re-stamps it from the config.yaml it just re-read, since that is the tree it arms the engine against, and warns when the root moved: the baselines, preserve refs and branches already recorded name objects in the previous one. `resolve` and the TUI's re-arm re-stamp it themselves, before they re-arm: both re-arm and then resume in one gesture, so resume's own re-stamp lands after the re-arm has already advanced the baseline in whichever tree the mirror still named); `journal.jsonl` (every decision, including the `session-synthesized-from-frontmatter` catch and its `spec-marker-repaired` repair, #276, plus one `verify-command-result` per verifier command — emitted on the dev, repair and review legs alike, carrying `verification_stage` and a per-story `verification_sequence` that orders the passes across all three; the two passes that leave no record are `bmad-loop confirm --reverify`, which runs after the run is over, and any pass with no `[verify] commands` configured, which records nothing because nothing ran — each entry also carrying `spawn_error`, set when the verify command's child could not be started at all — typically because its working directory is missing, is not a directory, or cannot be searched, though any spawn-time `OSError` (a missing shell, EMFILE, ENOMEM) reaches the same field and the wrapped exception is what names the cause — which is an environment fault that pauses the run rather than a command that failed — whose stream pointers name the `verify/` directory below, and one `park-proof-of-work-skipped` per attempt that cleared the dev artifact gate on an `awaiting-operator` park with proof-of-work waived — not per park that committed, since the stages after that gate can still reject the attempt — carrying `zero_diff`: `true` when the waived gate found no non-excluded changes (its exclusions include the spec, board, any restore-patch artifact, and an orchestrator-authored deferred-work ledger append), `false` when it found changes, and `null` when the probe could not answer (a git fault, a git refusal such as an unresolvable baseline, or an attempt with no recorded baseline to measure from) and the gate was waived anyway, so the waiver itself is recorded whatever the probe managed to say. `false` is a statement about the tree, not about who wrote what: the gate this stands in for cannot attribute residue to a session in a shared checkout, and the record inherits that limit rather than improving on it), and one `bundle-artifact-only-accepted` per sweep-bundle attempt that cleared the dev artifact gate on the artifact-only receipt (DW-273) — carrying `story_key`, `attempt`, `dw_ids` and `count`, the number of ignored files under `implementation_artifacts` this attempt created or changed against its start-of-attempt snapshot), and one `bundle-artifact-baseline-unavailable` per attempt whose snapshot could not be taken (a git fault; the receipt then refuses for that attempt); `tasks//` (per-session prompt + shared artifacts: [`result.json`, `escalation.json`] — respectively the per-session result and escalation outputs — plus adapter-specific breadcrumbs: `session-lifecycle.jsonl` records timeout fires, budget-guard trips (`budget-tripped` / `over-budget-fired`), transport-failure classification (`env-fault-classified`, #194), a mux session lost under the run (`session-vanished`, #489) and the #276 forensics (`spec-status-transition-observed`, `frontmatter-unmodified-refused`, `contract-nudge-sent`); `heartbeat.json` is the wait loop's proof-of-life; `resultless-stops.jsonl` records give-up Stops with a verdict — `no-artifact`, `ambiguous-frontmatter`, `unmodified-since-launch`, `terminal-frontmatter-pending`); `logs/`; `verify/` (verifier command stdout/stderr, one file per stream, pointed at by the journal's `verify-command-result` records — its own store, because every name in `logs/` is a session task id the TUI resolves as a pane log; each stream is retained tail-first up to `[verify] stream_capture_kb` (256 KiB, `0` = keep nothing) and the record carries the full byte count, a truncation flag, and a `capture_error` when the write itself failed); `deferred/`; `resolve/`; `ATTENTION`; `ctl-window` (the control-session window id the last TUI launch minted, so attach/stop follow the live window, #482). +- All run state in `.bmad-loop/runs//` (gitignored): `state.json` (which records `repo_root`, the git root code work happens in, so an out-of-process re-arm reads back the tree the run measured, #716 — resume re-stamps it from the config.yaml it just re-read, since that is the tree it arms the engine against, and warns when the root moved: the baselines, preserve refs and branches already recorded name objects in the previous one. `resolve` and the TUI's re-arm re-stamp it themselves, before they re-arm: both re-arm and then resume in one gesture, so resume's own re-stamp lands after the re-arm has already advanced the baseline in whichever tree the mirror still named); `journal.jsonl` (every decision, including the `session-synthesized-from-frontmatter` catch and its `spec-marker-repaired` repair, #276, plus one `verify-command-result` per verifier command — emitted on the dev, repair and review legs alike, carrying `verification_stage` and a per-story `verification_sequence` that orders the passes across all three; the two passes that leave no record are `bmad-loop confirm --reverify`, which runs after the run is over, and any pass with no `[verify] commands` configured, which records nothing because nothing ran — each entry also carrying `spawn_error`, set when the verify command's child could not be started at all — typically because its working directory is missing, is not a directory, or cannot be searched, though any spawn-time `OSError` (a missing shell, EMFILE, ENOMEM) reaches the same field and the wrapped exception is what names the cause — which is an environment fault that pauses the run rather than a command that failed — whose stream pointers name the `verify/` directory below, and one `park-proof-of-work-skipped` per attempt that cleared the dev artifact gate on an `awaiting-operator` park with proof-of-work waived — not per park that committed, since the stages after that gate can still reject the attempt — carrying `zero_diff`: `true` when the waived gate found no non-excluded changes (its exclusions include the spec, board, any restore-patch artifact, and an orchestrator-authored deferred-work ledger append), `false` when it found changes, and `null` when the probe could not answer (a git fault, a git refusal such as an unresolvable baseline, or an attempt with no recorded baseline to measure from) and the gate was waived anyway, so the waiver itself is recorded whatever the probe managed to say. `false` is a statement about the tree, not about who wrote what: the gate this stands in for cannot attribute residue to a session in a shared checkout, and the record inherits that limit rather than improving on it), and one `bundle-artifact-only-accepted` per sweep-bundle attempt that cleared the dev artifact gate on the artifact-only receipt (DW-273) — carrying `story_key`, `attempt`, `dw_ids` and `count`, the number of ignored files under `implementation_artifacts` this attempt created or changed against its start-of-attempt snapshot), and one `bundle-artifact-baseline-unavailable` per attempt whose snapshot could not be taken (a git fault; the receipt then refuses for that attempt); `tasks//` (per-session prompt + shared artifacts: [`result.json`, `escalation.json`] — respectively the per-session result and escalation outputs — plus adapter-specific breadcrumbs: `session-lifecycle.jsonl` records timeout fires, budget-guard trips (`budget-tripped` / `over-budget-fired`), transport-failure classification (`env-fault-classified`, #194), a mux session lost under the run (`session-vanished`, #489) and the #276 forensics (`spec-status-transition-observed`, `frontmatter-unmodified-refused`, `contract-nudge-sent`); `heartbeat.json` is the wait loop's proof-of-life, carrying `transcript_idle_s` — seconds since the live transcript last changed, `null` until a hook event names it (#680); `resultless-stops.jsonl` records give-up Stops with a verdict — `no-artifact`, `ambiguous-frontmatter`, `unmodified-since-launch`, `terminal-frontmatter-pending`); `logs/`; `verify/` (verifier command stdout/stderr, one file per stream, pointed at by the journal's `verify-command-result` records — its own store, because every name in `logs/` is a session task id the TUI resolves as a pane log; each stream is retained tail-first up to `[verify] stream_capture_kb` (256 KiB, `0` = keep nothing) and the record carries the full byte count, a truncation flag, and a `capture_error` when the write itself failed); `deferred/`; `resolve/`; `ATTENTION`; `ctl-window` (the control-session window id the last TUI launch minted, so attach/stop follow the live window, #482). - One piece deliberately lives **outside** that directory: the hook-event channel (#494) is at `///events/` under the user-scoped state root (`BMAD_LOOP_STATE_DIR`, see the [transport section](#hook-based-transport-no-pane-scraping) below and the README's env-var table), not `/events/`. The orchestrator still polls the legacy in-tree location, so a project whose installed relay predates the move keeps completing its sessions. `delete`, `archive` and `clean` remove the out-of-tree counterpart along with the run dir, and `clean` sweeps counterparts whose run dir is already gone; an **archived** run's tarball therefore no longer contains `events/` — those files are transient completion signals, consumed while the run was live, and everything an archive is read for later is in the run dir. - `journal.jsonl` records `session-end` for every session unconditionally — even a teardown that throws still lands one (status `aborted` when the outcome is unknowable). A timed-out session's entry carries `fired_at` (wall time the deadline was declared), `teardown_s` (wall seconds from that fire to this entry — the teardown gap), and `expired_clock` (`monotonic` / `wall` / `both` — `wall` alone fingerprints a host suspend that froze the monotonic clock). Every entry whose usage was read carries `tokens` (raw) and `tokens_weighted` (cache reads at `limits.cache_read_weight`), keeping per-session spend reconstructible; both are `null` when the usage read failed, and both are absent on an `aborted` end. `tokens_weighted` is the end-of-session total — distinct from a tripped session's `budget_weighted`, the guard's mid-session sample at trip time. diff --git a/docs/tui-guide.md b/docs/tui-guide.md index 6bf18389c..55cb93438 100644 --- a/docs/tui-guide.md +++ b/docs/tui-guide.md @@ -208,7 +208,11 @@ cost-weighted total first (cache reads at `limits.cache_read_weight`), the unweighted one in parentheses. Below the counts, an **agent line** names who is driving: while a session is open it reads `agent · · ` (the resolved adapter for the live stage — `model` omitted when the session ran the -CLI profile's default, `role` is the stage `dev` / `review` / `triage`); when no +CLI profile's default, `role` is the stage `dev` / `review` / `triage`), with a +yellow `· idle ` appended while the session's transcript has sat still past +`limits.dev_stall_grace_s` (#680 — derived from the journal's open +`session-idle`, cleared by its `session-active`; `` is whole minutes, or +`1h05m` above an hour); when no session is open it falls back to the run's configured adapters, rebuilt from the run's policy snapshot — `agents ` when dev and review resolve alike, else `agents dev review `, plus a `triage ` diff --git a/src/bmad_loop/adapters/base.py b/src/bmad_loop/adapters/base.py index f021ff5e1..c9db9df29 100644 --- a/src/bmad_loop/adapters/base.py +++ b/src/bmad_loop/adapters/base.py @@ -18,11 +18,17 @@ from abc import ABC, abstractmethod from dataclasses import dataclass, field from pathlib import Path -from typing import Any +from typing import TYPE_CHECKING, Any from ..model import TokenUsage from ..platform_util import is_link_like, safe_segment +if TYPE_CHECKING: + # `journal.py` imports nothing from `adapters/`, so the runtime import would be + # cycle-free too; TYPE_CHECKING keeps the adapter seam's import graph as thin as + # it was (journal pulls in model + platform_util) for the annotation alone. + from ..journal import Journal + class AdapterTaskDirectoryError(ValueError): """A built-in adapter refused an unsafe or redirected task directory.""" @@ -250,6 +256,21 @@ class SessionResult: # stalled/timeout/over_budget, which this flag can never accompany; add it # there if `crashed` ever joins that rescue set. session_vanished: bool = False + # Whether the session showed ANY sign of working before it ended on a + # non-completed verdict (#727). `True` when a `Stop` arrived, when the adapter + # has no pane log to read (opencode-http, unit fixtures — "unknown never + # blocks"), or when the pane log changed on a tick later than + # `generic.FIRST_FRAME_S` after the wait loop started and before the first + # stall wake nudge was sent. `False` means the CLI painted at most its first + # frame and then sat still until the grace, the nudge and the exit: a + # permission dialog, a login prompt, a dead-on-arrival window. `decide_dev` + # PAUSEs such a session ahead of the attempt budget, the way an environment + # fault does, so re-arm restores the attempt instead of a fresh session being + # launched into the identical wall. Distinct from `stop_seen` (the hook half + # alone) and from `_ResultFileMixin._produced_work` (the #261 read-back gate's + # byte floor, which a rendered dialog clears). Default `True` so every + # positional construction keeps today's routing. APPENDED, never inserted. + produced_work: bool = True class CodingCLIAdapter(ABC): @@ -257,6 +278,14 @@ class CodingCLIAdapter(ABC): injection: str = "" observation: str = "" state: str = "" + # The run's journal, attached by the engine to every adapter it owns so the + # adapter can record what only it can see (the #680 `session-idle` / + # `session-active` pair). None outside an engine — `resolve.run_session`, + # `probe`, unit fixtures — and every adapter-side emit is gated on it: no + # journal, no entry. The wait loop runs on the engine thread while the + # engine's own journal is quiescent, so this adds no second writer, and + # entries keep the engine's `log_task`/`log_pos` stamps. + journal: Journal | None = None @abstractmethod def start_session(self, spec: SessionSpec) -> SessionHandle: ... diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 0f7fcb5e0..ab4334b63 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -6,7 +6,10 @@ presence of the skill-written result.json — the pane log's *contents* never drive the wait loop (only tee'd for human debugging), though its *growth* (mtime/size, never the bytes — see ``_log_activity_key``) is read as a liveness -signal to re-arm the dev-stall grace window. The one exception is post-mortem: +signal to re-arm the dev-stall grace window and, on a separate timeline, as the +#727 no-work verdict (``SessionResult.produced_work`` — see ``_work_verdict``); +the live transcript's growth is likewise stat'ed, never parsed, for the #680 +idle notice (``_sample_transcript_idle``). The one exception is post-mortem: after the verdict and reconcile have settled, a single tail read of the log classifies a transport-failure environment fault (#194, see ``_classify_env_fault``) — it labels the result, it never drives the wait loop. @@ -28,6 +31,7 @@ import shlex import time from collections.abc import Callable +from dataclasses import dataclass from pathlib import Path from typing import TYPE_CHECKING, Protocol, cast @@ -126,9 +130,42 @@ class _SnapVerdict(enum.Enum): REFUSE = "refuse" +@dataclass +class _IdleTracker: + """Per-session state of the #680 transcript idle detector, owned by one + `wait_for_completion` call and advanced by `_sample_transcript_idle` on the + heartbeat cadence. + + `last_key` is the transcript's (mtime_ns, size) as of the last successful + sample; None means no sample yet, and it is the ONLY "have we sampled" + sentinel — the two `last_change_*` clocks read as 0.0 until then and are never + consulted before it is set. `idle_s` is the latest measured age (what + `heartbeat.json` reports), None until the first sample. `open_since` is the + wall time the currently open idle stretch began — the `since_ts` its + `session-idle` carried — or None between stretches: the latch that makes the + pair one-per-stretch.""" + + last_key: tuple[int, int] | None = None + last_change_mono: float = 0.0 + last_change_wall: float = 0.0 + idle_s: float | None = None + open_since: float | None = None + + # min spacing between heartbeat.json overwrites in wait_for_completion; the # heartbeat's staleness is what makes a frozen orchestrator (#157) diagnosable. HEARTBEAT_INTERVAL_S = 30.0 +# Startup-frame window for the #727 no-work verdict: pane-log growth detected on a +# tick later than this many seconds after the wait loop started counts as work; +# growth inside it is the CLI painting its first frame — a banner, a menu, a +# permission dialog — which a parked session does exactly once and a working one +# streams past for minutes. Seconds, because a launch paint lands in seconds, and +# an order of magnitude under the 600 s default `dev_stall_grace_s`, so a working +# session has the whole grace to prove itself past the window. A CLI slower than +# this to paint at all retries as it does today (its first frame reads as work). +# Not a policy knob: the value separates two regimes an order of magnitude apart, +# so its exact position is not load-bearing. +FIRST_FRAME_S = 30.0 EVENT_KINDS = {"SessionStart", "Stop", "SessionEnd"} NUDGE_TEXT = ( "You are running in bmad-loop automation mode. Finish the workflow now: " @@ -291,6 +328,36 @@ def _log_evidence(self, handle: SessionHandle) -> bool | None: tees a pane log.""" return None + def _work_verdict(self, handle: SessionHandle, stop_seen: bool, activity_seen: bool) -> bool: + """`SessionResult.produced_work` for a non-completed exit (#727): did this + session do anything at all before it ended? + + Three ways to answer True, ORed like `_produced_work`'s halves and for the + same reasons: a `Stop` arrived (a turn ended — the hook half, immune to a + misbound pane sink); there is no pane log to read (`_log_evidence` is None — + opencode-http, unit fixtures — and unknown never blocks); or the wait loop + saw the pane log change on a tick later than `FIRST_FRAME_S` after it started + and before any stall wake nudge was sent (`activity_seen`, the timeline half). + + The timeline half is what separates this from `_produced_work`, and why the + #261 gate is reused for its tristate only, not its verdict: that gate's + 256-byte floor was calibrated for wedged windows that logged 0 and 2 bytes, + and a permission dialog rendered once is ~2 KB — it clears the floor, so the + floor alone files a parked CLI as one that worked. The question the operator + asks is "did the pane ever change after its first frame?", and only the loop + that watched it tick by tick can answer. Growth after the first stall wake + nudge is excluded by construction (the caller never flips `activity_seen` + once `stall_nudges_sent` is positive): the nudge's `send-keys … Enter` + confirms a dialog's default and the pane grows with the echo and the exit + text, which is the loop's own keystrokes, not work — a session that + genuinely woke proves it with a `Stop`, the doctrine the nudge-budget refill + already follows. Only `STALL_NUDGE_TEXT` counts as that nudge; the budget + wrap-up nudge (`BUDGET_NUDGE_TEXT`) and the #276 contract nudge do not + close the window, and are out of this verdict's scope.""" + if stop_seen or activity_seen: + return True + return self._log_evidence(handle) is None + def _session_vanished(self) -> bool: """Whether the whole multiplexer session is gone, asked only once a crash verdict has already been reached (#489). Base: False — an adapter @@ -315,6 +382,7 @@ def _final( accept_result: bool = True, budget_weighted: int | None = None, stop_seen: bool = False, + produced_work: bool = True, ) -> SessionResult: """Session is gone or done responding: completed if the result file landed anyway, otherwise the fallback status. ``accept_result=False`` @@ -323,7 +391,11 @@ def _final( ``budget_weighted`` (a tripped session-budget guard's sample) rides every exit so the engine can journal it whatever the verdict. ``stop_seen`` is the proof-of-work hook signal, threaded separately from - ``session_id``/``transcript`` because those are also set by a mere launch.""" + ``session_id``/``transcript`` because those are also set by a mere launch. + ``produced_work`` is the wait loop's `_work_verdict` (#727), stamped on + every NON-completed result; a read-back upgrade to ``completed`` resets it + to True, because the flag is scoped to non-completed exits and a + ``completed`` session-end must not carry a no-work stamp.""" result_json = self._result_json(handle, spec, wait=False) if accept_result else None if ( result_json is not None @@ -376,6 +448,7 @@ def _final( budget_weighted=budget_weighted, stop_seen=stop_seen, session_vanished=vanished, + produced_work=True if status == "completed" else produced_work, ) def _result_path(self, task_id: str) -> Path: @@ -688,8 +761,44 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi budget_weighted: int | None = None budget_deadline: float | None = None budget_wall_deadline: float | None = None + # No-work verdict (#727), the timeline half of `_work_verdict`. `frame_key` + # is the pane log's (mtime_ns, size) as of the last tick, sampled once at + # the top of EVERY tick — a sibling of `last_activity`, never the same + # variable: that one drives the stall re-arm and is re-baselined on Stop + # and nudge, which is exactly the accounting this must not share. It flips + # `activity_seen` when the key changes on a tick later than FIRST_FRAME_S + # after the loop started and before the first stall wake nudge went out; + # growth after a nudge is the loop's own keystrokes echoing (see + # `_work_verdict`). Latched: once seen, the session worked. + loop_started = time.monotonic() + frame_key = self._log_activity_key(handle.task_id) + activity_seen = False + + def produced_work() -> bool: + # Read at call time, so every exit below reports the loop's final view. + return self._work_verdict(handle, stop_seen, activity_seen) + + # Idle detection (#680): the live transcript's (mtime_ns, size), sampled on + # the heartbeat cadence from the first tick that knows `transcript_path` + # — see `_sample_transcript_idle`. Observes only: nothing here nudges, + # stalls or kills (#680 item 2 stays open), and `stall_deadline` is + # neither consulted nor touched. + idle = _IdleTracker() while True: + # Top-of-tick pane-frame sample for the no-work verdict (#727). Before + # the timeout check so growth on the final tick still counts; before the + # nudge arm so a tick that both sees growth and sends a nudge scores the + # growth (the nudge cannot have caused what preceded it). + tick_key = self._log_activity_key(handle.task_id) + if tick_key is not None and tick_key != frame_key: + if ( + not activity_seen + and stall_nudges_sent == 0 + and time.monotonic() - loop_started > FIRST_FRAME_S + ): + activity_seen = True + frame_key = tick_key remaining = deadline - time.monotonic() wall_expired = time.time() >= wall_deadline if remaining <= 0 or wall_expired: @@ -716,6 +825,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi timeout_expired_clock=expired, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) # Hard-stop poll (#319), per-iteration and deliberately NOT inside # the heartbeat throttle below: the loop's own wait is capped at 5s @@ -737,10 +847,16 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path=transcript_path, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) now = time.monotonic() if last_heartbeat is None or now - last_heartbeat >= HEARTBEAT_INTERVAL_S: last_heartbeat = now + # Transcript idle sample (#680), ahead of the heartbeat write so + # the payload carries this tick's age. Inert until a hook event + # has named the transcript. + if transcript_path: + self._sample_transcript_idle(handle.task_id, transcript_path, idle, now) self._write_heartbeat( handle.task_id, { @@ -748,6 +864,9 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi "remaining_s": round(remaining, 3), "stall_armed": stall_deadline is not None, "stall_nudges_sent": stall_nudges_sent, + # seconds since the live transcript last changed (#680); + # null until a hook event has named the transcript. + "transcript_idle_s": idle.idle_s, }, ) # Mid-session spec-status transition sampling (#276 M2) rides the @@ -807,6 +926,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path, budget_weighted=weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) except MultiplexerError: pass @@ -824,6 +944,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path=transcript_path, budget_weighted=weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) try: self.send_text(handle, BUDGET_NUDGE_TEXT) @@ -856,6 +977,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) except MultiplexerError: pass @@ -873,6 +995,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path=transcript_path, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) event = self.watcher.wait_for( handle.task_id, @@ -900,6 +1023,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path=transcript_path, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) if event is None: try: @@ -923,6 +1047,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) if stall_deadline is not None: # No artifact shortcut here: the window is alive on this tick @@ -982,6 +1107,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) except MultiplexerError: pass @@ -997,6 +1123,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi accept_result=False, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) continue if ( @@ -1050,6 +1177,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) # A result-less Stop, but the session may have ended its turn to # await a background process (a Unity PlayMode run, a slow test) @@ -1073,6 +1201,7 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi transcript_path, budget_weighted=budget_weighted, stop_seen=stop_seen, + produced_work=produced_work(), ) def _log_evidence(self, handle: SessionHandle) -> bool | None: @@ -1108,6 +1237,78 @@ def _log_activity_key(self, task_id: str) -> tuple[int, int] | None: return None return (st.st_mtime_ns, st.st_size) + @staticmethod + def _transcript_activity_key(transcript_path: str) -> tuple[int, int] | None: + """Activity signature of the live transcript the hooks named: (mtime_ns, + size), or None when it cannot be stat'ed this tick (not yet created, torn + by a rename, unreadable). The stat-only sibling of `_log_activity_key` for + the #680 idle detector: the transcript is what the CLI appends to when it + is actually doing something — a tool result, a model turn — where the pane + log also grows for a spinner repaint. Deliberately never parsed: + `_sample_weighted_usage` returns None for `usage_parser = "none"`, and idle + detection has to work for that profile too. None is "no sample", never + "idle" — the caller skips the tick.""" + try: + st = Path(transcript_path).stat() + except OSError: + return None + return (st.st_mtime_ns, st.st_size) + + def _sample_transcript_idle( + self, task_id: str, transcript_path: str, idle: _IdleTracker, now: float + ) -> None: + """One heartbeat-cadence sample of the #680 idle detector: advance `idle` + from the transcript's current stat key and journal the stretch boundaries. + + A None key (not yet created, torn by a rename, unreadable) skips the tick + and leaves the stretch as it was — `_sample_weighted_usage`'s tolerance, + for a stat. A key that moved closes any open stretch with one + `session-active` carrying the stretch's full length; a key that has not + moved for `_stall_grace_s` opens one with one `session-idle` (`idle_s`, + `since_ts`, `threshold_s`), latched until the key moves again. The + threshold is the stall grace on purpose: the event fires exactly when the + session WOULD have stalled had its pane not kept repainting, so the two + records are directly comparable, and `0` disables both. No journal + attached (`resolve.run_session`, `probe`, fixtures) means no events; the + age is still measured for `heartbeat.json`. Every write is best-effort — + an unwritable journal must not end a session that is, by this very + evidence, alive.""" + key = self._transcript_activity_key(transcript_path) + if key is None: + return + if key != idle.last_key: + if idle.open_since is not None and self.journal is not None: + try: + self.journal.append( + "session-active", + task_id=task_id, + idle_s=round(now - idle.last_change_mono, 3), + ) + except OSError: + pass + idle.open_since = None + idle.last_key = key + idle.last_change_mono = now + idle.last_change_wall = time.time() + idle.idle_s = round(now - idle.last_change_mono, 3) + if ( + idle.open_since is None + and self.journal is not None + and self._stall_grace_s > 0 + and idle.idle_s >= self._stall_grace_s + ): + idle.open_since = idle.last_change_wall + try: + self.journal.append( + "session-idle", + task_id=task_id, + idle_s=idle.idle_s, + since_ts=idle.open_since, + threshold_s=self._stall_grace_s, + ) + except OSError: + pass + def _window_alive(self, handle: SessionHandle) -> bool: return handle.native_id in self.mux.list_window_ids(self.session_name) diff --git a/src/bmad_loop/data/settings/core.toml b/src/bmad_loop/data/settings/core.toml index c5c356756..b5d44e056 100644 --- a/src/bmad_loop/data/settings/core.toml +++ b/src/bmad_loop/data/settings/core.toml @@ -137,7 +137,7 @@ key = "dev_stall_grace_s" kind = "int" minimum = 0 default_ref = "LimitsPolicy.dev_stall_grace_s" -description = "silence grace for a dev/review session, armed at launch and re-armed by transport activity or fresh Stop/idle evidence, before bounded nudges/stalled classification · 0 = no launch timer, but a result-less turn end still fails fast" +description = "silence grace for a dev/review session, armed at launch and re-armed by transport activity or fresh Stop/idle evidence, before bounded nudges/stalled classification · also the transcript-idle notice threshold (journal session-idle/session-active, TUI idle age) · 0 = no launch timer (and no idle notice), but a result-less turn end still fails fast" [[section.field]] key = "dev_stall_nudges" kind = "int" diff --git a/src/bmad_loop/engine.py b/src/bmad_loop/engine.py index a93612cb3..aac63ccdf 100644 --- a/src/bmad_loop/engine.py +++ b/src/bmad_loop/engine.py @@ -770,6 +770,17 @@ def __init__( } self.run_dir = run_dir self.journal = journal + # Hand the run's journal to every adapter this engine owns, so an adapter + # can record what only it sees — the #680 `session-idle`/`session-active` + # pair rides it. Deduplicated by identity: dev and review commonly share + # one adapter object. Attached, never wrapped: the adapter appends on the + # engine thread while the engine's own journal is quiescent, so this is + # one writer with one set of `log_task`/`log_pos` stamps, not two. + seen_adapters: list[CodingCLIAdapter] = [] + for owned in self.adapters.values(): + if not any(owned is done for done in seen_adapters): + owned.journal = journal + seen_adapters.append(owned) self.state = state self.max_stories = max_stories self.epic_filter = epic_filter @@ -2908,6 +2919,9 @@ def _dev_phase(self, task: StoryTask, resume_result: SessionResult | None = None # `_session_end_extras` (#489); here the flag pairs the # diagnosis with the decision it fed. session_vanished=result.session_vanished, + # Whether the session did anything before it ended (#727); False + # is what routed a non-completed result to the no-work PAUSE. + produced_work=result.produced_work, ) if decision.action == Action.PROCEED: # DEV_VERIFY + spec_file is not itself proof of acceptance: this @@ -6485,6 +6499,11 @@ def _session_end_extras(self, result: SessionResult) -> dict: # healthy moments before the probe asked. if result.session_vanished: extras["session_vanished"] = True + # no-work diagnosis (#727): same convention — present only when the + # session ended non-completed without ever changing its pane after the + # first frame, so a grep for the field finds exactly the parked sessions. + if not result.produced_work: + extras["produced_work"] = False return extras @staticmethod diff --git a/src/bmad_loop/escalation.py b/src/bmad_loop/escalation.py index 3d55e8d44..c87ef2185 100644 --- a/src/bmad_loop/escalation.py +++ b/src/bmad_loop/escalation.py @@ -199,6 +199,24 @@ def env_fault_pause_reason(role: str, result: SessionResult) -> str: return f"environment fault: {session_failure_reason(role, result)} ({env_fault_detail(result)})" +def no_work_pause_reason(role: str, result: SessionResult) -> str: + """The pause reason for a non-completed session that never did anything (#727): + ``no work produced: session (...)``. + + Composed over `session_failure_reason`, like `env_fault_pause_reason`, so the + #489 lost-session suffix survives: a session the multiplexer destroyed before + it painted a second frame carries both facts, and the operator needs both. The + parenthetical names what the adapter measured — no turn ended and the pane did + not change after its first frame — and what that most often means, because the + verdict alone (`crashed` / `stalled` / `timeout`) reads as an agent that ran and + failed, when the CLI in fact sat at a prompt only a human can answer.""" + return ( + f"no work produced: {session_failure_reason(role, result)} (no turn ended and " + "the pane never changed after its first frame — the CLI is likely waiting on a " + "human: a permission prompt, a login, a confirmation; the attempt is not charged)" + ) + + def session_failure_reason(role: str, result: SessionResult) -> str: """The reason text for a non-completed session: `` session ``, plus the lost-session diagnosis (#489). @@ -251,6 +269,21 @@ def decide_dev( Action.PAUSE, env_fault_pause_reason("dev", result), ) + if not result.produced_work: + # The session never did anything (#727): no turn ended and the pane + # never changed after its first frame — a CLI parked on a permission + # dialog, a login, a dead-on-arrival window. A RETRY would launch a + # fresh session into the identical wall and burn `max_dev_attempts` + # without a line of work, so pause for a human instead, ahead of the + # budget like the env-fault arm above: a spent budget must not file + # it as deferred work. Re-arm resets the attempt. After `env_fault` + # because a transport failure explains the silence better than the + # silence explains itself. Default `True` keeps every adapter that + # cannot measure this (opencode-http, unit fixtures) on today's path. + return Decision( + Action.PAUSE, + no_work_pause_reason("dev", result), + ) reason = session_failure_reason("dev", result) if budget_left: return Decision(Action.RETRY, reason) diff --git a/src/bmad_loop/policy.py b/src/bmad_loop/policy.py index 8ba462e1d..6cf0228bf 100644 --- a/src/bmad_loop/policy.py +++ b/src/bmad_loop/policy.py @@ -113,8 +113,11 @@ class LimitsPolicy: # stalled. The grace starts at session launch and re-arms on transport # activity (pane-log output or parent/child OpenCode SSE frames) and fresh # Stop/idle evidence, so productive work keeps extending it. Bounded by - # session_timeout_min. 0 disables the launch timer while retaining fail-fast - # handling when a turn ends without a terminal spec/result. + # session_timeout_min. Also the transcript-idle notice threshold (#680): the + # journal's session-idle/session-active pair and the TUI's idle age fire when + # the live transcript sits still this long. 0 disables the launch timer (and + # the idle notice) while retaining fail-fast handling when a turn ends without + # a terminal spec/result. dev_stall_grace_s: int = 600 # how many best-effort wake nudges a silent dev/review session receives on # dev_stall_grace_s expiry before it is called stalled. Transport activity @@ -1314,7 +1317,7 @@ def _fold_deprecated_engine( git_timeout_s = 120 # bound on any single git subprocess; exceeding it pauses/degrades (never crashes the run) — raise on a loaded host or a very large worktree teardown_grace_s = 20 # verified teardown: poll a killed session window up to this long, then force-kill its pane pids and re-kill (#157). 0 = single unverified best-effort kill stop_without_result_nudges = 1 -dev_stall_grace_s = 600 # silence grace armed at dev/review launch and re-armed by transport activity or fresh Stop/idle evidence before bounded recovery. 0 = no launch timer, but a result-less turn end still fails fast +dev_stall_grace_s = 600 # silence grace armed at dev/review launch and re-armed by transport activity or fresh Stop/idle evidence before bounded recovery; also the transcript-idle notice threshold (journal session-idle/session-active, TUI idle age). 0 = no launch timer (and no idle notice), but a result-less turn end still fails fast dev_stall_nudges = 2 # best-effort wake nudges per silent grace before stalling; fresh Stop/idle evidence restores this budget. 0 = stall on grace expiry dev_stall_nudges_cap = 6 # total (never-restored) nudge bound per dev/review session; bounds launch-time recovery and Stop/idle budget refills because an accepted nudge does not guarantee a wake. 0 = stall on first grace expiry workflow_stall_nudges_cap = 3 # total (never-restored) stall nudges for an injected plugin-workflow session before it is called stalled; bounds a session that finished its work but never wrote its completion marker. 0 = stall on first grace expiry diff --git a/src/bmad_loop/sweep.py b/src/bmad_loop/sweep.py index f432d5e72..fba4c9dcd 100644 --- a/src/bmad_loop/sweep.py +++ b/src/bmad_loop/sweep.py @@ -1323,6 +1323,10 @@ def __init__( self.adapters["triage"] = ( triage_adapter if triage_adapter is not None else self.adapters["dev"] ) + # `Engine.__init__` attached the journal to the adapters it knew about; a + # distinct triage adapter arrives after that, so attach it here too or every + # sweep triage session would emit no `session-idle`/`session-active` (#680). + self.adapters["triage"].journal = self.journal self.prompting = prompting self.decisions_only = decisions_only self.max_bundles = max_bundles if max_bundles is not None else self.policy.sweep.max_bundles diff --git a/src/bmad_loop/tui/data.py b/src/bmad_loop/tui/data.py index 18de994af..83998481c 100644 --- a/src/bmad_loop/tui/data.py +++ b/src/bmad_loop/tui/data.py @@ -574,17 +574,51 @@ def _open_session_start(journal_entries: list[dict[str, Any]]) -> dict[str, Any] session-start with no later matching session-end. None when every started session has ended (or none started). The task_id is tracked as a string so the session-end match is byte-identical to what active_task_id compared.""" + entry, _ = _open_session_start_indexed(journal_entries) + return entry + + +def _open_session_start_indexed( + journal_entries: list[dict[str, Any]], +) -> tuple[dict[str, Any] | None, int]: + """`_open_session_start` plus the entry's index in `journal_entries` (-1 when + None), so a caller can scan the entries that FOLLOW the open start — the + #680 idle events belong to a session only from its start onward, and a + `session-idle` left behind by an earlier session with a reused task id must + not be read as this one's.""" open_entry: dict[str, Any] | None = None + open_index = -1 active: str | None = None - for entry in journal_entries: + for index, entry in enumerate(journal_entries): kind = entry.get("kind") if kind == "session-start" and entry.get("task_id") is not None: active = str(entry["task_id"]) open_entry = entry + open_index = index elif kind == "session-end" and str(entry.get("task_id")) == active: active = None open_entry = None - return open_entry + open_index = -1 + return open_entry, open_index + + +def _idle_since(journal_entries: list[dict[str, Any]], start: int, task_id: str) -> float | None: + """Wall timestamp the open session's current idle stretch began (#680), or + None when it is not idle: the `since_ts` of the last `session-idle` for + `task_id` after index `start`, unless a later `session-active` for the same + task closed it. A `session-idle` without a numeric `since_ts` is skipped, not + trusted — the TUI ages the text from it. Never raises on a malformed entry.""" + since: float | None = None + for entry in journal_entries[start + 1 :]: + if str(entry.get("task_id")) != task_id: + continue + kind = entry.get("kind") + if kind == "session-idle": + raw = entry.get("since_ts") + since = float(raw) if isinstance(raw, (int, float)) else None + elif kind == "session-active": + since = None + return since def active_task_id(run_dir: Path, journal_entries: list[dict[str, Any]]) -> str | None: @@ -615,6 +649,11 @@ class ActiveAgent: role: str name: str model: str + # Wall timestamp the session's open idle stretch began (#680) — the `since_ts` + # of the last `session-idle` not closed by a later `session-active` — or None + # while the transcript is moving. The header renders `· idle ` from it + # only when set. APPENDED, so every positional construction stays valid. + idle_since: float | None = None def _story_key_from_task_id(task_id: str, role: str) -> str: @@ -651,7 +690,7 @@ def active_agent( yields nothing trustworthy (no/empty snapshot) the agent is unknown -> None. Never raises on a malformed entry.""" try: - entry = _open_session_start(journal_entries) + entry, start_index = _open_session_start_indexed(journal_entries) if entry is None: return None task_id = str(entry.get("task_id", "")) @@ -667,7 +706,14 @@ def active_agent( name, model = resolved.name, resolved.model story_raw = entry.get("story_key") story_key = str(story_raw) if story_raw else _story_key_from_task_id(task_id, role) - return ActiveAgent(task_id=task_id, story_key=story_key, role=role, name=name, model=model) + return ActiveAgent( + task_id=task_id, + story_key=story_key, + role=role, + name=name, + model=model, + idle_since=_idle_since(journal_entries, start_index, task_id), + ) except Exception: return None diff --git a/src/bmad_loop/tui/widgets.py b/src/bmad_loop/tui/widgets.py index 54b25cfed..2d989bec6 100644 --- a/src/bmad_loop/tui/widgets.py +++ b/src/bmad_loop/tui/widgets.py @@ -112,6 +112,19 @@ def agent_label(name: str, model: str) -> str: return f"{name}·{model}" if model else name +def _format_age(seconds: float) -> str: + """Coarse age for the header's `· idle ` text (#680): whole minutes + below an hour (`12m`), hours and minutes above (`1h05m`), never seconds — the + threshold is the stall grace (minutes), so finer resolution would only make + the line flicker on every poll. A negative age (a clock stepped backward + between the adapter's stamp and this render) reads as `0m` rather than a + minus sign.""" + minutes = max(0, int(seconds // 60)) + if minutes < 60: + return f"{minutes}m" + return f"{minutes // 60}h{minutes % 60:02d}m" + + class RunHeader(Static): """One-glance summary of the selected run, or the empty-state hint.""" @@ -193,6 +206,15 @@ def show_run( text.append(f" · {agent.model}", style="cyan") if agent.role: text.append(f" · {agent.role}", style="dim") + if agent.idle_since is not None: + # The transcript has sat still past the stall grace (#680): the + # pane may still be repainting a spinner, so this is the one + # surface that separates a session working from one parked in a + # tool call. Yellow, not red — it is a notice, not a verdict, and + # nothing bounds the stretch. + text.append( + f" · idle {_format_age(time.time() - agent.idle_since)}", style="yellow" + ) else: # No session open: show the configured adapters from the run's policy # snapshot. Skip the line entirely when the snapshot can't be rebuilt diff --git a/tests/test_engine.py b/tests/test_engine.py index fcbf400ca..13d6b89f8 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -11936,6 +11936,59 @@ def test_session_env_fault_pauses_dev_without_burning_budget(project): assert load_state(engine.run_dir).tasks["1-1-a"].attempt == 0 +def test_session_with_no_work_pauses_dev_without_burning_budget(project): + """A dev session that produced nothing (#727 — a CLI parked on a permission + dialog until the grace, the nudge and window death) pauses the run at the + first story rather than charging the attempt and launching a second session + into the same wall; `dev-decision` and `session-end` both carry the flag, and + re-arm restores the budget (attempt -> 0). + + ABLATION: delete the `produced_work` arm in `decide_dev` and this RETRYs — a + second dev session is launched and the story ends deferred, not paused.""" + write_sprint(project, {"1-1-a": "ready-for-dev"}) + engine, adapter = make_engine( + project, + [SessionResult(status="stalled", produced_work=False)], + ) + summary = engine.run() + + assert summary.paused and summary.escalated == 1 and summary.deferred == 0 + assert [s.role for s in adapter.sessions] == ["dev"] # no retry session burned + task = engine.state.tasks["1-1-a"] + assert task.phase == Phase.ESCALATED + assert task.attempt == 1 # the one real session, not a spent budget + assert engine.state.paused_stage == PAUSE_ESCALATION + assert engine.state.paused_reason.startswith("no work produced: dev session stalled") + + dec = [e for e in engine.journal.entries() if e["kind"] == "dev-decision"][-1] + assert dec["action"] == "pause" + assert dec["produced_work"] is False + assert dec["env_fault"] is False + end = [e for e in engine.journal.entries() if e["kind"] == "session-end"][-1] + assert end["produced_work"] is False + + # the resolve workflow's re-arm step is what makes "not charged" true + rearm_escalation(engine.run_dir, isolated_redrive=False, resolution_recorded=True) + assert load_state(engine.run_dir).tasks["1-1-a"].attempt == 0 + + +def test_engine_attaches_its_journal_to_every_adapter(project): + """The engine hands its `Journal` to the adapters it owns (#680), so an + adapter-side `session-idle` lands in the same file with the same + `log_task`/`log_pos` stamps; a session that worked leaves no `produced_work` + key on `session-end` (the field is present only when False, like + `session_vanished`) and `dev-decision` records it True.""" + write_sprint(project, {"1-1-a": "ready-for-dev"}) + engine, adapter = make_engine(project, [SessionResult(status="timeout")]) + assert adapter.journal is engine.journal + assert engine.adapters["review"].journal is engine.journal + engine.run() + dec = [e for e in engine.journal.entries() if e["kind"] == "dev-decision"] + assert dec and all(d["produced_work"] is True for d in dec) + ends = [e for e in engine.journal.entries() if e["kind"] == "session-end"] + assert ends and all("produced_work" not in e for e in ends) + + def test_two_plain_timeouts_still_defer(project): """Guard: NON-env-fault timeouts keep today's flow — two of them exhaust the dev budget and defer the story (the env-fault pause must not intercept them).""" diff --git a/tests/test_escalation.py b/tests/test_escalation.py index 0536c9ce4..99369aa70 100644 --- a/tests/test_escalation.py +++ b/tests/test_escalation.py @@ -191,6 +191,76 @@ def test_dev_env_fault_session_pauses_even_when_budget_exhausted(): assert "environment fault" in decision.reason +def test_dev_no_work_session_pauses_even_with_budget_left(): + """A dev session that never did anything (#727) — no turn ended and the pane + never changed after its first frame: a CLI parked on a permission dialog — + PAUSEs for a human instead of RETRYing into the identical wall. The reason + names the measurement, not the verdict alone. + + ABLATION: delete the `produced_work` arm in `decide_dev` and this RETRYs.""" + task = _task(attempt=1) # 1 < 2 -> budget remains + parked = SessionResult(status="stalled", produced_work=False) + decision = decide_dev(task, parked, None, POLICY) + assert decision.action == Action.PAUSE + assert decision.reason.startswith("no work produced: dev session stalled") + assert "permission prompt" in decision.reason + assert "the attempt is not charged" in decision.reason + + +def test_dev_no_work_session_pauses_even_when_budget_exhausted(): + """The no-work pause outranks budget exhaustion like the env-fault pause does: + a spent budget must not file a CLI waiting on a human as deferred work.""" + task = _task(attempt=2) # 2 == max_dev_attempts -> budget spent + parked = SessionResult(status="crashed", produced_work=False) + decision = decide_dev(task, parked, None, POLICY) + assert decision.action == Action.PAUSE + assert decision.reason.startswith("no work produced: dev session crashed") + + +def test_dev_produced_work_default_keeps_todays_routing(): + """`produced_work` defaults True — "unknown never blocks" — so every positional + construction (the engine's hand-built results, opencode-http, every fixture) + keeps RETRY-with-budget / DEFER-without. Pinned on both arms so the default + cannot silently flip.""" + plain = SessionResult(status="timeout") + assert plain.produced_work is True + assert decide_dev(_task(attempt=1), plain, None, POLICY).action == Action.RETRY + assert decide_dev(_task(attempt=2), plain, None, POLICY).action == Action.DEFER + assert "no work produced" not in decide_dev(_task(attempt=1), plain, None, POLICY).reason + + +def test_dev_env_fault_outranks_no_work(): + """Both flags set: the env-fault arm is checked first, so the reason blames + the transport, not the silence — a lost API connection explains a still + pane better than the still pane explains itself.""" + task = _task(attempt=1) + both = SessionResult( + status="timeout", + env_fault=True, + env_fault_evidence="API Error: ETIMEDOUT", + produced_work=False, + ) + decision = decide_dev(task, both, None, POLICY) + assert decision.action == Action.PAUSE + assert decision.reason.startswith("environment fault: dev session timeout") + assert "no work produced" not in decision.reason + + +def test_no_work_reason_keeps_the_lost_session_suffix(): + """#727 x #489: the no-work reason is composed over `session_failure_reason`, + so a session the multiplexer destroyed before it painted a second frame + carries both facts instead of one cancelling the other.""" + task = _task(attempt=1) + both = SessionResult(status="crashed", session_vanished=True, produced_work=False) + decision = decide_dev(task, both, None, POLICY) + assert decision.action == Action.PAUSE + assert decision.reason.startswith("no work produced: dev session crashed:") + assert "multiplexer no longer reports the session" in decision.reason + # the review decider does not carry the arm (a named follow-up, not this wave) + review = decide_review_session(task, both, POLICY) + assert "no work produced" not in review.reason + + def test_dev_plain_noncompleted_still_retries_with_budget(): """Guard pin: a NON-env-fault timeout with budget left still RETRYs — the env-fault branch must not swallow ordinary transient failures.""" diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 5f62ab5ad..323763aff 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -38,7 +38,7 @@ from bmad_loop.adapters.multiplexer import MultiplexerError from bmad_loop.adapters.profile import get_profile from bmad_loop.bmadconfig import ProjectPaths -from bmad_loop.journal import TASK_CYCLE_ARTIFACTS +from bmad_loop.journal import TASK_CYCLE_ARTIFACTS, Journal from bmad_loop.model import TokenUsage from bmad_loop.policy import LimitsPolicy, NotifyPolicy, Policy from bmad_loop.signals import HookEvent @@ -1988,6 +1988,7 @@ def advance(call_n): "remaining_s": 100.0, "stall_armed": True, "stall_nudges_sent": 0, + "transcript_idle_s": None, # no hook event has named a transcript (#680) } assert [w["remaining_s"] for w in writes] == [100.0, 59.0] # tick 2 was throttled hb = json.loads((adapter.tasks_dir / "3-1-dev-1" / "heartbeat.json").read_text()) @@ -6302,3 +6303,522 @@ def test_classify_env_fault_scans_a_single_oversized_terminated_line(tmp_path, t assert result.env_fault is True assert result.env_fault_evidence.startswith("…") assert "API Error: Connection closed mid-response" in result.env_fault_evidence + + +# ------------------------------- no-work verdict (#727) +# +# `SessionResult.produced_work`: did the session do ANYTHING before it ended on a +# non-completed verdict? The hook half is a `Stop`; the timeline half is pane-log +# growth on a tick later than FIRST_FRAME_S after the loop started and before the +# first stall wake nudge. The #261 byte floor is deliberately NOT the predicate: the +# #727 capture is a 1,930-byte permission dialog rendered once, which clears it. +# The stall re-arm, the nudge arm and `_log_activity_key` are untouched — the stall +# suite above is the byte-for-byte guard. + + +def _steerable_clock(monkeypatch): + """Frozen monotonic + wall clocks the test advances together, so a + `since_ts` is a real (moving) wall timestamp rather than `_frozen_stall_clock`'s + constant 0.0.""" + clock = {"t": 1000.0} + + class _Clock: + monotonic = staticmethod(lambda: clock["t"]) + time = staticmethod(lambda: 5000.0 + (clock["t"] - 1000.0)) + sleep = staticmethod(lambda *_: None) + time_ns = staticmethod(lambda: 0) + + monkeypatch.setattr(generic, "time", _Clock) + return clock + + +def _grow(path: Path, payload: bytes) -> None: + with path.open("ab") as stream: + stream.write(payload) + + +def test_no_work_menu_paint_then_nudge_echo_then_death(tmp_path, monkeypatch): + """The #727 capture, tick by tick: the CLI paints its permission dialog once + (1,930 B — over the #261 floor), sits still through the grace, the wake nudge + confirms the dialog's default and the pane grows with the echo, then the window + dies. `crashed`, and `produced_work` is False — neither the first frame nor the + post-nudge echo counts as work. + + ABLATION B: drop the `> FIRST_FRAME_S` guard and the first paint counts (True). + ABLATION C: drop the `stall_nudges_sent == 0` guard and the echo counts (True).""" + monkeypatch.setattr(generic, "RESULT_GRACE_S", 0.0) + mux = _UnitMux() + adapter, _ = make_dev_adapter(tmp_path, mux=mux) + # The grace must outlast FIRST_FRAME_S, as the 600 s default does by an order + # of magnitude: otherwise the echo lands inside the startup window and the + # FIRST_FRAME_S guard masks the nudge guard (ABLATION C then stays green). + adapter._stall_grace_s = 40.0 + adapter._stall_nudges = 1 + alive = {"v": True} + adapter._window_alive = lambda handle: alive["v"] + log = _pane_log(adapter, "3-1-dev-1", 0) # start_session creates it empty + clock = _steerable_clock(monkeypatch) + + def script(call_n): + if call_n == 1: + clock["t"] += 1.0 # t≈1 s: the dialog paints, once + _grow(log, b"Do you trust the files in this folder? [Yes/No, exit]\n" * 35) + elif call_n == 2: + clock["t"] += 41.0 # grace elapses in silence -> nudge (t≈42 > FIRST_FRAME_S) + elif call_n == 3: + clock["t"] += 1.0 # the nudge's Enter confirmed "No, exit": echo + exit text + _grow(log, b"\n> \nNo, exit\nGoodbye.\n") + else: + alive["v"] = False # window dead next tick + + adapter.watcher = _ScriptedWatcher([], on_call=script) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=100.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + + assert result.status == "crashed" + assert [text for _, text in mux.sent] == [generic.STALL_NUDGE_TEXT] + assert log.stat().st_size > generic.PROOF_OF_WORK_MIN_LOG_BYTES # floor cleared… + assert adapter._produced_work(_dev_handle(), False) is True # …so #261 says "work" + assert result.produced_work is False # …and the timeline says otherwise + assert result.stop_seen is False + + +def test_no_work_session_end_after_nudge_echo(tmp_path, monkeypatch): + """The same capture ending through the CLI announcing its own exit — a + `SessionEnd` hook after the nudge's echo — takes the SessionEnd `_final` + arm, which must thread the verdict like the window-death arm does. + + ABLATION: drop `produced_work=produced_work()` from that one `_final` call and + this reads True (the default).""" + monkeypatch.setattr(generic, "RESULT_GRACE_S", 0.0) + mux = _UnitMux() + adapter, _ = make_dev_adapter(tmp_path, mux=mux) + adapter._stall_grace_s = 40.0 + adapter._stall_nudges = 1 + adapter._window_alive = lambda handle: True + log = _pane_log(adapter, "3-1-dev-1", 0) + clock = _steerable_clock(monkeypatch) + + def script(call_n): + if call_n == 1: + clock["t"] += 1.0 + _grow(log, b"Do you trust the files in this folder? [Yes/No, exit]\n" * 35) + elif call_n == 2: + clock["t"] += 41.0 # grace elapses -> nudge, past FIRST_FRAME_S + elif call_n == 3: + clock["t"] += 1.0 + _grow(log, b"\n> \nNo, exit\nGoodbye.\n") # the echo, then SessionEnd + + session_end = HookEvent( + ts=1, + event="SessionEnd", + task_id="3-1-dev-1", + session_id="sess", + transcript_path=None, + path=Path("x"), + ) + adapter.watcher = _ScriptedWatcher([None, None, None, session_end], on_call=script) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=100.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + + assert [text for _, text in mux.sent] == [generic.STALL_NUDGE_TEXT] + assert (result.status, result.produced_work) == ("crashed", False) + + +def test_no_work_dead_on_arrival_window(tmp_path): + """A 0-byte log and a window dead on the first tick: `crashed`, no work.""" + mux = _UnitMux() + adapter, _ = make_dev_adapter(tmp_path, mux=mux) + adapter._window_alive = lambda handle: False + _pane_log(adapter, "3-1-dev-1", 0) + adapter.watcher = _ScriptedWatcher([None]) + result = adapter.wait_for_completion(_dev_handle(), _dev_spec(tmp_path)) + assert (result.status, result.produced_work) == ("crashed", False) + + +def test_working_session_that_later_stalls_produced_work(tmp_path, monkeypatch): + """The pane grows on a tick past FIRST_FRAME_S with no nudge sent, then falls + silent through the grace and both nudges: `stalled`, but the session worked, + so `produced_work` is True and the decision RETRYs as it does today.""" + monkeypatch.setattr(generic, "RESULT_GRACE_S", 0.0) + mux = _UnitMux() + adapter, _ = make_dev_adapter(tmp_path, mux=mux) + adapter._stall_grace_s = 40.0 + adapter._stall_nudges = 2 + adapter._window_alive = lambda handle: True + log = _pane_log(adapter, "3-1-dev-1", 0) + clock = _steerable_clock(monkeypatch) + + def script(call_n): + if call_n == 1: + clock["t"] += generic.FIRST_FRAME_S + 1.0 # past the startup window + _grow(log, b"Reading src/bmad_loop/engine.py ...\n") + else: + clock["t"] += 41.0 # each further grace elapses in silence + + adapter.watcher = _ScriptedWatcher([], on_call=script) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=1000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + + assert result.status == "stalled" + assert [text for _, text in mux.sent] == [generic.STALL_NUDGE_TEXT] * 2 + assert result.produced_work is True + + +def test_growth_inside_first_frame_window_alone_is_not_work(tmp_path, monkeypatch): + """The complement of the row above, isolating ABLATION B from the nudge arm: + the same growth landing INSIDE FIRST_FRAME_S (no nudge ever sent — the + session stalls with the nudge budget at zero) is the startup paint and does + not count.""" + monkeypatch.setattr(generic, "RESULT_GRACE_S", 0.0) + adapter, _ = make_dev_adapter(tmp_path, mux=_UnitMux()) + adapter._stall_grace_s = 40.0 + adapter._stall_nudges = 0 + adapter._window_alive = lambda handle: True + log = _pane_log(adapter, "3-1-dev-1", 0) + clock = _steerable_clock(monkeypatch) + + def script(call_n): + if call_n == 1: + clock["t"] += generic.FIRST_FRAME_S - 1.0 # inside the startup window + _grow(log, b"Reading src/bmad_loop/engine.py ...\n") + else: + clock["t"] += 41.0 + + adapter.watcher = _ScriptedWatcher([], on_call=script) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=1000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert (result.status, result.produced_work) == ("stalled", False) + + +def test_turn_ended_with_empty_log_is_work(tmp_path, monkeypatch): + """The hook half: a result-less `Stop` on a session whose pane log never grew + (a misbound pane sink, #254/#217) still counts — a turn ENDED. The grace then + expires and the session stalls, carrying `produced_work=True`.""" + monkeypatch.setattr(generic, "RESULT_GRACE_S", 0.0) + monkeypatch.setattr(generic, "RESULT_POLL_S", 0.0) + adapter, _ = make_dev_adapter(tmp_path, mux=_UnitMux()) + adapter._stall_grace_s = 10.0 + adapter._stall_nudges = 0 + adapter._window_alive = lambda handle: True + _pane_log(adapter, "3-1-dev-1", 0) + clock = _steerable_clock(monkeypatch) + + def script(call_n): + if call_n == 2: + clock["t"] += 11.0 + + adapter.watcher = _ScriptedWatcher( + [_stop_event("3-1-dev-1", "sess", str(tmp_path / "t.jsonl"))], on_call=script + ) + result = adapter.wait_for_completion(_dev_handle(), _dev_spec(tmp_path)) + assert result.status == "stalled" + assert result.stop_seen is True + assert result.produced_work is True + + +def test_no_pane_log_means_unknown_never_blocks(tmp_path): + """A handle this adapter never launched (every unit fixture; the opencode-http + transport has no pane at all): `_log_evidence` is None, so the verdict is + True — exactly `_produced_work`'s "unknown never blocks".""" + adapter, _ = make_dev_adapter(tmp_path, mux=_UnitMux()) + adapter._window_alive = lambda handle: False + assert not (adapter.logs_dir / "3-1-dev-1.log").exists() + adapter.watcher = _ScriptedWatcher([None]) + result = adapter.wait_for_completion(_dev_handle(), _dev_spec(tmp_path)) + assert (result.status, result.produced_work) == ("crashed", True) + + +def test_timeout_with_static_log_is_no_work(tmp_path, monkeypatch): + """The session clock elapses with the pane unchanged since its first frame: + `timeout`, `produced_work=False` — the same wall as #727 on a profile whose + grace is disabled.""" + adapter, clock = _timeout_clock_adapter(tmp_path, monkeypatch) + adapter._stall_grace_s = 0.0 # no grace: only the deadline can end this + log = _pane_log(adapter, "3-1-dev-1", 0) + + def script(call_n): + if call_n == 1: + clock["mono"] += 1.0 + _grow(log, b"Do you trust the files in this folder?\n" * 50) + else: + clock["mono"] += 1000.0 + + adapter.watcher = _ScriptedWatcher([], on_call=script) + result = adapter.wait_for_completion(_dev_handle(), _short_spec(tmp_path, timeout_s=100.0)) + assert (result.status, result.produced_work) == ("timeout", False) + + +def test_readback_upgrade_to_completed_resets_produced_work(tmp_path, monkeypatch): + """The flag is scoped to non-completed exits: a dead window whose artifact + upgrades the crash to `completed` (log over the #261 floor, no Stop, the + loop's timeline verdict False) carries `produced_work=True`, so a completed + session-end never gets a no-work stamp. + + ABLATION: pass the loop's verdict through unconditionally and this reads False.""" + adapter, impl = make_dev_adapter(tmp_path, mux=_UnitMux()) + monkeypatch.setattr(generic, "RESULT_GRACE_S", 0.0) + (impl / "spec-3-1-foo.md").write_text( + "---\nstatus: done\nbaseline_revision: abc123\n---\n\n" + "## Auto Run Result\n\nStatus: done\nImplemented.\n" + ) + _pane_log(adapter, "3-1-dev-1", 5000) + res = adapter._final( + _dev_handle(), _dev_spec(tmp_path), "crashed", None, None, produced_work=False + ) + assert res.status == "completed" + assert res.produced_work is True + # the non-completed path keeps the loop's verdict + kept = adapter._final( + _dev_handle(), + _dev_spec(tmp_path), + "stalled", + None, + None, + accept_result=False, + produced_work=False, + ) + assert (kept.status, kept.produced_work) == ("stalled", False) + + +def test_work_verdict_arms(tmp_path): + """The predicate in isolation: Stop OR no-log OR activity; a present, static + log with neither signal is the only False.""" + adapter, _ = make_dev_adapter(tmp_path, mux=_UnitMux()) + handle = _dev_handle() + assert adapter._work_verdict(handle, stop_seen=False, activity_seen=False) is True # no log + _pane_log(adapter, "3-1-dev-1", 5000) # present, and well over the #261 floor + assert adapter._work_verdict(handle, stop_seen=False, activity_seen=False) is False + assert adapter._work_verdict(handle, stop_seen=True, activity_seen=False) is True + assert adapter._work_verdict(handle, stop_seen=False, activity_seen=True) is True + + +# ------------------------------- transcript idle detection (#680) +# +# Observability only. The live transcript's (mtime_ns, size) is sampled on the +# heartbeat cadence; `heartbeat.json` carries the age; the journal gets one +# `session-idle` per stretch at the stall-grace crossing and one `session-active` +# when the key moves again. Nothing here nudges, stalls or kills. + + +class _FakeJournal: + def __init__(self): + self.entries: list[dict] = [] + + def append(self, kind, **fields): + self.entries.append({"kind": kind, **fields}) + + +def _session_start(task_id, transcript_path): + return HookEvent( + ts=1, + event="SessionStart", + task_id=task_id, + session_id="sess", + transcript_path=transcript_path, + path=Path("x"), + ) + + +def _idle_adapter(tmp_path, monkeypatch, *, grace=60.0, journal=True): + """Dev adapter with a live pane log that the script keeps repainting (the #680 + spinner: the stall re-arm never fires) and a transcript file the script + advances on cue. Heartbeats are captured in order.""" + mux = _UnitMux() + adapter, _ = make_dev_adapter(tmp_path, mux=mux) + adapter._stall_grace_s = grace + adapter._stall_nudges = 0 + adapter._window_alive = lambda handle: True + if journal: + adapter.journal = _FakeJournal() + log = _pane_log(adapter, "3-1-dev-1", 0) + transcript = tmp_path / "transcript.jsonl" + transcript.write_bytes(b'{"type":"user"}\n') + clock = _steerable_clock(monkeypatch) + heartbeats: list[dict] = [] + adapter._write_heartbeat = lambda task_id, payload: heartbeats.append(payload) + return adapter, mux, log, transcript, clock, heartbeats + + +def test_idle_stretch_journals_one_pair_and_stamps_heartbeat(tmp_path, monkeypatch): + """A transcript still for >= the grace while the pane keeps repainting: exactly + one `session-idle` at the crossing (age >= threshold, `since_ts` = the wall + time of the last change), `transcript_idle_s` climbing on every heartbeat, one + `session-active` with the stretch's length when the transcript moves, and a + fresh pair for a later stretch. The session is neither nudged nor stalled. + + ABLATION D: drop the `open_since` latch and tick 6 emits a second + `session-idle` for the same stretch.""" + adapter, mux, log, transcript, clock, heartbeats = _idle_adapter(tmp_path, monkeypatch) + # A REAL journal here (the other idle rows use `_FakeJournal`), so the + # `append(kind, **fields)` signature the adapter relies on is pinned against + # `bmad_loop.journal.Journal` itself, read back through `entries()`. + adapter.journal = Journal(tmp_path / "journal-run") + + def script(call_n): + if call_n >= 2: + clock["t"] += generic.HEARTBEAT_INTERVAL_S # one heartbeat per tick + _grow(log, "\r⠋ Thinking…".encode()) # the spinner keeps the pane alive + if call_n == 6: + _grow(transcript, b'{"type":"assistant"}\n') # the stretch ends + if call_n == 10: + clock["t"] += 10_000.0 # past spec.timeout_s: end the loop + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + + assert result.status == "timeout" # the idle stretch itself ended nothing + assert mux.sent == [] # never nudged + # heartbeat 1 predates the transcript; the first sample is age 0; the age + # climbs; the move resets it; the second stretch climbs to its own crossing + assert [hb["transcript_idle_s"] for hb in heartbeats] == [ + None, + 0.0, + 30.0, + 60.0, + 90.0, + 0.0, + 30.0, + 60.0, + 90.0, + ] + entries = adapter.journal.entries() + kinds = [e["kind"] for e in entries] + assert kinds == ["session-idle", "session-active", "session-idle"] + first, active, second = entries + assert all(isinstance(e.pop("ts"), float) for e in entries) # Journal's own stamp + assert first == { + "kind": "session-idle", + "task_id": "3-1-dev-1", + "idle_s": 60.0, + "since_ts": 5030.0, # wall time of the first sample (mono 1030) + "threshold_s": 60.0, + } + assert active == {"kind": "session-active", "task_id": "3-1-dev-1", "idle_s": 120.0} + assert second["since_ts"] == 5150.0 # the move at mono 1150 started the new stretch + assert second["idle_s"] == 60.0 + + +def test_idle_events_need_a_positive_grace(tmp_path, monkeypatch): + """`dev_stall_grace_s = 0` disables the events (no new knob); the heartbeat + still stamps the age. + + ABLATION D: drop the `_stall_grace_s > 0` guard and `idle_s >= 0` fires on the + first sample.""" + adapter, _, log, transcript, clock, heartbeats = _idle_adapter(tmp_path, monkeypatch, grace=0.0) + + def script(call_n): + if call_n >= 2: + clock["t"] += generic.HEARTBEAT_INTERVAL_S + _grow(log, "\r⠋".encode()) + if call_n == 7: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + adapter.wait_for_completion(_dev_handle(), spec) + + assert adapter.journal.entries == [] + assert [hb["transcript_idle_s"] for hb in heartbeats] == [None, 0.0, 30.0, 60.0, 90.0, 120.0] + + +def test_idle_events_need_an_attached_journal(tmp_path, monkeypatch): + """No journal attached (`resolve.run_session`, `probe`, fixtures): no events, + no error; the heartbeat still carries the age. + + ABLATION D: drop the `journal is None` guard and this raises on `None.append`.""" + adapter, _, log, transcript, clock, heartbeats = _idle_adapter( + tmp_path, monkeypatch, journal=False + ) + assert adapter.journal is None + + def script(call_n): + if call_n >= 2: + clock["t"] += generic.HEARTBEAT_INTERVAL_S + _grow(log, "\r⠋".encode()) + if call_n == 7: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + adapter.wait_for_completion(_dev_handle(), spec) + assert heartbeats[-1]["transcript_idle_s"] == 120.0 + + +def test_idle_age_is_null_without_a_transcript(tmp_path, monkeypatch): + """No hook event ever names a transcript: nothing to sample, `null` on every + heartbeat, no events.""" + adapter, _, log, _transcript, clock, heartbeats = _idle_adapter(tmp_path, monkeypatch) + + def script(call_n): + clock["t"] += generic.HEARTBEAT_INTERVAL_S + _grow(log, "\r⠋".encode()) + if call_n == 4: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher([], on_call=script) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + adapter.wait_for_completion(_dev_handle(), spec) + assert heartbeats and all(hb["transcript_idle_s"] is None for hb in heartbeats) + assert adapter.journal.entries == [] + + +def test_unreadable_transcript_stat_skips_the_sample(tmp_path, monkeypatch): + """A transcript the hook named but that does not exist yet (or is mid-rename): + the stat raises, the key is None, the tick is skipped and the loop goes on. + When the file appears the clock starts from THAT sample.""" + adapter, _, log, transcript, clock, heartbeats = _idle_adapter(tmp_path, monkeypatch) + transcript.unlink() + assert generic.GenericAdapter._transcript_activity_key(str(transcript)) is None + + def script(call_n): + if call_n >= 2: + clock["t"] += generic.HEARTBEAT_INTERVAL_S + _grow(log, "\r⠋".encode()) + if call_n == 4: + transcript.write_bytes(b"{}\n") # appears before heartbeat 4 + if call_n == 6: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + adapter.wait_for_completion(_dev_handle(), spec) + assert [hb["transcript_idle_s"] for hb in heartbeats] == [None, None, None, 0.0, 30.0] + assert adapter.journal.entries == [] + + +def test_idle_journal_write_failure_is_swallowed(tmp_path, monkeypatch): + """An unwritable journal is observability, never a reason to end a session + that is, by this very evidence, alive.""" + adapter, _, log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch) + + class _Broken: + def append(self, kind, **fields): + raise OSError("disk full") + + adapter.journal = _Broken() + + def script(call_n): + if call_n >= 2: + clock["t"] += generic.HEARTBEAT_INTERVAL_S + _grow(log, "\r⠋".encode()) + if call_n == 6: + _grow(transcript, b"{}\n") + if call_n == 8: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert result.status == "timeout" diff --git a/tests/test_portability_guard.py b/tests/test_portability_guard.py index 30a055985..ced5f402d 100644 --- a/tests/test_portability_guard.py +++ b/tests/test_portability_guard.py @@ -564,6 +564,9 @@ "harvest_attempt", "head", "id_collisions", + # `session-idle` / `session-active` (#680): seconds the live transcript has + # sat still — a float the adapter measured from two stats, no identifier. + "idle_s", "items", "kept", "key", @@ -635,6 +638,11 @@ "policy_changed", "preserve_ref", "problem", + # `dev-decision` and `session-end` (#727): whether the session changed its + # pane after the first frame or ended a turn. A bare boolean about the + # verdict — it names no story, no path and no text, and `False` is what + # routed the result to the no-work PAUSE. + "produced_work", # A closed two-value enum (`file-limit` | `payload-limit`) emitted only # for measured artifact publication admission refusals. The arbitrary # path and exception prose ride `error`, which diagnostics drops. @@ -698,6 +706,9 @@ "session_status", "session_vanished", "signum", + # `session-idle` (#680): the wall timestamp the idle stretch began — the + # `ts`-shaped float the TUI ages the `· idle ` text from. + "since_ts", "site", "skip", "source", @@ -724,6 +735,10 @@ "stop_cause", "strategy", "teardown_s", + # `session-idle` (#680): the grace the crossing was judged against — + # `limits.dev_stall_grace_s` as a float, so the record is comparable to a + # stall without the policy snapshot in hand. + "threshold_s", "to", "tokens", "tokens_weighted", @@ -1039,6 +1054,15 @@ # the scan's, not the tree's. JOURNAL_KINDS = frozenset( { + # adapters/generic.py — the only adapter-side writer. The engine hands its + # `Journal` to every adapter it owns (`CodingCLIAdapter.journal`, #680) so + # the wait loop can record what only it sees: the live transcript's idle + # stretches, one `session-idle` at the crossing of `dev_stall_grace_s` and + # one `session-active` when the transcript moves again. Both carry only + # `task_id` (routed) and measured floats (`idle_s`, `since_ts`, + # `threshold_s`, declared benign). + "session-active", + "session-idle", # cli.py "run-resume", # cli.py + runs.py diff --git a/tests/test_stories_e2e.py b/tests/test_stories_e2e.py index f75e3eb1f..32b371c8d 100644 --- a/tests/test_stories_e2e.py +++ b/tests/test_stories_e2e.py @@ -743,7 +743,12 @@ def test_e2e_two_story_happy_path_build_auto(tmp_path): assert _status(root, "2") == "done" assert _commit_count(root) == base + 2 - run_dir = root / ".bmad-loop" / "runs" / _run_id(root) + run_id = _run_id(root) + run_dir = root / ".bmad-loop" / "runs" / run_id + # A FINISHED run tears down its mux session (`cleanup_session_on_finish`); the + # suite's one real-tmux pin of that — the timeout row now pauses (#727) and a + # pause keeps the session for resume by design. + assert not _tmux_has_session(f"bmad-loop-{run_id}") dispatched = [ p.read_text(encoding="utf-8") for p in (run_dir / "tasks").glob("*/fake-prompt.txt") ] @@ -1708,6 +1713,15 @@ def _tmux_has_session(name: str) -> bool: return subprocess.run(["tmux", "has-session", "-t", name], capture_output=True).returncode == 0 +def _tmux_window_names(session: str) -> list[str]: + out = subprocess.run( + ["tmux", "list-windows", "-t", f"={session}", "-F", "#{window_name}"], + capture_output=True, + text=True, + ) + return out.stdout.split() + + @pytest.mark.parametrize( "force_live_reap_assertion", [False, True], ids=["reaped", "live-assertion"] ) @@ -1716,7 +1730,15 @@ def test_e2e_session_timeout_teardown(tmp_path, monkeypatch, force_live_reap_ass forever (SessionStart, then sleep — never a Stop) is bounded only by the session timeout, and the fix makes that firing timely and observable. The 1-minute policy floor is too coarse for a fast test, so the engine's - BMAD_LOOP_SESSION_TIMEOUT_S seam drives a 3-second budget.""" + BMAD_LOOP_SESSION_TIMEOUT_S seam drives a 3-second budget. + + Since #727 the same session is also the no-work shape — it painted once and + never changed its pane before the deadline — so the run PAUSES at escalation + (`no work produced: dev session timeout`) instead of deferring, and a pause + deliberately leaves the run's mux SESSION for `resume` to reuse. The teardown + under test is the agent window's: it and its process tree must be gone, and the + session must hold nothing but its root shell window. The session itself is + killed on the way out so the host is not left with an orphan.""" root = tmp_path / "sbx" story = "1-1-timeout" _scaffold_sprint( @@ -1736,6 +1758,7 @@ def test_e2e_session_timeout_teardown(tmp_path, monkeypatch, force_live_reap_ass injected_child: subprocess.Popen | None = None poll_failure: AssertionError | None = None injected_exit: int | None = None + run_id: str | None = None try: # Everything up to the bind is the pre-bind window: the fake CLI's child is # already running but no fd names it yet, so a `_run` timeout or any assertion @@ -1810,8 +1833,19 @@ def test_e2e_session_timeout_teardown(tmp_path, monkeypatch, force_live_reap_ass hb = json.loads((tdir / "heartbeat.json").read_text(encoding="utf-8")) assert time.time() - hb["ts"] < 120, hb - # (4) teardown actually reaped the session — no orphan tmux session/process - assert not _tmux_has_session(f"bmad-loop-{run_id}") + # (4) teardown actually reaped the agent window and its process tree. The + # run is paused (see the docstring), so the session survives by design — + # with only its root shell window left, never the task's. + state = json.loads((run_dir / "state.json").read_text(encoding="utf-8")) + assert state.get("paused_stage") == "escalation", state + assert str(state.get("paused_reason", "")).startswith( + "no work produced: dev session timeout" + ), state + assert end.get("produced_work") is False, end + session_name = f"bmad-loop-{run_id}" + assert _tmux_has_session(session_name) + windows = _tmux_window_names(session_name) + assert task_id[-40:] not in windows and len(windows) == 1, windows if shutil.which("pgrep"): pg = subprocess.run(["pgrep", "-af", "fake-cli.sh"], capture_output=True, text=True) assert not [ln for ln in pg.stdout.splitlines() if str(root) in ln], pg.stdout @@ -1850,6 +1884,11 @@ def test_e2e_session_timeout_teardown(tmp_path, monkeypatch, force_live_reap_ass finally: if injected_child is not None and injected_child.poll() is None: _reap(injected_child) + # The paused run left its session for a resume that never comes. + if run_id is not None: + subprocess.run( + ["tmux", "kill-session", "-t", f"=bmad-loop-{run_id}"], capture_output=True + ) if force_live_reap_assertion: assert str(poll_failure).splitlines()[0] == f"sleep child {poll_pid} survived teardown" diff --git a/tests/test_sweep.py b/tests/test_sweep.py index 8727a6ff4..2698665ff 100644 --- a/tests/test_sweep.py +++ b/tests/test_sweep.py @@ -141,6 +141,20 @@ def make_sweep( return engine, adapter +def test_sweep_attaches_journal_to_a_distinct_triage_adapter(project): + """#680: `Engine.__init__` attaches its journal to the adapters it knows; the + triage adapter is assigned AFTER that, so a distinct one would otherwise keep + `journal = None` and every sweep triage session would emit no idle events. + + ABLATION: drop the `self.adapters["triage"].journal = self.journal` line and + the distinct-adapter assertion reddens.""" + triage = MockAdapter([]) + engine, dev = make_sweep(project, [], triage_adapter=triage) + assert engine.adapters["triage"] is triage + assert engine.adapters["triage"].journal is engine.journal + assert dev.journal is engine.journal + + def test_remaining_estimate_is_none_for_an_undecodable_ledger(project): """`None` and `0` mean opposite things to the graceful stop, and both are PUBLISHED — in the `run-stop` journal row and the stop notice. `None` is "no diff --git a/tests/test_tui_app.py b/tests/test_tui_app.py index 4284aba79..ad3acb8fe 100644 --- a/tests/test_tui_app.py +++ b/tests/test_tui_app.py @@ -5222,6 +5222,52 @@ async def test_active_agent_shows_in_header_and_task_cell(project, monkeypatch): ) +async def test_header_agent_line_shows_open_idle_stretch(project, monkeypatch): + """#680: with a `session-idle` open for the live session the agent line ends + `· idle `; after the matching `session-active` the text is gone. Drives + `show_run` with an `ActiveAgent` directly (the derivation is + `test_tui_data`'s) and pins the age formatter's two shapes. + + ABLATION E: drop the `idle_since` branch in `show_run` and the first + assertion reddens; the negative rows hold on their own only because the + positive one passes.""" + monkeypatch.setattr(widgets.time, "time", lambda: 10_000.0) + state = RunState( + run_id="r1", + project=str(project.project), + started_at="now", + tasks={"1-1-alpha": StoryTask(story_key="1-1-alpha", epic=1, phase=Phase.DEV_RUNNING)}, + ) + working = data.ActiveAgent( + task_id="1-1-alpha-dev-1", story_key="1-1-alpha", role="dev", name="claude", model="opus" + ) + app = BmadLoopApp(project.project) + async with app.run_test(): + header = dashboard(app).query_one("#runheader", RunHeader) + header.show_run("r1", data.RUNNING, state, agent=working) + assert "claude · opus · dev" in str(header.content) + assert "idle" not in str(header.content) + + idle = dataclasses.replace(working, idle_since=10_000.0 - 12 * 60 - 5) + header.show_run("r1", data.RUNNING, state, agent=idle) + assert "claude · opus · dev · idle 12m" in str(header.content) + + long_idle = dataclasses.replace(working, idle_since=10_000.0 - 65 * 60) + header.show_run("r1", data.RUNNING, state, agent=long_idle) + assert "· idle 1h05m" in str(header.content) + + # a stamp from the future (a clock stepped back between the adapter's + # stamp and this render) clamps to 0m rather than rendering a minus sign + future = dataclasses.replace(working, idle_since=10_000.0 + 5) + header.show_run("r1", data.RUNNING, state, agent=future) + assert "· idle 0m" in str(header.content) + + header.show_run("r1", data.RUNNING, state, agent=working) # session-active + assert "idle" not in str(header.content) + header.show_run("r1", data.RUNNING, state, agent=None) # session-end + assert "idle" not in str(header.content) + + async def test_idle_run_shows_configured_agents_and_cell_falls_back(project, monkeypatch): # No session open (session-start then a matching session-end): the header shows # the configured adapters from the snapshot (dev/review differ, so the full diff --git a/tests/test_tui_data.py b/tests/test_tui_data.py index 6163cc11e..dfae6e90a 100644 --- a/tests/test_tui_data.py +++ b/tests/test_tui_data.py @@ -935,6 +935,76 @@ def test_active_agent_labeled_session_peels_story_key(): assert (agent.name, agent.model) == ("codex", "gpt-5") +def _stamped_start(task_id="1-1-alpha-dev-3"): + return { + "kind": "session-start", + "task_id": task_id, + "role": "dev", + "adapter": "claude", + "model": "opus", + "story_key": "1-1-alpha", + } + + +def test_active_agent_idle_since_from_open_idle_stretch(): + """#680: the last `session-idle` for the open session's task, not closed by a + later `session-active`, sets `idle_since` to its `since_ts`; the default is + None, so every existing construction and comparison stands. + + ABLATION E: drop the `_idle_since` derivation and the first assertion reddens.""" + entries = [ + _stamped_start(), + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": 5030.0, "idle_s": 60.0}, + ] + agent = data.active_agent(entries, None) + assert agent is not None and agent.idle_since == 5030.0 + assert data.active_agent([_stamped_start()], None).idle_since is None + + +def test_active_agent_idle_since_cleared_by_session_active_and_session_end(): + idle = {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": 5030.0} + active = {"kind": "session-active", "task_id": "1-1-alpha-dev-3", "idle_s": 120.0} + agent = data.active_agent([_stamped_start(), idle, active], None) + assert agent is not None and agent.idle_since is None + # a later stretch reopens it with its own since_ts + later = {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": 5150.0} + agent = data.active_agent([_stamped_start(), idle, active, later], None) + assert agent is not None and agent.idle_since == 5150.0 + # session-end closes the session: no agent at all + ended = {"kind": "session-end", "task_id": "1-1-alpha-dev-3"} + assert data.active_agent([_stamped_start(), idle, ended], None) is None + + +def test_active_agent_idle_since_ignores_other_tasks_and_earlier_sessions(): + """A `session-idle` for another task, or one left behind by an EARLIER session + (before this session-start), is not this session's.""" + stale = {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": 4000.0} + other = {"kind": "session-idle", "task_id": "2-2-beta-dev-1", "since_ts": 5030.0} + agent = data.active_agent([stale, _stamped_start(), other], None) + assert agent is not None and agent.idle_since is None + + +def test_active_agent_idle_since_never_raises_on_malformed_entry(): + """A `session-idle` without a numeric `since_ts` is skipped (the TUI ages the + text from it); the agent itself is still derived.""" + for bad in ( + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3"}, + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": "soon"}, + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": None}, + ): + agent = data.active_agent([_stamped_start(), bad], None) + assert agent is not None and agent.idle_since is None + # an int since_ts is a number too + agent = data.active_agent( + [ + _stamped_start(), + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": 5030}, + ], + None, + ) + assert agent is not None and agent.idle_since == 5030.0 + + def test_active_agent_none_without_resolvable_snapshot(): # Unstamped entry + no trustworthy snapshot: an all-"claude" reconstruction # would mislabel a run that predates stamping, so the agent is unknown. From c461fd3597c79203618a6089f83c96b65299a584 Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 19:32:58 -0700 Subject: [PATCH 02/17] fix(adapters): re-sample the pane frame before each no-work exit verdict Output that lands during `watcher.wait_for` and is followed by window death or a `SessionEnd` in the same iteration was judged on the previous tick's key, so genuine post-frame work in a session's final seconds read as no work and paused the run instead of the normal crash retry. `produced_work()` now runs the same frame sample the top of the tick does; the post-nudge exclusion is unchanged because `stall_nudges_sent` is already positive on every tick after the nudge. Codex review finding on #822. --- src/bmad_loop/adapters/generic.py | 34 ++++++++++++++++++++++--------- tests/test_generic_tmux.py | 27 ++++++++++++++++++++++++ 2 files changed, 51 insertions(+), 10 deletions(-) diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index ab4334b63..9a895ccd9 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -774,8 +774,30 @@ def wait_for_completion(self, handle: SessionHandle, spec: SessionSpec) -> Sessi frame_key = self._log_activity_key(handle.task_id) activity_seen = False + def sample_frame() -> None: + # One pane-frame sample: flip `activity_seen` on growth that lands later + # than FIRST_FRAME_S after the loop started and before the first stall + # wake nudge. Called at the top of every tick and again by + # `produced_work()` right before each exit verdict, because output that + # arrives during `watcher.wait_for` and is followed by window death or a + # `SessionEnd` in the same iteration would otherwise be judged on the + # previous tick's key. The post-nudge exclusion holds on the re-sample + # too: `stall_nudges_sent` is already > 0 on every tick after the nudge. + nonlocal frame_key, activity_seen + tick_key = self._log_activity_key(handle.task_id) + if tick_key is not None and tick_key != frame_key: + if ( + not activity_seen + and stall_nudges_sent == 0 + and time.monotonic() - loop_started > FIRST_FRAME_S + ): + activity_seen = True + frame_key = tick_key + def produced_work() -> bool: - # Read at call time, so every exit below reports the loop's final view. + # Read at call time, after a final frame sample, so every exit below + # reports the loop's final view of the pane rather than the last tick's. + sample_frame() return self._work_verdict(handle, stop_seen, activity_seen) # Idle detection (#680): the live transcript's (mtime_ns, size), sampled on @@ -790,15 +812,7 @@ def produced_work() -> bool: # the timeout check so growth on the final tick still counts; before the # nudge arm so a tick that both sees growth and sends a nudge scores the # growth (the nudge cannot have caused what preceded it). - tick_key = self._log_activity_key(handle.task_id) - if tick_key is not None and tick_key != frame_key: - if ( - not activity_seen - and stall_nudges_sent == 0 - and time.monotonic() - loop_started > FIRST_FRAME_S - ): - activity_seen = True - frame_key = tick_key + sample_frame() remaining = deadline - time.monotonic() wall_expired = time.time() >= wall_deadline if remaining <= 0 or wall_expired: diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 323763aff..2bdd06729 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6465,6 +6465,33 @@ def script(call_n): assert result.produced_work is True +def test_growth_during_the_final_wait_then_death_in_the_same_tick_is_work(tmp_path, monkeypatch): + """Output that lands during `watcher.wait_for` and is followed by window death + in the SAME iteration: the top-of-tick sample predates the growth, so the exit + verdict must re-sample the pane before judging. Past FIRST_FRAME_S, no nudge + sent — `crashed`, but the session worked (`produced_work=True`). + + ABLATION: drop the `sample_frame()` call inside `produced_work()` and the exit + judges the previous tick's key — False.""" + monkeypatch.setattr(generic, "RESULT_GRACE_S", 0.0) + adapter, _ = make_dev_adapter(tmp_path, mux=_UnitMux()) + alive = {"v": True} + adapter._window_alive = lambda handle: alive["v"] + log = _pane_log(adapter, "3-1-dev-1", 0) + clock = _steerable_clock(monkeypatch) + + def script(call_n): + # inside wait_for: the CLI prints its last output and exits before the + # liveness probe that follows this very call + clock["t"] += generic.FIRST_FRAME_S + 1.0 + _grow(log, b"Wrote src/bmad_loop/engine.py\nTraceback (most recent call last):\n") + alive["v"] = False + + adapter.watcher = _ScriptedWatcher([], on_call=script) + result = adapter.wait_for_completion(_dev_handle(), _dev_spec(tmp_path)) + assert (result.status, result.produced_work) == ("crashed", True) + + def test_growth_inside_first_frame_window_alone_is_not_work(tmp_path, monkeypatch): """The complement of the row above, isolating ABLATION B from the nudge arm: the same growth landing INSIDE FIRST_FRAME_S (no nudge ever sent — the From c7a83ee0e02a3dd358e90f64064f0b87847c38fe Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 19:47:38 -0700 Subject: [PATCH 03/17] fix(adapters): count transcript growth and nonzero usage as produced work With a misbound pane sink (#254/#217) the pane log stays at 0 bytes while the CLI works; the no-work verdict read only the pane and `stop_seen`, so such a session that crashed, timed out or tripped the token budget before a Stop was filed as no work and paused the run instead of taking the normal retry/budget path. `_IdleTracker.moved` latches the first transcript change after its first heartbeat sample and `usage_seen` latches a nonzero weighted spend; either is the model having produced tokens, evidence a pane sink cannot hide and a nudge echo cannot fabricate, so neither carries the first-frame or nudge guard. Codex review finding on #822. --- CHANGELOG.md | 6 +-- docs/FEATURES.md | 2 +- src/bmad_loop/adapters/base.py | 8 ++-- src/bmad_loop/adapters/generic.py | 35 ++++++++++++---- tests/test_generic_tmux.py | 68 +++++++++++++++++++++++++++++++ 5 files changed, 104 insertions(+), 15 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1367ecd20..04b780a2b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,9 +19,9 @@ breaking changes may land in a minor release. ### Fixed - Pause a dev session that produced no work instead of retrying into the same wall - (#727). `SessionResult.produced_work` is `false` when no turn ended and the pane - never changed after its first frame before any wake nudge (a permission dialog, a - login, a dead-on-arrival window); `decide_dev` pauses ahead of the budget as an + (#727). `SessionResult.produced_work` is `false` when no turn ended, the pane + never changed after its first frame before any wake nudge, and the transcript + never grew (a permission dialog, a login, a dead-on-arrival window); `decide_dev` pauses ahead of the budget as an environment fault does, `dev-decision` and `session-end` carry the flag, and re-arm resets the attempt. diff --git a/docs/FEATURES.md b/docs/FEATURES.md index 7648625c2..15971852d 100644 --- a/docs/FEATURES.md +++ b/docs/FEATURES.md @@ -74,7 +74,7 @@ See [README.md](../README.md) for the narrative overview and [setup-guide.md](se - Typed escalations: `CRITICAL` pauses the run + notifies (desktop + `ATTENTION` file); `PREFERENCE` is journaled and continues. A story's escalation trail is append-only and deliberately survives a re-arm (it is the run-dir audit a later resolve cycle reads), so a second `bmad-loop resolve` used to re-present every CRITICAL the story ever raised, interleaved with the new ones and with nothing marking which was which — against a resolve skill whose contract is singular. An interactive resolve session that records a `resolution.json` now **watermarks** the trail at its current length, and every later cycle hands the agent only the escalations recorded since; how many earlier ones were withheld is printed to your terminal, never added to the agent's `context.json`. When that filtered list contains entries, the resolve skill presents them newest-first under the existing globally de-duplicated contract. When a new pause precedes any newer recorded escalation and the filtered list is empty, the skill presents `paused_reason` as the available current-pause evidence and discloses that no newer recorded detail exists; it does not read below the watermark, recover an older artifact entry, or synthesize an escalation object. The watermark moves only on a gesture that actually accepted a resolution — a resolve session that exited without writing one, `resolve --no-interactive`, and the TUI's Re-arm button all leave it where it stands. Leaving a watermark is not clearing it: a watermark already standing still filters on those paths, which show everything recorded since the last accepted resolution rather than the whole trail. That is where the bias is deliberate, and it is a claim about which GESTURES move the watermark: one that accepted nothing never moves it. Within a cycle that DID accept a resolution the watermark covers everything that cycle PRESENTED — it is stamped at the trail's length, not at the entries individually answered — so answering one of five escalations shown together retires all five. A task's watermark is reported as the `esc-upto` column of `bmad-loop diagnose`'s markdown task table, and as `escalations_resolved_upto` under `--json` (that is the key to grep in a support bundle), which is what explains a short or empty `context.json` escalation list on a bug report. - A rejected dev attempt notifies too, with its reason (#640). RETRY was the only dev outcome that rejected an attempt silently, and it is the one that discards a completed implementation — the non-fixable leg resets the tree to baseline. The notice fires once per rejected attempt in an uninterrupted run (so ordinarily at most `max_dev_attempts` per story) and has no suppression knob of its own; it follows `[notify]` like every other notice. One attempt can raise it twice: the notice precedes the rollback, so a host that dies in between replays that verdict on resume and announces it again — treat the count as a floor on attempts rejected, not an exact tally. The reason is reduced to its first line and capped, with a `[…]` marker when it was trimmed, because a `Decision.reason` routinely carries a verify-output tail that would otherwise spill into `ATTENTION` and a desktop bubble; the untruncated reason stays in the `dev-decision` journal entry. It fires above the fixable/non-fixable split, so on a leg that goes on to pause for manual recovery the operator sees both notices. - Environment faults pause without burning budget (#194): a session whose coding CLI never reached the API — a verify command whose _environment_ is broken (`sh` reports rc `126`/`127`; on Windows a missing tool is caught by its `is not recognized` message or by resolving the command's leading token, and a command naming a file `cmd` cannot execute — a `.sh`, or any extension outside `PATHEXT`, which cmd hands to the file association and which exits `0` without running anything — is a fault rather than a silent rc `0` pass, #302; and on either OS a verify command whose child could not be started at all — most often because the directory it was to run in is missing, is a file, or cannot be searched, but any spawn-time `OSError` counts — is translated into the same fault instead of crashing the run, since no exit code exists to classify) **or** a session whose log matches the profile's `env_fault_patterns` (an `API Error … Connection refused`-class transport failure, or a provider quota/usage-limit refusal, that idled out the session clock) — pauses the run with the matched evidence instead of charging the attempt and deferring the story as if its code were broken. Re-arm restores the budget. Patterns are per-profile: `claude` seeds three, reproducing only complete error sentences its CLI was captured printing (connection loss, and the two captured provider 5xx refusals — statuses enumerated, never ranged, so an uncaptured `503` stays prose), so a story that merely writes _about_ a provider error cannot trip them (#507); `opencode` seeds a provider quota/rate-limit and connection pair (#323), matched against the `opencode serve` process's own stdout, which the model cannot write to; the other four profiles ship none. Each adapter matches them against the log named by its `ENV_FAULT_LOG_SUFFIX` — the tmux pane capture `logs/.log`, or `.server.out` (the `opencode serve` process's own stdout) for `opencode-http`, never that adapter's model-written transcript. A pattern is only sound against a log the model cannot write to; where that does not hold — the pane capture — the pattern has to reproduce a whole captured sentence, because an error token plus a cause on the same line is precisely the shape a story writing about the error emits, and that framing is what the guard now refuses (#507). A usage-limit / quota cause stays unseeded on the pane-capture profiles for the same evidentiary reason: no captured line exists for them (#323). Extend or disable them in a project profile overlay. -- A session that never did anything pauses instead of retrying (#727). A dev CLI parked on a permission dialog, a login, or a dead-on-arrival window ends `stalled`/`crashed`/`timeout`, and all three used to RETRY while budget lasted — a fresh session into the identical wall, `max_dev_attempts` burned without a line of work. The tmux adapter now stamps `produced_work` on every non-completed result: `true` when a `Stop` arrived (a turn ended), when there is no pane log to read (opencode-http, "unknown never blocks"), or when the pane log changed on a tick more than 30 s (`FIRST_FRAME_S`) after the wait loop started and before the first stall wake nudge went out; `false` otherwise. The first frame is excluded because a parked CLI paints exactly once — the #727 capture is a 1,930-byte dialog, which clears the #261 read-back gate's 256-byte floor, so that floor is deliberately not the predicate — and post-nudge growth is excluded because the nudge's `Enter` confirms the dialog's default and the pane grows with the echo and exit text, the loop's own keystrokes. `decide_dev` PAUSEs a `produced_work=false` result ahead of the budget, exactly as an environment fault does (`no work produced: dev session (no turn ended and the pane never changed after its first frame — the CLI is likely waiting on a human: a permission prompt, a login, a confirmation; the attempt is not charged)`), the env-fault arm outranks it, the `#489` lost-session suffix survives inside it, and re-arm resets `attempt` to `0`. The flag rides `dev-decision` beside `session_vanished` and, when `false`, every role's `session-end`. Two deliberate costs, both toward today's behavior: a CLI slower than 30 s to paint at all retries as before, and a session that woke only after a nudge and then never ended a turn pauses for the operator instead of retrying. The review, fix and sweep deciders are unchanged, and `stall_deadline`, its pane-growth re-arm and the nudge budget are untouched. +- A session that never did anything pauses instead of retrying (#727). A dev CLI parked on a permission dialog, a login, or a dead-on-arrival window ends `stalled`/`crashed`/`timeout`, and all three used to RETRY while budget lasted — a fresh session into the identical wall, `max_dev_attempts` burned without a line of work. The tmux adapter now stamps `produced_work` on every non-completed result: `true` when a `Stop` arrived (a turn ended), when there is no pane log to read (opencode-http, "unknown never blocks"), when the pane log changed on a tick more than 30 s (`FIRST_FRAME_S`) after the wait loop started and before the first stall wake nudge went out, or when the CLI's own transcript changed after its first heartbeat sample or the usage sampler read a nonzero spend from it (the model produced tokens — evidence a misbound pane sink, #254/#217, cannot hide and a nudge echo cannot fabricate, so neither carries the first-frame or nudge guard); `false` otherwise. The first frame is excluded because a parked CLI paints exactly once — the #727 capture is a 1,930-byte dialog, which clears the #261 read-back gate's 256-byte floor, so that floor is deliberately not the predicate — and post-nudge growth is excluded because the nudge's `Enter` confirms the dialog's default and the pane grows with the echo and exit text, the loop's own keystrokes. `decide_dev` PAUSEs a `produced_work=false` result ahead of the budget, exactly as an environment fault does (`no work produced: dev session (no turn ended and the pane never changed after its first frame — the CLI is likely waiting on a human: a permission prompt, a login, a confirmation; the attempt is not charged)`), the env-fault arm outranks it, the `#489` lost-session suffix survives inside it, and re-arm resets `attempt` to `0`. The flag rides `dev-decision` beside `session_vanished` and, when `false`, every role's `session-end`. Two deliberate costs, both toward today's behavior: a CLI slower than 30 s to paint at all retries as before, and a session that woke only after a nudge and then never ended a turn pauses for the operator instead of retrying. The review, fix and sweep deciders are unchanged, and `stall_deadline`, its pane-growth re-arm and the nudge budget are untouched. - An idle session is visible while it sits (#680). A session idling inside a tool call (`sleep 590; cat …`) keeps its pane log growing through spinner repaints, so the stall re-arm — correctly — never fires and nothing separated it from a working session but `session_timeout_min`. The adapter now stats the live transcript's `(mtime_ns, size)` on the heartbeat cadence from the first hook event that names it (a stat, never parsed usage, so it works for `usage_parser = "none"`), stamps the age on `heartbeat.json` as `transcript_idle_s` (`null` before a transcript is known), and — when the run's journal is attached, which the engine does for every adapter it owns — journals one `session-idle` (`task_id`, `idle_s`, `since_ts`, `threshold_s`) when the age crosses `limits.dev_stall_grace_s` and one `session-active` (`task_id`, `idle_s`) when the transcript moves again; a later stretch emits a fresh pair. The threshold is the stall grace on purpose — the event fires exactly when the session _would_ have stalled had its pane not kept repainting, so the two records are directly comparable — and `0` disables the events with no new knob. The TUI's agent line shows the open stretch as `· idle `. Observability only: nothing bounds the stretch, and the session is neither nudged, stalled nor killed for it. - A session the multiplexer lost says so (#489). Sessions complete on a hook `Stop` or on window death, and a window is gone whether the CLI exited or something destroyed the whole mux session out from under the run — an external reaper, a concurrent prune or `bmad-loop stop`, an operator `kill-session`, a server crash, the host sleeping. Both are `crashed`, so the retry/defer reason an operator reads said only `dev session crashed` — pointing at the agent when the host was at fault. The crash verdict now asks whether the _session_ still exists and, when it does not, says so in the reason (`… session crashed: the multiplexer no longer reports the session, so the window's disappearance is not evidence the CLI exited`), as `session_vanished` on `dev-decision` and `fix-decision` either way, beside the routing each fed, on every role's `session-end` journal entry when it is true (the convention `env_fault` already uses there), and as a `session-vanished` breadcrumb in `session-lifecycle.jsonl`. The repair path carries it the same way: when fix attempts are exhausted the defer names the lost session instead of blaming the tree for repairs that never ran. The wording states what the evidence _withdraws_, not what it proves: `has_session` maps every nonzero backend result to False, so a negative lookup is "the backend did not confirm it" rather than proof the session is gone — enough to stop an operator reading window death as a CLI exit, not enough to name a destroyer. It composes with an environment-fault pause instead of being swallowed by it. A session reaped _after_ flushing its result still scores `completed` and is not diagnosed — it produced something. Diagnosis only — the routing is unchanged, and a retry re-creates the session. - CRITICAL resolution: `bmad-loop resolve ` opens an interactive resolve agent seeded with the escalation + frozen spec; you disambiguate, it re-arms the story (`escalated → pending`, spec reset to `ready-for-dev`) and resumes. `--no-interactive` skips to re-arm if you fixed the spec yourself. The re-arm advances the story's diff --git a/src/bmad_loop/adapters/base.py b/src/bmad_loop/adapters/base.py index c9db9df29..d5b261616 100644 --- a/src/bmad_loop/adapters/base.py +++ b/src/bmad_loop/adapters/base.py @@ -259,10 +259,12 @@ class SessionResult: # Whether the session showed ANY sign of working before it ended on a # non-completed verdict (#727). `True` when a `Stop` arrived, when the adapter # has no pane log to read (opencode-http, unit fixtures — "unknown never - # blocks"), or when the pane log changed on a tick later than + # blocks"), when the pane log changed on a tick later than # `generic.FIRST_FRAME_S` after the wait loop started and before the first - # stall wake nudge was sent. `False` means the CLI painted at most its first - # frame and then sat still until the grace, the nudge and the exit: a + # stall wake nudge was sent, or when the CLI's own transcript changed after + # its first sample / the usage sampler read a nonzero spend from it (writes a + # misbound pane sink cannot hide). `False` means the CLI painted at most its + # first frame and then sat still until the grace, the nudge and the exit: a # permission dialog, a login prompt, a dead-on-arrival window. `decide_dev` # PAUSEs such a session ahead of the attempt budget, the way an environment # fault does, so re-arm restores the attempt instead of a fresh session being diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 9a895ccd9..8eba0c6e7 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -150,6 +150,10 @@ class _IdleTracker: last_change_wall: float = 0.0 idle_s: float | None = None open_since: float | None = None + # Latched True the first time the key CHANGES after the first sample: the CLI + # appended to its own transcript, which is the #727 no-work verdict's + # transcript half (see `_work_verdict`). Never reset. + moved: bool = False # min spacing between heartbeat.json overwrites in wait_for_completion; the @@ -336,8 +340,12 @@ def _work_verdict(self, handle: SessionHandle, stop_seen: bool, activity_seen: b same reasons: a `Stop` arrived (a turn ended — the hook half, immune to a misbound pane sink); there is no pane log to read (`_log_evidence` is None — opencode-http, unit fixtures — and unknown never blocks); or the wait loop - saw the pane log change on a tick later than `FIRST_FRAME_S` after it started - and before any stall wake nudge was sent (`activity_seen`, the timeline half). + saw activity (`activity_seen`): the pane log changed on a tick later than + `FIRST_FRAME_S` after it started and before the first stall wake nudge (the + timeline half), OR the live transcript changed after its first sample, OR + the usage sampler read a nonzero spend from it — the last two are the CLI's + own writes, which a misbound pane sink cannot hide and a nudge echo cannot + produce, so neither carries the first-frame or nudge guard. The timeline half is what separates this from `_produced_work`, and why the #261 gate is reused for its tristate only, not its verdict: that gate's @@ -794,12 +802,6 @@ def sample_frame() -> None: activity_seen = True frame_key = tick_key - def produced_work() -> bool: - # Read at call time, after a final frame sample, so every exit below - # reports the loop's final view of the pane rather than the last tick's. - sample_frame() - return self._work_verdict(handle, stop_seen, activity_seen) - # Idle detection (#680): the live transcript's (mtime_ns, size), sampled on # the heartbeat cadence from the first tick that knows `transcript_path` # — see `_sample_transcript_idle`. Observes only: nothing here nudges, @@ -807,6 +809,19 @@ def produced_work() -> bool: # neither consulted nor touched. idle = _IdleTracker() + # Definitive activity the pane cannot fake and a misbound pane sink + # (#254/#217) cannot hide: the CLI appended to its own transcript + # (`idle.moved`, sampled on the heartbeat cadence below) or the usage + # sampler read a nonzero spend from it (`usage_seen`). Either one is the + # model having produced tokens, so it counts as work whatever the pane did. + usage_seen = False + + def produced_work() -> bool: + # Read at call time, after a final frame sample, so every exit below + # reports the loop's final view of the pane rather than the last tick's. + sample_frame() + return self._work_verdict(handle, stop_seen, activity_seen or idle.moved or usage_seen) + while True: # Top-of-tick pane-frame sample for the no-work verdict (#727). Before # the timeout check so growth on the final tick still counts; before the @@ -897,6 +912,8 @@ def produced_work() -> bool: and transcript_path ): weighted = self._sample_weighted_usage(transcript_path, spec) + if weighted is not None and weighted > 0: + usage_seen = True if weighted is not None and weighted > spec.token_budget: budget_tripped = True budget_weighted = weighted @@ -1291,6 +1308,8 @@ def _sample_transcript_idle( if key is None: return if key != idle.last_key: + if idle.last_key is not None: + idle.moved = True if idle.open_since is not None and self.journal is not None: try: self.journal.append( diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 2bdd06729..9f413cbb8 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6492,6 +6492,74 @@ def script(call_n): assert (result.status, result.produced_work) == ("crashed", True) +def test_transcript_growth_under_a_static_pane_is_work(tmp_path, monkeypatch): + """A misbound pane sink (#254/#217): the pane log exists at 0 bytes forever, + but the transcript a `SessionStart` named keeps growing — the CLI is writing + its own record. No `Stop` before the deadline: `timeout`, but the session + worked, so `produced_work=True` and the decision keeps today's routing. + + ABLATION: drop `idle.moved` from `produced_work()` and this reads False.""" + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_grace_s = 0.0 # only the deadline can end this + # the pane never grows: `_idle_adapter`'s script is replaced below, and the log + # stays the 0-byte file `_pane_log` created + + def script(call_n): + if call_n >= 2: + clock["t"] += generic.HEARTBEAT_INTERVAL_S + if call_n == 4: + _grow(transcript, b'{"type":"assistant"}\n') # the CLI's own write + if call_n == 6: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert (adapter.logs_dir / "3-1-dev-1.log").stat().st_size == 0 # pane said nothing + assert (result.status, result.produced_work) == ("timeout", True) + + +def test_static_transcript_under_a_static_pane_is_no_work(tmp_path, monkeypatch): + """The complement: a named transcript that never changes after its first + sample is not activity — the first sample alone must not latch `moved`.""" + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_grace_s = 0.0 + + def script(call_n): + if call_n >= 2: + clock["t"] += generic.HEARTBEAT_INTERVAL_S + if call_n == 6: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert (result.status, result.produced_work) == ("timeout", False) + + +def test_nonzero_usage_under_a_static_pane_is_work(tmp_path, monkeypatch): + """The budget sampler read a nonzero spend from the transcript: the model + produced tokens, which is work whatever the (misbound, 0-byte) pane says. + Enforce mode trips and the grace expires: `over_budget`, `produced_work=True`. + + ABLATION: drop the `usage_seen` latch and this reads False.""" + adapter, clock, _sent = _budget_adapter(tmp_path, monkeypatch) + _pane_log(adapter, "b-1", 0) # present and empty: `_log_evidence` is False, not None + transcript = tmp_path / "t.jsonl" + _write_claude_transcript(transcript, input_tokens=5000) + adapter.watcher = _ScriptedWatcher([_start_event(transcript)], on_call=_advance_31(clock)) + result = adapter.wait_for_completion( + _budget_handle(), _budget_spec(tmp_path, mode="enforce", grace_s=50.0) + ) + assert result.status == "over_budget" + assert result.stop_seen is False + assert result.produced_work is True + + def test_growth_inside_first_frame_window_alone_is_not_work(tmp_path, monkeypatch): """The complement of the row above, isolating ABLATION B from the nudge arm: the same growth landing INSIDE FIRST_FRAME_S (no nudge ever sent — the From b450bf4507b718ecc7ac8202f7d8a6b41a5a98d7 Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 20:01:43 -0700 Subject: [PATCH 04/17] fix(adapters): baseline the transcript when it is first named; re-compare it at exit MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A transcript write between the SessionStart that names it and the next 30 s heartbeat was absorbed into `_IdleTracker.last_key` as the baseline, so a misbound-pane session that worked only inside that interval read as no work. The baseline is now taken the moment a hook event first names the transcript (so the idle age is measured from then), and `produced_work()` compares the transcript against that baseline before each exit verdict — a write inside the final heartbeat interval counts too. FEATURES scopes the idle notice per profile: antigravity fires no SessionStart and names its transcript only on Stop, so its first turn is invisible to the notice. Codex review findings on #822. --- docs/FEATURES.md | 2 +- src/bmad_loop/adapters/generic.py | 17 ++++++++ tests/test_generic_tmux.py | 71 ++++++++++++++++++++++++++++--- 3 files changed, 82 insertions(+), 8 deletions(-) diff --git a/docs/FEATURES.md b/docs/FEATURES.md index 15971852d..5525ca80e 100644 --- a/docs/FEATURES.md +++ b/docs/FEATURES.md @@ -75,7 +75,7 @@ See [README.md](../README.md) for the narrative overview and [setup-guide.md](se - A rejected dev attempt notifies too, with its reason (#640). RETRY was the only dev outcome that rejected an attempt silently, and it is the one that discards a completed implementation — the non-fixable leg resets the tree to baseline. The notice fires once per rejected attempt in an uninterrupted run (so ordinarily at most `max_dev_attempts` per story) and has no suppression knob of its own; it follows `[notify]` like every other notice. One attempt can raise it twice: the notice precedes the rollback, so a host that dies in between replays that verdict on resume and announces it again — treat the count as a floor on attempts rejected, not an exact tally. The reason is reduced to its first line and capped, with a `[…]` marker when it was trimmed, because a `Decision.reason` routinely carries a verify-output tail that would otherwise spill into `ATTENTION` and a desktop bubble; the untruncated reason stays in the `dev-decision` journal entry. It fires above the fixable/non-fixable split, so on a leg that goes on to pause for manual recovery the operator sees both notices. - Environment faults pause without burning budget (#194): a session whose coding CLI never reached the API — a verify command whose _environment_ is broken (`sh` reports rc `126`/`127`; on Windows a missing tool is caught by its `is not recognized` message or by resolving the command's leading token, and a command naming a file `cmd` cannot execute — a `.sh`, or any extension outside `PATHEXT`, which cmd hands to the file association and which exits `0` without running anything — is a fault rather than a silent rc `0` pass, #302; and on either OS a verify command whose child could not be started at all — most often because the directory it was to run in is missing, is a file, or cannot be searched, but any spawn-time `OSError` counts — is translated into the same fault instead of crashing the run, since no exit code exists to classify) **or** a session whose log matches the profile's `env_fault_patterns` (an `API Error … Connection refused`-class transport failure, or a provider quota/usage-limit refusal, that idled out the session clock) — pauses the run with the matched evidence instead of charging the attempt and deferring the story as if its code were broken. Re-arm restores the budget. Patterns are per-profile: `claude` seeds three, reproducing only complete error sentences its CLI was captured printing (connection loss, and the two captured provider 5xx refusals — statuses enumerated, never ranged, so an uncaptured `503` stays prose), so a story that merely writes _about_ a provider error cannot trip them (#507); `opencode` seeds a provider quota/rate-limit and connection pair (#323), matched against the `opencode serve` process's own stdout, which the model cannot write to; the other four profiles ship none. Each adapter matches them against the log named by its `ENV_FAULT_LOG_SUFFIX` — the tmux pane capture `logs/.log`, or `.server.out` (the `opencode serve` process's own stdout) for `opencode-http`, never that adapter's model-written transcript. A pattern is only sound against a log the model cannot write to; where that does not hold — the pane capture — the pattern has to reproduce a whole captured sentence, because an error token plus a cause on the same line is precisely the shape a story writing about the error emits, and that framing is what the guard now refuses (#507). A usage-limit / quota cause stays unseeded on the pane-capture profiles for the same evidentiary reason: no captured line exists for them (#323). Extend or disable them in a project profile overlay. - A session that never did anything pauses instead of retrying (#727). A dev CLI parked on a permission dialog, a login, or a dead-on-arrival window ends `stalled`/`crashed`/`timeout`, and all three used to RETRY while budget lasted — a fresh session into the identical wall, `max_dev_attempts` burned without a line of work. The tmux adapter now stamps `produced_work` on every non-completed result: `true` when a `Stop` arrived (a turn ended), when there is no pane log to read (opencode-http, "unknown never blocks"), when the pane log changed on a tick more than 30 s (`FIRST_FRAME_S`) after the wait loop started and before the first stall wake nudge went out, or when the CLI's own transcript changed after its first heartbeat sample or the usage sampler read a nonzero spend from it (the model produced tokens — evidence a misbound pane sink, #254/#217, cannot hide and a nudge echo cannot fabricate, so neither carries the first-frame or nudge guard); `false` otherwise. The first frame is excluded because a parked CLI paints exactly once — the #727 capture is a 1,930-byte dialog, which clears the #261 read-back gate's 256-byte floor, so that floor is deliberately not the predicate — and post-nudge growth is excluded because the nudge's `Enter` confirms the dialog's default and the pane grows with the echo and exit text, the loop's own keystrokes. `decide_dev` PAUSEs a `produced_work=false` result ahead of the budget, exactly as an environment fault does (`no work produced: dev session (no turn ended and the pane never changed after its first frame — the CLI is likely waiting on a human: a permission prompt, a login, a confirmation; the attempt is not charged)`), the env-fault arm outranks it, the `#489` lost-session suffix survives inside it, and re-arm resets `attempt` to `0`. The flag rides `dev-decision` beside `session_vanished` and, when `false`, every role's `session-end`. Two deliberate costs, both toward today's behavior: a CLI slower than 30 s to paint at all retries as before, and a session that woke only after a nudge and then never ended a turn pauses for the operator instead of retrying. The review, fix and sweep deciders are unchanged, and `stall_deadline`, its pane-growth re-arm and the nudge budget are untouched. -- An idle session is visible while it sits (#680). A session idling inside a tool call (`sleep 590; cat …`) keeps its pane log growing through spinner repaints, so the stall re-arm — correctly — never fires and nothing separated it from a working session but `session_timeout_min`. The adapter now stats the live transcript's `(mtime_ns, size)` on the heartbeat cadence from the first hook event that names it (a stat, never parsed usage, so it works for `usage_parser = "none"`), stamps the age on `heartbeat.json` as `transcript_idle_s` (`null` before a transcript is known), and — when the run's journal is attached, which the engine does for every adapter it owns — journals one `session-idle` (`task_id`, `idle_s`, `since_ts`, `threshold_s`) when the age crosses `limits.dev_stall_grace_s` and one `session-active` (`task_id`, `idle_s`) when the transcript moves again; a later stretch emits a fresh pair. The threshold is the stall grace on purpose — the event fires exactly when the session _would_ have stalled had its pane not kept repainting, so the two records are directly comparable — and `0` disables the events with no new knob. The TUI's agent line shows the open stretch as `· idle `. Observability only: nothing bounds the stretch, and the session is neither nudged, stalled nor killed for it. +- An idle session is visible while it sits (#680). A session idling inside a tool call (`sleep 590; cat …`) keeps its pane log growing through spinner repaints, so the stall re-arm — correctly — never fires and nothing separated it from a working session but `session_timeout_min`. The adapter now stats the live transcript's `(mtime_ns, size)` — a baseline the moment the first hook event names it, then on the heartbeat cadence (a stat, never parsed usage, so it works for `usage_parser = "none"`) — stamps the age on `heartbeat.json` as `transcript_idle_s` (`null` before a transcript is known), and — when the run's journal is attached, which the engine does for every adapter it owns — journals one `session-idle` (`task_id`, `idle_s`, `since_ts`, `threshold_s`) when the age crosses `limits.dev_stall_grace_s` and one `session-active` (`task_id`, `idle_s`) when the transcript moves again; a later stretch emits a fresh pair. The threshold is the stall grace on purpose — the event fires exactly when the session _would_ have stalled had its pane not kept repainting, so the two records are directly comparable — and `0` disables the events with no new knob. The TUI's agent line shows the open stretch as `· idle `. Observability only: nothing bounds the stretch, and the session is neither nudged, stalled nor killed for it. Scope: the notice starts when a hook event names the transcript — `SessionStart` on the `claude`, `codex`, `gemini` and `copilot` profiles, so it covers a session's first turn there; `antigravity` fires no `SessionStart` and names the transcript only on its `Stop`, so its first turn is invisible to the notice (the heartbeat's `transcript_idle_s` stays `null` until then), and the `opencode-http` transport has no pane wait loop and emits neither the field nor the events. - A session the multiplexer lost says so (#489). Sessions complete on a hook `Stop` or on window death, and a window is gone whether the CLI exited or something destroyed the whole mux session out from under the run — an external reaper, a concurrent prune or `bmad-loop stop`, an operator `kill-session`, a server crash, the host sleeping. Both are `crashed`, so the retry/defer reason an operator reads said only `dev session crashed` — pointing at the agent when the host was at fault. The crash verdict now asks whether the _session_ still exists and, when it does not, says so in the reason (`… session crashed: the multiplexer no longer reports the session, so the window's disappearance is not evidence the CLI exited`), as `session_vanished` on `dev-decision` and `fix-decision` either way, beside the routing each fed, on every role's `session-end` journal entry when it is true (the convention `env_fault` already uses there), and as a `session-vanished` breadcrumb in `session-lifecycle.jsonl`. The repair path carries it the same way: when fix attempts are exhausted the defer names the lost session instead of blaming the tree for repairs that never ran. The wording states what the evidence _withdraws_, not what it proves: `has_session` maps every nonzero backend result to False, so a negative lookup is "the backend did not confirm it" rather than proof the session is gone — enough to stop an operator reading window death as a CLI exit, not enough to name a destroyer. It composes with an environment-fault pause instead of being swallowed by it. A session reaped _after_ flushing its result still scores `completed` and is not diagnosed — it produced something. Diagnosis only — the routing is unchanged, and a retry re-creates the session. - CRITICAL resolution: `bmad-loop resolve ` opens an interactive resolve agent seeded with the escalation + frozen spec; you disambiguate, it re-arms the story (`escalated → pending`, spec reset to `ready-for-dev`) and resumes. `--no-interactive` skips to re-arm if you fixed the spec yourself. The re-arm advances the story's baseline in the **code tree** and is honest when it cannot: a failed advance is narrowed to typed git diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 8eba0c6e7..8de10341d 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -820,6 +820,13 @@ def produced_work() -> bool: # Read at call time, after a final frame sample, so every exit below # reports the loop's final view of the pane rather than the last tick's. sample_frame() + if transcript_path and not idle.moved and idle.last_key is not None: + # Same for the transcript: a write inside the final heartbeat + # interval has not been sampled yet. Compare against the tracker's + # baseline without advancing it — the idle record is the heartbeat's. + key = self._transcript_activity_key(transcript_path) + if key is not None and key != idle.last_key: + idle.moved = True return self._work_verdict(handle, stop_seen, activity_seen or idle.moved or usage_seen) while True: @@ -1170,6 +1177,16 @@ def produced_work() -> bool: # real transcript is preserved for usage tallying. continue session_id = event.session_id or session_id + if event.transcript_path and not transcript_path: + # First observation of the transcript (#680): take the idle + # baseline NOW, not at the next heartbeat, so the age is measured + # from when the transcript became known and every later write — + # including one inside the first heartbeat interval — is seen as a + # change by the #727 transcript latch (`_IdleTracker.moved`) rather + # than absorbed into the baseline. + self._sample_transcript_idle( + handle.task_id, event.transcript_path, idle, time.monotonic() + ) transcript_path = event.transcript_path or transcript_path if event.event == "SessionStart": diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 9f413cbb8..b68febe40 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6521,6 +6521,61 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", True) +def test_transcript_write_inside_the_first_heartbeat_interval_is_work(tmp_path, monkeypatch): + """The transcript is written between the `SessionStart` that names it and the + next heartbeat. The idle baseline is taken the moment the transcript is named, + so that write is a CHANGE at the first heartbeat sample — not absorbed into + the baseline. Static pane, no Stop, then timeout: `produced_work=True`. + + ABLATION: drop the `_sample_transcript_idle` call at first observation and the + heartbeat sample becomes the baseline — False.""" + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_grace_s = 0.0 + + def script(call_n): + if call_n == 2: + clock["t"] += 10.0 # inside the first heartbeat interval + _grow(transcript, b'{"type":"assistant"}\n') + elif call_n == 3: + clock["t"] += 20.0 # heartbeat 2 fires at +30 and samples the change + elif call_n == 4: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert (result.status, result.produced_work) == ("timeout", True) + + +def test_transcript_write_in_the_final_interval_is_work(tmp_path, monkeypatch): + """The transcript's only write lands after the last heartbeat sample and the + deadline elapses before another: the exit verdict compares the transcript + against the tracker's baseline itself. `timeout`, `produced_work=True`. + + ABLATION: drop the transcript comparison inside `produced_work()` — False.""" + adapter, _, _log, transcript, clock, heartbeats = _idle_adapter( + tmp_path, monkeypatch, journal=False + ) + adapter._stall_grace_s = 0.0 + + def script(call_n): + if call_n == 2: + clock["t"] += 10.0 + _grow(transcript, b'{"type":"assistant"}\n') + elif call_n == 3: + clock["t"] += 10_000.0 # no heartbeat fires before the deadline check + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert [hb["transcript_idle_s"] for hb in heartbeats] == [None] # never re-sampled + assert (result.status, result.produced_work) == ("timeout", True) + + def test_static_transcript_under_a_static_pane_is_no_work(tmp_path, monkeypatch): """The complement: a named transcript that never changes after its first sample is not activity — the first sample alone must not latch `moved`.""" @@ -6767,14 +6822,16 @@ def script(call_n): assert result.status == "timeout" # the idle stretch itself ended nothing assert mux.sent == [] # never nudged - # heartbeat 1 predates the transcript; the first sample is age 0; the age - # climbs; the move resets it; the second stretch climbs to its own crossing + # heartbeat 1 predates the transcript; the baseline is taken the moment the + # SessionStart names it (mono 1000, inside tick 1), so heartbeat 2 already + # reads 30 s; the age climbs; the move resets it; the second stretch climbs + # to its own crossing assert [hb["transcript_idle_s"] for hb in heartbeats] == [ None, - 0.0, 30.0, 60.0, 90.0, + 120.0, 0.0, 30.0, 60.0, @@ -6789,10 +6846,10 @@ def script(call_n): "kind": "session-idle", "task_id": "3-1-dev-1", "idle_s": 60.0, - "since_ts": 5030.0, # wall time of the first sample (mono 1030) + "since_ts": 5000.0, # wall time the transcript was first named (mono 1000) "threshold_s": 60.0, } - assert active == {"kind": "session-active", "task_id": "3-1-dev-1", "idle_s": 120.0} + assert active == {"kind": "session-active", "task_id": "3-1-dev-1", "idle_s": 150.0} assert second["since_ts"] == 5150.0 # the move at mono 1150 started the new stretch assert second["idle_s"] == 60.0 @@ -6819,7 +6876,7 @@ def script(call_n): adapter.wait_for_completion(_dev_handle(), spec) assert adapter.journal.entries == [] - assert [hb["transcript_idle_s"] for hb in heartbeats] == [None, 0.0, 30.0, 60.0, 90.0, 120.0] + assert [hb["transcript_idle_s"] for hb in heartbeats] == [None, 30.0, 60.0, 90.0, 120.0, 150.0] def test_idle_events_need_an_attached_journal(tmp_path, monkeypatch): @@ -6844,7 +6901,7 @@ def script(call_n): ) spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) adapter.wait_for_completion(_dev_handle(), spec) - assert heartbeats[-1]["transcript_idle_s"] == 120.0 + assert heartbeats[-1]["transcript_idle_s"] == 150.0 def test_idle_age_is_null_without_a_transcript(tmp_path, monkeypatch): From dccc7619de861ad57298b8ffb91dc8404ad7898d Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 20:14:37 -0700 Subject: [PATCH 05/17] fix(adapters): close an idle stretch that ends in the final heartbeat interval MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The exit-time transcript check only latched the #727 verdict; an idle stretch whose transcript moved after the last heartbeat, with the session ending before another, was left open in the journal — a `session-idle` with no `session-active` ahead of `session-end`. The exit now runs the same `_sample_transcript_idle` the heartbeat does, so the stretch is closed and the latch set from one sample. Codex review finding on #822. --- src/bmad_loop/adapters/generic.py | 14 ++++++----- tests/test_generic_tmux.py | 39 +++++++++++++++++++++++++++++-- 2 files changed, 45 insertions(+), 8 deletions(-) diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 8de10341d..fe9e34892 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -820,13 +820,15 @@ def produced_work() -> bool: # Read at call time, after a final frame sample, so every exit below # reports the loop's final view of the pane rather than the last tick's. sample_frame() - if transcript_path and not idle.moved and idle.last_key is not None: + if transcript_path: # Same for the transcript: a write inside the final heartbeat - # interval has not been sampled yet. Compare against the tracker's - # baseline without advancing it — the idle record is the heartbeat's. - key = self._transcript_activity_key(transcript_path) - if key is not None and key != idle.last_key: - idle.moved = True + # interval has not been sampled yet. A full sample, not a bare + # compare, so an idle stretch that ended in that interval is closed + # with its `session-active` before `session-end` lands, and the + # #727 latch (`idle.moved`) sees the write. + self._sample_transcript_idle( + handle.task_id, transcript_path, idle, time.monotonic() + ) return self._work_verdict(handle, stop_seen, activity_seen or idle.moved or usage_seen) while True: diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index b68febe40..fef3cf83d 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6554,7 +6554,7 @@ def test_transcript_write_in_the_final_interval_is_work(tmp_path, monkeypatch): deadline elapses before another: the exit verdict compares the transcript against the tracker's baseline itself. `timeout`, `produced_work=True`. - ABLATION: drop the transcript comparison inside `produced_work()` — False.""" + ABLATION: drop the transcript sample inside `produced_work()` — False.""" adapter, _, _log, transcript, clock, heartbeats = _idle_adapter( tmp_path, monkeypatch, journal=False ) @@ -6854,6 +6854,37 @@ def script(call_n): assert second["idle_s"] == 60.0 +def test_idle_stretch_ending_in_the_final_interval_is_closed_at_exit(tmp_path, monkeypatch): + """An open idle stretch whose transcript moves after the last heartbeat, with + the deadline elapsing before another: the exit-time sample closes it, so the + journal reads `session-idle` then `session-active` ahead of the engine's + `session-end` rather than a stretch that never recovered. + + ABLATION: replace the exit-time `_sample_transcript_idle` with a bare key + compare and the `session-active` is missing.""" + adapter, _, log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch) + + def script(call_n): + if call_n >= 2: + _grow(log, "\r⠋".encode()) # the spinner keeps the pane alive throughout + if 2 <= call_n <= 4: + clock["t"] += generic.HEARTBEAT_INTERVAL_S # ages 30, 60 (crossing), 90 + if call_n == 5: + clock["t"] += 10.0 # inside the final interval: no heartbeat fires + _grow(transcript, b'{"type":"assistant"}\n') + if call_n == 6: + clock["t"] += 10_000.0 # deadline next tick, still no heartbeat first + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert result.status == "timeout" + assert [e["kind"] for e in adapter.journal.entries] == ["session-idle", "session-active"] + assert result.produced_work is True # the same write is the #727 latch + + def test_idle_events_need_a_positive_grace(tmp_path, monkeypatch): """`dev_stall_grace_s = 0` disables the events (no new knob); the heartbeat still stamps the age. @@ -6926,7 +6957,11 @@ def test_unreadable_transcript_stat_skips_the_sample(tmp_path, monkeypatch): """A transcript the hook named but that does not exist yet (or is mid-rename): the stat raises, the key is None, the tick is skipped and the loop goes on. When the file appears the clock starts from THAT sample.""" - adapter, _, log, transcript, clock, heartbeats = _idle_adapter(tmp_path, monkeypatch) + # grace far above the timeline, so the exit-time sample after the final clock + # jump cannot open a stretch: this row is about the None-key skip only + adapter, _, log, transcript, clock, heartbeats = _idle_adapter( + tmp_path, monkeypatch, grace=100_000.0 + ) transcript.unlink() assert generic.GenericAdapter._transcript_activity_key(str(transcript)) is None From ecdbe064383b1892178facf9dc0a421ee0f7e490 Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 20:28:29 -0700 Subject: [PATCH 06/17] fix(adapters): read the idle-notice threshold from policy, not the stall knob MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The plain GenericAdapter — what the sweep's triage role and plugin-workflow sessions run on — leaves `_stall_grace_s` at 0 because it arms no stall timer, so gating the #680 notice on it silenced every triage session under the default policy. `_idle_threshold_s` is now `limits.dev_stall_grace_s` read directly in the base constructor: same knob, no new policy field, and the dev adapter's two values stay equal. Codex review finding on #822. --- src/bmad_loop/adapters/generic.py | 19 ++++++++++++++----- tests/test_generic_tmux.py | 31 +++++++++++++++++++++++++++++++ 2 files changed, 45 insertions(+), 5 deletions(-) diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index fe9e34892..2310c75f1 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -589,6 +589,13 @@ def __init__( # keeps the fail-fast behavior; the dev adapter raises it so a session # that ended its turn awaiting a background process isn't mis-stalled. self._stall_grace_s = 0.0 + # Threshold for the #680 transcript-idle notice, in seconds: the policy's + # `dev_stall_grace_s` read directly, NOT `_stall_grace_s`, because the base + # adapter leaves that at 0 (no stall detection for triage / plugin-workflow + # / non-synthesizing sessions) while the idle notice is observation only + # and belongs to every pane-driven session the same. Same knob, no new + # policy field; 0 disables the notice along with the stall timer. + self._idle_threshold_s = float(policy.limits.dev_stall_grace_s) # Wake-nudges to spend on grace expiry before stalling. 0 here is moot for # the base adapter (grace 0 never opens the window); the dev adapter sets # it from policy so an idle wait is re-invoked rather than killed outright. @@ -1314,9 +1321,11 @@ def _sample_transcript_idle( and leaves the stretch as it was — `_sample_weighted_usage`'s tolerance, for a stat. A key that moved closes any open stretch with one `session-active` carrying the stretch's full length; a key that has not - moved for `_stall_grace_s` opens one with one `session-idle` (`idle_s`, + moved for `_idle_threshold_s` opens one with one `session-idle` (`idle_s`, `since_ts`, `threshold_s`), latched until the key moves again. The - threshold is the stall grace on purpose: the event fires exactly when the + threshold is `limits.dev_stall_grace_s` on purpose — read from policy, so + the plain adapter (triage, plugin workflows) honours it although it arms + no stall timer: on a dev/review session the event fires exactly when the session WOULD have stalled had its pane not kept repainting, so the two records are directly comparable, and `0` disables both. No journal attached (`resolve.run_session`, `probe`, fixtures) means no events; the @@ -1346,8 +1355,8 @@ def _sample_transcript_idle( if ( idle.open_since is None and self.journal is not None - and self._stall_grace_s > 0 - and idle.idle_s >= self._stall_grace_s + and self._idle_threshold_s > 0 + and idle.idle_s >= self._idle_threshold_s ): idle.open_since = idle.last_change_wall try: @@ -1356,7 +1365,7 @@ def _sample_transcript_idle( task_id=task_id, idle_s=idle.idle_s, since_ts=idle.open_since, - threshold_s=self._stall_grace_s, + threshold_s=self._idle_threshold_s, ) except OSError: pass diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index fef3cf83d..9937e137e 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6777,6 +6777,7 @@ def _idle_adapter(tmp_path, monkeypatch, *, grace=60.0, journal=True): mux = _UnitMux() adapter, _ = make_dev_adapter(tmp_path, mux=mux) adapter._stall_grace_s = grace + adapter._idle_threshold_s = grace # the same knob, read from policy in production adapter._stall_nudges = 0 adapter._window_alive = lambda handle: True if journal: @@ -6885,6 +6886,36 @@ def script(call_n): assert result.produced_work is True # the same write is the #727 latch +def test_plain_adapter_honours_the_idle_threshold_from_policy(tmp_path, monkeypatch): + """The plain `GenericAdapter` — what `runsetup.make_adapters` builds for the + sweep's triage role — arms no stall timer (`_stall_grace_s` stays 0), yet the + idle notice must still fire at `limits.dev_stall_grace_s` (600 by default): + the threshold is read from policy, not from the stall knob. + + ABLATION: gate the notice on `_stall_grace_s` instead and this emits nothing.""" + adapter, clock, _sent = _budget_adapter(tmp_path, monkeypatch) + assert adapter._stall_grace_s == 0.0 and adapter._idle_threshold_s == 600.0 + adapter.journal = _FakeJournal() + transcript = tmp_path / "t.jsonl" + transcript.write_bytes(b"{}\n") + + def script(call_n): + if call_n >= 2: + clock["t"] += 300.0 # heartbeats at ages 300 and 600 (the crossing) + clock["wall"] += 300.0 + if call_n == 4: + clock["t"] += 100_000.0 # past the deadline + + adapter.watcher = _ScriptedWatcher([_start_event(transcript)], on_call=script) + result = adapter.wait_for_completion( + _budget_handle(), _budget_spec(tmp_path, mode="off", timeout_s=5000.0) + ) + assert result.status == "timeout" + kinds = [e["kind"] for e in adapter.journal.entries] + assert kinds == ["session-idle"] + assert adapter.journal.entries[0]["threshold_s"] == 600.0 + + def test_idle_events_need_a_positive_grace(tmp_path, monkeypatch): """`dev_stall_grace_s = 0` disables the events (no new knob); the heartbeat still stamps the age. From a27418521632ba5b63630bd108be2102274ea9db Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 20:38:56 -0700 Subject: [PATCH 07/17] docs(tui-guide): name the idle-notice threshold on the dev_stall_grace_s row --- docs/tui-guide.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/tui-guide.md b/docs/tui-guide.md index 55cb93438..670ae7d7f 100644 --- a/docs/tui-guide.md +++ b/docs/tui-guide.md @@ -657,7 +657,7 @@ behavior. | `limits.git_timeout_s` | int ≥ 1 | 120 | bound on any single git subprocess; exceeding it pauses/degrades, never crashes the run — raise on a loaded host or a very large worktree | | `limits.teardown_grace_s` | int ≥ 0 | 20 | verified teardown: poll a killed session up to this long, then force-kill its pane pids and re-kill · 0 = single unverified best-effort kill | | `limits.stop_without_result_nudges` | int ≥ 0 | 1 | nudges when a session stops without result.json | -| `limits.dev_stall_grace_s` | int ≥ 0 | 600 | silence grace armed at dev/review launch and re-armed by transport activity or fresh Stop/idle evidence · 0 = no launch timer, but a result-less turn end still fails fast | +| `limits.dev_stall_grace_s` | int ≥ 0 | 600 | silence grace armed at dev/review launch and re-armed by transport activity or fresh Stop/idle evidence · also the transcript-idle notice threshold (journal `session-idle`/`session-active`, TUI idle age) · 0 = no launch timer (and no idle notice), but a result-less turn end still fails fast | | `limits.dev_stall_nudges` | int ≥ 0 | 2 | best-effort wake nudges per silent grace before stalling; fresh Stop/idle evidence restores this budget · 0 = stall on grace expiry | | `limits.dev_stall_nudges_cap` | int ≥ 0 | 6 | total (never-restored) nudge bound per dev/review session — an accepted nudge does not guarantee a wake · 0 = stall on first grace expiry | | `limits.workflow_stall_nudges_cap` | int ≥ 0 | 3 | same monotonic cap for an injected plugin-workflow session that finished its work but never wrote its completion marker · 0 = stall on first grace expiry | From f52c8fcdf0f346dbd16ebd9437c612d3bf0b7f0e Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 20:50:51 -0700 Subject: [PATCH 08/17] fix(adapters): count a transcript created after its naming as work When SessionStart names a transcript that does not exist yet, the None-key skip left no baseline, so the exit-time sample took the CLI's freshly created and populated file AS the baseline and a static-pane session that worked only in that interval read as no work. `_IdleTracker.seen_absent` remembers the absent sample; the file's later appearance is the CLI's first write and sets `moved`. Codex review finding on #822. --- src/bmad_loop/adapters/generic.py | 20 +++++++++++++++----- tests/test_generic_tmux.py | 27 +++++++++++++++++++++++++++ 2 files changed, 42 insertions(+), 5 deletions(-) diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 2310c75f1..23464f078 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -150,10 +150,15 @@ class _IdleTracker: last_change_wall: float = 0.0 idle_s: float | None = None open_since: float | None = None - # Latched True the first time the key CHANGES after the first sample: the CLI - # appended to its own transcript, which is the #727 no-work verdict's - # transcript half (see `_work_verdict`). Never reset. + # Latched True the first time the key CHANGES after the first sample — or the + # file APPEARS after a sample found it absent: the CLI appended to (or created) + # its own transcript, which is the #727 no-work verdict's transcript half (see + # `_work_verdict`). Never reset. moved: bool = False + # A sample ran while the named transcript could not be stat'ed (not yet + # created). The next successful sample is then the file's creation, which + # counts as movement rather than as the baseline. + seen_absent: bool = False # min spacing between heartbeat.json overwrites in wait_for_completion; the @@ -1319,7 +1324,8 @@ def _sample_transcript_idle( A None key (not yet created, torn by a rename, unreadable) skips the tick and leaves the stretch as it was — `_sample_weighted_usage`'s tolerance, - for a stat. A key that moved closes any open stretch with one + for a stat — but remembers that the named path was absent, so the file's + later appearance is the CLI's first write (`moved`), not the baseline. A key that moved closes any open stretch with one `session-active` carrying the stretch's full length; a key that has not moved for `_idle_threshold_s` opens one with one `session-idle` (`idle_s`, `since_ts`, `threshold_s`), latched until the key moves again. The @@ -1334,9 +1340,13 @@ def _sample_transcript_idle( evidence, alive.""" key = self._transcript_activity_key(transcript_path) if key is None: + if idle.last_key is None: + idle.seen_absent = True return if key != idle.last_key: - if idle.last_key is not None: + if idle.last_key is not None or idle.seen_absent: + # a change since the baseline, or the file appearing after a + # sample found the named path absent — the CLI wrote it either way idle.moved = True if idle.open_since is not None and self.journal is not None: try: diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 9937e137e..55db708ae 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6576,6 +6576,33 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", True) +def test_transcript_created_after_being_named_is_work(tmp_path, monkeypatch): + """`SessionStart` names a transcript that does not exist yet; the CLI creates + and writes it later and then times out with no further write and a static + pane. Creation after an absent sample is the CLI's first write, so the + populated file is movement, not the baseline: `produced_work=True`. + + ABLATION: drop the `seen_absent` arm and the exit-time sample baselines the + populated file — False.""" + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_grace_s = 0.0 + transcript.unlink() + + def script(call_n): + if call_n == 2: + clock["t"] += 10.0 + transcript.write_bytes(b'{"type":"user"}\n{"type":"assistant"}\n') # created + elif call_n == 3: + clock["t"] += 10_000.0 # deadline; only the exit-time sample sees the file + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert (result.status, result.produced_work) == ("timeout", True) + + def test_static_transcript_under_a_static_pane_is_no_work(tmp_path, monkeypatch): """The complement: a named transcript that never changes after its first sample is not activity — the first sample alone must not latch `moved`.""" From 0e135adce9596c7a57fa4e626295e8d344eeec58 Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 21:03:43 -0700 Subject: [PATCH 09/17] fix(adapters): rebaseline the idle tracker when a hook event re-points the transcript A later hook event naming a different transcript left `_IdleTracker.last_key` belonging to the first file, so the next sample compared two unrelated files and could set `moved` (and close a stretch) without a write. The tracker now records the path it sampled and starts over on a new one: first key a baseline, open stretch dropped, `moved` left as it was. CodeRabbit review finding on #822. --- src/bmad_loop/adapters/generic.py | 14 ++++++++++++ tests/test_generic_tmux.py | 36 +++++++++++++++++++++++++++++++ 2 files changed, 50 insertions(+) diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 23464f078..8d905affd 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -145,6 +145,10 @@ class _IdleTracker: `session-idle` carried — or None between stretches: the latch that makes the pair one-per-stretch.""" + # The transcript path the samples below belong to. A later hook event that + # names a DIFFERENT path rebaselines the tracker (`_sample_transcript_idle`): + # a key measured on one file says nothing about another. + path: str | None = None last_key: tuple[int, int] | None = None last_change_mono: float = 0.0 last_change_wall: float = 0.0 @@ -1338,6 +1342,16 @@ def _sample_transcript_idle( age is still measured for `heartbeat.json`. Every write is best-effort — an unwritable journal must not end a session that is, by this very evidence, alive.""" + if idle.path != transcript_path: + # A different transcript than the one sampled so far (a hook event + # re-pointed it): start over on this file — its first key is a + # baseline, not a change, and any open stretch belonged to the old + # file. `moved` stays latched if it already was. + idle.path = transcript_path + idle.last_key = None + idle.idle_s = None + idle.open_since = None + idle.seen_absent = False key = self._transcript_activity_key(transcript_path) if key is None: if idle.last_key is None: diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 55db708ae..48694840c 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6603,6 +6603,42 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", True) +def test_repointed_transcript_rebaselines_instead_of_reading_as_movement(tmp_path, monkeypatch): + """A later hook event names a DIFFERENT transcript. Its key is compared to + nothing the tracker measured before: the new file is a fresh baseline, so a + static second transcript under a static pane is still no work, and the age + restarts from the re-pointing. + + ABLATION: drop the `idle.path` rebaseline and the second file's key differs + from the first file's, reading as movement — True.""" + adapter, _, _log, transcript, clock, heartbeats = _idle_adapter( + tmp_path, monkeypatch, journal=False + ) + adapter._stall_grace_s = 0.0 + other = tmp_path / "other.jsonl" + other.write_bytes(b'{"type":"user","other":true}\n') # exists, differs, never changes + + def script(call_n): + if call_n >= 2: + clock["t"] += generic.HEARTBEAT_INTERVAL_S + if call_n == 5: + clock["t"] += 10_000.0 + + events = [ + _session_start("3-1-dev-1", str(transcript)), + None, + _session_start("3-1-dev-1", str(other)), # re-pointed on tick 3 + ] + adapter.watcher = _ScriptedWatcher(events, on_call=script) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + # ages: none before naming; tick 2's heartbeat is throttled (the clock moves + # inside wait_for); 30 on the first file; then the re-pointed file's own + # clock — 0 at the heartbeat that first sampled it, 30 on the next + assert [hb["transcript_idle_s"] for hb in heartbeats] == [None, 30.0, 0.0, 30.0] + assert (result.status, result.produced_work) == ("timeout", False) + + def test_static_transcript_under_a_static_pane_is_no_work(tmp_path, monkeypatch): """The complement: a named transcript that never changes after its first sample is not activity — the first sample alone must not latch `moved`.""" From 46e96500fa9aadaeae96aaa548302981459c94e3 Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 21:17:05 -0700 Subject: [PATCH 10/17] fix(adapters): close an open idle stretch on a completing Stop and on a transcript re-point The successful Stop return was the one exit that bypassed the exit-time transcript sample, and the re-point rebaseline dropped an open stretch without its `session-active`; in both cases the journal ended on an open `session-idle`. Both now close the stretch before moving on. Codex review findings on #822. --- src/bmad_loop/adapters/generic.py | 22 ++++++++- tests/test_generic_tmux.py | 81 +++++++++++++++++++++++++++++++ 2 files changed, 101 insertions(+), 2 deletions(-) diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 8d905affd..8b42cdbea 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -1217,6 +1217,13 @@ def produced_work() -> bool: stop_seen = True result_json = self._result_json(handle, spec, wait=True) if result_json is not None: + if transcript_path: + # The one exit that does not go through `produced_work()`: + # sample once more so an idle stretch that ended inside the + # final interval is closed before `session-end` (#680). + self._sample_transcript_idle( + handle.task_id, transcript_path, idle, time.monotonic() + ) return SessionResult( status="completed", result_json=result_json, @@ -1345,8 +1352,19 @@ def _sample_transcript_idle( if idle.path != transcript_path: # A different transcript than the one sampled so far (a hook event # re-pointed it): start over on this file — its first key is a - # baseline, not a change, and any open stretch belonged to the old - # file. `moved` stays latched if it already was. + # baseline, not a change. An open stretch belonged to the old file + # and is closed here, since nothing else can close it: the TUI would + # otherwise read the old `session-idle` for as long as the new file + # keeps moving. `moved` stays latched if it already was. + if idle.open_since is not None and self.journal is not None: + try: + self.journal.append( + "session-active", + task_id=task_id, + idle_s=round(now - idle.last_change_mono, 3), + ) + except OSError: + pass idle.path = transcript_path idle.last_key = None idle.idle_s = None diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 48694840c..4487db7b9 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6979,6 +6979,87 @@ def script(call_n): assert adapter.journal.entries[0]["threshold_s"] == 600.0 +def test_idle_stretch_is_closed_on_a_completing_stop(tmp_path, monkeypatch): + """The successful Stop is the one exit that bypasses `produced_work()`: an + open idle stretch whose transcript moved inside the final interval is still + closed before the `completed` return, so the journal reads + `session-idle`, `session-active` ahead of `session-end`. + + ABLATION: drop the sample before the `completed` return — the + `session-active` is missing.""" + monkeypatch.setattr(generic, "RESULT_POLL_S", 0.0) + adapter, _, log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch) + impl = tmp_path / "impl" # `make_dev_adapter`'s implementation-artifacts dir + + def script(call_n): + if call_n >= 2: + _grow(log, "\r⠋".encode()) + if 2 <= call_n <= 4: + clock["t"] += generic.HEARTBEAT_INTERVAL_S # ages 30, 60 (crossing), 90 + if call_n == 5: + clock["t"] += 10.0 # inside the final interval: no heartbeat fires + _grow(transcript, b'{"type":"assistant"}\n') + # the turn ends with its spec flipped to done: the dev adapter + # synthesizes the result from it + (impl / "spec-3-1-foo.md").write_text( + "---\nstatus: done\nbaseline_revision: abc123\n---\n\n## Auto Run Result\n\nStatus: done\n" + ) + + adapter.watcher = _ScriptedWatcher( + [ + _session_start("3-1-dev-1", str(transcript)), + None, + None, + None, + _stop_event("3-1-dev-1", "sess", str(transcript)), + ], + on_call=script, + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert result.status == "completed" + assert [e["kind"] for e in adapter.journal.entries] == ["session-idle", "session-active"] + + +def test_repointing_the_transcript_closes_an_open_idle_stretch(tmp_path, monkeypatch): + """A hook event re-points the transcript while a stretch is open on the old + one: the rebaseline closes that stretch with a `session-active`, since the + new file can never close it and the TUI would otherwise keep reading the old + `session-idle`. + + ABLATION: drop the `session-active` inside the rebaseline — the journal ends + on an open `session-idle`.""" + adapter, _, log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch) + adapter._stall_grace_s = 0.0 + other = tmp_path / "other.jsonl" + other.write_bytes(b'{"type":"user","other":true}\n') + + def script(call_n): + if call_n >= 2: + clock["t"] += generic.HEARTBEAT_INTERVAL_S + _grow(log, "\r⠋".encode()) + if call_n == 6: + clock["t"] += 10_000.0 + + # tick 1 names the transcript; the stretch opens at age 60; tick 4's event + # re-points to `other` + events = [ + _session_start("3-1-dev-1", str(transcript)), + None, + None, + _session_start("3-1-dev-1", str(other)), + ] + adapter.watcher = _ScriptedWatcher(events, on_call=script) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert result.status == "timeout" + entries = adapter.journal.entries + # the old file's stretch is closed at the re-point; the new file then runs its + # own clock from a fresh baseline and crosses on the final (jumped) sample + assert [e["kind"] for e in entries] == ["session-idle", "session-active", "session-idle"] + assert entries[2]["since_ts"] > entries[0]["since_ts"] + + def test_idle_events_need_a_positive_grace(tmp_path, monkeypatch): """`dev_stall_grace_s = 0` disables the events (no new knob); the heartbeat still stamps the age. From eb2a05275b4448640f2490d2488f9df6f6075a9c Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 22:44:46 -0700 Subject: [PATCH 11/17] fix(generic): distinguish model work from stuck-session noise --- docs/FEATURES.md | 2 +- src/bmad_loop/adapters/generic.py | 157 ++++++++++++++++++---------- src/bmad_loop/tui/data.py | 13 ++- tests/test_engine.py | 9 +- tests/test_generic_tmux.py | 167 +++++++++++++++++++++++++++++- tests/test_tui_data.py | 14 +++ 6 files changed, 297 insertions(+), 65 deletions(-) diff --git a/docs/FEATURES.md b/docs/FEATURES.md index 5525ca80e..7f3a0ca10 100644 --- a/docs/FEATURES.md +++ b/docs/FEATURES.md @@ -74,7 +74,7 @@ See [README.md](../README.md) for the narrative overview and [setup-guide.md](se - Typed escalations: `CRITICAL` pauses the run + notifies (desktop + `ATTENTION` file); `PREFERENCE` is journaled and continues. A story's escalation trail is append-only and deliberately survives a re-arm (it is the run-dir audit a later resolve cycle reads), so a second `bmad-loop resolve` used to re-present every CRITICAL the story ever raised, interleaved with the new ones and with nothing marking which was which — against a resolve skill whose contract is singular. An interactive resolve session that records a `resolution.json` now **watermarks** the trail at its current length, and every later cycle hands the agent only the escalations recorded since; how many earlier ones were withheld is printed to your terminal, never added to the agent's `context.json`. When that filtered list contains entries, the resolve skill presents them newest-first under the existing globally de-duplicated contract. When a new pause precedes any newer recorded escalation and the filtered list is empty, the skill presents `paused_reason` as the available current-pause evidence and discloses that no newer recorded detail exists; it does not read below the watermark, recover an older artifact entry, or synthesize an escalation object. The watermark moves only on a gesture that actually accepted a resolution — a resolve session that exited without writing one, `resolve --no-interactive`, and the TUI's Re-arm button all leave it where it stands. Leaving a watermark is not clearing it: a watermark already standing still filters on those paths, which show everything recorded since the last accepted resolution rather than the whole trail. That is where the bias is deliberate, and it is a claim about which GESTURES move the watermark: one that accepted nothing never moves it. Within a cycle that DID accept a resolution the watermark covers everything that cycle PRESENTED — it is stamped at the trail's length, not at the entries individually answered — so answering one of five escalations shown together retires all five. A task's watermark is reported as the `esc-upto` column of `bmad-loop diagnose`'s markdown task table, and as `escalations_resolved_upto` under `--json` (that is the key to grep in a support bundle), which is what explains a short or empty `context.json` escalation list on a bug report. - A rejected dev attempt notifies too, with its reason (#640). RETRY was the only dev outcome that rejected an attempt silently, and it is the one that discards a completed implementation — the non-fixable leg resets the tree to baseline. The notice fires once per rejected attempt in an uninterrupted run (so ordinarily at most `max_dev_attempts` per story) and has no suppression knob of its own; it follows `[notify]` like every other notice. One attempt can raise it twice: the notice precedes the rollback, so a host that dies in between replays that verdict on resume and announces it again — treat the count as a floor on attempts rejected, not an exact tally. The reason is reduced to its first line and capped, with a `[…]` marker when it was trimmed, because a `Decision.reason` routinely carries a verify-output tail that would otherwise spill into `ATTENTION` and a desktop bubble; the untruncated reason stays in the `dev-decision` journal entry. It fires above the fixable/non-fixable split, so on a leg that goes on to pause for manual recovery the operator sees both notices. - Environment faults pause without burning budget (#194): a session whose coding CLI never reached the API — a verify command whose _environment_ is broken (`sh` reports rc `126`/`127`; on Windows a missing tool is caught by its `is not recognized` message or by resolving the command's leading token, and a command naming a file `cmd` cannot execute — a `.sh`, or any extension outside `PATHEXT`, which cmd hands to the file association and which exits `0` without running anything — is a fault rather than a silent rc `0` pass, #302; and on either OS a verify command whose child could not be started at all — most often because the directory it was to run in is missing, is a file, or cannot be searched, but any spawn-time `OSError` counts — is translated into the same fault instead of crashing the run, since no exit code exists to classify) **or** a session whose log matches the profile's `env_fault_patterns` (an `API Error … Connection refused`-class transport failure, or a provider quota/usage-limit refusal, that idled out the session clock) — pauses the run with the matched evidence instead of charging the attempt and deferring the story as if its code were broken. Re-arm restores the budget. Patterns are per-profile: `claude` seeds three, reproducing only complete error sentences its CLI was captured printing (connection loss, and the two captured provider 5xx refusals — statuses enumerated, never ranged, so an uncaptured `503` stays prose), so a story that merely writes _about_ a provider error cannot trip them (#507); `opencode` seeds a provider quota/rate-limit and connection pair (#323), matched against the `opencode serve` process's own stdout, which the model cannot write to; the other four profiles ship none. Each adapter matches them against the log named by its `ENV_FAULT_LOG_SUFFIX` — the tmux pane capture `logs/.log`, or `.server.out` (the `opencode serve` process's own stdout) for `opencode-http`, never that adapter's model-written transcript. A pattern is only sound against a log the model cannot write to; where that does not hold — the pane capture — the pattern has to reproduce a whole captured sentence, because an error token plus a cause on the same line is precisely the shape a story writing about the error emits, and that framing is what the guard now refuses (#507). A usage-limit / quota cause stays unseeded on the pane-capture profiles for the same evidentiary reason: no captured line exists for them (#323). Extend or disable them in a project profile overlay. -- A session that never did anything pauses instead of retrying (#727). A dev CLI parked on a permission dialog, a login, or a dead-on-arrival window ends `stalled`/`crashed`/`timeout`, and all three used to RETRY while budget lasted — a fresh session into the identical wall, `max_dev_attempts` burned without a line of work. The tmux adapter now stamps `produced_work` on every non-completed result: `true` when a `Stop` arrived (a turn ended), when there is no pane log to read (opencode-http, "unknown never blocks"), when the pane log changed on a tick more than 30 s (`FIRST_FRAME_S`) after the wait loop started and before the first stall wake nudge went out, or when the CLI's own transcript changed after its first heartbeat sample or the usage sampler read a nonzero spend from it (the model produced tokens — evidence a misbound pane sink, #254/#217, cannot hide and a nudge echo cannot fabricate, so neither carries the first-frame or nudge guard); `false` otherwise. The first frame is excluded because a parked CLI paints exactly once — the #727 capture is a 1,930-byte dialog, which clears the #261 read-back gate's 256-byte floor, so that floor is deliberately not the predicate — and post-nudge growth is excluded because the nudge's `Enter` confirms the dialog's default and the pane grows with the echo and exit text, the loop's own keystrokes. `decide_dev` PAUSEs a `produced_work=false` result ahead of the budget, exactly as an environment fault does (`no work produced: dev session (no turn ended and the pane never changed after its first frame — the CLI is likely waiting on a human: a permission prompt, a login, a confirmation; the attempt is not charged)`), the env-fault arm outranks it, the `#489` lost-session suffix survives inside it, and re-arm resets `attempt` to `0`. The flag rides `dev-decision` beside `session_vanished` and, when `false`, every role's `session-end`. Two deliberate costs, both toward today's behavior: a CLI slower than 30 s to paint at all retries as before, and a session that woke only after a nudge and then never ended a turn pauses for the operator instead of retrying. The review, fix and sweep deciders are unchanged, and `stall_deadline`, its pane-growth re-arm and the nudge budget are untouched. +- A session that never did anything pauses instead of retrying (#727). A dev CLI parked on a permission dialog, a login, or a dead-on-arrival window ends `stalled`/`crashed`/`timeout`, and all three used to RETRY while budget lasted — a fresh session into the identical wall, `max_dev_attempts` burned without a line of work. The tmux adapter now stamps `produced_work` on every non-completed result: `true` when a `Stop` arrived (a turn ended), when there is no pane log to read (opencode-http, "unknown never blocks"), when the pane log changed on a tick more than 30 s (`FIRST_FRAME_S`) after the wait loop started and before the first stall wake nudge went out, or when a model-side transcript record was appended after its sampled baseline before the first stall wake nudge, or the usage sampler saw nonzero spend before that nudge (signals a misbound pane sink, #254/#217, cannot hide; user/setup-only transcript writes and post-nudge writes do not count); `false` otherwise. The first frame is excluded because a parked CLI paints exactly once — the #727 capture is a 1,930-byte dialog, which clears the #261 read-back gate's 256-byte floor, so that floor is deliberately not the predicate — and post-nudge growth is excluded because the nudge's `Enter` confirms the dialog's default and the pane grows with the echo and exit text, the loop's own keystrokes. `decide_dev` PAUSEs a `produced_work=false` result ahead of the budget, exactly as an environment fault does (`no work produced: dev session (no turn ended and the pane never changed after its first frame — the CLI is likely waiting on a human: a permission prompt, a login, a confirmation; the attempt is not charged)`), the env-fault arm outranks it, the `#489` lost-session suffix survives inside it, and re-arm resets `attempt` to `0`. The flag rides `dev-decision` beside `session_vanished` and, when `false`, every role's `session-end`. Two deliberate costs, both toward today's behavior: a CLI slower than 30 s to paint at all retries as before, and a session that woke only after a nudge and then never ended a turn pauses for the operator instead of retrying. The review, fix and sweep deciders are unchanged, and `stall_deadline`, its pane-growth re-arm and the nudge budget are untouched. - An idle session is visible while it sits (#680). A session idling inside a tool call (`sleep 590; cat …`) keeps its pane log growing through spinner repaints, so the stall re-arm — correctly — never fires and nothing separated it from a working session but `session_timeout_min`. The adapter now stats the live transcript's `(mtime_ns, size)` — a baseline the moment the first hook event names it, then on the heartbeat cadence (a stat, never parsed usage, so it works for `usage_parser = "none"`) — stamps the age on `heartbeat.json` as `transcript_idle_s` (`null` before a transcript is known), and — when the run's journal is attached, which the engine does for every adapter it owns — journals one `session-idle` (`task_id`, `idle_s`, `since_ts`, `threshold_s`) when the age crosses `limits.dev_stall_grace_s` and one `session-active` (`task_id`, `idle_s`) when the transcript moves again; a later stretch emits a fresh pair. The threshold is the stall grace on purpose — the event fires exactly when the session _would_ have stalled had its pane not kept repainting, so the two records are directly comparable — and `0` disables the events with no new knob. The TUI's agent line shows the open stretch as `· idle `. Observability only: nothing bounds the stretch, and the session is neither nudged, stalled nor killed for it. Scope: the notice starts when a hook event names the transcript — `SessionStart` on the `claude`, `codex`, `gemini` and `copilot` profiles, so it covers a session's first turn there; `antigravity` fires no `SessionStart` and names the transcript only on its `Stop`, so its first turn is invisible to the notice (the heartbeat's `transcript_idle_s` stays `null` until then), and the `opencode-http` transport has no pane wait loop and emits neither the field nor the events. - A session the multiplexer lost says so (#489). Sessions complete on a hook `Stop` or on window death, and a window is gone whether the CLI exited or something destroyed the whole mux session out from under the run — an external reaper, a concurrent prune or `bmad-loop stop`, an operator `kill-session`, a server crash, the host sleeping. Both are `crashed`, so the retry/defer reason an operator reads said only `dev session crashed` — pointing at the agent when the host was at fault. The crash verdict now asks whether the _session_ still exists and, when it does not, says so in the reason (`… session crashed: the multiplexer no longer reports the session, so the window's disappearance is not evidence the CLI exited`), as `session_vanished` on `dev-decision` and `fix-decision` either way, beside the routing each fed, on every role's `session-end` journal entry when it is true (the convention `env_fault` already uses there), and as a `session-vanished` breadcrumb in `session-lifecycle.jsonl`. The repair path carries it the same way: when fix attempts are exhausted the defer names the lost session instead of blaming the tree for repairs that never ran. The wording states what the evidence _withdraws_, not what it proves: `has_session` maps every nonzero backend result to False, so a negative lookup is "the backend did not confirm it" rather than proof the session is gone — enough to stop an operator reading window death as a CLI exit, not enough to name a destroyer. It composes with an environment-fault pause instead of being swallowed by it. A session reaped _after_ flushing its result still scores `completed` and is not diagnosed — it produced something. Diagnosis only — the routing is unchanged, and a retry re-creates the session. - CRITICAL resolution: `bmad-loop resolve ` opens an interactive resolve agent seeded with the escalation + frozen spec; you disambiguate, it re-arms the story (`escalated → pending`, spec reset to `ready-for-dev`) and resumes. `--no-interactive` skips to re-arm if you fixed the spec yourself. The re-arm advances the story's diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 8b42cdbea..fb25557bb 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -154,14 +154,12 @@ class _IdleTracker: last_change_wall: float = 0.0 idle_s: float | None = None open_since: float | None = None - # Latched True the first time the key CHANGES after the first sample — or the - # file APPEARS after a sample found it absent: the CLI appended to (or created) - # its own transcript, which is the #727 no-work verdict's transcript half (see - # `_work_verdict`). Never reset. - moved: bool = False + # A close event whose best-effort journal write failed. Retry it on later + # samples so the TUI does not keep showing an idle session as stuck. + pending_active_s: float | None = None # A sample ran while the named transcript could not be stat'ed (not yet - # created). The next successful sample is then the file's creation, which - # counts as movement rather than as the baseline. + # created). The next successful sample is a change from absence, not a + # pre-existing file's baseline. seen_absent: bool = False @@ -351,10 +349,10 @@ def _work_verdict(self, handle: SessionHandle, stop_seen: bool, activity_seen: b opencode-http, unit fixtures — and unknown never blocks); or the wait loop saw activity (`activity_seen`): the pane log changed on a tick later than `FIRST_FRAME_S` after it started and before the first stall wake nudge (the - timeline half), OR the live transcript changed after its first sample, OR - the usage sampler read a nonzero spend from it — the last two are the CLI's - own writes, which a misbound pane sink cannot hide and a nudge echo cannot - produce, so neither carries the first-frame or nudge guard. + timeline half), OR a pre-nudge transcript change carried a model-side + record, OR pre-nudge usage reported model spend. These last two signals + survive a misbound pane sink; setup-only and post-nudge writes do not + supply proof. The timeline half is what separates this from `_produced_work`, and why the #261 gate is reused for its tristate only, not its verdict: that gate's @@ -375,6 +373,37 @@ def _work_verdict(self, handle: SessionHandle, stop_seen: bool, activity_seen: b return True return self._log_evidence(handle) is None + @staticmethod + def _transcript_has_assistant_activity(transcript_path: str, since_size: int) -> bool: + """A model-side JSONL record written after a sampled baseline. + + The idle detector remains stat-only. Reading content here is solely for + the no-work verdict. A line crossing the old EOF is included so a torn + line completed by the latest append can still prove work. + """ + try: + with Path(transcript_path).open("rb") as stream: + while line := stream.readline(): + if stream.tell() <= since_size: + continue + try: + entry = json.loads(line) + except (json.JSONDecodeError, UnicodeDecodeError): + continue + if not isinstance(entry, dict): + continue + if entry.get("type") == "assistant" or entry.get("role") in ( + "assistant", + "model", + ): + return True + payload = entry.get("payload") + if isinstance(payload, dict) and payload.get("type") == "agent_message": + return True + except OSError: + pass + return False + def _session_vanished(self) -> bool: """Whether the whole multiplexer session is gone, asked only once a crash verdict has already been reached (#489). Base: False — an adapter @@ -825,13 +854,35 @@ def sample_frame() -> None: # neither consulted nor touched. idle = _IdleTracker() - # Definitive activity the pane cannot fake and a misbound pane sink - # (#254/#217) cannot hide: the CLI appended to its own transcript - # (`idle.moved`, sampled on the heartbeat cadence below) or the usage - # sampler read a nonzero spend from it (`usage_seen`). Either one is the - # model having produced tokens, so it counts as work whatever the pane did. + # A transcript can grow for an initial user prompt or the loop's own + # wake nudge, neither of which proves model work. Latch model-side + # evidence only while the pre-nudge window remains open. + transcript_work_seen = False usage_seen = False + def sample_transcript(path: str, now: float) -> None: + nonlocal transcript_work_seen + same_path = idle.path == path + prior_key = idle.last_key if same_path else None + was_absent = idle.seen_absent if same_path else False + self._sample_transcript_idle(handle.task_id, path, idle, now) + current_key = idle.last_key + changed = current_key is not None and current_key != prior_key + if ( + changed + and (prior_key is not None or was_absent) + and stall_nudges_sent == 0 + and not transcript_work_seen + ): + start = ( + prior_key[1] + if prior_key is not None + and current_key is not None + and current_key[1] > prior_key[1] + else 0 + ) + transcript_work_seen = self._transcript_has_assistant_activity(path, start) + def produced_work() -> bool: # Read at call time, after a final frame sample, so every exit below # reports the loop's final view of the pane rather than the last tick's. @@ -841,11 +892,11 @@ def produced_work() -> bool: # interval has not been sampled yet. A full sample, not a bare # compare, so an idle stretch that ended in that interval is closed # with its `session-active` before `session-end` lands, and the - # #727 latch (`idle.moved`) sees the write. - self._sample_transcript_idle( - handle.task_id, transcript_path, idle, time.monotonic() - ) - return self._work_verdict(handle, stop_seen, activity_seen or idle.moved or usage_seen) + # #727 transcript evidence check sees the write. + sample_transcript(transcript_path, time.monotonic()) + return self._work_verdict( + handle, stop_seen, activity_seen or transcript_work_seen or usage_seen + ) while True: # Top-of-tick pane-frame sample for the no-work verdict (#727). Before @@ -910,7 +961,7 @@ def produced_work() -> bool: # the payload carries this tick's age. Inert until a hook event # has named the transcript. if transcript_path: - self._sample_transcript_idle(handle.task_id, transcript_path, idle, now) + sample_transcript(transcript_path, now) self._write_heartbeat( handle.task_id, { @@ -937,7 +988,7 @@ def produced_work() -> bool: and transcript_path ): weighted = self._sample_weighted_usage(transcript_path, spec) - if weighted is not None and weighted > 0: + if weighted is not None and weighted > 0 and stall_nudges_sent == 0: usage_seen = True if weighted is not None and weighted > spec.token_budget: budget_tripped = True @@ -1200,11 +1251,9 @@ def produced_work() -> bool: # baseline NOW, not at the next heartbeat, so the age is measured # from when the transcript became known and every later write — # including one inside the first heartbeat interval — is seen as a - # change by the #727 transcript latch (`_IdleTracker.moved`) rather - # than absorbed into the baseline. - self._sample_transcript_idle( - handle.task_id, event.transcript_path, idle, time.monotonic() - ) + # change by the #727 transcript evidence check rather than + # absorbed into the baseline. + sample_transcript(event.transcript_path, time.monotonic()) transcript_path = event.transcript_path or transcript_path if event.event == "SessionStart": @@ -1221,9 +1270,7 @@ def produced_work() -> bool: # The one exit that does not go through `produced_work()`: # sample once more so an idle stretch that ended inside the # final interval is closed before `session-end` (#680). - self._sample_transcript_idle( - handle.task_id, transcript_path, idle, time.monotonic() - ) + sample_transcript(transcript_path, time.monotonic()) return SessionResult( status="completed", result_json=result_json, @@ -1336,7 +1383,7 @@ def _sample_transcript_idle( A None key (not yet created, torn by a rename, unreadable) skips the tick and leaves the stretch as it was — `_sample_weighted_usage`'s tolerance, for a stat — but remembers that the named path was absent, so the file's - later appearance is the CLI's first write (`moved`), not the baseline. A key that moved closes any open stretch with one + later appearance is a change, not the baseline. A key that moved closes any open stretch with one `session-active` carrying the stretch's full length; a key that has not moved for `_idle_threshold_s` opens one with one `session-idle` (`idle_s`, `since_ts`, `threshold_s`), latched until the key moves again. The @@ -1349,46 +1396,40 @@ def _sample_transcript_idle( age is still measured for `heartbeat.json`. Every write is best-effort — an unwritable journal must not end a session that is, by this very evidence, alive.""" + + def flush_active() -> None: + if idle.pending_active_s is None or self.journal is None: + return + try: + self.journal.append("session-active", task_id=task_id, idle_s=idle.pending_active_s) + except OSError: + return + idle.pending_active_s = None + if idle.path != transcript_path: # A different transcript than the one sampled so far (a hook event # re-pointed it): start over on this file — its first key is a # baseline, not a change. An open stretch belonged to the old file # and is closed here, since nothing else can close it: the TUI would # otherwise read the old `session-idle` for as long as the new file - # keeps moving. `moved` stays latched if it already was. - if idle.open_since is not None and self.journal is not None: - try: - self.journal.append( - "session-active", - task_id=task_id, - idle_s=round(now - idle.last_change_mono, 3), - ) - except OSError: - pass + # keeps moving. Any earlier work verdict remains latched by the caller. + if idle.open_since is not None: + idle.pending_active_s = round(now - idle.last_change_mono, 3) idle.path = transcript_path idle.last_key = None idle.idle_s = None idle.open_since = None idle.seen_absent = False key = self._transcript_activity_key(transcript_path) + flush_active() if key is None: if idle.last_key is None: idle.seen_absent = True return if key != idle.last_key: - if idle.last_key is not None or idle.seen_absent: - # a change since the baseline, or the file appearing after a - # sample found the named path absent — the CLI wrote it either way - idle.moved = True - if idle.open_since is not None and self.journal is not None: - try: - self.journal.append( - "session-active", - task_id=task_id, - idle_s=round(now - idle.last_change_mono, 3), - ) - except OSError: - pass + if idle.open_since is not None: + idle.pending_active_s = round(now - idle.last_change_mono, 3) + flush_active() idle.open_since = None idle.last_key = key idle.last_change_mono = now @@ -1396,21 +1437,23 @@ def _sample_transcript_idle( idle.idle_s = round(now - idle.last_change_mono, 3) if ( idle.open_since is None + and idle.pending_active_s is None and self.journal is not None and self._idle_threshold_s > 0 and idle.idle_s >= self._idle_threshold_s ): - idle.open_since = idle.last_change_wall try: self.journal.append( "session-idle", task_id=task_id, idle_s=idle.idle_s, - since_ts=idle.open_since, + since_ts=idle.last_change_wall, threshold_s=self._idle_threshold_s, ) except OSError: pass + else: + idle.open_since = idle.last_change_wall def _window_alive(self, handle: SessionHandle) -> bool: return handle.native_id in self.mux.list_window_ids(self.session_name) diff --git a/src/bmad_loop/tui/data.py b/src/bmad_loop/tui/data.py index 83998481c..235efd5da 100644 --- a/src/bmad_loop/tui/data.py +++ b/src/bmad_loop/tui/data.py @@ -20,6 +20,7 @@ import bisect import json +import math import re from collections import deque from dataclasses import dataclass @@ -606,8 +607,8 @@ def _idle_since(journal_entries: list[dict[str, Any]], start: int, task_id: str) """Wall timestamp the open session's current idle stretch began (#680), or None when it is not idle: the `since_ts` of the last `session-idle` for `task_id` after index `start`, unless a later `session-active` for the same - task closed it. A `session-idle` without a numeric `since_ts` is skipped, not - trusted — the TUI ages the text from it. Never raises on a malformed entry.""" + task closed it. Malformed or non-finite timestamps are ignored without + erasing an earlier valid stretch. Never raises on a malformed entry.""" since: float | None = None for entry in journal_entries[start + 1 :]: if str(entry.get("task_id")) != task_id: @@ -615,7 +616,13 @@ def _idle_since(journal_entries: list[dict[str, Any]], start: int, task_id: str) kind = entry.get("kind") if kind == "session-idle": raw = entry.get("since_ts") - since = float(raw) if isinstance(raw, (int, float)) else None + if isinstance(raw, (int, float)) and not isinstance(raw, bool): + try: + stamp = float(raw) + except OverflowError: + continue + if math.isfinite(stamp): + since = stamp elif kind == "session-active": since = None return since diff --git a/tests/test_engine.py b/tests/test_engine.py index 13d6b89f8..d95091380 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -11979,9 +11979,14 @@ def test_engine_attaches_its_journal_to_every_adapter(project): key on `session-end` (the field is present only when False, like `session_vanished`) and `dev-decision` records it True.""" write_sprint(project, {"1-1-a": "ready-for-dev"}) - engine, adapter = make_engine(project, [SessionResult(status="timeout")]) + review_adapter = MockAdapter([]) + engine, adapter = make_engine( + project, [SessionResult(status="timeout")], review_adapter=review_adapter + ) assert adapter.journal is engine.journal - assert engine.adapters["review"].journal is engine.journal + assert review_adapter is not adapter + assert engine.adapters["review"] is review_adapter + assert review_adapter.journal is engine.journal engine.run() dec = [e for e in engine.journal.entries() if e["kind"] == "dev-decision"] assert dec and all(d["produced_work"] is True for d in dec) diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 4487db7b9..850df94c7 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6498,7 +6498,7 @@ def test_transcript_growth_under_a_static_pane_is_work(tmp_path, monkeypatch): its own record. No `Stop` before the deadline: `timeout`, but the session worked, so `produced_work=True` and the decision keeps today's routing. - ABLATION: drop `idle.moved` from `produced_work()` and this reads False.""" + ABLATION: drop the transcript evidence latch from `produced_work()` and this reads False.""" adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) adapter._stall_grace_s = 0.0 # only the deadline can end this # the pane never grows: `_idle_adapter`'s script is replaced below, and the log @@ -6521,6 +6521,127 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", True) +def test_setup_only_transcript_growth_is_not_work(tmp_path, monkeypatch): + """A prompt echo or metadata append before any nudge is not model output. + + ABLATION: treat any transcript stat change as work and this reads True. + """ + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_grace_s = 0.0 + + def script(call_n): + if call_n == 2: + _grow(transcript, b'{"type":"user","message":"setup"}\n') + elif call_n == 3: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + result = adapter.wait_for_completion( + _dev_handle(), dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + ) + assert (result.status, result.produced_work) == ("timeout", False) + + +def test_old_assistant_record_is_not_credited_to_a_new_user_append(tmp_path, monkeypatch): + """Only records crossing the sampled EOF can prove post-baseline work.""" + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_grace_s = 0.0 + _grow(transcript, b'{"type":"assistant","message":"old"}\n') + + def script(call_n): + if call_n == 2: + _grow(transcript, b'{"type":"user","message":"new prompt"}\n') + elif call_n == 3: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + result = adapter.wait_for_completion( + _dev_handle(), dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + ) + assert (result.status, result.produced_work) == ("timeout", False) + + +def test_empty_transcript_creation_is_not_work(tmp_path, monkeypatch): + """Creating a named path with zero bytes is setup, not a model turn.""" + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_grace_s = 0.0 + transcript.unlink() + + def script(call_n): + if call_n == 2: + transcript.touch() + elif call_n == 3: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + result = adapter.wait_for_completion( + _dev_handle(), dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + ) + assert (result.status, result.produced_work) == ("timeout", False) + + +def test_post_nudge_transcript_growth_is_not_work(tmp_path, monkeypatch): + """Even an assistant-shaped append after the loop's wake nudge needs Stop. + + ABLATION: drop the `stall_nudges_sent == 0` guard on transcript evidence + and this becomes produced_work=True. + """ + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_nudges = 1 + sent: list[str] = [] + adapter.send_text = lambda handle, value: sent.append(value) + alive = {"v": True} + adapter._window_alive = lambda handle: alive["v"] + + def script(call_n): + if call_n == 2: + clock["t"] += 61.0 # cross grace; the adapter sends its wake nudge + elif call_n == 3: + _grow(transcript, b'{"type":"assistant","message":"late"}\n') + alive["v"] = False + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + result = adapter.wait_for_completion(_dev_handle(), _dev_spec(tmp_path)) + assert sent == [generic.STALL_NUDGE_TEXT] + assert (result.status, result.produced_work) == ("crashed", False) + + +def test_post_nudge_usage_sample_is_not_work(tmp_path, monkeypatch): + """A spend first observed after the wake nudge cannot override no-work. + + ABLATION: drop the nudge guard on `usage_seen` and this reads True. + """ + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_nudges = 1 + sent: list[str] = [] + adapter.send_text = lambda handle, value: sent.append(value) + adapter._sample_weighted_usage = lambda path, spec: 100 if sent else 0 + alive = {"v": True} + adapter._window_alive = lambda handle: alive["v"] + + def script(call_n): + if call_n == 2: + clock["t"] += 61.0 + elif call_n == 3: + alive["v"] = False + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), token_budget=1000, token_budget_mode="warn") + result = adapter.wait_for_completion(_dev_handle(), spec) + assert sent == [generic.STALL_NUDGE_TEXT] + assert (result.status, result.produced_work) == ("crashed", False) + + def test_transcript_write_inside_the_first_heartbeat_interval_is_work(tmp_path, monkeypatch): """The transcript is written between the `SessionStart` that names it and the next heartbeat. The idle baseline is taken the moment the transcript is named, @@ -6641,7 +6762,7 @@ def script(call_n): def test_static_transcript_under_a_static_pane_is_no_work(tmp_path, monkeypatch): """The complement: a named transcript that never changes after its first - sample is not activity — the first sample alone must not latch `moved`.""" + sample is not activity — the first sample alone must not prove work.""" adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) adapter._stall_grace_s = 0.0 @@ -7184,3 +7305,45 @@ def script(call_n): spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) result = adapter.wait_for_completion(_dev_handle(), spec) assert result.status == "timeout" + + +def test_idle_journal_retries_transient_event_failures(tmp_path, monkeypatch): + """A failed append cannot consume either boundary of an idle stretch. + + ABLATION: latch open_since before the idle append, or clear the active + pending state after its failed append, and one of the two events is lost. + """ + adapter, _ = make_dev_adapter(tmp_path, mux=_UnitMux()) + adapter._idle_threshold_s = 60.0 + transcript = tmp_path / "transcript.jsonl" + transcript.write_bytes(b'{"type":"user"}\n') + idle = generic._IdleTracker() + + class _FailOncePerKind: + def __init__(self): + self.entries: list[dict] = [] + self.failed: set[str] = set() + + def append(self, kind, **fields): + if kind not in self.failed: + self.failed.add(kind) + raise OSError("temporary journal failure") + self.entries.append({"kind": kind, **fields}) + + journal = _FailOncePerKind() + adapter.journal = journal + clock = _steerable_clock(monkeypatch) + adapter._sample_transcript_idle("3-1-dev-1", str(transcript), idle, clock["t"]) + clock["t"] += 60.0 + adapter._sample_transcript_idle("3-1-dev-1", str(transcript), idle, clock["t"]) + assert journal.entries == [] + clock["t"] += 30.0 + adapter._sample_transcript_idle("3-1-dev-1", str(transcript), idle, clock["t"]) + assert [entry["kind"] for entry in journal.entries] == ["session-idle"] + _grow(transcript, b'{"type":"assistant"}\n') + clock["t"] += 10.0 + adapter._sample_transcript_idle("3-1-dev-1", str(transcript), idle, clock["t"]) + assert [entry["kind"] for entry in journal.entries] == ["session-idle"] + clock["t"] += 30.0 + adapter._sample_transcript_idle("3-1-dev-1", str(transcript), idle, clock["t"]) + assert [entry["kind"] for entry in journal.entries] == ["session-idle", "session-active"] diff --git a/tests/test_tui_data.py b/tests/test_tui_data.py index dfae6e90a..f9cb70d67 100644 --- a/tests/test_tui_data.py +++ b/tests/test_tui_data.py @@ -991,9 +991,23 @@ def test_active_agent_idle_since_never_raises_on_malformed_entry(): {"kind": "session-idle", "task_id": "1-1-alpha-dev-3"}, {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": "soon"}, {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": None}, + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": True}, + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": float("nan")}, + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": float("inf")}, + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": float("-inf")}, + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": 10**1000}, ): agent = data.active_agent([_stamped_start(), bad], None) assert agent is not None and agent.idle_since is None + agent = data.active_agent( + [ + _stamped_start(), + {"kind": "session-idle", "task_id": "1-1-alpha-dev-3", "since_ts": 5030.0}, + bad, + ], + None, + ) + assert agent is not None and agent.idle_since == 5030.0 # an int since_ts is a number too agent = data.active_agent( [ From b8310f1d846dc78fd19197fff3d2ef62314b3662 Mon Sep 17 00:00:00 2001 From: t Date: Sun, 20 Sep 2026 23:12:02 -0700 Subject: [PATCH 12/17] fix(adapters): count Gemini transcript model work --- src/bmad_loop/adapters/generic.py | 40 +++++++++++++----- tests/test_generic_tmux.py | 67 ++++++++++++++++++++++++++++--- 2 files changed, 93 insertions(+), 14 deletions(-) diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index fb25557bb..3e1e4a7d3 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -379,26 +379,48 @@ def _transcript_has_assistant_activity(transcript_path: str, since_size: int) -> The idle detector remains stat-only. Reading content here is solely for the no-work verdict. A line crossing the old EOF is included so a torn - line completed by the latest append can still prove work. + line completed by the latest append can still prove work. Gemini's + `$set.messages` snapshots can replay older messages, so a model message + with an ID only proves work when it is new or changed. """ + seen_messages: dict[str, dict] = {} try: with Path(transcript_path).open("rb") as stream: while line := stream.readline(): - if stream.tell() <= since_size: - continue + after_baseline = stream.tell() > since_size try: entry = json.loads(line) except (json.JSONDecodeError, UnicodeDecodeError): continue if not isinstance(entry, dict): continue - if entry.get("type") == "assistant" or entry.get("role") in ( - "assistant", - "model", - ): - return True + messages = [entry] + set_patch = entry.get("$set") + if isinstance(set_patch, dict): + snapshot = set_patch.get("messages") + if isinstance(snapshot, list): + messages.extend( + message for message in snapshot if isinstance(message, dict) + ) + for message in messages: + if message.get("type") not in ("assistant", "gemini") and message.get( + "role" + ) not in ("assistant", "model"): + continue + message_id = message.get("id") + if isinstance(message_id, str): + previous = seen_messages.get(message_id) + seen_messages[message_id] = message + if after_baseline and message != previous: + return True + elif after_baseline: + return True payload = entry.get("payload") - if isinstance(payload, dict) and payload.get("type") == "agent_message": + if ( + after_baseline + and isinstance(payload, dict) + and payload.get("type") == "agent_message" + ): return True except OSError: pass diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 850df94c7..1dd6d9e3c 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6521,7 +6521,14 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", True) -def test_setup_only_transcript_growth_is_not_work(tmp_path, monkeypatch): +@pytest.mark.parametrize( + "setup_record", + [ + {"type": "user", "message": "setup"}, + {"$set": {"messages": [{"id": "u1", "type": "user", "content": []}]}}, + ], +) +def test_setup_only_transcript_growth_is_not_work(tmp_path, monkeypatch, setup_record): """A prompt echo or metadata append before any nudge is not model output. ABLATION: treat any transcript stat change as work and this reads True. @@ -6531,7 +6538,7 @@ def test_setup_only_transcript_growth_is_not_work(tmp_path, monkeypatch): def script(call_n): if call_n == 2: - _grow(transcript, b'{"type":"user","message":"setup"}\n') + _grow(transcript, (json.dumps(setup_record) + "\n").encode()) elif call_n == 3: clock["t"] += 10_000.0 @@ -6565,6 +6572,46 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", False) +@pytest.mark.parametrize( + ("reply_content", "produced_work"), + [("earlier reply", False), ("continued reply", True)], +) +def test_gemini_snapshot_only_counts_new_model_content( + tmp_path, monkeypatch, reply_content, produced_work +): + """A `$set.messages` snapshot can replay or update a model message. + + ABLATION: credit any Gemini record in the appended snapshot and the replay + reads True; compare IDs alone and the update reads False. + """ + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_grace_s = 0.0 + old_reply = {"id": "g1", "type": "gemini", "content": "earlier reply"} + _grow(transcript, (json.dumps(old_reply) + "\n").encode()) + + def script(call_n): + if call_n == 2: + patch = { + "$set": { + "messages": [ + {**old_reply, "content": reply_content}, + {"id": "u2", "type": "user", "content": "retry"}, + ] + } + } + _grow(transcript, (json.dumps(patch) + "\n").encode()) + elif call_n == 3: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + result = adapter.wait_for_completion( + _dev_handle(), dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + ) + assert (result.status, result.produced_work) == ("timeout", produced_work) + + def test_empty_transcript_creation_is_not_work(tmp_path, monkeypatch): """Creating a named path with zero bytes is setup, not a model turn.""" adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) @@ -6670,12 +6717,22 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", True) -def test_transcript_write_in_the_final_interval_is_work(tmp_path, monkeypatch): +@pytest.mark.parametrize( + "model_record", + [ + {"type": "assistant"}, + {"id": "g1", "type": "gemini", "content": "reply"}, + {"$set": {"messages": [{"id": "g1", "type": "gemini", "content": "reply"}]}}, + {"$set": {"messages": [{"id": "g1", "role": "model", "content": "reply"}]}}, + ], +) +def test_transcript_write_in_the_final_interval_is_work(tmp_path, monkeypatch, model_record): """The transcript's only write lands after the last heartbeat sample and the deadline elapses before another: the exit verdict compares the transcript against the tracker's baseline itself. `timeout`, `produced_work=True`. - ABLATION: drop the transcript sample inside `produced_work()` — False.""" + Includes Gemini's bare and `$set.messages` records. ABLATION: drop the + transcript sample inside `produced_work()` or the model-record predicate — False.""" adapter, _, _log, transcript, clock, heartbeats = _idle_adapter( tmp_path, monkeypatch, journal=False ) @@ -6684,7 +6741,7 @@ def test_transcript_write_in_the_final_interval_is_work(tmp_path, monkeypatch): def script(call_n): if call_n == 2: clock["t"] += 10.0 - _grow(transcript, b'{"type":"assistant"}\n') + _grow(transcript, (json.dumps(model_record) + "\n").encode()) elif call_n == 3: clock["t"] += 10_000.0 # no heartbeat fires before the deadline check From 6f176a64e83e3d065a2ebba0f059f95625fc08df Mon Sep 17 00:00:00 2001 From: t Date: Mon, 21 Sep 2026 08:24:42 -0700 Subject: [PATCH 13/17] fix(adapters): baseline repointed transcripts at hook time --- src/bmad_loop/adapters/generic.py | 12 +++++------- tests/test_generic_tmux.py | 30 ++++++++++++++++++++++++++++++ 2 files changed, 35 insertions(+), 7 deletions(-) diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 3e1e4a7d3..4ecb2dc13 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -1268,13 +1268,11 @@ def produced_work() -> bool: # real transcript is preserved for usage tallying. continue session_id = event.session_id or session_id - if event.transcript_path and not transcript_path: - # First observation of the transcript (#680): take the idle - # baseline NOW, not at the next heartbeat, so the age is measured - # from when the transcript became known and every later write — - # including one inside the first heartbeat interval — is seen as a - # change by the #727 transcript evidence check rather than - # absorbed into the baseline. + if event.transcript_path and event.transcript_path != transcript_path: + # Take the idle baseline as soon as a hook names a new transcript, + # including a later re-point (#680). A write before the next + # heartbeat is then a change for the #727 work check rather than + # being absorbed into the baseline at exit. sample_transcript(event.transcript_path, time.monotonic()) transcript_path = event.transcript_path or transcript_path diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 1dd6d9e3c..e24e81988 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6817,6 +6817,36 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", False) +def test_repointed_transcript_write_in_final_interval_is_work(tmp_path, monkeypatch): + """A new SessionStart names another transcript, which receives model output + before the next heartbeat. Exit-time sampling must see that write as movement. + + ABLATION: sample only the first named path and the exit sample baselines the + already populated replacement transcript, leaving produced_work False.""" + adapter, _, _log, transcript, clock, heartbeats = _idle_adapter( + tmp_path, monkeypatch, journal=False + ) + adapter._stall_grace_s = 0.0 + other = tmp_path / "other.jsonl" + other.write_bytes(b'{"type":"user"}\n') + + def script(call_n): + if call_n == 2: + clock["t"] += 10.0 # the new path is named between heartbeats + elif call_n == 3: + _grow(other, b'{"type":"assistant","content":"reply"}\n') + clock["t"] += 10_000.0 # exit before another heartbeat + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript)), _session_start("3-1-dev-1", str(other))], + on_call=script, + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert [hb["transcript_idle_s"] for hb in heartbeats] == [None] + assert (result.status, result.produced_work) == ("timeout", True) + + def test_static_transcript_under_a_static_pane_is_no_work(tmp_path, monkeypatch): """The complement: a named transcript that never changes after its first sample is not activity — the first sample alone must not prove work.""" From 256c311b8e5e0c159021a6896a6fd928e244145d Mon Sep 17 00:00:00 2001 From: t Date: Mon, 21 Sep 2026 08:38:59 -0700 Subject: [PATCH 14/17] fix(adapters): count Copilot metrics as session work --- CHANGELOG.md | 3 ++ src/bmad_loop/adapters/generic.py | 15 +++++++++- tests/test_generic_tmux.py | 47 +++++++++++++++++++++++++++++-- 3 files changed, 62 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 04b780a2b..275c6e305 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,9 @@ breaking changes may land in a minor release. ### Fixed +- Count Copilot shutdown metrics with model output as work when a dev session + exits before the next transcript heartbeat (#822). + - Pause a dev session that produced no work instead of retrying into the same wall (#727). `SessionResult.produced_work` is `false` when no turn ended, the pane never changed after its first frame before any wake nudge, and the transcript diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 4ecb2dc13..f1ecd573e 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -381,7 +381,9 @@ def _transcript_has_assistant_activity(transcript_path: str, since_size: int) -> the no-work verdict. A line crossing the old EOF is included so a torn line completed by the latest append can still prove work. Gemini's `$set.messages` snapshots can replay older messages, so a model message - with an ID only proves work when it is new or changed. + with an ID only proves work when it is new or changed. Copilot's metrics + only prove work when output or reasoning tokens are positive; input + tokens alone can be a submitted prompt. """ seen_messages: dict[str, dict] = {} try: @@ -422,6 +424,17 @@ def _transcript_has_assistant_activity(transcript_path: str, since_size: int) -> and payload.get("type") == "agent_message" ): return True + if after_baseline: + data = entry.get("data") + metrics = data.get("modelMetrics") if isinstance(data, dict) else None + if isinstance(metrics, dict): + for model in metrics.values(): + usage = model.get("usage") if isinstance(model, dict) else None + if isinstance(usage, dict) and any( + type(usage.get(key)) is int and usage[key] > 0 + for key in ("outputTokens", "reasoningTokens") + ): + return True except OSError: pass return False diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index e24e81988..1e5953f87 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6754,6 +6754,49 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", True) +@pytest.mark.parametrize( + ("usage", "produced_work"), + [ + ({"inputTokens": 20, "outputTokens": 3}, True), + ({"inputTokens": 20, "reasoningTokens": 3}, True), + ({"inputTokens": 20, "outputTokens": 0, "reasoningTokens": 0}, False), + ], +) +def test_copilot_metrics_in_final_interval_prove_model_work( + tmp_path, monkeypatch, usage, produced_work +): + """Copilot's shutdown metrics can be the first model evidence after the last + heartbeat. Input tokens alone can come from setup and must not prove work. + + ABLATION: ignore Copilot metrics and the positive rows fail; accept any + modelMetrics record and the input-only row fails. + """ + adapter, _, _log, transcript, clock, heartbeats = _idle_adapter( + tmp_path, monkeypatch, journal=False, profile_name="copilot" + ) + adapter._stall_grace_s = 0.0 + + def script(call_n): + if call_n == 2: + clock["t"] += 10.0 + record = { + "id": "metrics-1", + "type": "metrics", + "data": {"modelMetrics": {"gpt-5-mini": {"usage": usage}}}, + } + _grow(transcript, (json.dumps(record) + "\n").encode()) + elif call_n == 3: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert [hb["transcript_idle_s"] for hb in heartbeats] == [None] + assert (result.status, result.produced_work) == ("timeout", produced_work) + + def test_transcript_created_after_being_named_is_work(tmp_path, monkeypatch): """`SessionStart` names a transcript that does not exist yet; the CLI creates and writes it later and then times out with no further write and a static @@ -7041,12 +7084,12 @@ def _session_start(task_id, transcript_path): ) -def _idle_adapter(tmp_path, monkeypatch, *, grace=60.0, journal=True): +def _idle_adapter(tmp_path, monkeypatch, *, grace=60.0, journal=True, profile_name="claude"): """Dev adapter with a live pane log that the script keeps repainting (the #680 spinner: the stall re-arm never fires) and a transcript file the script advances on cue. Heartbeats are captured in order.""" mux = _UnitMux() - adapter, _ = make_dev_adapter(tmp_path, mux=mux) + adapter, _ = make_dev_adapter(tmp_path, profile_name=profile_name, mux=mux) adapter._stall_grace_s = grace adapter._idle_threshold_s = grace # the same knob, read from policy in production adapter._stall_nudges = 0 From f2cf8cf70bc1eab0fa518aca3387127643181642 Mon Sep 17 00:00:00 2001 From: t Date: Mon, 21 Sep 2026 09:03:53 -0700 Subject: [PATCH 15/17] test(tui): pin exited child PID in watcher tests --- tests/test_tui_data.py | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/tests/test_tui_data.py b/tests/test_tui_data.py index f9cb70d67..305db1d87 100644 --- a/tests/test_tui_data.py +++ b/tests/test_tui_data.py @@ -7,11 +7,12 @@ import os import subprocess import sys +import time from pathlib import Path from conftest import install_bmad_config, refuse_to_resolve, write_sprint -from bmad_loop import bmadconfig, deferredwork, policy +from bmad_loop import bmadconfig, deferredwork, platform_util, policy from bmad_loop.journal import UNREADABLE_LINE_KIND, Journal, save_state from bmad_loop.model import RunState from bmad_loop.runs import RUNS_DIR @@ -30,10 +31,19 @@ def make_run(root: Path, run_id: str, **state_kwargs) -> Path: return run_dir +_DEAD_CHILDREN: list[subprocess.Popen[bytes]] = [] + + def dead_pid() -> int: - """Pid guaranteed (modulo astronomically unlikely reuse) to be dead.""" + """Return an exited child's PID, retaining its handle to prevent Windows reuse.""" proc = subprocess.Popen([sys.executable, "-c", ""]) proc.wait() + _DEAD_CHILDREN.append(proc) + deadline = time.monotonic() + 10.0 + while platform_util.pid_alive(proc.pid): + if time.monotonic() > deadline: + raise RuntimeError(f"exited child {proc.pid} still reads alive after 10s") + time.sleep(0.01) return proc.pid From b5ffe5202e4a6a464b83e84fd5f408b0854fac35 Mon Sep 17 00:00:00 2001 From: t Date: Mon, 21 Sep 2026 09:07:34 -0700 Subject: [PATCH 16/17] fix(adapters): reject stale transcript work evidence --- CHANGELOG.md | 8 +++--- docs/FEATURES.md | 2 +- src/bmad_loop/adapters/generic.py | 27 +++++++++---------- src/bmad_loop/escalation.py | 8 +++--- tests/test_escalation.py | 5 ++-- tests/test_generic_tmux.py | 44 +++++++++++++++++++++++++++++++ 6 files changed, 69 insertions(+), 25 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 275c6e305..1b30d1d7d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,10 +21,10 @@ breaking changes may land in a minor release. - Count Copilot shutdown metrics with model output as work when a dev session exits before the next transcript heartbeat (#822). -- Pause a dev session that produced no work instead of retrying into the same wall - (#727). `SessionResult.produced_work` is `false` when no turn ended, the pane - never changed after its first frame before any wake nudge, and the transcript - never grew (a permission dialog, a login, a dead-on-arrival window); `decide_dev` pauses ahead of the budget as an +- Pause a dev session with no confirmed work instead of retrying into the same wall + (#727). `SessionResult.produced_work` is `false` when no turn ended and no + qualifying pane, transcript, or usage activity was observed (a permission + dialog, a login, a dead-on-arrival window); `decide_dev` pauses ahead of the budget as an environment fault does, `dev-decision` and `session-end` carry the flag, and re-arm resets the attempt. diff --git a/docs/FEATURES.md b/docs/FEATURES.md index 7f3a0ca10..dffc976b8 100644 --- a/docs/FEATURES.md +++ b/docs/FEATURES.md @@ -74,7 +74,7 @@ See [README.md](../README.md) for the narrative overview and [setup-guide.md](se - Typed escalations: `CRITICAL` pauses the run + notifies (desktop + `ATTENTION` file); `PREFERENCE` is journaled and continues. A story's escalation trail is append-only and deliberately survives a re-arm (it is the run-dir audit a later resolve cycle reads), so a second `bmad-loop resolve` used to re-present every CRITICAL the story ever raised, interleaved with the new ones and with nothing marking which was which — against a resolve skill whose contract is singular. An interactive resolve session that records a `resolution.json` now **watermarks** the trail at its current length, and every later cycle hands the agent only the escalations recorded since; how many earlier ones were withheld is printed to your terminal, never added to the agent's `context.json`. When that filtered list contains entries, the resolve skill presents them newest-first under the existing globally de-duplicated contract. When a new pause precedes any newer recorded escalation and the filtered list is empty, the skill presents `paused_reason` as the available current-pause evidence and discloses that no newer recorded detail exists; it does not read below the watermark, recover an older artifact entry, or synthesize an escalation object. The watermark moves only on a gesture that actually accepted a resolution — a resolve session that exited without writing one, `resolve --no-interactive`, and the TUI's Re-arm button all leave it where it stands. Leaving a watermark is not clearing it: a watermark already standing still filters on those paths, which show everything recorded since the last accepted resolution rather than the whole trail. That is where the bias is deliberate, and it is a claim about which GESTURES move the watermark: one that accepted nothing never moves it. Within a cycle that DID accept a resolution the watermark covers everything that cycle PRESENTED — it is stamped at the trail's length, not at the entries individually answered — so answering one of five escalations shown together retires all five. A task's watermark is reported as the `esc-upto` column of `bmad-loop diagnose`'s markdown task table, and as `escalations_resolved_upto` under `--json` (that is the key to grep in a support bundle), which is what explains a short or empty `context.json` escalation list on a bug report. - A rejected dev attempt notifies too, with its reason (#640). RETRY was the only dev outcome that rejected an attempt silently, and it is the one that discards a completed implementation — the non-fixable leg resets the tree to baseline. The notice fires once per rejected attempt in an uninterrupted run (so ordinarily at most `max_dev_attempts` per story) and has no suppression knob of its own; it follows `[notify]` like every other notice. One attempt can raise it twice: the notice precedes the rollback, so a host that dies in between replays that verdict on resume and announces it again — treat the count as a floor on attempts rejected, not an exact tally. The reason is reduced to its first line and capped, with a `[…]` marker when it was trimmed, because a `Decision.reason` routinely carries a verify-output tail that would otherwise spill into `ATTENTION` and a desktop bubble; the untruncated reason stays in the `dev-decision` journal entry. It fires above the fixable/non-fixable split, so on a leg that goes on to pause for manual recovery the operator sees both notices. - Environment faults pause without burning budget (#194): a session whose coding CLI never reached the API — a verify command whose _environment_ is broken (`sh` reports rc `126`/`127`; on Windows a missing tool is caught by its `is not recognized` message or by resolving the command's leading token, and a command naming a file `cmd` cannot execute — a `.sh`, or any extension outside `PATHEXT`, which cmd hands to the file association and which exits `0` without running anything — is a fault rather than a silent rc `0` pass, #302; and on either OS a verify command whose child could not be started at all — most often because the directory it was to run in is missing, is a file, or cannot be searched, but any spawn-time `OSError` counts — is translated into the same fault instead of crashing the run, since no exit code exists to classify) **or** a session whose log matches the profile's `env_fault_patterns` (an `API Error … Connection refused`-class transport failure, or a provider quota/usage-limit refusal, that idled out the session clock) — pauses the run with the matched evidence instead of charging the attempt and deferring the story as if its code were broken. Re-arm restores the budget. Patterns are per-profile: `claude` seeds three, reproducing only complete error sentences its CLI was captured printing (connection loss, and the two captured provider 5xx refusals — statuses enumerated, never ranged, so an uncaptured `503` stays prose), so a story that merely writes _about_ a provider error cannot trip them (#507); `opencode` seeds a provider quota/rate-limit and connection pair (#323), matched against the `opencode serve` process's own stdout, which the model cannot write to; the other four profiles ship none. Each adapter matches them against the log named by its `ENV_FAULT_LOG_SUFFIX` — the tmux pane capture `logs/.log`, or `.server.out` (the `opencode serve` process's own stdout) for `opencode-http`, never that adapter's model-written transcript. A pattern is only sound against a log the model cannot write to; where that does not hold — the pane capture — the pattern has to reproduce a whole captured sentence, because an error token plus a cause on the same line is precisely the shape a story writing about the error emits, and that framing is what the guard now refuses (#507). A usage-limit / quota cause stays unseeded on the pane-capture profiles for the same evidentiary reason: no captured line exists for them (#323). Extend or disable them in a project profile overlay. -- A session that never did anything pauses instead of retrying (#727). A dev CLI parked on a permission dialog, a login, or a dead-on-arrival window ends `stalled`/`crashed`/`timeout`, and all three used to RETRY while budget lasted — a fresh session into the identical wall, `max_dev_attempts` burned without a line of work. The tmux adapter now stamps `produced_work` on every non-completed result: `true` when a `Stop` arrived (a turn ended), when there is no pane log to read (opencode-http, "unknown never blocks"), when the pane log changed on a tick more than 30 s (`FIRST_FRAME_S`) after the wait loop started and before the first stall wake nudge went out, or when a model-side transcript record was appended after its sampled baseline before the first stall wake nudge, or the usage sampler saw nonzero spend before that nudge (signals a misbound pane sink, #254/#217, cannot hide; user/setup-only transcript writes and post-nudge writes do not count); `false` otherwise. The first frame is excluded because a parked CLI paints exactly once — the #727 capture is a 1,930-byte dialog, which clears the #261 read-back gate's 256-byte floor, so that floor is deliberately not the predicate — and post-nudge growth is excluded because the nudge's `Enter` confirms the dialog's default and the pane grows with the echo and exit text, the loop's own keystrokes. `decide_dev` PAUSEs a `produced_work=false` result ahead of the budget, exactly as an environment fault does (`no work produced: dev session (no turn ended and the pane never changed after its first frame — the CLI is likely waiting on a human: a permission prompt, a login, a confirmation; the attempt is not charged)`), the env-fault arm outranks it, the `#489` lost-session suffix survives inside it, and re-arm resets `attempt` to `0`. The flag rides `dev-decision` beside `session_vanished` and, when `false`, every role's `session-end`. Two deliberate costs, both toward today's behavior: a CLI slower than 30 s to paint at all retries as before, and a session that woke only after a nudge and then never ended a turn pauses for the operator instead of retrying. The review, fix and sweep deciders are unchanged, and `stall_deadline`, its pane-growth re-arm and the nudge budget are untouched. +- A session that never did anything pauses instead of retrying (#727). A dev CLI parked on a permission dialog, a login, or a dead-on-arrival window ends `stalled`/`crashed`/`timeout`, and all three used to RETRY while budget lasted — a fresh session into the identical wall, `max_dev_attempts` burned without a line of work. The tmux adapter now stamps `produced_work` on every non-completed result: `true` when a `Stop` arrived (a turn ended), when there is no pane log to read (opencode-http, "unknown never blocks"), when the pane log changed on a tick more than 30 s (`FIRST_FRAME_S`) after the wait loop started and before the first stall wake nudge went out, or when a model-side transcript record was appended after its sampled baseline before the first stall wake nudge, or the usage sampler saw nonzero spend before that nudge (signals a misbound pane sink, #254/#217, cannot hide; user/setup-only transcript writes and post-nudge writes do not count); `false` otherwise. The first frame is excluded because a parked CLI paints exactly once — the #727 capture is a 1,930-byte dialog, which clears the #261 read-back gate's 256-byte floor, so that floor is deliberately not the predicate — and post-nudge growth is excluded because the nudge's `Enter` confirms the dialog's default and the pane grows with the echo and exit text, the loop's own keystrokes. `decide_dev` PAUSEs a `produced_work=false` result ahead of the budget, exactly as an environment fault does (`no work produced: dev session (no completed turn or qualifying activity was observed — the CLI may be waiting on a human: a permission prompt, a login, a confirmation; the attempt is not charged)`), the env-fault arm outranks it, the `#489` lost-session suffix survives inside it, and re-arm resets `attempt` to `0`. The flag rides `dev-decision` beside `session_vanished` and, when `false`, every role's `session-end`. Two deliberate costs, both toward today's behavior: a CLI slower than 30 s to paint at all retries as before, and a session that woke only after a nudge and then never ended a turn pauses for the operator instead of retrying. The review, fix and sweep deciders are unchanged, and `stall_deadline`, its pane-growth re-arm and the nudge budget are untouched. - An idle session is visible while it sits (#680). A session idling inside a tool call (`sleep 590; cat …`) keeps its pane log growing through spinner repaints, so the stall re-arm — correctly — never fires and nothing separated it from a working session but `session_timeout_min`. The adapter now stats the live transcript's `(mtime_ns, size)` — a baseline the moment the first hook event names it, then on the heartbeat cadence (a stat, never parsed usage, so it works for `usage_parser = "none"`) — stamps the age on `heartbeat.json` as `transcript_idle_s` (`null` before a transcript is known), and — when the run's journal is attached, which the engine does for every adapter it owns — journals one `session-idle` (`task_id`, `idle_s`, `since_ts`, `threshold_s`) when the age crosses `limits.dev_stall_grace_s` and one `session-active` (`task_id`, `idle_s`) when the transcript moves again; a later stretch emits a fresh pair. The threshold is the stall grace on purpose — the event fires exactly when the session _would_ have stalled had its pane not kept repainting, so the two records are directly comparable — and `0` disables the events with no new knob. The TUI's agent line shows the open stretch as `· idle `. Observability only: nothing bounds the stretch, and the session is neither nudged, stalled nor killed for it. Scope: the notice starts when a hook event names the transcript — `SessionStart` on the `claude`, `codex`, `gemini` and `copilot` profiles, so it covers a session's first turn there; `antigravity` fires no `SessionStart` and names the transcript only on its `Stop`, so its first turn is invisible to the notice (the heartbeat's `transcript_idle_s` stays `null` until then), and the `opencode-http` transport has no pane wait loop and emits neither the field nor the events. - A session the multiplexer lost says so (#489). Sessions complete on a hook `Stop` or on window death, and a window is gone whether the CLI exited or something destroyed the whole mux session out from under the run — an external reaper, a concurrent prune or `bmad-loop stop`, an operator `kill-session`, a server crash, the host sleeping. Both are `crashed`, so the retry/defer reason an operator reads said only `dev session crashed` — pointing at the agent when the host was at fault. The crash verdict now asks whether the _session_ still exists and, when it does not, says so in the reason (`… session crashed: the multiplexer no longer reports the session, so the window's disappearance is not evidence the CLI exited`), as `session_vanished` on `dev-decision` and `fix-decision` either way, beside the routing each fed, on every role's `session-end` journal entry when it is true (the convention `env_fault` already uses there), and as a `session-vanished` breadcrumb in `session-lifecycle.jsonl`. The repair path carries it the same way: when fix attempts are exhausted the defer names the lost session instead of blaming the tree for repairs that never ran. The wording states what the evidence _withdraws_, not what it proves: `has_session` maps every nonzero backend result to False, so a negative lookup is "the backend did not confirm it" rather than proof the session is gone — enough to stop an operator reading window death as a CLI exit, not enough to name a destroyer. It composes with an environment-fault pause instead of being swallowed by it. A session reaped _after_ flushing its result still scores `completed` and is not diagnosed — it produced something. Diagnosis only — the routing is unchanged, and a retry re-creates the session. - CRITICAL resolution: `bmad-loop resolve ` opens an interactive resolve agent seeded with the escalation + frozen spec; you disambiguate, it re-arms the story (`escalated → pending`, spec reset to `ready-for-dev`) and resumes. `--no-interactive` skips to re-arm if you fixed the spec yourself. The re-arm advances the story's diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index f1ecd573e..6f48c2e17 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -386,6 +386,10 @@ def _transcript_has_assistant_activity(transcript_path: str, since_size: int) -> tokens alone can be a submitted prompt. """ seen_messages: dict[str, dict] = {} + # Hook paths are external observations. A FIFO can be stat'ed but opening + # it for a JSONL scan would block the deterministic wait loop indefinitely. + if not Path(transcript_path).is_file(): + return False try: with Path(transcript_path).open("rb") as stream: while line := stream.readline(): @@ -902,20 +906,15 @@ def sample_transcript(path: str, now: float) -> None: was_absent = idle.seen_absent if same_path else False self._sample_transcript_idle(handle.task_id, path, idle, now) current_key = idle.last_key - changed = current_key is not None and current_key != prior_key - if ( - changed - and (prior_key is not None or was_absent) - and stall_nudges_sent == 0 - and not transcript_work_seen - ): - start = ( - prior_key[1] - if prior_key is not None - and current_key is not None - and current_key[1] > prior_key[1] - else 0 - ) + # A same-size rewrite or truncation does not append a new record. + # Scanning from byte zero in that case would credit an old assistant + # record as fresh work merely because mtime changed. + grew = current_key is not None and ( + (prior_key is not None and current_key[1] > prior_key[1]) + or (prior_key is None and was_absent and current_key[1] > 0) + ) + if grew and stall_nudges_sent == 0 and not transcript_work_seen: + start = prior_key[1] if prior_key is not None else 0 transcript_work_seen = self._transcript_has_assistant_activity(path, start) def produced_work() -> bool: diff --git a/src/bmad_loop/escalation.py b/src/bmad_loop/escalation.py index c87ef2185..3fb557022 100644 --- a/src/bmad_loop/escalation.py +++ b/src/bmad_loop/escalation.py @@ -206,13 +206,13 @@ def no_work_pause_reason(role: str, result: SessionResult) -> str: Composed over `session_failure_reason`, like `env_fault_pause_reason`, so the #489 lost-session suffix survives: a session the multiplexer destroyed before it painted a second frame carries both facts, and the operator needs both. The - parenthetical names what the adapter measured — no turn ended and the pane did - not change after its first frame — and what that most often means, because the + parenthetical names what the adapter measured — no completed turn or qualifying + activity — and what that most often means, because the verdict alone (`crashed` / `stalled` / `timeout`) reads as an agent that ran and failed, when the CLI in fact sat at a prompt only a human can answer.""" return ( - f"no work produced: {session_failure_reason(role, result)} (no turn ended and " - "the pane never changed after its first frame — the CLI is likely waiting on a " + f"no work produced: {session_failure_reason(role, result)} (no completed turn " + "or qualifying activity was observed — the CLI may be waiting on a " "human: a permission prompt, a login, a confirmation; the attempt is not charged)" ) diff --git a/tests/test_escalation.py b/tests/test_escalation.py index 99369aa70..cebcb9df4 100644 --- a/tests/test_escalation.py +++ b/tests/test_escalation.py @@ -192,8 +192,8 @@ def test_dev_env_fault_session_pauses_even_when_budget_exhausted(): def test_dev_no_work_session_pauses_even_with_budget_left(): - """A dev session that never did anything (#727) — no turn ended and the pane - never changed after its first frame: a CLI parked on a permission dialog — + """A dev session with no qualifying work evidence (#727), such as a CLI + parked on a permission dialog, PAUSEs for a human instead of RETRYing into the identical wall. The reason names the measurement, not the verdict alone. @@ -203,6 +203,7 @@ def test_dev_no_work_session_pauses_even_with_budget_left(): decision = decide_dev(task, parked, None, POLICY) assert decision.action == Action.PAUSE assert decision.reason.startswith("no work produced: dev session stalled") + assert "no completed turn or qualifying activity was observed" in decision.reason assert "permission prompt" in decision.reason assert "the attempt is not charged" in decision.reason diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index 1e5953f87..e0b35871a 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6521,6 +6521,50 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", True) +def test_unchanged_transcript_rewrite_is_not_new_work(tmp_path, monkeypatch): + """An old assistant record cannot become proof merely because mtime moves. + + ABLATION: scan from byte zero on a same-size stat change and this reads True. + """ + adapter, _, _log, transcript, clock, _ = _idle_adapter(tmp_path, monkeypatch, journal=False) + adapter._stall_grace_s = 0.0 + transcript.write_bytes(b'{"type":"assistant"}\n') + + def script(call_n): + if call_n == 2: + old = transcript.stat().st_mtime_ns + os.utime(transcript, ns=(old + 1_000_000_000, old + 1_000_000_000)) + elif call_n == 3: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + result = adapter.wait_for_completion( + _dev_handle(), dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + ) + assert (result.status, result.produced_work) == ("timeout", False) + + +@pytest.mark.skipif(not hasattr(os, "mkfifo"), reason="named pipes unavailable") +def test_transcript_scan_skips_fifo(tmp_path, monkeypatch): + """A hook-named FIFO must not block the adapter's wait loop on open. + + ABLATION: remove the regular-file guard and the stubbed open fails. + """ + fifo = tmp_path / "transcript.jsonl" + os.mkfifo(fifo) + original_open = Path.open + + def guarded_open(path, *args, **kwargs): + if path == fifo: + raise AssertionError("transcript FIFO would block on open") + return original_open(path, *args, **kwargs) + + monkeypatch.setattr(Path, "open", guarded_open) + assert generic.GenericAdapter._transcript_has_assistant_activity(str(fifo), 0) is False + + @pytest.mark.parametrize( "setup_record", [ From 014fda2d8be2eac519fe64d66420d898f57c3e01 Mon Sep 17 00:00:00 2001 From: t Date: Mon, 21 Sep 2026 10:43:38 -0700 Subject: [PATCH 17/17] fix(adapters): count Codex output token growth as work --- CHANGELOG.md | 4 +-- src/bmad_loop/adapters/generic.py | 14 +++++++- tests/test_generic_tmux.py | 57 +++++++++++++++++++++++++++++++ 3 files changed, 72 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1b30d1d7d..01c3a8e0a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,8 +18,8 @@ breaking changes may land in a minor release. ### Fixed -- Count Copilot shutdown metrics with model output as work when a dev session - exits before the next transcript heartbeat (#822). +- Count Copilot shutdown metrics and increased Codex output-token totals as work + when a dev session exits before the next transcript heartbeat (#822). - Pause a dev session with no confirmed work instead of retrying into the same wall (#727). `SessionResult.produced_work` is `false` when no turn ended and no diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index 6f48c2e17..e5b067fab 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -383,9 +383,11 @@ def _transcript_has_assistant_activity(transcript_path: str, since_size: int) -> `$set.messages` snapshots can replay older messages, so a model message with an ID only proves work when it is new or changed. Copilot's metrics only prove work when output or reasoning tokens are positive; input - tokens alone can be a submitted prompt. + tokens alone can be a submitted prompt. Codex token counts are cumulative, + so only an increase in output tokens proves new work. """ seen_messages: dict[str, dict] = {} + codex_output_seen = 0 # Hook paths are external observations. A FIFO can be stat'ed but opening # it for a JSONL scan would block the deterministic wait loop indefinitely. if not Path(transcript_path).is_file(): @@ -428,6 +430,16 @@ def _transcript_has_assistant_activity(transcript_path: str, since_size: int) -> and payload.get("type") == "agent_message" ): return True + if isinstance(payload, dict) and payload.get("type") == "token_count": + info = payload.get("info") + if isinstance(info, dict): + totals = info.get("total_token_usage") + usage = totals if isinstance(totals, dict) else info + output = usage.get("output_tokens") + if type(output) is int: + if after_baseline and output > codex_output_seen: + return True + codex_output_seen = max(codex_output_seen, output) if after_baseline: data = entry.get("data") metrics = data.get("modelMetrics") if isinstance(data, dict) else None diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index e0b35871a..65fb66a55 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -6841,6 +6841,63 @@ def script(call_n): assert (result.status, result.produced_work) == ("timeout", produced_work) +@pytest.mark.parametrize( + ("baseline_output", "final_output", "produced_work"), + [ + (None, 3, True), + (None, 0, False), + (10, 11, True), + (10, 10, False), + ], +) +def test_codex_token_count_in_final_interval_proves_new_model_work( + tmp_path, monkeypatch, baseline_output, final_output, produced_work +): + """Codex can write cumulative token totals before its agent_message. A final + output increase proves work even when the pane stays static and no heartbeat + follows; input-only growth or an unchanged prior output total does not. + + ABLATION: ignore token_count and the positive rows fail; accept any positive + appended total and the unchanged-output row fails. + """ + adapter, _, _log, transcript, clock, heartbeats = _idle_adapter( + tmp_path, monkeypatch, journal=False, profile_name="codex" + ) + adapter._stall_grace_s = 0.0 + + def token_count(output_tokens, input_tokens): + return { + "type": "event_msg", + "payload": { + "type": "token_count", + "info": { + "total_token_usage": { + "input_tokens": input_tokens, + "output_tokens": output_tokens, + } + }, + }, + } + + if baseline_output is not None: + _grow(transcript, (json.dumps(token_count(baseline_output, 20)) + "\n").encode()) + + def script(call_n): + if call_n == 2: + clock["t"] += 10.0 + _grow(transcript, (json.dumps(token_count(final_output, 30)) + "\n").encode()) + elif call_n == 3: + clock["t"] += 10_000.0 + + adapter.watcher = _ScriptedWatcher( + [_session_start("3-1-dev-1", str(transcript))], on_call=script + ) + spec = dataclasses.replace(_dev_spec(tmp_path), timeout_s=5000.0) + result = adapter.wait_for_completion(_dev_handle(), spec) + assert [hb["transcript_idle_s"] for hb in heartbeats] == [None] + assert (result.status, result.produced_work) == ("timeout", produced_work) + + def test_transcript_created_after_being_named_is_work(tmp_path, monkeypatch): """`SessionStart` names a transcript that does not exist yet; the CLI creates and writes it later and then times out with no further write and a static