EU-Utility/core/debug_logger.py

142 lines
4.5 KiB
Python

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