feat(minimald): log RPC dispatch, session lifecycle, and upload bytes - #895

The deficit, measured

On main, crates/minimald/src/rpc.rs (1292 lines) contains:

Every one of the 18 warns is the same interpolated line —
tracing::warn!("RPC handler for {} failed: {}", X::NAME, e) — which is
also the shape docs/rust-coding-standards.md explicitly rules out.

Three consequences, all verified in the tree:

1. The trace ids are minted and thrown away. handle_ssh_rpc builds an
   rpc span carrying rpc, trace_id, span_id, parent_span_id and
   instruments every handler future with it — but emits no event inside
   it. grep -rn 'FmtSpan\|with_span_events' crates/minimald/src returns
   nothing, so neither the console layer nor mlog::json_file_layer renders
   span open/close. A span containing no events produces no output
   whatsoever. The W3C traceparent is parsed off the channel env, adopted,
   re-minted as a child — and then never written anywhere.
2. serve_create_session logs nothing on success.
3. serve_stream_workspace_files — the workspace upload — emits nothing
   at all: no start, no byte count, no completion, and no failure line
   beyond whatever the transport happens to log. The daemon pipes
   c.make_reader() → ZstdDecoder → async_tar::Archive::unpack with no
   counter anywhere.

Why it matters — the incident

During #869, a guest-side log read, in full:

INFO  minimald::server: accepted connection conn=4 peer=cid: 2 port: 3903114191
WARN  minimald::server: session ended with error conn=4 error=Protocol error: No buffer space available (os error 105)

Between those two lines, 1.81 seconds apart, the daemon created a session
and received ~12.5 MB of tar. Neither is in any log. The session's UUIDv7
decodes to 0.4 ms after the accept, which is how it was eventually
established — by decoding a timestamp out of a session id, because no log
line said so.

Worse, the absence was misread as evidence. The investigation concluded the
console had dropped records and spent a stretch reasoning about a transport
that was fine. A later measurement — diffing the console mirror against the
on-volume log byte for byte — showed nothing was ever dropped. The
evidence was never written.

What each new record buys a reader

1. One pair of records per served RPC (served)

INFO conn{conn=4 transport=vsock}:rpc{rpc=…/CreateSession trace_id=… span_id=…}: rpc dispatched
INFO conn{conn=4 transport=vsock}:rpc{rpc=…/CreateSession trace_id=… span_id=…}: rpc served outcome=ok duration_ms=3

This is the record that makes the rpc span emit at all — the ids above
reach the log for the first time. It also gives the incident's silent
window a shape: which RPCs ran on conn=4, in what order, and how long
each took. duration_ms is the field that separates "the daemon was busy"
from "the daemon was blocked".

The rpc name, trace_id and span_id come from the span rather than being
repeated as event fields: mlog::json_file_layer sets
flatten_span_list_on_top_level(true), so span fields already land at the
top level of every JSON record, and duplicating rpc on the event would
emit a duplicate key.

2. Session lifecycle

INFO …:rpc{rpc=…/CreateSession …}: session created session_id=0198… session_name=norrie-minimal-4f2a
INFO …:rpc{rpc=…/DestroySession …}: session destroyed session_id=0198… session_name=norrie-minimal-4f2a

Directly answers the question that cost the most time in #869: did the
daemon create a session on this connection, and which one? No UUIDv7
timestamp archaeology. DestroySession carries only an id on the wire, so
the name is resolved from the record before the delete — best-effort, and a
failed lookup degrades to <anonymous> rather than failing a destroy that
would otherwise succeed.

3. Workspace upload, with bytes

INFO …:rpc{rpc=…/WorkspaceFilesTarZst …}: workspace upload started session_id=0198…
INFO …:rpc{rpc=…/WorkspaceFilesTarZst …}: workspace upload complete bytes_received=12782336
WARN …:rpc{rpc=…/WorkspaceFilesTarZst …}: workspace upload failed bytes_received=12500992 error=unpack failed: …

bytes_received is the single most valuable number in this PR. In the
incident, "12.5 MB received, then failed" against a 12.78 MB client-side
payload points straight at a transport that dies near the end of a large
transfer — as opposed to a rejected handshake (bytes_received=0) or a
malformed archive (full byte count, unpack error). That distinction was
unavailable and had to be reconstructed by hand.

The tally comes from a CountingReader spliced between the SSH channel and
the zstd decoder, so it counts compressed wire bytes — the figure that
compares directly against what the client sent, not the size of the
unpacked tree. The counter is an Arc<AtomicU64> rather than a return
value precisely because the reader is swallowed by the decoder and then the
unpacker: on a mid-stream failure they surface an error and drop the
reader, and the shared tally is the only surviving evidence of how far the
upload got.

