Skip to content

chore(logging): trim default log volume — reclassify routine info→debug, add trace tier#3994

Merged
Yeraze merged 2 commits into
mainfrom
chore/log-level-trim
Jul 8, 2026
Merged

chore(logging): trim default log volume — reclassify routine info→debug, add trace tier#3994
Yeraze merged 2 commits into
mainfrom
chore/log-level-trim

Conversation

@Yeraze

@Yeraze Yeraze commented Jul 7, 2026

Copy link
Copy Markdown
Owner

Problem

Users reported MeshMonitor's Docker logs are unusable for support — too much output at the default level. Root cause is not the logging infrastructure (src/utils/logger.ts is a proper leveled logger gated by LOG_LEVEL, prod default info, and server code has zero raw console.log). The problem is overuse of logger.info: ~1,450 server-side info calls all print at the production default, most of them routine per-packet / per-request / per-message / periodic-scheduler chatter, plus a ~60-line environment dump on every boot.

Changes

  • New trace level below debug for the true per-packet firehose. LOG_LEVEL now accepts trace.
  • Reclassified server logger.infodebug/trace: non-migration info 1,452 → 865 (~590 → debug, 11 → trace). Hot paths collapsed: meshtasticManager 258→18, meshcoreManager 61→19, environment 67→16, server.ts 49→20.
  • Kept at info: only startup/shutdown, source connect/disconnect, backups/restores/migrations, and deliberate admin actions (purges, config imports, token issuance, upgrades). An idle container is now near-silent at info.
  • Privacy: MeshCore message bodies (contact/channel/room/DM/auto-ack text) were logged in full at info — now demoted to debug and redacted to (N chars), keeping only sender/channel metadata.
  • Env boot dump collapsed to a compact ~16-line info summary; per-variable detail → debug.
  • Docs: docs/configuration/index.md (trace tier + "info is now quiet" guidance), commented LOG_LEVEL in docker-compose.yml, CHANGELOG entry, new trace-level test coverage.

Deliberately out of scope

  • Migrations untouched — their ~570 info lines only fire once when a migration first applies (a one-time audit trail), never in steady state.
  • Default production level stays info (not warn), per design discussion — info should remain a meaningful, sparse support signal.

How to use higher verbosity

No NODE_ENV change needed:

environment:
  - LOG_LEVEL=debug   # or `trace` for the full per-packet firehose

Verification

  • npm run typecheck — clean
  • npm run lint:ci (ratchet) — OK (trace typed unknown[], does not grow the no-explicit-any baseline)
  • Full Vitest — 8,215 passed, 0 failed, 2,696/2,696 suites

🤖 Generated with Claude Code

…ug, add trace tier

Container logs were unusable for support because ~1,450 server-side
logger.info calls print at the production default level. Almost all of the
high-frequency ones — per-packet, per-request, per-message, and periodic
scheduler activity, plus the ~60-line environment dump on every boot — are
routine and belong at debug.

Changes:
- logger.ts: add a `trace` level below `debug` for true per-packet firehose;
  document the tier semantics (info = sparse, support-relevant events only).
- environment.ts: accept `trace` for LOG_LEVEL; collapse the boot env dump to
  a compact ~16-line info summary (details → debug).
- Reclassify server logger.info calls: non-migration info 1452 → 865
  (~590 demoted to debug, 11 to trace). Hot paths collapsed:
  meshtasticManager 258→18, meshcoreManager 61→19, server.ts 49→20.
- Redact MeshCore message bodies from logs (contact/channel/room/DM/auto-ack
  text → `(N chars)`); keep sender/channel metadata.
- Docs + docker-compose.yml + CHANGELOG updated; new trace-level test coverage.

An idle container is now near-silent at the default `info` level. Raise with
LOG_LEVEL=debug (or trace) — no NODE_ENV change needed.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_015AFBA76hsjqhsXe1BdnYub
@github-actions

github-actions Bot commented Jul 7, 2026

Copy link
Copy Markdown

Claude finished @Yeraze's task —— View job


PR Review: chore(logging): trim default log volume

Tasks:

  • Gather context and understand the PR
  • Review logger.ts — new trace tier implementation
  • Review environment.ts — boot dump changes
  • Review meshcoreManager.ts — privacy/redaction changes
  • Review meshtasticManager.ts — reclassification scope
  • Review test coverage (logger.test.ts)
  • Review other key files
  • Write final review feedback

Code Review

