mirror of
https://github.com/ChuckBuilds/LEDMatrix.git
synced 2026-08-01 08:48:05 +00:00
perf(plugins): run scheduled updates off the render thread (#407)
* perf(plugins): run scheduled updates off the render thread plugin update() executed inline in the render loop — execute_update's internal thread.join(timeout=30) blocked it, so one slow plugin HTTP fetch froze scrolling for the whole fetch (up to 30s; DNS-retry storms made this a regular occurrence on flaky networks). Scheduling stays on the render thread and keeps every existing gate (enabled, circuit breaker, can_execute, interval); due updates are now enqueued to a single background worker (serialized — same one-at-a-time execution as before, no thundering herd). RUNNING is set at enqueue so can_execute blocks re-entry alongside the pending-set dedup. Per-plugin locks make the old implicit update/display no-overlap guarantee explicit: the worker holds the plugin's lock through its update; the display side try-locks and, when the plugin is mid-update, holds the last frame for that iteration — reported as success so a mid-update skip never advances the rotation. Unlike before, the guarantee now also holds across the post-timeout window (previously the lingering update thread overlapped display()). Deadlock-free by construction: the worker takes one lock; display never blocks. Timeout semantics unchanged (lingering daemon thread documented). Kill switch: plugin_system.synchronous_updates: true restores the inline path. 8 new concurrency tests (non-blocking scheduler, overlap assertion under a hammering display loop, lock release on failure/timeout paths, dedup, kill switch); 4-min devpi soak clean (updates completing, rotation advancing, no stuck RUNNING states). Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FqzC1nzTWL4kaqgMaQZFam * fix(plugins): fix skipped-frame health/force_change tracking, config validation, and lock-lifetime gaps in async updates Addresses PR #407 review findings: - display_controller: only clear force_change / record health success when display() actually ran this frame, not when the frame was skipped because the plugin's lock was busy (a skip must preserve a pending mode-switch force_clear). - plugin_manager: replace bool() coercion of synchronous_updates with explicit isinstance validation of plugin_system/synchronous_updates, failing safe to synchronous mode (with a logged reason) on malformed config instead of silently defaulting to async. - plugin_manager: _update_worker_loop now acquires the plugin lock before looking up its instance and re-checks under the lock, so an unloaded plugin's lifecycle state is never resurrected to ENABLED. - plugin_manager + display_controller: move lock ownership (and, for updates, RUNNING/pending lifecycle bookkeeping) into the actual update()/ display() call itself rather than the timeout-wrapped caller, so the lock stays held for the real operation's duration even after PluginExecutor's own join(timeout) elapses and a lingering daemon thread keeps running in the background. - DisplayController.cleanup() now stops the update worker before tearing down display/cache resources; stop_update_worker() logs when the join times out instead of failing silently. - test_async_plugin_updates: rewrite test_unloaded_while_queued_is_harmless to exercise the public unload_plugin() lifecycle (via a deterministic blocker) instead of deleting pm.plugins directly, and add a regression test proving the plugin lock stays held through PluginExecutor's own timeout while the real update() call is still running. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01KEZK1P1Q1fu5pcuVrkrCFZ --------- Co-authored-by: Chuck <chuck@example.com> Co-authored-by: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
co-authored by
Claude Sonnet 5
Chuck
parent
9837315308
commit
0aca40cf3a
+131
-27
@@ -23,6 +23,9 @@ Entry point: :func:`main` — instantiates :class:`DisplayController` and calls
|
||||
import time
|
||||
import os
|
||||
import json
|
||||
import threading
|
||||
import types
|
||||
from contextlib import contextmanager
|
||||
from pathlib import Path
|
||||
from typing import Dict, Any, List, Optional, Callable
|
||||
from datetime import datetime
|
||||
@@ -892,6 +895,30 @@ class DisplayController:
|
||||
except Exception: # pylint: disable=broad-except
|
||||
logger.exception("Error running scheduled plugin updates")
|
||||
|
||||
@contextmanager
|
||||
def _display_lock_or_skip(self, plugin_id):
|
||||
"""Try-lock guard keeping a plugin's display() off its in-flight update().
|
||||
|
||||
Yields True when display may run (lock held, released on exit) or
|
||||
when no lock support exists (older plugin manager). Yields False when
|
||||
the plugin's update() is currently executing on the background
|
||||
worker — the caller should treat the frame as displayed (the panel
|
||||
holds the last pushed frame) rather than as a plugin failure, so a
|
||||
mid-update skip never advances the rotation.
|
||||
"""
|
||||
pm = self.plugin_manager
|
||||
if not pm or not hasattr(pm, 'get_plugin_lock') or not plugin_id:
|
||||
yield True
|
||||
return
|
||||
lock = pm.get_plugin_lock(plugin_id)
|
||||
if not lock.acquire(blocking=False):
|
||||
yield False
|
||||
return
|
||||
try:
|
||||
yield True
|
||||
finally:
|
||||
lock.release()
|
||||
|
||||
_FOLLOWER_SEND_INTERVAL = 1.0 / 90 # raw bytes are cheap; 90fps > follower render rate
|
||||
|
||||
def _follower_rebuild_scroll_image(self) -> None:
|
||||
@@ -1879,6 +1906,7 @@ class DisplayController:
|
||||
plugin_id = getattr(manager_to_display, 'plugin_id', active_mode)
|
||||
try:
|
||||
logger.debug(f"Calling display() for {active_mode} with force_clear={self.force_change}")
|
||||
can_display = False
|
||||
if hasattr(manager_to_display, 'display'):
|
||||
# Opt #1: look up (or compute once) whether display() accepts display_mode
|
||||
_cache_key = plugin_id
|
||||
@@ -1889,14 +1917,64 @@ class DisplayController:
|
||||
)
|
||||
_accepts_display_mode = self._plugin_accepts_display_mode[_cache_key]
|
||||
|
||||
# Use PluginExecutor for safe execution with timeout
|
||||
if self.plugin_manager and hasattr(self.plugin_manager, 'plugin_executor'):
|
||||
result = self.plugin_manager.plugin_executor.execute_display(
|
||||
manager_to_display,
|
||||
plugin_id,
|
||||
force_clear=self.force_change,
|
||||
display_mode=active_mode if _accepts_display_mode else None
|
||||
)
|
||||
pm = self.plugin_manager
|
||||
display_lock = None
|
||||
can_display = True
|
||||
if pm and hasattr(pm, 'get_plugin_lock'):
|
||||
display_lock = pm.get_plugin_lock(plugin_id)
|
||||
can_display = display_lock.acquire(blocking=False)
|
||||
|
||||
if not can_display:
|
||||
# update() in flight on the worker — hold
|
||||
# the last frame; not a plugin failure
|
||||
result = True
|
||||
elif pm and hasattr(pm, 'plugin_executor'):
|
||||
# PluginExecutor's own thread.join(timeout) can
|
||||
# return before the real display() call
|
||||
# finishes (a lingering daemon thread keeps
|
||||
# running it) -- so the lock is released from
|
||||
# inside the wrapped call itself, whichever
|
||||
# thread actually finishes it, rather than
|
||||
# here when this dispatch merely returns.
|
||||
release_guard = threading.Lock()
|
||||
released = {'done': False}
|
||||
|
||||
def _release_display_lock():
|
||||
with release_guard:
|
||||
if released['done']:
|
||||
return
|
||||
released['done'] = True
|
||||
if display_lock is not None:
|
||||
display_lock.release()
|
||||
|
||||
if _accepts_display_mode:
|
||||
def _display_target(display_mode=None, force_clear=False):
|
||||
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):
|
||||
try:
|
||||
return manager_to_display.display(force_clear=force_clear)
|
||||
finally:
|
||||
_release_display_lock()
|
||||
|
||||
try:
|
||||
result = self.plugin_manager.plugin_executor.execute_display(
|
||||
types.SimpleNamespace(display=_display_target),
|
||||
plugin_id,
|
||||
force_clear=self.force_change,
|
||||
display_mode=active_mode if _accepts_display_mode else None
|
||||
)
|
||||
except Exception: # pragma: no cover - defensive;
|
||||
# execute_display catches everything
|
||||
# internally, but guarantee the lock is
|
||||
# never leaked if something unexpected
|
||||
# slips through.
|
||||
_release_display_lock()
|
||||
raise
|
||||
# execute_display returns bool, convert to expected format
|
||||
if result:
|
||||
result = True # Success
|
||||
@@ -1904,10 +1982,14 @@ class DisplayController:
|
||||
result = False # Failed
|
||||
else:
|
||||
# Fallback to direct call if executor not available
|
||||
if _accepts_display_mode:
|
||||
result = manager_to_display.display(display_mode=active_mode, force_clear=self.force_change)
|
||||
else:
|
||||
result = manager_to_display.display(force_clear=self.force_change)
|
||||
try:
|
||||
if _accepts_display_mode:
|
||||
result = manager_to_display.display(display_mode=active_mode, force_clear=self.force_change)
|
||||
else:
|
||||
result = manager_to_display.display(force_clear=self.force_change)
|
||||
finally:
|
||||
if display_lock is not None:
|
||||
display_lock.release()
|
||||
|
||||
logger.debug(f"display() returned: {result} (type: {type(result)})")
|
||||
# Check if display() returned a boolean (new behavior)
|
||||
@@ -1916,11 +1998,15 @@ class DisplayController:
|
||||
if not display_result:
|
||||
logger.info("Plugin %s display() returned False for mode %s", plugin_id, active_mode)
|
||||
|
||||
# Record success if display completed without exception
|
||||
if self.plugin_manager and hasattr(self.plugin_manager, 'health_tracker') and self.plugin_manager.health_tracker:
|
||||
self.plugin_manager.health_tracker.record_success(plugin_id)
|
||||
|
||||
self.force_change = False
|
||||
# Record success only when display() actually ran this
|
||||
# frame -- a skipped frame (lock busy) held the last
|
||||
# frame, not a real success, and must not clear
|
||||
# force_change or the pending mode-switch clear will
|
||||
# be lost when display() finally does run.
|
||||
if can_display:
|
||||
if self.plugin_manager and hasattr(self.plugin_manager, 'health_tracker') and self.plugin_manager.health_tracker:
|
||||
self.plugin_manager.health_tracker.record_success(plugin_id)
|
||||
self.force_change = False
|
||||
except Exception as exc: # pylint: disable=broad-except
|
||||
logger.exception("Error displaying %s", self.current_display_mode)
|
||||
# Record failure
|
||||
@@ -2205,11 +2291,16 @@ class DisplayController:
|
||||
|
||||
while True:
|
||||
try:
|
||||
# Pass display_mode to maintain sticky manager state
|
||||
if _accepts_display_mode:
|
||||
result = manager_to_display.display(display_mode=active_mode, force_clear=False)
|
||||
else:
|
||||
result = manager_to_display.display(force_clear=False)
|
||||
with self._display_lock_or_skip(plugin_id) as can_display:
|
||||
if can_display:
|
||||
# Pass display_mode to maintain sticky manager state
|
||||
if _accepts_display_mode:
|
||||
result = manager_to_display.display(display_mode=active_mode, force_clear=False)
|
||||
else:
|
||||
result = manager_to_display.display(force_clear=False)
|
||||
else:
|
||||
# update() in flight — hold the last frame
|
||||
result = True
|
||||
if isinstance(result, bool) and not result:
|
||||
logger.debug("Display returned False, breaking early")
|
||||
break
|
||||
@@ -2269,11 +2360,16 @@ class DisplayController:
|
||||
break
|
||||
|
||||
try:
|
||||
# Pass display_mode to maintain sticky manager state
|
||||
if _accepts_display_mode:
|
||||
result = manager_to_display.display(display_mode=active_mode, force_clear=False)
|
||||
else:
|
||||
result = manager_to_display.display(force_clear=False)
|
||||
with self._display_lock_or_skip(plugin_id) as can_display:
|
||||
if can_display:
|
||||
# Pass display_mode to maintain sticky manager state
|
||||
if _accepts_display_mode:
|
||||
result = manager_to_display.display(display_mode=active_mode, force_clear=False)
|
||||
else:
|
||||
result = manager_to_display.display(force_clear=False)
|
||||
else:
|
||||
# update() in flight — hold the last frame
|
||||
result = True
|
||||
if isinstance(result, bool) and not result:
|
||||
# For dynamic duration plugins, don't exit on False - keep looping
|
||||
# until cycle is complete or max duration is reached
|
||||
@@ -2791,6 +2887,14 @@ class DisplayController:
|
||||
|
||||
def cleanup(self):
|
||||
"""Clean up resources."""
|
||||
# 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.
|
||||
if self.plugin_manager and hasattr(self.plugin_manager, 'stop_update_worker'):
|
||||
try:
|
||||
self.plugin_manager.stop_update_worker()
|
||||
except Exception as e:
|
||||
logger.warning("Error stopping plugin update worker: %s", e)
|
||||
# Shutdown config service if it exists
|
||||
if hasattr(self, 'config_service'):
|
||||
try:
|
||||
|
||||
@@ -8,12 +8,13 @@ API Version: 1.0.0
|
||||
"""
|
||||
|
||||
import json
|
||||
import queue
|
||||
import sys
|
||||
import time
|
||||
import threading
|
||||
import types
|
||||
from pathlib import Path
|
||||
from typing import Dict, List, Optional, Any
|
||||
from typing import Dict, List, Optional, Any, Tuple
|
||||
import logging
|
||||
from src.exceptions import PluginError, ConfigError
|
||||
from src.logging_config import get_logger
|
||||
@@ -97,6 +98,50 @@ class PluginManager:
|
||||
# Health tracking (optional, set by display_controller if available)
|
||||
self.health_tracker = None
|
||||
self.resource_monitor = None
|
||||
|
||||
# --- Asynchronous plugin updates -------------------------------
|
||||
# update() used to run inline in the render loop (execute_update's
|
||||
# internal thread.join(timeout=30) blocked it), so one slow plugin
|
||||
# HTTP fetch froze scrolling for the whole fetch. Scheduling still
|
||||
# happens on the render thread (run_scheduled_updates), but
|
||||
# execution moves to this single background worker. Per-plugin
|
||||
# locks keep a plugin's update() and display() mutually exclusive —
|
||||
# today's implicit guarantee, now explicit (and, unlike today,
|
||||
# also held across the post-timeout window).
|
||||
# Kill switch: plugin_system.synchronous_updates: true restores the
|
||||
# inline path.
|
||||
self._update_queue: "queue.Queue[Optional[Tuple[str, float]]]" = queue.Queue()
|
||||
self._pending_updates: set = set()
|
||||
self._pending_lock = threading.Lock()
|
||||
self._plugin_locks: Dict[str, threading.Lock] = {}
|
||||
self._plugin_locks_guard = threading.Lock()
|
||||
self._update_worker: Optional[threading.Thread] = None
|
||||
self._synchronous_updates = False
|
||||
if self.config_manager is not None:
|
||||
try:
|
||||
cfg = self.config_manager.get_config() or {}
|
||||
except (OSError, ValueError) as exc:
|
||||
self.logger.warning(
|
||||
"Could not load config to check plugin_system.synchronous_updates "
|
||||
"(%s: %s); defaulting to synchronous updates", type(exc).__name__, exc)
|
||||
self._synchronous_updates = True
|
||||
else:
|
||||
plugin_system_cfg = cfg.get('plugin_system', {})
|
||||
if not isinstance(plugin_system_cfg, dict):
|
||||
self.logger.warning(
|
||||
"config plugin_system must be a mapping, got %s; "
|
||||
"defaulting to synchronous updates",
|
||||
type(plugin_system_cfg).__name__)
|
||||
self._synchronous_updates = True
|
||||
else:
|
||||
sync_value = plugin_system_cfg.get('synchronous_updates', False)
|
||||
if not isinstance(sync_value, bool):
|
||||
self.logger.warning(
|
||||
"config plugin_system.synchronous_updates must be a boolean, "
|
||||
"got %r; defaulting to synchronous updates", sync_value)
|
||||
self._synchronous_updates = True
|
||||
else:
|
||||
self._synchronous_updates = sync_value
|
||||
|
||||
# Ensure plugins directory exists with proper permissions
|
||||
try:
|
||||
@@ -744,47 +789,189 @@ class PluginManager:
|
||||
last_update = self.plugin_last_update.get(plugin_id, 0.0)
|
||||
|
||||
if last_update == 0.0 or (current_time - last_update) >= interval:
|
||||
# Update state to RUNNING
|
||||
self.state_manager.set_state(plugin_id, PluginState.RUNNING)
|
||||
|
||||
try:
|
||||
# Use PluginExecutor for safe execution
|
||||
success = False
|
||||
if self.resource_monitor:
|
||||
# If resource monitor exists, wrap the call
|
||||
def monitored_update():
|
||||
self.resource_monitor.monitor_call(plugin_id, plugin_instance.update)
|
||||
# SimpleNamespace stores `update` as an *instance*
|
||||
# attribute, so attribute lookup returns the plain
|
||||
# function object as-is. A dynamically-built class
|
||||
# (`type(..., {'update': monitored_update})`) instead
|
||||
# stores it as a *class* attribute, which the
|
||||
# descriptor protocol turns into a bound method on
|
||||
# access -- silently prepending the instance as an
|
||||
# implicit first argument to a function that takes
|
||||
# none, raising "monitored_update() takes 0
|
||||
# positional arguments but 1 was given" on every call.
|
||||
success = self.plugin_executor.execute_update(
|
||||
types.SimpleNamespace(update=monitored_update),
|
||||
plugin_id
|
||||
)
|
||||
else:
|
||||
success = self.plugin_executor.execute_update(plugin_instance, plugin_id)
|
||||
|
||||
if success:
|
||||
with self._plugin_last_update_lock:
|
||||
self.plugin_last_update[plugin_id] = current_time
|
||||
self.state_manager.record_update(plugin_id)
|
||||
# Update state back to ENABLED
|
||||
self.state_manager.set_state(plugin_id, PluginState.ENABLED)
|
||||
# Record success
|
||||
if self.health_tracker:
|
||||
self.health_tracker.record_success(plugin_id)
|
||||
else:
|
||||
self._record_update_failure(plugin_id)
|
||||
except Exception as exc: # pylint: disable=broad-except
|
||||
self.logger.exception("Error updating plugin %s: %s", plugin_id, exc)
|
||||
if self._synchronous_updates:
|
||||
# Kill-switch path: the original inline execution
|
||||
# (blocks the caller until update() completes/times out)
|
||||
self.state_manager.set_state(plugin_id, PluginState.RUNNING)
|
||||
self._execute_update_now(plugin_id, plugin_instance, current_time)
|
||||
else:
|
||||
self._enqueue_update(plugin_id, current_time)
|
||||
|
||||
def get_plugin_lock(self, plugin_id: str) -> threading.Lock:
|
||||
"""Per-plugin lock keeping update() and display() mutually exclusive.
|
||||
|
||||
The update worker holds it for the duration of a plugin's update();
|
||||
the display side acquires it non-blocking and skips that frame's
|
||||
display() call when the plugin is mid-update.
|
||||
"""
|
||||
with self._plugin_locks_guard:
|
||||
lock = self._plugin_locks.get(plugin_id)
|
||||
if lock is None:
|
||||
lock = threading.Lock()
|
||||
self._plugin_locks[plugin_id] = lock
|
||||
return lock
|
||||
|
||||
def _enqueue_update(self, plugin_id: str, scheduled_time: float) -> None:
|
||||
"""Queue a due update for the background worker (dedup while pending)."""
|
||||
with self._pending_lock:
|
||||
if plugin_id in self._pending_updates:
|
||||
return
|
||||
self._pending_updates.add(plugin_id)
|
||||
# RUNNING is set at enqueue time so can_execute() blocks re-entry and
|
||||
# the web UI shows the truthful state while the item waits its turn.
|
||||
self.state_manager.set_state(plugin_id, PluginState.RUNNING)
|
||||
self._ensure_update_worker()
|
||||
self._update_queue.put((plugin_id, scheduled_time))
|
||||
|
||||
def _ensure_update_worker(self) -> None:
|
||||
if self._update_worker is not None and self._update_worker.is_alive():
|
||||
return
|
||||
self._update_worker = threading.Thread(
|
||||
target=self._update_worker_loop, name='plugin-update-worker',
|
||||
daemon=True)
|
||||
self._update_worker.start()
|
||||
|
||||
def _update_worker_loop(self) -> None:
|
||||
"""Single worker: dispatches queued updates off the render thread
|
||||
(matching the old inline behavior — no thundering herd of
|
||||
concurrent fetches).
|
||||
|
||||
The plugin's lock is acquired here, before its instance is looked
|
||||
up, and the instance is re-fetched under the lock — a concurrent
|
||||
unload_plugin() can't leave this loop about to run update() on an
|
||||
instance that's already been torn down. The lock — and RUNNING/
|
||||
pending lifecycle state — is released by the update itself once the
|
||||
real update() call genuinely finishes (see _execute_update_now),
|
||||
which can be after this dispatch returns if PluginExecutor's own
|
||||
timeout elapses first.
|
||||
"""
|
||||
while True:
|
||||
item = self._update_queue.get()
|
||||
if item is None: # shutdown sentinel
|
||||
return
|
||||
plugin_id, scheduled_time = item
|
||||
lock = self.get_plugin_lock(plugin_id)
|
||||
lock.acquire()
|
||||
plugin_instance = self.plugins.get(plugin_id)
|
||||
if plugin_instance is None: # unloaded while queued; its
|
||||
# lifecycle state was already cleared by unload_plugin —
|
||||
# leave it alone rather than resurrecting it to ENABLED
|
||||
lock.release()
|
||||
with self._pending_lock:
|
||||
self._pending_updates.discard(plugin_id)
|
||||
continue
|
||||
try:
|
||||
self._execute_update_now(plugin_id, plugin_instance,
|
||||
scheduled_time, lock=lock)
|
||||
except Exception: # pylint: disable=broad-except
|
||||
# _execute_update_now guarantees the lock/pending bookkeeping
|
||||
# is released via its own _finish() before returning or
|
||||
# raising; this is a last-resort log only.
|
||||
self.logger.exception("update worker: unexpected error for %s",
|
||||
plugin_id)
|
||||
|
||||
def stop_update_worker(self, timeout: float = 5.0) -> None:
|
||||
"""Signal the worker to exit (used by cleanup; thread is a daemon)."""
|
||||
if self._update_worker is not None and self._update_worker.is_alive():
|
||||
self._update_queue.put(None)
|
||||
self._update_worker.join(timeout=timeout)
|
||||
if self._update_worker.is_alive():
|
||||
self.logger.warning(
|
||||
"Update worker did not stop within %.1fs; it is a daemon "
|
||||
"thread and will be abandoned on shutdown", timeout)
|
||||
|
||||
def _execute_update_now(self, plugin_id: str, plugin_instance: Any,
|
||||
scheduled_time: float,
|
||||
lock: Optional[threading.Lock] = None) -> None:
|
||||
"""Execute a plugin's update() via PluginExecutor, then bookkeep.
|
||||
|
||||
Caller is responsible for having set RUNNING state.
|
||||
|
||||
On the synchronous path (``lock=None``) this is the original,
|
||||
unchanged inline behavior. On the async worker path, PluginExecutor's
|
||||
internal thread.join(timeout) blocks only the calling thread -- on
|
||||
timeout the lingering daemon update-thread keeps running the real
|
||||
plugin.update() call unkillable in the background. So that the
|
||||
plugin's lock (and its RUNNING/pending lifecycle state) stays held
|
||||
for that real duration rather than just this bounded wait, ownership
|
||||
of both is carried by the wrapped update callable itself, released
|
||||
from whichever thread actually finishes it -- see _finish() below.
|
||||
"""
|
||||
finish_guard = threading.Lock()
|
||||
finished = {'done': False}
|
||||
|
||||
def _finish(success: bool, exc: Optional[Exception] = None) -> None:
|
||||
with finish_guard:
|
||||
if finished['done']:
|
||||
return
|
||||
finished['done'] = True
|
||||
try:
|
||||
if success:
|
||||
with self._plugin_last_update_lock:
|
||||
self.plugin_last_update[plugin_id] = scheduled_time
|
||||
self.state_manager.record_update(plugin_id)
|
||||
self.state_manager.set_state(plugin_id, PluginState.ENABLED)
|
||||
if self.health_tracker:
|
||||
self.health_tracker.record_success(plugin_id)
|
||||
else:
|
||||
self._record_update_failure(plugin_id, exc=exc)
|
||||
finally:
|
||||
if lock is not None:
|
||||
lock.release()
|
||||
with self._pending_lock:
|
||||
self._pending_updates.discard(plugin_id)
|
||||
|
||||
if lock is None:
|
||||
# Synchronous / no-lock path: unchanged behavior.
|
||||
try:
|
||||
if self.resource_monitor:
|
||||
def monitored_update():
|
||||
self.resource_monitor.monitor_call(plugin_id, plugin_instance.update)
|
||||
# SimpleNamespace stores `update` as an *instance*
|
||||
# attribute, so attribute lookup returns the plain
|
||||
# function object as-is. A dynamically-built class
|
||||
# (`type(..., {'update': monitored_update})`) instead
|
||||
# stores it as a *class* attribute, which the
|
||||
# descriptor protocol turns into a bound method on
|
||||
# access -- silently prepending the instance as an
|
||||
# implicit first argument to a function that takes
|
||||
# none, raising "monitored_update() takes 0
|
||||
# positional arguments but 1 was given" on every call.
|
||||
success = self.plugin_executor.execute_update(
|
||||
types.SimpleNamespace(update=monitored_update),
|
||||
plugin_id
|
||||
)
|
||||
else:
|
||||
success = self.plugin_executor.execute_update(plugin_instance, plugin_id)
|
||||
_finish(success)
|
||||
except Exception as exc: # pylint: disable=broad-except
|
||||
self.logger.exception("Error updating plugin %s: %s", plugin_id, exc)
|
||||
_finish(False, exc=exc)
|
||||
return
|
||||
|
||||
# Async worker path: the real update() call -- through the resource
|
||||
# monitor, if configured -- owns finishing the lock/lifecycle
|
||||
# bookkeeping, from whichever thread actually runs it to completion.
|
||||
def _target_update() -> None:
|
||||
try:
|
||||
if self.resource_monitor:
|
||||
self.resource_monitor.monitor_call(plugin_id, plugin_instance.update)
|
||||
else:
|
||||
plugin_instance.update()
|
||||
except Exception as exc:
|
||||
_finish(False, exc=exc)
|
||||
raise
|
||||
else:
|
||||
_finish(True)
|
||||
|
||||
try:
|
||||
self.plugin_executor.execute_update(
|
||||
types.SimpleNamespace(update=_target_update), plugin_id)
|
||||
except Exception as exc: # pragma: no cover - defensive; execute_update
|
||||
# catches everything internally, but guarantee _finish still
|
||||
# runs (releasing the lock) if something unexpected slips through.
|
||||
self.logger.exception("Unexpected error dispatching update for %s: %s", plugin_id, exc)
|
||||
_finish(False, exc=exc)
|
||||
|
||||
def run_scheduled_updates_with_changes(self, current_time: Optional[float] = None) -> List[str]:
|
||||
"""
|
||||
|
||||
@@ -0,0 +1,270 @@
|
||||
"""Tests for asynchronous plugin updates (plugin_manager background worker).
|
||||
|
||||
The invariants that keep this change safe:
|
||||
1. run_scheduled_updates returns immediately — a slow update() can never
|
||||
again freeze the render loop (the original defect: 30s scroll freezes).
|
||||
2. A plugin's update() and display() are NEVER concurrent — the per-plugin
|
||||
lock makes the old implicit no-overlap guarantee explicit, and it stays
|
||||
held through PluginExecutor's own timeout: a lingering, still-running
|
||||
update() keeps the lock even after PluginExecutor gives up waiting on it.
|
||||
3. Failure/timeout bookkeeping is unchanged (same executor, same
|
||||
_record_update_failure path, same last-update stamping).
|
||||
4. The kill switch (plugin_system.synchronous_updates) restores the
|
||||
inline path exactly.
|
||||
"""
|
||||
|
||||
import os
|
||||
import sys
|
||||
import threading
|
||||
import time
|
||||
|
||||
import pytest
|
||||
|
||||
sys.path.insert(0, os.path.join(os.path.dirname(__file__), ".."))
|
||||
|
||||
from src.plugin_system.plugin_manager import PluginManager # noqa: E402
|
||||
from src.plugin_system.plugin_state import PluginState # noqa: E402
|
||||
|
||||
|
||||
class SlowPlugin:
|
||||
"""Fake plugin whose update() sleeps and records overlap violations."""
|
||||
|
||||
def __init__(self, update_seconds=0.5):
|
||||
self.enabled = True
|
||||
self.update_seconds = update_seconds
|
||||
self.update_calls = 0
|
||||
self.display_calls = 0
|
||||
self.in_update = False
|
||||
self.overlap_detected = False
|
||||
|
||||
def update(self):
|
||||
self.in_update = True
|
||||
self.update_calls += 1
|
||||
time.sleep(self.update_seconds)
|
||||
self.in_update = False
|
||||
return True
|
||||
|
||||
def display(self, force_clear=False):
|
||||
if self.in_update:
|
||||
self.overlap_detected = True
|
||||
self.display_calls += 1
|
||||
return True
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def pm(tmp_path):
|
||||
manager = PluginManager(plugins_dir=str(tmp_path), config_manager=None,
|
||||
display_manager=None, cache_manager=None)
|
||||
yield manager
|
||||
manager.stop_update_worker()
|
||||
|
||||
|
||||
def _install(pm, plugin, plugin_id="slow-plugin"):
|
||||
pm.plugins[plugin_id] = plugin
|
||||
pm._update_interval_cache[plugin_id] = 0.01 # always due
|
||||
# load_plugin normally registers state; can_execute() gates on it
|
||||
pm.state_manager.set_state(plugin_id, PluginState.ENABLED)
|
||||
return plugin_id
|
||||
|
||||
|
||||
class TestSchedulerNonBlocking:
|
||||
def test_run_scheduled_updates_returns_immediately(self, pm):
|
||||
plugin_id = _install(pm, SlowPlugin(update_seconds=2.0))
|
||||
start = time.monotonic()
|
||||
pm.run_scheduled_updates()
|
||||
elapsed = time.monotonic() - start
|
||||
assert elapsed < 0.1, f"scheduler blocked for {elapsed:.2f}s"
|
||||
# the update actually runs in the background
|
||||
deadline = time.monotonic() + 5
|
||||
while pm.plugins[plugin_id].update_calls == 0 and time.monotonic() < deadline:
|
||||
time.sleep(0.05)
|
||||
assert pm.plugins[plugin_id].update_calls == 1
|
||||
|
||||
def test_no_double_enqueue_while_pending(self, pm):
|
||||
plugin_id = _install(pm, SlowPlugin(update_seconds=0.8))
|
||||
for _ in range(20):
|
||||
pm.run_scheduled_updates()
|
||||
time.sleep(0.01)
|
||||
time.sleep(1.5) # let the single queued update finish
|
||||
assert pm.plugins[plugin_id].update_calls == 1
|
||||
|
||||
|
||||
class TestUpdateDisplayExclusion:
|
||||
def test_display_lock_held_during_update(self, pm):
|
||||
plugin_id = _install(pm, SlowPlugin(update_seconds=0.6))
|
||||
pm.run_scheduled_updates()
|
||||
# give the worker a moment to take the lock and enter update()
|
||||
deadline = time.monotonic() + 2
|
||||
while not pm.plugins[plugin_id].in_update and time.monotonic() < deadline:
|
||||
time.sleep(0.01)
|
||||
lock = pm.get_plugin_lock(plugin_id)
|
||||
assert lock.acquire(blocking=False) is False, \
|
||||
"lock must be held while update() runs"
|
||||
# and released afterwards
|
||||
deadline = time.monotonic() + 3
|
||||
while pm.plugins[plugin_id].in_update and time.monotonic() < deadline:
|
||||
time.sleep(0.05)
|
||||
time.sleep(0.1)
|
||||
assert lock.acquire(blocking=False) is True
|
||||
lock.release()
|
||||
|
||||
def test_no_overlap_under_hammering_display_loop(self, pm):
|
||||
"""Simulate the render loop's try-lock display pattern at high rate
|
||||
while updates fire — the plugin itself asserts no overlap."""
|
||||
plugin = SlowPlugin(update_seconds=0.15)
|
||||
plugin_id = _install(pm, plugin)
|
||||
stop = threading.Event()
|
||||
|
||||
def render_loop():
|
||||
while not stop.is_set():
|
||||
lock = pm.get_plugin_lock(plugin_id)
|
||||
if lock.acquire(blocking=False):
|
||||
try:
|
||||
plugin.display()
|
||||
finally:
|
||||
lock.release()
|
||||
time.sleep(0.002)
|
||||
|
||||
renderer = threading.Thread(target=render_loop, daemon=True)
|
||||
renderer.start()
|
||||
try:
|
||||
for _ in range(6):
|
||||
pm.plugin_last_update.pop(plugin_id, None) # force due
|
||||
pm.run_scheduled_updates()
|
||||
time.sleep(0.3)
|
||||
finally:
|
||||
stop.set()
|
||||
renderer.join(timeout=2)
|
||||
assert plugin.update_calls >= 3
|
||||
assert plugin.display_calls > 10
|
||||
assert plugin.overlap_detected is False
|
||||
|
||||
def test_lock_held_through_timeout_until_real_update_finishes(self, pm):
|
||||
"""PluginExecutor's join(timeout) can return before the real
|
||||
update() call does -- the lingering daemon thread keeps running it.
|
||||
The plugin's lock must stay held for that whole real duration, not
|
||||
just PluginExecutor's bounded wait, or display() could run
|
||||
concurrently with a still-executing update()."""
|
||||
plugin = SlowPlugin(update_seconds=0.3)
|
||||
plugin_id = _install(pm, plugin)
|
||||
pm.plugin_executor.default_timeout = 0.05 # times out well before
|
||||
# update_seconds elapses
|
||||
|
||||
pm.run_scheduled_updates()
|
||||
|
||||
deadline = time.monotonic() + 2
|
||||
while not plugin.in_update and time.monotonic() < deadline:
|
||||
time.sleep(0.01)
|
||||
assert plugin.in_update is True
|
||||
|
||||
# PluginExecutor's own timeout has now elapsed, but the real
|
||||
# update() (0.3s) is still running in its lingering daemon thread.
|
||||
time.sleep(0.15)
|
||||
assert plugin.in_update is True, "test setup: update should still be running"
|
||||
lock = pm.get_plugin_lock(plugin_id)
|
||||
assert lock.acquire(blocking=False) is False, \
|
||||
"lock must stay held through PluginExecutor's timeout while the real update() runs"
|
||||
|
||||
# Once the real update() genuinely finishes, the lock is released.
|
||||
deadline = time.monotonic() + 2
|
||||
while plugin.in_update and time.monotonic() < deadline:
|
||||
time.sleep(0.02)
|
||||
time.sleep(0.1)
|
||||
assert lock.acquire(blocking=False) is True
|
||||
lock.release()
|
||||
|
||||
def test_state_returns_to_enabled_after_update(self, pm):
|
||||
"""RUNNING is set at enqueue (blocks re-entry via can_execute) and
|
||||
must return to an executable state once the update finishes."""
|
||||
plugin_id = _install(pm, SlowPlugin(update_seconds=0.1))
|
||||
pm.run_scheduled_updates()
|
||||
# while queued/running, re-entry is blocked
|
||||
assert pm.state_manager.can_execute(plugin_id) is False
|
||||
deadline = time.monotonic() + 3
|
||||
while time.monotonic() < deadline:
|
||||
if (pm.plugins[plugin_id].update_calls
|
||||
and pm.state_manager.can_execute(plugin_id)):
|
||||
break
|
||||
time.sleep(0.05)
|
||||
assert pm.plugins[plugin_id].update_calls == 1
|
||||
assert pm.state_manager.can_execute(plugin_id) is True
|
||||
|
||||
|
||||
class TestFailurePaths:
|
||||
def test_update_failure_routes_through_failure_bookkeeping(self, pm):
|
||||
class FailingPlugin(SlowPlugin):
|
||||
def update(self):
|
||||
self.update_calls += 1
|
||||
raise RuntimeError("boom")
|
||||
|
||||
plugin_id = _install(pm, FailingPlugin())
|
||||
pm.run_scheduled_updates()
|
||||
deadline = time.monotonic() + 3
|
||||
while pm.plugins[plugin_id].update_calls == 0 and time.monotonic() < deadline:
|
||||
time.sleep(0.05)
|
||||
time.sleep(0.2)
|
||||
# failure stamped so the interval gate holds (no hot retry loop)
|
||||
assert pm.plugin_last_update.get(plugin_id, 0) > 0
|
||||
# lock released after failure
|
||||
assert pm.get_plugin_lock(plugin_id).acquire(blocking=False) is True
|
||||
pm.get_plugin_lock(plugin_id).release()
|
||||
|
||||
def test_unloaded_while_queued_is_harmless(self, pm):
|
||||
"""Exercise the public unload_plugin() lifecycle rather than
|
||||
deleting pm.plugins directly: queue the target's update behind a
|
||||
deterministic blocker (occupying the single worker), unload the
|
||||
target while its item still sits queued, then release the blocker
|
||||
and confirm the target's update never ran and its state stayed
|
||||
unloaded rather than being resurrected to ENABLED."""
|
||||
blocker_event = threading.Event()
|
||||
|
||||
class BlockerPlugin(SlowPlugin):
|
||||
def update(self):
|
||||
self.update_calls += 1
|
||||
blocker_event.wait(timeout=5)
|
||||
return True
|
||||
|
||||
blocker_id = _install(pm, BlockerPlugin(), plugin_id="blocker-plugin")
|
||||
target = SlowPlugin(update_seconds=0.05)
|
||||
target_id = _install(pm, target, plugin_id="slow-plugin")
|
||||
|
||||
# Dispatch the blocker first so it occupies the single worker
|
||||
# thread, then enqueue the target behind it -- deterministically
|
||||
# queued, not yet started.
|
||||
pm._enqueue_update(blocker_id, time.time())
|
||||
deadline = time.monotonic() + 2
|
||||
while pm.plugins[blocker_id].update_calls == 0 and time.monotonic() < deadline:
|
||||
time.sleep(0.01)
|
||||
assert pm.plugins[blocker_id].update_calls == 1
|
||||
|
||||
pm._enqueue_update(target_id, time.time())
|
||||
assert target_id in pm._pending_updates
|
||||
|
||||
assert pm.unload_plugin(target_id) is True
|
||||
assert target_id not in pm.plugins
|
||||
|
||||
blocker_event.set() # let the blocker finish; worker moves on to
|
||||
# the target's queued item
|
||||
|
||||
deadline = time.monotonic() + 3
|
||||
while target_id in pm._pending_updates and time.monotonic() < deadline:
|
||||
time.sleep(0.02)
|
||||
|
||||
assert target.update_calls == 0, "update() must not run for an unloaded plugin"
|
||||
assert target_id not in pm._pending_updates
|
||||
assert pm.state_manager.get_state(target_id) == PluginState.UNLOADED
|
||||
|
||||
|
||||
class TestKillSwitch:
|
||||
def test_synchronous_mode_blocks_like_before(self, pm):
|
||||
pm._synchronous_updates = True
|
||||
plugin_id = _install(pm, SlowPlugin(update_seconds=0.4))
|
||||
start = time.monotonic()
|
||||
pm.run_scheduled_updates()
|
||||
elapsed = time.monotonic() - start
|
||||
assert elapsed >= 0.4, "synchronous mode must run inline"
|
||||
assert pm.plugins[plugin_id].update_calls == 1
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
sys.exit(pytest.main([__file__, "-v"]))
|
||||
@@ -123,6 +123,14 @@ class TestPluginManager:
|
||||
|
||||
pm.run_scheduled_updates(current_time=time.time())
|
||||
|
||||
# Updates now execute on the background worker (the scheduler
|
||||
# returns immediately) — wait for completion before asserting.
|
||||
deadline = time.time() + 5
|
||||
while (plugin_instance.update.call_count == 0
|
||||
and time.time() < deadline):
|
||||
time.sleep(0.02)
|
||||
pm.stop_update_worker()
|
||||
|
||||
plugin_instance.update.assert_called_once()
|
||||
assert "test_plugin" in pm.plugin_last_update
|
||||
assert pm.state_manager.get_state("test_plugin") == PluginState.ENABLED
|
||||
|
||||
Reference in New Issue
Block a user