fix(proxy): let HEADROOM_LOG_LEVEL=debug turn on Headroom's own debug logs

[chopratejas]

Description

You couldn't turn on Headroom's own debug logs in a running proxy. HEADROOM_LOG_LEVEL set only uvicorn's level. _setup_file_logging pinned the headroom logger and the proxy.log handler to INFO, so no headroom.* DEBUG line was ever emitted. Meanwhile docs/content/docs/metrics.mdx:320 tells operators to run HEADROOM_LOG_LEVEL=debug headroom proxy to diagnose problems.

Now debug and trace lower both the headroom logger and the proxy.log handler to DEBUG. Every other value keeps INFO. The default, warning, only quiets uvicorn, so Headroom's INFO events (PERF lines and the like) are still written as before.

Debug lines stay in the owner-only file. Some Headroom debug lines carry request-derived data, such as error messages that quote a request. With HEADROOM_DEBUG_DUMP=full, they also include the tool output the router compresses. Those lines had never been reachable before. Without a guard they would also propagate to the root handlers, meaning stdout, container logs and wrap's stdio capture. A filter on the root handlers drops headroom.* records below INFO, so debug reaches only proxy.log (mode 0600), and stdout shows exactly what it showed before. Turning debug on logs one startup WARNING that names the file and says what it now records. A same-port re-setup also lowers the reused handler's level, so switching from info to debug takes effect.

Refs #4136

Type of Change

• Bug fix (non-breaking change that fixes an issue)
• New feature (non-breaking change that adds functionality)
• Breaking change (fix or feature that would cause existing functionality to change)
• Documentation update
• Performance improvement
• Code refactoring (no functional changes)

Changes Made

• headroom/proxy/helpers.py: _headroom_log_level() (DEBUG for debug/trace, otherwise INFO) sets the headroom logger and the proxy.log handler, including a reused handler. When debug is on, the _HeadroomDebugStaysInProxyLog filter goes on the root handlers, plus one startup warning.

• tests/test_perf_per_port_logs.py: three regression tests. (1) Parametrized: debug lines and the startup warning reach proxy.log only for debug/TRACE. (2) A headroom.* debug line reaches proxy.log but not a root stdout handler, while INFO and third-party warnings still do. (3) Same-port re-setup from info to debug. All four checks fail on the previous commit.

• headroom/transforms/content_router.py: _log_router_debug, which dumps the tool output being routed, now also needs the explicit content opt-in HEADROOM_DEBUG_DUMP=full. HEADROOM_LOG_LEVEL=debug alone no longer writes that content. The startup warning says so.

Testing

• Unit tests pass (pytest)
• Linting passes (ruff check .)
• Type checking passes (mypy headroom)
• New tests added for new functionality
• Manual testing performed

Test Output

$ pytest -q tests/test_perf_per_port_logs.py -k log_level        # on origin/main code
FAILED ...[debug-True]  FAILED ...[TRACE-True]   2 failed, 3 passed
$ pytest -q tests/test_perf_per_port_logs.py tests/test_cache_breakpoint_diagnostics.py tests/test_pr208_changes.py tests/test_direct_chat_ccr_resolution.py <every test mentioning HEADROOM_LOG_LEVEL>
125 passed, 1 skipped
$ pytest -q tests/test_perf_per_port_logs.py   # 18 passed; on the previous commit: 4 failed
$ pytest -q <40 test files that use caplog on headroom loggers>   # 956 passed, 1 skipped
$ ruff check / ruff format --check / mypy headroom/proxy/helpers.py
All checks passed! / 2 files already formatted / Success: no issues found in 1 source file

Real Behavior Proof

• Environment: macOS, Python 3.12. This branch runs as a real headroom proxy on a random port with a temp HOME and workspace, offline, against a local fake Anthropic/OpenAI upstream (the shared smoke harness).
• Exact command / steps: HEADROOM_LOG_LEVEL=debug smoke.sh <worktree>: one POST /v1/messages and one POST /v1/chat/completions, each with a 400-row tool result. Then compared the proxy's stdout with proxy-<port>.log.
• Observed result (head 2f43785, HEADROOM_LOG_LEVEL=debug): every run returns HTTP 200 for both requests with 13574 tokens saved (99.82%), and proxy.log is mode 600.
  • Without HEADROOM_DEBUG_DUMP: proxy.log has 19 Headroom DEBUG lines and 0 lines with the tool-output marker item-399.
  • With HEADROOM_DEBUG_DUMP=full: 25 DEBUG lines and 6 marker lines.
  • stdout has 0 DEBUG lines and 0 marker lines in both runs.
  • The startup warning appears in both. With HEADROOM_LOG_LEVEL unset, proxy.log has no DEBUG lines and no warning.
• Not tested: Windows (owner-only perms there follow the existing fileperms path), and multi-worker mode.

Runtime Rollout Safety

• Rollout-managed feature(s): None.
• Minimum rollout channel: N/A; logging only.
• Stable/default behavior changed: No. The default and every non-debug value keep today's INFO level; only debug/trace change, and they were documented to do this.
• Kill switch / disable path: Unset HEADROOM_LOG_LEVEL, or set it to anything other than debug/trace.
• Unsafe override required: No.
• Qualification impact: None.
• Rollback path: Revert this commit.

Review Readiness

• I have performed a self-review
• This PR is ready for human review

Checklist

• My code follows the project's style guidelines
• I have performed a self-review of my code
• I have commented my code, particularly in hard-to-understand areas
• I have made corresponding changes to the documentation
• My changes generate no new warnings
• I have added tests that prove my fix is effective or that my feature works
• New and existing unit tests pass locally with my changes
• I did not edit CHANGELOG.md — it is generated by release-please from my Conventional Commit PR title (a CI guard enforces this)

Screenshots (if applicable)

N/A

Additional Notes

Depends on #4138 (shared headroom.log_safety helpers). Its files show in this diff until it merges.

Part of maintainer-requested cleanup #4136. Many Headroom failure paths log at DEBUG, so before this change nobody running the proxy could see them. Debug output can include request-derived data, and with HEADROOM_DEBUG_DUMP=full the tool output the router compresses. It therefore goes only to the owner-only proxy.log, never to stdout. The proxy.mdx knob table will say this in the separate docs PR.

🤖 Generated with Claude Code

[github-actions]

PR governance

This PR does not yet satisfy the required template fields:

• Fill in Real Behavior Proof → Observed result.

Please update the PR body, or move the PR back to draft while it is still in progress.

[JerrettDavis]

Please update the reused file handler's level before returning from the same-path initialization branch. The parent logger is updated to DEBUG, but an existing proxy-log handler remains at INFO.

I reproduced this in a temporary workspace: set HEADROOM_LOG_LEVEL=info, call _setup_file_logging(port=9911), switch the environment to debug, call setup again for 9911, then emit INFO and DEBUG sentinels. The file contained INFO but not DEBUG. All 16 current focused tests pass because their handler setup starts fresh; they do not cover this transition. The reverse transition can also leave the handler configuration inconsistent.

Keep the existing handler/file-descriptor reuse, adjust its level to the newly resolved value, and add a same-path reconfiguration regression. This confirms the existing inline report. Update the configuration documentation for the new Headroom-level behavior too. The branch contains main a9815bb. I stopped qualification at this reproduced blocker; no contributor logic was changed and no contributor CI action is requested.