Skip to content

Apply LOG_LEVEL as a threshold across the resolver and both daemons - #11

Merged
andylemin merged 4 commits into
masterfrom
logging-levels
Sep 3, 2026
Merged

Apply LOG_LEVEL as a threshold across the resolver and both daemons#11
andylemin merged 4 commits into
masterfrom
logging-levels

Conversation

@andylemin

@andylemin andylemin commented Sep 3, 2026

Copy link
Copy Markdown
Owner

LOG_LEVEL: ERROR still emitted per-query informational logs, on the resolver
and on both daemons. Three separate causes, all of which the shipped configs
trigger.

The resolver never applied LOG_LEVEL at all

The only test of its value anywhere in pfui_unbound.py was == "DEBUG". Eight
informational lines were therefore gated on LOGGING alone and printed at every
level, and eight more had no guard at all and printed even with
LOGGING: False:

pythonmod: operate, id: 0, module_event_pass
PFUIDNS: Sending '{...}' to /var/run/pfui/pfui_firewall.sock
PFUIDNS: www.example.com. Found IPv4 address 93.184.216.34

The shipped pfui_unbound.yml sets LOGGING: True with LOG_LEVEL: ERROR,
which is precisely the combination that emits them, so every install did this.

Unbound injects log_info and log_err into the embedded interpreter and both
write unconditionally, so there is no framework doing the filtering and the
module has to do it itself. log_at(level) is that filter and all 22 sites now
name a severity. log_err stays ungated: the level chooses how much detail
accompanies a fault, not whether faults are reported.

server-python escaped this because it uses stdlib logging with setLevel(),
and the Rust daemon because Logger::info suppresses at ERROR.

Two of those lines were failures, not chatter

Gating them at DEBUG would have traded per-query noise for a dead firewall
invisible at the default level, so they are errors now.

Line Was Now
no acknowledgement from {target}, last was ... log_info, ungated log_err
Timeout udp receive - all retries log_info, ungated log_err

The daemons' reply line ignored LOGGING

Close msg: ACKUPDATE was the one per-message line in either daemon not gated on
LOGGING; the Rust daemon inherited it from the Python reference. The installers
ship LOGGING: False with LOG_LEVEL: DEBUG, so both wrote a syslog line per
DNS answer while verbose logging was nominally off. It is duplicative too: a
refusal is already reported at error level with its reason, and a success by the
gated PF Table updated line. A test asserts the refusal path still leaves a
trace with logging off, so the gate cannot hide why a message was rejected.

LOG_LEVEL was case-sensitive everywhere

The Rust daemon matched raw yml text while the CTL match directly below it
trims and folds case, so debug fell through to the catch-all and silently
selected ERROR. The Python daemon compared raw text the same way, self.stats
included. Both normalise now, and the resolver says so out loud when a value is
unrecognised, because the symptom of a typo is silently quieter logs.

Two gaps that would have made the fix look wrong

  • log_at("INFO") had no call sites, so INFO would have behaved identically to
    ERROR while the yml advertises it for testing.
  • The circuit breaker logged opening at error level and closing silently, so an
    operator watched a firewall leave and never saw it return. Recovery is now the
    INFO tier's content, reported on the transition only, never per successful
    query.

What each level gives you

Level Output
ERROR (default) Faults only: refusals with their likely cause, breaker trips, socket errors
INFO Plus operational transitions, such as a firewall acknowledging again
DEBUG Plus per-query detail, the RR dump, and the Query Unblocked latency line

Documentation

BLOCKING had no prose, only two example lines that read like something to opt
into. It is the default. The new section separates what it governs — a freshly
resolved answer waits for ACKUPDATE, a cache hit does not wait whatever the
setting is, because a positive cached answer implies access was already allowed
by the rr report that released it and the cache report only resets the TTL. A
test pins that, and the behaviour is unchanged. The latency figure is scoped to
the round trip it measures, since it was being read as a general number.

The blocklist example now prefers HaGeZi's lists, with a tier table. HaGeZi
publishes no /etc/hosts format, so unbound-adblock's -l/-u do not apply
and the domain-only lists go in through -d/-t. Two further paths do not work
and are called out: the adblock/ directory carries ABP filter syntax, which
unbound-adblock does not parse, and the plain wildcard/*.txt files carry *.
wildcards. Only the -onlydomains variants are usable.
tools/update_dns_blocklist.sh still fetches StevenBlack in hosts format, which
the section notes rather than papers over.

Testing

  • 246 Python tests, 100 Rust unit tests, framing and message vector suites clean
  • Each new test verified failing against the old behaviour first: the threshold
    test fails if log_at returns unconditionally, the error-visibility test if
    no acknowledgement returns to log_info, the daemon test if Close msg
    loses its gate
  • One test caught a real inconsistency while being written — load_config
    stripped whitespace from LOG_LEVEL but log_at did not, so " DEBUG " was
    honoured at load and ignored at use

Follow-ups, not in this change

  • pfui_wire.py imports lz4.frame unconditionally, so COMPRESS: False does
    not make the package optional the way it is meant to
  • COMPRESS is one global key per end, so it cannot be off for a local socket
    and on for a remote resolver
  • On the stream transports the client reads its reply until EOF, and the daemon
    closes only after Redis and the persist write, so a blocking query appears to
    wait for work the PF → ACKUPDATE → Redis → persist ordering exists to exclude

Andy Lemin added 4 commits September 4, 2026 00:37
LOG_LEVEL was never compared against a threshold. The only test of its value
anywhere was == "DEBUG", so eight informational lines were gated on LOGGING
alone and printed at every level, and eight more had no guard at all and
printed even with LOGGING: False. The shipped pfui_unbound.yml sets
LOGGING: True with LOG_LEVEL: ERROR, which is exactly the combination that
emits per-query output, so every install did this:

    pythonmod: operate, id: 0, module_event_pass
    PFUIDNS: Sending '{...}' to /var/run/pfui/pfui_firewall.sock
    PFUIDNS: www.example.com. Found IPv4 address 93.184.216.34

Unbound injects log_info and log_err into the interpreter and both write
unconditionally, so there is no framework to filter them and the module has to
do it itself. log_at() is that filter, and every site now names a severity.
log_err stays ungated throughout: the level chooses how much detail accompanies
a fault, not whether faults are reported.

Two of the unguarded lines were failures rather than chatter, so gating them at
DEBUG would have traded per-query noise for a dead firewall invisible at the
default level. Those are errors now: an unacknowledged send and a UDP receive
that exhausted its retries.

LOG_LEVEL is also normalised and checked when the config loads, because the
symptom of a typo is silently quieter logs.

Two further gaps closed while auditing, either of which would have made the
change look wrong:

  - log_at("INFO") had no call sites, so INFO would have behaved identically to
    ERROR while the yml advertises it for testing.
  - The circuit breaker logged opening at error level and closing silently, so
    a firewall was seen leaving and never coming back. Recovery is the INFO
    tier's content, reported on the transition only, not per successful query.

The cache-report path gains a docstring and a test recording why it does not
honour BLOCKING: a positive cached answer implies access was already allowed by
the rr report that released it, so the report only resets the TTL. Behaviour
there is unchanged.
"Close msg: ACKUPDATE" was the one per-message line in either daemon not gated
on LOGGING, and the Rust daemon inherited it from the Python reference. The
config the installers ship sets LOGGING: False with LOG_LEVEL: DEBUG, so both
daemons wrote a syslog line per DNS answer while verbose logging was nominally
off.

It is duplicative as well as ungated. A refusal is already reported at error
level with its reason, and a success by the "PF Table updated" line, which is
gated. Nothing is lost by holding this one behind the same flag as its
neighbours, and a test asserts the refusal path still leaves a trace with
logging off, so the gate cannot hide why a message was rejected.

The Python daemon also normalises LOG_LEVEL before anything reads it, self.stats
included, for the same reason the resolver now does: matching the raw text made
'debug' select ERROR.
The match ran against the raw yml text while the CTL match directly below it
trims and folds case, so 'debug' or ' DEBUG ' fell through to the catch-all and
silently selected ERROR. An operator who lower-cased the value got a daemon
that logged nothing but faults and no indication why.
Two documentation gaps, both of which cost an operator time.

The blocklist example now uses HaGeZi's lists as its source, with a tier table
covering light, pro, pro.plus and tif. HaGeZi publishes no /etc/hosts format, so
unbound-adblock's -l and -u options do not apply and the domain-only lists go in
through -d or -t instead. Two further paths do not work and are called out: the
adblock/ directory carries ABP filter syntax, which unbound-adblock does not
parse, and the plain wildcard/*.txt files carry *. wildcards. Only the
-onlydomains variants are usable. tools/update_dns_blocklist.sh still fetches
StevenBlack in hosts format, which the section notes rather than papers over.

BLOCKING had no prose at all, only two example lines that read like something
to opt into. It is the default. The new section says so, separates the paths it
governs, and records that a cache hit does not wait whatever it is set to,
because a positive cached answer implies access was already allowed and the
report only resets the TTL. The latency figure is scoped to the round trip it
actually measures, since it was being read as a general number.
@andylemin
andylemin merged commit 5ee5e1a into master Sep 3, 2026
14 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant