# Structured Access Logging Pattern (FastAPI)

Log every HTTP request with structured fields: method, path, status, duration, client IP, authenticated user ID, and request ID — without polluting route handlers.

## Overview

Access logs are cross-cutting. They should be added once as middleware, not sprinkled across every route handler. The pattern: a middleware records timing before dispatching the request and logs the result after the response is sent.

## Middleware Implementation

```python
# app/core/middleware.py
import time
from starlette.requests import Request

def add_access_log_middleware(app: FastAPI) -> None:
    logger = get_logger("access")

    @app.middleware("http")
    async def access_log_middleware(request: Request, call_next):
        start = time.monotonic()
        method = request.method
        path = request.url.path
        query = request.url.query

        response = await call_next(request)

        duration_ms = int((time.monotonic() - start) * 1000)
        request_id = response.headers.get("X-Request-ID", "")
        ip = get_client_ip(request)
        user_id = getattr(request.state, "user_id", None)

        logger.info(
            "request",
            method=method,
            path=path,
            query=query or None,
            status=response.status_code,
            duration_ms=duration_ms,
            ip=ip,
            request_id=request_id,
            user_id=user_id,
        )

        return response
```

**Key design choices:**
- `user_id` may be `None` for unauthenticated routes — the log entry still captures everything else
- `duration_ms` in integer milliseconds (precision sufficient for sub-second monitoring)
- Structlog named fields enable structured JSON output in production
- The middleware runs AFTER `request_id_middleware` so X-Request-ID is set on the response

## Wiring Order Matters

Middleware order in FastAPI/Starlette is **reversed** — the first registered middleware wraps the outermost layer. Wire them in dependency order:

```python
# app/main.py
def create_app() -> FastAPI:
    app = FastAPI(lifespan=lifespan)

    # Wire from outermost (first) to innermost (last):
    add_cors_middleware(app)        # Outermost — handles CORS preflight
    add_request_id_middleware(app)  # Sets X-Request-ID before logging
    add_access_log_middleware(app)  # Logs after response is complete
    add_trusted_host_middleware(app)# Innermost — validates Host header

    # ... exception handlers, routers ...
    return app
```

## Extracting Authenticated User ID

The middleware reads `request.state.user_id`. The auth dependency must set this value. Modify the shared auth helper to accept an optional `request` parameter:

```python
# app/core/auth.py
async def require_user_id_from_token(token: str, request: Request | None = None) -> int:
    payload = await decode_and_check_access_token(token)
    user_id = int(payload["sub"])
    if request is not None:
        request.state.user_id = user_id
    return user_id
```

Then each module's `require_user_id` FastAPI dependency passes the request:

```python
# app/modules/<name>/presentation/dependencies.py
async def require_user_id(
    token: Annotated[str, Depends(oauth2_scheme)],
    request: Request,  # FastAPI injects this automatically
) -> int:
    return await require_user_id_from_token(token, request=request)
```

For routes that decode the token directly (not via the shared helper), set `request.state.user_id` manually:

```python
@router.post("/logout", status_code=204)
async def logout(token: str = Depends(oauth2_scheme), request: Request, ...):
    payload = decode_and_check_access_token(token)
    user_id = int(payload["sub"])
    request.state.user_id = user_id  # For access log
    # ... proceed with logout ...
```

## Testing

Because the middleware runs on every request, integration tests exercise it implicitly. To verify specific log output:

```python
# Use structlog's capturing handler in tests (optional)
from structlog.testing import capture_logs

def test_access_log_emits_user_id(test_client, settings):
    with capture_logs() as cap_logs:
        token = create_access_token(subject="1")
        response = await test_client.get(
            "/api/v1/auth/me",
            headers={"Authorization": f"Bearer {token}"},
        )
    # Filter for access log entries
    access_logs = [e for e in cap_logs if e.get("event") == "request"]
    assert len(access_logs) == 2  # register, login, me...
    # In practice, just verify the HTTP response and check structured logs externally
```

For production, use structured JSON output (structlog `JSONRenderer` when `ENVIRONMENT != "local"`).

## Key Invariants

1. **Never block the request** — access log middleware catches all exceptions and always returns the response
2. **Never fail on missing state** — `getattr(request.state, "user_id", None)` not `request.state.user_id`
3. **Never log sensitive data** — no request body, no auth headers, no query params that could contain secrets
4. **Duration is wall-clock time** — `time.monotonic()` not affected by NTP adjustments
5. **X-Request-ID ties logs to traces** — include it in both structured logs and HTTP response headers