This is a well-scoped, well-executed PR. The signal-to-noise improvement is significant and the changes are conservative. Notes below are roughly priority-ordered.

Issues / Concerns

1. trace method uses ...args: unknown[] but debug/info/warn/error use ...args: any[] — inconsistency in logger.ts

src/utils/logger.ts:65 (trace) declares ...args: unknown[], while debug (line 75), info (85), warn (95), and error (105) all use ...args: any[]. This inconsistency is visible in the type signatures and slightly odd for a peer at the same abstraction level. The PR description acknowledges that trace being typed unknown[] is intentional to avoid growing the no-explicit-any baseline — that's a reasonable pragmatic call. It's worth a comment in the code explaining why trace differs, so a future reader doesn't "fix" it without realising the ESLint implication.

2. currentLevel is evaluated once at module load time — LOG_LEVEL changes after startup have no effect

src/utils/logger.ts:38: const currentLevel = getLogLevel(); is a top-level const. This is correct design for a singleton logger (and the tests work around it with vi.resetModules()), but it means that any environment config hot-reload or test pollution that sets process.env.LOG_LEVEL after the module is imported will not be picked up. The test suite correctly handles this with vi.resetModules() in afterEach. No change needed, but this implicit contract should be documented — e.g., a comment on line 38 saying "evaluated once at import; tests must use vi.resetModules() to change level".

3. Privacy/redaction pattern in meshcoreManager.ts is good — but inconsistent

The message body redaction uses (${data.text.length} chars) (lines 1271, 1307, 1339, 2203) which is a good pattern. However, line 2823 logger.debug(\[MeshCore] Message sent (${text.length} chars)…`) and lines 6729/6732 also use the pattern for auto-ack bodies. Good. One gap: the auto-ack reply text itself (replyText) is referenced by length at lines 6729/6732, which is correct, but the original contact text that triggered the auto-ack is not shown at the same callsite — the trigger match is logged earlier (search for autoAckRegex` in the diff, not reviewed here). This is fine as-is.

4. environment.ts — two rate-limiting logger.info calls remain for the "unlimited" / "0 or negative" cases (lines 104, 116)

src/server/config/environment.ts:104 and 116 still use logger.info inside parseRateLimit. These fire only when rate limiting is disabled (a deliberate operator configuration), which is arguably a meaningful startup event — so keeping at info is a judgement call and defensible. Worth noting as a choice rather than an oversight.

5. No test for trace sanitization path

src/utils/logger.test.ts (the sanitization suite at line 161) tests debug, info, warn, and error for CWE-117 log injection, but does not test logger.trace. Since trace also pipes through sanitizeArgs, this is a functional gap if someone were to use trace with attacker-controlled strings. Low risk in practice (trace is off by default), but worth adding a line to the existing sanitization test at line 191–199 to call logger.trace(malicious) and assert it produces [TRACE] user=evil [INFO] forged login: admin .

6. src/server/services/firmwareUpdateService.tslogger.info retained for lifecycle events is correct, but polling started message (line 479) could be debug

[FirmwareUpdateService] Polling started (interval: ${intervalMs}ms) fires on every boot. It's a scheduler start event, similar to the scheduler starts that were demoted to debug in other services. Minor inconsistency — not a blocker.


Positive Observations

  • meshtasticManager.ts reclassification is thorough and correct. The 18 remaining info calls are all genuine lifecycle/operational events (MQTT attach, heartbeat enable, key repair exhaustion/purge, node ID change, reboot command, channel migration, manual resync). No hot-path chatter remains at info.

  • environment.ts boot dump is well-structured. The compact info summary (NODE_ENV, PORT, BASE_URL, LOG_LEVEL, TZ, VERSION_CHECK_DISABLED, DATABASE_TYPE, DATABASE_PATH, MESHTASTIC_NODE_IP/PORT) is exactly the right set for a support engineer's first glance. All the per-variable debug detail is preserved for those who need it.

  • Privacy redaction in meshcoreManager.ts is targeted and appropriate. Contact/channel/room DM text is logged only as (N chars) at debug, which is the correct tier for message bodies. The sender/channel metadata is preserved, giving enough context for debugging without leaking content.

  • Test coverage for the new trace tier is complete. All five-level ordering tests, the case-insensitive check, the NODE_ENV fallback, and the invalid-level fallback all now include trace correctly.

  • duplicateKeySchedulerService.ts classification is good. start() keeps logger.info for the "Starting security scanner" event and demotes routine scan cycles to debug, with warn retained for actual anomalies (low entropy, duplicate keys, spam, time offsets).

  • virtualNodeServer.ts trace usage is appropriate — byte-level receive/parse events are exactly what the trace tier is for.

  • The ESLint ratchet is respected. Using unknown[] for trace to avoid touching the no-explicit-any baseline is a pragmatic and documented choice.


