Logging redesign — JSONL machine events + leveled stderr diagnostics#212
Merged
Conversation
Replace the ~37 organically-grown <devourer-*> XML-ish tags with a
two-plane logging system (docs/logging.md is the schema source of truth):
- Machine events: JSON Lines on stdout, one object per line, the event
name always serialized first ({"ev":"rx.txhit",...}) so shell consumers
can grep -F without a JSON parser. src/Event.h is the dependency-free
emitter (inline buffer + thread-local spill, 64 KiB cap with
"truncated":true, JSON escaping, hex/array helpers).
- Human diagnostics: stderr, `devourer [I] msg` (level letter T/D/I/W/E),
via the rewritten src/logger.h (new Trace level, EventSink member).
Both planes write each line with a single fwrite + fflush: per-line
atomicity across the RX/coex/TX threads, and a piped consumer (test
script, AI agent) sees every event at emission — no more libc
full-buffering stalls (tests/pipe_latency_check.py proves it on
hardware; setvbuf(_IOLBF) was not an option, MSVC full-buffers it).
The 44 scattered per-site fflush() calls are gone.
Production builds stop paying for verbosity: DEVOURER_LOG_MAX_LEVEL
(CMake: TRACE..SILENT) compiles trace/debug out entirely, including
argument evaluation at the new DVR_TRACE/DVR_DEBUG hot-path macros;
unset it derives from NDEBUG, preserving the old behavior. Runtime
level + event routing stay per-Logger — the library still reads no
environment; demos map DEVOURER_LOG_LEVEL / DEVOURER_EVENTS /
DEVOURER_EVENT_FLUSH in examples/common/env_config (apply_logging_env).
Migrated atomically (no compat layer): every library + demo emitter,
29 python consumers (via the new shared tests/devourer_events.py
parser), 41 shell scripts, and the docs. "Failed to send packet"
string-matching in regress.py is replaced by a structured tx.fail
event. Register dumps meant for kernel diffing (canary/bb/efuse/txpwr)
deliberately stay text on the diagnostic plane; canary_diff.py strips
the new prefix itself. sense and streamtx route events to stderr
(their stdout is a live display / data path).
Hardware-validated: regress 4/4 on ch6 (+ devourer cells on ch36),
bench_init, 5286 on-air rx.frame events with all fields, txpwr
regcheck 12 PASS / 0 FAIL (J2+J3), hop.dwell/hop.prof/hop.done,
canary extraction round-trip CLEAN, bf.report 2764 events vs 0 in the
unarmed control. ctest 12/12 incl. the new log_event_selftest;
INFO/SILENT compile-gate configs build clean.
Out-of-tree consumers grepping the old tags must migrate to the schema
in docs/logging.md.
Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
MSVC rejects the constant 0.0/0.0 NaN outright (C2124 hard error) — use std::numeric_limits<double>::quiet_NaN(). The mingw job builds an explicit target list, so every registered ctest binary must be named there; add LogEventSelftest (it was failing as "Not Run"). Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Capture::text() ended with an fread; the next event's fwrite to the same update stream without an intervening reposition is undefined (C11 7.21.5.3) — glibc tolerates it, msvcrt drops the write, failing the scratch-reuse check on mingw. fseek to EOF after reading. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Why
Devourer's log output grew out of debug sessions: ~37 hand-crafted
<devourer-*>tags that newcomers can't decode, python scripts scraping them with brittle regexes, 44 scatteredfflush()calls papering over pipe-buffering stalls (a subprocess supervisor — test script or AI agent — saw nothing until libc's 4 KiB buffer filled), and verbose debug output that production consumers paid for.What
Two planes (
docs/logging.mdis the schema source of truth):{"ev":"rx.txhit","hits":3,...}, event name always serialized first, sogrep -F '"ev":"rx.txhit"'needs no JSON parserdevourer [I] message(level letter T/D/I/W/E)src/Event.h— dependency-free JSONL emitter: 768 B inline buffer + reused thread-local spill, 64 KiB cap with"truncated":true, correct escaping, hex/array helpers. Onefwrite+fflushper line → per-line atomicity across the RX/coex/TX threads and immediate delivery through pipes.tests/pipe_latency_check.pyproves it on hardware (worst inter-arrival 0.51 s at a 0.5 s cadence throughsubprocess.PIPE).setvbuf(_IOLBF)was not an option — MSVC treats it as full buffering.src/logger.hrewritten —Tracelevel,events()sink accessor,DVR_TRACE/DVR_DEBUGmacros that elide argument evaluation, and a compile-time floor:-DDEVOURER_LOG_MAX_LEVEL=WARNcompiles trace/debug out entirely for production builds (unset = NDEBUG-derived, today's behavior).DEVOURER_LOG_LEVEL/DEVOURER_EVENTS=stdout|stderr|off/DEVOURER_EVENT_FLUSH=0inexamples/common/env_config(apply_logging_env).tests/devourer_events.pyparser), 41 shell scripts, docs.regress.pynow keys on a structuredtx.failevent instead of matching the"Failed to send packet"string.KIND 0xADDR = 0xVALUEtext on the diagnostic plane (kernel cross-validation format;canary_diff.pystrips the prefix itself,tools/canary_kernel_dump.shoutput unchanged).sense/streamtxroute events to stderr (their stdout is a live display / data path).Validation
log_event_selftest(escaping, spill, truncation,"ev"-first guarantee);DEVOURER_LOG_MAX_LEVEL=INFOand=SILENTconfigs build clean, bogus values rejected at configuretests/regress.py: 4/4 cells ch6; devourer cells 6300/6827 hits on ch36 (kernel-TX column ~0 there even kernel→kernel — kernel-side beacon weakness on 5 GHz, not a parsing regression)tests/pipe_latency_check.pyPASS (the core buffering complaint)tests/bench_init.py(init.timing), 5286 on-airrx.frameevents with all fields (c811→8813),txpwr_offset_regcheck.sh12 PASS / 0 FAIL (Jaguar2+3, incl. the 8822E 0x41e8 quirk cell), hop.dwell/hop.prof/hop.done on-air, canary stderr extraction →canary_diff.pyCLEAN,bf_selfsound_jaguar3.sh2764bf.reportevents vs 0 unarmedBreaking change
Out-of-tree consumers grepping the old
<devourer-*>tags must migrate to the event schema indocs/logging.md. Additive schema changes are safe going forward; renames need a consumer sweep like this one.Note:
tests/verify_stream_fields.shreferences a TP-Link 2357:0120 TX no longer on the rig (pre-existing drift); its assertion was validated manually with c811→8813.🤖 Generated with Claude Code