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
6 changed files with 150 additions and 123 deletions
+46 -2
View File
@@ -9,7 +9,7 @@ import time
import logging import logging
import threading import threading
from typing import Dict, Optional, Any, Callable from typing import Dict, Optional, Any, Callable
from dataclasses import dataclass, field from dataclasses import dataclass, field, fields
try: try:
import psutil import psutil
@@ -102,6 +102,50 @@ class PluginResourceMonitor:
"psutil not available - resource monitoring will be limited to execution time only" "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: def _get_metrics_key(self, plugin_id: str) -> str:
"""Get cache key for plugin metrics.""" """Get cache key for plugin metrics."""
return f"plugin_metrics:{plugin_id}" 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 cache_key, max_age=None, memory_ttl=0 if force_reload else None
) )
if cached: if cached:
metrics = ResourceMetrics(**cached) metrics = self._metrics_from_cache(plugin_id, cached)
else: else:
metrics = ResourceMetrics() metrics = ResourceMetrics()
self._metrics[plugin_id] = metrics self._metrics[plugin_id] = metrics
+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)
-84
View File
@@ -1,84 +0,0 @@
"""A pull that changed nothing on the running system is not an applied update.
git_pull replaces files on disk and restarts nothing -- there is no systemctl
call anywhere in the handler. The display and web services keep running the
code they loaded at boot, so the user is told "Code updated successfully" and
sees no change until they happen to reboot. The response now says whether a
restart is owed, and the UI raises the existing restart-pending banner.
"""
import subprocess
import sys
from pathlib import Path
from unittest.mock import patch
import pytest
from flask import Flask
sys.path.insert(0, str(Path(__file__).resolve().parent.parent))
from web_interface.blueprints import api_v3 as mod # noqa: E402
from web_interface.blueprints.api_v3 import api_v3 # noqa: E402
@pytest.fixture
def client():
app = Flask(__name__)
app.config['TESTING'] = True
app.register_blueprint(api_v3, url_prefix='/api/v3')
# The handler consults these after a successful pull; None is the
# "not wired up" case it already guards for.
api_v3.plugin_store_manager = None
api_v3.config_manager = None
return app.test_client()
def _git(heads, pull_rc=0, pull_out='Updating a1b2c3..d4e5f6\n'):
"""Fake git. `heads` are the successive answers to rev-parse HEAD."""
seq = list(heads)
def run(args, **kwargs):
def ok(stdout='', rc=0, b=False):
return subprocess.CompletedProcess(
args, rc, stdout=(stdout.encode() if b else stdout),
stderr=(b'' if b else ''))
if args[:2] == ['git', 'rev-parse'] and args[-1] == 'HEAD':
return ok(seq.pop(0) + '\n' if seq else 'deadbeef\n')
if 'symbolic-full-name' in args or '@{u}' in args:
return ok('origin/main\n')
if args[:2] == ['git', 'status']:
return ok('')
if args[:2] == ['git', 'diff']:
return ok('')
if args[:2] == ['git', 'pull']:
return ok(pull_out, pull_rc)
return ok('')
return run
def _pull(client):
return client.post('/api/v3/system/action',
json={'action': 'git_pull'}).get_json()
class TestRestartIsRequestedWhenCodeChanged:
def test_a_pull_that_moved_head_asks_for_a_restart(self, client):
with patch.object(mod.subprocess, 'run', _git(['aaa111', 'bbb222'])):
data = _pull(client)
assert data['status'] == 'success'
assert data['restart_required'] is True, (
"new code on disk, services still running the old code, and "
"nothing told the user to restart")
def test_already_up_to_date_does_not(self, client):
with patch.object(mod.subprocess, 'run',
_git(['aaa111', 'aaa111'], pull_out='Already up to date.\n')):
data = _pull(client)
assert data['status'] == 'success'
assert data['restart_required'] is False, (
"prompting after a no-op update trains users to ignore the prompt")
def test_a_failed_pull_does_not(self, client):
with patch.object(mod.subprocess, 'run', _git(['aaa111'], pull_rc=1)):
data = _pull(client)
assert data['status'] == 'error'
assert data['restart_required'] is False
-11
View File
@@ -1996,11 +1996,6 @@ def execute_system_action():
except subprocess.TimeoutExpired: except subprocess.TimeoutExpired:
logger.warning("git rev-parse timed out before pull") logger.warning("git rev-parse timed out before pull")
# Whether the pull actually brought new code in. "Already up to
# date" is a success too, and prompting for a restart then would
# train users to ignore the prompt.
code_changed = False
# Perform the git pull. Branches without an upstream were given # Perform the git pull. Branches without an upstream were given
# an explicit "origin <branch>" above so the update still works. # an explicit "origin <branch>" above so the update still works.
result = subprocess.run( result = subprocess.run(
@@ -2044,7 +2039,6 @@ def execute_system_action():
capture_output=True, text=True, timeout=10, cwd=project_dir) capture_output=True, text=True, timeout=10, cwd=project_dir)
new_head = _post.stdout.strip() if _post.returncode == 0 else None new_head = _post.stdout.strip() if _post.returncode == 0 else None
if old_head and new_head and old_head != new_head: if old_head and new_head and old_head != new_head:
code_changed = True
diff = subprocess.run( diff = subprocess.run(
['git', 'diff', '--name-only', f'{old_head}..{new_head}'], ['git', 'diff', '--name-only', f'{old_head}..{new_head}'],
capture_output=True, text=True, timeout=15, cwd=project_dir) capture_output=True, text=True, timeout=15, cwd=project_dir)
@@ -2104,14 +2098,9 @@ def execute_system_action():
if ln.strip()), '') if ln.strip()), '')
pull_message = f"Update failed: {detail}" if detail else "Update failed; check logs for details" pull_message = f"Update failed: {detail}" if detail else "Update failed; check logs for details"
# Nothing here restarts anything: the pull replaces files on
# disk while the display and web services keep running the code
# they loaded at boot. Without this the user is told the update
# succeeded and sees no change until they happen to reboot.
return jsonify({ return jsonify({
'status': 'success' if result.returncode == 0 else 'error', 'status': 'success' if result.returncode == 0 else 'error',
'message': pull_message, 'message': pull_message,
'restart_required': bool(result.returncode == 0 and code_changed),
}) })
elif action == 'checkout_branch': elif action == 'checkout_branch':
# Switch branches from the Tools tab. Needed because a checkout # Switch branches from the Tools tab. Needed because a checkout
+3 -17
View File
@@ -116,25 +116,14 @@ document.body.addEventListener('htmx:afterRequest', function(event) {
// ===== Restart-pending banner ===== // ===== Restart-pending banner =====
// Shown after restart-requiring saves; persists across tab switches (and // Shown after restart-requiring saves; persists across tab switches (and
// reloads, via sessionStorage) until the display restarts or it's dismissed. // reloads, via sessionStorage) until the display restarts or it's dismissed.
window.showRestartPending = function(message) { window.showRestartPending = function() {
try { try { sessionStorage.setItem('ledmatrix-restart-pending', '1'); } catch { /* private browsing */ }
sessionStorage.setItem('ledmatrix-restart-pending', '1');
// Persisted alongside the flag: a code update and a config save want
// different wording, and the banner outlives the page that raised it.
if (message) sessionStorage.setItem('ledmatrix-restart-pending-text', message);
else sessionStorage.removeItem('ledmatrix-restart-pending-text');
} catch { /* private browsing */ }
const banner = document.getElementById('restart-pending-banner'); const banner = document.getElementById('restart-pending-banner');
const text = document.getElementById('restart-pending-text');
if (text && message) text.textContent = message;
if (banner) banner.style.display = 'block'; if (banner) banner.style.display = 'block';
}; };
window.dismissRestartPending = function() { window.dismissRestartPending = function() {
try { try { sessionStorage.removeItem('ledmatrix-restart-pending'); } catch { /* no-op */ }
sessionStorage.removeItem('ledmatrix-restart-pending');
sessionStorage.removeItem('ledmatrix-restart-pending-text');
} catch { /* no-op */ }
const banner = document.getElementById('restart-pending-banner'); const banner = document.getElementById('restart-pending-banner');
if (banner) banner.style.display = 'none'; if (banner) banner.style.display = 'none';
}; };
@@ -162,9 +151,6 @@ document.addEventListener('DOMContentLoaded', function() {
try { try {
if (sessionStorage.getItem('ledmatrix-restart-pending') === '1') { if (sessionStorage.getItem('ledmatrix-restart-pending') === '1') {
const banner = document.getElementById('restart-pending-banner'); const banner = document.getElementById('restart-pending-banner');
const saved = sessionStorage.getItem('ledmatrix-restart-pending-text');
const text = document.getElementById('restart-pending-text');
if (text && saved) text.textContent = saved;
if (banner) banner.style.display = 'block'; if (banner) banner.style.display = 'block';
} }
} catch { /* no-op */ } } catch { /* no-op */ }
+1 -9
View File
@@ -413,8 +413,7 @@
<div class="flex items-center justify-between"> <div class="flex items-center justify-between">
<div class="flex items-center space-x-3"> <div class="flex items-center space-x-3">
<i class="fas fa-rotate text-lg"></i> <i class="fas fa-rotate text-lg"></i>
<span class="text-sm font-medium" aria-live="polite" <span class="text-sm font-medium" aria-live="polite">
id="restart-pending-text">
Configuration saved &mdash; restart the display to apply the changes Configuration saved &mdash; restart the display to apply the changes
</span> </span>
</div> </div>
@@ -1147,13 +1146,6 @@
if (data.status === 'success') { if (data.status === 'success') {
document.getElementById('update-banner').style.display = 'none'; document.getElementById('update-banner').style.display = 'none';
try { sessionStorage.removeItem('update-sha-dismissed'); } catch(e) {} try { sessionStorage.removeItem('update-sha-dismissed'); } catch(e) {}
// The pull replaced files on disk; the running services still
// hold the code they loaded at boot. Ask for the restart that
// makes the update actually take effect.
if (data.restart_required && typeof window.showRestartPending === 'function') {
window.showRestartPending(
'Update installed \u2014 restart the display to run the new code');
}
} }
if (typeof showNotification === 'function') { if (typeof showNotification === 'function') {
showNotification(data.message || 'Update complete', data.status || 'success'); showNotification(data.message || 'Update complete', data.status || 'success');