Lección 45 — Logs estructurados

Stack: Django + logging JSON · Proyecto: TicketFlow Estado: Publicada — apertura del módulo de observabilidad Prerrequisito: Lección 44 — Infraestructura como código (Terraform)

Objetivos

1. Reemplazar los logs de texto por logs estructurados (JSON) con niveles, contexto y el trace_id que sigue una petición de punta a punta.
2. Configurar el logging de Django/DRF con contexto por request (middleware) sin filtrar PII (23).
3. Decidir qué se registra y con qué nivel, usando el principio: el log es para diagnosticar, no para narrar.

1. Del texto al JSON: por qué la estructura gana

El log de texto (ERROR 2027-09-28... reserva fallida para usuario juan) es para ojos humanos en un terminal; a escala (10k requests/hora, grep desesperado del 47) es ruido no-consultable. El JSON con claves estables se filtra, agrupa y correlaciona: {"level": "error", "event": "reservation_failed", "trace_id": "7c9e...", "user_id": "u-841", "reason": "seat-unavailable"}. La regla del formato: cada línea es UN evento JSON válido (un log por línea: el colector del proveedor lo corta por línea); los claves estables y en inglés (event, level, trace_id) porque quien filtra no eres tú — es el índice del stack de logs.

{"ts": "2027-09-28T14:22:03.114Z", "level": "info", "logger": "reservations.service",
 "event": "reservation_confirmed", "trace_id": "7c9e6679-...", "user_id": "u-841",
 "ref": "RF-8A21", "duration_ms": 183, "env": "prod", "version": "a1b2c3d"}

Las claves del contrato: ts (ISO8601 UTC SIEMPRE — la TZ local del servidor es el clásico del 31), level, event (verbo-en-pasado del dominio, no el nombre de la función), trace_id (§2), y el contexto de negocio (ref, user_id, event_id). Y las del release: env y version (el commit del 41) en TODAS las líneas — el log de un deploy mixto (blue/green conviviendo, 41) se separa por versión sin adivinar.

2. El trace_id: la columna vertebral

El trace_id es un UUID generado al ENTRAR el request (en el edge/middleware) y propagado: en los logs de ESE request, en las tareas Celery que encola (el id viaja en los kwargs del task), en los eventos del outbox (25), en los problem+json de los errores (26: el cliente puede reportarlo) y en los headers de salida (X-Request-ID). La consulta del diagnóstico: "trace_id=7c9e... " devuelve TODA la vida del pedido del cliente: la petición, la saga, los emails, el webhook — el hilo que el 47 tira. El middleware del contexto:

# core/logging.py
import contextvars, uuid

trace_id_var = contextvars.ContextVar("trace_id", default=None)

class TraceIdMiddleware:
    def __init__(self, get_response): self.get_response = get_response
    def __call__(self, request):
        tid = request.headers.get("X-Request-ID") or str(uuid.uuid4())
        trace_id_var.set(tid)
        response = self.get_response(request)
        response["X-Request-ID"] = tid
        return response

class ContextFilter(logging.Filter):
    def filter(self, record):
        record.trace_id = trace_id_var.get() or "-"
        record.version = os.environ.get("APP_VERSION", "dev")
        return True

contextvars (no threading.local): correcto bajo async (16) y por-hilo — el detalle que evita que dos requests mezclen trace_ids bajo gunicorn con threads.

3. El logging de Django, configurado adulto

# settings.py
LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "filters": {"context": {"()": "core.logging.ContextFilter"}},
    "formatters": {"json": {"()": "pythonjsonlogger.jsonlogger.JsonFormatter",
                            "format": "%(asctime)s %(levelname)s %(name)s %(message)s"}},
    "handlers": {"stdout": {"class": "logging.StreamHandler",
                            "filters": ["context"], "formatter": "json", "stream": "ext://sys.stdout"}},
    "root": {"handlers": ["stdout"], "level": "INFO"},
    "loggers": {
        "reservations": {"level": "INFO"},
        "django.request": {"level": "WARNING"},   # los 4xx del request: WARNING, no spam de ERROR
        "django.db.backends": {"level": "WARNING"},  # jamás DEBUG en prod: las SQL llevan parámetros (PII, 23)
    },
}

Las decisiones del contrato: los logs van a STDOUT (el contenedor del 40 no escribe ficheros: el colector de la plataforma los recoge — el fichero local es el que rota mal y llena el disco del 47); django.request a WARNING (cada 404/401 como ERROR inunda el índice: la 26 ya decidió que el 401 es ruido); django.db.backends jamás en DEBUG en prod (la SQL con parámetros imprime el payload del usuario: PII al log, la 23). El nivel por logger es config (27) con default INFO — el DEBUG global es el botón de emergencia del incidente (47) con ventana corta.

4. Qué se registra (y qué no): el catálogo de eventos

El catálogo mínimo de TicketFlow con niveles: INFO (los eventos de dominio consumados: reservation_confirmed, payment_succeeded, saga_compensated, outbox_published — lo que el negocio haría en su libro mayor, el ledger del 08 como log); WARNING (lo anómalo-recoverable: reintento de gateway, dedup del 29 activado, lock skip del 31, rate limit del 23); ERROR (lo que requiere acción: saga UNKNOWN expirada, DLQ > 0, task_failed); CRITICAL (reservado: la pérdida de dinero confirmada). Y lo que NO va: los payloads de request/response completos (PII, 23 — el campo del body que el usuario escribió: JAMÁS), los tokens/headers de auth, la SQL en DEBUG. El pseudónimo del "log todo": el audit log del 56/23 es una TABLA append-only distinta (regulatorio, con quién/cuándo/qué) — no mezclar con el log de diagnóstico.

logger.info("reservation_confirmed", extra={"ref": r.public_ref, "user_id": r.user_id,
                                            "duration_ms": 183})   # el extra: las claves del contrato

El logger.info(msg, extra=...) con claves planas (el JsonFormatter las serializa): el hábito es extra SIEMPRE (nunca f-string con datos: f"reserva {ref}" produce logs no-filtrables por ref).

5. La correlación en async y el test del pipeline

Las tareas Celery (29) reciben el trace_id en los kwargs (enviar_email.delay(ref, trace_id=tid)) y lo re-setean al arrancar la tarea (trace_id_var.set(kwargs["trace_id"])): el email del cliente se sigue del endpoint al worker. El outbox (25) lleva el trace_id en el payload del evento: el consumidor lo restaura. El test del pipeline (la 34/35 lo integra):

def test_trace_id_sobrevive_a_la_cola(self):
    with captureOnCommitCallbacks(execute=True):
        reservar(...)                      # el middleware del test fijó un tid conocido
    logs = [r for r in self.caplog.records if r.trace_id == TID]
    assert any(r.event == "reservation_confirmed" for r in logs)

Y la retención del stack: 30 días caliente + frío 1 año (o el que el 56 exija): el "hace 3 semanas se cobró doble" se investiga con log disponible, no con el resumen de la memoria del on-call.

Autoevaluación

1. ¿Por qué el JSON gana al texto a escala y cuáles son las claves del contrato mínimo de cada línea?
2. ¿Dónde nace el trace_id, por dónde se propaga en TicketFlow (endpoint→cola→outbox) y qué permite la consulta por trace_id?
3. ¿Por qué contextvars y no threading.local? ¿Qué rompe la mezcla de trace_ids?
4. ¿Qué va a INFO/WARNING/ERROR en el catálogo de TicketFlow y qué JAMÁS entra al log (23)?
5. ¿Por qué los logs van a STDOUT y qué dos decisiones del LOGGING evitan tanto el spam como la fuga de PII?

Continúa con los ejercicios. Las solutions.md solo tras intentarlo.