From b518c51679cb643ff7114d73d4c0b8e53275beaf Mon Sep 17 00:00:00 2001 From: Chuck <33324927+ChuckBuilds@users.noreply.github.com> Date: Mon, 28 Sep 2026 08:25:45 -0400 Subject: [PATCH] fix(plugin-system): load/enable failures, atomic state files, pip lock, test-double parity (#645) - load_plugin: an on_enable() that raises unregisters the instance, so the next load retries instead of returning True "already loaded". - get_plugin_info: guard plugin.get_info(); one plugin raising no longer breaks /api/v3/plugins/installed. - plugin_state.json and the operation history are written with atomic_write_text under their lock. - plugin_loader: module-level lock serialises pip installs across the parallel startup loaders. - store_manager._install_via_download: extract dir cleanup moved to finally. - Test doubles: draw_image() warns (DeprecationWarning; the real DisplayManager has none), MockDisplayManager.draw_text accepts the real signature's optional params, VisualTestDisplayManager logs draw errors at WARNING. - Docs/comments: compatibility.py method name, PluginState.LOADED meaning, brittle schema count, why _report_skip_once uses setdefault. - Remove unused PluginOperationQueue.get_active_operations(). Co-authored-by: Claude Opus 5.5 --- CHANGELOG.md | 8 + src/plugin_system/compatibility.py | 2 +- src/plugin_system/operation_history.py | 14 +- src/plugin_system/operation_queue.py | 14 -- src/plugin_system/plugin_loader.py | 174 +++++++++--------- src/plugin_system/plugin_manager.py | 25 ++- src/plugin_system/plugin_state.py | 2 +- src/plugin_system/state_manager.py | 24 ++- src/plugin_system/store_manager.py | 12 +- src/plugin_system/testing/mocks.py | 27 ++- .../testing/visual_display_manager.py | 19 +- test/test_install_via_download_cleanup.py | 66 +++++++ test/test_plugin_loader.py | 46 +++++ test/test_plugin_manager_load_failures.py | 84 +++++++++ test/test_plugin_state_files_atomic.py | 57 ++++++ test/test_testing_mocks.py | 63 +++++++ 16 files changed, 507 insertions(+), 130 deletions(-) create mode 100644 test/test_install_via_download_cleanup.py create mode 100644 test/test_plugin_manager_load_failures.py create mode 100644 test/test_plugin_state_files_atomic.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 6efc241c..6926c5b2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -37,6 +37,14 @@ accepts both, but the store flags the old spelling as deprecated - `check_system_compatibility.sh` no longer reports installed packages as missing. - A network failure fetching GitHub repo info logs a warning, not an error. +- Plugin system: + - A plugin whose `on_enable()` raises is no longer left registered: the next load retries it instead of reporting "already loaded" for a plugin that never ran. + - One plugin's `get_info()` raising no longer breaks the installed-plugins list; it is logged and shown with empty runtime info. + - `plugin_state.json` and the operation history are written atomically (temp file + rename) under their lock, so concurrent saves or a failed save can't leave a truncated file. + - Plugin dependency installs run one `pip` at a time during parallel startup loading. + - A failed store download no longer leaves its extraction directory in the temp dir. + - Test doubles: `draw_image()` on `MockDisplayManager`, `VisualTestDisplayManager` and `BoundsCheckingDisplayManager` now emits a `DeprecationWarning` — the real `DisplayManager` has no such method; use `display_manager.image.paste(img, (x, y))`. `MockDisplayManager.draw_text` accepts the real signature's `small_font`/`centered` and default `x`/`y`, and `VisualTestDisplayManager` logs draw errors at WARNING. + - Removed the unused `PluginOperationQueue.get_active_operations()`. - Display runtime: - Vegas comes back after live content interrupts it. It stayed paused, and the display fell back to normal rotation until a restart. - A day with dimming turned off in a per-day dim schedule stays at normal brightness. Before, brightness went back to dim for most of each minute. diff --git a/src/plugin_system/compatibility.py b/src/plugin_system/compatibility.py index 4537be85..36677c41 100644 --- a/src/plugin_system/compatibility.py +++ b/src/plugin_system/compatibility.py @@ -193,7 +193,7 @@ def declared_min_version(manifest: Dict[str, Any]) -> Optional[str]: """The core version this plugin says it needs, or ``None`` if it doesn't say. Checked in order of specificity. `ledmatrix_min` is the deprecated spelling - of `ledmatrix_min_version` (`store_manager._validate_manifest_fields` flags + of `ledmatrix_min_version` (`store_manager._validate_manifest_version_fields` flags it); both are read because a large share of published manifests still carry the old one. diff --git a/src/plugin_system/operation_history.py b/src/plugin_system/operation_history.py index 24217e74..f20fd2a4 100644 --- a/src/plugin_system/operation_history.py +++ b/src/plugin_system/operation_history.py @@ -11,6 +11,7 @@ from datetime import datetime from pathlib import Path from dataclasses import dataclass, asdict +from src.config_manager_atomic import atomic_write_text from src.logging_config import get_logger @@ -180,15 +181,16 @@ class OperationHistory: return try: + # Held across the write, and written via a temp file, so two + # threads saving at once can't interleave or truncate the file. with self._lock: history_data = [record.to_dict() for record in self._history] - # Ensure directory exists - self.history_file.parent.mkdir(parents=True, exist_ok=True) - - # Write to file - with open(self.history_file, 'w') as f: - json.dump(history_data, f, indent=2) + # Ensure directory exists + self.history_file.parent.mkdir(parents=True, exist_ok=True) + + # Write to file + atomic_write_text(self.history_file, json.dumps(history_data, indent=2)) except Exception as e: self.logger.error(f"Error saving operation history: {e}", exc_info=True) diff --git a/src/plugin_system/operation_queue.py b/src/plugin_system/operation_queue.py index b0e421b8..38dae2d1 100644 --- a/src/plugin_system/operation_queue.py +++ b/src/plugin_system/operation_queue.py @@ -172,20 +172,6 @@ class PluginOperationQueue: ) return history[:limit] - def get_active_operations(self) -> List[PluginOperation]: - """ - Get all currently active operations (pending or running). - - Returns: - List of active operations - """ - with self._lock: - active = [] - for operation in self._operations.values(): - if operation.status in [OperationStatus.PENDING, OperationStatus.RUNNING]: - active.append(operation) - return active - def _start_worker(self) -> None: """Start the worker thread that processes operations.""" if self._worker_thread and self._worker_thread.is_alive(): diff --git a/src/plugin_system/plugin_loader.py b/src/plugin_system/plugin_loader.py index 7547c8f0..3053387d 100644 --- a/src/plugin_system/plugin_loader.py +++ b/src/plugin_system/plugin_loader.py @@ -23,6 +23,11 @@ from src.exceptions import PluginError from src.logging_config import get_logger from src.plugin_system.plugin_dirs import resolve_plugin_dir +#: Serialises pip runs across threads. Startup loads plugins on a small +#: thread pool, and two concurrent ``pip install`` processes writing the same +#: site-packages can corrupt it or fail on each other's partial installs. +_PIP_INSTALL_LOCK = threading.Lock() + def requirements_has_real_deps(requirements_file: str) -> bool: """ @@ -325,93 +330,94 @@ class PluginLoader: if requirements_file is None: return True - try: - self.logger.info("Installing dependencies for plugin %s...", plugin_id) - result = subprocess.run( - [sys.executable, "-m", "pip", "install", "--break-system-packages", "-r", requirements_file], - capture_output=True, - text=True, - timeout=timeout, - check=False - ) + with _PIP_INSTALL_LOCK: + try: + self.logger.info("Installing dependencies for plugin %s...", plugin_id) + result = subprocess.run( + [sys.executable, "-m", "pip", "install", "--break-system-packages", "-r", requirements_file], + capture_output=True, + text=True, + timeout=timeout, + check=False + ) - if result.returncode == 0: - self.logger.info("Dependencies installed successfully for %s", plugin_id) - return True - else: - stderr = result.stderr or "" - # uninstall-no-record-file means a system-managed copy of a package - # (e.g. apt's python3-requests, which ships no pip RECORD file) is in - # the way of the version this requirements.txt pins. Retry with - # --ignore-installed so pip lays the pinned version down alongside - # the system copy instead of trying to replace it — matching the - # retry already used by install_dependencies_apt.py / safe_pip_install.sh. - # Without this retry, the plugin would silently keep running against - # whatever version the system happened to ship. - if "uninstall-no-record-file" in stderr: - self.logger.warning( - "Dependencies for %s conflict with a system-managed package " - "(no pip RECORD); retrying with --ignore-installed: %s", - plugin_id, stderr.strip() - ) - # Wrapped in its own try/except so a retry timeout is - # tolerated the same way as a retry failure, instead of - # propagating to the outer handler and returning False - # (which would contradict the "assume satisfied" fallback - # below). - try: - # sys.executable is this process's own interpreter (not - # attacker-influenced), and requirements_file is rebuilt - # by contained_plugin_dir() from a trusted listing, never raw - # external input. - retry_result = subprocess.run( # nosec B603 - no shell invoked (list-form argv) # nosemgrep - [sys.executable, "-m", "pip", "install", "--break-system-packages", - "--ignore-installed", "-r", requirements_file], - capture_output=True, - text=True, - timeout=timeout, - check=False - ) - if retry_result.returncode != 0: - self.logger.warning( - "Retry with --ignore-installed also failed for %s; assuming the " - "system-managed version satisfies the requirement: %s", - plugin_id, (retry_result.stderr or "").strip() - ) - except subprocess.TimeoutExpired: - self.logger.warning( - "Retry with --ignore-installed timed out for %s; assuming the " - "system-managed version satisfies the requirement", - plugin_id - ) + if result.returncode == 0: + self.logger.info("Dependencies installed successfully for %s", plugin_id) return True - self.logger.warning( - "Dependency installation returned non-zero exit code for %s: %s", - plugin_id, - stderr - ) + else: + stderr = result.stderr or "" + # uninstall-no-record-file means a system-managed copy of a package + # (e.g. apt's python3-requests, which ships no pip RECORD file) is in + # the way of the version this requirements.txt pins. Retry with + # --ignore-installed so pip lays the pinned version down alongside + # the system copy instead of trying to replace it — matching the + # retry already used by install_dependencies_apt.py / safe_pip_install.sh. + # Without this retry, the plugin would silently keep running against + # whatever version the system happened to ship. + if "uninstall-no-record-file" in stderr: + self.logger.warning( + "Dependencies for %s conflict with a system-managed package " + "(no pip RECORD); retrying with --ignore-installed: %s", + plugin_id, stderr.strip() + ) + # Wrapped in its own try/except so a retry timeout is + # tolerated the same way as a retry failure, instead of + # propagating to the outer handler and returning False + # (which would contradict the "assume satisfied" fallback + # below). + try: + # sys.executable is this process's own interpreter (not + # attacker-influenced), and requirements_file is rebuilt + # by contained_plugin_dir() from a trusted listing, never raw + # external input. + retry_result = subprocess.run( # nosec B603 - no shell invoked (list-form argv) # nosemgrep + [sys.executable, "-m", "pip", "install", "--break-system-packages", + "--ignore-installed", "-r", requirements_file], + capture_output=True, + text=True, + timeout=timeout, + check=False + ) + if retry_result.returncode != 0: + self.logger.warning( + "Retry with --ignore-installed also failed for %s; assuming the " + "system-managed version satisfies the requirement: %s", + plugin_id, (retry_result.stderr or "").strip() + ) + except subprocess.TimeoutExpired: + self.logger.warning( + "Retry with --ignore-installed timed out for %s; assuming the " + "system-managed version satisfies the requirement", + plugin_id + ) + return True + self.logger.warning( + "Dependency installation returned non-zero exit code for %s: %s", + plugin_id, + stderr + ) + return False + except subprocess.TimeoutExpired: + self.logger.error("Dependency installation timed out for %s", plugin_id) + return False + except FileNotFoundError: + self.logger.warning("pip not found. Skipping dependency installation for %s", plugin_id) + return True + except OSError as e: + # A broken pipe (EPIPE) happens when pip's output pipe closes + # mid-download, usually a network interruption. + if e.errno == errno.EPIPE: + self.logger.error( + "Broken pipe error during dependency installation for %s. " + "This usually indicates a network interruption or pip output buffer issue. " + "Try installing again or check your network connection.", plugin_id + ) + else: + self.logger.error("OS error during dependency installation for %s: %s", plugin_id, e) + return False + except Exception as e: + self.logger.error("Unexpected error installing dependencies for %s: %s", plugin_id, e, exc_info=True) return False - except subprocess.TimeoutExpired: - self.logger.error("Dependency installation timed out for %s", plugin_id) - return False - except FileNotFoundError: - self.logger.warning("pip not found. Skipping dependency installation for %s", plugin_id) - return True - except OSError as e: - # A broken pipe (EPIPE) happens when pip's output pipe closes - # mid-download, usually a network interruption. - if e.errno == errno.EPIPE: - self.logger.error( - "Broken pipe error during dependency installation for %s. " - "This usually indicates a network interruption or pip output buffer issue. " - "Try installing again or check your network connection.", plugin_id - ) - else: - self.logger.error("OS error during dependency installation for %s: %s", plugin_id, e) - return False - except Exception as e: - self.logger.error("Unexpected error installing dependencies for %s: %s", plugin_id, e, exc_info=True) - return False @staticmethod def _iter_plugin_bare_modules( diff --git a/src/plugin_system/plugin_manager.py b/src/plugin_system/plugin_manager.py index 90d7bc67..d06c347e 100644 --- a/src/plugin_system/plugin_manager.py +++ b/src/plugin_system/plugin_manager.py @@ -183,6 +183,8 @@ class PluginManager: someone opened a page -- the same log-volume problem this is meant to help diagnose. """ + # setdefault rather than self._skip_reported: tests build a bare + # scanner with PluginManager.__new__ and skip __init__. reported = self.__dict__.setdefault('_skip_reported', set()) if key in reported: return @@ -433,7 +435,18 @@ class PluginManager: self.state_manager.set_state(plugin_id, PluginState.ENABLED) # Call on_enable if plugin is enabled if hasattr(plugin_instance, 'on_enable'): - plugin_instance.on_enable() + try: + plugin_instance.on_enable() + except Exception: + # Undo the registration above before the outer + # handler marks it ERROR: left in self.plugins, the + # next load_plugin() would return True as "already + # loaded" for a plugin that never enabled. + self.plugins.pop(plugin_id, None) + with self._plugin_last_update_lock: + self.plugin_last_update.pop(plugin_id, None) + self._update_interval_cache.pop(plugin_id, None) + raise else: self.state_manager.set_state(plugin_id, PluginState.DISABLED) @@ -452,7 +465,7 @@ class PluginManager: #: Config keys the **core** reads out of a plugin's own config block. The #: plugin never declares them, so a schema with - #: ``"additionalProperties": false`` — 37 of the 42 published ones — reports + #: ``"additionalProperties": false`` — most published ones do — reports #: them as violations and the plugin gets flagged degraded in the web UI for #: using a documented core feature. #: @@ -744,7 +757,13 @@ class PluginManager: if plugin: info['loaded'] = True if hasattr(plugin, 'get_info'): - info['runtime_info'] = plugin.get_info() + # One plugin's get_info() raising must not take down the + # whole installed-plugins listing (/api/v3/plugins/installed). + try: + info['runtime_info'] = plugin.get_info() + except Exception as e: + self.logger.warning("Plugin %s get_info() failed: %s", plugin_id, e) + info['runtime_info'] = {} else: info['loaded'] = False diff --git a/src/plugin_system/plugin_state.py b/src/plugin_system/plugin_state.py index e1e26db1..2f4b9641 100644 --- a/src/plugin_system/plugin_state.py +++ b/src/plugin_system/plugin_state.py @@ -17,7 +17,7 @@ from src.logging_config import get_logger class PluginState(Enum): """Plugin state enumeration.""" UNLOADED = "unloaded" # Plugin not loaded - LOADED = "loaded" # Plugin module loaded but not instantiated + LOADED = "loaded" # load_plugin() in progress: set before the module is imported ENABLED = "enabled" # Plugin instantiated and enabled RUNNING = "running" # Plugin is currently executing ERROR = "error" # Plugin encountered an error diff --git a/src/plugin_system/state_manager.py b/src/plugin_system/state_manager.py index da8ea449..35d9feee 100644 --- a/src/plugin_system/state_manager.py +++ b/src/plugin_system/state_manager.py @@ -13,6 +13,7 @@ from datetime import datetime from dataclasses import dataclass, asdict from enum import Enum +from src.config_manager_atomic import atomic_write_text from src.logging_config import get_logger @@ -283,6 +284,10 @@ class PluginStateManager: return try: + # The write stays under the lock and goes through a temp file: + # Flask serves requests on threads, and two saves racing on a + # plain open('w') could interleave or leave a truncated file + # that _load_state then drops wholesale. with self._lock: # Convert states to dicts states_data = { @@ -296,16 +301,15 @@ class PluginStateManager: 'last_updated': datetime.now().isoformat() } - # Ensure directory exists with proper permissions - from src.common.permission_utils import ( - ensure_directory_permissions, - get_config_dir_mode - ) - ensure_directory_permissions(self.state_file.parent, get_config_dir_mode()) - - # Write to file - with open(self.state_file, 'w') as f: - json.dump(state_data, f, indent=2) + # Ensure directory exists with proper permissions + from src.common.permission_utils import ( + ensure_directory_permissions, + get_config_dir_mode + ) + ensure_directory_permissions(self.state_file.parent, get_config_dir_mode()) + + # Write to file + atomic_write_text(self.state_file, json.dumps(state_data, indent=2)) except Exception as e: self.logger.error(f"Error saving plugin state: {e}", exc_info=True) diff --git a/src/plugin_system/store_manager.py b/src/plugin_system/store_manager.py index 47f64842..204aca57 100644 --- a/src/plugin_system/store_manager.py +++ b/src/plugin_system/store_manager.py @@ -1994,6 +1994,7 @@ class PluginStoreManager: tmp_file.write(chunk) tmp_zip_path = tmp_file.name + temp_extract = None try: # Extract zip with zipfile.ZipFile(tmp_zip_path, 'r') as zip_ref: @@ -2015,7 +2016,6 @@ class PluginStoreManager: f"Zip-slip detected: member {member!r} resolves outside " f"temp directory, aborting" ) - shutil.rmtree(temp_extract, ignore_errors=True) return False zip_ref.extractall(temp_extract) @@ -2027,10 +2027,6 @@ class PluginStoreManager: else: # No root dir, move everything shutil.move(str(temp_extract), str(target_path)) - - # Cleanup temp extract dir - if temp_extract.exists(): - shutil.rmtree(temp_extract, ignore_errors=True) return True @@ -2038,6 +2034,12 @@ class PluginStoreManager: # Remove temporary zip file if os.path.exists(tmp_zip_path): os.remove(tmp_zip_path) + # Cleanup temp extract dir here rather than on the success + # path, so a failed extract or move doesn't leave a copy of + # the plugin in /tmp on every attempt. (Gone already when the + # whole dir was moved into place.) + if temp_extract is not None and temp_extract.exists(): + shutil.rmtree(temp_extract, ignore_errors=True) except Exception as e: self.logger.error(f"Download failed: {e}") diff --git a/src/plugin_system/testing/mocks.py b/src/plugin_system/testing/mocks.py index 46104c68..a103670b 100644 --- a/src/plugin_system/testing/mocks.py +++ b/src/plugin_system/testing/mocks.py @@ -5,9 +5,21 @@ Provides mock implementations of display_manager, cache_manager, config_manager, and plugin_manager for use in plugin unit tests. """ +import warnings from typing import Dict, Any, Optional from PIL import Image +#: Why draw_image() warns. Kept (rather than removed) so existing plugin test +#: suites that call it keep passing, but a plugin that calls it passes its +#: tests and then crashes on the Pi. +DRAW_IMAGE_DEPRECATION = ( + "display_manager.draw_image() exists only on the test doubles; the real " + "DisplayManager has no such method, so this raises AttributeError on a " + "device. Paste onto the canvas instead: " + "display_manager.image.paste(img, (x, y)) (with the image as mask, " + "image.paste(rgba, (x, y), rgba), for transparency)." +) + class MockDisplayManager: """Mock display manager for testing.""" @@ -31,8 +43,16 @@ class MockDisplayManager: """Update the display.""" self.update_called = True - def draw_text(self, text: str, x: int, y: int, color: tuple = (255, 255, 255), font=None): - """Draw text on the display.""" + def draw_text(self, text: str, x: int = None, y: int = None, color: tuple = (255, 255, 255), + font=None, small_font: bool = False, centered: bool = False): + """Draw text on the display. + + Accepts every argument the real ``DisplayManager.draw_text`` does, so + a plugin passing ``small_font``/``centered`` (or leaving x/y to + default) doesn't fail here while working on the device. ``font`` + stays fifth for callers of the old mock signature; pass the rest by + keyword, as the real method's positional order differs. + """ self.draw_calls.append({ 'type': 'text', 'text': text, @@ -43,7 +63,8 @@ class MockDisplayManager: }) def draw_image(self, image: Image.Image, x: int, y: int): - """Draw an image on the display.""" + """Draw an image on the display. Deprecated: see DRAW_IMAGE_DEPRECATION.""" + warnings.warn(DRAW_IMAGE_DEPRECATION, DeprecationWarning, stacklevel=2) self.draw_calls.append({ 'type': 'image', 'image': image, diff --git a/src/plugin_system/testing/visual_display_manager.py b/src/plugin_system/testing/visual_display_manager.py index 4ce4289c..01536514 100644 --- a/src/plugin_system/testing/visual_display_manager.py +++ b/src/plugin_system/testing/visual_display_manager.py @@ -29,6 +29,7 @@ through src/common/bdf_font.py, so those pixels cannot drift. import math import os import time +import warnings from contextlib import contextmanager from pathlib import Path from typing import Any, List, Optional, Tuple @@ -38,9 +39,12 @@ from src.common.bdf_font import draw_bdf_text, load_bdf_face from src.common.font_layout import crisp_size, load_truetype from src.logging_config import get_logger +from src.plugin_system.testing.mocks import DRAW_IMAGE_DEPRECATION logger = get_logger(__name__) +_draw_image_warning_logged = False + class _MatrixProxy: """Lightweight proxy so plugins can access display_manager.matrix.width/height.""" @@ -321,17 +325,26 @@ class VisualTestDisplayManager: else: self.draw.text((x, y), text, font=current_font, fill=color) except Exception as e: - logger.debug(f"Error drawing text: {e}") + # WARNING, not DEBUG: the real DisplayManager logs this at ERROR, + # and a test double that hides it lets a broken draw pass. + logger.warning(f"Error drawing text: {e}") def draw_image(self, image: Image.Image, x: int, y: int): - """Draw an image on the display.""" + """Draw an image on the display. Deprecated: see DRAW_IMAGE_DEPRECATION.""" + warnings.warn(DRAW_IMAGE_DEPRECATION, DeprecationWarning, stacklevel=2) + global _draw_image_warning_logged + if not _draw_image_warning_logged: + # Also logged once: the dev preview server drives this class + # outside pytest, where DeprecationWarning is hidden by default. + _draw_image_warning_logged = True + logger.warning(DRAW_IMAGE_DEPRECATION) self.draw_calls.append({ 'type': 'image', 'image': image, 'x': x, 'y': y, }) try: self.image.paste(image, (x, y)) except Exception as e: - logger.debug(f"Error drawing image: {e}") + logger.warning(f"Error drawing image: {e}") def _draw_bdf_text(self, text, x, y, color=(255, 255, 255), font=None): """Draw text in a BDF ``freetype.Face`` with (x, y) as its top-left. diff --git a/test/test_install_via_download_cleanup.py b/test/test_install_via_download_cleanup.py new file mode 100644 index 00000000..dbf3c666 --- /dev/null +++ b/test/test_install_via_download_cleanup.py @@ -0,0 +1,66 @@ +"""_install_via_download removes its extraction directory on failure too. + +The temp extract dir was only removed on the success path (and on a zip-slip +abort), so an extract or move that raised left a full copy of the plugin in +the system temp dir on every failed attempt. Cleanup now lives in ``finally``. +""" + +import io +import tempfile +import zipfile +from pathlib import Path +from unittest.mock import MagicMock, patch + +from src.plugin_system.store_manager import PluginStoreManager + + +def _zip_bytes(): + buf = io.BytesIO() + with zipfile.ZipFile(buf, 'w') as zf: + zf.writestr('demo-main/manifest.json', '{"id": "demo"}') + zf.writestr('demo-main/manager.py', '') + return buf.getvalue() + + +def _response(payload): + response = MagicMock() + response.raise_for_status.return_value = None + response.iter_content.return_value = [payload] + return response + + +def _run(tmp_path, move_side_effect=None): + plugins_dir = tmp_path / "plugin-repos" + plugins_dir.mkdir() + sm = PluginStoreManager(plugins_dir=str(plugins_dir)) + created = [] + real_mkdtemp = tempfile.mkdtemp + + def tracking_mkdtemp(*args, **kwargs): + path = real_mkdtemp(*args, **kwargs) + created.append(Path(path)) + return path + + with patch.object(sm, '_http_get_with_retries', return_value=_response(_zip_bytes())), \ + patch('src.plugin_system.store_manager.tempfile.mkdtemp', side_effect=tracking_mkdtemp), \ + patch('src.plugin_system.store_manager.shutil.move', side_effect=move_side_effect): + ok = sm._install_via_download('https://example.invalid/demo.zip', plugins_dir / 'demo') + return ok, created + + +def test_extract_dir_removed_when_the_move_fails(tmp_path): + ok, created = _run(tmp_path, move_side_effect=OSError("disk full")) + + assert ok is False + assert len(created) == 1 + assert not created[0].exists() + + +def test_extract_dir_removed_on_success(tmp_path): + # shutil.move patched to a no-op: the extracted tree stays in temp and + # must still be cleaned up. + ok, created = _run(tmp_path, move_side_effect=lambda *a, **k: None) + + assert ok is True + assert len(created) == 1 + assert not created[0].exists() diff --git a/test/test_plugin_loader.py b/test/test_plugin_loader.py index efc42833..a6a43d15 100644 --- a/test/test_plugin_loader.py +++ b/test/test_plugin_loader.py @@ -342,3 +342,49 @@ class TestPluginLoader: assert result is False mock_subprocess.assert_not_called() + + @patch('src.plugin_system.plugin_loader.requirements_are_satisfied', return_value=False) + def test_install_dependencies_never_runs_pip_concurrently( + self, mock_satisfied, tmp_plugins_dir + ): + """Startup loads plugins on a thread pool; two pip processes writing + the same site-packages at once can corrupt it, so installs for + different plugins must run one at a time.""" + import threading + import time + + state = {'running': 0, 'peak': 0} + guard = threading.Lock() + + def fake_pip(*args, **kwargs): + with guard: + state['running'] += 1 + state['peak'] = max(state['peak'], state['running']) + time.sleep(0.05) + with guard: + state['running'] -= 1 + return MagicMock(returncode=0, stderr="") + + plugin_dirs = [] + for n in range(4): + d = tmp_plugins_dir / f"plugin_{n}" + d.mkdir() + (d / "requirements.txt").write_text("package1==1.0.0\n") + plugin_dirs.append(d) + + results = [] + + def install(d): + results.append(PluginLoader().install_dependencies( + d, d.name, plugins_dir=tmp_plugins_dir)) + + with patch('subprocess.run', side_effect=fake_pip) as mock_subprocess: + threads = [threading.Thread(target=install, args=(d,)) for d in plugin_dirs] + for t in threads: + t.start() + for t in threads: + t.join() + + assert results == [True] * 4 + assert mock_subprocess.call_count == 4 + assert state['peak'] == 1 diff --git a/test/test_plugin_manager_load_failures.py b/test/test_plugin_manager_load_failures.py new file mode 100644 index 00000000..13a05d5f --- /dev/null +++ b/test/test_plugin_manager_load_failures.py @@ -0,0 +1,84 @@ +"""PluginManager failure paths that used to leave the manager inconsistent. + +- load_plugin registered the instance in ``self.plugins`` before calling + ``on_enable()``. When on_enable raised, the plugin stayed registered in + ERROR state, so the next load_plugin returned True ("already loaded") for + a plugin that never ran. +- get_plugin_info called ``plugin.get_info()`` unguarded, so one plugin + raising broke /api/v3/plugins/installed for every plugin. +""" + +import logging +from unittest.mock import MagicMock + +import pytest + +from src.plugin_system.plugin_manager import PluginManager +from src.plugin_system.plugin_state import PluginState + + +class _Plugin: + def __init__(self, fail_enable=False, fail_info=False): + self.fail_enable = fail_enable + self.fail_info = fail_info + self.enabled_calls = 0 + + def on_enable(self): + self.enabled_calls += 1 + if self.fail_enable: + raise RuntimeError("on_enable blew up") + + def get_info(self): + if self.fail_info: + raise RuntimeError("get_info blew up") + return {"ok": True} + + +@pytest.fixture +def pm(tmp_path): + plugins_dir = tmp_path / "plugins" + (plugins_dir / "demo").mkdir(parents=True) + manager = PluginManager(plugins_dir=str(plugins_dir)) + manager.plugin_manifests["demo"] = {"id": "demo", "name": "Demo"} + manager.schema_manager = MagicMock() + manager.schema_manager.get_schema_path.return_value = None + manager.plugin_loader = MagicMock() + manager.plugin_loader.find_plugin_directory.return_value = plugins_dir / "demo" + return manager + + +def test_on_enable_failure_unregisters_the_plugin(pm): + plugin = _Plugin(fail_enable=True) + pm.plugin_loader.load_plugin.return_value = (plugin, None) + + assert pm.load_plugin("demo") is False + assert "demo" not in pm.plugins + assert "demo" not in pm.plugin_last_update + assert pm.state_manager.get_state("demo") == PluginState.ERROR + + +def test_load_after_on_enable_failure_retries_instead_of_already_loaded(pm): + pm.plugin_loader.load_plugin.return_value = (_Plugin(fail_enable=True), None) + assert pm.load_plugin("demo") is False + + fixed = _Plugin() + pm.plugin_loader.load_plugin.return_value = (fixed, None) + assert pm.load_plugin("demo") is True + assert pm.plugins["demo"] is fixed + assert fixed.enabled_calls == 1 + assert pm.state_manager.get_state("demo") == PluginState.ENABLED + + +def test_get_info_failure_does_not_break_the_listing(pm, caplog): + pm.plugin_manifests["good"] = {"id": "good", "name": "Good"} + pm.plugins["demo"] = _Plugin(fail_info=True) + pm.plugins["good"] = _Plugin() + + with caplog.at_level(logging.WARNING): + infos = {i["id"]: i for i in pm.get_all_plugin_info()} + + assert infos["demo"]["loaded"] is True + assert infos["demo"]["runtime_info"] == {} + assert infos["good"]["runtime_info"] == {"ok": True} + assert any("demo" in r.getMessage() and r.levelno == logging.WARNING + for r in caplog.records) diff --git a/test/test_plugin_state_files_atomic.py b/test/test_plugin_state_files_atomic.py new file mode 100644 index 00000000..1405da36 --- /dev/null +++ b/test/test_plugin_state_files_atomic.py @@ -0,0 +1,57 @@ +"""plugin_state.json and the operation history file are replaced atomically. + +Both were written with a plain ``open(path, 'w')`` + ``json.dump`` outside +their lock. The open truncates first, so a value json can't encode (or a +crash, or a second Flask thread saving at the same moment) left a partial +file, and the next load dropped every saved state. They now serialise first +and go through a temp file + rename while holding the lock. +""" + +import json +import threading + +from src.plugin_system.operation_history import OperationHistory +from src.plugin_system.state_manager import PluginStateManager + + +def test_state_file_survives_a_failed_save(tmp_path): + state_file = tmp_path / "plugin_state.json" + mgr = PluginStateManager(state_file=str(state_file)) + mgr.set_plugin_enabled("clock", True) + before = json.loads(state_file.read_text()) + + # Not JSON-serialisable: the save fails (and is logged, not raised). + mgr.update_plugin_state("clock", {"metadata": {"bad": object()}}) + + assert json.loads(state_file.read_text()) == before + assert [p.name for p in tmp_path.iterdir()] == ["plugin_state.json"] + + +def test_state_file_is_valid_after_concurrent_saves(tmp_path): + state_file = tmp_path / "plugin_state.json" + mgr = PluginStateManager(state_file=str(state_file)) + + def worker(n): + for i in range(15): + mgr.set_plugin_enabled(f"plugin-{n}", i % 2 == 0) + + threads = [threading.Thread(target=worker, args=(n,)) for n in range(6)] + for t in threads: + t.start() + for t in threads: + t.join() + + data = json.loads(state_file.read_text()) + assert set(data["states"]) == {f"plugin-{n}" for n in range(6)} + + +def test_history_file_survives_a_failed_save(tmp_path): + history_file = tmp_path / "operation_history.json" + history = OperationHistory(history_file=str(history_file)) + history.record_operation("install", plugin_id="clock") + before = json.loads(history_file.read_text()) + + history.record_operation("update", plugin_id="clock", details={"bad": object()}) + + assert json.loads(history_file.read_text()) == before + assert [p.name for p in tmp_path.iterdir()] == ["operation_history.json"] diff --git a/test/test_testing_mocks.py b/test/test_testing_mocks.py index f8ed6516..57da4def 100644 --- a/test/test_testing_mocks.py +++ b/test/test_testing_mocks.py @@ -9,6 +9,8 @@ get_cached_data_with_strategy() and previously hit an AttributeError that its own broad except swallowed, producing an empty-but-green render). """ +import pytest + from src.plugin_system.testing.mocks import MockCacheManager @@ -43,3 +45,64 @@ class TestMockCacheManagerStrategyMethod: cm.get_cached_data_with_strategy("k", "sports_live") cm.reset() assert cm.get_cached_data_with_strategy_calls == [] + + +class TestDisplayDoublesMatchTheRealDisplayManager: + """The real DisplayManager has no draw_image(); the doubles keep it so + existing plugin test suites still pass, but warn, because a plugin that + calls it passes its tests and then raises AttributeError on the Pi.""" + + @staticmethod + def _real_display_manager(monkeypatch): + # Without EMULATOR the import needs the hardware rgbmatrix module. + monkeypatch.setenv("EMULATOR", "true") + from src.display_manager import DisplayManager + return DisplayManager + + def test_real_display_manager_has_no_draw_image(self, monkeypatch): + DisplayManager = self._real_display_manager(monkeypatch) + assert not hasattr(DisplayManager, 'draw_image') + + def test_mock_draw_image_warns_and_still_records(self): + from PIL import Image + from src.plugin_system.testing.mocks import MockDisplayManager + + dm = MockDisplayManager() + with pytest.warns(DeprecationWarning, match=r"image\.paste\(img, \(x, y\)\)"): + dm.draw_image(Image.new('RGB', (4, 4)), 1, 2) + assert dm.draw_calls[-1]['type'] == 'image' + + @pytest.mark.parametrize("cls_name", ["VisualTestDisplayManager", "BoundsCheckingDisplayManager"]) + def test_visual_draw_image_warns_and_still_pastes(self, cls_name): + from PIL import Image + import src.plugin_system.testing as testing + + dm = getattr(testing, cls_name)(width=16, height=8) + with pytest.warns(DeprecationWarning, match="DisplayManager has no such method"): + dm.draw_image(Image.new('RGB', (2, 2), (0, 0, 255)), 3, 3) + assert dm.image.getpixel((3, 3)) == (0, 0, 255) + + def test_mock_draw_text_accepts_the_real_signature(self, monkeypatch): + import inspect + DisplayManager = self._real_display_manager(monkeypatch) + from src.plugin_system.testing.mocks import MockDisplayManager + + real = inspect.signature(DisplayManager.draw_text).parameters + mock = inspect.signature(MockDisplayManager.draw_text).parameters + for name, param in real.items(): + assert name in mock, name + assert mock[name].default == param.default, name + + dm = MockDisplayManager() + dm.draw_text("hi", small_font=True, centered=True) + assert dm.draw_calls[-1]['text'] == "hi" + + def test_visual_draw_failure_is_logged_at_warning(self, caplog): + import logging + from src.plugin_system.testing import VisualTestDisplayManager + + dm = VisualTestDisplayManager(width=16, height=8) + with caplog.at_level(logging.WARNING): + dm.draw_image(object(), 0, 0) # not an image: paste raises + assert any(r.levelno == logging.WARNING and "Error drawing image" in r.getMessage() + for r in caplog.records)