refactor: streamline logging setup and replace custom middleware with structured logging

alimkhann · alimkhann · commit b047b6e3172f · 2025-11-17T15:00:44.000+08:00
diff --git a/commitly-backend/app/core/logging.py b/commitly-backend/app/core/logging.py
@@ -0,0 +1,189 @@
+from __future__ import annotations
+
+import contextvars
+import json
+import logging
+from logging.config import dictConfig
+import time
+from datetime import datetime, timezone
+from typing import Any, Dict, MutableMapping, Optional
+from uuid import uuid4
+
+from fastapi import Request
+from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint
+from starlette.types import ASGIApp
+
+from app.core.config import settings
+
+RequestContext = Dict[str, Any]
+
+_request_context: contextvars.ContextVar[RequestContext] = contextvars.ContextVar(
+    "request_context", default={}
+)
+_LOGGING_CONFIGURED = False
+
+
+class RequestContextFilter(logging.Filter):
+    """Inject per-request context stored in a ContextVar into all log records."""
+
+    def filter(self, record: logging.LogRecord) -> bool:  # pragma: no cover - simple
+        context = dict(_request_context.get() or {})
+        for key, value in context.items():
+            setattr(record, key, value)
+        return True
+
+
+class JsonFormatter(logging.Formatter):
+    """Render log records as structured JSON."""
+
+    def format(self, record: logging.LogRecord) -> str:  # pragma: no cover - formatting
+        log: MutableMapping[str, Any] = {
+            "timestamp": self._format_timestamp(record.created),
+            "level": record.levelname,
+            "logger": record.name,
+            "message": record.getMessage(),
+        }
+
+        for attr in (
+            "request_id",
+            "client_ip",
+            "method",
+            "path",
+            "status_code",
+            "elapsed_ms",
+            "user_id",
+            "event",
+        ):
+            value = getattr(record, attr, None)
+            if value not in (None, ""):
+                log[attr] = value
+
+        if record.exc_info:
+            log["exc_info"] = self.formatException(record.exc_info)
+        if record.stack_info:
+            log["stack"] = self.formatStack(record.stack_info)
+
+        return json.dumps(log, ensure_ascii=False)
+
+    @staticmethod
+    def _format_timestamp(created: float) -> str:
+        return datetime.fromtimestamp(created, tz=timezone.utc).isoformat()
+
+
+def bind_request_context(**kwargs: Any) -> None:
+    """Merge values into the request-scoped logging context."""
+
+    current = dict(_request_context.get() or {})
+    current.update({k: v for k, v in kwargs.items() if v is not None})
+    _request_context.set(current)
+
+
+def clear_request_context() -> None:
+    """Reset the request-scoped logging context."""
+
+    _request_context.set({})
+
+
+def configure_logging() -> None:
+    global _LOGGING_CONFIGURED
+    if _LOGGING_CONFIGURED:
+        return
+
+    level = "DEBUG" if settings.debug else "INFO"
+    dictConfig(
+        {
+            "version": 1,
+            "disable_existing_loggers": False,
+            "formatters": {
+                "json": {
+                    "()": "app.core.logging.JsonFormatter",
+                }
+            },
+            "filters": {
+                "request_context": {
+                    "()": "app.core.logging.RequestContextFilter",
+                }
+            },
+            "handlers": {
+                "default": {
+                    "class": "logging.StreamHandler",
+                    "filters": ["request_context"],
+                    "formatter": "json",
+                    "stream": "ext://sys.stdout",
+                }
+            },
+            "loggers": {
+                "": {"handlers": ["default"], "level": level},
+                "uvicorn": {
+                    "handlers": ["default"],
+                    "level": level,
+                    "propagate": False,
+                },
+                "uvicorn.error": {
+                    "handlers": ["default"],
+                    "level": level,
+                    "propagate": False,
+                },
+                "uvicorn.access": {
+                    "handlers": ["default"],
+                    "level": "WARNING",
+                    "propagate": False,
+                },
+            },
+        }
+    )
+    _LOGGING_CONFIGURED = True
+
+
+class StructuredLoggingMiddleware(BaseHTTPMiddleware):
+    """Capture per-request diagnostics (latency, user ID, request ID)."""
+
+    def __init__(self, app: ASGIApp) -> None:
+        super().__init__(app)
+        self.logger = logging.getLogger("app.request")
+
+    async def dispatch(
+        self, request: Request, call_next: RequestResponseEndpoint
+    ):  # type: ignore[override]
+        request_id = (
+            request.headers.get("X-Request-ID")
+            or request.headers.get("X-Request-Id")
+            or uuid4().hex
+        )
+        client_ip: Optional[str] = request.client.host if request.client else None
+
+        bind_request_context(
+            request_id=request_id,
+            method=request.method,
+            path=request.url.path,
+            client_ip=client_ip,
+        )
+
+        start = time.perf_counter()
+        self.logger.info("request.started", extra={"event": "request_start"})
+
+        try:
+            response = await call_next(request)
+        except Exception:
+            elapsed_ms = (time.perf_counter() - start) * 1000
+            bind_request_context(elapsed_ms=round(elapsed_ms, 2), status_code=500)
+            self.logger.exception("request.failed", extra={"event": "request_error"})
+            raise
+        else:
+            elapsed_ms = (time.perf_counter() - start) * 1000
+            claims: Optional[Dict[str, Any]] = getattr(request.state, "clerk_claims", None)
+            user_id = claims.get("sub") if isinstance(claims, dict) else None
+
+            bind_request_context(
+                elapsed_ms=round(elapsed_ms, 2),
+                status_code=response.status_code,
+                user_id=user_id,
+            )
+            response.headers.setdefault("X-Request-ID", request_id)
+            self.logger.info(
+                "request.completed",
+                extra={"event": "request_complete"},
+            )
+            return response
+        finally:
+            clear_request_context()
diff --git a/commitly-backend/app/main.py b/commitly-backend/app/main.py
@@ -1,6 +1,5 @@
 from contextlib import asynccontextmanager
 import logging
