|
| 1 | +"""Structured logging with a per-request correlation id. |
| 2 | +
|
| 3 | +One app logger tree (``paw.*``) writes to stderr; every record carries a |
| 4 | +``request_id`` bound by the HTTP middleware (see ``main``), so a line |
| 5 | +from deep in a controller can be traced back to the request that caused |
| 6 | +it. ``PAW_LOG_JSON=true`` switches to one JSON object per line for log |
| 7 | +shippers; the default is a readable text line for dev. |
| 8 | +""" |
| 9 | + |
| 10 | +from __future__ import annotations |
| 11 | + |
| 12 | +import json |
| 13 | +import logging |
| 14 | +import sys |
| 15 | +from contextvars import ContextVar, Token |
| 16 | + |
| 17 | +# Bound per request by the middleware; "-" outside a request (startup, |
| 18 | +# background threads that didn't inherit the context). |
| 19 | +_request_id: ContextVar[str] = ContextVar("request_id", default="-") |
| 20 | + |
| 21 | + |
| 22 | +def set_request_id(rid: str) -> Token[str]: |
| 23 | + return _request_id.set(rid) |
| 24 | + |
| 25 | + |
| 26 | +def reset_request_id(token: Token[str]) -> None: |
| 27 | + _request_id.reset(token) |
| 28 | + |
| 29 | + |
| 30 | +def current_request_id() -> str: |
| 31 | + return _request_id.get() |
| 32 | + |
| 33 | + |
| 34 | +class _RequestIdFilter(logging.Filter): |
| 35 | + def filter(self, record: logging.LogRecord) -> bool: |
| 36 | + record.request_id = _request_id.get() |
| 37 | + return True |
| 38 | + |
| 39 | + |
| 40 | +class _JsonFormatter(logging.Formatter): |
| 41 | + def format(self, record: logging.LogRecord) -> str: |
| 42 | + payload = { |
| 43 | + "ts": self.formatTime(record, "%Y-%m-%dT%H:%M:%S%z"), |
| 44 | + "level": record.levelname, |
| 45 | + "logger": record.name, |
| 46 | + "request_id": getattr(record, "request_id", "-"), |
| 47 | + "message": record.getMessage(), |
| 48 | + } |
| 49 | + if record.exc_info: |
| 50 | + payload["exc"] = self.formatException(record.exc_info) |
| 51 | + return json.dumps(payload, ensure_ascii=False) |
| 52 | + |
| 53 | + |
| 54 | +def configure_logging(level: str = "INFO", json_logs: bool = False) -> None: |
| 55 | + """(Re)configure the ``paw`` logger tree. Idempotent per call.""" |
| 56 | + logger = logging.getLogger("paw") |
| 57 | + logger.handlers.clear() |
| 58 | + handler = logging.StreamHandler(sys.stderr) |
| 59 | + handler.addFilter(_RequestIdFilter()) |
| 60 | + if json_logs: |
| 61 | + handler.setFormatter(_JsonFormatter()) |
| 62 | + else: |
| 63 | + handler.setFormatter( |
| 64 | + logging.Formatter( |
| 65 | + "%(asctime)s %(levelname)-5s %(name)s [%(request_id)s] %(message)s", |
| 66 | + datefmt="%H:%M:%S", |
| 67 | + ) |
| 68 | + ) |
| 69 | + logger.addHandler(handler) |
| 70 | + logger.setLevel(level.upper()) |
| 71 | + logger.propagate = False # don't double-log through the root logger |
| 72 | + |
| 73 | + |
| 74 | +def get_logger(name: str) -> logging.Logger: |
| 75 | + """A child logger under the configured ``paw`` tree.""" |
| 76 | + return logging.getLogger(f"paw.{name}") |
0 commit comments