diff --git a/CHANGELOG.md b/CHANGELOG.md index 46d599a320..efad99e30b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,7 @@ +### 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. + ### Review sidecar catalog interleaves credential accounts - `build_zdr_prioritized_catalog` now fills each free/ZDR tier round-robin across independently credentialed accounts instead of in provider-name order. The sidecar exports `ORCHESTRATOR_CATALOG_ACCOUNT_CAP=8` with `ORCHESTRATOR_CATALOG_LIMIT=12`, and the sorted fill took 8 `nvidia_nim` routes and 4 `nvidia_nim_sub` routes before any `openrouter` route was reached, so a review that admitted 62 free routes across three accounts served a NVIDIA-only catalog (`noema-review` run 33969842312: `free_pool_admitted_routes` 62, `free_selected_count` 12, runtime preflight `ready_count` 2 of 12) and the failover loop had no other account to leave a stalled NVIDIA endpoint for -- the `noema-review` 502 class tracked in contextual-orchestrator#1045. Tier order (free before priced, ZDR before non-ZDR), the account cap, the limit, and the discovery-order independence contract are unchanged; the same input now yields 4 + 4 + 4. Contrasts with #1476, which hardens `_routable_discovered_models` against a pin that regresses the OpenRouter `evidence_only` flag: on the current pin (`2e414d15`, includes contextual-orchestrator#949) OpenRouter rows already reach the catalog builder, and the selection was what dropped them. diff --git a/scripts/ci/contextual_orchestrator_review_launcher.py b/scripts/ci/contextual_orchestrator_review_launcher.py index 2e56809639..502843c994 100644 --- a/scripts/ci/contextual_orchestrator_review_launcher.py +++ b/scripts/ci/contextual_orchestrator_review_launcher.py @@ -23,11 +23,12 @@ import argparse import json +import logging import os import re import sys from pathlib import Path -from typing import Any +from typing import Any, Callable from scripts.ci.contextual_orchestrator_review_policy import FREE_POOL_CREDENTIAL_NAMES @@ -673,6 +674,62 @@ def _catalog_account_cap(default: int) -> int: return int(os.environ.get("ORCHESTRATOR_CATALOG_ACCOUNT_CAP", str(default))) +DEFAULT_SIDECAR_LOG_LEVEL = "DEBUG" +SIDECAR_LOG_FORMAT = "%(asctime)s %(levelname)s %(name)s %(message)s" + + +def _sidecar_log_level() -> str: + """Return the log level the review sidecar configures for its orchestrator process. + + Defaults to ``DEBUG`` because that is where ``contextual_orchestrator`` + records the per-request trace a failed review needs afterwards: every + provider attempt (``provider_attempt``), its classified failure + (``provider_attempt_failed`` with error type and transient flag), backoff, + and circuit events are ``_LOGGER.debug`` calls, while the default + ``WARNING`` level keeps only ``provider_exhausted``/``circuit_opened``. At + the vendored pin none of those DEBUG sites logs a prompt, payload, or + response body; the one free-text field is ``provider_attempt_failed``'s + ``error_message`` (the exception text, which can quote an upstream error + body), and the sidecar pipes this process's stderr through the allow-list + sanitizer before it reaches disk, so only lines the sanitizer recognises + -- and only their structured fields -- become CI evidence. On + 2026-09-05 a 3122 s ``noema-review`` failure could not be attributed to + "six ready routes, two retry layers, 548 s per hop" from the job log alone + because this trace was never emitted. Override with + ``ORCHESTRATOR_SIDECAR_LOG_LEVEL``. + """ + return os.environ.get("ORCHESTRATOR_SIDECAR_LOG_LEVEL", DEFAULT_SIDECAR_LOG_LEVEL) + + +def _configure_sidecar_logging(configure_logging: Callable[[str], None]) -> str: + """Configure the orchestrator process's logging for CI evidence. + + ``configure_logging`` is ``contextual_orchestrator.debug_logging.configure_logging`` + (injected so this module stays importable without the vendored package): + it installs the root level with ``basicConfig(force=True)``. Its default + formatter carries no timestamp, and a per-attempt trace without + timestamps cannot yield per-hop durations, so every root handler is then + given :data:`SIDECAR_LOG_FORMAT`. + + Returns: + The level name that was applied. + + Raises: + SystemExit: If ``ORCHESTRATOR_SIDECAR_LOG_LEVEL`` is not a level name + the orchestrator accepts; a misspelt level must not silently leave + the process at ``WARNING``. + """ + level = _sidecar_log_level() + try: + configure_logging(level) + except ValueError as exc: + raise SystemExit(f"ORCHESTRATOR_SIDECAR_LOG_LEVEL is invalid: {exc}") from None + formatter = logging.Formatter(SIDECAR_LOG_FORMAT) + for handler in logging.getLogger().handlers: + handler.setFormatter(formatter) + return level + + def _with_discovery_counts( report: dict[str, object], rows: list[dict[str, Any]], @@ -802,7 +859,9 @@ def main(argv: list[str] | None = None) -> int: parse_discovery_report, provider_account, ) + from contextual_orchestrator.debug_logging import configure_logging + _configure_sidecar_logging(configure_logging) registered = register_review_credentials(os.environ) auth_token = args.auth_token or get_credential(REVIEW_AUTH_CREDENTIAL_NAME) if not auth_token: diff --git a/tests/test_contextual_orchestrator_review_runtime_preflight.py b/tests/test_contextual_orchestrator_review_runtime_preflight.py index 559c2d1e99..d38cd19c43 100644 --- a/tests/test_contextual_orchestrator_review_runtime_preflight.py +++ b/tests/test_contextual_orchestrator_review_runtime_preflight.py @@ -1768,3 +1768,66 @@ def test_sidecar_stream_sanitizer_omits_no_summary_for_fully_safe_input( assert main() == 0 assert output.getvalue() == "client_disconnected\n" + + +def test_sidecar_log_level_defaults_to_debug(monkeypatch: pytest.MonkeyPatch) -> None: + """The sidecar asks for DEBUG so provider attempts and circuit events are recorded.""" + monkeypatch.delenv("ORCHESTRATOR_SIDECAR_LOG_LEVEL", raising=False) + namespace = _load_launcher() + assert namespace["_sidecar_log_level"]() == "DEBUG" + assert namespace["DEFAULT_SIDECAR_LOG_LEVEL"] == "DEBUG" + + +def test_sidecar_log_level_honors_an_explicit_override(monkeypatch: pytest.MonkeyPatch) -> None: + """An operator-set ``ORCHESTRATOR_SIDECAR_LOG_LEVEL`` is passed through untouched.""" + monkeypatch.setenv("ORCHESTRATOR_SIDECAR_LOG_LEVEL", "INFO") + namespace = _load_launcher() + assert namespace["_sidecar_log_level"]() == "INFO" + + +def test_configure_sidecar_logging_applies_level_and_timestamped_format( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """The injected configurator receives the level and every root handler gets timestamps.""" + import logging + + monkeypatch.delenv("ORCHESTRATOR_SIDECAR_LOG_LEVEL", raising=False) + namespace = _load_launcher() + received: list[str] = [] + + def fake_configure_logging(level_name: str) -> None: + received.append(level_name) + logging.basicConfig(level=getattr(logging, level_name), force=True) + + try: + applied = namespace["_configure_sidecar_logging"](fake_configure_logging) + assert applied == "DEBUG" + assert received == ["DEBUG"] + handlers = logging.getLogger().handlers + assert handlers, "basicConfig(force=True) must have installed a root handler" + for handler in handlers: + assert handler.formatter is not None + assert "%(asctime)s" in handler.formatter._fmt # noqa: SLF001 - formatter has no public getter + finally: + logging.basicConfig(level=logging.WARNING, force=True) + + +def test_configure_sidecar_logging_rejects_an_invalid_level(monkeypatch: pytest.MonkeyPatch) -> None: + """A misspelt level fails the launch instead of silently staying at WARNING.""" + monkeypatch.setenv("ORCHESTRATOR_SIDECAR_LOG_LEVEL", "LOUD") + namespace = _load_launcher() + + def strict_configure_logging(level_name: str) -> None: + raise ValueError(f"unknown log level {level_name!r}") + + with pytest.raises(SystemExit, match="ORCHESTRATOR_SIDECAR_LOG_LEVEL is invalid: unknown log level 'LOUD'"): + namespace["_configure_sidecar_logging"](strict_configure_logging) + + +def test_main_configures_sidecar_logging_before_touching_credentials() -> None: + """``main()`` wires the orchestrator's own ``configure_logging`` in before any credential work.""" + source = _LAUNCHER.read_text(encoding="utf-8") + configure_at = source.index("_configure_sidecar_logging(configure_logging)") + credentials_at = source.index("registered = register_review_credentials(os.environ)") + assert configure_at < credentials_at + assert "from contextual_orchestrator.debug_logging import configure_logging" in source