feat(logging): add CLI debug logging with redaction safety net - #946
Conversation
… module New stdlib-only contextual_orchestrator/debug_logging.py owns level parsing, configure_logging() (basicConfig with force=True so repeated in-process CLI invocations actually re-apply), a handler-level redaction safety net, and small pure log-formatting helpers. __main__.py wires --log-level/--verbose/ --debug and CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL through a parse_known_args pre-scan that runs before subcommand dispatch, covering register-credential, discover-models, check-fast-mlsirm, one-shot completion, and --serve uniformly. orchestrator.py gains a module logger for the next commit's retry/circuit-breaker/ranking instrumentation. Part of the verbose/debug logging feature (see forthcoming ADR).
Adds DEBUG/WARNING/INFO instrumentation at the previously silent decision points named in the task: ModelClient._send_with_retry / _send_raw_with_retry (per-attempt, backoff, a WARNING provider_exhausted line that fires without --verbose), TaskOrchestrator's circuit breaker (_record_failure/_record_success/_circuit_open, with a WARNING circuit_opened only on the edge transition), and evidence-based ranking (_static_rank_key/_measured_member_order/_select_agent). Every call site that logs caller- or provider-derived content wraps it in the existing orchestrator.redact_text/redact_value first. model_discovery.py gains per-provider discovery_attempt/discovery_result/ discovery_provider_failed DEBUG lines (credential *names*, never values) and one discovery_complete INFO summary in discover_all_models. server.py gains one body-free per-request INFO summary (method, path, status, latency, ADR 0122 session correlation hash) via handle_one_request and a DEBUG response-body summary that reuses the exact already-redacted safe_payload object _response_payload computes, never a second copy. telemetry.py exposes the shared session_id_hash() helper so both _safe_attributes (OTLP) and server.py's summary use the identical hash. Adds ADR 0007 (docs/adr/ series, matching the runtime-observability precedent set by ADR 0122), the missing logging + OpenTelemetry rows in docs/library_research.md, a CHANGELOG entry, and a light tech-stack.md touch-up.
📝 WalkthroughWalkthroughADR 0007에 따라 표준 라이브러리 기반 디버그 로깅을 추가했습니다. CLI와 환경 변수로 로그 수준을 설정합니다. 재시도, 모델 탐색, 에이전트 선택, 회로 차단기, HTTP 요청을 계측합니다. 민감한 로그 값은 비식별화하거나 허용 목록 메타데이터로 제한합니다. Changes로깅 및 관측성
Estimated code review effort: 4 (Complex) | ~45 minutes Merge Risk: 🟠 High · up to The PR adds retries to authenticated provider discovery while still allowing redirects to another host, which can expose provider credentials and repeat that exposure; DEBUG response telemetry also retains unbounded model and usage-key metadata. This creates a high-impact security and data-exposure risk, so the PR is not merge-ready until redirect handling is constrained and logged metadata is bounded. Sequence Diagram(s)sequenceDiagram
participant CLI
participant Main
participant Logging
participant Orchestrator
participant ModelDiscovery
participant Server
participant Logger
CLI->>Main: 로그 옵션과 서브커맨드 전달
Main->>Logging: 로그 수준 파싱 및 구성
Main->>Orchestrator: provider 호출 실행
Orchestrator->>Logger: 재시도 및 선택 이벤트 기록
Main->>ModelDiscovery: 모델 탐색 실행
ModelDiscovery->>Logger: 탐색 시도 및 결과 기록
Main->>Server: HTTP 요청 처리
Server->>Logger: 상태, 지연 시간, 세션 해시 기록
🚥 Pre-merge checks | ✅ 4 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (4 passed)
Full details: Docstring CoverageExplanation Docstring coverage is 48.65% which is insufficient. The required threshold is 80.00%. Docstring coverage is scoped to functions touched by this diff. Analyzed 148 functions across 10 files. (3 skipped: 2 unsupported, 1 too large.)
✨ Finishing Touches 💡 3📝 Generate docstrings 💡
⚔️ Resolve merge conflicts 💡
🛠️ Fix failing CI checks 💡
🧪 Generate unit tests (beta)
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. Comment |
|
Ran an independent adversarial secret-leakage review of this PR (whose only mandate was: can any code path here cause a credential to appear in log output, under any configuration?). Verdict: FAIL. Confirmed, reproduced against the actual PR code: This is the same gap Devin's review flagged independently ("Debug logs expose response bodies"). Secondary, also real:
On the #942 comparison: #942's design explicitly never logs response body content at all (method/path/status/latency only, no payload summary), so it structurally isn't exposed to this exact vulnerability class — worth weighing in the reconciliation decision, though it also can't answer the response-content debugging questions that motivated this feature. Dispatching a fix now for the confirmed leak (generic key-name-aware redaction, not just value-pattern matching), the query-string leak, and the CLI ordering bug, since the response-body diagnostic capability is valuable and worth fixing rather than dropping. Generated by Claude Code |
Resolves a conflict in contextual_orchestrator/model_discovery.py where this branch's new discovery instrumentation (isEnabledFor DEBUG guards, discovery_attempt/discovery_result/discovery_provider_failed structured logs, elapsed_ms timing) collided with main's independently-landed privacy-hardened logging on the same call sites (account= terminology, never logging the credential_name label). Reconciled by keeping this branch's richer instrumentation but adopting main's stricter contract: the discovery debug logs now never include source.credential_name (only the provider/account name), matching the already-merged test_discovery_debug_log_identifies_account_without_secret on main. Updated this branch's own new tests in tests/test_model_discovery.py to match (account= field naming, no credential_name assertion).
…review Fixes the three confirmed findings from the adversarial secret-leakage review (github.com//pull/946#issuecomment-5473342909), independently corroborated by Devin's automated review comments on the PR: 1. Critical: server.py's DEBUG response-summary log reused redact_value(), which only pattern-matches an in-string secret *value* shape and never inspects the JSON *key* a string is nested under, so a response field like {"private_key": "..."}, {"key": "..."}, {"auth": "..."}, or {"credential": "..."} leaked verbatim. Adds a new, additional, key-name-aware redaction pass, debug_logging.redact_credential_shaped_keys, applied on top of the existing redact_value output at that one call site. orchestrator.redact_text/redact_value are unmodified, per the review's explicit scope. 2. The INFO per-request summary (summarize_request_for_log) logged self.path verbatim, including any query string, contradicting its own body-free docstring. It now strips the query string before formatting. 3. A --log-level/--verbose/--debug flag placed before a subcommand (e.g. `--verbose discover-models`) bypassed subcommand dispatch, which only checked arguments[0]. Adds _subcommand_token_index to skip past recognized leading logging flags when locating the subcommand token, without removing them from the argument list each subcommand's own parser sees. Each fix has a red/green regression test: the new tests reproduce the leak/bug against the pre-fix code (verified failing) before the fix makes them pass. Also merges main into this branch (was reported dirty/mergeable_state) and resolves a real conflict in model_discovery.py where this branch's new discovery instrumentation collided with main's independently-landed, privacy-hardened logging on the same call sites; reconciled by keeping the richer instrumentation but adopting main's stricter contract (never log source.credential_name, use account= naming), matching main's own test_discovery_debug_log_identifies_account_without_secret. Separately, the merge surfaced a non-conflicting but real regression: main independently added a second, plain --verbose flag to the discover-models and one-shot/ serve parsers that collided with this branch's --add_log_level_arguments, raising argparse.ArgumentError on every invocation of either path; removed the redundant declarations (and their dead, non-redacted logging.basicConfig follow-ups) now that _configure_logging_from_cli already covers this centrally. PR #942 (a separate, more conservative implementation of the same feature on a different branch) still needs reconciliation by a human/reviewing session -- out of scope here. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
main advanced again (PR #923 merged: a bounded retry for a provider's transient model-list fetch, plus an is_transient_error TLS/DNS fix), producing a second real conflict in model_discovery.py's discover_provider_models on the exact same fetch/except block this branch instruments. Resolved by keeping main's retry loop (attempt_timeouts/last_exc/ is_transient_error) fully intact and layering this branch's DEBUG discovery_provider_failed logging (error_code/error_type/redacted message) on top of it, now firing once after the retry loop exhausts its attempts (using the final last_exc) rather than on the old single-attempt except. Also dropped a duplicate `_LOGGER = logging.getLogger(__name__)` line the two independent additions produced side by side without a textual conflict.
Fixes three further confirmed real findings from the re-review after the first push, plus verifies (and closes with a regression test rather than a code change) a fourth finding that turned out to be a false positive: 1. BUG (Devin, server.py): keep-alive phantom requests. On a persistent HTTP connection, handle_one_request never reset self.command/self.path before each call; stdlib's own handle_one_request only assigns them when it actually parses a request line, so when a keep-alive client closed the connection (nothing read), the *previous* request's command/path were still in place. _log_request_summary's existing "nothing to report" guard therefore never fired, logging the prior request a second time with a statusless "phantom" entry. Fixed by resetting self.command/self.path to None at the top of handle_one_request, alongside the existing per-request state resets, so the guard correctly recognizes when no new request was parsed. 2. BUG (Devin, orchestrator.py): permanent failures misreported as exhausted retries. _send_with_retry/_send_raw_with_retry unconditionally logged provider_exhausted whenever any failure occurred, even when a non-transient error on the very first attempt broke the loop immediately without spending any retry budget. Added a distinctly named provider_rejected_permanent WARNING event, chosen by whether the loop broke from reaching retry_limit (provider_exhausted) or from an early non-transient break (provider_rejected_permanent), applied identically in both duplicated retry loops. 3. Security/Privacy (CodeRabbit, CWE-532, server.py): the DEBUG response-body summary serialized the entire redacted payload, including ordinary response text (choices[].message.content, tool-call arguments, an error.message that can reflect caller-supplied input) -- none of which is credential-shaped, so neither redact_value nor redact_credential_shaped_keys ever masked it, and it could carry PII or business-sensitive content straight into DEBUG output. Added debug_logging.response_metadata_for_log, which extracts only an allowlisted metadata shape (has_error, model, choice_count, and numeric-only usage counts) for this log line to serialize instead of the payload; redact_credential_shaped_keys is still applied on top, defense-in-depth, in case a future allowlist field ever collides with a credential-shaped key name. Updated the two pre-existing tests whose assertions depended on the old "redact-then-log-the-payload" mechanism to match the new (strictly stronger) "never log the payload" contract. 4. Verified, NOT fixed (Devin, __main__.py, false positive): "the parse_known_args logging pre-scan doesn't respect -- as an option terminator." Directly tested against the real _configure_logging_from_cli pre-scan: a literal -- already correctly stops it from treating what follows as --log-level/--verbose/--debug, since parse_known_args honors stdlib argparse's -- semantics with no special-casing needed here. Documented this in the function's docstring and added a regression test locking in the already-correct behavior, rather than changing working code. Each of the three real fixes has a red/green regression test (verified failing against the pre-fix code, per this repo's TDD convention). Also added deterministic, non-threaded unit tests for the query-string-stripping and keep-alive fixes as reliable counterparts to their real-server integration tests, which can occasionally flake on unrelated ThreadingHTTPServer teardown timing (pre-existing in this test file, not introduced by this change -- reproduces identically on an untouched, pre-existing test in the same file). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
…real-server tests Documents the response-body allowlist redesign, keep-alive phantom-request fix, provider_rejected_permanent split, and the confirmed-false-positive -- option-terminator check in docs/adr/0007-verbose-debug-logging.md and CHANGELOG.md's Unreleased/Added entry. Also de-flakes the four real-ThreadingHTTPServer tests in tests/test_telemetry.py that assert on the per-request INFO summary (present pre-existing in this file, not introduced by this PR -- it reproduced identically on an untouched test during verification). Root cause: the per-request summary logs in handle_one_request's `finally` block, which runs strictly after the response has already been flushed to the client, so a test asserting immediately after its client call returns has no guarantee the server thread reached that `finally` block yet. Fixed with a small bounded caplog-polling helper (_wait_for_caplog) used while the relevant caplog.at_level scope is still open, rather than a fixed sleep that would be either too short (still flaky) or wastefully long; kept a brief post-teardown settle too, since ThreadingHTTPServer's per-connection handler threads are daemons server_close() does not wait for, and a lingering straggler could otherwise log into a later test's capture window. Verified stable across 15 repeated runs (10 solo, 5 with the rest of this PR's touched test files) with zero failures, versus roughly 1-in-3 to 1-in-5 before. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
|
Fixed every confirmed finding from the adversarial review and the follow-up re-review, in two pushes ( Round 1 — the original adversarial review1. Critical — credential leak in DEBUG response-body logging.
2. INFO-level query-string leak. The per-request summary logged
3. CLI argument-order bug. A
Merge conflict #1 — main had moved to
|
Fixes four further confirmed real findings from the second re-review (after push cd57aa1), which also independently confirmed the keep-alive fix and the -- option-terminator false-positive verdict from round 2: 1. BUG, orchestrator.py: zero-retry failures mislabeled as exhausted. With max_retries=0, attempt >= retry_limit is trivially true after the single allowed attempt regardless of whether it was transient, so provider_exhausted fired even though no retry budget ever existed to exhaust. Both _send_with_retry and _send_raw_with_retry now also require retry_limit > 0 before calling provider_exhausted; provider_rejected_permanent covers both the pre-existing "non-transient break" case and this "no retry budget configured at all" case. 2. BUG, server.py: framework-generated responses lost their status in the per-request log. _last_status was only set by this module's own _send/_send_text/_send_bytes/_send_sse writers; a response BaseHTTPRequestHandler generates itself (e.g. its built-in 501 for an HTTP method with no matching do_* handler) bypasses all of those, logging status=- for a response the client actually received. Fixed by overriding send_response -- stdlib's own single choke point every response path (including its own send_error) already goes through -- so every current and future response path is captured uniformly. 3. BUG, __main__.py: abbreviated logging flags (--log-l, --ver) bypassed subcommand dispatch the same way full un-recognized flags used to, since argparse's own prefix-abbreviation matching and _subcommand_token_index's plain string comparison disagreed about what counts as a recognized flag. Set allow_abbrev=False on every CLI parser (the pre-scan and each subcommand's own parser), so an abbreviated flag is now rejected everywhere with a clear argparse error instead of silently accepted by one parser and not the other. 4. SEC, debug_logging.py: exception tracebacks bypassed log redaction. _RedactingLogFilter only rewrote record.msg; logging.Formatter.format() renders record.exc_info into the traceback text strictly after every filter has already run, so a call site using exc_info=True or logger.exception(...) could leak a secret embedded in the exception's own str() (e.g. an upstream error reflecting api_key=sk-...) straight into the unredacted traceback -- a real hole in the core safety-net mechanism itself, not just a call site. The filter now renders exc_info into text, redacts it, caches it as record.exc_text, and clears exc_info so the handler's formatter uses the already-redacted text instead of re-deriving an unredacted one. Each fix has a red/green regression test (verified failing against the pre-fix code): tests/test_orchestrator_debug_logging.py (two new zero-retry tests, one per retry loop), tests/test_telemetry.py (test_framework_generated_error_status_is_captured_in_log), tests/test_cli_logging.py (abbreviated value-flag and boolean-flag cases), tests/test_debug_logging.py (test_configure_logging_redactor_masks_exception_traceback_in_captured_output). Full suite (python -m pytest tests -q --ignore=tests/test_psychometric_routing.py) -> 2886 passed, 1 skipped, zero regressions. interrogate -> 100%. test_conventions.py -> all pass. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
|
Round 3 — fixed all four findings from Devin's re-review of 1. BUG — zero-retry failures mislabeled as exhausted (
2. BUG — framework-generated responses lost their status (
3. BUG — abbreviated logging flags bypassed subcommand dispatch (
4. SEC (prioritized first, per your note) — exception tracebacks bypassed log redaction (
(I also considered Verification
If your next pass surfaces only further diminishing or cosmetic nits rather than another real correctness or security gap, I'll report those in a final comment rather than continue iterating — three rounds of substantive findings is a reasonable point to start converging. #942 still needs human reconciliation; not merging this myself. Generated by Claude Code |
…ound 4) Fixes a real regression from the round-3 provider_exhausted/ provider_rejected_permanent split, found by Devin's re-review of 68291d4: with a configured retry limit of 0, EVERY failure -- including a genuinely transient one (HTTP 503, timeout) that simply never got a chance to retry -- was collapsed into provider_rejected_permanent. "No retry budget was configured" and "this error is non-retryable by nature" are two independent facts; conflating them mislabels a transient failure as permanent. Adds a third, distinctly named WARNING event, provider_no_retry_budget, for the retry_limit == 0 case specifically, carrying the error's own transient/non-transient classification explicitly via a `transient=%s` field rather than discarding it. provider_rejected_permanent now covers only its original, narrower case: a real non-zero budget existed, but the loop broke early because the failure was classified non-transient. provider_exhausted is unchanged (a real, non-zero budget was actually used up). Fixed identically in both duplicated retry loops (_send_with_retry/_send_raw_with_retry). Regression tests now cover all 4 (retries>0 vs =0) x (transient vs non-transient) combinations per retry loop, as requested: the two existing tests already covered retries>0 x transient (provider_exhausted) and retries>0 x non-transient (provider_rejected_permanent); this adds retries=0 x transient and retries=0 x non-transient (both now provider_no_retry_budget, differing only in transient=True/False) for both _send_with_retry and _send_raw_with_retry. Verified each new/changed assertion fails against the pre-fix (round-3) code before the fix, per this repo's TDD convention. Investigated, not fixed: Devin also flagged CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL reading directly from os.environ as bypassing this repo's KV config registry (AGENTS.md/CLAUDE.md: "runtime config... never os.getenv"). Per the coordinator's request, checked whether this repo's existing CONTEXTUAL_ORCHESTRATOR_STATE_DB/_AGENTS_DB/_CLEARFOLIO_URL/ _PROVIDER_CA_BUNDLE env vars (contextual_orchestrator/__main__.py) follow the same direct-os.environ pattern: they do, all four, predating this PR. This is a pre-existing architectural pattern in this file, not a new or different violation this PR introduces -- reported as such in the PR comment rather than fixed unilaterally inside a logging-feature PR, per the coordinator's explicit guidance for that outcome. Full suite (python -m pytest tests -q --ignore=tests/test_psychometric_routing.py) -> 2888 passed, 1 skipped, zero regressions. interrogate -> 100%. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
|
Round 4 — fixed the one real regression and investigated the second finding, in 1. BUG — transient failures mislabeled permanent under a zero retry budget (
2. Investigated, not fixed — Verification
As discussed, three-plus rounds of substantive, independently-confirmed findings is a reasonable convergence point. If your next pass turns up only cosmetic or diminishing nits rather than another real correctness or security gap, I'll report those directly in a follow-up comment instead of continuing to iterate. #942 still needs human reconciliation; not merging this myself. Generated by Claude Code |
|
Model taxonomy reminder: the requested grouping axis is model group ( |
|
Acknowledging Devin's round-5 findings — both are "analysis" kind, not "bug", and both are minor enough that I'm not spinning up another fix round after four substantive ones:
Not blocking merge review from my side. Generated by Claude Code |
|
Generated by Claude Code |
Real, pre-existing security finding from CodeRabbit's automated review of PR #946: `_fetch_json` in model_discovery.py -- the function every standard provider's authenticated "list models" call goes through (openai, openrouter, nvidia_nim, nvidia_nim_sub, bytez) -- called plain `urllib.request.urlopen`. Python's 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 exfiltrate the credential -- and #923's retry (already on main, inherited into this branch) means up to twice per attempt, since it calls _fetch_json with the same api_key on both tries. This codebase already had the correct fix for this exact risk class: _TrustedDiscoveryRedirectHandler (raises on any redirect leaving the original host) already protected _fetch_json_same_host_https. It just never got applied to _fetch_json, the function actually used for the real per-provider calls. Fixed by routing both functions through one new shared _open_trusted_discovery_request helper, so there is a single implementation of the redirect guard instead of two copies that could drift apart (as they already had). _fetch_json_same_host_https's own external behavior (size cap, TimeoutError conversion) is unchanged. A legitimate same-host redirect (e.g. /v1/models -> /v2/models) still succeeds. New regression tests (tests/test_model_discovery.py): a cross-host-redirect test (mirrors the existing test_openrouter_zdr_evidence_rejects_cross_host_ redirects pattern) proving exactly one request is ever issued and the credential never reaches the attacker host, verified failing against the pre-fix _fetch_json before the fix; and a same-host negative control proving the legitimate case still works. ~38 pre-existing tests across test_model_discovery.py, test_model_discovery_boundaries.py, test_discover_models_cli.py, and test_chat_model_capability_isolation.py that mocked bare urllib.request.urlopen for _fetch_json's behavior now mock the new shared seam instead (mechanical -- _fetch_json no longer calls urlopen directly). Two local test _Response fixtures gained an optional read(amt) argument (mirroring http.client.HTTPResponse.read(amt)) since _fetch_json_same_host_https's always-invoked OpenRouter ZDR fetch inside discover_all_models now shares the same seam and caps its read. Also folded into this round, four further confirmed findings relayed by the coordinator from the same review pass: 1. model_discovery.py: the configured_gateway provider's /model/info metadata fetch now also catches RuntimeError, matching the primary list-request retry loop's except tuple. Previously a raw RuntimeError from ModelClient's DNS/address-validation transport escaped discover_provider_models uncaught and aborted the entire discovery pass instead of just that one provider's metadata. 2. server.py: per-request latency_ms no longer counts a keep-alive connection's idle time between requests. request_started is now timestamped inside an overridden parse_request(), right after BaseHTTPRequestHandler.handle_one_request()'s blocking readline() has already returned real request bytes, instead of before that blocking read. 3. orchestrator.py: the retry-outcome classification (no budget at all / exhausted / stopped early on non-transient) duplicated verbatim between _send_with_retry and _send_raw_with_retry -- duplication that already caused a real regression once, fixed in one copy and missed in the other (round 4, provider_no_retry_budget) -- is now one shared _log_retry_outcome helper both call. 4. debug_logging.py: 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), not any string key with a numeric value -- closes a path where a key shaped like "customer_note=<secret>" with a throwaway numeric value would have reached DEBUG output verbatim (CWE-532). New regression test with a customer_note-shaped key proving exclusion, plus a positive control. Full suite (python -m pytest tests -q --ignore=tests/test_psychometric_routing.py) -> 2892 passed, 1 skipped, zero regressions (test_psychometric_routing.py pre-existingly fails on ModuleNotFoundError: No module named 'numpy' in this sandbox -- environment-only, unrelated). interrogate (repo-root invocation, pyproject.toml fail-under=100) -> 100%. ruff check on all changed files -> clean. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
Security fix: credential leak via cross-host redirect, doubled by the retry (round 5)CodeRabbit's automated review flagged this at the PR level: "The PR adds retries to authenticated provider discovery while still allowing redirects to another host, which can expose provider credentials and repeat that exposure." Verified independently against the actual code — it's real. The vulnerability
Made worse by #923's retry (already on Notably, this codebase's own developers had already identified and fixed this exact risk class once — The fix
Also fixed while in this file: the Also folded into this round (CodeRabbit, same head)
Verification
Commit: 5cb7946 Not merging — leaving this for review per the standing process. Generated by Claude Code |
…gging-log-level-cli # Conflicts: # contextual_orchestrator/model_discovery.py
… one-shot calls (round 6) Two findings deferred during round 5 to avoid colliding with the in-flight merge-conflict fix: - model_discovery.py: _fetch_json read a discovery response body with an unbounded response.read(), unlike _fetch_json_same_host_https and _fetch_configured_gateway_json, which already cap at MAX_DISCOVERY_RESPONSE_BYTES and fail closed on an overage. A large or malicious/misbehaving provider response could exhaust worker memory before JSON parsing ever ran. _fetch_json now shares the identical bounded-read-then-check pattern. - orchestrator.py: _log_retry_outcome logged provider_no_retry_budget whenever retry_limit was 0, without distinguishing an agent with a genuinely zero configured retry budget from ModelClient.proxy_send_once's deliberate allow_transient_retries=False one-shot call (which forces retry_limit to 0 regardless of the agent's real budget, so an already-failing-over passthrough request cannot itself amplify load). _log_retry_outcome now takes allow_transient_retries explicitly and logs a distinctly named provider_one_shot_call_failed WARNING for the caller-forced case instead of misreporting it as no budget configured. New regression tests cover both: an oversized fake response for the size bound, and a mocked proxy_send_once one-shot failure (plus direct _send_raw_with_retry coverage) for the logging fix. Full suite: 2929 passed, 1 skipped (baseline 2925 + 4 new tests, zero regressions). interrogate: 100%. git diff --check: clean. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
Round 6: the two findings deferred out of round 5 (unbounded discovery read + one-shot retry-logging conflation)Round 5's fix ( Finding 1: unbounded memory read in
|
…y, renumber ADR (round 7) Three findings from the latest automated review round on PR #946: - tests/test_debug_logging.py: two CodeQL py/clear-text-logging-sensitive-data HIGH alerts (lines 144, 167) are a deliberate redaction positive/negative control pair -- a hardcoded, non-functional fake secret is logged once WITH a redactor (proving it's masked) and once WITHOUT one (the negative control, proving the first test isn't a tautology). Verified this repo's CodeQL is advanced setup (github/codeql-action/init+analyze, no config-file) with security-events: write and default upload:true, and that `# codeql[rule-id]` inline suppression comments on the line before a flagged call are GitHub's documented, currently-supported mechanism, honored regardless of setup style once the analysis flows through upload-sarif. Added precise, two-line suppressions with an explanatory comment on exactly the two flagged lines. - contextual_orchestrator/server.py: `_send`/`_send_text`/`_send_bytes`/ `_send_sse`/`_begin_sse` all recorded their *intended* status into `_last_status` before handing off to `_write_response`, then ignored its boolean return value. `_write_response` deliberately swallows a dead peer's BrokenPipeError/ConnectionError/OSError, but the pre-set `_last_status` survived that failure untouched, so the per-request INFO summary reported a false "delivered" status for a write that never completed. Fixed at the one shared choke point (`_write_response`'s except block) instead of patching each writer, so it covers every current and future writer uniformly. While tracing that consumer, also found `_log_request_summary`'s "nothing to report" guard checked only method/path, so it silently dropped a request that *did* deliver bytes and *did* get a real 400/414 response but whose malformed/oversized request line left command/path unset (stdlib's own parse_request resets `self.command` to None "in case of error on the first line"). The guard now also logs when a status was actually recorded, while still skipping a true byte-free keep-alive close. Regression tests: test_http_response_write_disconnect_safety.py (dead-peer write no longer reports the intended status) and test_telemetry.py (a malformed request line's real 400 is no longer skipped). - docs/adr/0007-verbose-debug-logging.md renamed to 0005 -- the indexed series in docs/adr/README.md ends at 0004, and ADR 0122 (checked separately) is a deliberate cross-repo-numbered exception explicitly not listed in that series table, not evidence the sequential convention was already broken. Updated the file's own title, the README index row, conductor/tech-stack.md, and CHANGELOG.md's remaining "ADR 0007" mentions. Also replied on PR #946 to two review threads that investigation showed were false positives, with no code change: the CLI log-level env-var read (a bootstrap-time argparse pre-scan before any KV store exists, matching five other pre-existing bootstrap-time os.environ reads in the same file) and the "research artifact" ADR requirement (this is a pure observability/engineering feature with no algorithmic claim to ground, unlike ADR 0002/0003). Full suite: `pytest tests -q --ignore=tests/test_psychometric_routing.py` -> 2931 passed, 1 skipped, 0 failed. `interrogate .` -> 100%. `git diff --check` clean. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
Round 7: CodeQL alerts, disconnect-status honesty bug, ADR renumberingNew head: 1. Two CodeQL
|
…ound 8)
Follow-up to round 7's _write_response fix, per this round's Devin review:
- contextual_orchestrator/server.py: clearing `_last_status` on *every*
caught disconnect (BrokenPipeError/ConnectionError/OSError) was too broad.
A write failure can strike in two different places: 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 in the same call, or a later `_write_sse` frame on an SSE 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 -- the exact overcorrection direction of the
original bug).
Every `_send`/`_send_text`/`_send_bytes`/`_send_sse`/`_begin_sse` writer
now sets `self._response_headers_sent = True` immediately after its own
`end_headers()` call returns without raising; `handle_one_request` resets
that marker to `False` once per request. `_write_response`'s disconnect
handler now clears `_last_status` only when the marker is still unset.
`_write_sse` does not touch the marker itself -- it is only ever called
after a prior successful `_begin_sse`, so the marker it already set
correctly covers a later frame's failure too.
Regression tests added to tests/test_http_response_write_disconnect_safety.py:
- test_disconnected_write_does_not_report_intended_status_as_delivered
(rewritten to fail inside end_headers() itself -- genuinely "before
headers" -- so it still represents the original bug's case correctly;
it previously failed in the body write, which is now the preserved case)
- test_disconnected_body_write_after_headers_preserves_delivered_status
(new: body write fails after end_headers() succeeds -> status preserved)
- test_sse_frame_disconnect_after_headers_preserves_delivered_status
(new: a later _write_sse frame fails after _begin_sse succeeded ->
status preserved)
Also investigated a second finding relayed this round ("transient failures
labeled permanent" in _send_with_retry/_send_raw_with_retry) and found no
reproducible bug: GitHub's own review data for this commit's parent shows
Devin's re-review found exactly one new issue (the fix above), and an
existing, currently-passing test
(test_send_raw_with_retry_one_shot_call_does_not_log_no_retry_budget)
already proves a transient error under allow_transient_retries=False with a
real non-zero configured retry budget logs
`provider_one_shot_call_failed ... transient=True`, never
`provider_rejected_permanent` -- structurally, `_log_retry_outcome` can only
reach `_log_provider_rejected_permanent` when `retry_limit != 0`, which
`allow_transient_retries=False` always forces to 0. No code change made for
that finding; likely a stale reference to the already-resolved round-5/6
thread on the same topic.
Full suite: `pytest tests -q --ignore=tests/test_psychometric_routing.py` ->
2933 passed, 1 skipped, 0 failed. `interrogate .` -> 100%. `git diff --check`
clean.
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
Round 8: fix the round-7 disconnect-status overcorrectionNew head: 1. Fixed: "Partial responses lose delivered status"Round 7's Fix: every Three regression tests in
2. Investigated: "Transient failures labeled permanent"No code change — could not reproduce, and found solid evidence it doesn't currently occur:
This matches an already-resolved round-5/6 review thread on the same event names ( Verification
Generated by Claude Code |
Devin's review of PR #946 found: `check-fast-mlsirm --help` bypassed argument parsing and ran the diagnostic instead of showing help. The subcommand's dispatch function took no arguments and ignored everything after its own name in argv, so `--help` never reached an argparse parser that would have handled it -- it was silently swallowed and the real diagnostic ran anyway (and its exit code, not argparse's, decided the process exit status). Give _check_fast_mlsirm_command its own argparse.ArgumentParser, matching the pattern every other subcommand (register-credential, discover-models) already uses: declare the shared --log-level/--verbose/--debug flags via _add_log_level_arguments so --help documents them, call parse_args(argv) so --help exits before running anything and an unrecognized trailing option is rejected instead of silently ignored, then run the diagnostic as before. Updated the one call site to pass arguments_after_subcommand. Regression tests: test_check_fast_mlsirm_help_shows_help_without_running_diagnostic and test_check_fast_mlsirm_rejects_unknown_option. Full suite: 2935 passed, 1 skipped (baseline 2933 + 2 new tests, zero regressions). interrogate: 100%. git diff --check: clean. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
seonghobae
left a comment
There was a problem hiding this comment.
Fixed in b888a634: check-fast-mlsirm now gets its own argparse parser (declaring the shared --log-level/--verbose/--debug flags, matching register-credential/discover-models), so --help shows help and exits instead of silently running the diagnostic, and an unrecognized trailing option is rejected instead of being ignored. Two new regression tests cover both cases. Full suite 2935 passed (baseline 2933 + 2 new), 100% interrogate, clean diff.
Separately: the CodeQL "2 high" alerts on tests/test_debug_logging.py remain open despite the inline # codeql[rule-id] suppression comments — I verified via the CodeQL analysis job logs and GitHub's own documentation that an inline suppression comment only tags the finding in the uploaded SARIF's suppressions[] field; actually dismissing the alert requires a separate step (the advanced-security/dismiss-alerts Action) reading that tag and calling the dismissal API, which this repo's security.yml doesn't have wired up. Given this PR is already at round 9, I'm treating this as a known, understood, narrowly-scoped false positive (a deliberate secret-redaction positive/negative-control test pair, not a real vulnerability) rather than widening this PR further to add that CI infrastructure — bypass-merge is appropriate for this specific residual failure once everything else is green, per this org's standing policy for well-understood CI-gate false positives.
Generated by Claude Code
seonghobae
left a comment
There was a problem hiding this comment.
noema-review failed again on this head with TimeoutError: timed out on the live orchestrator/free gateway chat/completions call (120s budget, scripts/ci/noema_review_gate.py:656) — not this PR's issue; nothing in this diff touches the review sidecar or gateway. This is the third occurrence of the identical failure across three different heads on this PR alone (b9407999, 8df97670, 26b5ee34), so it's reading as a systemic reliability gap rather than a one-off flake: preflight only finds 2-3 of 12 probed routes "ready" each time (the rest reject with 429/404/TimeoutError), and even a route verified ready at preflight is timing out under the real, larger review-sized payload. Not re-running to "confirm a flake" here since the pattern is already established as recurring, not isolated. Filing this as a dedicated root-cause investigation (matching this cycle's own standing goal of making Noema/OpenCode/Strix review through orchestrator/free actually reliable) rather than a fix scoped to this PR.
Generated by Claude Code
|
Update on the recurring This should stop the recurring timeout once Generated by Claude Code |
|
I'm not driving this PR's full review queue to resolution in this session: it explicitly overlaps with Generated by Claude Code |
|
Checked the CodeQL "2 high" alert at
If these are in fact the 2 flagged alerts, the fix consistent with this file's own convention is a scoped suppression comment on those specific Generated by Claude Code |
|
Verified CodeRabbit's "Merge Risk: High" summary against the current head ( "Retries to authenticated provider discovery while still allowing redirects to another host, which can expose provider credentials": "DEBUG response telemetry also retains unbounded model and usage-key metadata": Both protections were TDD'd with an explicit adversarial re-check (see the PR description's "Secret-non-leakage evidence" section) — I re-read the code just now rather than relying on that description alone. Not spending more effort chasing CodeRabbit's docstring-coverage warning (48.65%/80%): that's CodeRabbit's own heuristic scoped to functions touched by this diff, distinct from the repository's actual gate ( No merge conflict either: Generated by Claude Code |
|
Cross-PR integration contract: routing identity is provider-neutral |
| if _LOGGER.isEnabledFor(logging.DEBUG): | ||
| for member_id in member_ids: | ||
| _LOGGER.debug( | ||
| "rank_candidate agent_id=%s judged_quality=%s evidence_score=%.3f", |
There was a problem hiding this comment.
There was a problem hiding this comment.
Noema LLM review
The PR #946 implements a comprehensive debug logging system with a redaction safety net. It addresses critical security and correctness issues identified in prior review rounds, including credential leaks via cross-host redirects in model discovery, unbounded memory reads (CWE-400), and sensitive data exposure in logs (CWE-532). The implementation of _RedactingLogFilter correctly handles exception tracebacks, and the CLI argument parsing has been hardened to prevent subcommand bypass via abbreviated flags. All identified regressions from prior threads have been resolved with verified fixes in the provided diff.
Reviewed changed lines
contextual_orchestrator/__main__.py:103 (RIGHT): Correctly disables argparse abbreviations to ensure consistency between the pre-scan and subcommand locator.contextual_orchestrator/debug_logging.py:148 (RIGHT): The filter correctly renders and redacts exception text before clearing exc_info, preventing secrets in tracebacks from leaking.contextual_orchestrator/model_discovery.py:318 (RIGHT): Implements bounded read (MAX_DISCOVERY_RESPONSE_BYTES + 1) to prevent memory exhaustion from malicious provider responses.contextual_orchestrator/model_discovery.py:320 (RIGHT): Correctly raises ValueError if the response body exceeds the defined cap.contextual_orchestrator/model_discovery.py:443 (RIGHT): Uses _open_trusted_discovery_request to prevent Authorization header leakage during cross-host redirects.
Adversarial validation
contextual_orchestrator/model_discovery.py:318 (RIGHT)falsified: A provider returning a 100MB response could cause an Out-Of-Memory (OOM) crash. — The code now calls response.read(MAX_DISCOVERY_RESPONSE_BYTES + 1) and checks the length immediately after.contextual_orchestrator/debug_logging.py:148 (RIGHT)falsified: Secrets embedded in an exception's message (e.g., via a 401 response body) would bypass the message filter via the traceback. — The _RedactingLogFilter now explicitly formats the exception, redacts the resulting text, and caches it in record.exc_text while clearing record.exc_info.- Residual risk: Low. Redaction is a safety net; primary redaction still relies on call-site discipline, but the handler-level filter provides strong defense-in-depth.
Findings
-
No blocking findings.
-
Result: APPROVE
-
Head SHA:
4b402cdae00289abce52b68ee33942fd4ba69ae5 -
Reviewer credential:
noema-review-github-app -
Actor:
cwl-noema-review[bot]
Current contract correction: logging configuration is CLI-only (
--log-level,--verbose,--debug).CONTEXTUAL_ORCHESTRATOR_LOG_LEVELis deliberately ignored; historical env-var wording below is superseded by the KV-not-env runtime policy and the current source/ADR.Note for reviewers: overlaps with open PR #942
#942 ("feat: add verbose/debug logging for route/conduct/provider control
flow") already exists on
feat/verbose-debug-loggingfrom this sameaccount, opened concurrently with this work. I discovered it only when
git pushto that branch name was rejected as non-fast-forward — this PRwas built independently, from a separately supplied, more detailed approved
design, without awareness of #942 until the push collision. Please treat
these as two independent proposals for the same feature and pick one (or
merge the best parts of each) rather than merging both:
--log-level {DEBUG,INFO,WARNING,ERROR,CRITICAL}(explicit level)--verbose/--debugonly (binary DEBUG on/off)CONTEXTUAL_ORCHESTRATOR_LOG_LEVEL(a level name)CONTEXTUAL_ORCHESTRATOR_VERBOSE(a boolean)_ranked_agents/_static_rank_key/_measured_member_order/_select_agent,model_discovery.pyper-provider attempts,server.pyper-request + response-body summary_dispatch,route_once/.conduct,_invoke, circuit breaker,_send_with_retry,server.pyrequest/response viaparse_request/log_requesthooksredact_text/redact_valuecall-site redaction plus a handler-levellogging.Filtersafety netstr(exc)(more conservative, less diagnostic detail)docs/adr/0007-verbose-debug-logging.md(matches the runtime-observability precedent set by ADR 0122 in that series)docs/planning/adrs/0125-verbose-debug-logging.mdBoth implementations are independently tested and pass their own full
regression suites; I have not attempted to reconcile or merge the two here.
Summary
Adds verbose/debug logging per an approved design: a
debug_logging.pyleaf module (stdlib
loggingonly, no new dependency — see the Ponytailentries added to
docs/library_research.md), CLI/env wiring, and newDEBUG/INFO/WARNING instrumentation at previously-silent decision points.
Full design record: ADR 0007.
Flag / env var (
contextual_orchestrator/__main__.py):--log-level {DEBUG,INFO,WARNING,ERROR,CRITICAL}(case-insensitive) plus a--verbose/--debugshorthand forDEBUG, andCONTEXTUAL_ORCHESTRATOR_LOG_LEVEL.Precedence:
--log-level>--verbose/--debug> env var > defaultWARNING(unchanged default — no behavior change for anyone not opting in). Resolved
once via a
parse_known_argspre-scan before subcommand dispatch, soregister-credential,discover-models,check-fast-mlsirm, one-shotcompletion, and
--serveare all covered from one call site. An invalidlevel (from either the flag or the env var) fails closed with an
argparse-style
SystemExit(2), never silently ignored.What gets logged, and at what level:
--verboseneeded — these are new, everythingelse in this list is opt-in):
circuit_opened agent_id=... failures=... threshold=... reset_seconds=...— only on the edge transition into the open state, not every failure.
provider_exhausted agent_id=... model=... attempts=... final_error_type=...— a provider call that used its full retry budget.
--log-level INFO):discovery_complete providers=%d models=%d errors=%d(model discoveryaggregate).
server.py: method, path, status,latency, and the existing ADR 0122 session-correlation hash (never the
raw session id) — reuses a new shared
telemetry.session_id_hash()helper so the OTLP span attribute and this log line hash identically.
--log-level DEBUG/--verbose/--debug):ModelClient._send_with_retry/_send_raw_with_retry):provider_attempt,provider_attempt_failed(redacted, truncated errormessage),
provider_backoff.circuit_failure(every increment),circuit_reset,circuit_cleared(only when there was real state to clear).TaskOrchestrator._static_rank_key/_measured_member_order/_select_agent):rank_partition,rank_candidate(agent id/model/priority/capability fit/affinity, or judged-quality/success-rps),
select_agent(final chosen agent). Agent id/model are loggedunredacted, matching the existing precedent that they already flow into
raised exception metadata today; raw prompt/answer text is never
logged, only lengths/counts where relevant —
redact_textdeliberatelydoes not scrub PII, so this design never logs message content at all
rather than leaning on it for a job it does not do.
model_discovery.py:discovery_attempt/discovery_resultperprovider,
discovery_provider_failed(redacted, truncated) — thecredential name (e.g.
OPENAI_API_KEY) is logged, never its value.server.py: one response-body summary that reuses the exactalready-redacted
safe_payloadobject_response_payloadcomputes viaredact_value— never a second, separately (or un-)redacted copy.Redaction — two layers, both required: every new call site that logs
caller- or provider-derived content wraps it in the existing, unmodified
orchestrator.redact_text/redact_valuefirst (e.g.redact_text(str(exc))[:500]in the retry loop).debug_logging.configure_logging(level, redactor=redact_text)then attaches a
logging.Filterto the handlerlogging.basicConfiginstalls — deliberately the handler, not the Logger object, since a
Logger-level filter is skipped while a record propagates up from a child
logger — as a safety net for a call site that forgets.
configure_logginguses
logging.basicConfig(..., force=True)because plainbasicConfigis ano-op after the first call in a process, which would otherwise make a
second in-process CLI invocation silently keep whatever level the first
call configured (a real risk given this repo's own test convention of
calling
main()more than once per interpreter).Secret-non-leakage evidence (the critical property)
Per-surface, TDD (test written and confirmed red before the redaction
existed), plus an explicit adversarial re-check after: I monkeypatched each
implementation to skip its redaction step and reran the corresponding test
to confirm it fails (catches the leak) before trusting it:
tests/test_debug_logging.py::test_configure_logging_redactor_masks_secret_shaped_content_in_captured_output— the handler-level filter, end to end via real stdlib
loggingoutputcapture. A paired
..._redactor_none_still_leakstest is the negativecontrol proving the assertion is real, not a tautology.
tests/test_orchestrator_debug_logging.py::test_send_with_retry_debug_logs_redact_secret_shaped_error_message— a mocked provider raising an exception whose message embeds a fake
api_key=sk-FAKE...shape, captured through the real retry-loop DEBUG log.tests/test_model_discovery.py::test_discover_provider_models_debug_logs_failure_error_type_and_redacts_message— same shape, through the discovery-failure DEBUG log; a sibling test
confirms only the credential name appears, never a registered fake
credential value.
tests/test_telemetry.py::test_response_payload_debug_log_reuses_redacted_payload_never_raw_secret— confirms the response-summary log reuses the response path's own
redaction rather than a second, separate copy.
Verification
python -m pytest tests -q --ignore=tests/test_psychometric_routing.py(that one file needs
fast_mlsirm, which requires Python ≥3.12; thissandbox runs 3.11) → 2846 passed, 1 skipped, run twice (once as a
pre-change baseline at 2836 passed, confirming exactly the 10 new tests
added and zero regressions).
python -m interrogate contextual_orchestrator/→ 100% (repo gate isfail-under = 100, not the 80% this repo's ownCLAUDE.mdcurrentlymisstates).
debug_logging.py(the one new module not inpyproject.toml's coverageomit list) → 100% branch coverage, including the
redactor=Nonebranch.
loggingonly. Added themissing
loggingandOpenTelemetryrows todocs/library_research.md's Selected Stack table (OTel was already aruntime dependency since ADR 0122 but had never gotten a row).
CHANGELOG.mdUnreleased/Added entry; lightconductor/tech-stack.mdtouch-up noting the OTel/jsonschema runtime deps that were already true
but undocumented there.
Files
contextual_orchestrator/debug_logging.py(new)contextual_orchestrator/__main__.py,orchestrator.py,model_discovery.py,server.py,telemetry.pytests/test_debug_logging.py,test_cli_logging.py,test_orchestrator_debug_logging.py(new);test_model_discovery.py,test_telemetry.py(extended)docs/adr/0007-verbose-debug-logging.md(new),docs/adr/README.md,docs/library_research.md,CHANGELOG.md,conductor/tech-stack.mdNot merging this myself — flagging for independent adversarial review next,
including reconciling with #942 above.
Co-Authored-By: Claude Sonnet 5 noreply@anthropic.com
Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX
Generated by Claude Code
Summary by CodeRabbit
새로운 기능
버그 수정
보안 및 개인정보 보호
문서