La lección anterior dejó a Jordi Sala con una alerta en la mano: PedidosBurnRateRapido, el 8 % de los pedidos falla. Las métricas le dicen cuánto y desde cuándo; no le dicen qué pedidos, ni en qué servicio, ni por qué. En el monolito de Kilómetro Cero la respuesta estaba a un grep de distancia en un único fichero de log. Hoy un pedido atraviesa Kong, tres réplicas de pedidos, dos de inventario, pagos, un tópico de Kafka y analitica, cada uno escribiendo en su propio contenedor; el log del pedido P-2026-000125 está repartido en siete sitios y en ninguno se llama igual. Esta lección construye los otros dos pilares de la observabilidad: logs estructurados y centralizados, para que un identificador reúna todo lo que pasó con una petición, y trazas distribuidas, para ver el recorrido y el tiempo de esa petición por todos los servicios. Al final, las tres señales quedan unidas en Grafana: de la métrica que alerta, a la traza que localiza, al log que explica.

1. Por qué tail -f ya no vale
2. Logs estructurados: campos estándar, niveles y qué no loguear
3. Pipeline de recogida: agente, almacén y consulta
4. servicios/comun/logs.py: JSON con trace_id inyectado
5. Trazabilidad distribuida: trazas, spans y contexto
6. Instrumentación con OpenTelemetry: servicios/comun/trazas.py
7. Collector, backends y muestreo
8. Una traza de "crear pedido" comentada
9. Unir las tres señales
10. Errores comunes y consejos
11. Ejercicios y soluciones
12. Conclusión

En una máquina, un log es un fichero y un incidente se investiga con tail -f, grep y less. En un sistema distribuido eso deja de funcionar por razones que no son de comodidad, sino estructurales:

• La información de una petición está repartida. Crear el pedido P-2026-000125 genera líneas en Kong, pedidos, inventario, pagos y analitica. Para reconstruir la historia hay que abrir cinco terminales y adivinar qué línea de cada una corresponde a ese pedido.
• Los relojes no coinciden. Como se vio en 01-05, ordenar por timestamp líneas de máquinas distintas puede invertir causa y efecto. Hace falta un identificador de correlación, no solo la hora.
• Los contenedores son efímeros. Cuando Kubernetes (07-05) reemplaza un pod de pedidos, su log desaparece con él. Si el fallo ocurrió justo antes de morir, se ha perdido la evidencia.
• El formato libre no se consulta. Pedido 125 rechazado por stock (tomate-rosa) es legible para una persona; para preguntar "cuántos rechazos por stock de tomate-rosa en Lleida en la última hora" hay que parsear con expresiones regulares frágiles.
• Volumen. 140 repartidores enviando una posición cada 5 s, 100 peticiones/s en pedidos: son millones de líneas al día. Nadie las lee; hay que poder filtrarlas.

La solución tiene dos partes: que cada servicio escriba logs estructurados con campos comunes, y que un pipeline los recoja de todos los nodos en un almacén central consultable.

Un log estructurado es un registro con campos con nombre, normalmente una línea JSON por evento:

Los campos que todos los servicios de km0/ incluyen siempre:

Los campos específicos (pedido_id, producto, replica) se añaden como claves adicionales, no dentro del mensaje. Y sí: aquí pedido_id es bienvenido. Lo que en las métricas era un problema de cardinalidad (07-01) en los logs es exactamente lo que se busca, porque un log se indexa por texto o por unas pocas etiquetas, no crea una serie por valor.

Los logs viajan por la red, se almacenan meses y los lee mucha gente. Todo lo que el Módulo 6 protegió con cifrado y control de acceso puede acabar en claro en un log si no se vigila:

• Secretos: tokens JWT (ni siquiera "para depurar"), contraseñas, credenciales de Vault, claves de API de la pasarela de pagos, cabeceras Authorization completas. Una traza HTTP en debug que vuelque cabeceras es una fuga.
• Datos personales en claro: nombre, email, teléfono y dirección de Ana. Se registra usuario: "u:9f1c3a" (el seudónimo de 06-02) y pedido_id; quien necesite el teléfono lo obtiene de la base de datos con su permiso y su auditoría.
• Datos de tarjeta: nunca, en ninguna forma (06-02).
• Cuerpos completos de peticiones: además de datos personales, son enormes. Se loguean los campos relevantes escogidos uno a uno.

Los logs de auditoría de 06-05 (quién hizo qué, hash encadenado, object lock en MinIO) son un canal distinto con garantías distintas: inmutabilidad y retención larga. Los logs operativos de esta lección son para diagnosticar, se retienen semanas y se pueden borrar; no se deben mezclar.

