Compare commits

..
Author SHA1 Message Date
ChuckBuilds 29f1c68bea fix(plugins): one bad metrics cache entry should not stop every plugin
Caught live on a rig: every plugin failing, once each, continuously.

    ERROR - src.plugin_system.plugin_manager - plugin geochron operation failed:
    ResourceMetrics.__init__() got an unexpected keyword argument
    'consecutive_failures'

    ERROR - ... plugin text-display operation failed: ...
    ERROR - ... plugin news operation failed: ...
    ERROR - ... plugin odds-ticker operation failed: ...

with /api/v3/health reporting plugin_system: not_initialized while the display
process itself kept running and updating the panel.

`consecutive_failures` is a plugin_health field, not a metrics one.
get_metrics() does ResourceMetrics(**cached), which raises TypeError on a
single unrecognised key, and that exception escapes into plugin_manager and is
reported per plugin. One malformed cache entry takes the whole plugin system
down.

How a health-shaped record came to sit under a plugin_metrics key on that
machine is not established, and I could not finish the diagnosis: the rig went
back into its EIO failure mode partway through -- SSH resetting pre-banner,
systemctl unexecutable -- while the web API kept answering from RAM. Checked
before that: the cache files on disk are correctly shaped and separate, and
CacheManager.get() returns the right record for each key, so it is not a live
key collision. A restored backup mixing two machines' caches is the likeliest
explanation, and that rig had one restored onto it.

Either way the loader should not be brittle enough for the answer to matter.
plugin_health already repairs its records field by field rather than trusting
what is on disk; this does the same. Known fields are kept, unknown ones are
dropped and named once in the log so a genuine schema change stays visible
rather than being silently discarded, and a non-mapping entry no longer raises.

Keeping the known fields matters: discarding the record wholesale would throw
away real call counts and timings because of an unrelated stray key.

Mutation-checked: restoring ResourceMetrics(**cached) fails 6 checks, dropping
the whole record fails the field-preservation check, and dropping unknown
fields silently fails the logging check. 28 tests pass across the resource
monitor and plugin health suites.
2026-08-20 03:26:20 -04:00
4 changed files with 146 additions and 203 deletions
+46 -2
View File
@@ -9,7 +9,7 @@ import time
import logging
import threading
from typing import Dict, Optional, Any, Callable
from dataclasses import dataclass, field
from dataclasses import dataclass, field, fields
try:
import psutil
@@ -102,6 +102,50 @@ class PluginResourceMonitor:
"psutil not available - resource monitoring will be limited to execution time only"
)
def _metrics_from_cache(self, plugin_id: str, cached: Any) -> "ResourceMetrics":
"""Build metrics from a cached record, ignoring anything unrecognised.
ResourceMetrics(**cached) raises TypeError on a single unexpected key,
and that exception escapes into plugin_manager, which reports it as
"plugin <id> operation failed". Every plugin fails, and the plugin
system never finishes initialising.
Seen on a live rig: every plugin failing with
ResourceMetrics.__init__() got an unexpected keyword argument
'consecutive_failures'
which is a plugin_health field, not a metrics one. How a health-shaped
record came to sit under a plugin_metrics key on that machine is not
established -- a restored backup that mixed two machines' caches is the
likeliest explanation -- but the loader should not be brittle enough for
it to matter. plugin_health already repairs its records field by field
rather than trusting whatever is on disk; this does the same.
Unknown keys are dropped and named once, so a genuine schema change is
visible in the log instead of silently discarded.
"""
if not isinstance(cached, dict):
self.logger.warning(
"Ignoring cached metrics for %s: expected a mapping, got %s",
plugin_id, type(cached).__name__)
return ResourceMetrics()
known = {f.name for f in fields(ResourceMetrics)}
unknown = sorted(set(cached) - known)
if unknown:
self.logger.warning(
"Dropping unrecognised field(s) from cached metrics for %s: %s",
plugin_id, ", ".join(unknown))
usable = {k: v for k, v in cached.items() if k in known}
try:
return ResourceMetrics(**usable)
except (TypeError, ValueError) as e:
self.logger.warning(
"Cached metrics for %s unusable (%s); starting fresh",
plugin_id, e)
return ResourceMetrics()
def _get_metrics_key(self, plugin_id: str) -> str:
"""Get cache key for plugin metrics."""
return f"plugin_metrics:{plugin_id}"
@@ -126,7 +170,7 @@ class PluginResourceMonitor:
cache_key, max_age=None, memory_ttl=0 if force_reload else None
)
if cached:
metrics = ResourceMetrics(**cached)
metrics = self._metrics_from_cache(plugin_id, cached)
else:
metrics = ResourceMetrics()
self._metrics[plugin_id] = metrics
-68
View File
@@ -63,9 +63,6 @@ class StartupValidator:
if self.plugin_manager:
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
if is_valid:
@@ -77,71 +74,6 @@ class StartupValidator:
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:
"""Validate configuration files."""
try:
+100
View File
@@ -0,0 +1,100 @@
"""A malformed metrics cache entry must not take every plugin down with it.
`ResourceMetrics(**cached)` raises TypeError on a single unexpected key, and
that exception escapes into plugin_manager, which reports it per plugin as
"plugin <id> operation failed". Every plugin fails and the plugin system never
finishes initialising -- the health endpoint reports
`plugin_system: not_initialized` while the display itself keeps running.
Seen on a live rig, once per plugin, continuously:
ERROR - src.plugin_system.plugin_manager - plugin geochron operation failed:
ResourceMetrics.__init__() got an unexpected keyword argument
'consecutive_failures'
`consecutive_failures` belongs to plugin_health, not to metrics. How a
health-shaped record came to sit under a plugin_metrics key on that machine is
not established -- a restored backup that mixed two machines' caches is the
likeliest explanation, and the same rig had one restored onto it -- but a
loader that turns one bad cache entry into a total outage is the part worth
fixing. plugin_health already repairs its own records field by field rather
than trusting what is on disk.
"""
import logging
from dataclasses import fields
from unittest.mock import MagicMock
import pytest
from src.plugin_system.resource_monitor import PluginResourceMonitor, ResourceMetrics
class _Cache:
def __init__(self, payload=None):
self.payload = payload
def get(self, key, max_age=None, memory_ttl=None, **kwargs):
return self.payload
def set(self, key, data, ttl=None, **kwargs):
pass
def _monitor(payload):
m = PluginResourceMonitor(cache_manager=_Cache(payload))
m.logger = logging.getLogger("test")
return m
#: What the rig actually had under the metrics key.
HEALTH_SHAPED = {
"consecutive_failures": 0, "circuit_state": "closed",
"circuit_opened_time": None, "half_open_start_time": None,
"last_error": None, "last_failure_time": None,
"last_success_time": 1_700_000_000.0, "total_failures": 0,
"total_successes": 42,
}
def test_a_health_record_under_the_metrics_key_does_not_raise():
"""The exact failure: it must degrade, not take the plugin system down."""
monitor = _monitor(HEALTH_SHAPED)
metrics = monitor.get_metrics(" plugin-a".strip())
assert isinstance(metrics, ResourceMetrics)
def test_recognised_fields_in_a_mixed_record_are_kept():
"""Dropping the record wholesale would lose real history unnecessarily."""
mixed = dict(HEALTH_SHAPED, call_count=7, memory_mb=12.5)
metrics = _monitor(mixed).get_metrics("plugin-b")
assert metrics.call_count == 7
assert metrics.memory_mb == 12.5
def test_a_clean_record_still_loads_unchanged():
clean = {f.name: 3 for f in fields(ResourceMetrics)}
metrics = _monitor(clean).get_metrics("plugin-c")
for name in (f.name for f in fields(ResourceMetrics)):
assert getattr(metrics, name) == 3
def test_unknown_fields_are_named_in_the_log(caplog):
"""Silently discarding them would hide a real schema change."""
with caplog.at_level(logging.WARNING):
_monitor(HEALTH_SHAPED).get_metrics("plugin-d")
# getMessage(), not .message: the latter is only populated once a handler
# formats the record, so the obvious spelling silently never matches.
assert any("consecutive_failures" in r.getMessage() for r in caplog.records), \
caplog.text
@pytest.mark.parametrize("payload", ["a string", 42, ["a", "list"]])
def test_a_non_mapping_cache_entry_does_not_raise(payload):
metrics = _monitor(payload).get_metrics("plugin-e")
assert isinstance(metrics, ResourceMetrics)
def test_values_of_the_wrong_type_do_not_raise():
"""A dataclass will accept these, but a later float() on them would not."""
metrics = _monitor({"call_count": "not a number"}).get_metrics("plugin-f")
assert isinstance(metrics, ResourceMetrics)
-133
View File
@@ -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