diff --git a/CHANGELOG.md b/CHANGELOG.md index 892b83c1..baad4af8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -19,6 +19,45 @@ accepts both, but the store flags the old spelling as deprecated ## Unreleased +### Frozen-panel detection + +A render loop stuck inside a plugin's `display()` left `ledmatrix.service` +"active" with the panel frozen, and nothing noticed: `/api/v3/health` judged +the display by the preview PNG's age, and the automatic update's health check +passed "service active plus one HTTP 200". + +- **systemd watchdog.** `ledmatrix.service` now has `WatchdogSec=120` and + `NotifyAccess=main` (still `Type=simple`). The render thread itself pings + systemd over `$NOTIFY_SOCKET` (`src/display_watchdog.py`, standard library + only), so a stuck render thread stops the pings even while the update + worker and Vegas's tick thread carry on. systemd then kills the display with + SIGABRT -- faulthandler writes every thread's stack to the journal, which + names the plugin -- and restarts it. The process widens the limit to 15 + minutes while it starts and while it loads a plugin enabled from the web UI + (either can run pip), and sends `READY=1` and narrows it back after its + first frame. +- **Heartbeat.** The render loop writes `/run/ledmatrix/display-heartbeat.json` + every 5 seconds (`RuntimeDirectory=ledmatrix`; tmpfs, so no SD-card + writes). `/api/v3/health` reports it as `checks.display_loop`: `running`, + `stalled` (older than 60s; the overall status turns `degraded`) or + `not_reported` when there is no heartbeat (dev server, emulator, Windows), + which leaves the verdict to the older checks as before. +- **Update health check.** When the display wrote a heartbeat before an + automatic update, the restarted display must keep one fresh (30s) for the + update to pass; a frozen panel is rolled back. Code that never wrote one is + checked as before. The check runs as the copy taken before the update, so + this takes effect from the update after the one that installs it. +- **Crash loops back off.** `RestartSteps=4` and `RestartMaxDelaySec=2min` + stretch the delay between automatic restarts from 10s to two minutes, instead + of retrying every 10s forever. systemd before 254 (Bookworm) ignores the two + lines with a warning. A start limit was ruled out: once tripped it leaves the + panel dark and refuses the web UI's Start button and the update rollback. +- **Existing installs** keep their old unit until `sudo + ./scripts/install/install_service.sh` is re-run (an update never rewrites + units; the startup validator warns about the drift). Until then there is no + watchdog, but the display creates `/run/ledmatrix` itself, so the heartbeat, + the health check and the update check work straight away. + ### Security - The web interface refuses state-changing requests (`POST`, `PUT`, `PATCH`, diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index be73bab3..323300ff 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -52,6 +52,7 @@ each other. They share three things: | Preview frame | `/tmp/led_matrix_preview.png` | display: `DisplayManager`, gated by [`snapshot_policy`](../src/common/snapshot_policy.py) | web: display SSE stream, `/api/v3/health` (file age) | | Preview viewer marker | `/tmp/led_matrix_preview_viewer` | web, while a preview is open | display: writes full-rate snapshots only while it is fresh | | Hardware init status | `/tmp/led_matrix_hw_status.json` | display | web: `/api/v3/hardware/status` | +| Render-loop heartbeat | `/run/ledmatrix/display-heartbeat.json` (tmpfs) | display: the render thread, via [`display_watchdog`](../src/display_watchdog.py) | web: `/api/v3/health` (`checks.display_loop`); the update health check | The on-demand start route starts `ledmatrix.service` when it is not running (`start_service`, on by default) but never restarts a running one: the display @@ -228,6 +229,43 @@ then normal rotation. `sync.role`: a leader sends a follower its share of each frame over UDP (port 5765). +### Liveness + +A render thread stuck inside a plugin leaves the service "active" and the +panel frozen, so liveness is reported by the render thread itself +([`src/display_watchdog.py`](../src/display_watchdog.py), standard library +only). `beat()` from any other thread is ignored: the update worker, Vegas's +tick thread and the prefetcher keep running while the render thread is stuck, +and must not vouch for it. + +- **Check-in points.** The top of `run()`'s loop (`loop_pass()`), every + dwell second (`_sleep_with_plugin_updates`), every frame of the per-screen + loops (`_display_once`), every frame of Vegas's own loop and static pause + (`coordinator.run_iteration`), each plugin fetched for a Vegas cycle + (`StreamManager._fetch_plugin_content`), each update on the + `synchronous_updates` path, and every frame pushed + (`DisplayManager.update_display` -> `note_frame()`). Beats are + rate-limited to one ping and one heartbeat write every 5 s. +- **systemd watchdog.** `ledmatrix.service` is `Type=simple` with + `WatchdogSec=120` and `NotifyAccess=main`. `run.py` sends + `WATCHDOG_USEC` = 15 minutes before importing anything heavy (start-up loads + plugins and runs the 20 s update budget, and the watchdog clock starts with + the process). After the first frame -- or the first full pass, when there is + nothing to draw -- the loop sends `READY=1`, restores the unit's 120 s and + pings. `PluginManager.load_plugin()` on the render thread (a plugin enabled + from the web UI, or loaded for on-demand) gets 15 minutes again, since it + can run pip. A missed deadline is a SIGABRT; faulthandler, enabled on + arming, dumps every thread's stack to the journal. +- **Heartbeat.** `/run/ledmatrix/display-heartbeat.json` + (`{"pid", "mono", "wall"}`; `RuntimeDirectory=ledmatrix`, 0755, file 0644 so + the web user can read it). Readers compare `mono` with their own + `time.monotonic()` -- CLOCK_MONOTONIC is shared by every process and does not + jump when NTP first sets an RTC-less Pi's clock. `/api/v3/health` calls it + `stalled` past 60 s; no file is `not_reported` and changes nothing. A clean + stop removes it. Without `RuntimeDirectory=` (an older unit) the display, + as root, creates the directory itself; off Linux, or without root, there + is no heartbeat. + ## Plugin system [`src/plugin_system/`](../src/plugin_system/): @@ -310,7 +348,9 @@ everything else through `_reinstall_with_rollback()`. `ledmatrix-update-verify.path`, which runs the verifier as a separate unit (so restarting the web service does not kill it). The verifier restarts both services, waits for the web API to answer and the display service to - stay up, and on failure resets to the previous commit and restarts again. + stay up -- and, when the display wrote a heartbeat before the update, to + keep one fresh from the restarted process (see Liveness) -- and on failure + resets to the previous commit and restarts again. Plugin updates run only after a verified core update. State is in `data/auto_update_state.json` and `data/auto_update_pending.json`. - **Startup validator.** `StartupValidator` @@ -318,7 +358,9 @@ everything else through `_reinstall_with_rollback()`. `DisplayController.__init__`: config and cache directory first, then enabled plugins once the plugin manager exists. It also warns when an installed systemd unit differs from its template in `systemd/`. Results - are logged; startup continues either way. + are logged; startup continues either way. Nothing rewrites installed units + on update: a unit change such as the watchdog reaches an existing install + only when `install_service.sh` is re-run. ## Where to start reading diff --git a/docs/REST_API_REFERENCE.md b/docs/REST_API_REFERENCE.md index 5db4cf55..6248cb43 100644 --- a/docs/REST_API_REFERENCE.md +++ b/docs/REST_API_REFERENCE.md @@ -2101,9 +2101,17 @@ Health of the web interface, display service, config file, plugin system and display snapshot. `data.status` is `healthy` or `degraded`, with `data.services` and `data.checks`. +`data.checks.display_loop` is the display's render-loop heartbeat: `running` +(with `heartbeat_age_seconds`), `stalled` (no heartbeat for 60s: the panel is +frozen even if the service is active; the status turns `degraded`), or +`not_reported` when the display writes none (not started yet, the dev server, +Windows), which does not affect the status. + Open even when the web login is on, for uptime monitors; a caller that is not logged in (and has no token) then gets only `{"status": "success", "data": -{"status": "healthy" | "degraded"}}`. +{"status": "healthy" | "degraded"}}`. A stalled render loop still shows there +as `degraded`; the `checks` detail is only for logged-in callers, tokens and +requests from the Pi itself. ### Hardware Status diff --git a/docs/TROUBLESHOOTING.md b/docs/TROUBLESHOOTING.md index 1d126eed..e93b1859 100644 --- a/docs/TROUBLESHOOTING.md +++ b/docs/TROUBLESHOOTING.md @@ -516,6 +516,64 @@ sudo systemctl cat ledmatrix-web | grep User python3 scripts/check_plugin.py --plugin plugin-id ``` +#### Panel Frozen, or the Display Restarts Every Few Minutes + +**Symptoms:** +- The panel stops changing while `systemctl status ledmatrix` says `active` +- The display restarts on its own, a couple of minutes after it froze +- `/api/v3/health` shows `checks.display_loop.status` as `stalled` + +The display's render loop checks in with systemd every few seconds +(`WatchdogSec=120` in `ledmatrix.service`) and writes a heartbeat to +`/run/ledmatrix/display-heartbeat.json`. When the loop gets stuck -- almost +always inside one plugin's `display()` -- the check-ins stop, and after two +minutes systemd kills and restarts the display. The kill dumps every thread's +stack into the log, so it says which plugin was stuck. + +**Solutions:** + +1. **Find the stuck plugin.** Look for the watchdog kill and the stack dump + after it. The render loop is the thread whose stack runs through + `display_controller.py` in `run` (usually the `Current thread` block); + the first `plugin-repos/...` file in it is the plugin: + ```bash + sudo journalctl -u ledmatrix --since "1 hour ago" | grep -A40 "Watchdog timeout" + ``` + +2. **Check the heartbeat by hand.** Its age should stay under about ten + seconds while the display runs: + ```bash + cat /run/ledmatrix/display-heartbeat.json + curl -s http://localhost:5000/api/v3/health | python3 -m json.tool | grep -A3 display_loop + ``` + `not_reported` means the display writes no heartbeat: it has not drawn + its first frame yet, or it runs an older version. + +3. **Disable the plugin** in the web UI and report it to its author with the + stack dump. Restarts that repeat back off from 10 seconds to two minutes + apart, so a plugin that hangs on every start does not restart the display + hundreds of times an hour. + +4. **Is the watchdog installed?** Installs from before it keep their old unit + until the installer is re-run (a startup warning says the unit differs + from its template): + ```bash + systemctl show -p WatchdogUSec ledmatrix # 2min once running; 0 = not installed + sudo ./scripts/install/install_service.sh + ``` + `WatchdogUSec` reads `15min` for the first minutes after a start: that is + the start-up allowance, narrowed to two minutes once the first frame is on + the panel. + +5. **A plugin that legitimately blocks longer** than two minutes (it should + not; `display()` runs on the render thread) can be given more time with a + drop-in, `sudo systemctl edit ledmatrix`: + ```ini + [Service] + WatchdogSec=300 + ``` + `WatchdogSec=0` turns the watchdog off. + #### Stale Cache Data **Symptoms:** diff --git a/run.py b/run.py index b7b1f52a..c327d549 100755 --- a/run.py +++ b/run.py @@ -14,6 +14,14 @@ project_dir = os.path.dirname(os.path.abspath(__file__)) if project_dir not in sys.path: sys.path.insert(0, project_dir) +# Under systemd the watchdog clock is already running, and start-up (plugin +# loads, initial updates) takes far longer than the render loop's limit. Widen +# it before anything slow is imported; the render loop narrows it again once +# its first frame is on the panel. A no-op outside systemd. Standard library +# only -- see src/display_watchdog.py. +from src import display_watchdog +display_watchdog.watchdog.begin_startup() + # Parse command-line arguments BEFORE any imports parser = argparse.ArgumentParser(description='LEDMatrix Display Controller') parser.add_argument('-e', '--emulator', action='store_true', diff --git a/scripts/utils/auto_update_verify.py b/scripts/utils/auto_update_verify.py index d75fe276..37097c42 100644 --- a/scripts/utils/auto_update_verify.py +++ b/scripts/utils/auto_update_verify.py @@ -20,6 +20,13 @@ This moves its status to "verifying" and then to one of "success", "rolled_back" or "rollback_failed", with "reason" and "detail" saying why. The web interface reports that outcome and raises a banner for anything but success. + +"The display service is active" does not mean the panel is drawing: a render +loop stuck inside a plugin leaves the service active and the panel frozen. +Where the display writes a heartbeat (/run/ledmatrix, see +src/display_watchdog.py), the display also has to keep it fresh, from the +restarted process, to count as healthy. Where it never wrote one -- the code +being updated predates it -- the check is what it always was. """ import json import os @@ -36,6 +43,14 @@ from pathlib import Path PENDING_NAME = 'auto_update_pending.json' REQUIREMENT_FILES = ('requirements.txt', 'web_interface/requirements.txt') WEB_HEALTH_URL = 'http://127.0.0.1:5000/api/v3/system/version' +#: Written by the display's render loop every few seconds. A copy of +#: src/display_watchdog.HEARTBEAT_PATH, not an import: this file runs as a +#: copy made before the update and must not depend on the code it checks. +HEARTBEAT_PATH = '/run/ledmatrix/display-heartbeat.json' +#: How old the heartbeat may be. Well under STABLE_SECONDS: a display that +#: draws its first frame and then freezes must go stale inside the window it +#: has to stay healthy for, or the check would pass it. +HEARTBEAT_FRESH_SECONDS = 30 #: How long the services get to come up after a restart... HEALTH_TIMEOUT_SECONDS = 180 #: ...and how long they must then stay up. Restart=on-failure makes a crash @@ -113,16 +128,35 @@ def _short(sha): return (sha or 'unknown')[:7] +def _read_heartbeat(path=HEARTBEAT_PATH): + """The display's heartbeat, or None when there is none (or it is unreadable).""" + try: + with open(path, 'r', encoding='utf-8') as f: + data = json.load(f) + except (OSError, ValueError): + return None + return data if isinstance(data, dict) else None + + class Verifier: def __init__(self, project_root, run=subprocess.run, sleep=time.sleep, - clock=time.monotonic, web_responds=_web_responds, log=None): + clock=time.monotonic, web_responds=_web_responds, log=None, + read_heartbeat=_read_heartbeat): self.project_root = Path(project_root) self.pending_file = pending_path(project_root) self.run = run self.sleep = sleep + # Monotonic, and compared with the heartbeat's own monotonic stamp: + # CLOCK_MONOTONIC is one clock for every process on the machine. self.clock = clock self.web_responds = web_responds self.log = log or (lambda msg: print(f'[auto-update-verify] {msg}', flush=True)) + self.read_heartbeat = read_heartbeat + #: Whether the display was writing a heartbeat before the update. + self.expect_heartbeat = False + #: When the display was last restarted; an older heartbeat is the + #: previous process's, not proof the new one draws. + self.display_restarted_at = None def _run(self, args, timeout=GIT_TIMEOUT_SECONDS): try: @@ -154,18 +188,32 @@ class Verifier: ok = True # A display the user had stopped stays stopped. if display: + self.display_restarted_at = self.clock() ok = self.restart('ledmatrix') and ok return self.restart('ledmatrix-web') and ok + def display_drawing(self): + """True while the restarted display keeps its heartbeat fresh.""" + data = self.read_heartbeat() + mono = data.get('mono') if data else None + if not isinstance(mono, (int, float)) or isinstance(mono, bool): + return False + if self.display_restarted_at is not None and mono < self.display_restarted_at: + return False # still the process from before the restart + return self.clock() - mono <= HEARTBEAT_FRESH_SECONDS + def wait_healthy(self, display): """None once the services are up and stay up, else what went wrong.""" deadline = self.clock() + HEALTH_TIMEOUT_SECONDS + STABLE_SECONDS healthy_since = baseline = None web = disp = False + active = drawing = True count_known = True while self.clock() < deadline: web = self.web_responds() - disp = self.service_active('ledmatrix') if display else True + active = self.service_active('ledmatrix') if display else True + drawing = self.display_drawing() if (display and self.expect_heartbeat) else True + disp = active and drawing restarts = self.restart_count('ledmatrix') if display else None # Without a restart count a crash loop looks healthy between # attempts, so an unreadable count never counts as stable. @@ -181,8 +229,11 @@ class Verifier: problems = [] if not web: problems.append('the web interface did not respond') - if not disp: + if not active: problems.append('the display service did not stay running') + elif not drawing: + problems.append('the display service is running but its panel is not ' + 'being drawn (no fresh heartbeat)') if web and disp and not count_known: problems.append("the display service's restart count could not be read") return '; '.join(problems) or 'the display service kept restarting' @@ -258,6 +309,10 @@ class Verifier: write_pending(self.pending_file, pending) display = bool(pending.get('display_was_active')) + # Read before anything restarts: the display still running is the + # pre-update code, and whether it writes a heartbeat decides whether + # the updated one must. + self.expect_heartbeat = display and self.read_heartbeat() is not None dependency_failures = pending.get('dependency_failures') or [] if dependency_failures: # Never restart onto code whose packages did not install. diff --git a/src/display_controller.py b/src/display_controller.py index df148f10..883b16d6 100644 --- a/src/display_controller.py +++ b/src/display_controller.py @@ -34,6 +34,7 @@ from datetime import datetime from concurrent.futures import ThreadPoolExecutor, as_completed # pylint: disable=no-name-in-module import pytz +from src import display_watchdog from src.display_manager import DisplayManager from src.config_manager import ConfigManager from src.config_service import ConfigService @@ -1052,6 +1053,8 @@ class DisplayController: the plugin's update() holds its lock (the panel keeps the last frame; that is not a failure). """ + # Every frame of both per-screen render loops comes through here. + display_watchdog.watchdog.beat() plugin_id = getattr(plugin, 'plugin_id', None) with self._display_lock_or_skip(plugin_id) as can_display: if not can_display: @@ -1148,6 +1151,9 @@ class DisplayController: sleep_time = min(tick_interval, remaining) time.sleep(sleep_time) + # A dwell can be a minute long (sixty seconds while scheduled + # off); the watchdog must hear from this thread throughout. + display_watchdog.watchdog.beat() self._tick_plugin_updates() self._service_pending_changes() if (self.current_display_mode != mode @@ -2238,6 +2244,11 @@ class DisplayController: "plugin is enabled via the web UI." ) + # This thread is the one the systemd watchdog and the heartbeat + # vouch for: beats from any other thread are ignored, so a render + # thread stuck inside a plugin stops them. + display_watchdog.watchdog.bind_render_thread() + try: # Initialize with cached data for fast startup - let background updates refresh naturally logger.info("Starting display with cached data (fast startup mode)") @@ -2246,6 +2257,11 @@ class DisplayController: self._publish_current_mode_state() while True: + # Arms the watchdog after the first frame -- or after the + # first full pass, when there is nothing to draw -- and pings + # it from then on. + display_watchdog.watchdog.loop_pass() + # Apply plugin enable/disable edits saved via the web UI. The # config-watcher thread only sets the flag; loading/unloading and # rebuilding available_modes happens here on the render thread so @@ -3625,6 +3641,9 @@ class DisplayController: def cleanup(self): """Clean up resources.""" + # First: a clean stop is not a hang, and a heartbeat left behind + # would read as a frozen panel to the web interface. + display_watchdog.watchdog.stopping() # Stop the async update worker first so no in-flight update() call # is still touching display/cache-backed resources while they're # torn down below. diff --git a/src/display_manager.py b/src/display_manager.py index 0b6ca7a7..4e32f630 100644 --- a/src/display_manager.py +++ b/src/display_manager.py @@ -57,6 +57,7 @@ import zlib import freetype from src.common import snapshot_policy +from src import display_watchdog from src.common.frame_timing import FrameTimingRecorder if TYPE_CHECKING: @@ -928,6 +929,9 @@ class DisplayManager: # the fallback branch, so captured content never reaches the # web preview either. return + # The render loop's watchdog arms on the first frame to reach + # the panel (or the emulator/fallback path standing in for it). + display_watchdog.note_frame() with self._update_lock: if self.matrix is None: # Fallback mode - no actual hardware to update diff --git a/src/display_watchdog.py b/src/display_watchdog.py new file mode 100644 index 00000000..c32f82df --- /dev/null +++ b/src/display_watchdog.py @@ -0,0 +1,414 @@ +"""Render-loop liveness: systemd watchdog pings and a heartbeat file. + +A panel can freeze while ``ledmatrix.service`` stays "active": a plugin's +``display()`` that never returns, a deadlock, a stuck hardware swap. Nothing +outside the process could tell, so nothing restarted it. This module lets the +render loop prove it is still going round, in two ways: + +* **systemd watchdog.** The unit sets ``WatchdogSec=`` and + ``NotifyAccess=main``; this sends ``WATCHDOG=1`` over ``$NOTIFY_SOCKET``. + When the pings stop, systemd kills the process (SIGABRT, so faulthandler + prints every thread's stack to the journal first) and ``Restart=`` brings it + back. +* **Heartbeat file**, ``/run/ledmatrix/display-heartbeat.json``, for the web + interface's ``/api/v3/health`` and the automatic update's health check. + ``/run`` is tmpfs, so the writes never reach the SD card. + +Both are driven only from the render thread -- ``beat()`` from any other +thread is ignored -- so a render thread stuck inside a plugin stops them even +while every other thread carries on. The unit's ``WatchdogSec=`` is the +steady-state limit; start-up (plugin loads, the 20s initial update budget, +dependency installs) is far longer and happens before the render loop exists, +so ``begin_startup()`` widens the limit for it and the render loop narrows it +back, sends ``READY=1`` and starts pinging once its first frame is on the +panel. See docs/ARCHITECTURE.md ("Liveness") for the unit settings. + +Standard library only, and no import of the rest of ``src``: ``run.py`` loads +this before anything heavy so the start-up allowance is in place long before +the unit's own ``WatchdogSec`` could expire. Without ``$NOTIFY_SOCKET`` (dev +server, emulator, Windows, an older unit) every call is a cheap no-op, and the +heartbeat is written only where ``/run/ledmatrix`` exists or can be created. +""" +import contextlib +import json +import logging +import os +import socket +import tempfile +import threading +import time +from typing import Any, Callable, Dict, Iterator, Mapping, Optional + +logger = logging.getLogger(__name__) + +#: Where the display writes its heartbeat. ``RuntimeDirectory=ledmatrix`` in +#: the unit creates the directory; a display running under an older unit +#: creates it itself (it runs as root). The web interface, which is not root, +#: only reads it: the directory is 0755 and the file 0644. +HEARTBEAT_DIR = '/run/ledmatrix' +HEARTBEAT_NAME = 'display-heartbeat.json' +HEARTBEAT_PATH = HEARTBEAT_DIR + '/' + HEARTBEAT_NAME + +#: How often the render loop pings systemd and rewrites the heartbeat. Beats +#: come many times a second; this is the rate limit on the side effects. +BEAT_INTERVAL_SECONDS = 5.0 + +#: A heartbeat older than this means the render loop has stopped. Above the +#: longest gap a healthy loop has (the executor's 30s display() timeout), so a +#: slow plugin does not read as a frozen panel. +HEARTBEAT_STALE_SECONDS = 60.0 + +#: The watchdog limit while the process starts, before the render loop runs. +#: Start-up loads every plugin (pip included, when a dependency is missing: +#: up to 300s a try), then spends up to 20s on initial updates. A hang in +#: there is still caught, just later. +STARTUP_ALLOWANCE_SECONDS = 15 * 60 + +#: The watchdog limit while the render thread loads a plugin that was just +#: enabled from the web UI: loading can run pip, on this thread. +PLUGIN_LOAD_ALLOWANCE_SECONDS = 15 * 60 + + +# -- sd_notify ------------------------------------------------------------- + +def notify(message: str, environ: Optional[Mapping[str, str]] = None, + socket_factory: Optional[Callable[..., Any]] = None) -> bool: + """Send ``message`` to systemd over ``$NOTIFY_SOCKET``; True if it was sent. + + The same protocol as libsystemd's ``sd_notify()``: one datagram of + newline-separated ``KEY=VALUE`` lines to an AF_UNIX socket. An address + starting with ``@`` is in the abstract namespace (a leading NUL byte). + Never raises: a missing socket or a failed send is simply False, so a + display run outside systemd behaves exactly as before. + """ + env = os.environ if environ is None else environ + address = env.get('NOTIFY_SOCKET') or '' + if address.startswith('@'): + address = '\0' + address[1:] + elif not address.startswith('/'): + # Unset, or a vsock: address (systemd 253+, VMs only). + return False + family = getattr(socket, 'AF_UNIX', None) + if family is None: + return False + factory = socket_factory or socket.socket + try: + sock = factory(family, socket.SOCK_DGRAM | getattr(socket, 'SOCK_CLOEXEC', 0)) + try: + sock.connect(address) + sock.sendall(message.encode('utf-8')) + finally: + sock.close() + return True + except OSError as e: + logger.debug("sd_notify(%r) failed: %s", message, e) + return False + + +def watchdog_usec(environ: Optional[Mapping[str, str]] = None) -> Optional[int]: + """The unit's ``WatchdogSec`` in microseconds, or None when it has none. + + systemd passes it as ``$WATCHDOG_USEC``, with ``$WATCHDOG_PID`` naming the + process it is meant for (a child that inherited the environment must not + think the watchdog is its own). + """ + env = os.environ if environ is None else environ + pid = env.get('WATCHDOG_PID') + if pid and pid != str(os.getpid()): + return None + try: + usec = int(env.get('WATCHDOG_USEC', '')) + except ValueError: + return None + return usec if usec > 0 else None + + +# -- heartbeat reading (web interface) --------------------------------------- + +def read_heartbeat(path: str = HEARTBEAT_PATH) -> Optional[Dict[str, Any]]: + """The heartbeat the display last wrote, or None when there is none. + + None covers a display that does not write one -- dev server, emulator, + Windows, a display that has not drawn its first frame yet -- as well as an + unreadable file, so callers fall back to whatever they did before. + """ + try: + with open(path, 'r', encoding='utf-8') as f: + data = json.load(f) + except (OSError, ValueError): + return None + return data if isinstance(data, dict) else None + + +def heartbeat_age(data: Mapping[str, Any], now_mono: Optional[float] = None, + now_wall: Optional[float] = None) -> Optional[float]: + """Seconds since the heartbeat in ``data`` was written, or None if it has no time. + + Measured on the monotonic clock when it can be: on Linux that is + CLOCK_MONOTONIC, shared by every process, and it does not jump when NTP + first corrects the clock of a Pi with no RTC. /run is emptied at boot, so + a heartbeat always comes from this boot. Falls back to the wall clock. + """ + now_mono = time.monotonic() if now_mono is None else now_mono + now_wall = time.time() if now_wall is None else now_wall + mono = data.get('mono') + if isinstance(mono, (int, float)) and not isinstance(mono, bool): + age = now_mono - mono + if age >= -1.0: # a clock this far behind is not the same clock + return max(age, 0.0) + wall = data.get('wall') + if isinstance(wall, (int, float)) and not isinstance(wall, bool): + return max(now_wall - wall, 0.0) + return None + + +# -- the render loop's side ---------------------------------------------------- + +_DEFAULT_DIR = object() + + +class RenderWatchdog: + """Pings systemd and writes the heartbeat, from the render thread only. + + Lifecycle: ``begin_startup()`` as the process starts, ``bind_render_thread()`` + when ``DisplayController.run()`` starts, then ``note_frame()`` for every + frame pushed to the panel and ``beat()`` / ``loop_pass()`` from every place + the render loop reliably comes back to. The first beat after the first + frame (or after the loop's first full pass, when there is nothing to draw) + arms it: ``READY=1``, the unit's own ``WatchdogSec``, and the heartbeat. + """ + + def __init__(self, environ: Optional[Mapping[str, str]] = None, + send: Optional[Callable[[str], bool]] = None, + clock: Callable[[], float] = time.monotonic, + wall_clock: Callable[[], float] = time.time, + heartbeat_dir: Any = _DEFAULT_DIR, + enable_faulthandler: bool = True): + env = dict(os.environ if environ is None else environ) + self._send = send or (lambda message: notify(message, env)) + self._clock = clock + self._wall_clock = wall_clock + self._usec = watchdog_usec(env) + if heartbeat_dir is _DEFAULT_DIR: + # /run exists only on Linux; elsewhere (Windows dev) there is no + # heartbeat rather than a C:\run folder. + heartbeat_dir = HEARTBEAT_DIR if os.name == 'posix' else None + self._heartbeat_dir: Optional[str] = heartbeat_dir + # None until the first write; False for good if that one failed + # (nowhere to write: not root, no /run); True once one landed. + self._heartbeat_ok: Optional[bool] = None + self._heartbeat_warned = False + self._enable_faulthandler = enable_faulthandler + self._render_thread: Optional[int] = None + self._frame_pushed = False + self._passes = 0 + self._armed = False + self._last_beat: Optional[float] = None + self._extend_depth = 0 + interval = BEAT_INTERVAL_SECONDS + if self._usec: + # systemd's advice is to ping at half the limit; a third leaves + # room for one late beat even if someone sets a very short one. + interval = min(interval, self._usec / 1e6 / 3) + self._interval = interval + + @property + def armed(self) -> bool: + return self._armed + + def _on_render_thread(self) -> bool: + return self._render_thread is not None and threading.get_ident() == self._render_thread + + def begin_startup(self) -> None: + """Widen the watchdog to cover start-up. Call as early as possible. + + systemd starts the watchdog clock when a Type=simple service starts, + and start-up routinely takes longer than the render loop's limit. + Only widens: an operator who set a longer ``WatchdogSec`` keeps it. + """ + if not self._usec: + return + allowance = max(self._usec, int(STARTUP_ALLOWANCE_SECONDS * 1e6)) + self._send(f'WATCHDOG_USEC={allowance}\nSTATUS=Starting: loading plugins') + + def bind_render_thread(self) -> None: + """Mark the calling thread as the render thread; beats from others are ignored.""" + self._render_thread = threading.get_ident() + self._frame_pushed = False + self._passes = 0 + + def note_frame(self) -> None: + """A frame was pushed to the panel (DisplayManager.update_display). + + Any thread may push the first one -- the first dispatch of a screen + runs on PluginExecutor's thread -- so this only records it; the + render thread's next beat arms the watchdog. + """ + if self._render_thread is None: + return # start-up screens, before the render loop exists + self._frame_pushed = True + if self._on_render_thread(): + self.beat() + + def loop_pass(self) -> None: + """The top of the render loop's ``while True``. + + A second arrival here means a whole pass finished. That counts as the + first frame when there was nothing to draw (no plugins enabled, every + screen empty): the loop is plainly alive, and a watchdog that never + armed would leave a later hang uncaught. + """ + if not self._on_render_thread(): + return + self._passes += 1 + if self._passes > 1: + self._frame_pushed = True + self.beat() + + def beat(self) -> None: + """The render loop is still going round. Cheap; call it freely.""" + if not self._on_render_thread(): + return + if not self._armed: + if not self._frame_pushed: + return + self._arm() + return + now = self._clock() + if self._last_beat is not None and now - self._last_beat < self._interval: + return + self._last_beat = now + if self._usec: + self._send('WATCHDOG=1') + self._write_heartbeat(now) + + def _arm(self) -> None: + self._armed = True + self._last_beat = self._clock() + if self._usec: + # Back from the start-up allowance to the unit's own limit. + self._send(f'READY=1\nWATCHDOG_USEC={self._usec}\nWATCHDOG=1\nSTATUS=Rendering') + self._install_faulthandler() + logger.info("systemd watchdog armed: the render loop must check in every %.0fs", + self._usec / 1e6) + else: + self._send('READY=1\nSTATUS=Rendering') + self._write_heartbeat(self._last_beat) + + def _install_faulthandler(self) -> None: + """Dump every thread's stack when the watchdog's SIGABRT arrives. + + That trace, in the journal, is what says which plugin the render + thread was stuck in. + """ + if not self._enable_faulthandler: + return + try: + import faulthandler + import sys + if not faulthandler.is_enabled() and sys.stderr is not None: + faulthandler.enable(all_threads=True) + except (ImportError, RuntimeError, ValueError, OSError, AttributeError) as e: + logger.debug("faulthandler not enabled: %s", e) + + @contextlib.contextmanager + def extended(self, seconds: float, reason: str = '') -> Iterator[None]: + """Allow the render thread ``seconds`` for one blocking job. + + For the few legitimate jobs that can outlast the watchdog, such as + loading a newly enabled plugin, which can run pip on this thread. + Nests; the unit's limit comes back when the outermost one ends. + """ + if not (self._armed and self._usec and self._on_render_thread()): + yield + return + usec = max(self._usec, int(seconds * 1e6)) + if self._extend_depth == 0: + self._send(f'WATCHDOG_USEC={usec}\nWATCHDOG=1' + + (f'\nSTATUS=Busy: {reason}' if reason else '')) + self._extend_depth += 1 + try: + yield + finally: + self._extend_depth -= 1 + if self._extend_depth == 0: + self._send(f'WATCHDOG_USEC={self._usec}\nWATCHDOG=1\nSTATUS=Rendering') + self._last_beat = self._clock() + self._write_heartbeat(self._last_beat) + + def stopping(self) -> None: + """Clean shutdown: tell systemd, and take the heartbeat down with us. + + A heartbeat left behind by a stopped display would read as a frozen + one to the web interface. + """ + if self._usec or self._armed: + self._send('STOPPING=1') + path = self._heartbeat_path() + if path and self._heartbeat_ok: + try: + os.unlink(path) + except OSError: + pass + + # -- heartbeat file ---------------------------------------------------- + + def _heartbeat_path(self) -> Optional[str]: + if not self._heartbeat_dir: + return None + return os.path.join(self._heartbeat_dir, HEARTBEAT_NAME) + + def _write_heartbeat(self, now_mono: float) -> None: + path = self._heartbeat_path() + if path is None or self._heartbeat_ok is False: + return + directory = self._heartbeat_dir + try: + if not os.path.isdir(directory): + # An install whose unit predates RuntimeDirectory=: the + # display runs as root and can make it. Anyone else cannot, + # and gets no heartbeat -- which readers treat as "unknown". + os.makedirs(directory, mode=0o755, exist_ok=True) + payload = json.dumps({'pid': os.getpid(), 'mono': now_mono, + 'wall': self._wall_clock()}) + fd, tmp = tempfile.mkstemp(dir=directory, prefix='.heartbeat-') + try: + with os.fdopen(fd, 'w', encoding='utf-8') as f: + f.write(payload) + os.chmod(tmp, 0o644) + os.replace(tmp, path) + except BaseException: + try: + os.unlink(tmp) + except OSError: + pass + raise + if self._heartbeat_ok is None: + logger.info("Writing the display heartbeat to %s", path) + self._heartbeat_ok = True + except OSError as e: + if self._heartbeat_ok is None: + logger.info("Not writing a display heartbeat (%s: %s); health checks " + "fall back to their older signals", directory, e) + self._heartbeat_ok = False + elif not self._heartbeat_warned: + # It worked before, so keep trying, but say so only once. + logger.warning("Could not update the display heartbeat: %s", e) + self._heartbeat_warned = True + + +#: The process-wide instance: one display process, one render loop. +watchdog = RenderWatchdog() + + +def beat() -> None: + """Module-level shortcut so the Vegas loop and the plugin manager need no reference.""" + watchdog.beat() + + +def note_frame() -> None: + watchdog.note_frame() + + +def extended(seconds: float, reason: str = ''): + return watchdog.extended(seconds, reason) diff --git a/src/plugin_system/plugin_manager.py b/src/plugin_system/plugin_manager.py index 7b02ad22..cc9bff35 100644 --- a/src/plugin_system/plugin_manager.py +++ b/src/plugin_system/plugin_manager.py @@ -18,6 +18,7 @@ import types from pathlib import Path from typing import Dict, List, NamedTuple, Optional, Any, Tuple, Union import logging +from src import display_watchdog from src.exceptions import PluginError, ConfigError from src.logging_config import get_logger from src.plugin_system.plugin_loader import PluginLoader @@ -354,6 +355,19 @@ class PluginManager: return plugin_ids def load_plugin(self, plugin_id: str, force_enabled: bool = False) -> bool: + """Load a plugin by ID; see _load_plugin. + + Loading can install the plugin's dependencies with pip -- minutes, + not seconds. When that happens on the display's render thread (a + plugin enabled from the web UI, or loaded for on-demand), its + systemd watchdog gets a longer limit for the duration. Start-up + loads, on a thread pool, are covered by the start-up allowance. + """ + with display_watchdog.extended(display_watchdog.PLUGIN_LOAD_ALLOWANCE_SECONDS, + f'loading plugin {plugin_id}'): + return self._load_plugin(plugin_id, force_enabled) + + def _load_plugin(self, plugin_id: str, force_enabled: bool = False) -> bool: """ Load a plugin by ID. @@ -1244,6 +1258,9 @@ class PluginManager: # Kill-switch path: the original inline execution # (blocks the caller until update() completes/times out) self._execute_update_now(plugin_id, plugin_instance, current_time) + # Up to the executor's 30s each, one after another on the + # render thread: check in with its watchdog between them. + display_watchdog.beat() else: self._enqueue_update(plugin_id, current_time) diff --git a/src/vegas_mode/coordinator.py b/src/vegas_mode/coordinator.py index ccd70319..6d2ae4f1 100644 --- a/src/vegas_mode/coordinator.py +++ b/src/vegas_mode/coordinator.py @@ -20,6 +20,7 @@ import time import threading from typing import Optional, Dict, Any, List, Callable, TYPE_CHECKING +from src import display_watchdog from src.common import render_gate from src.vegas_mode.config import VegasModeConfig from src.vegas_mode.plugin_adapter import PluginAdapter @@ -542,6 +543,9 @@ class VegasModeCoordinator: # the whole budget -- the render loop stalls for the size of the # correction. A forward jump inflates p99 and worst-frame instead. frame_started = time.monotonic() + # An iteration runs for minutes (max_cycle_duration) without + # returning to the display controller's loop. + display_watchdog.beat() # Check for STATIC mode plugin that should pause scroll static_plugin = self._check_static_plugin_trigger() @@ -923,6 +927,7 @@ class VegasModeCoordinator: # Sleep in small increments to remain responsive time.sleep(0.1) + display_watchdog.beat() logger.info( "Static pause completed for %s after %.1fs", diff --git a/src/vegas_mode/stream_manager.py b/src/vegas_mode/stream_manager.py index 039aae80..bca474a1 100644 --- a/src/vegas_mode/stream_manager.py +++ b/src/vegas_mode/stream_manager.py @@ -21,6 +21,7 @@ from collections import deque from dataclasses import dataclass, field from PIL import Image +from src import display_watchdog from src.vegas_mode.config import VegasModeConfig from src.vegas_mode.plugin_adapter import PluginAdapter from src.plugin_system.base_plugin import VegasDisplayMode, resolve_vegas_participation @@ -562,6 +563,9 @@ class StreamManager: Returns: ContentSegment or None if fetch failed """ + # Composing a cycle fetches plugin after plugin on the render thread + # (on the prefetch thread this is ignored), so check in between. + display_watchdog.beat() try: if not hasattr(self.plugin_manager, 'plugins'): logger.warning("[%s] plugin_manager has no plugins attribute", plugin_id) diff --git a/systemd/README.md b/systemd/README.md index cdc65ec6..ed46ea2d 100644 --- a/systemd/README.md +++ b/systemd/README.md @@ -8,6 +8,10 @@ This directory contains systemd service unit files for LEDMatrix services. - Runs the display controller (`run.py`) - Starts automatically on boot - Runs as root for hardware access + - Restarted by systemd's watchdog (`WatchdogSec=120`) when its render loop + stops checking in, e.g. stuck inside a plugin; the loop writes a heartbeat + to `/run/ledmatrix/display-heartbeat.json` (`RuntimeDirectory=`) that the + web interface's health check reads. See `src/display_watchdog.py` - **`ledmatrix-web.service`** - Web interface service - Runs the web interface conditionally based on config diff --git a/systemd/ledmatrix.service b/systemd/ledmatrix.service index faaeb9bc..0377c7d0 100644 --- a/systemd/ledmatrix.service +++ b/systemd/ledmatrix.service @@ -27,6 +27,49 @@ ExecStart=/usr/bin/python3 __PROJECT_ROOT_DIR__/run.py # that a successful outcome and never bringing it back. Restart=always RestartSec=10 +# Back off when it keeps failing: 10s after the first failure, growing to two +# minutes by the fourth, so a plugin that crashes or hangs the display on +# every start retries a couple of dozen times an hour instead of hundreds. +# Deliberately not StartLimitBurst=: once that trips the unit stays failed -- +# the panel dark until someone reboots -- and every start is refused until the +# interval passes, including the web UI's Start button and the automatic +# update's rollback, neither of which may run "systemctl reset-failed". +# systemd before 254 (Debian Bookworm has 252) ignores these two lines with an +# "Unknown key name" warning and keeps the flat RestartSec. +RestartSteps=4 +RestartMaxDelaySec=2min +# Render-loop watchdog (src/display_watchdog.py). The render thread itself +# pings systemd every few seconds, so a render loop stuck inside a plugin -- +# service still "active", panel frozen -- stops the pings, and systemd kills +# the process (SIGABRT: faulthandler writes every thread's stack to the +# journal) and restarts it. +# +# Type=simple, not Type=notify. Type=notify would hold "systemctl start" and +# "restart" until READY=1, i.e. until plugins have loaded -- minutes on a slow +# board -- and the web interface, the installer and the update health check all +# call those with timeouts well short of that. The process still sends READY=1 +# (harmless here); NotifyAccess=main is what lets systemd hear it at all, and +# only from run.py itself, not from pip or anything else it starts. +# +# 120s is the steady-state limit, four times the longest gap a healthy loop +# has: a screen's first display() call runs under PluginExecutor's 30s +# timeout. Everything else the loop blocks on checks in between steps (Vegas +# frames, each plugin fetched for a Vegas cycle, each dwell second). Start-up +# is longer than this and happens before the loop exists, so the process +# widens the limit to 15 minutes as it starts and narrows it back to this +# value after its first frame; loading a plugin enabled from the web UI, which +# can run pip on the render thread, gets the same 15 minutes. Raise it with a +# drop-in (systemctl edit ledmatrix) if a plugin legitimately needs longer; +# WatchdogSec=0 turns it off. +WatchdogSec=120 +NotifyAccess=main +# /run/ledmatrix, for the render loop's heartbeat (display-heartbeat.json), +# which /api/v3/health and the update health check read. /run is tmpfs, so a +# write every few seconds never touches the SD card. 0755 and root-owned: the +# web interface runs as another user and only needs to read it. Removed when +# the service stops, so a stopped display leaves no stale heartbeat behind. +RuntimeDirectory=ledmatrix +RuntimeDirectoryMode=0755 # Memory ceiling as a share of physical RAM, so one unit file suits a 512 MB # Pi Zero 2 W and an 8 GB Pi 5 alike. This is a backstop, not a tuning knob: it # turns "the board runs out of memory, stops being able to fork, and takes sshd diff --git a/test/conftest.py b/test/conftest.py index 93ae4881..36901316 100644 --- a/test/conftest.py +++ b/test/conftest.py @@ -301,6 +301,20 @@ def emulator_mode(monkeypatch): return True +@pytest.fixture(autouse=True) +def _hermetic_display_watchdog(monkeypatch): + """Keep the render loop's watchdog off the host. + + Every test that runs DisplayController.run() arms the process-wide + watchdog, which would ping a real $NOTIFY_SOCKET and write a heartbeat + into /run/ledmatrix -- the live display's, when the suite runs as root on + a device. Each test gets a fresh instance that does neither. + """ + from src import display_watchdog + monkeypatch.setattr(display_watchdog, 'watchdog', + display_watchdog.RenderWatchdog(environ={}, heartbeat_dir=None)) + + @pytest.fixture(autouse=True) def reset_logging(): """Reset logging configuration before each test.""" diff --git a/test/test_api_v3_health.py b/test/test_api_v3_health.py index 888b3101..a96f469f 100644 --- a/test/test_api_v3_health.py +++ b/test/test_api_v3_health.py @@ -5,8 +5,10 @@ PluginManager does not have; a hasattr guard turned that into a permanent 0. Each check that fails answers "see logs for details", so it has to log. """ +import json import logging import sys +import time from pathlib import Path from types import SimpleNamespace @@ -25,6 +27,28 @@ def _no_systemctl(monkeypatch): lambda: {"active": True}) +@pytest.fixture(autouse=True) +def heartbeat(tmp_path, monkeypatch): + """The display's heartbeat file, somewhere private; absent until written.""" + from src import display_watchdog + path = tmp_path / "display-heartbeat.json" + monkeypatch.setattr(display_watchdog, "HEARTBEAT_PATH", str(path)) + + def write(age): + path.write_text(json.dumps({"pid": 1, "mono": time.monotonic() - age, + "wall": time.time() - age})) + return write + + +@pytest.fixture +def fresh_preview(tmp_path, monkeypatch): + """A just-written preview frame, so only the heartbeat decides the verdict.""" + from web_interface import display_preview + snapshot = tmp_path / "preview.png" + snapshot.write_bytes(b"png") + monkeypatch.setattr(display_preview, "SNAPSHOT_PATH", str(snapshot)) + + def _checks(client): response = client.get(URL) assert response.status_code == 200, response.get_json() @@ -88,3 +112,59 @@ def test_a_failed_hardware_check_is_logged(api_v3_client, api_v3_module, caplog, assert check["status"] == "unknown" logged = [r for r in caplog.records if "snapshot" in r.getMessage()] assert logged and logged[0].exc_info + + +# -- the display's render-loop heartbeat ----------------------------------------- +# +# The preview frame's age said nothing about a panel frozen by a render thread +# stuck in a plugin; the heartbeat is written by that thread itself. + +def _health(client): + response = client.get(URL) + assert response.status_code == 200, response.get_json() + return response.get_json()["data"] + + +def test_a_fresh_heartbeat_is_a_running_display_loop(api_v3_client, heartbeat, fresh_preview): + heartbeat(age=3) + + data = _health(api_v3_client) + + assert data["checks"]["display_loop"]["status"] == "running" + assert 2 <= data["checks"]["display_loop"]["heartbeat_age_seconds"] < 10 + assert data["status"] == "healthy" + + +def test_a_stale_heartbeat_is_a_stalled_display_loop(api_v3_client, heartbeat, fresh_preview): + """Service active, preview recent, and still the panel is frozen.""" + heartbeat(age=300) + + data = _health(api_v3_client) + + assert data["checks"]["display_loop"]["status"] == "stalled" + assert data["checks"]["display_loop"]["heartbeat_age_seconds"] >= 299 + assert data["status"] == "degraded" + + +def test_no_heartbeat_falls_back_to_the_older_checks(api_v3_client, fresh_preview): + """The dev server, the emulator, Windows, or a display without the + feature: absence is not a failure, and the verdict is what it was.""" + data = _health(api_v3_client) + + assert data["checks"]["display_loop"]["status"] == "not_reported" + assert data["checks"]["hardware"]["status"] == "connected" + assert data["status"] == "healthy" + + +def test_an_unreadable_heartbeat_is_reported_not_raised(api_v3_client, monkeypatch, caplog): + from src import display_watchdog + + def boom(_path): + raise RuntimeError("bad heartbeat") + monkeypatch.setattr(display_watchdog, "read_heartbeat", boom) + + with caplog.at_level(logging.WARNING): + check = _checks(api_v3_client)["display_loop"] + + assert check["status"] == "unknown" + assert any("heartbeat" in r.getMessage() for r in caplog.records) diff --git a/test/test_auto_update_verify.py b/test/test_auto_update_verify.py index e491d42b..5eae212d 100644 --- a/test/test_auto_update_verify.py +++ b/test/test_auto_update_verify.py @@ -59,10 +59,15 @@ class FakeHost: Services run whatever commit was checked out when they were last restarted; ``failure`` says how they misbehave on the new commit - ("display_down", "web_down", "crash_loop") or on any commit ("always"). + ("display_down", "web_down", "crash_loop", "frozen": active but the + render loop stuck after its first frame) or on any commit ("always"). + + ``heartbeat`` is whether the display writes one: never (``None``, code + from before the heartbeat), or on every commit (``"always"``). """ - def __init__(self, repo, bad_head, failure=None, pip_ok=True, restart_failures=0, count_readable=True): + def __init__(self, repo, bad_head, failure=None, pip_ok=True, restart_failures=0, count_readable=True, + heartbeat=None): self.repo, self.bad_head, self.failure, self.pip_ok = repo, bad_head, failure, pip_ok self.restart_failures = restart_failures # how many restart commands fail, first to last self.count_readable = count_readable @@ -73,6 +78,8 @@ class FakeHost: self.pip = None # optional (args, host) -> result, or raises, instead of pip_ok self.now = 0.0 self.nrestarts = 0 + self.heartbeat = heartbeat + self.display_started_at = -1000.0 # the pre-update display, long running def broken(self, kind): if self.running_head is None: @@ -102,28 +109,43 @@ class FakeHost: return done(args, rc=1) # the old process keeps running self.running_head = git(self.repo, 'rev-parse', 'HEAD') self.restarts.append((args[4], self.running_head)) + if args[4] == 'ledmatrix.service': + self.display_started_at = self.now return done(args) raise AssertionError(f'unexpected command: {args}') def web_responds(self): return not self.broken('web_down') + def read_heartbeat(self): + if self.heartbeat is None: + return None + first_frame = self.display_started_at + 10 # plugins load, then it draws + if self.now < first_frame: + # Nothing from this process yet. A display whose unit predates + # RuntimeDirectory= leaves its predecessor's file behind. + return {'mono': self.display_started_at - 1} + if self.broken('frozen'): + return {'mono': first_frame} # drew once, then stuck + return {'mono': self.now} + def sleep(self, seconds): self.now += seconds def verifier(self): return av.Verifier(self.repo, run=self.run, sleep=self.sleep, clock=lambda: self.now, - web_responds=self.web_responds, log=lambda msg: None) + web_responds=self.web_responds, log=lambda msg: None, + read_heartbeat=self.read_heartbeat) def check(tmp_path, failure=None, new_requirements=False, pip_ok=True, restart_failures=0, - count_readable=True, **pending): + count_readable=True, heartbeat=None, **pending): repo, old, new = updated_repo(tmp_path, new_requirements) fields = {'status': 'pending', 'old_head': old, 'new_head': new, 'display_was_active': True, 'dependency_failures': []} fields.update(pending) av.write_pending(av.pending_path(repo), fields) - host = FakeHost(repo, new, failure, pip_ok, restart_failures, count_readable) + host = FakeHost(repo, new, failure, pip_ok, restart_failures, count_readable, heartbeat) code = host.verifier().verify() result = av.read_pending(av.pending_path(repo)) return code, result, host, git(repo, 'rev-parse', 'HEAD'), old, new @@ -323,3 +345,63 @@ def test_units_installers_and_updater_agree(): for sudoers in ('scripts/install/configure_web_sudo.sh', 'first_time_install.sh', 'scripts/install/lib_sudoers.sh'): assert not re.search(r'NOPASSWD:.*update-verify', (ROOT / sudoers).read_text(encoding='utf-8')), sudoers + + +# -- the display's heartbeat ------------------------------------------------------- +# +# "Service active" plus one HTTP 200 passed a panel frozen by a render loop +# stuck in a plugin. Where the display writes a heartbeat, the restarted +# display has to keep it fresh too. + +FROZEN_REASON = ('the display service is running but its panel is not being drawn ' + '(no fresh heartbeat)') + + +def test_a_display_that_keeps_drawing_passes(tmp_path): + code, result, host, head, old, new = check(tmp_path, heartbeat='always') + assert result['status'] == 'success' and head == new + + +def test_a_frozen_panel_is_rolled_back(tmp_path): + code, result, host, head, old, new = check(tmp_path, 'frozen', heartbeat='always') + assert result['status'] == 'rolled_back' and result['reason'] == FROZEN_REASON + assert head == old + + +def test_the_previous_processs_heartbeat_does_not_count(tmp_path): + """Under a unit without RuntimeDirectory= the old file outlives the old + process; a restarted display that never draws must not pass on it.""" + repo, old, new = updated_repo(tmp_path) + host = FakeHost(repo, new, heartbeat='always') + verifier = host.verifier() + verifier.expect_heartbeat = True + host.display_started_at = host.now = 100.0 + verifier.display_restarted_at = 100.0 + host.now = 101.0 # the new process has not drawn yet + assert verifier.display_drawing() is False + host.now = 115.0 + assert verifier.display_drawing() is True + + +def test_without_a_heartbeat_the_check_is_what_it_was(tmp_path): + """Code from before the heartbeat (or a display that cannot write one) + never wrote one, so it cannot be asked for -- a frozen panel then passes, + exactly as it did.""" + code, result, host, head, old, new = check(tmp_path, 'frozen', heartbeat=None) + assert result['status'] == 'success' + + +def test_a_stopped_display_is_not_asked_for_a_heartbeat(tmp_path): + code, result, host, head, old, new = check(tmp_path, 'frozen', heartbeat='always', + display_was_active=False) + assert result['status'] == 'success' + + +def test_the_heartbeat_location_and_freshness_match_the_display(): + """A copy, not an import: the verifier must not depend on the code it checks.""" + from src import display_watchdog + assert av.HEARTBEAT_PATH == display_watchdog.HEARTBEAT_PATH + # A display frozen right after its first frame must go stale inside the + # window it has to stay healthy for. + assert av.HEARTBEAT_FRESH_SECONDS + av.POLL_SECONDS < av.STABLE_SECONDS + assert av.HEARTBEAT_FRESH_SECONDS > display_watchdog.BEAT_INTERVAL_SECONDS * 2 diff --git a/test/test_display_watchdog.py b/test/test_display_watchdog.py new file mode 100644 index 00000000..257336c7 --- /dev/null +++ b/test/test_display_watchdog.py @@ -0,0 +1,660 @@ +"""The render loop's liveness signals: systemd watchdog pings and the heartbeat. + +A panel can freeze while ledmatrix.service stays "active" -- a render thread +stuck inside a plugin's display(). src/display_watchdog.py lets only the +render thread vouch for itself, to systemd (sd_notify WATCHDOG=1) and to the +web interface (a heartbeat file under /run/ledmatrix). These tests pin: + +* the sd_notify wire format, including abstract-namespace sockets; +* that nothing is armed until the first frame, so start-up keeps its allowance; +* that beats from any other thread are ignored, so a stuck render thread + goes quiet even while the update worker and Vegas's tick thread carry on; +* the places the render loop checks in from (dwell sleeps, per-frame + display, Vegas's own loop, a plugin load's longer allowance). +""" +import json +import os +import socket +import sys +import threading +import time +from types import SimpleNamespace +from unittest.mock import MagicMock + +import pytest + +os.environ.setdefault("EMULATOR", "true") # display_controller imports without hardware + +from src import display_watchdog # noqa: E402 +from src.display_watchdog import ( # noqa: E402 + RenderWatchdog, heartbeat_age, notify, read_heartbeat, watchdog_usec) + +WATCHDOG_120 = {'NOTIFY_SOCKET': '/run/systemd/notify', 'WATCHDOG_USEC': '120000000'} + + +class FakeSocket: + """Records what notify() does with the socket it creates.""" + + def __init__(self, record, fail_connect=False): + self.record = record + self.fail_connect = fail_connect + self.closed = False + + def connect(self, address): + self.record['address'] = address + if self.fail_connect: + raise ConnectionRefusedError('nobody listening') + + def sendall(self, data): + self.record.setdefault('sent', []).append(data) + + def close(self): + self.closed = True + self.record['closed'] = True + + +def fake_factory(record, fail_connect=False): + def factory(family, kind): + record['family'], record['type'] = family, kind + return FakeSocket(record, fail_connect) + return factory + + +@pytest.fixture +def af_unix(monkeypatch): + """AF_UNIX for the fake-socket tests, even on a Python built without it.""" + monkeypatch.setattr(socket, 'AF_UNIX', getattr(socket, 'AF_UNIX', 1), raising=False) + return socket.AF_UNIX + + +# -- sd_notify ------------------------------------------------------------- + +class TestNotify: + def test_sends_one_datagram_to_the_socket_path(self, af_unix): + record = {} + assert notify('WATCHDOG=1', {'NOTIFY_SOCKET': '/run/systemd/notify'}, + socket_factory=fake_factory(record)) is True + assert record['family'] == af_unix + assert record['type'] & socket.SOCK_DGRAM == socket.SOCK_DGRAM + assert record['address'] == '/run/systemd/notify' + assert record['sent'] == [b'WATCHDOG=1'] + assert record['closed'] + + def test_an_at_sign_means_the_abstract_namespace(self, af_unix): + record = {} + notify('READY=1\nSTATUS=Rendering', {'NOTIFY_SOCKET': '@/org/freedesktop/systemd1/notify'}, + socket_factory=fake_factory(record)) + assert record['address'] == '\0/org/freedesktop/systemd1/notify' + assert record['sent'] == [b'READY=1\nSTATUS=Rendering'] + + @pytest.mark.parametrize('address', [None, '', 'relative/path', 'vsock:2:1234']) + def test_no_usable_socket_sends_nothing(self, af_unix, address): + record = {} + env = {} if address is None else {'NOTIFY_SOCKET': address} + assert notify('WATCHDOG=1', env, socket_factory=fake_factory(record)) is False + assert record == {} + + def test_a_failed_send_is_false_not_an_exception(self, af_unix): + record = {} + assert notify('WATCHDOG=1', {'NOTIFY_SOCKET': '/nope'}, + socket_factory=fake_factory(record, fail_connect=True)) is False + assert record['closed'] + + @pytest.mark.skipif(not hasattr(socket, 'AF_UNIX') or os.name != 'posix', + reason='needs AF_UNIX datagram sockets') + def test_a_real_socket_receives_the_message(self, tmp_path): + path = str(tmp_path / 'notify') + server = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM) + try: + server.bind(path) + server.settimeout(2) + assert notify('WATCHDOG=1', {'NOTIFY_SOCKET': path}) is True + assert server.recv(4096) == b'WATCHDOG=1' + finally: + server.close() + + @pytest.mark.skipif(not sys.platform.startswith('linux'), + reason='abstract sockets are Linux-only') + def test_a_real_abstract_socket_receives_the_message(self): + name = f'ledmatrix-test-{os.getpid()}-{time.monotonic_ns()}' + server = socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM) + try: + server.bind('\0' + name) + server.settimeout(2) + assert notify('READY=1', {'NOTIFY_SOCKET': '@' + name}) is True + assert server.recv(4096) == b'READY=1' + finally: + server.close() + + +class TestWatchdogUsec: + def test_reads_the_units_value(self): + assert watchdog_usec({'WATCHDOG_USEC': '120000000'}) == 120_000_000 + + def test_meant_for_another_process(self): + assert watchdog_usec({'WATCHDOG_USEC': '120000000', + 'WATCHDOG_PID': str(os.getpid() + 1)}) is None + + def test_meant_for_this_process(self): + assert watchdog_usec({'WATCHDOG_USEC': '5000000', + 'WATCHDOG_PID': str(os.getpid())}) == 5_000_000 + + @pytest.mark.parametrize('value', [None, '', 'abc', '0', '-5']) + def test_no_watchdog(self, value): + env = {} if value is None else {'WATCHDOG_USEC': value} + assert watchdog_usec(env) is None + + +# -- the render loop's side ---------------------------------------------------- + +class Clock: + def __init__(self, now=1000.0): + self.now = now + + def __call__(self): + return self.now + + +def make(environ=WATCHDOG_120, heartbeat_dir=None, clock=None): + sent = [] + wd = RenderWatchdog(environ=environ, send=lambda m: sent.append(m) or True, + clock=clock or Clock(), wall_clock=lambda: 1_700_000_000.0, + heartbeat_dir=heartbeat_dir, enable_faulthandler=False) + return wd, sent + + +def pings(sent): + return [m for m in sent if 'WATCHDOG=1' in m.split('\n')] + + +def on_other_thread(fn): + t = threading.Thread(target=fn) + t.start() + t.join() + + +class TestStartup: + def test_start_up_widens_the_limit(self): + wd, sent = make() + wd.begin_startup() + assert sent == [f'WATCHDOG_USEC={int(display_watchdog.STARTUP_ALLOWANCE_SECONDS * 1e6)}' + '\nSTATUS=Starting: loading plugins'] + + def test_start_up_never_shortens_a_longer_unit_limit(self): + wd, sent = make({'NOTIFY_SOCKET': '/x', 'WATCHDOG_USEC': str(3600 * 10**6)}) + wd.begin_startup() + assert sent[0].startswith(f'WATCHDOG_USEC={3600 * 10**6}\n') + + def test_without_a_watchdog_start_up_sends_nothing(self): + wd, sent = make({'NOTIFY_SOCKET': '/x'}) + wd.begin_startup() + assert sent == [] + + +class TestArming: + def test_nothing_before_the_render_loop_starts(self, tmp_path): + wd, sent = make(heartbeat_dir=str(tmp_path)) + wd.note_frame() # a start-up screen + wd.beat() + wd.loop_pass() + assert sent == [] and not wd.armed + assert not (tmp_path / display_watchdog.HEARTBEAT_NAME).exists() + + def test_nothing_before_the_first_frame(self, tmp_path): + wd, sent = make(heartbeat_dir=str(tmp_path)) + wd.bind_render_thread() + wd.loop_pass() # the first pass has begun... + wd.beat() # ...and is, say, composing Vegas content + assert sent == [] and not wd.armed + assert not (tmp_path / display_watchdog.HEARTBEAT_NAME).exists() + + def test_the_first_frame_arms_it(self, tmp_path): + wd, sent = make(heartbeat_dir=str(tmp_path)) + wd.bind_render_thread() + wd.note_frame() + assert wd.armed + assert sent == ['READY=1\nWATCHDOG_USEC=120000000\nWATCHDOG=1\nSTATUS=Rendering'] + heartbeat = json.loads((tmp_path / display_watchdog.HEARTBEAT_NAME).read_text()) + assert heartbeat == {'pid': os.getpid(), 'mono': 1000.0, 'wall': 1_700_000_000.0} + + def test_a_first_frame_pushed_by_another_thread_arms_on_the_next_render_beat(self): + """A screen's first display() runs on PluginExecutor's thread.""" + wd, sent = make() + wd.bind_render_thread() + on_other_thread(wd.note_frame) + assert not wd.armed and sent == [] + wd.beat() + assert wd.armed and sent[0].startswith('READY=1\n') + + def test_a_full_pass_with_nothing_drawn_arms_it(self): + """No plugins enabled, or every screen empty: the loop is still alive.""" + wd, sent = make() + wd.bind_render_thread() + wd.loop_pass() + assert not wd.armed + wd.loop_pass() + assert wd.armed and sent[0].startswith('READY=1\n') + + def test_without_a_watchdog_it_still_says_ready_and_writes_the_heartbeat(self, tmp_path): + wd, sent = make({'NOTIFY_SOCKET': '/x'}, heartbeat_dir=str(tmp_path)) + wd.bind_render_thread() + wd.note_frame() + assert sent == ['READY=1\nSTATUS=Rendering'] + assert (tmp_path / display_watchdog.HEARTBEAT_NAME).exists() + sent_before = len(sent) + wd.beat() + assert len(sent) == sent_before # no WATCHDOG=1 without a watchdog + + +class TestBeats: + def test_pings_are_rate_limited(self, tmp_path): + clock = Clock() + wd, sent = make(heartbeat_dir=str(tmp_path), clock=clock) + wd.bind_render_thread() + wd.note_frame() + del sent[:] + for _ in range(100): # a burst of frames + wd.beat() + assert sent == [] + clock.now += display_watchdog.BEAT_INTERVAL_SECONDS + wd.beat() + assert sent == ['WATCHDOG=1'] + heartbeat = read_heartbeat(str(tmp_path / display_watchdog.HEARTBEAT_NAME)) + assert heartbeat['mono'] == clock.now + + def test_a_short_unit_limit_pings_more_often(self): + clock = Clock() + wd, sent = make({'NOTIFY_SOCKET': '/x', 'WATCHDOG_USEC': '3000000'}, clock=clock) + wd.bind_render_thread() + wd.note_frame() + del sent[:] + clock.now += 1.0 # a third of 3s + wd.beat() + assert sent == ['WATCHDOG=1'] + + def test_beats_from_other_threads_are_ignored(self, tmp_path): + """The update worker, Vegas's tick thread and the prefetcher keep + running while the render thread is stuck; they must not keep the + watchdog fed on its behalf.""" + clock = Clock() + wd, sent = make(heartbeat_dir=str(tmp_path), clock=clock) + wd.bind_render_thread() + wd.note_frame() + del sent[:] + before = (tmp_path / display_watchdog.HEARTBEAT_NAME).read_text() + clock.now += 60 + on_other_thread(wd.beat) + on_other_thread(wd.note_frame) + on_other_thread(wd.loop_pass) + assert sent == [] + assert (tmp_path / display_watchdog.HEARTBEAT_NAME).read_text() == before + + def test_the_module_shortcuts_reach_the_process_instance(self, monkeypatch): + wd, sent = make() + monkeypatch.setattr(display_watchdog, 'watchdog', wd) + wd.bind_render_thread() + display_watchdog.note_frame() + assert wd.armed + with display_watchdog.extended(600, 'x'): + pass + display_watchdog.beat() + assert any('WATCHDOG_USEC=600000000' in m for m in sent) + + +class TestExtended: + def test_a_long_job_gets_the_longer_limit_then_the_units_back(self): + wd, sent = make() + wd.bind_render_thread() + wd.note_frame() + del sent[:] + with wd.extended(900, 'loading plugin weather'): + assert sent == ['WATCHDOG_USEC=900000000\nWATCHDOG=1\nSTATUS=Busy: loading plugin weather'] + assert sent[-1] == 'WATCHDOG_USEC=120000000\nWATCHDOG=1\nSTATUS=Rendering' + + def test_nested_jobs_restore_once(self): + wd, sent = make() + wd.bind_render_thread() + wd.note_frame() + del sent[:] + with wd.extended(900): + with wd.extended(900): + pass + assert len(sent) == 1 # the inner one neither re-extends nor restores + assert len(sent) == 2 and sent[-1].startswith('WATCHDOG_USEC=120000000\n') + + def test_restored_even_when_the_job_fails(self): + wd, sent = make() + wd.bind_render_thread() + wd.note_frame() + with pytest.raises(RuntimeError): + with wd.extended(900): + raise RuntimeError('pip failed') + assert sent[-1].startswith('WATCHDOG_USEC=120000000\n') + + def test_off_the_render_thread_or_before_arming_it_does_nothing(self): + """Start-up loads run on a thread pool under the start-up allowance.""" + wd, sent = make() + wd.bind_render_thread() + with wd.extended(900): + pass + wd.note_frame() + del sent[:] + on_other_thread(lambda: wd.extended(900).__enter__()) + assert sent == [] + + +class TestStopping: + def test_a_clean_stop_removes_the_heartbeat(self, tmp_path): + wd, sent = make(heartbeat_dir=str(tmp_path)) + wd.bind_render_thread() + wd.note_frame() + wd.stopping() + assert sent[-1] == 'STOPPING=1' + assert not (tmp_path / display_watchdog.HEARTBEAT_NAME).exists() + + def test_stopping_outside_systemd_is_harmless(self): + wd, sent = make({}) + wd.stopping() + assert sent == [] + + +class TestHeartbeatFile: + def test_the_directory_is_created_when_missing(self, tmp_path): + """An install whose unit predates RuntimeDirectory=; the display is root.""" + target = tmp_path / 'run' / 'ledmatrix' + wd, _ = make(heartbeat_dir=str(target)) + wd.bind_render_thread() + wd.note_frame() + assert (target / display_watchdog.HEARTBEAT_NAME).is_file() + assert [p.name for p in target.iterdir()] == [display_watchdog.HEARTBEAT_NAME] + + @pytest.mark.skipif(os.name != 'posix', reason='POSIX permissions') + def test_other_users_can_read_it(self, tmp_path): + wd, _ = make(heartbeat_dir=str(tmp_path)) + wd.bind_render_thread() + wd.note_frame() + mode = (tmp_path / display_watchdog.HEARTBEAT_NAME).stat().st_mode & 0o777 + assert mode == 0o644 + + def test_nowhere_to_write_is_not_an_error(self, tmp_path): + blocker = tmp_path / 'not-a-dir' + blocker.write_text('x') + clock = Clock() + wd, sent = make(heartbeat_dir=str(blocker / 'ledmatrix'), clock=clock) + wd.bind_render_thread() + wd.note_frame() + clock.now += 10 + wd.beat() + assert wd.armed and pings(sent) # the watchdog works regardless + + def test_windows_gets_no_heartbeat_by_default(self, monkeypatch): + monkeypatch.setattr(display_watchdog.os, 'name', 'nt') + wd = RenderWatchdog(environ={}, send=lambda m: True) + assert wd._heartbeat_path() is None + + +class TestHeartbeatAge: + def test_monotonic_is_preferred(self): + assert heartbeat_age({'mono': 100.0, 'wall': 0.0}, now_mono=112.5, now_wall=9e9) == 12.5 + + def test_the_wall_clock_is_the_fallback(self): + assert heartbeat_age({'wall': 50.0}, now_mono=1.0, now_wall=80.0) == 30.0 + + def test_a_monotonic_stamp_from_the_future_is_not_trusted(self): + """Not the same clock -- fall back rather than report a fresh heartbeat.""" + assert heartbeat_age({'mono': 500.0, 'wall': 50.0}, now_mono=100.0, now_wall=170.0) == 120.0 + + def test_no_time_at_all(self): + assert heartbeat_age({'pid': 1}) is None + assert heartbeat_age({'mono': True}) is None + + def test_reading_a_missing_or_broken_file(self, tmp_path): + assert read_heartbeat(str(tmp_path / 'absent.json')) is None + (tmp_path / 'broken.json').write_text('{not json') + assert read_heartbeat(str(tmp_path / 'broken.json')) is None + (tmp_path / 'list.json').write_text('[1, 2]') + assert read_heartbeat(str(tmp_path / 'list.json')) is None + + +# -- where the render loop checks in ------------------------------------------- + +@pytest.fixture +def armed(monkeypatch): + """A process watchdog bound to this thread and armed, with a clock to advance.""" + clock = Clock() + wd, sent = make(clock=clock) + monkeypatch.setattr(display_watchdog, 'watchdog', wd) + wd.bind_render_thread() + wd.note_frame() + del sent[:] + return SimpleNamespace(wd=wd, sent=sent, clock=clock) + + +def _tick_clock(armed): + """Advance the watchdog's clock past the rate limit on every beat check.""" + original = armed.wd._clock + + def advancing(): + armed.clock.now += display_watchdog.BEAT_INTERVAL_SECONDS + return original() + armed.wd._clock = advancing + + +class TestCheckInPoints: + def test_the_dwell_sleep_checks_in(self, armed): + from src.display_controller import DisplayController + dc = object.__new__(DisplayController) + dc.current_display_mode = 'm' + dc.is_display_active = True + dc.on_demand_active = False + dc._tick_plugin_updates = lambda: None + dc._service_pending_changes = lambda: None + _tick_clock(armed) + dc._sleep_with_plugin_updates(0.05, tick_interval=0.01) + assert len(pings(armed.sent)) >= 3 + + def test_every_frame_of_a_screen_checks_in(self, armed): + from src.display_controller import DisplayController + dc = object.__new__(DisplayController) + dc.plugin_manager = None + plugin = MagicMock(plugin_id='p') + _tick_clock(armed) + for _ in range(3): + dc._display_once(plugin, 'm', accepts_display_mode=False) + assert len(pings(armed.sent)) == 3 + + def test_vegas_checks_in_every_frame_of_its_own_loop(self, armed): + """An iteration runs for minutes without returning to run().""" + import threading as _threading + from src.vegas_mode.config import VegasModeConfig + from src.vegas_mode.coordinator import VegasModeCoordinator + coord = VegasModeCoordinator.__new__(VegasModeCoordinator) + coord.vegas_config = VegasModeConfig.from_config({'display': {'vegas_scroll': { + 'enabled': True, 'max_cycle_duration': 60}}}) + coord.render_pipeline = MagicMock(frame_interval=0.0, target_fps=90) + coord.display_manager = MagicMock() + coord._state_lock = _threading.Lock() + coord._is_active = True + coord._is_paused = False + coord._should_stop = False + coord._live_priority_active = False + coord._fps_last_health_log = 0.0 + coord._fps_was_degraded = False + coord._interrupt_check = None + coord._interrupt_check_interval = 10 + coord._update_callback = None + coord._update_tick_running = False + coord._check_static_plugin_trigger = lambda: None + frames = [] + + def run_frame(): + frames.append(1) + if len(frames) == 5: + coord._should_stop = True + return False + return True + coord.run_frame = run_frame + _tick_clock(armed) + coord.run_iteration() + assert len(pings(armed.sent)) == 5 + + def test_each_plugin_fetched_for_a_vegas_cycle_checks_in(self, armed): + from src.vegas_mode.stream_manager import StreamManager + sm = StreamManager.__new__(StreamManager) + sm.plugin_manager = SimpleNamespace(plugins={}) + _tick_clock(armed) + for plugin_id in ('a', 'b'): + sm._fetch_plugin_content(plugin_id) + assert len(pings(armed.sent)) == 2 + + def test_loading_a_plugin_gets_the_longer_limit(self, armed): + from src.plugin_system.plugin_manager import PluginManager + pm = PluginManager.__new__(PluginManager) + seen = [] + pm._load_plugin = lambda plugin_id, force_enabled=False: seen.append(list(armed.sent)) or True + assert pm.load_plugin('weather') is True + allowance = int(display_watchdog.PLUGIN_LOAD_ALLOWANCE_SECONDS * 1e6) + assert seen[0] and seen[0][-1].startswith(f'WATCHDOG_USEC={allowance}\n') + assert armed.sent[-1].startswith('WATCHDOG_USEC=120000000\n') + + +class TestStuckRenderThread: + def test_a_render_thread_stuck_in_display_stops_the_pings(self, test_display_controller, + monkeypatch): + """End to end through DisplayController.run(): pings flow while frames + do, stop while display() is stuck even though other threads keep + calling beat(), and nothing else in the process keeps them alive.""" + sent = [] + lock = threading.Lock() + + def record(message): + with lock: + sent.append(message) + return True + # 0.3s limit -> a ping at most every 0.1s. + wd = RenderWatchdog(environ={'NOTIFY_SOCKET': '/x', 'WATCHDOG_USEC': '300000'}, + send=record, heartbeat_dir=None, enable_faulthandler=False) + monkeypatch.setattr(display_watchdog, 'watchdog', wd) + + stuck, release = threading.Event(), threading.Event() + + class Plugin: + plugin_id = 'stuck-plugin' + needs_high_fps = True + enabled = True + calls = 0 + + def display(self, force_clear=False): + Plugin.calls += 1 + display_watchdog.note_frame() # DisplayManager is mocked here + if Plugin.calls >= 60: # about half a second of frames + stuck.set() + release.wait(10) + raise KeyboardInterrupt # ends run() the way SIGTERM does + + controller = test_display_controller + controller.available_modes = ['stuck-mode'] + controller.plugin_modes = {'stuck-mode': Plugin()} + controller.mode_to_plugin_id = {'stuck-mode': 'stuck-plugin'} + controller.current_mode_index = 0 + + runner = threading.Thread(target=controller.run, daemon=True) + runner.start() + assert stuck.wait(10), 'the render loop never reached the plugin' + with lock: + before = len(pings(sent)) + assert wd.armed and any(m.startswith('READY=1') for m in sent) + assert before >= 2, sent + + # Other threads carry on while the render thread is stuck. + stop_others = threading.Event() + + def busy_other_thread(): + while not stop_others.is_set(): + display_watchdog.beat() + display_watchdog.note_frame() + time.sleep(0.01) + other = threading.Thread(target=busy_other_thread, daemon=True) + other.start() + time.sleep(0.8) # well past the 0.3s limit + with lock: + after = len(pings(sent)) + stop_others.set() + release.set() + other.join(5) + runner.join(10) + assert after == before, 'something other than the render thread fed the watchdog' + assert not runner.is_alive() + assert sent[-1] == 'STOPPING=1' + + +# -- the unit and the entry point ---------------------------------------------- + +ROOT = os.path.dirname(os.path.dirname(os.path.abspath(__file__))) + + +def _service_directives(): + with open(os.path.join(ROOT, 'systemd', 'ledmatrix.service'), encoding='utf-8') as f: + lines = [line.strip() for line in f] + return dict(line.split('=', 1) for line in lines + if line and not line.startswith(('#', '[')) and '=' in line + and not line.startswith('Environment=')) + + +def _seconds(value): + value = value.strip() + for suffix, factor in (('min', 60), ('s', 1)): + if value.endswith(suffix): + return float(value[:-len(suffix)]) * factor + return float(value) + + +class TestUnit: + def test_the_display_unit_has_a_watchdog_the_process_can_feed(self): + d = _service_directives() + # Type=notify would block "systemctl start/restart" until READY=1 -- + # after plugins load -- and the web UI and the update check call those + # with short timeouts. + assert d['Type'] == 'simple' + assert d['NotifyAccess'] == 'main' + assert 'WatchdogSec' in d + + def test_the_watchdog_outlasts_the_loops_longest_healthy_gap(self): + from src.plugin_system.plugin_executor import PluginExecutor + limit = _seconds(_service_directives()['WatchdogSec']) + executor_timeout = PluginExecutor().default_timeout + assert limit >= 3 * executor_timeout, ( + "a screen's first display() may legitimately take the executor's " + f"{executor_timeout}s timeout; WatchdogSec={limit:.0f}s leaves too little margin") + assert limit < display_watchdog.STARTUP_ALLOWANCE_SECONDS + assert limit < display_watchdog.PLUGIN_LOAD_ALLOWANCE_SECONDS + assert display_watchdog.BEAT_INTERVAL_SECONDS * 4 <= limit + assert limit > display_watchdog.HEARTBEAT_STALE_SECONDS >= 2 * executor_timeout + + def test_the_heartbeat_directory_is_created_readable_by_the_web_user(self): + d = _service_directives() + assert d['RuntimeDirectory'] == 'ledmatrix' + assert display_watchdog.HEARTBEAT_DIR == '/run/' + d['RuntimeDirectory'] + assert d['RuntimeDirectoryMode'] == '0755' + + def test_a_crash_loop_backs_off_instead_of_stopping_for_good(self): + """A tripped start limit leaves the panel dark and refuses the web UI's + Start button and the update rollback's restart.""" + d = _service_directives() + assert d['Restart'] == 'always' + assert 'StartLimitBurst' not in d + assert int(d['RestartSteps']) > 0 + assert _seconds(d['RestartMaxDelaySec']) > _seconds(d['RestartSec']) + + def test_run_py_widens_the_watchdog_before_importing_anything_heavy(self): + with open(os.path.join(ROOT, 'run.py'), encoding='utf-8') as f: + text = f.read() + call = text.index('display_watchdog.watchdog.begin_startup()') + assert call < text.index('from src.logging_config') + assert call < text.index('from src.display_controller') + + def test_the_module_imports_nothing_else_from_src(self): + """run.py loads it first thing; importing it must stay cheap.""" + with open(os.path.join(ROOT, 'src', 'display_watchdog.py'), encoding='utf-8') as f: + imports = [line for line in f if line.startswith(('import ', 'from '))] + assert not [line for line in imports if 'src' in line], imports diff --git a/test/test_web_auth.py b/test/test_web_auth.py index c318c016..4279047b 100644 --- a/test/test_web_auth.py +++ b/test/test_web_auth.py @@ -503,6 +503,42 @@ class TestExemptions: assert set(r.get_json()['data']) == {'status'} assert 'checks' in admin.get('/api/v3/health').get_json()['data'] + def test_a_stalled_render_loop_reaches_the_minimal_answer( + self, config_manager, api_v3_module, tmp_path, monkeypatch): + """The display's heartbeat (checks.display_loop) feeds the one word a + caller who is not logged in gets, without its detail.""" + import time + from src import display_watchdog + from web_interface import display_preview + from web_interface.blueprints.api_v3 import misc + # Every other check healthy, so the heartbeat alone decides. + monkeypatch.setattr(misc, '_get_display_service_status', lambda: {'active': True}) + monkeypatch.setattr(misc, '_discovered_plugin_manifests', lambda: {}) + monkeypatch.setattr(api_v3_module.api_v3, 'plugin_catalog', object(), raising=False) + preview = tmp_path / 'preview.png' + preview.write_bytes(b'png') + monkeypatch.setattr(display_preview, 'SNAPSHOT_PATH', str(preview)) + heartbeat = tmp_path / 'display-heartbeat.json' + monkeypatch.setattr(display_watchdog, 'HEARTBEAT_PATH', str(heartbeat)) + + def beat(age): + heartbeat.write_text(json.dumps({'pid': 1, 'mono': time.monotonic() - age, + 'wall': time.time() - age})) + + app = build(config_manager, api_v3_module) + admin = enable(app) + stranger = lan_client(app) + + beat(age=2) + assert admin.get('/api/v3/health').get_json()['data']['checks']['display_loop']['status'] == 'running' + assert stranger.get('/api/v3/health').get_json()['data'] == {'status': 'healthy'} + + beat(age=300) + full = admin.get('/api/v3/health').get_json()['data'] + assert full['checks']['display_loop']['status'] == 'stalled' + assert full['status'] == 'degraded' + assert stranger.get('/api/v3/health').get_json()['data'] == {'status': 'degraded'} + # --- The hash never leaves ------------------------------------------------------ diff --git a/web_interface/blueprints/api_v3/misc.py b/web_interface/blueprints/api_v3/misc.py index 87f9a697..c6961f69 100644 --- a/web_interface/blueprints/api_v3/misc.py +++ b/web_interface/blueprints/api_v3/misc.py @@ -14,6 +14,7 @@ from web_interface.blueprints.api_v3 import ( subprocess, success_response, tempfile, ) from src.common.path_safety import safe_path_component +from src import display_watchdog from src.common import sync_manager as _sync from src import error_aggregator as _errors from web_interface import display_preview @@ -93,6 +94,34 @@ def get_health(): 'error': 'see logs for details' } + # Is the render loop still going round? The display rewrites this + # heartbeat every few seconds from the render thread itself, so a + # thread stuck inside a plugin lets it go stale even though the + # service is "active". No heartbeat at all (the dev server, an older + # display) is not a failure: the preview-frame check below is then + # the only signal, as it always was. + try: + heartbeat = display_watchdog.read_heartbeat(display_watchdog.HEARTBEAT_PATH) + age = display_watchdog.heartbeat_age(heartbeat) if heartbeat else None + if age is None: + health_status['checks']['display_loop'] = { + 'status': 'not_reported', + 'note': 'The display is not writing a heartbeat (not started yet, ' + 'or a version or setup without one)', + } + else: + fresh = age < display_watchdog.HEARTBEAT_STALE_SECONDS + health_status['checks']['display_loop'] = { + 'status': 'running' if fresh else 'stalled', + 'heartbeat_age_seconds': round(age, 1), + } + except Exception: + logger.warning("Health check could not read the display heartbeat", exc_info=True) + health_status['checks']['display_loop'] = { + 'status': 'unknown', + 'error': 'see logs for details' + } + # Check hardware connectivity (if display manager available) try: snapshot_path = display_preview.SNAPSHOT_PATH @@ -117,8 +146,10 @@ def get_health(): } # Determine overall health + # 'not_reported' is the absence of a signal, not a bad one. all_healthy = all( - check.get('status') in ['accessible', 'operational', 'connected', 'running', 'active'] + check.get('status') in ['accessible', 'operational', 'connected', 'running', 'active', + 'not_reported'] for check in health_status['checks'].values() )