Cada servicio escribe JSON en stdout (no en ficheros propios: el contenedor no debe saber dónde acaban sus logs). Un agente por nodo lee la salida de todos los contenedores del nodo, añade etiquetas (servicio, instancia, nodo) y envía al almacén central. La consulta se hace desde una interfaz que entiende el formato.

Loki frente a Elasticsearch, que es la decisión de arquitectura real:

Kilómetro Cero elige Loki porque su patrón de consulta es casi siempre "servicio + rango + trace_id", el almacenamiento va a MinIO y ya usa Grafana y Prometheus. La cardinalidad vuelve a importar, esta vez en las etiquetas de Loki: servicio, instancia y nivel son etiquetas; trace_id, pedido_id y usuario no lo son (crearían un stream por valor), se buscan dentro del contenido con | json | trace_id="...".

Los logs crecen sin límite si nadie decide lo contrario. Una política típica: debug no se envía en producción; info se conserva 14 días; warning/error 90 días; los logs de Kong (una línea por petición) 30 días; los de auditoría son otro sistema con años de retención. En Loki la retención se configura por stream y los chunks antiguos se borran del bucket. Reducir el volumen en origen (no loguear cada posición de reparto, sino un resumen por minuto y los rechazos) suele ser la medida más eficaz.

Configuración mínima de Promtail y Loki en docker-compose.yml:

Con structlog, cada servicio configura una vez el logger y después usa log.info("evento", clave=valor). Un processor consulta el contexto de OpenTelemetry (sección 6) y añade trace_id y span_id si hay un span activo:

Cómo se usa en pedidos, con el middleware que captura el X-Request-Id que Kong propaga:

Detalles que conviene notar:

• structlog no formatea cadenas: log.warning("reserva_stock_rechazada", producto=...) produce claves separadas. Escribir log.warning(f"Rechazado {producto}") funciona, pero pierde la estructura. La disciplina es "nombre de evento estable + campos".
• El processor censurar es una red de seguridad, no la política: la política es no pasar esos datos. Pero cuesta poco y evita que un log.debug("peticion", headers=dict(request.headers)) de un martes por la noche acabe volcando tokens.
• El trace_id se lee del span activo de OpenTelemetry. Sin trazas configuradas, el contexto es inválido y simplemente no aparece; con ellas, cada línea de log de cualquier servicio que participe en la misma petición lleva el mismo trace_id, aunque los servicios no hayan hecho nada explícito para pasarlo.

Consultas LogQL en Grafana:

La segunda consulta muestra un uso valioso: métricas a partir de logs para preguntas que no merecen una métrica propia (07-01, ejercicio 1) pero que sí se quieren graficar de vez en cuando.

Los logs con trace_id responden "qué pasó"; las trazas responden "por dónde pasó y cuánto tardó cada paso". El modelo, heredado de Dapper (Google) y estandarizado por OpenTelemetry:

• Una traza es el árbol completo de trabajo causado por una petición externa. Se identifica por un trace_id de 128 bits.
• Un span es una unidad de trabajo con nombre, inicio, fin, atributos (pedido_id, rpc.method, db.statement), estado (OK/ERROR) y eventos. Tiene span_id y un parent_span_id, salvo el raíz.
• El contexto de propagación es lo que viaja de un servicio a otro para que el span del receptor cuelgue del emisor. El estándar es W3C Trace Context: una cabecera traceparent:

(Y una opcional tracestate para datos de proveedores.) En HTTP y gRPC es una cabecera; en Kafka, una cabecera del mensaje; en la saga, se guarda junto al estado en la tabla sagas para que la compensación horas después siga colgando de la traza original.

OpenTelemetry (OTel) aporta tres cosas: un SDK que crea spans y gestiona el contexto, instrumentaciones automáticas para librerías conocidas (gRPC, FastAPI, psycopg, redis, requests, kafka-python/confluent-kafka), y un protocolo de exportación (OTLP) hacia un Collector o un backend. Los servicios de km0/ comparten la configuración:

Cómo lo usa pedidos al publicar el evento tras la saga, y analitica al consumirlo:

Dos aclaraciones:

• gRPC, HTTP y PostgreSQL no requieren código: los instrumentors interceptan las llamadas, crean spans y meten/leen traceparent en los metadatos. En inventario, AuthInterceptor y el MetricasInterceptor de 07-01 conviven con el interceptor de OTel; el orden no afecta al contexto.
• Kafka sí requiere propagación manual (o el instrumentor de confluent-kafka, que hace lo mismo por debajo): el mensaje es un dato inerte que se consume más tarde, en otro proceso; nadie lo "llama". Lo mismo ocurre con la saga: saga_pedido.py guarda traceparent en la fila de la tabla sagas, y cuando el relay del outbox o una compensación retoman el trabajo, reconstruyen el contexto con propagate.extract sobre ese valor. Sin esto, la compensación de P-2026-000125 aparecería como una traza huérfana sin relación con el pedido.

Los servicios no envían las trazas al backend directamente, sino al OpenTelemetry Collector: un proceso intermedio que recibe OTLP, procesa (añade atributos, filtra, agrupa, muestrea) y exporta a uno o varios destinos. Ventajas: los servicios solo conocen un endpoint; cambiar de Jaeger a Tempo es cambiar el Collector; el muestreo de cola se hace ahí.

Kilómetro Cero usa Tempo, con los bloques en el bucket km0-trazas de MinIO, por coherencia con Loki y Grafana.

Guardar todas las trazas de 100 peticiones/s con 8-12 spans cada una es caro y casi inútil: la mayoría son idénticas y correctas. Dos estrategias:

Lo habitual, y lo que hace km0/, es combinarlos: un ParentBased en el SDK para que la decisión sea coherente en toda la traza, un ratio alto en origen (o 100 % en servicios de bajo tráfico) y tail sampling en el Collector para quedarse con lo interesante.

Así aparece en Grafana (Tempo) la traza 4bf92f35... del pedido P-2026-000125 de Ana, que tardó 482 ms y acabó bien. La sangría indica la relación padre-hijo:

Lo que la traza cuenta y las métricas no podían:

• De los 482 ms, 318 son la pasarela de pagos externa. Nada en km0/ puede acelerarlos; sí se puede paralelizar la reserva y el cobro, o aceptar el pedido "pendiente de confirmar" (07-04).
• El UPDATE de inventario tardó 98 ms en una operación que normalmente tarda 2: hay contención de bloqueo sobre vino-crianza (la Semana de la Vendimia, muchos pedidos del mismo producto). La métrica p99 de ReservarStock lo mostraba subiendo; la traza dice en qué sentencia.
• El span de analitica pertenece a la misma traza aunque ocurra después de la respuesta: es el efecto de propagar traceparent en las cabeceras Kafka.
• Cada span lleva el trace_id, y por tanto un clic lleva a las líneas de log de los cinco servicios con ese identificador, en orden.

La observabilidad no son tres herramientas, sino un recorrido: la métrica dice que algo va mal, la traza dice dónde, el log dice por qué. Grafana permite que ese recorrido sean tres clics:

• Exemplars: Prometheus puede guardar, junto a cada bucket del histograma, el trace_id de una observación reciente. En prometheus_client se pasa exemplar={"trace_id": ...} a observe(); en el gráfico del p99, cada punto tiene un rombo que abre esa traza. Es el enlace métrica → traza.
• Enlace log ↔ traza: el datasource de Loki en Grafana se configura con una derived field que reconoce trace_id en el JSON y muestra un botón "ver traza en Tempo"; y Tempo, a la inversa, con "logs de esta traza" que lanza {servicio=~".+"} | json | trace_id="..." en Loki.
• Traza → métrica: Tempo puede generar métricas RED a partir de los spans (span metrics), útil para servicios sin instrumentar con Prometheus.

Un ejemplo de exemplar en metricas.py (07-01), ahora que existe el contexto de traza:

Con esto, el sábado a las 10:13 el recorrido de Jordi es: alerta PedidosBurnRateRapido → panel con la tasa de error → rombo de exemplar sobre el pico → traza de un pedido fallido con el span ReservarStock en rojo y rpc.grpc.status_code=UNAVAILABLE → "logs de esta traza" → {"evento": "circuito_abierto", "dependencia": "inventario"}... que es donde entra el resto del módulo.

