feat(logging): add CLI debug logging with redaction safety net

CHANGELOG.md

@@ -42,9 +42,103 @@ 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=<secret>"` with a throwaway
+  numeric value would otherwise have sailed through the old numeric-only
+  filter and reached DEBUG output verbatim (CWE-532).
 
 ### Added
 
+- Verbose/debug logging (ADR 0007): a new stdlib-only `debug_logging.py`
+  module, a `--log-level {DEBUG,INFO,WARNING,ERROR,CRITICAL}` CLI flag with a
+  `--verbose`/`--debug` shorthand and a `CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL`
+  env-var default (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

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 0007) remain Python standard-library based.
 
 Production target dependencies after this lab hardens:
 

contextual_orchestrator/__main__.py

@@ -12,6 +12,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 +35,7 @@
     ModelClient,
     TaskOrchestrator,
     load_agents,
+    redact_text,
 )
 from .privacy_policy_analysis import (
     analyze_discovered_privacy_policies,
@@ -44,6 +46,145 @@
 DEFAULT_ADMIN_CREDENTIAL_NAME = "CONTEXTUAL_ORCHESTRATOR_ADMIN_TOKEN"
 DEFAULT_INFERENCE_CREDENTIAL_NAME = "CONTEXTUAL_ORCHESTRATOR_INFERENCE_TOKEN"
 
+#: Bootstrap-transport env var read once at process start to default the
+#: effective log level (see docs/planning/adrs, ADR "verbose debug logging").
+#: Never read again at request time -- this is a CLI/process-start knob, not
+#: runtime config sourced from the KV.
+LOG_LEVEL_ENVIRONMENT_VARIABLE = "CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL"
+
+
+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 and " + LOG_LEVEL_ENVIRONMENT_VARIABLE + "; 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`` >
+    ``CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL`` > default ``WARNING``.
+
+    Raises:
+        SystemExit: With status 2 and an argparse-style message on stderr, if
+            an explicit ``--log-level`` or the env var 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:
+        raw_env = os.environ.get(LOG_LEVEL_ENVIRONMENT_VARIABLE, "").strip()
+        try:
+            effective_level = _log_level(raw_env) if raw_env else "WARNING"
+        except argparse.ArgumentTypeError as exc:
+            pre_scan.error(str(exc))
+            return  # pragma: no cover - pre_scan.error() always raises SystemExit
+    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."""
@@ -185,8 +326,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 +410,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 +444,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 +622,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":
+    if subcommand == "check-fast-mlsirm":
         _check_fast_mlsirm_command()
         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 +741,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,