Fix to stop the screen reader from hanging when plugins fail.

src/cthulhu/cthulhuVersion.py

@@ -24,4 +24,4 @@
 # Original source: https://gitlab.gnome.org/GNOME/orca
 
 version = "2025.04.03"
-codeName = "testing"
+codeName = "plugins"

src/cthulhu/plugin_system_manager.py

@@ -12,6 +12,8 @@ import os
 import inspect
 import importlib.util
 import logging
+import threading
+import time
 from enum import IntEnum
 
 # Import pluggy if available
@@ -152,6 +154,8 @@ class PluginSystemManager:
                 self._plugins[name].instance = old_info.instance
                 self._plugins[name].module = old_info.module
         
+        logger.info(f"Rescanned plugins, found {len(self._plugins)} plugins")
+
     def _scan_plugins_in_directory(self, directory):
         """Scan for plugins in a directory."""
         if not os.path.exists(directory) or not os.path.isdir(directory):
@@ -159,6 +163,7 @@ class PluginSystemManager:
             return
 
         logger.info(f"Scanning for plugins in directory: {directory}")
+        try:
             for item in os.listdir(directory):
                 plugin_dir = os.path.join(directory, item)
                 if not os.path.isdir(plugin_dir):
@@ -197,6 +202,10 @@ class PluginSystemManager:
                     self._plugins[module_name] = plugin_info
                 else:
                     logger.warning(f"No plugin file found in directory: {plugin_dir}")
+        except Exception as e:
+            logger.error(f"Error scanning directory {directory}: {e}")
+            import traceback
+            logger.error(traceback.format_exc())
 
     def _load_plugin_metadata(self, metadata_file):
         """Load plugin metadata from a file."""
@@ -231,6 +240,10 @@ class PluginSystemManager:
             logger.info("No plugins found, rescanning...")
             self.rescanPlugins()
             
+            # Double-check we found plugins after rescanning
+            if not self._plugins and activePlugins:
+                logger.warning("No plugins found after rescanning but active plugins requested. Continuing anyway.")
+        
         self._active_plugins = activePlugins
         
         # Log active vs available plugins
@@ -243,7 +256,12 @@ class PluginSystemManager:
         if missing_plugins:
             logger.warning(f"Active plugins not found: {missing_plugins}")
         
+        try:    
             self.syncAllPluginsActive()
+        except Exception as e:
+            logger.error(f"Error syncing plugins: {e}")
+            import traceback
+            logger.error(traceback.format_exc())
 
     def setPluginActive(self, pluginInfo, active):
         """Set the active state of a plugin."""
@@ -303,6 +321,11 @@ class PluginSystemManager:
             logger.warning("Pluggy not available, skipping plugin sync")
             return
         
+        # Skip if no plugins found - don't waste time trying to sync nothing
+        if not self._plugins:
+            logger.warning("No plugins found, skipping plugin sync")
+            return
+            
         # Log plugin status before syncing
         if PLUGIN_DEBUG:
             for pluginInfo in self.plugins:
@@ -311,15 +334,17 @@ class PluginSystemManager:
                 logger.debug(f"Plugin {pluginInfo.get_module_name()}: active={is_active}, loaded={is_loaded}")
         
         try:
+            # Create plans first, then execute to avoid changing collection during iteration
+            to_unload = [p for p in self.plugins if not self.isPluginActive(p) and p.loaded]
+            to_load = [p for p in self.plugins if self.isPluginActive(p) and not p.loaded]
+            
             # First unload inactive plugins
-            for pluginInfo in self.plugins:
+            for pluginInfo in to_unload:
-                if not self.isPluginActive(pluginInfo) and pluginInfo.loaded:
                 logger.info(f"Unloading inactive plugin: {pluginInfo.get_module_name()}")
                 self.unloadPlugin(pluginInfo)
 
             # Then load active plugins
-            for pluginInfo in self.plugins:
+            for pluginInfo in to_load:
-                if self.isPluginActive(pluginInfo) and not pluginInfo.loaded:
                 logger.info(f"Loading active plugin: {pluginInfo.get_module_name()}")
                 result = self.loadPlugin(pluginInfo)
                 logger.info(f"Plugin {pluginInfo.get_module_name()} load result: {result}")
@@ -342,12 +367,25 @@ class PluginSystemManager:
             return False
 
         module_name = pluginInfo.get_module_name()
-        logger.info(f"Attempting to load plugin: {module_name}")
+        logger.debug(f"===== PLUGIN LOADING START: {module_name} =====")
+
+        # Setup timeout for plugin loading
+        load_timeout = 5  # seconds
+        load_completed = False
+
+        def timeout_handler():
+            nonlocal load_completed
+            if not load_completed:
+                logger.error(f"Plugin loading timed out for {module_name}")
+
+        timer = threading.Timer(load_timeout, timeout_handler)
+        timer.start()
 
         try:
             # Already loaded?
             if pluginInfo.loaded:
                 logger.info(f"Plugin {module_name} already loaded, skipping")
+                load_completed = True
                 return True
 
             # Try to find the plugin file
@@ -366,12 +404,14 @@ class PluginSystemManager:
             
             if not os.path.exists(plugin_file):
                 logger.error(f"Plugin file not found: {plugin_file}")
+                load_completed = True
                 return False
                 
             logger.info(f"Loading plugin from: {plugin_file}")
             spec = importlib.util.spec_from_file_location(module_name, plugin_file)
             if spec is None:
                 logger.error(f"Failed to create spec for plugin: {module_name}")
+                load_completed = True
                 return False
                 
             module = importlib.util.module_from_spec(spec)
@@ -391,6 +431,7 @@ class PluginSystemManager:
 
             if not plugin_class:
                 logger.error(f"No plugin class found in {module_name}")
+                load_completed = True
                 return False
 
             # Create and initialize plugin instance
@@ -410,9 +451,15 @@ class PluginSystemManager:
                 plugin_instance.set_plugin_info(pluginInfo)
                 logger.info(f"Called set_plugin_info() for plugin: {module_name}")
 
+            # Log plugin methods for debugging
+            if PLUGIN_DEBUG:
+                logger.debug(f"Plugin instance methods: {[m for m in dir(plugin_instance) if not m.startswith('_')]}")
+                logger.debug(f"Checking for activate method: {'activate' in dir(plugin_instance)}")
+
             # Register with pluggy and activate
             if self.plugin_manager is None:
                 logger.error(f"Plugin manager is None when loading {module_name}")
+                load_completed = True
                 return False
                 
             logger.info(f"Registering plugin with pluggy: {module_name}")
@@ -425,17 +472,23 @@ class PluginSystemManager:
                 logger.error(f"Error activating plugin {module_name}: {e}")
                 import traceback
                 logger.error(traceback.format_exc())
+                load_completed = True
                 return False
 
             pluginInfo.loaded = True
-            logger.info(f"Successfully loaded plugin: {module_name}")
+            logger.debug(f"===== PLUGIN LOADING SUCCESS: {module_name} =====")
+            load_completed = True
             return True
 
         except Exception as e:
             logger.error(f"Failed to load plugin {module_name}: {e}")
             import traceback
             logger.error(traceback.format_exc())
+            logger.debug(f"===== PLUGIN LOADING FAILED: {module_name} =====")
+            load_completed = True
             return False
+        finally:
+            timer.cancel()
 
     def unloadPlugin(self, pluginInfo):
         """Unload a plugin."""