feat(observability): add opt-in verbose/DEBUG routing, failover, and discovery logging

[seonghobae]

Summary

orchestrator/free pool exhaustion has repeatedly surfaced as an opaque final error with no visibility into which candidates were tried, why they were excluded, or which provider actually failed. This PR makes the already-secret-free internal decision evidence in the routing/failover/discovery path visible in live process output, opt-in via --verbose/-v or CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL=DEBUG.

No root logger configuration previously existed anywhere in the repository (no basicConfig, StreamHandler, setLevel, addHandler), so every existing .debug()/.info() call across server.py, telemetry.py, video_jobs.py, and openrouter_uptime.py was silently unreachable. This closes that gap by adding _configure_logging() in __main__.py (env-var and --verbose-driven, idempotent, package-scoped) and new call sites at the actual decision points:

• TaskOrchestrator._append_audit_event now also emits its already-PII-protected event detail through logging at DEBUG (one extra redact_value pass as defense-in-depth).
• TaskOrchestrator._failover_candidates emits a failover_candidates_resolved event with a stage-by-stage exclusion funnel (disabled / ZDR-filtered / non-chat / tag-mismatch / circuit-open-fallback counts) — the exact evidence needed to tell whether a thin orchestrator/free pool is caused by ZDR-only mode, a capability/tag mismatch, an open circuit breaker, or genuinely few ranked candidates.
• TaskOrchestrator._invoke emits candidate_pool_exhausted when every candidate in a role's pool fails, naming the candidates tried and the final error kind.
• The circuit breaker (_circuit_open, _record_failure, _record_success) logs circuit_breaker_opened (WARNING), circuit_breaker_auto_closed (INFO), and circuit_breaker_closed (INFO) on actual state transitions only.
• model_discovery.py's discover_provider_models/discover_all_models log per-provider skip/failure/completion (provider_discovery_skipped, provider_discovery_failed, provider_discovery_completed, discovery_run_completed), and the shared Models.dev retry loop logs each retry/exhaustion/recovery.

This branch was rebased onto current main after PR #941 (codex/all-key-discovery-latency-routing) landed its own independent, simpler --verbose/logging.basicConfig(level=logging.DEBUG) wiring and its own DEBUG-level model_discovery.py log lines in the same functions. The two were reconciled rather than layered: _configure_logging() (env-var precedence, idempotent handler attach, package-scoped) replaces the bare logging.basicConfig calls at both --verbose call sites, and the richer INFO/WARNING-level discovery events (with credential_name, free_count, structured reason codes) replace #941's DEBUG-only duplicates of the same events, since the whole point of this PR is that this evidence needs to be visible by default in a --verbose run, not require chasing DEBUG output to find it.

Explicitly not a fix for orchestrator/free exhaustion itself — this is the observability layer needed to empirically diagnose why it happens, since guessing at (or assuming) the cause — including whether NVIDIA_NIM_API_KEY and NVIDIA_NIM_API_KEY_SUB actually expose identical model catalogs — is exactly what this closes the door on.

Developer experience

• New _configure_logging() in contextual_orchestrator/__main__.py: --verbose/-v on both the main CLI and discover-models subcommand, or CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL=<LEVEL>; explicit flag wins if both are set; idempotent (no duplicate handlers across repeated calls).
• docs/architecture.md documents the event names to watch for and how to enable them.
• docs/library_research.md records the Ponytail decision (stdlib logging, no new dependency; OTel/ADR 0122 stays scoped to per-request span correlation, not this pool-lifecycle evidence).
• CHANGELOG.d/verbose-debug-logging.md fragment added per this repo's convention.

User experience

No behavior change to routing, failover, or discovery outcomes — this is additive, opt-in diagnostic output only. Default (no flag, no env var) behavior is byte-for-byte unchanged.

Test plan

