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 157 additions and 185 deletions
+54 -1
View File
@@ -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.
-143
View File
@@ -1,143 +0,0 @@
"""GET /config/main must not hand out credentials.
The endpoint returned the raw config to anyone who could reach the port, and
this web interface has no authentication of any kind. Measured against a live
rig, an unauthenticated request returned:
github.api_token 40 chars
incoming-packages.ha_token 183 chars
jellyfin-now-playing.api_key 32 chars
ledmatrix-weather.api_key 32 chars
on-air.mqtt_password 8 chars
youtube.api_key 20 chars
youtube-stats.api_key 39 chars
A GitHub token and a Home Assistant long-lived token among them.
The x-secret masking the plugin config endpoints use does not apply here: this
endpoint never consults a schema, and core keys such as github.api_token have
no schema to carry the marker. Several of those fields *are* tagged x-secret in
their plugin's schema and were still returned in full, which is what makes the
schema route the wrong one to rely on for this endpoint.
Matching on field name is blunt. For a whole-config dump it is the right
default: anything named like a credential should not leave the process, and a
new plugin that adds a differently-shaped secret is covered without anyone
remembering to tag it.
"""
import pytest
from web_interface.blueprints.api_v3 import (
_looks_like_a_credential,
_redact_credentials,
)
@pytest.mark.parametrize("name", [
"password", "mqtt_password", "opensky_password", "passwd",
"api_key", "apikey", "API_KEY", "flightaware_api_key",
"token", "ha_token", "api_token", "access_token",
"secret", "client_secret", "spotify_client_secret",
"access_key", "private_key",
])
def test_credential_names_are_recognised(name):
assert _looks_like_a_credential(name)
@pytest.mark.parametrize("name", [
"timezone", "city", "brightness", "enabled", "update_interval",
"favorite_teams", "display_duration", "keyword",
])
def test_ordinary_names_are_left_alone(name):
assert not _looks_like_a_credential(name)
def test_the_measured_leak_is_closed():
"""The exact shape taken off the rig."""
config = {
"github": {"api_token": "ghp_" + "x" * 36},
"incoming-packages": {"ha_token": "y" * 183, "enabled": True},
"jellyfin-now-playing": {"api_key": "z" * 32},
"on-air": {"mqtt_password": "hunter22"},
"youtube": {"api_key": "k" * 20},
"timezone": "America/New_York",
}
out = _redact_credentials(config)
assert out["github"]["api_token"] == ""
assert out["incoming-packages"]["ha_token"] == ""
assert out["jellyfin-now-playing"]["api_key"] == ""
assert out["on-air"]["mqtt_password"] == ""
assert out["youtube"]["api_key"] == ""
# Everything else survives, or the config editor breaks.
assert out["timezone"] == "America/New_York"
assert out["incoming-packages"]["enabled"] is True
def test_nested_and_listed_credentials_are_reached():
config = {"a": {"b": {"c": {"password": "p"}}},
"feeds": [{"name": "x", "api_key": "k"}, {"name": "y"}]}
out = _redact_credentials(config)
assert out["a"]["b"]["c"]["password"] == ""
assert out["feeds"][0]["api_key"] == ""
assert out["feeds"][0]["name"] == "x"
def test_the_original_is_not_mutated():
"""The caller holds the live config; redaction must not edit it in place."""
config = {"github": {"api_token": "keepme"}}
_redact_credentials(config)
assert config["github"]["api_token"] == "keepme"
def test_a_credential_shaped_container_is_still_walked():
"""`secrets: {...}` is a section name, not a value to blank."""
config = {"secrets": {"api_key": "k", "note": "keep"}}
out = _redact_credentials(config)
assert out["secrets"]["api_key"] == ""
assert out["secrets"]["note"] == "keep"
def test_non_dict_input_passes_through():
assert _redact_credentials("plain") == "plain"
assert _redact_credentials(7) == 7
assert _redact_credentials(None) is None
def test_the_endpoint_itself_redacts():
"""Through the view function, not the helper.
The helper tests above all passed with the route still returning
`config` -- reverting the one line that calls the redactor changed
nothing, because nothing exercised the route. A property asserted on a
helper is not a property asserted on the endpoint, and it is the endpoint
that is exposed to the network.
"""
import json as _json
from unittest.mock import MagicMock
import flask
from web_interface.blueprints import api_v3 as mod
raw = {"github": {"api_token": "ghp_secret_value"},
"timezone": "America/New_York"}
manager = MagicMock()
manager.load_config.return_value = raw
previous = getattr(mod.api_v3, "config_manager", None)
mod.api_v3.config_manager = manager
app = flask.Flask(__name__)
try:
with app.test_request_context("/config/main"):
response = mod.get_main_config()
payload = response.get_json() if hasattr(response, "get_json") else _json.loads(response[0].data)
finally:
mod.api_v3.config_manager = previous
data = payload["data"]
assert data["github"]["api_token"] == "", (
"the endpoint returned the token; the redactor is not wired in")
assert data["timezone"] == "America/New_York"
# And the config the manager handed over is untouched.
assert raw["github"]["api_token"] == "ghp_secret_value"
+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()
+2 -41
View File
@@ -262,54 +262,15 @@ def _stop_display_service():
result['status'] = status result['status'] = status
return result return result
#: Field names whose value is a credential. Matched by name because this
#: endpoint returns the whole config, core keys included, and core config has
#: no schema to carry x-secret markers.
_CREDENTIAL_NAME_PARTS = ("password", "passwd", "secret", "token", "api_key",
"apikey", "access_key", "private_key", "client_secret")
def _looks_like_a_credential(name: str) -> bool:
lowered = name.lower()
return any(part in lowered for part in _CREDENTIAL_NAME_PARTS)
def _redact_credentials(value):
"""A copy of `value` with credential-named fields blanked.
/config/main returned the raw config to anyone who could reach the port,
and this interface has no authentication. On one rig that meant a 40-char
GitHub token, a 183-char Home Assistant token and five API keys were
readable by anything on the LAN.
The x-secret masking used by the plugin config endpoints does not help
here: this endpoint never consults a schema, and core keys such as
github.api_token have no schema to mark. Matching on the field name is
blunt, but for a whole-config dump the right default is that anything
named like a credential does not leave the process.
Blanked rather than removed, and safe to blank: POST /config/main merges
into the loaded config and only writes the keys it was given, so a client
that round-trips this response cannot erase a secret it never saw.
"""
if isinstance(value, dict):
return {k: ("" if _looks_like_a_credential(k) and not isinstance(v, (dict, list))
else _redact_credentials(v))
for k, v in value.items()}
if isinstance(value, list):
return [_redact_credentials(item) for item in value]
return value
@api_v3.route('/config/main', methods=['GET']) @api_v3.route('/config/main', methods=['GET'])
def get_main_config(): def get_main_config():
"""Get main configuration, with credentials redacted.""" """Get main configuration"""
try: try:
if not api_v3.config_manager: if not api_v3.config_manager:
return jsonify({'status': 'error', 'message': 'Config manager not initialized'}), 500 return jsonify({'status': 'error', 'message': 'Config manager not initialized'}), 500
config = api_v3.config_manager.load_config() config = api_v3.config_manager.load_config()
return jsonify({'status': 'success', 'data': _redact_credentials(config)}) return jsonify({'status': 'success', 'data': config})
except Exception as e: except Exception as e:
logger.error('Unhandled exception', exc_info=True) logger.error('Unhandled exception', exc_info=True)
return jsonify({'status': 'error', 'message': 'An error occurred; see logs for details', 'details': describe_exception(e)}), 500 return jsonify({'status': 'error', 'message': 'An error occurred; see logs for details', 'details': describe_exception(e)}), 500