285 lines
9.8 KiB
Python
285 lines
9.8 KiB
Python
"""
|
|
Standardized logging utility to replace print statements and provide consistent logging patterns.
|
|
"""
|
|
import logging
|
|
import sys
|
|
from typing import Any, Dict, Optional, Union
|
|
from functools import wraps
|
|
from datetime import datetime
|
|
import json
|
|
from pathlib import Path
|
|
from app.config import settings
|
|
|
|
|
|
class StructuredLogger:
|
|
"""Enhanced logger with structured logging capabilities."""
|
|
|
|
def __init__(self, name: str, level: str = "INFO"):
|
|
self.logger = logging.getLogger(name)
|
|
self.logger.setLevel(getattr(logging, level.upper()))
|
|
|
|
if not self.logger.handlers:
|
|
self._setup_handlers()
|
|
|
|
def _setup_handlers(self):
|
|
"""Setup console and file handlers with appropriate formatters."""
|
|
|
|
# Console handler
|
|
console_handler = logging.StreamHandler(sys.stdout)
|
|
console_formatter = logging.Formatter(
|
|
'%(asctime)s - %(name)s - %(levelname)s - %(message)s',
|
|
datefmt='%Y-%m-%d %H:%M:%S'
|
|
)
|
|
console_handler.setFormatter(console_formatter)
|
|
self.logger.addHandler(console_handler)
|
|
|
|
# File handler (if configured)
|
|
if hasattr(settings, 'LOG_FILE_PATH') and settings.LOG_FILE_PATH:
|
|
log_path = Path(settings.LOG_FILE_PATH)
|
|
log_path.parent.mkdir(parents=True, exist_ok=True)
|
|
|
|
file_handler = logging.FileHandler(log_path)
|
|
file_formatter = logging.Formatter(
|
|
'%(asctime)s - %(name)s - %(levelname)s - %(funcName)s:%(lineno)d - %(message)s',
|
|
datefmt='%Y-%m-%d %H:%M:%S'
|
|
)
|
|
file_handler.setFormatter(file_formatter)
|
|
self.logger.addHandler(file_handler)
|
|
|
|
def debug(self, message: str, **kwargs):
|
|
"""Log debug message with optional structured data."""
|
|
self._log(logging.DEBUG, message, **kwargs)
|
|
|
|
def info(self, message: str, **kwargs):
|
|
"""Log info message with optional structured data."""
|
|
self._log(logging.INFO, message, **kwargs)
|
|
|
|
def warning(self, message: str, **kwargs):
|
|
"""Log warning message with optional structured data."""
|
|
self._log(logging.WARNING, message, **kwargs)
|
|
|
|
def error(self, message: str, **kwargs):
|
|
"""Log error message with optional structured data."""
|
|
self._log(logging.ERROR, message, **kwargs)
|
|
|
|
def critical(self, message: str, **kwargs):
|
|
"""Log critical message with optional structured data."""
|
|
self._log(logging.CRITICAL, message, **kwargs)
|
|
|
|
def _log(self, level: int, message: str, **kwargs):
|
|
"""Internal method to log with structured data."""
|
|
if kwargs:
|
|
structured_message = f"{message} | Context: {json.dumps(kwargs, default=str)}"
|
|
else:
|
|
structured_message = message
|
|
|
|
self.logger.log(level, structured_message)
|
|
|
|
|
|
class ImportLogger(StructuredLogger):
|
|
"""Specialized logger for import operations."""
|
|
|
|
def __init__(self):
|
|
super().__init__("import_operations", "INFO")
|
|
|
|
def log_import_start(self, import_type: str, file_name: str, record_count: int = None):
|
|
"""Log the start of an import operation."""
|
|
context = {
|
|
"import_type": import_type,
|
|
"file_name": file_name,
|
|
"timestamp": datetime.now().isoformat()
|
|
}
|
|
if record_count is not None:
|
|
context["expected_records"] = record_count
|
|
|
|
self.info(f"Starting {import_type} import", **context)
|
|
|
|
def log_import_progress(self, processed: int, total: int = None, errors: int = 0):
|
|
"""Log import progress."""
|
|
context = {
|
|
"processed": processed,
|
|
"errors": errors,
|
|
"timestamp": datetime.now().isoformat()
|
|
}
|
|
if total is not None:
|
|
context["total"] = total
|
|
context["progress_percent"] = round((processed / total) * 100, 2)
|
|
|
|
self.info(f"Import progress: {processed} processed", **context)
|
|
|
|
def log_import_error(self, line_number: int, error_message: str, row_data: Dict = None):
|
|
"""Log import errors with context."""
|
|
context = {
|
|
"line_number": line_number,
|
|
"error": error_message,
|
|
"timestamp": datetime.now().isoformat()
|
|
}
|
|
if row_data:
|
|
context["row_data"] = row_data
|
|
|
|
self.warning(f"Import error at line {line_number}", **context)
|
|
|
|
def log_import_complete(self, processed: int, errors: int, duration_seconds: float):
|
|
"""Log completion of import operation."""
|
|
context = {
|
|
"total_processed": processed,
|
|
"total_errors": errors,
|
|
"duration_seconds": duration_seconds,
|
|
"records_per_second": round(processed / max(duration_seconds, 0.1), 2),
|
|
"timestamp": datetime.now().isoformat()
|
|
}
|
|
|
|
self.info(f"Import completed: {processed} processed, {errors} errors", **context)
|
|
|
|
|
|
class SecurityLogger(StructuredLogger):
|
|
"""Specialized logger for security events."""
|
|
|
|
def __init__(self):
|
|
super().__init__("security", "WARNING")
|
|
|
|
def log_auth_attempt(self, username: str, success: bool, ip_address: str = None):
|
|
"""Log authentication attempts."""
|
|
context = {
|
|
"username": username,
|
|
"success": success,
|
|
"ip_address": ip_address,
|
|
"timestamp": datetime.now().isoformat()
|
|
}
|
|
|
|
if success:
|
|
self.info("Successful authentication", **context)
|
|
else:
|
|
self.warning("Failed authentication attempt", **context)
|
|
|
|
def log_permission_denied(self, username: str, resource: str, action: str):
|
|
"""Log permission denied events."""
|
|
context = {
|
|
"username": username,
|
|
"resource": resource,
|
|
"action": action,
|
|
"timestamp": datetime.now().isoformat()
|
|
}
|
|
|
|
self.warning("Permission denied", **context)
|
|
|
|
def log_security_event(self, event_type: str, details: Dict[str, Any]):
|
|
"""Log general security events."""
|
|
context = {
|
|
"event_type": event_type,
|
|
"timestamp": datetime.now().isoformat(),
|
|
**details
|
|
}
|
|
|
|
self.warning(f"Security event: {event_type}", **context)
|
|
|
|
|
|
class DatabaseLogger(StructuredLogger):
|
|
"""Specialized logger for database operations."""
|
|
|
|
def __init__(self):
|
|
super().__init__("database", "INFO")
|
|
|
|
def log_query_performance(self, query_type: str, duration_ms: float, affected_rows: int = None):
|
|
"""Log database query performance."""
|
|
context = {
|
|
"query_type": query_type,
|
|
"duration_ms": duration_ms,
|
|
"timestamp": datetime.now().isoformat()
|
|
}
|
|
if affected_rows is not None:
|
|
context["affected_rows"] = affected_rows
|
|
|
|
if duration_ms > 1000: # Log slow queries as warnings
|
|
self.warning(f"Slow query detected: {query_type}", **context)
|
|
else:
|
|
self.debug(f"Query executed: {query_type}", **context)
|
|
|
|
def log_transaction_event(self, event_type: str, details: Dict[str, Any] = None):
|
|
"""Log database transaction events."""
|
|
context = {
|
|
"event_type": event_type,
|
|
"timestamp": datetime.now().isoformat()
|
|
}
|
|
if details:
|
|
context.update(details)
|
|
|
|
self.info(f"Transaction {event_type}", **context)
|
|
|
|
|
|
def log_function_call(logger: StructuredLogger = None, level: str = "DEBUG"):
|
|
"""
|
|
Decorator to log function calls with parameters and execution time.
|
|
|
|
Args:
|
|
logger: Logger instance to use (creates default if None)
|
|
level: Log level to use
|
|
"""
|
|
def decorator(func):
|
|
nonlocal logger
|
|
if logger is None:
|
|
logger = StructuredLogger(func.__module__, level)
|
|
|
|
@wraps(func)
|
|
def wrapper(*args, **kwargs):
|
|
start_time = datetime.now()
|
|
|
|
# Log function entry
|
|
context = {
|
|
"function": func.__name__,
|
|
"args_count": len(args),
|
|
"kwargs": list(kwargs.keys()),
|
|
"start_time": start_time.isoformat()
|
|
}
|
|
logger.debug(f"Entering function {func.__name__}", **context)
|
|
|
|
try:
|
|
result = func(*args, **kwargs)
|
|
|
|
# Log successful completion
|
|
duration = (datetime.now() - start_time).total_seconds()
|
|
logger.debug(
|
|
f"Function {func.__name__} completed successfully",
|
|
duration_seconds=duration,
|
|
function=func.__name__
|
|
)
|
|
|
|
return result
|
|
|
|
except Exception as e:
|
|
# Log error
|
|
duration = (datetime.now() - start_time).total_seconds()
|
|
logger.error(
|
|
f"Function {func.__name__} failed with error: {str(e)}",
|
|
duration_seconds=duration,
|
|
function=func.__name__,
|
|
error_type=type(e).__name__
|
|
)
|
|
raise
|
|
|
|
return wrapper
|
|
return decorator
|
|
|
|
|
|
# Pre-configured logger instances
|
|
app_logger = StructuredLogger("application")
|
|
import_logger = ImportLogger()
|
|
security_logger = SecurityLogger()
|
|
database_logger = DatabaseLogger()
|
|
|
|
# Convenience functions
|
|
def log_info(message: str, **kwargs):
|
|
"""Quick info logging."""
|
|
app_logger.info(message, **kwargs)
|
|
|
|
def log_warning(message: str, **kwargs):
|
|
"""Quick warning logging."""
|
|
app_logger.warning(message, **kwargs)
|
|
|
|
def log_error(message: str, **kwargs):
|
|
"""Quick error logging."""
|
|
app_logger.error(message, **kwargs)
|
|
|
|
def log_debug(message: str, **kwargs):
|
|
"""Quick debug logging."""
|
|
app_logger.debug(message, **kwargs) |