logging_utils/fc_debug/logger.py

"""
Function Calling Debug Logger.

Centralized singleton logger for all Function Calling components.
Provides per-module logging with separate log files, configurable
log levels, payload truncation, and request ID correlation.
"""

import logging
import logging.handlers
from dataclasses import dataclass
from pathlib import Path
from threading import Lock
from typing import Any, Dict, Optional

from .config import FCDebugConfig
from .handlers import create_rotating_file_handler, ensure_log_directory
from .modules import FCModule
from .truncation import TruncationConfig, truncate_payload


@dataclass
class ModuleLogger:
    """Wrapper for a module-specific logger with configuration."""

    module: FCModule
    logger: logging.Logger
    enabled: bool
    level: int
    file_handler: Optional[logging.handlers.RotatingFileHandler] = None


class FunctionCallingDebugLogger:
    """
    Centralized debug logger for Function Calling components.

    Thread-safe singleton that manages per-module loggers with:
    - Independent enable/disable per module
    - Separate log files per module
    - Configurable log levels
    - Payload truncation
    - Request ID correlation

    Usage:
        fc_logger = FunctionCallingDebugLogger.get_instance()

        # Log with specific module
        fc_logger.debug(FCModule.CACHE, "Cache hit", req_id="abc123")
        fc_logger.info(FCModule.UI, "Opening dialog", req_id="abc123")

        # Log with payload truncation
        fc_logger.debug(
            FCModule.SCHEMA,
            "Converting tools",
            req_id="abc123",
            payload={"tools": large_tool_list}
        )
    """

    _instance: Optional["FunctionCallingDebugLogger"] = None
    _lock: Lock = Lock()

    def __init__(self) -> None:
        """Initialize the logger. Use get_instance() instead."""
        self._config: Optional[FCDebugConfig] = None
        self._truncation: Optional[TruncationConfig] = None
        self._module_loggers: Dict[FCModule, ModuleLogger] = {}
        self._combined_handler: Optional[logging.handlers.RotatingFileHandler] = None
        self._initialized = False

    @classmethod
    def get_instance(cls) -> "FunctionCallingDebugLogger":
        """Get the singleton instance, creating if needed."""
        if cls._instance is None:
            with cls._lock:
                if cls._instance is None:
                    cls._instance = cls()
                    cls._instance._initialize()
        return cls._instance

    @classmethod
    def reset_instance(cls) -> None:
        """Reset the singleton instance (for testing)."""
        with cls._lock:
            if cls._instance is not None:
                cls._instance._cleanup()
                cls._instance = None

    def _initialize(self) -> None:
        """Initialize all module loggers based on configuration."""
        if self._initialized:
            return

        try:
            self._config = FCDebugConfig.from_env()
            self._truncation = TruncationConfig.from_env()
        except Exception:
            # Graceful degradation: use defaults if config loading fails
            self._config = FCDebugConfig()
            self._truncation = TruncationConfig()

        # Create log directory
        log_dir = Path("logs/fc_debug")
        ensure_log_directory(log_dir)

        # Initialize combined handler if enabled
        if self._config.combined_log_enabled:
            self._combined_handler = create_rotating_file_handler(
                log_dir / "fc_combined.log",
                max_bytes=self._config.log_max_bytes,
                backup_count=self._config.log_backup_count,
            )

        # Initialize per-module loggers
        for module in FCModule:
            self._module_loggers[module] = self._create_module_logger(module, log_dir)

        self._initialized = True

    def _create_module_logger(
        self,
        module: FCModule,
        log_dir: Path,
    ) -> ModuleLogger:
        """Create a logger for a specific module."""
        assert self._config is not None

        # Get module-specific config
        enabled = self._config.is_module_enabled(module)
        level = self._config.get_module_level(module)

        # Create logger with unique name
        logger_name = f"AIStudioProxyServer.FC.{module.name}"
        logger = logging.getLogger(logger_name)
        logger.setLevel(level if enabled else logging.CRITICAL + 1)
        logger.propagate = False  # Don't propagate to root logger

        # Clear existing handlers
        logger.handlers.clear()

        file_handler = None
        if enabled and self._config.master_enabled:
            # Create file handler
            file_handler = create_rotating_file_handler(
                log_dir / module.log_filename,
                max_bytes=self._config.log_max_bytes,
                backup_count=self._config.log_backup_count,
                level=level,
            )
            logger.addHandler(file_handler)

            # Add to combined log if enabled
            if self._combined_handler:
                logger.addHandler(self._combined_handler)

        return ModuleLogger(
            module=module,
            logger=logger,
            enabled=enabled and self._config.master_enabled,
            level=level,
            file_handler=file_handler,
        )

    def _cleanup(self) -> None:
        """Clean up all handlers."""
        for module_logger in self._module_loggers.values():
            if module_logger.file_handler:
                module_logger.file_handler.close()
                module_logger.logger.removeHandler(module_logger.file_handler)

        if self._combined_handler:
            self._combined_handler.close()

        self._module_loggers.clear()
        self._initialized = False

    # =========================================================================
    # Public Logging Methods
    # =========================================================================

    def is_enabled(self, module: FCModule) -> bool:
        """Check if a module is enabled for logging."""
        if module not in self._module_loggers:
            return False
        return self._module_loggers[module].enabled

    def debug(
        self,
        module: FCModule,
        message: str,
        req_id: str = "",
        payload: Optional[Any] = None,
        **kwargs: Any,
    ) -> None:
        """Log a DEBUG message for a module."""
        self._log(module, logging.DEBUG, message, req_id, payload, **kwargs)

    def info(
        self,
        module: FCModule,
        message: str,
        req_id: str = "",
        payload: Optional[Any] = None,
        **kwargs: Any,
    ) -> None:
        """Log an INFO message for a module."""
        self._log(module, logging.INFO, message, req_id, payload, **kwargs)

    def warning(
        self,
        module: FCModule,
        message: str,
        req_id: str = "",
        payload: Optional[Any] = None,
        **kwargs: Any,
    ) -> None:
        """Log a WARNING message for a module."""
        self._log(module, logging.WARNING, message, req_id, payload, **kwargs)

    def error(
        self,
        module: FCModule,
        message: str,
        req_id: str = "",
        payload: Optional[Any] = None,
        exc_info: bool = False,
        **kwargs: Any,
    ) -> None:
        """Log an ERROR message for a module."""
        self._log(
            module, logging.ERROR, message, req_id, payload, exc_info=exc_info, **kwargs
        )

    def _log(
        self,
        module: FCModule,
        level: int,
        message: str,
        req_id: str = "",
        payload: Optional[Any] = None,
        exc_info: bool = False,
        **kwargs: Any,
    ) -> None:
        """Internal logging method."""
        if module not in self._module_loggers:
            return

        module_logger = self._module_loggers[module]
        if not module_logger.enabled:
            return

        # Build the full message
        prefix = module.prefix
        req_prefix = f"[{req_id}] " if req_id else ""

        # Handle payload truncation
        payload_str = ""
        if payload is not None:
            payload_str = self._format_payload(payload, module)

        full_message = f"{req_prefix}{prefix} {message}"
        if payload_str:
            full_message += f"\n{payload_str}"

        # Log it
        module_logger.logger.log(level, full_message, exc_info=exc_info)

    def _format_payload(self, payload: Any, module: FCModule) -> str:
        """Format and optionally truncate a payload for logging."""
        if self._truncation is None or not self._truncation.enabled:
            return str(payload)

        # Determine max length based on payload type
        max_length = self._truncation.get_max_length(payload, module)
        return truncate_payload(payload, max_length)

    # =========================================================================
    # Convenience Methods for Specific Modules
    # =========================================================================

    def log_cache_hit(self, req_id: str, digest: str, age_seconds: float) -> None:
        """Log a cache hit event."""
        self.debug(
            FCModule.CACHE,
            f"HIT - digest={digest[:8]}..., age={age_seconds:.1f}s",
            req_id=req_id,
        )

    def log_cache_miss(self, req_id: str, reason: str) -> None:
        """Log a cache miss event."""
        self.debug(
            FCModule.CACHE,
            f"MISS - reason={reason}",
            req_id=req_id,
        )

    def log_ui_action(
        self,
        req_id: str,
        action: str,
        element: str,
        elapsed_ms: Optional[float] = None,
    ) -> None:
        """Log a UI action."""
        timing = f" ({elapsed_ms:.0f}ms)" if elapsed_ms else ""
        self.debug(
            FCModule.UI,
            f"{action} {element}{timing}",
            req_id=req_id,
        )

    def log_wire_parse(
        self,
        req_id: str,
        func_name: str,
        params: Dict[str, Any],
        success: bool = True,
    ) -> None:
        """Log wire format parsing."""
        status = "parsed" if success else "FAILED"
        self.debug(
            FCModule.WIRE,
            f"Function '{func_name}' {status}",
            req_id=req_id,
            payload=params if params else None,
        )

    def log_dom_extraction(
        self,
        req_id: str,
        call_count: int,
        strategy: str,
    ) -> None:
        """Log DOM-based function call extraction."""
        self.debug(
            FCModule.DOM,
            f"Extracted {call_count} call(s) via {strategy}",
            req_id=req_id,
        )

    def log_schema_conversion(
        self,
        req_id: str,
        tool_count: int,
        elapsed_ms: float,
    ) -> None:
        """Log schema conversion."""
        self.info(
            FCModule.SCHEMA,
            f"Converted {tool_count} tools in {elapsed_ms:.2f}ms",
            req_id=req_id,
        )

    def log_response_format(
        self,
        req_id: str,
        call_count: int,
        finish_reason: str,
    ) -> None:
        """Log response formatting."""
        self.debug(
            FCModule.RESPONSE,
            f"Formatted {call_count} tool calls, finish_reason={finish_reason}",
            req_id=req_id,
        )

    def log_mode_selection(
        self,
        req_id: str,
        mode: str,
        reason: str,
    ) -> None:
        """Log mode selection decision."""
        self.info(
            FCModule.ORCHESTRATOR,
            f"Mode={mode}, reason={reason}",
            req_id=req_id,
        )


# Global convenience function
def get_fc_logger() -> FunctionCallingDebugLogger:
    """Get the FC debug logger instance."""
    return FunctionCallingDebugLogger.get_instance()