backend/logging_config.py

"""
Comprehensive Logging Configuration for AegisLM Backend.

Provides structured logging with multiple handlers, log levels,
and monitoring integration for production deployment.
"""

import logging
import logging.handlers
import json
import sys
from datetime import datetime
from pathlib import Path
from typing import Dict, Any
import os

from core.config import settings


class StructuredFormatter(logging.Formatter):
    """
    Structured JSON formatter for consistent log formatting.
    """
    
    def format(self, record: logging.LogRecord) -> str:
        log_data = {
            'timestamp': datetime.utcnow().isoformat(),
            'level': record.levelname,
            'logger': record.name,
            'message': record.getMessage(),
            'module': record.module,
            'function': record.funcName,
            'line': record.lineno,
            'thread': record.thread,
            'process': record.process
        }
        
        # Add exception information if present
        if record.exc_info:
            log_data['exception'] = self.formatException(record.exc_info)
        
        # Add extra fields
        for key, value in record.__dict__.items():
            if key not in ['name', 'msg', 'args', 'levelname', 'levelno', 'pathname',
                          'filename', 'module', 'lineno', 'funcName', 'created', 'msecs',
                          'relativeCreated', 'thread', 'threadName', 'processName',
                          'process', 'getMessage', 'exc_info', 'exc_text', 'stack_info']:
                log_data[key] = value
        
        return json.dumps(log_data)


class ColoredFormatter(logging.Formatter):
    """
    Colored formatter for console output during development.
    """
    
    COLORS = {
        'DEBUG': '\033[36m',      # Cyan
        'INFO': '\033[32m',       # Green
        'WARNING': '\033[33m',    # Yellow
        'ERROR': '\033[31m',      # Red
        'CRITICAL': '\033[35m',   # Magenta
    }
    RESET = '\033[0m'
    
    def format(self, record: logging.LogRecord) -> str:
        color = self.COLORS.get(record.levelname, self.RESET)
        reset = self.RESET
        
        # Format the basic log message
        formatted = super().format(record)
        
        # Add color to the level name
        return formatted.replace(
            f"[{record.levelname}]",
            f"[{color}{record.levelname}{reset}]"
        )


def setup_logging():
    """
    Setup comprehensive logging configuration.
    """
    # Create logs directory if it doesn't exist
    logs_dir = Path("logs")
    logs_dir.mkdir(exist_ok=True)
    
    # Root logger configuration
    root_logger = logging.getLogger()
    root_logger.setLevel(getattr(logging, settings.LOG_LEVEL.upper(), logging.INFO))
    
    # Clear existing handlers
    root_logger.handlers.clear()
    
    # Console handler (colored for development)
    console_handler = logging.StreamHandler(sys.stdout)
    console_handler.setLevel(logging.DEBUG)
    
    if settings.DEBUG:
        console_formatter = ColoredFormatter(
            fmt='[%(levelname)s] %(asctime)s - %(name)s - %(message)s',
            datefmt='%Y-%m-%d %H:%M:%S'
        )
    else:
        console_formatter = StructuredFormatter()
    
    console_handler.setFormatter(console_formatter)
    root_logger.addHandler(console_handler)
    
    # File handler for all logs (rotating)
    file_handler = logging.handlers.RotatingFileHandler(
        filename=logs_dir / "aegislm.log",
        maxBytes=50 * 1024 * 1024,  # 50MB
        backupCount=5
    )
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(StructuredFormatter())
    root_logger.addHandler(file_handler)
    
    # Error file handler (only errors and above)
    error_handler = logging.handlers.RotatingFileHandler(
        filename=logs_dir / "errors.log",
        maxBytes=10 * 1024 * 1024,  # 10MB
        backupCount=3
    )
    error_handler.setLevel(logging.ERROR)
    error_handler.setFormatter(StructuredFormatter())
    root_logger.addHandler(error_handler)
    
    # Security audit log handler
    security_handler = logging.handlers.RotatingFileHandler(
        filename=logs_dir / "security.log",
        maxBytes=10 * 1024 * 1024,  # 10MB
        backupCount=3
    )
    security_handler.setLevel(logging.INFO)
    security_handler.setFormatter(StructuredFormatter())
    
    # Create security logger
    security_logger = logging.getLogger('security')
    security_logger.addHandler(security_handler)
    security_logger.propagate = False  # Don't propagate to root logger
    
    # Performance monitoring logger
    performance_handler = logging.handlers.RotatingFileHandler(
        filename=logs_dir / "performance.log",
        maxBytes=20 * 1024 * 1024,  # 20MB
        backupCount=3
    )
    performance_handler.setLevel(logging.INFO)
    performance_handler.setFormatter(StructuredFormatter())
    
    # Create performance logger
    performance_logger = logging.getLogger('performance')
    performance_logger.addHandler(performance_handler)
    performance_logger.propagate = False  # Don't propagate to root logger
    
    # Suppress noisy third-party loggers
    logging.getLogger('uvicorn.access').setLevel(logging.WARNING)
    logging.getLogger('uvicorn.error').setLevel(logging.WARNING)
    logging.getLogger('sqlalchemy.engine').setLevel(logging.WARNING)
    logging.getLogger('httpx').setLevel(logging.WARNING)
    
    # Log startup
    logger = logging.getLogger(__name__)
    logger.info(
        "Logging system initialized",
        extra={
            'log_level': settings.LOG_LEVEL,
            'debug_mode': settings.DEBUG,
            'environment': getattr(settings, 'ENVIRONMENT', 'development')
        }
    )


