Logging redesign — JSONL machine events + leveled stderr diagnostics

.github/workflows/cmake-multi-platform.yml

@@ -148,7 +148,7 @@ jobs:
           devourer streamtx duplex StreamStdinSelftest
           ToneMaskSelftest BfReportDecodeSelftest SweepSpecSelftest
           TxPowerQuantSelftest LinkHealthSelftest TxCapsSelftest TxPktPwrSelftest
-          RxQualitySelftest AdapterHealthSelftest
+          RxQualitySelftest AdapterHealthSelftest LogEventSelftest
 
       - name: Test
         working-directory: build

CLAUDE.md

@@ -86,8 +86,8 @@ rows are not authoritative for LDPC/STBC — that driver strips those bits),
 `--keep-logs` puts per-cell logs at `/tmp/devourer-regress-last/`. Full
 semantics: `tests/README.md`.
 
-Startup-time benchmarking: `tests/bench_init.py` (per-stage `init-timing:`
-lines from `src/InitTimer.h`; methodology + numbers in `docs/startup-time.md`).
+Startup-time benchmarking: `tests/bench_init.py` (per-stage `init.timing`
+events from `src/InitTimer.h`; methodology + numbers in `docs/startup-time.md`).
 On-air TX throughput: measure **Mbps via SDR duty × PHY rate**
 (`tests/bench_onair.py`), never monitor-sniffer frame counts — a sensitive
 receiver decodes weak frames and masks a real drop. Keep a known-good control
@@ -105,6 +105,25 @@ survive re-enumeration, temp-blacklist instead; and `authorized`-toggle
 "cold" leaves chip state (real VBUS cold via `REGRESS_VBUS_MAP` /
 uhubctl — never on xhci root ports on this rig).
 
+## Logging
+
+Two planes (`docs/logging.md` is the schema source of truth): **machine events**
+= JSON Lines on stdout, one object per line, first field always
+`{"ev":"<name>",...}` — so `grep -F '"ev":"rx.txhit"'` works without a JSON
+parser, and `tests/devourer_events.py` (`iter_events`/`parse_event`) is the
+python helper every test script uses. **Human diagnostics** = stderr,
+`devourer [I] msg` (level letter T/D/I/W/E). Every line is written with one
+fwrite + flush, so piped consumers never stall on buffering and threads never
+interleave mid-line. `2>/dev/null` gives a pure event stream.
+
+Demo knobs: `DEVOURER_LOG_LEVEL=trace..silent` (stderr verbosity, default
+debug), `DEVOURER_EVENTS=stdout|stderr|off`, `DEVOURER_EVENT_FLUSH=0`
+(max-rate benches). Compile-time floor: `-DDEVOURER_LOG_MAX_LEVEL=WARN`
+compiles trace/debug out entirely (args included at `DVR_TRACE`/`DVR_DEBUG`
+sites) for production builds; unset = NDEBUG-derived. Exceptions kept as
+diffable text on the diagnostic plane: canary / bb / efuse / txpwr register
+dumps (kernel cross-validation format).
+
 ## Configuration
 
 **The library reads no environment.** Construction-time knobs live in
@@ -155,7 +174,7 @@ Knob-specific facts that aren't obvious from the field docs:
   saves/restores `0x808`). Toggle spec `0xAA:0xBB[:0xCC]@<ms>` cycles masks on
   a timer for mobility/MRC measurements (`docs/measuring-spatial-diversity.md`,
   `tests/mrc_mobility.py`). `DEVOURER_RX_ALLPATHS=1` emits per-chain
