Lección 45 — Logs estructurados

Ejercicio 1 — El JSON formatter

1. La línea de verificación:

{"asctime": "2027-09-28T14:22:03Z", "levelname": "info", "name": "reservations.service",
 "message": "reservation_confirmed", "trace_id": "7c9e6679-7425-40de-944b-e07fc1f90ae7",
 "version": "a1b2c3d", "ref": "RF-8A21", "user_id": "u-841", "duration_ms": 183}

jq. /tmp/app.log lo parsea sin error: la prueba del formato.

1. El cambio del hábito: logger.info(f"reserva {ref} confirmada") → logger.info("reservation_confirmed", extra={"ref": ref}). El grep vacío es la regla: los datos van en extra (filtrable) y el message es el verbo del evento (agrupable). La razón fina: el f-string destruye la cardinalidad — 500 reservas producen 500 "mensajes distintos" que el índice no agrupa; el evento con extra produce UN mensaje × 500 líneas con ref distinto: agrupable y filtrable.

1. La TZ: el log graba UTC SIEMPRE (el ts del formatter en UTC — el colector y los correlatos de otros servicios lo esperan); la hora de negocio (el evento empieza a las 20:00 hora local del comprador) es campo del dominio (la 31: la TZ del evento), no del log. La mezcla de TZs en el log es el clásico: dos sistemas con 2 h de diferencia correlacionando mal el incidente.

Ejercicio 2 — El trace_id

1. La evidencia de no-mezcla: dos threads concurrentes, cada request con su tid:

{"trace_id": "aaa-...", "event": "reservation_created", ...}
{"trace_id": "bbb-...", "event": "reservation_created", ...}

Con threading.local + async (16): el context del event loop comparte el local del thread → los tids se mezclan (el incidente fantasma: el log de la petición A contiene datos de la B). contextvars es la primitiva correcta para async y threads.

1. La cola: el kwargs del task llevan el tid; la tarea lo re-setea PRIMERO:

@shared_task
def enviar_email_confirmacion(ref, trace_id=None):
    trace_id_var.set(trace_id or "-")
    ...

El test eager: el log de la tarea lleva el tid del request que la encoló. En prod (worker separado), el tid viaja en el mensaje Celery: el hilo no se corta en la cola.

1. El hilo E2E completo: X-Request-ID en la respuesta → el mismo tid en el log del endpoint → en el payload del outbox → en el log del consumidor que envía el email fake. La consulta del 47 ("¿qué pasó con ESTA reserva?") es un grep por tid que devuelve la vida completa — 4 sistemas, un hilo.

Ejercicio 3 — El catálogo

1. La tabla (extracto de ~12):

1. Los re-clasificados: el 404/401 del request NO es ERROR (el escáner de Internet genera miles: la 26 ya lo decidió; django.request a WARNING); el gateway_retry es WARNING (recoverable, la métrica del 46 lo cuenta); el login_failed WARNING (señal de fuerza bruta) pero login_success INFO en audit. El ratio sano en la suite: <5% de líneas en WARNING+ERROR — si el ruido se come la señal, el nivel está mal puesto y NADIE leerá el ERROR verdadero.

1. Los hallazgos de PII: logger.info("reserva recibida", extra={"body": request.data}) (el body lleva el email/teléfono del comprador: JAMÁS; va user_id y ref) y django.db.backends en DEBUG (la SQL con parámetros: el payload del usuario al índice; en WARNING). El fix con el principio: el log lleva IDENTIFICADORES (los datos viven en la BD con su acceso controlado), nunca CONTENIDO.

Ejercicio 4 — La consulta del diagnóstico

1. La historia de RF-8A21:

jq 'select(.ref=="RF-8A21" or .trace_id==(jq 'select(.ref=="RF-8A21")' app.log | jq -r '.[0].trace_id'))' app.log
# → reservation_created (tid 7c9e...) → payment_pending → gateway_retry (WARNING ×2)
#   → payment_succeeded → saga CONFIRMED → email_sent: la historia completa en 1 comando

1. La política de acceso al log: la consulta por usuario ES una consulta de datos personales: la política (23/56) — solo el on-call con ticket de incidente (el log guarda las consultas si el stack lo permite), resultados anonimizados en el postmortem, y el acceso administrativo al índice con audit propio. El log que cualquiera consulta por cualquier usuario es un dump de PII con interfaz de búsqueda.

1. La retención con número: ~500 logs/reserva (el curso) × 50k reservas/mes × ~400 B = ~10 GB/mes caliente (30 días: 10 GB) + frío comprimido (~2 GB/mes): el costo es ~2-5 €/mes: barato; la decisión es del 56 (¿el regulador pide 1 año?) y del 23 (¿la PII del log viva 1 año? — los identificadores sí, el contenido jamás entra).

Ejercicio 5 — Audit vs log

1. La doble vida decidida: SÍ a ambos con propósitos distintos — el audit log (tabla) responde "quién hizo qué" con integridad (append-only, sin UPDATE/DELETE, la 23) para el auditor/regulador; el log responde "qué pasó en el sistema" con contexto técnico (tid, duración). El login_success: fila audit (el auditor lo exige) + log INFO (el diagnóstico lo usa). Lo que solo vive en audit: la descarga de export (el acceso a datos personales: el RGPD lo pide demostrable).

1. Las consultas: el auditor: SELECT * FROM audit_log WHERE action='role_changed' AND ts BETWEEN... (la consulta del 56: quién escaló a staff y cuándo); el diagnóstico: jq 'select(.event=="role_changed")' con tid y contexto. Cada uno sirve a su cliente: el regulador no lee JSON de logs, el on-call no quiere SQL del audit.

1. El top de errores que la 46 alertará:

jq -r 'select(.levelname=="error") | .message' app.log | sort | uniq -c | sort -rn | head 5
#   412 saga_unknown_expirada      ← el candidato a alerta
#    87 dlq_push
#    12 gateway_hard_fail

La consulta de esta lección es la semilla de la alerta de la siguiente: el ERROR agrupado por evento con umbral — el paso natural del log a la métrica.

Resumen del profesor

• JSON por línea con contrato fijo (ts UTC, level, event, trace_id, version); los datos en extra (agrupables), jamás f-string (cardinalidad destruida).
• El trace_id nace en el edge y viaja por cola y outbox con contextvars; la consulta por tid es el hilo del 47.
• INFO = hechos de negocio, WARNING = anómalo-recoverable, ERROR = acción requerida; identificadores sí, contenido/PII jamás; el audit log es otra cosa (append-only, para el regulador).