More work on pluggy.

src/cthulhu/cthulhu.py

@@ -1018,6 +1018,8 @@ class Cthulhu(GObject.Object):
         self.APIHelper = APIHelper(self)
         self.createCompatAPI()
         self.pluginSystemManager = plugin_system_manager.PluginSystemManager(self)
+        # Scan for available plugins at startup
+        self.pluginSystemManager.rescanPlugins()
     def getAPIHelper(self):
         return self.APIHelper
     def getPluginSystemManager(self):

src/cthulhu/plugin.py

@@ -16,6 +16,7 @@ try:
     import pluggy
     cthulhu_hookimpl = pluggy.HookimplMarker("cthulhu")
     PLUGGY_AVAILABLE = True
+    logging.getLogger(__name__).info("Successfully imported pluggy")
 except ImportError:
     # Fallback if pluggy is not available
     def cthulhu_hookimpl(func=None, **kwargs):
@@ -29,7 +30,9 @@ except ImportError:
             return lambda f: f
         return func
     PLUGGY_AVAILABLE = False
-    logging.getLogger(__name__).info("Pluggy not available, plugins will be disabled")
+    logging.getLogger(__name__).warning("Pluggy not available, plugins will be disabled")
+    import traceback
+    logging.getLogger(__name__).debug(traceback.format_exc())
 
 logger = logging.getLogger(__name__)
 

src/cthulhu/plugin_system_manager.py

@@ -22,7 +22,12 @@ except ImportError:
     PLUGGY_AVAILABLE = False
     logging.getLogger(__name__).info("Pluggy not available, plugins will be disabled")
 
+# Set to True for more detailed plugin loading debug info
+PLUGIN_DEBUG = True
+
 logger = logging.getLogger(__name__)
+if PLUGIN_DEBUG:
+    logger.setLevel(logging.DEBUG)
 
 class PluginType(IntEnum):
     """Types of plugins we support."""
@@ -74,9 +79,11 @@ class PluginSystemManager:
 
     def __init__(self, app):
         self.app = app
+        logger.info("Initializing PluginSystemManager")
 
         # Initialize plugin manager
         if PLUGGY_AVAILABLE:
+            logger.info("Pluggy is available, setting up plugin manager")
             self.plugin_manager = pluggy.PluginManager("cthulhu")
 
             # Define hook specifications
@@ -93,8 +100,10 @@ class PluginSystemManager:
                     """Called when the plugin is deactivated."""
                     pass
 
+            logger.info("Adding hook specifications to plugin manager")
             self.plugin_manager.add_hookspecs(CthulhuHookSpecs)
         else:
+            logger.warning("Pluggy is not available, plugins will be disabled")
             self.plugin_manager = None
 
         # Plugin storage
@@ -103,6 +112,10 @@ class PluginSystemManager:
 
         # Create plugin directories
         self._setup_plugin_dirs()
+        
+        # Log available plugins directory paths
+        logger.info(f"System plugins directory: {PluginType.SYSTEM.get_root_dir()}")
+        logger.info(f"User plugins directory: {PluginType.USER.get_root_dir()}")
 
     def _setup_plugin_dirs(self):
         """Ensure plugin directories exist."""
@@ -190,7 +203,25 @@ class PluginSystemManager:
 
     def setActivePlugins(self, activePlugins):
         """Set active plugins and sync their state."""
+        logger.info(f"Setting active plugins: {activePlugins}")
+        
+        # Make sure we have scanned for plugins first
+        if not self._plugins:
+            logger.info("No plugins found, rescanning...")
+            self.rescanPlugins()
+            
         self._active_plugins = activePlugins
+        
+        # Log active vs available plugins
+        available_plugins = [p.get_module_name() for p in self.plugins]
+        logger.info(f"Available plugins: {available_plugins}")
+        logger.info(f"Active plugins: {self._active_plugins}")
+        
+        # Find missing plugins
+        missing_plugins = [p for p in self._active_plugins if p not in available_plugins]
+        if missing_plugins:
+            logger.warning(f"Active plugins not found: {missing_plugins}")
+            
         self.syncAllPluginsActive()
 
     def setPluginActive(self, pluginInfo, active):
@@ -211,25 +242,52 @@ class PluginSystemManager:
 
     def isPluginActive(self, pluginInfo):
         """Check if a plugin is active."""
+        module_name = pluginInfo.get_module_name()
+        
+        # Builtin plugins are always active
         if pluginInfo.builtin:
+            logger.debug(f"Plugin {module_name} is builtin, active by default")
             return True
 
