From ba7ec48c4f0e5834ae6c7e6efba15f6b1892d6cf Mon Sep 17 00:00:00 2001 From: Wang Defa Date: Tue, 9 Dec 2025 17:46:07 +0800 Subject: [PATCH] =?UTF-8?q?=E6=96=B0=E5=A2=9E=E8=AF=B7=E6=B1=82/=E5=93=8D?= =?UTF-8?q?=E5=BA=94=E6=97=A5=E5=BF=97=E4=B8=AD=E9=97=B4=E4=BB=B6=EF=BC=8C?= =?UTF-8?q?=E6=94=AF=E6=8C=81=E8=AF=A6=E7=BB=86=E7=9A=84=E8=AF=B7=E6=B1=82?= =?UTF-8?q?=E5=92=8C=E5=93=8D=E5=BA=94=E4=BF=A1=E6=81=AF=E8=AE=B0=E5=BD=95?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .env.example | 8 +- src/api/middleware/__init__.py | 6 + src/api/middleware/logging_middleware.py | 156 +++++++++++++++++++++++ src/main.py | 4 + 4 files changed, 172 insertions(+), 2 deletions(-) create mode 100644 src/api/middleware/__init__.py create mode 100644 src/api/middleware/logging_middleware.py diff --git a/.env.example b/.env.example index 5a7a4a7..6366707 100644 --- a/.env.example +++ b/.env.example @@ -53,10 +53,14 @@ STREAM_CHUNK_SIZE=1024 # Logging # Log level: DEBUG, INFO, WARNING, ERROR, CRITICAL LOG_LEVEL=INFO -# Log incoming requests (may contain sensitive data) + +# Enable detailed request/response logging for debugging +# LOG_REQUESTS: Print incoming request details (method, URL, headers, body) +# LOG_RESPONSES: Print outgoing response details (status, headers, body) +# Note: Sensitive data (like API keys) are automatically filtered from logs LOG_REQUESTS=false -# Log responses (may contain sensitive data) LOG_RESPONSES=false + # Log file path (optional, if not set logs only to console) LOG_FILE=./logs/app.log # Max log file size in MB (default: 10) diff --git a/src/api/middleware/__init__.py b/src/api/middleware/__init__.py new file mode 100644 index 0000000..2611b07 --- /dev/null +++ b/src/api/middleware/__init__.py @@ -0,0 +1,6 @@ +""" +API middleware components. +""" +from .logging_middleware import LoggingMiddleware, setup_logging_middleware + +__all__ = ["LoggingMiddleware", "setup_logging_middleware"] diff --git a/src/api/middleware/logging_middleware.py b/src/api/middleware/logging_middleware.py new file mode 100644 index 0000000..305ecee --- /dev/null +++ b/src/api/middleware/logging_middleware.py @@ -0,0 +1,156 @@ +""" +Logging middleware for request/response debugging. +""" +import json +import logging +import time +from typing import Callable +from fastapi import Request, Response +from starlette.middleware.base import BaseHTTPMiddleware +from starlette.responses import StreamingResponse + +from core.config import get_settings + +logger = logging.getLogger(__name__) + + +class LoggingMiddleware(BaseHTTPMiddleware): + """ + Middleware to log detailed request and response information. + Activated when LOG_REQUESTS or LOG_RESPONSES is enabled. + """ + + async def dispatch(self, request: Request, call_next: Callable) -> Response: + """Process request and log details.""" + settings = get_settings() + + # Generate request ID for tracking + request_id = f"req_{int(time.time() * 1000)}" + + # Log request details + if settings.log_requests or settings.debug: + await self._log_request(request, request_id) + + # Record start time + start_time = time.time() + + # Process request + response = await call_next(request) + + # Calculate processing time + process_time = time.time() - start_time + + # Log response details (only for non-streaming responses) + if (settings.log_responses or settings.debug) and not isinstance(response, StreamingResponse): + await self._log_response(response, request_id, process_time) + elif isinstance(response, StreamingResponse): + logger.debug(f"[{request_id}] Response: Streaming response (not logged)") + + return response + + async def _log_request(self, request: Request, request_id: str): + """Log detailed request information.""" + try: + # Basic request info + logger.debug("=" * 80) + logger.debug(f"[{request_id}] 📨 INCOMING REQUEST") + logger.debug("=" * 80) + logger.debug(f"Method: {request.method}") + logger.debug(f"URL: {request.url.path}") + logger.debug(f"Query Params: {dict(request.query_params)}") + + # Headers (filter sensitive data) + headers = dict(request.headers) + if "authorization" in headers: + headers["authorization"] = "Bearer ***" + logger.debug(f"Headers: {json.dumps(headers, indent=2)}") + + # Request body + if request.method in ["POST", "PUT", "PATCH"]: + body = await self._read_body(request) + if body: + try: + # Try to parse and pretty-print JSON + body_json = json.loads(body) + logger.debug(f"Request Body:\n{json.dumps(body_json, indent=2, ensure_ascii=False)}") + except json.JSONDecodeError: + # Log raw body if not JSON + logger.debug(f"Request Body (raw): {body[:1000]}...") # Limit to 1000 chars + + logger.debug("=" * 80) + + except Exception as e: + logger.error(f"Error logging request: {e}") + + async def _log_response(self, response: Response, request_id: str, process_time: float): + """Log detailed response information.""" + try: + logger.debug("=" * 80) + logger.debug(f"[{request_id}] 📤 OUTGOING RESPONSE") + logger.debug("=" * 80) + logger.debug(f"Status Code: {response.status_code}") + logger.debug(f"Processing Time: {process_time:.3f}s") + + # Headers + headers = dict(response.headers) + logger.debug(f"Headers: {json.dumps(headers, indent=2)}") + + # Response body + body = b"" + async for chunk in response.body_iterator: + body += chunk + + # Recreate response body iterator + response.body_iterator = self._create_body_iterator(body) + + if body: + try: + # Try to parse and pretty-print JSON + body_json = json.loads(body.decode()) + logger.debug(f"Response Body:\n{json.dumps(body_json, indent=2, ensure_ascii=False)}") + except (json.JSONDecodeError, UnicodeDecodeError): + # Log raw body if not JSON + logger.debug(f"Response Body (raw): {body[:1000]}...") # Limit to 1000 chars + + logger.debug("=" * 80) + + except Exception as e: + logger.error(f"Error logging response: {e}") + + async def _read_body(self, request: Request) -> str: + """Read request body without consuming it.""" + try: + body = await request.body() + + # Create new receive callable to preserve body for downstream handlers + async def receive(): + return {"type": "http.request", "body": body} + + # Replace request's receive + request._receive = receive + + return body.decode() + except Exception as e: + logger.error(f"Error reading request body: {e}") + return "" + + def _create_body_iterator(self, body: bytes): + """Create an async iterator for response body.""" + async def iterator(): + yield body + return iterator() + + +def setup_logging_middleware(app): + """ + Add logging middleware to FastAPI app. + Only active when LOG_REQUESTS or LOG_RESPONSES is enabled. + """ + settings = get_settings() + if settings.log_requests or settings.log_responses or settings.debug: + app.add_middleware(LoggingMiddleware) + logger.info("🔍 Request/Response logging middleware enabled") + if settings.log_requests or settings.debug: + logger.info(" - Request logging: ON") + if settings.log_responses or settings.debug: + logger.info(" - Response logging: ON") diff --git a/src/main.py b/src/main.py index 475a437..def69ee 100644 --- a/src/main.py +++ b/src/main.py @@ -20,6 +20,7 @@ from api.routers import models, chat, embeddings from api.schemas import ErrorResponse, ErrorDetail from api.error_handler import OCIErrorHandler from api.exceptions import ModelNotFoundException, InvalidModelTypeException +from api.middleware import setup_logging_middleware # Configure logging @@ -133,6 +134,9 @@ app.add_middleware( allow_headers=["*"], ) +# Add logging middleware (for request/response debugging) +setup_logging_middleware(app) + # Exception handlers @app.exception_handler(ModelNotFoundException)