fix(plugins): one hung plugin no longer stops every plugin from updating

CHANGELOG.md

@@ -101,6 +101,32 @@ accepts both, but the store flags the old spelling as deprecated
 - A stop request now clears an on-demand error. After a failed request,
   `/display/on-demand/status` kept reporting `status: error` for up to two
   minutes even after a stop.
+- One hung plugin no longer stops every plugin from updating. The single
+  update worker waited on each plugin's lock with no time limit, and the
+  render thread holds that lock while it runs the plugin's display(); a
+  display() that never returned (or a first frame still running after the
+  executor's 30s timeout) parked the worker for good, so scores, weather and
+  clocks all froze while the panel kept scrolling. The worker now waits at
+  most 5s (the bound `unload_plugin()` already uses) and skips that update;
+  the other plugins keep updating. The skip is logged (at most once a minute
+  per plugin) and counted in plugin health as a busy skip (`busy_skip_count`,
+  `last_busy_skip`), but it is not a failure and never opens the circuit
+  breaker: Vegas mode holds a plugin's lock for its whole content render,
+  which on a slow Pi can outlast 5s, and a healthy plugin must not be pulled
+  from rotation for that.
+- display() calls are timed on every frame. One taking 2s or more is logged
+  (at most once a minute per plugin) and counted in plugin health
+  (`slow_call_count`, `last_slow_call`); one that runs past the executor's
+  timeout counts as a hang (`hang_count`, `last_hang`) and as a failure to
+  the circuit breaker. A first frame that times out is no longer recorded as
+  a success, and an update() still running after its timeout is recorded as
+  a hang instead of leaving the plugin silently stuck. Only these real hangs
+  count toward the breaker.
+- A plugin's `on_config_change()` no longer runs while its update() is
+  running on the worker thread. It now runs under the plugin's lock; if the
+  lock stays busy past the same 5s bound the change is handed to the update
+  worker, which applies the latest one as soon as the lock frees, and before
+  the plugin's next update() at the latest. The plugin API is unchanged.
 
 ## 3.7.0
 

docs/ARCHITECTURE.md

@@ -105,7 +105,8 @@ then normal rotation.
   changes. The controller refreshes its cached settings; enabling or
   disabling a plugin queues `_reconcile_enabled_plugins()`, which loads or
   unloads it on the display thread; each plugin gets `on_config_change()`
-  for its own section. Set `LEDMATRIX_HOT_RELOAD=false` to turn this off.
+  for its own section, under its plugin lock
+  (`PluginManager.apply_config_change()`). Set `LEDMATRIX_HOT_RELOAD=false` to turn this off.
   Matrix hardware settings are only read at start-up.
 - **Vegas mode.** [`src/vegas_mode/`](../src/vegas_mode/): the display loop
   calls `VegasModeCoordinator.run_iteration()`

docs/PLUGIN_API_REFERENCE.md

@@ -151,6 +151,12 @@ Clean up resources when plugin is unloaded. Override to close connections, stop
 
 Called after plugin configuration is updated via web API.
 
+In the display service it runs on the config watcher thread while holding
+the plugin's lock, so it never overlaps your `update()` or `display()`. If
+the plugin stays busy for more than 5 seconds, the change is applied later
+from the update thread: as soon as the plugin is free, and before its next
+`update()` at the latest.
+
 #### `on_enable() -> None`
 
 Called when plugin is enabled.

src/display_controller.py

@@ -1029,17 +1029,28 @@ def _display_once(self, plugin, mode: str, accepts_display_mode: bool,
             accepts_display_mode: Whether display() takes ``display_mode``.
             force_clear: Passed through to display().
 
+        Each call is timed (two monotonic reads) and handed to
+        PluginManager.note_display_duration, which logs and records slow
+        calls and counts one that ran past the executor's timeout as a hang.
+
         Returns:
             display()'s result, or True when the frame was skipped because
             the plugin's update() holds its lock (the panel keeps the last
             frame; that is not a failure).
         """
-        with self._display_lock_or_skip(getattr(plugin, 'plugin_id', None)) as can_display:
+        plugin_id = getattr(plugin, 'plugin_id', None)
+        with self._display_lock_or_skip(plugin_id) as can_display:
             if not can_display:
                 return True
-            if accepts_display_mode:
-                return plugin.display(display_mode=mode, force_clear=force_clear)
-            return plugin.display(force_clear=force_clear)
+            started = time.monotonic()
+            try:
+                if accepts_display_mode:
+                    return plugin.display(display_mode=mode, force_clear=force_clear)
+                return plugin.display(force_clear=force_clear)
+            finally:
+                note = getattr(self.plugin_manager, 'note_display_duration', None)
+                if note is not None and plugin_id:
+                    note(plugin_id, time.monotonic() - started)
 
     def _health_tracker(self):
         """The plugin circuit breaker, or None when it is not enabled."""
@@ -2498,6 +2509,7 @@ def run(self):
                         pm = self.plugin_manager
                         display_lock = pm.get_plugin_lock(plugin_id) if pm else None
                         can_display = display_lock is None or display_lock.acquire(blocking=False)
+                        display_hung = False
 
                         if display_lock is None:
                             # Only when plugin loading failed part-way.
@@ -2517,7 +2529,7 @@ def run(self):
                             # thread actually finishes it, rather than
                             # here when this dispatch merely returns.
                             release_guard = threading.Lock()
-                            released = {'done': False}
+                            released = {'done': False, 'started': False}
 
                             def _release_display_lock():
                                 with release_guard:
@@ -2528,18 +2540,21 @@ def _release_display_lock():
 
                             if _accepts_display_mode:
                                 def _display_target(display_mode=None, force_clear=False):
+                                    released['started'] = True
                                     try:
                                         return manager_to_display.display(
                                             display_mode=display_mode, force_clear=force_clear)
                                     finally:
                                         _release_display_lock()
                             else:
                                 def _display_target(force_clear=False):
+                                    released['started'] = True
                                     try:
                                         return manager_to_display.display(force_clear=force_clear)
                                     finally:
                                         _release_display_lock()
 
+                            dispatch_start = time.monotonic()
                             try:
                                 result = pm.plugin_executor.execute_display(
                                     types.SimpleNamespace(display=_display_target),
@@ -2562,6 +2577,18 @@ def _display_target(force_clear=False):
                                 _release_display_lock()
                                 raise
 
+                            dispatch_seconds = time.monotonic() - dispatch_start
+                            if released['started'] and not released['done']:
+                                # The executor gave up waiting and display()
+                                # is still running on its thread, holding
+                                # the lock. A hang, not a success: recorded
+                                # so repeats open the circuit breaker, and
+                                # the update worker's bounded wait skips it.
+                                display_hung = True
+                                pm.record_display_hang(plugin_id, dispatch_seconds)
+                            else:
+                                pm.note_display_duration(plugin_id, dispatch_seconds)
+
                         logger.debug(f"display() returned: {result} (type: {type(result)})")
                         if isinstance(result, bool):
                             display_result = result
@@ -2575,7 +2602,7 @@ def _display_target(force_clear=False):
                         # be lost when display() finally does run.
                         if can_display:
                             health_tracker = self._health_tracker()
-                            if health_tracker is not None:
+                            if health_tracker is not None and not display_hung:
                                 health_tracker.record_success(plugin_id)
                             self.force_change = False
                     except Exception as exc:  # pylint: disable=broad-except
@@ -3274,8 +3301,18 @@ def config_change_callback(old_config: Dict[str, Any], new_config: Dict[str, Any
                         # says disabled, and on_config_change would switch
                         # the instance off mid-session.
                         new_config = {**new_config, 'enabled': True}
-                    _plugin.on_config_change(new_config)
-                    logger.debug("Plugin %s notified of config change", _pid)
+                    # Runs on ConfigService's watcher thread. Under the
+                    # plugin's lock, so it cannot interleave with update()
+                    # on the worker or display() on the render thread; a
+                    # lock held past the bound defers it to the worker.
+                    apply = getattr(self.plugin_manager, 'apply_config_change', None)
+                    if callable(apply):
+                        applied = apply(_pid, new_config, plugin_instance=_plugin)
+                    else:
+                        _plugin.on_config_change(new_config)
+                        applied = True
+                    logger.debug("Plugin %s notified of config change%s", _pid,
+                                 "" if applied else " (deferred: plugin busy)")
                 except Exception as e:
                     logger.error("Error in plugin %s config change handler: %s", _pid, e, exc_info=True)
 

src/plugin_system/plugin_executor.py

@@ -19,8 +19,25 @@ class PluginTimeoutError(Exception):
     """Raised when a plugin operation times out."""
 
 
+class PluginBusyError(PluginTimeoutError):
+    """A plugin's lock stayed held past its bound.
+
+    Not raised; recorded. The lock is held by the plugin's own display(),
+    update(), on_config_change() or a Vegas content render -- slow, or hung
+    -- so the caller skipped the plugin rather than wait on it. Report-only:
+    it is kept as the plugin's state error info and counted as a busy skip in
+    health, never as a failure, so it cannot open the circuit breaker.
+    """
+
+
 class PluginExecutor:
     """Handles plugin execution with timeout and error isolation."""
+
+    #: A display() call at least this long is logged and counted as slow.
+    #: A frame is milliseconds; two seconds is a plugin doing I/O in display().
+    SLOW_DISPLAY_SECONDS = 2.0
+    #: An update() call at least this long is logged as slow.
+    SLOW_UPDATE_SECONDS = 5.0
 
     def __init__(
         self,
@@ -117,15 +134,15 @@ def execute_update(
             True if update succeeded, False otherwise
         """
         try:
-            start_time = time.time()
+            start_time = time.monotonic()
             self.execute_with_timeout(
                 lambda: plugin.update(),
                 timeout=timeout,
                 plugin_id=plugin_id
             )
-            duration = time.time() - start_time
+            duration = time.monotonic() - start_time
 
-            if duration > 5.0:  # Warn if update takes more than 5 seconds
+            if duration > self.SLOW_UPDATE_SECONDS:
                 self.logger.warning(
                     "Plugin %s update() took %.2fs (consider optimizing)",
                     plugin_id,
@@ -175,7 +192,7 @@ def execute_display(
             True if display succeeded, False otherwise
         """
         try:
-            start_time = time.time()
+            start_time = time.monotonic()
 
             # Does display() take a display_mode keyword? The caller usually
             # knows and caches the answer, so prefer what it passed.
@@ -206,9 +223,9 @@ def execute_display(
                     plugin_id=plugin_id
                 )
 
-            duration = time.time() - start_time
+            duration = time.monotonic() - start_time
 
-            if duration > 2.0:  # Warn if display takes more than 2 seconds
+            if duration > self.SLOW_DISPLAY_SECONDS:
                 self.logger.warning(
                     "Plugin %s display() took %.2fs (consider optimizing)",
                     plugin_id,

src/plugin_system/plugin_health.py

@@ -254,6 +254,104 @@ def record_failure(self, plugin_id: str, error: Optional[Exception] = None) -> N
 
         self._save_health_state(plugin_id, state)
 
+    def record_hang(self, plugin_id: str, operation: str, seconds: float,
+                    error: Optional[Exception] = None) -> None:
+        """Record a display() or update() call that ran past its limit.
+
+        Counts as a failure, so the ordinary circuit breaker handles a plugin
+        that keeps hanging: after ``failure_threshold`` in a row it is skipped
+        by both the update scheduler and the display rotation until the
+        cooldown ends. The hang itself is kept alongside (``hang_count``,
+        ``last_hang``) so the health API can tell "hung" from "raised".
+
+        Not for an update skipped because the plugin's lock stayed held: the
+        holder may be a healthy but long render (Vegas prefetch). That is
+        :meth:`record_busy_skip`, which never touches the breaker.
+
+        Args:
+            plugin_id: Plugin identifier
+            operation: What hung: ``"display"`` or ``"update"``.
+            seconds: How long it had been running when this was recorded.
+            error: The error to store as ``last_error``; one is built from
+                the other arguments when omitted.
+        """
+        state = self.get_health_state(plugin_id)
+        count = state.get('hang_count')
+        state['hang_count'] = (count if isinstance(count, int) and not isinstance(count, bool)
+                               else 0) + 1
+        state['last_hang'] = {
+            'operation': operation,
+            'seconds': round(float(seconds), 3),
+            'time': time.time(),
+        }
+        if error is None:
+            error = TimeoutError(f"{operation} still running after {seconds:.1f}s")
+        # record_failure saves the record, hang fields included.
+        self.record_failure(plugin_id, error)
+
+    #: Minimum seconds between persisting a plugin's slow-call or busy-skip
+    #: counters. The in-memory record is updated every time; a plugin that is
+    #: slow on every frame must not become an SD-card write per frame.
+    SLOW_CALL_PERSIST_INTERVAL = 60.0
+
+    def record_slow_call(self, plugin_id: str, operation: str, seconds: float) -> None:
+        """Note a call that finished, but slowly. Reporting only.
+
+        Unlike :meth:`record_hang` this never touches the circuit breaker: a
+        slow display() still drew its frame.
+        """
+        state = self.get_health_state(plugin_id)
+        count = state.get('slow_call_count')
+        state['slow_call_count'] = (count if isinstance(count, int) and not isinstance(count, bool)
+                                    else 0) + 1
+        now = time.time()
+        state['last_slow_call'] = {
+            'operation': operation,
+            'seconds': round(float(seconds), 3),
+            'time': now,
+        }
+        self._save_reporting_throttled('slow', plugin_id, state, now)
+
+    def record_busy_skip(self, plugin_id: str, operation: str, seconds: float) -> None:
+        """Note a call skipped because the plugin's lock stayed held. Reporting only.
+
+        The update worker gives up on a plugin's lock after
+        ``PluginManager.PLUGIN_LOCK_TIMEOUT``. Whatever held it may be healthy
+        -- Vegas prefetch holds the lock for a plugin's whole content render,
+        which on a slow Pi can take longer than that -- so like
+        :meth:`record_slow_call` this never touches the circuit breaker, the
+        failure streak or ``last_error``. A real hang is recorded by
+        :meth:`record_hang` where it is measured.
+
+        Args:
+            plugin_id: Plugin identifier
+            operation: What was skipped, e.g. ``"update lock wait"``.
+            seconds: How long the lock was waited on.
+        """
+        state = self.get_health_state(plugin_id)
+        count = state.get('busy_skip_count')
+        state['busy_skip_count'] = (count if isinstance(count, int) and not isinstance(count, bool)
+                                    else 0) + 1
+        now = time.time()
+        state['last_busy_skip'] = {
+            'operation': operation,
+            'seconds': round(float(seconds), 3),
+            'time': now,
+        }
+        self._save_reporting_throttled('busy', plugin_id, state, now)
+
+    def _save_reporting_throttled(self, kind: str, plugin_id: str,
+                                  state: Dict[str, Any], now: float) -> None:
+        """Persist a reporting-only change at most once per
+        SLOW_CALL_PERSIST_INTERVAL per plugin and ``kind``. The first one is
+        saved at once, so the web process (which reads the persisted record)
+        sees it; repeats in between stay in memory until the next save."""
+        saved_at = self.__dict__.setdefault('_reporting_saved_at', {})
+        last = saved_at.get((kind, plugin_id))
+        if last is None or now - last >= self.SLOW_CALL_PERSIST_INTERVAL:
+            saved_at[(kind, plugin_id)] = now
+            self._save_health_state(plugin_id, state)
+
     def set_degraded(self, plugin_id: str, reason: Optional[str]) -> None:
         """Flag (or clear) a plugin as degraded without touching the circuit breaker.
 
@@ -345,7 +443,13 @@ def get_health_summary(self, plugin_id: str, force_reload: bool = False) -> Dict
             'degraded': state.get('degraded', False),
             'degraded_reason': state.get('degraded_reason'),
             'circuit_opened_time': state.get('circuit_opened_time'),
-            'half_open_start_time': state.get('half_open_start_time')
+            'half_open_start_time': state.get('half_open_start_time'),
+            'hang_count': state.get('hang_count', 0),
+            'last_hang': state.get('last_hang'),
+            'slow_call_count': state.get('slow_call_count', 0),
+            'last_slow_call': state.get('last_slow_call'),
+            'busy_skip_count': state.get('busy_skip_count', 0),
+            'last_busy_skip': state.get('last_busy_skip'),
         }
 
     def get_all_health_summaries(self) -> Dict[str, Dict[str, Any]]: