pdf/gateway/app/services/logs.py

"""Structured logging, and the correlation id that makes it useful.

The conversion engine had no logging at all: 181 broad ``except`` handlers
across ``app/services/convert/`` and not one ``logger`` reference among them.
What existed elsewhere was 41 ``print()`` calls — no level, no timestamp, no
traceback, and no way to tell which of six concurrent conversions emitted a
line. One of them printed a bearer token.

Three decisions, each made for a reason worth writing down:

**Key=value, not free prose.** ``ocr_failed page=7 stage=recognise
reason=TimeoutError`` can be grepped, counted and alerted on. "OCR failed on
page 7" cannot. JSON is available for a log shipper
(``CONVERT_LOG_FORMAT=json``); the default stays human-readable because the
usual reader is a person tailing a container.

**A correlation id bound to the work, not passed through it.** A conversion
crosses forty modules and several threads. Threading a ``job_id`` parameter
through all of them would be a large change that every future caller can
forget. A ``ContextVar`` set once at the boundary is carried automatically —
including into ``run_with_timeout``'s workers, which copy the caller's context
by design.

**Configured once, explicitly.** The stdlib's default root level is WARNING, so
the handful of ``logger.info`` calls that already existed were being discarded
at runtime. ``configure()`` is idempotent and safe to call from a test.

No new dependency: stdlib ``logging`` only.
"""

from __future__ import annotations

import contextvars
import json
import logging
import os
import sys
import time
import uuid
from collections.abc import Iterator
from contextlib import contextmanager
from typing import Any

# The id of the unit of work currently running, or "-" outside one. Read by the
# formatter, so nothing in the call chain has to carry it.
_correlation: contextvars.ContextVar[str] = contextvars.ContextVar(
    "log_correlation_id", default="-"
)

# Field values that must never reach a log line, matched on the *key*. Matching
# on key rather than value is what makes this reliable: a token is only
# recognisable by the name of the thing holding it.
_REDACTED_KEYS = frozenset(
    {
        "auth_token",
        "authorization",
        "api_key",
        "apikey",
        "password",
        "secret",
        "token",
        "fresh_token",
        "cookie",
        "x-csrf-token",
        "csrf_token",
        "bearer",
    }
)

REDACTED = "***"

_configured = False


def correlation_id() -> str:
    """The id of the work in flight, for a caller that wants to echo it."""
    return _correlation.get()


@contextmanager
def correlation_scope(value: str | None = None) -> Iterator[str]:
    """Bind a correlation id for the duration of one unit of work.

    Resets on exit rather than overwriting, so a pooled worker thread cannot
    leak one job's id into the next job that lands on it.
    """
    ident = value or uuid.uuid4().hex[:12]
    token = _correlation.set(ident)
    try:
        yield ident
    finally:
        _correlation.reset(token)


def redact(key: str, value: Any) -> Any:
    """Blank a value whose *key* names a secret."""
    return REDACTED if key.strip().lower() in _REDACTED_KEYS else value


def redact_mapping(data: Any) -> Any:
    """Recursively redact a mapping before it is logged.

    Used for context dictionaries that are useful to see but hold credentials
    among their fields — logging the whole dict is how the token leak happened.
    """
    if isinstance(data, dict):
        return {
            k: (REDACTED if str(k).strip().lower() in _REDACTED_KEYS else redact_mapping(v))
            for k, v in data.items()
        }
    if isinstance(data, (list, tuple)):
        return [redact_mapping(v) for v in data]
    return data


def _render_value(value: Any) -> str:
    """One field, rendered so a grep for ``key=value`` finds it."""
    if value is None:
        return "-"
    if isinstance(value, bool):
        return "true" if value else "false"
    if isinstance(value, float):
        return f"{value:.3f}"
    text = str(value)
    if not text:
        return '""'
    if any(c.isspace() or c == '"' for c in text):
        return json.dumps(text)
    return text