-  RSSI/SNR/EVM on a separate `<devourer-rxpath>` tag (C/D nonzero only on the
+  RSSI/SNR/EVM as a separate `rx.path` event (C/D nonzero only on the
   8814AU).
 - `DEVOURER_RX_CSI_MASK` / `DEVOURER_RX_NBI` (RX per-tone equalizer mask /
   narrowband notch, `src/ToneMask.h`) apply at RX-loop start and revert on a
@@ -166,7 +185,7 @@ Knob-specific facts that aren't obvious from the field docs:
   `crc_err`/`icv_err` set — the entry point for the fused-FEC salvage layer
   (`docs/fused-fec.md`). Opt-in: a body with a corrupt tail is the worst-case
   input for an IP-stack consumer that didn't ask for it.
-- `DEVOURER_THERMAL_POLL_MS=N` emits `<devourer-thermal>` lines from the RF
+- `DEVOURER_THERMAL_POLL_MS=N` emits `thermal` events from the RF
   0x42 meter: `raw` is 0..63 thermal units (~1.5–2 °C each, **not** absolute
   °C — hence bucketed status, not a fake temperature), `delta` = raw −
   EFUSE baseline. Jaguar1 has no hard thermal TX shutdown — a rising delta is
@@ -306,6 +325,6 @@ dev->send_packet(buffer, len);  // buffer[0..] = radiotap header, then 802.11
 
 The canonical test beacon (`examples/tx/main.cpp`) uses SA
 `57:42:75:05:d6:00` — the same constant is hardcoded into
-`examples/rx/main.cpp` as the `<devourer-tx-hit>` matcher and into
+`examples/rx/main.cpp` as the `rx.txhit` event matcher and into
 `tests/regress.py` (`CANONICAL_SA`). Change all three together if it ever
 moves.

CMakeLists.txt

@@ -26,6 +26,24 @@ option(DEVOURER_JAGUAR2_8821C "RTL8811CU / 8821CU (Jaguar2, rtl8821c, 1T1R)"
 option(DEVOURER_JAGUAR3_8822C "RTL8812CU / 8822CU (Jaguar3, rtl8822c)"          ON)
 option(DEVOURER_JAGUAR3_8822E "RTL8812EU / 8822EU (Jaguar3, rtl8822e)"          ON)
 
+# Compile-time diagnostics floor (src/logger.h). Calls below the floor —
+# including their argument expressions at DVR_TRACE/DVR_DEBUG sites — compile
+# to nothing. Empty (the default) keeps the NDEBUG-derived behavior: release
+# builds drop trace/debug, debug builds keep everything. Example production
+# firmware build: -DDEVOURER_LOG_MAX_LEVEL=WARN
+set(DEVOURER_LOG_MAX_LEVEL "" CACHE STRING
+    "Compile-time log floor: TRACE, DEBUG, INFO, WARN, ERROR or SILENT (empty = NDEBUG-derived)")
+set_property(CACHE DEVOURER_LOG_MAX_LEVEL PROPERTY STRINGS
+    "" TRACE DEBUG INFO WARN ERROR SILENT)
+if(NOT DEVOURER_LOG_MAX_LEVEL STREQUAL "")
+    set(_devourer_ll_valid TRACE DEBUG INFO WARN ERROR SILENT)
+    if(NOT DEVOURER_LOG_MAX_LEVEL IN_LIST _devourer_ll_valid)
+        message(FATAL_ERROR
+            "DEVOURER_LOG_MAX_LEVEL=${DEVOURER_LOG_MAX_LEVEL} — must be one of "
+            "TRACE, DEBUG, INFO, WARN, ERROR, SILENT (or empty).")
+    endif()
+endif()
+
 if(DEVOURER_8814 AND NOT DEVOURER_JAGUAR1)
     message(FATAL_ERROR
         "DEVOURER_8814=ON requires DEVOURER_JAGUAR1=ON (8814 reuses the Jaguar1 HAL).")
@@ -57,6 +75,7 @@ pkg_check_modules(libusb REQUIRED IMPORTED_TARGET libusb-1.0)
 add_library(devourer
     # --- generation-agnostic core (always compiled) ---
     src/logger.h
+    src/Event.h
     hal/basic_types.h
     hal/hal_com_reg.h
     src/ieee80211_radiotap.h
@@ -99,6 +118,13 @@ add_library(devourer
 
 target_compile_features(devourer PUBLIC cxx_std_20)
 
+# PUBLIC: logger.h is header-only, so the library and its consumers must agree
+# on the compile-time log floor (ODR).
+if(NOT DEVOURER_LOG_MAX_LEVEL STREQUAL "")
+    target_compile_definitions(devourer PUBLIC
+        DEVOURER_LOG_MAX_LEVEL=DEVOURER_LL_${DEVOURER_LOG_MAX_LEVEL})
+endif()
+
 # Link devourer with libusb as found via pkg-config.
 target_link_libraries(devourer PUBLIC PkgConfig::libusb)
 
@@ -347,6 +373,16 @@ target_link_libraries(ToneMaskSelftest PRIVATE devourer)
 
 add_test(NAME tone_mask_math COMMAND ToneMaskSelftest)
 
+# Headless guard for the JSONL event emitter (src/Event.h) — the machine
+# event stream every test script parses (docs/logging.md): first-field
+# serialization guarantee, escaping, spill + truncation paths.
+add_executable(LogEventSelftest
+    tests/log_event_selftest.cpp
+)
+target_link_libraries(LogEventSelftest PRIVATE devourer)
+
+add_test(NAME log_event_json COMMAND LogEventSelftest)
+
 # Headless guard for the sweep/hop bin-list grammar (src/SweepSpec.h) — the
 # channel-list / channel-range / MHz-range parsing behind DEVOURER_RX_SWEEP and
 # DEVOURER_HOP_CHANNELS, so a grammar regression fails `ctest` instead of only

docs/adapter-doctor.md

@@ -42,7 +42,7 @@ build/doctor --bus 3 --port 2.3.3  # topology select (two same-PID adapters)
    (same trap as [startup-time](startup-time.md) benchmarking).
 
 Verdict → exit code: `HEALTHY`=0, `SUSPECT`=1, `FAILING`=2 (3 = tool /
-open error), plus a `<devourer-doctor>` machine line and per-reason
+open error), plus a `doctor.verdict` machine event and per-reason
 text. The classifier is pure logic (`src/AdapterHealth.h`, ctest'd in
 `tests/adapter_health_selftest.cpp`); grading rules and their
 rationale live next to the code.

docs/beamforming-victim-sensing.md

@@ -200,7 +200,7 @@ DEVOURER_PID=0x8812 DEVOURER_CHANNEL=6 DEVOURER_TX_RATE=VHT2SS_MCS0 \
   DEVOURER_TX_NDPA_RA=<beamformee-MAC> DEVOURER_TX_NDPA=1 \
   DEVOURER_BF_ARM_SOUNDER=1 DEVOURER_TX_WITH_RX=thread \
   DEVOURER_BF_DETECT_REPORT=4 DEVOURER_TX_GAP_US=4000 \
-  ./build/txdemo 2>/dev/null | grep '<devourer-bf-report-raw>' > cap.raw
+  ./build/txdemo 2>/dev/null | grep -F '"ev":"bf.report_raw"' > cap.raw
 ```
 
 Beamformee (the client), on its adapter:

docs/bench-testing-near-field.md

@@ -65,7 +65,7 @@ multipath-desense regime.
    `rxdemo` classifies each window and says so in plain language:
 
    ```
-   <devourer-linkhealth>verdict=SATURATED rssi_dbm=-33 snr_db=19.5 evm_db=-22.5
+   {"ev":"link.health","verdict":"SATURATED","rssi_dbm":-33,"snr_db":19.5,"evm_db":-22.5,
      cause="strong RSSI but poor EVM — receiver front-end overload and/or the
      strong signal self-jamming via reflections (near-field). SNR alone can
      look fine here"
@@ -78,7 +78,7 @@ multipath-desense regime.
    antenna is the answer. If it says `SATURATED`, the answer is the opposite —
    and no amount of antenna tuning will fix a receiver that is clipping.
 
-## The link doctor (`<devourer-linkhealth>`)
+## The link doctor (the `link.health` event)
 
 `src/LinkHealth.h` maps the RX sensor tuple to one of: `SATURATED`,
 `INTERFERENCE`, `WEAK`, `MARGINAL`, `HEALTHY`, `NO_SIGNAL`, each with a

docs/frequency-hopping.md

@@ -306,7 +306,7 @@ every generation overrides it with a lean path built from the tricks above:
 | RTL8822CU (Jaguar3) | ~12 ms | **~1.9 ms** | ~0.21 ms | 9 |
 | RTL8812EU (Jaguar3) | ~12 ms | **~2.4 ms** | ~0.27 ms | 9 |
 
-(Median `<devourer-hop>switch_us` over a 1/6/11 hop set; per-stage numbers from
+(Median `hop.dwell` switch_us over a 1/6/11 hop set; per-stage numbers from
 `DEVOURER_HOP_PROF=1`. Every hop microsecond is USB round-trips: one register
 read or write is one synchronous control transfer, whose latency is a property
 of the chip's EP0 handling — it varies 5× across the family — so the only code

docs/fused-fec.md

@@ -211,7 +211,7 @@ for both receivers. Only the receiver — and thus the inner decode — differs:
 | `svc_spatial_uep_sim.py` | per-SVC-layer spatial UEP — the 3-axis staircase (MCS + FEC + STBC), quantifying the spatial knob's survival-SNR contribution |
 | `spatial_sbi_sim.py` | spatial diversity keeps corruption localized — how combining (by fade correlation ρ) moves frames out of the frame-wide-loss bin into the SBI-salvageable one |
 | `fused_fec_link.py` | chip-path `FusedFecSender` / `FusedFecReceiver` (baseline-vs-SBI) |
-| `fused_fec_tx.py` / `fused_fec_rx.py` | chip-path CLIs (bytes ↔ `streamtx` / `<devourer-stream>`) |
+| `fused_fec_tx.py` / `fused_fec_rx.py` | chip-path CLIs (bytes ↔ `streamtx` / `rx.frame` events) |
 | `fec_fusion_sim.py` | offline simulation: quantify SBI gain, size sub-blocks, no hardware |
 | `soft_erasure_fec.py` | errors-and-erasures Reed-Solomon (BCH form) + soft-reliability GMD; the reference that quantifies the inner-vs-outer soft-information question |
 | `fec_ab_sim.py` | the SBI-vs-plain-block-FEC A/B over measured channels (does SBI beat just adding parity, at equal overhead?) |

docs/logging.md

@@ -0,0 +1,160 @@
+# Logging
+
+Devourer's output is split into two planes:
+
+| Plane | Stream | Format | Audience |
+|---|---|---|---|
+| **Machine events** | stdout | JSON Lines — one JSON object per line | test scripts, AI agents, telemetry consumers |
+| **Human diagnostics** | stderr | `devourer [I] message` (level letter T/D/I/W/E) | people debugging |
+
+`rxdemo 2>/dev/null` therefore yields a pure JSONL stream; `2>&1` into one log
+is also safe — event parsers skip non-event lines.
+
+## The event contract
+
+Every event line serializes the event name **first**, exactly:
+
+```json
+{"ev":"rx.txhit","hits":3,"total_rx":10,"len":247}
+```
+
+so shell consumers may `grep -F '"ev":"rx.txhit"'` without a JSON parser, and
+everything richer goes through `json.loads` — see `tests/devourer_events.py`
+(`iter_events` / `parse_event`), the shared helper the python test scripts use.
+
+Conventions:
+
+- Event names are lowercase dotted namespaces (`rx.frame`, `txpwr.state`).
+- Register addresses/values/masks are hex **strings** (`"addr":"0x0808"`).
+- Per-chain metrics are arrays (`"rssi":[-52,-60]`).
+- A field the chip can't provide is JSON `null` (the old text format used `-`).
+- `t` is monotonic **ms since process start**; periodic/marker events carry it,
+  per-frame events rely on `seq`/`tsfl` instead.
+- Byte blobs (frame bodies, C2H payloads) are lowercase hex strings.
+- A line is hard-capped at 64 KiB: an overflowing field is dropped (→ `null`)
+  and `"truncated":true` is appended.
+
+Emission is a single `fwrite` of the complete line followed by `fflush`
+(`src/Event.h`) — per-line atomicity across threads (RX loop / coex / TX), and
+a piped consumer (python subprocess, AI agent) sees each event immediately;
+there is no libc full-buffering stall. `DEVOURER_EVENT_FLUSH=0` drops the
+per-line flush for max-rate benches.
+
+## Demo environment knobs
+
+Mapped in `examples/common/env_config.cpp` (`apply_logging_env`); the library
+itself reads no environment — programmatic consumers configure the same things
+on the `Logger` object (`set_level`, `set_diag_stream`, `events().configure`).
+
+| Var | Values | Meaning |
+|---|---|---|
+| `DEVOURER_LOG_LEVEL` | `trace`,`debug` (default),`info`,`warn`,`error`,`silent` | stderr diagnostic verbosity |
+| `DEVOURER_EVENTS` | `stdout` (default), `stderr`, `off` | event-stream destination — `sense` and `streamtx` default to stderr themselves (their stdout is a display / data path) |
+| `DEVOURER_EVENT_FLUSH` | `0` | disable per-event flush |
+
+## Compile-time gating
+
+`DEVOURER_LOG_MAX_LEVEL` (CMake cache var: `TRACE`/`DEBUG`/`INFO`/`WARN`/
+`ERROR`/`SILENT`) is the compile-time floor: calls below it — including their
+argument expressions at `DVR_TRACE`/`DVR_DEBUG` macro sites — compile to
+nothing. Unset, the floor derives from `NDEBUG`: release builds drop
+trace/debug, debug builds keep everything. Production firmware build:
+
+```sh
+cmake -S . -B build -DDEVOURER_LOG_MAX_LEVEL=WARN
+```
+
+Hot-path trace/debug sites in the library go through `DVR_TRACE(logger, ...)`
+/ `DVR_DEBUG(logger, ...)` so a disabled level also skips evaluating the
+arguments (one branch). `info/warn/error` are plain `logger->` methods.
+
+## Event schema
+
+Emitters: L = library, RX/TX/... = demo. Optional fields in [brackets];
+`|null` marks fields that go null when the chip doesn't expose them.
+
+### Init / infrastructure
+| ev | emitter | fields |
+|---|---|---|
+| `init.timing` | L (`src/InitTimer.h`) + demos | stage ("scope.stage", e.g. "demo.first_rx_frame", "txdemo.first_tx_submit"), ms |
+| `debug.wreg` | L (`DEVOURER_LOG_WRITES`) | addr "0x0nnn", width, val "0x…" |
+| `hop.prof` | L (`DEVOURER_HOP_PROF`) | gen, ch, `<stage>_us`…, total_us |
+| `tx.fail` | L (send failure; regress.py keys on it) | {status, actual_len, timeout} or {rc, timeout} |
+
+### RX plane
+| ev | emitter | fields |
+|---|---|---|
+| `rx.pkt` | RX | n, len (first 10 + every 100th frame) |
+| `rx.frame` | RX (`DEVOURER_STREAM_OUT`), duplex | rate, len, crc, icv, rssi[2], evm[2], snr[2], seq, tsfl, bw, stbc, ldpc, sgi, body hex |
+| `rx.body` | RX (`DEVOURER_DUMP_BODY`) | rate, rssi[2], evm[2], snr[2], crc, len, body hex |
+| `rx.corrupt` | RX (`DEVOURER_RX_DUMP_ALL`) | len, crc, icv, rate, bw, stbc, ldpc, sgi, rssi[2], evm[2], snr[2] |
+| `rx.txhit` | RX, TX | hits, total_rx, len — canonical-SA (57:42:75:05:d6:00) matcher |
+| `rx.count` | TX (its RX thread) | total, len |
+| `rx.path` | RX (`DEVOURER_RX_ALLPATHS`) | seq, rssi[4], snr[4], evm[4] |
+| `rx.path_mask` | L (toggle spec) | t, mask "0xNN" |
+| `rx.scrambler` | RX (`DEVOURER_DUMP_SCRAMBLER`) | seed "0xNN", rate, hits, len |
+| `rx.energy` | RX (`DEVOURER_RX_ENERGY_MS` / sweep) | t, [ch], cca_ofdm\|null, cca_cck\|null, fa_ofdm\|null, fa_cck\|null, igi\|null, [retune_us], frames, rssi_mean, rssi_max, snr_mean, snr_min, evm_mean |
+| `rx.nhm` | RX | [ch], peak, busy, dur, hist[12] |
+| `rx.quality` | RX (`DEVOURER_RXQUALITY`) | verdict, frames, rssi_mean_dbm, rssi_max_dbm, snr_mean_db, snr_min_db, evm_db\|null, noise_floor_dbm\|null, igi |
+| `link.health` | RX (`DEVOURER_LINKHEALTH`) | verdict, rssi_dbm, snr_db, evm_db\|null, frames, fa_ofdm\|null, igi\|null, [igi_floor], [igi_ceil], cause, fix |
+| `fw.c2h` | RX, duplex (`DEVOURER_TX_STATUS`) | len, bytes hex |
+
+### TX plane
+| ev | emitter | fields |
+|---|---|---|
+| `tx.frame` | TX | n, rc — precoder demo variant: n, ok |
+| `tx.stats` | TX | submitted, failed, was_timeout, last_rc |
+| `tx.status` | RX, duplex (C2H TX_RPT decode) | hoff, queue, retry, airtime_us, rate |
+| `tx.queue` | RX (`DEVOURER_QUEUE_POLL_MS`, 8814) | q1…q5 "0x%08x" |
+| `tx.contx` | TX (continuous mode) | mcs, t_ms |
+
+### TX power / thermal
+| ev | emitter | fields |
+|---|---|---|
+| `txpwr.set` | TX | index, t_ms |
+| `txpwr.readback` | TX | index, cck1m, ofdm6m, mcs7, rb |
+| `txpwr.state` | txpower | flat, offset_qdb, steps, satlo, sathi, cck, ofdm, mcs7, rb |
+| `txpwr.caps` | txpower | supported, max, step_qdb, step_measured, min_qdb, max_qdb |
+| `txpwr.offset` | txpower | requested, applied |
+| `thermal` | RX, TX, txpower | t, raw, baseline\|null, [delta], status |
+
+### Hopping
+| ev | emitter | fields |
+|---|---|---|
+| `hop.dwell` | TX, duplex | dwell, round, channel, frame, switch_us, t_ms, [mode] |
+| `hop.done` | TX, duplex | frames, dwells |
+
+### Beamforming / CSI
+| ev | emitter | fields |
+|---|---|---|
+| `bf.report` | BfReportDetect.h | kind, n, sa, nc, nr, bw, ng, len |
+| `bf.any` | BfReportDetect.h | fc "0xNNNN", cat, act, crc, len |
+| `bf.report_raw` | BfReportDetect.h, sense (stderr) | frame hex |
+| `bf.csi` | BfReportDetect.h (mode 3) | len, csi hex |
+| `csi.hit` / `csi.wedged` | RX (`DEVOURER_RX_DUMP_CSI`) | hit, selector "0x…", value "0x…" / selector |
+
+### Stream demos / misc
+| ev | emitter | fields |
+|---|---|---|
+| `stream.rx` / `stream.ctl` / `stream.eof` / `stream.tx` | duplex (stdout), streamtx (stderr) | hits / op, len / tx_count, [bytes] / n, ok, psdu, [total] |
+| `stream.done` | streamtx (stderr) | sent |
+| `svc.stats` | svctx | frames, crit, t0, t1, t2, t3plus |
+| `doctor.verdict` | doctor | verdict, reasons "0x…", efuse_reads, efuse_mismatch, efuse_bad_id, efuse_id, fw_attempted, fw_ready, rx_ok, rx_crc, init |
+
+## Not JSON by design
+
+Register dumps meant for line-by-line diffing against kernel output keep their
+text format on the **diagnostic plane** (stderr, `devourer [I] ` prefix):
+the `DEVOURER_DUMP_CANARY` canary block (`KIND 0xADDR = 0xVALUE`, matching
+`tools/canary_kernel_dump.sh` / `iwpriv read`; `tests/canary_diff.py` strips
+the prefix itself), `DEVOURER_BB_DUMP`, `DEVOURER_EFUSE_DUMP`,
+`DEVOURER_LOG_TXPWR`. The doctor tool's human report stays on stdout — its
+machine summary is the `doctor.verdict` event.
+
+## Schema stability
+
+Event names and listed fields are an interface: test scripts and out-of-tree
+consumers (OpenIPC integrations) parse them. Additive changes (new fields, new
+events) are safe; renames/removals need the same-PR consumer sweep this schema
+landed with. This table is the source of truth — update it with any emitter
+change.