Structured event logs

Test-harness scaffolding (Codeberg #39 piece 1, Stage 6) for capturing mesh-protocol events as parseable lines so multi-node failures can be diagnosed from a single merged log instead of N hand-correlated process traces.

Format

Each emitted event renders to a single line:

EVENT_NAME node=<n> key1=val1 key2=val2 ... t=<rel-ms>

Rules:

• EVENT_NAME first. Comes from the literal string passed as the event field in a tracing::debug! call.
• node= second. Value comes from LEVICULUM_EVENT_NODE environment variable; defaults to local.
• All other keys appear alphabetically sorted between node= and t=.
• t= last. Millisecond offset from layer registration time.

Records that don't carry an event = "..." field are silently dropped, so the legacy printf-style tracing::debug!("[FOO] ...") sites stay valid alongside the converted ones.

Per-packet journey contract

The packet-level events PKT_TX, PKT_RX, PKT_FORWARD, PKT_DROP and DEDUP_DROP form the journey contract an external collector uses to stitch one packet's path across nodes:

• They are emitted on the dedicated tracing target leviculum_core::pkt (DEBUG), so a collector can enable exactly this stream via RUST_LOG=leviculum_core::pkt=debug without the rest of the transport noise. The event-log layer sees every record regardless of target.

• Each carries ph, the first 16 hex chars of the dedup packet hash (SHA-256 over the hashable part, which strips hops and transport_id). ph is therefore stable across hops and across Type1/Type2 header conversion: the same value appears in the sender's PKT_TX, every relay's PKT_RX/PKT_FORWARD and the receiver's PKT_RX, or in the PKT_DROP/DEDUP_DROP where the packet died.

• PKT_DROP renders its reason as the kebab-case DropReason (no-path, plain-group-multihop, forward-max-hops, ...). unknown-context is the one reason that says nothing about the packet's validity: it means the packet was addressed to US and carries a context byte this build assigns no meaning to, so nothing above transport could interpret it. The same packet addressed to someone else is relayed normally and never reaches this counter — the context byte is semantic, not routing information. A rising unknown-context on a node that is also an endpoint means a peer speaks a dialect (newer RNS, third implementation) we do not.

• no-such-interface is the one PKT_DROP on the OUTBOUND path, and the one with a different field set: the action was routed to an interface the driver's dispatch slice does not contain, so it never became a received packet and carries iface_out and len instead of dst, type and iface_in. Non-zero means the driver and the core disagree about interface numbering — a configuration fault in the driver, not a mesh condition, which is why it does not share a counter with no-path.

• A relay whose outbound path points back out of the arrival interface forwards there — same-interface relay on a shared medium is a normal hop, not a drop (see Python-RNS Compatibility). Its PKT_FORWARD carries iface_out equal to iface_in.

• PKT_TX on a Broadcast action reports iface=bcast: the sans-I/O core does not know the concrete interface set the driver expands the broadcast to; journeys stitch by ph.

• PKT_TX and PKT_RX both carry hops, but they are counted at different points and the difference is the contract:

  • PKT_TX hops is the hop count of the packet as transmitted — the byte that goes on the wire, read from the packed buffer being handed to the driver.
  • PKT_RX hops is the hop count after receipt, i.e. after the receiver's increment (Transport::incoming_hop_count, mirroring Python Transport.py:1457).

  So for one ph crossing one radio hop, rx hops = tx hops + 1. A collector reads a journey's DIRECTION from exactly that relation: the node observing the packet at the lower hop count transmitted it, the node at one more heard that transmission. Without hops on PKT_TX, a node that ORIGINATES a packet (a firmware node, or a daemon's own announces, path requests and link proofs) contributes no hop count at all and drops out of that relation.

  The relation is deliberately +1 only for a real medium crossing. Over the local-IPC hop — a LocalClient interface, or the uplink to a shared instance — incoming_hop_count undoes its own increment, so there rx hops = tx hops. That is Python's behaviour (Transport.py :1481-1484) and it is correct: the IPC hop is not a network hop. A collector pairing on +1 therefore ignores IPC hops, which is what it should do.

• The hash is never computed twice for one packet: emission sites reuse the dedup/cache hash where it exists and otherwise hash only while the leviculum_core::pkt target is enabled. With the target disabled the whole contract is zero-cost.