def get_logger(name: str) -> logging.Logger:
    """
    Get a logger instance with the specified name.
    
    Args:
        name: Logger name (typically __name__)
        
    Returns:
        Configured logger instance
    """
    return logging.getLogger(name)


def log_security_event(event_type: str, details: Dict[str, Any]):
    """
    Log a security event.
    
    Args:
        event_type: Type of security event
        details: Event details
    """
    security_logger = logging.getLogger('security')
    security_logger.info(
        f"Security event: {event_type}",
        extra={
            'event_type': event_type,
            'category': 'security',
            **details
        }
    )


def log_performance_metric(metric_name: str, value: float, unit: str = 'ms', **kwargs):
    """
    Log a performance metric.
    
    Args:
        metric_name: Name of the metric
        value: Metric value
        unit: Unit of measurement
        **kwargs: Additional metadata
    """
    performance_logger = logging.getLogger('performance')
    performance_logger.info(
        f"Performance metric: {metric_name} = {value} {unit}",
        extra={
            'metric_name': metric_name,
            'metric_value': value,
            'metric_unit': unit,
            'category': 'performance',
            **kwargs
        }
    )


def log_api_request(
    method: str,
    path: str,
    status_code: int,
    response_time: float,
    user_id: int = None,
    ip_address: str = None
):
    """
    Log an API request for monitoring.
    
    Args:
        method: HTTP method
        path: Request path
        status_code: Response status code
        response_time: Response time in milliseconds
        user_id: User ID if authenticated
        ip_address: Client IP address
    """
    logger = get_logger('api')
    log_level = logging.WARNING if status_code >= 400 else logging.INFO
    
    logger.log(
        log_level,
        f"API Request: {method} {path} - {status_code} - {response_time:.2f}ms",
        extra={
            'method': method,
            'path': path,
            'status_code': status_code,
            'response_time_ms': response_time,
            'user_id': user_id,
            'ip_address': ip_address,
            'category': 'api_request'
        }
    )


def log_evaluation_event(
    evaluation_id: str,
    event_type: str,
    details: Dict[str, Any],
    user_id: int = None
):
    """
    Log an evaluation-related event.
    
    Args:
        evaluation_id: Evaluation ID
        event_type: Type of event (started, completed, failed, etc.)
        details: Event details
        user_id: User ID
    """
    logger = get_logger('evaluation')
    logger.info(
        f"Evaluation {event_type}: {evaluation_id}",
        extra={
            'evaluation_id': evaluation_id,
            'event_type': event_type,
            'user_id': user_id,
            'category': 'evaluation',
            **details
        }
    )


def log_system_event(
    event_type: str,
    message: str,
    level: str = 'info',
    **kwargs
):
    """
    Log a system-level event.
    
    Args:
        event_type: Type of system event
        message: Event message
        level: Log level (info, warning, error)
        **kwargs: Additional metadata
    """
    logger = get_logger('system')
    log_method = getattr(logger, level.lower())
    
    log_method(
        f"System event: {event_type} - {message}",
        extra={
            'event_type': event_type,
            'category': 'system',
            **kwargs
        }
    )


class RequestLogger:
    """
    Middleware for logging HTTP requests and responses.
    """
    
    def __init__(self):
        self.logger = get_logger('http_requests')
    
    async def log_request(self, request, response_time: float, status_code: int):
        """Log HTTP request details."""
        await log_api_request(
            method=request.method,
            path=request.url.path,
            status_code=status_code,
            response_time=response_time,
            ip_address=request.client.host if request.client else None
        )


# Context manager for performance logging
class PerformanceTimer:
    """
    Context manager for timing operations and logging performance metrics.
    """
    
    def __init__(self, operation_name: str, **metadata):
        self.operation_name = operation_name
        self.metadata = metadata
        self.start_time = None
        self.logger = get_logger('performance')
    
    def __enter__(self):
        self.start_time = datetime.utcnow()
        return self
    
    def __exit__(self, exc_type, exc_val, exc_tb):
        if self.start_time:
            duration = (datetime.utcnow() - self.start_time).total_seconds() * 1000
            log_performance_metric(
                metric_name=self.operation_name,
                value=duration,
                unit='ms',
                **self.metadata
            )


def performance_timer(operation_name: str, **metadata):
    """
    Decorator for timing function execution.
    
    Args:
        operation_name: Name of the operation being timed
        **metadata: Additional metadata to log
    """
    def decorator(func):
        def wrapper(*args, **kwargs):
            with PerformanceTimer(operation_name, **metadata):
                return func(*args, **kwargs)
        return wrapper
    return decorator


# Initialize logging when module is imported
setup_logging()