fix(sidecar): let the stream sanitizer pass orchestrator route and circuit events

CHANGELOG.md

@@ -1,3 +1,6 @@
+### Sidecar sanitizer admits orchestrator route and circuit events
+
+- `scripts/ci/sanitize_contextual_orchestrator_sidecar_stream.py` now passes the orchestrator's own `provider_attempt`, `provider_attempt_failed` (cut before the free-text `error_message=`), `provider_backoff`, `provider_exhausted`, `provider_rejected_permanent`, `provider_no_retry_budget` and `circuit_failure|opened|reset|cleared` lines (whose `failures`/`reset_seconds` are floats at runtime, `2.0`/`30.0`), matched field by field against bounded identifier and number charsets, with either Python's default `LEVEL:name:` prefix or the sidecar formatter's `asctime LEVEL name` prefix (the timestamp is kept so per-route durations can be read as differences). Until now every one of these lines was folded into `omitted_unstructured_lines`, so the `provider_exhausted` WARNING that already fires today after a route's retry budget is spent never reached an artifact, and a 3122 s walk across six ready routes (run `33981136873`) had no per-route trace. Companion to #1943 (sidecar DEBUG logging) and #1944 (Noema uploads the file on failure). Refs #1935, #1939.
 ### Review sidecar records the orchestrator's per-attempt trace
 
 - `contextual_orchestrator_review_launcher.py` now configures the orchestrator process's logging before serving (`_configure_sidecar_logging`, calling the vendored `contextual_orchestrator.debug_logging.configure_logging`), defaulting to `DEBUG` with a timestamped format and overridable through `ORCHESTRATOR_SIDECAR_LOG_LEVEL`. The orchestrator logs every provider attempt, its classified failure, backoff, and circuit event at `DEBUG` and only `provider_exhausted`/`circuit_opened` at the default `WARNING`, so a failed review left no way to see which routes were tried or how long each took: a 3122 s `noema-review` 502 on 2026-09-05 could only be attributed to "six ready routes, two retry layers, about 548 s per hop" by reading source, not the log. None of the `DEBUG` sites at the vendored pin carries prompt or response content, and the sidecar already pipes this stderr through the redacting sanitizer before it is written to `strix_runs/contextual-orchestrator-sidecar.stderr.log`; a companion change uploads that file as a failure artifact.

scripts/ci/sanitize_contextual_orchestrator_sidecar_stream.py

@@ -20,6 +20,38 @@
     r"error_type=(?P<error_type>[A-Za-z_][A-Za-z0-9_]{0,63})"
     r"(?: http_status=(?P<http_status>[1-5][0-9]{2}))?"
 )
+_LOG_PREFIX = re.compile(
+    r"^(?:(?P<asctime>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3}) )?"
+    r"(?:DEBUG|INFO|WARNING|ERROR)[: ][A-Za-z0-9_.]+[: ]"
+)
+_AGENT_ID = r"[a-z][a-z0-9_]*"
+_MODEL_ID = r"[A-Za-z0-9_./:-]+"
+_ERROR_TYPE = r"[A-Za-z_][A-Za-z0-9_.]*"
+_NUMBER = r"\d+(?:\.\d+)?"
+# contextual_orchestrator/orchestrator.py templates at the vendored pin. Every
+# field is a bounded identifier or number; ``error_message`` is free text and is
+# deliberately excluded from the match so it can never be re-emitted.
+# ``failures`` and ``reset_seconds`` are floats at runtime (``0.0 += 1.0``, ``30.0``),
+# so they take the number charset; ``threshold`` is an int.
+_ORCHESTRATOR_EVENTS = tuple(
+    re.compile(pattern)
+    for pattern in (
+        rf"^provider_attempt agent_id={_AGENT_ID} model={_MODEL_ID} attempt=\d+/\d+$",
+        rf"^provider_attempt_failed agent_id={_AGENT_ID} model={_MODEL_ID} attempt=\d+ "
+        rf"error_type={_ERROR_TYPE} transient=(?:True|False)(?= error_message=)",
+        rf"^provider_backoff agent_id={_AGENT_ID} attempt=\d+ delay_seconds={_NUMBER}$",
+        rf"^provider_exhausted agent_id={_AGENT_ID} model={_MODEL_ID} attempts=\d+ "
+        rf"final_error_type={_ERROR_TYPE}$",
+        rf"^provider_rejected_permanent agent_id={_AGENT_ID} model={_MODEL_ID} attempts=\d+ "
+        rf"final_error_type={_ERROR_TYPE}$",
+        rf"^provider_no_retry_budget agent_id={_AGENT_ID} model={_MODEL_ID} attempts=\d+ "
+        rf"final_error_type={_ERROR_TYPE} transient=(?:True|False)$",
+        rf"^circuit_failure agent_id={_AGENT_ID} failures={_NUMBER} threshold=\d+$",
+        rf"^circuit_opened agent_id={_AGENT_ID} failures={_NUMBER} threshold=\d+ reset_seconds={_NUMBER}$",
+        rf"^circuit_reset agent_id={_AGENT_ID}$",
+        rf"^circuit_cleared agent_id={_AGENT_ID}$",
+    )
+)
 _PREFIX_SUMMARIES = (
     ("review sidecar preflight failed:", "review sidecar preflight failed"),
     ("review sidecar discovery failed:", "review sidecar discovery failed"),
@@ -43,6 +75,29 @@
 )
 
 
+def _sanitize_orchestrator_event(stripped: str) -> str | None:
+    """Return an orchestrator route or circuit event reduced to its bounded fields.
+
+    Accepts the bare message, Python's default ``LEVEL:name:message`` prefix, and
+    the sidecar formatter's ``asctime LEVEL name message`` prefix; the timestamp
+    is kept (digits and punctuation only) so per-route durations can be read as
+    differences. ``provider_attempt_failed`` is cut before ``error_message=``,
+    which carries upstream text.
+    """
+    prefix = _LOG_PREFIX.match(stripped)
+    message = stripped[prefix.end():] if prefix is not None else stripped
+    for pattern in _ORCHESTRATOR_EVENTS:
+        match = pattern.match(message)
+        if match is None:
+            continue
+        summary = match.group(0)
+        if message.startswith("provider_attempt_failed "):
+            summary += " error_message=<omitted>"
+        asctime = prefix.group("asctime") if prefix is not None else None
+        return f"{asctime} {summary}" if asctime else summary
+    return None
+
+
 def sanitize_line(line: str) -> str | None:
     """Return one allowlisted diagnostic summary or ``None`` for raw content."""
     stripped = line.strip()
@@ -68,6 +123,9 @@ def sanitize_line(line: str) -> str | None:
         if http_status is not None:
             summary += f" http_status={http_status}"
         return summary
+    orchestrator_event = _sanitize_orchestrator_event(stripped)
+    if orchestrator_event is not None:
+        return orchestrator_event
     if stripped in ("client_disconnected", "discovery_diagnostics_complete"):
         return stripped
     for prefix, summary in _PREFIX_SUMMARIES:

tests/test_contextual_orchestrator_review_runtime_preflight.py

@@ -1719,6 +1719,118 @@ def test_sidecar_stream_sanitizer_allowlists_only_bounded_diagnostics() -> None:
     assert sanitize_line("provider response sk-secret") is None
 
 