-import sys
 
 from fastapi import Depends, FastAPI, Request, status
 from fastapi.exceptions import RequestValidationError
@@ -9,30 +8,15 @@
 from fastapi.openapi.utils import get_openapi
 from fastapi.responses import JSONResponse
 from sqlalchemy import text
-from starlette.middleware.base import BaseHTTPMiddleware
 
 from app.api import auth, donate, github, roadmap, waitlist
 from app.core.auth import ClerkAuthMiddleware, ClerkClaims, require_clerk_auth
 from app.core.config import settings
 from app.core.database import SessionLocal
+from app.core.logging import configure_logging, StructuredLoggingMiddleware
 
 
-def _configure_logging() -> None:
-    root_logger = logging.getLogger()
-    if root_logger.handlers:
-        return
-    handler = logging.StreamHandler(sys.stdout)
-    handler.setFormatter(
-        logging.Formatter(
-            fmt="%(asctime)s %(levelname)s [%(name)s] %(message)s",
-            datefmt="%Y-%m-%d %H:%M:%S",
-        )
-    )
-    root_logger.addHandler(handler)
-    root_logger.setLevel(logging.INFO)
-
-
-_configure_logging()
+configure_logging()
 logger = logging.getLogger(__name__)
 
 
@@ -109,38 +93,7 @@ def _ping():
     allow_headers=["*"],
 )
 app.add_middleware(ClerkAuthMiddleware)
-
-
-class RequestLoggingMiddleware(BaseHTTPMiddleware):
-    """Log all incoming requests for debugging."""
-
-    async def dispatch(self, request: Request, call_next):
-        import time
-
-        start_time = time.time()
-        logger.info(
-            f"Request: {request.method} {request.url.path} "
-            f"from {request.client.host if request.client else 'unknown'}"
-        )
-        try:
-            response = await call_next(request)
-            elapsed = time.time() - start_time
-            logger.info(
-                f"Response: {request.method} {request.url.path} "
-                f"-> {response.status_code} ({elapsed:.3f}s)"
-            )
-            return response
-        except Exception as e:
-            elapsed = time.time() - start_time
-            logger.error(
-                f"Error processing {request.method} {request.url.path} "
-                f"after {elapsed:.3f}s: {type(e).__name__}: {e}",
-                exc_info=True,
-            )
-            raise
-
-
-app.add_middleware(RequestLoggingMiddleware)
+app.add_middleware(StructuredLoggingMiddleware)
 
 # Include routers
 protected = [Depends(require_clerk_auth)]
diff --git a/commitly-backend/app/services/roadmap_repository.py b/commitly-backend/app/services/roadmap_repository.py