• tests/test_verbose_debug_logging.py (new): audit-event→logging bridge (DEBUG marker, secret redaction via redact_value, no-log-below-threshold), _failover_candidates' exclusion funnel (normal and circuit-open-fallback cases), candidate_pool_exhausted on full failure, circuit-breaker open/close/auto-close log transitions, and model_discovery.py's skip/success/failure/retry/recovery logging.
• tests/test_verbose_logging_cli.py (new): _configure_logging's own contract (noop when unset, env sets level+handler, explicit wins over env, idempotent, invalid level raises ValueError) plus --verbose integration on both CLI paths.
• tests/test_tool_execution_fallback.py: fixed a pre-existing exact-list assertion over list_recent_audit_events() that broke once failover_candidates_resolved (no action key) also appears in the same audit stream — narrowed to filter by event_type instead of loosening the new event.
• tests/test_model_discovery.py: updated one assertion (account=/model_count= → provider=/discovered_count=) to match the reconciled log format from merging with fix(discovery): keep credential catalogs independent #941.
• Full suite: python -m pytest tests -q (2820+ tests; the only unrelated failure is a pre-existing ModuleNotFoundError: No module named 'fast_mlsirm' in tests/test_psychometric_routing.py, an optional native dependency not installed in this sandbox).
• interrogate (project-wide, fail-under = 80 per pyproject.toml): 100% on the changed files.
• git diff --stat origin/main...HEAD scoped to exactly the 10 intended files (branch was rebased from stale, already-squash-merged fix(routing): classify primary provider transport failures explicitly #922 history onto fresh main).

---

Generated by Claude Code

[coderabbitai]

Important

Draft PR not reviewed

Draft PRs are not automatically reviewed by default.

• Trigger a manual review

To automatically review draft PRs, update your CodeRabbit configuration:

reviews:
  auto_review:
    drafts: true

---

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

• X
• Mastodon
• Reddit
• LinkedIn

_{Comment @coderabbitai help to get the list of available commands.}

[seonghobae]

opencode-review failed immediately (39s after the run started) with:

No APPROVED or CHANGES_REQUESTED from opencode-agent on the current head. This required check is not a review and must not succeed until the authenticated dispatch posts a current-head verdict.

This is not caused by this PR's diff. opencode-review-target in .github's central opencode-review.yml is a fail-closed gate by design: it only checks whether opencode-agent has already posted an APPROVED/CHANGES_REQUESTED review on this exact head SHA via repos/{repo}/pulls/{pr}/reviews. The actual review is dispatched separately (opencode-review-dispatch.yml via repository_dispatch, driven by noema-review, which was still in_progress when this check ran seconds after the push). Every fresh push in this org fails this check first and it self-heals once .github's pr_review_merge_scheduler.py (which owns dispatching the review and re-running this job via rerun_actions_job) sees a posted verdict — no fix belongs in this PR for it.

Re-running it now would just fail again identically (no verdict exists yet), so I'm not spending the one re-run on it; I'll keep this PR watched until the scheduler's retry lands a verdict and this goes green on its own.

---

Generated by Claude Code

[seonghobae]

Fixed in 2d7977c: Semgrep (multi-language SAST) failed on a real (if false-positive) finding from this PR's own diff — python-logger-credential-disclosure flagged the new provider_discovery_skipped log line in model_discovery.py because its message mentions credential_name. That field is the KV registry key identifier (e.g. "OPENAI_API_KEY"), never the resolved secret value — api_key itself never reaches this or any other log call in the module, consistent with the repo's KV-not-env and PII-redaction conventions elsewhere in this same diff.

Reproduced the exact finding locally against this PR's head (ab1fd3015158578e822cd0fd43d198bc8b3b1a85) with the same pinned semgrep/semgrep@sha256:2b33f4... ruleset and flags the workflow uses, confirmed it disappears after adding a # nosemgrep: ... suppression with justification (matching this repo's existing suppression style in orchestrator.py/model_discovery.py/openrouter_uptime.py), then re-ran interrogate (100%) and the targeted test files before pushing.

---

Generated by Claude Code

[seonghobae]

Found and ported a fix for a pre-existing main-branch test failure in f68f9690, unrelated to this PR's diff: tests/test_discovery_bootstrap_selection.py::test_bootstrap_selector_treats_nim_primary_and_sub_as_one_outage_domain fails unconditionally on origin/main (verified on a clean checkout with none of this PR's changes present).

Root cause: commit 5224a4c4 (part of #941) deliberately removed nvidia_nim/nvidia_nim_sub provider-family grouping from select_bootstrap_discovered_agents — documented in docs/product-technical-gap-baseline.md and ADR 0032 as a superseded design ("this historical provider-family conclusion is no longer the product contract... each credential account is discovered and judged independently"), because each NIM API key can be entitled to a different model catalog and must not be assumed identical. That commit updated the production code and docs but left this one test still asserting the old, now-superseded grouping behavior, so it's been red on main since #941 merged.

Updated the test (no production code changed) to assert the current, documented, already-shipped independent-account contract: with nvidia_nim and nvidia_nim_sub as the two cheapest candidates and limit=2, both are now selected ([nim_primary, nim_sub]) since there's no more provider-name-based family collapsing — matching every other provider pair in this file.

This is filed here per the CI-red rule (base-branch failure ported into this PR rather than left blocking it), not scope creep on the logging feature — happy to also land it as its own PR against main directly if preferred.

---

Generated by Claude Code

[seonghobae]

Closing as redundant within this three-PR logging cluster (#942/#943/#946, all opened concurrently for the same feature) — keeping three competing full implementations open isn't productive.

main already has a bare --verbose flag (via #941). Of the three, #946 is the most complete/best-scoped: a discrete --log-level {DEBUG,INFO,WARNING,ERROR,CRITICAL} + CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL design (vs. this PR's binary --verbose/-v), a dedicated debug_logging.py module with a handler-level redaction logging.Filter safety net on top of call-site redact_text/redact_value (defense-in-depth this PR doesn't have), WARNING-level default-visible circuit_opened/provider_exhausted events, and ranking-function instrumentation (_static_rank_key/_measured_member_order/_select_agent) that neither this PR nor #942 add.

To be clear about what this PR does that #946 currently doesn't: the _failover_candidates stage-by-stage exclusion funnel (failover_candidates_resolved, with disabled/ZDR/non-chat/tag-mismatch/circuit-open-fallback counts) and the candidate_pool_exhausted event are genuinely useful, not present in #946, and were a good instinct for root-causing a thin/exhausted orchestrator/free pool. Worth re-proposing as a focused follow-up against whichever logging implementation ends up merged, rather than keeping this as a full second implementation.

Per triage, only #946 is staying open across this cluster. Thanks for the root-cause framing (ContextualWisdomLab/.github#1437/#1438) — closing this specific implementation in favor of #946, not the diagnosis behind it.

---

Generated by Claude Code

[seonghobae]

Model taxonomy reminder: the requested grouping axis is model group (model_group) only, not provider family. Any retained or reconciled work in this PR must preserve independent KV credentials and must not introduce provider-family grouping.