• Deliberate exclusions: the high-volume overheard drop (overheard-transport-id) and IFAC drops stay counter-only (PKT_DROP_SUMMARY); announce-pipeline drops (replay, rate-limit, ingress-burst, over-max-hops, blackhole) are covered by the announce event family and the summary counters.

Architecture

All test threads, including tokio multi-thread workers, route through the same global subscriber registered once via Layer composition.

Specifically: tracing_setup::init_tracing_with_event_log() builds a Registry::default().with(fmt_layer).with(event_log_layer) chain and installs it via set_global_default once per process (Once- guarded). Every thread, every spawned future, every tokio worker inherits this global subscriber. This is the load-bearing architectural choice that lets a #[tokio::test(multi_thread)] mvr see events emitted from worker threads.

Per-test buffer isolation is built on top: init_event_log() returns an EventLogHandle whose Arc<Mutex<Vec<String>>> buffer is registered in the layer's active-handles list. The layer's on_event iterates the active list and pushes the formatted line to every active buffer. When the test's handle drops, it removes itself from the list.

Concurrency consequence: every active buffer receives every event the layer sees, regardless of which test emitted it. Tests that assert on buffer contents must filter by event name to avoid cross-test pollution. Use disjoint event names per test (EV_BASIC, EV_VIOLATION, …); mvr tests already enforce --test-threads=1 so this only affects unit tests.

How to wire a test

Inside any test, before the test body runs:

#![allow(unused)]
fn main() {
let _evlog = leviculum_std::test_support::event_log::init_event_log();
}

The handle is RAII: when the binding goes out of scope it removes itself from the layer's active-handles list. If the test thread is panicking at drop-time, the buffer dumps to stderr with a === EVENT LOG DUMP … banner that cargo test surfaces in the failure listing.

Use init_event_log_to_file(path) instead of init_event_log() when the test wants to assert on the dumped content directly (std::fs::read_to_string(path)).

To make the test fail loud on undocumented schema gaps, end the test body with:

#![allow(unused)]
fn main() {
leviculum_std::assert_no_schema_violations!(_evlog);
}

It panics if any EVENT_SCHEMA_VIOLATION line appears in the buffer.

How to add an event

Two steps, both in the same commit:

1. Convert the call site. Replace the printf-style tracing::debug! with structured fields:

   #![allow(unused)]
   fn main() {
   tracing::debug!(
       event = "FOO",
       iface = %iface_name,
       dst   = %HexShort(&dst_hash),
       hops  = packet.hops,
       len   = bytes.len(),
   );
   }

   % for Display, ? for Debug. Values must be ASCII without whitespace, =, or non-printable characters — otherwise the field-value validator fires (see below). For Rust keywords like type, use the raw identifier r#type.

   No trailing message. tracing::debug!(event = "FOO", a = 1, "some prose") renders the prose under a message field whose spaces split the line for every token-based parser. What the sentence would have said belongs in a structured field or in a comment at the call site.

2. Add a catalogue entry in leviculum-std/src/event_log.rs's EVENT_CATALOG:

   #![allow(unused)]
   fn main() {
   EventSchema {
       name: "FOO",
       required_keys: &["iface", "dst", "hops", "len"],
   },
   }

   required_keys is the INTERSECTION of the keys the name's call sites set — the contract is "present on every emission". Where sites differ in a way worth checking, the name gets several entries and a record passes if any one shape is fully present (Codeberg #320); note that a shorter shape dominates a longer one that merely extends it, so a second entry only earns its place when neither shape contains the other. The subscriber checks that every catalogued event's emission satisfies some declared shape; a record that satisfies none produces a EVENT_SCHEMA_VIOLATION line in the dumped buffer alongside the original event.

Step 2 is not on the honour system. leviculum-std's #[cfg(test)] mod event_catalog_completeness walks the tracing::*!(event = "...") sites of every workspace member's src/ and fails on a name EVENT_CATALOG is missing, and on a site that passes a message argument. It runs under cargo test --workspace --lib, which is what just fast and the forge gate run.

It exists because the honour system had already failed: the miauhaus soak of 2026-09-18 (397 023 881 events) found eight emitted names undeclared, LINK_ENTRY_SET among them at 612 639 emissions. An undeclared name is not cosmetic — the layer validates a shape only for a name it finds in the catalogue, so an undeclared event can lose a required field forever and nothing says a word. What caught LINK_ENTRY_SET's broken next_hop, 252 669 times, was the field-VALUE check, which runs regardless of the catalogue.