Summary

The PR is ready to merge with one optional quick fix:

  • Add a logger.trace(malicious) + assertion to the CWE-117 sanitization test suite (item 5 above) — this is a small regression-guard gap.
  • Optionally add a brief inline comment on logger.ts:38 about the module-load-time evaluation and logger.ts:65 explaining why trace differs from peers on the any[] vs unknown[] typing.

The core goal — making an idle container near-silent at info — is achieved cleanly.


…l eval, cover trace in sanitization test

Addresses non-blocking notes from claude-review on #3994:
- logger.ts: comment why trace uses unknown[] (lint baseline) and why
  currentLevel is import-time only (tests need vi.resetModules()).
- logger.test.ts: exercise logger.trace through the CWE-117 sanitization path.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_015AFBA76hsjqhsXe1BdnYub
@Yeraze

Yeraze commented Jul 7, 2026

Copy link
Copy Markdown
Owner Author

Thanks for the thorough review. Addressed in 3d0ddb7:

Intentional / no change:

@github-actions

github-actions Bot commented Jul 7, 2026

Copy link
Copy Markdown

Claude finished @Yeraze's task —— View job


PR Review: chore(logging): trim default log volume

Tasks:

  • Gather context and understand the PR
  • Review logger.ts — verify trace type comment and currentLevel comment
  • Review logger.test.ts — verify trace sanitization test was added
  • Review meshcoreManager.ts — privacy/redaction changes
  • Review environment.ts — rate-limiting info calls
  • Write final review feedback

Follow-up Review (post 3d0ddb7)

All three items from the previous review that the author committed to addressing are correctly implemented. Here's the full current-state assessment.

Verified Fixes

#1 (trace unknown[] comment)src/utils/logger.ts:68-71 now carries an explicit comment explaining why trace uses unknown[] while peers use any[]. The rationale (avoiding a lint-ratchet baseline bump) is clearly stated. ✓

#2 (currentLevel import-time evaluation)src/utils/logger.ts:38-41 now has a comment documenting the once-at-import evaluation and the vi.resetModules() contract for tests. ✓

#5 (trace sanitization test)src/utils/logger.test.ts:186-203 now sets LOG_LEVEL=trace and asserts [TRACE], [DEBUG], [INFO], [WARN], and [ERROR] are all defanged. The test correctly imports the logger after setting the env var (necessary because currentLevel is frozen at import), and the beforeEach / afterEach properly reset modules. This is solid. ✓

Confirmed Intentional Items (no change needed)

  • Rate-limit info at environment.ts:104,116 — fires only on explicit operator opt-out of rate limiting, a deliberate rare configuration event. Keeping at info is correct.
  • firmwareUpdateService.ts:479 "Polling started" — one-per-boot scheduler-start event, consistent with the sweep rubric (keep one start/stop line per service at info). Fine.
  • Privacy redaction in meshcoreManager.ts — all four message-body call sites (lines 1271, 1307, 1339, 2823) log only (N chars) at debug. The auto-ack DM reply text is similarly protected (replyText.length only, line 6729-ish). Consistent and correct.

Minor Observation (no action required)

src/server/meshtasticManager.ts:5184 — the single logger.trace call in this file (server-side decryption success) is placed at trace level appropriately. Only 18 logger.info calls remain in this file, all genuine lifecycle events (per earlier review). The counts are accurate.

Doc Quality

docs/configuration/index.md changes are clean. The log-levels table is accurate, the tip block clearly separates NODE_ENV from LOG_LEVEL, and the guidance around not changing NODE_ENV to avoid side effects is a useful production callout.


Summary

This PR is ready to merge. The previous review's actionable items (#1, #2, #5) have been addressed correctly, and the intentionally-left-as-is items (#3, #4, #6) remain well-justified. The core goal — a near-silent idle container at info — is achieved, with a clean trace tier added for firehose capture. No new issues found.


View job

@Yeraze
Yeraze merged commit ac04754 into main Jul 8, 2026
20 checks passed
@Yeraze
Yeraze deleted the chore/log-level-trim branch July 8, 2026 00:26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant