From 64efb7ef9a1e9066122c762a22592f172bbb1e4c Mon Sep 17 00:00:00 2001 From: Jack McIntyre Date: Mon, 27 Jul 2026 10:37:31 +1000 Subject: [PATCH] fix(adapters,profiles): classify provider quota as an env fault on opencode-http MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A hard provider usage-limit error was not recognised as an environment fault. The loop recorded env_fault=false, spent max_dev_attempts on the story, deferred it, and moved to the next story — which hit the same wall. One 5-hour quota window became three deferred stories and seven dead sessions, four of which consumed zero tokens. STRUCTURAL FIX. run() has always called _classify_env_fault for every adapter (adapters/base.py), but the implementation lived on GenericAdapter while OpencodeHttpAdapter is its sibling, not its subclass — so the base identity no-op applied and the feature was absent. Its docstring justified that with "adapters with no post-mortem signal (HTTP/mock)", a premise that stopped being true once opencode_http began teeing the serve process's stdout/stderr to logs/.log — the exact path the classifier reads. Hoist the classifier into adapters/env_fault.EnvFaultMixin and mix it into both adapters. The signal is the log, not the transport, so any adapter writing logs/.log inherits it rather than re-omitting it. Patterns compile lazily off self.profile, so mixing the class in is the whole wiring step — there is no __init__ line to forget, which is how this was missed. WHICH FILE IS SCANNED IS PART OF THE CONTRACT. EnvFaultMixin gained ENV_FAULT_LOG_SUFFIX; opencode overrides it to ".server.out". Its ".log" is the curated [bmad] conversation transcript written by the SSE reader, so it carries the model's own words, while the provider's AI_APICallError logfmt lines only ever land in the server sink. Scanning the transcript would break two things at once: the evidence would not be there, and the profile's patterns — which are only sound against a model-free log — would start matching stories that quote a provider error. Unit tests could not catch this (they write their fixture to whatever path the code resolves); only the end-to-end test through run() did. The scanned file is also DROPPED at start_session, mirroring what GenericAdapter already does with its pane tee. A re-armed run reuses task_ids and the server sink is opened "ab", so without this the next session would scan the PREVIOUS cycle's provider error — and this bites hardest on the exact path the classifier serves: env fault pauses the run, the operator re-arms, the next session rescans the stale refusal and pauses again, however healthy its own log. A pause loop surviving every re-arm, off one stale line. PATTERNS: ONE PROFILE, DELIBERATELY. opencode.toml is seeded, anchored on the structured field the serve process emits (error.error="AI_APICallError: …") and verified by replaying the shipped profile through the mixin over a real outage's logs: four sessions classify, the healthy merged story's do not, and the first hit lands on story 2's second attempt — where the run now pauses instead of marching into stories 3, 4 and 5. The gap inside that pattern is [^"], not `.`, so it cannot walk past the closing quote and find a cause word in a later logfmt field — otherwise an unrelated `AI_APICallError: Invalid API key` on a line whose trailing fields mention a quota path reads as a quota outage. codex, gemini, copilot and antigravity stay INERT. Patterns for them were drafted and withdrawn. They could only be written from error strings scraped off public issue trackers, for CLIs nobody here has run, and an unverified pattern is not a neutral bet: the tmux adapters match against a pane capture containing the model's own output, so a pattern that fires on a story which merely *implements* rate limiting pauses a healthy run. That inverse bug is worse than the miss, because the miss only reproduces today's behaviour. An adversarial pass demonstrated it on realistic fixture and assertion text before these shipped. A quota pattern was drafted for claude.toml and withdrawn for the same reason, so that profile is untouched from main: an Anthropic plan's usage limit is still unclassified. Its existing connection pattern already matches ordinary prose about provider errors — including this repo's own CHANGELOG and docs — which is pre-existing #194 debt, now pinned by an xfail(strict) test rather than left undocumented. ALSO FIXED in the classifier, both found by adversarial review: - The 64 KiB tail seek lands on an arbitrary byte, so the line straddling the window edge arrived as a fragment whose head could be a U+FFFD from the errors="replace" decode. That fragment is now discarded rather than matched and quoted as evidence. - _excerpt marked a dropped prefix but silently dropped a suffix, so a truncated excerpt read as a complete line that simply ended there. Both ends are marked now, and the markers are spent FROM the evidence budget rather than added on top of it. - The evidence window is centred on the match rather than the line head: an opencode logfmt line carries ~250 characters of metadata before error.error=, so the operator previously saw every field except the failure. Test corpora are split into the half that must classify (captured error lines), the half that must not (realistic healthy-session output), and a third that pins the LIMIT of content-based matching: a story quoting a provider error verbatim produces a line byte-identical to the emitted one, so it matches and no pattern can separate them. That is acceptable here only because opencode's scanned log is the serve process's own stdout, which the model cannot write to; it is asserted positively so it cannot change silently. Reachability of the bait is itself asserted — this corpus was briefly vacuous, guarding nothing while looking thorough, after the profile it had been written for was withdrawn. Correlation ids in the test corpora are fakes; the run they were captured from is a private project. Claude-Session: https://claude.ai/code/session_01TXq8NfCFZv922RYqx1kU3s --- src/bmad_loop/adapters/base.py | 22 +- src/bmad_loop/adapters/env_fault.py | 261 +++++++++++++ src/bmad_loop/adapters/generic.py | 109 +----- src/bmad_loop/adapters/opencode_http.py | 24 +- src/bmad_loop/adapters/profile.py | 19 +- src/bmad_loop/data/profiles/opencode.toml | 36 ++ tests/test_env_fault_patterns.py | 442 ++++++++++++++++++++++ tests/test_generic_tmux.py | 81 +++- tests/test_opencode_http.py | 186 ++++++++- tests/test_profile.py | 16 +- 10 files changed, 1080 insertions(+), 116 deletions(-) create mode 100644 src/bmad_loop/adapters/env_fault.py create mode 100644 tests/test_env_fault_patterns.py 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)