utils/logger.py

"""
Enhanced logging system for real estate tokenization platform
Provides structured logging with performance monitoring and transaction tracking
"""

import logging
import logging.handlers
import time
import functools
from typing import Any, Dict, Optional
from pathlib import Path
from datetime import datetime
import json

from config import settings


class PerformanceLogger:
    """Performance monitoring logger for slow operations"""
    
    @staticmethod
    def log_slow_operation(operation_name: str, duration: float, details: Dict[str, Any] = None):
        """Log operations that exceed the threshold"""
        if duration > settings.SLOW_QUERY_THRESHOLD:
            logger = logging.getLogger("performance")
            logger.warning(
                f"SLOW_OPERATION: {operation_name} took {duration:.3f}s",
                extra={
                    "operation": operation_name,
                    "duration": duration,
                    "threshold": settings.SLOW_QUERY_THRESHOLD,
                    "details": details or {}
                }
            )


class TransactionLogger:
    """Blockchain transaction monitoring and logging"""
    
    @staticmethod
    def log_transaction_start(tx_type: str, user_id: str, property_id: str = None, amount: float = None):
        """Log the start of a blockchain transaction"""
        logger = logging.getLogger("transactions")
        logger.info(
            f"TRANSACTION_START: {tx_type}",
            extra={
                "event": "transaction_start",
                "tx_type": tx_type,
                "user_id": user_id,
                "property_id": property_id,
                "amount": amount,
                "timestamp": datetime.utcnow().isoformat()
            }
        )
    
    @staticmethod
    def log_transaction_success(tx_type: str, tx_hash: str, user_id: str, duration: float, details: Dict[str, Any] = None):
        """Log successful blockchain transaction"""
        logger = logging.getLogger("transactions")
        logger.info(
            f"TRANSACTION_SUCCESS: {tx_type} completed in {duration:.3f}s",
            extra={
                "event": "transaction_success",
                "tx_type": tx_type,
                "tx_hash": tx_hash,
                "user_id": user_id,
                "duration": duration,
                "details": details or {},
                "timestamp": datetime.utcnow().isoformat()
            }
        )
    
    @staticmethod
    def log_transaction_failure(tx_type: str, error: str, user_id: str, duration: float, details: Dict[str, Any] = None):
        """Log failed blockchain transaction"""
        logger = logging.getLogger("transactions")
        logger.error(
            f"TRANSACTION_FAILURE: {tx_type} failed after {duration:.3f}s - {error}",
            extra={
                "event": "transaction_failure",
                "tx_type": tx_type,
                "error": error,
                "user_id": user_id,
                "duration": duration,
                "details": details or {},
                "timestamp": datetime.utcnow().isoformat()
            }
        )


class CustomFormatter(logging.Formatter):
    """Custom formatter for structured logging"""
    
    def format(self, record):
        # Add timestamp and environment info
        record.environment = settings.ENVIRONMENT
        record.service = "real-estate-tokenization"
        
        # Format the base message
        formatted = super().format(record)
        
        # Add structured data if present
        if hasattr(record, 'event'):
            structured_data = {
                "timestamp": record.created,
                "level": record.levelname,
                "environment": record.environment,
                "service": record.service,
                "event": record.event,
                "message": record.getMessage()
            }
            
            # 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', 'environment', 'service', 'message']:
                    structured_data[key] = value
            
            # Return JSON for structured logs
            return json.dumps(structured_data, default=str)
        
        return formatted


def setup_logging():
    """Setup comprehensive logging configuration"""
    
    # Determine log path - use /tmp on cloud platforms (HF Spaces, etc.)
    log_file_enabled = settings.LOG_FILE_ENABLED
    log_file_path = settings.LOG_FILE_PATH
    
    # Try to create logs directory, fall back to /tmp or disable if fails
    if log_file_enabled:
        try:
            log_path = Path(log_file_path)
            log_path.parent.mkdir(parents=True, exist_ok=True)
        except PermissionError:
            # Fall back to /tmp for cloud environments
            log_file_path = "/tmp/app.log"
            try:
                Path(log_file_path).parent.mkdir(parents=True, exist_ok=True)
            except PermissionError:
                # Disable file logging if we can't write anywhere
                log_file_enabled = False
                print("[LOGGER] Warning: Cannot create log directory, file logging disabled")
    
    # Configure root logger
    logging.basicConfig(
        level=getattr(logging, settings.LOG_LEVEL),
        format='%(asctime)s - %(name)s - %(levelname)s - %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S'
    )
    
    # Configure application logger
    app_logger = logging.getLogger("app")
    app_logger.setLevel(getattr(logging, settings.LOG_LEVEL))
    
    # Configure performance logger
    perf_logger = logging.getLogger("performance")
    perf_logger.setLevel(logging.WARNING)
    
    # Configure transaction logger
    tx_logger = logging.getLogger("transactions")
    tx_logger.setLevel(logging.INFO)
    
    # Add file handlers if enabled
    if log_file_enabled:
        try:
            # Rotating file handler for general logs
            file_handler = logging.handlers.RotatingFileHandler(
                log_file_path,
                maxBytes=settings.LOG_FILE_MAX_SIZE,
                backupCount=settings.LOG_FILE_BACKUP_COUNT
            )
            file_handler.setFormatter(CustomFormatter(
                '%(asctime)s - %(environment)s - %(name)s - %(levelname)s - %(message)s'
            ))
            
            # Add to all loggers
            app_logger.addHandler(file_handler)
            perf_logger.addHandler(file_handler)
            tx_logger.addHandler(file_handler)
        except PermissionError:
            print("[LOGGER] Warning: Cannot create log file, file logging disabled")
    
    # Console handler for development
    if settings.is_development():
        console_handler = logging.StreamHandler()
        console_handler.setFormatter(logging.Formatter(
            '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
        ))
        
        app_logger.addHandler(console_handler)
        perf_logger.addHandler(console_handler)
        tx_logger.addHandler(console_handler)
    
    return app_logger


