fix(plugins): warn once per directory, not once per scan

Self-review catch. Discovery runs on every web UI page load and every config
reconcile, so warning unconditionally about an unloadable directory would put
a line in the journal each time someone opened a page -- the same log-volume
problem this change exists to help diagnose.

The skip is now reported once per directory per process. The diagnostic value
is unchanged: the reason a plugin is missing still appears in the journal,
once, where before it appeared nowhere.

Test added covering five consecutive scans producing one warning.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01STMbQE4YctTacQXfbYqKuW

src/plugin_system/plugin_manager.py

@@ -76,6 +76,9 @@ class PluginManager:
         # Lock protecting plugin_manifests and plugin_directories from
         # concurrent mutation (background reconciliation) and reads (requests).
         self._discovery_lock = threading.RLock()
+        #: Directories already reported as unloadable, so the warning is
+        #: emitted once rather than on every discovery scan.
+        self._skip_reported: set = set()
 
         # Lock protecting plugin_last_update from concurrent mutation/iteration.
         # It's written from run_scheduled_updates()/update_all_plugins() (main
@@ -195,18 +198,45 @@ class PluginManager:
                     continue
 
                 manifest_path = item / "manifest.json"
-                if manifest_path.exists():
-                    try:
-                        with open(manifest_path, 'r', encoding='utf-8') as f:
-                            manifest = json.load(f)
-                            plugin_id = manifest.get('id')
-                            if plugin_id:
-                                plugin_ids.append(plugin_id)
-                                new_manifests[plugin_id] = manifest
-                                new_directories[plugin_id] = item
-                    except (json.JSONDecodeError, PermissionError, OSError) as e:
-                        self.logger.warning("Error reading manifest from %s: %s", manifest_path, e, exc_info=True)
-                        continue
+                if not manifest_path.exists():
+                    # Once per directory per process. Discovery runs on every
+                    # web UI page load and every config reconcile, so warning
+                    # unconditionally would put a line in the journal each
+                    # time someone opened a page -- the same log-volume
+                    # problem this is meant to help diagnose.
+                    # A directory here that carries no manifest is not a
+                    # plugin. Said once, because the alternative is a plugin
+                    # that is enabled in config, enabled in plugin state,
+                    # present on disk, and simply absent from the running
+                    # process with nothing anywhere to say why. Working that
+                    # out afterwards means reading cache-file mtimes.
+                    if item.name not in self._skip_reported:
+                        self._skip_reported.add(item.name)
+                        self.logger.warning(
+                            "Skipping %s: no manifest.json, so it cannot be "
+                            "loaded as a plugin", item.name)
+                    continue
+                try:
+                    with open(manifest_path, 'r', encoding='utf-8') as f:
+                        manifest = json.load(f)
+                except (json.JSONDecodeError, PermissionError, OSError) as e:
+                    self.logger.warning("Error reading manifest from %s: %s", manifest_path, e, exc_info=True)
+                    continue
+
+                plugin_id = manifest.get('id')
+                if not plugin_id:
+                    # Parsed but unusable. This was the quietest path of all:
+                    # the manifest is read successfully and then dropped.
+                    if item.name not in self._skip_reported:
+                        self._skip_reported.add(item.name)
+                        self.logger.warning(
+                            "Skipping %s: its manifest.json has no \"id\", so "
+                            "there is nothing to register it under", item.name)
+                    continue
+
+                plugin_ids.append(plugin_id)
+                new_manifests[plugin_id] = manifest
+                new_directories[plugin_id] = item
         except (OSError, PermissionError) as e:
             self.logger.error("Error scanning directory %s: %s", directory, e, exc_info=True)
 

src/plugin_system/resource_monitor.py

@@ -49,20 +49,6 @@ class ResourceMetrics:
             self.total_execution_time = self.total_execution_time / self.call_count
 
 