• Logs de texto libre "porque se leen mejor". Se leen mejor uno a uno; no se consultan. Nombre de evento estable + campos; para leer en local, structlog tiene un renderizador de consola con colores.
• Promocionar trace_id o pedido_id a etiqueta de Loki. Cada valor crea un stream y Loki se degrada igual que Prometheus con cardinalidad alta. Etiquetas: servicio, instancia, nivel, entorno. Lo demás, en el JSON.
• Loguear cabeceras o cuerpos completos en debug y dejarlo activado. Es la fuga de tokens y datos personales más habitual. Un processor de censura como red, y debug apagado por defecto.
• Perder el contexto en los saltos asíncronos. Un ThreadPoolExecutor, un asyncio.create_task o un mensaje Kafka sin propagate.inject rompen la traza. Ante una traza que "termina de repente", buscar el salto sin propagación.
• Muestreo solo en cabecera. Descarta el 90 % de los errores. Tail sampling en el Collector para quedarse con errores y trazas lentas.
• Trazas sin atributos de negocio. Un span POST /pedidos sin km0.pedido_id obliga a buscar por tiempo. Añadir el identificador de dominio como atributo (en trazas y logs no hay problema de cardinalidad).
• Confundir logs operativos con auditoría. Retención, inmutabilidad y acceso son distintos (06-05). Ni la auditoría va a Loki con 14 días, ni los logs de depuración van al bucket con object lock.
• Enviar trazas directamente al backend desde cada servicio. Acopla todos los servicios al backend y hace imposible el tail sampling. Un Collector en medio.

Ejercicio 1. Marc reporta a soporte que su pedido de la Semana del Queso Artesano "dio error" y aporta el X-Request-Id que la web le mostró: 7a1b.... Marta abre Grafana. (a) Escribe la consulta LogQL que reúne todo lo que pasó con esa petición en todos los servicios. (b) La consulta devuelve líneas de Kong y pedidos con trace_id 9c4d..., pero ninguna de inventario; en cambio, hay líneas de inventario con un trace_id distinto en el mismo segundo. ¿Qué se ha roto y dónde lo buscarías? (c) Marta encuentra en la línea de pedidos el campo "usuario": "u:2b77e1". ¿Cómo confirma que es Marc sin que nadie más pueda hacerlo por su cuenta, y por qué el log no contiene su email?

Ejercicio 2. El equipo decide que reparto publique una línea de log por cada posición recibida (140 repartidores, una cada 5 s) con el nivel info, y que debug incluya el cuerpo del mensaje. (a) Calcula cuántas líneas al día genera solo reparto y estima el volumen si cada línea ocupa 350 bytes. (b) Propón una alternativa que conserve la capacidad de investigar "por qué el panel mostraba a furgoneta-3-017 en Girona cuando estaba en Lleida" sin ese volumen. (c) ¿Qué problema de privacidad añade el debug con el cuerpo, y con qué mecanismo de esta lección lo mitigarías como último recurso?

Ejercicio 3. La traza de la sección 8 muestra 318 ms en la pasarela de pagos y 98 ms de espera de bloqueo en inventario. Un compañero propone "poner TraceIdRatioBased(1.0) en todos los servicios para no perder ninguna traza como esta". (a) Calcula cuántos spans por segundo recibiría el Collector con 100 peticiones/s a pedidos y 12 spans por traza, más el tráfico de catalogo (400 peticiones/s, 4 spans). (b) Explica por qué la configuración de otel-collector.yaml de la sección 7 ya habría conservado esta traza aunque el ratio fuera 0,1, y qué habría pasado si el ratio 0,1 se hubiera configurado sin ParentBased. (c) Un span de la compensación de la saga, ejecutado dos horas después de que el pedido fallara, aparece como traza nueva y no dentro de la del pedido. ¿Qué falta y dónde?

Ejercicio 1.

(a) {servicio=~".+"} | json | request_id="7a1b...", con el rango de tiempo acotado al momento del pedido (Loki escanea el contenido, así que el rango importa). (b) Kong y pedidos comparten trace_id, luego la propagación HTTP funciona; inventario tiene otro trace_id en el mismo instante, luego inventario está creando trazas nuevas en lugar de continuar la de pedidos: el traceparent no llega en los metadatos gRPC o no se lee. Sospechosos por orden: GrpcInstrumentorClient no instrumentado en pedidos (el cliente no inyecta), un interceptor propio en inventario que reconstruye los metadatos y descarta traceparent (revisar AuthInterceptor/ServicioInterceptor de 06-04), o un stub gRPC creado antes de llamar a configurar_trazas. Se comprueba con un log.debug de los metadatos recibidos en inventario (censurando authorization) o mirando en Tempo si el span servidor de inventario es raíz. (c) La seudonimización de 06-02 es una función con clave (HMAC) sobre el identificador del usuario: Marta pide al servicio de identidades, con su rol de operador y su ticket de soporte (queda auditado, 06-05), que resuelva u:2b77e1; o calcula el seudónimo del sub de Marc y compara. El log no contiene el email porque es un dato personal que viaja a Loki, a MinIO y a la pantalla de cualquiera con acceso a Grafana: se registra el seudónimo, que no identifica sin la clave, y el pedido_id, que es lo que soporte necesita.

