""" Comprehensive logging and telemetry system for MorphGuard. This module provides centralized logging, performance metrics tracking, and telemetry data collection for monitoring and analysis. """ import logging import time import json import os import sys import socket import uuid import threading import platform import psutil import queue from typing import Dict, Any, Optional, List, Callable, Union from datetime import datetime import traceback import atexit from contextlib import contextmanager from enum import Enum # Import local error handling module from error_handling import MGError, ErrorCode, ErrorSeverity, ErrorCategory class LogLevel(Enum): """Log levels for telemetry events.""" DEBUG = "debug" INFO = "info" WARNING = "warning" ERROR = "error" CRITICAL = "critical" class MetricType(Enum): """Types of metrics that can be tracked.""" COUNTER = "counter" GAUGE = "gauge" HISTOGRAM = "histogram" SUMMARY = "summary" TIMER = "timer" class EventCategory(Enum): """Categories of telemetry events.""" API = "api" AUTHENTICATION = "authentication" DETECTION = "detection" DEMORPHING = "demorphing" DATABASE = "database" FILE = "file" MODEL = "model" PERFORMANCE = "performance" SECURITY = "security" USER = "user" SYSTEM = "system" ERROR = "error" class TelemetryManager: """ Central manager for logging, metrics, and telemetry. This class provides: - Structured logging with context - Performance metrics tracking - System resource monitoring - Telemetry event collection - Integration with external monitoring systems """ def __init__( self, app_name: str = "morphguard", log_dir: Optional[str] = None, telemetry_dir: Optional[str] = None, log_level: int = logging.INFO, console_logging: bool = True, file_logging: bool = True, json_logging: bool = False, system_metrics_interval: int = 60, enable_telemetry: bool = True, max_queue_size: int = 1000, flush_interval: int = 5, export_metrics: bool = False, metrics_exporter: Optional[str] = None ): """ Initialize the telemetry manager. Args: app_name: Application name for logs and metrics log_dir: Directory to store log files telemetry_dir: Directory to store telemetry data log_level: Default log level console_logging: Whether to log to console file_logging: Whether to log to file json_logging: Whether to use JSON format for logs system_metrics_interval: Interval for system metrics collection in seconds enable_telemetry: Whether to collect telemetry data max_queue_size: Maximum size of telemetry event queue flush_interval: Interval to flush telemetry queue in seconds export_metrics: Whether to export metrics to external systems metrics_exporter: Type of metrics exporter (prometheus, influxdb, etc.) """ self.app_name = app_name self.log_dir = log_dir self.telemetry_dir = telemetry_dir self.console_logging = console_logging self.file_logging = file_logging self.json_logging = json_logging self.enable_telemetry = enable_telemetry self.export_metrics = export_metrics self.metrics_exporter = metrics_exporter self.max_queue_size = max_queue_size self.flush_interval = flush_interval # Create directories if needed if log_dir and not os.path.exists(log_dir): os.makedirs(log_dir) if telemetry_dir and not os.path.exists(telemetry_dir): os.makedirs(telemetry_dir) # Setup main logger self.logger = self._setup_logger(log_level) # Metrics storage self.metrics: Dict[str, Dict[str, Any]] = { "counters": {}, "gauges": {}, "histograms": {}, "summaries": {}, "timers": {} } # Context for logs and telemetry self.global_context: Dict[str, Any] = { "host": socket.gethostname(), "app_name": app_name, "instance_id": str(uuid.uuid4()), "platform": platform.system(), "python_version": platform.python_version(), "start_time": datetime.utcnow().isoformat() } # Thread-local storage for context self.context = threading.local() self.context.values = {} # Telemetry queue and worker thread self.telemetry_queue: queue.Queue = queue.Queue(maxsize=max_queue_size) self.telemetry_thread: Optional[threading.Thread] = None # System metrics thread self.system_metrics_interval = system_metrics_interval self.system_metrics_thread: Optional[threading.Thread] = None # Locks self.metrics_lock = threading.RLock() # Start telemetry worker if enabled if enable_telemetry: self._start_telemetry_worker() self._start_system_metrics_collector() # Register cleanup on exit atexit.register(self.shutdown) # Log startup self.info("Telemetry system initialized", category=EventCategory.SYSTEM, context={"telemetry_enabled": enable_telemetry}) def _setup_logger(self, log_level: int) -> logging.Logger: """ Set up the main logger. Args: log_level: Default log level Returns: Configured logger """ logger = logging.getLogger(self.app_name) logger.setLevel(log_level) logger.propagate = False # Clear existing handlers if logger.handlers: for handler in logger.handlers: logger.removeHandler(handler) # Formatter if self.json_logging: formatter = self._json_formatter else: formatter = logging.Formatter( '%(asctime)s [%(levelname)s] [%(name)s] %(message)s', datefmt='%Y-%m-%d %H:%M:%S' ) # Console handler if self.console_logging: console_handler = logging.StreamHandler(sys.stdout) console_handler.setFormatter(formatter) logger.addHandler(console_handler) # File handler if self.file_logging and self.log_dir: log_file = os.path.join(self.log_dir, f"{self.app_name}.log") file_handler = logging.FileHandler(log_file) file_handler.setFormatter(formatter) logger.addHandler(file_handler) # Also create error log error_log_file = os.path.join(self.log_dir, f"{self.app_name}_error.log") error_handler = logging.FileHandler(error_log_file) error_handler.setLevel(logging.ERROR) error_handler.setFormatter(formatter) logger.addHandler(error_handler) return logger def _json_formatter(self, record: logging.LogRecord) -> str: """ Format log record as JSON. Args: record: Log record to format Returns: JSON string """ timestamp = datetime.fromtimestamp(record.created).isoformat() # Basic log data log_data = { "timestamp": timestamp, "level": record.levelname, "logger": record.name, "message": record.getMessage(), "module": record.module, "function": record.funcName, "line": record.lineno } # Add context if available context = getattr(record, 'context', None) if context: log_data["context"] = context # Add exception info if available if record.exc_info: log_data["exception"] = { "type": record.exc_info[0].__name__, "message": str(record.exc_info[1]), "traceback": traceback.format_exception(*record.exc_info) } return json.dumps(log_data) def _start_telemetry_worker(self) -> None: """Start the background telemetry worker thread.""" self.telemetry_thread = threading.Thread( target=self._telemetry_worker, daemon=True, name="telemetry_worker" ) self.telemetry_thread.start() def _telemetry_worker(self) -> None: """Background worker to process and export telemetry events.""" while True: try: # Wait for the flush interval time.sleep(self.flush_interval) # Process all events in the queue events = [] while not self.telemetry_queue.empty(): try: event = self.telemetry_queue.get_nowait() events.append(event) self.telemetry_queue.task_done() except queue.Empty: break if events: self._export_events(events) except Exception as e: # Log the error but keep the thread running self.logger.error(f"Error in telemetry worker: {e}", exc_info=True) def _export_events(self, events: List[Dict[str, Any]]) -> None: """ Export telemetry events to storage or external systems. Args: events: List of telemetry events to export """ if not events: return # Save to file if telemetry directory is configured if self.telemetry_dir: timestamp = datetime.utcnow().strftime("%Y%m%d_%H%M%S") file_path = os.path.join(self.telemetry_dir, f"telemetry_{timestamp}.json") try: with open(file_path, "w") as f: json.dump(events, f) except Exception as e: self.logger.error(f"Failed to save telemetry events: {e}", exc_info=True) # Add exporters for other systems here (e.g. Prometheus, InfluxDB, etc.) if self.export_metrics and self.metrics_exporter: if self.metrics_exporter.lower() == "prometheus": self._export_to_prometheus(events) elif self.metrics_exporter.lower() == "influxdb": self._export_to_influxdb(events) def _export_to_prometheus(self, events: List[Dict[str, Any]]) -> None: """ Export metrics to Prometheus. Args: events: List of telemetry events to export """ # Placeholder for Prometheus export pass def _export_to_influxdb(self, events: List[Dict[str, Any]]) -> None: """ Export metrics to InfluxDB. Args: events: List of telemetry events to export """ # Placeholder for InfluxDB export pass def _start_system_metrics_collector(self) -> None: """Start the background system metrics collector thread.""" self.system_metrics_thread = threading.Thread( target=self._system_metrics_collector, daemon=True, name="system_metrics_collector" ) self.system_metrics_thread.start() def _system_metrics_collector(self) -> None: """Background worker to collect system metrics periodically.""" while True: try: # Collect system metrics self._collect_system_metrics() # Wait for the next collection interval time.sleep(self.system_metrics_interval) except Exception as e: # Log the error but keep the thread running self.logger.error(f"Error in system metrics collector: {e}", exc_info=True) time.sleep(self.system_metrics_interval) def _collect_system_metrics(self) -> None: """Collect system metrics and record them.""" try: # CPU usage cpu_percent = psutil.cpu_percent(interval=1) self.gauge("system.cpu.percent", cpu_percent) # Memory usage memory = psutil.virtual_memory() self.gauge("system.memory.total", memory.total) self.gauge("system.memory.available", memory.available) self.gauge("system.memory.used", memory.used) self.gauge("system.memory.percent", memory.percent) # Disk usage disk = psutil.disk_usage('/') self.gauge("system.disk.total", disk.total) self.gauge("system.disk.used", disk.used) self.gauge("system.disk.free", disk.free) self.gauge("system.disk.percent", disk.percent) # Network IO net_io = psutil.net_io_counters() self.gauge("system.network.bytes_sent", net_io.bytes_sent) self.gauge("system.network.bytes_recv", net_io.bytes_recv) # Process metrics process = psutil.Process() self.gauge("process.cpu_percent", process.cpu_percent(interval=1)) self.gauge("process.memory.rss", process.memory_info().rss) self.gauge("process.memory.vms", process.memory_info().vms) self.gauge("process.threads", process.num_threads()) self.gauge("process.open_files", len(process.open_files())) # Add telemetry event self.telemetry( EventCategory.SYSTEM, "system_metrics_collected", level=LogLevel.DEBUG, data={ "cpu_percent": cpu_percent, "memory_percent": memory.percent, "disk_percent": disk.percent, "process_cpu_percent": process.cpu_percent(interval=0) } ) except Exception as e: self.logger.error(f"Failed to collect system metrics: {e}", exc_info=True) def set_context(self, **kwargs) -> None: """ Set context values for the current thread. Args: **kwargs: Key-value pairs to add to the context """ if not hasattr(self.context, 'values'): self.context.values = {} for key, value in kwargs.items(): self.context.values[key] = value def clear_context(self, *keys) -> None: """ Clear context values for the current thread. Args: *keys: Keys to clear. If none provided, clears all context. """ if not hasattr(self.context, 'values'): return if not keys: # Clear all context self.context.values = {} else: # Clear specific keys for key in keys: if key in self.context.values: del self.context.values[key] def get_context(self) -> Dict[str, Any]: """ Get the current thread's context combined with global context. Returns: Combined context dictionary """ context = self.global_context.copy() # Add thread local context if available if hasattr(self.context, 'values'): context.update(self.context.values) return context def _add_log_context(self, extra: Optional[Dict[str, Any]] = None) -> Dict[str, Any]: """ Prepare log record extra with context. Args: extra: Additional extra data for the log record Returns: Combined extra dictionary with context """ result = {'context': self.get_context()} if extra: # If context is provided in extra, merge it with the existing context if 'context' in extra: result['context'].update(extra.pop('context')) # Add remaining extra fields result.update(extra) return result def debug(self, message: str, category: Optional[EventCategory] = None, context: Optional[Dict[str, Any]] = None, **kwargs) -> None: """ Log a debug message. Args: message: Log message category: Event category context: Additional context for this log **kwargs: Additional data for the log record """ extra = self._add_log_context(kwargs) if context: extra['context'].update(context) if category: extra['context']['category'] = category.value self.logger.debug(message, extra=extra) def info(self, message: str, category: Optional[EventCategory] = None, context: Optional[Dict[str, Any]] = None, **kwargs) -> None: """ Log an info message. Args: message: Log message category: Event category context: Additional context for this log **kwargs: Additional data for the log record """ extra = self._add_log_context(kwargs) if context: extra['context'].update(context) if category: extra['context']['category'] = category.value self.logger.info(message, extra=extra) def warning(self, message: str, category: Optional[EventCategory] = None, context: Optional[Dict[str, Any]] = None, **kwargs) -> None: """ Log a warning message. Args: message: Log message category: Event category context: Additional context for this log **kwargs: Additional data for the log record """ extra = self._add_log_context(kwargs) if context: extra['context'].update(context) if category: extra['context']['category'] = category.value self.logger.warning(message, extra=extra) def error(self, message: str, category: Optional[EventCategory] = None, context: Optional[Dict[str, Any]] = None, exc_info: bool = True, **kwargs) -> None: """ Log an error message. Args: message: Log message category: Event category context: Additional context for this log exc_info: Whether to include exception info **kwargs: Additional data for the log record """ extra = self._add_log_context(kwargs) if context: extra['context'].update(context) if category: extra['context']['category'] = category.value self.logger.error(message, exc_info=exc_info, extra=extra) # Also send an error telemetry event if self.enable_telemetry: error_data = { "message": message, "context": extra.get('context', {}) } if exc_info and sys.exc_info()[0] is not None: error_type = sys.exc_info()[0].__name__ error_message = str(sys.exc_info()[1]) error_data["exception"] = { "type": error_type, "message": error_message } self.telemetry( EventCategory.ERROR if not category else category, "error", level=LogLevel.ERROR, data=error_data ) def critical(self, message: str, category: Optional[EventCategory] = None, context: Optional[Dict[str, Any]] = None, exc_info: bool = True, **kwargs) -> None: """ Log a critical message. Args: message: Log message category: Event category context: Additional context for this log exc_info: Whether to include exception info **kwargs: Additional data for the log record """ extra = self._add_log_context(kwargs) if context: extra['context'].update(context) if category: extra['context']['category'] = category.value self.logger.critical(message, exc_info=exc_info, extra=extra) # Also send a critical telemetry event if self.enable_telemetry: error_data = { "message": message, "context": extra.get('context', {}) } if exc_info and sys.exc_info()[0] is not None: error_type = sys.exc_info()[0].__name__ error_message = str(sys.exc_info()[1]) error_data["exception"] = { "type": error_type, "message": error_message } self.telemetry( EventCategory.ERROR if not category else category, "critical_error", level=LogLevel.CRITICAL, data=error_data ) def log_error(self, error: Union[MGError, Exception], category: Optional[EventCategory] = None, context: Optional[Dict[str, Any]] = None) -> None: """ Log an error object. Args: error: Error object to log category: Event category context: Additional context for this log """ if isinstance(error, MGError): # Use the error's severity to determine log level if error.severity == ErrorSeverity.DEBUG: log_func = self.debug elif error.severity == ErrorSeverity.INFO: log_func = self.info elif error.severity == ErrorSeverity.WARNING: log_func = self.warning elif error.severity == ErrorSeverity.CRITICAL: log_func = self.critical else: log_func = self.error # Determine category if not category: # Map error category to event category if error.category == ErrorCategory.API: event_category = EventCategory.API elif error.category == ErrorCategory.AUTHENTICATION: event_category = EventCategory.AUTHENTICATION elif error.category == ErrorCategory.FILE: event_category = EventCategory.FILE elif error.category == ErrorCategory.MODEL: event_category = EventCategory.MODEL elif error.category == ErrorCategory.DATABASE: event_category = EventCategory.DATABASE else: event_category = EventCategory.ERROR else: event_category = category # Prepare context error_context = {} if context: error_context.update(context) error_context.update({ "error_code": error.code, "error_category": error.category }) if error.details: error_context["error_details"] = error.details # Log the error log_func( f"[{error.code}] {error.message}", category=event_category, context=error_context, exc_info=True ) else: # Regular exception self.error( str(error), category=category or EventCategory.ERROR, context=context, exc_info=True ) def counter(self, name: str, value: int = 1, tags: Optional[Dict[str, str]] = None) -> None: """ Increment a counter metric. Args: name: Metric name value: Value to increment by tags: Tags for the metric """ with self.metrics_lock: if name not in self.metrics["counters"]: self.metrics["counters"][name] = { "value": 0, "created_at": time.time(), "tags": tags or {} } # Increment counter self.metrics["counters"][name]["value"] += value self.metrics["counters"][name]["updated_at"] = time.time() # Update tags if provided if tags: self.metrics["counters"][name]["tags"].update(tags) def gauge(self, name: str, value: float, tags: Optional[Dict[str, str]] = None) -> None: """ Set a gauge metric. Args: name: Metric name value: Gauge value tags: Tags for the metric """ with self.metrics_lock: # Update or create gauge self.metrics["gauges"][name] = { "value": value, "updated_at": time.time(), "tags": tags or {} } if "created_at" not in self.metrics["gauges"][name]: self.metrics["gauges"][name]["created_at"] = time.time() def histogram(self, name: str, value: float, tags: Optional[Dict[str, str]] = None) -> None: """ Add a value to a histogram metric. Args: name: Metric name value: Value to add tags: Tags for the metric """ with self.metrics_lock: if name not in self.metrics["histograms"]: self.metrics["histograms"][name] = { "count": 0, "sum": 0, "min": float('inf'), "max": float('-inf'), "values": [], "created_at": time.time(), "tags": tags or {} } # Update histogram self.metrics["histograms"][name]["count"] += 1 self.metrics["histograms"][name]["sum"] += value self.metrics["histograms"][name]["min"] = min( self.metrics["histograms"][name]["min"], value ) self.metrics["histograms"][name]["max"] = max( self.metrics["histograms"][name]["max"], value ) self.metrics["histograms"][name]["values"].append(value) self.metrics["histograms"][name]["updated_at"] = time.time() # Keep only the last 1000 values to limit memory usage if len(self.metrics["histograms"][name]["values"]) > 1000: self.metrics["histograms"][name]["values"].pop(0) # Update tags if provided if tags: self.metrics["histograms"][name]["tags"].update(tags) def timer(self, name: str, duration: float, tags: Optional[Dict[str, str]] = None) -> None: """ Record a timing metric. Args: name: Metric name duration: Duration in seconds tags: Tags for the metric """ # Timers are implemented as histograms self.histogram(name, duration, tags) @contextmanager def timing(self, name: str, tags: Optional[Dict[str, str]] = None) -> None: """ Context manager for timing a block of code. Args: name: Metric name tags: Tags for the metric Yields: None """ start_time = time.time() try: yield finally: duration = time.time() - start_time self.timer(name, duration, tags) def summary(self, name: str, value: float, tags: Optional[Dict[str, str]] = None) -> None: """ Update a summary metric. Args: name: Metric name value: Value to add tags: Tags for the metric """ with self.metrics_lock: if name not in self.metrics["summaries"]: self.metrics["summaries"][name] = { "count": 0, "sum": 0, "created_at": time.time(), "tags": tags or {} } # Update summary self.metrics["summaries"][name]["count"] += 1 self.metrics["summaries"][name]["sum"] += value self.metrics["summaries"][name]["updated_at"] = time.time() # Update tags if provided if tags: self.metrics["summaries"][name]["tags"].update(tags) def get_metrics(self) -> Dict[str, Any]: """ Get all metrics. Returns: Dictionary with all metrics """ with self.metrics_lock: return { "counters": self.metrics["counters"].copy(), "gauges": self.metrics["gauges"].copy(), "histograms": self.metrics["histograms"].copy(), "summaries": self.metrics["summaries"].copy() } def get_metric(self, name: str, metric_type: MetricType) -> Optional[Dict[str, Any]]: """ Get a specific metric. Args: name: Metric name metric_type: Metric type Returns: Metric data or None if not found """ with self.metrics_lock: if metric_type == MetricType.COUNTER: return self.metrics["counters"].get(name) elif metric_type == MetricType.GAUGE: return self.metrics["gauges"].get(name) elif metric_type == MetricType.HISTOGRAM: return self.metrics["histograms"].get(name) elif metric_type == MetricType.SUMMARY: return self.metrics["summaries"].get(name) elif metric_type == MetricType.TIMER: return self.metrics["histograms"].get(name) # Timers are stored as histograms else: return None def reset_metrics(self) -> None: """Reset all metrics.""" with self.metrics_lock: self.metrics = { "counters": {}, "gauges": {}, "histograms": {}, "summaries": {} } def telemetry( self, category: EventCategory, event_type: str, level: LogLevel = LogLevel.INFO, data: Optional[Dict[str, Any]] = None ) -> None: """ Submit a telemetry event. Args: category: Event category event_type: Type of event level: Log level for the event data: Event data """ if not self.enable_telemetry: return event = { "category": category.value, "type": event_type, "level": level.value, "timestamp": datetime.utcnow().isoformat(), "context": self.get_context() } if data: event["data"] = data try: # Don't block if queue is full self.telemetry_queue.put(event, block=False) except queue.Full: self.logger.warning("Telemetry queue is full, event dropped") def shutdown(self) -> None: """Shutdown the telemetry system and flush pending events.""" if self.enable_telemetry: # Flush telemetry queue self.logger.info("Shutting down telemetry system") try: events = [] while not self.telemetry_queue.empty(): try: event = self.telemetry_queue.get_nowait() events.append(event) self.telemetry_queue.task_done() except queue.Empty: break if events: self._export_events(events) except Exception as e: self.logger.error(f"Error during telemetry shutdown: {e}", exc_info=True) # Create a singleton instance _instance = None def get_telemetry( app_name: str = "morphguard", log_dir: Optional[str] = None, telemetry_dir: Optional[str] = None, log_level: int = logging.INFO, console_logging: bool = True, file_logging: bool = True, enable_telemetry: bool = True ) -> TelemetryManager: """ Get the global telemetry manager instance. Args: app_name: Application name log_dir: Directory for log files telemetry_dir: Directory for telemetry data log_level: Default log level console_logging: Whether to log to console file_logging: Whether to log to file enable_telemetry: Whether to enable telemetry Returns: TelemetryManager instance """ global _instance if _instance is None: _instance = TelemetryManager( app_name=app_name, log_dir=log_dir, telemetry_dir=telemetry_dir, log_level=log_level, console_logging=console_logging, file_logging=file_logging, enable_telemetry=enable_telemetry ) return _instance