feat!: rework logging as macros, with rate limiting and a trace level - #76
Merged
Conversation
Logger held an owned string, a string_view either aliasing it or pointing at a literal, and a flag saying which, so the move operations were written by hand and their failure mode was a string_view left aliasing a moved-from string. One string halves the object, 48 bytes to 24, and defaults the moves. It costs an allocation for the two static names past libstdc++'s small-buffer limit, both process-lifetime singletons. The tests that went with it covered only the machinery: which constructor is noexcept, and the char array without a trailing NUL that was the one case telling the array constructor from the literal one.
log_level = "warning" is no longer accepted, and records that read WARNING now read WARN, so configs and any log tooling matching the old spelling need updating. "warn" is the conventional short form and puts the four levels on an even footing: debug, info, warn, error.
Rate limiting needs per-call-site state, and a function API cannot get it: the call site's identity reaches a function only as a value, never as something that can name a distinct object. A macro expands at the call site, so a static there belongs to that statement alone. Converting everything now rather than mixing two spellings later. The macros take the logger explicitly, so the per-object loggers carrying "RawSocket:eth0" and "DialProxy:tv:src->dst" are unchanged. The level gate lives at the call site, so a filtered record no longer evaluates its arguments: Interface::Refresh's Debug line was building three address strings on every refresh at the default Info level, and raw_socket built an Error::FromErrno for three suppressed lines. Emit replaces the four per-level methods, which would otherwise be public and ungated.
Emit was a template, so the entire record builder was instantiated once per combination of argument types: localtime_r, strftime, both format calls and the fwrite, copied 86 times across the tree. Type-erasing the arguments through make_format_args leaves each call site with just the argument array to build, and the builder compiles once. Release text drops from 425,984 to 376,832 bytes, around 10% of the stripped binary, measured on an arm64 LTO build. std::format has no vformat_to_n, so bounding the message buffer needs an output iterator of our own to keep truncation working.
A failure that recurs per packet or per peer floods the log and buries everything else. NFL_LOG_WARN_RATE and NFL_LOG_ERROR_RATE emit at most once per window per call site, count what they swallow, and disclose the count on the next line that gets through. The window is a consteval constructor argument, so a site cannot pass one that varies between calls, and the gate is constant-initialized rather than carrying a thread-safe init guard, and its atomic load, into every call. MonotonicSecs is one-based, which leaves 0 to mean "nothing emitted yet" even for a daemon that logs during its first second of uptime, and makes the window arithmetic underflow-free without a guard. The disclosure is interpolated into the record rather than appended to the message, so a message long enough to be truncated cannot take it down with it, and an ordinary log never tests for one.
One inbound packet produces one of these lines, so a peer sets the rate: the oversized-frame drops in both capture backends, the reflect failures in each reflector, and the session, connection and reservation caps. One window for all of them, so what survives is a coherent sample rather than a scatter of sites whose windows opened at different times. Nothing else is gated. A socket that will not open or a group that will not join reports at the rate we chose to retry it, which is a rate worth seeing. Ten tests asserted a gated line reached stdout beside an assertion of the behaviour that produced it. A gate outlives the test that trips it, so those passed only in the order they happened to run; the log assertions go.
Trace is for the detail that only matters when reconstructing what the daemon did, so a release build drops those statements rather than testing a level for them: NDEBUG lowers a compile-time floor the macros check before anything else. The arguments still compile, so a Trace line cannot rot in the configuration that leaves it out. Off completes the set the config file accepts. Both levels parse from the file and from REFLECTOR_LOG_LEVEL, which share a parser. No site logs at Trace yet.
Debug now means one line per lifecycle event: an interface resolved, a group joined, a capture re-bound. Everything that fires per packet, per fd operation or per address examined moved to trace, which a release build does not carry. The new lines are mostly address selection: which v4 won, which v6 took the source or routable slot and at what rank, and what the flags filtered out. That reasoning was invisible before, and it decides what the daemon can send from.
Sixteen tests asserted a line reached stdout beside an assertion that already pinned the behaviour producing it: a reflector left invalid, a registration count unchanged, a payload forwarded byte for byte. Log text is not a contract and the assertions break on ordering once a site is rate limited, so the behavioural assertion is the one to keep. The rest stay. A logger test asserting its own output has nothing else to look at, and a name in the record does not prove the message after it survived.
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
Rate limiting needs per-call-site state, and a function API cannot have it: a
call site's identity reaches a function only as a value, never as something that
can name a distinct object. A macro expands at the call site, so a
staticthere belongs to that statement alone.
log_level = "warning"stops parsing; it iswarnnow.traceandoffare new.Choices worth flagging
The rate window is a
constevalconstructor argument. A template parameterenforces the same thing but instantiates
Admitper distinct window, ~259 bytesa site in Debug for no Release gain. A
constexprlocal works but leavesguard-freedom depending on that local surviving later edits.
constevalmakes aruntime window a compile error by the language's own rule, and the gate stays
constant-initialized, so no site carries a thread-safe init guard.
Only 12 sites are gated. An earlier pass gated 78, everything that could
repeat. That reads worse: 78 independent windows means the surviving lines opened
at unrelated moments and the sequence no longer reconstructs. Gated now are the
lines a peer emits one-for-one with packets. Repair paths still log once per
retry, a rate we chose and one worth seeing.
IpAddress::ToCharsis not gated despite being hot: it runs inside thelogger's own formatters, so a gate would put rate-limit state in the middle of
formatting a record.
Trace is absent from release objects, not skipped.
NDEBUGlowers acompile-time floor the macros check first, so the statement and its literal are
gone. The arguments still compile, so a trace line cannot rot in the build that
omits it.
26 tests lost a log assertion. A gate is a static that outlives the test
tripping it, so those passed only in the order they ran. Each sat beside an
assertion of the behaviour that produced the line, which is what remains. The
other 74 were audited and kept: a logger test asserting its own output has
nothing else to look at, and a name in a record does not prove the message after
it survived.