Catalogue entries without a live emitting site are explicitly discouraged: the runtime-validation layer can't detect them, so they silently rot. Only add entries you have a corresponding emit for. (That direction is still unchecked, and the catalogue carries entries whose emitter lives outside this workspace: SILENCE_LNODE_ENTER/SILENCE_LNODE_EXIT are periculum's.)

Firmware-side events

The nRF firmware emits the same line grammar, but not through this machinery. leviculum-nrf is no_std and cannot depend on leviculum-std, so there is no tracing subscriber, no node= field, and no runtime schema validation; the line goes into the debug-CDC ring buffer behind the module prefix that the rest of the firmware log uses:

[BLE ] BLE_TX_DROP kind=packet len=312 frag=1 of=2 sent=1 reason=stalled code=0 waits=0 dropped=3 t=48210

The prefix does not disturb the grammar — the event name is still one whitespace-delimited token and grep BLE_TX_DROP over a captured debug-port log still works — but the event deliberately does not appear in EVENT_CATALOG. A catalogue entry the subscriber can never see emitted is exactly the silent rot the rule above forbids. Firmware events are documented here and at their call site instead.

Who writes t= on a firmware line

Nobody at the call site. Since #344 the firmware's log formatter (leviculum-nrf/src/log.rs, shape in leviculum-log-line) appends t=<uptime-ms> to every line it emits — event lines, plain [LORA]/[INFO] lines, boot banners, tracing records alike. A call site that also writes its own t= renders the field twice; BLE_TX_DROP did, and stopped.

The stamp is taken when the line is formatted, not when it is drained: the ring is emptied in 64-byte USB packets on a 100 ms loop, so host arrival times measure that loop and nothing else.

A line may still legitimately carry two t= fields. The boot replay of the persistent tail wraps a line from the previous boot, its stamp included, inside a line of this boot:

[INFO!] [PERSISTENT_LOG] [LORA] RX 41 bytes t=91422 t=137

Both are true. A line's own stamp is always its last t= — the same rule merge_event_logs already applies, so the two agree.

Epochs do not. A firmware t= is milliseconds of board uptime; a host-side t= is milliseconds since that subscriber's init. Merging a debug-port capture into a host event log with merge_event_logs therefore orders each stream correctly within itself and says nothing across the two.

Current firmware events:

Host-side BLE events

