diff --git a/routstr/core/exceptions.py b/routstr/core/exceptions.py new file mode 100644 index 00000000..e74d3e05 --- /dev/null +++ b/routstr/core/exceptions.py @@ -0,0 +1,57 @@ +from fastapi import Request +from fastapi.responses import JSONResponse + +from .logging import get_logger + +logger = get_logger(__name__) + + +async def http_exception_handler(request: Request, exc: Exception) -> JSONResponse: + """Handle HTTP exceptions and include request ID in response.""" + request_id = getattr(request.state, "request_id", "unknown") + + # Get status code and detail - works for both FastAPI and Starlette HTTPException + status_code = getattr(exc, "status_code", 500) + detail = getattr(exc, "detail", str(exc)) + + logger.warning( + "HTTP exception", + extra={ + "request_id": request_id, + "status_code": status_code, + "detail": detail, + "path": request.url.path, + }, + ) + + return JSONResponse( + status_code=status_code, + content={ + "detail": detail, + "request_id": request_id, + }, + ) + + +async def general_exception_handler(request: Request, exc: Exception) -> JSONResponse: + """Handle general exceptions and include request ID in response.""" + request_id = getattr(request.state, "request_id", "unknown") + + logger.error( + "Unhandled exception", + extra={ + "request_id": request_id, + "error": str(exc), + "error_type": type(exc).__name__, + "path": request.url.path, + }, + exc_info=True, + ) + + return JSONResponse( + status_code=500, + content={ + "detail": "Internal server error, please contact support with the request ID.", + "request_id": request_id, + }, + ) diff --git a/routstr/core/logging.py b/routstr/core/logging.py index 79690ac7..3f17c44e 100644 --- a/routstr/core/logging.py +++ b/routstr/core/logging.py @@ -50,6 +50,7 @@ class DailyRotatingFileHandler(logging.handlers.TimedRotatingFileHandler): self.baseFilename = new_filename self.current_date = new_date + print("self.backupCount", self.backupCount) # FIX ME: not sure if we need this # self._cleanup_old_files() @@ -115,6 +116,23 @@ class VersionFilter(logging.Filter): return True +class RequestIdFilter(logging.Filter): + """Filter to add request ID to all log records.""" + + def filter(self, record: logging.LogRecord) -> bool: + """Add request ID to the log record if available.""" + try: + # Import here to avoid circular imports + from .middleware import request_id_context + + request_id = request_id_context.get() + record.request_id = request_id if request_id else "no-request-id" + except ImportError: + # If middleware isn't available yet, just use default + record.request_id = "no-request-id" + return True + + class SecurityFilter(logging.Filter): """Filter to remove sensitive information from logs.""" @@ -198,12 +216,13 @@ def setup_logging() -> None: "formatters": { "json": { "()": jsonlogger.JsonFormatter, - "format": "%(asctime)s %(name)s %(levelname)s %(message)s %(pathname)s %(lineno)d %(version)s", + "format": "%(asctime)s %(name)s %(levelname)s %(message)s %(pathname)s %(lineno)d %(version)s %(request_id)s", "datefmt": "%Y-%m-%d %H:%M:%S", }, }, "filters": { "version_filter": {"()": VersionFilter}, + "request_id_filter": {"()": RequestIdFilter}, "security_filter": {"()": SecurityFilter}, }, "handlers": { @@ -214,7 +233,7 @@ def setup_logging() -> None: "show_path": False, "rich_tracebacks": True, "markup": True, - "filters": ["security_filter"], + "filters": ["request_id_filter", "security_filter"], }, "file": { "()": DailyRotatingFileHandler, @@ -225,14 +244,14 @@ def setup_logging() -> None: "interval": 1, # Every 1 day "backupCount": 30, # Keep 30 days of logs "atTime": None, # Rotate at midnight (00:00) - "filters": ["version_filter", "security_filter"], + "filters": ["version_filter", "request_id_filter", "security_filter"], }, }, "loggers": { "routstr": { "level": log_level, "handlers": handlers, - "propagate": True, + "propagate": False, }, "routstr.payment": { "level": log_level, @@ -249,6 +268,21 @@ def setup_logging() -> None: "handlers": handlers, "propagate": False, }, + "routstr.payment.models": { + "level": log_level, + "handlers": handlers, + "propagate": False, + }, + "routstr.core.exceptions": { + "level": log_level, + "handlers": handlers, + "propagate": False, + }, + "routstr.core.middleware": { + "level": log_level, + "handlers": ["file"], + "propagate": False, + }, # Suppress verbose third-party logging "httpx": { "level": "WARNING", @@ -261,13 +295,13 @@ def setup_logging() -> None: "propagate": False, }, "uvicorn.access": { - "level": "WARNING", - "handlers": ["console"] if console_enabled else [], + "level": log_level, # Use the configured log level instead of WARNING + "handlers": handlers, # Use both console and file handlers "propagate": False, }, "uvicorn.error": { - "level": "INFO", - "handlers": ["console"], + "level": log_level, # Use the configured log level + "handlers": handlers, # Use both console and file handlers "propagate": False, }, "watchfiles.main": {"level": "WARNING", "handlers": [], "propagate": False}, diff --git a/routstr/core/middleware.py b/routstr/core/middleware.py new file mode 100644 index 00000000..3feada7e --- /dev/null +++ b/routstr/core/middleware.py @@ -0,0 +1,126 @@ +import time +import uuid +from contextvars import ContextVar +from typing import Callable + +from fastapi import Request, Response +from starlette.middleware.base import BaseHTTPMiddleware + +from .logging import get_logger + +logger = get_logger(__name__) + +# Context variable to store request ID across async context +request_id_context: ContextVar[str | None] = ContextVar("request_id", default=None) + + +class LoggingMiddleware(BaseHTTPMiddleware): + """Middleware to log detailed request and response information.""" + + async def dispatch(self, request: Request, call_next: Callable) -> Response: + # Generate request ID + request_id = str(uuid.uuid4()) + request.state.request_id = request_id + + # Set request ID in context for logging + token = request_id_context.set(request_id) + + # Start timing + start_time = time.time() + + # Log request details + request_body = None + if request.method in ["POST", "PUT", "PATCH"]: + try: + # Only read body for non-streaming requests + if hasattr(request, "_body"): + request_body = await request.body() + except Exception: + pass + + # Extract request info + client_host = None + if request.client: + client_host = request.client.host + + # Log incoming request + logger.info( + "Incoming request", + extra={ + "request_id": request_id, + "method": request.method, + "path": request.url.path, + "query_params": dict(request.query_params), + "client_host": client_host, + "headers": { + k: v + for k, v in request.headers.items() + if k.lower() not in ["authorization", "x-cashu", "cookie"] + }, + "body_size": len(request_body) if request_body else 0, + }, + ) + + # Log at TRACE level for full body (security filter will redact sensitive data) + if request_body and hasattr(logger, "trace"): + logger.trace( + "Request body", + extra={ + "request_id": request_id, + "method": request.method, + "path": request.url.path, + "body": request_body.decode("utf-8", errors="ignore")[ + :1000 + ], # Limit size + }, + ) + + # Process request + try: + response = await call_next(request) + + # Calculate duration + duration = time.time() - start_time + + # Log response + logger.info( + "Request completed", + extra={ + "request_id": request_id, + "method": request.method, + "path": request.url.path, + "status_code": response.status_code, + "duration_ms": round(duration * 1000, 2), + "client_host": client_host, + }, + ) + if hasattr(response, "headers"): + response.headers["X-Routstr-Request-Id"] = request_id + + return response + + except Exception as e: + # Calculate duration + duration = time.time() - start_time + + # Log error + logger.error( + "Request failed", + extra={ + "request_id": request_id, + "method": request.method, + "path": request.url.path, + "duration_ms": round(duration * 1000, 2), + "client_host": client_host, + "error": str(e), + "error_type": type(e).__name__, + }, + exc_info=True, + ) + raise + finally: + # Reset context + request_id_context.reset(token) + + +__all__ = ["LoggingMiddleware", "request_id_context"]