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 <noreply@anthropic.com>

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.
 

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)

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():

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(

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
         

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

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)

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}")

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,

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.