From 311654ddafd6edc0fa7deb5dc1fce106dd9d0948 Mon Sep 17 00:00:00 2001 From: kamiotakaaki Date: Tue, 18 Aug 2026 04:50:56 +0900 Subject: [PATCH 01/22] add verification results to post-dev hook --- CHANGELOG.md | 7 +++ docs/plugin-authoring-guide.md | 13 ++++- src/bmad_loop/engine.py | 78 +++++++++++++++++++++++++++-- src/bmad_loop/journal.py | 16 ++++++ src/bmad_loop/plugins/context.py | 14 ++++++ src/bmad_loop/verify.py | 46 ++++++++++++++--- tests/test_engine.py | 85 ++++++++++++++++++++++++++++++++ tests/test_hook_bus.py | 11 +++++ tests/test_verify.py | 18 +++++++ 9 files changed, 277 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d0877c84..98312dd1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,13 @@ 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`. Core writes `verify-command-result` journal records with stream pointers + under the run's `logs/` directory; plugins remain unable to alter verification or commit + decisions. Storage, upload, signing, and any policy response stay plugin-owned. + - **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 diff --git a/docs/plugin-authoring-guide.md b/docs/plugin-authoring-guide.md index bedeb926..ce9039c4 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -390,7 +390,18 @@ there. | ---------------------------------- | --------------------------- | ------------------------------------------------------------------------------------ | | `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 | — | +| `post_dev_verify` | after dev or repair verification | — | + +`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. 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 `logs/`; full streams are not embedded in the +journal. Treat verifier output as potentially sensitive and store, upload, sign, +or act on it only from an explicitly configured plugin. ### Review diff --git a/src/bmad_loop/engine.py b/src/bmad_loop/engine.py index 74b4d672..048fd0e7 100644 --- a/src/bmad_loop/engine.py +++ b/src/bmad_loop/engine.py @@ -1808,16 +1808,20 @@ def _dev_phase(self, task: StoryTask, resume_result: SessionResult | None = None else: task.followup_review_recommended = self._followup_from_spec(task, rj) outcome = harvest_outcome or self._verify_dev_artifacts(task, result.result_json) + command_results = () 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, command_results = self._verify_commands_with_results(task, "dev") + else: + command_results = () 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=command_results, ) decision = decide_dev(task, result, outcome, self.policy) self.journal.append( @@ -3772,6 +3776,62 @@ 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, tuple[verify.CommandResult, ...]]: + """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. + """ + results = tuple(verify.run_verify_commands(self.policy, self.workspace.root)) + self._journal_verify_command_results(task, verification_stage, results) + return verify.verify_command_results_outcome(list(results), self.workspace.root), results + + def _journal_verify_command_results( + self, + task: StoryTask, + verification_stage: str, + results: tuple[verify.CommandResult, ...], + ) -> None: + """Record each verifier subprocess result plus bounded log pointers. + + ``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. + """ + prior_sequences = [ + int(entry["verification_sequence"]) + for entry in self.journal.entries() + if entry.get("kind") == "verify-command-result" + and entry.get("story_key") == task.story_key + and isinstance(entry.get("verification_sequence"), int) + ] + verification_sequence = max(prior_sequences, default=0) + 1 + for command_index, result in enumerate(results): + stem = ( + f"verify-{safe_segment(task.story_key)}-" + f"{verification_stage}-{task.attempt}-{verification_sequence}-{command_index}" + ) + stdout_path = self.journal.write_log_payload(f"{stem}.stdout.log", result.stdout) + stderr_path = self.journal.write_log_payload(f"{stem}.stderr.log", result.stderr) + 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, + stdout_path=stdout_path, + stdout_bytes=len(result.stdout.encode("utf-8")), + stderr_path=stderr_path, + stderr_bytes=len(result.stderr.encode("utf-8")), + ) + 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. @@ -4906,6 +4966,7 @@ def _fix_phase(self, task: StoryTask, reason: str) -> Decision: 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 + command_results = () terminal = None if result.status == "completed": # A repair is another generic dev-primitive pass: it can leave @@ -4939,15 +5000,24 @@ 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, command_results = 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=command_results, + ) self.journal.append( "fix-decision", story_key=task.story_key, diff --git a/src/bmad_loop/journal.py b/src/bmad_loop/journal.py index 837f7a9d..78a1f355 100644 --- a/src/bmad_loop/journal.py +++ b/src/bmad_loop/journal.py @@ -43,6 +43,22 @@ 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_log_payload(self, name: str, content: str) -> str: + """Atomically retain a verifier stream under ``logs/`` and return its + run-relative pointer. The journal records the pointer and byte count, + never unbounded subprocess output inline. + + ``name`` is engine-generated (not plugin or command supplied), so it is + safe to join below. Callers retain the original stream separately in a + hook context; this method is journal storage only. + """ + target = self.run_dir / LOGS_DIR / name + target.parent.mkdir(parents=True, exist_ok=True) + tmp = target.with_suffix(target.suffix + ".tmp") + tmp.write_text(content, encoding="utf-8") + atomic_replace(tmp, target) + return target.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/plugins/context.py b/src/bmad_loop/plugins/context.py index 1b8d6093..37a44b2d 100644 --- a/src/bmad_loop/plugins/context.py +++ b/src/bmad_loop/plugins/context.py @@ -79,6 +79,7 @@ def __init__( result_json: dict[str, Any] | None = None, session_status: str | None = None, verify_reason: str | None = None, + command_results: tuple[Any, ...] = (), decision_action: str | None = None, settings: dict[str, Any] | None = None, shared: dict[str, Any] | None = None, @@ -107,6 +108,10 @@ def __init__( self._result_json = dict(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) 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 +189,15 @@ def session_status(self) -> str | None: def verify_reason(self) -> str | None: return self._verify_reason + @property + def command_results(self) -> tuple[Any, ...]: + """The per-command results from this dev verification attempt. + + Present only as a read-only observability value for ``post_dev_verify``; + an empty tuple means that this attempt did not execute verify commands. + """ + return self._command_results + @property def decision_action(self) -> str | None: return self._decision_action diff --git a/src/bmad_loop/verify.py b/src/bmad_loop/verify.py index b213e2da..5fe3698d 100644 --- a/src/bmad_loop/verify.py +++ b/src/bmad_loop/verify.py @@ -2105,9 +2105,19 @@ def _stories_relpaths(project: Path, spec_folder: Path) -> tuple[str, ...]: @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. + """ + command: str returncode: int output_tail: str + stdout: str = "" + stderr: str = "" # sh launcher convention (verify commands run shell=True): 126 = command found @@ -2249,6 +2259,15 @@ 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 without reintroducing decode faults.""" + if value is None: + return "" + if isinstance(value, bytes): + return value.decode(errors="replace") + return value + + def run_verify_commands(policy: Policy, cwd: Path) -> list[CommandResult]: """Run each of the policy's verify commands, one CommandResult apiece. @@ -2274,14 +2293,25 @@ def run_verify_commands(policy: Policy, cwd: Path) -> list[CommandResult]: 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")) + results.append(CommandResult(command, proc.returncode, output, proc.stdout, proc.stderr)) + except subprocess.TimeoutExpired as exc: + results.append( + CommandResult( + command, + -1, + "timed out", + _timeout_stream(exc.stdout), + _timeout_stream(exc.stderr), + ) + ) 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 @@ -2289,7 +2319,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: @@ -2311,6 +2340,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_engine.py b/tests/test_engine.py index 48a52c8c..cbdae165 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -128,6 +128,91 @@ 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" + + +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.""" + write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) + policy = Policy( + gates=GatesPolicy(mode="none"), + notify=QUIET, + review=ReviewPolicy(enabled=False), + limits=LimitsPolicy(max_dev_attempts=2), + ) + engine, _ = make_engine( + project, + [dev_effect(project, "1-1-a", followup_review=False), dev_effect(project, "1-1-a")], + policy=policy, + ) + capture = _PostDevVerifyCaptureBus() + engine._bus = capture + calls = iter( + [ + [verify.CommandResult("check", 0, "first", "first-out", "")], + [verify.CommandResult("check", 1, "review fail", "", "review fail")], + [verify.CommandResult("check", 0, "fixed", "fixed-out", "")], + [verify.CommandResult("check", 0, "final", "final-out", "")], + ] + ) + monkeypatch.setattr(verify, "run_verify_commands", lambda policy, cwd: next(calls)) + + summary = engine.run() + + 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 _notify_engine(project): return make_engine( project, diff --git a/tests/test_hook_bus.py b/tests/test_hook_bus.py index 4d1168be..a945f8b5 100644 --- a/tests/test_hook_bus.py +++ b/tests/test_hook_bus.py @@ -98,6 +98,17 @@ 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_mutations_pipeline_last_writer_wins(): # lower priority runs first; the later plugin sees the earlier edit and wins class First(Plugin): diff --git a/tests/test_verify.py b/tests/test_verify.py index 0999b1c1..367437f6 100644 --- a/tests/test_verify.py +++ b/tests/test_verify.py @@ -1051,6 +1051,24 @@ 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_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" + + 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.""" From 374a285baa7651f5b9796f4b8fdc95fb96341956 Mon Sep 17 00:00:00 2001 From: kamiotakaaki Date: Tue, 18 Aug 2026 08:20:10 +0900 Subject: [PATCH 02/22] test timeout verification streams --- tests/test_verify.py | 27 +++++++++++++++++++++++++++ 1 file changed, 27 insertions(+) diff --git a/tests/test_verify.py b/tests/test_verify.py index 367437f6..53809fdf 100644 --- a/tests/test_verify.py +++ b/tests/test_verify.py @@ -1069,6 +1069,33 @@ def test_verify_commands_preserve_separate_stdout_and_stderr(tmp_path): assert result.output_tail == "stdout proof\nstderr proof\n" +@pytest.mark.parametrize( + ("stdout", "stderr", "expected_stdout", "expected_stderr"), + [ + (None, None, "", ""), + ("stdout proof", "stderr proof", "stdout proof", "stderr proof"), + (b"stdout \xff", b"stderr \xff", "stdout \ufffd", "stderr \ufffd"), + ], +) +def test_verify_commands_timeout_normalizes_separate_streams( + tmp_path, monkeypatch, stdout, stderr, expected_stdout, expected_stderr +): + """Timeout output keeps the same separate-stream contract as a completed child.""" + policy = Policy(verify=VerifyPolicy(commands=("verify command",))) + + def timeout(*args, **kwargs): + raise subprocess.TimeoutExpired("verify command", 1, output=stdout, stderr=stderr) + + monkeypatch.setattr(verify.subprocess, "run", timeout) + + (result,) = verify.run_verify_commands(policy, tmp_path) + + assert result.returncode == -1 + assert result.output_tail == "timed out" + assert result.stdout == expected_stdout + assert result.stderr == expected_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.""" From fa69b23aa078a221d47e50d571ee8787bfe7ff58 Mon Sep 17 00:00:00 2001 From: t Date: Tue, 18 Aug 2026 22:03:51 -0700 Subject: [PATCH 03/22] style: apply trunk fmt to post-dev verify changes --- docs/plugin-authoring-guide.md | 10 +++++----- src/bmad_loop/verify.py | 4 +++- tests/test_engine.py | 3 +-- 3 files changed, 9 insertions(+), 8 deletions(-) diff --git a/docs/plugin-authoring-guide.md b/docs/plugin-authoring-guide.md index ce9039c4..a073f797 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -386,11 +386,11 @@ 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 or repair 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` exposes `ctx.command_results`: an immutable tuple of the per-command `CommandResult` records core just executed. Each has `command`, diff --git a/src/bmad_loop/verify.py b/src/bmad_loop/verify.py index 5fe3698d..4ec1fa7e 100644 --- a/src/bmad_loop/verify.py +++ b/src/bmad_loop/verify.py @@ -2293,7 +2293,9 @@ def run_verify_commands(policy: Policy, cwd: Path) -> list[CommandResult]: timeout=COMMAND_TIMEOUT_S, ) output = (proc.stdout + proc.stderr)[-2000:] - results.append(CommandResult(command, proc.returncode, output, proc.stdout, proc.stderr)) + results.append( + CommandResult(command, proc.returncode, output, proc.stdout, proc.stderr) + ) except subprocess.TimeoutExpired as exc: results.append( CommandResult( diff --git a/tests/test_engine.py b/tests/test_engine.py index cbdae165..490f1eb6 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -205,8 +205,7 @@ def test_fix_verification_emits_post_dev_verify_with_command_results(project, mo 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 + (e["verification_stage"], e["verification_sequence"], e["command_index"]) for e in entries ] == [ ("dev", 1, 0), ("fix", 2, 0), From dd22a4f77821b8ee86617b21e0dbbe9799f71374 Mon Sep 17 00:00:00 2001 From: t Date: Tue, 18 Aug 2026 22:12:12 -0700 Subject: [PATCH 04/22] fix(verify): decode timeout output on the run's codec, not UTF-8 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit _timeout_stream's bytes arm used bytes.decode's UTF-8 default, contradicting run_verify_commands' own rule (#378) that host-tool output stays on the locale codec that text=True resolves. On POSIX the arm is live: _check_timeout raises TimeoutExpired carrying the raw joined chunks before the text-mode decode, so under an ASCII locale the same bytes read back differently depending on whether the command completed or timed out. Decode with locale.getpreferredencoding(False) — what text=True resolves for an unset encoding, and deliberately not locale.getencoding(), which disagrees under UTF-8 mode. errors="replace", the None -> "" case, and the str passthrough that carries Windows' output are all unchanged. Replace the monkeypatched timeout test, which handed the code str objects and never ran the stdlib decode, with one driving a real hanging child. The decode is exercised inside an ASCII-locale interpreter because on a UTF-8 host both spellings agree and any assertion would be vacuous. --- src/bmad_loop/verify.py | 25 +++++++- tests/test_verify.py | 124 ++++++++++++++++++++++++++++++++++------ 2 files changed, 128 insertions(+), 21 deletions(-) diff --git a/src/bmad_loop/verify.py b/src/bmad_loop/verify.py index 4ec1fa7e..eb223650 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 shlex import shutil @@ -2260,11 +2261,31 @@ def env_fault_reason(result: CommandResult, cwd: Path) -> str | None: def _timeout_stream(value: str | bytes | None) -> str: - """Normalize optional timeout output without reintroducing decode faults.""" + """Normalize optional timeout output onto the codec the completed path used. + + ``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. + + The bytes branch decoding with ``bytes.decode``'s UTF-8 default contradicted + :func:`run_verify_commands`' own rule (#378) that host-tool output stays on + the locale codec, and the two paths disagreed for real: under an ASCII locale + ``b"caf\\xc3\\xa9"`` completes as ``"caf\\ufffd\\ufffd"`` but timed out as + ``"café"``. ``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.""" if value is None: return "" if isinstance(value, bytes): - return value.decode(errors="replace") + return value.decode(locale.getpreferredencoding(False), errors="replace") return value diff --git a/tests/test_verify.py b/tests/test_verify.py index 53809fdf..a2d0f105 100644 --- a/tests/test_verify.py +++ b/tests/test_verify.py @@ -1,5 +1,6 @@ import dataclasses import io +import json import os import subprocess import sys @@ -1070,30 +1071,115 @@ def test_verify_commands_preserve_separate_stdout_and_stderr(tmp_path): @pytest.mark.parametrize( - ("stdout", "stderr", "expected_stdout", "expected_stderr"), - [ - (None, None, "", ""), - ("stdout proof", "stderr proof", "stdout proof", "stderr proof"), - (b"stdout \xff", b"stderr \xff", "stdout \ufffd", "stderr \ufffd"), - ], + ("value", "expected"), + [(None, ""), ("already decoded", "already decoded")], + ids=["none", "str-passthrough"], ) -def test_verify_commands_timeout_normalizes_separate_streams( - tmp_path, monkeypatch, stdout, stderr, expected_stdout, expected_stderr -): - """Timeout output keeps the same separate-stream contract as a completed child.""" - policy = Policy(verify=VerifyPolicy(commands=("verify command",))) +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 + + +# ---- timeout-path decode agrees with the completed path (#378, follow-on) +# +# The divergence this pins is observable only where the run's codec is not UTF-8: +# on a UTF-8 host `bytes.decode()`'s hardcoded default and the locale codec are +# the same codec, so an in-process assertion passes unchanged with the bug +# restored. 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 exactly where the guard is wanted, which is the inverse of what that +# marker achieves for its own tests. The decode is therefore driven inside a +# child interpreter pinned to an ASCII locale, making the divergence real on any +# host. Everything below that boundary is genuine: a real grandchild writes the +# bytes and hangs, and CPython's own timeout leg is what hands them over — +# monkeypatching `subprocess.run` instead would supply str objects directly and +# never run the decode at all (see the #378 block below). +_TIMEOUT_RAW = b"caf\xc3\xa9\n" # decodable as UTF-8, not as ASCII: the spellings disagree - def timeout(*args, **kwargs): - raise subprocess.TimeoutExpired("verify command", 1, output=stdout, stderr=stderr) - monkeypatch.setattr(verify.subprocess, "run", timeout) +@pytest.mark.skipif( + sys.platform == "win32", + reason="the bytes arm is unreachable on Windows (run() re-collects via " + "communicate() after kill(), which returns str), and LC_ALL is not how " + "Windows resolves the codec", +) +def test_verify_commands_timeout_decodes_on_the_run_codec(tmp_path): + """A timed-out child's output decodes on the same codec a completed child's + does, not on ``bytes.decode``'s UTF-8 default. + + run_verify_commands' docstring pins host-tool output to the locale codec + (``text=True``); the timeout arm hardcoded UTF-8, so under an ASCII locale + the same bytes read back as ``café`` when the command timed out and + ``caf`` when it completed — the tail a human or repair session sees + depended on which path produced it. + + Ablation: restore ``value.decode(errors="replace")`` in ``_timeout_stream`` + and this fails, because the child resolves ASCII while that spelling stays + on UTF-8. Note that ``LC_ALL=C`` alone does NOT redden it: the C locale + auto-enables UTF-8 mode (PEP 540), which puts both spellings back on the + same codec, so ``PYTHONUTF8=0`` is load-bearing in the env below.""" + hang = tmp_path / "hang_timeout.py" + hang.write_text( + "import sys, time\n" + f"sys.stdout.buffer.write({_TIMEOUT_RAW!r})\n" + "sys.stdout.buffer.flush()\n" + "time.sleep(10)\n", + encoding="utf-8", + ) + driver = tmp_path / "drive_timeout.py" + # 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" + 'cmd = \'"%s" "%s"\' % (sys.executable, sys.argv[1])\n' + "(result,) = verify.run_verify_commands(\n" + " Policy(verify=VerifyPolicy(commands=(cmd,))), Path(sys.argv[2])\n" + ")\n" + "json.dump({'encoding': locale.getpreferredencoding(False),\n" + " 'returncode': result.returncode, 'output_tail': result.output_tail,\n" + " 'stdout': result.stdout, 'stderr': result.stderr}, 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) - (result,) = verify.run_verify_commands(policy, tmp_path) + proc = subprocess.run( + [sys.executable, str(driver), str(hang), str(tmp_path)], + capture_output=True, + text=True, + encoding="utf-8", + env=env, + timeout=120, + ) - assert result.returncode == -1 - assert result.output_tail == "timed out" - assert result.stdout == expected_stdout - assert result.stderr == expected_stderr + assert proc.returncode == 0, proc.stderr + observed = json.loads(proc.stdout) + on_run_codec = _TIMEOUT_RAW.decode(observed["encoding"], errors="replace") + # Anti-vacuity: without this the equality below would hold on a UTF-8 host + # with the bug in place, and the test would prove nothing. + assert on_run_codec != _TIMEOUT_RAW.decode("utf-8", errors="replace") + + assert observed["returncode"] == -1 + assert observed["output_tail"] == "timed out" + assert observed["stdout"] == on_run_codec + # The child wrote nothing to stderr, so POSIX handed _timeout_stream None. + assert observed["stderr"] == "" def test_verify_commands_timeout_stays_charged(tmp_path, monkeypatch): From e72089d46dc2ba169f55cc02a9f7b3197eb61296 Mon Sep 17 00:00:00 2001 From: t Date: Tue, 18 Aug 2026 22:40:17 -0700 Subject: [PATCH 05/22] fix(verify): collapse newlines on the timeout path too MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The codec was only half the divergence. POSIX raises TimeoutExpired before the text-mode conversion at the end of _communicate, and that conversion is Popen._translate_newlines: decode, THEN collapse \r\n and lone \r to \n. The timeout arm did neither, so a child emitting CRLF still read back differently depending on which path produced it. Mirror the whole of _translate_newlines rather than just its decode. The str arm stays untouched: on Windows the reader thread reads through the text wrapper, so those newlines are already translated. The test now asserts the two paths agree instead of re-implementing the expected transformation — one grandchild script emits identical bytes on both paths, and the completed result is the reference, so the assertion is against what the stdlib does rather than this test's idea of it. Ablating either half reddens it, and each isolates one: dropping the codec leaves the newlines already agreeing, dropping the replace chain leaves the codec already agreeing. --- src/bmad_loop/verify.py | 21 ++++--- tests/test_verify.py | 126 +++++++++++++++++++++++----------------- 2 files changed, 87 insertions(+), 60 deletions(-) diff --git a/src/bmad_loop/verify.py b/src/bmad_loop/verify.py index eb223650..94a708a9 100644 --- a/src/bmad_loop/verify.py +++ b/src/bmad_loop/verify.py @@ -2261,7 +2261,7 @@ def env_fault_reason(result: CommandResult, cwd: Path) -> str | None: def _timeout_stream(value: str | bytes | None) -> str: - """Normalize optional timeout output onto the codec the completed path used. + """Normalize optional timeout output into what the completed path would give. ``subprocess.run``'s timeout leg is not uniform, so three shapes arrive: @@ -2273,19 +2273,26 @@ def _timeout_stream(value: str | bytes | None) -> str: this branch is the only way the output arrives at all. * ``None`` — POSIX again, when nothing had been buffered on that stream. - The bytes branch decoding with ``bytes.decode``'s UTF-8 default contradicted + 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, and the two paths disagreed for real: under an ASCII locale - ``b"caf\\xc3\\xa9"`` completes as ``"caf\\ufffd\\ufffd"`` but timed out as - ``"café"``. ``locale.getpreferredencoding(False)`` is what ``text=True`` + 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.""" + 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): - return value.decode(locale.getpreferredencoding(False), errors="replace") + decoded = value.decode(locale.getpreferredencoding(False), errors="replace") + return decoded.replace("\r\n", "\n").replace("\r", "\n") return value diff --git a/tests/test_verify.py b/tests/test_verify.py index a2d0f105..23047040 100644 --- a/tests/test_verify.py +++ b/tests/test_verify.py @@ -1090,69 +1090,84 @@ def test_timeout_stream_shapes_that_carry_no_decode(value, expected): assert verify._timeout_stream(value) == expected -# ---- timeout-path decode agrees with the completed path (#378, follow-on) +# ---- a timed-out child's output reads like a completed one's (#378, follow-on) # -# The divergence this pins is observable only where the run's codec is not UTF-8: -# on a UTF-8 host `bytes.decode()`'s hardcoded default and the locale codec are -# the same codec, so an in-process assertion passes unchanged with the bug -# restored. 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 exactly where the guard is wanted, which is the inverse of what that -# marker achieves for its own tests. The decode is therefore driven inside a -# child interpreter pinned to an ASCII locale, making the divergence real on any -# host. Everything below that boundary is genuine: a real grandchild writes the -# bytes and hangs, and CPython's own timeout leg is what hands them over — -# monkeypatching `subprocess.run` instead would supply str objects directly and -# never run the decode at all (see the #378 block below). -_TIMEOUT_RAW = b"caf\xc3\xa9\n" # decodable as UTF-8, not as ASCII: the spellings disagree +# 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), and LC_ALL is not how " - "Windows resolves the codec", + "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_decodes_on_the_run_codec(tmp_path): - """A timed-out child's output decodes on the same codec a completed child's - does, not on ``bytes.decode``'s UTF-8 default. - - run_verify_commands' docstring pins host-tool output to the locale codec - (``text=True``); the timeout arm hardcoded UTF-8, so under an ASCII locale - the same bytes read back as ``café`` when the command timed out and - ``caf`` when it completed — the tail a human or repair session sees - depended on which path produced it. - - Ablation: restore ``value.decode(errors="replace")`` in ``_timeout_stream`` - and this fails, because the child resolves ASCII while that spelling stays - on UTF-8. Note that ``LC_ALL=C`` alone does NOT redden it: the C locale - auto-enables UTF-8 mode (PEP 540), which puts both spellings back on the - same codec, so ``PYTHONUTF8=0`` is load-bearing in the env below.""" - hang = tmp_path / "hang_timeout.py" - hang.write_text( +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" - "time.sleep(10)\n", + "if sys.argv[1] == 'hang':\n" + " time.sleep(10)\n", encoding="utf-8", ) driver = tmp_path / "drive_timeout.py" - # 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. + # 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" - 'cmd = \'"%s" "%s"\' % (sys.executable, sys.argv[1])\n' - "(result,) = verify.run_verify_commands(\n" - " Policy(verify=VerifyPolicy(commands=(cmd,))), Path(sys.argv[2])\n" - ")\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" - " 'returncode': result.returncode, 'output_tail': result.output_tail,\n" - " 'stdout': result.stdout, 'stderr': result.stderr}, sys.stdout)\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")} @@ -1160,7 +1175,7 @@ def test_verify_commands_timeout_decodes_on_the_run_codec(tmp_path): env["PYTHONUTF8"] = "0" # without this the C locale would resolve to UTF-8 (PEP 540) proc = subprocess.run( - [sys.executable, str(driver), str(hang), str(tmp_path)], + [sys.executable, str(driver), str(emit), str(tmp_path)], capture_output=True, text=True, encoding="utf-8", @@ -1170,16 +1185,21 @@ def test_verify_commands_timeout_decodes_on_the_run_codec(tmp_path): assert proc.returncode == 0, proc.stderr observed = json.loads(proc.stdout) - on_run_codec = _TIMEOUT_RAW.decode(observed["encoding"], errors="replace") - # Anti-vacuity: without this the equality below would hold on a UTF-8 host - # with the bug in place, and the test would prove nothing. - assert on_run_codec != _TIMEOUT_RAW.decode("utf-8", errors="replace") - - assert observed["returncode"] == -1 - assert observed["output_tail"] == "timed out" - assert observed["stdout"] == on_run_codec + 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["stderr"] == "" + assert observed["timeout_stderr"] == "" def test_verify_commands_timeout_stays_charged(tmp_path, monkeypatch): From 5b8bcb8f5bfb29326326a9c760e4a1f1608343e8 Mon Sep 17 00:00:00 2001 From: t Date: Tue, 18 Aug 2026 22:56:21 -0700 Subject: [PATCH 06/22] fix(verify): store verifier streams outside the adapters' logs/ MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Every other inhabitant of logs/ is a coding-CLI pane capture named after a session task id, and the TUI reads the directory as exactly that: 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 reopens as logs/{stem}.log. Verifier streams landed in precisely that window — session-end is journalled when the session ends, before its result reaches verification, so nothing is open when those files are newest. The path resolved, so the log pane rendered verifier stderr in place of the agent session log. Give the store its own run-dir subdirectory (verify/) and rename Journal.write_log_payload to write_verify_stream, which names what it stores. Journal record fields are unchanged: stdout_path/stderr_path stay run-relative pointers, only the directory moves. Separating the directory makes the collision unrepresentable rather than leaving a name filter every future reader of logs/ must remember to apply. --- CHANGELOG.md | 3 ++- README.md | 2 +- docs/FEATURES.md | 2 +- docs/plugin-authoring-guide.md | 6 ++++-- src/bmad_loop/engine.py | 4 ++-- src/bmad_loop/journal.py | 26 +++++++++++++++++++++----- tests/test_engine.py | 7 ++++++- tests/test_tui_data.py | 33 +++++++++++++++++++++++++++++++++ 8 files changed, 70 insertions(+), 13 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 98312dd1..62bffb92 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,7 +13,8 @@ breaking changes may land in a minor release. `post_dev_verify` hook receives immutable per-command results after normal and repair verification, with separate `stdout`/`stderr` alongside the compatible bounded `output_tail`. Core writes `verify-command-result` journal records with stream pointers - under the run's `logs/` directory; plugins remain unable to alter verification or commit + 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. - **A refused auto-sweep is now visible outside the journal (#501).** A run whose deferred-work diff --git a/README.md b/README.md index 4049c27b..da50cf88 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), `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 417516b6..7e1421bb 100644 --- a/docs/FEATURES.md +++ b/docs/FEATURES.md @@ -108,7 +108,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); `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); `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 a073f797..9cd1d3c2 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -399,8 +399,10 @@ and `stderr` strings. 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 `logs/`; full streams are not embedded in the -journal. Treat verifier output as potentially sensitive and store, upload, sign, +`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. Treat verifier output as potentially sensitive and store, upload, sign, or act on it only from an explicitly configured plugin. ### Review diff --git a/src/bmad_loop/engine.py b/src/bmad_loop/engine.py index 048fd0e7..4182f315 100644 --- a/src/bmad_loop/engine.py +++ b/src/bmad_loop/engine.py @@ -3814,8 +3814,8 @@ def _journal_verify_command_results( f"verify-{safe_segment(task.story_key)}-" f"{verification_stage}-{task.attempt}-{verification_sequence}-{command_index}" ) - stdout_path = self.journal.write_log_payload(f"{stem}.stdout.log", result.stdout) - stderr_path = self.journal.write_log_payload(f"{stem}.stderr.log", result.stderr) + stdout_path = self.journal.write_verify_stream(f"{stem}.stdout.log", result.stdout) + stderr_path = self.journal.write_verify_stream(f"{stem}.stderr.log", result.stderr) self.journal.append( "verify-command-result", story_key=task.story_key, diff --git a/src/bmad_loop/journal.py b/src/bmad_loop/journal.py index 78a1f355..7f0e9f55 100644 --- a/src/bmad_loop/journal.py +++ b/src/bmad_loop/journal.py @@ -13,6 +13,9 @@ 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,16 +46,29 @@ 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_log_payload(self, name: str, content: str) -> str: - """Atomically retain a verifier stream under ``logs/`` and return its - run-relative pointer. The journal records the pointer and byte count, - never unbounded subprocess output inline. + 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 + count, 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. Callers retain the original stream separately in a hook context; this method is journal storage only. """ - target = self.run_dir / LOGS_DIR / name + target = self.run_dir / VERIFY_DIR / name target.parent.mkdir(parents=True, exist_ok=True) tmp = target.with_suffix(target.suffix + ".tmp") tmp.write_text(content, encoding="utf-8") diff --git a/tests/test_engine.py b/tests/test_engine.py index 490f1eb6..2801ce78 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, @@ -171,6 +171,11 @@ def test_post_dev_verify_exposes_journaled_command_results(project, monkeypatch) 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_fix_verification_emits_post_dev_verify_with_command_results(project, monkeypatch): 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 From bfa09225769dda02bc299828e447fd659788f794 Mon Sep 17 00:00:00 2001 From: t Date: Tue, 18 Aug 2026 22:56:34 -0700 Subject: [PATCH 07/22] fix(verify): sanitize the whole verify stream filename composition MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The filename composes six parts but passed only task.story_key through safe_segment. _session_task_id documents the opposite rule for exactly this shape: sanitize the whole composition, not the parts — two individually capped parts can still compose past a filename segment limit, and safe_segment's digest suffix differs between the two orders. A 124-character story key produced a 137-character segment against a 120 cap. Follow the documented idiom. --- src/bmad_loop/engine.py | 9 ++++++--- tests/test_engine.py | 24 ++++++++++++++++++++++++ 2 files changed, 30 insertions(+), 3 deletions(-) diff --git a/src/bmad_loop/engine.py b/src/bmad_loop/engine.py index 4182f315..913f5806 100644 --- a/src/bmad_loop/engine.py +++ b/src/bmad_loop/engine.py @@ -3799,7 +3799,10 @@ def _journal_verify_command_results( ``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. + 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. """ prior_sequences = [ int(entry["verification_sequence"]) @@ -3810,8 +3813,8 @@ def _journal_verify_command_results( ] verification_sequence = max(prior_sequences, default=0) + 1 for command_index, result in enumerate(results): - stem = ( - f"verify-{safe_segment(task.story_key)}-" + stem = safe_segment( + f"verify-{task.story_key}-" f"{verification_stage}-{task.attempt}-{verification_sequence}-{command_index}" ) stdout_path = self.journal.write_verify_stream(f"{stem}.stdout.log", result.stdout) diff --git a/tests/test_engine.py b/tests/test_engine.py index 2801ce78..471642d0 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -178,6 +178,30 @@ def test_post_dev_verify_exposes_journaled_command_results(project, monkeypatch) 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 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.""" write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) From eed034c97c13989e941e7fe0cdca6702e8b066b0 Mon Sep 17 00:00:00 2001 From: t Date: Tue, 18 Aug 2026 23:21:57 -0700 Subject: [PATCH 08/22] fix(verify): bound, gate and degrade the verifier stream capture MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The retain path wrote the FULL stdout and stderr of every verify command, on every verification, with no cap, no GC and no way to switch it off. Under COMMAND_TIMEOUT_S (30 minutes) a chatty suite emits hundreds of MB per attempt, and retention never reclaims it — _HEAVY_RUN_ENTRIES is ("worktrees",) alone. Cap it. A bounded TAIL is retained per stream, the direction every other bound on this output takes (the merged output_tail is [-2000:]) because a failing suite puts its failure at the end. The record stays honest about the cut: the FULL byte count travels beside the retained one with an explicit *_truncated flag, since a silently short file reads as a complete one. A byte cut landing mid-character drops the partial lead rather than decoding it into a U+FFFD this code would be inventing at a boundary it chose. Gate it. New [verify] stream_capture_kb, default 256 KiB per stream, with the matching core.toml entry the sync test requires. 0 = capture nothing: no files at all, and the record still lands with null pointers and the full byte counts, because "nothing was retained" and "the command was silent" differ. Degrade it. The writer had no error handling, so an OSError (ENOSPC, a read-only run dir, ENAMETOOLONG) propagated out and crashed the run — a diagnostic killing the dev pass it exists to diagnose, on a story whose verify commands PASSED. This is observation, so it degrades: the record lands with a null pointer and a capture_error, and the run continues. Also switch to atomic_write_text (#379). The bare write_text plus a FIXED .tmp sibling is exactly the collision that helper's docstring exists to prevent; follow_symlinks=False because these are machine-minted files under a run dir a coding-CLI session can reach. Text mode translates \n on Windows, so the byte counts are now defined over the STREAM, never the file — stated in the record's docstring, the journal helper, and the plugin guide. Each test ablated: uncapping reddens the size and truncation assertions; errors="replace" both breaks the cap (3 bytes for 1) and invents a marker; dropping the zero guard creates verify/ and empty files; dropping the except arm returns crashed=True with done=0; dropping the policy floor stops refusing a negative. --- CHANGELOG.md | 6 + README.md | 2 +- docs/FEATURES.md | 2 +- docs/plugin-authoring-guide.md | 17 ++- docs/tui-guide.md | 1 + src/bmad_loop/data/settings/core.toml | 7 ++ src/bmad_loop/engine.py | 71 +++++++++++- src/bmad_loop/journal.py | 33 ++++-- src/bmad_loop/policy.py | 29 ++++- tests/test_engine.py | 160 ++++++++++++++++++++++++++ tests/test_policy.py | 16 +++ 11 files changed, 327 insertions(+), 17 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 62bffb92..338cc8ef 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,6 +16,12 @@ breaking changes may land in a minor release. 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. + 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. 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"` diff --git a/README.md b/README.md index da50cf88..aba79143 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), `verify/` (verifier command stdout/stderr, pointed at by the journal's `verify-command-result` records), `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 7e1421bb..46888655 100644 --- a/docs/FEATURES.md +++ b/docs/FEATURES.md @@ -108,7 +108,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/`; `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); `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); `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 9cd1d3c2..028c61e9 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -402,7 +402,22 @@ verification-sequence correlation, `output_tail`, byte counts, and run-relative `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. Treat verifier output as potentially sensitive and store, upload, sign, +by the TUI. + +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), 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. ### Review 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/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/engine.py b/src/bmad_loop/engine.py index 913f5806..618ba39a 100644 --- a/src/bmad_loop/engine.py +++ b/src/bmad_loop/engine.py @@ -88,6 +88,35 @@ 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". + """ + encoded = text.encode("utf-8") + full_bytes = len(encoded) + if full_bytes <= max_bytes: + return text, full_bytes, full_bytes + tail = encoded[full_bytes - max_bytes :].decode("utf-8", errors="ignore") + return tail, full_bytes, len(tail.encode("utf-8")) + + class RunPaused(Exception): def __init__(self, reason: str, stage: str, story_key: str | None = None): super().__init__(reason) @@ -3803,6 +3832,22 @@ def _journal_verify_command_results( 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. """ prior_sequences = [ int(entry["verification_sequence"]) @@ -3812,13 +3857,29 @@ def _journal_verify_command_results( and isinstance(entry.get("verification_sequence"), int) ] verification_sequence = max(prior_sequences, default=0) + 1 + 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}" ) - stdout_path = self.journal.write_verify_stream(f"{stem}.stdout.log", result.stdout) - stderr_path = self.journal.write_verify_stream(f"{stem}.stderr.log", result.stderr) + streams: dict[str, str | int | bool | None] = {} + capture_error: str | None = None + for kind, text in (("stdout", result.stdout), ("stderr", result.stderr)): + tail, full_bytes, captured_bytes = _bounded_stream_tail(text, max_bytes) + 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, @@ -3829,10 +3890,8 @@ def _journal_verify_command_results( command=result.command, returncode=result.returncode, output_tail=result.output_tail, - stdout_path=stdout_path, - stdout_bytes=len(result.stdout.encode("utf-8")), - stderr_path=stderr_path, - stderr_bytes=len(result.stderr.encode("utf-8")), + capture_error=capture_error, + **streams, ) def _resume_after_dev_verify(self, task: StoryTask) -> None: diff --git a/src/bmad_loop/journal.py b/src/bmad_loop/journal.py index 7f0e9f55..1c908285 100644 --- a/src/bmad_loop/journal.py +++ b/src/bmad_loop/journal.py @@ -8,7 +8,7 @@ from typing import Any from .model import RunState -from .platform_util import atomic_replace +from .platform_util import atomic_replace, atomic_write_text STATE_FILE = "state.json" JOURNAL_FILE = "journal.jsonl" @@ -49,7 +49,7 @@ def append(self, kind: str, **fields: Any) -> None: 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 - count, never unbounded subprocess output inline. + 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 @@ -65,14 +65,33 @@ def write_verify_stream(self, name: str, content: str) -> str: 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. Callers retain the original stream separately in a - hook context; this method is journal storage only. + 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. + + Raises ``OSError`` — the caller degrades (this is observation), it does + not swallow it here. """ target = self.run_dir / VERIFY_DIR / name target.parent.mkdir(parents=True, exist_ok=True) - tmp = target.with_suffix(target.suffix + ".tmp") - tmp.write_text(content, encoding="utf-8") - atomic_replace(tmp, target) + atomic_write_text(target, content, follow_symlinks=False) return target.relative_to(self.run_dir).as_posix() def entries(self) -> list[dict[str, Any]]: diff --git a/src/bmad_loop/policy.py b/src/bmad_loop/policy.py index 2f3fde2c..9c870753 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) @@ -832,7 +853,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)), @@ -1145,6 +1171,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/tests/test_engine.py b/tests/test_engine.py index 471642d0..a3ffcf86 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -202,6 +202,166 @@ def test_verify_stream_filenames_sanitize_the_whole_composition(project): 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_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(path, text, **kwargs): + raise OSError(28, "No space left on device") + + monkeypatch.setattr("bmad_loop.journal.atomic_write_text", _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.""" write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) diff --git a/tests/test_policy.py b/tests/test_policy.py index abde1e8d..2e565029 100644 --- a/tests/test_policy.py +++ b/tests/test_policy.py @@ -779,6 +779,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="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') From b82ba46bc42d5d5fa469a86da2eaed33dad04cf3 Mon Sep 17 00:00:00 2001 From: t Date: Tue, 18 Aug 2026 23:41:57 -0700 Subject: [PATCH 09/22] fix(verify): seed the verification counter, discriminate the two emits MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Three follow-ups on the post_dev_verify verification-results surface. M3 — the per-story `verification_sequence` was re-derived by rescanning journal.jsonl on EVERY dev and fix verification: read_text of the whole file plus json.loads per line, over a file the same writer keeps appending to, so the cost grew with the run paying it. Replace it with a per-engine map seeded from the journal once, then incremented in memory. The seed is what keeps the ordinal 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 used, which is the property the rescan bought and the part a naive counter breaks. Kept off StoryTask deliberately: the value is recoverable from the journal on every resume, so a state.json field could only disagree with the record it duplicates. A pass with no results still allocates nothing, preserving the old numbering exactly. M5 — both emits carried stage="post_dev_verify", phase=DEV_VERIFY and one shared attempt counter, so a plugin could tell neither which leg it was on nor which journal records its context was about. Put `verification_stage` and `verification_sequence` on the context: the stage is the dev-vs-repair discriminator, and story + stage + sequence is the join key back to the `verify-command-result` entries. `stage` is set whenever a pass ran, including the zero-command case, so "the pass ran and executed nothing" stays distinct from "no pass ran". The `command_results` docstring no longer asserts something narrower than the code: it enumerates the four causes that reach an empty tuple with no stage, and names the fields (session_status, verify_reason) that separate them. N1 — `command_results` was the only HookContext field with an erased element type. Give it `tuple[CommandResult, ...]` via TYPE_CHECKING, the idiom plugins/model.py already uses; verified there is no cycle (verify.py reaches deferredwork/bmadconfig/frontmatter/model/platform_util/policy/ sprintstatus, none of which touch plugins/). Tests: resume monotonicity, per-story keying, one journal read per engine rather than per verification, the empty-pass/no-pass taxonomy, and the dev-vs-fix discrimination with its journal join. Every ablation was run and confirmed to redden its test — including two that did NOT, whose docstrings now state the ablation that actually does. Adds a test that goes through the real HookBus into a registered plugin, since the existing engine tests swap in a capture double and skip the dispatch path. --- CHANGELOG.md | 11 +- docs/plugin-authoring-guide.md | 31 ++++ src/bmad_loop/engine.py | 151 +++++++++++++--- src/bmad_loop/plugins/context.py | 83 ++++++++- tests/test_engine.py | 290 +++++++++++++++++++++++++++++-- tests/test_hook_bus.py | 36 ++++ 6 files changed, 553 insertions(+), 49 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 338cc8ef..4fb59a2d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,10 +12,13 @@ breaking changes may land in a minor release. - **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`. 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. + `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. 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 diff --git a/docs/plugin-authoring-guide.md b/docs/plugin-authoring-guide.md index 028c61e9..e2e945e2 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -404,6 +404,37 @@ 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` / diff --git a/src/bmad_loop/engine.py b/src/bmad_loop/engine.py index 618ba39a..5dd362ff 100644 --- a/src/bmad_loop/engine.py +++ b/src/bmad_loop/engine.py @@ -117,6 +117,35 @@ def _bounded_stream_tail(text: str, max_bytes: int) -> tuple[str, int, int]: 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) @@ -482,6 +511,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 @@ -1759,6 +1792,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 @@ -1837,20 +1871,22 @@ def _dev_phase(self, task: StoryTask, resume_result: SessionResult | None = None else: task.followup_review_recommended = self._followup_from_spec(task, rj) outcome = harvest_outcome or self._verify_dev_artifacts(task, result.result_json) - command_results = () 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, command_results = self._verify_commands_with_results(task, "dev") - else: - command_results = () + 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=command_results, + 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( @@ -3807,23 +3843,87 @@ def _run_verify_commands_after_dev(self, task: StoryTask, result_json: dict | No def _verify_commands_with_results( self, task: StoryTask, verification_stage: str - ) -> tuple[VerifyOutcome, tuple[verify.CommandResult, ...]]: + ) -> 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)) - self._journal_verify_command_results(task, verification_stage, results) - return verify.verify_command_results_outcome(list(results), self.workspace.root), results + 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, ...], - ) -> None: - """Record each verifier subprocess result plus bounded log pointers. + ) -> 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 @@ -3848,15 +3948,17 @@ def _journal_verify_command_results( ``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. """ - prior_sequences = [ - int(entry["verification_sequence"]) - for entry in self.journal.entries() - if entry.get("kind") == "verify-command-result" - and entry.get("story_key") == task.story_key - and isinstance(entry.get("verification_sequence"), int) - ] - verification_sequence = max(prior_sequences, default=0) + 1 + 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( @@ -3893,6 +3995,7 @@ def _journal_verify_command_results( 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). @@ -5028,7 +5131,7 @@ def _fix_phase(self, task: StoryTask, reason: str) -> Decision: 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 - command_results = () + verified = NO_VERIFY_COMMANDS terminal = None if result.status == "completed": # A repair is another generic dev-primitive pass: it can leave @@ -5065,7 +5168,7 @@ def _fix_phase(self, task: StoryTask, reason: str) -> Decision: if harvest_outcome is not None: outcome = harvest_outcome else: - outcome, command_results = self._verify_commands_with_results(task, "fix") + outcome, verified = self._verify_commands_with_results(task, "fix") if not outcome.ok: reason = outcome.reason ok = outcome is not None and outcome.ok @@ -5078,7 +5181,13 @@ def _fix_phase(self, task: StoryTask, reason: str) -> Decision: session_status=result.status, result_json=result.result_json, verify_reason=(outcome.reason if outcome is not None else None), - command_results=command_results, + 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", diff --git a/src/bmad_loop/plugins/context.py b/src/bmad_loop/plugins/context.py index 37a44b2d..6c189cfb 100644 --- a/src/bmad_loop/plugins/context.py +++ b/src/bmad_loop/plugins/context.py @@ -21,7 +21,17 @@ from __future__ import annotations 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,7 +89,9 @@ def __init__( result_json: dict[str, Any] | None = None, session_status: str | None = None, verify_reason: str | None = None, - command_results: tuple[Any, ...] = (), + 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, @@ -112,6 +124,12 @@ def __init__( # 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) @@ -190,14 +208,65 @@ def verify_reason(self) -> str | None: return self._verify_reason @property - def command_results(self) -> tuple[Any, ...]: - """The per-command results from this dev verification attempt. - - Present only as a read-only observability value for ``post_dev_verify``; - an empty tuple means that this attempt did not execute verify commands. + 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/tests/test_engine.py b/tests/test_engine.py index a3ffcf86..8dd5a99c 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -364,19 +364,168 @@ def _enospc(path, text, **kwargs): 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. + """ write_sprint(project, {"epic-1": "backlog", "1-1-a": "ready-for-dev"}) - policy = Policy( - gates=GatesPolicy(mode="none"), - notify=QUIET, - review=ReviewPolicy(enabled=False), - limits=LimitsPolicy(max_dev_attempts=2), - ) engine, _ = make_engine( project, [dev_effect(project, "1-1-a", followup_review=False), dev_effect(project, "1-1-a")], - policy=policy, + policy=Policy( + gates=GatesPolicy(mode="none"), + notify=QUIET, + review=ReviewPolicy(enabled=False), + limits=LimitsPolicy(max_dev_attempts=2), + ), ) - capture = _PostDevVerifyCaptureBus() engine._bus = capture calls = iter( [ @@ -387,18 +536,125 @@ def test_fix_verification_emits_post_dev_verify_with_command_results(project, mo ] ) monkeypatch.setattr(verify, "run_verify_commands", lambda policy, cwd: next(calls)) + return engine, engine.run() - summary = 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 - 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), - ] + 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] + + +_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): diff --git a/tests/test_hook_bus.py b/tests/test_hook_bus.py index a945f8b5..9ad85cb7 100644 --- a/tests/test_hook_bus.py +++ b/tests/test_hook_bus.py @@ -392,6 +392,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) From d795fd5bd16227676692b82f63c4dd7b6ec222ce Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 00:03:52 -0700 Subject: [PATCH 10/22] fix(verify): emit post_dev_verify before the fix leg escalates MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit M4: a repair session reporting a CRITICAL escalation fired no post_dev_verify at all — `_escalate` raises RunPaused, and `_fix_phase` checked `critical_escalations` before its emit. The dev leg reaches the same check inside `decide_dev`, which its caller invokes AFTER emitting, so one event class was observable on one leg and invisible on the other. Move the fix leg's check below the emit and the `fix-decision` record, and above the env-fault arm — the same precedence `decide_dev` applies. N7: `_crash_after_harvest` raised on any `post_dev_verify`, a stage that now names two points in the loop. Latch it to the first emit so it fires where its docstring says. Docs: state plainly in the plugin guide that the stage fires on both legs and so more than once per story; name `verify-command-result` in FEATURES.md's run-state inventory. Add the ### Changed entry — emitting an existing hook from a second site is a behavior change for plugins written against "fires once, after dev verification". N9: route the verifier record's free-text fields through `_JOURNAL_DROP_FIELDS` as presence booleans. `scrub_json` failed closed only by accident of shape: a one-word `command` like `make` is identifier-shaped and shipped verbatim. --- CHANGELOG.md | 8 ++++ docs/FEATURES.md | 2 +- docs/plugin-authoring-guide.md | 9 ++++ src/bmad_loop/diagnostics.py | 17 +++++++ src/bmad_loop/engine.py | 21 +++++++-- tests/test_diagnostics.py | 60 ++++++++++++++++++++++++ tests/test_engine.py | 86 +++++++++++++++++++++++++++++++++- 7 files changed, 196 insertions(+), 7 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 4fb59a2d..c11812fd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -37,6 +37,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. + - **Files the orchestrator replaces by name now land at `0600`.** Those writes pass `follow_symlinks=False`, and that mode deliberately carries nothing over from the target — not its permission bits, not its xattrs — so the new contents arrive at `mkstemp`'s private default. diff --git a/docs/FEATURES.md b/docs/FEATURES.md index 46888655..4f5f6665 100644 --- a/docs/FEATURES.md +++ b/docs/FEATURES.md @@ -108,7 +108,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/`; `verify/` (verifier command stdout/stderr, one file per stream, pointed at by the journal's `verify-command-result` records — its own store, because every name in `logs/` is a session task id the TUI resolves as a pane log; each stream is retained tail-first up to `[verify] stream_capture_kb` (256 KiB, `0` = keep nothing) and the record carries the full byte count, a truncation flag, and a `capture_error` when the write itself failed); `deferred/`; `resolve/`; `ATTENTION`; `ctl-window` (the control-session window id the last TUI launch minted, so attach/stop follow the live window, #482). +- All run state in `.bmad-loop/runs//` (gitignored): `state.json`; `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 e2e945e2..7be249ed 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -392,6 +392,15 @@ there. | `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` diff --git a/src/bmad_loop/diagnostics.py b/src/bmad_loop/diagnostics.py index e481fdea..3dc4650f 100644 --- a/src/bmad_loop/diagnostics.py +++ b/src/bmad_loop/diagnostics.py @@ -120,6 +120,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", @@ -132,6 +144,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). diff --git a/src/bmad_loop/engine.py b/src/bmad_loop/engine.py index 5dd362ff..8fce9cc9 100644 --- a/src/bmad_loop/engine.py +++ b/src/bmad_loop/engine.py @@ -5126,10 +5126,6 @@ def _fix_phase(self, task: StoryTask, reason: str) -> Decision: session_stage="pre_fix_session", ) 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 @@ -5200,6 +5196,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/tests/test_diagnostics.py b/tests/test_diagnostics.py index 0757b450..7ed480a0 100644 --- a/tests/test_diagnostics.py +++ b/tests/test_diagnostics.py @@ -438,6 +438,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]) diff --git a/tests/test_engine.py b/tests/test_engine.py index 8dd5a99c..0bafc43b 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -584,6 +584,76 @@ def test_post_dev_verify_discriminates_a_dev_emit_from_a_fix_emit(project, monke 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("check", 0, "dev", "dev-out", "")], + [verify.CommandResult("check", 1, "commit fail", "", "commit fail")], + [verify.CommandResult("check", 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, @@ -10022,11 +10092,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) From 91594afb3ce2614b7a046620a2db781e130de9b6 Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 00:11:58 -0700 Subject: [PATCH 11/22] docs(plugins): state the dev-phase boundary on command_results (#641) The verify-command-result journal records and the post_dev_verify command_results surface cover the dev phase only. The review gate runs the same [verify] commands through the same core classifier and retains nothing -- no journal record, no hook -- across five engine gates plus the stories and sweep variants. confirm --reverify runs them out of band by construction, having no run journal or hook bus to reach. Left unstated, that gap is the defect in a feature sold as auditability: a plugin would read verify-command-result as a census of a run's verifier invocations, when every story that commits ran the commands at least once more than the records show. Documented rather than closed -- the review leg needs its own hook stage plus a changed return shape on three core verify_review* functions, which is a separate change. Tracked as #656. Also name the boundary at the fixture that pins it: _dev_then_fix_run scripts four verifier returns for two journalled sequences, and the inequality now reads as the boundary rather than a miscount. --- CHANGELOG.md | 3 +++ docs/plugin-authoring-guide.md | 30 ++++++++++++++++++++++++++++++ tests/test_engine.py | 11 +++++++++++ 3 files changed, 44 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index c11812fd..8299b4e0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,9 @@ breaking changes may land in a minor release. 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 diff --git a/docs/plugin-authoring-guide.md b/docs/plugin-authoring-guide.md index 7be249ed..9fcbf904 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -460,6 +460,33 @@ carries the reason. A plugin reading these pointers must therefore treat both 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 | Stage | When | Mutable surface | @@ -470,6 +497,9 @@ or act on it only from an explicitly configured plugin. | `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/tests/test_engine.py b/tests/test_engine.py index 0bafc43b..b9e88d91 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -514,6 +514,17 @@ def _dev_then_fix_run(project, monkeypatch, capture): 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( From f20440d6f3687ba5c58e2a43c257790090fa1c71 Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 00:13:20 -0700 Subject: [PATCH 12/22] test(policy): escape the stream_capture_kb match= pattern match= is a regex, so the unescaped dots matched any character and the assertion passed on a message naming a different key (measured: the old pattern accepts 'verifyXstream_capture_kb', the escaped one rejects it). Every other policy-key assertion in this file already uses the escaped raw-string form. Not a lint fix -- RUF043 is outside the repo's ruff select -- so nothing is ratcheted; this only conforms to the convention the file already keeps. Reported by CodeRabbit. Its second half, applying the same change to core.toml, does not apply: that file is TOML settings, not a regex. --- tests/test_policy.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/test_policy.py b/tests/test_policy.py index 2e565029..8755e6f1 100644 --- a/tests/test_policy.py +++ b/tests/test_policy.py @@ -791,7 +791,7 @@ def test_verify_stream_capture_kb(tmp_path): 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="verify.stream_capture_kb"): + with pytest.raises(policy.PolicyError, match=r"verify\.stream_capture_kb"): policy.load(p) From 96b1beb5c5486e09f459a5b764689aaacce34a74 Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 00:24:44 -0700 Subject: [PATCH 13/22] fix(journal): anchor verify-stream writes against a planted verify/ symlink follow_symlinks=False covers the final component and nothing above it. Sessions are handed the run directory outright (BMAD_LOOP_RUN_DIR, where they write result.json), so a session that plants verify/ as a symlink before verification redirects every verifier record out of the run dir: mkdir(parents=True, exist_ok=True) ACCEPTS a symlink-to-directory -- it re-raises only when is_dir() is false, and that follows links. Measured, both halves: with no guard the same planted link writes into the link target while write_verify_stream returns the pointer 'verify/v.stdout.log', so the file is outside the run dir and the record claims it is inside. Fixed with the primitive the repo already keeps for this exact threat (tui/launch.py writes its control-window record the same way): open_dir_confined walks each component below the run dir O_NOFOLLOW and atomic_write_text_at never names a path again, so a re-plant between check and write renames something this no longer consults. win32 has no *at() family and keeps a check-then-write with the residual documented. Refusal raises OSError, which is the caller's EXISTING degrade path -- the record still lands with a null pointer and capture_error, so this adds no new failure mode. Also repairs a test this silently disarmed: the ENOSPC degrade test patched bmad_loop.journal.atomic_write_text only, which on POSIX now intercepts nothing, so it was passing without ever running the degrade arm. It patches both writers now. The two guards OVERLAP, so ablating the POSIX arm alone reddens only the message; removing BOTH is what reproduces the escape. Recorded in the test docstring so a future reader does not mistake the weaker ablation for the proof. Reported by codex (P1). Reviewed in both directions before acting: all three of its premises reproduce. --- docs/plugin-authoring-guide.md | 4 +- src/bmad_loop/journal.py | 62 ++++++++++++++++++++++--- tests/test_engine.py | 8 +++- tests/test_journal.py | 84 +++++++++++++++++++++++++++++++++- 4 files changed, 148 insertions(+), 10 deletions(-) diff --git a/docs/plugin-authoring-guide.md b/docs/plugin-authoring-guide.md index 9fcbf904..5a8aab9e 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -454,7 +454,9 @@ translation makes the file larger there. Set the knob to `0` to retain nothing a 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), the pointer is null and `capture_error` +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, diff --git a/src/bmad_loop/journal.py b/src/bmad_loop/journal.py index 1c908285..31264fc4 100644 --- a/src/bmad_loop/journal.py +++ b/src/bmad_loop/journal.py @@ -3,12 +3,19 @@ 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, atomic_write_text +from .platform_util import ( + DIR_FD_ANCHORED_WRITES, + atomic_replace, + atomic_write_text, + atomic_write_text_at, + open_dir_confined, +) STATE_FILE = "state.json" JOURNAL_FILE = "journal.jsonl" @@ -86,13 +93,54 @@ def write_verify_stream(self, name: str, content: str) -> str: so the file can be larger there than the count. ``read_text`` normalizes it back, so the content round-trips either way. - Raises ``OSError`` — the caller degrades (this is observation), it does - not swallow it here. + 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 with the residual that implies: 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``. """ - target = self.run_dir / VERIFY_DIR / name - target.parent.mkdir(parents=True, exist_ok=True) - atomic_write_text(target, content, follow_symlinks=False) - return target.relative_to(self.run_dir).as_posix() + 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 verify_dir.is_symlink(): + raise OSError(f"refusing to write into a symlinked 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(): diff --git a/tests/test_engine.py b/tests/test_engine.py index b9e88d91..89e9012d 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -343,10 +343,16 @@ def test_verify_stream_capture_oserror_degrades_instead_of_killing_the_run(proje lambda policy, cwd: [verify.CommandResult("pytest -q", 0, "tail", "out\n", "err\n")], ) - def _enospc(path, text, **kwargs): + 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() diff --git a/tests/test_journal.py b/tests/test_journal.py index ed14c9d9..7e6fec15 100644 --- a/tests/test_journal.py +++ b/tests/test_journal.py @@ -7,8 +7,11 @@ import os +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 +35,82 @@ 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 `verify_dir.is_symlink()` 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"symlinked 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" From 7d926f8d2b08d80066b0bd8f676644b10d038a12 Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 00:33:16 -0700 Subject: [PATCH 14/22] fix(journal): refuse a junctioned verify/ on the win32 fallback too The win32 arm I added last commit checked is_symlink() only, which is False for a DIRECTORY JUNCTION. mklink /J needs no elevation, while a directory symlink needs SeCreateSymbolicLinkPrivilege or Developer Mode -- so the guard covered the privileged half of the escape and left the unprivileged half open, with no race to win. The predicate the repo already keeps for this moves to platform_util as is_link_like(): lstat().st_reparse_tag against the symlink and mount-point tags. Deliberately NOT os.path.isjunction(), which is 3.12+ while requires-python is >=3.11, and deliberately not 'any reparse tag' -- OneDrive placeholders and dedup stubs are reparse points too, and refusing those would stall a legitimate run. events.py and the standalone hook relay keep their own copies on purpose (they run under the HOST interpreter, not this package's), so this adds a third caller rather than refactoring theirs -- untouched code stays untouched. Both new tests ablated, not assumed: dropping the st_reparse_tag arm reddens the platform_util assertion, and pointing the journal guard back at is_symlink() fails the junction test DID NOT RAISE. The junction is simulated with the repo's existing _ReparseStat idiom, since the branch is reachable only on Windows and would otherwise ship unexercised. Reported by codex (P1, second round). --- src/bmad_loop/journal.py | 18 +++++++++---- src/bmad_loop/platform_util.py | 45 +++++++++++++++++++++++++++++++ tests/test_journal.py | 48 ++++++++++++++++++++++++++++++++-- tests/test_platform_util.py | 38 +++++++++++++++++++++++++++ 4 files changed, 142 insertions(+), 7 deletions(-) diff --git a/src/bmad_loop/journal.py b/src/bmad_loop/journal.py index 31264fc4..169517cf 100644 --- a/src/bmad_loop/journal.py +++ b/src/bmad_loop/journal.py @@ -14,6 +14,7 @@ atomic_replace, atomic_write_text, atomic_write_text_at, + is_link_like, open_dir_confined, ) @@ -115,9 +116,16 @@ def write_verify_stream(self, name: str, content: str) -> str: produces. win32 has no ``*at()`` family to anchor against, so it keeps a - check-then-write with the residual that implies: 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. + 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. @@ -137,8 +145,8 @@ def write_verify_stream(self, name: str, content: str) -> str: finally: os.close(dir_fd) else: - if verify_dir.is_symlink(): - raise OSError(f"refusing to write into a symlinked verify directory: {verify_dir}") + 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() diff --git a/src/bmad_loop/platform_util.py b/src/bmad_loop/platform_util.py index d0a7a509..78a4657e 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,50 @@ 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 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/tests/test_journal.py b/tests/test_journal.py index 7e6fec15..d3c78b0d 100644 --- a/tests/test_journal.py +++ b/tests/test_journal.py @@ -6,6 +6,7 @@ from __future__ import annotations import os +import stat import pytest @@ -86,14 +87,14 @@ def test_write_verify_stream_refuses_a_symlinked_verify_directory_on_the_win32_p """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 `verify_dir.is_symlink()` guard and this fails + 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"symlinked verify directory"): + with pytest.raises(OSError, match=r"redirected verify directory"): journal.write_verify_stream("v.stdout.log", "verifier output") assert list(elsewhere.iterdir()) == [] @@ -114,3 +115,46 @@ def test_write_verify_stream_writes_an_ordinary_verify_directory(tmp_path): 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..d660d23a 100644 --- a/tests/test_platform_util.py +++ b/tests/test_platform_util.py @@ -1524,3 +1524,41 @@ 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 From 0e39fc6038ec138c0b7ed988cb32066c4d2d5213 Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 00:57:04 -0700 Subject: [PATCH 15/22] fix(diagnostics): count the verifier stream store in file totals verify/ was absent from _FILE_CATEGORIES, so both the Markdown and JSON diagnose dumps omitted its file count and size. That is the category's exact purpose -- 'we stat them; we never read into output' -- and the store is a plausible candidate for the largest thing 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. A dump that omits it cannot show the retention or disk-usage problem it is the natural place to notice. Registered via the VERIFY_DIR constant rather than a fourth spelling of the literal, so the reporter cannot drift from the writer that creates the directory. diagnostics already imports from .journal, so this adds no dependency edge. The test asserts both halves: the size is counted, and the retained stream contents reach neither renderer. Ablated -- dropping VERIFY_DIR makes the group None, since the is_dir() guard lets an unregistered category vanish silently rather than redden, which is how this was missed in the first place. Reported by codex (P2). --- src/bmad_loop/diagnostics.py | 22 ++++++++++++++++++-- tests/test_diagnostics.py | 39 ++++++++++++++++++++++++++++++++++++ 2 files changed, 59 insertions(+), 2 deletions(-) diff --git a/src/bmad_loop/diagnostics.py b/src/bmad_loop/diagnostics.py index 2723a72f..589a0ab0 100644 --- a/src/bmad_loop/diagnostics.py +++ b/src/bmad_loop/diagnostics.py @@ -49,7 +49,7 @@ 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 # The guard machinery (fail-closed egress self-check + alias-substitution @@ -75,7 +75,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, diff --git a/tests/test_diagnostics.py b/tests/test_diagnostics.py index 03844e36..3c2a9e82 100644 --- a/tests/test_diagnostics.py +++ b/tests/test_diagnostics.py @@ -1051,3 +1051,42 @@ 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) From 1c80f647ef5184a3a107c58fecbe74e69472d5bc Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 01:02:58 -0700 Subject: [PATCH 16/22] test(engine): name a resolvable verifier command in the new fixtures The two post_dev_verify fixtures stubbed run_verify_commands with the command name "check", which resolves nowhere. On POSIX that is harmless: env_fault_reason keys on sh's rc=126/127 and never inspects the name. On Windows _win32_env_fault_reason ALSO does a PATH/file lookup on the leading token, so a FAILING result naming a binary that does not exist classifies as an environment fault (#302 -- an unrunnable command is a silent pass there, not a failure). The run then paused instead of completing and three tests read done=0: test_fix_verification_emits_post_dev_verify_with_command_results test_post_dev_verify_discriminates_a_dev_emit_from_a_fix_emit test_a_critical_session_emits_post_dev_verify_on_both_legs[fix] Only the rc=1 entries tripped it -- the branch is guarded on returncode != 0 -- which is why the failures named 'review fail' and 'commit fail' specifically. Fixed by using "pytest -q", the name every other stub in this file already uses. Reproduced and verified on Linux by calling _win32_env_fault_reason directly: 'check' at rc=1 returns 'check not found on PATH', 'pytest -q' at rc=1 returns None. Caught only by CI: the local suite is Linux, where the branch is unreachable. Windows was green on main at the merged commit, so this was introduced here, not inherited. --- tests/test_engine.py | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/tests/test_engine.py b/tests/test_engine.py index 4aca7358..d55cc003 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -546,10 +546,10 @@ def _dev_then_fix_run(project, monkeypatch, capture): engine._bus = capture calls = iter( [ - [verify.CommandResult("check", 0, "first", "first-out", "")], - [verify.CommandResult("check", 1, "review fail", "", "review fail")], - [verify.CommandResult("check", 0, "fixed", "fixed-out", "")], - [verify.CommandResult("check", 0, "final", "final-out", "")], + [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)) @@ -652,9 +652,9 @@ def test_a_critical_session_emits_post_dev_verify_on_both_legs(project, monkeypa # that routes the story into `_fix_phase`, then the repair session's pass calls = iter( [ - [verify.CommandResult("check", 0, "dev", "dev-out", "")], - [verify.CommandResult("check", 1, "commit fail", "", "commit fail")], - [verify.CommandResult("check", 0, "fix", "fix-out", "")], + [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)) From 75ab65820a0f07da32425a678f286a40512783ef Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 01:48:44 -0700 Subject: [PATCH 17/22] fix(runs): reclaim the verifier stream store when a run is trimmed MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `verify/` was written by every dev-phase verification and reclaimed by nothing. `[verify] stream_capture_kb` defaults to 256 KiB per stream, so a run accumulated up to 512 KiB per verify command per attempt and kept it for as long as the run dir survived — the gap `diagnose` was taught to make visible in 0e39fc60 but that nothing closed. Add VERIFY_DIR to `_HEAVY_RUN_ENTRIES` so `clean` trims it with the worktrees, on the same bargain: a trimmed run is one you can still see and resume, not one you can still re-read every artifact of. Size the reclaim estimate over `heavy_run_entries` rather than `worktrees/` alone. Both are needed and they fail differently — with only the tuple changed, `clean` removes the store and reports freeing 0 bytes. --- CHANGELOG.md | 4 ++- src/bmad_loop/cli.py | 12 ++++--- src/bmad_loop/documents.py | 2 +- src/bmad_loop/runs.py | 36 ++++++++++++++----- tests/test_cleanup.py | 73 +++++++++++++++++++++++++++++++++++++- 5 files changed, 111 insertions(+), 16 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a34b2115..54918393 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -25,7 +25,9 @@ breaking changes may land in a minor release. 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. Retaining a stream is observation, so a failed write (ENOSPC, a read-only run + 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. 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. diff --git a/src/bmad_loop/cli.py b/src/bmad_loop/cli.py index 18b27cd9..f8ceedbf 100644 --- a/src/bmad_loop/cli.py +++ b/src/bmad_loop/cli.py @@ -3458,9 +3458,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 +3492,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 +3506,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/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/runs.py b/src/bmad_loop/runs.py index 1251e23f..a861fe2c 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, @@ -1065,10 +1065,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): @@ -1247,16 +1267,16 @@ def reconcile_orphan_state_dirs(project: Path, *, dry_run: bool = False) -> list 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 + for p in heavy_run_entries(run_dir): if p.exists() or p.is_symlink(): removed.append(p) if not dry_run: diff --git a/tests/test_cleanup.py b/tests/test_cleanup.py index 269a228d..a94a365d 100644 --- a/tests/test_cleanup.py +++ b/tests/test_cleanup.py @@ -6,7 +6,7 @@ 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 +193,42 @@ 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"] + + # ------------------------------------------------------------- cmd_clean @@ -454,6 +490,41 @@ 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 + + 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. From 0dc292832dcfba807fee33f214b3138e5cc73ad9 Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 02:03:27 -0700 Subject: [PATCH 18/22] fix(runs,cli): trim a planted redirect as a link, and never size through one MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Codex P1 on the reclaim path, the mirror image of the write-path escape this branch already closed: a session is handed the writable run dir via BMAD_LOOP_RUN_DIR and can plant a link at `verify/`. `shutil.rmtree` REFUSES a directory symlink by design — following it would delete the target's contents — and `ignore_errors=True` swallows that refusal, so `trim_run_dir` appended the entry to `removed` and left the link untouched. Remove the redirect itself instead: `unlink` for a POSIX symlink and a win32 file symlink, `rmdir` for the win32 directory symlink/junction that `DeleteFileW` rejects and `RemoveDirectoryW` drops without following. The link goes; its target does not. `_dir_size` had the same shape of bug against its own docstring. `os.walk` does not descend into links but does follow the top path it is handed, so sizing a redirected entry billed `clean`'s reclaim estimate for out-of-run bytes still on disk afterwards — measured at exactly the target's size. Refuse a link-like path up front, which is what "symlinks not followed" already claimed. Both use `is_link_like`, not `is_symlink`: a win32 junction is the unprivileged arm of this escape and `is_symlink()` reports False for it. --- src/bmad_loop/cli.py | 13 ++++++-- src/bmad_loop/runs.py | 34 ++++++++++++++++++--- tests/test_cleanup.py | 69 +++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 110 insertions(+), 6 deletions(-) diff --git a/src/bmad_loop/cli.py b/src/bmad_loop/cli.py index f8ceedbf..ada18b16 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, is_link_like, resolve_or_lexical from .process_host import ProcessHostError # The run-composition helpers now live in runsetup.py (the library layer a non-CLI @@ -3372,7 +3372,16 @@ 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`` (symlinks not followed). + + ``os.walk`` does not descend into links, but it DOES follow the top path it + is handed, so the "not followed" contract only holds if a link-like ``path`` + is refused up front. It is not hypothetical here: a session can plant a + redirect at a run-dir entry (`BMAD_LOOP_RUN_DIR` names the writable dir), and + walking it would bill `clean`'s reclaim estimate for bytes that live outside + the run and that the trim provably does not free.""" + if is_link_like(path): + return 0 total = 0 for root, _dirs, files in os.walk(path, onerror=lambda _e: None): for name in files: diff --git a/src/bmad_loop/runs.py b/src/bmad_loop/runs.py index a861fe2c..94fd346e 100644 --- a/src/bmad_loop/runs.py +++ b/src/bmad_loop/runs.py @@ -26,6 +26,7 @@ atomic_write_text, has_parent_ref, is_absolute_path, + is_link_like, retrying_unlink, safe_segment, ) @@ -1266,6 +1267,25 @@ 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 and the retained verifier stream store) from a concluded run dir, preserving its TUI-visible @@ -1277,10 +1297,16 @@ def trim_run_dir(run_dir: Path, *, dry_run: bool = False) -> list[Path]: resumable, so its state dir has to outlive its scaffolding.""" removed: list[Path] = [] for p in heavy_run_entries(run_dir): - if p.exists() or p.is_symlink(): - removed.append(p) - if not dry_run: - shutil.rmtree(p, ignore_errors=True) + 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/tests/test_cleanup.py b/tests/test_cleanup.py index a94a365d..49ffb6ee 100644 --- a/tests/test_cleanup.py +++ b/tests/test_cleanup.py @@ -2,7 +2,9 @@ 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 @@ -229,6 +231,41 @@ def test_trim_run_dir_reclaims_the_verifier_stream_store(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 @@ -525,6 +562,38 @@ def test_cmd_clean_counts_the_verifier_stream_store_it_reclaimed(project, capsys 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. From f722d8a5292b414df92e5a6dbaa749085835554c Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 02:15:47 -0700 Subject: [PATCH 19/22] fix(diagnostics,cli): never let a planted redirect widen a walk MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two more codex P2s, both the same shape as the reclaim-path escape and both reachable only because this branch registered `verify/` as something a session can plant: every other category root and run-dir entry is engine-created. `summarize_files` admitted a category root on `root.is_dir()`, which follows a link, then walked it with `rglob("*")`. Measured: a redirected `verify/` made `diagnose` report an outside tree's 2 files and 3100 bytes as this run's retained verifier output. `_dir_size` refused a link-like TOP but still used a plain `os.walk`, which prunes a symlinked subdirectory via `os.path.islink` — False for a Windows junction. So on win32 a nested junction was descended into, and `clean` could bill `freed_bytes` for a tree it never touches. The junction is the unprivileged arm, so that is the half worth having. Both callers got it wrong identically, so the fix is one helper: `walk_files_unlinked` refuses a link-like top and prunes link-like children with `is_link_like`, not `is_symlink`. The nested arm is invisible on POSIX — `os.walk` prunes symlinks itself — so its test simulates the predicate disagreement that IS the win32 behaviour rather than grading `os.walk`. --- src/bmad_loop/cli.py | 26 ++++++++------------- src/bmad_loop/diagnostics.py | 8 ++++--- src/bmad_loop/platform_util.py | 29 ++++++++++++++++++++++++ tests/test_diagnostics.py | 34 ++++++++++++++++++++++++++++ tests/test_platform_util.py | 41 ++++++++++++++++++++++++++++++++++ 5 files changed, 118 insertions(+), 20 deletions(-) diff --git a/src/bmad_loop/cli.py b/src/bmad_loop/cli.py index ada18b16..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, is_link_like, 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,23 +3372,15 @@ def cmd_cleanup(args: argparse.Namespace) -> int: def _dir_size(path: Path) -> int: - """Best-effort total bytes under ``path`` (symlinks not followed). - - ``os.walk`` does not descend into links, but it DOES follow the top path it - is handed, so the "not followed" contract only holds if a link-like ``path`` - is refused up front. It is not hypothetical here: a session can plant a - redirect at a run-dir entry (`BMAD_LOOP_RUN_DIR` names the writable dir), and - walking it would bill `clean`'s reclaim estimate for bytes that live outside - the run and that the trim provably does not free.""" - if is_link_like(path): - return 0 + """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 diff --git a/src/bmad_loop/diagnostics.py b/src/bmad_loop/diagnostics.py index 589a0ab0..b014ef98 100644 --- a/src/bmad_loop/diagnostics.py +++ b/src/bmad_loop/diagnostics.py @@ -51,6 +51,7 @@ from . import __version__, sanitize 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 @@ -387,9 +388,10 @@ 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 + # 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): count += 1 try: total_bytes += p.stat().st_size diff --git a/src/bmad_loop/platform_util.py b/src/bmad_loop/platform_util.py index 78a4657e..db3f5fde 100644 --- a/src/bmad_loop/platform_util.py +++ b/src/bmad_loop/platform_util.py @@ -634,6 +634,35 @@ def is_link_like(path: Path) -> bool: return False +def walk_files_unlinked(top: Path) -> Iterator[Path]: + """Every regular file under ``top``, never crossing a redirect out of it. + + 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/tests/test_diagnostics.py b/tests/test_diagnostics.py index 3c2a9e82..6f11ac20 100644 --- a/tests/test_diagnostics.py +++ b/tests/test_diagnostics.py @@ -1090,3 +1090,37 @@ def test_verify_streams_are_counted_but_never_read(project, tmp_path): # 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 diff --git a/tests/test_platform_util.py b/tests/test_platform_util.py index d660d23a..5aebc456 100644 --- a/tests/test_platform_util.py +++ b/tests/test_platform_util.py @@ -1562,3 +1562,44 @@ def test_is_link_like_refuses_a_reparse_tagged_dir(tmp_path, monkeypatch): 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)) == [] From 336d5198118e2234d4da5b30f780772036a8be80 Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 08:12:38 -0700 Subject: [PATCH 20/22] fix(verify): bound verifier streams in memory, separately from the disk cap MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Codex P2. `stream_capture_kb` bounds what reaches disk; nothing bounded what was held. `capture_output=True` always materialises one command's whole output, but the full streams were then RETAINED in the results list while every later command ran, so peak memory scaled with the number of configured verify commands rather than with the largest one. Add MAX_STREAM_MEMORY_BYTES (32 MiB per stream), applied at the subprocess boundary on both the normal and timeout legs. It is a constant, not a policy field: plugins are meant to see the streams essentially whole, so this is a backstop against a pathologically chatty suite and not something to tune. The cut must not become a lie. Sizing the journal record off the string still in hand would under-report emission and compute `*_truncated` against a false baseline — calling a cut stream whole, the one thing that flag exists to prevent. CommandResult therefore carries `*_full_bytes`, defaulting to None so every three-field construction stays correct. `byte_tail` is now the single implementation of the tail-slice rule this feature applies at both bounds. Duplicating it would have meant two copies of the subtle half: a byte cut can land mid-character, and decoding the partial with `errors="replace"` would break the very cap it enforces, since U+FFFD is three bytes standing in for the one it replaces. --- CHANGELOG.md | 6 ++- docs/plugin-authoring-guide.md | 12 +++++- src/bmad_loop/engine.py | 17 ++++++--- src/bmad_loop/verify.py | 70 +++++++++++++++++++++++++++++----- tests/test_engine.py | 32 ++++++++++++++++ tests/test_verify.py | 28 ++++++++++++++ 6 files changed, 147 insertions(+), 18 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 54918393..31542f4c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -27,7 +27,11 @@ breaking changes may land in a minor release. 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. Retaining a stream is observation, so a failed write (ENOSPC, a read-only run + 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. diff --git a/docs/plugin-authoring-guide.md b/docs/plugin-authoring-guide.md index 5a8aab9e..b0d19294 100644 --- a/docs/plugin-authoring-guide.md +++ b/docs/plugin-authoring-guide.md @@ -404,8 +404,16 @@ 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. This is observation data only: a plugin cannot change the -verifier's outcome or the commit decision. The run's `journal.jsonl` also records +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 diff --git a/src/bmad_loop/engine.py b/src/bmad_loop/engine.py index 21e6feca..f8921ace 100644 --- a/src/bmad_loop/engine.py +++ b/src/bmad_loop/engine.py @@ -110,11 +110,7 @@ def _bounded_stream_tail(text: str, max_bytes: int) -> tuple[str, int, int]: ``max_bytes <= 0`` needs no branch of its own: the slice is empty by construction, which is exactly "capture nothing". """ - encoded = text.encode("utf-8") - full_bytes = len(encoded) - if full_bytes <= max_bytes: - return text, full_bytes, full_bytes - tail = encoded[full_bytes - max_bytes :].decode("utf-8", errors="ignore") + tail, full_bytes = verify.byte_tail(text, max_bytes) return tail, full_bytes, len(tail.encode("utf-8")) @@ -4205,8 +4201,17 @@ def _journal_verify_command_results( ) streams: dict[str, str | int | bool | None] = {} capture_error: str | None = None - for kind, text in (("stdout", result.stdout), ("stderr", result.stderr)): + 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: diff --git a/src/bmad_loop/verify.py b/src/bmad_loop/verify.py index 86be5e2e..66108629 100644 --- a/src/bmad_loop/verify.py +++ b/src/bmad_loop/verify.py @@ -2513,6 +2513,45 @@ 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. @@ -2521,6 +2560,12 @@ class CommandResult: 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 @@ -2528,6 +2573,8 @@ class CommandResult: 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 @@ -2729,19 +2776,24 @@ def run_verify_commands(policy: Policy, cwd: Path) -> list[CommandResult]: errors="replace", timeout=COMMAND_TIMEOUT_S, ) - output = (proc.stdout + proc.stderr)[-2000:] + 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, proc.stdout, proc.stderr) + 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", - _timeout_stream(exc.stdout), - _timeout_stream(exc.stderr), - ) + CommandResult(command, -1, "timed out", t_out, t_err, t_out_full, t_err_full) ) return results diff --git a/tests/test_engine.py b/tests/test_engine.py index d55cc003..7d01ab71 100644 --- a/tests/test_engine.py +++ b/tests/test_engine.py @@ -252,6 +252,38 @@ def test_verify_stream_capture_retains_a_bounded_tail(project): 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. diff --git a/tests/test_verify.py b/tests/test_verify.py index 6d448bc0..f73890e2 100644 --- a/tests/test_verify.py +++ b/tests/test_verify.py @@ -1536,6 +1536,34 @@ 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.""" From 68703aaad3bad2a4b29cd425274b03a4d2a0e9b3 Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 08:54:08 -0700 Subject: [PATCH 21/22] fix(plugins): deep-copy result_json so a plugin cannot erase a CRITICAL MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `HookContext` copies the session result so plugins observe rather than rewrite it, and the comment at the copy said as much. `dict()` is shallow, though, 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)` — the dev leg via `decide_dev`, the fix leg at the call this branch reordered — so an in-process plugin that cleared that list erased the escalation before the audit ran, and a verify-green repair proceeded where the run owed a pause. Ablation: restore `dict(result_json)` and the new bus test's audit comes back empty, naming the escalation that vanished. --- CHANGELOG.md | 9 +++++++++ src/bmad_loop/plugins/context.py | 15 ++++++++++++--- tests/test_hook_bus.py | 32 ++++++++++++++++++++++++++++++++ 3 files changed, 53 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 31542f4c..190de40b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -116,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/src/bmad_loop/plugins/context.py b/src/bmad_loop/plugins/context.py index 6c189cfb..590ec9ab 100644 --- a/src/bmad_loop/plugins/context.py +++ b/src/bmad_loop/plugins/context.py @@ -20,6 +20,7 @@ from __future__ import annotations +import copy from dataclasses import dataclass from typing import TYPE_CHECKING, Any @@ -115,9 +116,17 @@ 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 diff --git a/tests/test_hook_bus.py b/tests/test_hook_bus.py index 9ad85cb7..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 ( @@ -109,6 +110,37 @@ def test_command_results_are_readonly_observation_data(): 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): From 9533ab63e61a639c376edb219454e66b3e1c5e38 Mon Sep 17 00:00:00 2001 From: t Date: Wed, 19 Aug 2026 08:54:20 -0700 Subject: [PATCH 22/22] fix(diagnostics): never open a non-regular file the walk hands back MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `f722d8a5` swapped `rglob("*")` for `walk_files_unlinked` to stop a planted redirect widening the walk, and dropped the `is_file()` guard the old loop carried: `os.walk` puts every non-directory entry in `files`, FIFOs and symlinks included. The `logs` arm OPENS what it counts, so a FIFO a session planted in its own run directory — the dir is exported as `BMAD_LOOP_RUN_DIR` — blocked `diagnose` forever, and a symlinked entry was billed to this run. The inventory filters on `lstat` + `S_ISREG` (not `is_file()`, which follows and answers about the target), and the line count moves to `_count_lines`, which anchors on the descriptor the way `runs.read_trusted_config_digest` and `tui.launch._read_ctl_window` already do for the same hazard: `O_NONBLOCK` so a FIFO cannot block the open, `S_ISREG` on the fd because a path check before the open is a race on a directory the session can write, and `O_NOFOLLOW` so the final component cannot redirect the read out of the run. `walk_files_unlinked`'s docstring no longer promises regular files — that false claim is what made the swap look safe. Four ablation axes, each reddening exactly one of the four new tests: O_NONBLOCK (alarm fires), fd S_ISREG (counts 3 piped lines and drains the pipe), O_NOFOLLOW (returns the target's 2 lines), inventory S_ISREG (the group reports 3 files instead of 1). --- src/bmad_loop/diagnostics.py | 56 ++++++++++++-- src/bmad_loop/platform_util.py | 10 ++- tests/test_diagnostics.py | 131 +++++++++++++++++++++++++++++++++ 3 files changed, 188 insertions(+), 9 deletions(-) diff --git a/src/bmad_loop/diagnostics.py b/src/bmad_loop/diagnostics.py index b014ef98..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 @@ -373,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. @@ -392,17 +426,23 @@ def summarize_files(run_dir: Path, *, events_dir: Path | None = None) -> list[Fi # 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): - count += 1 + # 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/platform_util.py b/src/bmad_loop/platform_util.py index db3f5fde..619b8f72 100644 --- a/src/bmad_loop/platform_util.py +++ b/src/bmad_loop/platform_util.py @@ -635,7 +635,15 @@ def is_link_like(path: Path) -> bool: def walk_files_unlinked(top: Path) -> Iterator[Path]: - """Every regular file under ``top``, never crossing a redirect out of it. + """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: diff --git a/tests/test_diagnostics.py b/tests/test_diagnostics.py index 6f11ac20..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 @@ -1124,3 +1125,133 @@ def test_a_redirected_verify_root_is_not_counted_as_this_runs_output(project, tm 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)