diff --git a/src/logging_config.py b/src/logging_config.py index 17d831bb..a4431016 100644 --- a/src/logging_config.py +++ b/src/logging_config.py @@ -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 "" 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 "" 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 "" 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. diff --git a/test/test_journald_log_priority.py b/test/test_journald_log_priority.py new file mode 100644 index 00000000..b60855e0 --- /dev/null +++ b/test/test_journald_log_priority.py @@ -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 "" 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()