+        # If a plugin is already loaded, it's active
         if pluginInfo.loaded:
+            logger.debug(f"Plugin {module_name} is already loaded, considered active")
             return True
 
-        return pluginInfo.get_module_name() in self.getActivePlugins()
+        # Check if plugin is in the active plugins list
+        is_active = module_name in self.getActivePlugins()
+        logger.debug(f"Plugin {module_name} active status: {is_active}")
+        return is_active
 
     def syncAllPluginsActive(self):
         """Sync the active state of all plugins."""
+        logger.info("Syncing active state of all plugins")
+        
+        # Log plugin status before syncing
+        if PLUGIN_DEBUG:
+            for pluginInfo in self.plugins:
+                is_active = self.isPluginActive(pluginInfo)
+                is_loaded = pluginInfo.loaded
+                logger.debug(f"Plugin {pluginInfo.get_module_name()}: active={is_active}, loaded={is_loaded}")
+        
         # First unload inactive plugins
         for pluginInfo in self.plugins:
             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:
             if self.isPluginActive(pluginInfo) and not pluginInfo.loaded:
-                self.loadPlugin(pluginInfo)
+                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}")
+        
+        # Log final plugin status
+        active_plugins = [p.get_module_name() for p in self.plugins if p.loaded]
+        logger.info(f"Active plugins after sync: {active_plugins}")
+        inactive_plugins = [p.get_module_name() for p in self.plugins if not p.loaded]
+        logger.info(f"Inactive plugins after sync: {inactive_plugins}")
 
     def loadPlugin(self, pluginInfo):
         """Load a plugin."""
@@ -239,15 +297,26 @@ class PluginSystemManager:
             return False
 
         module_name = pluginInfo.get_module_name()
+        logger.info(f"Attempting to load plugin: {module_name}")
 
         try:
             # Already loaded?
             if pluginInfo.loaded:
+                logger.info(f"Plugin {module_name} already loaded, skipping")
                 return True
 
             # Import plugin module
             plugin_file = os.path.join(pluginInfo.get_module_dir(), "plugin.py")
+            if not os.path.exists(plugin_file):
+                logger.error(f"Plugin file not found: {plugin_file}")
+                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}")
+                return False
+                
             module = importlib.util.module_from_spec(spec)
             spec.loader.exec_module(module)
             pluginInfo.module = module
@@ -260,6 +329,7 @@ class PluginSystemManager:
                     attr.__module__ == module.__name__ and
                     hasattr(attr, 'activate')):
                     plugin_class = attr
+                    logger.info(f"Found plugin class: {attr.__name__} in {module_name}")
                     break
 
             if not plugin_class:
@@ -267,32 +337,47 @@ class PluginSystemManager:
                 return False
 
             # Create and initialize plugin instance
+            logger.info(f"Creating instance of plugin class: {plugin_class.__name__}")
             plugin_instance = plugin_class()
             pluginInfo.instance = plugin_instance
 
             # Ensure plugins have a reference to the app
             plugin_instance.app = self.getApp()
+            logger.info(f"Set app reference for plugin: {module_name}")
             
             if hasattr(plugin_instance, 'set_app'):
                 plugin_instance.set_app(self.getApp())
+                logger.info(f"Called set_app() for plugin: {module_name}")
 
             if hasattr(plugin_instance, 'set_plugin_info'):
                 plugin_instance.set_plugin_info(pluginInfo)
+                logger.info(f"Called set_plugin_info() for plugin: {module_name}")
 
             # Register with pluggy and activate
+            if self.plugin_manager is None:
+                logger.error(f"Plugin manager is None when loading {module_name}")
+                return False
+                
+            logger.info(f"Registering plugin with pluggy: {module_name}")
             self.plugin_manager.register(plugin_instance)
+            
             try:
+                logger.info(f"Activating plugin: {module_name}")
                 self.plugin_manager.hook.activate(plugin=plugin_instance)
             except Exception as e:
                 logger.error(f"Error activating plugin {module_name}: {e}")
+                import traceback
+                logger.error(traceback.format_exc())
                 return False
 
             pluginInfo.loaded = True
-            logger.info(f"Loaded plugin: {module_name}")
+            logger.info(f"Successfully loaded plugin: {module_name}")
             return True
 
         except Exception as e:
             logger.error(f"Failed to load plugin {module_name}: {e}")
+            import traceback
+            logger.error(traceback.format_exc())
             return False
 
     def unloadPlugin(self, pluginInfo):