Start-and-finish vs finish-only

Chosen: start-and-finish. Finish-only halves the volume and is
tempting, but a finish-only log cannot distinguish these two states:

• an RPC that is still running, and
• an RPC that was never dispatched.

Both look identical: nothing in the log. "Started and never finished" is
exactly what a hang looks like, and a hang is the failure mode this logging
exists to catch — #869's connection died with an RPC in flight. A dispatch
record turns that from an absence into a positive statement: this rpc,
with this trace id, on this connection, began and did not return.

The same argument applies to the workspace upload's start record, which is
emitted after the session resolves and before the first byte is pulled, so
a wedged transfer still leaves a line naming its destination session.

Log-volume impact at INFO

The RPC subsystem is a per-CLI-invocation path, not a per-keystroke
one: interactive attach traffic runs over shell/exec channels, which this
PR does not touch. So the multiplier applies to command dispatches, not to
terminal I/O.

Per served RPC: 2 INFO records where there were 0. A console record at
this shape (timestamp + level + conn/transport + the four rpc span
fields + target + message) runs ~260 B, so ~520 B per RPC.

A full session launch is CreateSession → WorkspaceFilesTarZst →
ConfigureLoadout (± SubmitVerdict) ≈ 4 RPCs:

A minimal ls is 1 RPC → 2 records, ~0.5 KB.

At a sustained 10 RPC/s — well beyond realistic interactive use; that is
ten CLI invocations every second, every second — this adds ~5 KB/s, ~19 MB/h.
The file log is Rotation::DAILY with max_log_files(14), so even a
pathological load is bounded by rotation rather than growing without limit.
Realistic steady state is single-digit RPCs per user action: tens of
records per minute, low hundreds of KB per day.

Nothing was added at DEBUG; the level distribution stays deliberate rather
than becoming a firehose that has to be filtered back out.

Arguably already-owed scope

Spec 10 R4.3 (on origin/arch/diagnostics-spec, not main —
docs/specs/10-spec-diagnostics/10-spec-diagnostics.md:540) reads:

R4.3: Top-level operations (CLI command dispatch, daemon RPC
dispatch, session/binding lifecycles) shall mint ids in OTLP-required
formats — trace_id 32 lowercase hex, span_id 16 lowercase hex —
recorded as span fields. Correlation values (channel_id, session_id,
…) are span fields with stable snake_case keys, never interpolated into
messages.

Daemon RPC dispatch does mint them, correctly, in the required formats.
It just never emits them, which makes the requirement satisfied on paper
and inert in practice. This PR is the missing half.

Incidental cleanup

The 18 duplicated if let Err(e) = res { tracing::warn!("RPC handler for {} failed: {}", …) } blocks are subsumed by the dispatch record, so the
serve_* handlers now return their Result instead of swallowing it —
one error path instead of eighteen, and the interpolated-string form is
gone from the file. serve_stream_workspace_files still relays its failure
to the client over extended data exactly as before.

Verification

macOS cannot build minimald (procfs), so both runs are via cross against
aarch64-unknown-linux-musl.

$ CROSS_CONTAINER_OPTS="--env HOME=/tmp" cross test -p minimald --target aarch64-unknown-linux-musl
running 146 tests
test rpc::tests::counting_reader_tallies_every_byte_pulled_through ... ok
test rpc::tests::stream_workspace_files_rejects_unknown_session ... ok
test rpc::tests::stream_workspace_files_unpacks_tarball_into_workspace ... ok
test result: ok. 146 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 73.50s

     Running unittests src/main.rs
test result: ok. 3 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.08s

     Running tests/mesh_uc7.rs
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

     Running tests/netns_root_integration.rs
test result: ok. 0 passed; 0 failed; 3 ignored; 0 measured; 0 filtered out

   Doc-tests minimald
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

$ CROSS_CONTAINER_OPTS="--env HOME=/tmp" cross clippy -p minimald \
    --target aarch64-unknown-linux-musl --all-targets -- -D warnings
    Checking minimald v0.5.0-rc1
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 1m 19s

The one new test, counting_reader_tallies_every_byte_pulled_through,
pulls an 8 KiB payload through CountingReader in many small polls and
asserts the tally accumulates across them rather than recording only the
last read — the counter is worth logging only if it is exact. The record
emission itself is declarative; the arithmetic is the part that can be
wrong.

Refs: #869

Summary by CodeRabbit

• Improvements
  • Improved RPC reliability and consistency across session, workspace, and system operations.
  • Added clearer logging for RPC dispatches, outcomes, durations, session deletion, and workspace uploads.
  • Improved visibility into workspace upload sizes, including compressed data transferred.
  • Standardized error handling to provide more consistent failure reporting.