Ejercicio 2.

(a) 140 × (86 400 / 5) = 2 419 200 líneas al día; a 350 bytes, unos 847 MB diarios sin comprimir solo de posiciones, unos 25 GB al mes. (b) Loguear en info solo lo anómalo (posiciones rechazadas por validación, saltos imposibles entre dos posiciones, mensajes fuera de orden) y un resumen por repartidor y minuto (posiciones_recibidas, ultima_ts); para reconstruir la ruta de furgoneta-3-017, los datos ya están en reparto.posiciones con retención de horas y en el lago HDFS (04-02): investigar consultando esos datos, no el log. Además, una traza muestreada por repartidor cada N mensajes da el recorrido interno sin loguear cada uno. (c) El cuerpo contiene la posición exacta de un empleado con su identificador, un dato personal (06-05, ejercicio 3); si alguien activa debug en producción, se copia a Loki sin las garantías de acceso de reparto.posiciones. Como último recurso, el processor censurar con posicion/lat/lon en CLAVES_PROHIBIDAS (y que el cuerpo se loguee como campos, nunca como cadena opaca, para que el censor pueda actuar); pero la política correcta es no loguear el cuerpo.

Ejercicio 3.

(a) pedidos: 100 × 12 = 1 200 spans/s; catalogo: 400 × 4 = 1 600 spans/s; total unos 2 800 spans/s, 242 millones al día, que el Collector debe recibir y retener 10 s cada uno para decidir (unos 28 000 spans en memoria de forma permanente, factible), y de los que Tempo escribiría lo que las políticas dejen pasar. Con TraceIdRatioBased(1.0) el coste está en la red y en el Collector, no en el almacenamiento, siempre que haya tail sampling. (b) La traza dura 482 ms y la política lentas conserva todo lo que supere 500 ms... no la conservaría por duración; pero tampoco importa: si tuvo un span con error, la política errores la guarda; si no, cae en el 10 % probabilístico. Con el ratio 0,1 en cabecera, la decisión la tomó Kong (o pedidos) al crear la traza, y ParentBased hace que todos los servicios la respeten: o se muestrea entera o ninguno la genera. Sin ParentBased, cada servicio tiraría su propio dado: pedidos la conservaría y inventario no, y la traza quedaría con agujeros (el span ReservarStock servidor ausente, justo el de los 98 ms). (c) Falta guardar el traceparent del pedido en la fila de la tabla sagas cuando se crea la saga, y al ejecutar la compensación reconstruir el contexto con propagate.extract sobre ese valor y crear el span de compensación con context=ctx (o como link a la traza original si se prefiere una traza nueva enlazada). Está en saga_pedido.py, en el punto donde el relay o el planificador retoman una saga pendiente.

Con esta lección la observabilidad de Kilómetro Cero tiene sus tres señales. Los logs dejan de ser texto en ficheros de contenedores efímeros para ser eventos JSON con campos comunes (ts en UTC, nivel, servicio, instancia, trace_id, request_id, usuario seudonimizado, evento), sin secretos ni datos personales, recogidos por Promtail en cada nodo y almacenados en Loki con etiquetas de baja cardinalidad, consultables con LogQL por el X-Request-Id que Kong asigna o por el trace_id que OpenTelemetry inyecta. Las trazas dan el recorrido: spans anidados con traceparent W3C propagado por HTTP y gRPC sin código, y a mano por las cabeceras de Kafka y por la tabla sagas, enviados a un Collector que muestrea en cola para conservar errores y lentitud, y almacenados en Tempo. Y las tres se unen en Grafana con exemplars y enlaces log↔traza, de modo que una alerta se convierte en tres clics en una traza con el span culpable y las líneas de log que lo explican.

Ya sabemos que falla, dónde y por qué. El recorrido de Jordi terminaba en un log de pedidos que decía circuito_abierto hacia inventario, y en Tempo un span ReservarStock en rojo con UNAVAILABLE: inventario-1 no responde. La pregunta siguiente no es de observabilidad, sino de supervivencia: ¿cómo detecta la plataforma que un nodo ha caído y no simplemente está lento? ¿Quién decide que inv-vlc pase a ser primario, y cómo se evita que inv-bcn vuelva creyendo que sigue siéndolo? ¿Y si lo que se ha perdido no es un proceso sino los datos de km0_inventario de las últimas dos horas? La siguiente lección trata la gestión de fallos y la recuperación: detección, failover con cercado, backups y PITR, y qué hacer en los minutos en que todo lo anterior está pasando.