From 319816717bb44d92bf4a8d6551dfef79aab9f5bc Mon Sep 17 00:00:00 2001 From: Yash-1511 Date: Mon, 15 Jun 2026 18:59:26 +0530 Subject: [PATCH] fix(stop-hooks): add circuit breaker to stop the orchestrator runaway (#29) The story-automator Stop hook read its stdin and discarded it, so it never inspected `stop_hook_active` and blocked unconditionally while stories remained. On a long-lived/resumed orchestrator this fought Claude Code's "go idle, get woken on completion" model: every stop attempt was re-blocked until the harness force-ended the turn at CLAUDE_CODE_STOP_HOOK_BLOCK_CAP, and each empty "Holding" turn replayed the whole growing transcript. Issue #29 measured the result: 1,599 turns / 478M cache_read tokens in one resumed session, a 5-hour quota window burned in ~30 minutes. Fixes: 1. Stop-hook circuit breaker (commands/basic.py): parse the hook input, honor `stop_hook_active`, and count consecutive blocks WITHOUT step progress in the marker. After STORY_AUTOMATOR_MAX_STOP_BLOCKS (default 5, below the harness cap of 9) release the stop with a systemMessage instead of busy-waiting. Progress = a story completed or the marker heartbeat bumped at a verified step (wired into step-03-execute.md). 2. Reload anti-polling guidance on resume: add monitoring-pattern.md to the LOAD-ONCE set in data-file-index.md and mandate reading it in step-03-execute.md and step-01b-continue.md before any tmux interaction, so a Stop-hook resume cannot improvise per-turn cat/capture-pane polling. 3. Cost ceiling in stop-hook-recovery.md: replace unbounded "do whatever it takes" with an explicit ceiling and forbidden-polling decision rows. 4. Tighten the false-complete contract (commands/tmux.py): monitor-session re-confirms a completed-but-unverified session in-process up to --completion-rechecks (default 3) before returning `incomplete`, absorbing false-completes inside the single blocking call. A broken verifier contract still returns immediately so it escalates. Adds tests for the circuit breaker (test_stop_hooks.py) and the monitor-session re-poll (test_monitor_session.py). --- .../data/data-file-index.md | 3 +- .../data/monitoring-pattern.md | 14 +- .../data/stop-hook-recovery.md | 38 +++++- .../src/story_automator/commands/basic.py | 85 +++++++++++- .../src/story_automator/commands/tmux.py | 36 +++++- .../steps-c/step-01b-continue.md | 6 + .../steps-c/step-03-execute.md | 16 +++ tests/test_monitor_session.py | 122 ++++++++++++++++++ tests/test_stop_hooks.py | 121 +++++++++++++++++ 9 files changed, 429 insertions(+), 12 deletions(-) create mode 100644 tests/test_monitor_session.py diff --git a/skills/bmad-story-automator/data/data-file-index.md b/skills/bmad-story-automator/data/data-file-index.md index 375d69fb..1de806c1 100644 --- a/skills/bmad-story-automator/data/data-file-index.md +++ b/skills/bmad-story-automator/data/data-file-index.md @@ -20,6 +20,7 @@ |------|-----| | `orchestrator-rules.md` | Core rules for orchestrator behavior | | `execution-patterns.md` | FORBIDDEN patterns - must know before any execution | +| `monitoring-pattern.md` | FORBIDDEN polling patterns + single-call spawn/monitor/verify cycle — MUST be in context before any tmux interaction (issue #29) | | `scripts-reference.md` | Script usage patterns | ### LOAD ON TRIGGER @@ -60,7 +61,7 @@ ``` Starting execution? - → Load: orchestrator-rules.md, execution-patterns.md, scripts-reference.md + → Load: orchestrator-rules.md, execution-patterns.md, monitoring-pattern.md, scripts-reference.md Step failed? → Load: retry-fallback-strategy.md diff --git a/skills/bmad-story-automator/data/monitoring-pattern.md b/skills/bmad-story-automator/data/monitoring-pattern.md index cfa8441f..0d716c2d 100644 --- a/skills/bmad-story-automator/data/monitoring-pattern.md +++ b/skills/bmad-story-automator/data/monitoring-pattern.md @@ -80,10 +80,14 @@ verified=$(echo "$validation" | jq -r '.verified') "$scripts" monitor-session [options] # Options: -# --max-polls N Maximum iterations (default: 30) -# --timeout MIN Overall timeout in minutes (default: 60) -# --verbose Print progress to stderr -# --json Output as JSON instead of CSV +# --max-polls N Maximum iterations (default: 30) +# --timeout MIN Overall timeout in minutes (default: 60) +# --completion-rechecks N Re-confirm a "completed-but-unverified" session +# N times in-process before returning `incomplete` +# (default: 3). Absorbs false-completes inside this +# single call so you never hand-poll. +# --verbose Print progress to stderr +# --json Output as JSON instead of CSV # Output (JSON): # {"final_state":"completed|crashed|stuck|timeout|incomplete|not_found","output_file":"/tmp/...","exit_reason":"..."} @@ -123,7 +127,7 @@ After `$scripts monitor-session` returns: | final_state | Action | |-------------|--------| | `completed` | Run step verifier or parser for the active workflow | -| `incomplete` | **(v2.2)** Session idle but workflow NOT verified → Escalate immediately | +| `incomplete` | Session idle but workflow NOT verified, even after in-process rechecks → **re-spawn `monitor-session` once** (one blocking call). If a second `incomplete` comes back, escalate. **NEVER** `cat` the output file or `tmux capture-pane` in a fresh turn to "wait" — that is the forbidden polling loop (issue #29). | | `crashed` | Check retry count → retry or escalate | | `stuck` | Get output → investigate → may need restart | | `timeout` | Get output → escalate to user | diff --git a/skills/bmad-story-automator/data/stop-hook-recovery.md b/skills/bmad-story-automator/data/stop-hook-recovery.md index f45fa35c..91dc9764 100644 --- a/skills/bmad-story-automator/data/stop-hook-recovery.md +++ b/skills/bmad-story-automator/data/stop-hook-recovery.md @@ -20,6 +20,34 @@ | Unrecoverable error (all retries exhausted) | **STOP** → Follow stop procedure below | Cannot proceed without intervention | | External dependency down (API, service) | **RETRY** → Sleep with increasing delay (1m, 2m, 4m, 8m, 16m), max 5 attempts | Often recovers on its own | | User explicitly requested stop earlier | **STOP** → Follow stop procedure below | Honoring user intent | +| **You are about to "check" an in-flight session in a new turn** | **STOP** → Do NOT poll. Re-spawn `monitor-session` (one blocking call) instead | Per-turn polling is the #1 cost runaway (issue #29) | +| **This is the Nth resume in a row with no step progress** | **STOP** → Let the circuit breaker release; document why the step isn't progressing | A wait that isn't advancing is not "do whatever it takes" — it's a loop | + +--- + +## 🚨 Cost Ceiling — "do whatever it takes" has a limit + +"Continue" does NOT mean "burn an entire quota window busy-waiting." The Stop hook now +has a **circuit breaker**: after `STORY_AUTOMATOR_MAX_STOP_BLOCKS` (default **5**) +consecutive blocks with **no step progress** (no story completed, no marker heartbeat +bumped), it stops blocking and releases the session with a `systemMessage`. This is by +design — a long-lived orchestrator stopping-and-resuming in fresh LLM turns replays its +entire (growing) transcript every turn, so an idle busy-wait can cost thousands of dollars +of cache-read with zero work done (issue #29: 1,599 turns / 478M cache-read tokens). + +**To stay productive — and keep the breaker from tripping on a healthy long run — you MUST:** + +1. **Wait with ONE blocking `monitor-session` call.** While that single Bash call runs, you + take no turns and pay nothing. NEVER re-read its output file, `tmux capture-pane`, or + `tmux-status-check` in a separate turn to see "is it done yet." That per-turn polling is + forbidden (see `monitoring-pattern.md`). +2. **On a verified step, the orchestrator bumps the marker heartbeat** (`orchestrator-helper + marker heartbeat`). That heartbeat is what tells the breaker "real progress happened, + reset the counter." If you are doing real work, progress advances and the breaker never + fires. If the breaker fires, it means you were looping without progress — that is the bug + it exists to stop. +3. **If `monitor-session` returns without a verified artifact, re-spawn it** (one more + blocking call) — do not hand-poll. See the Decision Flow in `monitoring-pattern.md`. --- @@ -69,9 +97,13 @@ The stop hook fires when Claude pauses, not just when explicitly stopping. ## Core Principle -**Your job is to finish every story in the correct order.** +**Your job is to finish every story in the correct order — efficiently.** -Do whatever it takes. Make autonomous decisions. Only stop when genuinely unrecoverable (all retries exhausted, user explicitly requested stop). +Make autonomous decisions and keep moving. "Do whatever it takes" means *make progress*, +not *spin in place*: a turn that neither advances a step nor waits inside a single blocking +call is wasted, and enough of them trip the cost ceiling above. Stop when genuinely +unrecoverable (all retries exhausted, user explicitly requested stop) **or** when the +circuit breaker releases you because the active step has stalled without progress. --- @@ -85,3 +117,5 @@ Do whatever it takes. Make autonomous decisions. Only stop when genuinely unreco | Waiting for user at decision points | Decide autonomously, keep moving | | Stopping on first API/service failure | Retry with exponential backoff (5 attempts) | | Asking user which path to take | Pick the path that finishes stories in order | +| `cat`-ing a monitor output file / `tmux capture-pane` in a new turn to check progress | Wait inside ONE `monitor-session` call; re-spawn it if it returns early | +| Treating the Stop hook firing as "poll again" | The hook is a guard, not a clock — make progress or wait in a single call, don't busy-loop | diff --git a/skills/bmad-story-automator/src/story_automator/commands/basic.py b/skills/bmad-story-automator/src/story_automator/commands/basic.py index 3869f8ea..e646311d 100644 --- a/skills/bmad-story-automator/src/story_automator/commands/basic.py +++ b/skills/bmad-story-automator/src/story_automator/commands/basic.py @@ -10,6 +10,7 @@ from ..core.runtime_layout import active_marker_path, runtime_provider from ..core.stop_hooks import HookConfigError, ensure_stop_hook from ..core.utils import ( + atomic_write, get_project_slug, run_cmd, write_json, @@ -140,10 +141,36 @@ def cmd_ensure_stop_hook(args: list[str]) -> int: return 0 +DEFAULT_MAX_STOP_BLOCKS = 5 + + +def _max_stop_blocks() -> int: + """Consecutive no-progress Stop-hook blocks before the circuit breaker releases. + + Kept below Claude Code's own ``CLAUDE_CODE_STOP_HOOK_BLOCK_CAP`` (defaults to + 9) so the orchestrator releases gracefully with an explanation instead of the + harness force-ending the turn after a runaway busy-wait. See + ``data/stop-hook-recovery.md`` and issue #29. + """ + raw = os.environ.get("STORY_AUTOMATOR_MAX_STOP_BLOCKS", "").strip() + if raw.isdigit() and int(raw) > 0: + return int(raw) + return DEFAULT_MAX_STOP_BLOCKS + + def cmd_stop_hook(_: list[str]) -> int: - sys.stdin.read() + raw_input = sys.stdin.read() if os.environ.get("STORY_AUTOMATOR_CHILD", "").lower() == "true": return 0 + try: + hook_input = json.loads(raw_input) if raw_input.strip() else {} + except json.JSONDecodeError: + hook_input = {} + # Claude Code sets ``stop_hook_active`` when this stop only happened because a + # prior Stop hook blocked it (i.e. we are inside a continuation loop). The + # documented guard against infinite Stop-hook loops keys off this flag. + stop_hook_active = bool(hook_input.get("stop_hook_active")) + marker = active_marker_path() if not marker.exists(): return 0 @@ -151,11 +178,56 @@ def cmd_stop_hook(_: list[str]) -> int: payload = json.loads(marker.read_text()) except json.JSONDecodeError: return 0 + if not isinstance(payload, dict): + return 0 remaining = payload.get("storiesRemaining", 0) if isinstance(remaining, str) and remaining.isdigit(): remaining = int(remaining) - if not remaining: + if not isinstance(remaining, int) or not remaining: return 0 + + # --- Circuit breaker ------------------------------------------------- + # Count consecutive blocks that the orchestrator survived WITHOUT making + # real progress, so a long-lived session can't busy-wait an entire quota + # window away by stopping-and-resuming in fresh LLM turns (issue #29). + # + # "Progress" = a story completed (storiesRemaining decreased) OR the + # orchestrator bumped the marker heartbeat at a verified step. A healthy + # blocking ``monitor-session`` wait makes no stop attempts at all, so it + # never accrues blocks; only turn-by-turn polling does. + seen_heartbeat = payload.get("stopHookSeenHeartbeat") + seen_remaining = payload.get("stopHookSeenRemaining") + current_heartbeat = payload.get("heartbeat") + progressed = current_heartbeat != seen_heartbeat or ( + isinstance(seen_remaining, int) and remaining < seen_remaining + ) + if progressed or not stop_hook_active: + blocks = 0 + else: + prev = payload.get("stopHookBlocks", 0) + blocks = (prev + 1) if isinstance(prev, int) else 1 + + payload["stopHookSeenHeartbeat"] = current_heartbeat + payload["stopHookSeenRemaining"] = remaining + + if blocks >= _max_stop_blocks(): + # Release: allow the stop so the session goes idle instead of burning + # turns. Reset the counter so a manual/background-triggered resume + # starts clean. The user sees why via systemMessage. + payload["stopHookBlocks"] = 0 + _write_marker(marker, payload) + message = ( + f"Story Automator auto-paused after {blocks} consecutive stop-hook blocks " + f"with no step progress (circuit breaker). {remaining} stories remain. " + "This guards against runaway LLM-turn polling — see " + f"{_workflow_doc_relative('stop-hook-recovery.md')}. " + "Resume the orchestrator to continue, or investigate why the active step is not progressing." + ) + print(json.dumps({"systemMessage": message}, indent=2)) + return 0 + + payload["stopHookBlocks"] = blocks + _write_marker(marker, payload) reason = ( "Story Automator active " f"({remaining} stories remaining). Read " @@ -165,6 +237,15 @@ def cmd_stop_hook(_: list[str]) -> int: return 0 +def _write_marker(path: Path, payload: dict[str, object]) -> None: + try: + atomic_write(path, json.dumps(payload, indent=2) + "\n") + except OSError: + # A marker we cannot persist must never crash the Stop hook; the + # breaker simply won't advance this cycle. + pass + + def cmd_commit_story(args: list[str]) -> int: repo = "" story = "" diff --git a/skills/bmad-story-automator/src/story_automator/commands/tmux.py b/skills/bmad-story-automator/src/story_automator/commands/tmux.py index 1d62e10c..47326d8d 100644 --- a/skills/bmad-story-automator/src/story_automator/commands/tmux.py +++ b/skills/bmad-story-automator/src/story_automator/commands/tmux.py @@ -29,6 +29,14 @@ project_slug, ) +# When tmux reports a session "completed" but the workflow verifier still says +# the artifact isn't there, the pane is often just idle mid-tool-call (a +# false-complete). Rather than bounce an ``incomplete`` that the orchestrator +# then hand-polls in fresh LLM turns (issue #29), re-confirm in-process a few +# times inside the same blocking call before giving up. +COMPLETION_RECHECKS = 3 +RECHECK_GRACE_SECONDS = 15 + def cmd_tmux_wrapper(args: list[str]) -> int: if not args: @@ -285,12 +293,13 @@ def cmd_monitor_session(args: list[str]) -> int: return 1 if args[0] in {"--help", "-h"}: print("Usage: monitor-session [options]") - print("Options: --max-polls N --initial-wait N --project-root PATH --timeout MIN --verbose --json --agent TYPE --workflow TYPE --story-key KEY --state-file PATH") + print("Options: --max-polls N --initial-wait N --project-root PATH --timeout MIN --completion-rechecks N --verbose --json --agent TYPE --workflow TYPE --story-key KEY --state-file PATH") return 0 session = args[0] max_polls = 30 initial_wait = 5 timeout_minutes = 60 + completion_rechecks = COMPLETION_RECHECKS json_output = False workflow = "dev" story_key = "" @@ -312,6 +321,10 @@ def cmd_monitor_session(args: list[str]) -> int: timeout_minutes = int(args[idx + 1]) idx += 2 continue + if arg == "--completion-rechecks" and idx + 1 < len(args): + completion_rechecks = max(0, int(args[idx + 1])) + idx += 2 + continue if arg == "--json": json_output = True elif arg == "--agent" and idx + 1 < len(args): @@ -346,6 +359,7 @@ def cmd_monitor_session(args: list[str]) -> int: start = time.time() last_done = 0 last_total = 0 + unverified_completions = 0 for _ in range(1, max_polls + 1): if time.time() - start >= timeout_minutes * 60: return _emit_monitor(json_output, "timeout", last_done, last_total, "", f"exceeded_{timeout_minutes}m") @@ -354,6 +368,10 @@ def cmd_monitor_session(args: list[str]) -> int: last_done = int(status["todos_done"]) last_total = int(status["todos_total"]) state = str(status["session_state"]) + if state != "completed": + # Session is active again (or never idle): any earlier false-complete + # is void — reset the recheck counter. + unverified_completions = 0 if state == "completed": output = session_status(session, full=True, codex=agent == "codex", project_root=project_root, mode=runtime_mode())["active_task"] verification = _verify_monitor_completion( @@ -376,13 +394,27 @@ def cmd_monitor_session(args: list[str]) -> int: reason, output_verified=bool(verified.get("verified")), ) + reason = str(verified.get("reason") or "workflow_not_verified") + unverified_completions += 1 + # A broken verifier CONTRACT won't fix itself by waiting — surface + # it immediately so the orchestrator escalates. Only re-poll the + # genuine false-complete case (pane idle mid-tool-call, artifact + # not written yet). + if reason != "verifier_contract_invalid" and unverified_completions < completion_rechecks: + # Re-confirm in-process instead of returning an `incomplete` + # the orchestrator would hand-poll. Stays inside this one call. + remaining_time = timeout_minutes * 60 - (time.time() - start) + if remaining_time <= 0: + return _emit_monitor(json_output, "timeout", last_done, last_total, str(output), f"exceeded_{timeout_minutes}m") + time.sleep(min(RECHECK_GRACE_SECONDS, max(1, int(remaining_time)))) + continue return _emit_monitor( json_output, "incomplete", last_done, last_total, str(output), - str(verified.get("reason") or "workflow_not_verified"), + reason, output_verified=bool(verified.get("verified")), ) return _emit_monitor(json_output, "completed", last_done, last_total, str(output), "normal_completion") diff --git a/skills/bmad-story-automator/steps-c/step-01b-continue.md b/skills/bmad-story-automator/steps-c/step-01b-continue.md index 2f839fc4..79d9f806 100644 --- a/skills/bmad-story-automator/steps-c/step-01b-continue.md +++ b/skills/bmad-story-automator/steps-c/step-01b-continue.md @@ -209,6 +209,12 @@ marker_entry=$(echo "$marker_info" | jq -r '.entry') --project-slug "$project_slug" --pid "$$" --heartbeat "{timestamp}" ``` +**🚨 BEFORE routing into any execution step, load `../data/monitoring-pattern.md` and +`../data/execution-patterns.md` into context.** A Stop-hook resume re-enters mid-run with +none of the execution guidance loaded; without the FORBIDDEN-polling table the orchestrator +improvises per-turn `cat`/`tmux capture-pane` polling and burns a quota window (issue #29). +This is mandatory on the resume path, not optional. + **Then** route per Menu Handling Logic in section 5 above. --- diff --git a/skills/bmad-story-automator/steps-c/step-03-execute.md b/skills/bmad-story-automator/steps-c/step-03-execute.md index b7df134b..f3f6ad58 100644 --- a/skills/bmad-story-automator/steps-c/step-03-execute.md +++ b/skills/bmad-story-automator/steps-c/step-03-execute.md @@ -71,8 +71,19 @@ state_file="{outputFile}" - REQUIRED patterns (verify state after each step) - Monitoring failure fallback sequence +**ALSO read `../data/monitoring-pattern.md` BEFORE any tmux interaction.** It carries +the FORBIDDEN polling table and the single-API-call spawn→monitor→verify cycle. Skipping +it is how a Stop-hook resume drifts into per-turn `cat /tmp/*.json` / `tmux capture-pane` +polling that torches a quota window (issue #29). Do NOT spawn or poll any session until it +is in context. + **Key rule:** Each step (create/dev/auto/review) MUST be executed and monitored separately. NEVER chain steps in loops. +**Waiting rule:** A session is waited on by ONE blocking `monitor-session` call. NEVER +re-read a monitor output file, `tmux capture-pane`, or `tmux-status-check` in a fresh LLM +turn to "check if it's done yet" — that is the forbidden polling pattern. If a wait returns +without a verified artifact, re-spawn `monitor-session` (one call), don't poll by hand. + ## Story Loop > **⚠️ SPAWN PATTERN - READ THIS:** @@ -150,6 +161,9 @@ validation=$("$scripts" orchestrator-helper verify-step create {story_id} --stat # Update Story Progress: mark create-story done tmp_state=$(mktemp) sed "s/^| ${story_id} |.*$/| ${story_id} | done | - | - | - | - | in-progress |/" "$state_file" > "$tmp_state" && mv "$tmp_state" "$state_file" + # Heartbeat on real progress: resets the Stop-hook circuit breaker so long + # stories never trip it (see data/stop-hook-recovery.md). REQUIRED. + "$scripts" orchestrator-helper marker heartbeat >/dev/null ``` → proceed to B - If `validation.verified == false` AND attempts < 5 → retry with next agent (see `{retryStrategy}`) @@ -192,6 +206,8 @@ reasons=$(echo "$parsed" | jq -c '.reasons // []') # Update Story Progress: mark dev-story done tmp_state=$(mktemp) sed "s/^| ${story_id} |.*$/| ${story_id} | done | done | - | - | - | in-progress |/" "$state_file" > "$tmp_state" && mv "$tmp_state" "$state_file" + # Heartbeat on real progress: resets the Stop-hook circuit breaker. REQUIRED. + "$scripts" orchestrator-helper marker heartbeat >/dev/null ``` → proceed to C (next step) - If `next_action == "retry"` OR `result.final_state == "crashed"`: diff --git a/tests/test_monitor_session.py b/tests/test_monitor_session.py new file mode 100644 index 00000000..614256ff --- /dev/null +++ b/tests/test_monitor_session.py @@ -0,0 +1,122 @@ +from __future__ import annotations + +import io +import json +import unittest +from contextlib import redirect_stdout +from unittest.mock import patch + +from story_automator.commands import tmux as tmux_cmd +from story_automator.commands.tmux import cmd_monitor_session + + +def _completed_status(output_file: str = "/tmp/out.txt") -> dict[str, object]: + return { + "status": "idle", + "todos_done": 0, + "todos_total": 0, + "active_task": output_file, + "wait_estimate": 0, + "session_state": "completed", + } + + +def _active_status() -> dict[str, object]: + return { + "status": "active", + "todos_done": 1, + "todos_total": 3, + "active_task": "working", + "wait_estimate": 5, + "session_state": "in_progress", + } + + +class MonitorSessionRepollTests(unittest.TestCase): + """The false-complete contract: re-confirm in-process instead of bouncing + an ``incomplete`` the orchestrator would hand-poll (issue #29).""" + + def _run(self, *extra_args: str) -> dict[str, object]: + stdout = io.StringIO() + args = ["sess", "--agent", "claude", "--initial-wait", "0", "--json", "--workflow", "create", *extra_args] + with ( + patch.object(tmux_cmd, "_resolve_agent_selection", return_value="claude"), + patch.object(tmux_cmd, "runtime_mode", return_value="runner"), + patch.object(tmux_cmd.time, "sleep", return_value=None), + redirect_stdout(stdout), + ): + code = cmd_monitor_session(args) + self.assertEqual(code, 0) + return json.loads(stdout.getvalue().strip().splitlines()[-1]) + + def test_verified_completion_returns_immediately(self) -> None: + verify = patch.object( + tmux_cmd, + "_verify_monitor_completion", + return_value=({"verified": True}, "story_create"), + ) + with patch.object(tmux_cmd, "session_status", return_value=_completed_status()), verify as verify_mock: + payload = self._run() + self.assertEqual(payload["final_state"], "completed") + self.assertTrue(payload["output_verified"]) + self.assertEqual(verify_mock.call_count, 1) + + def test_false_complete_rechecks_then_incomplete(self) -> None: + verify = patch.object( + tmux_cmd, + "_verify_monitor_completion", + return_value=({"verified": False, "reason": "story_missing"}, "story_create"), + ) + with patch.object(tmux_cmd, "session_status", return_value=_completed_status()), verify as verify_mock: + payload = self._run() # default completion_rechecks == 3 + self.assertEqual(payload["final_state"], "incomplete") + self.assertEqual(payload["exit_reason"], "story_missing") + # Re-confirmed in-process 3 times before giving up — never bounced early. + self.assertEqual(verify_mock.call_count, 3) + + def test_recheck_recovers_when_verifier_passes(self) -> None: + verify = patch.object( + tmux_cmd, + "_verify_monitor_completion", + side_effect=[ + ({"verified": False, "reason": "not_yet"}, "story_create"), + ({"verified": True}, "story_create"), + ], + ) + with patch.object(tmux_cmd, "session_status", return_value=_completed_status()), verify as verify_mock: + payload = self._run() + self.assertEqual(payload["final_state"], "completed") + self.assertTrue(payload["output_verified"]) + self.assertEqual(verify_mock.call_count, 2) + + def test_completion_rechecks_one_disables_repoll(self) -> None: + verify = patch.object( + tmux_cmd, + "_verify_monitor_completion", + return_value=({"verified": False, "reason": "story_missing"}, "story_create"), + ) + with patch.object(tmux_cmd, "session_status", return_value=_completed_status()), verify as verify_mock: + payload = self._run("--completion-rechecks", "1") + self.assertEqual(payload["final_state"], "incomplete") + self.assertEqual(verify_mock.call_count, 1) + + def test_false_complete_void_when_session_resumes_activity(self) -> None: + # completed(unverified) -> active again -> completed(verified): the + # transient idle must not count toward the recheck budget. + statuses = [_completed_status(), _completed_status(), _active_status(), _completed_status(), _completed_status()] + verify = patch.object( + tmux_cmd, + "_verify_monitor_completion", + side_effect=[ + ({"verified": False, "reason": "not_yet"}, "story_create"), + ({"verified": True}, "story_create"), + ], + ) + with patch.object(tmux_cmd, "session_status", side_effect=statuses), verify: + payload = self._run() + self.assertEqual(payload["final_state"], "completed") + self.assertTrue(payload["output_verified"]) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_stop_hooks.py b/tests/test_stop_hooks.py index a27513b9..9a4a3148 100644 --- a/tests/test_stop_hooks.py +++ b/tests/test_stop_hooks.py @@ -595,6 +595,127 @@ def test_ensure_stop_hook_codex_reports_invalid_config_toml(self) -> None: self.assertEqual((codex_dir / "config.toml").read_text(encoding="utf-8"), "[features\n") self.assertFalse((codex_dir / "hooks.json").exists()) + # --- Circuit breaker (issue #29) ------------------------------------ + + def _stop_hook_marker(self) -> Path: + return self.project_root / ".story-automator-active" + + def _write_active_marker(self, **fields: object) -> None: + payload: dict[str, object] = {"storiesRemaining": 3} + payload.update(fields) + self._stop_hook_marker().write_text(json.dumps(payload), encoding="utf-8") + + def _bump_marker(self, **fields: object) -> None: + marker = json.loads(self._stop_hook_marker().read_text(encoding="utf-8")) + marker.update(fields) + self._stop_hook_marker().write_text(json.dumps(marker), encoding="utf-8") + + def _invoke_stop_hook( + self, + *, + stop_hook_active: bool, + max_blocks: int | None = None, + ) -> tuple[dict[str, object] | None, dict[str, object]]: + stdout = io.StringIO() + env = { + "PROJECT_ROOT": str(self.project_root), + "STORY_AUTOMATOR_ACTIVE_MARKER": str(self._stop_hook_marker()), + } + if max_blocks is not None: + env["STORY_AUTOMATOR_MAX_STOP_BLOCKS"] = str(max_blocks) + stdin_payload = json.dumps({"stop_hook_active": stop_hook_active}) + with ( + patch.dict(os.environ, env, clear=False), + patch("story_automator.commands.basic.sys.stdin", io.StringIO(stdin_payload)), + patch("os.getcwd", return_value=str(self.project_root)), + redirect_stdout(stdout), + ): + code = cmd_stop_hook([]) + self.assertEqual(code, 0) + raw = stdout.getvalue().strip() + parsed = json.loads(raw) if raw else None + marker = json.loads(self._stop_hook_marker().read_text(encoding="utf-8")) + return parsed, marker + + def test_stop_hook_allows_stop_without_marker(self) -> None: + stdout = io.StringIO() + env = { + "PROJECT_ROOT": str(self.project_root), + "STORY_AUTOMATOR_ACTIVE_MARKER": str(self._stop_hook_marker()), + } + with ( + patch.dict(os.environ, env, clear=False), + patch("story_automator.commands.basic.sys.stdin", io.StringIO("{}")), + patch("os.getcwd", return_value=str(self.project_root)), + redirect_stdout(stdout), + ): + code = cmd_stop_hook([]) + self.assertEqual(code, 0) + self.assertEqual(stdout.getvalue().strip(), "") + + def test_stop_hook_blocks_when_stories_remain(self) -> None: + self._write_active_marker(storiesRemaining=2) + out, marker = self._invoke_stop_hook(stop_hook_active=False) + assert out is not None + self.assertEqual(out["decision"], "block") + self.assertIn("2 stories remaining", out["reason"]) + self.assertEqual(marker["stopHookBlocks"], 0) + + def test_stop_hook_circuit_breaker_releases_after_cap(self) -> None: + self._write_active_marker(storiesRemaining=2) + out1, marker1 = self._invoke_stop_hook(stop_hook_active=True, max_blocks=3) + assert out1 is not None + self.assertEqual(out1["decision"], "block") + self.assertEqual(marker1["stopHookBlocks"], 1) + + out2, marker2 = self._invoke_stop_hook(stop_hook_active=True, max_blocks=3) + assert out2 is not None + self.assertEqual(out2["decision"], "block") + self.assertEqual(marker2["stopHookBlocks"], 2) + + out3, marker3 = self._invoke_stop_hook(stop_hook_active=True, max_blocks=3) + assert out3 is not None + self.assertNotIn("decision", out3) + self.assertIn("systemMessage", out3) + self.assertIn("circuit breaker", out3["systemMessage"]) + self.assertEqual(marker3["stopHookBlocks"], 0) + + def test_stop_hook_resets_blocks_on_heartbeat_progress(self) -> None: + self._write_active_marker(storiesRemaining=2, heartbeat="t0") + # First call establishes the heartbeat baseline (counts as progress). + self._invoke_stop_hook(stop_hook_active=True, max_blocks=5) + _, marker2 = self._invoke_stop_hook(stop_hook_active=True, max_blocks=5) + self.assertEqual(marker2["stopHookBlocks"], 1) + + self._bump_marker(heartbeat="t1") # orchestrator made real progress + out3, marker3 = self._invoke_stop_hook(stop_hook_active=True, max_blocks=5) + assert out3 is not None + self.assertEqual(out3["decision"], "block") + self.assertEqual(marker3["stopHookBlocks"], 0) + + def test_stop_hook_resets_blocks_when_not_stop_hook_active(self) -> None: + self._write_active_marker(storiesRemaining=2) + self._invoke_stop_hook(stop_hook_active=True, max_blocks=5) + _, marker2 = self._invoke_stop_hook(stop_hook_active=True, max_blocks=5) + self.assertEqual(marker2["stopHookBlocks"], 2) + + out3, marker3 = self._invoke_stop_hook(stop_hook_active=False, max_blocks=5) + assert out3 is not None + self.assertEqual(out3["decision"], "block") + self.assertEqual(marker3["stopHookBlocks"], 0) + + def test_stop_hook_resets_blocks_when_remaining_decreases(self) -> None: + self._write_active_marker(storiesRemaining=3) + self._invoke_stop_hook(stop_hook_active=True, max_blocks=5) + _, marker2 = self._invoke_stop_hook(stop_hook_active=True, max_blocks=5) + self.assertEqual(marker2["stopHookBlocks"], 2) + + self._bump_marker(storiesRemaining=2) # a story finished + out3, marker3 = self._invoke_stop_hook(stop_hook_active=True, max_blocks=5) + assert out3 is not None + self.assertEqual(out3["decision"], "block") + self.assertEqual(marker3["stopHookBlocks"], 0) + def _install_bundle(self, runtime_dir: str) -> None: source_skill = REPO_ROOT / "skills" / "bmad-story-automator" source_review = REPO_ROOT / "skills" / "bmad-story-automator-review"