mirror of
https://github.com/ChuckBuilds/LEDMatrix.git
synced 2026-08-21 10:29:06 +00:00
Compare 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.
|
||||||
|
|
||||||
|
|||||||
@@ -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()
|
||||||
@@ -194,46 +194,15 @@ class TestSavePluginConfig:
|
|||||||
|
|
||||||
def test_secret_count_message_counts_top_level_keys(self, env):
|
def test_secret_count_message_counts_top_level_keys(self, env):
|
||||||
# Pinned: the "(N secret field(s))" message counts TOP-LEVEL keys of
|
# Pinned: the "(N secret field(s))" message counts TOP-LEVEL keys of
|
||||||
# the separated secrets dict. Here that is 1: the posted accounts
|
# the separated secrets dict. Here that is 2: the posted accounts
|
||||||
# array, whose item tokens all count as ONE key.
|
# array (all its item tokens count as ONE key) plus the schema's
|
||||||
#
|
# api_key default ("") that merge_with_defaults adds before
|
||||||
# It was 2 before blank secrets were dropped, the second being the
|
# separation.
|
||||||
# schema's api_key default (""), which merge_with_defaults adds to
|
|
||||||
# every save. Counting it was the visible edge of a real bug: that
|
|
||||||
# injected blank was merged over the stored api_key, so saving any
|
|
||||||
# unrelated field destroyed the credential. See
|
|
||||||
# test_an_unrelated_edit_does_not_erase_a_stored_secret.
|
|
||||||
resp = self._save(env, {
|
resp = self._save(env, {
|
||||||
"accounts": [{"name": "a", "token": "t"}],
|
"accounts": [{"name": "a", "token": "t"}],
|
||||||
})
|
})
|
||||||
message = resp.get_json()["message"]
|
message = resp.get_json()["message"]
|
||||||
assert "(1 secret field(s) saved to config_secrets.json)" in message
|
assert "(2 secret field(s) saved to config_secrets.json)" in message
|
||||||
|
|
||||||
def test_an_unrelated_edit_does_not_erase_a_stored_secret(self, env):
|
|
||||||
"""Editing one field must not wipe the plugin's API key.
|
|
||||||
|
|
||||||
The config form renders secrets masked, so the browser posts them
|
|
||||||
back blank; merge_with_defaults injects a blank api_key even when
|
|
||||||
the client omits it entirely. Either way a "" reached the secrets
|
|
||||||
file and deep_merge wrote it over the stored credential.
|
|
||||||
"""
|
|
||||||
assert self._save(env, {"api_key": "REAL-KEY-0123456789",
|
|
||||||
"city": "Austin"}).status_code == 200
|
|
||||||
assert _on_disk(env.secrets_file)[PLUGIN_ID]["api_key"] == \
|
|
||||||
"REAL-KEY-0123456789"
|
|
||||||
|
|
||||||
# the user changes the city; the masked api_key rides along blank
|
|
||||||
assert self._save(env, {"api_key": "", "city": "Dallas"}).status_code == 200
|
|
||||||
|
|
||||||
assert _on_disk(env.secrets_file)[PLUGIN_ID]["api_key"] == \
|
|
||||||
"REAL-KEY-0123456789", "an unrelated edit destroyed the API key"
|
|
||||||
assert env.fresh_load()[PLUGIN_ID]["city"] == "Dallas"
|
|
||||||
|
|
||||||
def test_a_secret_can_still_be_changed(self, env):
|
|
||||||
"""Dropping blanks must not stop a real new value from being saved."""
|
|
||||||
self._save(env, {"api_key": "first-key"})
|
|
||||||
self._save(env, {"api_key": "second-key"})
|
|
||||||
assert _on_disk(env.secrets_file)[PLUGIN_ID]["api_key"] == "second-key"
|
|
||||||
|
|
||||||
def test_resave_replaces_stored_secrets_list_wholesale(self, env):
|
def test_resave_replaces_stored_secrets_list_wholesale(self, env):
|
||||||
# Characterized: api_v3's deep_merge intentionally replaces lists,
|
# Characterized: api_v3's deep_merge intentionally replaces lists,
|
||||||
|
|||||||
@@ -21,8 +21,7 @@ logger = logging.getLogger(__name__)
|
|||||||
# Import new infrastructure
|
# Import new infrastructure
|
||||||
from src.web_interface.api_helpers import success_response, error_response, validate_request_json
|
from src.web_interface.api_helpers import success_response, error_response, validate_request_json
|
||||||
from src.web_interface.errors import ErrorCode
|
from src.web_interface.errors import ErrorCode
|
||||||
from src.web_interface.secret_helpers import (find_secret_fields, remove_empty_secrets,
|
from src.web_interface.secret_helpers import find_secret_fields, separate_secrets
|
||||||
separate_secrets)
|
|
||||||
from src.web_interface.error_handler import describe_exception, redact_text
|
from src.web_interface.error_handler import describe_exception, redact_text
|
||||||
from src.plugin_system.operation_types import OperationType
|
from src.plugin_system.operation_types import OperationType
|
||||||
from src.web_interface.validators import (
|
from src.web_interface.validators import (
|
||||||
@@ -1217,11 +1216,6 @@ def save_main_config():
|
|||||||
|
|
||||||
# Separate secrets from regular config (same logic as save_plugin_config)
|
# Separate secrets from regular config (same logic as save_plugin_config)
|
||||||
regular_config, secrets_config = separate_secrets(plugin_config, secret_fields)
|
regular_config, secrets_config = separate_secrets(plugin_config, secret_fields)
|
||||||
# The config form renders secrets masked, so every save posts
|
|
||||||
# them back blank. Without this the blank is merged over the
|
|
||||||
# stored value and the credential is destroyed by the act of
|
|
||||||
# changing an unrelated setting. A blank means "unchanged".
|
|
||||||
secrets_config = remove_empty_secrets(secrets_config)
|
|
||||||
|
|
||||||
# PRE-PROCESSING: Preserve 'enabled' state if not in regular_config
|
# PRE-PROCESSING: Preserve 'enabled' state if not in regular_config
|
||||||
# This prevents overwriting the enabled state when saving config from a form that doesn't include the toggle
|
# This prevents overwriting the enabled state when saving config from a form that doesn't include the toggle
|
||||||
@@ -5605,11 +5599,6 @@ def save_plugin_config():
|
|||||||
# Separate secrets from regular config (handles nested configs and
|
# Separate secrets from regular config (handles nested configs and
|
||||||
# array-item secrets — see src/web_interface/secret_helpers.py)
|
# array-item secrets — see src/web_interface/secret_helpers.py)
|
||||||
regular_config, secrets_config = separate_secrets(plugin_config, secret_fields)
|
regular_config, secrets_config = separate_secrets(plugin_config, secret_fields)
|
||||||
# The config form renders secrets masked, so every save posts
|
|
||||||
# them back blank. Without this the blank is merged over the
|
|
||||||
# stored value and the credential is destroyed by the act of
|
|
||||||
# changing an unrelated setting. A blank means "unchanged".
|
|
||||||
secrets_config = remove_empty_secrets(secrets_config)
|
|
||||||
|
|
||||||
# Get current configs
|
# Get current configs
|
||||||
current_config = api_v3.config_manager.load_config()
|
current_config = api_v3.config_manager.load_config()
|
||||||
|
|||||||
Reference in New Issue
Block a user