Skip to content

A module's log is a clog category: one writer per file, off the caller's thread, and DEBUG never written in production (card c7be807a) - #5710

Merged
joelteply merged 2 commits into
canaryfrom
cormac/logs-rotate
Nov 2, 2026
Merged

joelteply merged 2 commits into
canaryfrom
cormac/logs-rotate

Conversation

@joelteply

Copy link
Copy Markdown
Contributor

Measured on the IntelMac 2026-11-02 17:3xZ: jtag/logs/system/modules/command-executor.log
2.7 GB, of which 17,963 of the last 17,964 lines were the per-call DEBUG routing line;
data.log 0.9 GB; pressure-broker.log 0.26 GB. The M5 read 6.2 GB / 1.5 GB / 0.7 GB (Fable).

ModuleLogger held a file of its own: opened on the caller's thread, appended forever, never
rotated, and named the same as the logger module's modules/{name} category file, so one path
had two writers. It now holds no file. Its lines are clog events to modules/{name}, so the
logger module's single off-thread writer owns every such file and its existing size bound,
behind the 100 lines/s per-category rate limit. debug() goes to tracing at debug, which the
production filter (info) drops. Deleted: its hand-built ~/.continuum path, its OpenOptions
write, its Mutex, and the unused log_path().

Test: the clog routing test now also drives ModuleLogger. A TIMING line lands in
modules/command-executor once, and its DEBUG line reaches no category file. Mutation receipt:
routing debug() back to a category fails it. kernel logging:: + module_ 29/0.

Co-Authored-By: Claude Opus 5.5 (1M context) noreply@anthropic.com
Claude-Session: https://claude.ai/code/session_01FRQWzgSfo79JtnwZywHKrE

…r's thread, and DEBUG never written in production (card c7be807a)

Measured on the IntelMac 2026-11-02 17:3xZ: jtag/logs/system/modules/command-executor.log
2.7 GB, of which 17,963 of the last 17,964 lines were the per-call DEBUG routing line;
data.log 0.9 GB; pressure-broker.log 0.26 GB. The M5 read 6.2 GB / 1.5 GB / 0.7 GB (Fable).

ModuleLogger held a file of its own: opened on the caller's thread, appended forever, never
rotated, and named the same as the logger module's `modules/{name}` category file, so one path
had two writers. It now holds no file. Its lines are clog events to `modules/{name}`, so the
logger module's single off-thread writer owns every such file and its existing size bound,
behind the 100 lines/s per-category rate limit. debug() goes to tracing at debug, which the
production filter (info) drops. Deleted: its hand-built ~/.continuum path, its OpenOptions
write, its Mutex<File>, and the unused log_path().

Test: the clog routing test now also drives ModuleLogger. A TIMING line lands in
modules/command-executor once, and its DEBUG line reaches no category file. Mutation receipt:
routing debug() back to a category fails it. kernel logging:: + module_ 29/0.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FRQWzgSfo79JtnwZywHKrE
@joelteply

Copy link
Copy Markdown
Contributor Author

Scoped source review passes at 09aa0aa. ModuleLogger no longer opens, locks, flushes or owns a second file; INFO/WARN/ERROR and timing use the shared category route, and DEBUG uses tracing debug. The routing fixture covers the module timing category and exclusion of DEBUG from category files. The 29 passing tests and mutation receipt are author-reported; not executed locally here.

This clears the routing consolidation, not the separate rotation/grant work or post-deploy size proof. Existing writer bounds and drop accounting remain their owner's responsibility. Do not describe this source review as proof that all daemon/module log growth is repaired.

@joelteply joelteply left a comment

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review at 09aa0aa (source read; no local run claimed). The direction is right: the hand-built $HOME/.continuum path and the per-module file handle are deleted, one off-thread writer owns each file, and DEBUG drops to tracing debug. Claim verified: the category writer is bounded (logger.rs ensure_file_handle reopens past MAX_LOG_FILE_SIZE) and rate-limited per category per second (RateLimiter::check).

Three requests:

  1. TIMING per call is still written in production. M5 measured 2026-11-02 ~18:5xZ: the last 3 MB of modules/data.log is 31,341 [TIMING] [data] query took Nms | collection=chat_messages lines (1.5 GB file). timing/timing_with_meta stay at INFO, so this file keeps the same growth, now bounded only by the truncate. A per-call timing line is a probe or trace concern: route it to tracing debug like DEBUG, or to a time_sync!/probe. Hourly aggregates belong in the health ledger, not one line per query.

  2. The bound truncates the whole file to empty (fs::write(log_file_path, b"") past MAX_LOG_FILE_SIZE). Every crossing loses all history, and it is a second bounded-writer pattern beside the kernel's CappedAppender (generations, keep-tail). The card's own plan is CappedAppender for every log. Either this PR moves the category writer onto CappedAppender and deletes the truncate path, or that is the named next PR. One rotation owner, not two.

  3. emit's _ => INFO is a fallback arm. It's only called with INFO/WARN/ERROR today, but the match accepts any Level. A private three-variant enum (Info | Warn | Error) makes it exhaustive, with no catch-all (Joel 2026-11-02: "Fallbacks are the enemy of good design").

…ile levels are a private Info/Warn/Error with no catch-all arm (Fable on #5710)

The M5's data.log held 31,341 per-query '[TIMING] [data] query ... chat_messages' lines in
its last 3 MB. The clog test now proves a WARN routes to modules/{name} and neither DEBUG
nor TIMING reaches it. Mutation receipt: timing_with_meta routed back to INFO fails it.
kernel logging:: + module_ 29/0.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FRQWzgSfo79JtnwZywHKrE

@joelteply joelteply left a comment

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

PASS at 99bb487 on my asks (source read; Cormac's kernel 29/0 and mutation receipt are his): (1) both timing paths now go to tracing::debug!, so per-call TIMING never reaches a category file; (3) Level is a private Info/Warn/Error enum and emit has no catch-all arm. (2), the truncate-to-empty bound, is tracked as the named rotation follow-up (cormac/logs-rotate-owner).

@joelteply

Copy link
Copy Markdown
Contributor Author

Source clearance updated to 99bb487. Reviewed delta: private exhaustive Info/Warn/Error and both timing methods at tracing debug address the additional asks. Fixture checks WARN category routing and excludes DEBUG/TIMING. Kernel 29/0 and mutation results are author-reported, not locally rerun. Newest-preserving rotation and aggregate budget ownership remain the named follow-up, outside this clearance.

@joelteply
joelteply merged commit 30b2404 into canary Nov 2, 2026
36 checks passed
@joelteply
joelteply deleted the cormac/logs-rotate branch November 2, 2026 19:46
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant