Refine and review user logs

[Mirko-von-Leipzig]

Focus item from #1874.

We now support separate user level logs as of #tracing. We've already done a pass or two on the emitted events and it should already be much better as of v0.15.1.

However we should refine and review the list of exactly what gets emitted by default and how users can tweak this for specific usage.

[Mirko-von-Leipzig]

@marijamijailovic if you could provide a list of required events, then we can see what isn't currently covered.

@kkovaacs if you could provide a list of currently covered-by-default items.

[melnikga]

@Mirko-von-Leipzig

I ran node v0.16.0-alpha.1 using the default filter (info,user=debug) and
evaluated it across multiple scenarios. In all cases the binaries were built
locally from source and run as separate processes (no docker). The setup included both a sequencer +
validator configuration with real mint/consume transactions submitted through
miden-benchmark, as well as the full 4-terminal setup (validator, sequencer,
ntx-builder, and remote-prover). The testing covered creating accounts,
consuming notes, writing to contract storage, re-submitting transactions to
observe rejection behavior, and performing a ctrl+c shutdown. The findings from
all of these scenarios are summarized below.

1. INFO and DEBUG are inverted for the events users care about

Everything you'd actually look for is at DEBUG: transaction submission, the tx
inputs line, block production. On plain info you can't see transactions
arriving and you can't tell whether the chain is advancing. The one per-tx line
that does reach INFO is a prover internal:

INFO ... prove_trace_sync: Generated execution trace of 73 columns and 64 steps (padded from 45) ...

What I'd propose:

• transaction submitted (id, account, expiry) and transaction accepted at INFO.
• a short block committed block=N txs=M at INFO, so the chain's heartbeat is
  visible by default. The detailed Block applied line can stay at DEBUG, but it
  currently prints block.number, block.commitment and block.transactions.count
  up to three times per line, once per span level, and should be deduplicated.
• prover internals down to DEBUG.

2. Accounts, notes, storage and the mempool have no lifecycle events

• Creating an account produces no event of its own. The only hint is
  account_commitment: None inside the tx-inputs debug dump, and that field means
  several different things, so it tells you very little. The account id next to it
  prints as raw internals:
  account_id: V1(AccountIdV1 { suffix: 2601478155324788736, prefix: 17696453536757913361 })
• Consumed notes come out as a bare tuple with no labels:
  input_notes=[(0xc681..., 0xeb38...)]. Nothing says the first value is the
  nullifier and the second is the note id. You find that out by reading
  format_input_notes (crates/utils/src/formatting.rs:12). Created notes are
  fine (note_id + sender).
• At block level, consuming a note is just aggregate counters. A same-block swap
  note shows up as erased_notes.count=1 with nullifiers.count=0.
• You can't tell a storage write apart from a transfer or an empty nonce bump.
  The counter contract I tested wrote 0→5 to a slot and produced the same Block applied
  line as everything else, with updated_accounts.count=1 and no mention of which
  slot or what changed.
• The mempool logs nothing at any level, so when a tx doesn't land in a block
  there's nowhere to look.

What I'd propose: a few small labeled events. account registered and
note created / note consumed (id, nullifier, block) at INFO.
account storage updated account=0x... slot=... at DEBUG for public accounts.
Basic mempool events at DEBUG: tx added, evicted, expired.

3. Formatting and noise

• "Submitting transaction" is logged twice per tx, once by the RPC layer and once
  by the block-producer.
• Every RPC line on stdout drags the full gRPC/OTel span context along with it
  (rpc.system, otel.name, server.address, client.port,
  network.peer.address, network.transport, network.type, and so on). The OTel
  exporter needs all of that. A human reading stdout doesn't. The stdout and OTel
  layers have independent filters, so this can be trimmed on stdout alone.
• Several fields print as raw Rust Debug: BatchId(Word([5514860...])) instead
  of hex, expires_at=4294967295 instead of "never", the AccountIdV1 internals
  above.
• The stdout format hides the log target, so you can't tell whether a line came
  from store, rpc, or block-producer.

4. Errors

A rejected transaction produces three separate ERROR lines for the same error,
one per instrumented span level, and only the outermost one carries the
human-readable cause. ERROR is also the wrong severity here: this is a client
mistake, and as it stands anyone can paint an operator's log red by submitting
bad transactions. One line per error, at WARN or below when the client is at
fault, with ERROR kept for problems with the node itself.

5. Startup, shutdown, and silent failures

• No version or config summary on startup, and no clear "node is ready" line. The
  closest is Server initialized, which dumps the raw Debug repr of the listener
  (TcpListener { addr: ..., fd: 58 }) and the whole RPC mode struct, tonic
  channel internals included.
• bootstrap never says it finished. The log just stops after "Database created".
• Bootstrapping with a custom genesis config (--genesis-config-file genesis.toml)
  never logs which file it actually read. The accounts it initialized are already
  printed (faucet_miden.mac 0xd66f... (Public, nonce=1) and so on), so putting the
  genesis config path next to them would be enough to confirm what the node started
  from.
• A configured but unreachable service is completely silent. I pointed
  --ntx-builder.url at a dead port and the node never logged a single warning.
• ctrl+c logs "Shutdown signal received", then the process exits with code 1,
  which breaks systemd and any script expecting 0. There's no "shutdown complete"
  either.

6. Log configuration is undocumented

MIDEN_STDOUT_FILTER, the RUST_LOG fallback, and the user::* targets
(user::miden-rpc, user::miden-store, and the rest) are documented only in a
rustdoc comment in crates/utils/src/logging.rs. The operator docs
(operation / monitoring / troubleshooting) don't mention logging at all.

---

Rather than one big "fix logging" issue, I'd split this up: (1) startup/shutdown
messages, the genesis config path, and the exit code, (2) INFO-level tx and block
lifecycle events plus demoting client errors, (3) account/note/storage/mempool
lifecycle events, (4) formatting cleanup: span dedup, raw Debug dumps, gRPC
noise, missing target, (5) a warning when a configured service is unreachable,
(6) a docs page for log configuration. I have raw log excerpts for every item
and will attach them to the individual issues.

[Mirko-von-Leipzig]

Thanks @melnikga, I really appreciate the write up.

We'll take a closer look at what we can do to improve matters. We're trying to strike a balance between OTel for production and stdout for local test networkse but the tooling we have isn't really made for this (yet).

We had some more convoluted ideas which I think would have addressed some of these issues, but we felt the complexity was worse than the benefit. But perhaps now that we have a reasonableish base we can iterate.