diff --git a/CHANGELOG.md b/CHANGELOG.md index fdeb9457..190de40b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,32 @@ breaking changes may land in a minor release. ### Added +- **Plugins can now observe structured dev verification results (#641).** The existing + `post_dev_verify` hook receives immutable per-command results after normal and repair + verification, with separate `stdout`/`stderr` alongside the compatible bounded + `output_tail`. The context also carries `verification_stage` (`"dev"` or `"fix"`) and + `verification_sequence` — the only way to tell a dev verification from a repair one + (both emit the same stage from the same phase) and the key that joins the context to + its own journal records. Core writes `verify-command-result` journal records with + stream pointers under the run's `verify/` directory — its own store, kept out of the + adapter-owned, TUI-consumed `logs/`; plugins remain unable to alter verification or + commit decisions. Storage, upload, signing, and any policy response stay plugin-owned. + Scope is the dev phase: the review gate runs the same `[verify] commands` and retains + nothing, so the journal records are not a census of a run's verifier invocations — + `docs/plugin-authoring-guide.md` states the boundary, and #656 tracks closing it. + Retention is bounded by the new `[verify] stream_capture_kb` (default 256 KiB per + stream, `0` = capture nothing): the tail is kept, and the record carries the full + byte count plus a `*_truncated` flag so a cut file is never mistaken for a whole + one. A concluded run gives the store back: `bmad-loop clean` trims `verify/` with the + rest of a run's heavy scaffolding and counts it in the reclaimed total, leaving the + run listed and resumable. Separately from that on-disk cap, a hard 32 MiB per-stream + ceiling bounds what is held in memory while the remaining commands run, so a + pathologically chatty suite cannot grow peak memory with the number of configured + verify commands; the record still reports what the command emitted, so a stream the + ceiling cut is never mistaken for a whole one. Retaining a stream is observation, so a failed write (ENOSPC, a read-only run + dir) degrades — the record still lands, with a null pointer and `capture_error` — + instead of taking down a dev pass whose verify commands passed. + - **A refused auto-sweep is now visible outside the journal (#501).** A run whose deferred-work sweep was refused ended looking exactly like one that swept, and under `[sweep] auto = "run-end"` there is one trigger per run that is never re-asked once the run finishes — so the journal was @@ -38,6 +64,14 @@ breaking changes may land in a minor release. ### Changed +- **`post_dev_verify` now fires on the repair leg too, not only after dev verification (#641).** + A plugin written against "once per story, after the dev session" will see the stage again after + every repair session's verification, and on the way to a pause: an attempt whose session reported + a CRITICAL escalation now emits before the run stops, on either leg, where the repair leg used to + escalate without emitting at all. Discriminate the legs with `ctx.verification_stage` + (`"dev"` / `"fix"`) and de-duplicate on `ctx.verification_sequence`; handlers that assumed one + call per story must be idempotent. + - **`probe-adapter` now bounds how long a single scrubbed line can be (#481).** `scrub_text` capped how many lines it emitted but never how long one of them could be, so a single very long line — from a foreign CLI's `--version`/`--help`, or from a log tail — reached the `probe-adapter` @@ -82,6 +116,15 @@ breaking changes may land in a minor release. ### Fixed +- **A plugin can no longer erase a CRITICAL escalation out from under the engine's audit.** + `HookContext` copies the session `result_json` precisely so a plugin observes history rather + than rewriting it, but `dict()` is shallow: the nested `escalations` list stayed the engine's + own object, and both verify legs emit `post_dev_verify` before reading + `critical_escalations(result.result_json)`. An in-process plugin that cleared that list + therefore erased the escalation before the audit ran, and a verify-green repair proceeded + where the run owed a pause. The copy is now deep, so the observe-only guarantee holds at the + depth escalations actually live. + - **The egress self-check now sees Windows→WSL UNC home paths (#512).** `diagnose` and `probe-adapter` re-scan their own rendered bytes before emitting and refuse to emit at all on a hit, but the absolute-home-path rule knew only forward-slash spellings — so a path reached through diff --git a/README.md b/README.md index 30f80a6d..9dfddc55 100644 --- a/README.md +++ b/README.md @@ -592,7 +592,7 @@ Game-engine (Unity) runs read a wider `BMAD_LOOP_UNITY_*` / `BMAD_LOOP_ENGINE_*` ## Run state -Everything about a run lives in `.bmad-loop/runs//` (gitignored): `state.json` (resumable engine state), `journal.jsonl` (every decision), `tasks//` (per-session prompt + result + escalations, plus diagnostic breadcrumbs — `session-lifecycle.jsonl` records when a timeout fired, `heartbeat.json` is the wait loop's proof-of-life, `resultless-stops.jsonl` records give-up Stops), `logs/` (raw pane output, debugging only), `deferred/` (stashed specs from deferred stories), `resolve//` (escalation `context.json` + the resolve agent's `resolution.json`), `ATTENTION` (human-readable alerts), and — only while a graceful stop is pending — `stop-request.json` (the control file the engine consumes at the next item boundary). +Everything about a run lives in `.bmad-loop/runs//` (gitignored): `state.json` (resumable engine state), `journal.jsonl` (every decision), `tasks//` (per-session prompt + result + escalations, plus diagnostic breadcrumbs — `session-lifecycle.jsonl` records when a timeout fired, `heartbeat.json` is the wait loop's proof-of-life, `resultless-stops.jsonl` records give-up Stops), `logs/` (raw pane output, debugging only), `verify/` (verifier command stdout/stderr, pointed at by the journal's `verify-command-result` records; the retained tail is capped per stream by `[verify] stream_capture_kb`, `0` to keep nothing), `deferred/` (stashed specs from deferred stories), `resolve//` (escalation `context.json` + the resolve agent's `resolution.json`), `ATTENTION` (human-readable alerts), and — only while a graceful stop is pending — `stop-request.json` (the control file the engine consumes at the next item boundary). One piece deliberately lives elsewhere: the **hook-event channel** (the session completion signals the orchestrator waits on) sits under the user-scoped state root at `///events/`, outside the project tree — a branch switch, a worktree mount or a rollback must not be able to take a live run's control plane away. See `BMAD_LOOP_STATE_DIR` above for where that root resolves. The orchestrator also keeps polling the old in-tree `events/` location, so a project whose installed hook relay predates the move still completes its sessions; re-run `bmad-loop init` to refresh the relay. diff --git a/docs/FEATURES.md b/docs/FEATURES.md index 1694cf82..505363c5 100644 --- a/docs/FEATURES.md +++ b/docs/FEATURES.md @@ -109,7 +109,7 @@ See [README.md](../README.md) for the narrative overview and [setup-guide.md](se - 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. -- All run state in `.bmad-loop/runs//` (gitignored): `state.json`; `journal.jsonl` (every decision, including the `session-synthesized-from-frontmatter` catch and its `spec-marker-repaired` repair, #276); `tasks//` (per-session prompt + `result.json` + 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/`; `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`; `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 and repair legs alike — whose stream pointers name the `verify/` directory below); `tasks//` (per-session prompt + `result.json` + 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). - 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/plugin-authoring-guide.md b/docs/plugin-authoring-guide.md index bedeb926..b0d19294 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -386,11 +386,116 @@ there. ### Dev -| Stage | When | Mutable surface | -| ---------------------------------- | --------------------------- | ------------------------------------------------------------------------------------ | -| `pre_dev_phase` / `post_dev_phase` | around the dev attempt loop | veto (`pre_`); `post_dev_phase` is a [workflow injection point](#workflows-provides) | -| `pre_dev_session` | before each dev session | `proposed_prompt`, `proposed_env`, veto | -| `post_dev_verify` | after dev verification | — | +| Stage | When | Mutable surface | +| ---------------------------------- | -------------------------------- | ------------------------------------------------------------------------------------ | +| `pre_dev_phase` / `post_dev_phase` | around the dev attempt loop | veto (`pre_`); `post_dev_phase` is a [workflow injection point](#workflows-provides) | +| `pre_dev_session` | before each dev session | `proposed_prompt`, `proposed_env`, veto | +| `post_dev_verify` | after dev or repair verification | — | + +`post_dev_verify` fires on **both** legs of the dev phase — once after the dev +session's verification, and again after each repair session's — so a handler sees +it **more than once per story**, not once. The two legs share one `attempt` +counter bounded by `[limits] max_dev_attempts`, which is also the bound on how +many times the stage can fire for one story. Write handlers to be idempotent and +to key on the correlation fields below rather than on the story alone. It also +fires on the way to a pause: an attempt whose session reported a CRITICAL +escalation emits before the run stops, on either leg. + +`post_dev_verify` exposes `ctx.command_results`: an immutable tuple of the +per-command `CommandResult` records core just executed. Each has `command`, +`returncode`, the existing merged bounded `output_tail`, and separate `stdout` +and `stderr` strings. Those two are intended to be the streams essentially whole +— they are not cut to `[verify] stream_capture_kb`, which bounds only what is +written to disk — but they are not unbounded either: a hard 32 MiB per-stream +ceiling applies, so a pathologically chatty command cannot grow the orchestrator's +peak memory with the number of configured verify commands. When that ceiling cuts +a stream the **tail** is what a plugin receives, and the matching journal record's +`stdout_bytes` / `stderr_bytes` still report what the command emitted, so the cut +is always detectable rather than silent. Ordinary suites never reach it. This is +observation data only: a plugin cannot change the verifier's outcome or the commit +decision. The run's `journal.jsonl` also records +one `verify-command-result` entry per command with run/story/attempt/stage and +verification-sequence correlation, `output_tail`, byte counts, and run-relative `stdout_path` / +`stderr_path` pointers under the run's `verify/` directory; full streams are not +embedded in the journal. That store is deliberately separate from `logs/`, which +holds coding-CLI pane captures named after session task ids and is read as such +by the TUI. + +Two more context fields say **which** verification the results came from, because +nothing else on the context can: both the dev leg and the repair leg emit +`post_dev_verify` from `Phase.DEV_VERIFY`, and `ctx.attempt` is one per-story +counter the repair leg continues rather than restarts, so its value orders the +two but names neither. + +| Field | Value | +| --------------------------- | -------------------------------------------------------------------------------------- | +| `ctx.verification_stage` | `"dev"` for the initial dev verification, `"fix"` for a repair one, `None` if none ran | +| `ctx.verification_sequence` | the story's 1-based ordinal for that pass, or `None` if it recorded nothing | + +Together they are the join key: the `verify-command-result` entries carrying this +`story_key` + `verification_stage` + `verification_sequence` are exactly this +context's results, one per record, ordered by `command_index`. The sequence is +monotonic per story **across a pause/resume** — unlike `attempt`, which a human +re-arm reuses — so it is safe to persist as a correlation id. + +Read `ctx.command_results == ()` together with `verification_stage`; on its own it +is ambiguous: + +- **`verification_stage is None`** — no verify pass ran. Several causes land here + and the empty tuple names none of them: the session did not complete + (`ctx.session_status`), an earlier gate already failed the attempt — the + dev-artifact check or the deferral harvest (`ctx.verify_reason`) — or the engine + variant suppressed the pass for this leg (stories mode skips it on a plan-halt + leg, which has no implementation to build). +- **stage set, `verification_sequence is None`** — the pass ran and executed + nothing, because `[verify] commands` is empty. No journal record exists either. +- **stage set, sequence an int** — those commands ran, and each has a matching + journal record. + +What lands on disk is bounded by `[verify] stream_capture_kb` (default 256 KiB per +stream): the **tail** is retained, and the record stays explicit about the cut — +`stdout_bytes` / `stderr_bytes` are what the command emitted, `stdout_captured_bytes` / +`stderr_captured_bytes` how much of that reached disk, and `stdout_truncated` / +`stderr_truncated` their inequality. Both counts are UTF-8 lengths of the decoded +stream, **not** file sizes: the files are written in text mode, so Windows newline +translation makes the file larger there. Set the knob to `0` to retain nothing at +all — no files are written and the pointers are null, but the record still lands +with the full byte counts, because "nothing was retained" and "the command was +silent" are different facts. Retaining is observation and never fails a run: if the +write raises (ENOSPC, a read-only run dir, or a `verify/` directory whose +confinement cannot be established — the store refuses rather than write through +a symlink a session planted), the pointer is null and `capture_error` +carries the reason. A plugin reading these pointers must therefore treat both +`None` and a missing file as normal, and consult `*_truncated` before assuming a +file holds a command's whole output. Treat verifier output as potentially sensitive and store, upload, sign, +or act on it only from an explicitly configured plugin. + +**The dev phase is the whole of this surface.** `[verify] commands` also run at +the _review_ gate — `verify_review` / `verify_review_stories` / +`verify_review_bundle` end on the same core classifier — and **none of those runs +are journalled or published to any hook.** Five engine gates reach them: the +converged review pass, the review-budget-exhaustion rescue, the review-timeout +salvage, and both passes inside the skip-review commit path (which runs the gate +again after a repair). `bmad-loop confirm --reverify` runs the commands too, out +of band by construction — the run that parked the story is finished, so there is +no journal to write to and no hook bus to emit on. + +Two consequences a handler has to be written for: + +- **`verify-command-result` entries are not a complete census of a run's verifier + invocations.** Every story that reaches a commit ran the commands at least once + more than the records show. Never derive "the verifier ran N times" or "the last + thing the verifier saw" from the journal — derive only "these are the dev-phase + passes", which is what the records claim. +- **A green commit is not evidence that the last journalled pass was green**, and a + red journalled pass is not evidence the commit was blocked: a `fix` pass can fail + and the story still commit after a later review-gate run that left no record. + Correlate a decision with the `dev-decision` / `fix-decision` / `review-result` + entries beside the results, not with the results alone. + +The boundary is deliberate, not an oversight — the review leg would need its own +hook stage rather than a second meaning for one named `post_dev_verify` — and is +tracked as a follow-up in [#656](https://github.com/bmad-code-org/bmad-loop/issues/656). ### Review @@ -402,6 +507,9 @@ there. | `post_review_result` | after a review verdict | a [workflow injection point](#workflows-provides) | | `pre_fix_session` | before a verify-repair session | `proposed_prompt`, `proposed_env`, veto | +None of these carries the review gate's `[verify] commands` results — that gate +runs the commands and retains nothing. See the boundary note above `### Review`. + ### Commit | Stage | When | Mutable surface | diff --git a/docs/tui-guide.md b/docs/tui-guide.md index 1455a8b9..de014b0c 100644 --- a/docs/tui-guide.md +++ b/docs/tui-guide.md @@ -609,6 +609,7 @@ behavior. | `limits.max_tokens_per_session` | int ≥ 1 | 4000000 | weighted per-session cap sampled every ~30s mid-session; healthy sessions run ~1–2.5M weighted, so the default trips only true runaways | | `limits.session_budget_grace_s` | int ≥ 0 | 240 | enforce mode: wrap-up window after the nudge before `over_budget` · 0 = terminate at trip, no nudge | | `verify.commands` | one per line | (none) | test/lint commands run before commit | +| `verify.stream_capture_kb` | int ≥ 0 | 256 | per-stream cap (KiB) on verifier stdout/stderr retained under the run's `verify/` directory; the tail is kept and the journal records the full size plus a truncation flag · 0 = capture nothing | | `notify.desktop` | switch | on | desktop notifications | | `notify.file` | switch | on | ATTENTION file logging | | `review.enabled` | switch | on | off = skip the separate review session; dev pass runs its review layers inline | diff --git a/src/bmad_loop/cli.py b/src/bmad_loop/cli.py index 18b27cd9..70b1239c 100644 --- a/src/bmad_loop/cli.py +++ b/src/bmad_loop/cli.py @@ -72,7 +72,7 @@ from .engine import Engine from .journal import Journal, load_state, save_state from .model import RunState -from .platform_util import MAX_SEGMENT, resolve_or_lexical +from .platform_util import MAX_SEGMENT, resolve_or_lexical, walk_files_unlinked from .process_host import ProcessHostError # The run-composition helpers now live in runsetup.py (the library layer a non-CLI @@ -3372,14 +3372,15 @@ def cmd_cleanup(args: argparse.Namespace) -> int: def _dir_size(path: Path) -> int: - """Best-effort total bytes under ``path`` (symlinks not followed).""" + """Best-effort total bytes under ``path``, never crossing a redirect out of + it — see :func:`walk_files_unlinked` for why plain ``os.walk`` is not enough. + Sizes with ``lstat``, so a symlinked file counts as the link it is.""" total = 0 - for root, _dirs, files in os.walk(path, onerror=lambda _e: None): - for name in files: - try: - total += (Path(root) / name).lstat().st_size - except OSError: - pass + for f in walk_files_unlinked(path): + try: + total += f.lstat().st_size + except OSError: + pass return total @@ -3458,9 +3459,11 @@ def cmd_clean(args: argparse.Namespace) -> int: f"run {run_dir.name}: engine may still be live (unverifiable pid)", file=sys.stderr, ) - # measure before mutating so the reclaim estimate holds for --dry-run too - wt_dir = run_dir / "worktrees" - wt_bytes = _dir_size(wt_dir) if wt_dir.is_dir() else 0 + # measure before mutating so the reclaim estimate holds for --dry-run too. + # Sized over `heavy_run_entries`, not over "worktrees" alone: that is the + # exact set `trim_run_dir` removes, so the estimate cannot go stale the + # next time an entry joins it (the verifier stream store did). + heavy_bytes = sum(_dir_size(p) for p in runs.heavy_run_entries(run_dir) if p.is_dir()) run_bytes = _dir_size(run_dir) # collect, never print-as-you-mutate: the document is emitted once at the # end, so every per-item line has to survive the loop as data @@ -3490,7 +3493,7 @@ def cmd_clean(args: argparse.Namespace) -> int: # concurrent resume — is older than this guard (`reclaimable` is # sampled in the loop above and never re-read) and is tracked in # issue #533. - freed += wt_bytes - run_bytes + freed += heavy_bytes - run_bytes # Classify by what happened, not by what was intended: the steps # above may already have taken this run's worktree and artifacts, # and `protected` means "left untouched" in the --json contract. @@ -3504,7 +3507,7 @@ def cmd_clean(args: argparse.Namespace) -> int: ) elif pol.cleanup.trim_artifacts: if runs.trim_run_dir(run_dir, dry_run=dry): - freed += wt_bytes + freed += heavy_bytes trimmed.append(run_dir.name) # After the loop, so the counterparts the removals above already took are gone diff --git a/src/bmad_loop/data/settings/core.toml b/src/bmad_loop/data/settings/core.toml index 2603b23b..2af6551c 100644 --- a/src/bmad_loop/data/settings/core.toml +++ b/src/bmad_loop/data/settings/core.toml @@ -188,6 +188,13 @@ description = "post-implementation verification commands" [[section.field]] key = "commands" kind = "lines" +[[section.field]] +key = "stream_capture_kb" +kind = "int" +minimum = 0 +default_ref = "VerifyPolicy.stream_capture_kb" +label = "verifier stream capture (KiB)" +description = "per-stream cap on the verifier stdout/stderr retained under the run's verify/ directory (the tail is kept; the journal records the full size and a truncation flag) · 0 = capture nothing" [[section]] name = "notify" diff --git a/src/bmad_loop/diagnostics.py b/src/bmad_loop/diagnostics.py index f5a09261..4d8ad4b0 100644 --- a/src/bmad_loop/diagnostics.py +++ b/src/bmad_loop/diagnostics.py @@ -39,8 +39,10 @@ from __future__ import annotations import json +import os import platform import re +import stat import sys from collections import Counter from dataclasses import dataclass, field @@ -49,8 +51,9 @@ from typing import Any from . import __version__, sanitize -from .journal import Journal, load_state +from .journal import VERIFY_DIR, Journal, load_state from .model import RunState, StoryTask +from .platform_util import walk_files_unlinked # The guard machinery (fail-closed egress self-check + alias-substitution # repair) moved to sanitize.py so probe-adapter shares the single audited @@ -75,7 +78,25 @@ # # All are run-dir-relative EXCEPT "events", which since #494 lives out of the # project tree at the user state root — see `_category_roots`. -_FILE_CATEGORIES = ("logs", "tasks", "feedback", "bundles", "failed", "worktrees", "events") +# +# VERIFY_DIR belongs here for the reason the category exists: retained verifier +# stdout/stderr is a build's own output — off-limits to read, but its SIZE is +# exactly the diagnostic. `[verify] stream_capture_kb` defaults to 256 KiB per +# stream, so a run retains up to 512 KiB per command per attempt with no GC +# behind it yet, which can make this store one of the larger things in a run +# dir. Omitting it left `diagnose` unable to show a retention or disk-usage +# problem it is the natural place to notice. Imported, not re-spelled, so the +# reporter cannot drift from the writer that creates the directory. +_FILE_CATEGORIES = ( + "logs", + "tasks", + "feedback", + "bundles", + "failed", + "worktrees", + "events", + VERIFY_DIR, +) _EVENTS_CATEGORY = "events" # Journal fields that name a proprietary identifier — pseudonymized, not dropped, @@ -126,6 +147,18 @@ # Journal fields that carry free text (LLM/merge prose, prompts, errors). Never # emitted — replaced with a boolean presence marker so a maintainer still learns # the field was set without seeing it. +# +# The `verify-command-result` group at the end is the same convention applied to +# the verifier records: `command` is operator-authored shell (`[verify] commands`), +# `output_tail` is a build's own output, `capture_error` is an OSError string +# carrying a path, and the two pointers embed the story key. Routing them here +# rather than leaving them to `scrub_json` is deliberate — that fallback fails +# closed only by accident of shape, since `_IDENTIFIER_RE` forbids `/` and spaces +# and so collapses paths, argv-ish commands and multi-line tails, while a +# one-word `command` (`make`) or a one-word tail (`FAILED`) is identifier-shaped +# and would ship verbatim. The presence boolean is also strictly more useful for +# the pointers: it separates "a stream was retained" from "the cap is 0 or the +# write failed", which a redacted string cannot. _JOURNAL_DROP_FIELDS = frozenset( { "prompt", @@ -138,6 +171,11 @@ "blocker", "commit_message", "was_paused", + "command", + "output_tail", + "capture_error", + "stdout_path", + "stderr_path", } ) # Journal fields whose value is a LIST of story keys (sprint unknown-keys). @@ -337,6 +375,38 @@ def _category_roots(category: str, run_dir: Path, events_dir: Path | None) -> li return [events_dir, legacy] +def _count_lines(path: Path) -> int: + """Lines in a regular file, or 0 — never blocking on a FIFO a session planted. + + ``O_NONBLOCK`` plus an ``S_ISREG`` check **on the descriptor**, the idiom + ``runs.read_trusted_config_digest`` and ``tui.launch._read_ctl_window`` + already carry for the same hazard: the run directory is exported to the + driven session as ``BMAD_LOOP_RUN_DIR``, so an lstat taken before the open is + a check-then-open race, and ``fstat`` describes the object actually opened. + Opening a FIFO read-only without ``O_NONBLOCK`` blocks until a writer + arrives — indefinitely, for a diagnostic dump nobody is feeding, and + ``diagnose`` is a foreground command a human is waiting on. ``O_NOFOLLOW`` + keeps the final component from redirecting the read out of the run, which is + the one hop :func:`platform_util.walk_files_unlinked` cannot refuse for it. + The POSIX-only flags degrade to 0 on win32, where the fd check carries alone. + """ + flags = os.O_RDONLY | getattr(os, "O_NOFOLLOW", 0) | getattr(os, "O_NONBLOCK", 0) + flags |= getattr(os, "O_BINARY", 0) # win32: no CRLF translation on the raw fd + try: + fd = os.open(path, flags) + except OSError: + return 0 + try: + if not stat.S_ISREG(os.fstat(fd).st_mode): + return 0 + with os.fdopen(fd, "rb", closefd=False) as f: + return sum(1 for _ in f) + except OSError: + return 0 + finally: + os.close(fd) + + def summarize_files(run_dir: Path, *, events_dir: Path | None = None) -> list[FileGroup]: """Counts/sizes only — file contents are NEVER opened into the output. @@ -352,20 +422,27 @@ def summarize_files(run_dir: Path, *, events_dir: Path | None = None) -> list[Fi for root in _category_roots(category, run_dir, events_dir): if not root.is_dir(): continue - for p in root.rglob("*"): - if not p.is_file(): - continue - count += 1 + # walk_files_unlinked, not rglob: `is_dir()` above FOLLOWS a link, so a + # planted redirect at a category root reads as a directory and rglob + # then counts the target's tree as this run's retained output. + for p in walk_files_unlinked(root): + # The regular-file filter `rglob` + `is_file()` used to carry, and + # which came off with the switch: `os.walk` reports every + # non-directory entry, so `files` holds FIFOs, device nodes and + # symlinks too. None of those is retained output of this run, and + # the `logs` arm below OPENS what it counts. lstat, not + # `is_file()` — that FOLLOWS, so it answers about the target of a + # planted link rather than about the entry in this run's tree. try: - total_bytes += p.stat().st_size + info = p.lstat() except OSError: - pass + continue + if not stat.S_ISREG(info.st_mode): + continue + count += 1 + total_bytes += info.st_size if category == "logs": - try: - with p.open("rb") as f: - total_lines += sum(1 for _ in f) - except OSError: - pass + total_lines += _count_lines(p) if count: groups.append( FileGroup( diff --git a/src/bmad_loop/documents.py b/src/bmad_loop/documents.py index 484c17e4..c6a11132 100644 --- a/src/bmad_loop/documents.py +++ b/src/bmad_loop/documents.py @@ -474,7 +474,7 @@ def clean_document( this number, and formatting is the renderer's job. It is the same estimate the text prints: measured before mutating (so it holds under --dry-run) and approximate by construction, since it sums whole run dirs for archive/delete - but only the `worktrees/` tree for a trim. + but only the trimmed scaffolding (`runs.heavy_run_entries`) for a trim. Every list names items the text enumerates or counts: `worktrees` holds absolute worktree paths, the rest hold run ids. `protected` is the runs left diff --git a/src/bmad_loop/engine.py b/src/bmad_loop/engine.py index 94f0c19a..f8921ace 100644 --- a/src/bmad_loop/engine.py +++ b/src/bmad_loop/engine.py @@ -89,6 +89,60 @@ def _digest_of(text: str | None) -> str: return hashlib.sha256((text or "").encode("utf-8")).hexdigest() +def _bounded_stream_tail(text: str, max_bytes: int) -> tuple[str, int, int]: + """Cut a verifier stream down to what ``verify.stream_capture_kb`` retains. + + Returns ``(tail, full_bytes, retained_bytes)``. Both counts measure the + DECODED STREAM encoded as UTF-8 — never the file the caller writes it to, + whose size differs on Windows because text mode translates ``\\n``. Keeping + the counts on one side of that boundary is what makes the journal record + unambiguous: ``full_bytes`` is what the command emitted, ``retained_bytes`` + is how much of it survived the cap, and their inequality IS the truncation. + + The TAIL is kept, the direction every other bound on this output takes + (``run_verify_commands``' merged ``[-2000:]``): a failing suite puts its + failure at the end. + + A byte cut can land mid-character, so the leading partial is dropped rather + than decoded into a ``\\ufffd`` this function would be inventing — the stream + already carries whatever replacement chars its own decode produced, and + minting one here would put a corruption marker at a boundary WE chose. + ``max_bytes <= 0`` needs no branch of its own: the slice is empty by + construction, which is exactly "capture nothing". + """ + tail, full_bytes = verify.byte_tail(text, max_bytes) + return tail, full_bytes, len(tail.encode("utf-8")) + + +@dataclass(frozen=True) +class VerifyCommandRecords: + """What one verify-command pass published to ``post_dev_verify``. + + The records themselves plus the two keys that say WHICH pass they are: + ``stage`` (``"dev"`` | ``"fix"``) and the story's ``sequence`` ordinal. Both + already ride the journal's ``verify-command-result`` entries; carrying them + on the hook context too is what lets a plugin tell the two legs apart and + join back to those entries — neither of which the results alone can do, + since both legs emit the same stage from the same phase on one shared + ``attempt`` counter. + + The default instance (:data:`NO_VERIFY_COMMANDS`) is the "no pass ran" value + the callers start from, so a leg that never reaches verification publishes + three explicit ``None``/empty fields rather than three unexplained defaults. + ``sequence`` stays ``None`` when the pass ran but recorded nothing (no + ``[verify] commands`` configured) — nothing was journalled, so there is no + ordinal to join on. See ``HookContext.command_results`` for the full + taxonomy a reader has to apply. + """ + + results: tuple[verify.CommandResult, ...] = () + stage: str | None = None + sequence: int | None = None + + +NO_VERIFY_COMMANDS = VerifyCommandRecords() + + class RunPaused(Exception): def __init__(self, reason: str, stage: str, story_key: str | None = None): super().__init__(reason) @@ -454,6 +508,10 @@ def __init__( # because under isolation each unit resolves against its OWN worktree and # one Engine drives every unit of a run. self._dev_skill_cache: dict[tuple[Path, str | None], str] = {} + # story_key -> the highest `verify-command-result` sequence allocated so + # far. None until the first verify pass seeds it from the journal — see + # _next_verification_sequence, which owns the whole invariant. + self._verification_sequences: dict[str, int] | None = None # Per-unit worktree isolation + integration flow (issue #244 F-3/F-9a). # Built from narrow deps + engine callbacks; the same-name Engine._* worktree # methods below delegate to it. `emit` is late-bound (a lambda, not the bound @@ -1956,6 +2014,7 @@ def _dev_phase(self, task: StoryTask, resume_result: SessionResult | None = None ) advance(task, Phase.DEV_VERIFY) outcome = None + verified = NO_VERIFY_COMMANDS if result.status == "completed": # Everything below this point that appends to the ledger is the # orchestrator, not the session. Preserve attribution on crash @@ -2037,13 +2096,19 @@ def _dev_phase(self, task: StoryTask, resume_result: SessionResult | None = None if outcome.ok and self._run_verify_commands_after_dev(task, result.result_json): # deterministic gates run here too: a broken build must not # reach the (far more expensive) review loop - outcome = verify.verify_commands_outcome(self.policy, self.workspace.root) + outcome, verified = self._verify_commands_with_results(task, "dev") self._emit( "post_dev_verify", task, session_status=result.status, result_json=result.result_json, verify_reason=(outcome.reason if outcome is not None else None), + command_results=verified.results, + # The dev-vs-repair discriminator + the journal join key. Left at + # NO_VERIFY_COMMANDS' Nones on every arm that never reached + # verification, which `session_status`/`verify_reason` name. + verification_stage=verified.stage, + verification_sequence=verified.sequence, ) decision = decide_dev(task, result, outcome, self.policy) self.journal.append( @@ -4010,6 +4075,171 @@ def _run_verify_commands_after_dev(self, task: StoryTask, result_json: dict | No build/test gate would spuriously fail before the plan review.""" return True + def _verify_commands_with_results( + self, task: StoryTask, verification_stage: str + ) -> tuple[VerifyOutcome, VerifyCommandRecords]: + """Execute, retain, and classify verifier results as one engine action. + + Core alone executes and classifies commands. The returned immutable + records are only journalled and exposed to ``post_dev_verify`` plugins. + + ``stage`` is set on the returned records whenever this method ran at all, + including the zero-command case: "the pass ran and executed nothing" and + "no pass ran" are different facts, and only the caller that never reaches + here may publish the second one. + """ + results = tuple(verify.run_verify_commands(self.policy, self.workspace.root)) + sequence = self._journal_verify_command_results(task, verification_stage, results) + outcome = verify.verify_command_results_outcome(list(results), self.workspace.root) + return outcome, VerifyCommandRecords( + results=results, stage=verification_stage, sequence=sequence + ) + + def _next_verification_sequence(self, story_key: str) -> int: + """Allocate this story's next ``verify-command-result`` sequence. + + The ordinal is a public journal field and a ``post_dev_verify`` + correlation key, so it has to stay monotonic per story ACROSS A RESUME — + a fresh process must not restart at 1 and mint a second record claiming + an ordinal an earlier one already used. That property is the whole reason + this used to re-derive the ordinal by rescanning the journal on every + verification, which read and JSON-parsed the entire file each time — a + file this same method keeps appending to, so the cost grew with the run + that was paying it. + + The rescan survives here, once: the first allocation of an engine's life + seeds the per-story map from the journal, and every later one is an + in-memory increment. One scan, not one per verification, and the resume + property is unchanged because a resumed run's seed reads the same journal + the rescan did. + + Seeding EVERY story in one pass (rather than lazily per story) is sound + because :meth:`_journal_verify_command_results` is the sole writer of + this record kind and one Engine drives every unit of a run, so after the + seed the map — not the file — is authoritative. A nested auto-sweep is + not an exception: a child run composes its own run dir and ``Journal``. + + Deliberately an ``Engine`` field and not a ``StoryTask`` one: the value + is recoverable from the journal on every resume, so persisting it would + add a ``state.json`` field that can only disagree with the record it + duplicates. It is also NOT ``attempt`` — a human re-arm reuses attempt + numbers, which is exactly why this counter exists beside it. + """ + if self._verification_sequences is None: + self._verification_sequences = self._seed_verification_sequences() + allocated = self._verification_sequences.get(story_key, 0) + 1 + self._verification_sequences[story_key] = allocated + return allocated + + def _seed_verification_sequences(self) -> dict[str, int]: + """The highest sequence already journalled per story — the resume seed. + + Tolerant by design, like every other journal read-back: a truncated or + hand-edited line that lost either key is skipped rather than raising, and + the worst case is an ordinal reused in a run whose journal was already + corrupt. Missing story = 0, so the first allocation is 1. + """ + highest: dict[str, int] = {} + for entry in self.journal.entries(): + if entry.get("kind") != "verify-command-result": + continue + story_key = entry.get("story_key") + sequence = entry.get("verification_sequence") + if isinstance(story_key, str) and isinstance(sequence, int): + highest[story_key] = max(highest.get(story_key, 0), sequence) + return highest + + def _journal_verify_command_results( + self, + task: StoryTask, + verification_stage: str, + results: tuple[verify.CommandResult, ...], + ) -> int | None: + """Record each verifier subprocess result plus bounded log pointers, and + return the sequence they were recorded under — ``None`` when there was + nothing to record. + + ``attempt`` and ``verification_stage`` make the public journal records + correlate to a concrete dev or repair verification pass. The filenames + contain only engine-derived ordinal values; command text never becomes a + filesystem path. Sanitize the whole composition, not the parts, for the + reason :func:`_session_task_id` gives: two individually capped parts can + still compose past a filename segment limit, and ``safe_segment``'s digest + suffix differs between the two orders. + + Retention is bounded by ``verify.stream_capture_kb`` per stream, and the + record says so rather than leaving the reader to guess: ``*_bytes`` is + what the command emitted, ``*_captured_bytes`` how much of that reached + disk, ``*_truncated`` their inequality. Both counts are UTF-8 lengths of + the decoded stream, NOT file sizes — see :func:`_bounded_stream_tail`. A + zero cap writes no file at all and leaves the pointer null; the record + still lands, still carrying the full byte count, because "nothing was + retained" and "the command was silent" are different facts. + + This is observation, so it degrades and never raises (AGENTS.md). An + ``OSError`` from the write — ENOSPC, a read-only run dir, ENAMETOOLONG on + a path this composition did not shorten enough — is journalled as + ``capture_error`` beside a null pointer and the verification continues. + The alternative is a lost log killing a dev pass whose commands passed, + which trades a diagnostic for the run it was there to diagnose. + + No results means no records, and therefore no sequence: the ordinal is + allocated only when at least one record lands, so it never runs ahead of + the journal it indexes. That is also the pre-existing behaviour — the + max-of-journalled rescan this replaced could not observe an ordinal it + had not written — and keeping it is what makes a resumed run number its + passes identically to an uninterrupted one. + """ + if not results: + return None + verification_sequence = self._next_verification_sequence(task.story_key) + max_bytes = self.policy.verify.stream_capture_kb * 1024 + for command_index, result in enumerate(results): + stem = safe_segment( + f"verify-{task.story_key}-" + f"{verification_stage}-{task.attempt}-{verification_sequence}-{command_index}" + ) + streams: dict[str, str | int | bool | None] = {} + capture_error: str | None = None + for kind, text, emitted in ( + ("stdout", result.stdout, result.stdout_full_bytes), + ("stderr", result.stderr, result.stderr_full_bytes), + ): + tail, full_bytes, captured_bytes = _bounded_stream_tail(text, max_bytes) + # `full_bytes` is what we still HOLD; when the in-memory ceiling + # already cut this stream, what the command EMITTED is larger and + # only the result knows it. Reporting the held size would quietly + # under-report emission and, worse, could call a truncated stream + # whole — the one thing `*_truncated` exists to prevent. + full_bytes = full_bytes if emitted is None else emitted + path: str | None = None + if max_bytes > 0: + try: + path = self.journal.write_verify_stream(f"{stem}.{kind}.log", tail) + except OSError as exc: + # Nothing published: atomic_write_text removes its temp and + # leaves the target absent, so 0 retained is the literal truth. + captured_bytes = 0 + capture_error = capture_error or f"{kind}: {exc}" + streams[f"{kind}_path"] = path + streams[f"{kind}_bytes"] = full_bytes + streams[f"{kind}_captured_bytes"] = captured_bytes + streams[f"{kind}_truncated"] = captured_bytes < full_bytes + self.journal.append( + "verify-command-result", + story_key=task.story_key, + attempt=task.attempt, + verification_stage=verification_stage, + verification_sequence=verification_sequence, + command_index=command_index, + command=result.command, + returncode=result.returncode, + output_tail=result.output_tail, + capture_error=capture_error, + **streams, + ) + return verification_sequence + def _resume_after_dev_verify(self, task: StoryTask) -> None: """Resume a task the run paused at DEV_VERIFY (dev verified, spec on disk). Base: the spec-approval-gate resume — run the review loop + commit. @@ -5250,11 +5480,8 @@ def _fix_phase(self, task: StoryTask, reason: str) -> Decision: preserve_dispatched_spec_snapshot=preserve_chain_snapshot, ) advance(task, Phase.DEV_VERIFY) - crits = critical_escalations(result.result_json) - if crits: - details = "; ".join(str(e.get("detail", e.get("type", "?"))) for e in crits) - self._escalate(task, f"CRITICAL escalation from fix session: {details}") outcome = None + verified = NO_VERIFY_COMMANDS terminal = None if result.status == "completed": # A repair is another generic dev-primitive pass: it can leave @@ -5288,15 +5515,30 @@ def _fix_phase(self, task: StoryTask, reason: str) -> Decision: ) else: terminal = None - outcome = harvest_outcome or verify.verify_commands_outcome( - self.policy, self.workspace.root - ) + if harvest_outcome is not None: + outcome = harvest_outcome + else: + outcome, verified = self._verify_commands_with_results(task, "fix") if not outcome.ok: reason = outcome.reason ok = outcome is not None and outcome.ok session_failure = ( "" if result.status == "completed" else session_failure_reason("fix", result) ) + self._emit( + "post_dev_verify", + task, + session_status=result.status, + result_json=result.result_json, + verify_reason=(outcome.reason if outcome is not None else None), + command_results=verified.results, + # Stage "fix" is the only thing separating this emit from the dev + # one: same stage, same DEV_VERIFY phase, same `attempt` counter. + # Stays None when the harvest short-circuited above and the + # commands never ran — `verify_reason` carries that reason. + verification_stage=verified.stage, + verification_sequence=verified.sequence, + ) self.journal.append( "fix-decision", story_key=task.story_key, @@ -5308,6 +5550,23 @@ def _fix_phase(self, task: StoryTask, reason: str) -> Decision: # it fed, so the fix path is greppable the same way (#489). session_vanished=result.session_vanished, ) + # CRITICAL routing, deliberately AFTER the emit and the journal record + # above, and deliberately AHEAD of the env-fault/retryable arms below. + # Both halves mirror `decide_dev`, which the dev leg reaches at the + # same point in its own loop: it tests `critical_escalations` FIRST, + # so a CRITICAL outranks an env fault there too, and its caller has + # already emitted `post_dev_verify` and journalled `dev-decision` by + # then. Escalating here before the emit — as this leg used to — made + # one event class observable on the dev leg and invisible on the + # repair leg: `_escalate` raises `RunPaused`, so a repair session + # reporting CRITICAL fired no `post_dev_verify` at all, while a dev + # session reporting the same thing fired one. The hook is named for + # the verification, the verification ran, and a plugin correlating + # verify passes cannot have half of them silently withheld. + crits = critical_escalations(result.result_json) + if crits: + details = "; ".join(str(e.get("detail", e.get("type", "?"))) for e in crits) + self._escalate(task, f"CRITICAL escalation from fix session: {details}") if result.status != "completed" and result.env_fault: # A fix session whose CLI lost its API connection (#194) did no # repair work — another attempt cannot fix the run environment, so diff --git a/src/bmad_loop/journal.py b/src/bmad_loop/journal.py index 837f7a9d..169517cf 100644 --- a/src/bmad_loop/journal.py +++ b/src/bmad_loop/journal.py @@ -3,16 +3,27 @@ from __future__ import annotations import json +import os import time from pathlib import Path from typing import Any from .model import RunState -from .platform_util import atomic_replace +from .platform_util import ( + DIR_FD_ANCHORED_WRITES, + atomic_replace, + atomic_write_text, + atomic_write_text_at, + is_link_like, + open_dir_confined, +) STATE_FILE = "state.json" JOURNAL_FILE = "journal.jsonl" LOGS_DIR = "logs" +# Verifier subprocess streams, deliberately NOT under LOGS_DIR — see +# Journal.write_verify_stream for why sharing that directory is a TUI bug. +VERIFY_DIR = "verify" class Journal: @@ -43,6 +54,102 @@ def append(self, kind: str, **fields: Any) -> None: with self.path.open("a", encoding="utf-8") as f: f.write(json.dumps(entry, default=str) + "\n") + def write_verify_stream(self, name: str, content: str) -> str: + """Atomically retain one verifier subprocess stream under ``verify/`` and + return its run-relative pointer. The journal records the pointer and byte + counts, never unbounded subprocess output inline. + + Its own directory, not ``logs/``: every other inhabitant of ``logs/`` is a + coding-CLI pane capture named after a session task id. The adapters own + that namespace (they write ``{task_id}.log``) and the TUI reads the whole + directory as one — with no session open, ``tui.data.active_task_id`` falls + back to the newest ``logs/*.log`` and returns its stem as the live task, + which the dashboard then reopens as ``logs/{stem}.log``. Verifier streams + land in exactly that window: session-end is journalled when the session + ends, before its result reaches verification, so at the moment these files + are newest no session is open and the fallback fires. Under ``logs/`` that + rendered verifier stderr in the agent log pane. Keeping the store in a + separate directory makes that unrepresentable, rather than a name filter + every future reader of ``logs/`` would have to remember to apply. + + ``name`` is engine-generated (not plugin or command supplied), so it is + safe to join below. ``content`` arrives already bounded — the cap is + ``verify.stream_capture_kb``, applied by the caller, which is also where + the full-size and truncation bookkeeping lives; this method is journal + storage only and never decides how much to keep. Callers retain the + original stream separately in a hook context. + + :func:`atomic_write_text`, never ``write_text`` (#379) — the rule + ``install.py`` states flatly. The fixed ``.tmp`` sibling this replaces is + the collision that helper's own docstring exists to prevent, and its + fsync-before-replace is what keeps a pointer from ever naming blocks that + were never written. ``follow_symlinks=False`` because these are + machine-minted records under a run directory a coding-CLI session can + reach: honouring a planted link would aim the write at a path of that + session's choosing, and there is no operator-curated target here to + preserve (contrast the ledgers the default was built for). + + Text mode is deliberate, and it is why the record's byte counts are + defined over the *stream*, not the file: ``\\n`` is translated on Windows, + so the file can be larger there than the count. ``read_text`` normalizes + it back, so the content round-trips either way. + + The write is **anchored at a directory descriptor** where the platform has + one, because ``follow_symlinks=False`` covers the final component and + nothing above it. Sessions are handed this run directory outright + (``BMAD_LOOP_RUN_DIR``, which is where they write ``result.json``), so a + session that plants a symlink at ``verify/`` before verification redirects + every record: ``mkdir(exist_ok=True)`` ACCEPTS a symlink-to-directory — + it re-raises only when ``is_dir()`` is false, and that follows links — and + the replace then lands wherever the link points, outside the run dir + entirely. Measured, not theorised. + + ``open_dir_confined`` is the fix the repo already keeps for exactly this + (``tui/launch.py`` writes its control-window record the same way): it walks + each component below the run dir ``O_NOFOLLOW`` and hands back a descriptor + for the directory it actually reached, and :func:`atomic_write_text_at` + never names a path again. A path check would be answered *about a path* + and stale the moment it returned — the session can re-plant the link + between check and write — so this closes the window rather than narrowing + it. The ``mkdir`` above may still be fooled; that is harmless, because the + confinement walk that follows is not, and refusal is what the fooled case + produces. + + win32 has no ``*at()`` family to anchor against, so it keeps a + check-then-write, and the check is :func:`is_link_like` rather than + ``is_symlink()`` — on Windows the redirect that matters is a DIRECTORY + JUNCTION, which ``is_symlink()`` reports False for and which ``mklink /J`` + creates with no elevation at all, while a directory symlink needs + SeCreateSymbolicLinkPrivilege or Developer Mode. Checking only for + symlinks there would leave the unprivileged half of the same escape open, + and with no race to win. The residual is the platform's: a path check is + stale the moment it returns, but the planting session runs as the same uid + as this writer and the names here are engine-minted, so the exposure is a + redirected diagnostic rather than a foothold. + + Raises ``OSError`` — including when confinement cannot be established, so + an unconfined ``verify/`` REFUSES rather than writing through the link. + The caller degrades (this is observation), it does not swallow it here: + the record still lands, with a null pointer and ``capture_error``. + """ + verify_dir = self.run_dir / VERIFY_DIR + verify_dir.mkdir(parents=True, exist_ok=True) + if DIR_FD_ANCHORED_WRITES: + dir_fd = open_dir_confined(self.run_dir, verify_dir) + if dir_fd is None: + raise OSError( + f"refusing to write into an unconfined verify directory: {verify_dir}" + ) + try: + atomic_write_text_at(dir_fd, name, content) + finally: + os.close(dir_fd) + else: + if is_link_like(verify_dir): + raise OSError(f"refusing to write into a redirected verify directory: {verify_dir}") + atomic_write_text(verify_dir / name, content, follow_symlinks=False) + return (verify_dir / name).relative_to(self.run_dir).as_posix() + def entries(self) -> list[dict[str, Any]]: if not self.path.is_file(): return [] diff --git a/src/bmad_loop/platform_util.py b/src/bmad_loop/platform_util.py index d0a7a509..619b8f72 100644 --- a/src/bmad_loop/platform_util.py +++ b/src/bmad_loop/platform_util.py @@ -25,6 +25,7 @@ import random import re import shutil +import stat import subprocess import sys import tempfile @@ -589,6 +590,87 @@ def _atomic_write( DIR_FD_ANCHORED_WRITES = hasattr(os, "O_DIRECTORY") +# Windows reparse tags that make a directory entry REDIRECT somewhere else, +# compared against os.lstat().st_reparse_tag (Windows, 3.8+). Deliberately not +# os.path.isjunction(), which is 3.12+ while this package's floor is 3.11. +# Deliberately not "any reparse tag" either: cloud placeholders (OneDrive) and +# dedup stubs are reparse points too, and refusing those would stall a +# legitimate run. Empty on POSIX. +_LINK_REPARSE_TAGS = tuple( + tag + for tag in ( + getattr(stat, "IO_REPARSE_TAG_SYMLINK", None), + getattr(stat, "IO_REPARSE_TAG_MOUNT_POINT", None), + ) + if tag is not None +) + + +def is_link_like(path: Path) -> bool: + """True when ``path`` redirects elsewhere: a POSIX symlink, or a Windows + symlink OR DIRECTORY JUNCTION. + + ``Path.is_symlink()`` is False for a junction — junctions are a distinct + reparse kind, which is why ``os.path.isjunction()`` exists at all. On Windows + the junction is the arm that matters: ``mklink /J`` needs no elevation, while + a directory symlink needs SeCreateSymbolicLinkPrivilege or Developer Mode, so + the UNPRIVILEGED redirect is exactly the one an ``is_symlink()`` check misses. + + This is the win32 half of :func:`open_dir_confined`, which anchors the POSIX + side at a descriptor instead. A path check is inherently check-then-write — + answered about a name, and stale the moment it returns — so it narrows the + window rather than closing it. That residual is the platform's, not this + function's: win32 has no ``*at()`` family to anchor against. + + ``events.py`` and the standalone hook relay keep their own copies of this + predicate on purpose: they run under the HOST's interpreter, not this + package's, so they cannot import it from here. + """ + if path.is_symlink(): + return True + try: + return getattr(os.lstat(path), "st_reparse_tag", 0) in _LINK_REPARSE_TAGS + except OSError: + return False + + +def walk_files_unlinked(top: Path) -> Iterator[Path]: + """Every non-directory entry under ``top``, never crossing a redirect out of it. + + **Non-directory, not regular file** — ``os.walk`` puts FIFOs, device nodes and + symlinks in ``files`` alongside ordinary ones, and this yields what it is + handed. A caller that only counts or ``lstat``s is fine; a caller that OPENS + what it yields owes its own regular-file check, because opening a planted + FIFO blocks forever. Swapping ``rglob`` for this helper silently drops the + ``is_file()`` guard the old loop carried — that regression shipped once + (``diagnostics.summarize_files``, whose ``logs`` arm reads to count lines). + + Two holes, closed together because a caller that measures or counts a tree + gets both wrong in the same way: + + ``os.walk`` already declines to recurse into a symlinked subdirectory — but + it decides that with ``os.path.islink``, which is False for a Windows + DIRECTORY JUNCTION. That is the unprivileged redirect (see + :func:`is_link_like`), so on win32 the pruning `os.walk` documents is exactly + the arm an attacker would use. And ``os.walk`` always follows the top path it + is handed, symlink or not, so refusing to descend into links says nothing + about the root. + + Both matter to more than tidiness: a session is handed a writable run + directory (`BMAD_LOOP_RUN_DIR`) and can plant a link at an entry that `clean` + sizes and `diagnose` counts, which would bill a reclaim estimate — or a + diagnostic dump — for an arbitrarily large tree outside the run that neither + command touches. Yields paths; the caller chooses ``stat`` or ``lstat``. + """ + if is_link_like(top): + return + for root, dirs, files in os.walk(top, onerror=lambda _e: None): + # in-place, which is how os.walk documents pruning under topdown=True + dirs[:] = [d for d in dirs if not is_link_like(Path(root) / d)] + for name in files: + yield Path(root) / name + + def open_dir_confined(root: Path, target: Path) -> int | None: """An open descriptor for ``target``, reached from ``root`` without traversing a symlink at any component below it — or None when that cannot be diff --git a/src/bmad_loop/plugins/context.py b/src/bmad_loop/plugins/context.py index 1b8d6093..590ec9ab 100644 --- a/src/bmad_loop/plugins/context.py +++ b/src/bmad_loop/plugins/context.py @@ -20,8 +20,19 @@ from __future__ import annotations +import copy from dataclasses import dataclass -from typing import Any +from typing import TYPE_CHECKING, Any + +if TYPE_CHECKING: + # Type-only, exactly as `model.py` imports `HookContext`: the concrete + # verifier record type belongs in the signature, but importing it for real + # would be this package's SECOND core import (after manifest.py -> + # platform_util) and would point `plugins/` at the engine's I/O layer. There + # is no cycle today — `verify` reaches deferredwork/bmadconfig/frontmatter/ + # model/platform_util/policy/sprintstatus, none of which touch `plugins/` — + # so this is layering, not a workaround. + from ..verify import CommandResult # Veto actions, least to most conservative. `skip` drops the current unit and # continues the loop; `defer` routes through the engine's defer primitive; `pause` @@ -79,6 +90,9 @@ def __init__( result_json: dict[str, Any] | None = None, session_status: str | None = None, verify_reason: str | None = None, + command_results: tuple[CommandResult, ...] = (), + verification_stage: str | None = None, + verification_sequence: int | None = None, decision_action: str | None = None, settings: dict[str, Any] | None = None, shared: dict[str, Any] | None = None, @@ -102,11 +116,29 @@ def __init__( # the agent ids of the CLIs that run in this unit's worktree (dev + review), # for a plugin that routes per-agent config (e.g. the engine's MCP routing). self._agents = tuple(agents) - # a *copy* — result_json feeds the critical_escalations audit and must - # never be mutated through a plugin. - self._result_json = dict(result_json) if result_json is not None else None + # A *deep* copy, and the depth is the whole point. `dict()` is shallow, so + # the nested `escalations` list stayed SHARED with the engine's own + # `result.result_json` — and both verify legs now emit `post_dev_verify` + # ahead of their `critical_escalations` audit (dev via `decide_dev`, fix + # at the reordered call in `_fix_phase`). An in-process plugin holding + # this context could therefore clear that list and erase a CRITICAL + # escalation out from under the audit, letting a verify-green repair + # proceed where the run owed a pause. Copying at all exists to make + # "plugins observe, cannot alter" true; shallow made it true only of the + # top level, which is not where escalations live. + self._result_json = copy.deepcopy(result_json) if result_json is not None else None self._session_status = session_status self._verify_reason = verify_reason + # Frozen command-result records with immutable strings. This is an + # observe-only surface: plugins cannot replace the verifier outcome or + # modify this tuple, and the engine never reads it back for a decision. + self._command_results = tuple(command_results) + # The journal correlation keys for the pass those records came from — + # `verification_stage` is also the dev-vs-repair discriminator, which + # neither `stage` (both legs emit `post_dev_verify`) nor `phase` (both + # are DEV_VERIFY) nor `attempt` (one counter, shared) can supply. + self._verification_stage = verification_stage + self._verification_sequence = verification_sequence self._decision_action = decision_action self._settings = dict(settings) if settings is not None else {} # free-form, persisted across stages (engine backs it with plugin_shared) @@ -184,6 +216,66 @@ def session_status(self) -> str | None: def verify_reason(self) -> str | None: return self._verify_reason + @property + def command_results(self) -> tuple[CommandResult, ...]: + """The verifier ``CommandResult`` records from this attempt's verify pass, + in the order the commands ran. Read-only observability for + ``post_dev_verify``; nothing here feeds an engine decision. + + Empty is ambiguous ON ITS OWN and must not be read as "the commands did + not run" — read it together with :attr:`verification_stage`, which is what + separates the cases: + + * ``verification_stage is None`` — no verify pass ran at all. FOUR + distinct causes reach here and an empty tuple names none of them: + + 1. the session did not complete — ``session_status`` says so; + 2. the dev-artifact gate already failed the attempt — ``verify_reason``; + 3. on the repair leg, the deferral harvest short-circuited ahead of the + commands — also ``verify_reason``; + 4. the engine variant suppressed the pass for this leg — + ``StoriesEngine`` skips it on a plan-halt leg, which has no + implementation to build, so nothing on the context marks this one + apart from a run that simply configured no commands. + + ``session_status`` and ``verify_reason`` separate 1–3; this tuple + separates none of them, and does not try. + * ``verification_stage`` set with ``verification_sequence is None`` — the + pass DID run and executed nothing, because ``[verify] commands`` is + empty. No journal record exists for it either. + * ``verification_stage`` set with an int ``verification_sequence`` — those + commands ran, and each has a matching journal entry (see that property). + """ + return self._command_results + + @property + def verification_stage(self) -> str | None: + """Which leg produced :attr:`command_results` — ``"dev"`` for the initial + dev verification, ``"fix"`` for a feedback-driven repair one, ``None`` + when no verify pass ran (see :attr:`command_results`). + + This is the ONLY discriminator between the two. ``stage`` and ``phase`` + are literally identical across them (``post_dev_verify`` from + ``Phase.DEV_VERIFY``), and ``attempt`` is one per-story counter the + repair leg CONTINUES rather than restarts — so its value orders the two + but never names either, and a human re-arm reuses the numbers outright. + """ + return self._verification_stage + + @property + def verification_sequence(self) -> int | None: + """This story's 1-based ordinal for the verify pass that produced + :attr:`command_results`, or ``None`` when the pass recorded nothing. + + The join key back to the run journal: the ``verify-command-result`` + entries with this ``story_key`` + ``verification_stage`` + + ``verification_sequence`` are exactly these results, one per record, + ordered by their ``command_index``. Monotonic per story across a + pause/resume — the sequence is durable, unlike ``attempt``, which a human + re-arm can reuse. + """ + return self._verification_sequence + @property def decision_action(self) -> str | None: return self._decision_action diff --git a/src/bmad_loop/policy.py b/src/bmad_loop/policy.py index 1c4a0570..c9947183 100644 --- a/src/bmad_loop/policy.py +++ b/src/bmad_loop/policy.py @@ -161,6 +161,27 @@ class LimitsPolicy: @dataclass(frozen=True) class VerifyPolicy: commands: tuple[str, ...] = () + # stream_capture_kb bounds, per stream, the verifier stdout/stderr retained + # under the run's `verify/` directory for plugins and post-mortems (#641). + # A tail is kept, matching every other bound on this output — the merged + # `output_tail` is `[-2000:]`, and the end of a failing suite is where the + # failure is. The journal record stays honest about the cut: it carries the + # FULL byte count beside the retained one and an explicit truncation flag, + # because a silently short file reads as a complete one. + # + # 256 KiB is chosen against what the store is FOR: a repair session or a + # plugin reading a failing suite's tail. A verbose pytest/ruff failure runs + # tens of KB, so the cap is generous enough that the realistic case is never + # cut, while a chatty command under COMMAND_TIMEOUT_S (30 minutes) can no + # longer emit hundreds of MB per attempt. Worst case is bounded and small: + # commands x 2 streams x attempts x 256 KiB. It sits far under the file-store + # precedent it is modelled on (scm.failed_diff_max_mb = 5) and far above the + # inline-journal caps, which is the right side of both. + # + # 0 = capture nothing: no files are written at all, and the record still + # lands with null pointers and the full byte counts, so the journal keeps + # saying what the command emitted even when none of it is retained. + stream_capture_kb: int = 256 @dataclass(frozen=True) @@ -852,7 +873,12 @@ def loads(text: str, plugin_schemas: dict[str, Any] | None = None) -> Policy: f"limits.session_budget_grace_s must be >= 0: got {limits.session_budget_grace_s}" ) - verify = VerifyPolicy(commands=tuple(str(c) for c in verify_d.get("commands", ()))) + verify = VerifyPolicy( + commands=tuple(str(c) for c in verify_d.get("commands", ())), + stream_capture_kb=int(verify_d.get("stream_capture_kb", VerifyPolicy.stream_capture_kb)), + ) + if verify.stream_capture_kb < 0: + raise PolicyError(f"verify.stream_capture_kb must be >= 0: got {verify.stream_capture_kb}") notify = NotifyPolicy( desktop=bool(notify_d.get("desktop", NotifyPolicy.desktop)), file=bool(notify_d.get("file", NotifyPolicy.file)), @@ -1165,6 +1191,7 @@ def _fold_deprecated_engine( [verify] # Deterministic gates run by the orchestrator after a clean review, before commit. commands = [] # e.g. ["pytest -q", "ruff check ."] +stream_capture_kb = 256 # per-stream cap (KiB) on the verifier stdout/stderr retained under the run's verify/ directory; the TAIL is kept and the journal records the full byte count plus a truncation flag. 0 = capture nothing (records still land, with null pointers) [notify] desktop = true # notify-send (Linux) / osascript (macOS) / PowerShell toast (Windows), best-effort diff --git a/src/bmad_loop/runs.py b/src/bmad_loop/runs.py index 1251e23f..94fd346e 100644 --- a/src/bmad_loop/runs.py +++ b/src/bmad_loop/runs.py @@ -18,7 +18,7 @@ from . import devcontract, envvars, verify from .adapters.multiplexer import MultiplexerError, get_multiplexer -from .journal import STATE_FILE, Journal, load_state, save_state +from .journal import STATE_FILE, VERIFY_DIR, Journal, load_state, save_state from .model import PAUSE_ESCALATION, Phase, RunState, StoryTask from .platform_util import ( MAX_SEGMENT, @@ -26,6 +26,7 @@ atomic_write_text, has_parent_ref, is_absolute_path, + is_link_like, retrying_unlink, safe_segment, ) @@ -1065,10 +1066,30 @@ def archive_run(project: Path, run_dir: Path, *, force: bool = False) -> Path: # Heavy per-run scaffolding trimmed from a concluded run dir while the # TUI-visible core (state.json, journal.jsonl, logs/, ATTENTION) is preserved, -# so the run still lists and renders in the dashboard. The value mirrors +# so the run still lists and renders in the dashboard. "worktrees" mirrors # workspace.WORKTREE_DIRNAME; kept literal here to avoid an import cycle # (workspace imports nothing from runs, but runs stays leaf-light on purpose). -_HEAVY_RUN_ENTRIES = ("worktrees",) +# +# VERIFY_DIR is the retained verifier stdout/stderr store. It qualifies as heavy +# on the same measure as a worktree checkout: `[verify] stream_capture_kb` +# defaults to 256 KiB per stream, so a run accumulates up to 512 KiB per verify +# command per attempt, and nothing else ever reclaims it. Its journal records +# survive the trim and keep naming the files (`stdout_path`/`stderr_path`), which +# is the same bargain `worktrees` already makes — a trimmed run is a run you can +# still see and resume, not one you can still re-read every artifact of. Imported +# from the writer rather than re-spelled, so the reclaim cannot drift from the +# directory `Journal.write_verify_stream` actually creates. +_HEAVY_RUN_ENTRIES = ("worktrees", VERIFY_DIR) + + +def heavy_run_entries(run_dir: Path) -> list[Path]: + """The paths :func:`trim_run_dir` would remove from ``run_dir``. + + Exists so a caller sizing the reclaim measures exactly what the trim takes. + `clean` sums these before mutating (its estimate has to hold under + --dry-run); reading the tuple through this function is what keeps that sum + from silently going stale the next time an entry is added to it.""" + return [run_dir / name for name in _HEAVY_RUN_ENTRIES] def _state_or_none(run_dir: Path): @@ -1246,21 +1267,46 @@ def reconcile_orphan_state_dirs(project: Path, *, dry_run: bool = False) -> list return handled +def _unlink_redirect(p: Path) -> None: + """Remove a link-like entry itself, never what it points at. + + ``shutil.rmtree`` REFUSES a directory symlink by design (it would otherwise + delete the target's contents), and under ``ignore_errors=True`` that refusal + is swallowed — so trimming a planted redirect reported success while leaving + the link on disk. Unlink covers a POSIX symlink and a win32 file symlink; + ``rmdir`` is the win32 arm, where ``DeleteFileW`` rejects a directory symlink + or junction and ``RemoveDirectoryW`` drops the reparse point without + following it. Best-effort to match the ``rmtree`` beside it: a trim is + reclamation, and a run dir we cannot fully reclaim is not a reason to abort + the whole `clean`.""" + try: + p.unlink() + except OSError: + with contextlib.suppress(OSError): + p.rmdir() + + def trim_run_dir(run_dir: Path, *, dry_run: bool = False) -> list[Path]: - """Delete heavy scaffolding (the ``worktrees/`` tree) from a concluded run - dir, preserving its TUI-visible core so the run still appears in the - dashboard with full status/journal/logs. Returns the paths removed. + """Delete heavy scaffolding (the ``worktrees/`` tree and the retained + verifier stream store) from a concluded run dir, preserving its TUI-visible + core so the run still appears in the dashboard with full status/journal/logs. + Returns the paths removed. The run's out-of-tree control plane is deliberately left alone (see :func:`_discard_state_dir`): a trimmed run still exists and is still resumable, so its state dir has to outlive its scaffolding.""" removed: list[Path] = [] - for name in _HEAVY_RUN_ENTRIES: - p = run_dir / name - if p.exists() or p.is_symlink(): - removed.append(p) - if not dry_run: - shutil.rmtree(p, ignore_errors=True) + for p in heavy_run_entries(run_dir): + link = is_link_like(p) + if not (p.exists() or link): + continue + removed.append(p) + if dry_run: + continue + if link: + _unlink_redirect(p) + else: + shutil.rmtree(p, ignore_errors=True) return removed diff --git a/src/bmad_loop/verify.py b/src/bmad_loop/verify.py index 775ef06f..66108629 100644 --- a/src/bmad_loop/verify.py +++ b/src/bmad_loop/verify.py @@ -7,6 +7,7 @@ from __future__ import annotations +import locale import os import re import shlex @@ -2512,11 +2513,68 @@ def _stories_relpaths(project: Path, spec_folder: Path) -> tuple[str, ...]: return (f"{base}{STORIES_SUBDIR}", f"{base}{STORIES_FILENAME}") +# A hard ceiling on how much of one verifier stream is held in memory, separate +# from and far above `[verify] stream_capture_kb` (which bounds what reaches +# disk). `subprocess.run(capture_output=True)` already materialises a command's +# whole output, but before this bound the full streams were then RETAINED in the +# results list while every later command ran, so peak memory grew with the number +# of configured verify commands rather than with the largest one. Plugins are +# meant to see the streams essentially whole, so this is a backstop against a +# pathologically chatty suite, not a tuning knob — deliberately a constant, and +# deliberately high enough that ordinary suites never reach it. +# +# It bounds retention, not capture: while command N runs, memory still holds the +# capped earlier results plus whatever N itself emits. +MAX_STREAM_MEMORY_BYTES = 32 * 1024 * 1024 + + +def byte_tail(text: str, max_bytes: int) -> tuple[str, int]: + """``(tail, full_bytes)`` — ``text`` cut to its last ``max_bytes`` UTF-8 bytes. + + The one implementation of a rule this feature applies at two different + bounds (this in-memory ceiling and the engine's `stream_capture_kb` disk + cap), because the subtle half is easy to get wrong twice: a byte cut can + land mid-character, and the leading partial is DROPPED rather than decoded + into a ``\ufffd`` this function would be inventing. Decoding with + ``errors="replace"`` instead would also break the cap it is enforcing — + ``\ufffd`` is three UTF-8 bytes standing in for the one it replaces, so the + result can exceed ``max_bytes``. + + ``full_bytes`` always measures the input, so a caller can report what was + emitted even after keeping less of it. The TAIL is kept: a failing suite + puts its failure at the end. ``max_bytes <= 0`` needs no branch — the slice + is empty by construction, which is exactly "keep nothing". + """ + encoded = text.encode("utf-8") + full_bytes = len(encoded) + if full_bytes <= max_bytes: + return text, full_bytes + return encoded[full_bytes - max_bytes :].decode("utf-8", errors="ignore"), full_bytes + + @dataclass(frozen=True) class CommandResult: + """One verifier subprocess result. + + ``output_tail`` remains the merged, bounded compatibility field used by the + existing failure classifiers and repair feedback. ``stdout`` and ``stderr`` + retain the separate streams observed at the subprocess boundary so the + engine can expose them to trusted plugins and retain them by journal pointer. + + ``*_full_bytes`` is what the command EMITTED, which is only interesting when + it differs from the stream beside it — i.e. when ``MAX_STREAM_MEMORY_BYTES`` + cut one. ``None`` means nothing was cut and the stream is the whole of it, so + the many callers that build a result from three fields stay correct without + knowing this exists. + """ + command: str returncode: int output_tail: str + stdout: str = "" + stderr: str = "" + stdout_full_bytes: int | None = None + stderr_full_bytes: int | None = None # sh launcher convention (verify commands run shell=True): 126 = command found @@ -2658,6 +2716,42 @@ def env_fault_reason(result: CommandResult, cwd: Path) -> str | None: return _win32_env_fault_reason(result, cwd) +def _timeout_stream(value: str | bytes | None) -> str: + """Normalize optional timeout output into what the completed path would give. + + ``subprocess.run``'s timeout leg is not uniform, so three shapes arrive: + + * ``bytes`` — POSIX. ``Popen._communicate`` raises ``TimeoutExpired`` from + ``_check_timeout`` with the raw chunks joined, *before* the text-mode + decode that ends the loop, so ``text=True`` never touched them. + * ``str`` — Windows, where ``run`` calls ``communicate()`` after ``kill()`` + and the text wrapper has already decoded. Load-bearing: on that platform + this branch is the only way the output arrives at all. + * ``None`` — POSIX again, when nothing had been buffered on that stream. + + So the bytes branch has to reproduce what text mode would have done to them, + which is exactly ``Popen._translate_newlines``: decode, then collapse ``\\r\\n`` + and lone ``\\r`` to ``\\n``. Doing neither made the same bytes read back + differently depending on which path produced them — under an ASCII locale + ``b"caf\\xc3\\xa9\\r\\n"`` completed as ``"caf\\ufffd\\ufffd\\n"`` but timed out + as ``"café\\r\\n"``. The codec half also contradicted + :func:`run_verify_commands`' own rule (#378) that host-tool output stays on + the locale codec: ``locale.getpreferredencoding(False)`` is what ``text=True`` + resolves for an unset ``encoding`` — deliberately not ``locale.getencoding()``, + which disagrees with it under UTF-8 mode (PEP 540), a mode the C/POSIX locale + enables by itself. ``errors="replace"`` for the reason the completed path uses + it: one undecodable byte must not raise and lose every result. + + The str branch is left alone: its newlines were translated by the text + wrapper the reader thread read through, so there is nothing left to collapse.""" + if value is None: + return "" + if isinstance(value, bytes): + decoded = value.decode(locale.getpreferredencoding(False), errors="replace") + return decoded.replace("\r\n", "\n").replace("\r", "\n") + return value + + def run_verify_commands(policy: Policy, cwd: Path) -> list[CommandResult]: """Run each of the policy's verify commands, one CommandResult apiece. @@ -2682,15 +2776,33 @@ def run_verify_commands(policy: Policy, cwd: Path) -> list[CommandResult]: errors="replace", timeout=COMMAND_TIMEOUT_S, ) - output = (proc.stdout + proc.stderr)[-2000:] - results.append(CommandResult(command, proc.returncode, output)) - except subprocess.TimeoutExpired: - results.append(CommandResult(command, -1, "timed out")) + stdout, stdout_full = byte_tail(proc.stdout, MAX_STREAM_MEMORY_BYTES) + stderr, stderr_full = byte_tail(proc.stderr, MAX_STREAM_MEMORY_BYTES) + # merged from the ceilinged streams, not the raw pair: 2000 chars sits + # far below the ceiling, so the tail is identical while the full + # concatenation — a transient copy of both whole streams — is not built. + output = (stdout + stderr)[-2000:] + results.append( + CommandResult( + command, proc.returncode, output, stdout, stderr, stdout_full, stderr_full + ) + ) + except subprocess.TimeoutExpired as exc: + # the timeout leg is bounded too: a command killed at COMMAND_TIMEOUT_S + # is exactly the one that may have been spewing output when it died. + t_out, t_out_full = byte_tail(_timeout_stream(exc.stdout), MAX_STREAM_MEMORY_BYTES) + t_err, t_err_full = byte_tail(_timeout_stream(exc.stderr), MAX_STREAM_MEMORY_BYTES) + results.append( + CommandResult(command, -1, "timed out", t_out, t_err, t_out_full, t_err_full) + ) return results -def verify_commands_outcome(policy: Policy, cwd: Path) -> VerifyOutcome: - """Run the policy's deterministic verify commands. Failures are fixable: +def verify_command_results_outcome(results: list[CommandResult], cwd: Path) -> VerifyOutcome: + """Classify already-observed verifier results without discarding them. + + Kept separate from :func:`verify_commands_outcome` so the engine can retain + and expose exactly the same results it asks core to classify. Failures are fixable: the captured output is concrete feedback a repair session can act on — except environment faults (see env_fault_reason), which escalate so the run pauses for an environment fix instead of burning story budgets. An env @@ -2698,7 +2810,6 @@ def verify_commands_outcome(policy: Policy, cwd: Path) -> VerifyOutcome: session dispatched for the ordinary failure would still run in the broken environment. Note the first loop inspects rc=0 results too — on Windows an unrunnable command is a silent pass, not a failure (#302).""" - results = run_verify_commands(policy, cwd) for result in results: reason = env_fault_reason(result, cwd) if reason is not None: @@ -2720,6 +2831,11 @@ def verify_commands_outcome(policy: Policy, cwd: Path) -> VerifyOutcome: return VerifyOutcome.passed() +def verify_commands_outcome(policy: Policy, cwd: Path) -> VerifyOutcome: + """Run the policy's deterministic verify commands and classify the results.""" + return verify_command_results_outcome(run_verify_commands(policy, cwd), cwd) + + def verify_review( task: StoryTask, paths: ProjectPaths, diff --git a/tests/test_cleanup.py b/tests/test_cleanup.py index 269a228d..49ffb6ee 100644 --- a/tests/test_cleanup.py +++ b/tests/test_cleanup.py @@ -2,11 +2,13 @@ artifact trim, and the `clean` CLI command.""" import argparse +import os +import pytest from conftest import install_bmad_config, machine_json from bmad_loop import cli, runs, verify -from bmad_loop.journal import save_state +from bmad_loop.journal import VERIFY_DIR, save_state from bmad_loop.model import RunState from bmad_loop.tui import data @@ -193,6 +195,77 @@ def test_trim_run_dir_keeps_run_viewable(tmp_path): assert [i.run_id for i in infos] == ["20260101-000000-aaaa"] +def test_trim_run_dir_reclaims_the_verifier_stream_store(tmp_path): + """The retained verifier stdout/stderr store is trimmed with the worktrees, + and trimming it does not cost the run its place in the dashboard. + + It qualifies as heavy on the same measure a worktree checkout does: + `[verify] stream_capture_kb` defaults to 256 KiB per stream, so a run + accumulates up to 512 KiB per verify command per attempt. Nothing else ever + reclaimed it — the store outlived every trim and survived for as long as the + run dir did. What it costs is re-reading the streams the journal's + `stdout_path`/`stderr_path` still name, which is the bargain `worktrees` + already makes: a trimmed run is one you can still see and resume, not one you + can still open every artifact of. + + Ablation: drop VERIFY_DIR from `_HEAVY_RUN_ENTRIES` and `removed` comes back + `["worktrees"]` with the store still on disk. Verified. + """ + run_dir = _state_run(tmp_path, "20260101-000000-aaaa", finished=True) + (run_dir / "journal.jsonl").write_text('{"kind":"run-start"}\n') + (run_dir / "logs").mkdir() + (run_dir / "worktrees" / "u").mkdir(parents=True) + store = run_dir / VERIFY_DIR + store.mkdir() + (store / "verify-1-1-a-dev-1-1-0.stdout.log").write_bytes(b"o" * 2048) + (store / "verify-1-1-a-dev-1-1-0.stderr.log").write_bytes(b"e" * 1024) + + removed = runs.trim_run_dir(run_dir) + + assert [p.name for p in removed] == ["worktrees", VERIFY_DIR] + assert not store.exists() + # the TUI-visible core the trim exists to preserve + assert (run_dir / "state.json").is_file() + assert (run_dir / "journal.jsonl").is_file() + infos = data.discover_runs(tmp_path) + assert [i.run_id for i in infos] == ["20260101-000000-aaaa"] + + +@pytest.mark.skipif( + os.name != "posix", reason="planting a directory symlink needs privilege on win32" +) +def test_trim_run_dir_removes_a_planted_redirect_without_following_it(tmp_path): + """A trimmed entry that is a LINK is removed as a link, and its target is not. + + A session is handed the writable run dir (`BMAD_LOOP_RUN_DIR`) and can plant a + redirect at `verify/` — the same escape the write path was hardened against. + The reclaim path had the mirror-image hole: `shutil.rmtree` REFUSES a directory + symlink by design (following it would delete the target's contents), and under + `ignore_errors=True` that refusal is silent, so the trim appended the entry to + `removed` and left the link exactly where it was. + + Both halves are graded, because the obvious over-correction is worse than the + bug: the redirect goes, and what it pointed at stays. POSIX-only because + PLANTING the link needs privilege on win32, not because the fix is — the + junction arm rides on `is_link_like`, graded in tests/test_platform_util.py. + + Ablation: restore the bare `shutil.rmtree(p, ignore_errors=True)` and the link + is still on disk after the trim, with `removed` still naming it. Verified. + """ + run_dir = _state_run(tmp_path, "20260101-000000-aaaa", finished=True) + outside = tmp_path / "outside" + outside.mkdir() + (outside / "keep.txt").write_bytes(b"x" * 5000) + link = run_dir / VERIFY_DIR + link.symlink_to(outside, target_is_directory=True) + + removed = runs.trim_run_dir(run_dir) + + assert [p.name for p in removed] == [VERIFY_DIR] + assert not link.is_symlink() and not link.exists() # the redirect really went + assert outside.is_dir() and (outside / "keep.txt").is_file() # the target did not + + # ------------------------------------------------------------- cmd_clean @@ -454,6 +527,73 @@ def test_cmd_clean_json_real_run_reports_what_it_did(project, capsys): assert doc["freed_bytes"] >= 4096 +def test_cmd_clean_counts_the_verifier_stream_store_it_reclaimed(project, capsys): + """The reclaim estimate is sized over what the trim actually takes. + + `freed_bytes` is what an operator reads to decide whether `clean` was worth + running, and for a trimmed run it used to sum `worktrees/` alone. That was + exactly right while `worktrees/` was the only heavy entry and silently wrong + the moment the verifier stream store joined it: `clean` would remove up to + 512 KiB per verify command per attempt and report reclaiming nothing. + + Seeded with no `worktrees/` at all, so the removal and the accounting are + graded independently and neither can ride on the other's bytes. + + Ablation, two axes reddening different assertions: drop VERIFY_DIR from + `_HEAVY_RUN_ENTRIES` and `trimmed` empties — the trim finds nothing to take. + Restore it but size the estimate over `worktrees/` alone again and the store + is gone with `freed_bytes` at 0 — a reclaim that happened and went unreported. + Verified. + """ + install_bmad_config(project) + repo = project.project + run_dir = repo / ".bmad-loop" / "runs" / "20260101-000000-aaaa" + store = run_dir / VERIFY_DIR + store.mkdir(parents=True) + (store / "verify-1-1-a-dev-1-1-0.stdout.log").write_bytes(b"o" * 4096) + (store / "verify-1-1-a-dev-1-1-0.stderr.log").write_bytes(b"e" * 2048) + save_state(run_dir, RunState(run_id="r", project=str(repo), started_at="x", stopped=True)) + + doc = _clean_json(repo, capsys) + + assert doc["trimmed"] == ["20260101-000000-aaaa"] + assert not store.exists() + assert doc["freed_bytes"] == 4096 + 2048 + assert (run_dir / "state.json").is_file() # trimmed, not removed + + +@pytest.mark.skipif( + os.name != "posix", reason="planting a directory symlink needs privilege on win32" +) +def test_cmd_clean_does_not_bill_the_reclaim_for_bytes_behind_a_redirect(project, capsys): + """`freed_bytes` counts what the trim freed, never what a planted link points at. + + `os.walk` does not descend into links, but it does follow the top path it is + handed — so sizing a redirected entry bills the reclaim for out-of-run bytes + that are demonstrably still on disk when `clean` returns. That is the estimate + an operator reads to decide whether the command was worth running, and it is + the one number here a session can inflate from outside the run. + + Ablation: drop the `is_link_like` refusal from `_dir_size` and `freed_bytes` + comes back 5000 — bytes the assertion below proves were never freed. Verified. + """ + install_bmad_config(project) + repo = project.project + run_dir = repo / ".bmad-loop" / "runs" / "20260101-000000-aaaa" + run_dir.mkdir(parents=True, exist_ok=True) + outside = repo.parent / "outside" + outside.mkdir(exist_ok=True) + (outside / "keep.txt").write_bytes(b"x" * 5000) + (run_dir / VERIFY_DIR).symlink_to(outside, target_is_directory=True) + save_state(run_dir, RunState(run_id="r", project=str(repo), started_at="x", stopped=True)) + + doc = _clean_json(repo, capsys) + + assert doc["trimmed"] == ["20260101-000000-aaaa"] + assert doc["freed_bytes"] == 0 # nothing inside the run was actually freed + assert (outside / "keep.txt").is_file() # and the 5000 bytes are still there + + def test_cmd_clean_json_names_every_item_the_text_enumerates(project, capsys): # protected is a bare count in the text ("left N ... untouched") and # archived/deleted are per-line; the document names all of them. diff --git a/tests/test_diagnostics.py b/tests/test_diagnostics.py index f7800347..e5b2cfde 100644 --- a/tests/test_diagnostics.py +++ b/tests/test_diagnostics.py @@ -9,6 +9,7 @@ import dataclasses import json +import os import re import sys import types @@ -443,6 +444,66 @@ def test_a_windows_spec_path_normalizes_to_the_same_alias(): assert re.fullmatch(r"spec-[0-9a-f]{12}", trailing["spec"]) +def test_verify_command_free_text_drops_to_presence_booleans(): + """A `verify-command-result` record ships its correlation half, never its text. + + `_scrub_entry` routes by field NAME, and five of this record's fields are free + text: `command` is operator-authored shell, `output_tail` is a build's own + output, `capture_error` is an OSError string carrying a path, and the two + stream pointers embed the story key. Left to the `scrub_json` fallback they + fail closed only by ACCIDENT of shape — `_IDENTIFIER_RE` forbids `/` and + spaces, so paths, argv-ish commands and multi-line tails collapse — but a + one-word command like `make` satisfies it and ships verbatim. + + Ablation: remove the five names from `_JOURNAL_DROP_FIELDS`. `command` comes + back as the literal `make` (reddening the presence assertion AND the canary + sweep), while `output_tail` / `capture_error` / `stdout_path` merely turn into + `` — which is why `make` is the value under test and not a + path-shaped one: only it separates the drop list from the fallback. + """ + pseudo = sanitize.Pseudonymizer(salt=b"fixed") + out = diagnostics._scrub_entry( + { + "ts": 1.0, + "kind": "verify-command-result", + "story_key": STORY_KEY, + "attempt": 2, + "verification_stage": "dev", + "verification_sequence": 3, + "command_index": 0, + "command": "make", + "returncode": 1, + "output_tail": CODE, + "capture_error": f"stdout: [Errno 28] No space left on device: '{HOME_PATH}/x'", + "stdout_path": f"verify/verify-{STORY_KEY}-dev-2-3-0.stdout.log", + "stderr_path": None, + "stdout_bytes": 12, + "stdout_truncated": False, + }, + pseudo, + {}, + 1.0, + ) + + for field in ("command", "output_tail", "capture_error", "stdout_path", "stderr_path"): + assert field not in out, f"{field} must never be emitted" + assert out["command_present"] is True + assert out["output_tail_present"] is True + assert out["capture_error_present"] is True + # the pointers keep the one fact they are worth: whether a stream was retained + # at all — `stream_capture_kb = 0` and a failed write both leave it null. + assert out["stdout_path_present"] is True + assert out["stderr_path_present"] is False + # ... while everything a maintainer correlates on still ships verbatim + assert (out["verification_stage"], out["verification_sequence"]) == ("dev", 3) + assert (out["command_index"], out["returncode"], out["attempt"]) == (0, 1, 2) + assert (out["stdout_bytes"], out["stdout_truncated"]) == (12, False) + + rendered = json.dumps(out) + for canary in ("make", CODE, HOME_PATH, PROPRIETARY, *CANARIES): + assert canary not in rendered, f"LEAK: {canary!r}" + + def test_structure_is_preserved(project): run_dir = _seed_run(project.project) diag, _pseudo, _combined = _render_all([run_dir]) @@ -991,3 +1052,206 @@ def test_scrub_policy_passes_unknown_section_keys_verbatim(): # The pure guard-mechanics tests (hard-rule refusal, repair tally, cyclic # termination) live in tests/test_sanitize.py since #199 made guard shared API; # this file keeps the integration surface: real collectors, real renders. + + +# --------------------------------------------- the verifier stream store + + +def test_verify_streams_are_counted_but_never_read(project, tmp_path): + """`verify/` is stat-only: its SIZE is the diagnostic, its contents are not. + + The store can be one of the larger things in a run dir — `stream_capture_kb` + defaults to 256 KiB per stream, so up to 512 KiB per command per attempt, with + no GC behind it yet — so a dump that omits it cannot show the retention or + disk-usage problem a maintainer opens a dump to find. It is equally the one + category that must never be READ into the output: retained verifier output is + a build's own stdout/stderr and may carry anything the project's test suite + prints. + + Ablation guard: drop `VERIFY_DIR` from `_FILE_CATEGORIES` and the group is + None — the `is_dir()` guard makes an unregistered category vanish silently + rather than redden, which is exactly how this was missed. Verified. + """ + run_dir = _seed_bare_run(project.project) + verify_dir = run_dir / "verify" + verify_dir.mkdir(parents=True, exist_ok=True) + secret = "SUPER-SECRET-BUILD-OUTPUT-DO-NOT-EMIT" + (verify_dir / "verify-1-1-a-dev-1-1-0.stdout.log").write_text(secret, encoding="utf-8") + (verify_dir / "verify-1-1-a-dev-1-1-0.stderr.log").write_text("err", encoding="utf-8") + + diag = diagnostics.collect( + [run_dir], pseudo=sanitize.Pseudonymizer(), project=Path(project.project) + ) + group = next((g for g in diag.runs[0].files if g.category == "verify"), None) + + assert group is not None, "verify/ is not registered as a diagnostic category" + assert group.count == 2 + assert group.total_bytes == len(secret) + len("err") + + # the half that matters as much as the count: the dump STATS, never reads + assert secret not in diagnostics.render_markdown(diag) + assert secret not in diagnostics.render_json(diag) + + +@pytest.mark.skipif( + sys.platform == "win32", reason="planting a directory symlink needs privilege on win32" +) +def test_a_redirected_verify_root_is_not_counted_as_this_runs_output(project, tmp_path): + """A planted redirect at `verify/` must not make `diagnose` report someone + else's tree as this run's retained verifier output. + + `summarize_files` admits a category root on `root.is_dir()`, which FOLLOWS a + link, and then walked it with `rglob("*")`. Measured before the fix: two files + and 3100 bytes from outside the run, attributed to this run. Registering + `verify/` as a category — the fix for the earlier "invisible store" gap — is + what put a session-plantable directory on that traversal at all; every other + category root is engine-created, which is why the hole opened here and not + years ago. + + Ablation: walk the root with `rglob("*")` again and the group comes back + naming the target's count and bytes. Verified. + """ + run_dir = _seed_bare_run(project.project) + outside = tmp_path / "somewhere-else" + outside.mkdir() + (outside / "a.bin").write_bytes(b"a" * 3000) + (outside / "b.bin").write_bytes(b"b" * 100) + (run_dir / "verify").symlink_to(outside, target_is_directory=True) + + diag = diagnostics.collect( + [run_dir], pseudo=sanitize.Pseudonymizer(), project=Path(project.project) + ) + group = next((g for g in diag.runs[0].files if g.category == "verify"), None) + + assert group is None # nothing of ours is in there, so there is nothing to report + assert (outside / "a.bin").is_file() # and the dump did not touch what it found + + +# ---------------------------------------------------- planted non-regular files +# +# `summarize_files` walks with `walk_files_unlinked`, and `os.walk` reports every +# NON-DIRECTORY entry — FIFOs and symlinks included. The `is_file()` guard the old +# `rglob` loop carried came off with that switch, and the `logs` arm OPENS what it +# counts. Four ablation axes, and each reddens exactly one test below — the +# loop's `S_ISREG` inventory filter, and `_count_lines`' `O_NONBLOCK`, +# `O_NOFOLLOW`, and `S_ISREG`-on-the-fd. Disjoint failures are what shows the +# four guards are not standing in for each other. + +_FIFO = pytest.mark.skipif(not hasattr(os, "mkfifo"), reason="POSIX FIFOs") + + +@_FIFO +def test_count_lines_refuses_an_idle_fifo_instead_of_blocking(tmp_path): + """A FIFO nobody is feeding: opening it read-only without ``O_NONBLOCK`` + blocks until a writer arrives, which for a run directory the session owns + means `diagnose` never returns and the operator's terminal is wedged. + + Bounded with ``SIGALRM`` rather than a subprocess, following + `test_runs.py`'s twin: a hang is the failure under test, so the test needs a + deadline of its own or an ablation wedges the suite instead of reddening it. + + ABLATION: drop ``O_NONBLOCK`` from the flags and the alarm fires. Dropping the + fd ``S_ISREG`` check instead does NOT show up here — with no writer the read + hits EOF and answers 0 either way, which is exactly why the fed twin below + exists. Verified.""" + import signal + + path = tmp_path / "session.log" + os.mkfifo(path) + + def _blew_up(signum, frame): + raise AssertionError("the line count blocked on the FIFO instead of refusing it") + + previous = signal.signal(signal.SIGALRM, _blew_up) + signal.alarm(20) + try: + assert diagnostics._count_lines(path) == 0 + finally: + signal.alarm(0) + signal.signal(signal.SIGALRM, previous) + + +@_FIFO +def test_count_lines_refuses_a_fed_fifo_without_consuming_it(tmp_path): + """The half the alarm above cannot see. There the FIFO is idle, so the harm is + a hang and the bytes read are merely empty; here a writer holds it open and is + feeding it, so a reader that gets past the open never blocks — it counts + whatever the session piped in as this run's log lines, and drains the pipe on + the way through. Neither shows up as a hang, so the alarm above would never + notice. + + ``O_RDWR`` for the holder deliberately — a write-only open on a FIFO blocks + until a reader arrives and would wedge the test itself, and ``O_RDWR`` never + blocks. + + ABLATION: delete the ``S_ISREG(os.fstat(fd))`` check and this answers **3** — + the piped lines, billed to this run. The byte assert grades the second harm on + the same axis: the read consumed them, so the holder's own read no longer + finds what it wrote. Verified.""" + path = tmp_path / "session.log" + os.mkfifo(path) + + holder = os.open(path, os.O_RDWR | os.O_NONBLOCK) + try: + os.write(holder, b"one\ntwo\nthree\n") + assert diagnostics._count_lines(path) == 0 + assert os.read(holder, 64) == b"one\ntwo\nthree\n" # untouched + finally: + os.close(holder) + + +@pytest.mark.skipif(sys.platform == "win32", reason="POSIX symlink + O_NOFOLLOW") +def test_count_lines_refuses_a_symlink_instead_of_reading_its_target(tmp_path): + """``O_NOFOLLOW``: the walk refuses to descend THROUGH a redirect, but the + final component it hands back is still a name, and the inventory filter that + normally screens a symlinked entry out is a check-then-open race on a + directory the session can write. The read anchors on the flag instead. + + ABLATION: drop ``O_NOFOLLOW`` and this returns 2 — the target's lines, + attributed to this run. Verified.""" + outside = tmp_path / "elsewhere.txt" + outside.write_bytes(b"theirs\nnot ours\n") + link = tmp_path / "session.log" + link.symlink_to(outside) + + assert diagnostics._count_lines(link) == 0 + + +@_FIFO +def test_a_planted_fifo_is_not_counted_as_this_runs_log_output(project, tmp_path): + """The inventory half, at the level a maintainer reads: a FIFO and a symlink + planted in the run's own `logs/` are not this run's retained output, and + counting either bills the report for bytes nobody wrote. + + Alarmed like the unit twin because an ablation that reaches the open would + hang `collect` rather than fail it. + + ABLATION: delete the two ``S_ISREG`` inventory lines in `summarize_files` and + the group reports 3 files and the symlink target's 3000 bytes instead of the + one real log. Verified.""" + import signal + + run_dir = _seed_bare_run(project.project) + logs = run_dir / "logs" + logs.mkdir(parents=True) + (logs / "dev.log").write_bytes(b"one\ntwo\n") + os.mkfifo(logs / "piped.log") + outside = tmp_path / "theirs.log" + outside.write_bytes(b"t" * 3000) + (logs / "linked.log").symlink_to(outside) + + def _blew_up(signum, frame): + raise AssertionError("collect blocked on the planted FIFO") + + previous = signal.signal(signal.SIGALRM, _blew_up) + signal.alarm(30) + try: + diag = diagnostics.collect( + [run_dir], pseudo=sanitize.Pseudonymizer(), project=Path(project.project) + ) + finally: + signal.alarm(0) + signal.signal(signal.SIGALRM, previous) + + group = next(g for g in diag.runs[0].files if g.category == "logs") + assert (group.count, group.total_bytes, group.total_lines) == (1, 8, 2) diff --git a/tests/test_engine.py b/tests/test_engine.py index 0681a6db..7d01ab71 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -37,7 +37,7 @@ from bmad_loop.adapters.base import SessionResult from bmad_loop.adapters.mock import MockAdapter from bmad_loop.engine import Engine, RunPaused, RunStopped, _digest_of, _run_depth -from bmad_loop.journal import Journal, load_state +from bmad_loop.journal import LOGS_DIR, VERIFY_DIR, Journal, load_state from bmad_loop.model import ( PAUSE_EPIC_BOUNDARY, PAUSE_ESCALATION, @@ -128,6 +128,654 @@ def resume_engine(project, engine, script, policy=None) -> tuple[Engine, MockAda return new_engine, adapter +class _PostDevVerifyCaptureBus: + """Small hook-bus double for testing the engine-to-plugin public seam.""" + + def __init__(self): + self.contexts = [] + + def active(self, stage): + return stage == "post_dev_verify" + + def emit(self, stage, ctx): + self.contexts.append(ctx) + return ctx + + +def test_post_dev_verify_exposes_journaled_command_results(project, monkeypatch): + """A normal dev verification retains the exact result for the existing hook + and journals stream pointers instead of unbounded JSON payloads.""" + write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) + engine, _ = make_engine( + project, + [dev_effect(project, "1-1-a", followup_review=False)], + policy=Policy( + gates=GatesPolicy(mode="none"), + notify=QUIET, + review=ReviewPolicy(enabled=False), + ), + ) + capture = _PostDevVerifyCaptureBus() + engine._bus = capture + result = verify.CommandResult("pytest -q", 0, "out\nerr\n", "out\n", "err\n") + monkeypatch.setattr(verify, "run_verify_commands", lambda policy, cwd: [result]) + + summary = engine.run() + + assert summary.done == 1 + (ctx,) = capture.contexts + assert ctx.command_results == (result,) + (entry,) = [e for e in engine.journal.entries() if e["kind"] == "verify-command-result"] + assert entry["verification_stage"] == "dev" + assert entry["verification_sequence"] == 1 + assert entry["command_index"] == 0 and entry["returncode"] == 0 + assert (engine.run_dir / entry["stdout_path"]).read_text(encoding="utf-8") == "out\n" + assert (engine.run_dir / entry["stderr_path"]).read_text(encoding="utf-8") == "err\n" + # Pointers are run-relative and land in the verifier's own store: logs/ is the + # adapters' task-id namespace, which the TUI resolves as pane logs. + assert entry["stdout_path"].startswith(f"{VERIFY_DIR}/") + assert entry["stderr_path"].startswith(f"{VERIFY_DIR}/") + assert not list((engine.run_dir / LOGS_DIR).glob("verify-*")) + + +def test_verify_stream_filenames_sanitize_the_whole_composition(project): + """A long story key cannot push a composed filename past the segment cap. + + ``_session_task_id`` states the rule these filenames follow verbatim: + sanitize the whole composition, not the parts. Capping ``story_key`` alone + spends the entire budget on it and then appends the stage/attempt/sequence/ + index tail unchecked, so the segment overshoots by the length of that tail. + """ + engine, _ = make_engine(project, []) + task = StoryTask(story_key="1-1-" + "k" * platform_util.MAX_SEGMENT, epic=1) + + engine._journal_verify_command_results( + task, "dev", (verify.CommandResult("pytest -q", 0, "tail", "out", "err"),) + ) + + (entry,) = [e for e in engine.journal.entries() if e["kind"] == "verify-command-result"] + for pointer, suffix in ((entry["stdout_path"], "stdout"), (entry["stderr_path"], "stderr")): + stem = pointer.rsplit("/", 1)[-1].removesuffix(f".{suffix}.log") + assert len(stem) <= platform_util.MAX_SEGMENT + assert (engine.run_dir / pointer).is_file() + # the untruncated key still reaches the reader — through the record, not the name + assert entry["story_key"] == task.story_key + + +def _capture_engine(project, stream_capture_kb): + """An engine whose only interesting policy is the verifier stream cap.""" + return make_engine( + project, [], policy=Policy(verify=VerifyPolicy(stream_capture_kb=stream_capture_kb)) + )[0] + + +def _sole_verify_record(engine): + (entry,) = [e for e in engine.journal.entries() if e["kind"] == "verify-command-result"] + return entry + + +def test_verify_stream_capture_retains_a_bounded_tail(project): + """A chatty command is cut to `verify.stream_capture_kb`, and the record says so. + + COMMAND_TIMEOUT_S is 30 minutes, so an uncapped retain is hundreds of MB per + attempt with no GC behind it. The cut keeps the TAIL — the direction every + other bound on this output takes, and where a failing suite puts its failure. + + Ablation: have `_bounded_stream_tail` return `(text, full, full)` + unconditionally and the file grows back to the full stream, reddening both + the size and the truncation-flag assertions. + """ + engine = _capture_engine(project, 1) # 1 KiB per stream + stdout = "".join(f"chatty line {i}\n" for i in range(1000)) + full = len(stdout.encode("utf-8")) + assert full > 1024, "fixture must exceed the cap or it proves nothing" + + engine._journal_verify_command_results( + StoryTask(story_key="1-1-a", epic=1), + "dev", + (verify.CommandResult("pytest -q", 1, "tail", stdout, ""),), + ) + + entry = _sole_verify_record(engine) + retained = (engine.run_dir / entry["stdout_path"]).read_text(encoding="utf-8") + assert len(retained.encode("utf-8")) == 1024 + assert retained == stdout[-len(retained) :] # a tail, not a head + # The record stays honest about the cut: a silently short file reads as a + # complete one, so the FULL size and an explicit flag both travel with it. + assert entry["stdout_bytes"] == full + assert entry["stdout_captured_bytes"] == 1024 + assert entry["stdout_truncated"] is True + # an under-cap stream is kept whole and flagged as such + assert entry["stderr_bytes"] == 0 + assert entry["stderr_captured_bytes"] == 0 + assert entry["stderr_truncated"] is False + assert entry["capture_error"] is None + + +def test_a_ceilinged_stream_still_reports_what_the_command_emitted(project): + """When the in-memory ceiling already cut a stream, the record reports what + the COMMAND emitted — not what the engine still holds. + + `MAX_STREAM_MEMORY_BYTES` bounds retention in the results list, so by the time + a record is built the string in hand can be far smaller than what ran. Sizing + the record off that string would under-report emission and, worse, compute + `*_truncated` against a false baseline — calling a cut stream whole, which is + the single thing that flag exists to prevent. Only the result knows the real + figure, so it carries it. + + Ablation: drop the `emitted` override in `_journal_verify_command_results` and + `stdout_bytes` comes back 100 with `stdout_truncated` False — a stream cut + twice over, reported as complete. Verified. + """ + engine = _capture_engine(project, 1) + held = "o" * 100 # what survived the ceiling + + engine._journal_verify_command_results( + StoryTask(story_key="1-1-a", epic=1), + "dev", + (verify.CommandResult("pytest -q", 1, "tail", held, "", 9_000_000, 0),), + ) + + entry = _sole_verify_record(engine) + assert entry["stdout_bytes"] == 9_000_000 # emitted + assert entry["stdout_captured_bytes"] == 100 # retained + assert entry["stdout_truncated"] is True + # the untouched stream keeps the ordinary meaning: emitted == retained + assert entry["stderr_bytes"] == 0 and entry["stderr_truncated"] is False + + +def test_verify_stream_capture_cut_lands_on_a_character_boundary(project): + """A byte cap cutting a multi-byte character drops the partial lead, it does + not decode it into a replacement char. + + The stream already carries whatever U+FFFD its own `errors="replace"` decode + produced (#378); minting another one here would put a corruption marker at a + boundary WE chose, and a reader cannot tell the two apart. + + Ablation: switch `_bounded_stream_tail`'s decode to `errors="replace"` and + the tail both breaks the cap it was just given (U+FFFD is 3 bytes standing in + for the 1 it replaced, so 1024 in yields 1026 out) and carries an invented + corruption marker. The bound assertion is the one that fires first. + """ + engine = _capture_engine(project, 1) + stdout = "\u20ac" * 1000 # 3 bytes apiece + full = len(stdout.encode("utf-8")) + assert (full - 1024) % 3 != 0, "fixture must cut mid-character or it proves nothing" + + engine._journal_verify_command_results( + StoryTask(story_key="1-1-a", epic=1), + "dev", + (verify.CommandResult("pytest -q", 1, "tail", stdout, ""),), + ) + + entry = _sole_verify_record(engine) + retained = (engine.run_dir / entry["stdout_path"]).read_text(encoding="utf-8") + assert entry["stdout_bytes"] == full and entry["stdout_truncated"] is True + assert entry["stdout_captured_bytes"] == len(retained.encode("utf-8")) + # within the cap, and short of it by at most the one character that was cut + assert 1024 - 3 <= entry["stdout_captured_bytes"] <= 1024 + assert retained == stdout[-len(retained) :] + assert "\ufffd" not in retained + + +def test_verify_stream_capture_disabled_writes_no_files_and_still_journals(project): + """`stream_capture_kb = 0` retains nothing — and still records what was emitted. + + "Nothing was retained" and "the command was silent" are different facts, so + the byte counts survive the opt-out even though the pointers are null. + + Ablation: delete the `if max_bytes > 0:` guard in + `_journal_verify_command_results` and the writer is called with an empty + tail, which creates `verify/` and two empty files — reddening the + directory-absence and null-pointer assertions. + """ + engine = _capture_engine(project, 0) + + engine._journal_verify_command_results( + StoryTask(story_key="1-1-a", epic=1), + "dev", + (verify.CommandResult("pytest -q", 1, "tail", "out\n", "err\n"),), + ) + + assert not (engine.run_dir / VERIFY_DIR).exists() # not even the directory + entry = _sole_verify_record(engine) + assert entry["stdout_path"] is None and entry["stderr_path"] is None + assert entry["stdout_captured_bytes"] == 0 and entry["stderr_captured_bytes"] == 0 + assert entry["stdout_bytes"] == 4 and entry["stderr_bytes"] == 4 + assert entry["stdout_truncated"] is True and entry["stderr_truncated"] is True + assert entry["capture_error"] is None # opting out is not a failure + # the bounded merged feedback a repair session acts on is untouched by the knob + assert entry["output_tail"] == "tail" + + +def test_verify_stream_capture_oserror_degrades_instead_of_killing_the_run(project, monkeypatch): + """A failed retain is an observation loss, never a lost run (AGENTS.md). + + ENOSPC / a read-only run dir / ENAMETOOLONG used to propagate out of the + writer and take the dev phase with it — a diagnostic killing the run it + exists to diagnose, on a story whose verify commands PASSED. + + Ablation: delete the `except OSError` arm in + `_journal_verify_command_results` and `engine.run()` raises OSError, so the + run never reaches `summary.done == 1`. + """ + write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) + engine, _ = make_engine( + project, + [dev_effect(project, "1-1-a", followup_review=False)], + policy=Policy( + gates=GatesPolicy(mode="none"), + notify=QUIET, + review=ReviewPolicy(enabled=False), + ), + ) + monkeypatch.setattr( + verify, + "run_verify_commands", + lambda policy, cwd: [verify.CommandResult("pytest -q", 0, "tail", "out\n", "err\n")], + ) + + def _enospc(*_args, **_kwargs): + raise OSError(28, "No space left on device") + + # BOTH writers, because which one runs is platform-dependent: POSIX anchors + # the write at a directory descriptor (`atomic_write_text_at`) to refuse a + # symlinked `verify/`, win32 keeps the path-based `atomic_write_text`. + # Patching only the latter left this test green on POSIX for the wrong + # reason — no write was intercepted, so the degrade arm never ran. + monkeypatch.setattr("bmad_loop.journal.atomic_write_text", _enospc) + monkeypatch.setattr("bmad_loop.journal.atomic_write_text_at", _enospc) + + summary = engine.run() + + assert summary.done == 1 # the run survives its own logging + entry = _sole_verify_record(engine) + assert entry["capture_error"] is not None + assert "stdout" in entry["capture_error"] and "No space left" in entry["capture_error"] + assert entry["stdout_path"] is None and entry["stderr_path"] is None + # nothing was published, so 0 retained is the literal truth ... + assert entry["stdout_captured_bytes"] == 0 and entry["stderr_captured_bytes"] == 0 + # ... while what the command emitted, and its verdict, still reach the reader + assert entry["stdout_bytes"] == 4 and entry["stderr_bytes"] == 4 + assert entry["returncode"] == 0 and entry["output_tail"] == "tail" + + +def test_fix_verification_emits_post_dev_verify_with_command_results(project, monkeypatch): + """The repair leg emits the same existing hook after it re-runs verification.""" + capture = _PostDevVerifyCaptureBus() + engine, summary = _dev_then_fix_run(project, monkeypatch, capture) + + assert summary.done == 1 + assert [ctx.command_results[0].stdout for ctx in capture.contexts] == ["first-out", "fixed-out"] + entries = [e for e in engine.journal.entries() if e["kind"] == "verify-command-result"] + assert [ + (e["verification_stage"], e["verification_sequence"], e["command_index"]) for e in entries + ] == [ + ("dev", 1, 0), + ("fix", 2, 0), + ] + + +def _one_result(command="pytest -q"): + return (verify.CommandResult(command, 0, "tail", "out", "err"),) + + +def _journalled_sequences(engine): + return [ + (e["story_key"], e["verification_stage"], e["verification_sequence"]) + for e in engine.journal.entries() + if e["kind"] == "verify-command-result" + ] + + +def test_verification_sequence_survives_a_resume(project): + """A NEW engine over the same run dir keeps counting up, it does not restart. + + The ordinal is a public journal field AND the `post_dev_verify` join key, so + a resumed process re-issuing 1 for a story already at 2 mints a second record + claiming an ordinal the pre-pause run used — two different verify passes, + indistinguishable to anything correlating on it. Re-deriving the ordinal from + the journal on every verification is what used to buy this; the seeded + counter has to buy it once, and this is the part a naive counter breaks. + + Ablation: seed eagerly to empty instead of lazily from the journal — replace + `_next_verification_sequence`'s seed call with + `self._verification_sequences = {}` — and the resumed engine re-issues 1 and + 2, reddening both the return values and the journalled sequence list. + """ + first, _ = make_engine(project, []) + task = StoryTask(story_key="1-1-a", epic=1) + assert first._journal_verify_command_results(task, "dev", _one_result()) == 1 + assert first._journal_verify_command_results(task, "fix", _one_result()) == 2 + + # what a resume is: a fresh Engine (so a fresh counter) and a fresh Journal + # over the run dir the paused process left behind. + resumed, _ = make_engine(project, []) + assert resumed.journal.path == first.journal.path, "the fixture must reuse the run dir" + assert resumed._journal_verify_command_results(task, "fix", _one_result()) == 3 + # and from there it increments in memory — the seed is not re-read per pass + assert resumed._journal_verify_command_results(task, "fix", _one_result()) == 4 + + assert _journalled_sequences(resumed) == [ + ("1-1-a", "dev", 1), + ("1-1-a", "fix", 2), + ("1-1-a", "fix", 3), + ("1-1-a", "fix", 4), + ] + + +def test_verification_sequence_counts_each_story_separately(project): + """The ordinal is per story, and the resume seed has to keep it that way. + + A run drives many stories through one Engine and one journal. A counter (or a + seed) shared across them makes the ordinal a run-wide clock, so a plugin + joining on (story_key, stage, sequence) finds the record it wants only by + accident of ordering. + + Ablation: make the ordinal a run-wide clock — key BOTH the seed and the + allocator on one constant instead of `story_key` — and `1-1-a`'s post-resume + pass lands at 4 instead of 3, because `1-2-b`'s spent one of its numbers. + Ablating the seed alone is NOT enough and does not redden this: an unseeded + story falls back to 0 either way, so the run-wide bug only shows once both + halves share the key. + """ + first, _ = make_engine(project, []) + a, b = StoryTask(story_key="1-1-a", epic=1), StoryTask(story_key="1-2-b", epic=1) + assert first._journal_verify_command_results(a, "dev", _one_result()) == 1 + assert first._journal_verify_command_results(a, "fix", _one_result()) == 2 + + resumed, _ = make_engine(project, []) + # `b` has no records at all, so its seed is absent, not "the run's highest" + assert resumed._journal_verify_command_results(b, "dev", _one_result()) == 1 + assert resumed._journal_verify_command_results(a, "dev", _one_result()) == 3 + + assert _journalled_sequences(resumed) == [ + ("1-1-a", "dev", 1), + ("1-1-a", "fix", 2), + ("1-2-b", "dev", 1), + ("1-1-a", "dev", 3), + ] + + +def test_verification_sequence_does_not_rescan_the_journal_per_verification(project, monkeypatch): + """Allocating an ordinal reads the journal ONCE per engine, not once per pass. + + `Journal.entries()` read_text()s the whole file and json.loads every line — a + file this same writer keeps appending to, so a per-verification rescan costs + more the longer the run gets, for a number the writer already knows. + + Ablation: restore the rescan (derive the ordinal from + `max(... for entry in self.journal.entries() ...)`) and the count is 5, one + per verification, instead of the single seeding read. + """ + engine, _ = make_engine(project, []) + task = StoryTask(story_key="1-1-a", epic=1) + reads = [] + real_entries = engine.journal.entries + + def counting_entries(): + reads.append(len(reads)) + return real_entries() + + monkeypatch.setattr(engine.journal, "entries", counting_entries) + + sequences = [ + engine._journal_verify_command_results(task, "dev", _one_result()) for _ in range(5) + ] + + assert sequences == [1, 2, 3, 4, 5] # still correct, just not re-derived + assert len(reads) == 1, "the journal is read once to seed the counter, never per verification" + + +def test_verification_sequence_is_not_spent_by_a_pass_that_records_nothing(project): + """A pass with no configured commands journals nothing and burns no ordinal. + + The rescan this replaced could not observe an ordinal it had not written, so + an empty pass left the numbering untouched. A counter that increments anyway + would number a run's passes differently depending on WHERE it was resumed, + which is exactly the drift the seed exists to prevent. + + Ablation: allocate before the `if not results` guard and the second pass + lands at 2, with a gap where the empty pass silently spent 1. + """ + engine, _ = make_engine(project, []) + task = StoryTask(story_key="1-1-a", epic=1) + + assert engine._journal_verify_command_results(task, "dev", ()) is None + assert not _journalled_sequences(engine) + assert engine._journal_verify_command_results(task, "dev", _one_result()) == 1 + + +def _dev_then_fix_run(project, monkeypatch, capture): + """Drive one story through a dev verification and a repair verification. + + The first review-time verify fails, which routes the story into `_fix_phase`; + the repair session's verify passes and the story commits. Both legs emit + `post_dev_verify`, which is what the callers need. + + FOUR scripted returns, TWO journalled sequences — deliberately, and the + inequality is the documented scope boundary, not a miscount to "fix". Returns + 1 and 3 are the dev and repair verifications, which this PR journals. Returns + 2 and 4 are the two `_skip_review_and_commit` review gates (the second runs + after the repair), and the review leg is neither journalled nor published to + any hook — see the boundary section in `docs/plugin-authoring-guide.md` and + issue #656. The count is load-bearing, not padding: dropping the fourth value + leaves the post-repair gate with nothing to consume and the run ends + `crashed=True, crash_error='StopIteration: '` (measured), so a reader who + trims the list finds out immediately. + """ + write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) + engine, _ = make_engine( + project, + [dev_effect(project, "1-1-a", followup_review=False), dev_effect(project, "1-1-a")], + policy=Policy( + gates=GatesPolicy(mode="none"), + notify=QUIET, + review=ReviewPolicy(enabled=False), + limits=LimitsPolicy(max_dev_attempts=2), + ), + ) + engine._bus = capture + calls = iter( + [ + [verify.CommandResult("pytest -q", 0, "first", "first-out", "")], + [verify.CommandResult("pytest -q", 1, "review fail", "", "review fail")], + [verify.CommandResult("pytest -q", 0, "fixed", "fixed-out", "")], + [verify.CommandResult("pytest -q", 0, "final", "final-out", "")], + ] + ) + monkeypatch.setattr(verify, "run_verify_commands", lambda policy, cwd: next(calls)) + return engine, engine.run() + + +def test_post_dev_verify_discriminates_a_dev_emit_from_a_fix_emit(project, monkeypatch): + """A plugin can tell which leg it is on, and find its own journal records. + + Both emits carry stage `post_dev_verify` from `Phase.DEV_VERIFY` off one + shared `attempt` counter, so `ctx.stage` / `ctx.phase` / `ctx.attempt` cannot + separate a dev verification from a repair one. `verification_stage` is the + only thing that does, and `verification_sequence` is what joins the context + back to the `verify-command-result` entries it is about — which is the point + of exposing the results at all. + + Ablation: pass a constant (say `"dev"`) as `verification_stage` at both emit + sites and the discriminator assertion reddens; drop `verification_sequence` + from the emits and the journal join below finds no matching record. + """ + capture = _PostDevVerifyCaptureBus() + engine, summary = _dev_then_fix_run(project, monkeypatch, capture) + + assert summary.done == 1 + dev_ctx, fix_ctx = capture.contexts + # what a plugin CANNOT discriminate on: identical stage and phase, plus one + # per-story `attempt` counter the repair leg continues rather than restarts, + # so a bare 2 never says whether it was a dev retry or a repair. + assert dev_ctx.stage == fix_ctx.stage == "post_dev_verify" + assert dev_ctx.phase == fix_ctx.phase == str(Phase.DEV_VERIFY) + assert (dev_ctx.attempt, fix_ctx.attempt) == (1, 2) + # ... and what now separates them + assert (dev_ctx.verification_stage, dev_ctx.verification_sequence) == ("dev", 1) + assert (fix_ctx.verification_stage, fix_ctx.verification_sequence) == ("fix", 2) + + # the join a correlating plugin performs: story + stage + sequence names + # exactly this context's records, one per command, in command_index order. + for ctx in (dev_ctx, fix_ctx): + matched = [ + e + for e in engine.journal.entries() + if e["kind"] == "verify-command-result" + and e["story_key"] == ctx.story_key + and e["verification_stage"] == ctx.verification_stage + and e["verification_sequence"] == ctx.verification_sequence + ] + assert [e["command_index"] for e in matched] == list(range(len(ctx.command_results))) + assert [e["returncode"] for e in matched] == [r.returncode for r in ctx.command_results] + assert [e["command"] for e in matched] == [r.command for r in ctx.command_results] + + +def _critical(inner): + """Wrap a session effect so its result reports a CRITICAL escalation.""" + + def effect(spec): + result = inner(spec) + result.result_json["escalations"] = [ + {"type": "missing-config", "severity": "CRITICAL", "detail": "operator needed"} + ] + return result + + return effect + + +@pytest.mark.parametrize("leg", ["dev", "fix"]) +def test_a_critical_session_emits_post_dev_verify_on_both_legs(project, monkeypatch, leg): + """CRITICAL is one event class, so both legs must expose it identically. + + The dev leg reaches `decide_dev` — which tests `critical_escalations` first — + AFTER emitting `post_dev_verify`, so a CRITICAL dev session publishes its own + verify pass to plugins on the way to the pause. The repair leg used to + escalate ahead of its emit, and `_escalate` raises `RunPaused`: the same + event class fired the hook on one leg and nothing at all on the other, which + silently withholds half of a correlating plugin's verify passes. + + Both cases assert the same thing — the escalating session's OWN pass reached + a plugin — which is the parity claim itself. + + Ablation: restore the old ordering by moving `_fix_phase`'s `crits` block + back above `outcome = None` / `if result.status == "completed":`. The `fix` + case then reddens (one context, not two; no `"fix"` stage ever reaches a + plugin) while `dev` still passes — precisely the asymmetry. + """ + write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) + clean = dev_effect(project, "1-1-a", followup_review=False) + escalating = _critical(dev_effect(project, "1-1-a", followup_review=False)) + engine, _ = make_engine( + project, + [escalating] if leg == "dev" else [clean, escalating], + policy=Policy( + gates=GatesPolicy(mode="none"), + notify=QUIET, + review=ReviewPolicy(enabled=False), + limits=LimitsPolicy(max_dev_attempts=2), + ), + ) + capture = _PostDevVerifyCaptureBus() + engine._bus = capture + # the dev leg's own pass; then, on the `fix` case, the commit-time failure + # that routes the story into `_fix_phase`, then the repair session's pass + calls = iter( + [ + [verify.CommandResult("pytest -q", 0, "dev", "dev-out", "")], + [verify.CommandResult("pytest -q", 1, "commit fail", "", "commit fail")], + [verify.CommandResult("pytest -q", 0, "fix", "fix-out", "")], + ] + ) + monkeypatch.setattr(verify, "run_verify_commands", lambda policy, cwd: next(calls)) + + summary = engine.run() + + assert summary.paused and summary.escalated == 1 + (escalated,) = [e for e in engine.journal.entries() if e["kind"] == "story-escalated"] + assert escalated["reason"] == f"CRITICAL escalation from {leg} session: operator needed" + # ... and the escalating session's verification is on the hook either way + assert len(capture.contexts) == (1 if leg == "dev" else 2) + ctx = capture.contexts[-1] + assert ctx.verification_stage == leg + assert [r.stdout for r in ctx.command_results] == [f"{leg}-out"] + + +_ONE_ATTEMPT = Policy( + gates=GatesPolicy(mode="none"), + notify=QUIET, + review=ReviewPolicy(enabled=False), + limits=LimitsPolicy(max_dev_attempts=1), + scm=ScmPolicy(rollback_on_failure=True), +) + + +def _post_dev_verify_contexts(project, script, policy=_ONE_ATTEMPT): + """Run one story and return (engine, summary, the post_dev_verify contexts).""" + engine, _ = make_engine(project, script, policy) + capture = _PostDevVerifyCaptureBus() + engine._bus = capture + return engine, engine.run(), capture.contexts + + +def test_post_dev_verify_marks_a_pass_that_ran_and_executed_nothing(project): + """No `[verify] commands` configured: the pass RAN, and recorded nothing. + + `command_results == ()` alone cannot say that — it is equally what a plugin + sees when no pass happened at all. The stage says the pass ran; the null + sequence says there is no journal record to join to, which is the truth, + because a pass with no results writes none. + + Two independent gates, each verified to redden this on its own. Ablation + (stage): set it only when the pass recorded something — + `stage=verification_stage if sequence is not None else None` — and this pass + reports `None`, collapsing back into "no pass ran". Ablation (sequence): + return the allocated ordinal from `_journal_verify_command_results` even with + no results, and the context advertises a join key that the + `verify-command-result` assertion below proves no record answers. NOTE that + simply dropping `verification_sequence` from the emit does NOT redden this — + the field defaults to `None`, which is the value under test. + """ + write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) + engine, summary, contexts = _post_dev_verify_contexts( + project, [dev_effect(project, "1-1-a", followup_review=False)] + ) + + assert summary.done == 1 # an empty verify config is a pass, not a failure + (ctx,) = contexts + assert ctx.command_results == () and ctx.verification_stage == "dev" + assert ctx.verification_sequence is None + assert not [e for e in engine.journal.entries() if e["kind"] == "verify-command-result"] + + +def test_post_dev_verify_marks_an_attempt_that_never_reached_verification(project): + """The dev-artifact gate failed first, so no verify pass ran — stage is None. + + This is the other side of the empty tuple, and the one a plugin must not + misread as "the commands ran and passed". Four causes reach here (session did + not complete, an earlier gate failed, the fix leg's harvest short-circuited, + or the engine variant suppressed the pass); the stage separates the CLASS, + and `session_status` / `verify_reason` name the cause within it. + + Ablation: hoist `verification_stage` out of the records and pass the literal + `"dev"` at the emit site — the gate-failure attempt then claims a pass that + never ran, reddening both `is None` assertions. + """ + write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) + _, summary, contexts = _post_dev_verify_contexts( + project, [dev_effect(project, "1-1-a", final_status="in-progress")] + ) + + assert summary.done == 0 + (ctx,) = contexts + assert ctx.command_results == () + assert ctx.verification_stage is None and ctx.verification_sequence is None + # what the empty tuple cannot carry travels on the fields that can + assert ctx.session_status == "completed" and ctx.verify_reason + + def _notify_engine(project): return make_engine( project, @@ -10547,11 +11195,23 @@ def _gitignore_harvest_ledger(project) -> str: def _crash_after_harvest(engine) -> None: - """Crash after the ledger write but before the attempt decision acts.""" + """Crash after the ledger write but before the attempt decision acts. + + `post_dev_verify` names TWO points in the loop — the dev leg's emit and the + repair leg's — so an unqualified raise would fire inside `_fix_phase` too, + for any caller whose scenario reaches a review->fix route. The dev emit is + always the first of the two (a repair leg runs only after a dev leg + PROCEEDed, and emitted), so latching on the first one pins the crash to the + dev attempt this helper is named for rather than to whichever emit the + scenario happens to reach. + """ original_emit = engine._emit + crashed = False def crashing_emit(stage, *args, **kwargs): - if stage == "post_dev_verify": + nonlocal crashed + if stage == "post_dev_verify" and not crashed: + crashed = True raise RuntimeError("host died after harvest") return original_emit(stage, *args, **kwargs) diff --git a/tests/test_hook_bus.py b/tests/test_hook_bus.py index 4d1168be..705906c5 100644 --- a/tests/test_hook_bus.py +++ b/tests/test_hook_bus.py @@ -28,6 +28,7 @@ from bmad_loop.adapters.mock import MockAdapter from bmad_loop.engine import Engine +from bmad_loop.escalation import critical_escalations from bmad_loop.journal import Journal, load_state from bmad_loop.model import Phase, RunState, TokenUsage from bmad_loop.plugins import ( @@ -98,6 +99,48 @@ def on_pre_story(self, c): assert seen == {"story": "1-1-a", "stage": "pre_story"} +def test_command_results_are_readonly_observation_data(): + from bmad_loop.verify import CommandResult + + result = CommandResult("pytest -q", 0, "tail", "out", "err") + c = ctx("post_dev_verify", command_results=[result]) + + assert c.command_results == (result,) + with pytest.raises(AttributeError): + c.command_results = () + + +def test_a_plugin_cannot_erase_a_critical_escalation_through_result_json(): + """The observe-only claim has to hold at the depth escalations actually live. + + ``HookContext`` copies ``result_json`` so a plugin cannot rewrite the session + result — but ``dict()`` is shallow, so the nested ``escalations`` LIST stayed + the engine's own object. Both verify legs emit ``post_dev_verify`` before + reading ``critical_escalations(result.result_json)``, so an in-process plugin + that cleared that list erased the CRITICAL before the audit ran, and a + verify-green repair proceeded where the run owed a pause. + + Asserted through ``critical_escalations`` on the ENGINE's dict rather than by + comparing copies: that call is the read the fix exists to protect, and a test + that only checked ``c.result_json is not original`` passed before the fix. + + ABLATION: restore ``dict(result_json)`` in ``HookContext.__init__`` and the + audit comes back empty — the assert names the escalation that vanished. + Verified.""" + + class Eraser(Plugin): + def on_post_dev_verify(self, c): + c.result_json["escalations"].clear() + c.result_json["escalations"].append({"severity": "INFO", "detail": "all fine"}) + + original = {"escalations": [{"severity": "CRITICAL", "detail": "prod credential committed"}]} + c = HookContext("post_dev_verify", result_json=original) + HookBus(registry_of(py_plugin(Eraser))).emit("post_dev_verify", c) + + crits = critical_escalations(original) + assert [e["detail"] for e in crits] == ["prod credential committed"] + + def test_mutations_pipeline_last_writer_wins(): # lower priority runs first; the later plugin sees the earlier edit and wins class First(Plugin): @@ -381,6 +424,42 @@ def on_pre_commit(self, c): assert git(project.project, "log", "-1", "--format=%s") == "plugin-authored: 1-1-a" +def test_post_dev_verify_reaches_a_real_plugin_through_the_bus(project, monkeypatch): + """The verifier results and their discriminators survive the REAL dispatch. + + The engine-side tests for this surface swap `engine._bus` for a capture + double: that proves what the engine BUILDS, but skips everything the bus does + with it — stage activation, plugin routing, and the read-only view an actual + `Plugin` subclass receives. This one goes through `HookBus.emit` into a + registered plugin, so the plumbing itself is covered end to end. + + Ablation: drop `command_results`, `verification_stage` or + `verification_sequence` from the engine's `post_dev_verify` emit and the + plugin observes that field's default (`()` / `None`) instead. + """ + from bmad_loop import verify + + seen = [] + + class P(Plugin): + def on_post_dev_verify(self, c): + seen.append((c.verification_stage, c.verification_sequence, c.command_results)) + + result = verify.CommandResult("pytest -q", 0, "tail", "out", "err") + monkeypatch.setattr(verify, "run_verify_commands", lambda policy, cwd: [result]) + + engine, _ = make_engine(project, one_story(project), registry_of(py_plugin(P, "verifyobs"))) + summary = engine.run() + + assert summary.done == 1 + assert seen == [("dev", 1, (result,))] + # and the keys the plugin was handed are the ones its journal record carries, + # which is the correlation the whole surface exists for + (entry,) = [e for e in engine.journal.entries() if e["kind"] == "verify-command-result"] + assert (entry["verification_stage"], entry["verification_sequence"]) == ("dev", 1) + assert entry["story_key"] == "1-1-a" and entry["command"] == "pytest -q" + + def _resume_committing(project, engine, registry): """Resume a run whose task was persisted at COMMITTING (#115 crash state).""" state = load_state(engine.run_dir) diff --git a/tests/test_journal.py b/tests/test_journal.py index ed14c9d9..d3c78b0d 100644 --- a/tests/test_journal.py +++ b/tests/test_journal.py @@ -6,9 +6,13 @@ from __future__ import annotations import os +import stat +import pytest + +from bmad_loop import journal as journal_mod from bmad_loop import platform_util -from bmad_loop.journal import load_state, save_state +from bmad_loop.journal import Journal, load_state, save_state from bmad_loop.model import RunState @@ -32,3 +36,125 @@ def flaky_replace(src, dst): assert calls["n"] == 3 assert load_state(tmp_path).run_id == "r1" + + +def _planted_verify_symlink(tmp_path): + """A run dir whose `verify/` a session has already replaced with a link out.""" + run_dir, elsewhere = tmp_path / "run", tmp_path / "elsewhere" + run_dir.mkdir() + elsewhere.mkdir() + (run_dir / "verify").symlink_to(elsewhere, target_is_directory=True) + return Journal(run_dir), elsewhere + + +@pytest.mark.skipif(not journal_mod.DIR_FD_ANCHORED_WRITES, reason="dir-fd anchoring is POSIX-only") +def test_write_verify_stream_refuses_a_symlinked_verify_directory(tmp_path): + """A session that plants `verify/` as a link cannot redirect verifier output. + + Sessions are handed the run directory (`BMAD_LOOP_RUN_DIR`) and write their + own result.json into it, so this is a writer that really can plant the link. + `mkdir(parents=True, exist_ok=True)` ACCEPTS a symlink-to-directory — it + re-raises only when `is_dir()` is false, and that follows links — and + `follow_symlinks=False` covers the final component, never its parent. Without + the confinement walk the write lands in `elsewhere/`, outside the run dir. + + The refusal is an OSError because that is the caller's existing degrade path: + the journal record still lands, with a null pointer and `capture_error`. + + Ablation, measured, and the two guards OVERLAP — which is the part worth + writing down. Dropping the `open_dir_confined` arm alone reddens this test on + the *message* only, because the win32 `is_symlink()` fallback below still + refuses; so that ablation proves the arm is reached, not that it prevents the + escape. Removing BOTH guards is what proves the harm: each test then fails + `DID NOT RAISE`, and the same planted link writes `v.stdout.log` into + `elsewhere/` while `write_verify_stream` returns the pointer + `verify/v.stdout.log` — the file is outside the run dir and the record claims + it is inside. + """ + journal, elsewhere = _planted_verify_symlink(tmp_path) + + with pytest.raises(OSError, match=r"unconfined verify directory"): + journal.write_verify_stream("v.stdout.log", "verifier output") + + # the assertion that actually pins the fix: nothing escaped the run dir + assert list(elsewhere.iterdir()) == [] + + +@pytest.mark.skipif(not journal_mod.DIR_FD_ANCHORED_WRITES, reason="dir-fd anchoring is POSIX-only") +def test_write_verify_stream_refuses_a_symlinked_verify_directory_on_the_win32_path( + tmp_path, monkeypatch +): + """win32 has no *at() family, so it keeps a check-then-write — which must + still refuse the planted link rather than fall through to the write. + + Ablation: delete the `is_link_like(verify_dir)` guard and this fails + `DID NOT RAISE`, with the file landing in `elsewhere/` exactly as the + unguarded POSIX path did. + """ + monkeypatch.setattr(journal_mod, "DIR_FD_ANCHORED_WRITES", False) + journal, elsewhere = _planted_verify_symlink(tmp_path) + + with pytest.raises(OSError, match=r"redirected verify directory"): + journal.write_verify_stream("v.stdout.log", "verifier output") + + assert list(elsewhere.iterdir()) == [] + + +def test_write_verify_stream_writes_an_ordinary_verify_directory(tmp_path): + """The positive control: an unplanted run dir still retains its streams. + + Without this, both refusal tests above pass for a `write_verify_stream` that + refuses everything unconditionally — a negative assertion is green for every + reason a file could be absent. + """ + run_dir = tmp_path / "run" + run_dir.mkdir() + journal = Journal(run_dir) + + pointer = journal.write_verify_stream("v.stdout.log", "verifier output") + + assert pointer == "verify/v.stdout.log" + assert (run_dir / pointer).read_text(encoding="utf-8") == "verifier output" + + +class _ReparseStat: + """os.lstat() of a Windows junction: a DIRECTORY mode — which is why + Path.is_symlink() answers False — carrying a reparse tag.""" + + st_mode = stat.S_IFDIR | 0o755 + st_reparse_tag = 0xA0000003 # IO_REPARSE_TAG_MOUNT_POINT + + +def test_write_verify_stream_refuses_a_junctioned_verify_directory(tmp_path, monkeypatch): + """The win32 fallback must refuse a DIRECTORY JUNCTION, not just a symlink. + + `mklink /J` needs no elevation, while a directory symlink needs + SeCreateSymbolicLinkPrivilege or Developer Mode — so on Windows the junction + is the unprivileged half of the same escape, and `Path.is_symlink()` reports + False for it. A guard written as `is_symlink()` would leave that half open + with no race to win. Windows-only in reality; the logic is driven here so it + does not ship unexercised. + + Ablation: point the guard back at `verify_dir.is_symlink()` and this fails + `DID NOT RAISE` — verified. + """ + monkeypatch.setattr(journal_mod, "DIR_FD_ANCHORED_WRITES", False) + run_dir = tmp_path / "run" + run_dir.mkdir() + verify_dir = run_dir / "verify" + verify_dir.mkdir() # a real directory: is_symlink() is False, as for a junction + + # Patch the TAG TUPLE in platform_util, not `is_link_like` itself: journal.py + # bound the function by value at import, so replacing the name there would not + # reach this call — but the predicate reads `_LINK_REPARSE_TAGS` from its own + # module globals on every call, so this does. + real_lstat = os.lstat + monkeypatch.setattr(platform_util, "_LINK_REPARSE_TAGS", (_ReparseStat.st_reparse_tag,)) + monkeypatch.setattr( + os, + "lstat", + lambda p, *a, **k: _ReparseStat() if str(p) == str(verify_dir) else real_lstat(p), + ) + + with pytest.raises(OSError, match=r"redirected verify directory"): + Journal(run_dir).write_verify_stream("v.stdout.log", "verifier output") diff --git a/tests/test_platform_util.py b/tests/test_platform_util.py index cc0101a0..5aebc456 100644 --- a/tests/test_platform_util.py +++ b/tests/test_platform_util.py @@ -1524,3 +1524,82 @@ def test_the_lexical_fallback_keeps_every_bridge_spelling_matchable(spelling): pure = PureWindowsPath(spelling) assert pure.is_absolute(), "absolute() would prepend a POSIX cwd and destroy the prefix" assert platform_util.is_wsl_unc_path(pure) is True + + +class _ReparseStat: + """Stand-in for the os.lstat() result of a Windows junction: a DIRECTORY + mode (which is why Path.is_symlink() answers False) carrying a reparse tag.""" + + st_mode = stat.S_IFDIR | 0o755 + st_reparse_tag = 0xA0000003 # IO_REPARSE_TAG_MOUNT_POINT + + +def test_is_link_like_refuses_a_reparse_tagged_dir(tmp_path, monkeypatch): + """A Windows directory junction redirects but is NOT a symlink. + + `Path.is_symlink()` is False for a junction while `mkdir`/`os.open` follow + it, and `mklink /J` needs no elevation at all — unlike a directory symlink, + which needs SeCreateSymbolicLinkPrivilege or Developer Mode. So the junction + is the CHEAPER attack and the one an is_symlink() check misses. The refusal + keys on the reparse tag instead. + + That branch is reachable only on Windows; drive its logic here so it does not + ship unexercised (the `stat.IO_REPARSE_TAG_*` constants do not exist on + POSIX, hence the substituted tuple). + + Ablation guard: dropping the `st_reparse_tag` arm of `is_link_like` makes the + last assertion fail — verified. + """ + plain = tmp_path / "verify" + plain.mkdir() + assert platform_util.is_link_like(plain) is False # positive control + + real_lstat = os.lstat + monkeypatch.setattr(platform_util, "_LINK_REPARSE_TAGS", (_ReparseStat.st_reparse_tag,)) + monkeypatch.setattr( + os, + "lstat", + lambda p, *a, **k: _ReparseStat() if str(p) == str(plain) else real_lstat(p), + ) + assert platform_util.is_link_like(plain) is True + + +def test_walk_files_unlinked_prunes_a_link_like_subdirectory(tmp_path, monkeypatch): + """A nested redirect is pruned even where ``os.walk`` would descend into it. + + ``os.walk`` prunes a symlinked subdirectory by itself, so on POSIX this guard + looks redundant — which is exactly the trap. It prunes via ``os.path.islink``, + and a Windows DIRECTORY JUNCTION is not a symlink, so the arm that actually + needs pruning is the one ``os.walk`` misses, and it is unreachable from a + POSIX runner. The junction is therefore simulated by making ``is_link_like`` + answer True for an ordinary directory: that disagreement between the two + predicates IS the win32 behaviour under test, and a real symlink would grade + ``os.walk`` instead of this function. + + Ablation: delete the ``dirs[:]`` pruning line and `theirs.bin` joins the + result — 9000 bytes from a tree the caller never meant to walk. Verified. + """ + root = tmp_path / "run" + (root / "keep").mkdir(parents=True) + (root / "keep" / "mine.bin").write_bytes(b"m" * 10) + junction = root / "verify" + junction.mkdir() + (junction / "theirs.bin").write_bytes(b"t" * 9000) + + monkeypatch.setattr(platform_util, "is_link_like", lambda q: Path(q) == junction) + + assert sorted(q.name for q in platform_util.walk_files_unlinked(root)) == ["mine.bin"] + + +def test_walk_files_unlinked_refuses_a_link_like_top(tmp_path, monkeypatch): + """The other half: ``os.walk`` always follows the top path it is handed, so + declining to descend into links says nothing about the root itself. Same + simulation, and the two halves fail independently — pruning children cannot + save a caller who was pointed at the redirect to begin with.""" + outside = tmp_path / "outside" + outside.mkdir() + (outside / "theirs.bin").write_bytes(b"t" * 9000) + + monkeypatch.setattr(platform_util, "is_link_like", lambda q: Path(q) == outside) + + assert list(platform_util.walk_files_unlinked(outside)) == [] diff --git a/tests/test_policy.py b/tests/test_policy.py index f419f75f..01f5df6e 100644 --- a/tests/test_policy.py +++ b/tests/test_policy.py @@ -892,6 +892,22 @@ def test_scm_failed_diff_settings(tmp_path): policy.load(p) +def test_verify_stream_capture_kb(tmp_path): + """The retain cap parses, defaults, and admits 0 as "capture nothing" — + unlike scm.failed_diff_max_mb, whose 0 is rejected. The opt-out is the whole + point of the knob, so the floor is 0 and only a negative is refused.""" + p = tmp_path / "policy.toml" + p.write_text("[verify]\nstream_capture_kb = 8\n") + assert policy.load(p).verify.stream_capture_kb == 8 + p.write_text('[verify]\ncommands = ["pytest -q"]\n') + assert policy.load(p).verify.stream_capture_kb == 256 # default survives a partial table + p.write_text("[verify]\nstream_capture_kb = 0\n") + assert policy.load(p).verify.stream_capture_kb == 0 # opting out is legal + p.write_text("[verify]\nstream_capture_kb = -1\n") + with pytest.raises(policy.PolicyError, match=r"verify\.stream_capture_kb"): + policy.load(p) + + def test_scm_invalid_values(tmp_path): p = tmp_path / "policy.toml" p.write_text('[scm]\nisolation = "vm"\n') diff --git a/tests/test_tui_data.py b/tests/test_tui_data.py index bd4e4a70..983d6c5e 100644 --- a/tests/test_tui_data.py +++ b/tests/test_tui_data.py @@ -884,6 +884,39 @@ def test_active_task_id_matches_open_session_start(tmp_path): assert data.active_task_id(tmp_path, closed) == "t-new" +def test_active_task_id_ignores_verifier_streams(tmp_path): + """The newest-log fallback sees pane logs only: verifier streams are not tasks. + + Regression. Verifier stdout/stderr used to be retained in ``logs/``, whose + every other inhabitant is an adapter pane capture named after a session task + id. That collides in the COMMON case, not a corner: session-end is journalled + when the session ends, before its result reaches verification, so nothing is + open exactly when the verifier files are the newest in the directory. The + fallback then returned a stream's stem as the live task and the dashboard + reopened it as ``logs/{stem}.log`` — a path that resolves, so the log pane + rendered verifier stderr in place of the agent session log. + + The streams are written through the real writer, not hand-placed: pointing + ``Journal.write_verify_stream`` back at ``logs/`` must redden this test. + """ + logs = tmp_path / "logs" + logs.mkdir() + (logs / "1-1-a-dev-1.log").write_text("pane capture") + os.utime(logs / "1-1-a-dev-1.log", ns=(1, 1)) # older than anything written below + + journal = Journal(tmp_path) + journal.write_verify_stream("verify-1-1-a-dev-1-1-0.stdout.log", "out") + journal.write_verify_stream("verify-1-1-a-dev-1-1-0.stderr.log", "err") + + # a dev session that has ended -> no open session -> the fallback fires + ended = [ + {"kind": "session-start", "task_id": "1-1-a-dev-1"}, + {"kind": "session-end", "task_id": "1-1-a-dev-1"}, + ] + assert data.active_task_id(tmp_path, ended) == "1-1-a-dev-1" + assert data.active_task_id(tmp_path, []) == "1-1-a-dev-1" + + # ------------------------------------------------------------- active agent diff --git a/tests/test_verify.py b/tests/test_verify.py index bc423eda..f73890e2 100644 --- a/tests/test_verify.py +++ b/tests/test_verify.py @@ -1,6 +1,7 @@ import dataclasses import hashlib import io +import json import os import subprocess import sys @@ -1535,6 +1536,184 @@ def test_verify_commands_rc1_stays_fixable_retry(tmp_path): assert not out.ok and out.fixable and out.retryable and not out.env_fault +def test_verify_commands_bound_a_stream_instead_of_holding_it_whole(tmp_path, monkeypatch): + """A chatty command's stream is cut to `MAX_STREAM_MEMORY_BYTES` as it is + collected, and what it emitted is recorded rather than lost. + + `capture_output=True` always materialises one command's whole output; what + this bounds is RETENTION — before it, every command's full streams stayed in + the results list while all the later commands ran, so peak memory scaled with + the number of configured verify commands instead of with the largest one. + Plugins are meant to see streams essentially whole, so the ceiling sits far + above `stream_capture_kb` and is a backstop, not a knob; the test lowers it + rather than emitting 32 MiB to prove the same branch. + + Ablation: hand the raw `proc.stdout` to CommandResult again and `stdout` comes + back 5000 bytes with `stdout_full_bytes` None. Verified. + """ + script = tmp_path / "chatty.py" + script.write_text("import sys\nsys.stdout.write('o' * 5000)\n", encoding="utf-8") + policy = Policy(verify=VerifyPolicy(commands=(f'"{sys.executable}" "{script}"',))) + monkeypatch.setattr(verify, "MAX_STREAM_MEMORY_BYTES", 64) + + (result,) = verify.run_verify_commands(policy, tmp_path) + + assert result.stdout == "o" * 64 # the TAIL survives, as at every other bound + assert result.stdout_full_bytes == 5000 # and the emitted size is not lost + assert result.stderr == "" and result.stderr_full_bytes == 0 + assert result.output_tail == "o" * 64 # merged view built from the bounded pair + + +def test_verify_commands_preserve_separate_stdout_and_stderr(tmp_path): + """The merged bounded tail remains compatible while the raw streams stay + distinguishable for engine-owned journal pointers and plugin observation.""" + script = tmp_path / "streams.py" + script.write_text( + "import sys\nprint('stdout proof')\nprint('stderr proof', file=sys.stderr)\n", + encoding="utf-8", + ) + policy = Policy(verify=VerifyPolicy(commands=(f'"{sys.executable}" "{script}"',))) + + (result,) = verify.run_verify_commands(policy, tmp_path) + + assert result.returncode == 0 + assert result.stdout == "stdout proof\n" + assert result.stderr == "stderr proof\n" + assert result.output_tail == "stdout proof\nstderr proof\n" + + +@pytest.mark.parametrize( + ("value", "expected"), + [(None, ""), ("already decoded", "already decoded")], + ids=["none", "str-passthrough"], +) +def test_timeout_stream_shapes_that_carry_no_decode(value, expected): + """The two non-bytes shapes of a timeout payload, asserted directly because + neither reaches a codec — there is no stdlib decoding for a real child to + exercise, so driving one would add cost without adding evidence. + + ``None`` is POSIX's answer when nothing had been buffered on that stream + (``_check_timeout`` passes None, not ``b""``, for an empty chunk list); the + CommandResult must still carry a str. The str arm is Windows, where + ``subprocess.run`` re-collects through ``communicate()`` after ``kill()`` and + the text wrapper has already decoded — dropping it would lose that + platform's output entirely. The bytes shape, the only one that picks a + codec, is covered by the real-child test below.""" + assert verify._timeout_stream(value) == expected + + +# ---- a timed-out child's output reads like a completed one's (#378, follow-on) +# +# Both divergences pinned here are invisible on the hosts the suite usually runs +# on: `bytes.decode()`'s hardcoded UTF-8 equals the locale codec wherever the +# locale is UTF-8, and LF-only output has no carriage returns to collapse. Every +# CI leg is UTF-8 (Linux by locale, Windows by PYTHONUTF8=1), so gating on the +# host codec — the `needs_strict_codec` shape used above — would skip precisely +# where the guard is wanted, the inverse of what that marker buys its own tests. +# The work is therefore driven inside a child interpreter pinned to an ASCII +# locale. Everything below that boundary is genuine: one real grandchild script +# emits the bytes on both paths, and CPython's own timeout leg is what hands the +# hung one over. Monkeypatching `subprocess.run` instead would supply str objects +# directly and never run the stdlib's decoding at all (see the #378 block below). +_TIMEOUT_RAW = b"caf\xc3\xa9\r\nsecond\rthird\n" +"""Undecodable as ASCII and carrying both newline forms, so a single payload +exercises the codec choice, the CRLF pair and the lone CR at once.""" + + +@pytest.mark.skipif( + sys.platform == "win32", + reason="the bytes arm is unreachable on Windows (run() re-collects via " + "communicate() after kill(), which returns str, already decoded and " + "newline-translated), and LC_ALL is not how Windows resolves the codec", +) +def test_verify_commands_timeout_output_matches_the_completed_path(tmp_path): + """The same bytes must read back the same whether the command finished or + timed out — the tail a human or a repair session sees cannot depend on that. + + POSIX raises TimeoutExpired from ``_check_timeout`` with the raw chunks + joined, *before* the text-mode conversion at the end of ``_communicate``, so + the timeout arm has to redo that conversion itself. It did neither half: + ``bytes.decode()`` hardcoded UTF-8 against run_verify_commands' own rule + (#378) that host-tool output stays on the locale codec, and nothing + collapsed the newlines that ``Popen._translate_newlines`` collapses. + + The completed result is the reference rather than a literal, so the assertion + is against what the stdlib actually does, not against this test's idea of it. + + Ablation, two axes, and each reddens a different assertion: drop the + ``locale.getpreferredencoding(False)`` argument and the codec half fails; + drop the ``replace`` chain and the newline half does. Note that ``LC_ALL=C`` + alone does NOT redden the codec axis — the C locale auto-enables UTF-8 mode + (PEP 540), putting both spellings back on one codec — so ``PYTHONUTF8=0`` + below is load-bearing, and the anti-vacuity checks fail loudly if it is + ever lost rather than letting the test pass empty.""" + emit = tmp_path / "emit_timeout.py" + emit.write_text( + "import sys, time\n" + f"sys.stdout.buffer.write({_TIMEOUT_RAW!r})\n" + "sys.stdout.buffer.flush()\n" + "if sys.argv[1] == 'hang':\n" + " time.sleep(10)\n", + encoding="utf-8", + ) + driver = tmp_path / "drive_timeout.py" + # One script, two modes: the completed and timed-out runs are byte-identical + # by construction, so comparing their results compares only the two paths. + # Interpreter is sys.executable, never a bare `python` — the suite runs under + # uv, where no `python` need be on PATH. json defaults to ensure_ascii, so the + # report survives the ASCII stdout it is printed on. + driver.write_text( + "import json, locale, sys\n" + "from pathlib import Path\n" + "from bmad_loop import verify\n" + "from bmad_loop.policy import Policy, VerifyPolicy\n" + "verify.COMMAND_TIMEOUT_S = 1.0\n" + "def run(mode):\n" + ' cmd = \'"%s" "%s" %s\' % (sys.executable, sys.argv[1], mode)\n' + " (r,) = verify.run_verify_commands(\n" + " Policy(verify=VerifyPolicy(commands=(cmd,))), Path(sys.argv[2])\n" + " )\n" + " return r\n" + "done, hung = run('exit'), run('hang')\n" + "json.dump({'encoding': locale.getpreferredencoding(False),\n" + " 'completed_rc': done.returncode, 'completed_stdout': done.stdout,\n" + " 'timeout_rc': hung.returncode, 'timeout_tail': hung.output_tail,\n" + " 'timeout_stdout': hung.stdout, 'timeout_stderr': hung.stderr},\n" + " sys.stdout)\n", + encoding="utf-8", + ) + env = {k: v for k, v in os.environ.items() if k not in ("PYTHONIOENCODING", "LANG", "LC_CTYPE")} + env["LC_ALL"] = "C" + env["PYTHONUTF8"] = "0" # without this the C locale would resolve to UTF-8 (PEP 540) + + proc = subprocess.run( + [sys.executable, str(driver), str(emit), str(tmp_path)], + capture_output=True, + text=True, + encoding="utf-8", + env=env, + timeout=120, + ) + + assert proc.returncode == 0, proc.stderr + observed = json.loads(proc.stdout) + decoded = _TIMEOUT_RAW.decode(observed["encoding"], errors="replace") + # One anti-vacuity check per divergence: if the child ever stops resolving a + # non-UTF-8 codec, or the payload loses its carriage returns, the equality + # below would hold with the bug in place. These fail instead of going quiet. + assert decoded != _TIMEOUT_RAW.decode("utf-8", errors="replace") + assert "\r" in decoded + + assert observed["completed_rc"] == 0 + assert observed["completed_stdout"] == decoded.replace("\r\n", "\n").replace("\r", "\n") + + assert observed["timeout_rc"] == -1 + assert observed["timeout_tail"] == "timed out" + assert observed["timeout_stdout"] == observed["completed_stdout"] + # The child wrote nothing to stderr, so POSIX handed _timeout_stream None. + assert observed["timeout_stderr"] == "" + + def test_verify_commands_timeout_stays_charged(tmp_path, monkeypatch): """A timeout is plausibly the story's own tests hanging — it keeps the fixable-retry classification, not the env-fault escalate."""