mirror of
https://github.com/Routstr/routstr-core.git
synced 2026-10-05 20:28:23 +00:00
feat: add comprehensive logging infrastructure
- Add centralized logging configuration with daily rotation - Implement custom TRACE log level for detailed debugging - Add security filter to redact sensitive data (tokens, keys, passwords) - Add request ID tracking via middleware and context variables - Add version filter to include package version in all logs - Implement structured JSON logging for production - Add exception handlers with request ID tracking - Configure Rich console handler for development
This commit is contained in:
Shroominic
@@ -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,
|
||||
},
|
||||
)
|
||||
+42
-8
@@ -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},
|
||||
|
||||
@@ -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"]
|
||||
Reference in New Issue
Block a user