From af5272cbcabf92a5561677d02f5af50977b9dbdc Mon Sep 17 00:00:00 2001 From: Seongho Bae Date: Sun, 6 Sep 2026 17:23:33 +0900 Subject: [PATCH] fix(strix): sanitize strix-agent's recovered transient replay warning MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A completed scan (run.json completed, SARIF 0 results, attempt exit 0) was failed closed as STRIX_PROVIDER_UNAVAILABLE on .github#1689 run 34013778497 because three `strix.core.execution: transient model/provider error for ; replaying turn (attempt n/m, backoff Ns): …` WARNING lines survived sanitize_known_strix_report_warnings and tripped the report WARNING scan. strix-agent 1.5.3 emits that line only inside its bounded transient-retry branch (strix/core/execution.py:763), immediately before the replay runs; an exhausted retry logs `agent run failed for …; marking failed` at ERROR with a traceback and exits non-zero, and both of those still fail the gate. Two tests cover the production argument shape, where the reports root is passed and has_strix_report_failure_signal narrows to the newest run directory via latest_strix_report_dir, so the sanitized tree and the scanned tree are demonstrably the same one. The CHANGELOG records one side effect: a provider 503 body that appears only inside a retry line's exception repr is removed with that line, which can make the report-only branch of is_model_retryable_error read an outage as non-retryable. The direction is fail-closed and the contextual-orchestrator verdict branch answers first, so no path changes outcome today. Coupled to the strix-agent 1.5.3 execution.py:763 message format, like the two existing alternatives — re-verify on every strix-agent bump. Co-Authored-By: Claude Opus 5 --- CHANGELOG.md | 4 + scripts/ci/strix_quick_gate.sh | 15 +- ...est_strix_recovered_transient_sanitizer.py | 284 ++++++++++++++++++ 3 files changed, 302 insertions(+), 1 deletion(-) create mode 100644 tests/test_strix_recovered_transient_sanitizer.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 75a4109c9d..c59bce5b99 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,7 @@ +### Strix gate keeps a recovered transient model error from failing a completed scan + +- `scripts/ci/strix_quick_gate.sh` `sanitize_known_strix_report_warnings` now also strips strix-agent's `strix.core.execution: transient model/provider error for ; replaying turn (attempt n/m, backoff Ns): …` WARNING lines before the report failure-signal scan. strix-agent 1.5.3 (`strix/core/execution.py:763`) emits that line only inside its bounded transient-retry branch, immediately before the replay runs; an exhausted retry logs `agent run failed for …; marking failed` at ERROR with a traceback and exits non-zero, and both of those still fail the gate. Observed on `.github#1689` run `34013778497`: a completed 63-minute scan (`run.json` `completed`, SARIF 0 results, attempt exit 0) was failed closed as `STRIX_PROVIDER_UNAVAILABLE … exhausted` on three such warnings, and the scheduler then dispatched another same-head scan. The pattern is anchored before the exception repr so the same class keeps matching after a gateway pin advance changes the exception type; re-verify the message format on every strix-agent bump. One documented side effect: when a provider's 503 body appears only inside a retry line's exception repr, removing that line also removes the only text `has_strix_report_provider_failure_signal` would have matched in the report log, which can make `is_model_retryable_error`'s report-only branch read a genuine outage as non-retryable. The direction is fail-closed (an exhausted retry still exits non-zero with its ERROR and traceback retained), and with a contextual-orchestrator primary the verdict branch answers before that classifier is consulted, so no path today changes its outcome; if fallback-model classification is ever wanted for a non-gateway primary, read the pre-sanitize attempt copy that `preserve_attempt_log` already keeps. Tests: `tests/test_strix_recovered_transient_sanitizer.py`. + ### Strix gate names the sandbox bootstrap failure and retries it once - `scripts/ci/strix_quick_gate.sh` gives the Caido sandbox bootstrap race (`loginAsGuest failed after 10 attempts` on `127.0.0.1:`, upstream usestrix/strix#1036/#1037/#1056) its own bounded same-model retry budget, `STRIX_SANDBOX_BOOTSTRAP_RETRIES` (default 1), drawn on top of `STRIX_TRANSIENT_RETRY_PER_MODEL`. That budget is 0 in production because the gateway owns model failover, so the documented sandbox retry never ran: `argos` Strix run 34013128112 (2026-09-06) shows one attempt, `Docker image ready`, the proxy never reachable, Strix exiting after 240 s -- while the sidecar reported four ready and four deferred routes that were never called. The budget is charged in the same branch that grants the attempt, so a log matching the sandbox class together with a gateway class cannot extend the loop without charging it (caught by adversarial review of the first draft). The primary-scan verdict for that class now reads `STRIX_PROVIDER_UNAVAILABLE: STRIX_SANDBOX_UNAVAILABLE: the last Strix attempt ended in the sandbox bootstrap (...) after N sandbox-specific same-model retries (budget B); this verdict names Strix's sandbox, not the LLM gateway.` instead of `orchestrator/free exhausted`, stating only what the gate observed; the leading token is unchanged so the workflow's finding-free classification and its tests are untouched, and the second token lets the review census split sandbox outages from gateway ones (two of six recent Strix artifacts were this class). Refs #1948. diff --git a/scripts/ci/strix_quick_gate.sh b/scripts/ci/strix_quick_gate.sh index 617ca7c394..c08f2fa36c 100755 --- a/scripts/ci/strix_quick_gate.sh +++ b/scripts/ci/strix_quick_gate.sh @@ -178,11 +178,24 @@ import sys root = Path(sys.argv[1]) known_internal_warning = re.compile( r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d+ WARNING " - r"[^ ]+ - strix\.core\.execution: agent [0-9a-f]+ " + r"[^ ]+ - strix\.core\.execution: " + r"(?:" + r"agent [0-9a-f]+ " r"(?:" r"produced non-lifecycle final output in non-interactive mode" r"|ended a turn without a lifecycle tool call \(interactive=False\)" r"); forcing tool continuation \(\d+/\d+\): " + # strix-agent 1.5.3 strix/core/execution.py:763 logs this only inside its + # bounded transient-retry branch, immediately before the replay runs, so + # the line means "a retry is happening now", not "the scan failed". An + # exhausted retry logs `agent run failed for …; marking failed` at ERROR + # with a traceback and exits non-zero; neither of those is touched here. + # Anchored before the exception repr on purpose: the same class appears + # as InternalServerError today and as a different type after a gateway + # pin advance. Re-verify the message format on every strix-agent bump. + r"|transient model/provider error for [0-9a-f]+; replaying turn " + r"\(attempt \d+/\d+, backoff [0-9.]+s\): " + r")" ) known_scanner_warning = re.compile( r"^(?:│ MODEL QUALITY WARNING\s+│|" diff --git a/tests/test_strix_recovered_transient_sanitizer.py b/tests/test_strix_recovered_transient_sanitizer.py new file mode 100644 index 0000000000..28fda47205 --- /dev/null +++ b/tests/test_strix_recovered_transient_sanitizer.py @@ -0,0 +1,284 @@ +"""Regression contract for strix-agent's recovered transient model errors. + +strix-agent 1.5.3 (``strix/core/execution.py:760-763``) retries a transient +model/provider error up to ``_MAX_TRANSIENT_MODEL_RETRIES`` times and, inside +that branch only, logs:: + + WARNING - strix.core.execution: transient model/provider error for + ; replaying turn (attempt n/m, backoff Ns): + +immediately before the replay runs. The line therefore means "a retry is +happening now", never "the scan failed". When the budget is exhausted the same +module logs ``agent run failed for ; marking failed`` at ERROR with a +traceback and the process exits non-zero. + +Observed on ContextualWisdomLab/.github#1689 run ``34013778497``: a completed +63-minute scan (``run.json`` status ``completed``, SARIF 0 results, attempt exit +code 0) was failed closed as ``STRIX_PROVIDER_UNAVAILABLE … exhausted`` because +three such WARNING lines survived ``sanitize_known_strix_report_warnings`` and +tripped ``has_strix_report_failure_signal``'s ``WARNING`` scan. + +Negative control, as measured by running this file against ``main``'s gate before +this change: **3 failed, 4 passed.** The three that fail are +``test_recovered_transient_replay_warnings_are_sanitized`` (the lines remain and +the failure signal fires), ``test_production_argument_shape_sanitizes_the_scanned_directory`` +(the same, through the narrowing branch), and +``test_unrecovered_transient_keeps_the_error_and_traceback`` on its first assertion +only, since ``assertNotIn("replaying turn", ...)`` also needs the new alternative +while its ERROR-and-traceback retention assertions hold on both gates. The four +that pass on both gates are the guards: the two unknown-warning cases, the +foreign-module case, and the pre-existing forced-continuation case. +""" + +from __future__ import annotations + +import re +import subprocess +import tempfile +import unittest +from pathlib import Path + + +REPOSITORY_ROOT = Path(__file__).resolve().parents[1] +STRIX_GATE = REPOSITORY_ROOT / "scripts" / "ci" / "strix_quick_gate.sh" + +_PREFIX = "strix-pr-scope-qd1fsv_9ee6 - strix.core.execution: " + +# The three lines exactly as the run above wrote them (490 characters each). +_REPR = ( + "InternalServerError(\"Error code: 500 - {'error': {'code': 'internal_error', " + "'message': 'internal server error', 'detail': {'request_id': '%s'}}, " + "'error_code': 'internal_error', 'error_message': 'internal server error', " + "'error_detail': {'request_id': '%s'}}\")" +) +RECOVERED_LOG = ( + "2026-09-06 07:23:08.199 WARNING " + _PREFIX + + "transient model/provider error for 76d3c83d; replaying turn " + "(attempt 1/5, backoff 2.0s): " + + _REPR % ("466c7aee94e24a6e811cbd7fd12bc1a9", "466c7aee94e24a6e811cbd7fd12bc1a9") + + "\n" + "2026-09-06 07:23:10.205 DEBUG strix-pr-scope-qd1fsv_9ee6 - " + "strix.llm.context_budget: No LiteLLM model info for 'openai/orchestrator/free'; " + "using configured fallbacks\n" + "2026-09-06 07:45:20.154 WARNING " + _PREFIX + + "transient model/provider error for 76d3c83d; replaying turn " + "(attempt 2/5, backoff 4.0s): " + + _REPR % ("6dbf7b28ee16448592e10bb9728a523f", "6dbf7b28ee16448592e10bb9728a523f") + + "\n" + "2026-09-06 07:58:54.623 WARNING " + _PREFIX + + "transient model/provider error for 76d3c83d; replaying turn " + "(attempt 3/5, backoff 8.0s): " + + _REPR % ("a85b9828eb754e129f62d202359ea316", "a85b9828eb754e129f62d202359ea316") + + "\n" + "2026-09-06 08:09:35.584 INFO strix-pr-scope-qd1fsv_9ee6 - " + "strix.core.runner: Strix scan strix-pr-scope-qd1fsv_9ee6 done\n" +) + +# After the bounded budget is spent strix-agent logs at ERROR with a traceback +# (observed on a same-day run) and exits non-zero. The sanitizer must leave it. +UNRECOVERED_LOG = ( + "2026-09-06 07:24:31.010 WARNING strix-pr-scope-5p3h3c_e0d0 - " + "strix.core.execution: transient model/provider error for 6c480eb0; " + "replaying turn (attempt 5/5, backoff 32.0s): InternalServerError(\"Error code: 500\")\n" + "2026-09-06 07:24:40.562 ERROR strix-pr-scope-5p3h3c_e0d0 - " + "strix.core.execution: agent run failed for 6c480eb0; marking failed\n" + "Traceback (most recent call last):\n" + ' File "/opt/hostedtoolcache/Python/3.13.15/x64/lib/python3.13/site-packages/' + 'strix/core/execution.py", line 676, in _run_cycle\n' + " async for event in stream.stream_events():\n" + "openai.InternalServerError: Error code: 500\n" +) + +UNKNOWN_WARNING_LOG = ( + "2026-09-06 07:30:00.000 WARNING strix-pr-scope-qd1fsv_9ee6 - " + "strix.core.execution: transient model/provider error for 76d3c83d; " + "giving up after 5 attempts\n" +) + +# A different module echoing the same words must not be sanitized: the anchor +# is the logger name, not the phrase. +FOREIGN_MODULE_LOG = ( + "2026-09-06 07:30:00.000 WARNING strix-pr-scope-qd1fsv_9ee6 - " + "strix.tools.browser: transient model/provider error for 76d3c83d; " + "replaying turn (attempt 1/5, backoff 2.0s): Timeout\n" +) + +LEGACY_LOG = ( + "2026-06-18 13:08:05.986 WARNING strix-pr-scope-example - strix.core.execution: " + "agent a9fb4033 produced non-lifecycle final output in non-interactive mode; " + "forcing tool continuation (1/3): {'x': 1}\n" + "2026-08-22 09:53:26.193 WARNING strix-pr-scope-example - strix.core.execution: " + "agent 673f770f ended a turn without a lifecycle tool call (interactive=False); " + "forcing tool continuation (2/3): done\n" + "2026-06-18 13:10:44.089 INFO strix-pr-scope-example - strix.tools.finish.tool: " + "finish_scan: completed scan with 0 vulnerability report(s)\n" +) + + +def _function_block(source: str, function_name: str) -> str: + """Return one top-level Bash function, including its closing brace.""" + + match = re.search( + rf"(?ms)^{re.escape(function_name)}\(\) \{{\n.*?^\}}\n", + source, + ) + if match is None: + raise AssertionError(f"missing Bash function: {function_name}") + return match.group(0) + + +def _sanitize_then_signal(log_text: str) -> tuple[str, bool]: + """Run the production sanitizer, then the production failure-signal scan. + + Returns the report log's remaining text and whether + ``has_strix_report_failure_signal`` still fires on it. The report root is a + plain temp directory, so the function's ``STRIX_REPORTS_DIR`` branch + (which resolves the newest run) is not taken and needs no helper. + """ + + gate_source = STRIX_GATE.read_text(encoding="utf-8") + blocks = [ + _function_block(gate_source, name) + for name in ( + "sanitize_known_strix_report_warnings", + "has_strix_report_failure_signal", + ) + ] + with tempfile.TemporaryDirectory(prefix="strix-recovered-transient-") as temp_dir: + report_root = Path(temp_dir) / "strix_runs" / "strix-pr-scope-qd1fsv_9ee6" + report_root.mkdir(parents=True) + log_path = report_root / "strix.log" + log_path.write_text(log_text, encoding="utf-8") + script = "\n".join( + ( + "set -uo pipefail", + 'STRIX_REPORTS_DIR="/nonexistent/strix-reports"', + *blocks, + 'sanitize_known_strix_report_warnings "$1"', + 'if has_strix_report_failure_signal "$1"; then echo signal=1; else echo signal=0; fi', + ) + ) + completed = subprocess.run( + ["bash", "-c", script, "strix-sanitizer", str(report_root)], + check=False, + capture_output=True, + text=True, + ) + remaining = log_path.read_text(encoding="utf-8") + if completed.returncode != 0: + raise AssertionError(f"rc={completed.returncode}\n{completed.stderr}") + return remaining, "signal=1" in completed.stdout + + +def _sanitize_then_signal_production_shape(log_text: str) -> tuple[str, bool]: + """Same sequence with the argument shape production actually uses. + + Production passes ``ACTIVE_REPORTS_DIR``, which equals ``STRIX_REPORTS_DIR``, + so ``has_strix_report_failure_signal`` takes its narrowing branch and scans + only ``latest_strix_report_dir``'s newest run directory. ``_sanitize_then_signal`` + hands in that run directory directly and therefore skips the branch; this + helper covers it, so the pair proves the sanitized tree and the scanned tree + are the same one. + """ + + gate_source = STRIX_GATE.read_text(encoding="utf-8") + blocks = [ + _function_block(gate_source, name) + for name in ( + "sanitize_known_strix_report_warnings", + "has_strix_report_failure_signal", + "latest_strix_report_dir", + "is_preexisting_report_dir", + ) + ] + with tempfile.TemporaryDirectory(prefix="strix-recovered-transient-prod-") as temp_dir: + reports_root = Path(temp_dir) / "reports" + run_dir = reports_root / "strix-pr-scope-qd1fsv_9ee6" + run_dir.mkdir(parents=True) + log_path = run_dir / "strix.log" + log_path.write_text(log_text, encoding="utf-8") + script = "\n".join( + ( + "set -uo pipefail", + f'STRIX_REPORTS_DIR="{reports_root}"', + # Non-empty so "${PREEXISTING_REPORT_DIRS[@]}" is safe under set -u. + 'PREEXISTING_REPORT_DIRS=("/nonexistent/preexisting")', + *blocks, + 'sanitize_known_strix_report_warnings "$STRIX_REPORTS_DIR"', + 'if has_strix_report_failure_signal "$STRIX_REPORTS_DIR"; then echo signal=1; else echo signal=0; fi', + ) + ) + completed = subprocess.run( + ["bash", "-c", script, "strix-sanitizer-prod"], + check=False, + capture_output=True, + text=True, + ) + remaining = log_path.read_text(encoding="utf-8") + if completed.returncode != 0: + raise AssertionError(f"rc={completed.returncode}\n{completed.stderr}") + return remaining, "signal=1" in completed.stdout + + +class StrixRecoveredTransientSanitizerTests(unittest.TestCase): + """Keep a recovered transient model error from failing a completed scan.""" + + def test_recovered_transient_replay_warnings_are_sanitized(self) -> None: + """The three observed lines are removed and the WARNING scan stays quiet.""" + + remaining, signal = _sanitize_then_signal(RECOVERED_LOG) + self.assertNotIn("replaying turn", remaining) + self.assertNotIn("InternalServerError", remaining) + self.assertIn("strix.core.runner: Strix scan strix-pr-scope-qd1fsv_9ee6 done", remaining) + self.assertIn("strix.llm.context_budget", remaining) + self.assertFalse(signal) + + def test_unrecovered_transient_keeps_the_error_and_traceback(self) -> None: + """Only the retry line goes; the ERROR record and its traceback stay for the rc!=0 path.""" + + remaining, _signal = _sanitize_then_signal(UNRECOVERED_LOG) + self.assertNotIn("replaying turn", remaining) + self.assertIn("agent run failed for 6c480eb0; marking failed", remaining) + self.assertIn("Traceback (most recent call last):", remaining) + self.assertIn("openai.InternalServerError: Error code: 500", remaining) + + def test_unknown_execution_warning_still_fails_closed(self) -> None: + """A WARNING from the same logger with a different message is not sanitized.""" + + remaining, signal = _sanitize_then_signal(UNKNOWN_WARNING_LOG) + self.assertEqual(remaining, UNKNOWN_WARNING_LOG) + self.assertTrue(signal) + + def test_same_words_from_another_module_still_fail_closed(self) -> None: + """The anchor is the strix.core.execution logger, not the phrase.""" + + remaining, signal = _sanitize_then_signal(FOREIGN_MODULE_LOG) + self.assertEqual(remaining, FOREIGN_MODULE_LOG) + self.assertTrue(signal) + + def test_production_argument_shape_sanitizes_the_scanned_directory(self) -> None: + """With the reports root passed as production passes it, the narrowed scan is quiet.""" + + remaining, signal = _sanitize_then_signal_production_shape(RECOVERED_LOG) + self.assertNotIn("replaying turn", remaining) + self.assertIn("strix.core.runner: Strix scan strix-pr-scope-qd1fsv_9ee6 done", remaining) + self.assertFalse(signal) + + def test_production_argument_shape_still_fails_closed_on_an_unknown_warning(self) -> None: + """The narrowing branch does not swallow a warning the sanitizer does not know.""" + + remaining, signal = _sanitize_then_signal_production_shape(UNKNOWN_WARNING_LOG) + self.assertEqual(remaining, UNKNOWN_WARNING_LOG) + self.assertTrue(signal) + + def test_existing_forced_continuation_warnings_remain_sanitized(self) -> None: + """The two pre-existing alternatives keep working after the regex restructure.""" + + remaining, signal = _sanitize_then_signal(LEGACY_LOG) + self.assertNotIn("forcing tool continuation", remaining) + self.assertIn("finish_scan: completed scan with 0 vulnerability report(s)", remaining) + self.assertFalse(signal) + + +if __name__ == "__main__": + unittest.main()