From 2199d256b6549095ba357c75618d04c64733cfda Mon Sep 17 00:00:00 2001 From: Lukas Pupka-Lipinski Date: Mon, 6 Oct 2025 08:45:07 +0200 Subject: [PATCH] Update logging middleware for FastAPI - Enhanced logging with request tracking, performance monitoring, and security logging --- src/server/fastapi_app.py | 31 +-- .../middleware/fastapi_logging_middleware.py | 262 ++++++++++++++++++ web_todo.md | 2 +- 3 files changed, 265 insertions(+), 30 deletions(-) create mode 100644 src/server/web/middleware/fastapi_logging_middleware.py diff --git a/src/server/fastapi_app.py b/src/server/fastapi_app.py index 378ae07..408417c 100644 --- a/src/server/fastapi_app.py +++ b/src/server/fastapi_app.py @@ -37,6 +37,7 @@ from pydantic_settings import BaseSettings # Import our custom middleware from web.middleware.fastapi_auth_middleware import AuthMiddleware from web.middleware.fastapi_validation_middleware import ValidationMiddleware +from web.middleware.fastapi_logging_middleware import EnhancedLoggingMiddleware # Configure logging logging.basicConfig( @@ -251,38 +252,10 @@ app.add_middleware( ) # Add custom middleware +app.add_middleware(EnhancedLoggingMiddleware) app.add_middleware(AuthMiddleware) app.add_middleware(ValidationMiddleware) -# Request logging middleware -@app.middleware("http") -async def log_requests(request: Request, call_next): - """Log all incoming HTTP requests for debugging.""" - start_time = datetime.utcnow() - - # Log basic request info - client_ip = getattr(request.client, 'host', 'unknown') if request.client else 'unknown' - logger.info(f"Request: {request.method} {request.url} from {client_ip}") - - try: - response = await call_next(request) - - # Log response info - process_time = (datetime.utcnow() - start_time).total_seconds() - logger.info(f"Response: {response.status_code} ({process_time:.3f}s)") - - return response - except Exception as exc: - logger.error(f"Request failed: {exc}", exc_info=True) - return JSONResponse( - status_code=500, - content={ - "success": False, - "error": "Internal Server Error", - "code": "REQUEST_FAILED" - } - ) - # Add global exception handler app.add_exception_handler(Exception, global_exception_handler) diff --git a/src/server/web/middleware/fastapi_logging_middleware.py b/src/server/web/middleware/fastapi_logging_middleware.py new file mode 100644 index 0000000..05834ac --- /dev/null +++ b/src/server/web/middleware/fastapi_logging_middleware.py @@ -0,0 +1,262 @@ +""" +FastAPI enhanced logging middleware that integrates with the existing logging infrastructure. + +This module provides comprehensive logging for FastAPI applications including: +- Request/response logging +- Error logging with detailed context +- Performance monitoring +- Integration with existing logging systems +""" + +import json +import logging +import time +import traceback +from typing import Callable, Dict, Any, Optional +from fastapi import Request, Response, HTTPException, status +from fastapi.responses import JSONResponse +from datetime import datetime, timezone + + +class EnhancedLoggingMiddleware: + """ + Enhanced FastAPI logging middleware. + + This middleware provides comprehensive logging capabilities: + - Request/response logging with timing + - Detailed error logging with context + - Performance monitoring + - Integration with existing loggers + """ + + def __init__(self, app, log_level: str = "INFO", log_body: bool = False, max_body_size: int = 1024): + self.app = app + self.log_level = getattr(logging, log_level.upper()) + self.log_body = log_body + self.max_body_size = max_body_size + + # Setup loggers + self.setup_loggers() + + def setup_loggers(self): + """Setup specialized loggers for different types of events.""" + # Main request logger + self.request_logger = logging.getLogger("aniworld.requests") + self.request_logger.setLevel(self.log_level) + + # Performance logger + self.performance_logger = logging.getLogger("aniworld.performance") + self.performance_logger.setLevel(logging.INFO) + + # Error logger (integrates with existing error logging) + self.error_logger = logging.getLogger("aniworld.errors") + self.error_logger.setLevel(logging.ERROR) + + # Security logger for auth-related events + self.security_logger = logging.getLogger("aniworld.security") + self.security_logger.setLevel(logging.WARNING) + + # Setup file handlers if not already configured + if not any(isinstance(h, logging.FileHandler) for h in self.request_logger.handlers): + # Request handler + request_handler = logging.FileHandler("./logs/aniworld.log") + request_handler.setFormatter(logging.Formatter( + "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + )) + self.request_logger.addHandler(request_handler) + + # Error handler + error_handler = logging.FileHandler("./logs/errors.log") + error_handler.setFormatter(logging.Formatter( + "%(asctime)s - %(name)s - %(levelname)s - %(message)s\n%(exc_info)s" + )) + self.error_logger.addHandler(error_handler) + + # Security handler + security_handler = logging.FileHandler("./logs/auth_failures.log") + security_handler.setFormatter(logging.Formatter( + "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + )) + self.security_logger.addHandler(security_handler) + + async def __call__(self, request: Request, call_next: Callable) -> Response: + """ + Process logging for incoming requests. + + Args: + request: FastAPI request object + call_next: Next function in the middleware chain + + Returns: + Response from next middleware with logging + """ + start_time = time.time() + request_timestamp = datetime.now(timezone.utc) + + # Generate request ID for tracking + request_id = f"{int(start_time * 1000)}-{id(request)}" + request.state.request_id = request_id + + # Log incoming request + await self.log_request(request, request_id, request_timestamp) + + try: + # Process request + response = await call_next(request) + + # Calculate processing time + process_time = time.time() - start_time + + # Log successful response + await self.log_response(request, response, request_id, process_time) + + # Log performance metrics if slow + if process_time > 1.0: # Log slow requests (> 1 second) + self.performance_logger.warning( + f"Slow request detected - ID: {request_id}, " + f"Method: {request.method}, Path: {request.url.path}, " + f"Duration: {process_time:.3f}s" + ) + + # Add request ID to response headers for debugging + response.headers["X-Request-ID"] = request_id + + return response + + except HTTPException as e: + process_time = time.time() - start_time + await self.log_http_exception(request, e, request_id, process_time) + raise + + except Exception as e: + process_time = time.time() - start_time + await self.log_error(request, e, request_id, process_time) + + # Return generic error response + return JSONResponse( + status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, + content={ + "success": False, + "error": "Internal Server Error", + "code": "SERVER_ERROR", + "request_id": request_id + }, + headers={"X-Request-ID": request_id} + ) + + async def log_request(self, request: Request, request_id: str, timestamp: datetime): + """Log incoming request details.""" + client_ip = getattr(request.client, 'host', 'unknown') if request.client else 'unknown' + user_agent = request.headers.get('user-agent', 'unknown') + + log_data = { + "request_id": request_id, + "timestamp": timestamp.isoformat(), + "method": request.method, + "url": str(request.url), + "path": request.url.path, + "client_ip": client_ip, + "user_agent": user_agent, + "headers": dict(request.headers) if self.log_level <= logging.DEBUG else None + } + + # Log request body for debugging (be careful with sensitive data) + if self.log_body and self.log_level <= logging.DEBUG: + try: + body = await request.body() + if body and len(body) <= self.max_body_size: + try: + log_data["body"] = json.loads(body.decode()) + except (json.JSONDecodeError, UnicodeDecodeError): + log_data["body"] = body.decode('utf-8', errors='ignore')[:self.max_body_size] + except Exception: + pass # Skip body logging if it fails + + self.request_logger.info(f"Request started: {json.dumps(log_data, default=str)}") + + async def log_response(self, request: Request, response: Response, request_id: str, process_time: float): + """Log successful response details.""" + log_data = { + "request_id": request_id, + "status_code": response.status_code, + "process_time": f"{process_time:.3f}s", + "response_headers": dict(response.headers) if self.log_level <= logging.DEBUG else None + } + + self.request_logger.info(f"Request completed: {json.dumps(log_data, default=str)}") + + async def log_http_exception(self, request: Request, exc: HTTPException, request_id: str, process_time: float): + """Log HTTP exceptions with context.""" + log_data = { + "request_id": request_id, + "method": request.method, + "path": request.url.path, + "status_code": exc.status_code, + "detail": exc.detail, + "process_time": f"{process_time:.3f}s" + } + + # Log security-related HTTP errors + if exc.status_code in [401, 403]: + client_ip = getattr(request.client, 'host', 'unknown') if request.client else 'unknown' + self.security_logger.warning( + f"Authentication/Authorization failure - " + f"IP: {client_ip}, Path: {request.url.path}, " + f"Status: {exc.status_code}, Request ID: {request_id}" + ) + + if exc.status_code >= 500: + self.error_logger.error(f"HTTP Exception: {json.dumps(log_data, default=str)}") + else: + self.request_logger.warning(f"HTTP Exception: {json.dumps(log_data, default=str)}") + + async def log_error(self, request: Request, exc: Exception, request_id: str, process_time: float): + """Log unhandled exceptions with full context.""" + client_ip = getattr(request.client, 'host', 'unknown') if request.client else 'unknown' + + error_data = { + "request_id": request_id, + "method": request.method, + "url": str(request.url), + "path": request.url.path, + "client_ip": client_ip, + "error_type": type(exc).__name__, + "error_message": str(exc), + "process_time": f"{process_time:.3f}s", + "traceback": traceback.format_exc() + } + + self.error_logger.error(f"Unhandled exception: {json.dumps(error_data, default=str)}") + + +def setup_enhanced_logging(): + """ + Setup enhanced logging configuration for FastAPI. + + This function configures the logging system with appropriate + handlers and formatters for production use. + """ + # Create logs directory if it doesn't exist + import os + os.makedirs("./logs", exist_ok=True) + + # Configure root logger + logging.basicConfig( + level=logging.INFO, + format='%(asctime)s - %(name)s - %(levelname)s - %(message)s', + handlers=[ + logging.FileHandler('./logs/aniworld.log'), + logging.StreamHandler() + ] + ) + + # Reduce noise from external libraries + logging.getLogger("urllib3.connectionpool").setLevel(logging.WARNING) + logging.getLogger("charset_normalizer").setLevel(logging.WARNING) + logging.getLogger("uvicorn.access").setLevel(logging.WARNING) + + return logging.getLogger("aniworld") + + +# Initialize enhanced logging +enhanced_logger = setup_enhanced_logging() \ No newline at end of file diff --git a/web_todo.md b/web_todo.md index f0cb546..1619abf 100644 --- a/web_todo.md +++ b/web_todo.md @@ -106,7 +106,7 @@ This document contains tasks for migrating the web application from Flask to Fas - [x] Convert Flask middleware to FastAPI middleware - [x] Update error handling from Flask error handlers to FastAPI exception handlers - [x] Migrate request/response interceptors -- [ ] Update logging middleware if used +- [x] Update logging middleware if used ## 🧪 Testing and Validation