diff --git a/core/debug_logger.py b/core/debug_logger.py new file mode 100644 index 0000000..05f267e --- /dev/null +++ b/core/debug_logger.py @@ -0,0 +1,141 @@ +""" +EU-Utility - Debug Logger + +Comprehensive debug logging with timing measurements for performance diagnosis. +""" + +import time +import functools +import traceback +from typing import Optional, Callable, Any +from pathlib import Path +from datetime import datetime + + +class DebugLogger: + """Debug logger with timing and performance tracking.""" + + _instance = None + + def __new__(cls): + if cls._instance is None: + cls._instance = super().__new__(cls) + cls._instance._initialized = False + return cls._instance + + def __init__(self): + if self._initialized: + return + self._initialized = True + self.enabled = True + self.log_file = None + self.start_times = {} + + # Create log file + log_dir = Path.home() / "Documents" / "Entropia Universe" / "Logs" + log_dir.mkdir(parents=True, exist_ok=True) + self.log_file = log_dir / f"eu-utility-debug-{datetime.now().strftime('%Y%m%d-%H%M%S')}.log" + + self._log("=" * 80) + self._log("EU-Utility Debug Log Started") + self._log(f"Log file: {self.log_file}") + self._log("=" * 80) + + def _log(self, message: str): + """Write log message to file and console.""" + timestamp = datetime.now().strftime("%H:%M:%S.%f")[:-3] + line = f"[{timestamp}] {message}" + + # Always print to console + print(line) + + # Write to file + if self.log_file: + try: + with open(self.log_file, 'a', encoding='utf-8') as f: + f.write(line + "\n") + except Exception as e: + print(f"[DebugLogger] Failed to write to log: {e}") + + def debug(self, component: str, message: str): + """Log debug message.""" + if self.enabled: + self._log(f"[DEBUG][{component}] {message}") + + def info(self, component: str, message: str): + """Log info message.""" + self._log(f"[INFO][{component}] {message}") + + def warn(self, component: str, message: str): + """Log warning message.""" + self._log(f"[WARN][{component}] {message}") + + def error(self, component: str, message: str, exc_info: bool = True): + """Log error message.""" + self._log(f"[ERROR][{component}] {message}") + if exc_info: + self._log(traceback.format_exc()) + + def start_timer(self, name: str): + """Start timing an operation.""" + self.start_times[name] = time.perf_counter() + self._log(f"[TIMER][START] {name}") + + def end_timer(self, name: str) -> float: + """End timing an operation and log duration.""" + if name not in self.start_times: + self._log(f"[TIMER][ERROR] No start time for: {name}") + return 0.0 + + elapsed = (time.perf_counter() - self.start_times[name]) * 1000 + self._log(f"[TIMER][END] {name}: {elapsed:.2f}ms") + del self.start_times[name] + return elapsed + + def log_stack(self, component: str, message: str = ""): + """Log current call stack for debugging.""" + self._log(f"[STACK][{component}] {message}") + stack = traceback.format_stack()[:-1] # Exclude this call + for line in stack[-5:]: # Last 5 frames + self._log(f" {line.strip()}") + + +# Global instance +debug_logger = DebugLogger() + + +def timed(component: str, operation: Optional[str] = None): + """Decorator to time function execution.""" + def decorator(func: Callable) -> Callable: + @functools.wraps(func) + def wrapper(*args, **kwargs) -> Any: + op_name = operation or func.__name__ + timer_name = f"{component}.{op_name}" + + debug_logger.start_timer(timer_name) + try: + result = func(*args, **kwargs) + return result + finally: + debug_logger.end_timer(timer_name) + + return wrapper + return decorator + + +def log_call(component: str): + """Decorator to log function calls.""" + def decorator(func: Callable) -> Callable: + @functools.wraps(func) + def wrapper(*args, **kwargs) -> Any: + debug_logger.debug(component, f"CALL {func.__name__}()") + try: + result = func(*args, **kwargs) + debug_logger.debug(component, f"RETURN {func.__name__}()") + return result + except Exception as e: + debug_logger.error(component, f"EXCEPTION in {func.__name__}: {e}") + raise + + return wrapper + return decorator diff --git a/core/main.py b/core/main.py index fb655c4..4fbc9e2 100644 --- a/core/main.py +++ b/core/main.py @@ -6,6 +6,7 @@ Launch the overlay, floating icon, dashboard, and plugin system. import sys import os +import time from pathlib import Path # Add project root to path @@ -13,12 +14,20 @@ project_root = Path(__file__).parent.parent if str(project_root) not in sys.path: sys.path.insert(0, str(project_root)) +# Import debug logger FIRST (before anything else) +from core.debug_logger import debug_logger, timed, log_call + +debug_logger.info("MAIN", "Starting EU-Utility...") +start_time = time.perf_counter() + try: from PyQt6.QtWidgets import QApplication from PyQt6.QtCore import Qt, QObject, pyqtSignal PYQT_AVAILABLE = True -except ImportError: + debug_logger.info("MAIN", "PyQt6 imported successfully") +except ImportError as e: PYQT_AVAILABLE = False + debug_logger.error("MAIN", f"PyQt6 import failed: {e}") print("Error: PyQt6 is required.") print("Install with: pip install PyQt6") sys.exit(1) @@ -26,11 +35,15 @@ except ImportError: try: import keyboard KEYBOARD_AVAILABLE = True + debug_logger.info("MAIN", "keyboard library imported") except ImportError: KEYBOARD_AVAILABLE = False + debug_logger.warn("MAIN", "keyboard library not available") print("Warning: 'keyboard' library not installed.") print("Global hotkeys won't work. Install with: pip install keyboard") +debug_logger.start_timer("imports") + from core.plugin_manager import PluginManager from core.perfect_ux import create_perfect_window from core.tray_icon import TrayIcon @@ -48,6 +61,8 @@ from core.event_bus import get_event_bus from core.tasks import get_task_manager from core.audio import get_audio_manager from core.clipboard import get_clipboard_manager + +debug_logger.end_timer("imports") from core.data_store import get_data_store @@ -73,65 +88,85 @@ class EUUtilityApp: def run(self): """Start the application.""" + debug_logger.start_timer("MAIN_run_total") + # Create Qt Application + debug_logger.start_timer("MAIN_create_app") self.app = QApplication(sys.argv) self.app.setQuitOnLastWindowClosed(False) + debug_logger.end_timer("MAIN_create_app") # Enable high DPI scaling (Qt6 has this enabled by default) - # This block is kept for backwards compatibility with Qt5 if ever needed if hasattr(Qt, 'AA_EnableHighDpiScaling'): - # In Qt6, this attribute is deprecated and always enabled - # The check prevents warnings on Qt6 while maintaining Qt5 compatibility try: self.app.setAttribute(Qt.ApplicationAttribute.AA_EnableHighDpiScaling) except (AttributeError, TypeError): - pass # Qt6+ doesn't need this + pass # Initialize Plugin API + debug_logger.start_timer("MAIN_init_api") print("Initializing Plugin API...") self.api = get_api() self._setup_api_services() + debug_logger.end_timer("MAIN_init_api") # Initialize Event Bus + debug_logger.start_timer("MAIN_init_eventbus") print("Initializing Event Bus...") self.event_bus = get_event_bus() self._print_event_bus_stats() + debug_logger.end_timer("MAIN_init_eventbus") # Initialize Notification Manager + debug_logger.start_timer("MAIN_init_notifications") print("Initializing Notification Manager...") self.notification_manager = get_notification_manager() self.notification_manager.initialize(self.app) self.api.register_notification_service(self.notification_manager) print("[Core] Notification service registered") + debug_logger.end_timer("MAIN_init_notifications") # Load settings + debug_logger.start_timer("MAIN_load_settings") self.settings = get_settings() + debug_logger.end_timer("MAIN_load_settings") # Create hotkey handler (must be in main thread) + debug_logger.start_timer("MAIN_init_hotkeys") self.hotkey_handler = HotkeyHandler() + debug_logger.end_timer("MAIN_init_hotkeys") # Initialize plugin manager + debug_logger.start_timer("MAIN_load_plugins") print("Loading plugins...") self.plugin_manager = PluginManager(None) self.plugin_manager.load_all_plugins() + debug_logger.end_timer("MAIN_load_plugins") # Create overlay manager + debug_logger.start_timer("MAIN_init_overlay_mgr") self.overlay_manager = OverlayManager(self.app) + debug_logger.end_timer("MAIN_init_overlay_mgr") # Create perfect UX main window + debug_logger.start_timer("MAIN_create_window") print("Creating main window with perfect UX...") self.dashboard = create_perfect_window(self.plugin_manager) self.plugin_manager.overlay = self.dashboard self.dashboard.show() + debug_logger.end_timer("MAIN_create_window") # Create system tray icon (replaces floating icon) + debug_logger.start_timer("MAIN_create_tray") print("Creating system tray icon...") self.tray_icon = TrayIcon(self.app) self.tray_icon.show_dashboard.connect(self._toggle_overlay) self.tray_icon.toggle_activity_bar.connect(self._toggle_activity_bar) self.tray_icon.quit_app.connect(self.quit) + debug_logger.end_timer("MAIN_create_tray") # Create Activity Bar (in-game overlay) - hidden by default + debug_logger.start_timer("MAIN_create_activitybar") print("Creating Activity Bar...") try: from core.activity_bar import get_activity_bar @@ -151,15 +186,24 @@ class EUUtilityApp: except Exception as e: print(f"[Core] Failed to create Activity Bar: {e}") self.activity_bar = None + debug_logger.end_timer("MAIN_create_activitybar") # Connect hotkey signals self.hotkey_handler.toggle_signal.connect(self._on_toggle_signal) # Setup global hotkeys + debug_logger.start_timer("MAIN_setup_hotkeys") self._setup_hotkeys() + debug_logger.end_timer("MAIN_setup_hotkeys") # Load saved overlay widgets + debug_logger.start_timer("MAIN_load_widgets") self._load_overlay_widgets() + debug_logger.end_timer("MAIN_load_widgets") + + # Log total startup time + total_startup = debug_logger.end_timer("MAIN_run_total") + debug_logger.info("MAIN", f"=== TOTAL STARTUP TIME: {total_startup:.2f}ms ===") print("EU-Utility started!") print("Dashboard window is open") @@ -172,6 +216,7 @@ class EUUtilityApp: self._print_event_bus_stats() # Run + debug_logger.info("MAIN", "Starting Qt event loop...") return self.app.exec() def _setup_api_services(self): @@ -369,56 +414,92 @@ class EUUtilityApp: def _toggle_overlay(self): """Toggle dashboard visibility.""" + debug_logger.start_timer("MAIN_toggle_overlay") + debug_logger.debug("MAIN", f"_toggle_overlay called, dashboard exists: {self.dashboard is not None}") + if self.dashboard: if self.dashboard.isVisible(): + debug_logger.debug("MAIN", "Hiding dashboard...") self.dashboard.hide() + debug_logger.debug("MAIN", "Dashboard hidden") else: + debug_logger.debug("MAIN", "Showing dashboard...") self.dashboard.show() + debug_logger.debug("MAIN", "Dashboard shown, calling raise_...") self.dashboard.raise_() + debug_logger.debug("MAIN", "Calling activateWindow...") self.dashboard.activateWindow() + debug_logger.debug("MAIN", "Dashboard activation complete") + else: + debug_logger.warn("MAIN", "Dashboard is None!") + + debug_logger.end_timer("MAIN_toggle_overlay") def _toggle_activity_bar(self): """Toggle activity bar visibility.""" + debug_logger.start_timer("MAIN_toggle_activity_bar") + debug_logger.debug("MAIN", f"_toggle_activity_bar called, activity_bar exists: {hasattr(self, 'activity_bar')}") + if hasattr(self, 'activity_bar') and self.activity_bar: try: if self.activity_bar.isVisible(): + debug_logger.debug("MAIN", "Hiding activity bar...") self.activity_bar.hide() if hasattr(self, 'tray_icon') and self.tray_icon: self.tray_icon.set_activity_bar_checked(False) + debug_logger.debug("MAIN", "Activity bar hidden") else: + debug_logger.debug("MAIN", "Showing activity bar...") self.activity_bar.show() if hasattr(self, 'tray_icon') and self.tray_icon: self.tray_icon.set_activity_bar_checked(True) + debug_logger.debug("MAIN", "Activity bar shown") except Exception as e: - print(f"[Main] Error toggling activity bar: {e}") + debug_logger.error("MAIN", f"Error toggling activity bar: {e}") else: - print("[Main] Activity Bar not available") + debug_logger.warn("MAIN", "Activity Bar not available") + + debug_logger.end_timer("MAIN_toggle_activity_bar") def _start_eu_focus_detection(self): """Start timer to detect EU window focus and show/hide activity bar.""" from PyQt6.QtCore import QTimer - self.eu_focus_timer = QTimer(self.app) # Use app as parent, not self + debug_logger.info("MAIN", "Starting EU focus detection...") + debug_logger.start_timer("MAIN_start_eu_focus") + + self.eu_focus_timer = QTimer(self.app) self.eu_focus_timer.timeout.connect(self._check_eu_focus) - self.eu_focus_timer.start(2000) # Check every 2 seconds (was 500ms - too frequent) + self.eu_focus_timer.start(5000) # Check every 5 seconds (reduced from 2s for debugging) self._last_eu_focused = False - print("[Core] EU focus detection started") + + debug_logger.end_timer("MAIN_start_eu_focus") + debug_logger.info("MAIN", "EU focus detection started (5s interval)") def _check_eu_focus(self): """Check if EU window is focused and show/hide activity bar.""" + debug_logger.start_timer("MAIN_check_eu_focus") + try: if not hasattr(self, 'activity_bar') or not self.activity_bar: + debug_logger.debug("MAIN", "No activity bar, skipping focus check") return if not hasattr(self, 'window_manager') or not self.window_manager: + debug_logger.debug("MAIN", "No window manager, skipping focus check") return if not self.window_manager.is_available(): + debug_logger.debug("MAIN", "Window manager not available, skipping") return + debug_logger.debug("MAIN", "Finding EU window...") eu_window = self.window_manager.find_eu_window() + if eu_window: + debug_logger.debug("MAIN", "EU window found, checking focus...") is_focused = eu_window.is_focused() + debug_logger.debug("MAIN", f"EU focused: {is_focused}, last: {getattr(self, '_last_eu_focused', None)}") if is_focused != getattr(self, '_last_eu_focused', False): self._last_eu_focused = is_focused @@ -427,25 +508,33 @@ class EUUtilityApp: # EU just got focused - show activity bar if not self.activity_bar.isVisible(): try: + debug_logger.debug("MAIN", "Showing activity bar (EU focused)") self.activity_bar.show() if hasattr(self, 'tray_icon') and self.tray_icon: self.tray_icon.set_activity_bar_checked(True) - print("[Core] EU focused - Activity Bar shown") + debug_logger.info("MAIN", "EU focused - Activity Bar shown") except Exception as e: - print(f"[Core] Error showing activity bar: {e}") + debug_logger.error("MAIN", f"Error showing activity bar: {e}") else: # EU lost focus - hide activity bar if self.activity_bar.isVisible(): try: + debug_logger.debug("MAIN", "Hiding activity bar (EU unfocused)") self.activity_bar.hide() if hasattr(self, 'tray_icon') and self.tray_icon: self.tray_icon.set_activity_bar_checked(False) - print("[Core] EU unfocused - Activity Bar hidden") + debug_logger.info("MAIN", "EU unfocused - Activity Bar hidden") except Exception as e: - print(f"[Core] Error hiding activity bar: {e}") + debug_logger.error("MAIN", f"Error hiding activity bar: {e}") + else: + debug_logger.debug("MAIN", "EU window not found") + except Exception as e: - # Silently ignore errors (EU window might not exist) - pass + debug_logger.error("MAIN", f"Error in EU focus check: {e}") + + elapsed = debug_logger.end_timer("MAIN_check_eu_focus") + if elapsed > 100: # Log if taking more than 100ms + debug_logger.warn("MAIN", f"EU focus check took {elapsed:.2f}ms - SLOW!") def _load_overlay_widgets(self): """Load saved overlay widgets.""" diff --git a/core/tray_icon.py b/core/tray_icon.py index bed03c4..ad8c66e 100644 --- a/core/tray_icon.py +++ b/core/tray_icon.py @@ -1,13 +1,29 @@ """ -EU-Utility - System Tray Icon (Simplified) -========================================== +EU-Utility - System Tray Icon (Debug Version) +============================================= -Simple, responsive system tray icon. +Simple, responsive system tray icon with debug logging. """ from PyQt6.QtWidgets import QSystemTrayIcon, QMenu, QApplication, QWidget from PyQt6.QtGui import QAction, QIcon, QColor, QPainter, QFont, QPixmap -from PyQt6.QtCore import pyqtSignal, Qt +from PyQt6.QtCore import pyqtSignal, Qt, QTimer + +# Import debug logger +try: + from core.debug_logger import debug_logger + DEBUG_AVAILABLE = True +except ImportError: + DEBUG_AVAILABLE = False + # Dummy logger + class DummyLogger: + def debug(self, *args): pass + def info(self, *args): pass + def warn(self, *args): pass + def error(self, *args): pass + def start_timer(self, *args): pass + def end_timer(self, *args): return 0.0 + debug_logger = DummyLogger() class TrayIcon(QWidget): @@ -19,20 +35,30 @@ class TrayIcon(QWidget): quit_app = pyqtSignal() def __init__(self, app: QApplication, parent=None): + debug_logger.start_timer("TrayIcon.__init__") super().__init__(parent) self.app = app + debug_logger.debug("TRAY", "Creating tray icon...") + # Create icon self._create_icon() # Create menu (but don't set it yet) + debug_logger.debug("TRAY", "Creating menu...") self._create_menu() # Connect signals + debug_logger.debug("TRAY", "Connecting signals...") self.tray_icon.activated.connect(self._on_activated) + + debug_logger.end_timer("TrayIcon.__init__") + debug_logger.info("TRAY", "Tray icon initialized") def _create_icon(self): """Create tray icon.""" + debug_logger.start_timer("TrayIcon._create_icon") + # Create simple icon px = QPixmap(64, 64) px.fill(QColor(255, 140, 66)) # Orange @@ -48,37 +74,105 @@ class TrayIcon(QWidget): self.tray_icon.setIcon(QIcon(px)) self.tray_icon.setToolTip("EU-Utility") self.tray_icon.show() + + debug_logger.end_timer("TrayIcon._create_icon") def _create_menu(self): """Create simple context menu.""" + debug_logger.start_timer("TrayIcon._create_menu") + self.menu = QMenu() + # Track menu timing + self.menu.aboutToShow.connect(self._on_menu_about_to_show) + self.menu.aboutToHide.connect(self._on_menu_about_to_hide) + # Simple actions (no emojis to avoid encoding issues) + debug_logger.debug("TRAY", "Creating Dashboard action...") self.dashboard_action = QAction("Dashboard", self) - self.dashboard_action.triggered.connect(self.show_dashboard.emit) + self.dashboard_action.triggered.connect(self._on_dashboard_clicked) self.menu.addAction(self.dashboard_action) + debug_logger.debug("TRAY", "Creating Activity Bar action...") self.activity_bar_action = QAction("Activity Bar", self) self.activity_bar_action.setCheckable(True) - self.activity_bar_action.triggered.connect(self.toggle_activity_bar.emit) + self.activity_bar_action.triggered.connect(self._on_activity_bar_clicked) self.menu.addAction(self.activity_bar_action) self.menu.addSeparator() + debug_logger.debug("TRAY", "Creating Quit action...") self.quit_action = QAction("Quit", self) - self.quit_action.triggered.connect(self.quit_app.emit) + self.quit_action.triggered.connect(self._on_quit_clicked) self.menu.addAction(self.quit_action) # Set context menu + debug_logger.debug("TRAY", "Setting context menu...") self.tray_icon.setContextMenu(self.menu) + + debug_logger.end_timer("TrayIcon._create_menu") + + def _on_menu_about_to_show(self): + """Called when menu is about to show.""" + debug_logger.start_timer("TRAY_MENU_SHOW") + debug_logger.debug("TRAY", "Menu about to show") + + def _on_menu_about_to_hide(self): + """Called when menu is about to hide.""" + elapsed = debug_logger.end_timer("TRAY_MENU_SHOW") + debug_logger.debug("TRAY", f"Menu was visible for {elapsed:.2f}ms") + + def _on_dashboard_clicked(self): + """Handle dashboard click with timing.""" + debug_logger.start_timer("TRAY_DASHBOARD_CLICK") + debug_logger.debug("TRAY", "Dashboard clicked - emitting signal...") + + # Use single shot to not block menu + QTimer.singleShot(0, self._emit_dashboard) + + def _emit_dashboard(self): + """Emit dashboard signal.""" + debug_logger.debug("TRAY", "Emitting show_dashboard signal...") + self.show_dashboard.emit() + debug_logger.end_timer("TRAY_DASHBOARD_CLICK") + + def _on_activity_bar_clicked(self): + """Handle activity bar click with timing.""" + debug_logger.start_timer("TRAY_ACTIVITYBAR_CLICK") + debug_logger.debug("TRAY", "Activity Bar clicked - emitting signal...") + + # Use single shot to not block menu + QTimer.singleShot(0, self._emit_activity_bar) + + def _emit_activity_bar(self): + """Emit activity bar signal.""" + debug_logger.debug("TRAY", "Emitting toggle_activity_bar signal...") + self.toggle_activity_bar.emit() + debug_logger.end_timer("TRAY_ACTIVITYBAR_CLICK") + + def _on_quit_clicked(self): + """Handle quit click with timing.""" + debug_logger.start_timer("TRAY_QUIT_CLICK") + debug_logger.debug("TRAY", "Quit clicked - emitting signal...") + + # Use single shot to not block menu + QTimer.singleShot(0, self._emit_quit) + + def _emit_quit(self): + """Emit quit signal.""" + debug_logger.debug("TRAY", "Emitting quit_app signal...") + self.quit_app.emit() + debug_logger.end_timer("TRAY_QUIT_CLICK") def show(self): """Show the tray icon.""" + debug_logger.debug("TRAY", "show() called") if self.tray_icon: self.tray_icon.show() def hide(self): """Hide the tray icon.""" + debug_logger.debug("TRAY", "hide() called") if self.tray_icon: self.tray_icon.hide() @@ -88,9 +182,12 @@ class TrayIcon(QWidget): def _on_activated(self, reason): """Handle double-click.""" + debug_logger.debug("TRAY", f"Activated with reason: {reason}") if reason == QSystemTrayIcon.ActivationReason.DoubleClick: + debug_logger.debug("TRAY", "Double-click detected - showing dashboard") self.show_dashboard.emit() def set_activity_bar_checked(self, checked: bool): """Update checkbox.""" + debug_logger.debug("TRAY", f"Setting Activity Bar checked: {checked}") self.activity_bar_action.setChecked(checked)