diff --git a/src/bmad_loop/adapters/base.py b/src/bmad_loop/adapters/base.py index 44e3ff50..b49965ce 100644 --- a/src/bmad_loop/adapters/base.py +++ b/src/bmad_loop/adapters/base.py @@ -217,14 +217,24 @@ def _classify_env_fault( self, handle: SessionHandle, spec: SessionSpec, result: SessionResult ) -> SessionResult: """Last-chance post-mortem: label a non-completed session an environment - fault (#194) when the CLI lost its API connection and idled out the - session clock rather than doing real work. + fault (#194) when the CLI never got usable work out of the provider — + connection lost, or quota/rate limit refused — and idled out the session + clock rather than doing real work. Runs LAST in ``run()`` — after ``_post_kill_reconcile`` — so a reconcile upgrade to ``completed`` is never re-classified, and only a genuinely non-completed verdict (``result_json is None``) is ever inspected. Base - behavior: identity, like ``_post_kill_reconcile``, so adapters with no - post-mortem signal (HTTP/mock) stay inert. Adapters that tee the pane - (see GenericAdapter) may match profile patterns against the log tail here - and stamp ``env_fault`` / ``env_fault_evidence`` onto the result.""" + behavior: identity, like ``_post_kill_reconcile``, so an adapter with no + session log at all (mock) stays inert. + + Any adapter that writes ``logs/.log`` should mix in + ``EnvFaultMixin``, which matches profile patterns against the log tail + here and stamps ``env_fault`` / ``env_fault_evidence`` onto the result. + That covers the tmux adapters (pane capture) and the opencode HTTP + adapter (the serve process's stdout/stderr, ``.server.out``, + NOT its conversation transcript) alike — the signal is the + log, not the transport. This docstring used to say HTTP adapters had no + post-mortem signal; that stopped being true once opencode_http began + teeing its server log, and the stale premise is why a provider quota + outage went unclassified and burned three stories' retry budgets.""" return result diff --git a/src/bmad_loop/adapters/env_fault.py b/src/bmad_loop/adapters/env_fault.py new file mode 100644 index 00000000..c1dd2021 --- /dev/null +++ b/src/bmad_loop/adapters/env_fault.py @@ -0,0 +1,261 @@ +"""Post-mortem environment-fault classification, shared across transports (#194). + +After a session's verdict and reconcile have settled, a single tail read of the +session log can reclassify a non-completed verdict as an *environment fault* — +the CLI never got usable work out of the provider, so the attempt proved nothing +about the story. The engine routes that to a PAUSE (``env_fault_pause_reason``) +instead of charging a dev attempt, and re-arming resets the budget. + +This lives in its own module rather than on one adapter because the signal is +**transport-agnostic**: every adapter that writes ``logs/.log`` can be +classified from it, whatever produced the bytes. The tmux adapters tee a pane +capture there (``mux.pipe_pane``); the opencode HTTP adapter redirects the +``opencode serve`` process's own stdout/stderr there. Keeping the classifier +attached to a single adapter is what let #194 ship covering only half the +adapters, so the next sibling adapter inherits this instead of re-omitting it. + +Host-class contract: ``self.profile`` (a ``CLIProfile``), ``self.logs_dir``, and +``_note_lifecycle`` (from ``_ResultFileMixin``). Mix in alongside that mixin. + +Note the two log flavors differ in how *dirty* they are, which is why the +shipped patterns are anchored the way they are. A tmux pane capture contains the +model's own output — a story that implements rate limiting will print "429" and +"quota" in ordinary healthy work — whereas the opencode server log carries only +server and provider lines. A pattern loose enough to be wrong on the pane log is +wrong everywhere, so the profiles require an error-shaped anchor AND a cause on +the same line rather than relying on the cleaner log to save them. +""" + +from __future__ import annotations + +import dataclasses +import re +from functools import cached_property +from pathlib import Path +from typing import TYPE_CHECKING + +import regex + +from .base import SessionHandle, SessionResult, SessionSpec +from .profile import CLIProfile + +# Post-mortem transport-failure classification (#194): how much of the tee'd +# session log's tail to scan, how long an evidence excerpt to keep, and which +# non-completed statuses are eligible. over_budget is excluded — a budget +# crossing proves real API traffic — and completed never reaches the scan. +ENV_FAULT_TAIL_BYTES = 64 * 1024 +ENV_FAULT_EVIDENCE_MAX = 240 +# How much of the line *before* the match to keep when the line is too long to +# quote whole. Truncating from the start instead loses the error on any log whose +# lines lead with metadata: an opencode `level=ERROR message="stream error" …` +# line carries ~250 characters of timestamp/provider/session fields before +# `error.error=`, so a head-truncated excerpt showed the operator every field +# except the failure. The evidence string is what lands in the pause reason and +# the ATTENTION file — it has to contain the thing that matched. +ENV_FAULT_EVIDENCE_LEAD = 40 +ENV_FAULT_STATUSES = frozenset({"timeout", "stalled", "crashed"}) +# Wall-clock bound on EACH pattern match (run via the `regex` module, not stdlib +# `re`, whose `search` has no timeout), so a pathological profile regex cannot hang +# run() teardown indefinitely. Note what this does and does not bound: it is +# per-search, so the worst case for a scan is lines × patterns × this, not this. +# A sane pattern over the ≤64 KiB tail matches in microseconds, and the first +# search to blow the bound aborts the whole scan (TimeoutError → decline to +# classify), so the realistic ceiling is one timeout — but an operator writing a +# pattern that backtracks on many lines without exceeding the per-line bound can +# still make teardown slow. Keep patterns anchored and non-nested. +ENV_FAULT_MATCH_TIMEOUT_S = 2.0 +# Self-contained ANSI/terminal-control stripper for the log tail: CSI, OSC (BEL- +# or ST-terminated), other two-char ESC sequences, and raw C1 bytes. Deliberately +# NOT the TUI/pyte machinery — the classifier reads raw pane bytes best-effort and +# must not pull a terminal emulator into the adapter. Inert on a log that was +# never a terminal capture (the opencode server log), which costs one pass. +_ANSI_RE = re.compile( + r""" + \x1b\[ [0-?]* [ -/]* [@-~] # CSI ... final byte + | \x1b\] .*? (?: \x07 | \x1b\\ ) # OSC ... BEL or ST + | \x1b [@-Z\\-_] # 2-char ESC sequences (incl. C1 via ESC) + | [\x80-\x9f] # raw C1 control bytes + """, + re.VERBOSE, +) + + +class EnvFaultMixin: + """Classify a dead session as an environment fault from its log tail (#194). + + Mixed into every adapter that writes ``logs/.log``. Inert for a + profile with no ``env_fault_patterns``, so mixing it in is always safe.""" + + # Set by the concrete adapter's __init__; bare annotations (no runtime effect) + # tell the type checker which host attributes this mixin reads. + profile: CLIProfile + logs_dir: Path + + # Which per-task file in logs_dir carries the CLI's DIAGNOSTIC output. Default + # ".log" is the tmux adapters' pane capture. Overridden by any adapter that + # writes its diagnostics elsewhere. + # + # This is a suffix and not a hardcoded path because the two are not the same + # file for every transport, and getting it wrong is silent: the scan simply + # finds nothing and every provider outage reads as a failed story. The opencode + # adapter split them (its ".log" became a curated conversation transcript, + # diagnostics moved to ".server.out"), and the classifier kept scanning ".log" + # — passing every unit test, because they write the fixture to whatever path + # this resolves to, and failing only end to end. + # + # It also carries the SAFETY property the shipped patterns depend on. A file + # containing the model's own output cannot be scanned with content-based + # patterns: a story that quotes a provider error verbatim is byte-identical to + # the real thing (see tests/test_env_fault_patterns.py). The tmux adapters + # accept that risk knowingly and their profile patterns are anchored for it; + # opencode's are anchored on the assumption of a model-free log, so pointing + # this at a transcript would make them unsound. + ENV_FAULT_LOG_SUFFIX = ".log" + + def _env_fault_log_path(self, task_id: str) -> Path: + return self.logs_dir / f"{task_id}{self.ENV_FAULT_LOG_SUFFIX}" + + if TYPE_CHECKING: + # Supplied by _ResultFileMixin, which every host of this mixin already + # uses. Declared rather than inherited: generic.py imports this module, + # so depending on _ResultFileMixin here would be a cycle. + def _note_lifecycle(self, task_id: str, event: str, **fields: object) -> None: ... + + @cached_property + def _env_fault_patterns(self) -> tuple[regex.Pattern[str], ...]: + """Compiled once per adapter, on first classification. The profile + validated each pattern at parse time with this same engine, so + ``regex.compile`` cannot raise here; empty tuple = classification inert. + + A ``cached_property`` rather than an ``__init__`` line so every adapter + gains the behavior by mixing the class in, with nothing to remember to + wire — the omission that caused this bug. Tests may still assign + ``adapter._env_fault_patterns`` directly; that shadows the property in + the instance ``__dict__``, as it did when this was a plain attribute. + + CONSTRAINT: the cache is filled on first classification and never + invalidated, so reassigning ``self.profile`` afterwards leaves stale + patterns. Nothing in ``src/`` mutates ``profile`` after ``__init__`` (it + is constructor state), so this holds in production; a test that swaps the + profile must do so BEFORE the first classification, or assign + ``_env_fault_patterns`` directly instead.""" + return tuple(regex.compile(p) for p in self.profile.env_fault_patterns) + + def _classify_env_fault( + self, handle: SessionHandle, spec: SessionSpec, result: SessionResult + ) -> SessionResult: + """Post-mortem transport-failure classification (#194). + + Runs last in ``run()`` (after ``_post_kill_reconcile``): only a + non-completed verdict (``result.status`` in ``ENV_FAULT_STATUSES``, + ``result_json is None``) with configured patterns is inspected, so a + reconcile upgrade to ``completed`` is never re-classified and adapters + without patterns stay inert. On a matching log-tail line, stamp + ``env_fault`` / ``env_fault_evidence`` and drop an ``env-fault-classified`` + lifecycle breadcrumb. No match, no patterns, or an unreadable log leaves + the verdict untouched — best-effort, like ``_write_heartbeat``.""" + if ( + not self._env_fault_patterns + or result.status not in ENV_FAULT_STATUSES + or result.result_json is not None + ): + return result + evidence = self._env_fault_evidence(handle.task_id) + if evidence is None: + return result + self._note_lifecycle( + handle.task_id, "env-fault-classified", status=result.status, evidence=evidence + ) + return dataclasses.replace(result, env_fault=True, env_fault_evidence=evidence) + + def _env_fault_evidence(self, task_id: str) -> str | None: + """Scan the tail of the tee'd session log for a transport-failure pattern. + + Reads the last ``ENV_FAULT_TAIL_BYTES`` (binary, decoded with + ``errors="replace"``, ``\\r``→``\\n``), strips ANSI, and matches each line + against the precompiled patterns under a per-match ``ENV_FAULT_MATCH_TIMEOUT_S`` + bound. Returns the ANSI-stripped matching line (last match winning, windowed + to ``ENV_FAULT_EVIDENCE_MAX`` around the match), or None when nothing matches, + the log can't be read (any ``OSError``), or a pattern exceeds the match timeout + (``TimeoutError``) — no classification, the best-effort doctrine.""" + try: + with self._env_fault_log_path(task_id).open("rb") as fh: + fh.seek(0, 2) # SEEK_END + size = fh.tell() + truncated = size > ENV_FAULT_TAIL_BYTES + fh.seek(max(0, size - ENV_FAULT_TAIL_BYTES)) + raw = fh.read() + except OSError: + return None + text = _ANSI_RE.sub("", raw.decode("utf-8", errors="replace").replace("\r", "\n")) + lines = text.split("\n") + if truncated and len(lines) > 1: + # The seek lands on an arbitrary byte, so the first element is a + # fragment of whatever line straddled the window edge — not a line. + # Matching it would quote a half-line as evidence, and (because the + # cut can land mid-codepoint) its head may be a U+FFFD from the + # errors="replace" decode. Drop it: one lost line at the far end of a + # 64 KiB tail cannot matter, and a fabricated line can. + # + # `> 1`, not `and lines`: a truncated window with no newline in it at + # all is a single fragment, and dropping that leaves nothing to scan — + # trading a cosmetic half-line for a missed outage, which is the wrong + # way round. Degenerate (64 KiB without a newline), but silently + # classifying nothing is exactly the failure this change exists to fix. + lines = lines[1:] + match_line: str | None = None + match_pos = 0 + try: + for line in lines: + for pat in self._env_fault_patterns: + hit = pat.search(line, timeout=ENV_FAULT_MATCH_TIMEOUT_S) + if hit is not None: + match_line, match_pos = line, hit.start() # last match wins + break + except TimeoutError: + return None # runaway pattern → decline to classify (best-effort, like OSError) + if match_line is None: + return None + return _excerpt(match_line, match_pos) + + +def _excerpt(line: str, match_pos: int) -> str: + """Quote at most ``ENV_FAULT_EVIDENCE_MAX`` characters of ``line``, keeping the + matched region rather than the line's head. Short lines are returned whole. + + BOTH cut ends are marked with an ellipsis. Marking only the head (as this did + at first) makes a window that dropped a suffix read as a complete line that + simply ended there — which, for a string an operator reads out of a pause + reason to decide whether their run died of a provider outage, is the one thing + it must not do.""" + stripped = line.strip() + if len(stripped) <= ENV_FAULT_EVIDENCE_MAX: + return stripped + usable = len(line.rstrip()) + # The markers are spent FROM the budget, never added on top of it: this string + # is journalled and rendered in a pause reason, so ENV_FAULT_EVIDENCE_MAX has + # to be a real ceiling on what callers receive. But how many markers there are + # depends on the window, and the window depends on the budget, which depends on + # the markers. Resolve by fixed point over the only three possibilities — no + # marker, one, or two — taking the first that is self-consistent. Terminates in + # at most three passes; the final fallback (two markers) is always valid + # because a line long enough to reach here cannot need fewer than it reserves. + start, head, tail, budget = 0, False, False, ENV_FAULT_EVIDENCE_MAX + for reserved in (0, 1, 2): + budget = ENV_FAULT_EVIDENCE_MAX - reserved + # Prefer the match with LEAD chars of left context, but slide LEFT rather + # than return a short excerpt when the match sits near the end of the line. + # That is the common case here, not a corner: opencode's logfmt puts ~250 + # characters of metadata before `error.error=`, so the match is near the + # end of almost every line this classifier quotes. + start = max(0, min(match_pos - ENV_FAULT_EVIDENCE_LEAD, usable - budget)) + head = start > 0 + tail = start + budget < usable + if (1 if head else 0) + (1 if tail else 0) == reserved: + break + window = line[start : start + budget].strip() + if head: + window = f"…{window}" + if tail: + window = f"{window}…" + return window diff --git a/src/bmad_loop/adapters/generic.py b/src/bmad_loop/adapters/generic.py index ac9535ad..b220e38a 100644 --- a/src/bmad_loop/adapters/generic.py +++ b/src/bmad_loop/adapters/generic.py @@ -21,19 +21,15 @@ from __future__ import annotations -import dataclasses import enum import hashlib import json -import re import shlex import time from collections.abc import Callable from pathlib import Path from typing import TYPE_CHECKING -import regex - from .. import devcontract, gates, runs from ..bmadconfig import ProjectPaths from ..journal import LOGS_DIR @@ -44,6 +40,19 @@ from ..tokens import read_usage as tally_usage from ..verify import read_frontmatter from .base import CodingCLIAdapter, SessionHandle, SessionResult, SessionSpec, SpecSnapshot + +# Re-exported for importers that predate the env_fault module split (#194 landed +# these names on this module); the definitions now live in .env_fault. The +# redundant `X as X` form is the explicit-re-export spelling — it tells the linter +# these are deliberate pass-throughs, without an `__all__` that would read as a +# statement of this module's public API and understate it (callers also import +# GenericTmuxAdapter, the *_NUDGE_TEXT constants and HEARTBEAT_INTERVAL_S). +from .env_fault import _ANSI_RE as _ANSI_RE +from .env_fault import ENV_FAULT_EVIDENCE_MAX as ENV_FAULT_EVIDENCE_MAX +from .env_fault import ENV_FAULT_MATCH_TIMEOUT_S as ENV_FAULT_MATCH_TIMEOUT_S +from .env_fault import ENV_FAULT_STATUSES as ENV_FAULT_STATUSES +from .env_fault import ENV_FAULT_TAIL_BYTES as ENV_FAULT_TAIL_BYTES +from .env_fault import EnvFaultMixin from .multiplexer import MultiplexerError, TerminalMultiplexer, get_multiplexer from .profile import CLIProfile @@ -100,31 +109,6 @@ class _SnapVerdict(enum.Enum): REFUSE = "refuse" -# Post-mortem transport-failure classification (#194): how much of the tee'd -# pane log's tail to scan, how long an evidence excerpt to keep, and which -# non-completed statuses are eligible. over_budget is excluded — a budget -# crossing proves real API traffic — and completed never reaches the scan. -ENV_FAULT_TAIL_BYTES = 64 * 1024 -ENV_FAULT_EVIDENCE_MAX = 240 -ENV_FAULT_STATUSES = frozenset({"timeout", "stalled", "crashed"}) -# Wall-clock bound on each operator-supplied pattern match (run via the `regex` -# module, not stdlib `re`, whose `search` has no timeout): a pathological profile -# regex can't hang run() teardown. Huge headroom — a sane pattern over the ≤64 KiB -# tail matches in microseconds; a runaway is capped at ~this and declines to classify. -ENV_FAULT_MATCH_TIMEOUT_S = 2.0 -# Self-contained ANSI/terminal-control stripper for the log tail: CSI, OSC (BEL- -# or ST-terminated), other two-char ESC sequences, and raw C1 bytes. Deliberately -# NOT the TUI/pyte machinery — the classifier reads raw pane bytes best-effort and -# must not pull a terminal emulator into the adapter. -_ANSI_RE = re.compile( - r""" - \x1b\[ [0-?]* [ -/]* [@-~] # CSI ... final byte - | \x1b\] .*? (?: \x07 | \x1b\\ ) # OSC ... BEL or ST - | \x1b [@-Z\\-_] # 2-char ESC sequences (incl. C1 via ESC) - | [\x80-\x9f] # raw C1 control bytes - """, - re.VERBOSE, -) # min spacing between heartbeat.json overwrites in wait_for_completion; the # heartbeat's staleness is what makes a frozen orchestrator (#157) diagnosable. HEARTBEAT_INTERVAL_S = 30.0 @@ -367,7 +351,7 @@ def _await_result(self, task_id: str, grace_s: float = RESULT_GRACE_S) -> dict | time.sleep(RESULT_POLL_S) -class GenericAdapter(_ResultFileMixin, CodingCLIAdapter): +class GenericAdapter(_ResultFileMixin, EnvFaultMixin, CodingCLIAdapter): injection = "tmux-initial-prompt" observation = "hook-signal" state = "local-jsonl" @@ -386,10 +370,7 @@ def __init__( self.run_dir = run_dir self.policy = policy self.profile = profile - # Precompiled once per adapter (the profile validated each at parse time with - # the same regex engine, so regex.compile cannot raise here); matched under a - # per-pattern timeout in _env_fault_evidence. Empty tuple = classification inert. - self._env_fault_patterns = tuple(regex.compile(p) for p in profile.env_fault_patterns) + # env-fault patterns compile lazily off self.profile — see EnvFaultMixin. self.mux = mux or get_multiplexer() # None = use the profile's default bypass flags; a tuple replaces them self.extra_args = extra_args @@ -923,66 +904,6 @@ def _log_activity_key(self, task_id: str) -> tuple[int, int] | None: return None return (st.st_mtime_ns, st.st_size) - def _classify_env_fault( - self, handle: SessionHandle, spec: SessionSpec, result: SessionResult - ) -> SessionResult: - """Post-mortem transport-failure classification (#194). - - Runs last in ``run()`` (after ``_post_kill_reconcile``): only a - non-completed verdict (``result.status`` in ``ENV_FAULT_STATUSES``, - ``result_json is None``) with configured patterns is inspected, so a - reconcile upgrade to ``completed`` is never re-classified and adapters - without patterns stay inert. On a matching log-tail line, stamp - ``env_fault`` / ``env_fault_evidence`` and drop an ``env-fault-classified`` - lifecycle breadcrumb. No match, no patterns, or an unreadable log leaves - the verdict untouched — best-effort, like ``_write_heartbeat``.""" - if ( - not self._env_fault_patterns - or result.status not in ENV_FAULT_STATUSES - or result.result_json is not None - ): - return result - evidence = self._env_fault_evidence(handle.task_id) - if evidence is None: - return result - self._note_lifecycle( - handle.task_id, "env-fault-classified", status=result.status, evidence=evidence - ) - return dataclasses.replace(result, env_fault=True, env_fault_evidence=evidence) - - def _env_fault_evidence(self, task_id: str) -> str | None: - """Scan the tail of the tee'd pane log for a transport-failure pattern. - - Reads the last ``ENV_FAULT_TAIL_BYTES`` (binary, decoded with - ``errors="replace"``, ``\\r``→``\\n``), strips ANSI, and matches each line - against the precompiled patterns under a per-match ``ENV_FAULT_MATCH_TIMEOUT_S`` - bound. Returns the ANSI-stripped matching line (last match winning, truncated - to ``ENV_FAULT_EVIDENCE_MAX``), or None when nothing matches, the log can't be - read (any ``OSError``), or a pattern exceeds the match timeout - (``TimeoutError``) — no classification, the best-effort doctrine.""" - try: - with (self.logs_dir / f"{task_id}.log").open("rb") as fh: - fh.seek(0, 2) # SEEK_END - size = fh.tell() - fh.seek(max(0, size - ENV_FAULT_TAIL_BYTES)) - raw = fh.read() - except OSError: - return None - text = _ANSI_RE.sub("", raw.decode("utf-8", errors="replace").replace("\r", "\n")) - match_line: str | None = None - try: - for line in text.split("\n"): - if any( - pat.search(line, timeout=ENV_FAULT_MATCH_TIMEOUT_S) - for pat in self._env_fault_patterns - ): - match_line = line # last match wins - except TimeoutError: - return None # runaway pattern → decline to classify (best-effort, like OSError) - if match_line is None: - return None - return match_line.strip()[:ENV_FAULT_EVIDENCE_MAX] - def _window_alive(self, handle: SessionHandle) -> bool: return handle.native_id in self.mux.list_window_ids(self.session_name) diff --git a/src/bmad_loop/adapters/opencode_http.py b/src/bmad_loop/adapters/opencode_http.py index 50e9180e..28bb4968 100644 --- a/src/bmad_loop/adapters/opencode_http.py +++ b/src/bmad_loop/adapters/opencode_http.py @@ -151,6 +151,7 @@ from ..policy import Policy from ..process_host import ProcessHostError, get_process_host from .base import CodingCLIAdapter, SessionHandle, SessionResult, SessionSpec +from .env_fault import EnvFaultMixin from .generic import ( BUDGET_NUDGE_TEXT, HEARTBEAT_INTERVAL_S, @@ -366,7 +367,16 @@ class _ServerSession: floor_ms: int = 0 -class OpencodeHttpAdapter(_ResultFileMixin, CodingCLIAdapter): +class OpencodeHttpAdapter(_ResultFileMixin, EnvFaultMixin, CodingCLIAdapter): + # Env-fault classification scans the SERVER's own stdout/stderr, not + # .log — that file is the curated `[bmad]` conversation transcript + # written by the SSE reader, so it carries the model's own words. Two reasons + # this must be .server.out: the provider's AI_APICallError logfmt lines only + # ever land there, and the profile's patterns are anchored on the assumption + # that a story quoting a provider error verbatim cannot reach the scanned + # bytes. Point this at the transcript and both properties break at once. + ENV_FAULT_LOG_SUFFIX = ".server.out" + injection = "http" observation = "sse" state = "remote" @@ -608,6 +618,18 @@ def start_session(self, spec: SessionSpec) -> SessionHandle: # A re-armed/resumed run reuses task_ids; drop any prior cycle's result # so a session that writes nothing can't be read as a stale completion. (task_dir / "result.json").unlink(missing_ok=True) + # Same hazard, same reason, for the file the #194 tail scan reads (mirrors + # GenericAdapter.start_session, which unlinks its pane tee here). This one + # bites hardest on the path the classifier exists to serve: an env fault + # PAUSEs the run, the operator re-arms and resumes, and the next session + # reusing this task_id would scan the PREVIOUS cycle's provider error and + # pause again — however healthy the new session's own log. A pause loop + # that survives every re-arm, off one stale line. + # + # Unlinked HERE and not in _spawn_server, which deliberately opens the file + # "ab" so a spawn retry (free-port collision) keeps its predecessor's + # diagnostics inside the SAME session. + self._env_fault_log_path(spec.task_id).unlink(missing_ok=True) launched_ns = time.time_ns() sess = self._spawn_server(spec) diff --git a/src/bmad_loop/adapters/profile.py b/src/bmad_loop/adapters/profile.py index ec9b1a73..6f6fc6d0 100644 --- a/src/bmad_loop/adapters/profile.py +++ b/src/bmad_loop/adapters/profile.py @@ -89,12 +89,19 @@ class CLIProfile: # that a `git worktree add` checkout omits; provision_worktree copies them in # from the main repo so isolated dev/review sessions can reach the MCP server. seed_files: tuple[str, ...] = () - # Python `re` patterns matched line-by-line against the ANSI-stripped tail of - # a non-completed session's pane log to classify a transport/API *environment - # fault* (#194) — e.g. an "API Error … Connection refused" the CLI printed - # while idling out the session clock. Compiled and validated at parse time - # (an invalid regex is a profile error). Seeded only for `claude`; empty = - # inert. Override/extend via a project profile in .bmad-loop/profiles/. + # Patterns matched line-by-line against the ANSI-stripped tail of a + # non-completed session's log to classify a provider/transport *environment + # fault* (#194) — an "API Error … Connection refused" or a "usage limit + # reached" the CLI printed while idling out the session clock. The log is + # whatever the adapter tees to logs/.log: a tmux pane capture, or + # the opencode server's own stdout/stderr. Compiled and validated at parse + # time (an invalid regex is a profile error); empty = inert. + # + # Write them anchored: require an error-shaped token AND a cause on the SAME + # line. A pane capture contains the model's own output, so a bare `quota` or + # `429` matches a story that merely *implements* rate limiting and would + # pause a healthy run. Override/extend via a project profile in + # .bmad-loop/profiles/. env_fault_patterns: tuple[str, ...] = () @property diff --git a/src/bmad_loop/data/profiles/opencode.toml b/src/bmad_loop/data/profiles/opencode.toml index efd1510c..240e1f2f 100644 --- a/src/bmad_loop/data/profiles/opencode.toml +++ b/src/bmad_loop/data/profiles/opencode.toml @@ -9,5 +9,41 @@ usage_parser = "none" skill_tree = ".claude/skills" first_run_note = "run `opencode auth login` once on this machine; headless servers reuse the stored credentials" +# Transport/provider environment-fault classification (#194). Unlike the tmux +# adapters, the file scanned for this adapter is logs/.server.out — the +# `opencode serve` process's own stdout/stderr, structured logfmt, which the model +# never writes to. So the anchor can be the ai-sdk error class opencode reports in +# the `error.error=` field of a `level=ERROR message="stream error"` line, which is +# both precise and incapable of colliding with story output. +# +# NOT logs/.log: that is the curated `[bmad]` conversation transcript and +# it carries the model's own words. These patterns are only safe against a +# model-free log, so the file the classifier reads is part of their contract — +# see EnvFaultMixin.ENV_FAULT_LOG_SUFFIX. +# +# Verified against a real 5-hour provider quota outage: 22 matching lines across +# one run, in two forms — a clean refusal, and the socket drop providers fall +# back to once they stop answering at all: +# ... message="stream error" ... error.error="AI_APICallError: Usage limit reached for 5 hour. Your limit will reset at 2026-07-26 22:49:46" +# ... message="stream error" ... error.error="AI_APICallError: Cannot connect to API: The socket connection was closed unexpectedly." +# To disable or extend, copy this profile into .bmad-loop/profiles/ and edit. +# Anchored on the structured field name, not on the error class alone: the server +# reports the failure as `error.error="AI_APICallError: …"` inside a logfmt line. +# The bare class name would also match `const MSG = "AI_APICallError: Usage limit +# reached";` — unreachable in THIS log, but a pattern is copied into project +# overlays and read as an example, so it should not model a weaker rule than it +# means. Deliberately content-anchored rather than position-anchored: this file is +# a byte stream, and the tmux profiles' equivalent is a raw pipe-pane capture full +# of cursor-addressed repaints, so no column or line offset in it is meaningful. +# The gap is [^"], not `.`: it must stay INSIDE the quoted error value. With `.` +# the lazy gap walks past the closing quote and finds a cause word in a later +# logfmt field, so an unrelated `AI_APICallError: Invalid API key` on a line whose +# trailing fields mention a quota path classifies as a quota outage. In every +# captured line the cause is inside the quotes, so nothing real is lost. +env_fault_patterns = [ + 'error[.]error="AI_APICallError: [^"]{0,400}?(?i:usage limit reached|429|too many requests|rate[ _-]?limit|quota|overloaded)', + 'error[.]error="AI_APICallError: [^"]{0,400}?(?i:cannot connect to api|socket connection was closed|connection ?(error|refused|reset|timed ?out)|ECONNREFUSED|ETIMEDOUT|ENOTFOUND|EAI_AGAIN)', +] + [hooks] dialect = "none" diff --git a/tests/test_env_fault_patterns.py b/tests/test_env_fault_patterns.py new file mode 100644 index 00000000..b4049b27 --- /dev/null +++ b/tests/test_env_fault_patterns.py @@ -0,0 +1,442 @@ +"""The shipped profiles' env_fault_patterns, held to both halves of the contract. + +A pattern that misses a real provider outage burns a story's retry budget on an +environment fault (the bug that motivated this file). A pattern that fires on +ordinary model output pauses a *healthy* run — the inverse bug, and the worse of +the two, because the miss merely reproduces today's behaviour while the false +positive halts work that was fine. Both halves are cheap to assert and expensive +to rediscover, so the corpora below are the gate: add a line here before +loosening a pattern. + +Only two profiles seed patterns, and only because captured output exists for +them. The other four stay inert deliberately — see test_unseeded_profiles_stay_inert. + +WHAT BAIT IS FOR. The tmux adapters match against a tmux pane capture, which +contains the MODEL'S OWN OUTPUT: a story about quota handling prints this +vocabulary constantly, in fixtures, banners, acceptance criteria, docs and +assertions. Every BAIT line is something a healthy session plausibly emits. +The opencode adapter is structurally different — the file it scans is +`.server.out`, the `opencode serve` process's own stdout/stderr, which +the model cannot write to at all. (NOT `.log`, which is that adapter's +curated `[bmad]` conversation transcript and does carry the model's words.) It is +held to the same corpus anyway, because a pattern loose enough to be wrong on a +pane log should not be trusted just because today's log happens to be clean — +and because which file is scanned has already changed once underneath these +patterns. + +KNOWN LIMIT, so nobody mistakes a green run here for proof. This gate matches +line-by-line against text, whereas the real pane log is a raw `tmux pipe-pane` +byte stream carrying cursor-addressed repaints (the TUI renders the same file +through pyte — see tui/data.py). Line and column position in that stream do not +correspond to what was on screen. So patterns must not depend on POSITION, +only on content; a positional anchor would pass here and be meaningless in +production. +""" + +from __future__ import annotations + +import pytest +import regex + +from bmad_loop.adapters.profile import get_profile + +# The one profile whose patterns are backed by captured output from a real outage +# AND whose log the model cannot write to. Held to the full BAIT corpus. +SEEDED_PROFILES = ("opencode",) +# Profiles that deliberately seed NOTHING, so classification stays inert for them. +# Patterns were drafted for these and withdrawn: they could only be written from +# error strings scraped off public issue trackers, for CLIs nobody here has run. +# An unverified pattern is not a neutral bet — one that fires on a healthy session +# pauses the whole run, which is worse than the fault it was meant to catch. +# Seeding nothing costs only the status quo. See test_unseeded_profiles_stay_inert. +UNSEEDED_PROFILES = ("codex", "gemini", "copilot", "antigravity") +# claude ships #194's original connection pattern, which predates this module and +# is NOT held to BAIT — it cannot pass. See test_claude_pattern_is_known_to_false_positive. +LEGACY_PROFILES = ("claude",) +ALL_PROFILES = SEEDED_PROFILES + UNSEEDED_PROFILES + LEGACY_PROFILES + +# The two logfmt shapes `opencode serve` emitted during a real 5-hour provider +# quota outage on the opencode-http adapter (zai-coding-plan/glm-5.2). The line +# SHAPE and the AI_APICallError text are reproduced exactly — those are what the +# patterns key on — but the correlation ids are FAKES: the run this was captured +# from was a private client project, and a real `run=`/`session.id=` pair is a +# usable handle on it. Keep them fake; ids carry no test signal. +OPENCODE_REAL = [ + 'timestamp=2026-07-26T13:12:53.262Z level=ERROR run=fake0001 message="stream error" ' + "providerID=zai-coding-plan modelID=glm-5.2 session.id=ses_fake0000000000000000000001 " + 'small=false agent=general mode=subagent error.error="AI_APICallError: Usage limit ' + 'reached for 5 hour. Your limit will reset at 2026-07-26 22:49:46"', + 'timestamp=2026-07-26T22:52:57.193Z level=ERROR run=fake0002 message="stream error" ' + "providerID=zai-coding-plan modelID=glm-5.2 session.id=ses_fake0000000000000000000002 " + 'small=false agent=build mode=primary error.error="AI_APICallError: Cannot connect to ' + 'API: The socket connection was closed unexpectedly."', +] + +# Claude Code surfaces provider failures behind its own "API Error" prefix. Only +# the CONNECTION class is covered — claude.toml ships #194's original pattern and +# nothing more. A quota/rate-limit pattern of the same shape was drafted for this +# profile and withdrawn: no captured Claude Code quota line exists here, and the +# "API Error" anchor is too weak to add a second cause class safely (see +# test_claude_pattern_is_known_to_false_positive). So an Anthropic plan's usage +# limit is still unclassified on this adapter — a real, deliberately-left gap. +CLAUDE_REAL = [ + "API Error: Connection error (ECONNREFUSED)", +] + +# Every profile with patterns, paired with the lines its own CLI actually emits. +REAL_BY_PROFILE = [ + (name, line) + for name, corpus in (("opencode", OPENCODE_REAL), ("claude", CLAUDE_REAL)) + for line in corpus +] + +# Bait that actually REACHES a seeded profile's anchor. Kept separate because it +# is the half that is easiest to get wrong: a corpus can be large and still prove +# nothing if every line bounces off the anchor before the rest of the pattern is +# ever exercised. This list did exactly that once — it was written while claude +# was still seeded, and after claude was withdrawn not one line could reach the +# only remaining anchor, so the test guarded nothing while looking thorough. +# +# So the bar for a line here is mechanical, and test_anchor_reaching_bait_is_not_ +# vacuous enforces it: every seeded profile must have at least one line carrying +# its literal anchor. Lines below reproduce `error.error="AI_APICallError: ` (the +# opencode anchor) inside ordinary healthy-session output. +ANCHOR_REACHING_BAIT = [ + # The cause OUTSIDE the quoted error value: a real but UNRELATED provider + # error whose trailing logfmt fields merely happen to contain a cause word. + # These are why the gap in the pattern is [^"] and not `.` — with `.` the lazy + # gap walks past the closing quote and finds "quota" in a later field, so an + # invalid-API-key error reads as a quota outage. + 'timestamp=2026-07-26T13:12:53.262Z level=ERROR message="stream error" ' + 'error.error="AI_APICallError: Invalid API key" request.path=/v1/quota', + 'timestamp=2026-07-26T13:12:53.262Z level=ERROR message="stream error" ' + 'error.error="AI_APICallError: Model not found" endpoint=https://example/rate-limits', + 'error.error="AI_APICallError: Model not found" note=see-the-rate-limit-docs', + # The anchor named but not completed — prose about the field, not the field. + "docs: the server writes error.error= with an AI_APICallError when the quota trips", + # claude's framing, kept for the day a claude pattern is seeded again. + '// TODO: surface "API Error: 429" to the user with a Retry-After hint', + 'expect(banner).toBe("API Error: 429 rate_limit_error")', + "docs: document the API Error 429 quota path per AC-3", + ' it("renders API Error: overloaded", () => {', + "- [ ] AC-2: map API Error: 429 to a friendly rate limit message", +] + +# The limit of content-based matching, pinned rather than papered over. +# +# A story that quotes a provider's error VERBATIM — the whole framing token and a +# real cause, inside the quotes — produces a line byte-identical to the emitted +# one. No content-based pattern can separate those, because there is nothing left +# to separate them BY. It is a property of the approach, not a gap in these +# patterns, and it is the reason four profiles ship nothing at all: their real +# refusals are bare sentences, so every citation of them is indistinguishable. +# +# It is acceptable for opencode ONLY because of where that profile's log comes +# from: logs/.log is the `opencode serve` process's own stdout/stderr, +# which the model cannot write to, so a citation cannot physically reach the +# scanned bytes. If this adapter ever tees model output into the same file, these +# lines become live false positives and the patterns must be withdrawn. +# +# Characterisation test — asserts they DO match, so the day that changes it shows. +INSEPARABLE_VERBATIM_CITATIONS = [ + 'docs: the server logs error.error="AI_APICallError: Usage limit reached" on quota exhaustion', + " assert line == 'error.error=\"AI_APICallError: Usage limit reached for 5 hour\"'", + '# fixture: error.error="AI_APICallError: rate limit" — see tests/fixtures/quota.log', + "expect(parse(line)).toEqual({error: 'error.error=\"AI_APICallError: quota exceeded\"'})", +] + +# The literal each seeded profile's patterns key on. Used to prove the corpus +# above actually reaches them, rather than trusting that it does. +PROFILE_ANCHOR_LITERAL = {"opencode": 'error.error="AI_APICallError: '} + +# Ordinary output from a healthy session working on a story that involves rate +# limiting. Every one of these is reachable in a tmux pane capture. None may +# classify — a hit here means the loop pauses a run that was working fine. +BAIT = [ + " def test_rate_limit_retries_with_backoff(self): # story 4 AC-2", + "PASS tests/rate_limiter.test.ts (12 tests)", + "Implementing the quota exceeded banner per AC-3.", + "wrote src/middleware/rate_limit.py", + "- [x] AC-4: requests over quota return 429 with a Retry-After header", + "I'll add a 429 handler that surfaces a friendly message to the user.", + "429 lines changed across 12 files", + "grep -c 'rate limit' logs/app.log # 429", + "throw new Error('Rate limit exceeded'); // added in src/api/client.ts", + "docs: explain the quota model and the 429 response contract", + "INFO cleanup prune=7.days", + "timestamp=2026-07-26T15:45:39.732Z level=INFO message=stream providerID=zai-coding-plan", + # A story's own passing test whose NAME mentions the very error class the + # anchors key on — the nastiest realistic collision. + "PASS tests/test_api_error_handling.py::test_rate_limit_error_is_retried", + # …and the same collision on a FAILING test, which puts an error-shaped word + # ahead of the cause on the line. A pattern anchored on a bare "error|failed" + # rather than on a CLI-specific token trips on exactly this. + "FAILED tests/test_retry.py::test_econnrefused_is_retried", + "FAILED tests/network.spec.ts > retries on ETIMEDOUT", + " ✗ Error: handles RESOURCE_EXHAUSTED from the quota middleware", + "AssertionError: expected 429, got 200 — see src/quota/limiter.ts", + # --------------------------------------------------------------------- + # THE CLASS THAT WAS MISSED: the model CITING the provider's error, verbatim. + # + # Everything above is a story *paraphrasing* rate limiting, so a + # CLI-specific token was enough to separate it. These lines instead contain + # a CLI's exact error string — because the story's job IS that error: + # fixture literals, golden JSON, assertion text, test names, banner copy, + # ACs, doc bullets, commit subjects, diff hunks, stack frames. + # + # This class is why four profiles ship NO patterns. Their real refusals are + # bare provider sentences ("Resource has been exhausted (e.g. check quota).") + # with no framing to anchor on, so no amount of vocabulary separates the + # emitted line from the quoted one. A positional scheme was tried — anchor on + # the CLI "owning" column 0 — and abandoned as unsound: the pane log is a raw + # pipe-pane byte stream, so position in it is not position on screen (see this + # module's header). Lines below are retained as the standing bar any future + # pattern for those CLIs must clear before it is seeded. + 'ERROR in test setup: expected "code": "insufficient_quota"', + 'assert msg == "Resource has been exhausted (e.g. check quota)."', + '"You have exhausted your daily quota on this model." // banner copy, AC-2', + 'it("renders TerminalQuotaError", () => {', + 'docs: quota copy - "You exceeded your current quota, please check your plan..."', + 'expected = {"code": "quota_exceeded"}', + ' mock.return_value = {"code":"rate_limited"}', + 'expected = {"error": {"code": 429, "message": "Resource has been exhausted ' + '(e.g. check quota).", "status": "RESOURCE_EXHAUSTED"}}', + ' Received: {"error":{"code":429,"message":"Resource has been exhausted ' + '(e.g. check quota).","status":"RESOURCE_EXHAUSTED"}}', + '+ {"error": {"code": 429, "message": "Resource has been exhausted ' + '(e.g. check quota).", "status": "RESOURCE_EXHAUSTED"}}', + ' "status": "RESOURCE_EXHAUSTED",', + 'fixtures/gemini_429.json: {"error": {"code": 429, "status": "RESOURCE_EXHAUSTED"}}', + "class TerminalQuotaError extends Error { constructor() { super('quota exhausted'); } }", + "export { TerminalQuotaError, GaxiosError } from './errors';", + "fix(quota): raise TerminalQuotaError: quota exhausted when the token bucket empties", + " 47 | throw new TerminalQuotaError('quota exhausted');", + '# The upstream copy is "You have exhausted your daily quota on this model."', + 'TODO: handle "Quota exceeded for metric: generativelanguage.googleapis.com/' + 'generate_content_free_tier_requests"', + "docs(errors): document Resource has been exhausted (e.g. check quota). handling", + "* Copy per AC-6: You have exhausted your daily quota on this model.", + '# ERROR codex_api::endpoint::responses: error=http 429 Too Many Requests: Some("{', + ' "ERROR: exceeded retry limit, last status: 429 Too Many Requests, ' + 'request id: 9bd33f31fd269bb1-HNL",', + ' "You have exhausted your daily quota on this model.",', + '+ "Sorry, you\'ve hit a rate limit that restricts the number of Copilot model requests "', + "2026-07-27T11:02:03.114Z ERROR app::api::client: error=http 429 Too Many Requests", + "2026-07-27T11:02:03.114Z ERROR codex_client_stub: error=http 429 Too Many Requests", + "Error sending request for url (https://api.openai.com/v1/chat/completions): " + "error trying to connect: ECONNREFUSED", + "Error sending request for url (http://localhost:8080/v1/responses): " + "error trying to connect: ECONNREFUSED", + "GaxiosError: request to https://sheets.googleapis.com/v4/spreadsheets failed, " + "reason: connect ECONNREFUSED 127.0.0.1:443", + "✗ Model call failed: surfaces quota_exceeded as a 402 (12 ms)", + " ✓ Model call failed: retries rate_limited twice then gives up", + "│ Sorry, you've hit a rate limit — that's the banner string we render, per AC-2.", + ' assert body["message"] == "Sorry, you have exceeded your Copilot token usage."', + '- Model call failed: {"message":"You have no quota","code":"quota_exceeded"} ' + "<- tests/fixtures/copilot_402.json", + 'it.each([["rate_limited", 429], ["quota_exceeded", 402]])("maps %s to %d", (code, status) => {', + ' File "src/retry.py", line 41, in _raise_exhausted: ' + 'RuntimeError("exceeded retry limit, last status: 429 Too Many Requests")', + 'raise UpstreamError("exceeded retry limit, last status: 503 Service Unavailable")', + "> exceeded retry limit, last status: 429 Too Many Requests " + "(expected output, docs/retry.md)", + '+ RESOURCE_EXHAUSTED_COPY = "Resource has been exhausted (e.g. check quota)."', + '- code: "rate_limit_exceeded",', + 'FIXTURE = {"error": {"code": 429, "message": "Resource has been exhausted ' + '(e.g. check quota).", "status": "RESOURCE_EXHAUSTED"}}', + 'expect(body).toEqual({"error":{"code":429,"message":"Resource has been exhausted ' + '(e.g. check quota).","status":"RESOURCE_EXHAUSTED"}})', + 'assert_eq!(err.to_string(), "exceeded retry limit, last status: 429 Too Many Requests");', + 'assert res.json()["error"]["status"] == "RESOURCE_EXHAUSTED" # 429 path', + 'it("gives up once it has exceeded retry limit, last status: 503", async () => {', + " 1) rate limiter › Model call failed: rate_limited (expected, retries once)", + "stdout | src/quota.test.ts > Model call failed: quota_exceeded", + '✗ should render "Quota exceeded for metric: generativelanguage.googleapis.com/x" ' + "in the toast", + " ✓ TerminalQuotaError is raised after the third 429 (18ms)", + "# You have exhausted your daily quota on this model. <- exact upstream copy, " + "do not reword", + "* You exceeded your current quota, please check your plan and billing details.", + "> Resource has been exhausted (e.g. check quota).", + " GaxiosError: request to https://generativelanguage.googleapis.com/v1beta/models/x " + "failed, reason: connect ECONNREFUSED # expected in test_offline", + " ERROR codex_api::endpoint::responses: error=http 429 Too Many Requests " + "# pasted from openai/codex#9135", + "Quota exceeded for metric: {metric}, limit: {limit}", + 'You have exhausted your daily quota on this model. Retry at {reset_at}."', + "TerminalQuotaError = class extends Error {}", + "2026-07-27T04:11:02.001Z ERROR quota_api::endpoint::responses: " + "error=http 429 Too Many Requests", + "2026-07-27T04:12:00.113Z ERROR app_api::responses: error=http 503 Service Unavailable", + '[ERROR] billing: Model call failed shim returned {"code":"rate_limited"} (mocked)', + "feat(retry): give up after exceeded retry limit, last status: 429", + "fix(api): map RESOURCE_EXHAUSTED to a TerminalQuotaError subclass", + "chore(copy): use \"Sorry, you've hit a rate limit that restricts the number of " + 'Copilot model requests" verbatim', + "printf 'ERROR: exceeded retry limit, last status: %d\\n' \"$status\"", + 'console.log("Model call failed: " + JSON.stringify({ code: "rate_limited" }))', + 'throw new GaxiosError("connect ETIMEDOUT", { code: "ETIMEDOUT" });', + '> Model call failed: {"message":"You have no quota","code":"quota_exceeded"}', + 'banner_text = "Sorry, you have exceeded your Copilot token usage. ' + 'Please review our Terms of Service."', + "- [ ] AC-7: surface the \"Sorry, you've hit a rate limit that restricts the number " + 'of Copilot model requests" toast verbatim', + 'RESPONSE_FIXTURE = {"error": {"code": 429, "message": "Resource has been exhausted ' + '(e.g. check quota).", "status": "RESOURCE_EXHAUSTED"}}', + "expect(err).toBeInstanceOf(GaxiosError); // ECONNREFUSED path, AC-5", + 'test("GaxiosError: request to https://generativelanguage.googleapis.com/v1beta failed, ' + 'reason: connect ECONNREFUSED is retried", async () => {', + 'throw new Error("exceeded retry limit, last status: " + res.status);', + 'docs: document the "ERROR: exceeded retry limit, last status: 429" line codex prints', + "fix(api): map codex_api error=http 429 onto our RetryableError type", + ' ✓ Model call failed: {"message":"You have no quota","code":"quota_exceeded"} ' + "→ renders upgrade CTA (3 ms)", + " \"Sorry, you've hit a rate limit that restricts the number of Copilot model " + 'requests you can make within a specific time period."', + "[app] Error sending request for url (http://localhost:8080/v1/chat): " + "error trying to connect: ECONNREFUSED", + " Quota exceeded for metric: generativelanguage.googleapis.com/" + "generate_content_free_tier_input_token_count, limit: 0 # golden fixture", + "2026-07-27T09:14:02.117Z ERROR app::quota: error=http 429 Too Many Requests " + "(raised by our own middleware)", + ' ✗ quota banner shows "You have exhausted your daily quota on this model."', + 'chore: add fixture for the {"status": "RESOURCE_EXHAUSTED"} envelope', + "You have exhausted your daily quota on this model. <- expected copy for AC-2", + 'console.log("Model call failed: " + JSON.stringify({code: "rate_limited"}));', + "TerminalQuotaError = class extends Error {} // src/errors.ts", + " at TerminalQuotaError.handle (src/quota/errors.ts:42:11)", + 'PASS tests/quota.spec.ts > "You exceeded your current quota, please check your plan ' + 'and billing details."', + "Resource has been exhausted (e.g. check quota). # copied from the Google docs", + 'banner.text = "Sorry, you have exceeded your Copilot token usage"', + "2026-07-27T09:15:44.001Z ERROR codex_api_shim::mock: replaying error=http 429 " + "fixture for the retry test", + "- Sorry, you've hit a rate limit that restricts the number of Copilot model requests", +] + +# A duplicated bait line silently weakens the corpus (it reads as coverage it is +# not), and pytest's parametrize ids collide on it. Guard the list itself. +assert len(BAIT) == len(set(BAIT)), "BAIT contains duplicate lines" + + +def _patterns(name: str) -> tuple[regex.Pattern[str], ...]: + return tuple(regex.compile(p) for p in get_profile(name).env_fault_patterns) + + +def _matches(name: str, line: str) -> bool: + return any(p.search(line) for p in _patterns(name)) + + +@pytest.mark.parametrize("name", SEEDED_PROFILES) +@pytest.mark.parametrize("line", BAIT) +def test_seeded_profiles_never_classify_healthy_model_output(name: str, line: str) -> None: + """The false-positive half. A hit pauses a run that was working.""" + assert not _matches(name, line), f"{name}.toml false-positives on: {line}" + + +@pytest.mark.parametrize("name", SEEDED_PROFILES) +@pytest.mark.parametrize("line", ANCHOR_REACHING_BAIT) +def test_seeded_profiles_survive_bait_that_reaches_their_anchor(name: str, line: str) -> None: + """The half that a large corpus can silently fail to test. Lines here carry the + CLI's own framing token, so they get past the anchor and put the rest of the + pattern under real pressure.""" + assert not _matches(name, line), f"{name}.toml false-positives on: {line}" + + +@pytest.mark.parametrize("line", INSEPARABLE_VERBATIM_CITATIONS) +def test_verbatim_citation_of_the_real_error_is_inseparable(line: str) -> None: + """Characterises the limit of content-based matching: a verbatim citation of + the provider's error IS the provider's error, byte for byte, so it matches. + + Asserted positively on purpose. It is safe only because opencode's scanned log + is the serve process's own stdout — ``.server.out``, which the model + cannot write to. So if this ever starts failing, either the patterns gained a + citation-awareness they cannot soundly have, or the scanned file gained model + output and the patterns must go. Either way it should not change silently. + + That second case is not hypothetical: ``.log`` USED to be the server's + stdout and these patterns were seeded on that basis, then it was repurposed as + a curated `[bmad]` conversation transcript carrying the model's own words. The + classifier kept scanning it. Every test here still passed, because they write + their fixture to whatever path the code resolves — only the end-to-end test + caught it. If the scanned file is ever repointed again, re-derive this safety + argument before trusting it: see EnvFaultMixin.ENV_FAULT_LOG_SUFFIX.""" + assert _matches("opencode", line) + + +@pytest.mark.parametrize("name", SEEDED_PROFILES) +def test_anchor_reaching_bait_is_not_vacuous(name: str) -> None: + """Guards the guard. The test above is worthless unless its corpus actually + contains the anchor under test — and it silently stopped doing so once, when + the profile the corpus had been written for was withdrawn. Assert reachability + mechanically instead of trusting it.""" + anchor = PROFILE_ANCHOR_LITERAL[name] + reaching = [line for line in ANCHOR_REACHING_BAIT if anchor in line] + assert reaching, f"no ANCHOR_REACHING_BAIT line contains {name}'s anchor {anchor!r}" + + +@pytest.mark.parametrize(("name", "line"), REAL_BY_PROFILE) +def test_each_seeded_profile_catches_its_own_cli_error_lines(name: str, line: str) -> None: + """The false-negative half, per CLI. Each seeded profile is anchored on a + framing token its CLI emits, so a miss here means a real provider outage would + burn the story's retry budget instead of pausing the run.""" + assert _matches(name, line), f"{name}.toml misses a real error line: {line[:120]}" + + +@pytest.mark.parametrize("name", SEEDED_PROFILES) +def test_patterns_require_an_anchor_not_a_bare_cause(name: str) -> None: + """The doctrine itself: a cause word alone must never be sufficient. Guards + against a future edit that drops an anchor for 'better coverage'.""" + for bare in ("quota", "rate limit", "429", "usage limit reached", "too many requests"): + assert not _matches(name, bare), f"{name}.toml classifies the bare cause {bare!r}" + + +CLAUDE_KNOWN_FALSE_POSITIVES = [ + ' assert log == "API Error: Connection refused"', + 'docs: explain the "API Error: Unable to connect" retry path', + "- [ ] AC-5: show a banner on API Error: Connection timed out", + 'expect(msg).toBe("API Error: Connection error")', + "// handle API Error: ECONNREFUSED by retrying with backoff", +] + + +@pytest.mark.parametrize("line", CLAUDE_KNOWN_FALSE_POSITIVES) +@pytest.mark.xfail(strict=True, reason="pre-existing #194 defect: claude's pattern matches prose") +def test_claude_pattern_is_known_to_false_positive(line: str) -> None: + """Documents debt rather than hiding it. claude.toml's `API Error.*` + predates this module and cannot pass BAIT: its pane log is a tmux capture of + the model's own output, so a story that merely writes ABOUT provider errors — + a TODO, an assertion, an acceptance criterion — reads as an environment fault + and pauses a healthy run. + + It also fires on this repo's own tracked files (CHANGELOG.md, docs/FEATURES.md + and the profile comment describing the pattern), so a bmad-loop session + working on bmad-loop is exposed. + + Left in place here, not widened: a quota pattern of the same shape was drafted + for this profile and withdrawn for exactly this reason, so the gap is real — + an Anthropic plan's usage limit is still unclassified. Fixing it needs a + captured Claude Code quota line and a stronger anchor than "API Error", which + is a separate change from the one this branch makes. + + strict=True on purpose: the day the pattern is fixed, this test fails and + forces the debt note to be removed with it.""" + assert not _matches("claude", line) + + +@pytest.mark.parametrize("name", UNSEEDED_PROFILES) +def test_unseeded_profiles_stay_inert(name: str) -> None: + """These four ship no patterns ON PURPOSE, and this pins that. + + Patterns for them were drafted and withdrawn. They could only be written + against error strings scraped from public issue trackers — no captured output + from a real outage on any of these CLIs exists here — and an unverified + pattern is not a neutral bet: one that fires on a healthy session pauses the + entire run, which is worse than the fault it is meant to catch. Seeding + nothing costs only the status quo. + + Do not seed these from a plausible-looking string. Seed them from a captured + log line, with the run it came from cited, and add it to REAL_BY_PROFILE and + this module's BAIT in the same change.""" + assert get_profile(name).env_fault_patterns == () diff --git a/tests/test_generic_tmux.py b/tests/test_generic_tmux.py index f626bf46..9a4248cb 100644 --- a/tests/test_generic_tmux.py +++ b/tests/test_generic_tmux.py @@ -2474,9 +2474,20 @@ def test_classify_env_fault_ignores_result_json_present(tmp_path): def test_classify_env_fault_inert_without_patterns(tmp_path): - """A profile with no env_fault_patterns (codex) never classifies, even with a - matching line in the log.""" - adapter = make_adapter(tmp_path, profile_name="codex") + """A profile with no env_fault_patterns never classifies, even with a matching + line in the log — so mixing EnvFaultMixin into an adapter is always safe. + + Builds the empty profile explicitly rather than borrowing whichever shipped CLI + happens to have none (it used to borrow codex). Four profiles are in fact + unseeded — see test_unseeded_profiles_stay_inert — but which ones is a shipping + decision that has changed once already and should not be able to silently + invalidate this test. + + The profile is swapped BEFORE the first classification on purpose: + _env_fault_patterns is a cached_property, so a swap afterwards would leave the + old patterns compiled (documented on the property).""" + adapter = make_adapter(tmp_path) + adapter.profile = dataclasses.replace(adapter.profile, env_fault_patterns=()) assert adapter._env_fault_patterns == () _write_task_log(adapter, b"API Error: Connection refused\n") result = _classify(adapter, "timeout") @@ -4313,3 +4324,67 @@ def test_log_evidence_mro_is_not_shadowed_by_the_mixin(): assert GenericDevAdapter._READBACK_NEEDS_PROOF_OF_WORK is True assert OpencodeDevAdapter._READBACK_NEEDS_PROOF_OF_WORK is True assert GenericTmuxAdapter._READBACK_NEEDS_PROOF_OF_WORK is False + + +def test_classify_env_fault_marks_a_dropped_suffix(tmp_path): + """A window that dropped a SUFFIX says so. Marking only the head made a + truncated excerpt read as a complete line that simply ended there — the one + thing a string an operator reads out of a pause reason must not do. Both + markers are spent from ENV_FAULT_EVIDENCE_MAX, never added on top of it.""" + adapter = make_adapter(tmp_path) + lead = "y" * 300 # push the match past the head so both ends are cut + _write_task_log(adapter, f"{lead} API Error: Connection refused {'z' * 400}\n".encode()) + result = _classify(adapter, "timeout") + assert result.env_fault is True + ev = result.env_fault_evidence + assert ev.startswith("…") and ev.endswith("…") + assert len(ev) <= generic.ENV_FAULT_EVIDENCE_MAX + assert "API Error: Connection refused" in ev + + +def test_classify_env_fault_drops_the_partial_line_at_the_tail_seek(tmp_path): + """The 64 KiB tail seek lands on an arbitrary byte, so whatever line straddles + the window edge arrives as a fragment. Matching it would quote half a line as + evidence — and because the cut can land mid-codepoint, its head may be a U+FFFD + from the errors="replace" decode. The fragment is discarded.""" + adapter = make_adapter(tmp_path) + # The byte layout is the whole test, so it is computed rather than guessed: the + # seek must land INSIDE the matching line, and far enough into its leading junk + # that the surviving fragment would STILL match. Otherwise the test passes for + # the wrong reason — an earlier version padded so heavily that the matching line + # fell entirely outside the 64 KiB window, so it went green with the + # fragment-drop deleted and proved nothing. + prefix = b"P" * 50 + straddler = b"J" * 200 + b"API Error: Connection refused\n" # 230 bytes + cut_into_line = 10 + filler = b"filler line\n" # 12 bytes, matches nothing + tail_bytes = generic.ENV_FAULT_TAIL_BYTES - len(straddler) + cut_into_line + assert tail_bytes % len(filler) == 0 # exact fill; no accidental re-alignment + _write_task_log(adapter, prefix + straddler + filler * (tail_bytes // len(filler))) + + log = adapter.logs_dir / f"{_ENV_FAULT_TASK}.log" + size = log.stat().st_size + seek = size - generic.ENV_FAULT_TAIL_BYTES + assert size > generic.ENV_FAULT_TAIL_BYTES # the tail read actually truncates + assert len(prefix) < seek < len(prefix) + len(straddler) # cut is inside the line + # And the surviving fragment still carries the full pattern, so dropping it is + # the ONLY reason this must not classify. + assert b"API Error: Connection refused" in log.read_bytes()[seek:] + + result = _classify(adapter, "timeout") + assert result.env_fault is False + assert result.env_fault_evidence is None + + +def test_classify_env_fault_scans_a_truncated_window_with_no_newline(tmp_path): + """A >tail-window log containing NO newline is a single fragment. Dropping it + as a straddler would leave nothing to scan — trading a cosmetic half-line for + a missed outage, which is the wrong way round. The fragment is scanned; the + leading ellipsis marks that it is a window, not a whole line.""" + adapter = make_adapter(tmp_path) + hit = b"API Error: Connection refused" + _write_task_log(adapter, b"x" * (generic.ENV_FAULT_TAIL_BYTES + 10) + hit) + result = _classify(adapter, "timeout") + assert result.env_fault is True + assert result.env_fault_evidence.startswith("…") + assert "API Error: Connection refused" in result.env_fault_evidence diff --git a/tests/test_opencode_http.py b/tests/test_opencode_http.py index 2d3760f3..6eb194d3 100644 --- a/tests/test_opencode_http.py +++ b/tests/test_opencode_http.py @@ -25,7 +25,7 @@ from conftest import write_script_launcher from bmad_loop.adapters import generic, opencode_http -from bmad_loop.adapters.base import SessionHandle, SessionSpec +from bmad_loop.adapters.base import SessionHandle, SessionResult, SessionSpec from bmad_loop.adapters.generic import BUDGET_NUDGE_TEXT, NUDGE_TEXT, STALL_NUDGE_TEXT from bmad_loop.adapters.opencode_http import ( _RESET, @@ -74,6 +74,10 @@ # reconnect); the turn completes result+messages only — # completion is reachable only via the HTTP poll fallback # FAKE_OPENCODE_START_FAILURES=N makes the first N spawns exit(1) pre-bind. +# FAKE_OPENCODE_LOG_LINE: written to the server's own stdout at the top of every +# turn — i.e. into logs/.server.out, which is the channel the env-fault +# post-mortem reads (NOT .log, the curated conversation transcript). +# Unset = silent, so every other scenario is unaffected. # FAKE_OPENCODE_SPEC_PATH/_SPEC_TEXT: a bmad-dev-auto-style terminal spec the # turn writes wherever a scenario writes its result (and at the start of # busy-forever, for the post-kill rescue). Unset = no-op, like RESULT_PATH. @@ -88,6 +92,7 @@ SCENARIO = os.environ.get("FAKE_OPENCODE_SCENARIO", "completed") REC_DIR = os.environ["FAKE_OPENCODE_DIR"] RESULT_PATH = os.environ.get("FAKE_OPENCODE_RESULT_PATH", "") +LOG_LINE = os.environ.get("FAKE_OPENCODE_LOG_LINE", "") SPEC_PATH = os.environ.get("FAKE_OPENCODE_SPEC_PATH", "") SPEC_TEXT = os.environ.get("FAKE_OPENCODE_SPEC_TEXT", "") START_FAILURES = int(os.environ.get("FAKE_OPENCODE_START_FAILURES", "0")) @@ -163,6 +168,8 @@ def run_turn(): with LOCK: STATE["busy"] = True n = STATE["prompts"] + if LOG_LINE: + print(LOG_LINE, flush=True) # stdout is the adapter's tee'd session log # let the 204 flush before any scripted death tears the connection down time.sleep(0.15) if SCENARIO == "completed": @@ -2383,3 +2390,180 @@ def test_e2e_dev_wait_loop_drives_observe_tick(tmp_path, fake_opencode, monkeypa assert result.status == "completed" assert seen and all(tid == "3-1-dev-1" and same for tid, same in seen) assert_server_gone(rec) + + +# --------------------------------------------------------------- env fault (#194) +# The HTTP adapter went without env-fault classification entirely while the tmux +# adapter had it, because the hook was implemented on GenericAdapter rather than +# shared — so a 5-hour provider quota outage read as three healthy stories timing +# out and burned their retry budgets. The classifier now lives in EnvFaultMixin; +# these tests assert this adapter actually inherits it, which is the regression +# that matters (the mechanics themselves are covered in test_generic_tmux.py). +# +# This adapter's log is the `opencode serve` process's own stdout/stderr, not a +# tmux pane capture, so the lines below keep the server's logfmt SHAPE and the +# provider's verbatim AI_APICallError text (that text is what the patterns key +# on) — but every session/run identifier is a synthetic stand-in, not the real +# one from the outage, which came from a private client project's run. +_EF_TASK = "17-1b-dev-1" + +_QUOTA_LINE = ( + 'timestamp=2026-07-26T13:12:53.262Z level=ERROR run=fake0001 message="stream error" ' + "providerID=zai-coding-plan modelID=glm-5.2 session.id=ses_fake0000000000000000000001 " + 'small=false agent=general mode=subagent error.error="AI_APICallError: Usage limit ' + 'reached for 5 hour. Your limit will reset at 2026-07-26 22:49:46"' +) +_SOCKET_LINE = ( + 'timestamp=2026-07-26T22:52:57.193Z level=ERROR run=fake0002 message="stream error" ' + 'providerID=zai-coding-plan modelID=glm-5.2 error.error="AI_APICallError: Cannot ' + 'connect to API: The socket connection was closed unexpectedly."' +) + + +def _ef_classify(adapter, status, *, result_json=None, task_id=_EF_TASK): + handle = SessionHandle(task_id=task_id, native_id=task_id) + spec = SessionSpec(task_id=task_id, role="dev", prompt="/x", cwd=adapter.run_dir) + return adapter._classify_env_fault( + handle, spec, SessionResult(status=status, result_json=result_json) + ) + + +def _write_ef_log(adapter, text: str, task_id: str = _EF_TASK) -> None: + """Writes to whatever file the adapter actually scans, not a hardcoded name. + + These unit tests are deliberately blind to WHICH file that is — asserting the + suffix here would just restate the implementation. Pinning the wiring is + test_e2e_env_fault_classified_through_run's job, and it is the only thing that + caught the scan pointing at the wrong file after .log became the + conversation transcript.""" + adapter._env_fault_log_path(task_id).write_text(text, encoding="utf-8") + + +@pytest.mark.parametrize("line", [_QUOTA_LINE, _SOCKET_LINE]) +def test_opencode_classifies_provider_quota_as_env_fault(tmp_path, line): + """The headline regression: a timed-out session whose server log carries the + provider's refusal is an environment fault, not a failed story attempt.""" + adapter = make_adapter(tmp_path) + _write_ef_log(adapter, f"listening on 127.0.0.1\n{line}\ncleanup prune=7.days\n") + result = _ef_classify(adapter, "timeout") + assert result.env_fault is True + assert result.status == "timeout" # the verdict string is unchanged + assert "AI_APICallError" in result.env_fault_evidence + + +def test_opencode_env_fault_writes_lifecycle_breadcrumb(tmp_path): + adapter = make_adapter(tmp_path) + _write_ef_log(adapter, _QUOTA_LINE + "\n") + _ef_classify(adapter, "timeout") + events = [ + json.loads(line) + for line in (adapter.tasks_dir / _EF_TASK / "session-lifecycle.jsonl") + .read_text(encoding="utf-8") + .splitlines() + ] + assert [e["event"] for e in events] == ["env-fault-classified"] + assert events[0]["status"] == "timeout" + assert "Usage limit reached" in events[0]["evidence"] + + +def test_opencode_healthy_timeout_is_not_an_env_fault(tmp_path): + """The other half: an ordinary timeout whose log holds only normal server + chatter stays a real dev attempt. Classifying this would let a genuinely + stuck story pause the run forever instead of retrying.""" + adapter = make_adapter(tmp_path) + _write_ef_log( + adapter, + "timestamp=2026-07-26T15:45:39.732Z level=INFO message=stream " + "providerID=zai-coding-plan modelID=glm-5.2\ncleanup prune=7.days\n", + ) + result = _ef_classify(adapter, "timeout") + assert result.env_fault is False + assert result.env_fault_evidence is None + + +def test_opencode_env_fault_skips_completed_and_result_bearing(tmp_path): + """`completed` never reaches the scan, and a result-bearing verdict is a + session that did real work — a reconcile upgrade must not be re-classified.""" + adapter = make_adapter(tmp_path) + _write_ef_log(adapter, _QUOTA_LINE + "\n") + assert _ef_classify(adapter, "completed").env_fault is False + assert _ef_classify(adapter, "timeout", result_json={"status": "done"}).env_fault is False + assert not (adapter.tasks_dir / _EF_TASK / "session-lifecycle.jsonl").exists() + + +def test_opencode_env_fault_missing_log_degrades_silently(tmp_path): + """Best-effort doctrine: an unreadable log leaves the verdict untouched.""" + adapter = make_adapter(tmp_path) + result = _ef_classify(adapter, "timeout", task_id="never-ran") + assert result.env_fault is False + + +def test_e2e_env_fault_classified_through_run(tmp_path, fake_opencode): + """The wiring, not just the inheritance: every test above calls + _classify_env_fault directly, and all of them would still pass if + CodingCLIAdapter.run() never invoked the hook for this adapter — which is + exactly the regression (#194 went unclassified here for that reason). + + So drive a real session end to end: the fake server logs the provider's + refusal to its own stdout (logs/.server.out — NOT .log, the + curated conversation transcript) at the top of a turn that then never + finishes, the session idles out its clock, and the SessionResult that comes + back out of run() must carry the classification.""" + launcher, rec = fake_opencode + adapter = make_adapter(tmp_path, binary=str(launcher)) + spec = make_spec( + tmp_path, + rec, + "busy-forever", + timeout_s=1.5, + extra_env={"FAKE_OPENCODE_LOG_LINE": _QUOTA_LINE}, + ) + + result = adapter.run(spec) + + assert result.status == "timeout" # the verdict string is unchanged + assert result.result_json is None + assert result.env_fault is True + assert "Usage limit reached" in result.env_fault_evidence + # The signal came off the SERVER log specifically. Named literally rather than + # via adapter._env_fault_log_path, because this assertion exists to catch the + # scan being pointed at the wrong file — resolving the path through the code + # under test would make it agree with any answer. .log is the curated + # conversation transcript and must NOT be the source here. + logs = tmp_path / "run" / "logs" + assert "AI_APICallError" in (logs / "t-1.server.out").read_text(encoding="utf-8") + assert "AI_APICallError" not in (logs / "t-1.log").read_text(encoding="utf-8") + events = read_jsonl(tmp_path / "run" / "tasks" / "t-1" / "session-lifecycle.jsonl") + assert [e["event"] for e in events][-1:] == ["env-fault-classified"] + assert_server_gone(rec) + + +def test_env_fault_log_is_dropped_at_session_start(tmp_path, fake_opencode): + """A re-armed run reusing a task_id must not classify off the PREVIOUS cycle's + provider error. + + This is the pause loop the classifier would otherwise create for itself: an + env fault PAUSEs the run, the operator re-arms and resumes, and the next + session — however healthy its own log — rescans the stale refusal and pauses + again, forever. GenericAdapter.start_session unlinks its pane tee for exactly + this reason; the server sink needs the same treatment. + + Drives a real session so the unlink is exercised through the actual spawn + path, not asserted against a hand-placed file.""" + launcher, rec = fake_opencode + adapter = make_adapter(tmp_path, binary=str(launcher)) + stale = adapter._env_fault_log_path("t-1") + stale.parent.mkdir(parents=True, exist_ok=True) + stale.write_text(_QUOTA_LINE + "\n", encoding="utf-8") + + # This cycle times out with the provider saying NOTHING (no FAKE_OPENCODE_LOG_LINE), + # so it is eligible for classification and the only quota line anywhere is the + # stale one. Deliberately a non-completed verdict: `completed` short-circuits + # the classifier before it reads a byte, so it would pass with or without the + # unlink and prove nothing. + spec = make_spec(tmp_path, rec, "busy-forever", timeout_s=1.5) + result = adapter.run(spec) + + assert result.status == "timeout" + assert result.env_fault is False, f"classified off a stale log: {result.env_fault_evidence}" + assert "Usage limit reached" not in stale.read_text(encoding="utf-8", errors="replace") diff --git a/tests/test_profile.py b/tests/test_profile.py index f3deeb80..e8efdf69 100644 --- a/tests/test_profile.py +++ b/tests/test_profile.py @@ -75,11 +75,17 @@ def test_builtin_profiles_load(): for name in sorted(set(profiles) - {"claude"}): assert "CLAUDE_CODE_DISABLE_ALTERNATE_SCREEN" not in profiles[name].env assert "CLAUDE_CODE_DISABLE_BACKGROUND_TASKS" not in profiles[name].env - # transport-failure classification (#194): only claude seeds env_fault_patterns - # (the "API Error … connection cause" signature); every other built-in ships - # none, so classification stays inert until a project overlay adds patterns - assert profiles["claude"].env_fault_patterns # non-empty - for name in ("codex", "gemini", "copilot", "antigravity", "opencode-http"): + # transport/provider fault classification (#194): only the two profiles with + # captured real-world error output seed patterns — claude (the "API Error … + # connection cause" signature) and opencode-http (the serve process's + # `error.error="AI_APICallError: …"` field). The other four stay inert on + # purpose: patterns for them could only be written from strings scraped off + # public issue trackers, and an unverified pattern that fires on a healthy + # session pauses the whole run. Precision is asserted in + # tests/test_env_fault_patterns.py; here we only pin which profiles are seeded. + for name in ("claude", "opencode-http"): + assert profiles[name].env_fault_patterns, f"{name} ships no env_fault_patterns" + for name in ("codex", "gemini", "copilot", "antigravity"): assert profiles[name].env_fault_patterns == () # opencode-http is hookless (HTTP/SSE transport): no hook dialect surfaces, # skills read from the claude tree, usage comes over HTTP (no transcript parser)