diff --git a/CHANGELOG.md b/CHANGELOG.md index 6b38e0770..16436c84d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,13 @@ and this project uses [Semantic Versioning](https://semver.org/spec/v2.0.0.html) ### Fixed +- `check-fast-mlsirm --help` now shows help and exits instead of running the + diagnostic: the subcommand took no arguments and ignored everything after + its own name, so `--help` was silently swallowed and the real diagnostic + ran anyway. It now gets its own `argparse` parser (declaring the shared + `--log-level`/`--verbose`/`--debug` flags, matching every other + subcommand), so `--help` documents them and exits cleanly, and an + unrecognized trailing option is rejected instead of being ignored. - OpenRouter discovery no longer marks the entire credential account evidence-only. Authenticated catalog rows may serve ordinary requests, while ZDR-only requests still require explicit route-level ZDR evidence. @@ -42,9 +49,179 @@ and this project uses [Semantic Versioning](https://semver.org/spec/v2.0.0.html) retried as if it were a network blip. Fixes the shared classifier itself (not just the discovery retry call site), so every current and future caller of `is_transient_error` benefits. +- (CodeRabbit review on #946) **Credential leak via cross-host redirect, + doubled by #923's retry.** `_fetch_json` -- the function every standard + provider's authenticated "list models" call goes through (openai, + openrouter, nvidia_nim, nvidia_nim_sub, bytez), including under #923's one + bounded retry -- called plain `urllib.request.urlopen`, whose default + `HTTPRedirectHandler` copies the `Authorization` header onto a redirected + request even when the redirect target is a completely different host + (unlike some other HTTP clients, urllib never strips sensitive headers on + cross-origin redirects). A malicious or compromised provider endpoint + issuing a 3xx redirect could have exfiltrated the credential, and the + retry meant up to twice per discovery attempt. `_fetch_json_same_host_https` + already carried the correct fix for this exact risk (`_TrustedDiscoveryRedirectHandler`, + raising on any redirect leaving the original host) for a different call + path; `_fetch_json` now goes through the same protection via a new shared + `_open_trusted_discovery_request` helper, so both functions get one + single-implementation redirect guard instead of two copies that could + drift apart. A legitimate same-host redirect (e.g. a real provider's + `/v1/models` -> `/v2/models`) still succeeds unchanged. +- (CodeRabbit review on #946) The `configured_gateway` provider's + `/model/info` metadata fetch now also catches `RuntimeError` (raised by + `ModelClient._resolve_addresses`/`_open_provider` on a DNS or + request-validation transport failure), matching the primary list-request + retry loop's except tuple. Previously a raw `RuntimeError` from this one + metadata fetch escaped `discover_provider_models` uncaught and aborted the + entire discovery pass instead of just this provider's metadata. +- (CodeRabbit review on #946) `server.py`'s per-request `latency_ms` no + longer counts a keep-alive connection's idle time between requests. + `request_started` used to be timestamped immediately before + `BaseHTTPRequestHandler.handle_one_request()`, whose first action is a + blocking `self.rfile.readline()` that, on a reused connection, waits on + the client's next request rather than doing any work. The timestamp is + now taken inside an overridden `parse_request()`, right after that + blocking read has already returned real request bytes, so `latency_ms` + reflects only actual request handling. +- (CodeRabbit review on #946) `orchestrator.py`'s retry-outcome + classification (no retry budget at all / budget exhausted / stopped early + on a non-transient error) was duplicated verbatim in + `ModelClient._send_with_retry` and `_send_raw_with_retry` -- duplication + that had already caused a real regression once, when a fix landed in one + copy but was missed in the other (see the round-4 `provider_no_retry_budget` + fix above). Extracted into one shared `_log_retry_outcome` helper both + methods call, so the two call sites cannot diverge again. +- (CodeRabbit review on #946) `debug_logging.response_metadata_for_log`'s + `usage` summary now keeps only a fixed allowlist of known counter names + (`prompt_tokens`, `completion_tokens`, `total_tokens`, `input_tokens`, + `output_tokens`; see `SAFE_USAGE_COUNTER_KEY_NAMES`), not any string key + with a numeric value. A provider's `usage` object is upstream-controlled + JSON, so a key shaped like `"customer_note="` with a throwaway + numeric value would otherwise have sailed through the old numeric-only + filter and reached DEBUG output verbatim (CWE-532). +- (round 6) `model_discovery.py`'s `_fetch_json` read an authenticated + provider's entire response body into memory before parsing it as JSON + (`response.read()`, no size bound) -- unlike `_fetch_json_same_host_https` + and `_fetch_configured_gateway_json`, which already capped their reads at + `MAX_DISCOVERY_RESPONSE_BYTES` (8 MiB) and failed closed on an overage. + A large or malicious/misbehaving provider response (an outage page dumped + as an unbounded body, or a compromised endpoint) could exhaust worker + memory before JSON parsing ever ran (CWE-400). `_fetch_json` now shares + the identical bounded-read-then-check pattern: it reads at most + `MAX_DISCOVERY_RESPONSE_BYTES + 1` bytes and raises `ValueError` if the + body exceeds the cap, applied consistently everywhere + `_open_trusted_discovery_request`'s response body is consumed in this + module. +- (round 6) `_log_retry_outcome`'s zero-retry-budget classification + conflated two different situations under the same `provider_no_retry_budget` + WARNING: an agent with a genuinely zero configured retry budget, and + `ModelClient.proxy_send_once`'s deliberate one-shot call + (`allow_transient_retries=False`, used so an already-failing-over + passthrough request cannot itself amplify load with a nested retry loop). + `_send_raw_with_retry` computes `retry_limit = self._retry_limit(agent) if + allow_transient_retries else 0`, so the forced-to-0 one-shot case looked + identical to a real zero-budget agent by the time it reached + `_log_retry_outcome`, producing a false "no retry budget" warning even + when the agent's real budget was non-zero. `_log_retry_outcome` now takes + `allow_transient_retries` explicitly and, when a caller forced the retry + count to zero rather than the agent's own configuration being zero, logs a + distinctly named `provider_one_shot_call_failed` WARNING instead of + `provider_no_retry_budget`. `_send_with_retry` has no such caller-forced + restriction and is unaffected. +- (round 7) `server.py`'s `_send`/`_send_text`/`_send_bytes`/`_send_sse`/ + `_begin_sse` all set `self._last_status` to the *intended* status before + handing off to `_write_response`, then ignored its boolean return value. + `_write_response` deliberately swallows a dead peer's + `BrokenPipeError`/`ConnectionError`/`OSError` (so a disconnected client + cannot crash the handler thread), but that left `_last_status` claiming a + status the client never actually received, so the per-request INFO + summary (`_log_request_summary`) logged a false "200 delivered" for a + request that was really cut short mid-write. `_write_response` now resets + `_last_status` back to `None` -- this module's existing "response was + never sent" value -- whenever it catches a disconnect, fixing every + current and future writer uniformly at their one shared choke point + instead of patching each writer individually. +- (round 7) `_log_request_summary` also silently dropped a request that + *did* deliver bytes but whose request line `parse_request` rejected as + malformed (or that stdlib's `handle_one_request` rejected outright as too + long): a real 400/414 was sent and captured into `_last_status` via the + `send_response` override, but `command`/`path` stay unset for these + cases (stdlib's own `parse_request` resets `self.command` to `None` "in + case of error on the first line" and never reaches the assignment that + would set `path`), so the old "nothing to report" guard -- checking only + method/path -- skipped logging it, indistinguishable from a keep-alive + connection closing with zero bytes. The guard now also logs when + `_last_status` was actually recorded, while still skipping the true + no-bytes-at-all case. +- (round 7) Two CodeQL `py/clear-text-logging-sensitive-data` HIGH alerts on + `tests/test_debug_logging.py`'s redaction positive/negative-control pair + (lines 144 and 167) are precise, per-line `# codeql[...]` inline + suppressions with an explanatory comment, not a code change: both lines + log a hardcoded, non-functional fake secret (`# noqa: S105`'d against + bandit/ruff) as a deliberate test fixture -- one proving `redact_text` + masks it, the other (the negative control) proving the same literal + leaks with no redactor, which is exactly what the test exists to show. +- (round 8) Follow-up correction to round 7's `_write_response` fix: clearing + `_last_status` on *every* caught disconnect was too broad. A write failure + can strike either before the status line/headers were ever flushed (the + client received nothing -- clearing is correct) or after `end_headers()` + already completed (a later body-write chunk, or a later `_write_sse` frame + on a stream `_begin_sse` already opened -- the client genuinely received + the real status, so clearing it would falsely report "no status" for a + request that was, in fact, answered). Every `_send*`/`_begin_sse` writer + now sets a new `self._response_headers_sent` marker immediately after its + own `end_headers()` call returns (reset to `False` once per request by + `handle_one_request`); `_write_response`'s disconnect handler now clears + `_last_status` only when that marker is still unset, preserving it + otherwise. `_write_sse` relies on `_begin_sse`'s already-set marker rather + than touching it itself, since it is only ever called after a prior + successful header flush. ### Added +- Verbose/debug logging (ADR 0005): a new stdlib-only `debug_logging.py` + module, a `--log-level {DEBUG,INFO,WARNING,ERROR,CRITICAL}` CLI flag with a + `--verbose`/`--debug` shorthand (default unchanged: `WARNING`), and new + instrumentation at the provider retry loop, per-agent circuit breaker, evidence-based ranking + (`_ranked_agents`/`_select_agent`), model discovery, and one body-free + per-request summary line in `server.py`. The DEBUG response-body summary + logs only an allowlisted metadata shape (`debug_logging.response_metadata_for_log`: + whether the response is error-shaped, the model name, the choice count, and + numeric usage counts) rather than the payload itself, so ordinary response + text (message content, tool-call arguments, an error message) never reaches + DEBUG output — `redact_text`/`redact_value`'s in-string value-pattern + matching and the additional key-name-aware + `debug_logging.redact_credential_shaped_keys` pass (catches a secret nested + under a credential-shaped JSON key regardless of its value's shape) are + applied on top of that allowlist, defense-in-depth, plus a handler-level + filter safety net. Raw prompt/answer text is never logged, only lengths and + identifiers. The INFO per-request summary strips any query string before + logging, is skipped entirely for a keep-alive connection's closing call + that parsed no new request (previously logged the prior request a second + time, statuslessly), and now also captures a status the framework itself + sends (e.g. its built-in 501 for an unsupported HTTP method), not just + status codes sent through this module's own response writers. A + `--log-level`/`--verbose`/`--debug` flag placed before a subcommand + (`register-credential`, `discover-models`, `check-fast-mlsirm`) no longer + bypasses subcommand dispatch, including an abbreviated spelling of one of + those flags (`--log-l`, `--ver`) — every CLI parser now sets + `allow_abbrev=False` so an abbreviation is rejected consistently + everywhere with a clear error, rather than silently accepted by one parser + and not another. The retry loop's `provider_exhausted` WARNING now fires + only when a real, non-zero retry budget was actually used up; an + immediate non-transient (permanent) rejection with budget left logs the + distinct `provider_rejected_permanent`, and any failure at all with a + configured retry limit of 0 (there was never a budget to exhaust) logs a + separate `provider_no_retry_budget` carrying the error's own + transient/non-transient classification explicitly — collapsing a + zero-budget *transient* failure into "permanent" would conflate "no retry + budget was configured" with "this error is non-retryable by nature", two + independent facts. The handler-level + redaction safety net now also redacts an exception's traceback + (`exc_info=True` / `logger.exception(...)`), not just `record.msg` — a + secret embedded in an exception's own message (e.g. an upstream error + reflecting `api_key=sk-...`) previously reached DEBUG output unredacted + via the traceback even when the message-level redaction worked correctly. - Generalized the Models.dev free-cost cross-reference (ADR 0032) beyond `opencode_zen` to `nvidia_nim`, `nvidia_nim_sub`, and `openai` via a new declared `ProviderModelSource.models_dev_provider_id` field, and hoisted diff --git a/conductor/tech-stack.md b/conductor/tech-stack.md index f039eece6..673f97230 100644 --- a/conductor/tech-stack.md +++ b/conductor/tech-stack.md @@ -9,7 +9,9 @@ Python 3.11+. Runtime dependencies: - `cryptography` for AES-256-GCM protection of explicitly marked PII fields. -- The HTTP server, persistence, and orchestration core remain Python standard-library based. +- `opentelemetry-api`/`-sdk`/`-exporter-otlp-proto-http` for optional request-correlation tracing (ADR 0122; disabled unless an OTLP endpoint is configured). +- `jsonschema` for structured-output validation against caller-supplied schemas. +- The HTTP server, persistence, orchestration core, and verbose/debug logging (`debug_logging.py`, ADR 0005) remain Python standard-library based. Production target dependencies after this lab hardens: diff --git a/contextual_orchestrator/__main__.py b/contextual_orchestrator/__main__.py index ffd82536d..a6ab0ac53 100644 --- a/contextual_orchestrator/__main__.py +++ b/contextual_orchestrator/__main__.py @@ -4,7 +4,6 @@ import argparse import json -import logging import os import sys from dataclasses import replace @@ -12,6 +11,7 @@ from .cost_ledger import PriceBook from .cost_router import CostRoutingCoordinator from .credentials import get_credential, register_credential +from .debug_logging import configure_logging, parse_log_level_name from .kv_config import InMemoryConfigStore from .model_discovery import ( CONFIGURED_GATEWAY_CREDENTIAL_NAME, @@ -34,6 +34,7 @@ ModelClient, TaskOrchestrator, load_agents, + redact_text, ) from .privacy_policy_analysis import ( analyze_discovered_privacy_policies, @@ -44,6 +45,133 @@ DEFAULT_ADMIN_CREDENTIAL_NAME = "CONTEXTUAL_ORCHESTRATOR_ADMIN_TOKEN" DEFAULT_INFERENCE_CREDENTIAL_NAME = "CONTEXTUAL_ORCHESTRATOR_INFERENCE_TOKEN" +def _log_level(value: str) -> str: + """Parse a case-insensitive stdlib logging level name for an argparse option.""" + try: + return parse_log_level_name(value) + except ValueError as exc: + raise argparse.ArgumentTypeError(str(exc)) from exc + + +def _add_log_level_arguments(parser: argparse.ArgumentParser) -> None: + """Declare `--log-level`/`--verbose`/`--debug` on one parser for `--help`. + + Actual resolution happens once in :func:`_configure_logging_from_cli`, + which runs before subcommand dispatch and already consumed these values + from raw ``argv`` via its own pre-scan parser; declaring them here again + is only so ``--help`` documents them on every subcommand and so this + parser's own `parse_args` does not reject them as unrecognized. + """ + parser.add_argument( + "--log-level", + type=_log_level, + default=None, + metavar="{DEBUG,INFO,WARNING,ERROR,CRITICAL}", + help="Set the effective log level explicitly (case-insensitive; overrides " + "--verbose/--debug; default: WARNING).", + ) + parser.add_argument( + "--verbose", + "--debug", + action="store_true", + dest="verbose", + help="Shorthand for --log-level DEBUG, unless --log-level is also given explicitly.", + ) + + +def _configure_logging_from_cli(arguments: list[str]) -> None: + """Resolve the effective log level and configure stdlib logging, once. + + Runs before subcommand dispatch so ``register-credential``, + ``discover-models``, ``check-fast-mlsirm``, one-shot completion, and + ``--serve`` are all configured uniformly from one call site, using a + lightweight ``parse_known_args`` pre-scan that does not need to know any + subcommand's full argument set. Standard stdlib argparse + option-terminator semantics apply here for free: a literal ``--`` + anywhere in ``arguments`` stops this pre-scan from recognizing anything + after it as ``--log-level``/``--verbose``/``--debug``, since + ``parse_known_args`` itself already treats everything past a bare + ``--`` as positional (verified directly; this is not special-cased here + -- it falls out of using stdlib ``argparse`` as intended). + + Precedence: explicit ``--log-level`` > ``--verbose``/``--debug`` > + default ``WARNING``. + + Raises: + SystemExit: With status 2 and an argparse-style message on stderr, if + an explicit ``--log-level`` names an unrecognized level. The level + is never silently ignored. + """ + # allow_abbrev=False: an abbreviated flag (e.g. "--log-l" for + # "--log-level") would otherwise be silently accepted by this pre-scan's + # own parse_known_args, while _subcommand_token_index -- a plain string + # comparison, not argparse -- would not recognize that same abbreviation + # and misroute a leading "--log-l DEBUG discover-models" into one-shot + # completion. Disabling abbreviations here (and on every subcommand's own + # parser below) makes an abbreviated flag consistently rejected with a + # clear argparse error everywhere, rather than silently divergent + # between this pre-scan and the locator. + pre_scan = argparse.ArgumentParser(add_help=False, allow_abbrev=False) + _add_log_level_arguments(pre_scan) + known, _unrecognized = pre_scan.parse_known_args(arguments) + if known.log_level is not None: + effective_level = known.log_level + elif known.verbose: + effective_level = "DEBUG" + else: + effective_level = "WARNING" + configure_logging(effective_level, redactor=redact_text) + + +#: Global logging flags recognized by `_subcommand_token_index` while +#: scanning past them -- must stay in sync with what `_add_log_level_arguments` +#: declares (`--verbose`/`--debug` take no value; `--log-level` takes one, +#: either as a separate token or via `--log-level=...`). +_LOG_LEVEL_BOOLEAN_FLAGS = ("--verbose", "--debug") +_LOG_LEVEL_VALUE_FLAG = "--log-level" + + +def _subcommand_token_index(arguments: list[str]) -> int | None: + """Find the index of the subcommand token, skipping leading logging flags. + + `main` dispatches `register-credential`, `discover-models`, and + `check-fast-mlsirm` by checking a single argument token against each + subcommand name. Without this scan, a global logging flag placed before + the subcommand (e.g. ``--verbose discover-models``) would occupy that + checked position instead, so the subcommand name would fall through + unrecognized into the default one-shot completion parser and be treated + as a prompt string. Recognized flags are only skipped for the purpose of + *locating* the subcommand token here -- callers must still pass the + complete, unmodified argument list on to whichever parser handles the + dispatch, so each subcommand's own parser (and the pre-scan in + :func:`_configure_logging_from_cli`) still sees every flag. + + Args: + arguments: The full CLI argument list (excluding the program name). + + Returns: + The index of the first token that is not a recognized global logging + flag or its value, or ``None`` if every token is one of those (there + is no subcommand token to find). + """ + index = 0 + length = len(arguments) + while index < length: + token = arguments[index] + if token in _LOG_LEVEL_BOOLEAN_FLAGS: + index += 1 + continue + if token == _LOG_LEVEL_VALUE_FLAG: + index += 1 + if index < length: + index += 1 # skip the level name token, e.g. "DEBUG" + continue + if token.startswith(_LOG_LEVEL_VALUE_FLAG + "="): + index += 1 + continue + return index + return None + def _bootstrap_telemetry_config() -> InMemoryConfigStore: """Load non-secret OTEL deployment settings into the process KV at startup.""" @@ -166,8 +294,22 @@ def _fast_mlsirm_runtime_status() -> tuple[dict[str, object], bool]: return status, available -def _check_fast_mlsirm_command() -> None: - """Validate the same-interpreter fast-mlsirm integration boundary.""" +def _check_fast_mlsirm_command(argv: list[str]) -> None: + """Validate the same-interpreter fast-mlsirm integration boundary. + + Takes its own parser (matching every other subcommand) so ``--help`` + documents the shared logging flags and exits before running the + diagnostic, and an unrecognized trailing option is rejected instead of + being silently ignored. + """ + parser = argparse.ArgumentParser( + prog="python -m contextual_orchestrator check-fast-mlsirm", + description="Validate the same-interpreter fast-mlsirm integration boundary.", + allow_abbrev=False, + ) + _add_log_level_arguments(parser) + parser.parse_args(argv) + status, available = _fast_mlsirm_runtime_status() print(json.dumps(status, ensure_ascii=False, sort_keys=True)) if not available: @@ -185,8 +327,10 @@ def _register_credential_command(argv: list[str]) -> None: parser = argparse.ArgumentParser( prog="python -m contextual_orchestrator register-credential", description="Store a provider credential into the KV registry at bootstrap.", + allow_abbrev=False, ) parser.add_argument("--name", required=True, help="Credential name, e.g. OPENAI_API_KEY.") + _add_log_level_arguments(parser) source = parser.add_mutually_exclusive_group() source.add_argument( "--value-stdin", @@ -267,11 +411,7 @@ def _discover_models_command(argv: list[str]) -> None: parser = argparse.ArgumentParser( prog="python -m contextual_orchestrator discover-models", description="Discover models from every provider with a KV-registered credential.", - ) - parser.add_argument( - "--verbose", - action="store_true", - help="Emit secret-free provider discovery diagnostics to stderr.", + allow_abbrev=False, ) parser.add_argument( "--agents-db", @@ -305,9 +445,8 @@ def _discover_models_command(argv: list[str]) -> None: default=os.environ.get("CONTEXTUAL_ORCHESTRATOR_PROVIDER_CA_BUNDLE") or None, help="Optional reviewed CA bundle for configured-gateway discovery TLS verification.", ) + _add_log_level_arguments(parser) args = parser.parse_args(argv) - if args.verbose: - logging.basicConfig(level=logging.DEBUG) if args.enable_cheapest and not args.agents_db: parser.error("--enable-cheapest requires --agents-db") @@ -484,28 +623,37 @@ def _auto_discover_runtime_agents(orchestrator: TaskOrchestrator) -> dict[str, l def main(argv: list[str] | None = None) -> None: """Parse CLI options and run bootstrap, prompt completion, or the HTTP server.""" arguments = list(sys.argv[1:] if argv is None else argv) - if arguments and arguments[0] == "register-credential": - _register_credential_command(arguments[1:]) + _configure_logging_from_cli(arguments) + subcommand_index = _subcommand_token_index(arguments) + subcommand = arguments[subcommand_index] if subcommand_index is not None else None + # Leading logging flags are skipped only to *find* the subcommand token -- + # they stay in the list handed to that subcommand's own parser (see + # _subcommand_token_index's docstring). + arguments_after_subcommand = ( + arguments[:subcommand_index] + arguments[subcommand_index + 1 :] + if subcommand_index is not None + else arguments + ) + if subcommand == "register-credential": + _register_credential_command(arguments_after_subcommand) return - if arguments and arguments[0] == "discover-models": - _discover_models_command(arguments[1:]) + if subcommand == "discover-models": + _discover_models_command(arguments_after_subcommand) return - if arguments and arguments[0] == "check-fast-mlsirm": - _check_fast_mlsirm_command() + if subcommand == "check-fast-mlsirm": + _check_fast_mlsirm_command(arguments_after_subcommand) return - parser = argparse.ArgumentParser(description="Route or conduct chat requests across model agents.") + parser = argparse.ArgumentParser( + description="Route or conduct chat requests across model agents.", + allow_abbrev=False, + ) parser.add_argument("prompt", nargs="?", help="User prompt for CLI mode.") parser.add_argument("--agents", default="examples/agents.mock.json", help="Agent config JSON.") parser.add_argument("--state-db", default=os.environ.get("CONTEXTUAL_ORCHESTRATOR_STATE_DB", "") or None, help="Optional sqlite path to persist runs/audit/analytics across restarts (default: in-memory).") parser.add_argument("--mode", choices=["auto", "route", "conduct"], default="auto") parser.add_argument("--serve", action="store_true", help="Run the chat completions HTTP server.") - parser.add_argument( - "--verbose", - action="store_true", - help="Emit secret-free runtime and model-discovery diagnostics to stderr.", - ) parser.add_argument( "--release-authority-json", default=None, @@ -594,9 +742,8 @@ def main(argv: list[str] | None = None) -> None: action="store_true", help="discover source-declared chat-capable models at startup and activate them", ) + _add_log_level_arguments(parser) args = parser.parse_args(arguments) - if args.verbose: - logging.basicConfig(level=logging.DEBUG) client = ModelClient( ca_bundle=args.provider_ca_bundle, diff --git a/contextual_orchestrator/debug_logging.py b/contextual_orchestrator/debug_logging.py new file mode 100644 index 000000000..dad3598a6 --- /dev/null +++ b/contextual_orchestrator/debug_logging.py @@ -0,0 +1,391 @@ +"""Stdlib-only verbose/debug logging: level resolution, lazy DEBUG helpers, and a +handler-level redaction safety net. + +No new dependency. `logging` (the standard library module) is the only thing +this uses -- see the Ponytail entry in `docs/library_research.md`. This module +is a leaf: it imports nothing else from `contextual_orchestrator`, so +`orchestrator.py`, `model_discovery.py`, and `server.py` can all import it +without creating a cycle. + +Redaction here is deliberately a *safety net*, not the primary control. Call +sites that log caller- or provider-derived content must already redact it +(e.g. via `contextual_orchestrator.orchestrator.redact_text`/`redact_value`) +before it reaches a log call; `configure_logging`'s optional `redactor` +re-applies the same redaction over the final rendered message in case a call +site ever forgets. It never touches PII -- see `redact_text`'s own docstring +for why PII is out of scope here too. +""" + +from __future__ import annotations + +import json +import logging +from typing import Callable + +#: Redaction marker used in place of any value found under a credential-shaped +#: JSON key. Matches the marker `redact_value`/`redact_text` already use +#: elsewhere in this codebase, so a reader sees one consistent redaction +#: convention regardless of which pass caught a given secret. +REDACTED_MARKER = "[REDACTED]" + +#: Dict key names (case-insensitive, exact match) treated as always carrying +#: a credential, regardless of what the value looks like. This is +#: deliberately broad and shape-agnostic: `redact_value`/`redact_text` only +#: catch secrets by pattern-matching the *value*'s in-string shape (e.g. +#: "api_key=..." or "Bearer ..."), so they never look at the JSON key a +#: string is nested under -- a field like {"private_key": "-----BEGIN +#: PRIVATE KEY-----..."} or {"key": "AIzaSy..."} sails through unredacted. +#: This set closes that blind spot at the JSON-structure level instead. +CREDENTIAL_SHAPED_KEY_NAMES = frozenset( + { + "key", + "api_key", + "apikey", + "token", + "access_token", + "refresh_token", + "secret", + "client_secret", + "password", + "credential", + "credentials", + "auth", + "authorization", + "private_key", + "public_key", + "signing_key", + "pem", + } +) + +#: The only ``usage`` dict keys `response_metadata_for_log` ever logs, even +#: when their value happens to be numeric. A fixed allowlist, not just a +#: numeric-type check: a provider's ``usage`` object is attacker/upstream +#: -controlled JSON, so a key shaped like ``"customer_note="`` with a +#: throwaway numeric value would otherwise sail through the old numeric-only +#: filter and log that key string (CWE-532) verbatim. These are the standard +#: OpenAI-compatible token counters this codebase itself already reads +#: elsewhere (`orchestrator.py`, `cost_router.py`): ``prompt_tokens`` / +#: ``completion_tokens`` / ``total_tokens`` (the OpenAI chat-completion +#: names) and the ``input_tokens`` / ``output_tokens`` alternates some +#: providers use instead. +SAFE_USAGE_COUNTER_KEY_NAMES = frozenset( + { + "prompt_tokens", + "completion_tokens", + "total_tokens", + "input_tokens", + "output_tokens", + } +) + +#: Recognized stdlib logging level names, most to least verbose. +LOG_LEVEL_NAMES: tuple[str, ...] = ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL") + +#: Today's de facto stdlib default, kept unchanged so existing stderr-parsing +#: does not see new output just from upgrading to a version with this module. +DEFAULT_LOG_LEVEL_NAME = "WARNING" + + +def parse_log_level_name(level_name: str) -> str: + """Normalize a case-insensitive logging level name to its canonical spelling. + + Args: + level_name: A level name such as ``"debug"``, ``"Warning"``, or + ``"ERROR"`` (surrounding whitespace is ignored). + + Returns: + The canonical uppercase level name, one of :data:`LOG_LEVEL_NAMES`. + + Raises: + ValueError: If ``level_name`` does not name a recognized stdlib + logging level. + """ + normalized = level_name.strip().upper() + if normalized not in LOG_LEVEL_NAMES: + allowed = ", ".join(LOG_LEVEL_NAMES) + raise ValueError(f"invalid log level {level_name!r}; choose one of {allowed}") + return normalized + + +class _RedactingLogFilter(logging.Filter): + """Re-run a redactor over every record's fully rendered message. + + Attached to the handler `configure_logging` installs, never to a Logger + object: a Logger-level filter is skipped while a record propagates in + from a child logger, so only a handler-level filter reliably sees every + record this process ever emits, regardless of which logger created it. + """ + + def __init__(self, redactor: Callable[[str], str]) -> None: + """Store the redactor callable applied to every record this filters.""" + super().__init__() + self._redactor = redactor + + def filter(self, record: logging.LogRecord) -> bool: + """Rewrite ``record`` in place with its message AND traceback redacted. + + Renders ``record``'s message (applying any `%`-style args) first, so + the redactor sees the final text a handler would emit, then clears + ``args`` since the redacted text is no longer a format string. + + A record built via ``exc_info=True`` or ``logger.exception(...)`` + carries the exception separately in ``record.exc_info``; + ``logging.Formatter.format()`` renders it into text (caching the + result on ``record.exc_text``) *after* every filter has already run, + so redacting only ``record.msg`` above would leave the traceback -- + including the exception's own ``str()``, which can itself carry a + secret shape (e.g. an upstream error message embedding + ``api_key=sk-...``) -- to reach the handler completely unredacted. + This renders the traceback text itself now (via a throwaway + `logging.Formatter`, independent of whatever formatter the handler + actually uses), redacts it, and caches it as ``record.exc_text`` + while clearing ``record.exc_info`` so the handler's own formatter + uses this already-redacted text instead of re-deriving an + unredacted one from the original exception. + + Always returns ``True``: this filter redacts, it never drops records. + """ + record.msg = self._redactor(record.getMessage()) + record.args = () + if record.exc_info: + record.exc_text = self._redactor(logging.Formatter().formatException(record.exc_info)) + record.exc_info = None + elif record.exc_text: + record.exc_text = self._redactor(record.exc_text) + return True + + +def configure_logging( + level_name: str, + *, + redactor: Callable[[str], str] | None = None, +) -> None: + """Configure the root logger's level and, optionally, a redaction safety net. + + Uses ``logging.basicConfig(..., force=True)`` so repeated in-process calls + actually take effect. Plain `logging.basicConfig` is a no-op after the + first call in a process -- a classic stdlib footgun that would otherwise + make every subsequent in-process CLI invocation (this repo's own test + convention, and every real process that calls `main()` more than once + per interpreter) silently keep the first level it was ever given. + + Args: + level_name: A level name accepted by :func:`parse_log_level_name`. + redactor: Optional callable re-applied to every record's rendered + message before it reaches a handler. This is a defense-in-depth + safety net, not the primary redaction step -- see the module + docstring. + + Raises: + ValueError: If ``level_name`` is invalid. Nothing is configured in + that case; the previous configuration is left untouched. + """ + level = getattr(logging, parse_log_level_name(level_name)) + logging.basicConfig(level=level, force=True) + if redactor is None: + return + redacting_filter = _RedactingLogFilter(redactor) + for handler in logging.getLogger().handlers: + handler.addFilter(redacting_filter) + + +def log_debug_event(logger: logging.Logger, message: str, *args: object) -> None: + """Emit one DEBUG record, without formatting ``args`` unless DEBUG is enabled. + + `logging.Logger.debug` already defers `%`-style formatting internally, + but only for the formatting call itself -- it cannot save a caller from + eagerly building an expensive argument before passing it in. This helper + makes the guard explicit and independently testable: call sites that + already have cheap-to-construct args may still prefer this over + `logger.debug(...)` directly for that explicitness. Call sites that would + otherwise do nontrivial work to build one argument (e.g. redacting and + truncating a large value) should guard that work themselves with + ``logger.isEnabledFor(logging.DEBUG)`` rather than rely on this helper, + since the expensive part happens before any function call sees it. + + Args: + logger: The logger to emit on. + message: A `%`-style format string. + *args: Positional arguments substituted into ``message``. + """ + if logger.isEnabledFor(logging.DEBUG): + logger.debug(message, *args) + + +def summarize_request_for_log( + *, + method: str, + path: str, + status: int | None, + latency_ms: float, + session_id_hash: str | None = None, +) -> str: + """Format one body-free HTTP request/response summary line for INFO logging. + + Carries method, path, status, and latency only -- never headers, a query + string beyond the raw path, or a request/response body. Any query string + on ``path`` is stripped here, defensively, regardless of what the caller + passed in: a caller could plausibly put a token in a query parameter (a + common client habit) even though this server's own auth is header-only, + so this helper never trusts a caller to have already done that stripping + -- it enforces its own "body-free" contract itself. + + Args: + method: The HTTP method, e.g. ``"POST"``. + path: The request path as received (already excludes any body), with + or without a query string -- either is accepted, but only the + bare path before any ``?`` is ever logged. + status: The HTTP status code that was sent, or ``None`` when a + response was never sent (e.g. the connection dropped first). + latency_ms: Elapsed wall-clock time for the request, in milliseconds. + session_id_hash: The bounded correlation hash already computed by + `contextual_orchestrator.telemetry` (ADR 0122), or ``None``. The + raw session id itself must never be passed here. + + Returns: + One single-line, `%`-free summary string ready to hand to a logger. + """ + bare_path = path.split("?", 1)[0] + return ( + f"http_request method={method} path={bare_path} " + f"status={'-' if status is None else status} " + f"latency_ms={latency_ms:.1f} " + f"session_id_hash={session_id_hash or '-'}" + ) + + +def redact_credential_shaped_keys(value: object) -> object: + """Recursively replace any dict value whose key looks like a credential. + + This is a separate, additional pass from + `contextual_orchestrator.orchestrator.redact_value`/`redact_text`, which + only pattern-match a secret's in-string *value* shape (e.g. + ``api_key=...`` or ``Bearer ...``) and never inspect the JSON key a + string is nested under. A logging call site should apply both: this + catches ``{"private_key": "-----BEGIN PRIVATE KEY-----..."}``, + ``{"key": "AIzaSy..."}``, ``{"auth": "sk-live..."}``, or + ``{"credential": "..."}`` regardless of whether the value happens to + match any known secret pattern; `redact_value`/`redact_text` still catch + secret-shaped values nested under an unremarkable key name. + + A matched key's entire value is replaced with :data:`REDACTED_MARKER` + regardless of its shape or content -- a nested dict or list under a + credential-shaped key is not recursed into and explained away as + "probably fine": it is dropped wholesale, since a credential-shaped key + has no legitimate reason to carry structured data a log line needs. + + Args: + value: A JSON-like structure -- some combination of ``dict``, + ``list``, ``str``, ``int``, ``float``, ``bool``, and ``None``. + Any other type is returned unchanged. + + Returns: + A new structure of the same shape, with every credential-shaped + dict key's value replaced. The input is never mutated in place, so + it remains safe to keep using the original for anything other than + logging (e.g. the actual HTTP response body). + """ + if isinstance(value, dict): + return { + key: ( + REDACTED_MARKER + if isinstance(key, str) and key.strip().casefold() in CREDENTIAL_SHAPED_KEY_NAMES + else redact_credential_shaped_keys(item) + ) + for key, item in value.items() + } + if isinstance(value, list): + return [redact_credential_shaped_keys(item) for item in value] + return value + + +def response_metadata_for_log(payload: object) -> dict[str, object]: + """Extract an allowlisted, content-free metadata summary from a response payload. + + `redact_value`/`redact_credential_shaped_keys` only mask *credential*-shaped + content -- ordinary response text (``choices[].message.content``, + tool-call arguments, an ``error.message`` that can reflect + caller-supplied input) is not a credential, so neither pass ever masks + it, and it would otherwise reach DEBUG output verbatim. That text can + carry PII or business-sensitive content that has nothing to do with + secrets (CWE-532: insertion of sensitive information into a log file). + + This returns a small, fixed allowlist of shape/usage metadata instead -- + never any user- or provider-authored text -- for a caller (`server.py`'s + response-body DEBUG summary) to log in place of the payload itself. + + Args: + payload: A JSON-like response payload (typically an OpenAI-shaped + chat completion or error object). Any non-dict value is treated + as carrying no usable metadata. + + Returns: + A dict with exactly the keys ``has_error`` (bool), ``model`` (the + served model name, or ``None``), ``choice_count`` (``int``), and + ``usage`` (a dict of only the allowlisted, numeric usage counters -- + see :data:`SAFE_USAGE_COUNTER_KEY_NAMES` -- or ``None``) -- never any + other field from ``payload``. + """ + if not isinstance(payload, dict): + return {"has_error": False, "model": None, "choice_count": 0, "usage": None} + model = payload.get("model") + choices = payload.get("choices") + usage = payload.get("usage") + safe_usage: dict[str, object] | None = None + if isinstance(usage, dict): + # Allowlisted key names, not just a numeric-value check: `usage` is + # upstream-controlled JSON, so a key shaped like + # "customer_note=" with a throwaway numeric value must not + # sail through just because its value happens to be numeric. + safe_usage = { + key: value + for key, value in usage.items() + if isinstance(key, str) + and key in SAFE_USAGE_COUNTER_KEY_NAMES + and isinstance(value, (int, float)) + and not isinstance(value, bool) + } + return { + "has_error": isinstance(payload.get("error"), dict), + "model": model if isinstance(model, str) else None, + "choice_count": len(choices) if isinstance(choices, list) else 0, + "usage": safe_usage, + } + + +def summarize_payload_for_log( + label: str, + safe_payload: object, + *, + max_characters: int = 500, +) -> str: + """Bound an already-redacted request/response payload to one DEBUG log line. + + ``safe_payload`` must already be redacted by the caller (e.g. via + `contextual_orchestrator.orchestrator.redact_value`) before it reaches + this function -- it only serializes and truncates; it performs no + redaction of its own, so it must never be handed a payload that still + carries secrets. + + Args: + label: A short label identifying the payload, e.g. ``"request"`` or + ``"response"``. + safe_payload: The already-redacted value to summarize. + max_characters: Maximum length of the serialized body before it is + truncated (default 500). + + Returns: + A ``"{label}_summary {body}"`` string, truncated with a trailing + marker when ``safe_payload``'s serialization exceeds + ``max_characters``. + """ + try: + serialized = json.dumps(safe_payload, ensure_ascii=False, default=str) + except (TypeError, ValueError): + # e.g. a circular reference -- fall back to repr rather than raise + # out of a logging call site. + serialized = str(safe_payload) + if len(serialized) > max_characters: + serialized = f"{serialized[:max_characters]}..." + return f"{label}_summary {serialized}" diff --git a/contextual_orchestrator/model_discovery.py b/contextual_orchestrator/model_discovery.py index b95d01758..542566a13 100644 --- a/contextual_orchestrator/model_discovery.py +++ b/contextual_orchestrator/model_discovery.py @@ -40,13 +40,14 @@ ModelClient, format_authorization_header, is_transient_error, + redact_text, ) if TYPE_CHECKING: from .cost_ledger import PriceBook -DISCOVERY_TIMEOUT_SECONDS = 15.0 _LOGGER = logging.getLogger(__name__) +DISCOVERY_TIMEOUT_SECONDS = 15.0 # One bounded retry for a provider's primary model-list fetch, reusing the same # transient-vs-terminal classification completion calls already trust # (is_transient_error). A short, fixed delay and a shortened retry timeout keep @@ -297,28 +298,54 @@ def __init__(self, provider_name: str, error_code: str) -> None: def _fetch_json(url: str, *, api_key: str = "", auth_scheme: str = "Bearer", timeout: float) -> Any: + """Fetch JSON, sending any credential only to the original trusted HTTPS host. + + Plain ``urllib`` follows a 3xx redirect by copying the original request's + headers -- ``Authorization`` included -- onto the redirected request even + when the redirect target is a completely different host (unlike some + other HTTP clients, urllib never strips sensitive headers on cross-origin + redirects). Every call site here passes a real provider credential in + ``api_key``, so a malicious or compromised provider endpoint issuing a + redirect to an attacker-controlled host would otherwise leak it. This + uses the same :class:`_TrustedDiscoveryRedirectHandler` opener as + :func:`_fetch_json_same_host_https` to reject any redirect that leaves + the original host instead of silently forwarding the header. + + The body read is capped at :data:`MAX_DISCOVERY_RESPONSE_BYTES` -- an + unbounded ``response.read()`` would let an outage page, a misbehaving + proxy, or a compromised provider endpoint stream an arbitrarily large + body into memory before JSON parsing ever runs. This mirrors the same + bounded-read-then-check pattern already used by + :func:`_fetch_json_same_host_https` and :func:`_fetch_configured_gateway_json`. + """ if not url.startswith("https://"): # Every caller passes one of the hardcoded PROVIDER_SOURCES chat_base_url # constants below, never external input -- but urlopen also honors # file:// and other unsafe schemes, so refuse anything not https as a # cheap invariant check rather than trusting the constant list alone. raise ValueError(f"refusing non-https model discovery URL: {url!r}") + parsed = urlsplit(url) + if not parsed.hostname: + raise ValueError(f"refusing discovery URL without hostname: {url!r}") headers = {"user-agent": _HTTP_USER_AGENT} if api_key: headers["authorization"] = format_authorization_header(auth_scheme, api_key) request = urllib.request.Request(url, headers=headers, method="GET") # Scheme is enforced to https:// immediately above; url is never attacker-controlled. try: - response = urllib.request.urlopen(request, timeout=timeout) # noqa: S310 - fixed provider inventory # nosemgrep: python.lang.security.audit.dynamic-urllib-use-detected.dynamic-urllib-use-detected + response = _open_trusted_discovery_request(request, trusted_host=parsed.hostname, timeout=timeout) except urllib.error.URLError as exc: if not isinstance(exc.reason, ssl.SSLCertVerificationError): raise context = ssl.create_default_context(cafile=certifi.where()) - response = urllib.request.urlopen( # noqa: S310 - fixed provider inventory # nosemgrep: python.lang.security.audit.dynamic-urllib-use-detected.dynamic-urllib-use-detected - request, timeout=timeout, context=context + response = _open_trusted_discovery_request( + request, trusted_host=parsed.hostname, timeout=timeout, context=context ) with response: - return json.loads(response.read().decode("utf-8")) + raw = response.read(MAX_DISCOVERY_RESPONSE_BYTES + 1) + if len(raw) > MAX_DISCOVERY_RESPONSE_BYTES: + raise ValueError("model discovery response exceeds maximum size") + return json.loads(raw.decode("utf-8")) def _fetch_models_dev_metadata(*, timeout: float) -> Any | None: @@ -408,6 +435,28 @@ def redirect_request(self, req, fp, code, msg, headers, newurl): return super().redirect_request(req, fp, code, msg, headers, newurl) +def _open_trusted_discovery_request( + request: urllib.request.Request, + *, + trusted_host: str, + timeout: float, + context: ssl.SSLContext | None = None, +) -> Any: + """Open ``request`` through an opener that rejects redirects leaving ``trusted_host``. + + Shared by :func:`_fetch_json` and :func:`_fetch_json_same_host_https` so + both authenticated discovery paths get identical, single-implementation + redirect protection instead of two copies that could silently drift + apart. ``context`` lets a caller retry once under a certificate-fallback + ``SSLContext`` without losing the redirect guard. + """ + handlers: list[urllib.request.BaseHandler] = [_TrustedDiscoveryRedirectHandler(trusted_host)] + if context is not None: + handlers.append(urllib.request.HTTPSHandler(context=context)) + opener = urllib.request.build_opener(*handlers) + return opener.open(request, timeout=timeout) # nosemgrep: python.lang.security.audit.dynamic-urllib-use-detected.dynamic-urllib-use-detected + + def _fetch_json_same_host_https( url: str, *, api_key: str = "", auth_scheme: str = "Bearer", timeout: float ) -> Any: @@ -419,11 +468,8 @@ def _fetch_json_same_host_https( raise ValueError(f"refusing discovery URL without hostname: {url!r}") headers = {"authorization": format_authorization_header(auth_scheme, api_key)} if api_key else {} request = urllib.request.Request(url, headers=headers, method="GET") - opener = urllib.request.build_opener( - _TrustedDiscoveryRedirectHandler(parsed.hostname) - ) try: - response = opener.open(request, timeout=timeout) # nosemgrep: python.lang.security.audit.dynamic-urllib-use-detected.dynamic-urllib-use-detected + response = _open_trusted_discovery_request(request, trusted_host=parsed.hostname, timeout=timeout) except urllib.error.URLError as exc: if isinstance(exc.reason, TimeoutError): raise TimeoutError(str(exc.reason)) from exc @@ -1197,10 +1243,17 @@ def discover_provider_models( source.provider_name, ) return [] - _LOGGER.debug( - "model discovery started account=%s", - source.provider_name, - ) + if _LOGGER.isEnabledFor(logging.DEBUG): + # Never include source.credential_name here: it is the KV key label + # (e.g. "OPENAI_API_KEY") and main's + # test_discovery_debug_log_identifies_account_without_secret forbids + # it from appearing in this log line at all, on top of the actual + # credential value never being logged. + _LOGGER.debug( + "discovery_attempt account=%s", + source.provider_name, + ) + started = time.monotonic() url = source.list_url if source.task_filter: url = f"{url}?task={source.task_filter}" @@ -1235,11 +1288,14 @@ def discover_provider_models( time.sleep(_DISCOVERY_RETRY_DELAY_SECONDS) if last_exc is not None: error_code = _provider_discovery_error_code(last_exc) - _LOGGER.debug( - "model discovery failed account=%s error_code=%s", - source.provider_name, - error_code, - ) + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug( + "discovery_provider_failed account=%s error_code=%s error_type=%s error_message=%s", + source.provider_name, + error_code, + type(last_exc).__name__, + redact_text(str(last_exc))[:500], + ) raise ProviderDiscoveryError(source.provider_name, error_code) from None if source.models_dev_provider_id: if models_dev_metadata is _NOT_FETCHED: @@ -1277,7 +1333,14 @@ def discover_provider_models( timeout=timeout, ca_bundle=ca_bundle, ) - except (urllib.error.URLError, TimeoutError, ValueError, OSError): + except (urllib.error.URLError, TimeoutError, ValueError, OSError, RuntimeError): + # RuntimeError matches the primary list-request retry loop above: + # ModelClient._resolve_addresses / _open_provider raise RuntimeError + # for DNS and request-validation transport failures, and this + # metadata fetch sits outside that loop's except tuple -- without + # RuntimeError here, a raw transport failure on this call alone + # would escape discover_provider_models uncaught and abort the + # entire discovery pass instead of just this provider's metadata. metadata = None payload = _merge_configured_gateway_metadata(payload, metadata) if source.style == "bytez": @@ -1285,11 +1348,13 @@ def discover_provider_models( else: discovered = _parse_openai_compatible(payload, source) result = [replace(model, evidence_only=source.evidence_only) for model in discovered] - _LOGGER.debug( - "model discovery completed account=%s model_count=%d", - source.provider_name, - len(result), - ) + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug( + "discovery_result account=%s model_count=%d elapsed_ms=%.1f", + source.provider_name, + len(result), + (time.monotonic() - started) * 1000.0, + ) return result @@ -1347,6 +1412,13 @@ def discover_all_models( routed, openrouter_paid_inference_available(timeout=timeout), ) + if _LOGGER.isEnabledFor(logging.INFO): + _LOGGER.info( + "discovery_complete providers=%d models=%d errors=%d", + len(sources), + len(routed), + len(errors), + ) return routed, errors diff --git a/contextual_orchestrator/orchestrator.py b/contextual_orchestrator/orchestrator.py index 1f99f5fac..5ff45ac97 100644 --- a/contextual_orchestrator/orchestrator.py +++ b/contextual_orchestrator/orchestrator.py @@ -16,6 +16,7 @@ import io import ipaddress import json +import logging import math import os from pathlib import Path @@ -89,6 +90,7 @@ # content is usually str; multimodal vision messages use OpenAI content-parts lists. ChatMessage = dict[str, Any] ProviderDestination = tuple[int, tuple[Any, ...]] +_LOGGER = logging.getLogger(__name__) MAX_LOCAL_CONCURRENCY = 64 _PASSTHROUGH_UNAVAILABLE_STATUS = frozenset({404, 410, 413}) _PROVIDER_ERROR_CHAIN_LIMIT = 8 @@ -1135,6 +1137,199 @@ def is_transient_error(exc: BaseException) -> bool: return False +def _log_provider_attempt(agent: ModelAgent, attempt: int, retry_limit: int) -> None: + """DEBUG-log one provider call attempt before it is made.""" + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug( + "provider_attempt agent_id=%s model=%s attempt=%d/%d", + agent.id, + agent.model, + attempt + 1, + retry_limit + 1, + ) + + +def _log_provider_attempt_failed( + agent: ModelAgent, attempt: int, exc: Exception, transient: bool +) -> None: + """DEBUG-log one failed provider attempt with a redacted, bounded error message.""" + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug( + "provider_attempt_failed agent_id=%s model=%s attempt=%d error_type=%s transient=%s error_message=%s", + agent.id, + agent.model, + attempt + 1, + type(exc).__name__, + transient, + redact_text(str(exc))[:500], + ) + + +def _log_provider_backoff(agent: ModelAgent, attempt: int, delay: float) -> None: + """DEBUG-log one backoff sleep before the next retry attempt.""" + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug( + "provider_backoff agent_id=%s attempt=%d delay_seconds=%.3f", + agent.id, + attempt + 1, + delay, + ) + + +def _log_provider_exhausted(agent: ModelAgent, attempts: int, last_error: Exception) -> None: + """WARNING-log a provider call that failed after using its full retry budget. + + Fires by default (no --verbose needed): a provider call that ultimately + failed is an actionable operational event, not just internal reasoning. + Only fires when a *real, non-zero* retry budget was configured and + actually exhausted. Two distinct, more precise events cover the cases + this must not be confused with: :func:`_log_provider_rejected_permanent` + (a real budget existed, but the failure was judged non-retryable before + it ran out) and :func:`_log_provider_no_retry_budget` (no retry budget + was ever configured at all, so there was never anything to exhaust, + regardless of whether the error itself was transient or not) -- so an + operator scanning WARNING output never mistakes "gave up after using its + full retry budget" for either "was never going to be retried in the + first place" or "was never allowed to be retried at all". + """ + _LOGGER.warning( + "provider_exhausted agent_id=%s model=%s attempts=%s final_error_type=%s", + agent.id, + agent.model, + attempts, + type(last_error).__name__, + ) + + +def _log_provider_no_retry_budget( + agent: ModelAgent, attempts: int, last_error: Exception, *, transient: bool +) -> None: + """WARNING-log a provider call that failed with no retry budget configured at all. + + Fires by default (no --verbose needed), mirroring + :func:`_log_provider_exhausted`'s default visibility, but under a + distinct event name for the case where the agent's configured retry + limit is 0: there was never any retry budget to exhaust or to give up + on early, regardless of whether the error itself was transient or not + (``attempts`` is then always exactly 1). "No retry budget was + configured" and "this error is non-retryable by nature" are two + different, independent facts -- collapsing every zero-budget failure + into :func:`_log_provider_rejected_permanent` would misleadingly imply + the error type itself was judged permanent, even for a transient error + (e.g. an HTTP 503) that simply never got a chance to retry. ``transient`` + carries the error's own classification explicitly so an operator can + still tell "this might have succeeded on retry, but none was allowed" + from "this wouldn't have been retried anyway" from this one event name. + """ + _LOGGER.warning( + "provider_no_retry_budget agent_id=%s model=%s attempts=%s final_error_type=%s transient=%s", + agent.id, + agent.model, + attempts, + type(last_error).__name__, + transient, + ) + + +def _log_provider_one_shot_call_failed( + agent: ModelAgent, attempts: int, last_error: Exception, *, transient: bool +) -> None: + """WARNING-log a provider call that failed under a caller-forced single-attempt policy. + + Fires by default (no --verbose needed), mirroring + :func:`_log_provider_no_retry_budget`'s default visibility, but under a + distinct event name for a materially different situation: this call was + not made against an agent with no configured retry budget at all -- it + was ``ModelClient._send_raw_with_retry(..., allow_transient_retries=False)`` + deliberately restricting *this one call* to exactly one attempt (e.g. + ``proxy_send_once``, used so an already-failing-over passthrough request + cannot itself amplify load with a nested retry loop). The agent's real + ``_retry_limit`` may well be non-zero; it simply was never consulted for + this call. Reusing :func:`_log_provider_no_retry_budget` here would tell + an operator the agent has no retry budget configured, which may be false + and is misleading either way -- the true reason this call did not retry + was the caller's one-shot policy, not the agent's configuration. + ``attempts`` is always exactly 1 by construction, mirroring + :func:`_log_provider_no_retry_budget`. + """ + _LOGGER.warning( + "provider_one_shot_call_failed agent_id=%s model=%s attempts=%s final_error_type=%s transient=%s", + agent.id, + agent.model, + attempts, + type(last_error).__name__, + transient, + ) + + +def _log_provider_rejected_permanent(agent: ModelAgent, attempts: int, last_error: Exception) -> None: + """WARNING-log a provider call that stopped on a non-transient failure with budget left. + + Fires by default (no --verbose needed), mirroring + :func:`_log_provider_exhausted`'s default visibility, but under a + distinct event name: a real, non-zero retry budget was configured, and + the retry loop stopped early -- before that budget ran out -- because + ``is_transient_error`` classified the final failure as permanent (e.g. a + 401/403/malformed-request response). See :func:`_log_provider_no_retry_budget` + for the separate case where no retry budget was configured at all. + """ + _LOGGER.warning( + "provider_rejected_permanent agent_id=%s model=%s attempts=%s final_error_type=%s", + agent.id, + agent.model, + attempts, + type(last_error).__name__, + ) + + +def _log_retry_outcome( + agent: ModelAgent, + attempt: int, + retry_limit: int, + last_error: Exception, + *, + transient: bool, + allow_transient_retries: bool = True, +) -> None: + """Log a terminated retry loop's outcome under its correct distinct event name. + + ``ModelClient._send_with_retry`` and ``ModelClient._send_raw_with_retry`` + run this identical classification (no retry budget at all / a caller- + forced single attempt / budget exhausted / stopped early on a + non-transient error) once their retry loop ends. It used to be + duplicated verbatim in both methods, and that duplication already caused + a real regression once -- a fix landed in one copy but was missed in the + other (see ``tests/test_orchestrator_debug_logging.py``'s + ``test_send_raw_with_retry_*`` tests, which exist specifically to catch + that class of drift). Extracting the shared logic here makes it + impossible for the two call sites to diverge again. + + ``allow_transient_retries`` distinguishes *why* ``retry_limit`` came out + as 0. ``_send_raw_with_retry`` computes + ``retry_limit = self._retry_limit(agent) if allow_transient_retries else 0``: + when the caller passed ``allow_transient_retries=False`` (``proxy_send_once``, + a deliberate one-shot call so an already-failing-over passthrough request + cannot itself amplify load with a nested retry loop), a zero here says + nothing about whether the agent actually has a configured retry budget -- + it was simply never consulted. Logging that case as + :func:`_log_provider_no_retry_budget` would misreport a real, + possibly-non-zero budget as absent; :func:`_log_provider_one_shot_call_failed` + names the true reason instead. ``_send_with_retry`` has no such + caller-forced restriction and always passes the default ``True``, so its + zero-budget case is unaffected and still reaches + :func:`_log_provider_no_retry_budget`. + """ + if retry_limit == 0: + if allow_transient_retries: + _log_provider_no_retry_budget(agent, attempt + 1, last_error, transient=transient) + else: + _log_provider_one_shot_call_failed(agent, attempt + 1, last_error, transient=transient) + elif attempt >= retry_limit: + _log_provider_exhausted(agent, attempt + 1, last_error) + else: + _log_provider_rejected_permanent(agent, attempt + 1, last_error) + + def _record_provider_response_telemetry(data: Any, started_monotonic: float) -> None: """Annotate the active provider span with one response's concrete evidence. @@ -1611,7 +1806,9 @@ def _send_with_retry( """Call the provider, retrying transient failures with exponential backoff + jitter.""" last_error: Exception | None = None retry_limit = self._retry_limit(agent) + attempt = 0 for attempt in range(retry_limit + 1): # pragma: no branch - retry limits are validated non-negative + _log_provider_attempt(agent, attempt, retry_limit) try: return ( self._send(agent, payload, destination) @@ -1620,9 +1817,15 @@ def _send_with_retry( ) except Exception as exc: # noqa: BLE001 - classify then decide last_error = exc - if attempt >= retry_limit or not is_transient_error(exc): + transient = is_transient_error(exc) + _log_provider_attempt_failed(agent, attempt, exc, transient) + if attempt >= retry_limit or not transient: break - self._sleep(self._backoff_delay(attempt)) + delay = self._backoff_delay(attempt) + _log_provider_backoff(agent, attempt, delay) + self._sleep(delay) + if last_error is not None: + _log_retry_outcome(agent, attempt, retry_limit, last_error, transient=transient) if isinstance(last_error, urllib.error.HTTPError) and _is_tool_execution_stopped(last_error): raise _provider_tool_execution_stopped(agent) from None if isinstance(last_error, urllib.error.HTTPError) and ( @@ -2149,14 +2352,29 @@ def _send_raw_with_retry( """Passthrough transport with the same transient-failure retry policy as _send.""" last_error: Exception | None = None retry_limit = self._retry_limit(agent) if allow_transient_retries else 0 + attempt = 0 for attempt in range(retry_limit + 1): + _log_provider_attempt(agent, attempt, retry_limit) try: return self._send_raw(agent, endpoint, payload, destination) except Exception as exc: # noqa: BLE001 - classify then decide last_error = exc - if attempt >= retry_limit or not is_transient_error(exc): + transient = is_transient_error(exc) + _log_provider_attempt_failed(agent, attempt, exc, transient) + if attempt >= retry_limit or not transient: break - self._sleep(self._backoff_delay(attempt)) + delay = self._backoff_delay(attempt) + _log_provider_backoff(agent, attempt, delay) + self._sleep(delay) + if last_error is not None: + _log_retry_outcome( + agent, + attempt, + retry_limit, + last_error, + transient=transient, + allow_transient_retries=allow_transient_retries, + ) if isinstance(last_error, urllib.error.HTTPError) and _is_tool_execution_stopped(last_error): raise _provider_tool_execution_stopped(agent) from None if isinstance(last_error, urllib.error.HTTPError) and ( @@ -5715,6 +5933,15 @@ def _static_rank_key( priority = 0 has_affinity = 1 if affinity is None else 0 negated_affinity = 0.0 if affinity is None else -float(affinity) + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug( + "rank_candidate agent_id=%s model=%s priority=%s capability_fit=%s affinity=%s", + agent.id, + agent.model, + priority, + bool(role_fit), + "unmeasured" if affinity is None else f"{affinity:.3f}", + ) return (-role_fit, -int(priority), has_affinity, negated_affinity, agent.id) def _ranked_agents( @@ -5765,6 +5992,14 @@ def _ranked_agents( and (not chat_only or _is_general_chat_agent(agent)) and all(tag in agent.tags for tag in required_tags) ] + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug( + "rank_partition role=%s candidates=%d free_only=%s chat_only=%s", + role, + len(candidates), + free_only, + chat_only, + ) if not candidates: if _REQUEST_ZDR_ONLY.get(): raise RuntimeError("no ZDR-eligible agent is available for the active privacy policy") @@ -5814,12 +6049,20 @@ def _measured_member_order(self, member_ids: list[str]) -> list[str]: throughput/stability ledger decides; with no evidence at all the caller's input order survives untouched. No synthetic scores. """ - if any( + judged_quality = any( self._quality_router.member_observation_count(member_id) > 0 for member_id in member_ids - ): - return self._quality_router.ranked_member_ids(member_ids) - return self._group_router.ranked_member_ids(member_ids) + ) + router = self._quality_router if judged_quality else self._group_router + if _LOGGER.isEnabledFor(logging.DEBUG): + for member_id in member_ids: + _LOGGER.debug( + "rank_candidate agent_id=%s judged_quality=%s evidence_score=%.3f", + member_id, + judged_quality, + router.member_score(member_id), + ) + return router.ranked_member_ids(member_ids) def _psychometric_order( self, candidates: list[ModelAgent], prompt_context: str | None @@ -6160,6 +6403,15 @@ def _select_agent( raise RuntimeError(f"no enabled agent available for role={role}") if role in selected.provider_exclusions: # pragma: no cover raise RuntimeError(f"no eligible agent available for role={role}") + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug( + "select_agent role=%s free_only=%s zdr_only=%s chosen_agent_id=%s chosen_model=%s", + role, + free_only, + bool(_REQUEST_ZDR_ONLY.get()), + selected.id, + selected.model, + ) return selected def _capability_agents(self, capability: str, model_name: str | None = None) -> list[ModelAgent]: @@ -6774,19 +7026,45 @@ def _circuit_open(self, agent_id: str) -> bool: if time.monotonic() - state["opened_at"] >= self.circuit_reset_seconds: state["failures"] = 0.0 state["opened_at"] = 0.0 - return False - return True + reset_occurred = True + else: + reset_occurred = False + if reset_occurred: + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug("circuit_reset agent_id=%s", agent_id) + return False + return True def _record_failure(self, agent_id: str) -> None: + opened = False with self._circuit_lock: state = self._circuit.setdefault(agent_id, {"failures": 0.0, "opened_at": 0.0}) state["failures"] += 1.0 - if state["failures"] >= self.circuit_failure_threshold and not state["opened_at"]: + failures = state["failures"] + if failures >= self.circuit_failure_threshold and not state["opened_at"]: state["opened_at"] = time.monotonic() + opened = True + if _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug( + "circuit_failure agent_id=%s failures=%s threshold=%s", + agent_id, + failures, + self.circuit_failure_threshold, + ) + if opened: + _LOGGER.warning( + "circuit_opened agent_id=%s failures=%s threshold=%s reset_seconds=%s", + agent_id, + failures, + self.circuit_failure_threshold, + self.circuit_reset_seconds, + ) def _record_success(self, agent_id: str) -> None: with self._circuit_lock: - self._circuit.pop(agent_id, None) + cleared = self._circuit.pop(agent_id, None) + if cleared is not None and _LOGGER.isEnabledFor(logging.DEBUG): + _LOGGER.debug("circuit_cleared agent_id=%s", agent_id) def _agent(self, agent_id: str) -> ModelAgent: for agent in self.candidates: diff --git a/contextual_orchestrator/server.py b/contextual_orchestrator/server.py index 4ea2f1d8b..a12f54c32 100644 --- a/contextual_orchestrator/server.py +++ b/contextual_orchestrator/server.py @@ -33,6 +33,12 @@ InvalidBatchModelError, ) from .batch_routing import BatchRequest +from .debug_logging import ( + redact_credential_shaped_keys, + response_metadata_for_log, + summarize_payload_for_log, + summarize_request_for_log, +) from .orchestrator import ( BudgetExceededError, MAX_LOCAL_CONCURRENCY, @@ -62,6 +68,7 @@ reset_session_id, session_id_from_headers, session_id_from_request, + session_id_hash, set_session_id, ) from .video_jobs import ( @@ -5048,6 +5055,21 @@ def _strip_internal_fields(value: Any) -> Any: def _response_payload(payload: dict[str, Any], include_trace: bool) -> dict[str, Any]: safe_payload = redact_value(payload) + if _LOGGER.isEnabledFor(logging.DEBUG): + # The DEBUG response-body summary logs only an allowlisted metadata + # shape (has_error/model/choice_count/usage) via + # response_metadata_for_log -- never the payload itself. redact_value + # only pattern-matches a secret's in-string *value* shape, and even + # the additional redact_credential_shaped_keys pass only masks + # *credential*-shaped JSON keys; neither ever masks ordinary response + # text (choices[].message.content, tool-call arguments, an + # error.message that can reflect caller-supplied input), which is not + # a credential but can still carry PII or business-sensitive content + # (CWE-532). redact_credential_shaped_keys is applied on top of the + # allowlist anyway, defense-in-depth, in case a future allowlist + # field ever collides with a credential-shaped key name. + log_safe_payload = redact_credential_shaped_keys(response_metadata_for_log(safe_payload)) + _LOGGER.debug(summarize_payload_for_log("response", log_safe_payload)) public_payload = _strip_internal_fields(safe_payload) if include_trace: return public_payload @@ -5429,17 +5451,87 @@ def finish(self) -> None: # semantics: assume the connection closes until a request says keep-alive. close_connection = True + def send_response(self, code: int, message: str | None = None) -> None: + """Capture the response status for the per-request log, then delegate to stdlib. + + `_last_status` (read by `_log_request_summary`) used to be set + only by this class's own `_send`/`_send_text`/`_send_bytes`/ + `_send_sse` writers. A response the framework generates itself -- + e.g. `BaseHTTPRequestHandler`'s built-in 501 for an unsupported + HTTP method, or a `send_error` call from `parse_request()` on a + malformed request line -- calls `send_response` directly and + bypasses all of those writers, so the INFO summary logged + `status=-` even though a real status was already sent to the + client. `send_response` is stdlib's own single choke point every + response path (including its own `send_error`) already goes + through, so overriding it here captures the status for every + current and future response path uniformly, not just this + module's own writers. + """ + self._last_status = code + super().send_response(code, message) + + def parse_request(self) -> bool: + """Timestamp the moment real request data starts being handled. + + ``BaseHTTPRequestHandler.handle_one_request`` blocks on + ``self.rfile.readline()`` *before* calling this method -- on a + keep-alive connection that read waits on the client's idle time + between requests, not on any processing this server does. + Recording ``_request_started`` here, at the top of + ``parse_request`` (immediately after that blocking read has + already returned real request bytes), keeps + ``_log_request_summary``'s ``latency_ms`` scoped to actual + request handling instead of also counting the client's think + time. + """ + self._request_started = time.monotonic() + return super().parse_request() + def handle_one_request(self) -> None: """Reset per-request state before parsing each persistent request. Body-consumption tracking must restart per request so an unread declared body still closes the connection, and correlation/trace state must never leak across requests on a reused connection. + + ``command``/``path`` are reset here too: stdlib's own + ``handle_one_request`` only assigns them when it actually parses a + request line, so on a keep-alive connection's *last* call -- + triggered by the client closing the connection, where nothing is + read at all -- they would otherwise still hold the *previous* + request's values. Resetting them first lets + ``_log_request_summary``'s existing "nothing to report" guard + correctly recognize that no new request happened this call, + instead of logging the prior request a second time with a + statusless "phantom" entry. + + ``_request_started`` is reset to ``None`` here too, ahead of the + blocking read: it is only ever set for real inside + ``parse_request`` above (once request data has actually + arrived), and a call that reads nothing at all (a closed + keep-alive connection) never reaches that point -- exactly the + case ``_log_request_summary``'s own guard already skips. + + ``_response_headers_sent`` is reset to ``False`` here too: it is + the per-request marker ``_write_response`` reads to decide + whether a caught disconnect happened before or after the status + line/headers were actually flushed to the client (see + ``_write_response``'s docstring). Resetting it per request keeps + a prior request's successful delivery from leaking into this + one's disconnect classification on a reused keep-alive + connection. """ self._request_body_consumed = False + self._last_status = None + self._response_headers_sent = False + self.command = None + self.path = None + self._request_started = None try: super().handle_one_request() finally: + self._log_request_summary(self._request_started) self._reset_session() # A request that declared a body it never delivered (unsupported # method, rejected route) must not leave those bytes on a reusable @@ -5454,6 +5546,59 @@ def handle_one_request(self) -> None: ): self.close_connection = True + def _log_request_summary(self, started: float | None) -> None: + """Emit one body-free INFO summary line per completed request. + + Carries method, path, status, latency, and the bounded ADR 0122 + correlation hash only -- never headers, a query string beyond the + raw path, or a request/response body. A connection that never + delivered any request bytes at all (the client simply closed a + reused keep-alive connection) has no method, no path, AND no + status, and is skipped -- there is nothing to report. + + A request that *did* deliver bytes but whose request line + ``parse_request`` rejected as malformed (or that stdlib's + ``handle_one_request`` rejected outright as too long, before + ever calling our ``parse_request`` override) still gets a real + status sent to the client -- 400 or 414 -- via ``send_error``, + which flows through the ``send_response`` override above into + ``_last_status``, even though ``command``/``path`` stay unset + (stdlib's own ``parse_request`` explicitly resets ``self.command`` + to ``None`` "in case of error on the first line" and never + reaches the later assignment that would set ``path``). Skipping + on method/path alone, as this used to, silently dropped that + entry even though a real response was sent. ``_last_status`` is + reset to ``None`` at the top of every ``handle_one_request`` call + and only ever (re)populated by ``send_response`` during this + call's own processing, so treating "some status was recorded" + as an equally valid reason to log -- not just "some + method/path was recorded" -- captures every request that + actually produced a response while still skipping a truly + byte-free keep-alive close. + + ``started`` being ``None`` still means ``parse_request`` was + never entered (true of both the byte-free close above and the + too-long-request-line case, which stdlib rejects before ever + calling it); the ``or time.monotonic()`` fallback below keeps + that from ever raising on a future stdlib change. + """ + if not _LOGGER.isEnabledFor(logging.INFO): + return + method = getattr(self, "command", None) + path = getattr(self, "path", None) + status = getattr(self, "_last_status", None) + if not method and not path and status is None: + return + _LOGGER.info( + summarize_request_for_log( + method=method or "-", + path=path or "-", + status=status, + latency_ms=(time.monotonic() - (started or time.monotonic())) * 1000.0, + session_id_hash=session_id_hash(), + ) + ) + def do_GET(self) -> None: # noqa: N802 """Dispatch GET requests after applying the route's authorization scope.""" parsed = urllib.parse.urlparse(self.path) @@ -7886,6 +8031,25 @@ def _write_response(self, writer: Callable[[], None]) -> bool: socket and raises again -- uncaught this time, crashing the request-handling thread (visible as a second, unhandled BrokenPipeError in server logs after the first). + + A caught disconnect can strike in two different places, and only + one of them means the client received nothing: + + * Before the status line/headers were flushed (``end_headers()`` + itself raises, or an earlier ``send_response``/``send_header`` + call does). The client has no real response at all. + * After ``end_headers()`` already completed -- a later body + write in the same call, or a later ``_write_sse`` frame on an + SSE stream ``_begin_sse`` already opened successfully. The + client DID receive the real status line and headers; only the + body (or a later chunk of it) was cut short. + + Every ``_send*``/``_begin_sse`` writer sets + ``self._response_headers_sent = True`` immediately after its own + ``end_headers()`` call returns, so that flag -- reset to + ``False`` once per request by ``handle_one_request`` -- tells + this shared choke point which of the two cases just happened, + without each writer needing its own disconnect-handling logic. """ # A rejection can happen before _read_json (authentication, rate # limiting, or media type). Reusing that HTTP/1.1 connection would @@ -7902,6 +8066,27 @@ def _write_response(self, writer: Callable[[], None]) -> bool: return True except (BrokenPipeError, ConnectionError, OSError): _LOGGER.debug("client_disconnected") + # `_send*`/`_begin_sse` writers record their *intended* + # status in `self._last_status` before calling this method + # (and `send_response`'s override above does the same for + # whatever status the writer itself sends) -- but a dead + # peer before headers were ever flushed means that status + # was never actually delivered. Left uncorrected in that + # case, `_log_request_summary` reads `_last_status` straight + # into the per-request INFO summary, falsely reporting a + # completed 200/4xx/5xx response for a request whose write + # failed before anything reached the client. Clear it back + # to the same `None` this module already uses for "a + # response was never sent" ONLY then -- a disconnect that + # struck after `_response_headers_sent` was already set + # means the client genuinely received that status, so + # clearing it here would instead falsely report "no status" + # for a request that was, in fact, answered. + # `hasattr`/`getattr` guard against tests that call this + # method directly against a bare `object()` stand-in for + # `self`, which has no instance `__dict__` to assign into. + if hasattr(self, "_last_status") and not getattr(self, "_response_headers_sent", False): + self._last_status = None return False def _send( @@ -7911,6 +8096,7 @@ def _send( *, extra_headers: dict[str, str] | None = None, ) -> None: + self._last_status = status raw = json.dumps(payload, ensure_ascii=False).encode("utf-8") def _write() -> None: @@ -7921,11 +8107,17 @@ def _write() -> None: for name, value in (extra_headers or {}).items(): self.send_header(name, value) self.end_headers() + # Marks that the status line/headers were actually flushed + # to the client -- see `_write_response`'s docstring. Must + # be set only after `end_headers()` returns without raising, + # and only before the body write that might still fail. + self._response_headers_sent = True self.wfile.write(raw) self._write_response(_write) def _send_text(self, payload: str, content_type: str, status: int = 200) -> None: + self._last_status = status raw = payload.encode("utf-8") def _write() -> None: @@ -7934,22 +8126,27 @@ def _write() -> None: self.send_header("content-length", str(len(raw))) self._send_security_headers() self.end_headers() + self._response_headers_sent = True # see _write_response self.wfile.write(raw) self._write_response(_write) def _send_bytes(self, payload: bytes, content_type: str, status: int = 200) -> None: + self._last_status = status + def _write() -> None: self.send_response(status) self.send_header("content-type", content_type) self.send_header("content-length", str(len(payload))) self._send_security_headers() self.end_headers() + self._response_headers_sent = True # see _write_response self.wfile.write(payload) self._write_response(_write) def _send_sse(self, body: str, status: int = 200) -> None: + self._last_status = status raw = body.encode("utf-8") def _write() -> None: @@ -7959,12 +8156,14 @@ def _write() -> None: self.send_header("content-length", str(len(raw))) self._send_security_headers() self.end_headers() + self._response_headers_sent = True # see _write_response self.wfile.write(raw) self._write_response(_write) def _begin_sse(self) -> bool: # Incremental SSE: no content-length; the connection close delimits the body. + self._last_status = 200 self.close_connection = True def _write() -> None: @@ -7973,10 +8172,21 @@ def _write() -> None: self.send_header("cache-control", "no-cache") self._send_security_headers() self.end_headers() + self._response_headers_sent = True # see _write_response return self._write_response(_write) def _write_sse(self, frame: str) -> bool: + """Write one SSE frame; relies on a prior successful `_begin_sse`. + + Never touches `self._response_headers_sent` itself: a caller + only ever reaches this after `_begin_sse` already returned + `True`, so that flag is already set from the initial headers + flush. If a *later* frame's write fails here, `_write_response` + correctly sees the flag still set and preserves the 200 that was + genuinely already delivered, instead of erasing it. + """ + def _write() -> None: self.wfile.write(frame.encode("utf-8")) self.wfile.flush() diff --git a/contextual_orchestrator/telemetry.py b/contextual_orchestrator/telemetry.py index 3b9fdccb6..737441a39 100644 --- a/contextual_orchestrator/telemetry.py +++ b/contextual_orchestrator/telemetry.py @@ -134,6 +134,21 @@ def reset_session_id(token: Token[str | None]) -> None: _CURRENT_SESSION.reset(token) +def session_id_hash() -> str | None: + """Return the ADR 0122 bounded correlation hash for the current request. + + ``None`` when no session is bound. Shared by :func:`_safe_attributes` + (OTLP span attributes) and by `server.py`'s per-request log summary, so + every surface that ever needs "which request was this" uses exactly one + hash of exactly one algorithm -- the raw session id itself never leaves + this module. + """ + session_id = current_session_id() + if not session_id: + return None + return hashlib.sha256(session_id.encode("utf-8")).hexdigest() + + def attach_trace_context(headers: Mapping[str, str]) -> Any: """Attach an inbound W3C trace context and return its reset token.""" if _otel_extract is None or _otel_attach is None: @@ -182,11 +197,9 @@ def _safe_attributes( result[key] = value[:256] elif isinstance(value, (bool, int, float)): result[key] = value - session_id = current_session_id() - if session_id: - result["contextual_orchestrator.session_id_hash"] = hashlib.sha256( - session_id.encode("utf-8") - ).hexdigest() + hashed_session_id = session_id_hash() + if hashed_session_id is not None: + result["contextual_orchestrator.session_id_hash"] = hashed_session_id return result diff --git a/docs/adr/0005-verbose-debug-logging.md b/docs/adr/0005-verbose-debug-logging.md new file mode 100644 index 000000000..5de0da5ff --- /dev/null +++ b/docs/adr/0005-verbose-debug-logging.md @@ -0,0 +1,174 @@ +# ADR 0005: Verbose/debug logging with a redaction safety net + +## Status + +Accepted. + +## Context + +Diagnosing why the gateway picked a given agent, why a provider call was +retried, or why a circuit breaker opened required adding temporary `print` +statements: the codebase had the `_LOGGER = logging.getLogger(__name__)` +convention in three modules (`server.py`, `telemetry.py`, `video_jobs.py`) +but no `logging.basicConfig` call anywhere, no CLI verbosity flag, and no +shared policy for what may be logged at which level. `orchestrator.py` (the +retry loop, circuit breaker, and evidence-based ranking in `_ranked_agents`) +and `model_discovery.py` (per-provider discovery attempts) had no logger at +all. This mirrors the gap ADR 0122 closed for span-based tracing: that ADR +correlates a request across providers via OpenTelemetry; this one gives an +operator or developer the internal *why* of one gateway decision without a +tracing backend, and does so as a runtime-observability decision in this +series rather than a product-planning one (see `docs/planning/adrs`'s own +distinction). + +## Decision + +Add a leaf module, `contextual_orchestrator/debug_logging.py`, that owns +level-name parsing (`parse_log_level_name`), one configuration entrypoint +(`configure_logging(level_name, redactor=None)`), and small pure log-line +formatters. No new dependency: this is stdlib `logging` only (see the +Ponytail entry added to `docs/library_research.md`). Because leaf modules may +not import anything else in this package, `orchestrator.py`, +`model_discovery.py`, and `server.py` can all depend on it without a cycle. + +`configure_logging` calls `logging.basicConfig(level=level, force=True)` -- +`force=True` is required because plain `basicConfig` is a no-op after the +first call in a process, which would otherwise make a second in-process CLI +invocation (a real pattern in this repo's own test suite) silently keep +whatever level the first call configured. + +`contextual_orchestrator/__main__.py` resolves the effective level once, in +`_configure_logging_from_cli`, via a `parse_known_args` pre-scan that runs +before subcommand dispatch. This one call site covers +`register-credential`, `discover-models`, `check-fast-mlsirm`, one-shot +completion, and `--serve` uniformly. Precedence: explicit `--log-level` > +`--verbose`/`--debug` > default `WARNING` (the existing de facto stdlib +default, kept unchanged so an upgrade does not change anyone's stderr output +by default). An invalid flag value fails closed with an argparse-style +`SystemExit(2)`; it is never silently ignored. Subcommand dispatch itself is +resolved by `_subcommand_token_index`, which skips past any recognized +leading `--log-level`/`--verbose`/`--debug` tokens (without removing them +from the argument list a subcommand's own parser sees) so that, e.g., +`--verbose discover-models` still reaches the `discover-models` subcommand +instead of falling through to the one-shot completion parser with +`discover-models` parsed as the prompt. Every CLI parser here (the pre-scan +and each subcommand's own parser) sets `allow_abbrev=False`: without it, +argparse's own prefix-abbreviation matching (`--log-l` for `--log-level`, +`--ver` for `--verbose`) and `_subcommand_token_index`'s plain string +comparison would disagree -- argparse would silently accept the +abbreviation while the locator would not recognize it as a flag to skip +past, misrouting the same way an unrecognized flag would. Disabling +abbreviations everywhere removes the disagreement: an abbreviated flag is +now rejected consistently, with a clear argparse error, rather than +silently accepted by one parser and not the other. + +New instrumentation lands at the previously silent decision points: the +provider retry loop (`_send_with_retry`/`_send_raw_with_retry`: per-attempt, +backoff, and a WARNING-level `provider_exhausted` line that fires without +`--verbose`, since a call that used its full retry budget is an actionable +operational event -- fires only when a *real, non-zero* retry budget was +configured and actually used up. Two other, distinctly named events cover +the cases this must not be confused with: `provider_rejected_permanent` +(a real budget existed, but the retry loop stopped early because +`is_transient_error` classified the final failure as permanent) and +`provider_no_retry_budget` (the configured retry limit is 0, so there was +never any budget to exhaust or give up on early, regardless of whether the +error itself was transient -- carries that classification explicitly via a +`transient=%s` field, since "no retry budget was configured" and "this +error is non-retryable by nature" are independent facts that collapsing +into one event would conflate); the per-agent circuit breaker (`_record_failure` logs a +DEBUG line on every increment and a WARNING `circuit_opened` line only on the +edge transition into the open state; `_record_success` logs DEBUG only when +there was real breaker state to clear, to avoid a firehose on every healthy +call); and evidence-based ranking (`_static_rank_key`, `_measured_member_order`, +`_select_agent`). `model_discovery.py` gains per-provider `discovery_attempt` +/ `discovery_result` / `discovery_provider_failed` DEBUG lines (identifying +the account by provider name only -- never the KV credential name or value) +and one `discovery_complete` INFO summary. `server.py` gains one body-free +per-request INFO summary (method, bare path with any query string stripped, +status, latency, and the ADR 0122 session correlation hash -- factored into +a new `telemetry.session_id_hash()` shared by both surfaces; skipped +entirely on a keep-alive connection's closing call, which parses no new +request) and a DEBUG response-body summary that logs only an allowlisted +metadata shape, never the payload itself (see below). The status this +summary reports is captured by overriding `send_response` -- stdlib's own +single choke point every response path goes through, including its own +`send_error` -- rather than only this module's own `_send`/`_send_text`/ +`_send_bytes`/`_send_sse` writers, so a response `BaseHTTPRequestHandler` +generates itself (e.g. its built-in 501 for an HTTP method with no matching +`do_*` handler) is captured too, instead of logging `status=-` for a +response the client actually received. + +Redaction is layered, and for the response-body summary specifically an +allowlist replaces "log the (redacted) payload" outright: every call site +that logs caller- or provider-derived string content wraps it in the +existing, unmodified `orchestrator.redact_text`/`redact_value` before +logging (e.g. `redact_text(str(exc))[:500]` in the retry loop) -- but +`redact_text`/`redact_value` only pattern-match a secret's in-string *value* +shape (e.g. `api_key=...` or `Bearer ...`) and never inspect the JSON key a +string is nested under, nor do they (nor should they) touch *ordinary* +response text at all. An earlier revision of this design logged the entire +already-redacted response payload at DEBUG, plus an additional +`debug_logging.redact_credential_shaped_keys` pass that replaces any dict +value under a credential-shaped key name (`key`, `api_key`, `token`, +`secret`, `password`, `credential`, `auth`, `private_key`, `pem`, and +similar) with `[REDACTED]` regardless of the value's own shape; independent +adversarial review (CodeRabbit, CWE-532) found that this still let ordinary, +non-credential response content -- `choices[].message.content`, tool-call +arguments, an `error.message` that can reflect caller-supplied input -- +reach DEBUG output verbatim, which can carry PII or business-sensitive text +that has nothing to do with secrets. `debug_logging.response_metadata_for_log` +now extracts a small, fixed allowlist instead -- `has_error`, `model`, +`choice_count`, and numeric-only `usage` counts -- and that allowlisted dict, +not the payload, is what `redact_credential_shaped_keys` runs over +(defense-in-depth, in case a future allowlist field ever collides with a +credential-shaped key name) and what reaches the log line. This log-only +summary never changes what `_response_payload` returns to actual HTTP +callers. Finally, `configure_logging`'s optional `redactor` attaches a +`logging.Filter` to the handler `basicConfig` installs -- deliberately the +handler, not the Logger object, since a Logger-level filter does not run on +records propagating up from a child logger -- as a safety net for a call +site that forgets. That filter redacts a record's exception traceback too, +not just its rendered message: `logging.Formatter.format()` renders +`record.exc_info` into text strictly *after* every filter has already run, +so a call site using `exc_info=True`/`logger.exception(...)` could carry a +secret embedded in the exception's own `str()` (e.g. an upstream error +reflecting `api_key=sk-...`) straight into the formatted traceback, +bypassing message-level redaction entirely. The filter now renders +`record.exc_info` into text itself, redacts that text, caches it as +`record.exc_text`, and clears `record.exc_info` so the handler's own +formatter uses the already-redacted text instead of re-deriving an +unredacted one. Raw prompt or message text is never logged at any level, +only lengths, identifiers, and (for the response-body summary specifically) +allowlisted shape metadata: `redact_text` is documented to deliberately +leave PII alone, so this design does not lean on it to scrub content it was +never meant to scrub. + +## Consequences + +An operator can now answer "why did this request retry", "why did the +circuit breaker open on this agent", and "why did `orchestrator/free` pick +this model" from `--log-level DEBUG` / `--verbose` output, and get a +body-free per-request breadcrumb trail at `--log-level INFO`, without +touching OpenTelemetry. Layering value-pattern redaction, key-name-based +redaction, an allowlist for the one call site that would otherwise log +arbitrary content, and a handler-level safety net means a call site that +forgets one layer is still caught by one of the others, at the cost of a +little extra work per already-redacted DEBUG line when a redactor is +configured. Default (`WARNING`) behavior is unchanged: the new +DEBUG/INFO lines are opt-in, and the two new WARNING lines +(`circuit_opened`, `provider_exhausted`) are the only default-visible +additions, both operator-actionable rather than internal reasoning. + +## References + +Chickowski, E., et al. (OWASP Foundation). (n.d.). *Logging cheat sheet*. +Retrieved August 31, 2026, from +https://cheatsheetseries.owasp.org/cheatsheets/Logging_Cheat_Sheet.html + +Kent, K., & Souppaya, M. (2006). *Guide to computer security log management* +(NIST Special Publication 800-92). National Institute of Standards and +Technology. https://doi.org/10.6028/NIST.SP.800-92 + +Python Software Foundation. (n.d.). *Logging HOWTO*. Python 3 documentation. +Retrieved August 31, 2026, from https://docs.python.org/3/howto/logging.html diff --git a/docs/adr/README.md b/docs/adr/README.md index d4347e352..c3b50506d 100644 --- a/docs/adr/README.md +++ b/docs/adr/README.md @@ -12,6 +12,7 @@ They do not share numbering with `docs/planning/adrs/`. | [0002](0002-control-plane-orchestrator.md) | Control-plane orchestrator, not a trained coordinator | Accepted | Xu et al. (2025) TRINITY arXiv:2512.04695; Nielsen et al. (2025) Conductor arXiv:2512.04388; Sakana Fugu (2026) live pages | | [0003](0003-cost-aware-sync-batch-routing.md) | Cost-aware sync-versus-batch routing | Accepted | Chen et al. (2023) FrugalGPT arXiv:2305.05176; Ong et al. (2024) RouteLLM arXiv:2406.18665; Ding et al. (2024) Hybrid LLM arXiv:2404.14618 | | [0004](0004-msa-leaf-composition.md) | MSA leaf — standalone and callable | Accepted | NIST SP 800-204 independent deployability; planning ADR 0001 fail-closed judge composition | +| [0005](0005-verbose-debug-logging.md) | Verbose/debug logging with a redaction safety net | Accepted | OWASP Logging Cheat Sheet; NIST SP 800-92 log management; Python `logging` HOWTO | Each record uses Context / Decision / Consequences plus an APA 7th **References** section. Cite only verified DOI or official URLs. arXiv diff --git a/docs/library_research.md b/docs/library_research.md index 998004420..bff7ec1ec 100644 --- a/docs/library_research.md +++ b/docs/library_research.md @@ -19,6 +19,8 @@ primitives use maintained libraries when the enterprise target requires them. | Rendered policy browser | [MCP Python SDK](https://github.com/modelcontextprotocol/python-sdk) | Keep as a pinned deployment-provided optional package for the existing Camoufox MCP transport; do not claim a repository `policy-browser` extra until this project owns that lock and publish contract. | Reuses the protocol client and Streamable HTTP lifecycle instead of implementing a second transport; static policy analysis does not install it. | | Structured-output validation | `jsonschema` | Use the maintained validator for provider-returned JSON against caller-supplied JSON Schema; keep parsing and the single repair policy in the existing orchestrator. | Reusing `validator_for`, schema checks, and bounded validation avoids an incomplete custom JSON Schema implementation. Provider output and schemas remain untrusted and fail closed. | | SSE usage capture | Python stdlib streaming parser already used by `ModelClient._stream_send` | Reuse the existing line-delimited SSE parser and capture only provider-declared usage frames; do not add an SSE or provider SDK dependency. | OpenAI's Responses and Chat Completions references define terminal usage fields, while interrupted streams may omit the final usage frame. | +| Verbose/debug logging | Python stdlib `logging` (researched: `structlog`, `loguru`) | Use stdlib `logging` exclusively -- `logging.basicConfig(..., force=True)` for one configuration entrypoint, a `logging.Filter` on the installed handler for redaction, `%`-style lazy formatting for cost-free DEBUG below its threshold. `structlog`/`loguru` add structured/prettier output this repo's existing `print(json.dumps(...))` CLI-report convention and `_LOGGER = logging.getLogger(__name__)` precedent (3 modules) do not need yet. | Python's own `logging` HOWTO documents `basicConfig`'s one-shot-unless-`force` behavior, handler-level `Filter`s, and that `isEnabledFor` gates expensive argument construction, not just formatting -- covering every requirement (level control, lazy evaluation, a redaction hook) with zero new dependency surface. | +| Distributed tracing | [OpenTelemetry Python](https://github.com/open-telemetry/opentelemetry-python) (already a runtime dependency since ADR 0122; recorded here for completeness -- this row was missing when that ADR shipped) | Keep as the request-correlation/span backend for cross-provider tracing (`telemetry.py`); it stays a separate system from stdlib logging (verbose/debug logging row above) -- two systems, not one, because OTel's span/attribute model and stdlib `logging`'s line-oriented model solve different problems and merging them would require a third abstraction neither currently needs. | OpenTelemetry's Python SDK and OTLP HTTP exporter are the maintained reference implementation for the vendor-neutral tracing API this repo's GenAI span conventions already target (see ADR 0122's References). | ## Ponytail Decision diff --git a/tests/test_chat_model_capability_isolation.py b/tests/test_chat_model_capability_isolation.py index 5f93e012b..f141f2acd 100644 --- a/tests/test_chat_model_capability_isolation.py +++ b/tests/test_chat_model_capability_isolation.py @@ -120,7 +120,7 @@ def test_embedding_deployments_never_enter_chat_agent_discovery() -> None: } with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): discovered = discover_provider_models(source) @@ -172,7 +172,7 @@ def test_bytez_chat_catalog_still_rejects_non_chat_identifiers() -> None: } with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): discovered = discover_provider_models(source) @@ -235,7 +235,7 @@ def test_generic_media_catalog_rows_stay_out_of_bootstrap_and_review_chat_pool( ] } with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): discovered = discover_provider_models(source) diff --git a/tests/test_cli_logging.py b/tests/test_cli_logging.py new file mode 100644 index 000000000..9e65c917a --- /dev/null +++ b/tests/test_cli_logging.py @@ -0,0 +1,435 @@ +"""`--log-level`/`--verbose`/`--debug` CLI wiring.""" + +from __future__ import annotations + +import logging +import os +import sys +from contextlib import contextmanager +from io import StringIO +from pathlib import Path +from typing import Iterator +from unittest.mock import patch + +sys.path.insert(0, str(Path(__file__).resolve().parents[1])) + +from contextual_orchestrator.__main__ import _configure_logging_from_cli, main # noqa: E402 + +_REMOVED_ENV_VAR = "CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL" + + +@contextmanager +def _restored_root_logger() -> Iterator[None]: + """Snapshot/restore root logger level+handlers so a test cannot leak global state.""" + root = logging.getLogger() + original_level = root.level + original_handlers = list(root.handlers) + try: + yield + finally: + for handler in list(root.handlers): + if handler not in original_handlers: + root.removeHandler(handler) + handler.close() + root.handlers = original_handlers + root.setLevel(original_level) + + +def _run_one_shot(extra_args: list[str]) -> None: + with patch.object( + sys, + "argv", + ["contextual-orchestrator", "--agents", "examples/agents.mock.json", *extra_args, "hello"], + ): + main() + + +def test_help_text_lists_log_level_flag() -> None: + stdout = StringIO() + with ( + patch.object(sys, "argv", ["contextual-orchestrator", "--help"]), + patch.object(sys, "stdout", stdout), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 0 + else: # pragma: no cover + raise AssertionError("--help must exit") + help_text = stdout.getvalue() + assert "--log-level" in help_text + assert "--verbose" in help_text + assert "--debug" in help_text + + +def test_register_credential_help_lists_log_level_flag() -> None: + stdout = StringIO() + with ( + patch.object(sys, "argv", ["contextual-orchestrator", "register-credential", "--help"]), + patch.object(sys, "stdout", stdout), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 0 + else: # pragma: no cover + raise AssertionError("--help must exit") + assert "--log-level" in stdout.getvalue() + + +def test_discover_models_help_lists_log_level_flag() -> None: + stdout = StringIO() + with ( + patch.object(sys, "argv", ["contextual-orchestrator", "discover-models", "--help"]), + patch.object(sys, "stdout", stdout), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 0 + else: # pragma: no cover + raise AssertionError("--help must exit") + assert "--log-level" in stdout.getvalue() + + +def test_default_level_is_warning_without_any_flag() -> None: + with _restored_root_logger(): + _run_one_shot([]) + assert logging.getLogger().getEffectiveLevel() == logging.WARNING + + +def test_explicit_log_level_flag_sets_effective_level() -> None: + with _restored_root_logger(): + _run_one_shot(["--log-level", "DEBUG"]) + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG + + +def test_log_level_flag_is_case_insensitive() -> None: + with _restored_root_logger(): + _run_one_shot(["--log-level", "info"]) + assert logging.getLogger().getEffectiveLevel() == logging.INFO + + +def test_log_level_flag_after_option_terminator_is_not_consumed() -> None: + """A literal `--` stops the logging pre-scan from treating what follows as a flag. + + Confirms a Devin automated-review finding here ("parse_known_args still + consumes --log-level after --") was a false positive: `parse_known_args` + already respects stdlib argparse's `--` option-terminator semantics with + no special-casing needed in `_configure_logging_from_cli` -- verified + directly against the real pre-scan parser, not just argparse in the + abstract. + """ + with _restored_root_logger(): + _configure_logging_from_cli(["--", "--log-level", "DEBUG"]) + assert logging.getLogger().getEffectiveLevel() == logging.WARNING + + +def test_verbose_flag_is_equivalent_to_debug_log_level() -> None: + with _restored_root_logger(): + _run_one_shot(["--verbose"]) + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG + + +def test_debug_flag_is_a_synonym_for_verbose() -> None: + with _restored_root_logger(): + _run_one_shot(["--debug"]) + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG + + +def test_explicit_log_level_overrides_verbose_flag() -> None: + with _restored_root_logger(): + _run_one_shot(["--verbose", "--log-level", "ERROR"]) + assert logging.getLogger().getEffectiveLevel() == logging.ERROR + + +def test_log_level_environment_variable_is_not_runtime_configuration() -> None: + with _restored_root_logger(): + os.environ[_REMOVED_ENV_VAR] = "DEBUG" + try: + _run_one_shot([]) + finally: + del os.environ[_REMOVED_ENV_VAR] + assert logging.getLogger().getEffectiveLevel() == logging.WARNING + + +def test_invalid_log_level_exits_with_argparse_error_not_traceback() -> None: + stderr = StringIO() + with ( + _restored_root_logger(), + patch.object( + sys, + "argv", + ["contextual-orchestrator", "--log-level", "SUPER_VERBOSE", "hello"], + ), + patch.object(sys, "stderr", stderr), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 2 + else: # pragma: no cover + raise AssertionError("an invalid log level must exit(2)") + error_text = stderr.getvalue() + assert "SUPER_VERBOSE" in error_text + assert "Traceback" not in error_text + + +def test_serve_path_configures_logging_before_serve_call() -> None: + with ( + _restored_root_logger(), + patch.object( + sys, + "argv", + [ + "contextual-orchestrator", + "--serve", + "--log-level", + "DEBUG", + "--auth-token", + "local-token", + ], + ), + patch("contextual_orchestrator.__main__.serve") as serve, + ): + main() + assert serve.called + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG + + +def test_discover_models_path_configures_logging() -> None: + with ( + _restored_root_logger(), + patch.object( + sys, + "argv", + ["contextual-orchestrator", "discover-models", "--log-level", "DEBUG"], + ), + patch.object(sys, "stdout", StringIO()), + ): + main() + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG + + +def test_check_fast_mlsirm_path_configures_logging() -> None: + with ( + _restored_root_logger(), + patch.object( + sys, + "argv", + ["contextual-orchestrator", "check-fast-mlsirm", "--verbose"], + ), + patch.object(sys, "stdout", StringIO()), + ): + try: + main() + except SystemExit: + pass + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG + + +def test_leading_verbose_flag_before_discover_models_still_dispatches() -> None: + """A logging flag before the subcommand must not bypass subcommand dispatch. + + `main` used to locate the subcommand by checking only `arguments[0]`; a + global logging flag placed first (e.g. + ``python -m contextual_orchestrator --verbose discover-models``) would + then occupy that position, so the actual subcommand name fell through + unrecognized into the default one-shot completion parser and was parsed + as if it were a prompt string instead. + """ + stdout = StringIO() + with ( + _restored_root_logger(), + patch.object(sys, "argv", ["contextual-orchestrator", "--verbose", "discover-models", "--help"]), + patch.object(sys, "stdout", stdout), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 0 + else: # pragma: no cover + raise AssertionError("--help must exit") + help_text = stdout.getvalue() + assert "python -m contextual_orchestrator discover-models" in help_text + assert "--agents-db" in help_text + + +def test_leading_log_level_flag_before_register_credential_still_dispatches() -> None: + """Same bypass, exercised with `--log-level` (a value-taking flag) instead of a boolean one.""" + stdout = StringIO() + with ( + _restored_root_logger(), + patch.object( + sys, + "argv", + ["contextual-orchestrator", "--log-level", "DEBUG", "register-credential", "--help"], + ), + patch.object(sys, "stdout", stdout), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 0 + else: # pragma: no cover + raise AssertionError("--help must exit") + help_text = stdout.getvalue() + assert "python -m contextual_orchestrator register-credential" in help_text + assert "--name NAME" in help_text + + +def test_leading_debug_flag_before_check_fast_mlsirm_still_dispatches() -> None: + """`check-fast-mlsirm` takes no args of its own, but must still be reached.""" + stdout = StringIO() + with ( + _restored_root_logger(), + patch.object(sys, "argv", ["contextual-orchestrator", "--debug", "check-fast-mlsirm"]), + patch.object(sys, "stdout", stdout), + ): + try: + main() + except SystemExit: + pass + # _fast_mlsirm_runtime_status() always reports this key, whether or not + # the optional fast-mlsirm dependency is installed in this interpreter -- + # its presence proves check-fast-mlsirm actually ran, rather than + # "check-fast-mlsirm" being swallowed as a one-shot completion prompt. + assert '"package": "fast-mlsirm"' in stdout.getvalue() + + +def test_check_fast_mlsirm_help_shows_help_without_running_diagnostic() -> None: + """`check-fast-mlsirm --help` must show help and exit, not run the diagnostic. + + Regression test: before this fix, `_check_fast_mlsirm_command` took no + arguments and ignored everything after the subcommand token, so + `--help` silently ran the real diagnostic (and its process-exit code) + instead of printing usage -- the one CLI subcommand where `--help` + did something other than show help. + """ + stdout = StringIO() + with ( + _restored_root_logger(), + patch.object(sys, "argv", ["contextual-orchestrator", "check-fast-mlsirm", "--help"]), + patch.object(sys, "stdout", stdout), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 0 + else: # pragma: no cover + raise AssertionError("--help must exit") + help_text = stdout.getvalue() + assert "python -m contextual_orchestrator check-fast-mlsirm" in help_text + assert '"package": "fast-mlsirm"' not in help_text + + +def test_check_fast_mlsirm_rejects_unknown_option() -> None: + """An unrecognized trailing option must fail closed, not be silently ignored.""" + with ( + _restored_root_logger(), + patch.object( + sys, + "argv", + ["contextual-orchestrator", "check-fast-mlsirm", "--not-a-real-option"], + ), + patch.object(sys, "stderr", StringIO()), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 2 + else: # pragma: no cover + raise AssertionError("an unrecognized option must exit non-zero") + + +def test_leading_log_level_flag_before_serve_still_configures_and_serves() -> None: + """`--serve` is a plain optional flag on the main parser, so it is unaffected by the + subcommand-token bypass -- this locks that in as a regression guard. + """ + with ( + _restored_root_logger(), + patch.object( + sys, + "argv", + [ + "contextual-orchestrator", + "--log-level", + "DEBUG", + "--serve", + "--auth-token", + "local-token", + ], + ), + patch("contextual_orchestrator.__main__.serve") as serve, + ): + main() + assert serve.called + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG + + +def test_abbreviated_value_flag_before_subcommand_fails_closed_not_misrouted() -> None: + """An abbreviated `--log-level` (e.g. `--log-l`) before a subcommand must fail closed. + + argparse's abbreviation matching and `_subcommand_token_index`'s plain + string comparison used to disagree: argparse would accept `--log-l` as + shorthand for `--log-level`, but the locator did not recognize it as a + flag to skip past, so it treated `--log-l` itself as a (non-matching) + subcommand token and fell through to the one-shot completion parser with + the real subcommand name parsed as a prompt -- silently wrong, not an + error. `allow_abbrev=False` on every parser here removes the + disagreement instead: an abbreviated flag is now rejected everywhere + with a clear argparse `SystemExit(2)`, never silently accepted by one + parser and not the other. + """ + stderr = StringIO() + with ( + _restored_root_logger(), + patch.object( + sys, + "argv", + ["contextual-orchestrator", "--log-l", "DEBUG", "discover-models"], + ), + patch.object(sys, "stderr", stderr), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 2 + else: # pragma: no cover + raise AssertionError("an abbreviated flag before a subcommand must exit(2)") + assert "unrecognized arguments" in stderr.getvalue() + + +def test_abbreviated_boolean_flag_before_subcommand_fails_closed_not_misrouted() -> None: + """Same property as above, for a boolean flag abbreviation (`--ver` for `--verbose`).""" + stderr = StringIO() + with ( + _restored_root_logger(), + patch.object(sys, "argv", ["contextual-orchestrator", "--ver", "discover-models"]), + patch.object(sys, "stderr", stderr), + ): + try: + main() + except SystemExit as exc: + assert exc.code == 2 + else: # pragma: no cover + raise AssertionError("an abbreviated flag before a subcommand must exit(2)") + assert "unrecognized arguments" in stderr.getvalue() + + +if __name__ == "__main__": # pragma: no cover + test_help_text_lists_log_level_flag() + test_register_credential_help_lists_log_level_flag() + test_discover_models_help_lists_log_level_flag() + test_default_level_is_warning_without_any_flag() + test_explicit_log_level_flag_sets_effective_level() + test_log_level_flag_is_case_insensitive() + test_verbose_flag_is_equivalent_to_debug_log_level() + test_debug_flag_is_a_synonym_for_verbose() + test_explicit_log_level_overrides_verbose_flag() + test_log_level_environment_variable_is_not_runtime_configuration() + test_invalid_log_level_exits_with_argparse_error_not_traceback() + test_serve_path_configures_logging_before_serve_call() + test_discover_models_path_configures_logging() + test_check_fast_mlsirm_path_configures_logging() + print("ok") diff --git a/tests/test_debug_logging.py b/tests/test_debug_logging.py new file mode 100644 index 000000000..d88fc9ca1 --- /dev/null +++ b/tests/test_debug_logging.py @@ -0,0 +1,325 @@ +"""Stdlib-only logging configuration: level parsing, lazy DEBUG emission, redaction safety net.""" + +from __future__ import annotations + +import io +import logging +import sys +from contextlib import contextmanager +from pathlib import Path +from typing import Iterator + +sys.path.insert(0, str(Path(__file__).resolve().parents[1])) + +from contextual_orchestrator.debug_logging import ( # noqa: E402 + DEFAULT_LOG_LEVEL_NAME, + LOG_LEVEL_NAMES, + configure_logging, + log_debug_event, + parse_log_level_name, + response_metadata_for_log, + summarize_payload_for_log, + summarize_request_for_log, +) +from contextual_orchestrator.orchestrator import redact_text # noqa: E402 + + +@contextmanager +def _restored_root_logger() -> Iterator[None]: + """Snapshot/restore root logger level+handlers so a test cannot leak global state.""" + root = logging.getLogger() + original_level = root.level + original_handlers = list(root.handlers) + try: + yield + finally: + for handler in list(root.handlers): + if handler not in original_handlers: + root.removeHandler(handler) + handler.close() + root.handlers = original_handlers + root.setLevel(original_level) + + +def test_parse_log_level_name_accepts_known_levels_case_insensitively() -> None: + assert parse_log_level_name("debug") == "DEBUG" + assert parse_log_level_name("Warning") == "WARNING" + assert parse_log_level_name(" ERROR ") == "ERROR" + assert parse_log_level_name("critical") == "CRITICAL" + assert parse_log_level_name("info") == "INFO" + + +def test_parse_log_level_name_rejects_unknown_level() -> None: + try: + parse_log_level_name("VERBOSE") + except ValueError as exc: + assert "VERBOSE" in str(exc) + else: # pragma: no cover + raise AssertionError("an unknown level name must raise ValueError") + + +def test_default_log_level_name_is_warning_and_listed() -> None: + assert DEFAULT_LOG_LEVEL_NAME == "WARNING" + assert DEFAULT_LOG_LEVEL_NAME in LOG_LEVEL_NAMES + assert LOG_LEVEL_NAMES == ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL") + + +def test_configure_logging_force_reapplies_level_across_calls() -> None: + """Guards the classic basicConfig-is-a-no-op-after-first-call footgun.""" + with _restored_root_logger(): + configure_logging("DEBUG") + assert logging.getLogger().getEffectiveLevel() == logging.DEBUG + configure_logging("WARNING") + assert logging.getLogger().getEffectiveLevel() == logging.WARNING + configure_logging("ERROR") + assert logging.getLogger().getEffectiveLevel() == logging.ERROR + + +def test_configure_logging_rejects_invalid_level_without_side_effects() -> None: + with _restored_root_logger(): + configure_logging("INFO") + try: + configure_logging("NOT_A_LEVEL") + except ValueError: + pass + else: # pragma: no cover + raise AssertionError("invalid level must raise, never silently configure") + assert logging.getLogger().getEffectiveLevel() == logging.INFO + + +def test_configure_logging_without_redactor_attaches_no_filter() -> None: + with _restored_root_logger(): + configure_logging("DEBUG") + for handler in logging.getLogger().handlers: + assert handler.filters == [] + + +class _CountingRepr: + """Sentinel whose ``__repr__`` counts calls, to prove lazy %-formatting.""" + + def __init__(self) -> None: + self.calls = 0 + + def __repr__(self) -> str: # pragma: no cover - executed only if formatting happens + self.calls += 1 + return "" + + +def test_log_debug_event_skips_formatting_below_debug_level() -> None: + logger = logging.getLogger("contextual_orchestrator.test.lazy") + logger.setLevel(logging.WARNING) + sentinel = _CountingRepr() + log_debug_event(logger, "value=%r", sentinel) + assert sentinel.calls == 0 + + +def test_log_debug_event_formats_and_emits_when_debug_enabled() -> None: + logger = logging.getLogger("contextual_orchestrator.test.lazy_enabled") + logger.setLevel(logging.DEBUG) + buffer = io.StringIO() + handler = logging.StreamHandler(buffer) + logger.addHandler(handler) + logger.propagate = False + try: + sentinel = _CountingRepr() + log_debug_event(logger, "value=%r", sentinel) + assert sentinel.calls == 1 + assert "" in buffer.getvalue() + finally: + logger.removeHandler(handler) + handler.close() + + +def test_configure_logging_redactor_masks_secret_shaped_content_in_captured_output() -> None: + """THE key secret-leak test: a fake credential shape must never reach captured output.""" + fixture_value = "non-credential-fixture" + captured = io.StringIO() + original_stderr = sys.stderr + sys.stderr = captured + try: + with _restored_root_logger(): + configure_logging("DEBUG", redactor=redact_text) + logging.getLogger("contextual_orchestrator.test.leak").debug( + "provider payload leaked: api_key=%s", fixture_value + ) + finally: + sys.stderr = original_stderr + output = captured.getvalue() + assert "[REDACTED]" in output + assert fixture_value not in output + + +def test_configure_logging_redactor_none_still_leaves_secret_unmasked() -> None: + """Negative control: without a redactor, the same fake secret DOES leak. + + Proves the previous test is a real assertion, not a tautology -- it can + fail (and, run this way, does) before the redactor is wired in. + """ + fixture_value = "non-credential-fixture" + captured = io.StringIO() + original_stderr = sys.stderr + sys.stderr = captured + try: + with _restored_root_logger(): + configure_logging("DEBUG") # no redactor at all + logging.getLogger("contextual_orchestrator.test.leak_control").debug( + "provider payload leaked: api_key=%s", fixture_value + ) + finally: + sys.stderr = original_stderr + assert fixture_value in captured.getvalue() + + +def test_configure_logging_redactor_masks_exception_traceback_in_captured_output() -> None: + """Exception tracebacks (`exc_info=True` / `logger.exception`) must be redacted too. + + `_RedactingLogFilter` previously only rewrote `record.msg`/`record.args` + -- `record.exc_info` (and any already-rendered `record.exc_text`) passed + through untouched. `logging.Formatter.format()` renders the traceback + from `exc_info` *after* filters have already run and returned, so a call + site using `exc_info=True` or `logger.exception(...)` could still leak a + secret embedded in the exception's own `str()` straight into the + formatted traceback, bypassing this safety net entirely -- exactly the + kind of secret-shaped content (e.g. `api_key=sk-...`) this whole + redaction system exists to catch. + """ + fake_secret = "sk-FAKEFAKEFAKEFAKEFAKE1234567890" # noqa: S105 - obviously non-functional fixture + captured = io.StringIO() + original_stderr = sys.stderr + sys.stderr = captured + try: + with _restored_root_logger(): + configure_logging("DEBUG", redactor=redact_text) + logger = logging.getLogger("contextual_orchestrator.test.leak_traceback") + try: + raise RuntimeError(f"upstream rejected request: api_key={fake_secret}") + except RuntimeError: + logger.exception("provider call failed") + finally: + sys.stderr = original_stderr + output = captured.getvalue() + assert "[REDACTED]" in output + assert fake_secret not in output + + +def test_summarize_request_for_log_is_body_free_and_bounded() -> None: + line = summarize_request_for_log( + method="POST", + path="/v1/chat/completions", + status=200, + latency_ms=12.345, + session_id_hash="abc123", + ) + assert "POST" in line + assert "/v1/chat/completions" in line + assert "200" in line + assert "12.3" in line + assert "abc123" in line + + +def test_summarize_request_for_log_handles_missing_status_and_session() -> None: + line = summarize_request_for_log(method="GET", path="/healthz", status=None, latency_ms=0.5) + assert "status=-" in line + assert "session_id_hash=-" in line + + +def test_summarize_request_for_log_strips_query_string() -> None: + """A query string on `path` is never logged, only the bare path before `?`. + + Deterministic unit-level counterpart to + tests/test_telemetry.py::test_per_request_info_summary_never_includes_query_string, + which exercises the same property end to end through a real server but + can occasionally flake on unrelated threaded-server teardown timing; this + test proves the property directly against the formatter with no + threading involved. + """ + fake_token = "sk-FAKEFAKEFAKEFAKEFAKEQUERYSTRING123" + line = summarize_request_for_log( + method="GET", + path=f"/healthz?api_key={fake_token}", + status=200, + latency_ms=0.5, + ) + assert "path=/healthz" in line + assert "?" not in line + assert fake_token not in line + + +def test_summarize_payload_for_log_truncates_and_labels() -> None: + payload = {"choices": [{"message": {"content": "x" * 2000}}]} + line = summarize_payload_for_log("response", payload, max_characters=100) + assert line.startswith("response_summary ") + assert len(line) < 200 + assert "..." in line + + +def test_summarize_payload_for_log_handles_unserializable_payload() -> None: + circular: dict[str, object] = {} + circular["self"] = circular + line = summarize_payload_for_log("request", circular) + assert line.startswith("request_summary ") + + +def test_response_metadata_for_log_keeps_only_allowlisted_usage_counters() -> None: + """CodeRabbit regression: a numeric-looking key must still be allowlisted by name. + + Before this fix, `response_metadata_for_log`'s "usage" summary kept ANY + string key with a numeric value, not a fixed allowlist of known counter + names. A provider's `usage` object is upstream-controlled JSON, so a key + shaped like `"customer_note="` with a throwaway numeric value + would sail through the old numeric-only filter and get logged verbatim + (CWE-532). This proves such a key is excluded while the real, + allowlisted OpenAI-compatible counters still come through untouched. + """ + fake_secret = "sk-FAKEFAKEFAKEFAKEFAKE1234567890" # noqa: S105 - obviously non-functional fixture + payload = { + "model": "gpt-test", + "choices": [{"message": {"content": "ok"}}], + "usage": { + "prompt_tokens": 12, + "completion_tokens": 34, + "total_tokens": 46, + f"customer_note={fake_secret}": 1, + }, + } + + metadata = response_metadata_for_log(payload) + + assert metadata["usage"] == { + "prompt_tokens": 12, + "completion_tokens": 34, + "total_tokens": 46, + } + assert not any(fake_secret in str(key) for key in metadata["usage"]) + + +def test_response_metadata_for_log_usage_none_when_no_allowlisted_keys_present() -> None: + """An entirely non-allowlisted "usage" dict summarizes to an empty, not absent, dict. + + (`usage` stays a dict -- just with nothing left in it -- distinct from + a payload with no "usage" key at all, which stays `None`.) + """ + metadata = response_metadata_for_log( + {"usage": {"unexpected_field": 1, "another_one": 2.5}} + ) + assert metadata["usage"] == {} + + +if __name__ == "__main__": # pragma: no cover + test_parse_log_level_name_accepts_known_levels_case_insensitively() + test_parse_log_level_name_rejects_unknown_level() + test_default_log_level_name_is_warning_and_listed() + test_configure_logging_force_reapplies_level_across_calls() + test_configure_logging_rejects_invalid_level_without_side_effects() + test_configure_logging_without_redactor_attaches_no_filter() + test_log_debug_event_skips_formatting_below_debug_level() + test_log_debug_event_formats_and_emits_when_debug_enabled() + test_configure_logging_redactor_masks_secret_shaped_content_in_captured_output() + test_configure_logging_redactor_none_still_leaves_secret_unmasked() + test_summarize_request_for_log_is_body_free_and_bounded() + test_summarize_request_for_log_handles_missing_status_and_session() + test_summarize_payload_for_log_truncates_and_labels() + test_summarize_payload_for_log_handles_unserializable_payload() + test_response_metadata_for_log_keeps_only_allowlisted_usage_counters() + test_response_metadata_for_log_usage_none_when_no_allowlisted_keys_present() + print("ok") diff --git a/tests/test_discover_models_cli.py b/tests/test_discover_models_cli.py index 3b369fac7..a1650121f 100644 --- a/tests/test_discover_models_cli.py +++ b/tests/test_discover_models_cli.py @@ -31,8 +31,13 @@ def __enter__(self): def __exit__(self, *_args): return False - def read(self) -> bytes: - return self._body + def read(self, amt: int | None = None) -> bytes: + # amt mirrors http.client.HTTPResponse.read(amt): _fetch_json_same_host_https + # (the always-invoked OpenRouter ZDR fetch inside discover_all_models) + # and _fetch_json both cap their read at MAX_DISCOVERY_RESPONSE_BYTES + 1 + # -- both share this fixture via the same _open_trusted_discovery_request + # seam. + return self._body if amt is None else self._body[:amt] def test_free_only_help_rejects_name_inference() -> None: @@ -160,7 +165,7 @@ def test_discover_models_reports_models_found_over_a_registered_credential() -> register_credential("OPENAI_API_KEY", "sk-live") stdout = StringIO() - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if urllib.parse.urlsplit(request.full_url).hostname == "api.openai.com": return _Response({"data": [{"id": "gpt-5.5"}]}) return _Response({"data": []}) @@ -169,7 +174,7 @@ def urlopen(request, timeout=None): with ( patch.object(sys, "argv", ["contextual-orchestrator", "discover-models"]), patch.object(sys, "stdout", stdout), - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), ): main() finally: @@ -307,7 +312,7 @@ def test_discover_models_persists_to_agents_db(tmp_path) -> None: db_path = str(tmp_path / "pool.db") stdout = StringIO() - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if urllib.parse.urlsplit(request.full_url).hostname == "api.openai.com": return _Response({"data": [{"id": "gpt-5.5"}]}) return _Response({"data": []}) @@ -316,7 +321,7 @@ def urlopen(request, timeout=None): with ( patch.object(sys, "argv", ["contextual-orchestrator", "discover-models", "--agents-db", db_path]), patch.object(sys, "stdout", stdout), - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), ): main() finally: @@ -341,7 +346,7 @@ def close(self) -> None: closed.append(True) super().close() - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if urllib.parse.urlsplit(request.full_url).hostname == "api.openai.com": return _Response({"data": [{"id": "gpt-5.5"}]}) return _Response({"data": []}) @@ -351,7 +356,7 @@ def urlopen(request, timeout=None): patch.object(sys, "argv", ["contextual-orchestrator", "discover-models", "--agents-db", db_path]), patch.object(sys, "stdout", stdout), patch.object(cli, "TaskOrchestrator", TrackingOrchestrator), - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), ): main() finally: @@ -389,7 +394,7 @@ def test_enable_cheapest_activates_the_lowest_priced_discovered_agent(tmp_path) db_path = str(tmp_path / "pool.db") stdout = StringIO() - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): host = urllib.parse.urlsplit(request.full_url).hostname if host == "api.openai.com": return _Response({"data": [{"id": "pricey-model", "pricing": {"prompt": "0.00005", "completion": "0.0001"}}]}) @@ -405,7 +410,7 @@ def urlopen(request, timeout=None): ["contextual-orchestrator", "discover-models", "--agents-db", db_path, "--enable-cheapest", "1"], ), patch.object(sys, "stdout", stdout), - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), ): main() finally: @@ -431,7 +436,7 @@ def test_enable_cheapest_bootstraps_independent_provider_accounts(tmp_path) -> N db_path = str(tmp_path / "pool.db") stdout = StringIO() - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): host = urllib.parse.urlsplit(request.full_url).hostname payloads = { "api.openai.com": {"data": [{"id": "openai-model", "pricing": {"prompt": "0.001", "completion": "0.001"}}]}, @@ -448,7 +453,7 @@ def urlopen(request, timeout=None): ["contextual-orchestrator", "discover-models", "--agents-db", db_path, "--enable-cheapest", "3"], ), patch.object(sys, "stdout", stdout), - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), ): main() finally: diff --git a/tests/test_http_response_write_disconnect_safety.py b/tests/test_http_response_write_disconnect_safety.py index c932d5d28..39d5c5da0 100644 --- a/tests/test_http_response_write_disconnect_safety.py +++ b/tests/test_http_response_write_disconnect_safety.py @@ -9,6 +9,7 @@ sys.path.insert(0, str(Path(__file__).resolve().parents[1])) from contextual_orchestrator import ModelAgent, TaskOrchestrator # noqa: E402 +from contextual_orchestrator.debug_logging import summarize_request_for_log # noqa: E402 from contextual_orchestrator.server import SecurityConfig, build_server # noqa: E402 _TEST_AUTH_TOKEN = "http_response_write_disconnect_safety_token" # noqa: S105 @@ -302,7 +303,191 @@ def write(self, _payload): server.server_close() +def test_disconnected_write_does_not_report_intended_status_as_delivered() -> None: + """Case (a): a dead-peer write BEFORE headers ever go out clears `_last_status`. + + Regression for: `_send`/`_send_text`/`_send_bytes`/`_send_sse` all set + `self._last_status = status` *before* calling `_write_response`, and + ignored its boolean return value. `_write_response` deliberately + swallows `BrokenPipeError`/`ConnectionError`/`OSError` from a + disconnected peer -- but the caller's pre-set `_last_status` survived + that failure untouched, so `_log_request_summary` (via + `summarize_request_for_log`) went on to log the *intended* status + (e.g. 200) as if delivery had actually completed. + + The disconnect here strikes in `end_headers()` itself -- before the + status line/headers were ever flushed -- so `_response_headers_sent` + stays unset and `_write_response` clears `_last_status` back to `None`, + this module's existing "response was never sent" value. The body write + must never even be attempted in this case (asserted below), matching + what a real dead socket would do: nothing written after headers fail. + """ + server = build_server(build(), port=0, security=SecurityConfig(auth_token=_TEST_AUTH_TOKEN)) + handler_cls = server.RequestHandlerClass + + class DisconnectedBeforeHeadersHandler: + wfile = None + _last_status = "unset-before-send" + _request_body_consumed = True + + def send_response(self, _status): + return None + + def send_header(self, _name, _value): + return None + + def _send_security_headers(self): + return None + + def end_headers(self): + raise BrokenPipeError("simulated client disconnect before headers were delivered") + + def write(self, _payload): + raise AssertionError("body write must not be attempted once end_headers fails") + + _write_response = handler_cls._write_response + + try: + handler = DisconnectedBeforeHeadersHandler() + handler.wfile = handler + handler_cls._send_bytes(handler, b"audio", "audio/mpeg") + + assert handler._last_status != 200 + assert handler._last_status is None + + summary = summarize_request_for_log( + method="POST", + path="/v1/audio/speech", + status=handler._last_status, + latency_ms=1.0, + ) + assert "status=200" not in summary + assert "status=-" in summary + finally: + server.server_close() + + +def test_disconnected_body_write_after_headers_preserves_delivered_status() -> None: + """Case (b): a dead-peer write AFTER headers already went out preserves the status. + + Regression for a follow-up bug in the case-(a) fix above: clearing + `_last_status` on *every* caught disconnect was too broad. Once + `end_headers()` has actually completed, the client genuinely received + the real status line and headers -- only the body write that follows + (in the same `_write()` closure) failed. Reporting `status=-` for that + request would be just as dishonest as the original bug, in the other + direction: it would hide a response the client truly got. + """ + server = build_server(build(), port=0, security=SecurityConfig(auth_token=_TEST_AUTH_TOKEN)) + handler_cls = server.RequestHandlerClass + + class DisconnectedAfterHeadersHandler: + wfile = None + _last_status = "unset-before-send" + _request_body_consumed = True + + def send_response(self, _status): + return None + + def send_header(self, _name, _value): + return None + + def _send_security_headers(self): + return None + + def end_headers(self): + return None # succeeds: the status line/headers really went out + + def write(self, _payload): + raise BrokenPipeError("simulated client disconnect mid-body, after headers") + + _write_response = handler_cls._write_response + + try: + handler = DisconnectedAfterHeadersHandler() + handler.wfile = handler + handler_cls._send_bytes(handler, b"audio", "audio/mpeg") + + assert handler._response_headers_sent is True + assert handler._last_status == 200 + + summary = summarize_request_for_log( + method="POST", + path="/v1/audio/speech", + status=handler._last_status, + latency_ms=1.0, + ) + assert "status=200" in summary + assert "status=-" not in summary + finally: + server.server_close() + + +def test_sse_frame_disconnect_after_headers_preserves_delivered_status() -> None: + """A later SSE frame failing must not erase the status `_begin_sse` already sent. + + `_begin_sse` successfully flushes the real 200 status line and headers + -- the client DID receive it -- before any frame write is attempted. + A disconnect on a LATER `_write_sse` frame must not clear that + already-confirmed status; only a disconnect striking before headers + ever completed should do that (covered by the "before headers" test + above). + """ + server = build_server(build(), port=0, security=SecurityConfig(auth_token=_TEST_AUTH_TOKEN)) + handler_cls = server.RequestHandlerClass + + class SseHandler: + wfile = None + _last_status = "unset-before-send" + _request_body_consumed = True + + def send_response(self, _status): + return None + + def send_header(self, _name, _value): + return None + + def _send_security_headers(self): + return None + + def end_headers(self): + return None # succeeds: headers/status genuinely delivered + + def write(self, _payload): + raise BrokenPipeError("simulated disconnect mid-stream, after headers") + + def flush(self): + return None + + _write_response = handler_cls._write_response + _begin_sse = handler_cls._begin_sse + _write_sse = handler_cls._write_sse + + try: + handler = SseHandler() + handler.wfile = handler + assert handler_cls._begin_sse(handler) is True + assert handler._last_status == 200 + assert handler._response_headers_sent is True + + assert handler_cls._write_sse(handler, "data: frame\n\n") is False + assert handler._last_status == 200 # preserved, not cleared + + summary = summarize_request_for_log( + method="POST", + path="/v1/chat/completions", + status=handler._last_status, + latency_ms=1.0, + ) + assert "status=200" in summary + finally: + server.server_close() + + if __name__ == "__main__": test_write_response_swallows_a_broken_pipe_from_a_disconnected_client() test_write_response_still_propagates_unrelated_errors() + test_disconnected_write_does_not_report_intended_status_as_delivered() + test_disconnected_body_write_after_headers_preserves_delivered_status() + test_sse_frame_disconnect_after_headers_preserves_delivered_status() print("ok") diff --git a/tests/test_model_discovery.py b/tests/test_model_discovery.py index c753a3d6a..29fec54e5 100644 --- a/tests/test_model_discovery.py +++ b/tests/test_model_discovery.py @@ -2,12 +2,16 @@ from __future__ import annotations +import io import json +import logging import sys import urllib.error import urllib.parse +from contextlib import contextmanager from dataclasses import replace from pathlib import Path +from typing import Iterator from unittest.mock import patch import pytest @@ -352,7 +356,7 @@ def test_discovery_debug_log_identifies_account_without_secret(caplog) -> None: with ( caplog.at_level("DEBUG", logger="contextual_orchestrator.model_discovery"), patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response({"data": [{"id": "gpt-test"}]}), ), ): @@ -518,8 +522,13 @@ def __enter__(self): def __exit__(self, *_args): return False - def read(self) -> bytes: - return self._body + def read(self, amt: int | None = None) -> bytes: + # amt mirrors http.client.HTTPResponse.read(amt): _fetch_json, + # _fetch_json_same_host_https, and _fetch_configured_gateway_json all + # cap their read at MAX_DISCOVERY_RESPONSE_BYTES + 1 to enforce the + # size bound -- all three are exercised through this same fixture now + # that they share _open_trusted_discovery_request. + return self._body if amt is None else self._body[:amt] OPENAI_SOURCE = ProviderModelSource( @@ -575,7 +584,7 @@ def test_openrouter_paid_inference_uses_attested_remaining_credit( ) -> None: register_credential("OPENROUTER_API_KEY", "sk-router") with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): assert openrouter_paid_inference_available() is expected @@ -596,11 +605,11 @@ def test_discover_openai_compatible_parses_models_and_pricing() -> None: } seen_requests = [] - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): seen_requests.append(request) return _Response(payload) - with patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen): + with patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen): discovered = discover_provider_models(OPENROUTER_SOURCE) assert seen_requests[0].get_header("Authorization") == "Bearer sk-router" @@ -632,7 +641,7 @@ def test_openrouter_discovery_preserves_every_declared_modality() -> None: ] ] with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response({"data": rows}), ): discovered = discover_provider_models(OPENROUTER_SOURCE) @@ -686,7 +695,7 @@ def test_non_text_model_does_not_gain_structured_response_capability() -> None: ] } with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): discovered = discover_provider_models(OPENROUTER_SOURCE) @@ -717,7 +726,7 @@ def test_non_text_model_does_not_gain_chat_from_chat_like_identifier() -> None: def test_discovery_treats_null_modality_arrays_as_unspecified() -> None: register_credential("OPENROUTER_API_KEY", "sk-router") with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response( { "data": [ @@ -737,7 +746,7 @@ def test_discovery_treats_null_modality_arrays_as_unspecified() -> None: def test_discovery_preserves_operator_declared_source_capabilities() -> None: register_credential("EMBEDDING_API_KEY", "registered-secret") with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response({"data": [{"id": "embedding-deployment"}]}), ): discovered = discover_provider_models(EMBEDDING_SOURCE) @@ -755,7 +764,7 @@ def test_discovery_retains_full_catalog_and_marks_free_models() -> None: ] } with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): discovered = discover_provider_models(OPENROUTER_SOURCE) @@ -1187,7 +1196,7 @@ def test_opencode_zen_joins_models_dev_cost_and_modalities_without_name_inferenc source = next(item for item in PROVIDER_MODEL_SOURCES if item.provider_name == "opencode_zen") register_credential("OPENCODE_ZEN_API_KEY", "zen-key") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": assert request.get_header("Authorization") is None return _Response( @@ -1222,7 +1231,7 @@ def urlopen(request, timeout=None): ) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): discovered = discover_provider_models(source) @@ -1241,13 +1250,13 @@ def test_opencode_zen_metadata_failure_keeps_availability_but_not_free_suffix() register_credential("OPENCODE_ZEN_API_KEY", "zen-key") source = next(item for item in PROVIDER_MODEL_SOURCES if item.provider_name == "opencode_zen") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": raise urllib.error.URLError("offline") return _Response({"data": [{"id": "vendor/paid-free"}]}) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): discovered = discover_provider_models(source) @@ -1286,7 +1295,7 @@ def test_nvidia_nim_joins_models_dev_cost_and_modalities_without_name_inference( source = next(item for item in PROVIDER_MODEL_SOURCES if item.provider_name == "nvidia_nim") register_credential("NVIDIA_NIM_API_KEY", "nim-key") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": assert request.get_header("Authorization") is None return _Response( @@ -1321,7 +1330,7 @@ def urlopen(request, timeout=None): ) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): discovered = discover_provider_models(source) @@ -1345,13 +1354,13 @@ def test_nvidia_nim_metadata_failure_keeps_availability_but_not_free() -> None: register_credential("NVIDIA_NIM_API_KEY", "nim-key") source = next(item for item in PROVIDER_MODEL_SOURCES if item.provider_name == "nvidia_nim") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": raise urllib.error.URLError("offline") return _Response({"data": [{"id": "meta/llama-3.1-8b-instruct"}]}) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): discovered = discover_provider_models(source) @@ -1368,12 +1377,12 @@ def test_fetch_json_sends_a_stable_user_agent_on_every_request() -> None: """ captured: list[object] = [] - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): captured.append(request) return _Response({"data": []}) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): _fetch_json("https://models.dev/api.json", timeout=5.0) @@ -1394,7 +1403,7 @@ def test_nvidia_nim_join_requires_the_user_agent_header_to_avoid_a_403() -> None register_credential("NVIDIA_NIM_API_KEY", "nim-key") source = next(item for item in PROVIDER_MODEL_SOURCES if item.provider_name == "nvidia_nim") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": if not request.get_header("User-agent"): raise urllib.error.HTTPError( @@ -1406,7 +1415,7 @@ def urlopen(request, timeout=None): return _Response({"data": [{"id": "meta/llama-3.1-8b-instruct"}]}) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): discovered = discover_provider_models(source) @@ -1421,7 +1430,7 @@ def test_discover_all_models_fetches_models_dev_exactly_once_across_sources() -> register_credential("NVIDIA_NIM_API_KEY_SUB", "nim-sub-key") models_dev_calls = [] - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": models_dev_calls.append(request.full_url) return _Response( @@ -1445,7 +1454,7 @@ def urlopen(request, timeout=None): if item.provider_name in {"opencode_zen", "nvidia_nim", "nvidia_nim_sub"} ) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): discovered, errors = discover_all_models(sources) @@ -1465,7 +1474,7 @@ def test_discover_all_models_shared_models_dev_fetch_failure_keeps_is_free_false register_credential("NVIDIA_NIM_API_KEY", "nim-key") register_credential("NVIDIA_NIM_API_KEY_SUB", "nim-sub-key") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": raise urllib.error.URLError("offline") return _Response({"data": [{"id": "meta/llama-3.1-8b-instruct"}]}) @@ -1476,7 +1485,7 @@ def urlopen(request, timeout=None): if item.provider_name in {"nvidia_nim", "nvidia_nim_sub"} ) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): discovered, errors = discover_all_models(sources) @@ -1496,7 +1505,7 @@ def test_discover_all_models_shared_models_dev_fetch_retries_a_transient_failure register_credential("NVIDIA_NIM_API_KEY", "nim-key") attempts = {"models_dev": 0} - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": attempts["models_dev"] += 1 if attempts["models_dev"] < 2: @@ -1517,7 +1526,7 @@ def urlopen(request, timeout=None): sources = tuple(item for item in PROVIDER_MODEL_SOURCES if item.provider_name == "nvidia_nim") with ( - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), patch("contextual_orchestrator.model_discovery.time.sleep"), ): discovered, errors = discover_all_models(sources) @@ -1532,7 +1541,7 @@ def test_discover_all_models_shared_models_dev_fetch_gives_up_after_retry_budget register_credential("NVIDIA_NIM_API_KEY", "nim-key") attempts = {"models_dev": 0} - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": attempts["models_dev"] += 1 raise urllib.error.URLError("still offline") @@ -1540,7 +1549,7 @@ def urlopen(request, timeout=None): sources = tuple(item for item in PROVIDER_MODEL_SOURCES if item.provider_name == "nvidia_nim") with ( - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), patch("contextual_orchestrator.model_discovery.time.sleep"), ): discovered, errors = discover_all_models(sources) @@ -1555,7 +1564,7 @@ def test_discover_all_models_leaves_bytez_unaffected_and_skips_models_dev() -> N register_credential("BYTEZ_API_KEY", "bytez-key") models_dev_calls = [] - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == "https://models.dev/api.json": models_dev_calls.append(request.full_url) return _Response({}) @@ -1564,7 +1573,7 @@ def urlopen(request, timeout=None): ) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): discovered, errors = discover_all_models() @@ -1603,8 +1612,8 @@ def test_discover_all_models_blocks_only_paid_openrouter_without_credit( ] } with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", - side_effect=lambda request, timeout=None: _Response( + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", + side_effect=lambda request, **_kwargs: _Response( payload if request.full_url == OPENROUTER_SOURCE.list_url else {"data": []} ), ), patch( @@ -1639,11 +1648,11 @@ def test_discover_bytez_parses_models_with_key_auth_scheme() -> None: } seen_requests = [] - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): seen_requests.append(request) return _Response(payload) - with patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen): + with patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen): discovered = discover_provider_models(BYTEZ_SOURCE) assert seen_requests[0].get_header("Authorization") == "bytez-secret" @@ -1678,7 +1687,7 @@ def test_discover_bytez_marks_zero_meter_price_as_free() -> None: } with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): discovered = discover_provider_models(BYTEZ_SOURCE) @@ -1700,7 +1709,7 @@ def test_discover_bytez_missing_meter_price_stays_unknown_not_free() -> None: } with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): discovered = discover_provider_models(BYTEZ_SOURCE) @@ -1761,7 +1770,7 @@ def test_discover_bytez_preserves_operator_declared_capabilities() -> None: ) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response({"output": [{"modelId": "embedding-deployment"}]}), ): discovered = discover_provider_models(source) @@ -1773,12 +1782,12 @@ def test_discover_all_models_continues_after_one_provider_error() -> None: register_credential("OPENAI_API_KEY", "sk-openai") register_credential("OPENROUTER_API_KEY", "sk-router") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if urllib.parse.urlsplit(request.full_url).hostname == "api.openai.com": raise urllib.error.URLError("connection refused") return _Response({"data": [{"id": "meta/llama-3.3"}]}) - with patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen): + with patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen): discovered, errors = discover_all_models((OPENAI_SOURCE, OPENROUTER_SOURCE)) assert [m.model_id for m in discovered] == ["meta/llama-3.3"] @@ -1800,14 +1809,14 @@ def test_discover_all_models_applies_model_zdr_evidence_to_other_sources() -> No ) register_credential("NVIDIA_NIM_API_KEY", "nim-key") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == other_source.list_url: return _Response({"data": [{"id": "openai/shared-model"}]}) return _Response({"data": [{"id": "openai/shared-model"}]}) with ( patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ), patch( @@ -1878,6 +1887,109 @@ def build_opener(handler): assert seen_requests[0].get_header("Authorization") == "Bearer sk-openrouter" +def test_fetch_json_rejects_a_cross_host_redirect_and_does_not_leak_the_credential() -> None: + """CVE-shaped regression for CodeRabbit's PR #946 finding. + + ``_fetch_json`` is the function every standard provider's authenticated + "list models" call goes through (openai, openrouter, nvidia_nim, + nvidia_nim_sub, bytez), including under the one bounded retry added for + a transient failure -- so a credential leak here would fire up to twice. + Before the fix it called bare ``urllib.request.urlopen``, whose default + ``HTTPRedirectHandler`` copies the ``Authorization`` header onto a + redirected request even when the redirect leaves the original host. + This proves the leak is closed: the trusted-host opener must raise + before a second, cross-host request is ever issued -- red against the + unfixed ``_fetch_json`` (it followed the redirect and returned the + attacker's payload instead of raising), green after. + """ + seen_requests = [] + + class _RedirectingOpener: + def __init__(self, handler): + self._handler = handler + + def open(self, request, timeout=None): + seen_requests.append(request) + return self._handler.redirect_request( + request, + None, + 302, + "Found", + {"Location": "https://evil.example/steal"}, + "https://evil.example/steal", + ) + + def build_opener(*handlers): + assert len(handlers) == 1, "no SSL-context handler expected on the first attempt" + return _RedirectingOpener(handlers[0]) + + with patch( + "contextual_orchestrator.model_discovery.urllib.request.build_opener", + side_effect=build_opener, + ): + with pytest.raises(urllib.error.HTTPError): + _fetch_json( + "https://api.example.com/v1/models", + api_key="sk-super-secret-provider-key", + timeout=1.0, + ) + + # Exactly one request was ever issued -- to the original, trusted host. + # redirect_request raises instead of returning a request to evil.example, + # so the credential is never even constructed for, let alone sent to, it. + assert len(seen_requests) == 1 + assert seen_requests[0].full_url == "https://api.example.com/v1/models" + assert seen_requests[0].get_header("Authorization") == "Bearer sk-super-secret-provider-key" + + +def test_fetch_json_still_follows_a_same_host_redirect() -> None: + """Negative control: a same-host redirect (different path) must still work. + + The fix must not collaterally break the legitimate case a real + provider API can use -- e.g. ``api.example.com/v1/models`` redirecting to + ``api.example.com/v2/models``. + """ + seen_requests = [] + + class _RedirectingOpener: + def __init__(self, handler): + self._handler = handler + + def open(self, request, timeout=None): + seen_requests.append(request) + redirected = self._handler.redirect_request( + request, + None, + 302, + "Found", + {"Location": "https://api.example.com/v2/models"}, + "https://api.example.com/v2/models", + ) + seen_requests.append(redirected) + return _Response({"data": [{"id": "same-host-model"}]}) + + def build_opener(*handlers): + return _RedirectingOpener(handlers[0]) + + with patch( + "contextual_orchestrator.model_discovery.urllib.request.build_opener", + side_effect=build_opener, + ): + payload = _fetch_json( + "https://api.example.com/v1/models", + api_key="sk-super-secret-provider-key", + timeout=1.0, + ) + + assert payload == {"data": [{"id": "same-host-model"}]} + assert len(seen_requests) == 2 + assert seen_requests[0].full_url == "https://api.example.com/v1/models" + assert seen_requests[1].full_url == "https://api.example.com/v2/models" + # The redirected same-host request still legitimately carries the credential. + for request in seen_requests: + assert request.get_header("Authorization") == "Bearer sk-super-secret-provider-key" + + def test_discover_all_models_does_not_match_a_shared_zdr_model_suffix() -> None: register_credential("OPENROUTER_API_KEY", "sk-openrouter") other_source = ProviderModelSource( @@ -1889,14 +2001,14 @@ def test_discover_all_models_does_not_match_a_shared_zdr_model_suffix() -> None: ) register_credential("NVIDIA_NIM_API_KEY", "nim-key") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == other_source.list_url: return _Response({"data": [{"id": "shared-model"}]}) return _Response({"data": [{"id": "openai/shared-model"}]}) with ( patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ), patch( @@ -1924,14 +2036,14 @@ def test_discover_all_models_rejects_an_ambiguous_zdr_model_suffix() -> None: ) register_credential("NVIDIA_NIM_API_KEY", "nim-key") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): if request.full_url == other_source.list_url: return _Response({"data": [{"id": "shared-model"}]}) return _Response({"data": [{"id": "openai/shared-model"}]}) with ( patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ), patch( @@ -1976,12 +2088,12 @@ def test_discovery_boundary_contains_raw_connection_reset() -> None: register_credential("OPENAI_API_KEY", "sk-openai") attempts = [] - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): attempts.append(timeout) raise ConnectionResetError(104, "Connection reset by peer") with ( - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), patch("contextual_orchestrator.model_discovery.time.sleep") as mock_sleep, ): try: @@ -2009,14 +2121,14 @@ def test_discover_provider_models_retries_transient_failure_then_succeeds() -> N payload = {"data": [{"id": "gpt-test", "object": "model"}]} attempt_timeouts = [] - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): attempt_timeouts.append(timeout) if len(attempt_timeouts) == 1: raise urllib.error.HTTPError(request.full_url, 500, "Internal Server Error", {}, None) return _Response(payload) with ( - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), patch("contextual_orchestrator.model_discovery.time.sleep") as mock_sleep, ): discovered = discover_provider_models(OPENAI_SOURCE) @@ -2032,12 +2144,12 @@ def test_discover_provider_models_does_not_retry_non_transient_failure() -> None register_credential("OPENAI_API_KEY", "sk-openai") attempts = [] - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): attempts.append(timeout) raise urllib.error.HTTPError(request.full_url, 401, "Unauthorized", {}, None) with ( - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), patch("contextual_orchestrator.model_discovery.time.sleep") as mock_sleep, ): try: @@ -2095,14 +2207,14 @@ def test_discover_provider_models_retry_timeout_never_exceeds_callers_budget() - payload = {"data": [{"id": "gpt-test", "object": "model"}]} attempt_timeouts = [] - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): attempt_timeouts.append(timeout) if len(attempt_timeouts) == 1: raise urllib.error.HTTPError(request.full_url, 500, "Internal Server Error", {}, None) return _Response(payload) with ( - patch("contextual_orchestrator.model_discovery.urllib.request.urlopen", side_effect=urlopen), + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), patch("contextual_orchestrator.model_discovery.time.sleep"), ): discovered = discover_provider_models(OPENAI_SOURCE, timeout=2.0) @@ -2363,3 +2475,117 @@ def test_sync_discovered_agents_persists_when_agents_db_is_set(tmp_path) -> None second = TaskOrchestrator([ModelAgent("seed_agent", "seed-model")], agents_db=db_path) assert any(a.id == "openai_gpt_5_5" for a in second.candidates) + + +_MODEL_DISCOVERY_LOGGER_NAME = "contextual_orchestrator.model_discovery" + + +@contextmanager +def _captured_discovery_logs(level: int) -> Iterator[io.StringIO]: + """Attach an isolated StringIO handler to the model_discovery logger only.""" + logger = logging.getLogger(_MODEL_DISCOVERY_LOGGER_NAME) + previous_level = logger.level + previous_propagate = logger.propagate + buffer = io.StringIO() + handler = logging.StreamHandler(buffer) + logger.addHandler(handler) + logger.setLevel(level) + logger.propagate = False + try: + yield buffer + finally: + logger.removeHandler(handler) + handler.close() + logger.setLevel(previous_level) + logger.propagate = previous_propagate + + +def test_discover_provider_models_debug_logs_credential_name_not_value() -> None: + """Reconciled with main's stricter privacy contract (merge of #946 and the + independently-landed test_discovery_debug_log_identifies_account_without_secret): + the discovery debug logs identify the account by provider name only and + never include the KV credential *name* (label) either, not just never its + value. + """ + fake_value = "sk-FAKEFAKEFAKEFAKEFAKE1234567890" # noqa: S105 - obviously non-functional fixture + register_credential("OPENAI_API_KEY", fake_value) + with ( + patch( + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", + return_value=_Response({"data": [{"id": "gpt-5.5"}]}), + ), + _captured_discovery_logs(logging.DEBUG) as buffer, + ): + discover_provider_models(OPENAI_SOURCE) + output = buffer.getvalue() + assert "account=openai" in output + assert "OPENAI_API_KEY" not in output + assert fake_value not in output + + +def test_discover_provider_models_debug_logs_attempt_and_result() -> None: + register_credential("OPENAI_API_KEY", "sk-router") + with ( + patch( + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", + return_value=_Response({"data": [{"id": "gpt-5.5"}, {"id": "gpt-5.5-mini"}]}), + ), + _captured_discovery_logs(logging.DEBUG) as buffer, + ): + discover_provider_models(OPENAI_SOURCE) + output = buffer.getvalue() + assert "discovery_attempt account=openai" in output + assert "discovery_result account=openai model_count=2" in output + + +def test_discover_provider_models_debug_logs_are_silent_without_debug() -> None: + register_credential("OPENAI_API_KEY", "sk-router") + with ( + patch( + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", + return_value=_Response({"data": [{"id": "gpt-5.5"}]}), + ), + _captured_discovery_logs(logging.WARNING) as buffer, + ): + discover_provider_models(OPENAI_SOURCE) + assert buffer.getvalue() == "" + + +def test_discover_provider_models_debug_logs_failure_error_type_and_redacts_message() -> None: + register_credential("OPENAI_API_KEY", "sk-router") + fake_secret = "sk-FAKEFAKEFAKEFAKEFAKE1234567890" # noqa: S105 - obviously non-functional fixture + + def urlopen(request, timeout=None, **_kwargs): + raise urllib.error.URLError(f"connection refused api_key={fake_secret}") + + with ( + patch("contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen), + _captured_discovery_logs(logging.DEBUG) as buffer, + ): + try: + discover_provider_models(OPENAI_SOURCE) + except ProviderDiscoveryError: + pass + else: # pragma: no cover + raise AssertionError("a transport failure must raise ProviderDiscoveryError") + output = buffer.getvalue() + assert "discovery_provider_failed account=openai" in output + assert "error_type=URLError" in output + assert "[REDACTED]" in output + assert fake_secret not in output + + +def test_discover_all_models_logs_aggregate_summary_at_info() -> None: + register_credential("OPENAI_API_KEY", "sk-router") + with ( + patch( + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", + return_value=_Response({"data": [{"id": "gpt-5.5"}]}), + ), + _captured_discovery_logs(logging.INFO) as buffer, + ): + discover_all_models((OPENAI_SOURCE,)) + output = buffer.getvalue() + assert "discovery_complete providers=1" in output + assert "models=" in output + assert "errors=" in output diff --git a/tests/test_model_discovery_boundaries.py b/tests/test_model_discovery_boundaries.py index c17467e96..090987c79 100644 --- a/tests/test_model_discovery_boundaries.py +++ b/tests/test_model_discovery_boundaries.py @@ -60,13 +60,13 @@ def test_http_error_maps_to_stable_status_code_without_provider_text() -> None: """An HTTP 429 from a provider becomes ``http_status_429`` evidence.""" register_credential("OPENAI_API_KEY", "sk-openai") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): raise urllib.error.HTTPError( request.full_url, 429, "rate limited", hdrs=None, fp=None ) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): with pytest.raises(ProviderDiscoveryError) as excinfo: @@ -79,11 +79,11 @@ def test_timeout_maps_to_stable_timeout_code() -> None: """A socket-level timeout never leaks as an unclassified failure.""" register_credential("OPENAI_API_KEY", "sk-openai") - def urlopen(request, timeout=None): + def urlopen(request, timeout=None, **_kwargs): raise TimeoutError("timed out") with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): with pytest.raises(ProviderDiscoveryError) as excinfo: @@ -169,7 +169,7 @@ def urlopen(request, **kwargs): return _Response({"data": []}) with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", side_effect=urlopen, ): assert _fetch_json("https://provider.example/v1/models", timeout=1) == { @@ -180,6 +180,39 @@ def urlopen(request, **kwargs): assert calls[1]["context"].check_hostname is True +def test_fetch_json_rejects_oversized_response_body() -> None: + """An oversized provider body is rejected before JSON parsing, not buffered whole. + + Regression for the unbounded ``response.read()`` in ``_fetch_json``: a + large or malicious/misbehaving provider response (an outage page dumped + as an unbounded body, or a compromised endpoint) must not be read fully + into memory. The bounded-read call must request at most + ``MAX_DISCOVERY_RESPONSE_BYTES + 1`` bytes -- exactly enough to detect an + overage -- never the full oversized body. + """ + oversized = b"0" * (MAX_DISCOVERY_RESPONSE_BYTES + 1024) + reads: list[int | None] = [] + + class OversizedResponse: + def __enter__(self): + return self + + def __exit__(self, *_args): + return False + + def read(self, amt: int | None = None) -> bytes: + reads.append(amt) + return oversized if amt is None else oversized[:amt] + + with patch( + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", + return_value=OversizedResponse(), + ): + with pytest.raises(ValueError, match="model discovery response exceeds maximum size"): + _fetch_json("https://provider.example/v1/models", timeout=1) + assert reads == [MAX_DISCOVERY_RESPONSE_BYTES + 1] + + def test_malformed_json_maps_to_invalid_response_code() -> None: """A non-JSON provider body is invalid_response, not a crash.""" register_credential("OPENAI_API_KEY", "sk-openai") @@ -191,11 +224,14 @@ def __enter__(self): def __exit__(self, *_args): return False - def read(self) -> bytes: - return b"not json" + def read(self, amt: int | None = None) -> bytes: + # _fetch_json now caps its read (MAX_DISCOVERY_RESPONSE_BYTES + 1); + # accept the optional amt like http.client.HTTPResponse.read does. + body = b"not json" + return body if amt is None else body[:amt] with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=GarbageResponse(), ): with pytest.raises(ProviderDiscoveryError) as excinfo: @@ -213,7 +249,7 @@ def test_insecure_discovery_url_is_refused_before_any_network_call() -> None: ) register_credential("INSECURE_API_KEY", "secret-value") with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen" + "contextual_orchestrator.model_discovery._open_trusted_discovery_request" ) as urlopen: with pytest.raises(ProviderDiscoveryError) as excinfo: discover_provider_models(source) @@ -246,7 +282,7 @@ def test_openai_rows_that_are_not_objects_are_skipped() -> None: register_credential("OPENROUTER_API_KEY", "sk-router") payload = {"data": ["junk-string", 42, None, {"id": "meta/llama-3.3"}]} with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): discovered = discover_provider_models(OPENROUTER_SOURCE) @@ -258,7 +294,7 @@ def test_bytez_rows_that_are_not_objects_are_skipped() -> None: register_credential("BYTEZ_API_KEY", "bytez-secret") payload = {"output": [7, "bad", {"modelId": "0-hero/Matter-0.1-Slim-7B-C"}]} with patch( - "contextual_orchestrator.model_discovery.urllib.request.urlopen", + "contextual_orchestrator.model_discovery._open_trusted_discovery_request", return_value=_Response(payload), ): discovered = discover_provider_models(BYTEZ_SOURCE) diff --git a/tests/test_orchestrator_debug_logging.py b/tests/test_orchestrator_debug_logging.py new file mode 100644 index 000000000..93f5824f7 --- /dev/null +++ b/tests/test_orchestrator_debug_logging.py @@ -0,0 +1,493 @@ +"""DEBUG/WARNING instrumentation on the retry, circuit-breaker, and ranking paths. + +Mirrors tests/test_provider_reliability.py's style for driving `ModelClient` +and `TaskOrchestrator` directly. The key property under test throughout: a +credential/API-key-shaped string that flows through a path that emits a DEBUG +log must never appear verbatim in captured log output. +""" + +from __future__ import annotations + +import io +import logging +import sys +import urllib.error +from contextlib import contextmanager +from pathlib import Path +from typing import Iterator +from unittest.mock import patch + +sys.path.insert(0, str(Path(__file__).resolve().parents[1])) + +from contextual_orchestrator import ModelAgent, TaskOrchestrator # noqa: E402 +from contextual_orchestrator.orchestrator import ModelClient # noqa: E402 + +_ORCHESTRATOR_LOGGER_NAME = "contextual_orchestrator.orchestrator" +_FAKE_SECRET = "sk-FAKEFAKEFAKEFAKEFAKE1234567890" # noqa: S105 - obviously non-functional fixture + + +@contextmanager +def _captured_logs(level: int) -> Iterator[io.StringIO]: + """Attach an isolated StringIO handler to the orchestrator logger only.""" + logger = logging.getLogger(_ORCHESTRATOR_LOGGER_NAME) + previous_level = logger.level + previous_propagate = logger.propagate + buffer = io.StringIO() + handler = logging.StreamHandler(buffer) + logger.addHandler(handler) + logger.setLevel(level) + logger.propagate = False + try: + yield buffer + finally: + logger.removeHandler(handler) + handler.close() + logger.setLevel(previous_level) + logger.propagate = previous_propagate + + +def _http_error(code: int) -> urllib.error.HTTPError: + return urllib.error.HTTPError("https://provider.example/chat/completions", code, "err", None, None) + + +def test_judged_ranking_log_does_not_label_quality_as_throughput() -> None: + orchestrator = TaskOrchestrator( + [ + ModelAgent("worker_one", "model-one", group_name="shared_model"), + ModelAgent("worker_two", "model-two", group_name="shared_model"), + ] + ) + orchestrator._quality_router.observe_success("worker_one", 1.0) + + with _captured_logs(logging.DEBUG) as buffer: + orchestrator._measured_member_order(["worker_one", "worker_two"]) + + output = buffer.getvalue() + assert "judged_quality=True evidence_score=" in output + assert "success_rps=" not in output + + +def test_send_with_retry_debug_logs_redact_secret_shaped_error_message() -> None: + """THE key secret-leak test: a fake credential shape must never reach captured logs.""" + + class LeakyClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=0) + + def _send(self, agent: ModelAgent, payload: dict, destination=None) -> str: # type: ignore[override] + raise RuntimeError(f"upstream rejected request: api_key={_FAKE_SECRET}") + + client = LeakyClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.DEBUG) as buffer: + try: + client._send_with_retry(agent, {"model": "gpt"}) + except RuntimeError: + pass + else: # pragma: no cover + raise AssertionError("a failed provider request must raise") + output = buffer.getvalue() + assert "[REDACTED]" in output + assert _FAKE_SECRET not in output + + +def test_send_with_retry_debug_logs_report_agent_and_attempts_without_debug_by_default() -> None: + class FlakyClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=2, retry_backoff=0.0) + self.attempts = 0 + + def _send(self, agent: ModelAgent, payload: dict, destination=None) -> str: # type: ignore[override] + self.attempts += 1 + if self.attempts < 2: + raise _http_error(503) + return "recovered" + + client = FlakyClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + + with _captured_logs(logging.WARNING) as buffer: + assert client._send_with_retry(agent, {"model": "gpt"}) == "recovered" + assert buffer.getvalue() == "" # no DEBUG noise, and no failure at WARNING either + + client.attempts = 0 + with _captured_logs(logging.DEBUG) as buffer: + assert client._send_with_retry(agent, {"model": "gpt"}) == "recovered" + debug_output = buffer.getvalue() + assert "provider_attempt agent_id=worker_agent" in debug_output + assert "provider_attempt_failed agent_id=worker_agent" in debug_output + assert "provider_backoff agent_id=worker_agent" in debug_output + + +def test_provider_exhausted_warning_fires_without_verbose() -> None: + class AlwaysDownClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=1, retry_backoff=0.0) + + def _send(self, agent: ModelAgent, payload: dict, destination=None) -> str: # type: ignore[override] + raise _http_error(503) + + client = AlwaysDownClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.WARNING) as buffer: + try: + client._send_with_retry(agent, {"model": "gpt"}) + except Exception: + pass + output = buffer.getvalue() + assert "provider_exhausted agent_id=worker_agent" in output + assert "final_error_type=" in output + + +def test_provider_rejected_permanent_fires_instead_of_exhausted_on_immediate_non_transient_failure() -> None: + """A non-transient first failure never claims a retry budget it never used. + + With `max_retries=2` (a real, non-zero budget) and a first attempt that + fails with a non-transient error (401, not in TRANSIENT_HTTP_STATUS), the + loop breaks immediately without ever spending a retry. `provider_exhausted` + ("used its full retry budget") would misclassify this as an exhaustion + event; a distinctly named event for an immediate terminal rejection is + the accurate one. + """ + + class AlwaysUnauthorizedClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=2, retry_backoff=0.0) + self.attempts = 0 + + def _send(self, agent: ModelAgent, payload: dict, destination=None) -> str: # type: ignore[override] + self.attempts += 1 + raise _http_error(401) + + client = AlwaysUnauthorizedClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.WARNING) as buffer: + try: + client._send_with_retry(agent, {"model": "gpt"}) + except Exception: + pass + assert client.attempts == 1 # no retry budget was actually consumed + output = buffer.getvalue() + assert "provider_exhausted" not in output + assert "provider_rejected_permanent agent_id=worker_agent" in output + assert "final_error_type=" in output + + +def test_send_raw_with_retry_also_distinguishes_permanent_rejection_from_exhaustion() -> None: + """`_send_raw_with_retry` duplicates `_send_with_retry`'s retry loop and must share the fix.""" + + class AlwaysUnauthorizedRawClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=2, retry_backoff=0.0) + self.attempts = 0 + + def _send_raw(self, agent: ModelAgent, endpoint: str, payload: dict, destination=None) -> dict: # type: ignore[override] + self.attempts += 1 + raise _http_error(401) + + client = AlwaysUnauthorizedRawClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.WARNING) as buffer: + try: + client._send_raw_with_retry(agent, "chat/completions", {}) + except Exception: + pass + assert client.attempts == 1 + output = buffer.getvalue() + assert "provider_exhausted" not in output + assert "provider_rejected_permanent agent_id=worker_agent" in output + + +def test_zero_retry_limit_with_transient_error_logs_no_retry_budget_not_permanent() -> None: + """`max_retries=0` means no retry budget ever existed, so nothing was "exhausted" -- + and, separately, a *transient* error under a zero budget must not be mislabeled + "permanent" either: "no retry budget was configured" and "this error is + non-retryable by nature" are two independent facts. Uses a transient error + (503, would normally be retried) deliberately, paired with the + non-transient counterpart below to cover all 4 (retries>0 vs =0) x + (transient vs non-transient) combinations. + """ + + class ZeroRetryClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=0) + self.attempts = 0 + + def _send(self, agent: ModelAgent, payload: dict, destination=None) -> str: # type: ignore[override] + self.attempts += 1 + raise _http_error(503) # transient -- would normally be retried + + client = ZeroRetryClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.WARNING) as buffer: + try: + client._send_with_retry(agent, {"model": "gpt"}) + except Exception: + pass + assert client.attempts == 1 + output = buffer.getvalue() + assert "provider_exhausted" not in output + assert "provider_rejected_permanent" not in output + assert "provider_no_retry_budget agent_id=worker_agent" in output + assert "transient=True" in output + + +def test_zero_retry_limit_with_non_transient_error_logs_no_retry_budget_too() -> None: + """Same zero-budget event fires for a non-transient error too, with `transient=False`.""" + + class ZeroRetryUnauthorizedClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=0) + self.attempts = 0 + + def _send(self, agent: ModelAgent, payload: dict, destination=None) -> str: # type: ignore[override] + self.attempts += 1 + raise _http_error(401) # non-transient + + client = ZeroRetryUnauthorizedClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.WARNING) as buffer: + try: + client._send_with_retry(agent, {"model": "gpt"}) + except Exception: + pass + assert client.attempts == 1 + output = buffer.getvalue() + assert "provider_exhausted" not in output + assert "provider_rejected_permanent" not in output + assert "provider_no_retry_budget agent_id=worker_agent" in output + assert "transient=False" in output + + +def test_send_raw_with_retry_zero_retry_limit_with_transient_error_logs_no_retry_budget() -> None: + """`_send_raw_with_retry` duplicates the retry loop and must share the zero-retry fix.""" + + class ZeroRetryRawClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=0) + self.attempts = 0 + + def _send_raw(self, agent: ModelAgent, endpoint: str, payload: dict, destination=None) -> dict: # type: ignore[override] + self.attempts += 1 + raise _http_error(503) # transient -- would normally be retried + + client = ZeroRetryRawClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.WARNING) as buffer: + try: + client._send_raw_with_retry(agent, "chat/completions", {}) + except Exception: + pass + assert client.attempts == 1 + output = buffer.getvalue() + assert "provider_exhausted" not in output + assert "provider_rejected_permanent" not in output + assert "provider_no_retry_budget agent_id=worker_agent" in output + assert "transient=True" in output + + +def test_send_raw_with_retry_zero_retry_limit_with_non_transient_error_logs_no_retry_budget() -> None: + """`_send_raw_with_retry` counterpart of the non-transient zero-budget case.""" + + class ZeroRetryRawUnauthorizedClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=0) + self.attempts = 0 + + def _send_raw(self, agent: ModelAgent, endpoint: str, payload: dict, destination=None) -> dict: # type: ignore[override] + self.attempts += 1 + raise _http_error(401) # non-transient + + client = ZeroRetryRawUnauthorizedClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.WARNING) as buffer: + try: + client._send_raw_with_retry(agent, "chat/completions", {}) + except Exception: + pass + assert client.attempts == 1 + output = buffer.getvalue() + assert "provider_exhausted" not in output + assert "provider_rejected_permanent" not in output + assert "provider_no_retry_budget agent_id=worker_agent" in output + assert "transient=False" in output + + +def test_send_raw_with_retry_one_shot_call_does_not_log_no_retry_budget() -> None: + """`proxy_send_once`'s intentional single-attempt call must not claim `no_retry_budget`. + + Regression: with a real, non-zero configured retry budget (`max_retries=2`), + calling `_send_raw_with_retry(..., allow_transient_retries=False)` -- the + exact policy `proxy_send_once` uses so an already-failing-over passthrough + request cannot itself amplify load with a nested retry loop -- forces + `retry_limit` to 0 for this one call. Before the fix, `_log_retry_outcome` + could not tell that apart from an agent that genuinely has no retry budget + configured at all, and always logged the misleading + `provider_no_retry_budget` event. It must now log a distinctly named + `provider_one_shot_call_failed` event instead. + """ + + class OneShotRawClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=2, retry_backoff=0.0) + self.attempts = 0 + + def _send_raw(self, agent: ModelAgent, endpoint: str, payload: dict, destination=None) -> dict: # type: ignore[override] + self.attempts += 1 + raise _http_error(503) # transient -- would normally be retried + + client = OneShotRawClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.WARNING) as buffer: + try: + client._send_raw_with_retry( + agent, "chat/completions", {}, allow_transient_retries=False + ) + except Exception: + pass + assert client.attempts == 1 # forced to exactly one attempt despite max_retries=2 + output = buffer.getvalue() + assert "provider_no_retry_budget" not in output + assert "provider_exhausted" not in output + assert "provider_rejected_permanent" not in output + assert "provider_one_shot_call_failed agent_id=worker_agent" in output + assert "attempts=1" in output + assert "transient=True" in output + + +def test_send_raw_with_retry_one_shot_call_reports_transient_false_too() -> None: + """The one-shot event carries the real `transient` classification, not a fixed value.""" + + class OneShotRawUnauthorizedClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=2, retry_backoff=0.0) + self.attempts = 0 + + def _send_raw(self, agent: ModelAgent, endpoint: str, payload: dict, destination=None) -> dict: # type: ignore[override] + self.attempts += 1 + raise _http_error(401) # non-transient + + client = OneShotRawUnauthorizedClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with _captured_logs(logging.WARNING) as buffer: + try: + client._send_raw_with_retry( + agent, "chat/completions", {}, allow_transient_retries=False + ) + except Exception: + pass + assert client.attempts == 1 + output = buffer.getvalue() + assert "provider_no_retry_budget" not in output + assert "provider_one_shot_call_failed agent_id=worker_agent" in output + assert "transient=False" in output + + +def test_proxy_send_once_one_shot_failure_does_not_log_no_retry_budget() -> None: + """End-to-end: `proxy_send_once` itself must not emit the misleading event.""" + + class OneShotProxyClient(ModelClient): + def __init__(self) -> None: + super().__init__(max_retries=2, retry_backoff=0.0) + + def _send_raw(self, agent: ModelAgent, endpoint: str, payload: dict, destination=None) -> dict: # type: ignore[override] + raise _http_error(503) + + client = OneShotProxyClient() + agent = ModelAgent("worker_agent", "gpt", base_url="https://provider.example/v1") + with ( + patch.object(client, "_validate_provider", return_value=(2, ("203.0.113.10", 443))), + _captured_logs(logging.WARNING) as buffer, + ): + try: + client.proxy_send_once(agent, "chat/completions", {"model": "gpt"}) + except Exception: + pass + output = buffer.getvalue() + assert "provider_no_retry_budget" not in output + assert "provider_one_shot_call_failed agent_id=worker_agent" in output + + +def test_circuit_opened_emits_warning_without_debug() -> None: + """The WARNING-tier edge-transition line fires by default; the per-increment DEBUG line does not.""" + orchestrator = TaskOrchestrator([ModelAgent("solo_agent", "mock-model")]) + orchestrator.circuit_failure_threshold = 2 + with _captured_logs(logging.WARNING) as buffer: + orchestrator._record_failure("solo_agent") + assert buffer.getvalue() == "" # first failure: below threshold, no transition yet + orchestrator._record_failure("solo_agent") + output = buffer.getvalue() + assert "circuit_opened agent_id=solo_agent" in output + assert "circuit_failure" not in output # DEBUG-tier line must not appear at WARNING + + +def test_circuit_failure_debug_log_fires_on_every_increment() -> None: + orchestrator = TaskOrchestrator([ModelAgent("solo_agent", "mock-model")]) + orchestrator.circuit_failure_threshold = 5 + with _captured_logs(logging.DEBUG) as buffer: + orchestrator._record_failure("solo_agent") + orchestrator._record_failure("solo_agent") + output = buffer.getvalue() + assert output.count("circuit_failure agent_id=solo_agent") == 2 + + +def test_circuit_cleared_only_logs_when_state_existed() -> None: + orchestrator = TaskOrchestrator([ModelAgent("solo_agent", "mock-model")]) + orchestrator.circuit_failure_threshold = 5 + with _captured_logs(logging.DEBUG) as buffer: + orchestrator._record_success("solo_agent") # nothing to clear yet + assert "circuit_cleared" not in buffer.getvalue() + orchestrator._record_failure("solo_agent") + orchestrator._record_success("solo_agent") # now clears real state + output = buffer.getvalue() + assert "circuit_cleared agent_id=solo_agent" in output + + +def test_circuit_reset_debug_log_fires_on_cooldown_expiry() -> None: + orchestrator = TaskOrchestrator([ModelAgent("solo_agent", "mock-model")]) + orchestrator.circuit_failure_threshold = 1 + orchestrator.circuit_reset_seconds = 0.0 + orchestrator._record_failure("solo_agent") + with _captured_logs(logging.DEBUG) as buffer: + assert orchestrator._circuit_open("solo_agent") is False + output = buffer.getvalue() + assert "circuit_reset agent_id=solo_agent" in output + + +def test_ranked_agents_debug_logs_include_agent_id_not_prompt_text() -> None: + distinctive_prompt = "the quick zephyrblorp fox jumps xyzzy1234" + orchestrator = TaskOrchestrator( + [ + ModelAgent("general_agent", "mock-generalist", tags=("reasoning", "writing")), + ModelAgent("second_agent", "mock-second", tags=("reasoning", "writing")), + ] + ) + with _captured_logs(logging.DEBUG) as buffer: + orchestrator._ranked_agents(distinctive_prompt, "worker") + output = buffer.getvalue() + assert "general_agent" in output or "second_agent" in output + assert distinctive_prompt not in output + + +def test_select_agent_debug_log_reports_chosen_agent() -> None: + orchestrator = TaskOrchestrator( + [ModelAgent("general_agent", "mock-generalist", tags=("reasoning", "writing"))] + ) + with _captured_logs(logging.DEBUG) as buffer: + selected = orchestrator._select_agent("hello", "worker") + output = buffer.getvalue() + assert f"chosen_agent_id={selected.id}" in output + assert f"chosen_model={selected.model}" in output + + +if __name__ == "__main__": # pragma: no cover + test_send_with_retry_debug_logs_redact_secret_shaped_error_message() + test_send_with_retry_debug_logs_report_agent_and_attempts_without_debug_by_default() + test_provider_exhausted_warning_fires_without_verbose() + test_circuit_opened_emits_warning_without_debug() + test_circuit_failure_debug_log_fires_on_every_increment() + test_circuit_cleared_only_logs_when_state_existed() + test_circuit_reset_debug_log_fires_on_cooldown_expiry() + test_ranked_agents_debug_logs_include_agent_id_not_prompt_text() + test_select_agent_debug_log_reports_chosen_agent() + print("ok") diff --git a/tests/test_telemetry.py b/tests/test_telemetry.py index 91e744318..0c71b34ec 100644 --- a/tests/test_telemetry.py +++ b/tests/test_telemetry.py @@ -28,6 +28,30 @@ ) +def _wait_for_caplog(caplog, predicate, *, timeout: float = 1.0, interval: float = 0.02) -> None: + """Poll ``predicate(caplog.text)`` until true or ``timeout`` elapses. + + The per-request INFO summary is logged by a real server thread strictly + *after* it has already flushed the HTTP response back to the client + (`server.py`'s ``handle_one_request`` logs in its ``finally`` block, + which runs after ``super().handle_one_request()`` -- and therefore the + response write -- completes). A test that asserts on this log line + immediately after its client call returns has no guarantee the server + thread has reached that ``finally`` block yet; bounded polling closes + that race deterministically and quickly in the common case, rather than + a fixed sleep that is either too short (still flaky) or wastefully long. + Call this while the relevant ``caplog.at_level(...)`` scope is still + open, so a late record is not filtered out by the time it arrives. + """ + import time + + deadline = time.monotonic() + timeout + while not predicate(caplog.text): + if time.monotonic() >= deadline: + return + time.sleep(interval) + + def test_session_id_accepts_lineageweave_header_and_metadata(): """The two compatible transport forms identify the same processing session.""" assert ( @@ -94,6 +118,20 @@ def test_session_and_attribute_boundaries_reject_unsafe_values(): reset_session_id(token) +def test_session_id_hash_matches_safe_attributes_convention(): + """The shared correlation-hash helper agrees with _safe_attributes' own hashing.""" + assert telemetry_module.session_id_hash() is None + token = set_session_id("session-safe") + try: + assert telemetry_module.session_id_hash() == hashlib.sha256(b"session-safe").hexdigest() + assert ( + telemetry_module._safe_attributes({})["contextual_orchestrator.session_id_hash"] + == telemetry_module.session_id_hash() + ) + finally: + reset_session_id(token) + + def test_finish_reason_attribute_accepts_only_bounded_string_arrays(): """The standard finish-reasons array remains bounded and prompt-safe.""" assert telemetry_module._safe_attributes( @@ -269,6 +307,45 @@ def test_handler_resets_session_after_each_keep_alive_request(monkeypatch): server.server_close() +def test_handle_one_request_resets_command_and_path_before_each_call(monkeypatch): + """Deterministic unit-level counterpart to + test_keep_alive_close_does_not_log_phantom_request below, which proves + the same property end to end through a real socket but can occasionally + flake on unrelated threaded-server teardown timing. + + Simulates stdlib's own `handle_one_request`: the first call "parses" a + request (setting `command`/`path`, as `parse_request` would), the second + call reads nothing at all (an empty `raw_requestline` -- a closed + keep-alive connection) and touches neither attribute, matching real + stdlib behavior on that path. Without resetting them first, the second + call would leave the *first* call's `command`/`path` in place, causing + `_log_request_summary`'s "nothing to report" guard to never fire. + """ + server = build_server(SimpleNamespace(agents=[], candidates=[]), port=0) + handler = server.RequestHandlerClass.__new__(server.RequestHandlerClass) + call_count = {"n": 0} + + def fake_super_handle_one_request(self): + call_count["n"] += 1 + if call_count["n"] == 1: + self.command = "GET" + self.path = "/healthz" + # Second call: nothing read, nothing touched (matches stdlib on a + # closed connection). + + monkeypatch.setattr(BaseHTTPRequestHandler, "handle_one_request", fake_super_handle_one_request) + try: + handler.handle_one_request() + assert handler.command == "GET" + assert handler.path == "/healthz" + + handler.handle_one_request() + assert handler.command is None + assert handler.path is None + finally: + server.server_close() + + def test_handler_replaces_trace_context_on_reauthorization(monkeypatch): """A second authorization cannot leave the first trace context attached.""" server = build_server(SimpleNamespace(agents=[], candidates=[]), port=0) @@ -349,6 +426,354 @@ def flush(self): server.server_close() +def test_response_payload_debug_log_reuses_redacted_payload_never_raw_secret(caplog): + """The DEBUG response summary never carries a secret from an error message. + + Superseded mechanism, same property: this used to prove the secret was + caught by redact_value and replaced with "[REDACTED]" in an otherwise + logged error message. It now logs only allowlisted metadata + (response_metadata_for_log) and never the error message text at all -- + a strictly stronger guarantee, since the secret (and the rest of the + message) is absent rather than merely masked. + """ + fake_secret = "sk-FAKEFAKEFAKEFAKEFAKE1234567890" # noqa: S105 - obviously non-functional fixture + payload = { + "choices": [{"message": {"content": "ok"}}], + "error": {"message": f"upstream rejected request: api_key={fake_secret}"}, + } + + with caplog.at_level("DEBUG", logger="contextual_orchestrator.server"): + server_module._response_payload(payload, include_trace=True) + + assert "response_summary" in caplog.text + assert "has_error" in caplog.text + assert fake_secret not in caplog.text + + +def test_response_payload_debug_log_redacts_credential_shaped_json_keys(caplog): + """A secret under a credential-shaped key never reaches the response summary. + + `redact_value`/`redact_text` only pattern-match the literal in-string + shape `(api[_-]?key|token|secret|password)[:=]` or `bearer + ` -- they never inspect the JSON *key name* a string value is + nested under. A response payload shaped like `{"private_key": "..."}`, + `{"key": "..."}`, `{"auth": "..."}`, or `{"credential": "..."}` is now + caught structurally: the response summary logs only an allowlisted + metadata shape that never includes these fields at all (see + `response_metadata_for_log`), with the key-name-based + `redact_credential_shaped_keys` pass applied on top as a second, + defense-in-depth layer in case a future allowlist field ever collides + with a credential-shaped key name. + """ + fake_private_key = "-----BEGIN PRIVATE KEY-----\nMIIFAKEFAKEFAKE\n-----END PRIVATE KEY-----" + fake_api_key = "AIzaSyFAKEFAKEFAKEFAKEFAKEFAKEFAKEFAKE12" + fake_auth = "sk-live-FAKEFAKEFAKEFAKEFAKEFAKEFAKE" + fake_credential = "ghp_FAKEFAKEFAKEFAKEFAKEFAKEFAKEFAKE" + payload = { + "choices": [{"message": {"content": "ok"}}], + "metadata": { + "private_key": fake_private_key, + "key": fake_api_key, + "auth": fake_auth, + }, + "credential": fake_credential, + } + + with caplog.at_level("DEBUG", logger="contextual_orchestrator.server"): + server_module._response_payload(payload, include_trace=True) + + assert "response_summary" in caplog.text + assert fake_private_key not in caplog.text + assert fake_api_key not in caplog.text + assert fake_auth not in caplog.text + assert fake_credential not in caplog.text + + +def test_response_payload_debug_log_never_includes_ordinary_response_content(caplog): + """CWE-532 (CodeRabbit): the DEBUG summary must never carry response *content*. + + `redact_value`/`redact_credential_shaped_keys` only mask credential-shaped + content -- ordinary response text (`choices[].message.content`, tool-call + arguments, an `error.message` that can echo caller-supplied input) is not + a credential, so it was never masked and reached DEBUG output verbatim. + That text can carry PII or business-sensitive content that has nothing to + do with secrets. The summary now logs only an allowlisted metadata shape + (whether the response is error-shaped, the model name, the choice count, + and numeric usage counts) and never the payload's actual text. + """ + sensitive_content = "My SSN is 123-45-6789 and I live at 42 Example Lane." + sensitive_tool_argument = "wire $50000 to account 000111222 routing 333444555" + sensitive_error_text = "rejected request containing patient record MRN-778899" + payload = { + "id": "chatcmpl-abc123", + "model": "gpt-test", + "choices": [ + { + "index": 0, + "message": { + "role": "assistant", + "content": sensitive_content, + "tool_calls": [ + { + "id": "call_1", + "function": {"name": "wire_transfer", "arguments": sensitive_tool_argument}, + } + ], + }, + } + ], + "usage": {"prompt_tokens": 12, "completion_tokens": 34, "total_tokens": 46}, + "error": {"message": sensitive_error_text}, + } + + with caplog.at_level("DEBUG", logger="contextual_orchestrator.server"): + server_module._response_payload(payload, include_trace=True) + + assert "response_summary" in caplog.text + assert sensitive_content not in caplog.text + assert sensitive_tool_argument not in caplog.text + assert sensitive_error_text not in caplog.text + # The allowlisted metadata itself is still present. + assert "gpt-test" in caplog.text + assert "choice_count" in caplog.text + assert "46" in caplog.text # total_tokens, allowlisted numeric usage + + +def test_response_payload_debug_log_is_silent_without_debug(caplog): + payload = {"choices": [{"message": {"content": "ok"}}]} + + with caplog.at_level("INFO", logger="contextual_orchestrator.server"): + server_module._response_payload(payload, include_trace=True) + + assert "response_summary" not in caplog.text + + +def test_per_request_info_summary_reports_method_path_and_status(caplog): + """One body-free INFO line per completed request, using method/path/status/latency.""" + import threading + import time + import urllib.request + + server = build_server(SimpleNamespace(agents=[], candidates=[]), port=0) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + port = server.server_address[1] + try: + with caplog.at_level("INFO", logger="contextual_orchestrator.server"): + with urllib.request.urlopen(f"http://127.0.0.1:{port}/healthz", timeout=5) as response: + assert response.status == 200 + _wait_for_caplog(caplog, lambda text: "http_request" in text) + finally: + server.shutdown() + thread.join(timeout=5) + server.server_close() + # ThreadingHTTPServer's per-connection handler threads are daemon + # threads server_close() does not wait for; a brief settle avoids a + # straggler's own _log_request_summary call landing inside a *later* + # test's caplog window instead of being filtered out here at the + # default WARNING level once this test's own caplog.at_level scope + # has already exited. + time.sleep(0.2) + + assert "http_request" in caplog.text + assert "method=GET" in caplog.text + assert "path=/healthz" in caplog.text + assert "status=200" in caplog.text + + +def test_per_request_info_summary_never_includes_query_string(caplog): + """The INFO per-request summary logs the bare path only, never a query string. + + A caller could plausibly put a token in a query parameter (a common + client habit) even though this server's own auth is header-only; the + summary line's own docstring already claims to be body-free and never + carry "a query string beyond the raw path", so the raw query string + (and anything in it) must never reach this log line. + """ + import threading + import time + import urllib.request + + fake_token = "sk-FAKEFAKEFAKEFAKEFAKEQUERYSTRING123" + server = build_server(SimpleNamespace(agents=[], candidates=[]), port=0) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + port = server.server_address[1] + try: + with caplog.at_level("INFO", logger="contextual_orchestrator.server"): + with urllib.request.urlopen( + f"http://127.0.0.1:{port}/healthz?api_key={fake_token}", timeout=5 + ) as response: + assert response.status == 200 + _wait_for_caplog(caplog, lambda text: "http_request" in text) + finally: + server.shutdown() + thread.join(timeout=5) + server.server_close() + time.sleep(0.2) # see test_per_request_info_summary_reports_method_path_and_status + + assert "http_request" in caplog.text + assert "path=/healthz" in caplog.text + assert fake_token not in caplog.text + assert "?" not in caplog.text + + +def test_keep_alive_close_does_not_log_phantom_request(caplog): + """A keep-alive connection closing without a second request logs nothing extra. + + `handle_one_request` never reset `self.command`/`self.path` before each + call, so when a persistent connection's next read returns nothing (the + client closed it), those attributes were still whatever the *previous* + real request left them as. The per-request summary's own "nothing to + report" guard (`if not method and not path: return`) therefore never + fired, and the prior request got logged a second time with a statusless + "phantom" entry. + """ + import http.client + import threading + import time as time_module + + server = build_server(SimpleNamespace(agents=[], candidates=[]), port=0) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + port = server.server_address[1] + try: + with caplog.at_level("INFO", logger="contextual_orchestrator.server"): + connection = http.client.HTTPConnection("127.0.0.1", port, timeout=5) + connection.request("GET", "/healthz") + response = connection.getresponse() + assert response.status == 200 + response.read() + _wait_for_caplog(caplog, lambda text: "http_request" in text) + connection.close() # keep-alive connection closed with no second request + time_module.sleep(0.3) # let the server's connection thread observe the close + finally: + server.shutdown() + thread.join(timeout=5) + server.server_close() + time_module.sleep(0.2) # see test_per_request_info_summary_reports_method_path_and_status + + assert caplog.text.count("http_request") == 1 + assert "path=/healthz" in caplog.text + + +def test_framework_generated_error_status_is_captured_in_log(caplog): + """A status the framework sends itself (not via our own writers) is still logged. + + `_last_status` used to be updated only by this module's own + `_send`/`_send_text`/`_send_bytes`/`_send_sse` writers. + `BaseHTTPRequestHandler`'s own machinery -- e.g. its built-in 501 for an + HTTP method with no matching `do_*` handler -- calls `send_response` + directly and bypasses all of those writers, so the INFO per-request + summary logged `status=-` even though a real status (501) was already + sent to the client. + """ + import http.client + import threading + import time + + server = build_server(SimpleNamespace(agents=[], candidates=[]), port=0) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + port = server.server_address[1] + try: + with caplog.at_level("INFO", logger="contextual_orchestrator.server"): + connection = http.client.HTTPConnection("127.0.0.1", port, timeout=5) + connection.request("PUT", "/healthz") # no do_PUT -- stdlib's own 501 path + response = connection.getresponse() + assert response.status == 501 + response.read() + _wait_for_caplog(caplog, lambda text: "http_request" in text) + finally: + server.shutdown() + thread.join(timeout=5) + server.server_close() + time.sleep(0.2) # see test_per_request_info_summary_reports_method_path_and_status + + assert "http_request" in caplog.text + assert "status=501" in caplog.text + + +def test_malformed_request_line_is_captured_in_log(caplog): + """A malformed request line that still got a real response is not silently skipped. + + ``BaseHTTPRequestHandler.parse_request`` rejects an unparsable request + line via ``send_error`` -- captured by the ``send_response`` override + into ``_last_status`` -- *before* ``self.command``/``self.path`` are + ever assigned: stdlib's own ``parse_request`` explicitly resets + ``self.command`` to ``None`` "in case of error on the first line" and + only reaches the later assignment that would set ``path`` once parsing + succeeds. The per-request summary's old "nothing to report" guard only + checked method/path, so a connection that *did* deliver real bytes and + *did* get a real 400 response left no log trace at all -- indistinguishable, + from the log's perspective, from a keep-alive connection closing with + zero bytes (see ``test_keep_alive_close_does_not_log_phantom_request``, + which must stay silent). + """ + import socket + import threading + import time + + server = build_server(SimpleNamespace(agents=[], candidates=[]), port=0) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + port = server.server_address[1] + try: + with caplog.at_level("INFO", logger="contextual_orchestrator.server"): + with socket.create_connection(("127.0.0.1", port), timeout=5) as connection: + # A single-token request line: too few words for + # parse_request's `2 <= len(words) <= 3` shape check, so it + # calls send_error(400, ...) without ever assigning + # self.command/self.path. A request line this malformed never + # reaches the branch that promotes `self.request_version` + # past stdlib's own "HTTP/0.9" default, so `send_error`'s + # underlying `send_response_only`/`send_header` calls + # deliberately write no status line or headers at all (a + # documented stdlib quirk for an unparsable first line) -- + # only the HTML error body reaches the wire. The 400 is still + # real: it is what `send_response` records into + # `_last_status`, which is what this test is actually about. + connection.sendall(b"GARBAGE\r\n\r\n") + response = b"" + while True: + chunk = connection.recv(4096) + if not chunk: + break + response += chunk + assert b"400" in response + _wait_for_caplog(caplog, lambda text: "http_request" in text) + finally: + server.shutdown() + thread.join(timeout=5) + server.server_close() + time.sleep(0.2) # see test_per_request_info_summary_reports_method_path_and_status + + assert "http_request" in caplog.text + assert "status=400" in caplog.text + + +def test_per_request_info_summary_absent_below_info(caplog): + import threading + import time + import urllib.request + + server = build_server(SimpleNamespace(agents=[], candidates=[]), port=0) + thread = threading.Thread(target=server.serve_forever, daemon=True) + thread.start() + port = server.server_address[1] + try: + with caplog.at_level("WARNING", logger="contextual_orchestrator.server"): + with urllib.request.urlopen(f"http://127.0.0.1:{port}/healthz", timeout=5) as response: + assert response.status == 200 + finally: + server.shutdown() + thread.join(timeout=5) + server.server_close() + time.sleep(0.2) # see test_per_request_info_summary_reports_method_path_and_status + + assert "http_request" not in caplog.text + + def test_provider_calls_use_current_genai_semantic_convention(monkeypatch): """Provider spans expose the required, prompt-free GenAI attributes.""" captured = []