feat: enhance logging configuration and add request logging context

backend/app/core/error_handling.py

@@ -2,8 +2,8 @@
 
 from __future__ import annotations
 
-import logging
 from collections.abc import Awaitable, Callable
+from time import perf_counter
 from typing import TYPE_CHECKING, Any, Final
 from uuid import uuid4
 
@@ -13,12 +13,23 @@ from fastapi.responses import JSONResponse
 from starlette.exceptions import HTTPException as StarletteHTTPException
 from starlette.responses import Response
 
+from app.core.config import settings
+from app.core.logging import (
+    TRACE_LEVEL,
+    get_logger,
+    reset_request_id,
+    reset_request_route_context,
+    set_request_id,
+    set_request_route_context,
+)
+
 if TYPE_CHECKING:  # pragma: no cover
     from starlette.types import ASGIApp, Message, Receive, Scope, Send
 
-logger = logging.getLogger(__name__)
+logger = get_logger(__name__)
 
 REQUEST_ID_HEADER: Final[str] = "X-Request-Id"
+_HEALTH_CHECK_PATHS: Final[frozenset[str]] = frozenset({"/health", "/healthz", "/readyz"})
 
 ExceptionHandler = Callable[[Request, Exception], Response | Awaitable[Response]]
 
@@ -31,6 +42,8 @@ class RequestIdMiddleware:
         self._app = app
         self._header_name = header_name
         self._header_name_bytes = header_name.lower().encode("latin-1")
+        self._slow_request_ms = settings.request_log_slow_ms
+        self._include_health_logs = settings.request_log_include_health
 
     async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
         """Inject request-id into request state and response headers."""
@@ -38,18 +51,80 @@ class RequestIdMiddleware:
             await self._app(scope, receive, send)
             return
 
+        method = str(scope.get("method") or "UNKNOWN").upper()
+        path = str(scope.get("path") or "")
+        client = scope.get("client")
+        client_ip: str | None = None
+        if isinstance(client, tuple) and client and isinstance(client[0], str):
+            client_ip = client[0]
+        should_log = self._include_health_logs or path not in _HEALTH_CHECK_PATHS
+        started_at = perf_counter()
+        status_code: int | None = None
+
         request_id = self._get_or_create_request_id(scope)
+        context_token = set_request_id(request_id)
+        route_context_tokens = set_request_route_context(method, path)
+        if should_log:
+            logger.log(
+                TRACE_LEVEL,
+                "http.request.start",
+                extra={
+                    "method": method,
+                    "path": path,
+                    "client_ip": client_ip,
+                },
+            )
 
         async def send_with_request_id(message: Message) -> None:
+            nonlocal status_code
             if message["type"] == "http.response.start":
                 # Starlette uses `list[tuple[bytes, bytes]]` here.
                 headers: list[tuple[bytes, bytes]] = message.setdefault("headers", [])
                 if not any(key.lower() == self._header_name_bytes for key, _ in headers):
                     request_id_bytes = request_id.encode("latin-1")
                     headers.append((self._header_name_bytes, request_id_bytes))
+                status = message.get("status")
+                status_code = status if isinstance(status, int) else 500
+                if should_log:
+                    duration_ms = int((perf_counter() - started_at) * 1000)
+                    extra = {
+                        "method": method,
+                        "path": path,
+                        "status_code": status_code,
+                        "duration_ms": duration_ms,
+                        "client_ip": client_ip,
+                    }
+                    if status_code >= 500:
+                        logger.error("http.request.complete", extra=extra)
+                    elif status_code >= 400:
+                        logger.warning("http.request.complete", extra=extra)
+                    else:
+                        logger.debug("http.request.complete", extra=extra)
+                    if self._slow_request_ms and duration_ms >= self._slow_request_ms:
+                        logger.warning(
+                            "http.request.slow",
+                            extra={
+                                **extra,
+                                "slow_threshold_ms": self._slow_request_ms,
+                            },
+                        )
             await send(message)
 
-        await self._app(scope, receive, send_with_request_id)
+        try:
+            await self._app(scope, receive, send_with_request_id)
+        finally:
+            if should_log and status_code is None:
+                logger.warning(
+                    "http.request.incomplete",
+                    extra={
+                        "method": method,
+                        "path": path,
+                        "duration_ms": int((perf_counter() - started_at) * 1000),
+                        "client_ip": client_ip,
+                    },
+                )
+            reset_request_route_context(route_context_tokens)
+            reset_request_id(context_token)
 
     def _get_or_create_request_id(self, scope: Scope) -> str:
         # Accept a client-provided request id if present.