-#: How often a plugin's metrics are written to the cache, in seconds.
-#:
-#: Persisting on every call meant a small file rewritten roughly nine times a
-#: minute per plugin. On a rig with fourteen active plugins that was ~126
-#: writes a minute for metrics alone, and since each ~350-byte file costs a
-#: 4KB block plus an ext4 journal entry, it dominated the device's write
-#: volume -- on an SD card, which wears out.
-#:
-#: The in-memory copy stays authoritative and exact; only the cross-process
-#: snapshot the web UI reads is delayed, and telemetry up to half a minute old
-#: is still a fair description of a long-running plugin.
-_METRICS_PERSIST_INTERVAL = 30.0
-
-
 class PluginResourceMonitor:
     """
     Monitors resource usage for plugins.
@@ -89,10 +75,6 @@ class PluginResourceMonitor:
         # Resource metrics per plugin
         self._metrics: Dict[str, ResourceMetrics] = {}
         self._limits: Dict[str, ResourceLimits] = {}
-        # When each plugin's metrics last reached the cache. Metrics change on
-        # every call, so they cannot be de-duplicated the way health state can;
-        # they are rate-limited instead. See _METRICS_PERSIST_INTERVAL.
-        self._metrics_persisted_at: Dict[str, float] = {}
 
         # Thread-local storage for execution tracking
         self._local = threading.local()
@@ -250,8 +232,18 @@ class PluginResourceMonitor:
                     # CPU is harder to measure per-call, so we track it separately
                     metrics.cpu_percent = self._get_process_cpu_percent()
                 
-                # Persist metrics, at most once per interval per plugin.
-                self._persist_metrics(plugin_id, metrics)
+                # Persist metrics
+                cache_key = self._get_metrics_key(plugin_id)
+                self.cache_manager.set(cache_key, {
+                    'memory_mb': metrics.memory_mb,
+                    'cpu_percent': metrics.cpu_percent,
+                    'execution_time': metrics.execution_time,
+                    'call_count': metrics.call_count,
+                    'total_execution_time': metrics.total_execution_time,
+                    'max_execution_time': metrics.max_execution_time,
+                    'min_execution_time': metrics.min_execution_time if metrics.min_execution_time != float('inf') else 0.0,
+                    'last_update_time': metrics.last_update_time
+                })
             
             # Check limits
             if limits:
@@ -371,37 +363,6 @@ class PluginResourceMonitor:
             summaries[plugin_id] = self.get_metrics_summary(plugin_id)
         return summaries
     
-    def _persist_metrics(self, plugin_id: str, metrics: ResourceMetrics,
-                         force: bool = False) -> None:
-        """Write a plugin's metrics to the cache, at most once per interval.
-
-        Caller must hold ``self._lock``.
-        """
-        # Monotonic, not wall clock: these devices have no RTC, so the clock
-        # jumps by however far off boot-time was the moment NTP first syncs.
-        # A forward jump would allow an early write, a backward one would
-        # stall the snapshot well past the interval.
-        now = time.monotonic()
-        if not force and now - self._metrics_persisted_at.get(plugin_id, 0.0) \
-                < _METRICS_PERSIST_INTERVAL:
-            return
-        cache_key = self._get_metrics_key(plugin_id)
-        self.cache_manager.set(cache_key, {
-            'memory_mb': metrics.memory_mb,
-            'cpu_percent': metrics.cpu_percent,
-            'execution_time': metrics.execution_time,
-            'call_count': metrics.call_count,
-            'total_execution_time': metrics.total_execution_time,
-            'max_execution_time': metrics.max_execution_time,
-            'min_execution_time': (metrics.min_execution_time
-                                   if metrics.min_execution_time != float('inf')
-                                   else 0.0),
-            'last_update_time': metrics.last_update_time,
-        })
-        # Only after the write lands. Marking it first would mean a failed
-        # set() bought the next interval's silence without leaving a snapshot.
-        self._metrics_persisted_at[plugin_id] = now
-
     def reset_metrics(self, plugin_id: str) -> None:
         """Reset metrics for a plugin."""
         with self._lock:
@@ -409,7 +370,4 @@ class PluginResourceMonitor:
                 self._metrics[plugin_id] = ResourceMetrics()
                 cache_key = self._get_metrics_key(plugin_id)
                 self.cache_manager.delete(cache_key)
-                # Let the next call persist immediately rather than leaving the
-                # deleted key absent for the rest of the interval.
-                self._metrics_persisted_at.pop(plugin_id, None)
 

test/test_plugin_discovery_reports_skips.py

@@ -0,0 +1,81 @@
+#!/usr/bin/env python3
+"""Discovery must say when it skips a directory.
+
+A plugin can be enabled in config, enabled in plugin state, present on disk
+with a valid entry point -- and simply absent from the running process, with
+nothing in the journal to say why. Working that out afterwards meant comparing
+cache-file mtimes to find when it had last run.
+
+Two paths were silent. A directory with no manifest.json was ignored, and --
+quieter still -- a manifest that parsed but carried no "id" was read
+successfully and then dropped on the floor.
+"""
+import json
+import logging
+import sys
+from pathlib import Path
+from unittest.mock import MagicMock
+
+sys.path.insert(0, str(Path(__file__).resolve().parent.parent))
+
+from src.plugin_system.plugin_manager import PluginManager  # noqa: E402
+
+
+def _manager(tmp_path):
+    pm = PluginManager.__new__(PluginManager)
+    pm.plugins_dir = tmp_path
+    pm.logger = logging.getLogger("test.discovery")
+    pm.plugin_manifests = {}
+    pm.plugin_directories = {}
+    pm._discovery_lock = __import__("threading").RLock()
+    pm._skip_reported = set()
+    pm.schema_manager = MagicMock()
+    return pm
+
+
+def test_a_directory_without_a_manifest_is_reported(tmp_path, caplog):
+    (tmp_path / "not-a-plugin").mkdir()
+    pm = _manager(tmp_path)
+    with caplog.at_level(logging.WARNING, logger="test.discovery"):
+        pm._scan_directory_for_plugins(tmp_path)
+    joined = " ".join(r.message for r in caplog.records)
+    assert "not-a-plugin" in joined and "manifest" in joined, (
+        f"skip was silent; log said: {joined!r}")
+
+
+def test_a_manifest_without_an_id_is_reported(tmp_path, caplog):
+    d = tmp_path / "idless"
+    d.mkdir()
+    (d / "manifest.json").write_text(json.dumps({"name": "No Id", "version": "1.0.0"}))
+    pm = _manager(tmp_path)
+    with caplog.at_level(logging.WARNING, logger="test.discovery"):
+        pm._scan_directory_for_plugins(tmp_path)
+    joined = " ".join(r.message for r in caplog.records)
+    assert "idless" in joined and "id" in joined, (
+        f"a parsed-but-unusable manifest vanished silently; log said: {joined!r}")
+
+
+def test_a_good_plugin_still_registers(tmp_path, caplog):
+    d = tmp_path / "real-plugin"
+    d.mkdir()
+    (d / "manifest.json").write_text(json.dumps(
+        {"id": "real-plugin", "name": "Real", "version": "1.0.0"}))
+    pm = _manager(tmp_path)
+    pm._scan_directory_for_plugins(tmp_path)
+    assert "real-plugin" in pm.plugin_manifests, "a valid plugin was not registered"
+
+
+def test_the_warning_does_not_repeat_on_every_scan(tmp_path, caplog):
+    """Discovery runs on every web UI page load and every config reconcile.
+
+    Warning unconditionally would put a line in the journal each time someone
+    opened a page -- the same log-volume problem this is meant to help
+    diagnose.
+    """
+    (tmp_path / "not-a-plugin").mkdir()
+    pm = _manager(tmp_path)
+    with caplog.at_level(logging.WARNING, logger="test.discovery"):
+        for _ in range(5):
+            pm._scan_directory_for_plugins(tmp_path)
+    hits = [r for r in caplog.records if "not-a-plugin" in r.message]
+    assert len(hits) == 1, f"warned {len(hits)} times across 5 scans"

test/test_resource_monitor.py

@@ -127,67 +127,3 @@ class TestForceReload:
         fresh = mon.get_metrics_summary("p", force_reload=True)
         assert fresh["call_count"] == 7
         assert any(c.kwargs.get("memory_ttl") == 0 for c in cache.get.call_args_list)
-
-
-class TestMetricsPersistenceChurn:
-    """Metrics are telemetry; writing them on every call wore the SD card.
-
-    Each write is a ~350-byte file, which on ext4 costs a 4KB block plus a
-    journal entry. At roughly nine calls a minute per plugin across fourteen
-    plugins it dominated the device's write volume.
-    """
-
-    def test_repeated_calls_persist_once_per_interval(self):
-        cache = _cache()
-        mon = PluginResourceMonitor(cache, enable_monitoring=False)
-        for _ in range(50):
-            mon.monitor_call("p", lambda: None)
-        writes = [c for c in cache.set.call_args_list
-                  if c.args and str(c.args[0]).startswith("plugin_metrics:")]
-        assert len(writes) == 1, (
-            f"50 calls produced {len(writes)} metric writes; expected 1")
-
-    def test_the_interval_elapsing_allows_the_next_write(self, monkeypatch):
-        import src.plugin_system.resource_monitor as rm
-        cache = _cache()
-        mon = PluginResourceMonitor(cache, enable_monitoring=False)
-        mon.monitor_call("p", lambda: None)
-        # pretend the interval has passed
-        mon._metrics_persisted_at["p"] -= rm._METRICS_PERSIST_INTERVAL + 1
-        mon.monitor_call("p", lambda: None)
-        writes = [c for c in cache.set.call_args_list
-                  if c.args and str(c.args[0]).startswith("plugin_metrics:")]
-        assert len(writes) == 2
-
-    def test_in_memory_metrics_stay_exact_while_writes_are_skipped(self):
-        mon = PluginResourceMonitor(_cache(), enable_monitoring=False)
-        for _ in range(20):
-            mon.monitor_call("p", lambda: None)
-        assert mon.get_metrics("p").call_count == 20
-
-    def test_reset_lets_the_next_call_persist_immediately(self):
-        cache = _cache()
-        mon = PluginResourceMonitor(cache, enable_monitoring=False)
-        mon.monitor_call("p", lambda: None)
-        mon.reset_metrics("p")
-        mon.monitor_call("p", lambda: None)
-        writes = [c for c in cache.set.call_args_list
-                  if c.args and str(c.args[0]).startswith("plugin_metrics:")]
-        assert len(writes) == 2, "reset should clear the throttle timestamp"
-
-    def test_a_failed_write_does_not_buy_the_next_interval_of_silence(self):
-        """A set() that raises must not count as having persisted.
-
-        Marking the timestamp before the write would leave no snapshot in the
-        cache and still suppress the next 30 seconds of attempts.
-        """
-        cache = _cache()
-        cache.set.side_effect = [OSError("disk full"), None]
-        mon = PluginResourceMonitor(cache, enable_monitoring=False)
-        with pytest.raises(OSError):
-            mon.monitor_call("p", lambda: None)
-        # the very next call must try again rather than skip the interval
-        mon.monitor_call("p", lambda: None)
-        writes = [c for c in cache.set.call_args_list
-                  if c.args and str(c.args[0]).startswith("plugin_metrics:")]
-        assert len(writes) == 2, "a failed write should be retried, not skipped"