class _KeyValueFormatter(logging.Formatter):
    """``ts level logger cid=… event field=value`` — one line, greppable."""

    def format(self, record: logging.LogRecord) -> str:
        base = (
            f"{self.formatTime(record, '%Y-%m-%dT%H:%M:%S')} "
            f"{record.levelname:<7} {record.name} "
            f"cid={getattr(record, 'correlation_id', '-')} "
            f"{record.getMessage()}"
        )
        fields = getattr(record, "fields", None)
        if fields:
            base += " " + " ".join(f"{k}={_render_value(redact(k, v))}" for k, v in fields.items())
        if record.exc_info:
            base += "\n" + self.formatException(record.exc_info)
        return base


class _JsonFormatter(logging.Formatter):
    """One JSON object per line, for a log shipper."""

    def format(self, record: logging.LogRecord) -> str:
        payload: dict[str, Any] = {
            "ts": time.strftime("%Y-%m-%dT%H:%M:%S", time.gmtime(record.created)),
            "level": record.levelname,
            "logger": record.name,
            "cid": getattr(record, "correlation_id", "-"),
            "event": record.getMessage(),
        }
        for key, value in (getattr(record, "fields", None) or {}).items():
            payload[key] = redact(key, value)
        if record.exc_info:
            payload["exception"] = self.formatException(record.exc_info)
        return json.dumps(payload, default=str)


class _CorrelationFilter(logging.Filter):
    """Stamp every record with the id of the work that produced it."""

    def filter(self, record: logging.LogRecord) -> bool:
        record.correlation_id = _correlation.get()
        return True


def configure(force: bool = False) -> None:
    """Install the handler and level. Idempotent.

    ``CONVERT_LOG_LEVEL`` (default ``INFO``) and ``CONVERT_LOG_FORMAT``
    (``text`` | ``json``, default ``text``) are the only knobs. Both are read
    from the environment, never hardcoded per deployment.
    """
    global _configured
    if _configured and not force:
        return

    level_name = (os.environ.get("CONVERT_LOG_LEVEL") or "INFO").strip().upper()
    level = getattr(logging, level_name, logging.INFO)
    want_json = (os.environ.get("CONVERT_LOG_FORMAT") or "text").strip().lower() == "json"

    handler = logging.StreamHandler(sys.stderr)
    handler.setFormatter(_JsonFormatter() if want_json else _KeyValueFormatter())
    handler.addFilter(_CorrelationFilter())

    root = logging.getLogger()
    # Replace only the handlers this module installed, so calling configure()
    # twice does not stack duplicate output and uvicorn's own handlers survive.
    for existing in list(root.handlers):
        if getattr(existing, "_pdfengine", False):
            root.removeHandler(existing)
    handler._pdfengine = True  # type: ignore[attr-defined]
    root.addHandler(handler)
    root.setLevel(level)
    _configured = True


def get_logger(name: str) -> logging.Logger:
    """A logger that is guaranteed to have somewhere to write."""
    configure()
    return logging.getLogger(name)


def event(
    logger: logging.Logger,
    level: int,
    name: str,
    *,
    exc_info: bool | BaseException | None = None,
    **fields: Any,
) -> None:
    """Emit one structured event.

    The message is a stable, greppable identifier (``ocr_page_failed``), and
    everything that varies goes in *fields* — so a dashboard can count events
    without parsing prose.
    """
    logger.log(level, name, extra={"fields": fields}, exc_info=exc_info)


def info(logger: logging.Logger, name: str, **fields: Any) -> None:
    event(logger, logging.INFO, name, **fields)


def warn(logger: logging.Logger, name: str, **fields: Any) -> None:
    event(logger, logging.WARNING, name, **fields)


def error(logger: logging.Logger, name: str, *, exc_info: Any = None, **fields: Any) -> None:
    event(logger, logging.ERROR, name, exc_info=exc_info, **fields)


def debug(logger: logging.Logger, name: str, **fields: Any) -> None:
    event(logger, logging.DEBUG, name, **fields)