Compare commits

..
Author SHA1 Message Date
ChuckBuilds 780fca6365 fix(logging): give the journal the real severity of each line
Everything this process writes to stdout reaches the journal as PRIORITY=6,
whatever the Python level was, because journald has nothing else to go on.
Measured on a live rig over 24 hours:

    lines containing " - ERROR - "      55
    lines containing " - WARNING - "    13
    journald PRIORITY recorded          6, for every one of them

So `journalctl -p err -u ledmatrix` returns nothing while errors are being
logged, and `-p warning` likewise. Triage falls back to grepping message text,
which is slower and unreliable: during this audit a search for "oom" matched
the radar logging "zoom=9" twenty-four times and briefly looked like the OOM
killer had been firing.

systemd reads a leading "<N>" on each stdout line and takes it as the priority
(sd-daemon(3)), so a formatter that prefixes one costs no dependency. Every
line of a multi-line record is tagged, not just the first -- the journal splits
them, and an untagged continuation reverts to the default, which would leave
the body of a traceback filed as informational while its first line was an
error.

Applied only when JOURNAL_STREAM is set, which systemd sets for services whose
output it captures. Run from a terminal, in the emulator or under pytest the
prefixes would be literal noise, and the file handler keeps the plain
formatter for the same reason.

Mutation-checked three ways: prefixing unconditionally fails the
outside-systemd test, prefixing only the first line fails the multi-line test,
and mapping ERROR to 6 fails the level mapping. 39 tests pass across the
logging suites.
2026-08-20 02:54:18 -04:00
4 changed files with 155 additions and 155 deletions
@@ -37,10 +37,6 @@ echo " systemctl: $SYSTEMCTL_PATH"
echo ""
echo "Step 1: Configuring sudo permissions for nmcli..."
SUDOERS_FILE="/etc/sudoers.d/ledmatrix_wifi"
SYSCTL_PATH=$(command -v sysctl || echo /usr/sbin/sysctl)
NFT_PATH=$(command -v nft || echo /usr/sbin/nft)
RFKILL_PATH=$(command -v rfkill || echo /usr/sbin/rfkill)
MKDIR_PATH=$(command -v mkdir || echo /usr/bin/mkdir)
# Create a temporary sudoers file using mktemp (handles permissions better)
TEMP_SUDOERS=$(mktemp) || {
@@ -66,36 +62,6 @@ $WEB_USER ALL=(ALL) NOPASSWD: $SYSTEMCTL_PATH start dnsmasq
$WEB_USER ALL=(ALL) NOPASSWD: $SYSTEMCTL_PATH stop dnsmasq
$WEB_USER ALL=(ALL) NOPASSWD: $SYSTEMCTL_PATH restart dnsmasq
$WEB_USER ALL=(ALL) NOPASSWD: $SYSTEMCTL_PATH restart NetworkManager
# The captive portal turns IP forwarding on while the access point is up and
# restores the previous value when it comes down (wifi_manager._setup_iptables_
# redirect / _teardown_iptables_redirect). Without this rule that sudo call
# needs a password, so forwarding stays off and clients associate to the AP but
# cannot route. It goes unnoticed on a stock Raspberry Pi image, where
# /etc/sudoers.d/010_pi-nopasswd grants the default user blanket NOPASSWD and
# masks every gap in this file -- it only bites once that blanket rule is
# removed.
$WEB_USER ALL=(ALL) NOPASSWD: $SYSCTL_PATH -w net.ipv4.ip_forward=0
$WEB_USER ALL=(ALL) NOPASSWD: $SYSCTL_PATH -w net.ipv4.ip_forward=1
# The portal's redirect lives in its own nftables table, created when the AP
# comes up and deleted when it goes down, and the radio has to be unblocked
# before the AP can start at all. Same story as the sysctl rules above: called
# with sudo, never granted here, and invisible on a stock Pi image.
$WEB_USER ALL=(ALL) NOPASSWD: $NFT_PATH add table ip ledmatrix
$WEB_USER ALL=(ALL) NOPASSWD: $NFT_PATH delete table ip ledmatrix
$WEB_USER ALL=(ALL) NOPASSWD: $RFKILL_PATH unblock wifi
# NetworkManager's dnsmasq drop-in directory, exact path.
$WEB_USER ALL=(ALL) NOPASSWD: $MKDIR_PATH -p /etc/NetworkManager/dnsmasq-shared.d
#
# iptables is deliberately NOT granted here. Its rules are built from the live
# interface name and port, so a rule covering them needs a trailing wildcard --
# and `iptables --modprobe=/path/to/anything` runs that path as root, so
# `NOPASSWD: iptables *` is a root shell for the web user by another name. That
# is a worse outcome than the gap it would close, which today is masked anyway
# by the blanket NOPASSWD rule on stock Pi images.
#
# Closing it safely means a wrapper script that builds the rules itself and
# takes only an interface and a port, granted the way safe_plugin_rm.sh already
# is. That belongs in its own change rather than being smuggled into this one.
# Allow copying hostapd and dnsmasq config files into place
$WEB_USER ALL=(ALL) NOPASSWD: /usr/bin/cp /tmp/hostapd.conf /etc/hostapd/hostapd.conf
+54 -1
View File
@@ -130,7 +130,12 @@ def setup_logging(
# Console handler (always add)
console_handler = logging.StreamHandler(sys.stdout)
console_handler.setLevel(level)
console_handler.setFormatter(formatter)
# Under systemd, tag each line so the journal records the real severity
# rather than filing everything as informational. The file handler below
# keeps the plain formatter: the prefix is meaningful to journald and noise
# anywhere else.
console_handler.setFormatter(
JournalPriorityFormatter(formatter) if _under_systemd() else formatter)
root_logger.addHandler(console_handler)
# File handler (if specified)
@@ -145,6 +150,54 @@ def setup_logging(
sys.stderr.write(f"Warning: Could not set up file logging to {log_file}: {e}\n")
#: syslog priorities, which is what systemd parses from a "<N>" prefix on
#: stdout. Mapped from Python's levels.
_SYSLOG_PRIORITY = {
logging.CRITICAL: 2, # LOG_CRIT
logging.ERROR: 3, # LOG_ERR
logging.WARNING: 4, # LOG_WARNING
logging.INFO: 6, # LOG_INFO
logging.DEBUG: 7, # LOG_DEBUG
}
class JournalPriorityFormatter(logging.Formatter):
"""Wraps a formatter, prefixing each line with its syslog priority.
Under systemd everything this process writes to stdout lands in the journal
as PRIORITY=6, whatever the Python level was. Measured on a live rig: 55
ERROR lines and 13 WARNING lines in a day, every one of them recorded as
informational, so `journalctl -p err -u ledmatrix` returned nothing at all
while errors were being logged. Anyone triaging has to grep the message
text instead, which is both slower and wrong -- a search for "oom" matches
the radar logging "zoom=9".
systemd reads a leading "<N>" on each line and uses it as the priority
(sd-daemon(3)), so this needs no extra dependency. Multi-line records get
the prefix on every line, since the journal splits them and an unprefixed
continuation would fall back to the default.
"""
def __init__(self, inner: logging.Formatter):
super().__init__()
self._inner = inner
def format(self, record: logging.LogRecord) -> str:
text = self._inner.format(record)
prefix = f"<{_SYSLOG_PRIORITY.get(record.levelno, 6)}>"
return "\n".join(prefix + line for line in text.split("\n"))
def _under_systemd() -> bool:
"""True when stdout is the journal.
systemd sets JOURNAL_STREAM for services whose output it captures. Without
this check the "<N>" prefixes would show up as literal noise when the
program is run from a terminal, in the emulator, or in tests.
"""
return bool(os.environ.get("JOURNAL_STREAM"))
class PluginLoggerAdapter(logging.LoggerAdapter):
"""LoggerAdapter that stamps every record with its plugin_id.
+101
View File
@@ -0,0 +1,101 @@
"""Log lines must reach the journal with their real severity.
Everything this process writes to stdout lands in the journal as PRIORITY=6,
whatever the Python level was, because journald has no other signal. Measured
on a live rig over 24 hours: 55 lines containing " - ERROR - " and 13
containing " - WARNING - ", every one of them recorded as informational. So
journalctl -p err -u ledmatrix
returned nothing while errors were being logged, and anyone triaging has to
grep the message text instead. That is slower and it is wrong: a search for
"oom" also matches the radar logging "zoom=9", which is exactly the false
positive it produced during this audit.
systemd reads a leading "<N>" on each stdout line and uses it as the priority
(sd-daemon(3)), so this needs no extra dependency -- and it must only be
applied when systemd is actually reading, or the prefixes become literal noise
in a terminal, the emulator, and test output.
"""
import logging
import os
from unittest.mock import patch
import pytest
from src.logging_config import JournalPriorityFormatter, _SYSLOG_PRIORITY, _under_systemd
class _Plain(logging.Formatter):
def format(self, record):
return record.getMessage()
def _record(level, msg="hello"):
return logging.LogRecord("t", level, "f.py", 1, msg, None, None)
@pytest.mark.parametrize("level,expected", [
(logging.CRITICAL, 2),
(logging.ERROR, 3),
(logging.WARNING, 4),
(logging.INFO, 6),
(logging.DEBUG, 7),
])
def test_each_level_maps_to_its_syslog_priority(level, expected):
out = JournalPriorityFormatter(_Plain()).format(_record(level))
assert out.startswith(f"<{expected}>"), out
assert _SYSLOG_PRIORITY[level] == expected
def test_error_and_info_are_distinguishable():
"""The whole point: journalctl -p err must be able to tell them apart."""
fmt = JournalPriorityFormatter(_Plain())
assert fmt.format(_record(logging.ERROR))[:3] != fmt.format(_record(logging.INFO))[:3]
def test_every_line_of_a_multiline_record_is_tagged():
"""The journal splits them, and an untagged continuation loses its level.
A traceback is the case that matters -- it is the most important thing in
the log and the longest.
"""
out = JournalPriorityFormatter(_Plain()).format(
_record(logging.ERROR, "Traceback:\nline one\nline two"))
lines = out.split("\n")
assert len(lines) == 3
assert all(line.startswith("<3>") for line in lines), lines
def test_the_message_survives_intact():
out = JournalPriorityFormatter(_Plain()).format(_record(logging.WARNING, "disk full"))
assert out == "<4>disk full"
def test_an_unknown_level_falls_back_to_info():
out = JournalPriorityFormatter(_Plain()).format(_record(25))
assert out.startswith("<6>")
def test_prefixing_is_off_outside_systemd():
"""Otherwise a terminal run, the emulator and pytest all show `<6>`."""
with patch.dict(os.environ, {}, clear=True):
assert not _under_systemd()
with patch.dict(os.environ, {"JOURNAL_STREAM": "8:12345"}):
assert _under_systemd()
def test_setup_uses_the_wrapper_only_under_systemd():
from src.logging_config import setup_logging
for env, expect_wrapped in (({}, False), ({"JOURNAL_STREAM": "8:1"}, True)):
with patch.dict(os.environ, env, clear=True):
setup_logging()
handlers = [h for h in logging.getLogger().handlers
if isinstance(h, logging.StreamHandler)]
assert handlers, "no stream handler installed"
wrapped = any(isinstance(h.formatter, JournalPriorityFormatter)
for h in handlers)
assert wrapped is expect_wrapped, (
f"JOURNAL_STREAM={env}: wrapped={wrapped}, expected {expect_wrapped}")
logging.getLogger().handlers.clear()
-120
View File
@@ -1,120 +0,0 @@
"""The captive portal's fixed-argument sudo calls must be granted.
The installers write two allow-lists, /etc/sudoers.d/ledmatrix_web and
ledmatrix_wifi. A sudo call absent from both needs a password, which a service
cannot supply, so it fails.
Four such calls were ungranted, all of them captive-portal teardown/setup:
sysctl -w net.ipv4.ip_forward=0|1 wifi_manager.py:788, 883
nft add|delete table ip ledmatrix wifi_manager.py:835, 895
rfkill unblock wifi wifi_manager.py:1811
mkdir -p .../dnsmasq-shared.d wifi_manager.py:922
It goes unnoticed because a stock Raspberry Pi image ships
/etc/sudoers.d/010_pi-nopasswd granting the default user
`ALL=(ALL) NOPASSWD: ALL`, which satisfies every gap in both files. It only
bites once that blanket rule is removed or the service runs as another user.
Scope, deliberately narrow: this pins the four commands above, each of which
can be written out literally. The portal makes further sudo calls whose
arguments are built at runtime -- iptables and nft rules carrying an interface
name and a port, `ip addr`, `ip link` -- and those cannot be granted safely
here. A rule covering them needs a trailing wildcard, and
`iptables --modprobe=/path/to/anything` runs that path as root, so
`NOPASSWD: iptables *` is a root shell for the web user by another name.
Closing that half needs a privileged helper that builds the rules itself and
takes only an interface and a port, granted the way safe_plugin_rm.sh already
is. That is a design decision, not a one-line grant, and belongs in its own
change.
"""
import re
from pathlib import Path
import pytest
ROOT = Path(__file__).resolve().parent.parent
INSTALLERS = (
ROOT / "first_time_install.sh",
ROOT / "scripts" / "install" / "configure_wifi_permissions.sh",
)
#: Commands this change grants, each fully literal in the source.
REQUIRED = (
("sysctl", "-w", "net.ipv4.ip_forward=0"),
("sysctl", "-w", "net.ipv4.ip_forward=1"),
("nft", "add", "table", "ip", "ledmatrix"),
("nft", "delete", "table", "ip", "ledmatrix"),
("rfkill", "unblock", "wifi"),
("mkdir", "-p", "/etc/NetworkManager/dnsmasq-shared.d"),
)
#: Tools with an option that executes a program of the caller's choosing.
#: A trailing wildcard on any of these is a privilege escalation.
EXEC_CAPABLE = ("iptables", "ip6tables", "nft", "tcpdump", "find", "awk",
"sed", "perl", "python", "python3", "env")
def _grant_lines():
lines = []
for installer in INSTALLERS:
if not installer.is_file():
continue
for line in installer.read_text(encoding="utf-8", errors="replace").splitlines():
if "NOPASSWD:" in line:
lines.append(line.split("NOPASSWD:", 1)[1])
return lines
def _normalised_grants():
"""Grants with binary-path variables reduced to tool names.
Rules are written as `$SYSCTL_PATH -w ...`, so matching the literal
"sysctl" finds nothing and every rule looks absent -- which is exactly how
an earlier version of this test reported six gaps that did not exist.
Only NOPASSWD lines are considered, because taking the whole script let a
variable definition such as NFT_PATH=$(command -v nft) satisfy the check on
its own while the grant itself had been deleted.
"""
text = "\n".join(_grant_lines())
text = re.sub(r"\$\{?([A-Z][A-Z0-9_]*)_PATH\}?", lambda m: m.group(1).lower(), text)
return re.sub(r"/usr/(?:s?bin)/", "", text)
def test_the_installers_are_present():
missing = [str(p.relative_to(ROOT)) for p in INSTALLERS if not p.is_file()]
assert not missing, f"installer(s) missing: {missing}"
@pytest.mark.parametrize("command", REQUIRED, ids=lambda c: " ".join(c))
def test_the_command_is_granted(command):
"""Whole command, not just the binary.
Checking only the binary made this far weaker than it looked: with
`sysctl` present anywhere, deleting the ip_forward=0 grant still passed,
and the portal would then be unable to restore forwarding on teardown.
"""
pattern = r"\s+".join(re.escape(word) for word in command)
assert re.search(pattern, _normalised_grants()), (
f"no installer grants `{' '.join(command)}`")
def test_no_wildcard_on_a_tool_that_can_exec():
"""`NOPASSWD: iptables *` hands the web user root.
iptables --modprobe=/path runs that path as root. This caught a grant added
in this very change, which is why it is here.
"""
offenders = []
for rule in _grant_lines():
rule = rule.strip()
if not rule.endswith("*"):
continue
haystack = rule.replace("_PATH", "").lower()
for tool in EXEC_CAPABLE:
if re.search(rf"(^|/|\s|\$){tool}(\s|$)", haystack):
offenders.append(rule)
break
assert not offenders, (
"wildcard grant on a tool that can execute another program:\n "
+ "\n ".join(offenders))