def monitor_performance(operation_name: str):
    """Decorator to monitor function performance"""
    def decorator(func):
        @functools.wraps(func)
        def wrapper(*args, **kwargs):
            if not settings.ENABLE_PERFORMANCE_MONITORING:
                return func(*args, **kwargs)
            
            start_time = time.time()
            try:
                result = func(*args, **kwargs)
                duration = time.time() - start_time
                PerformanceLogger.log_slow_operation(operation_name, duration)
                return result
            except Exception as e:
                duration = time.time() - start_time
                PerformanceLogger.log_slow_operation(
                    f"{operation_name}_FAILED", 
                    duration, 
                    {"error": str(e)}
                )
                raise
        return wrapper
    return decorator


def monitor_transaction(tx_type: str):
    """Decorator to monitor blockchain transactions"""
    def decorator(func):
        @functools.wraps(func)
        def wrapper(*args, **kwargs):
            if not settings.ENABLE_TRANSACTION_MONITORING:
                return func(*args, **kwargs)
            
            # Extract user_id from kwargs or args
            user_id = kwargs.get('user_id') or getattr(args[0] if args else None, 'id', 'unknown')
            property_id = kwargs.get('property_id')
            amount = kwargs.get('amount')
            
            TransactionLogger.log_transaction_start(tx_type, user_id, property_id, amount)
            
            start_time = time.time()
            try:
                result = func(*args, **kwargs)
                duration = time.time() - start_time
                
                # Extract transaction hash from result if available
                tx_hash = None
                if isinstance(result, dict):
                    tx_hash = result.get('blockchain_tx_hash') or result.get('tx_hash')
                
                TransactionLogger.log_transaction_success(tx_type, tx_hash or 'N/A', user_id, duration)
                return result
            except Exception as e:
                duration = time.time() - start_time
                TransactionLogger.log_transaction_failure(tx_type, str(e), user_id, duration)
                raise
        return wrapper
    return decorator


# Initialize logging on import
app_logger = setup_logging()

# Export commonly used loggers
def get_logger(name: str = "app") -> logging.Logger:
    """Get a logger instance"""
    return logging.getLogger(name)


def setup_logger(
    name: str,
    level: int = logging.INFO,
    log_to_file: bool = True,
    log_to_console: bool = True
) -> logging.Logger:
    """
    Setup and return a configured logger (compatible with app_logger.py)
    
    Args:
        name: Logger name (typically __name__ from the calling module)
        level: Logging level (DEBUG, INFO, WARNING, ERROR, CRITICAL)
        log_to_file: Whether to write logs to file
        log_to_console: Whether to write logs to console
    
    Returns:
        Configured logger instance
    """
    # Create logger
    logger = logging.getLogger(name)
    logger.setLevel(level)
    
    # Avoid duplicate handlers if logger already configured
    if logger.handlers:
        return logger
    
    # Create logs directory if it doesn't exist - use /tmp as fallback
    log_file_path = settings.LOG_FILE_PATH
    if log_to_file and settings.LOG_FILE_ENABLED:
        try:
            log_path = Path(log_file_path)
            log_path.parent.mkdir(parents=True, exist_ok=True)
        except PermissionError:
            log_file_path = "/tmp/app.log"
            try:
                Path(log_file_path).parent.mkdir(parents=True, exist_ok=True)
            except PermissionError:
                log_to_file = False
    
    # Create formatters
    detailed_formatter = logging.Formatter(
        '%(asctime)s - %(name)s - %(levelname)s - %(funcName)s:%(lineno)d - %(message)s',
        datefmt='%Y-%m-%d %H:%M:%S'
    )
    
    simple_formatter = logging.Formatter(
        '%(asctime)s - %(levelname)s - %(message)s',
        datefmt='%H:%M:%S'
    )
    
    # Console handler
    if log_to_console:
        console_handler = logging.StreamHandler()
        console_handler.setLevel(level)
        console_handler.setFormatter(simple_formatter)
        logger.addHandler(console_handler)
    
    # File handler
    if log_to_file and settings.LOG_FILE_ENABLED:
        try:
            file_handler = logging.handlers.RotatingFileHandler(
                log_file_path,
                maxBytes=settings.LOG_FILE_MAX_SIZE,
                backupCount=settings.LOG_FILE_BACKUP_COUNT
            )
            file_handler.setFormatter(detailed_formatter)
            logger.addHandler(file_handler)
        except PermissionError:
            pass  # Skip file logging if permission denied
    
    return logger


# Pre-configured loggers for common modules (from app_logger.py)
repo_logger = setup_logger("repo", level=logging.INFO)
service_logger = setup_logger("services", level=logging.INFO)
route_logger = setup_logger("routes", level=logging.INFO)
utils_logger = setup_logger("utils", level=logging.DEBUG)


# Convenience functions
def log_info(message: str, **kwargs):
    """Log info message with structured data"""
    logger = get_logger()
    logger.info(message, extra=kwargs)


def log_warning(message: str, **kwargs):
    """Log warning message with structured data"""
    logger = get_logger()
    logger.warning(message, extra=kwargs)


def log_error(message: str, **kwargs):
    """Log error message with structured data"""
    logger = get_logger()
    logger.error(message, extra=kwargs)


def log_debug(message: str, **kwargs):
    """Log debug message with structured data"""
    logger = get_logger()
    logger.debug(message, extra=kwargs)