"""Structured access-log middleware. Emits a single ``http_request`` INFO event per request, capturing the HTTP verb, path, status code, wall-clock duration, client IP, and a truncated user-agent. The goal is a compact but auditable trail of production traffic without the noise of a traditional access log and without ever writing secrets to disk. Key design choices: - **No bodies, no query strings.** We deliberately skip query strings entirely to avoid leaking tokens that might end up there in future (the magic-link consume route keeps its token in the path, so we redact that explicitly below). - **Magic-link path redaction.** Requests to ``/admin/auth/consume/{token}`` have the token segment replaced with ```` before logging. ``CLAUDE.md`` forbids logging raw tokens anywhere. - **Skip ``/healthz``.** Compose / Docker health probes hit this every few seconds. Logging each one drowns out real traffic. - **Exceptions still get logged.** If the downstream handler raises, we record a ``status_code=500`` entry before re-raising so no failed request vanishes silently. """ from __future__ import annotations import time import structlog from fastapi import Request from fastapi.responses import Response from starlette.middleware.base import BaseHTTPMiddleware logger = structlog.get_logger(__name__) # Prefix used to recognise magic-link consume URLs whose trailing token # segment must be redacted before logging. _CONSUME_PREFIX: str = "/admin/auth/consume/" # Path we skip entirely to reduce health-probe log noise. _SKIP_PATH: str = "/healthz" # User-agent strings are unbounded; cap to 256 chars so a hostile client # can't bloat log lines to arbitrary size. _UA_MAX: int = 256 def _redact_path(path: str) -> str: """Return ``path`` with magic-link tokens replaced by ````. The consume URL is ``/admin/auth/consume/{token}``; everything after the prefix is swapped out. We preserve the prefix so log readers can still see which route was hit. """ if path.startswith(_CONSUME_PREFIX): return _CONSUME_PREFIX + "" return path class AccessLogMiddleware(BaseHTTPMiddleware): """Log one ``http_request`` event per completed request. Installed outermost in :mod:`app.main` so the timing measurement covers the entire downstream middleware stack, including security headers and CSRF cookie work. """ async def dispatch(self, request: Request, call_next): """Time the request, log a structured event, reraise on failure.""" path: str = request.url.path # Early exit for health probes — don't even record timing. if path == _SKIP_PATH: return await call_next(request) method: str = request.method client_ip: str = request.client.host if request.client else "" user_agent: str = request.headers.get("user-agent", "")[:_UA_MAX] redacted_path: str = _redact_path(path) start: float = time.monotonic() try: response: Response = await call_next(request) except Exception: duration_ms = int((time.monotonic() - start) * 1000) # Record the failure before re-raising so unhandled exceptions # don't vanish from the log. Status is synthetic (500) because # the framework hasn't written a response yet at this point. logger.info( "http_request", method=method, path=redacted_path, status_code=500, duration_ms=duration_ms, client_ip=client_ip, user_agent=user_agent, ) raise duration_ms = int((time.monotonic() - start) * 1000) logger.info( "http_request", method=method, path=redacted_path, status_code=response.status_code, duration_ms=duration_ms, client_ip=client_ip, user_agent=user_agent, ) return response