From abe8f8ee9091477bef2dd0d479285ee06382d919 Mon Sep 17 00:00:00 2001 From: curo1305 Date: Wed, 3 Jun 2026 18:47:49 +0200 Subject: [PATCH] feat(06-02): wire CorrelationIDMiddleware + config fields + promote 5 test stubs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - 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 --- backend/config.py | 4 ++ backend/main.py | 68 ++++++++++++++++++++++++++- backend/tests/test_logging.py | 88 ++++++++++++++++++++++++++++------- 3 files changed, 143 insertions(+), 17 deletions(-) diff --git a/backend/config.py b/backend/config.py index 5fbea8c..0844e33 100644 --- a/backend/config.py +++ b/backend/config.py @@ -70,5 +70,9 @@ class Settings(BaseSettings): # used to construct OAuth success/error redirect to Vue app (per Phase 5 B4 fix) # Note: frontend_url already declared above for Phase 2 (password reset links) — shared field + # Observability (Phase 6 — D-01) + log_level: str = "INFO" + log_json: bool = False + settings = Settings() diff --git a/backend/main.py b/backend/main.py index 7a3871b..94d8ef3 100644 --- a/backend/main.py +++ b/backend/main.py @@ -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 ──────────────────────────────────────────────────────────────────── diff --git a/backend/tests/test_logging.py b/backend/tests/test_logging.py index a29f744..60bce65 100644 --- a/backend/tests/test_logging.py +++ b/backend/tests/test_logging.py @@ -1,52 +1,108 @@ """ -Structured logging test stubs — D-01, D-02. +Structured logging tests — D-01, D-02. -Wave 0 xfail scaffold for Phase 6 plan 06-02. - -All tests use strict=False so an unexpected pass during development -never breaks CI. Implementation lands in plan 06-02. +Promoted from xfail scaffold (06-01) to real assertions by plan 06-02. """ from __future__ import annotations +import logging + import pytest +import structlog # ── D-01: JSON renderer wired through ProcessorFormatter ───────────────────── -@pytest.mark.xfail(strict=False, reason="implementation in 06-02") -async def test_setup_logging_emits_json_when_LOG_JSON_true(): +async def test_setup_logging_emits_json_when_LOG_JSON_true(capsys): """setup_logging(json_logs=True) installs JSONRenderer through ProcessorFormatter and the root logger emits JSON to stdout.""" - pytest.xfail("not implemented yet") + from services.logging import setup_logging + + setup_logging(json_logs=True, log_level="INFO") + structlog.get_logger("test").info("probe_event", check_key="check_value") + + captured = capsys.readouterr() + output = captured.err # logging.StreamHandler writes to stderr by default + assert '"event"' in output, f"Expected JSON with 'event' key, got: {output!r}" + assert "probe_event" in output, f"Expected 'probe_event' in output, got: {output!r}" # ── D-02: CorrelationIDMiddleware binds structlog contextvars ───────────────── -@pytest.mark.xfail(strict=False, reason="implementation in 06-02") async def test_correlation_id_middleware_binds_contextvar(async_client): """CorrelationIDMiddleware binds correlation_id, path, and method into structlog.contextvars for every inbound HTTP request.""" - pytest.xfail("not implemented yet") + # Make a request — if the middleware is wired, structlog contextvars are + # bound. We verify indirectly by checking the X-Correlation-ID header + # (the middleware also sets that from the same correlation_id it binds). + response = await async_client.get("/health") + assert response.status_code == 200 + assert "x-correlation-id" in response.headers, ( + "X-Correlation-ID header missing — CorrelationIDMiddleware may not be " + "registered or may not be binding contextvars correctly." + ) + cid = response.headers["x-correlation-id"] + # UUID4 format: 8-4-4-4-12 hex chars + import re + assert re.match( + r"^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$", + cid, + ), f"correlation_id is not a UUID4: {cid!r}" -@pytest.mark.xfail(strict=False, reason="implementation in 06-02") async def test_correlation_id_response_header_present(async_client): """Every HTTP response includes an X-Correlation-ID header set to the correlation_id bound by CorrelationIDMiddleware.""" - pytest.xfail("not implemented yet") + r1 = await async_client.get("/health") + r2 = await async_client.get("/health") + + assert "x-correlation-id" in r1.headers, "First request missing X-Correlation-ID" + assert "x-correlation-id" in r2.headers, "Second request missing X-Correlation-ID" + + cid1 = r1.headers["x-correlation-id"] + cid2 = r2.headers["x-correlation-id"] + + # Each request must receive its own unique correlation ID + assert cid1 != cid2, ( + f"Both requests received the same correlation_id ({cid1!r}) — " + "CorrelationIDMiddleware is not generating a fresh UUID per request." + ) -@pytest.mark.xfail(strict=False, reason="implementation in 06-02") async def test_contextvars_cleared_between_requests(async_client): """Pitfall 2 guard: clear_contextvars() runs first in the middleware so user_id from a prior request never bleeds into the next request's log context.""" - pytest.xfail("not implemented yet") + # Manually bind a sentinel value into structlog contextvars to simulate + # a "leftover" context from a previous request. + structlog.contextvars.bind_contextvars(sentinel_bleed_test="should_not_appear") + + # Make a new request — CorrelationIDMiddleware must clear_contextvars() first. + response = await async_client.get("/health") + assert response.status_code == 200 + + # After the request, the middleware has run clear_contextvars(). The sentinel + # we pre-bound should have been wiped. Verify by checking that the contextvars + # map no longer contains our sentinel (it may contain new keys bound by the + # middleware itself, e.g. correlation_id, path, method). + ctx = structlog.contextvars.get_contextvars() + assert "sentinel_bleed_test" not in ctx, ( + f"Bleed detected: 'sentinel_bleed_test' still in contextvars after request. " + f"clear_contextvars() may not be running as the first middleware operation. " + f"Context: {ctx}" + ) # ── D-01 / uvicorn log suppression ─────────────────────────────────────────── -@pytest.mark.xfail(strict=False, reason="implementation in 06-02") async def test_uvicorn_access_log_suppressed(): """uvicorn.access propagate=False after setup_logging() so the CorrelationIDMiddleware owns request logging and access lines are not doubled.""" - pytest.xfail("not implemented yet") + from services.logging import setup_logging + + setup_logging(json_logs=False, log_level="INFO") + access_logger = logging.getLogger("uvicorn.access") + assert access_logger.propagate is False, ( + "uvicorn.access.propagate should be False after setup_logging() to prevent " + "duplicate request log lines. Currently: " + f"propagate={access_logger.propagate}" + )