lnsd's Columba BLE interface (leviculum-std/src/interfaces/ble/) emits BLE_SCAN_DECISION with the same fields as the firmware's line of the same name — addr=, caps_record=, caps=, free_slots=, rule=, initiate= — so a merged rig timeline shows both sides of one mutual sighting deciding, and the two rule= values must be complementary (one initiate…, one wait…). Its link lifecycle is BLE_LINK_UP / BLE_LINK_DOWN (with role=central|peripheral and peer=<hex8>, the same hex the firmware logs and the LN-<hex8> name carries), the admission decisions are the firmware's BLE_LINK_SELF / BLE_LINK_DUP / BLE_LINK_REPLACED names — lnsd's lines carry rule=, origin=incoming|outgoing, old_mtu=/new_mtu=, old_silence_ms= and the reported old_data_silence_ms= exactly as the firmware's do (#360 round 2), plus old_role= on a replacement — and one lnsd has no firmware counterpart for: BLE_LINK_NOT_ADMITTED peer=<hex8> identity=<hex32> addr=<a> role=peripheral listed=<n> action=disconnect — the accept_only config key refused this incoming link at its identity handshake, so the peer never became a link. identity= carries the whole hash beside peer='s four bytes because both are spellings the key accepts, and listed= is how many peers the list names, so a capture shows that a list is in force without the config beside it. The line exists so a measuring host that turned strangers away does not read like a host nobody tried; its dialling-side sibling is BLE_DIAL_NOT_ALLOWED, which fires when initiate_only is what stopped a dial. The churn penalty (#417) is the firmware's BLE_CHURN_LEDGER with the bare token spelled state=: BLE_CHURN_LEDGER state=armed identity=<hex8> run=<n> reason=expiry_central|expiry_peripheral|replaced window_ms=<n> cooldown_ms=<n> when a rotating-addressed identity's run of departures (a BLE_LINK_DOWN reason=timeout or a BLE_LINK_REPLACED) closes the rotating fallback class, and BLE_CHURN_LEDGER state=held run=<n> until_ms=<n> now_ms=<n> once per cooldown when that closed a candidate out of the collection window. Same ledger, same constants (ChurnPolicy::MEASURED), no A/B switch on lnsd. A fan-out drop on a congested link is BLE_TX_FANOUT_DROP. The delivery-hint decision is the firmware's BLE_TX_ROUTE / BLE_TX_FLOOD / BLE_TX_ROUTE_MISS (#376), with conn=central|peripheral naming the role of the link rather than a SoftDevice handle; routing at a peripheral-role peer still reaches the other subscribed centrals, because BlueZ fans one notification out to every subscriber and the Columba service has a single notify characteristic. A reassembly discarded before completion is BLE_RX_ABANDON (#373) with iface=, peer=<hex8>, lost= (packets this frame cost) and total= (the link's running count) — the firmware's line of the same name is slot-keyed instead of identity-keyed, everything else matches. There is no lnsd counterpart of the firmware's BLE_CONN_PARAMS (#385), and the gap is in BlueZ rather than in this interface: the D-Bus Device1 interface publishes no connection interval, slave latency or supervision timeout — bluer's device properties (bluer 0.17.4, src/device.rs) run from Name and Rssi to ServicesResolved and BatteryPercentage and contain none of the three — and neither does sysfs, whose per-connection directory (/sys/class/bluetooth/hci<n>:<handle>) carries only uevent. The values exist one layer down, in the LE Connection Complete and LE Connection Update Complete events on the HCI transport, reachable only through an HCI monitor socket (what btmon reads) with the privileges that implies. So on a bench with an lnsd central the parameters are read from the capture or the central's kernel, as #385 did; on a link to a phone the board's line is the only source, which is why the firmware half exists. The same blindness applies to the answer lnsd gives: when a board asks its lnsd central for a longer supervision timeout (BLE_CONN_PARAMS_REQ), whether the kernel granted it is readable from the board's when=close line or from an HCI capture, and from nothing lnsd itself logs.

These are host events, so unlike the firmware's they do appear in EVENT_CATALOG and are schema-validated.

Reading "was the radio listening at instant X"

[SX_RX_ARM] is emitted at the SetRx that arms the SX1262, once per receive window:

[SX_RX_ARM] site=idle timeout_ms=0 dark_ms=3 t=123456

• t= is the instant the receiver went live. It is not derivable from the window's completion line: [T114_LORA_LOOP] op=rx_* duration_ms= brackets the whole receive() call, IRQ setup and buffer readout included, so t - duration_ms lands before the arming, not on it.
• dark_ms is the gap back to the previous window's end, computed on the board. The boot arm has no previous window and says dark_ms=first rather than a digit.
• site is which of the loop's six listening windows this is — idle, ack, csma, jitter, hold, yield — because their timeouts overlap and the length alone does not identify them.

The two together close the span: window n was listening from its own t= until t(n+1) - dark_ms(n+1). Everything outside those spans is standby, including CAD and TX. So the last window in a capture has no closing instant — its successor is what supplies it.

The line is written through log_fmt, so a board with nothing attached to the debug CDC (RUNTIME_DRAIN_OPEN == false) never formats it.

Reading a LINK_DIED age

LINK_DIED comes from the core (link_management.rs, target leviculum_core::link) and carries its age in milliseconds, to be read against the threshold_ms on the same line:

• elapsed_since_activity_ms is the time since the link's last inbound packet, and reads none for a link that never had one — every handshake that did not complete. There the expected number does not exist, and the raw subtraction would print the process uptime in its place: the field base of 2026-09-27 reported 91 responder culls as elapsed_since_activity_ms=9581430 beside threshold_ms=85824, for culls that were 72 to 90 s old and therefore on time (#354).
• since_request_ms appears on detail=handshake_timeout and is the age of the handshake itself, measured from the request — the initiator's send, the responder's proof. That is the clock establishment_timeout_ms() and hence threshold_ms is measured on, so those two are the pair to compare: a handshake culled on time shows a difference of one tick.

Validation behaviour

Two violation classes, both non-blocking — the original event line is never suppressed.

Schema violation (per-handle)

EVENT_SCHEMA_VIOLATION event=<NAME> missing=[a,b] caller=file:line t=<ms>

Emitted when a catalogued event misses required keys at emission. Each active handle's catalogue lookup chains the production EVENT_CATALOG with the handle's own extra_schemas, so test-only schemas don't pollute the production catalogue.

Field-value violation (per-event)

EVENT_FIELD_VIOLATION event=<NAME> field=<key> value_problem=<kind> caller=file:line t=<ms>

Emitted when a field's stringified value contains ASCII whitespace, =, or non-printable characters. Such values break the whitespace-tokenised parser used by Stage-7's jl --filter <key>=<value> filter. <kind> is one of whitespace, equals, non_printable.

The fix at the call site is to pick a value form that doesn't need escaping — substitute _ for spaces, drop = from value strings, etc. The original event line is still emitted; the tester sees the violation alongside, treats it as a bug.

User-named values: render them at the emission site

A value that can carry text a user chose — an interface name from the config file ([[TCP Uplink]]) or from discovery (autoconnect/Dark Doodad 23), a filesystem path, an instance name — is not a source bug when it contains a space: it is legitimate input that the EMISSION SITE has to render as a single token. Wrap it in leviculum_std::event_log::Scalar (or, inside leviculum-core, event_scalar::Scalar; the interface-name formatters IfaceName / IfaceNameOpt already do it for every iface = %… field):

#![allow(unused)]
fn main() {
tracing::debug!(event = "BLE_LINK_UP", iface = %Scalar(&self.name), …);
}

The sink still rescues an unwrapped value (sanitize_scalar), and for the handful of fields it can recognise as names by key (iface, iface_in, iface_out, in_iface, out_iface) it does so without raising a violation. That list cannot be completed from the sink side — next_hop carries an interface name at one site and a hash at another — so a name wrapped at the site is the only form that is correct at every field. Substitution, not quoting: jl, jldiff and every awk/grep one-liner split on whitespace, so a quoted value with a space is still several tokens to all of them.

Multi-process workflow

Spawned subprocesses (e.g. an lnsd child of an integration test) emit to a per-process file when given two env vars:

LEVICULUM_EVENT_LOG=/tmp/leviculum-events-<pid>.log \
LEVICULUM_EVENT_NODE=node-a \
    ./lnsd ...

• LEVICULUM_EVENT_LOG=<path> — child appends each event line (and any field-violations) to <path> as it emits. When unset, the subscriber writes only to the in-memory buffer used for panic-dump.
• LEVICULUM_EVENT_NODE=<name> — supplies the node= value.

After the children exit, the parent merges all per-process files:

#![allow(unused)]
fn main() {
use leviculum_std::test_support::event_log::merge_event_logs;
let merged: Vec<String> = merge_event_logs(&[
    PathBuf::from("/tmp/leviculum-events-12345.log"),
    PathBuf::from("/tmp/leviculum-events-12346.log"),
]);
}

merge_event_logs reads every input, parses the trailing t=<n> token of each line, and returns the union sorted by t (stable on tie). Lines without parseable t= sort to the end with their relative order preserved.

Per-process clock note: t= values are millisecond offsets from each subscriber's local init time, not a shared wall clock. Merged ordering is monotone across the union but doesn't directly say which real-world event came first across hosts. For wall-clock correlation add a per-emission timestamp field to the catalogue (ts=<unix-ms>) and sort on that instead.

Production-daemon integration

lnsd honours both env vars at startup via leviculum_std::test_support::event_log::install_global_subscriber(). When LEVICULUM_EVENT_LOG is unset, the install path is functionally equivalent to the previous tracing_subscriber::fmt().init() call — no event-log layer is built, so runtime overhead is whatever the fmt layer would otherwise impose.

rnsd is Python-side (reference/Reticulum); structured event capture for it is out of scope for the current Rust-side work.

See also

• Codeberg #39 piece 1 (this document's spec).
• leviculum-std/src/test_support/event_log.rs (implementation + catalogue).
• leviculum-std/src/test_support/tracing_setup.rs (Registry composition + Once-guard).
• leviculum-std/tests/event_log_subscriber.rs (unit tests).
• leviculum-std/tests/event_log_multiprocess.rs (multi-process merge integration test).
• Stage 7: jl / jldiff filter tools that consume this format.