462 lines
14 KiB
Python
462 lines
14 KiB
Python
"""
|
|
EU-Utility - Debug Toolbar
|
|
|
|
Provides debugging utilities, logging, and diagnostics for development.
|
|
Part of the developer experience improvements.
|
|
"""
|
|
|
|
import sys
|
|
import time
|
|
import logging
|
|
import functools
|
|
import traceback
|
|
from pathlib import Path
|
|
from typing import Dict, List, Optional, Callable, Any
|
|
from datetime import datetime
|
|
from dataclasses import dataclass, field, asdict
|
|
import json
|
|
import threading
|
|
|
|
|
|
@dataclass
|
|
class DebugEvent:
|
|
"""A single debug event entry."""
|
|
timestamp: str
|
|
level: str
|
|
source: str
|
|
message: str
|
|
details: Dict[str, Any] = field(default_factory=dict)
|
|
traceback: Optional[str] = None
|
|
|
|
|
|
class DebugLogger:
|
|
"""
|
|
Structured logging system for EU-Utility.
|
|
|
|
Features:
|
|
- Multiple log levels (DEBUG, INFO, WARNING, ERROR, CRITICAL)
|
|
- Source tracking (which plugin/component)
|
|
- Structured data attachments
|
|
- File and console output
|
|
- Log rotation
|
|
"""
|
|
|
|
_instance = None
|
|
_lock = threading.Lock()
|
|
|
|
LEVELS = {
|
|
'DEBUG': 10,
|
|
'INFO': 20,
|
|
'WARNING': 30,
|
|
'ERROR': 40,
|
|
'CRITICAL': 50
|
|
}
|
|
|
|
def __new__(cls):
|
|
if cls._instance is None:
|
|
with cls._lock:
|
|
if cls._instance is None:
|
|
cls._instance = super().__new__(cls)
|
|
cls._instance._initialized = False
|
|
return cls._instance
|
|
|
|
def __init__(self, log_dir: Path = None, min_level: str = 'INFO'):
|
|
if self._initialized:
|
|
return
|
|
|
|
self._initialized = True
|
|
self._log_dir = log_dir or Path('logs')
|
|
self._log_dir.mkdir(parents=True, exist_ok=True)
|
|
self._min_level = self.LEVELS.get(min_level, 20)
|
|
self._events: List[DebugEvent] = []
|
|
self._max_events = 1000
|
|
self._listeners: List[Callable[[DebugEvent], None]] = []
|
|
self._lock = threading.Lock()
|
|
|
|
# Setup file logging
|
|
self._setup_file_handler()
|
|
|
|
# Console output
|
|
self._console_output = True
|
|
|
|
def _setup_file_handler(self):
|
|
"""Setup file handler for persistent logging."""
|
|
timestamp = datetime.now().strftime('%Y%m%d')
|
|
self._log_file = self._log_dir / f'eu-utility-{timestamp}.log'
|
|
|
|
# Create file with header
|
|
if not self._log_file.exists():
|
|
with open(self._log_file, 'w') as f:
|
|
f.write(f"# EU-Utility Debug Log - {datetime.now().isoformat()}\n")
|
|
f.write("#" * 60 + "\n\n")
|
|
|
|
def _should_log(self, level: str) -> bool:
|
|
"""Check if level should be logged based on min_level."""
|
|
return self.LEVELS.get(level, 20) >= self._min_level
|
|
|
|
def _format_message(self, event: DebugEvent) -> str:
|
|
"""Format event for console/file output."""
|
|
timestamp = event.timestamp.split('T')[1].split('.')[0]
|
|
prefix = f"[{timestamp}] [{event.level:8}] [{event.source:20}]"
|
|
|
|
if event.details:
|
|
details_str = json.dumps(event.details, default=str)
|
|
return f"{prefix} {event.message} | {details_str}"
|
|
return f"{prefix} {event.message}"
|
|
|
|
def _write_to_file(self, event: DebugEvent):
|
|
"""Write event to log file."""
|
|
try:
|
|
with open(self._log_file, 'a') as f:
|
|
f.write(self._format_message(event) + '\n')
|
|
if event.traceback:
|
|
f.write(f"TRACEBACK:\n{event.traceback}\n")
|
|
f.write("-" * 60 + "\n")
|
|
except Exception as e:
|
|
print(f"[DebugLogger] Failed to write to file: {e}")
|
|
|
|
def _notify_listeners(self, event: DebugEvent):
|
|
"""Notify all registered listeners."""
|
|
for listener in self._listeners:
|
|
try:
|
|
listener(event)
|
|
except Exception as e:
|
|
print(f"[DebugLogger] Listener error: {e}")
|
|
|
|
def log(self, level: str, source: str, message: str, **details):
|
|
"""
|
|
Log a message with structured data.
|
|
|
|
Args:
|
|
level: Log level (DEBUG, INFO, WARNING, ERROR, CRITICAL)
|
|
source: Source component (plugin name, module, etc.)
|
|
message: Log message
|
|
**details: Additional structured data
|
|
"""
|
|
if not self._should_log(level):
|
|
return
|
|
|
|
event = DebugEvent(
|
|
timestamp=datetime.now().isoformat(),
|
|
level=level,
|
|
source=source,
|
|
message=message,
|
|
details=details
|
|
)
|
|
|
|
with self._lock:
|
|
self._events.append(event)
|
|
if len(self._events) > self._max_events:
|
|
self._events.pop(0)
|
|
|
|
# Console output
|
|
if self._console_output:
|
|
color = self._get_color(level)
|
|
reset = '\033[0m'
|
|
print(f"{color}{self._format_message(event)}{reset}")
|
|
|
|
# File output
|
|
self._write_to_file(event)
|
|
|
|
# Notify listeners
|
|
self._notify_listeners(event)
|
|
|
|
def _get_color(self, level: str) -> str:
|
|
"""Get ANSI color code for log level."""
|
|
colors = {
|
|
'DEBUG': '\033[36m', # Cyan
|
|
'INFO': '\033[32m', # Green
|
|
'WARNING': '\033[33m', # Yellow
|
|
'ERROR': '\033[31m', # Red
|
|
'CRITICAL': '\033[35m', # Magenta
|
|
}
|
|
return colors.get(level, '\033[0m')
|
|
|
|
# Convenience methods
|
|
def debug(self, source: str, message: str, **details):
|
|
"""Log debug message."""
|
|
self.log('DEBUG', source, message, **details)
|
|
|
|
def info(self, source: str, message: str, **details):
|
|
"""Log info message."""
|
|
self.log('INFO', source, message, **details)
|
|
|
|
def warning(self, source: str, message: str, **details):
|
|
"""Log warning message."""
|
|
self.log('WARNING', source, message, **details)
|
|
|
|
def error(self, source: str, message: str, exception: Exception = None, **details):
|
|
"""Log error message with optional exception."""
|
|
tb = None
|
|
if exception:
|
|
tb = ''.join(traceback.format_exception(type(exception), exception, exception.__traceback__))
|
|
|
|
event = DebugEvent(
|
|
timestamp=datetime.now().isoformat(),
|
|
level='ERROR',
|
|
source=source,
|
|
message=message,
|
|
details=details,
|
|
traceback=tb
|
|
)
|
|
|
|
with self._lock:
|
|
self._events.append(event)
|
|
|
|
if self._console_output:
|
|
print(f"\033[31m{self._format_message(event)}\033[0m")
|
|
|
|
self._write_to_file(event)
|
|
self._notify_listeners(event)
|
|
|
|
def critical(self, source: str, message: str, exception: Exception = None, **details):
|
|
"""Log critical message."""
|
|
tb = None
|
|
if exception:
|
|
tb = ''.join(traceback.format_exception(type(exception), exception, exception.__traceback__))
|
|
|
|
event = DebugEvent(
|
|
timestamp=datetime.now().isoformat(),
|
|
level='CRITICAL',
|
|
source=source,
|
|
message=message,
|
|
details=details,
|
|
traceback=tb
|
|
)
|
|
|
|
with self._lock:
|
|
self._events.append(event)
|
|
|
|
if self._console_output:
|
|
print(f"\033[35m{self._format_message(event)}\033[0m")
|
|
|
|
self._write_to_file(event)
|
|
self._notify_listeners(event)
|
|
|
|
def get_events(self, level: str = None, source: str = None, limit: int = None) -> List[DebugEvent]:
|
|
"""
|
|
Get logged events with optional filtering.
|
|
|
|
Args:
|
|
level: Filter by log level
|
|
source: Filter by source
|
|
limit: Maximum number of events
|
|
"""
|
|
with self._lock:
|
|
events = self._events.copy()
|
|
|
|
if level:
|
|
events = [e for e in events if e.level == level]
|
|
if source:
|
|
events = [e for e in events if e.source == source]
|
|
|
|
if limit:
|
|
events = events[-limit:]
|
|
|
|
return events
|
|
|
|
def add_listener(self, callback: Callable[[DebugEvent], None]):
|
|
"""Add a listener for real-time log events."""
|
|
self._listeners.append(callback)
|
|
|
|
def remove_listener(self, callback: Callable[[DebugEvent], None]):
|
|
"""Remove a listener."""
|
|
if callback in self._listeners:
|
|
self._listeners.remove(callback)
|
|
|
|
def set_min_level(self, level: str):
|
|
"""Set minimum log level."""
|
|
self._min_level = self.LEVELS.get(level, 20)
|
|
|
|
def clear(self):
|
|
"""Clear in-memory events."""
|
|
with self._lock:
|
|
self._events.clear()
|
|
|
|
def export_json(self, path: Path = None) -> Path:
|
|
"""Export events to JSON file."""
|
|
path = path or self._log_dir / f'export-{datetime.now().strftime("%Y%m%d-%H%M%S")}.json'
|
|
with self._lock:
|
|
data = [asdict(e) for e in self._events]
|
|
|
|
with open(path, 'w') as f:
|
|
json.dump(data, f, indent=2)
|
|
|
|
return path
|
|
|
|
|
|
# Global logger instance
|
|
def get_logger() -> DebugLogger:
|
|
"""Get the global debug logger instance."""
|
|
return DebugLogger()
|
|
|
|
|
|
class DebugToolbar:
|
|
"""
|
|
Debug toolbar for EU-Utility development.
|
|
|
|
Features:
|
|
- Performance profiling
|
|
- Plugin diagnostics
|
|
- System information
|
|
- Hot reload monitoring
|
|
"""
|
|
|
|
def __init__(self):
|
|
self.logger = get_logger()
|
|
self._profiling_data: Dict[str, Dict] = {}
|
|
self._start_times: Dict[str, float] = {}
|
|
|
|
def profile(self, name: str):
|
|
"""Context manager for profiling code blocks."""
|
|
return ProfileContext(self, name)
|
|
|
|
def start_timer(self, name: str):
|
|
"""Start a named timer."""
|
|
self._start_times[name] = time.perf_counter()
|
|
|
|
def end_timer(self, name: str) -> float:
|
|
"""End a named timer and return elapsed time."""
|
|
if name not in self._start_times:
|
|
self.logger.warning('DebugToolbar', f'Timer "{name}" not started')
|
|
return 0.0
|
|
|
|
elapsed = time.perf_counter() - self._start_times[name]
|
|
del self._start_times[name]
|
|
|
|
# Store profiling data
|
|
if name not in self._profiling_data:
|
|
self._profiling_data[name] = {'count': 0, 'total': 0, 'min': float('inf'), 'max': 0}
|
|
|
|
data = self._profiling_data[name]
|
|
data['count'] += 1
|
|
data['total'] += elapsed
|
|
data['min'] = min(data['min'], elapsed)
|
|
data['max'] = max(data['max'], elapsed)
|
|
data['avg'] = data['total'] / data['count']
|
|
|
|
self.logger.debug('DebugToolbar', f'Profile: {name}', elapsed_ms=round(elapsed * 1000, 2))
|
|
|
|
return elapsed
|
|
|
|
def get_profile_summary(self) -> Dict[str, Dict]:
|
|
"""Get profiling summary."""
|
|
return self._profiling_data.copy()
|
|
|
|
def get_system_info(self) -> Dict[str, Any]:
|
|
"""Get system information."""
|
|
import platform
|
|
|
|
return {
|
|
'python_version': platform.python_version(),
|
|
'platform': platform.platform(),
|
|
'processor': platform.processor(),
|
|
'machine': platform.machine(),
|
|
'node': platform.node(),
|
|
}
|
|
|
|
def print_summary(self):
|
|
"""Print debug summary to console."""
|
|
print("\n" + "=" * 60)
|
|
print("DEBUG TOOLBAR SUMMARY")
|
|
print("=" * 60)
|
|
|
|
# System info
|
|
print("\n📊 System Information:")
|
|
for key, value in self.get_system_info().items():
|
|
print(f" {key}: {value}")
|
|
|
|
# Profiling data
|
|
if self._profiling_data:
|
|
print("\n⏱️ Performance Profile:")
|
|
print(f" {'Name':<30} {'Count':>8} {'Avg (ms)':>10} {'Min (ms)':>10} {'Max (ms)':>10}")
|
|
print(" " + "-" * 70)
|
|
for name, data in sorted(self._profiling_data.items()):
|
|
avg_ms = data.get('avg', 0) * 1000
|
|
min_ms = data.get('min', 0) * 1000
|
|
max_ms = data.get('max', 0) * 1000
|
|
print(f" {name:<30} {data['count']:>8} {avg_ms:>10.2f} {min_ms:>10.2f} {max_ms:>10.2f}")
|
|
|
|
# Recent errors
|
|
errors = self.logger.get_events(level='ERROR', limit=5)
|
|
if errors:
|
|
print("\n❌ Recent Errors:")
|
|
for event in errors:
|
|
print(f" [{event.timestamp}] {event.source}: {event.message}")
|
|
|
|
print("\n" + "=" * 60)
|
|
|
|
|
|
class ProfileContext:
|
|
"""Context manager for profiling."""
|
|
|
|
def __init__(self, toolbar: DebugToolbar, name: str):
|
|
self.toolbar = toolbar
|
|
self.name = name
|
|
|
|
def __enter__(self):
|
|
self.toolbar.start_timer(self.name)
|
|
return self
|
|
|
|
def __exit__(self, exc_type, exc_val, exc_tb):
|
|
elapsed = self.toolbar.end_timer(self.name)
|
|
if exc_val:
|
|
self.toolbar.logger.error(
|
|
'DebugToolbar',
|
|
f'Exception in profiled block "{self.name}"',
|
|
exception=exc_val
|
|
)
|
|
|
|
|
|
def log_call(func: Callable) -> Callable:
|
|
"""Decorator to log function calls."""
|
|
@functools.wraps(func)
|
|
def wrapper(*args, **kwargs):
|
|
logger = get_logger()
|
|
source = func.__module__
|
|
|
|
logger.debug(source, f'Calling {func.__name__}', args=len(args), kwargs=len(kwargs))
|
|
|
|
try:
|
|
result = func(*args, **kwargs)
|
|
logger.debug(source, f'{func.__name__} completed successfully')
|
|
return result
|
|
except Exception as e:
|
|
logger.error(source, f'{func.__name__} failed', exception=e)
|
|
raise
|
|
|
|
return wrapper
|
|
|
|
|
|
def debug_on_error(func: Callable) -> Callable:
|
|
"""Decorator that enters pdb on exception."""
|
|
@functools.wraps(func)
|
|
def wrapper(*args, **kwargs):
|
|
try:
|
|
return func(*args, **kwargs)
|
|
except Exception as e:
|
|
logger = get_logger()
|
|
logger.error('debug_on_error', f'Exception in {func.__name__}', exception=e)
|
|
|
|
import pdb
|
|
pdb.post_mortem()
|
|
raise
|
|
|
|
return wrapper
|
|
|
|
|
|
# Convenience functions
|
|
def debug_print(message: str, **data):
|
|
"""Quick debug print with structured data."""
|
|
get_logger().debug('debug_print', message, **data)
|
|
|
|
|
|
def info_print(message: str, **data):
|
|
"""Quick info print with structured data."""
|
|
get_logger().info('info_print', message, **data)
|
|
|
|
|
|
def error_print(message: str, exception: Exception = None, **data):
|
|
"""Quick error print with structured data."""
|
|
get_logger().error('error_print', message, exception=exception, **data)
|