feat(06-02): wire CorrelationIDMiddleware + config fields + promote 5 test stubs
- backend/config.py: add log_level: str = "INFO" and log_json: bool = False fields under Observability (Phase 6 — D-01) comment; pydantic-settings reads LOG_LEVEL / LOG_JSON env vars automatically - backend/main.py: add imports (uuid, time, structlog, ASGIApp/Receive/Scope/Send, setup_logging); add CorrelationIDMiddleware raw-ASGI class (NOT BaseHTTPMiddleware — avoids streaming buffering); call setup_logging() as first lifespan statement; register CorrelationIDMiddleware LAST so it runs FIRST (Starlette reverse order) - backend/tests/test_logging.py: remove all 5 xfail decorators; replace single-line bodies with real assertions for JSON renderer, contextvar binding, X-Correlation-ID header, no-bleed between requests, uvicorn.access propagate=False
This commit is contained in:
+67
-1
@@ -1,6 +1,9 @@
|
||||
import asyncio
|
||||
import time
|
||||
import uuid
|
||||
from contextlib import asynccontextmanager
|
||||
|
||||
import structlog
|
||||
from redis import asyncio as aioredis
|
||||
from fastapi import FastAPI, Request, Response
|
||||
from fastapi.middleware.cors import CORSMiddleware
|
||||
@@ -12,12 +15,14 @@ from slowapi.middleware import SlowAPIMiddleware
|
||||
from sqlalchemy import text
|
||||
from starlette.middleware.base import BaseHTTPMiddleware
|
||||
from starlette.responses import Response as StarletteResponse
|
||||
from starlette.types import ASGIApp, Receive, Scope, Send
|
||||
|
||||
from api.auth import limiter as auth_limiter
|
||||
from api.documents import router as documents_router
|
||||
from api.topics import router as topics_router
|
||||
from config import settings
|
||||
from db.session import AsyncSessionLocal, engine
|
||||
from services.logging import setup_logging
|
||||
|
||||
|
||||
# ── CSP / Security headers middleware ────────────────────────────────────────
|
||||
@@ -62,6 +67,60 @@ class OriginValidationMiddleware(BaseHTTPMiddleware):
|
||||
return await call_next(request)
|
||||
|
||||
|
||||
# ── Correlation ID Middleware ─────────────────────────────────────────────────
|
||||
|
||||
class CorrelationIDMiddleware:
|
||||
"""Generate per-request UUID correlation ID; bind to structlog contextvars.
|
||||
|
||||
Uses raw ASGI (NOT BaseHTTPMiddleware) to avoid response-body buffering
|
||||
issues with streaming responses (RESEARCH.md Anti-Patterns).
|
||||
|
||||
Execution order (Starlette reverse-insertion):
|
||||
Registered LAST in app.add_middleware() so it runs FIRST on every request.
|
||||
|
||||
Per-request:
|
||||
1. clear_contextvars() — Pitfall 2 guard; prevents context bleed between
|
||||
requests handled by the same worker.
|
||||
2. bind_contextvars(correlation_id, path, method) — available in all
|
||||
downstream log calls.
|
||||
3. Appends X-Correlation-ID to the response headers.
|
||||
4. After response: bind duration_ms for final log emission.
|
||||
"""
|
||||
|
||||
def __init__(self, app: ASGIApp) -> None:
|
||||
self.app = app
|
||||
|
||||
async def __call__(self, scope: Scope, receive: Receive, send: Send) -> None:
|
||||
if scope["type"] != "http":
|
||||
await self.app(scope, receive, send)
|
||||
return
|
||||
|
||||
correlation_id = str(uuid.uuid4())
|
||||
start_ns = time.perf_counter_ns()
|
||||
|
||||
# Pitfall 2: MUST be first — clears any context from a prior request
|
||||
# on the same worker before binding new values.
|
||||
structlog.contextvars.clear_contextvars()
|
||||
structlog.contextvars.bind_contextvars(
|
||||
correlation_id=correlation_id,
|
||||
path=scope.get("path", ""),
|
||||
method=scope.get("method", ""),
|
||||
)
|
||||
|
||||
async def send_with_header(message: dict) -> None:
|
||||
if message["type"] == "http.response.start":
|
||||
headers = list(message.get("headers", []))
|
||||
headers.append((b"x-correlation-id", correlation_id.encode()))
|
||||
message = {**message, "headers": headers}
|
||||
await send(message)
|
||||
|
||||
await self.app(scope, receive, send_with_header)
|
||||
|
||||
# Bind duration after the response so downstream loggers can emit it.
|
||||
duration_ms = (time.perf_counter_ns() - start_ns) / 1_000_000
|
||||
structlog.contextvars.bind_contextvars(duration_ms=round(duration_ms, 2))
|
||||
|
||||
|
||||
# ── Lifespan ──────────────────────────────────────────────────────────────────
|
||||
|
||||
@asynccontextmanager
|
||||
@@ -74,6 +133,10 @@ async def lifespan(app: FastAPI):
|
||||
TOTP replay prevention (AUTH-08).
|
||||
Admin bootstrap (D-04): idempotent, runs only if no users exist.
|
||||
"""
|
||||
# Initialize structured logging first — all subsequent log calls use the
|
||||
# configured renderer (JSON in production, console in dev).
|
||||
setup_logging(json_logs=settings.log_json, log_level=settings.log_level)
|
||||
|
||||
# MinIO bucket initialization (RESEARCH.md Pattern 4)
|
||||
minio_client = Minio(
|
||||
settings.minio_endpoint,
|
||||
@@ -127,9 +190,12 @@ app.add_middleware(
|
||||
allow_headers=["*"],
|
||||
)
|
||||
|
||||
# 3. Origin validation — runs first (added last), before CORS and route handlers
|
||||
# 3. Origin validation — runs second (added second-to-last), before CORS and route handlers
|
||||
app.add_middleware(OriginValidationMiddleware)
|
||||
|
||||
# 4. CorrelationID — added LAST so it runs FIRST (Starlette reverse-insertion order)
|
||||
app.add_middleware(CorrelationIDMiddleware)
|
||||
|
||||
|
||||
# ── Routes ────────────────────────────────────────────────────────────────────
|
||||
|
||||
|
||||
Reference in New Issue
Block a user