Skip to content

Reduce per-request log noise to debug level and add structured (JSON) log output #377

Description

@zeljkoX

1. Hot-path RPCs log at info level

Every routine request emits an info log, which inflates CloudWatch ingestion/storage costs under production traffic and buries operationally meaningful events:

  • crates/server/src/services/get_state.rs:23 — "Getting state"
  • crates/server/src/services/get_delta.rs:25 — "Getting delta"
  • crates/server/src/services/get_delta_since.rs:27
  • crates/server/src/services/push_delta.rs:29 — "Pushing delta"
  • crates/server/src/services/configure_account.rs:33,174
  • crates/server/src/services/push_delta_proposal.rs:185,222
  • crates/server/src/services/sign_delta_proposal.rs:143
  • crates/server/src/services/lookup_account.rs, delta_commit.rs, abandon_candidate.rs

These are per-request traces, not operator-relevant events — they belong at debug.

2. No structured log output

LoggingConfig::init (crates/server/src/builder/logging.rs:23-35) hardcodes the default human-readable fmt layer. In CloudWatch this produces unstructured text lines (with ANSI escapes unless disabled), which are hard to read and can't be queried by field in CloudWatch Logs Insights.

3. Commitment-mismatch WARN fires on the normal not-yet-landed path

verify_state warns on any mismatch between the expected and on-chain commitment (crates/server/src/network/miden/mod.rs:170-175), but at that layer a mismatch is not yet a problem: while a candidate delta waits for its transaction to land, every canonicalization pass reads the on-chain commitment, sees it still at the candidate's base, and emits this WARN. A completely healthy create-then-canonicalize flow looks like this:

11:05:00.140  INFO push_delta{account_id=0xaef3...}: Pushing delta
11:05:03.100  WARN server::network::miden: Commitment mismatch during state verification account_id=0xaef3... expected=0xdc14... on_chain=0x2087...
11:05:06.077  INFO canonicalization::processor: Canonicalizing delta (commitment matches on-chain) nonce=3
11:05:06.096  INFO canonicalization::processor: Deleting matching proposal as delta is now canonical

The WARN is expected noise until the chain progresses; it is only meaningful if the mismatch persists. And the classification already lives in the caller (crates/server/src/jobs/canonicalization/processor.rs:742-763):

  • on_chain == prev_commitment — the transaction simply hasn't landed yet; routine, logged as deferral.
  • on_chain != prev_commitment — potential divergence, and even this is deferred at info level until divergence_confirmations consecutive observations confirm it (a single read can come from a lagging RPC node); the operator-relevant warn is emitted only on confirmed divergence (processor.rs:1012-1077).

So the network-layer WARN duplicates, at a higher severity and with less context, a signal the canonicalization layer already grades correctly. Under production traffic it makes WARN-level alerting on this logger useless.

Proposal

  1. Demote per-request logs to debug. Keep info for lifecycle/operator events (startup, config, background job outcomes, recovery actions). Errors/warnings unchanged. Requests remain observable via RUST_LOG=server=debug when needed.
  2. Add a log format option on LoggingConfig, e.g. a GUARDIAN_LOG_FORMAT env var (naming per docs/CONFIGURATION.md conventions):
  • text (default) — current behavior for local dev
  • json — tracing_subscriber::fmt::layer().json() with flattened fields, for CloudWatch Logs Insights querying (requires adding the json feature to tracing-subscriber in crates/server/Cargo.toml:54)
  • Consider also: compact for text, and disabling ANSI colors when stdout is not a TTY (or always in json mode)
  1. While there, consider #[tracing::instrument] spans on service handlers instead of ad-hoc entry logs — request context (account_id, nonce) then attaches to any warn/error emitted inside the handler, which is what you actually want at info+ in prod.
  2. Demote the network-layer "Commitment mismatch during state verification" log (network/miden/mod.rs:170) to debug. The streak-gated warn on confirmed divergence in the canonicalization processor is the operator signal; the raw per-read mismatch is diagnostic detail. Same review should sweep other network-layer logs whose severity assumes a context only the caller has.

Docs impact

  • docs/CONFIGURATION.md §Logging — document the new format variable and the level change (per-request logs now require debug)
  • docs/TROUBLESHOOTING.md logging section — update guidance for finding request traces; note that persistent commitment mismatch is surfaced by the canonicalization divergence warn, not the per-read network log

Metadata

Metadata

Assignees

No one assigned

    Labels

    enhancementNew feature or request

    Type

    Projects

    Status
    Backlog

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions