mirror of
https://github.com/ChuckBuilds/LEDMatrix.git
synced 2026-08-21 02:19:07 +00:00
Compare commits
1
Commits
| Author | SHA1 | Date | |
|---|---|---|---|
|
|
780fca6365 |
+54
-1
@@ -130,7 +130,12 @@ def setup_logging(
|
|||||||
# Console handler (always add)
|
# Console handler (always add)
|
||||||
console_handler = logging.StreamHandler(sys.stdout)
|
console_handler = logging.StreamHandler(sys.stdout)
|
||||||
console_handler.setLevel(level)
|
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)
|
root_logger.addHandler(console_handler)
|
||||||
|
|
||||||
# File handler (if specified)
|
# 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")
|
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):
|
class PluginLoggerAdapter(logging.LoggerAdapter):
|
||||||
"""LoggerAdapter that stamps every record with its plugin_id.
|
"""LoggerAdapter that stamps every record with its plugin_id.
|
||||||
|
|
||||||
|
|||||||
@@ -62,9 +62,6 @@ class StartupValidator:
|
|||||||
# Validate plugins if plugin manager is available
|
# Validate plugins if plugin manager is available
|
||||||
if self.plugin_manager:
|
if self.plugin_manager:
|
||||||
self._validate_plugins()
|
self._validate_plugins()
|
||||||
|
|
||||||
# Warn when the running systemd unit no longer matches the repo's
|
|
||||||
self._validate_systemd_units()
|
|
||||||
|
|
||||||
is_valid = len(self.errors) == 0
|
is_valid = len(self.errors) == 0
|
||||||
|
|
||||||
@@ -77,71 +74,6 @@ class StartupValidator:
|
|||||||
|
|
||||||
return (is_valid, self.errors.copy(), self.warnings.copy())
|
return (is_valid, self.errors.copy(), self.warnings.copy())
|
||||||
|
|
||||||
#: Units this project installs, and where each is installed to.
|
|
||||||
_UNITS = (
|
|
||||||
("systemd/ledmatrix.service", "/etc/systemd/system/ledmatrix.service"),
|
|
||||||
("systemd/ledmatrix-web.service", "/etc/systemd/system/ledmatrix-web.service"),
|
|
||||||
)
|
|
||||||
|
|
||||||
def _validate_systemd_units(self) -> None:
|
|
||||||
"""Warn when an installed unit has drifted from the repo's template.
|
|
||||||
|
|
||||||
Nothing re-applies these after the first install. `git pull` -- which is
|
|
||||||
what the web UI's update button runs -- brings a new template into the
|
|
||||||
checkout, but nothing copies it to /etc/systemd/system and nothing runs
|
|
||||||
`systemctl daemon-reload`, so the unit that actually runs is whatever
|
|
||||||
first_time_install.sh wrote on day one.
|
|
||||||
|
|
||||||
That makes every hardening added to a unit inert on existing installs.
|
|
||||||
Measured on one rig: the installed unit was thirteen days older than the
|
|
||||||
repo's and differed in content, so a MemoryMax the repo had specified
|
|
||||||
was not being enforced at all -- `systemctl show` reported
|
|
||||||
MemoryMax=infinity.
|
|
||||||
|
|
||||||
A warning rather than an error, and certainly not a silent rewrite:
|
|
||||||
editing files under /etc and restarting services is the installer's job,
|
|
||||||
not something a display process should do to a machine while it boots.
|
|
||||||
The remedy is to re-run scripts/install/install_service.sh.
|
|
||||||
"""
|
|
||||||
try:
|
|
||||||
project_root = Path(__file__).resolve().parent.parent
|
|
||||||
for template_rel, installed_path in self._UNITS:
|
|
||||||
template = project_root / template_rel
|
|
||||||
installed = Path(installed_path)
|
|
||||||
if not template.is_file() or not installed.is_file():
|
|
||||||
continue
|
|
||||||
|
|
||||||
# The template carries placeholders the installer substitutes,
|
|
||||||
# so compare the substituted form rather than the raw file.
|
|
||||||
expected = template.read_text(encoding="utf-8")
|
|
||||||
expected = expected.replace("__PROJECT_ROOT_DIR__", str(project_root))
|
|
||||||
expected = expected.replace("__USER__", "root")
|
|
||||||
|
|
||||||
try:
|
|
||||||
actual = installed.read_text(encoding="utf-8")
|
|
||||||
except PermissionError:
|
|
||||||
continue
|
|
||||||
|
|
||||||
if self._unit_body(expected) != self._unit_body(actual):
|
|
||||||
self.warnings.append(
|
|
||||||
f"{installed.name} differs from {template_rel}; the "
|
|
||||||
"installed unit is not refreshed by an update, so "
|
|
||||||
"settings added to the template are not in effect. "
|
|
||||||
"Re-run scripts/install/install_service.sh to apply them."
|
|
||||||
)
|
|
||||||
except OSError as e:
|
|
||||||
self.logger.debug("Could not compare systemd units: %s", e)
|
|
||||||
|
|
||||||
@staticmethod
|
|
||||||
def _unit_body(text: str) -> str:
|
|
||||||
"""A unit's meaningful lines: no comments, no blanks, no ordering noise."""
|
|
||||||
lines = []
|
|
||||||
for line in text.splitlines():
|
|
||||||
line = line.strip()
|
|
||||||
if line and not line.startswith("#"):
|
|
||||||
lines.append(line)
|
|
||||||
return "\n".join(sorted(lines))
|
|
||||||
|
|
||||||
def _validate_config(self) -> None:
|
def _validate_config(self) -> None:
|
||||||
"""Validate configuration files."""
|
"""Validate configuration files."""
|
||||||
try:
|
try:
|
||||||
|
|||||||
@@ -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()
|
||||||
@@ -1,133 +0,0 @@
|
|||||||
"""An installed unit that no longer matches the repo's must be reported.
|
|
||||||
|
|
||||||
Nothing re-applies systemd units after the first install. `git pull` -- what
|
|
||||||
the web UI's update button runs -- brings a new template into the checkout, but
|
|
||||||
no code in web_interface/ or src/ copies it to /etc/systemd/system or runs
|
|
||||||
`systemctl daemon-reload`. The unit that actually runs is whatever
|
|
||||||
first_time_install.sh wrote on day one.
|
|
||||||
|
|
||||||
So every hardening added to a unit is inert on existing installs. Measured on a
|
|
||||||
live rig: the installed unit was dated 2026-08-06 and the repo's 2026-08-19,
|
|
||||||
and they differed -- with the result that a MemoryMax=85% present in the repo's
|
|
||||||
template was not being enforced at all. `systemctl show` reported
|
|
||||||
MemoryMax=infinity.
|
|
||||||
|
|
||||||
This is a warning, not an error, and deliberately not a silent rewrite:
|
|
||||||
editing files under /etc and restarting services is the installer's job, not
|
|
||||||
something a display process should do to a machine while it boots.
|
|
||||||
"""
|
|
||||||
import logging
|
|
||||||
from pathlib import Path
|
|
||||||
from unittest.mock import MagicMock
|
|
||||||
|
|
||||||
import pytest
|
|
||||||
|
|
||||||
from src.startup_validator import StartupValidator
|
|
||||||
|
|
||||||
|
|
||||||
@pytest.fixture
|
|
||||||
def validator():
|
|
||||||
v = StartupValidator(config_manager=MagicMock())
|
|
||||||
v.logger = logging.getLogger("test")
|
|
||||||
v.warnings = []
|
|
||||||
v.errors = []
|
|
||||||
return v
|
|
||||||
|
|
||||||
|
|
||||||
def test_a_matching_unit_produces_no_warning(validator, tmp_path):
|
|
||||||
"""The installed unit, substituted exactly as the installer would."""
|
|
||||||
project_root = Path("src/startup_validator.py").resolve().parent.parent
|
|
||||||
template_rel = "systemd/ledmatrix.service"
|
|
||||||
template = project_root / template_rel
|
|
||||||
if not template.is_file():
|
|
||||||
pytest.skip("repo unit template not present")
|
|
||||||
|
|
||||||
installed = tmp_path / "ledmatrix.service"
|
|
||||||
installed.write_text(
|
|
||||||
template.read_text(encoding="utf-8")
|
|
||||||
.replace("__PROJECT_ROOT_DIR__", str(project_root))
|
|
||||||
.replace("__USER__", "root"),
|
|
||||||
encoding="utf-8")
|
|
||||||
|
|
||||||
validator._UNITS = ((template_rel, str(installed)),)
|
|
||||||
validator._validate_systemd_units()
|
|
||||||
assert not validator.warnings, f"a matching unit warned: {validator.warnings}"
|
|
||||||
assert not validator.errors
|
|
||||||
|
|
||||||
|
|
||||||
def test_comments_and_blank_lines_are_not_drift():
|
|
||||||
"""Otherwise every comment the repo adds would look like a changed unit."""
|
|
||||||
a = "[Service]\n# explains a setting\nExecStart=/x\nRestart=always\n"
|
|
||||||
b = "[Service]\nExecStart=/x\n\nRestart=always\n"
|
|
||||||
assert StartupValidator._unit_body(a) == StartupValidator._unit_body(b)
|
|
||||||
|
|
||||||
|
|
||||||
def test_a_changed_directive_is_drift():
|
|
||||||
a = "[Service]\nExecStart=/x\nMemoryMax=85%\n"
|
|
||||||
b = "[Service]\nExecStart=/x\n"
|
|
||||||
assert StartupValidator._unit_body(a) != StartupValidator._unit_body(b)
|
|
||||||
|
|
||||||
|
|
||||||
def test_reordered_directives_are_not_drift():
|
|
||||||
"""systemd does not care about order within a section, so neither should this."""
|
|
||||||
a = "[Service]\nExecStart=/x\nRestart=always\n"
|
|
||||||
b = "[Service]\nRestart=always\nExecStart=/x\n"
|
|
||||||
assert StartupValidator._unit_body(a) == StartupValidator._unit_body(b)
|
|
||||||
|
|
||||||
|
|
||||||
def test_cosmetic_differences_do_not_warn(validator, tmp_path):
|
|
||||||
"""Through the real comparison, not the helper.
|
|
||||||
|
|
||||||
The repo's template carries explanatory comments the installed copy may not
|
|
||||||
have, and the installer does not preserve ordering or blank lines. If those
|
|
||||||
counted as drift, every boot would warn and the warning would be ignored.
|
|
||||||
Asserting this on _unit_body alone would not catch a comparison that stopped
|
|
||||||
calling it -- which is exactly what a careless edit does.
|
|
||||||
"""
|
|
||||||
project_root = Path("src/startup_validator.py").resolve().parent.parent
|
|
||||||
template_rel = "systemd/ledmatrix.service"
|
|
||||||
template = project_root / template_rel
|
|
||||||
if not template.is_file():
|
|
||||||
pytest.skip("repo unit template not present")
|
|
||||||
|
|
||||||
substituted = (template.read_text(encoding="utf-8")
|
|
||||||
.replace("__PROJECT_ROOT_DIR__", str(project_root))
|
|
||||||
.replace("__USER__", "root"))
|
|
||||||
# Same directives, stripped of comments and blank lines and reordered.
|
|
||||||
directives = sorted(line.strip() for line in substituted.splitlines()
|
|
||||||
if line.strip() and not line.strip().startswith("#"))
|
|
||||||
installed = tmp_path / "ledmatrix.service"
|
|
||||||
installed.write_text("\n".join(reversed(directives)) + "\n", encoding="utf-8")
|
|
||||||
|
|
||||||
validator._UNITS = ((template_rel, str(installed)),)
|
|
||||||
validator._validate_systemd_units()
|
|
||||||
assert not validator.warnings, (
|
|
||||||
f"cosmetic-only difference reported as drift: {validator.warnings}")
|
|
||||||
|
|
||||||
|
|
||||||
def test_drift_is_reported_as_a_warning(validator, tmp_path):
|
|
||||||
"""The whole point: a real difference must surface, and only as a warning."""
|
|
||||||
installed = tmp_path / "ledmatrix.service"
|
|
||||||
installed.write_text("[Service]\nExecStart=/usr/bin/python3 /x/run.py\n")
|
|
||||||
|
|
||||||
project_root = Path("src/startup_validator.py").resolve().parent.parent
|
|
||||||
template_rel = "systemd/ledmatrix.service"
|
|
||||||
template = project_root / template_rel
|
|
||||||
if not template.is_file():
|
|
||||||
pytest.skip("repo unit template not present")
|
|
||||||
|
|
||||||
validator._UNITS = ((template_rel, str(installed)),)
|
|
||||||
validator._validate_systemd_units()
|
|
||||||
|
|
||||||
assert validator.warnings, "a differing unit produced no warning"
|
|
||||||
assert "install_service.sh" in validator.warnings[0], (
|
|
||||||
"the warning does not tell the user how to fix it")
|
|
||||||
assert not validator.errors, "drift must not be fatal at startup"
|
|
||||||
|
|
||||||
|
|
||||||
def test_a_missing_installed_unit_is_silent(validator, tmp_path):
|
|
||||||
"""Development checkouts have no /etc/systemd unit; that is not drift."""
|
|
||||||
validator._UNITS = (("systemd/ledmatrix.service", str(tmp_path / "absent.service")),)
|
|
||||||
validator._validate_systemd_units()
|
|
||||||
assert not validator.warnings
|
|
||||||
assert not validator.errors
|
|
||||||
Reference in New Issue
Block a user