diff --git a/CHANGELOG.md b/CHANGELOG.md index efad99e30b..15d9e6e188 100644 --- a/CHANGELOG.md +++ b/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. diff --git a/scripts/ci/sanitize_contextual_orchestrator_sidecar_stream.py b/scripts/ci/sanitize_contextual_orchestrator_sidecar_stream.py index 18bc11b667..51b9a5df27 100644 --- a/scripts/ci/sanitize_contextual_orchestrator_sidecar_stream.py +++ b/scripts/ci/sanitize_contextual_orchestrator_sidecar_stream.py @@ -20,6 +20,38 @@ r"error_type=(?P[A-Za-z_][A-Za-z0-9_]{0,63})" r"(?: http_status=(?P[1-5][0-9]{2}))?" ) +_LOG_PREFIX = re.compile( + r"^(?:(?P\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=" + 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: diff --git a/tests/test_contextual_orchestrator_review_runtime_preflight.py b/tests/test_contextual_orchestrator_review_runtime_preflight.py index d38cd19c43..d0ace81e8b 100644 --- a/tests/test_contextual_orchestrator_review_runtime_preflight.py +++ b/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=" + ) + 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: