From 8136a2d5258c1a41b94546d22690cd5e746f9a16 Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Fri, 2 Oct 2026 13:42:23 -0400 Subject: [PATCH] fix(ipc): a plugin reload no longer freezes the panel during Vegas (#723) A plugin.reload no longer freezes the panel during Vegas: the old instance is torn down and the new one loaded off the render thread (frame gap 3017 ms -> 9 ms in the ledpi reproduction). A failed or timed-out teardown stops the reload with a restart hint instead of loading over stale modules or tearing down an instance still in use. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 16 + docs/IPC_CONTROL_SOCKET.md | 34 +- src/display_controller.py | 233 ++++++-- src/plugin_system/plugin_manager.py | 74 ++- src/vegas_mode/plugin_adapter.py | 20 + src/vegas_mode/stream_manager.py | 7 +- test/_run_loop_harness.py | 21 + test/test_ipc_display_stage2.py | 22 +- test/test_plugin_reload_off_render_thread.py | 527 +++++++++++++++++++ 9 files changed, 905 insertions(+), 49 deletions(-) create mode 100644 test/test_plugin_reload_off_render_thread.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 29c9f698..5913a565 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -161,6 +161,22 @@ policies are unchanged. ### Fixes +- A plugin reload after a store update (`plugin.reload`, #720) no longer + freezes the panel during Vegas. On ledpi a football reload froze it for + 3.0 s (`Render stall over: no frame for 3043ms`). The reload ran on the + render thread, and its unload waited for the plugin's lock. The strip's + prefetch thread held that lock while it rebuilt the old instance's Vegas + content. The render thread now only takes the plugin out of the rotation + and out of the plugin manager (`PluginManager.detach_plugin`). A + `plugin-reload-` thread waits for the lock, tears the old instance + down and loads the new one, and the new instance joins the rotation + between two frames. In a test with a 3.0 s render holding the lock, the + longest gap between frames went from 3017 ms to 9 ms. The reply still + reports the real outcome, the modes keep their places in the rotation, + and Vegas fetches the plugin again. While it reloads, an on-demand request + for the plugin is refused (`plugin-reloading`), and a config reconcile + neither loads it twice nor unloads it mid-load. A Vegas fetch that waited + out a reload for the lock skips the old instance. - The schedule-off blank and the WiFi notice no longer start with a scroller's leftovers. Both are drawn by the display controller rather than dispatched to a plugin, so #716's handover never reached them: drawn while diff --git a/docs/IPC_CONTROL_SOCKET.md b/docs/IPC_CONTROL_SOCKET.md index a7ba8367..96919bc6 100644 --- a/docs/IPC_CONTROL_SOCKET.md +++ b/docs/IPC_CONTROL_SOCKET.md @@ -96,7 +96,8 @@ with its modes kept in their place in the rotation. Only a running plugin can be reloaded (`not_loaded` otherwise), so the id never makes the display import anything new. A plugin loaded only for an on-demand session gets `busy`. A new version that fails to load gets `failed` and stays out of the -rotation, as it would after a restart. +rotation, as it would after a restart. The load runs off the render thread, +so the panel keeps scrolling while it happens (see below). **Acknowledgements.** A queued on-demand command is *accepted*, not *done*. `{"accepted": true, "request_id": …}` means the command is waiting in the @@ -167,13 +168,33 @@ place it reads the mailbox: afterwards. - `brightness.set` is applied there and then (`_apply_control_brightness`), and the current frame is pushed again so the panel shows it. -- `plugin.reload` waits for the top of the next loop pass, the place where +- `plugin.reload` starts at the top of the next loop pass, the place where plugins are enabled and disabled live, because there no `display()` and no Vegas iteration is on the stack (`_apply_pending_plugin_reloads`). Until then the current screen ends early, as it does for a WiFi notice: the frame loops, the dwell and Vegas's interrupt check all treat a pending - reload as a reason to stop (`_screen_preempted`). The rotation then - advances, and the next pass reloads before it draws. + reload as a reason to stop (`_screen_preempted`). +- Only the quick half of the reload runs on the render thread + (`_start_plugin_reload`): the plugin's modes leave the rotation, its + config subscription is dropped, and `PluginManager.detach_plugin` takes + the instance out of `plugins`. After that nothing new calls the old + instance: no `update()`, and no Vegas fetch. The rotation then advances + (Vegas resumes its strip), and frames keep coming. +- The slow half runs on a `plugin-reload-` thread (`_PluginReloadJob`). + It waits for the plugin's lock, then tears the old instance down + (`unload_detached_plugin`) and loads the new one (`reload_plugin`). The + lock can be held for seconds by a Vegas render of the old instance. On + ledpi the render thread used to wait for it here, and a football reload + froze the panel for 3.0 s. +- The new instance joins the rotation between two frames + (`_finish_plugin_reloads`, from `_service_pending_changes` or the top of + the loop). Its modes go back to their old places, Vegas is told to fetch + it again, and the command is answered. +- While the plugin reloads, it is out of the rotation. Vegas scrolls what + its strip already holds of it. An on-demand request for it gets + `plugin-reloading`. A config reconcile neither loads it a second time nor + unloads it mid-load; a disable saved meanwhile is applied once the + reload is done. A second reload of the same plugin runs after the first. The 0.25 s floor on the mailbox read does not apply to the queue, because draining it costs no disk read. A queued command also lets @@ -204,7 +225,10 @@ Now the queue wakes the render thread: So a command lands within a millisecond or so on a static screen and in a dwell, and within one frame in Vegas and on a scrolling screen. The mailbox keeps its old delays. Commands still run only on the render thread: the -connection threads only queue them and set the event. +connection threads only queue them and set the event. The one exception is +the slow half of `plugin.reload` (tearing down and loading the plugin), +which runs on its own thread. Every change to the display's state still +happens on the render thread. The waits are timed `Event.wait()` calls: no polling, and no more wake-ups than the sleeps they replace when nothing arrives. Measured under WSL diff --git a/src/display_controller.py b/src/display_controller.py index e1173a0f..d160398f 100644 --- a/src/display_controller.py +++ b/src/display_controller.py @@ -78,6 +78,57 @@ _MIN_INITIAL_UPDATE_TIMEOUT_SECONDS = 2.0 DEFAULT_DYNAMIC_DURATION_CAP = 180.0 + +class _PluginReloadJob: + """A ``plugin.reload`` whose slow half runs off the render thread. + + The render thread takes the plugin out of the rotation and out of the + plugin manager (DisplayController._start_plugin_reload); then this job, + on its own thread, tears the old instance down and loads the new one + (run()). Tearing down waits for the plugin's lock, which a Vegas content + render of the old instance can hold for seconds. Done on the render + thread, that wait froze the panel (3.0 s on ledpi). The render thread + puts the new instance in the rotation once ``done`` is set + (DisplayController._finish_plugin_reloads). + """ + + def __init__(self, command: QueuedCommand, plugin_id: str, + previous_order: Dict[str, int], old_instance: Any) -> None: + self.command = command + self.plugin_id = plugin_id + #: Each mode's place in available_modes before the reload. + self.previous_order = previous_order + self.old_instance = old_instance + self.done = threading.Event() + self.loaded = False + #: The old instance's teardown failed, so its modules may still be in + #: sys.modules and a load now could quietly reuse the old code. + self.unload_failed = False + self.error: Optional[Exception] = None + #: Reloads of the same plugin asked for while this one ran. They + #: start once it is done, so they load the files as they are then. + self.followers: List[QueuedCommand] = [] + + def run(self, plugin_manager: Any) -> None: + """Tear down the old instance, then load the plugin again. Never raises.""" + try: + if self.old_instance is not None: + if not plugin_manager.unload_detached_plugin(self.plugin_id, self.old_instance): + # Loading now could reuse the old plugin_ module and + # report a reload that never happened (the synchronous + # path refused this too: reload_plugin stops when + # unload_plugin fails). + self.old_instance = None + self.unload_failed = True + return + self.old_instance = None + self.loaded = bool(plugin_manager.reload_plugin(self.plugin_id)) + except Exception as exc: # pylint: disable=broad-except + self.error = exc + finally: + self.done.set() + + # Follower dead reckoning (the follower branch of DisplayController.run()). # A leader position further off than this fraction of the strip is a cycle # reset, and is snapped to rather than corrected toward. @@ -726,7 +777,8 @@ class DisplayController: if self._check_wifi_status_message(): return True - # A plugin reload waits for the top of the loop, outside the iteration. + # A plugin reload starts at the top of the loop, outside the + # iteration; the iteration then resumes while it loads. if self._plugin_reload_pending: return True @@ -1520,6 +1572,10 @@ class DisplayController: self._last_pending_service = now try: + # A reloaded plugin rejoins the rotation as soon as it has + # loaded, between two frames of the screen or Vegas strip that + # carried on while it loaded. + self._finish_plugin_reloads() self._poll_on_demand_requests() self._check_on_demand_expiration() self._evaluate_schedule() @@ -1790,35 +1846,71 @@ class DisplayController: #: Plugin reloads from the control socket, waiting for the top of the #: next loop pass. A tuple, replaced rather than mutated. _pending_plugin_reloads: Tuple[QueuedCommand, ...] = () + #: Reloads started and not finished yet. Their plugin is out of the + #: rotation while a plugin-reload thread loads it again. A tuple, + #: replaced rather than mutated, so the config watcher can read it. + _plugin_reload_jobs: Tuple[_PluginReloadJob, ...] = () + #: A reconcile skipped a plugin that was reloading: run one again once + #: the reloads are done. + _reconcile_after_reload = False @property def _plugin_reload_pending(self) -> bool: + """A reload is waiting for the top of the loop, so the screen ends early. + + Only the start of a reload waits there. The load runs on another + thread while the screens carry on, and the new instance joins the + rotation between two frames (_finish_plugin_reloads). + """ return bool(self._pending_plugin_reloads) - def _apply_pending_plugin_reloads(self) -> None: - """Reload the plugins the control socket asked for. Render thread, - top of the loop pass: no display() and no Vegas iteration on the stack. + def _plugin_reloading(self, plugin_id: Optional[str]) -> bool: + """``plugin_id`` is out of the rotation while it is loaded again.""" + return any(job.plugin_id == plugin_id for job in self._plugin_reload_jobs) - The same steps as disabling and re-enabling the plugin live - (_unregister_plugin, then load and _register_loaded_plugin), with the + def _apply_pending_plugin_reloads(self) -> None: + """Start the plugin reloads the control socket asked for. Render + thread, top of the loop pass: no display() and no Vegas iteration on + the stack. + + The same steps as disabling and re-enabling the plugin live, with the manifest re-read from disk, so the running set ends up as a restart - would build it. A plugin that fails to load stays out of the - rotation, as it would after a restart. + would build it. Only taking the plugin out happens here. The old + instance is torn down and the new one loaded on a plugin-reload + thread, so the screens carry on meanwhile (_start_plugin_reload). + Reloads that have finished are put back in the rotation first. """ + self._finish_plugin_reloads() commands, self._pending_plugin_reloads = self._pending_plugin_reloads, () for command in commands: try: - self._reload_plugin_for_command(command) + self._start_plugin_reload(command) except Exception: # pylint: disable=broad-except logger.exception("Plugin reload over the control socket failed") command.fail(ControlErrorCode.INTERNAL, 'the display failed to reload it') - def _reload_plugin_for_command(self, command: QueuedCommand) -> None: + def _start_plugin_reload(self, command: QueuedCommand) -> None: + """Take the plugin out of the rotation and start loading it again. + + Render thread. Everything here is quick: the controller's maps, the + config subscription, and PluginManager.detach_plugin, after which + nothing new calls the old instance (no update(), no Vegas fetch). + The slow part runs on a plugin-reload thread: waiting for a Vegas + render or an update() of the old instance to let go of its lock, the + teardown, and the import and constructor of the new one. Meanwhile + Vegas scrolls what its strip already holds of the plugin. + """ args = command.args if not isinstance(args, PluginReloadArgs): command.fail(ControlErrorCode.INTERNAL, 'not a reload command') return plugin_id = args.plugin_id + for job in self._plugin_reload_jobs: + if job.plugin_id == plugin_id: + # Updated again while loading: reload once more when this + # one is done, so the newest files are the ones that run. + job.followers.append(command) + return if self.plugin_manager is None or plugin_id not in self.plugin_display_modes: command.fail(ControlErrorCode.NOT_LOADED, f'{plugin_id} is not running') return @@ -1832,23 +1924,80 @@ class DisplayController: previous_mode = self.current_display_mode previous_order = {mode: i for i, mode in enumerate(self.available_modes)} logger.info("Reloading plugin %s over the control socket", plugin_id) - self._unregister_plugin(plugin_id, action='Unloaded') - loaded = bool(self.plugin_manager.reload_plugin(plugin_id)) - modes: List[str] = [] - if loaded: - modes = list(self._register_loaded_plugin(plugin_id)) - # Registering appends; put its modes back where they were in the - # rotation (a mode the new version added goes last). - self.available_modes.sort( - key=lambda mode: previous_order.get(mode, len(previous_order))) + self._unregister_plugin(plugin_id, action='Reloading', unload=False) + old_instance = self.plugin_manager.detach_plugin(plugin_id) + job = _PluginReloadJob(command, plugin_id, previous_order, old_instance) + self._plugin_reload_jobs = self._plugin_reload_jobs + (job,) + self._resync_mode_index_after_change(previous_mode) + self._spawn_plugin_reload(job) + + def _spawn_plugin_reload(self, job: _PluginReloadJob) -> None: + """Run ``job`` on its own thread. The run-loop harness replaces this + to run it on its fake clock.""" + threading.Thread(target=job.run, args=(self.plugin_manager,), daemon=True, + name=f'plugin-reload-{job.plugin_id}').start() + + def _finish_plugin_reloads(self) -> None: + """Put the plugins whose reload has finished back in the rotation. + + Render thread: the top of the loop and _service_pending_changes, so + a new instance joins between two frames of whatever is showing. That + is never the plugin itself, which left the rotation when its reload + started. Its modes go back to their old places in the rotation, the + current screen stays current, Vegas fetches its content again, and + the command is answered with the outcome. + """ + jobs = self._plugin_reload_jobs + if not jobs: + return + finished = tuple(job for job in jobs if job.done.is_set()) + if not finished: + return + self._plugin_reload_jobs = tuple(job for job in jobs if job not in finished) + previous_mode = self.current_display_mode + for job in finished: + try: + self._finish_plugin_reload(job) + except Exception: # pylint: disable=broad-except + logger.exception("Plugin reload over the control socket failed") + job.command.fail(ControlErrorCode.INTERNAL, 'the display failed to reload it') + if job.followers: + self._pending_plugin_reloads = self._pending_plugin_reloads + tuple(job.followers) self._apply_plugin_rotation_order() self._resync_mode_index_after_change(previous_mode) - if not loaded: + if self._reconcile_after_reload and not self._plugin_reload_jobs: + self._reconcile_after_reload = False + with self._reconcile_flag_lock: + self._pending_plugin_reconcile = True + + def _finish_plugin_reload(self, job: _PluginReloadJob) -> None: + plugin_id = job.plugin_id + command = job.command + if job.error is not None: + logger.error("Plugin reload over the control socket failed", + exc_info=(type(job.error), job.error, job.error.__traceback__)) + command.fail(ControlErrorCode.INTERNAL, 'the display failed to reload it') + return + if job.unload_failed: + logger.error("Plugin %s: the old instance could not be unloaded, so the " + "update was not loaded; it is out of the rotation until the " + "display restarts", plugin_id) + command.fail(ControlErrorCode.FAILED, + f'{plugin_id}: the old version could not be unloaded; ' + f'restart the display to load the update') + return + if not job.loaded: logger.error("Plugin %s did not load after its update; it is out of the " "rotation until it loads", plugin_id) command.fail(ControlErrorCode.FAILED, f'{plugin_id} did not load; see the display log') return + modes = list(self._register_loaded_plugin(plugin_id)) + # Registering appends; put its modes back where they were in the + # rotation (a mode the new version added goes last). + previous_order = job.previous_order + self.available_modes.sort( + key=lambda mode: previous_order.get(mode, len(previous_order))) vegas = getattr(self, 'vegas_coordinator', None) if vegas is not None: try: @@ -2215,6 +2364,13 @@ class DisplayController: """Activate on-demand mode for a specific plugin display.""" plugin_id = request.get('plugin_id') mode = request.get('mode') + if plugin_id and self._plugin_reloading(plugin_id): + # Out of the rotation for a moment while a store update loads it + # again; loading it for on-demand now would load it twice. + logger.warning("On-demand: plugin '%s' is reloading; try again in a moment", + plugin_id) + self._set_on_demand_error("plugin-reloading") + return if (plugin_id and plugin_id not in self.plugin_display_modes and not self._load_plugin_for_on_demand(plugin_id)): return @@ -3287,9 +3443,11 @@ class DisplayController: self._service_pending_reconcile() # Plugin reloads from the control socket (a store update), - # here for the same reason: nothing of the plugin's is on the - # stack. The screen that was showing ended early for them. - if self._pending_plugin_reloads: + # started here for the same reason: nothing of the plugin's + # is on the stack. The screen that was showing ended early + # for them. Reloads that have finished loading join the + # rotation here too, if no frame got to them first. + if self._pending_plugin_reloads or self._plugin_reload_jobs: self._apply_pending_plugin_reloads() if not self.available_modes: @@ -4017,10 +4175,13 @@ class DisplayController: self._plugin_accepts_display_mode.pop(plugin_id, None) return display_modes - def _unregister_plugin(self, plugin_id: str, action: str = 'Disabled') -> None: + def _unregister_plugin(self, plugin_id: str, action: str = 'Disabled', + unload: bool = True) -> None: """Remove a plugin's modes, config subscription and instance, then unload it. Used by live disable hot-reload, and by a reload - (``action`` names which in the log line).""" + (``action`` names which in the log line), which passes + ``unload=False``: it hands the instance to its plugin-reload thread + to unload instead (_start_plugin_reload).""" with self._plugin_modes_lock: modes = self.plugin_display_modes.pop(plugin_id, []) for mode in modes: @@ -4047,10 +4208,11 @@ class DisplayController: self._plugin_accepts_display_mode.pop(plugin_id, None) # Tear down the instance (cleanup + on_disable + module unload). - try: - self.plugin_manager.unload_plugin(plugin_id) - except Exception as e: - logger.error("Error unloading plugin %s: %s", plugin_id, e, exc_info=True) + if unload: + try: + self.plugin_manager.unload_plugin(plugin_id) + except Exception as e: + logger.error("Error unloading plugin %s: %s", plugin_id, e, exc_info=True) logger.info("%s plugin %s live (removed modes: %s)", action, plugin_id, modes) @@ -4122,6 +4284,8 @@ class DisplayController: known = set(getattr(self.plugin_manager, 'plugin_manifests', ()) or ()) with self._plugin_modes_lock: running = set(self.plugin_display_modes) + # Out of plugin_display_modes only while a reload loads it again. + running.update(job.plugin_id for job in self._plugin_reload_jobs) for key, value in new_config.items(): if (key in known and isinstance(value, dict) and value.get('enabled', False) and key not in running): @@ -4160,9 +4324,18 @@ class DisplayController: p for p in discovered if isinstance(config.get(p), dict) and config.get(p, {}).get('enabled', False) } - current = set(self.plugin_display_modes.keys()) + # A plugin being reloaded counts as running, so it is not loaded a + # second time beside its plugin-reload thread. One disabled during + # its reload is unloaded by a reconcile run after the reload is done. + reloading = {job.plugin_id for job in self._plugin_reload_jobs} + current = set(self.plugin_display_modes.keys()) | reloading to_add = desired - current to_remove = current - desired + if to_remove & reloading: + logger.info("Plugin reconcile: %s will be unloaded after its reload", + sorted(to_remove & reloading)) + self._reconcile_after_reload = True + to_remove -= reloading if not to_add and not to_remove: return True diff --git a/src/plugin_system/plugin_manager.py b/src/plugin_system/plugin_manager.py index 25b9b8f5..79d689b3 100644 --- a/src/plugin_system/plugin_manager.py +++ b/src/plugin_system/plugin_manager.py @@ -70,6 +70,14 @@ class PluginManager: # before tearing the instance down anyway. UNLOAD_LOCK_TIMEOUT = 5.0 + # How long unload_detached_plugin() (a live reload, off the render thread) + # waits for the old instance's lock. Longer than UNLOAD_LOCK_TIMEOUT + # because nothing is blocked by the wait, and a Vegas content build of the + # old instance can hold the lock for several seconds (5.9 s seen on + # ledpi). Past it the reload is refused rather than tearing down an + # instance a Vegas call may still be running in. + DETACHED_UNLOAD_LOCK_TIMEOUT = 30.0 + # How long the update worker and apply_config_change() wait for a # plugin's lock -- the same bound unload already uses for the same lock. # A display() frame holds it for milliseconds, so this only runs out when @@ -151,7 +159,9 @@ class PluginManager: # # Which thread runs each plugin hook, and what it holds: # __init__, on_enable the loading thread (main thread at startup, - # the render thread on a live enable). + # the render thread on a live enable, a + # plugin-reload thread for a control socket + # reload). # update() plugin-update-worker, under the plugin lock, # via PluginExecutor (whose daemon thread runs # the call; if it outlives the executor's @@ -170,8 +180,10 @@ class PluginManager: # plugin lock via apply_config_change(); if the # lock stays busy it is deferred to the update # worker, which applies it under the lock. - # cleanup(), on_disable() whoever calls unload_plugin(), under the - # lock with UNLOAD_LOCK_TIMEOUT. + # cleanup(), on_disable() whoever calls unload_plugin() (or, for a + # reload, unload_detached_plugin() on its + # plugin-reload thread), under the lock with + # UNLOAD_LOCK_TIMEOUT. # No wait on a plugin lock is unbounded, so one hung plugin can only # cost the worker PLUGIN_LOCK_TIMEOUT per attempt. self._update_queue: "queue.Queue[Union[None, Tuple[str, float], _DeferredConfigChange]]" = queue.Queue() @@ -752,14 +764,57 @@ class PluginManager: if lock_acquired: lock.release() - def _unload_plugin_locked(self, plugin_id: str) -> bool: - """Body of unload_plugin(); caller holds (or gave up on) the plugin lock.""" - if plugin_id not in self.plugins: # unloaded while we waited + def detach_plugin(self, plugin_id: str) -> Optional[Any]: + """Take a loaded plugin out of ``plugins`` without tearing it down. + + The first half of a reload that must not block its caller, the render + thread (DisplayController._start_plugin_reload). Every new call into a + plugin starts by looking it up in ``plugins``: the update scheduler, + the update worker (which looks again under the plugin's lock) and + Vegas's fetches. So once detached, nothing new reaches the instance. + Work already running on it under its lock -- an update(), or a Vegas + content render that can take seconds -- carries on; + unload_detached_plugin() waits for it, on another thread. + + Returns the instance, or None when the plugin was not loaded. + """ + return self.plugins.pop(plugin_id, None) + + def unload_detached_plugin(self, plugin_id: str, plugin: Any) -> bool: + """Tear down an instance taken out by detach_plugin(): unload_plugin() + for an instance that is no longer in ``plugins``. + + Waits for the plugin's lock, bounded by DETACHED_UNLOAD_LOCK_TIMEOUT, + so it belongs off the render thread. Call it before loading the plugin + again: it drops the plugin's modules and lifecycle state along with the + instance. Unlike unload_plugin() it never tears down without the lock: + a call that took the lock before the detach (a Vegas content build) + may still be running in this instance. Returns False then, and the + caller must not load the plugin again over it. + """ + lock = self.get_plugin_lock(plugin_id) + if not lock.acquire(timeout=self.DETACHED_UNLOAD_LOCK_TIMEOUT): + self.logger.warning( + "Plugin %s still busy after %.1fs; not unloading it while in use", + plugin_id, self.DETACHED_UNLOAD_LOCK_TIMEOUT) + return False + try: + return self._unload_plugin_locked(plugin_id, plugin) + finally: + lock.release() + + def _unload_plugin_locked(self, plugin_id: str, detached: Optional[Any] = None) -> bool: + """Body of unload_plugin(); caller holds (or gave up on) the plugin lock. + + ``detached`` is an instance already taken out of ``plugins`` + (detach_plugin); without it, the loaded instance is unloaded. + """ + if detached is None and plugin_id not in self.plugins: # unloaded while we waited self.logger.warning("Plugin %s not loaded", plugin_id) return False try: - plugin = self.plugins[plugin_id] + plugin = self.plugins[plugin_id] if detached is None else detached # Call cleanup if available if hasattr(plugin, 'cleanup'): @@ -775,8 +830,9 @@ class PluginManager: except Exception as e: self.logger.warning("Error during plugin on_disable: %s", e) - # Remove from active plugins - del self.plugins[plugin_id] + # Remove from active plugins (a detached one already is) + if detached is None: + del self.plugins[plugin_id] with self._deferred_config_lock: self._deferred_config_changes.pop(plugin_id, None) with self._plugin_last_update_lock: diff --git a/src/vegas_mode/plugin_adapter.py b/src/vegas_mode/plugin_adapter.py index 3e51c208..3ebffdda 100644 --- a/src/vegas_mode/plugin_adapter.py +++ b/src/vegas_mode/plugin_adapter.py @@ -183,9 +183,27 @@ class PluginAdapter: "round", plugin_id, self.PLUGIN_LOCK_TIMEOUT ) return None + if not self._still_loaded(plugin, plugin_id): + return None return self._fetch_content(plugin, plugin_id, restricted=False, keyed=keyed) + def _still_loaded(self, plugin: 'BasePlugin', plugin_id: str) -> bool: + """Whether ``plugin`` is still the loaded instance of ``plugin_id``. + + Checked once the plugin's lock is held: a reload or a disable can + take the instance out and tear it down while this fetch waited for + the lock (PluginManager.detach_plugin), and a torn-down instance is + not asked for content. True when the manager keeps no ``plugins`` + mapping to ask. + """ + plugins = getattr(self.plugin_manager, 'plugins', None) + if not isinstance(plugins, dict) or plugins.get(plugin_id) is plugin: + return True + logger.debug("[%s] Unloaded or reloaded while waiting for its lock; " + "skipping the old instance", plugin_id) + return False + def is_live_capable(self, plugin: 'BasePlugin', plugin_id: str) -> bool: """Whether to ask this plugin for live elements rather than pictures. @@ -922,6 +940,8 @@ class PluginAdapter: return None epochs = self.live_epochs epoch = epochs.get(plugin_id) if epochs is not None else 0 + if not self._still_loaded(plugin, plugin_id): + return epoch, {} render_width = self.resolve_render_width(plugin, plugin_id) plugin._vegas_render_width = render_width try: diff --git a/src/vegas_mode/stream_manager.py b/src/vegas_mode/stream_manager.py index aa7b2978..46f9de16 100644 --- a/src/vegas_mode/stream_manager.py +++ b/src/vegas_mode/stream_manager.py @@ -333,8 +333,11 @@ class StreamManager: loaded = 0 if hasattr(self.plugin_manager, 'plugins'): - loaded = len(self.plugin_manager.plugins) - for plugin_id, plugin in self.plugin_manager.plugins.items(): + # A snapshot: a plugin reload adds and removes entries on its + # own thread (DisplayController._start_plugin_reload). + plugins = list(self.plugin_manager.plugins.items()) + loaded = len(plugins) + for plugin_id, plugin in plugins: if not getattr(plugin, 'enabled', False): logger.debug("[%s] Vegas: skipped (not enabled)", plugin_id) continue diff --git a/test/_run_loop_harness.py b/test/_run_loop_harness.py index 2e7f63d5..6d866760 100644 --- a/test/_run_loop_harness.py +++ b/test/_run_loop_harness.py @@ -258,6 +258,15 @@ class FakePluginManager: self.plugins.pop(plugin_id, None) return True + def detach_plugin(self, plugin_id): + return self.plugins.pop(plugin_id, None) + + def unload_detached_plugin(self, plugin_id, plugin): + return True + + def reload_plugin(self, plugin_id): + return False + def get_plugin_lock(self, plugin_id): if plugin_id in self.no_lock: return None # as when loading failed part-way @@ -549,7 +558,19 @@ class RunLoopHarness: self.sync = FakeSync(self) self.dm = self._display_manager() self._displayed_this_pass = False + #: How long a plugin reload's own thread takes, on the fake clock. + self.reload_seconds = 0.0 self.controller = self._build() + self.controller._spawn_plugin_reload = self._spawn_plugin_reload + + def _spawn_plugin_reload(self, job) -> None: + """The plugin-reload thread, on the fake clock: the job runs + ``reload_seconds`` after it was started, meanwhile the render thread + carries on (at once when that is 0).""" + if self.reload_seconds <= 0: + job.run(self.pm) + else: + self.clock.at(self.clock.rel() + self.reload_seconds, lambda: job.run(self.pm)) # -- event log ----------------------------------------------------------- def log(self, kind: str, subject: Any = None, quiet: bool = False, **data): diff --git a/test/test_ipc_display_stage2.py b/test/test_ipc_display_stage2.py index 33c7be84..97a59416 100644 --- a/test/test_ipc_display_stage2.py +++ b/test/test_ipc_display_stage2.py @@ -4,8 +4,10 @@ and answered with what the panel shows -- including when the dim schedule holds it lower, when the panel refuses it, and when the schedule has the display off; -* ``plugin.reload`` is answered from the top of the loop pass, for every - outcome: reloaded (new instance registered, Vegas told), not running, +* ``plugin.reload`` starts at the top of the loop pass and is answered once + its plugin-reload thread is done (test_plugin_reload_off_render_thread.py + has the timing), for every outcome: reloaded (new instance registered, + Vegas told), not running, loaded only for on-demand, failed to load, or raised; * the render thread wakes for a command in real time, not just on the fake clock (test_run_loop_socket_wake.py): within milliseconds on a static @@ -141,7 +143,17 @@ def running(dc): pm.plugin_manifests[pid] = {'version': '2.0.0'} return True + def detach(pid): + return pm.plugins.pop(pid, None) + + def unload_detached(pid, plugin): + calls.append(('unload', pid)) + assert pid not in pm.plugins, "torn down while still loaded" + return True + pm.unload_plugin = MagicMock(side_effect=unload) + pm.detach_plugin = MagicMock(side_effect=detach) + pm.unload_detached_plugin = MagicMock(side_effect=unload_detached) pm.reload_plugin = MagicMock(side_effect=reload) dc.plugin_manager = pm dc.plugin_display_modes = {'clock': ['clock_a', 'clock_b'], 'weather': ['weather']} @@ -159,8 +171,12 @@ class TestReload: dc._control_server = FakeServer(*commands) dc._poll_on_demand_requests() # the drain: queued, not applied assert dc._plugin_reload_pending - dc._apply_pending_plugin_reloads() # the top of the next pass + dc._apply_pending_plugin_reloads() # the top of the next pass: it starts assert not dc._plugin_reload_pending + for job in dc._plugin_reload_jobs: # its plugin-reload thread + assert job.done.wait(5) + dc._finish_plugin_reloads() # between two frames + assert not dc._plugin_reload_jobs def test_reloaded(self, running): dc = running.dc diff --git a/test/test_plugin_reload_off_render_thread.py b/test/test_plugin_reload_off_render_thread.py new file mode 100644 index 00000000..b5895c17 --- /dev/null +++ b/test/test_plugin_reload_off_render_thread.py @@ -0,0 +1,527 @@ +"""A ``plugin.reload`` never stalls the render thread (#720 follow-up). + +On ledpi a reload of football-scoreboard (a store update, 3.17.0 to 3.18.1) +arrived while Vegas mode was running, and the panel froze for 3.0 s +("Render stall over: no frame for 3043ms"). Vegas yielded at once, but the +reload ran on the render thread, and its first step, unload_plugin(), waited +for the plugin's lock. The strip's prefetch thread held that lock: it was +rebuilding the old instance's Vegas content, which takes seconds for a +scoreboard. The new instance was then loaded on the render thread too +(0.47 s on ledpi). + +Now the render thread only takes the plugin out of the rotation and out of +the plugin manager (detach_plugin), and a plugin-reload thread waits for the +lock, tears the old instance down and loads the new one. The new instance +joins the rotation between two frames. + +* Real threads, real PluginManager and PluginAdapter: frames keep coming + (no gap over 100 ms) while a slow Vegas render holds the old instance's + lock, and the reload still reports the real outcome. Before the fix the + gap was the whole render. +* The fake-clock run loop (test/_run_loop_harness.py): Vegas frames flow + through a reload whose thread takes 3 s, the ticker never leaves, and + the reload is answered when the new instance joins. +* Thread safety: the old instance is torn down only after its render let + go of the lock, is never asked for content again, and never gets an + update() once the reload starts; the new one is loaded once. +* The other reload cases still answer as before: a plugin that is on + screen, one that is not, one that fails to load, and a second reload of + a plugin that is still loading. +""" + +import json +import os +import threading +import time +from types import SimpleNamespace +from unittest.mock import MagicMock + +import pytest +from PIL import Image + +os.environ.setdefault("EMULATOR", "true") + +from src.ipc.contract import Command, ErrorCode, PluginReloadArgs # noqa: E402 +from src.ipc.server import CommandOutcome, QueuedCommand # noqa: E402 +from src.plugin_system.base_plugin import BasePlugin # noqa: E402 +from src.plugin_system.plugin_manager import PluginManager # noqa: E402 +from src.vegas_mode.config import VegasModeConfig # noqa: E402 +from src.vegas_mode.plugin_adapter import PluginAdapter # noqa: E402 +from test._run_loop_harness import FakePlugin, RunLoopHarness # noqa: E402 +from test.test_vegas_elements_api import _DM # noqa: E402 + +#: How long the old instance's Vegas render holds its lock. ledpi's was 3 s +#: (scripts in the PR body measure that); the gap scales with it. +RENDER_SECONDS = 1.5 +FRAME = 0.008 +#: "A frame or two", with room for a slow CI runner. +MAX_GAP = 0.1 + + +def _reload(plugin_id, request_id="r1"): + return QueuedCommand(request_id=request_id, cmd=Command.PLUGIN_RELOAD, + args=PluginReloadArgs(plugin_id), received_at=time.time(), + outcome=CommandOutcome()) + + +class _Server: + """The ControlServer surface the controller drains.""" + + def __init__(self): + self.commands = [] + + @property + def has_pending(self): + return bool(self.commands) + + def drain(self): + out, self.commands = self.commands, [] + return out + + def close(self): + pass + + +class _Rig: + """A real PluginManager running one slow-rendering plugin, 'slow'.""" + + def __init__(self, tmp_path, render_seconds): + self.events = [] + self.lock = threading.Lock() + self.render_started = threading.Event() + self.render_seconds = render_seconds + self.generation = 0 + rig = self + + class SlowVegas(BasePlugin): + """Draws its Vegas content slowly, as a scoreboard does on a Pi.""" + + def __init__(self, generation): # pylint: disable=super-init-not-called + self.plugin_id = "slow" + self.config = {"enabled": True} + self.enabled = True + self.modes = ["slow"] + self.plugin_manager = None + self.generation = generation + + def get_update_interval(self): + return 0.05 + + def update(self): + rig.log("update", self.generation) + + def display(self, force_clear=False): + pass + + def validate_config(self): + return True + + def get_vegas_content(self): + rig.log("render-start", self.generation) + rig.render_started.set() + time.sleep(rig.render_seconds if self.generation == 1 else 0) + rig.log("render-end", self.generation) + return [Image.new("RGB", (64, 16), (255, 0, 0))] + + def cleanup(self): + rig.log("cleanup", self.generation) + + def on_enable(self): + pass + + def on_disable(self): + pass + + def construct(**_kw): + rig.generation += 1 + return SlowVegas(rig.generation), None + + plugin_dir = tmp_path / "plugins" / "slow" + plugin_dir.mkdir(parents=True) + self.manifest_path = plugin_dir / "manifest.json" + manifest = {"id": "slow", "version": "1.0.0", "display_modes": ["slow"]} + self.manifest_path.write_text(json.dumps(manifest)) + pm = PluginManager(plugins_dir=str(tmp_path / "plugins")) + pm.plugin_manifests["slow"] = manifest + pm.schema_manager = MagicMock() + pm.schema_manager.get_schema_path.return_value = None + pm.schema_manager.prepare_plugin_config.side_effect = ( + lambda pid, cfg, schema=None, changed_paths=None: cfg) + pm.plugin_loader = MagicMock() + pm.plugin_loader.find_plugin_directory.return_value = plugin_dir + pm.plugin_loader.load_plugin.side_effect = construct + assert pm.load_plugin("slow") + self.pm = pm + self.adapter = PluginAdapter(_DM(), VegasModeConfig(), plugin_manager=pm) + self.prefetched = [] + + def log(self, kind, generation): + with self.lock: + self.events.append((kind, generation)) + + def index(self, kind, generation): + return self.events.index((kind, generation)) + + def start_vegas_render(self): + """The strip's prefetch thread rebuilding the old instance's content.""" + plugin = self.pm.plugins["slow"] + + def fetch(): + self.prefetched.append(self.adapter.get_content(plugin, "slow", offscreen_only=True)) + thread = threading.Thread(target=fetch, name="vegas-strip-prefetch", daemon=True) + thread.start() + assert self.render_started.wait(2) + return thread + + +@pytest.fixture +def dc(test_display_controller): + c = test_display_controller + c.display_manager.set_brightness = MagicMock(return_value=True) + c.display_manager.update_display = MagicMock() + c.config = {"timezone": "UTC", "display": {"hardware": {"brightness": 90}}} + c._normal_brightness = 90 + c.current_brightness = 90 + c.is_display_active = True + c._tz = None + c.vegas_coordinator = MagicMock() + return c + + +def _with_rig(dc, tmp_path, render_seconds=None): + rig = _Rig(tmp_path, RENDER_SECONDS if render_seconds is None else render_seconds) + clock = SimpleNamespace(modes=["clock"]) + dc.plugin_manager = rig.pm + dc.plugin_display_modes = {"clock": ["clock"]} + dc.available_modes = ["clock"] + dc.plugin_modes = {"clock": clock} + dc.mode_to_plugin_id = {"clock": "clock"} + dc._register_loaded_plugin("slow") + dc.current_mode_index = 0 + dc.current_display_mode = "clock" + dc._control_server = _Server() + return rig + + +def _render_frames(dc, rig, until, limit): + """What the render thread does while Vegas runs: one frame every 8 ms, + servicing pending changes between frames (Vegas's interrupt check) and, + when a screen-ending command is pending, the top of the loop pass. + Returns the frame times.""" + frames = [time.perf_counter()] + deadline = frames[0] + limit + while not until(): + dc._service_pending_changes() + if dc._plugin_reload_pending: + dc._apply_pending_plugin_reloads() # Vegas yields; resumes next pass + if len(frames) % 5 == 0: + rig.pm.run_scheduled_updates() # the update tick + time.sleep(FRAME) + frames.append(time.perf_counter()) + assert frames[-1] < deadline, "the reload never finished" + return frames + + +def _max_gap(frames): + return max(b - a for a, b in zip(frames, frames[1:])) + + +class TestFramesKeepFlowing: + def test_a_reload_during_a_slow_vegas_render(self, dc, tmp_path): + rig = _with_rig(dc, tmp_path) + old = rig.pm.plugins["slow"] + prefetch = rig.start_vegas_render() + rig.manifest_path.write_text(json.dumps( + {"id": "slow", "version": "2.0.0", "display_modes": ["slow"]})) + + command = _reload("slow") + posted = time.perf_counter() + dc._control_server.commands.append(command) + frames = _render_frames(dc, rig, lambda: command.outcome.done, limit=10) + answered = time.perf_counter() - posted + prefetch.join(2) + rig.pm.stop_update_worker() + + gap = _max_gap(frames) + print(f"\nlongest frame gap {gap * 1000:.0f} ms, answered after {answered:.2f} s " + f"(the old instance's render held its lock {RENDER_SECONDS:.1f} s)") + assert gap < MAX_GAP + # The real outcome, once the new instance is in the rotation. + assert command.outcome.result == {"plugin_id": "slow", "reloaded": True, + "version": "2.0.0", "modes": ["slow"]} + new = rig.pm.plugins["slow"] + assert new is not old and new.generation == 2 + assert dc.plugin_modes["slow"] is new + assert dc.available_modes == ["clock", "slow"] + assert dc.current_display_mode == "clock" + dc.vegas_coordinator.mark_plugin_updated.assert_called_once_with("slow") + # The old instance finished its render before it was torn down, and + # the strip got that render. + assert rig.index("render-end", 1) < rig.index("cleanup", 1) + assert rig.prefetched and rig.prefetched[0] + # Loaded once; no update() of the old instance once it was torn + # down, and none of the new one before. + assert rig.generation == 2 + cleanup = rig.index("cleanup", 1) + assert all(i < cleanup for i, e in enumerate(rig.events) if e == ("update", 1)) + assert all(i > cleanup for i, e in enumerate(rig.events) if e == ("update", 2)) + + def test_a_fetch_that_waited_out_the_reload_skips_the_old_instance(self, tmp_path): + """A Vegas fetch that looked the old instance up before the reload, + and got its lock only after the teardown, does not run it.""" + rig = _Rig(tmp_path, 0) + old = rig.pm.detach_plugin("slow") + assert rig.adapter.get_content(old, "slow", offscreen_only=True) is None + rig.pm.unload_detached_plugin("slow", old) + assert rig.pm.reload_plugin("slow") + assert rig.adapter.get_content(old, "slow", offscreen_only=True) is None + assert ("render-start", 1) not in rig.events + # The new instance is fetched as usual. + assert rig.adapter.get_content(rig.pm.plugins["slow"], "slow", offscreen_only=True) + assert ("render-start", 2) in rig.events + + +class TestPluginManagerDetach: + def test_teardown_waits_for_the_lock_and_leaves_plugins_alone(self, tmp_path): + rig = _Rig(tmp_path, 0) + pm = rig.pm + old = pm.detach_plugin("slow") + assert "slow" not in pm.plugins and old.generation == 1 + lock = pm.get_plugin_lock("slow") + lock.acquire() + done = threading.Event() + threading.Thread(target=lambda: (pm.unload_detached_plugin("slow", old), done.set()), + daemon=True).start() + assert not done.wait(0.2) # a render of the old instance holds it + assert ("cleanup", 1) not in rig.events + lock.release() + assert done.wait(5) + assert ("cleanup", 1) in rig.events + assert pm.reload_plugin("slow") + assert pm.plugins["slow"].generation == 2 + + def test_teardown_is_refused_while_the_lock_stays_held(self, tmp_path): + """A Vegas call that took the lock before the detach may still be + running in the old instance: never tear it down from under it.""" + rig = _Rig(tmp_path, 0) + pm = rig.pm + pm.DETACHED_UNLOAD_LOCK_TIMEOUT = 0.2 + old = pm.detach_plugin("slow") + lock = pm.get_plugin_lock("slow") + lock.acquire() + try: + assert pm.unload_detached_plugin("slow", old) is False + assert ("cleanup", 1) not in rig.events + finally: + lock.release() + + def test_detached_teardown_outwaits_the_ordinary_unload_bound(self): + # A Vegas build of the old instance held the lock 5.9 s on ledpi. + from src.plugin_system.plugin_manager import PluginManager + assert PluginManager.DETACHED_UNLOAD_LOCK_TIMEOUT > 2 * PluginManager.UNLOAD_LOCK_TIMEOUT + + def test_detaching_a_plugin_that_is_not_loaded(self, tmp_path): + pm = _Rig(tmp_path, 0).pm + assert pm.detach_plugin("nope") is None + + +# -- the run loop on the fake clock ---------------------------------------- + +POSTED = 10.3 + + +def _with_reloadable(h, version="2.0.0", loads=True): + new = FakePlugin("clock", ["clock"], duration=30) + + def reload_plugin(plugin_id): + h.log("reload", plugin_id) + if not loads: + return False + new._h = h + h.pm.plugins[plugin_id] = new + h.pm.plugin_manifests[plugin_id] = {"version": version, "display_modes": ["clock"]} + return True + + h.pm.reload_plugin = reload_plugin + return new + + +def _vegas(h): + h.add_plugin(FakePlugin("clock", ["clock"], duration=30)) + h.add_plugin(FakePlugin("weather", ["weather"], duration=30)) + h.enable_vegas(cycle=30) + + +def _hold_lock(h, plugin_id, seconds): + """A Vegas render of ``plugin_id`` holds its lock for ``seconds`` from + when the reload is asked for: the render thread would block that long in + unload_plugin(), and the plugin-reload thread does instead.""" + real_unload = h.pm.unload_plugin + + def unload_plugin(pid): + if pid == plugin_id: + h.clock.sleep(max(0.0, POSTED + seconds - h.clock.rel())) + return real_unload(pid) + h.pm.unload_plugin = unload_plugin + h.reload_seconds = seconds + + +def _vegas_frame_gaps(h): + times = [e[0] for e in h.events if e[1] == "vegas-frame"] + return max(b - a for a, b in zip(times, times[1:])) + + +def test_vegas_keeps_scrolling_through_a_slow_reload(tmp_path): + h = RunLoopHarness(tmp_path, horizon=40) + _vegas(h) + new = _with_reloadable(h) + _hold_lock(h, "clock", 3.0) + command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"}) + trace = h.run() + + # Frames every 8 ms throughout: before the fix, none for 3 s. + assert _vegas_frame_gaps(h) <= 0.1 + # The new instance loaded 3 s later, on its own thread, and joined then. + reload_at = next(e[0] for e in h.events if e[1] == "reload") + assert reload_at == pytest.approx(POSTED + 3.0, abs=0.01) + assert command.outcome.result == {"plugin_id": "clock", "reloaded": True, + "version": "2.0.0", "modes": ["clock"]} + assert h.controller.plugin_modes["clock"] is new + assert h.controller.available_modes == ["clock", "weather"] + # Only the start of the reload ended a Vegas iteration; the ticker + # carried on through it. + assert all(r[1] == "" for r in trace["screens"] if r[0] >= POSTED) + + +def test_a_reload_while_on_screen_lets_the_rotation_carry_on(tmp_path): + h = RunLoopHarness(tmp_path, horizon=70) + h.add_plugin(FakePlugin("clock", ["clock"], duration=30)) + h.add_plugin(FakePlugin("weather", ["weather"], duration=30)) + new = _with_reloadable(h) + _hold_lock(h, "clock", 3.0) + command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"}) + trace = h.run() + + # The clock screen ends when the reload is asked for, weather shows + # while the clock loads, and the reloaded clock comes round next. + assert trace["screens"][0][:3] == [0.0, "clock", POSTED] + assert trace["screens"][1][:2] == [POSTED, "weather"] + assert trace["screens"][2][1] == "clock" + assert command.outcome.result["reloaded"] is True + assert h.controller.plugin_modes["clock"] is new + + +def test_a_reload_of_a_plugin_not_on_screen_keeps_its_place(tmp_path): + h = RunLoopHarness(tmp_path, horizon=70) + h.add_plugin(FakePlugin("clock", ["clock"], duration=30)) + h.add_plugin(FakePlugin("weather", ["weather"], duration=30)) + h.add_plugin(FakePlugin("news", ["news"], duration=30)) + new_weather = FakePlugin("weather", ["weather"], duration=30) + + def reload_plugin(plugin_id): + h.log("reload", plugin_id) + new_weather._h = h + h.pm.plugins[plugin_id] = new_weather + h.pm.plugin_manifests[plugin_id] = {"version": "2.0.0"} + return True + h.pm.reload_plugin = reload_plugin + h.reload_seconds = 3.0 + command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "weather"}) + h.run() + + assert command.outcome.result["reloaded"] is True + assert h.controller.available_modes == ["clock", "weather", "news"] + assert h.controller.plugin_modes["weather"] is new_weather + + +def test_a_plugin_that_fails_to_load_after_a_slow_teardown(tmp_path): + h = RunLoopHarness(tmp_path, horizon=40) + _vegas(h) + _with_reloadable(h, loads=False) + _hold_lock(h, "clock", 3.0) + command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"}) + h.run() + + assert _vegas_frame_gaps(h) <= 0.1 + assert command.outcome.error_code == ErrorCode.FAILED + assert "clock" not in h.controller.available_modes + assert "clock" not in h.pm.plugins + + +def test_a_failed_teardown_stops_the_reload(tmp_path): + """Loading over a half-unloaded plugin could reuse its old module and + report a reload that never happened; report the failure instead.""" + h = RunLoopHarness(tmp_path, horizon=40) + _vegas(h) + reloads = [] + h.pm.unload_detached_plugin = lambda plugin_id, instance: False + h.pm.reload_plugin = lambda plugin_id: reloads.append(plugin_id) or True + command = h.control_socket().post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"}) + h.run() + + assert reloads == [] + assert command.outcome.error_code == ErrorCode.FAILED + assert "restart the display" in command.outcome.error_message + assert "clock" not in h.controller.available_modes + assert _vegas_frame_gaps(h) <= 0.1 + + +def test_a_second_reload_while_loading_runs_after_the_first(tmp_path): + h = RunLoopHarness(tmp_path, horizon=40) + _vegas(h) + loads = [] + + def reload_plugin(plugin_id): + plugin = FakePlugin("clock", ["clock"], duration=30) + plugin._h = h + loads.append(plugin) + h.log("reload", plugin_id) + h.pm.plugins[plugin_id] = plugin + h.pm.plugin_manifests[plugin_id] = {"version": f"{len(loads)}.0.0"} + return True + h.pm.reload_plugin = reload_plugin + h.reload_seconds = 3.0 + server = h.control_socket() + first = server.post(POSTED, Command.PLUGIN_RELOAD, {"plugin_id": "clock"}, "a") + second = server.post(POSTED + 1, Command.PLUGIN_RELOAD, {"plugin_id": "clock"}, "b") + h.run() + + # The second starts once the first has joined the rotation (within a + # quarter second of loading), and takes its own 3 s. + loaded = [e[0] for e in h.events if e[1] == "reload"] + assert len(loaded) == 2 + assert loaded[0] == pytest.approx(POSTED + 3.0, abs=0.05) + assert 3.0 <= loaded[1] - loaded[0] <= 3.5 + assert first.outcome.result["version"] == "1.0.0" + assert second.outcome.result["version"] == "2.0.0" + assert h.controller.plugin_modes["clock"] is loads[-1] + assert _vegas_frame_gaps(h) <= 0.1 + + +def test_a_reconcile_during_a_reload_does_not_load_it_twice(dc): + """The config watcher sees an enabled plugin missing from the rotation + while it reloads; the reconcile must not load it beside the reload.""" + pm = MagicMock() + pm.discover_plugins.return_value = ["slow"] + dc.plugin_manager = pm + dc.config_service = MagicMock() + dc.config_service.get_config.return_value = {"slow": {"enabled": True}} + dc.plugin_display_modes = {} + dc._plugin_reload_jobs = (SimpleNamespace(plugin_id="slow"),) + assert dc._reconcile_enabled_plugins() is True + pm.load_plugin.assert_not_called() + assert not dc._enabled_plugin_not_running({"slow": {"enabled": True}}) + + # Disabled while it reloads: unloaded by a reconcile after the reload. + dc.config_service.get_config.return_value = {"slow": {"enabled": False}} + assert dc._reconcile_enabled_plugins() is True + pm.unload_plugin.assert_not_called() + assert dc._reconcile_after_reload is True + + +def test_on_demand_for_a_reloading_plugin_is_refused(dc): + dc._plugin_reload_jobs = (SimpleNamespace(plugin_id="slow"),) + dc._load_plugin_for_on_demand = MagicMock() + dc._activate_on_demand({"plugin_id": "slow"}) + dc._load_plugin_for_on_demand.assert_not_called() + assert dc.on_demand_last_error == "plugin-reloading"