fix(*): codex usage, log redaction, and two observability gaps - #347
fix(*): codex usage, log redaction, and two observability gaps#3470xKT wants to merge 2 commits into
Conversation
Four gaps found while regression-testing the v0.1.11 fix list on main. None of them is on that list; the one item still owed from it (doctor not naming the resolved everos binary) is the last of the four. 1. openai_codex reported zero tokens for every turn. The backend does send usage, on `response.completed` -- an event the consumer already handled for its finish_reason and read nothing else from. With usage left empty the per-turn summary suppressed itself (it renders only when in/out tokens exceed zero) and token budgeting saw nothing. The cost half stays absent by design: a plan-billed provider has no per-token price. 2. httpx logs its request line at INFO, and the Telegram Bot API keys every route on /bot<token>/, so a gateway run wrote 15 working bot tokens into its rotating log file -- the file users attach to bug reports. All three sinks now redact. The bot id survives; only the secret half is masked, and ordinary URLs, ports and paths are left alone so the log stays debuggable. This is the message-body counterpart to the existing diagnose=False, which already kept tracebacks from serializing secrets. 3. Migration notices repeated on every load_config. The strips rewrite the in-memory copy only, so an unmigrated file re-emits them forever, and a gateway loads once per cron fire. Deduped per process, next to the existing _warned_paths precedent. A record the logger would drop is not counted as told: the gateway loads its config before it installs a sink, and counting that dropped first line would have turned the noise into silence. 4. doctor now names the everos binary it resolved. Which one raven picked was invisible from every command, and the resolver prefers the interpreter's own directory -- the detail that matters when PATH holds another environment's copy. Verification: 234 tests across the affected modules, diff coverage 95.45% against the 90% gate, and a real gateway run confirming zero token occurrences and one line per migration. Co-authored-by: Claude (claude-opus-5) <noreply@anthropic.com>
|
Claude finished @0xKT's task in 2m 21s —— View job ReviewNo blockers; this can merge.
The blocker previously flagged on Reviewed the rest of the diff against
|
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
| _log = _MigrationLog(_logging.getLogger(__name__)) | ||
|
|
||
| if run_stamped: | ||
| _migrate_legacy_context_window(data, notify=True) |
There was a problem hiding this comment.
[blocker] This call still bypasses the new per-process dedup. _migrate_legacy_context_window's notify=True branch (loader.py:223) logs via a raw logging.getLogger(__name__).info(...), not through the _MigrationLog wrapper constructed at line 392 — it never sees _log/_logged_migrations at all.
That matters because this path is exactly the one problem #3 in this PR is about: run_stamped is unstamped = _migration_version(path) < CURRENT_CONFIG_VERSION (loader.py:313), and the stamp write is best-effort (_write_migration_version, loader.py:186-197, swallows OSError). If the sidecar stamp can't be written (read-only config dir, permission issue, etc.), unstamped stays True forever, so this branch — and its logging.getLogger(__name__).info("Migrated: dropped agents.defaults.%s ...") line — fires on every single load_config() call, indefinitely. That's the identical "gateway loads once per cron fire" noise this PR sets out to fix, just for one specific migration that isn't routed through the new dedup.
The added tests (test_migration_logs_once_per_process etc.) only call _migrate_config(data) with the default run_stamped=False, so this path isn't exercised at all.
Suggest passing the dedup logger (or _logged_migrations) into _migrate_legacy_context_window as well, or moving its notify logging to go through _MigrationLog.
The dedup in the parent commit covered the migrations that log through _migrate_config's proxy, but _migrate_legacy_context_window logs from its own function with a raw logger and kept repeating. One command walks that migration twice -- load_config's own read, then the persist pass re-reading the raw file -- and the stamp that would stop a third walk is best effort: _write_migration_version swallows OSError, so a config directory that cannot take the stamp leaves the line firing on every load. That is the same repeat the parent commit set out to end. The proxy is now a module-level instance shared by both paths. The added tests cover the twice-per-command walk and the stamped pass; the parent commit's tests reached neither, since they all ran with run_stamped defaulted off. Reported by the PR reviewer on #347. Co-authored-by: Claude (claude-opus-5) <noreply@anthropic.com>
Verdict: accepted, fixed in 3c80956
Verified before acting, rather than taking the reasoning at face value:
One correction: the scope is wider than reportedThe finding attributes this to the So the repeat does not need a failed stamp write to appear. A single command FixRather than threading the logger through the signature, the proxy is now a Verify
|
gloryfromca
left a comment
gloryfromca
left a comment
There was a problem hiding this comment.
No blockers; this can merge as far as I am concerned.
Independent review of 3c80956 (both commits), not a re-read of the earlier bot thread.
What I covered: the full diff against github/main, the callers of every changed signature, AGENTS.md conventions (commit grammar/ASCII, test file naming, comment rules), backward compatibility, and whether the tests actually exercise the behaviour. Full suite run locally.
Verification
uv run pytest -q->1 failed, 6440 passed, 43 skipped. The single failure istests/test_cli_theme.py::test_bold_accent_renders_styled_not_bare, and it is not from this PR: the file is byte-identical tomain, no PR-touched module is imported by it, and it fails when that file is run on its own (rich falls back to 256-colour,38;5;221instead of truecolor) while passing when the test is run alone -- intra-file pollution that predates this branch. The 43 skips are all import-gated optional channel SDKs plus parametrized provider cases, none of them in this diff.uv run pytest -q tests/test_log_redaction.py tests/test_config_loader.py tests/test_openai_codex_provider.py tests/test_cli_doctor_commands.py tests/test_cli_log_file.py tests/test_cli_tui_logging_isolation.py->144 passed, 0 skipped.uv run ruff check raven/ tests/clean;ruff format --checkclean.
Things I checked and could not turn into a finding
- The dedup gap the earlier thread raised is genuinely closed:
_migrate_legacy_context_windownow logs through the shared module-level_MigrationLog, and the two new tests cover both the twice-per-command walk andrun_stamped=True(the earlier tests reached neither). Every_log.*call inloader.pyis.info, so the proxy exposing onlyinfocannot AttributeError. - The
isEnabledFor(INFO)guard behaves as documented: before_intercept_stdlib_loggingruns, root sits at WARNING so a dropped record is not counted as told; afterbasicConfig(level=0, force=True)the effective level is 0 and the line reaches the file sink.setLevel/basicConfigclear theisEnabledForcache, so the guard cannot latch. - Redaction is attached per sink, not once: the file sink, the terminal sink and the
RAVEN_CLI_DEBUGsink each carryredacting_filter, so a record filtered out of the file sink by handler level still gets redacted on the way to stderr. Loguru runs the filter before theenqueue=Truehandoff, which the on-disk assertion intest_gateway_log_file_never_receives_a_live_tokenproves end to end. The TUI's_drop_watcher_spammatches"rust notify timeout", which redaction cannot perturb. - Codex usage mapping matches the convention it claims:
input_tokensincludes cached tokens, and bothAgentLoop._build_usage_snapshotandraven/tracing/usage.normalizesubtractcache_read + cache_writeunder the same inequality test, so nothing is double counted._consume_sse/_request_codexare module-private and every caller (including tests) was updated for the 4-tuple. MemoryInfo.binaryis inserted mid-dataclass, but the only construction site is keyword-only, so no positional shift.binaryis set only underowned, and_probe_memory/_render_memory_capabilitiesbail on the same non-everos condition, so the "not found" line can never appear for a backend nobody looked up.everos_binary_pathswallows onlyEverosBinaryMissingError, which is all_everos_executableraises.
Worth knowing, not blocking: redaction rewrites record["message"] only. A logger.exception(...) traceback and the default stderr sink installed by raven/cli/_log_silence.py still bypass it. I looked for a concrete leak through either and did not find one in the current callers (the one URL-embedded credential in the repo, dingtalk's ?access_token= upload, logs the error interpolated into the message, so it is covered), so this is a note for later rather than a defect in this diff.
2 participants
Summary
Four gaps found while regression-testing the v0.1.11 fix list against
main.Three are new; the fourth is the one item that list still owed.
1.
openai_codexreported zero tokens for every turn. The backend sendsusage on
response.completed-- an event the SSE consumer already handled forits
finish_reasonwhile reading nothing else from it. Empty usage made theper-turn summary suppress itself (it renders only above zero tokens) and left
token budgeting blind. Cost stays absent by design: a plan-billed provider has
no per-token price.
2. Channel credentials reached the log file. httpx logs its request line at
INFO and the Telegram Bot API keys every route on
/bot<token>/, so one gatewayrun wrote 15 working bot tokens into its rotating log. All three sinks now
redact. The numeric bot id survives for debugging; ordinary URLs, ports and
paths are left untouched so the log stays usable.
3. Migration notices repeated on every
load_config. The strips rewrite thein-memory copy only, so an unmigrated file re-emits them forever -- and a gateway
loads once per cron fire. Deduped per process, alongside the existing
_warned_paths. A record the logger would drop does not count as told: thegateway loads its config before installing a sink, and counting that dropped
first line would trade the noise for silence. A test pins this.
4.
doctornow names the everos binary it resolved. Which one raven pickedwas invisible from every command, and the resolver prefers the interpreter's own
directory -- what matters when PATH holds another environment's copy.
Deliberately not included: the gateway log keeps its
0644mode. Redactionremoves the credentials; whether session content should also be unreadable to
other local users is a separate call.
Type
Verification
uv run pytest tests/test_openai_codex_provider.py tests/test_log_redaction.py tests/test_cli_doctor_commands.py tests/test_config_loader.py tests/test_everos_server.py tests/test_cli_gateway_commands.py tests/test_cli_tui_commands.py: 234 passed.make lint-python: clean (832 files).uv run python scripts/coverage_gate.py diff --base-ref origin/main --threshold 90: 95.45% (42/44 changed lines).Real gateway run against a live Telegram bot: the configured token appears 0
times in the log file (15 before), and each migration line appears once (4-8
per cron fire before).
Real codex turn: the summary now prints
3.7k in / 13 out tokens; it printednothing before.
Removing the dedup guard turns its test red, so the test is not self-satisfying.
Relevant tests pass locally
Relevant lint / type checks pass locally
User-facing docs or screenshots are updated when needed
Risk
Redaction rewrites log text, so a line quoting one of the masked shapes is
altered on its way to the sink; the patterns are anchored to credential syntax
and tests assert plain URLs, ports and paths pass through untouched.
_consume_ssegained a fourth return element -- both call sites are in the sameprivate module and updated here. Rollback is a revert of this branch.
Related Issues
N/A