Compare commits

..
Author SHA1 Message Date
ChuckBuilds 8d1e43c15a perf(vegas): trace the content path at DEBUG instead of INFO
plugin_adapter narrates every step of acquiring content from every plugin --
"Has get_vegas_content", "Native: calling get_vegas_content()", "Native
content returned None", "Has scroll_helper", per-item sizes -- once per plugin
per cycle, all at INFO.

Measured on a live rig: 13,408 log lines an hour, of which 13,366 were INFO
and 35 were WARNING. Roughly 223 lines a minute of string formatting on a Pi
that is also driving the panel, written through journald to the SD card, with
the 35 lines that actually indicate a problem buried among them.

Top repeated messages in that hour:

    717  Scroll progress: elapsed=... total_scrolled=.../... px
    399  [plugin] --> INCLUDED in Vegas scroll
    323  [plugin] content_type=static, display_mode=fixed
    195  [plugin] Has get_vegas_content: True
    195  [plugin] Native: calling get_vegas_content()
    168  [plugin] Native: get_vegas_content() returned None
    168  [plugin] Native content returned None        <- the same fact, twice

54 logger.info calls in plugin_adapter become logger.debug, along with the
per-frame scroll-progress line in scroll_helper. Together those are 3,174 of
the 13,408 lines an hour, a 23% cut, and the ~3,600 odds-manager lines are
addressed separately by ledmatrix-plugins#300.

Nothing is lost: the 19 warning/error/exception calls in the module are
untouched, so real failures still surface at their own level. This is a
logging-level change only -- no control flow, no behaviour.

One INFO call is deliberate and stays. The padding-strip message picks its
level at runtime (`logger.warning if (left and right) else logger.info`) and
test_vegas_plugin_adapter.py pins that choice; it survives because it is not a
direct logger.info call site. That test still passes.

Mutation-checked both ways: reintroducing a single INFO trace fails the guard,
and demoting the warning/error calls along with the trace fails a second guard
written for exactly that mistake. 537 vegas and scroll tests pass.

(cherry picked from commit e496d95dfe)
2026-08-19 20:49:31 -04:00
ChuckBuilds 0f77bd2345 perf(health): stop rewriting a health record on every healthy cycle
Every successful plugin update called record_success(), which persisted the
record unconditionally. In steady state the only fields that had changed were
total_successes and last_success_time -- a counter and a timestamp that
health_monitor surfaces for display and that nothing reads back after a
restart. Nothing alerts on the age of last_successful_update; it is carried in
the metrics dataclass and shown.

Measured on a rig running 24 plugins, all steady-state (0 consecutive
failures, circuit closed): a five-minute sample caught 22 health-file
rewrites, about 4.4 a minute or 6,300 a day. Each write is ~400 bytes through
cache_manager.set(), which writes a file per call, so each one costs a
filesystem block plus an ext4 journal write.

That lands on an SD card, where the unit of cost is an erase-block cycle
rather than the bytes involved, and where wear is what eventually kills the
card. Two cards have already failed on the other rig with the same
signature -- unreadable block device, EIO on exec, sshd unable to read its
host keys.

The circuit breaker still has to survive a restart, so the write is kept for
exactly the fields it is rebuilt from: consecutive_failures, circuit_state,
circuit_opened_time, half_open_start_time. A failure, a circuit opening and a
recovery are all still written the moment they happen. In-memory state is
updated every time either way, so the health API and web UI show what they
always did.

Tested: 100 healthy cycles now perform zero writes after the first, the
counters remain accurate in memory, and a failure, a recovery and a
half-open-to-closed transition each still reach disk. One test kills and
rebuilds the tracker from the cache to prove the breaker's state genuinely
survives what is no longer written.

Mutation-checked both ways: persisting unconditionally again fails the
steady-state test, and widening _DURABLE_FIELDS to include last_success_time
fails it too. The 46 existing health tests pass.

(cherry picked from commit 14abea2d24)
2026-08-19 20:49:31 -04:00
3 changed files with 5 additions and 183 deletions
+1 -66
View File
@@ -130,12 +130,7 @@ def setup_logging(
# Console handler (always add)
console_handler = logging.StreamHandler(sys.stdout)
console_handler.setLevel(level)
# 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)
console_handler.setFormatter(formatter)
root_logger.addHandler(console_handler)
# File handler (if specified)
@@ -150,66 +145,6 @@ 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
@property
def inner(self) -> logging.Formatter:
"""The formatter doing the actual work.
Whether journald tagging is applied depends on JOURNAL_STREAM, so it is
on under systemd and off in a terminal -- and anything asserting which
formatter setup_logging() selected would otherwise get a different
answer in CI than on a developer's machine. Exposing the inner one lets
those checks stay about format_type, which is what they mean.
"""
return self._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
@@ -1,101 +0,0 @@
"""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()
+4 -16
View File
@@ -183,27 +183,15 @@ class TestSetupLogging:
setup_logging()
assert len(logging.getLogger().handlers) == 1
@staticmethod
def _selected_formatter():
"""The formatter setup_logging() chose, past any journald wrapper.
Under systemd the console handler's formatter is wrapped so each line
carries its syslog priority. That wrapper is applied only when
JOURNAL_STREAM is set, which is true in CI and false in a terminal, so
asserting on the handler's formatter directly passes locally and fails
on the runner. These tests are about which formatter format_type
selects, so they look through the wrapper.
"""
formatter = logging.getLogger().handlers[0].formatter
return getattr(formatter, "inner", formatter)
def test_json_format_selects_structured_formatter(self):
setup_logging(format_type="json")
assert isinstance(self._selected_formatter(), StructuredFormatter)
assert isinstance(
logging.getLogger().handlers[0].formatter, StructuredFormatter)
def test_readable_format_selects_contextual_formatter(self):
setup_logging(format_type="readable")
assert isinstance(self._selected_formatter(), ContextualFormatter)
assert isinstance(
logging.getLogger().handlers[0].formatter, ContextualFormatter)
def test_log_file_adds_file_handler(self, tmp_path):
log_file = tmp_path / "test.log"