+def test_sidecar_stream_sanitizer_admits_orchestrator_route_events() -> None:
+    """Per-route attempt, retry-budget, and circuit events survive with bounded fields only.
+
+    Before this, every orchestrator ``provider_*``/``circuit_*`` line was folded
+    into ``omitted_unstructured_lines``, so a 3122 s walk across six routes left
+    no per-route trace in the artifact (#1935 / #1939). Both log prefixes are
+    accepted so runs before and after the sidecar formatter read the same way.
+    """
+    namespace = _load_sanitizer()
+    sanitize_line = namespace["sanitize_line"]
+    secret = "sk-secret-must-not-enter-artifact"
+
+    assert sanitize_line(
+        "provider_attempt agent_id=nvidia_nim_deepseek model=deepseek-ai/deepseek-v4-flash-0731 attempt=1/3"
+    ) == "provider_attempt agent_id=nvidia_nim_deepseek model=deepseek-ai/deepseek-v4-flash-0731 attempt=1/3"
+    assert sanitize_line(
+        "WARNING:contextual_orchestrator.orchestrator:provider_exhausted agent_id=nvidia_nim_x "
+        "model=deepseek-ai/deepseek-v4-flash-0731 attempts=3 final_error_type=TimeoutError"
+    ) == (
+        "provider_exhausted agent_id=nvidia_nim_x model=deepseek-ai/deepseek-v4-flash-0731 "
+        "attempts=3 final_error_type=TimeoutError"
+    )
+    failed = sanitize_line(
+        "2026-09-05 21:40:00,123 DEBUG contextual_orchestrator.orchestrator provider_attempt_failed "
+        f"agent_id=openrouter_gemma model=google/gemma-3-12b-it:free attempt=2 error_type=HTTPError "
+        f"transient=True error_message=upstream said {secret}"
+    )
+    assert failed == (
+        "2026-09-05 21:40:00,123 provider_attempt_failed agent_id=openrouter_gemma "
+        "model=google/gemma-3-12b-it:free attempt=2 error_type=HTTPError transient=True "
+        "error_message=<omitted>"
+    )
+    assert secret not in failed
+    assert sanitize_line(
+        "provider_backoff agent_id=nvidia_nim_x attempt=1 delay_seconds=0.500"
+    ) == "provider_backoff agent_id=nvidia_nim_x attempt=1 delay_seconds=0.500"
+    assert sanitize_line(
+        "INFO:contextual_orchestrator.orchestrator:provider_no_retry_budget agent_id=bytez_a "
+        "model=m/x attempts=1 final_error_type=InvalidChatResponse transient=False"
+    ) == (
+        "provider_no_retry_budget agent_id=bytez_a model=m/x attempts=1 "
+        "final_error_type=InvalidChatResponse transient=False"
+    )
+    assert sanitize_line(
+        "provider_rejected_permanent agent_id=bytez_a model=m/x attempts=1 final_error_type=ValueError"
+    ) == "provider_rejected_permanent agent_id=bytez_a model=m/x attempts=1 final_error_type=ValueError"
+    assert sanitize_line(
+        "2026-09-05 21:41:02,000 WARNING contextual_orchestrator.orchestrator circuit_opened "
+        "agent_id=nvidia_nim_x failures=3.0 threshold=3 reset_seconds=30.0"
+    ) == "2026-09-05 21:41:02,000 circuit_opened agent_id=nvidia_nim_x failures=3.0 threshold=3 reset_seconds=30.0"
+    assert sanitize_line("circuit_failure agent_id=nvidia_nim_x failures=2.0 threshold=3") == (
+        "circuit_failure agent_id=nvidia_nim_x failures=2.0 threshold=3"
+    )
+    assert sanitize_line("circuit_reset agent_id=nvidia_nim_x") == "circuit_reset agent_id=nvidia_nim_x"
+    assert sanitize_line("circuit_cleared agent_id=nvidia_nim_x") == "circuit_cleared agent_id=nvidia_nim_x"
+
+    # Tampered or free-text variants stay out: an uppercase agent id, trailing text
+    # after a complete template, a failed-attempt line that lacks the error_message
+    # boundary, and a prefix with no known template.
+    assert sanitize_line("provider_attempt agent_id=NVIDIA model=m/x attempt=1/3") is None
+    assert sanitize_line(f"provider_attempt agent_id=nvidia_nim_x model=m/x attempt=1/3 {secret}") is None
+    assert sanitize_line(
+        "provider_attempt_failed agent_id=nvidia_nim_x model=m/x attempt=1 error_type=E transient=False"
+    ) is None
+    assert sanitize_line(f"DEBUG:contextual_orchestrator.orchestrator:{secret}") is None
+
+
+def test_sidecar_stream_sanitizer_matches_real_formatter_output() -> None:
+    """Fixtures typed from a template miss runtime value types; render the real records.
+
+    The circuit counters are floats in the orchestrator (``failures`` starts at
+    ``0.0`` and is incremented by ``1.0``; ``circuit_reset_seconds`` is ``30.0``), so
+    the lines that actually reach stderr say ``failures=2.0``, not ``failures=2``.
+    Render each template through ``logging.Formatter`` with the sidecar format
+    and the runtime value types, and require every one to pass.
+    """
+    import logging
+
+    namespace = _load_sanitizer()
+    sanitize_line = namespace["sanitize_line"]
+    formatter = logging.Formatter("%(asctime)s %(levelname)s %(name)s %(message)s")
+    records = (
+        (logging.DEBUG, "provider_attempt agent_id=%s model=%s attempt=%d/%d", ("nvidia_nim_x", "deepseek-ai/deepseek-v4-flash-0731", 1, 3)),
+        (logging.DEBUG, "provider_attempt_failed agent_id=%s model=%s attempt=%d error_type=%s transient=%s error_message=%s", ("nvidia_nim_x", "deepseek-ai/deepseek-v4-flash-0731", 1, "TimeoutError", True, "Bearer sk-secret in body")),
+        (logging.DEBUG, "provider_backoff agent_id=%s attempt=%d delay_seconds=%.3f", ("nvidia_nim_x", 1, 0.5)),
+        (logging.WARNING, "provider_exhausted agent_id=%s model=%s attempts=%s final_error_type=%s", ("nvidia_nim_x", "deepseek-ai/deepseek-v4-flash-0731", 3, "TimeoutError")),
+        (logging.WARNING, "provider_rejected_permanent agent_id=%s model=%s attempts=%s final_error_type=%s", ("bytez_a", "m/x", 1, "ValueError")),
+        (logging.WARNING, "provider_no_retry_budget agent_id=%s model=%s attempts=%s final_error_type=%s transient=%s", ("bytez_a", "m/x", 1, "InvalidChatResponse", False)),
+        (logging.DEBUG, "circuit_failure agent_id=%s failures=%s threshold=%s", ("nvidia_nim_x", 2.0, 3)),
+        (logging.WARNING, "circuit_opened agent_id=%s failures=%s threshold=%s reset_seconds=%s", ("nvidia_nim_x", 3.0, 3, 30.0)),
+        (logging.DEBUG, "circuit_reset agent_id=%s", ("nvidia_nim_x",)),
+        (logging.DEBUG, "circuit_cleared agent_id=%s", ("nvidia_nim_x",)),
+    )
+    for level, template, args in records:
+        record = logging.LogRecord(
+            "contextual_orchestrator.orchestrator", level, __file__, 0, template, args, None
+        )
+        rendered = formatter.format(record)
+        sanitized = sanitize_line(rendered)
+        assert sanitized is not None, rendered
+        assert "sk-secret" not in sanitized
+        assert sanitized.split(" ", 2)[2].split(" ")[0] == template.split(" ")[0]
+    assert sanitize_line(
+        formatter.format(
+            logging.LogRecord(
+                "contextual_orchestrator.orchestrator", logging.DEBUG, __file__, 0,
+                "circuit_failure agent_id=%s failures=%s threshold=%s", ("nvidia_nim_x", 2.0, 3), None,
+            )
+        )
+    ).endswith("circuit_failure agent_id=nvidia_nim_x failures=2.0 threshold=3")
+
+
 def test_sidecar_stream_sanitizer_summarizes_unstructured_and_traceback_lines(
     monkeypatch: pytest.MonkeyPatch,
 ) -> None: