test(starlark): stop the pixlet-editor route tests leaking a fake Popen into the captive-portal check

TestPixletEditorHostDefaultsButDoesNotOverride patched Popen on the shared
subprocess module. The app's before_request captive-portal hook runs
subprocess.run (`with Popen(...) as p`) for `systemctl is-active hostapd`
whenever its 30s AP-mode cache is cold, so on a Linux host with systemctl -
the CI runner - the hook got the FakeProcess and the request 500'd with
"'FakeProcess' object does not support the context manager protocol".
Whether it happened depended on how long ago the previous request ran,
hence the intermittency; Windows has no systemctl and never reached it.

- Patch the starlark route module's own `subprocess` binding instead of
  the global Popen.
- Pin is_ap_mode_active to False in this file's client fixture, so no
  request here shells out to systemctl/nmcli at all.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

CHANGELOG.md

@@ -19,6 +19,18 @@ accepts both, but the store flags the old spelling as deprecated
 
 ## Unreleased
 
+### A scrolling screen held by its plugin's update() is reported
+
+- While a plugin's `update()` runs it holds the plugin's lock, and that
+  plugin's frames are skipped: on a scroller, a frozen strip, with nothing
+  logged (and a freeze of 5 s or more is a gap, not a freeze, to the frame
+  stats). The high-FPS loop now times each run of skipped frames; one of
+  250 ms or more logs `Display of <plugin> held N ms by its update()`
+  (rate-limited per plugin) when it ends, and is recorded on the plugin's
+  health as a `display hold` busy skip, which never counts toward the
+  circuit breaker. The 1 Hz loop is left out: its frames are a second apart,
+  so one skipped frame there measures nothing and freezes nothing visible.
+
 ### Fixed
 
 - The web preview and `/api/v3/display/current` no longer stay black for a

src/display_controller.py

@@ -1164,6 +1164,55 @@ class DisplayController:
         except Exception:  # pylint: disable=broad-except
             logger.exception("Error running scheduled plugin updates")
 
+    #: A run of frames skipped because a plugin's update() held its lock is
+    #: reported once it has lasted this long.
+    DISPLAY_HOLD_REPORT_SECONDS = 0.25
+
+    #: (plugin_id, monotonic start) of the current run of skipped frames.
+    _display_hold: Optional[Tuple[str, float]] = None
+
+    def _note_display_hold(self, plugin_id: str, held: bool) -> None:
+        """Report how long a plugin's update() kept its display() from drawing.
+
+        While update() runs on the worker it holds the plugin's lock, and every
+        frame of that plugin's screen is skipped: the panel keeps showing the
+        last frame, which on a scroller is a frozen strip. Nothing said so --
+        the frames are not failures, and a scroll freeze of 5 s or more is a
+        gap to the frame stats, not a freeze. This times each such run and,
+        when it ends after DISPLAY_HOLD_REPORT_SECONDS or more, logs it
+        (rate-limited per plugin) and records it on the plugin's health as a
+        busy skip, which never touches the circuit breaker. Only frames of the
+        high-FPS loop are timed (see _display_once's ``report_hold``).
+        """
+        # The clock is read only when a run starts or ends: on a frame that
+        # draws with no run open, this is one attribute check.
+        current = self._display_hold
+        if held:
+            if current is None or current[0] != plugin_id:
+                self._display_hold = (plugin_id, time.monotonic())
+            return
+        if current is None:
+            return
+        self._display_hold = None
+        if current[0] != plugin_id:
+            return
+        seconds = time.monotonic() - current[1]
+        if seconds < self.DISPLAY_HOLD_REPORT_SECONDS:
+            return
+        pm = self.plugin_manager
+        warn = getattr(pm, '_warn_rate_limited', None)
+        if warn is not None:
+            warn(f"display-hold:{plugin_id}",
+                 "Display of %s held %.0f ms by its update()",
+                 plugin_id, seconds * 1000.0)
+        tracker = getattr(pm, 'health_tracker', None)
+        record = getattr(tracker, 'record_busy_skip', None)
+        if record is not None:
+            try:
+                record(plugin_id, "display hold", seconds)
+            except Exception:  # pylint: disable=broad-except
+                logger.debug("Could not record a display hold", exc_info=True)
+
     @contextmanager
     def _display_lock_or_skip(self, plugin_id):
         """Try-lock guard keeping a plugin's display() off its in-flight update().
@@ -1189,7 +1238,7 @@ class DisplayController:
             lock.release()
 
     def _display_once(self, plugin, mode: str, accepts_display_mode: bool,
-                      force_clear: bool = False):
+                      force_clear: bool = False, report_hold: bool = False):
         """Call ``plugin.display()`` directly for one frame of a render loop.
 
         Frames after a screen's first dispatch come through here rather than
@@ -1205,6 +1254,12 @@ class DisplayController:
                 ``display_mode`` so plugins with several modes stay on it.
             accepts_display_mode: Whether display() takes ``display_mode``.
             force_clear: Passed through to display().
+            report_hold: Time runs of frames skipped because update() holds
+                the plugin's lock (see _note_display_hold). Only the high-FPS
+                loop asks: its frames are ~8 ms apart, so a run measures the
+                hold, and a held scroller is a frozen strip. The 1 Hz loop's
+                frames are a second apart, so one skipped frame there would
+                read as a 1 s hold of a screen that did not visibly change.
 
         Each call is timed (two monotonic reads) and handed to
         PluginManager.note_display_duration, which logs and records slow
@@ -1219,6 +1274,12 @@ class DisplayController:
         display_watchdog.watchdog.beat()
         plugin_id = getattr(plugin, 'plugin_id', None)
         with self._display_lock_or_skip(plugin_id) as can_display:
+            if report_hold and plugin_id:
+                self._note_display_hold(plugin_id, held=not can_display)
+            elif can_display and self._display_hold is not None:
+                # A drawn frame outside the high-FPS loop: whatever run was
+                # open is over, unreported.
+                self._display_hold = None
             if not can_display:
                 return True
             started = time.monotonic()
@@ -3987,7 +4048,8 @@ class DisplayController:
                             _frame_start = time.perf_counter()
                             try:
                                 result = self._display_once(
-                                    manager_to_display, active_mode, _accepts_display_mode)
+                                    manager_to_display, active_mode, _accepts_display_mode,
+                                    report_hold=True)
                                 if isinstance(result, bool) and not result:
                                     logger.debug("Display returned False, breaking early")
                                     break

test/test_display_hold_report.py

@@ -0,0 +1,142 @@
+"""The report of a scrolling screen held by its plugin's update().
+
+While a plugin's update() runs it holds the plugin's lock, and its screen's
+frames are skipped -- on a scroller, a frozen strip -- with nothing logged.
+_note_display_hold times each such run and reports one of
+DISPLAY_HOLD_REPORT_SECONDS or more.
+"""
+
+import threading
+import types
+from unittest.mock import MagicMock
+
+import pytest
+
+
+class _Clock:
+    """display_controller's clock: moves only when run() sleeps or a test says."""
+
+    def __init__(self, start=10_000.0):
+        self.t = start
+
+    def now(self):
+        return self.t
+
+    def sleep(self, seconds):
+        self.t += max(seconds, 0.0005)
+
+    def module(self):
+        return types.SimpleNamespace(time=self.now, monotonic=self.now,
+                                     perf_counter=self.now, sleep=self.sleep)
+
+
+@pytest.fixture
+def clock(monkeypatch):
+    c = _Clock()
+    monkeypatch.setattr("src.display_controller.time", c.module())
+    return c
+
+
+class _Locks:
+    """get_plugin_lock for one plugin, whose lock the test can hold."""
+
+    def __init__(self):
+        self.lock = threading.Lock()
+
+    def __call__(self, plugin_id):
+        return self.lock
+
+
+@pytest.fixture
+def held(test_display_controller):
+    c = test_display_controller
+    locks = _Locks()
+    c.plugin_manager.get_plugin_lock = locks
+    c.plugin_manager._warn_rate_limited = MagicMock()
+    c.plugin_manager.health_tracker = MagicMock()
+    c._display_hold = None
+    return c, locks.lock
+
+
+def _plugin(plugin_id):
+    p = MagicMock()
+    p.plugin_id = plugin_id
+    p.display.return_value = True
+    return p
+
+
+class TestTheDisplayHoldReport:
+    def test_a_long_hold_is_reported_when_it_ends(self, held, clock):
+        c, lock = held
+        ticker = _plugin("ticker")
+        lock.acquire()                         # update() running
+        assert c._display_once(ticker, "ticker", False, report_hold=True) is True
+        clock.t += 0.2
+        assert c._display_once(ticker, "ticker", False, report_hold=True) is True
+        assert ticker.display.call_count == 0
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+        clock.t += 0.2
+        lock.release()                         # update() done
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        assert ticker.display.call_count == 1
+        key, message, plugin_id, ms = c.plugin_manager._warn_rate_limited.call_args[0]
+        assert key == "display-hold:ticker" and plugin_id == "ticker"
+        assert "held" in message and ms == pytest.approx(400.0)
+        c.plugin_manager.health_tracker.record_busy_skip.assert_called_once_with(
+            "ticker", "display hold", pytest.approx(0.4))
+
+    def test_a_short_hold_is_not(self, held, clock):
+        c, lock = held
+        ticker = _plugin("ticker")
+        lock.acquire()
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        clock.t += 0.1
+        lock.release()
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+        c.plugin_manager.health_tracker.record_busy_skip.assert_not_called()
+
+    def test_a_hold_that_ends_on_another_plugins_screen_is_not_blamed_on_it(
+            self, held, clock):
+        c, lock = held
+        lock.acquire()
+        c._display_once(_plugin("ticker"), "ticker", False, report_hold=True)
+        clock.t += 1.0
+        lock.release()
+        c._display_once(_plugin("clock"), "clock", False, report_hold=True)
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+        assert c._display_hold is None
+
+    def test_frames_that_draw_report_nothing(self, held, clock):
+        c, _lock = held
+        ticker = _plugin("ticker")
+        for _ in range(5):
+            c._display_once(ticker, "ticker", False, report_hold=True)
+            clock.t += 0.5
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+
+    def test_the_1hz_loop_reports_no_holds(self, held, clock):
+        # A static screen's frames are a second apart: one skipped frame is
+        # not a measured hold, and nothing on the panel froze. (On ledpi the
+        # first version reported every such skip as "held 1000 ms".)
+        c, lock = held
+        board = _plugin("board")
+        lock.acquire()
+        c._display_once(board, "board", False)
+        clock.t += 1.0
+        lock.release()
+        c._display_once(board, "board", False)
+        c.plugin_manager._warn_rate_limited.assert_not_called()
+        c.plugin_manager.health_tracker.record_busy_skip.assert_not_called()
+
+    def test_a_run_left_open_is_dropped_by_a_1hz_frame(self, held, clock):
+        c, lock = held
+        ticker = _plugin("ticker")
+        lock.acquire()
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        lock.release()
+        c._display_once(ticker, "ticker", False)        # the 1 Hz loop draws
+        assert c._display_hold is None
+        clock.t += 5.0
+        c._display_once(ticker, "ticker", False, report_hold=True)
+        c.plugin_manager._warn_rate_limited.assert_not_called()

test/web_interface/test_starlark_pixlet_routes.py

@@ -26,8 +26,15 @@ import pytest
 
 
 @pytest.fixture
-def client():
+def client(monkeypatch):
+    from web_interface import app as web_app
     from web_interface.app import app
+    # The captive-portal before_request hook shells out to systemctl/nmcli
+    # whenever its 30s cache is cold, so on a Linux host whether a request
+    # here runs subprocess depended on how long ago the previous one was --
+    # and several tests below stub subprocess. Pin it: no test in this file
+    # is about AP mode.
+    monkeypatch.setattr(web_app, 'is_ap_mode_active', lambda: False)
     app.config['TESTING'] = True
     with app.test_client() as c:
         yield c
@@ -1136,12 +1143,23 @@ class TestPixletEditorHostDefaultsButDoesNotOverride:
                 captured['env'] = env
             return FakeProcess()
 
+        # Swap the route module's own ``subprocess`` binding, not the shared
+        # ``subprocess.Popen``: patching the attribute on the real module is
+        # process-wide, and the app's before_request hook (the captive-portal
+        # check) runs ``subprocess.run`` -- ``with Popen(...)`` -- whenever its
+        # 30s AP-mode cache is cold on a host with systemctl. On the Linux CI
+        # runner that handed it this FakeProcess and 500'd the request, but
+        # only when the previous request was more than 30s earlier.
+        fake_subprocess = types.ModuleType('subprocess')
+        fake_subprocess.__dict__.update(mod.subprocess.__dict__)
+        fake_subprocess.Popen = fake_popen
+
         with patch.object(mod, '_validate_starlark_app_path',
                           return_value=(app_dir, None)), \
              patch.object(mod, '_PIXLET_EDITOR_SCRIPT', script), \
              patch.object(mod, '_PIXLET_EDITOR_STATE', state_file), \
              patch.object(mod, '_find_pixlet_binary', return_value='/usr/bin/pixlet'), \
-             patch.object(mod.subprocess, 'Popen', side_effect=fake_popen), \
+             patch.object(mod, 'subprocess', fake_subprocess), \
              patch.dict(os.environ):
             if operator_host is None:
                 os.environ.pop('PIXLET_EDITOR_HOST', None)