feat: add verbose/debug logging for route/conduct/provider control flow - #942
Closed
seonghobae wants to merge 13 commits into
Closed
feat: add verbose/debug logging for route/conduct/provider control flow#942seonghobae wants to merge 13 commits into
seonghobae wants to merge 13 commits into
Conversation
Adds a --verbose/--debug CLI flag (also settable via CONTEXTUAL_ORCHESTRATOR_VERBOSE=true for an already-deployed server) that enables stdlib DEBUG-level logging of the route-vs-conduct decision, each route/conduct step's agent and latency, ModelClient provider request/retry attempts, TaskOrchestrator._invoke's failover classification, and per-agent circuit-breaker open/half-open/closed transitions, plus the HTTP request/response lifecycle in server.py. Off by default with no behavior change; every new log record is bounded and secret-free by construction. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
|
Warning Review limit reachedNext included review available in 18 minutes. View limit detailsLimit details: You’ve used the included review currently available. You've used all free OSS reviews for now. Wait for the free limit to reset to keep reviewing this public repository. Review configuration: ⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Pro Plus Run ID: 📒 Files selected for processing (6)
📝 WalkthroughWalkthroughCLI 플래그와 환경 변수로 제한된 DEBUG 로깅을 활성화합니다. 오케스트레이터, provider 전송, 회로 차단기, HTTP 요청 수명주기에 구조화된 로그를 추가합니다. 민감 정보와 프롬프트·응답 내용은 기록하지 않습니다. ChangesVerbose 디버그 로깅
Estimated code review effort: 3 (Moderate) | ~25 minutes Merge Risk: 🔵 Low · up to The PR adds opt-in DEBUG request lifecycle logging. In verbose mode, malformed request targets could interrupt normal request handling, while unusually long method tokens could inflate logs. These are bounded, localized issues that should receive explicit owner follow-up but do not by themselves require blocking the merge. 🚥 Pre-merge checks | ✅ 4 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (4 passed)
Full details: Docstring CoverageExplanation Docstring coverage is 75.51% which is insufficient. The required threshold is 80.00%. Docstring coverage is scoped to functions touched by this diff. Analyzed 49 functions across 3 files. (4 skipped: 3 unsupported, 1 too large.) ✨ Finishing Touches 💡 2📝 Generate docstrings 💡
🛠️ 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 |
![devin-ai-integration[bot]](https://avatars.githubusercontent.com/in/811515?s=60&v=4){kind=small}
Comment on lines
+114
to
+117
| ## References | ||
|
|
||
| Python Software Foundation. (2026). *logging — Logging facility for Python*. | ||
| https://docs.python.org/3/library/logging.html |
Contributor
There was a problem hiding this comment.
🔍 Research grounding remains absent
This observability feature cites only Python logging documentation. The repository requires relevant papers, or a citation, link, and summary when redistribution is unavailable.
Was this helpful? React with 👍 or 👎 to provide feedback.
Contributor
Author
There was a problem hiding this comment.
Declined, with reasoning. This PR is a stdlib-logging observability/debugging feature (a --verbose flag plus scoped .debug() call sites) — an operational engineering pattern, not a novel algorithm, model, or measured research claim in the sense docs/papers/ and the Fugu/TRINITY/Conductor-derived TDD convention target. The ADR already cites the one directly applicable reference: Python's logging module documentation, since the whole design (in particular the per-logger effective-level inheritance behavior the SEC finding on this same PR turned on) rests on its documented semantics.
Precedent: this repo's most recent engineering/process-only PR, #928 (a CI reliability bugfix to the provider-catalog-sync workflow), got the identical finding and was declined the same way — "not a novel algorithm or research claim... No prior CI-only fix in this repo's history... attaches a paper either" — and that reasoning holds here too.
Happy to add a citation if a maintainer sees a specific applicable one I'm missing. Leaving this thread open (not resolving) to match how the #928 precedent handled the same finding.
Generated by Claude Code
Contributor
Author
|
Propagation update: PR #941 is now merged to main at 42da1d5. This PR branch conflicts with automatic base update, so its implementation must preserve the main contract: every KV credential account is discovered independently; vendor or endpoint identity does not imply model equivalence; only explicit model_group membership shares routing evidence; peak observed RPM and TPM remain measured per account-model route. The protected base already enforces this contract even before this branch resolves its conflicts. |
Resolves the --verbose/logging.basicConfig conflict with #941's "secret-free provider discovery diagnostics" against __main__.py: keeps one --verbose/--debug flag per parser (mine, with the CONTEXTUAL_ORCHESTRATOR_VERBOSE env default and --debug alias) and folds #941's model_discovery.py DEBUG diagnostics into _configure_logging's audited logger scope now that they're verified secret-free (account/error_code/model_count only, never a raw exception or credential). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
…R 0125 Devin's review (PR #942) caught that the "already-deployed server can turn it on without a CLI edit" phrasing could be misread as live/dynamic toggling; the env var is read once at process startup like this file's four existing env-backed CLI defaults and still requires a restart. Makes that explicit everywhere the claim appears (README, CHANGELOG fragment, the --serve --help text), and rewrites ADR 0125's Decision/Excluded sections to describe the corrected _configure_logging design (scoped per-logger DEBUG, not the root logger) plus #941's folded-in model_discovery diagnostics and the server.py streaming-latency fix. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
…nbounded methods Devin's second review round on #942 caught a real availability bug: urllib.parse.urlparse() raises ValueError("Invalid IPv6 URL") on some malformed absolute-form request targets (an unmatched IPv6 bracket) that BaseHTTPRequestHandler.parse_request() accepts without validating -- it only splits the request line on whitespace, never parses the target as a URL. The unguarded urlparse() call inside this PR's new DEBUG log line raised before do_GET/do_POST ever ran, so with --verbose enabled a malformed target dropped the connection with zero HTTP response instead of stdlib's normal 501 -- a debug-only diagnostic silently changing production behavior. New _debug_request_path() never raises: on a parse failure it falls back to stripping everything from the first '?' without parsing, still keeping a leaked query-string secret out of the log line. Also addresses CodeRabbit's follow-up on the same commit: bounds the request-line method token to 32 chars via _debug_request_method() before it reaches a log line (handle_one_request only bounds the whole request line to 65536 bytes, never the method token alone), and completes tests/test_verbose_debug_logging.py's register-credential --verbose coverage (the earlier test only exercised discover-models despite its docstring claiming both). New regression tests: a unit-level parse_request check with a malformed IPv6-bracket target, and a real-socket end-to-end test proving verbose and non-verbose modes return byte-identical HTTP/501 responses for the same malformed request (the old bug returned zero bytes instead, verbose only). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
Contributor
Author
|
Cross-linking: #946 is an independently-built alternative implementation of this same feature (built from a separately supplied, more detailed approved design — I only discovered this PR when pushing to Generated by Claude Code |
Devin's third review round on #942 caught a real gap: stream_route/ ModelClient.stream_chat/_stream_send are a structurally separate path from _dispatch/route_once/_invoke/_send_with_retry, by design (stream_route's own docstring: "no cross-agent failover here -- bytes already sent can't be recalled"), so every non-streaming routing/provider DEBUG log added earlier in this PR stayed silent for a streamed request -- --verbose gave zero visibility into which agent/model/provider served a stream. Mirrors the correct, simpler shape for streaming rather than the retry/ failover-aware non-streaming one, which would misrepresent what streaming actually does: - stream_route: one stream.route_started log (agent selection) and one outcome log (stream.route_completed on success, stream.route_failed with error_type=%s -- never str(exc) -- on a mid-stream failure before re-raising). - ModelClient._stream_send: reuses the exact provider.request event name/ shape _send already emits, so the provider-request boundary is visible for a real (non-mock) stream too, not a new, streaming-only event. server.py's Chat Completions and Responses SSE handlers both call this same TaskOrchestrator.stream_route with no endpoint-specific branching in it, so one set of orchestrator-level tests covers both HTTP surfaces. New tests: selection+completion, mid-stream failure, absence-by-default, and the _stream_send provider.request parity check (present/absent). Also fixes a trailing blank line at EOF in tests/test_verbose_debug_logging.py that Devin's diff-check flagged. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
PR #942's "Full unit and contract suite" check was failing at every push -- not from anything #942 touches, but from a pre-existing stale test on main itself: tests/test_discovery_bootstrap_selection.py:: test_bootstrap_selector_treats_nim_primary_and_sub_as_one_outage_domain still asserted the collapsed-family behavior PR #941 (merged) deliberately removed from select_bootstrap_discovered_agents. #941 updated every test file its own _provider_family grep found; this one was missed because it asserts the collapsed behavior by outcome ([nim_primary, openrouter]), not by referencing _provider_family by name. Independently verified before porting: _provider_family no longer exists anywhere in contextual_orchestrator/model_discovery.py on this branch, and running this exact test against this branch (before this commit) reproduces the failure -- confirming it is a pre-existing gap on main, not caused by this PR's diff, and identical to what was failing on every other open PR merging against current main. Ports the identical fix already reviewed and verified in contextual-orchestrator#947 (branch fix/discovery-bootstrap-selection-stale- test, commit 90c5689) rather than blocking on that PR merging first, per the drive-to-green policy: renames the test to test_bootstrap_selector_keeps_nim_primary_and_sub_independent and corrects the assertion to [nim_primary, nim_sub], plus the matching gap-baseline doc entry. No production code touched. This will no-op once #947 lands on main. tests/test_discovery_bootstrap_selection.py -q: 14 passed (was 13 passed, 1 failed before this commit). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
Contributor
Author
|
Full unit and contract suite red at 7768358, not this PR's fault, fixed in 42e06f5. Cause: A fix already existed and was reviewed in #947 ( Generated by Claude Code |
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
Brings in #945's already-merged, authoritative fix for the stale test_bootstrap_selector_treats_nim_primary_and_sub_as_one_outage_domain (main @ bffbc72, merged via 0adca47) instead of keeping this branch's own port of the equivalent #947 fix, which #945 beat to main and #947 was then closed as superseded. Conflict in tests/test_discovery_bootstrap_selection.py resolved by taking main's version of that one test function entirely (git checkout --theirs) rather than reconciling two different renames of the same fix. Added a short "Update" note to this branch's earlier docs/product-technical-gap-baseline.md entry recording that #945 landed first; no other file conflicted. tests/test_discovery_bootstrap_selection.py -q: 14 passed. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
Contributor
Author
|
Correction/update to the comment above. After posting that, #945 (a different concurrent PR fixing the identical stale test) merged into Rather than keep my own ported copy alongside Generated by Claude Code |
Devin's fourth review round on #942 caught a real availability bug: _configure_logging called logging.basicConfig(format=_VERBOSE_LOG_FORMAT, force=True). Per stdlib docs, force=True "removes and closes" every existing root handler before installing basicConfig's own. Reproduced directly: a custom root handler installed before the call is gone (and closed) from root.handlers afterward. So a process that had already configured its own log delivery -- a hosted structured/JSON logging handler, a log shipper, a test harness's own capture handler -- had that delivery path silently destroyed and replaced with a plain stderr handler the instant --verbose was turned on. Fix: drop force=True entirely. _configure_logging now only installs a default stderr handler via plain logging.basicConfig(format=...) (no force) when the root logger has no handler at all -- matching basicConfig's own documented no-op-if-handlers-exist semantics exactly, so this can only ever add a handler, never remove one. When a handler already exists (of any kind), it is left completely untouched; only the three audited leaf loggers' levels are raised, which was always the actually load-bearing part of verbose mode. New regression test test_configure_logging_never_discards_an_existing_root_handler: preconfigures a custom root handler (tracking both .close() calls and emitted records), enables verbose mode, and asserts the handler is still attached, was never closed, and still receives a DEBUG record from an audited logger. Verified it fails against the pre-fix code and passes against the fix. Existing test_configure_logging_enables_debug_with_bounded_format renamed/ adjusted to test_configure_logging_installs_a_bounded_format_handler_on_a_bare_root, explicitly clearing root.handlers first to exercise the bare-root branch, since under pytest itself root already has handlers by default (so the old version was, without realizing it, also exercising the force=True removal path rather than a true "no handler yet" case). test_verbose_mode_keeps_openrouter_uptime_failures_silent had been passing only because the old force=True bug also happened to strip pytest's own caplog handler off root, making everything look silent for the wrong reason. Fixed to test the real, production-accurate invariant: no caplog.at_level("DEBUG") wrapper (that call itself elevates ROOT's level, an artificial condition production code never creates -- root's level is never touched by this file's design), relying only on _configure_logging(True) itself, which is what a real --verbose run does. tests/test_verbose_debug_logging.py -q: 34 passed. Full suite: 2851 passed, 1 skipped, 1 pre-existing unrelated failure (fast_mlsirm ModuleNotFoundError in this sandbox, confirmed identical on main). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
seonghobae
pushed a commit
that referenced
this pull request
Aug 31, 2026
…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
Devin's fifth review round on #942 caught a real follow-up to the previous force=True fix: once _configure_logging correctly stopped touching root's handlers, a *pre-existing* root handler with its own threshold above DEBUG (very plausible for anything hosting this process with its own logging setup -- e.g. a hosted structured/JSON handler at INFO) filters independently of the logger-level check. A DEBUG record from an audited leaf logger would propagate to that handler and be silently dropped there, so verbose mode would produce zero output in that real deployment scenario, with no error at all. Reproduced directly: a custom root handler at INFO never receives a DEBUG record from contextual_orchestrator.orchestrator even though the logger itself is correctly raised to DEBUG -- because Handler.handle() filters on the handler's own level, independent of any logger's effective level. Fix: _configure_logging now attaches one bounded-format StreamHandler directly to each of the three audited leaf loggers (never to root). A handler attached straight to the logger itself is evaluated on its own merits (a fresh Handler's level defaults to NOTSET -- accepts everything down to DEBUG) independent of any ancestor's handler, so this guarantees verbose output is actually delivered without ever touching, replacing, or being gated by whatever the host process already configured on root. Propagation to root is left untouched (never propagate = False): these loggers' pre-existing WARNING/ERROR call sites must keep reaching whatever the host already listens to on root, exactly as before this feature existed. Guarded by a handler name (contextual_orchestrator.verbose) so a second call in the same process (a test invoking main() more than once) replaces its own earlier handler instead of stacking duplicates, matching the "decided exactly once at startup, but replaceable" intent the earlier force=True was (wrongly) trying to serve. This also removes the now-unneeded "install a default handler on root when none exists" branch from the previous round's fix -- attaching directly to each leaf logger already covers the bare-process case, and keeping both would double-emit through root's default handler once basicConfig ever installed one. Existing test renamed from test_configure_logging_installs_a_bounded_format _handler_on_a_bare_root to test_configure_logging_attaches_a_bounded_format _handler_to_each_leaf_logger to match: it now asserts root is completely untouched (handlers list unchanged) and each of the three leaf loggers has its own formatted handler, rather than asserting a handler landed on root. New regression test test_configure_logging_still_emits_through_a_stricter_ existing_root_handler: preconfigures a root handler at INFO, enables verbose mode, and asserts (a) the dedicated per-logger handler actually receives the DEBUG record, (b) the hosted INFO handler correctly still filters it on its own terms, and (c) the hosted handler remains attached and was never closed. Verified this and the renamed test both fail against the previous commit's code and pass against this fix -- including catching a real bug in an earlier draft of this test that patched logging.StreamHandler globally and, without noticing, also intercepted pytest's own internal handler construction, masking the regression it was meant to catch. tests/test_verbose_debug_logging.py -q: 35 passed. Full suite: 2852 passed, 1 skipped[or none once discovery fix landed], plus the two known unrelated environment gaps in this sandbox (fast_mlsirm ModuleNotFoundError, and an unpinned local `mcp` package missing the `Client` attribute test_pinned_mcp_client_renders_and_closes_camoufox_tab expects) -- neither touched by this diff, and GitHub's own "Full unit and contract suite" check already passed cleanly for the previous head, confirming these are sandbox- only gaps that do not reproduce in the properly-provisioned CI environment. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
This comment was marked as resolved.
This comment was marked as resolved.
Sorry, something went wrong.
…vers Devin's sixth review round on #942 caught the mirror-image case to round 5's fix: now that the dedicated per-logger handler guarantees DEBUG delivery regardless of a STRICT host handler's threshold, a host whose own root (or ancestor) handler is already PERMISSIVE (no level set, or set at/below DEBUG -- extremely common, since a bare logging.Handler() and StreamHandler() both default to NOTSET) sees every matching record twice: once via propagation to that handler, once via the new dedicated one. Reproduced directly: a permissive root handler (default NOTSET level) received a probe record via propagation exactly as before, AND the new dedicated per-logger handler also emitted it -- a visible duplicate line for anything reaching root through a host-configured handler that was already permissive enough to show it. Fix: new _logger_already_delivers_debug(logger) walks from the logger itself up through .parent (stopping at the first ancestor with propagate=False, mirroring stdlib Logger.callHandlers's own walk) and returns True as soon as any handler along the way has a level at or below DEBUG. _configure_logging now only attaches its own dedicated handler when this returns False -- i.e. only when nothing already in the propagation chain would deliver the record, which is exactly round 5's two real cases (no handler anywhere, or a handler only at INFO/WARNING/ERROR). This is deliberately best-effort (a handler can carry its own Filters this can't introspect), matching the requested scope: a level-based check covers the realistic cases without over-engineering a full filter simulation. New regression test test_configure_logging_skips_its_own_handler_when_a_permissive_host_handler_exists: preconfigures a permissive (NOTSET) root handler, enables verbose mode, and asserts no dedicated handler gets attached and the record is delivered exactly once (via propagation), not twice. Verified this fails against the previous commit's code (dedicated handler attaches unconditionally, i.e. would duplicate) and passes against this fix. Both existing round-5 tests needed root.handlers.clear() added: pytest's own logging-capture machinery attaches root handlers at level NOTSET regardless of what a test sets up, which _logger_already_delivers_debug correctly (but unhelpfully for isolating a specific test scenario) treats as "already permissive." Verified both still pass unchanged against the previous commit's code (no regression in what they cover), and still pass against this fix once isolated from pytest's own handlers. tests/test_verbose_debug_logging.py -q: 37 passed. Full suite: 2853 passed, plus the two known unrelated environment gaps in this sandbox (fast_mlsirm ModuleNotFoundError, an unpinned local mcp package missing the Client attribute) -- neither touched by this diff, and GitHub's own "Full unit and contract suite" check already passed cleanly for the previous head, confirming these are sandbox-only gaps. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
Devin's seventh review round on PR #942: the dedicated handler round 5 attaches directly to a leaf logger (for the strict-host-handler case) is a plain StreamHandler() with no level filter, so it accepts every level from DEBUG upward, not DEBUG alone. A WARNING/ERROR record already reaches the host's own handler via propagation; once the dedicated handler is also attached, that same record reaches it too, doubling every real server failure's log line. Add _ExactLevelFilter, applied to the dedicated handler, so it only ever emits records at exactly the level verbose mode enables (DEBUG) -- a handler's own setLevel is a floor, not a ceiling, so this needed a Filter, not a level change. WARNING/ERROR keep reaching the host by the normal propagation path only, exactly as before this feature existed. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
Comment on lines
+188
to
+206
| if not verbose: | ||
| return | ||
| formatter = logging.Formatter(_VERBOSE_LOG_FORMAT) | ||
| for logger_name in _VERBOSE_LOGGER_NAMES: | ||
| logger = logging.getLogger(logger_name) | ||
| logger.setLevel(logging.DEBUG) | ||
| previous = next( | ||
| (h for h in logger.handlers if getattr(h, "name", None) == _VERBOSE_HANDLER_NAME), | ||
| None, | ||
| ) | ||
| if previous is not None: | ||
| logger.removeHandler(previous) | ||
| if _logger_already_delivers_debug(logger): | ||
| continue | ||
| handler = logging.StreamHandler() | ||
| handler.name = _VERBOSE_HANDLER_NAME | ||
| handler.setFormatter(formatter) | ||
| handler.addFilter(_ExactLevelFilter(logging.DEBUG)) | ||
| logger.addHandler(handler) |
Contributor
There was a problem hiding this comment.
📝 Info: Host logging remains intact
_configure_logging preserves host handlers and adds a leaf handler only when propagation cannot deliver DEBUG. Its exact-level filter prevents duplicate warnings.
Was this helpful? React with 👍 or 👎 to provide feedback.
Contributor
Author
|
Closing as redundant within this three-PR logging cluster (#942/#943/#946, all opened concurrently for the same feature).
Per triage, only one of the three is staying open — #946, as the most complete and best-scoped of the three. Closing this one rather than merging a competing, overlapping logging surface. Thanks for the work here; the Generated by Claude Code |
7 tasks
seonghobae
added a commit
that referenced
this pull request
Sep 1, 2026
* feat(logging): add --log-level/--verbose CLI wiring and debug_logging 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). * feat(logging): instrument retry/circuit-breaker/ranking/discovery/server 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. * fix(logging): close adversarial secret-leakage findings from PR #946 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 * fix(logging): address second-round Devin/CodeRabbit findings on PR #946 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 * docs+test: update ADR/CHANGELOG for the second-round fixes; de-flake 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 * fix(logging): address third-round Devin findings on PR #946 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 * fix(logging): distinguish no-retry-budget from permanent rejection (round 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 * fix(discovery): close credential leak via cross-host redirect (round 5) 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 * fix(test): patch _open_trusted_discovery_request in merged Bytez/OpenRouter tests PR #948/#949 (main) added three tests that mocked urllib.request.urlopen directly. This branch's round-5 credential-leak fix already moved _fetch_json's transport call behind _open_trusted_discovery_request (a custom redirect-protected opener), so after merging origin/main the old urlopen patch no longer intercepted the call and these tests hit the real network (observed: a live 401 from api.bytez.com). Repoint the three tests at _open_trusted_discovery_request, matching every other test in this file post-refactor. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KPmJErfkcHer4UVEgrQxUX * fix(discovery,logging): bound _fetch_json's read; stop misclassifying 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 * fix(logging,server): suppress CodeQL FP, fix disconnect status honesty, 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 * fix(server): preserve delivered status on a post-header disconnect (round 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 * fix(cli): give check-fast-mlsirm its own argparse parser (round 9) 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 * fix(logging): keep runtime config out of environment * test(logging): avoid clear-text credential fixtures * fix(logging): distinguish ranking evidence from throughput --------- Co-authored-by: Claude <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
Adds a
--verbose/--debugCLI flag (also settable viaCONTEXTUAL_ORCHESTRATOR_VERBOSE=trueso an already-deployed server can turn it on without a CLI edit) that enables stdlibloggingDEBUG-level visibility into the orchestrator's control flow. Off by default with zero behavior change — every new call site is a plain.debug()that stays silent unless DEBUG is enabled. See ADR 0125 for the full design record and what is deliberately excluded.New DEBUG log call sites (bounded metadata only — never a prompt, a model answer, an API key, an
Authorizationheader, or a raw exception message):contextual_orchestrator/orchestrator.pyTaskOrchestrator._dispatch— the route-vs-conduct decision.TaskOrchestrator.route_once/.conduct— each attempt/step (role, agent id, access-list scope, served agent, latency, failover flag).TaskOrchestrator._invoke— per-candidate attempt, failure classification (ToolFailureDecision.kind/.action/.reason_code), retry-to-failover downgrade, success.TaskOrchestrator._record_failure/_circuit_open/_record_success— circuit-breaker opened / half-open / closed transitions.ModelClient._send_with_retry/_send— provider attempt, retry/backoff decision (exception class name only, neverstr(exc)), request (agent/model/provider/host, never headers).contextual_orchestrator/server.pyHandler.parse_request/.log_request— request-received and response-sent (method, path capped at 256 chars with query stripped, status, latency). Reuses the two stdlib hooksBaseHTTPRequestHandleralready calls on every request, so no new call sites indo_GET/do_POST. The existinglog_messagesuppression ("keep service output structured") is untouched.contextual_orchestrator/__main__.py--verbose/--debugon the main--serveparser and, for consistency, theregister-credentialanddiscover-modelssubcommand parsers._configure_logging()callslogging.basicConfig(level=logging.DEBUG, format=..., force=True)only when requested — a no-op otherwise.CONTEXTUAL_ORCHESTRATOR_VERBOSEenv var (truthy:1/true/yes/on), matching this file's existingCONTEXTUAL_ORCHESTRATOR_STATE_DB/_AGENTS_DB/_CLEARFOLIO_URL/_PROVIDER_CA_BUNDLEpattern.No new dependency —
loggingis already imported by this package (telemetry.py,server.py,video_jobs.py,openrouter_uptime.pyalready have module-level_LOGGERs and existing.debug()/.warning()call sites); Ponytail research is recorded in the ADR rather thandocs/library_research.mdsince no new library decision was made.Test plan
tests/test_verbose_debug_logging.py(21 tests): CLI flag/env-var enablement (with root-logger save/restore so nothing leaks into other tests), the route-vs-conduct decision log, route/conduct step logs,_invokecandidate/failure/success logs, circuit-breaker opened/half-open/closed logs, provider request/retry/attempt-exhausted logs, and the HTTP request/response lifecycle logs — each paired with a "same operation, nocaplog.at_level" test proving DEBUG output is absent by default, and a dedicated assertion in every content-bearing test that a fed-through fake secret and the raw prompt/response text never reachcaplog.text.python3 -m pytest tests/test_verbose_debug_logging.py -q→ 21 passed.test_telemetry.py,test_paper_contracts.py,test_orchestrator_dispatch_boundaries.py,test_cli_auth.py,test_discover_models_cli.py,test_tool_execution_fallback.py,test_passthrough_provider_failover.py,test_provider_bootstrap.py,test_conventions.py,test_self_check.py,test_api_contract.py,test_generated_workflow.py,test_model_judge.py,test_routing_eval.py,test_provider_usage_capture.py,test_model_group.py,test_security_hardening.py,test_auto_discovery_server.py,test_cost_review_server.py,test_cost_router*.py,test_orchestrated_responses_stream.py,test_orchestrator_client_boundaries.py,test_provider_*.py,test_workflow_run_object_authorization.py,test_planning_adr_identifiers.py) → all passing on top of this branch.python3 -m interrogate contextual_orchestrator/__main__.py contextual_orchestrator/orchestrator.py contextual_orchestrator/server.py→ 100% on the changed files; the repo-wideinterrogaterun reports the same pre-existing 97.9% (missing docstrings infuzz/*.pyone_input/mainharness entry points) onorigin/mainwith this branch's diff stashed out, confirming it is not a regression from this change.origin/mainbefore this branch's edits:python -m pytest tests -q→ 2802 passed, 1 skipped, 1 pre-existing failure (test_psychometric_routing.py—fast_mlsirmrequires Python ≥3.12; this sandbox runs 3.11.15) unrelated to this change.Note for reviewers
Repository-wide
interrogateand the fullpytest tests -qrun both report one pre-existing, environment-caused gap each (see above) that exist identically onorigin/mainwithout this branch's changes — verified withgit stashbefore writing this PR. Neither is touched or caused by this diff.Co-Authored-By: Claude Sonnet 5 noreply@anthropic.com
https://claude.ai/code/session_015Gs7KmNvH75nxz1sL8mKjw
Summary by CodeRabbit
새 기능
--verbose또는--debug옵션으로 상세 디버그 로깅을 활성화할 수 있습니다.CONTEXTUAL_ORCHESTRATOR_VERBOSE=true환경 변수로도 활성화할 수 있습니다.문서