app/structured_log.py

"""Structured (JSON) logging + per-request context (P9 CP-A).

Three pieces:

- `JsonFormatter` — emits one JSON object per record with a stable schema.
- `RequestContextFilter` — pulls `request_id` + `slot_id` from contextvars
  and attaches them as record attributes.
- `RequestIdMiddleware` — mints a request_id per request (or reuses an
  incoming `X-Request-ID`), sets the contextvar, echoes it on the
  response.

Production sets `BRIDGE_LOG_FORMAT=json`; dev defaults to plaintext.

P8 CP-B's `RedactFilter` is applied independently; both filters coexist
on the root logger. CLI parity: stdlib only.
"""
from __future__ import annotations

import contextvars
import json
import logging
import os
import sys
import uuid
from datetime import datetime, timezone

from starlette.middleware.base import BaseHTTPMiddleware
from starlette.requests import Request


# ----- per-request context vars -------------------------------------------

request_id_ctx: contextvars.ContextVar[str | None] = contextvars.ContextVar(
    "bridge_request_id", default=None
)
slot_id_ctx: contextvars.ContextVar[str | None] = contextvars.ContextVar(
    "bridge_slot_id", default=None
)


# ----- formatter ----------------------------------------------------------

class JsonFormatter(logging.Formatter):
    """One JSON object per record with a stable field order."""

    def format(self, record: logging.LogRecord) -> str:
        payload: dict[str, object] = {
            "ts": datetime.now(timezone.utc).strftime("%Y-%m-%dT%H:%M:%S.%fZ"),
            "level": record.levelname,
            "logger": record.name,
        }
        # Context attached by RequestContextFilter (if running under request scope)
        rid = getattr(record, "request_id", None)
        sid = getattr(record, "slot_id", None)
        if rid:
            payload["request_id"] = rid
        if sid:
            payload["slot_id"] = sid
        try:
            payload["msg"] = record.getMessage()
        except Exception as exc:
            payload["msg"] = f"<format error: {exc.__class__.__name__}>"
        # Exception info (if any)
        if record.exc_info:
            payload["exc"] = self.formatException(record.exc_info)
        return json.dumps(payload, separators=(",", ":"), ensure_ascii=False)


# ----- filter -------------------------------------------------------------

class RequestContextFilter(logging.Filter):
    """Attaches the current request_id + slot_id contextvars to every record."""

    def filter(self, record: logging.LogRecord) -> bool:
        record.request_id = request_id_ctx.get()
        record.slot_id = slot_id_ctx.get()
        return True


# ----- middleware ---------------------------------------------------------

_REQUEST_ID_HEADER = "X-Request-ID"


class RequestIdMiddleware(BaseHTTPMiddleware):
    """Mints a request_id per request (or reuses incoming), sets contextvars,
    echoes the header on the response."""

    async def dispatch(self, request: Request, call_next):
        incoming = request.headers.get(_REQUEST_ID_HEADER)
        rid = incoming or uuid.uuid4().hex[:12]
        token_rid = request_id_ctx.set(rid)
        # slot_id is set by the JWT middleware later (or stays None for public routes)
        try:
            response = await call_next(request)
        finally:
            request_id_ctx.reset(token_rid)
        # Echo on response, regardless of inbound source
        response.headers[_REQUEST_ID_HEADER] = rid
        return response


# ----- install hook -------------------------------------------------------

_INSTALLED = False


def install_structured_logging() -> None:
    """Apply JsonFormatter + RequestContextFilter to the root logger.

    Honors `BRIDGE_LOG_FORMAT` env: `json` (production) installs; any other
    value (default `text`) is a no-op so dev keeps human-readable logs.

    Idempotent. Safe to call multiple times.
    """
    global _INSTALLED
    if _INSTALLED:
        return
    if os.environ.get("BRIDGE_LOG_FORMAT", "text").lower() != "json":
        return
    root = logging.getLogger()
    # If no handler yet, attach a stderr handler (uvicorn usually installs its
    # own, but be defensive).
    if not root.handlers:
        root.addHandler(logging.StreamHandler(stream=sys.stderr))
    fmt = JsonFormatter()
    for h in root.handlers:
        h.setFormatter(fmt)
    # Attach the context filter idempotently (don't duplicate)
    if not any(isinstance(f, RequestContextFilter) for f in root.filters):
        root.addFilter(RequestContextFilter())
    _INSTALLED = True


def reset_for_tests() -> None:
    """Test helper — drop the context filter + reset formatters; clear sentinel."""
    global _INSTALLED
    root = logging.getLogger()
    root.filters = [f for f in root.filters if not isinstance(f, RequestContextFilter)]
    _INSTALLED = False