IPSExtractor/services/extraction/domain/logging_config.py

"""Configuración de logging en formato JSON y loggers dedicados.

Crea handlers rotativos para:
- logs de aplicación (`logs/ips_extractor.log`),
- logs de normalización LLM (`logs/llm.log`),
- logs de llamadas a APIs (`logs/api_calls.log`),
además de un stream a consola para WARNING+.
"""
from __future__ import annotations

import json
import logging
import logging.handlers
import os
import time
from datetime import datetime
from functools import wraps
from typing import Callable, Any
import coloredlogs


class JsonFormatter(logging.Formatter):
    """Formatter que serializa registros a JSON con extras."""
    def format(self, record: logging.LogRecord) -> str:
        base = {
            "ts": datetime.utcfromtimestamp(record.created).isoformat() + "Z",
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),
        }
        # incluir extras no estándar
        extras = {}
        for k, v in record.__dict__.items():
            if k in (
                "name", "msg", "args", "levelname", "levelno", "pathname", "filename",
                "module", "exc_info", "exc_text", "stack_info", "lineno", "funcName",
                "created", "msecs", "relativeCreated", "thread", "threadName", "processName",
                "process", "message", "asctime",
            ):
                continue
            # evitar objetos no serializables
            try:
                json.dumps(v)
                extras[k] = v
            except Exception:
                extras[k] = str(v)
        if extras:
            base.update(extras)
        return json.dumps(base, ensure_ascii=False)


_configured = False


def log_execution_time(logger: logging.Logger | None = None, level: int = logging.DEBUG) -> Callable:
    """Decorador para registrar el tiempo de ejecución de una función."""
    def decorator(func: Callable) -> Callable:
        @wraps(func)
        def wrapper(*args: Any, **kwargs: Any) -> Any:
            # Si no se pasa logger, intentar obtenerlo del primer argumento (self) si es una clase
            # o usar el logger del módulo de la función.
            _logger = logger
            if _logger is None:
                if args and hasattr(args[0], '__class__'):
                     # Intenta buscar un logger en la instancia
                    _logger = getattr(args[0], 'logger', None)
                
                if _logger is None:
                     _logger = logging.getLogger(func.__module__)

            start_time = time.time()
            try:
                result = func(*args, **kwargs)
                return result
            except Exception as e:
                duration_ms = (time.time() - start_time) * 1000
                if _logger:
                    _logger.exception(
                        f"Error en ejecución de {func.__name__}",
                        extra={"duration_ms": duration_ms, "function": func.__name__, "error": str(e)}
                    )
                raise
            finally:
                duration_ms = (time.time() - start_time) * 1000
                if _logger:
                    _logger.log(
                        level,
                        f"Ejecución de {func.__name__} completada",
                        extra={"duration_ms": duration_ms, "function": func.__name__}
                    )
        return wrapper
    return decorator


def configure_logging(level: int = logging.INFO) -> None:
    """Configura logging global de forma idempotente.

    - Crea archivos rotativos en `logs/` con formato JSON.
    - Configura salida a consola con colores y formato legible.
    - Define loggers dedicados para normalización LLM y llamadas a APIs.
    """
    global _configured
    if _configured:
        return
    os.makedirs("logs", exist_ok=True)

    root = logging.getLogger()
    # idempotencia: limpiar handlers existentes solo si fueron nuestros json
    # si ya hay handlers, no duplicar
    if not root.handlers:
        root.setLevel(level)

        # Handler de archivo principal (JSON)
        app_handler = logging.handlers.RotatingFileHandler(
            filename=os.path.join("logs", "ips_extractor.log"),
            maxBytes=10 * 1024 * 1024,
            backupCount=5,
            encoding="utf-8",
        )
        app_handler.setFormatter(JsonFormatter())
        app_handler.setLevel(logging.INFO)
        root.addHandler(app_handler)

        # Handler de consola (Colores y legible para humanos)
        console = logging.StreamHandler()
        console.setLevel(level) # Usar el nivel configurado (INFO por defecto)
        
        # Formato de consola: Tiempo | Nivel | Logger | Mensaje
        console_fmt = "%(asctime)s %(levelname)-8s %(name)s %(message)s"
        console_formatter = coloredlogs.ColoredFormatter(
            fmt=console_fmt,
            datefmt='%H:%M:%S',
            level_styles={
                'debug': {'color': 'black', 'bright': True},
                'info': {'color': 'green'},
                'warning': {'color': 'yellow'},
                'error': {'color': 'red'},
                'critical': {'color': 'red', 'bold': True},
            },
            field_styles={
                'asctime': {'color': 'cyan'},
                'levelname': {'bold': True},
                'name': {'color': 'blue'},
            }
        )
        console.setFormatter(console_formatter)
        root.addHandler(console)

    # Logger dedicado para normalizador (LLM)
    llm_logger = logging.getLogger("domain.normalizer")
    # evitar duplicados si ya está configurado
    has_file = any(isinstance(h, logging.handlers.RotatingFileHandler) for h in llm_logger.handlers)
    if not has_file:
        llm_handler = logging.handlers.RotatingFileHandler(
            filename=os.path.join("logs", "llm.log"),
            maxBytes=10 * 1024 * 1024,
            backupCount=5,
            encoding="utf-8",
        )
        llm_handler.setFormatter(JsonFormatter())
        llm_handler.setLevel(logging.INFO)
        llm_logger.addHandler(llm_handler)
        llm_logger.setLevel(logging.INFO)
        llm_logger.propagate = False # No propagar al root para no duplicar en consola/main log si no se desea

    # Logger dedicado para llamadas a APIs (peticiones y tokens)
    api_calls_logger = logging.getLogger("domain.api_calls")
    has_api_file = any(isinstance(h, logging.handlers.RotatingFileHandler) for h in api_calls_logger.handlers)
    if not has_api_file:
        api_handler = logging.handlers.RotatingFileHandler(
            filename=os.path.join("logs", "api_calls.log"),
            maxBytes=10 * 1024 * 1024,
            backupCount=5,
            encoding="utf-8",
        )
        api_handler.setFormatter(JsonFormatter())
        api_handler.setLevel(logging.INFO)
        api_calls_logger.addHandler(api_handler)
        api_calls_logger.setLevel(logging.INFO)
        api_calls_logger.propagate = False

    _configured = True