Módulo 2: Logging estructurado y trazado de un run

Descripción

El Módulo 1 cerró con una advertencia concreta, no con una promesa vaga. En su última lección, run_and_observe —la primera envoltura de instrumentación de esta guía— midió cuatro señales completas sobre un lote de runs reales: pasos, tool calls, errores, costo, latencia. Funcionó bien, hasta que se le dio un guion que agota max_iterations. En ese caso, run_reservo_agent lanza un RuntimeError, la excepción se propaga antes de que run_and_observe pueda construir un solo RunReport, y todo lo que ese run hizo —cada tool que sí llegó a ejecutarse, cada resultado que sí llegó a producir— desaparece con él. Ni un print, ni un RunReport, ni un rastro. La lección 08 de ese módulo lo dijo con precisión: "Resolver esto de verdad —registrar cada paso según va pasando, no al final— es, con precisión, el problema que el Módulo 2 construye desde su primera lección."

Este módulo resuelve exactamente eso. No con un truco ni con una reescritura de reservo_agent.py —esta guía no toca esa lógica, en ningún módulo—, sino con dos ideas que, juntas, cambian por completo qué se puede saber de un run: logging estructurado (cada evento como una línea de JSON completa, parseable, con campos fijos) y un trace_id que correlaciona cada uno de esos eventos con el run exacto al que pertenecen, de punta a punta, incluso cuando ese run termina mal. Al final de la lección 05 —la mitad del módulo— vas a ver, ejecutado, el mismo guion que le ganó a run_and_observe en el Módulo 1: un RuntimeError real, y esta vez, un rastro completo de lo que pasó antes de que todo se cayera.

Regla dura de esta guía (heredada, sin cambios)

La regla dura del Módulo 1 sigue exactamente igual: la decisión del modelo no se ejecuta. Cuando una lección diga "el modelo (claude-sonnet-5, concepto) pidió get_quote", eso sigue siendo un guion de turnos escrito a mano. Lo que agrega este módulo es una capa de honestidad propia, porque ahora el tema es cómo se registra lo que pasa, y registrar mal es tan peligroso como no registrar:

El logging estructurado sí se ejecuta, de verdad, con logging de la librería estándar más un formatter JSON propio. Cada línea que vas a ver en un bloque "Qué esperar" de este módulo es la salida real de haber corrido ese código — nunca un ejemplo inventado a mano.
El trace_id es determinista, siempre. Nunca uuid4(), nunca ninguna otra fuente de aleatoriedad. La lección 04 construye uno con un hash de las entradas del run —la pregunta y un número de secuencia lógico—, precisamente para que el mismo run produzca, siempre, el mismo trace_id, en tu máquina y en la mía.
Nada de reloj real en los datos. Ni datetime.now(), ni time.time(). Cuando un evento necesita algo parecido a un timestamp para ordenarse, este módulo usa un contador de secuencia lógico (seq, un entero que crece de a uno por cada evento que se genera) — nunca la hora real de la pared. Es una simplificación deliberada, y cada lección que la usa lo dice explícitamente: en producción de verdad, cada línea de log lleva un timestamp real (%(asctime)s de logging, o un datetime.utcnow().isoformat() explícito); aquí se omite para que la salida de cada ejemplo sea reproducible, línea por línea, sin importar a qué hora del día lo corras.
El costo y la latencia siguen sin ser el tema de este módulo. Vas a ver ambos loguearse como campos dentro de algunos eventos —cuando corresponda—, pero su cálculo a fondo, su agregación sobre lotes, sus percentiles: eso es el Módulo 3 (costo) y el Módulo 4 (latencia). Aquí el trabajo es registrar, no medir.

Guárdate esta frase, porque la vas a usar en cada lección que sigue: un evento sin trace_id es ruido; un trace_id sin un evento en cada paso del loop es una promesa sin cumplir. Este módulo construye las dos piezas juntas, porque ninguna de las dos, por sí sola, resuelve el problema que el Módulo 1 dejó abierto.

Dónde estamos en el ecosistema

Agentes en producción — operar el agente de Reservo
├── Módulo 1: Por qué operar es distinto de construir
├── Módulo 2: Logging estructurado y trazado de un run  ← ESTÁS AQUÍ
│   → JSON estructurado, un trace_id determinista, cada paso
│     del loop registrado según ocurre, RUN_LOG.jsonl real
├── Módulo 3: Medir costo y tokens por run
├── Módulo 4: Medir latencia con honestidad
├── Módulo 5: Evals de regresión como gate de producción
├── Módulo 6: Fallos a escala — backoff, circuit breakers y rate limits
├── Módulo 7: Versionado y rollout seguro
└── Módulo 8: Proyecto — el agente de Reservo en producción

Este es el primero de los siete módulos que construyen, uno por uno, las cuatro disciplinas que el Módulo 1 nombró: observar → medir → gatear → endurecer+versionar. El diagrama de esa lección 01 fue explícito sobre el orden: no puedes medir con sentido lo que no puedes observar primero. Este módulo es la capa de observar — el cimiento sobre el que se paran los seis módulos que quedan. observability/run_logger.py, el artefacto que vas a construir lección a lección, se reusa sin cambios desde el Módulo 3 en adelante: cada vez que una lección futura diga "logueamos este evento", va a estar usando literalmente el mismo traced_run que termina de tomar forma en la lección 06 de este módulo.

La analogía central de este módulo: el número de guía de un paquete

Cuando envías un paquete por una empresa de mensajería, recibes un número de guía. Ese número no transporta el paquete —no hace nada físico—, pero hace algo igual de importante: te deja seguir ese paquete en particular, y solo ese, a través de todas las estaciones por las que pasa —el centro de distribución de origen, el camión, el aeropuerto, la aduana, el centro de distribución de destino, el repartidor final—, aunque la empresa esté moviendo, al mismo tiempo, miles de paquetes distintos por esas mismas estaciones. Sin ese número, cada estación sigue registrando algo —"llegó un paquete", "salió un paquete"—, pero esos registros, mezclados entre sí, no te dicen nada sobre tu paquete en particular. Con el número, filtras: le pides al sistema "muéstrame solo los eventos con esta guía", y lo que te devuelve es la historia completa de un envío, sin ningún otro envío mezclado.

Un trace_id es exactamente ese número, aplicado a un run del agente de Reservo en vez de a una caja. Cada paso del loop —cada tool_use, cada tool_result, el inicio y el final del run mismo— es una "estación" por la que ese run pasa, y cada una deja un registro. Si diez usuarios le piden algo a Reservo en el mismo minuto —diez runs, corriendo uno detrás de otro, o incluso entrelazados en un sistema real con varias solicitudes a la vez—, sus eventos van a terminar en el mismo lugar: el mismo archivo de logs, la misma salida de terminal. Sin un trace_id en cada línea, esos diez runs se mezclan en un solo torrente indistinguible. Con un trace_id determinista en cada línea, puedes pedirle al sistema —con un simple filtro, como vas a hacer en la lección 07— "muéstrame solo los eventos de este run", y reconstruir, de principio a fin, exactamente qué pasó, sin que ningún otro run se cuele en el medio.

La diferencia entre un número de guía y un trace_id de este módulo es una sola, y es la que ya adelantó la regla dura de arriba: una empresa de mensajería puede darse el lujo de generar números de guía al azar —nadie necesita reproducir el mismo número dos veces—. Esta guía no puede: cada ejemplo tiene que producir, siempre, la misma salida, para que puedas confirmarla en tu propia máquina byte por byte. Por eso el trace_id de este módulo nunca es aleatorio — es un hash determinista de las entradas del run, construido en la lección 04.

Lo que el Módulo 1 no pudo resolver, y este módulo sí

Vale la pena ser preciso sobre el límite exacto que se cierra aquí, porque no es un límite abstracto — lo viste ejecutado, con tus propios ojos, en la última lección del Módulo 1:

stuck_script = [...]  # tres tool_use de list_rooms, sin end_turn
try:
    final, report = run_and_observe("Reserva algo", stuck_script, max_iterations=2)
except RuntimeError as exc:
    print("RuntimeError capturado en run_and_observe:", exc)

RuntimeError capturado en run_and_observe: max_iterations alcanzado (2)

Ni un RunReport, ni un solo logging.info, ni ningún rastro del intento. La causa no es un error en run_and_observe — es una decisión de diseño que cualquier envoltura que solo mida "al final" hereda automáticamente: toda la lógica de conteo vive después de la llamada que puede fallar, así que si esa llamada falla antes de devolver nada, no hay nada que contar.

Este módulo cambia el punto en el que se registra: en vez de esperar a que run_reservo_agent termine (bien o mal) para después mirar hacia atrás, este módulo instrumenta el punto exacto por el que pasa cada tool call —antes de que exista la posibilidad de que el run entero se caiga— y deja un rastro en el instante en que cada evento ocurre. Cuando llegues a la lección 05, vas a correr el mismo stuck_script de arriba, con la misma trampa (max_iterations=2), y en vez de "ningún rastro del intento", vas a tener un archivo con las líneas exactas de los dos pasos que sí llegaron a ejecutarse, antes de que el tercero disparara el RuntimeError. Esa es, con precisión, la diferencia entre "medir al final" y "observar según ocurre" — y es el argumento completo de este módulo, resuelto con código real.

El caso que sigue acompañando la guía: Reservo, sin reconstruir nada

Las cuatro tools son las mismas de siempre — list_rooms(), get_quote(room, tier, hours), book_room(room, tier, hours, member), cancel_booking(id) — y las dos anclas de precio siguen intactas: Focus basic 3h = 7500 centavos, Focus pro 3h = 6000 centavos (descuento pro del 20%, * 80 // 100, aritmética entera). Este módulo no declara ni una tool nueva ni un caso de negocio nuevo — reutiliza, sin tocar una línea, reservo_tools.py, reservo_contracts.py, reservo_robust.py y reservo_agent.py, exactamente como quedaron en agent-fundamentals-and-tool-calling-guide M8.

Lo nuevo de este módulo es un artefacto que vive alrededor de esos archivos, nunca dentro de ellos: observability/run_logger.py. Se construye en capas, una por lección:

Lección 03 arma el formatter JSON y las dos primeras dataclasses de eventos (RunEvent, para el nivel de un run completo).
Lección 04 agrega make_trace_id (determinista) y open_run, un contextlib.contextmanager que abre y cierra un run con su trace_id.
Lección 05 es donde pasa lo interesante: agrega ToolCallEvent y una técnica de instrumentación —envolver reservo_robust.dispatch_robust desde afuera, sin editar su archivo— para que cada tool_use/tool_result quede registrado en el instante exacto en que ocurre.
Lección 06 completa los niveles de severidad (INFO, ERROR, DEBUG, y cuándo usar cada uno) y dos capas de detalle: una vista operacional liviana y una vista completa para depuración profunda.
Lecciones 07-08 persisten todo esto en un archivo real, RUN_LOG.jsonl, y lo leen de vuelta para reconstruir un run —o un lote completo de runs— a partir de sus logs.

Como en cada módulo de esta guía: identificadores y código en inglés; prosa y comentarios en español; dinero, cuando aparezca, en centavos int.

Prerequisitos

Conocimiento requerido:

✅ Haber completado el Módulo 1 de esta guía, en especial las lecciones 03 (lo que no se puede ver sin instrumentación) y 08 (el límite de run_and_observe). Este módulo asume que ya viste ese límite ejecutado, y lo resuelve directamente.
✅ Haber completado (o conocer bien) agent-fundamentals-and-tool-calling-guide M8: la firma de run_reservo_agent(question, model_script, max_iterations=10, summarize=None), el formato de history (turnos user/assistant, bloques tool_use/tool_result/text), y que dispatch_robust nunca lanza una excepción sin control — siempre devuelve un tool_result, con is_error: True cuando algo salió mal.
✅ Python: funciones, diccionarios, try/except/finally, comprensión básica de decoradores (una función que envuelve a otra y le agrega comportamiento). Este módulo usa contextlib.contextmanager, dataclasses y logging de la librería estándar — si no los conoces a fondo, no importa: cada uno se explica la primera vez que aparece.

NO requerido:

❌ No necesitas una API key ni conexión a internet: la decisión del modelo sigue siendo concepto, y todo el logging de este módulo corre 100% local, sobre archivos de tu propio disco.
❌ No necesitas conocer un stack de observabilidad de infraestructura (Datadog, LangSmith, Sentry, Prometheus). Este módulo construye, a mano, el mecanismo que esos productos envuelven — para que entiendas exactamente qué hacen antes de delegárselo a uno.
❌ No necesitas saber nada de SRE, SLI/SLO ni el ciclo de vida de un incidente: eso pertenece a sre-and-incident-response-guide, una guía vecina que opera infraestructura, no el agente. Este módulo logea una aplicación, no un sistema distribuido.

Entorno:

✅ Python 3.14.0 con su librería estándar (logging, json, dataclasses, contextlib, hashlib, itertools). Nada que instalar.
✅ Un editor de texto y una terminal. Vas a crear al menos un archivo real (RUN_LOG.jsonl) en tu disco desde la lección 07.

Roadmap del módulo

Lección 01 — Introducción al módulo (esta)

El límite exacto del Módulo 1 que este módulo resuelve, la analogía del número de guía, y el mapa de las ocho lecciones.

Lección 02 — `print` no es logging

Por qué la herramienta más obvia para "ver qué está pasando" es, precisamente, la que falla en cada una de las formas que van a importar: no tiene nivel, no tiene estructura, no se puede filtrar, y se mezcla con la salida real del programa.

Lección 03 — Logs estructurados como JSON

Un formatter propio sobre logging que convierte cada evento en una línea de JSON completa y parseable — el primer bloque de run_logger.py, probado con eventos simples antes de tocar el agente.

Lección 04 — El `trace_id`: correlacionando un run

Un identificador determinista —nunca uuid4()— que sigue a un run de punta a punta, y un contextlib.contextmanager (open_run) que garantiza un evento de cierre incluso cuando el run termina en excepción.

Lección 05 — Logueando cada paso del loop

La lección central del módulo: instrumentar dispatch_robust desde afuera —sin tocar su código— para que cada tool_use y tool_result quede registrado en el instante en que ocurre. Aquí se cierra, con código ejecutado, el límite del Módulo 1.

Lección 06 — Niveles de log y qué capturar

INFO para los pasos, ERROR para los fallos de tool, DEBUG para el detalle completo — y por qué mezclar los tres en un solo nivel es tan malo como no tener ninguno.

Lección 07 — Leyendo un trace hacia atrás

Persistir RUN_LOG.jsonl a disco de verdad, y reconstruir —a partir de sus líneas, y solo de ellas— exactamente qué le pasó a un run, sin haber estado mirando cuando ocurrió.

Lección 08 — Mini-proyecto: un run de Reservo trazado

Un lote de runs de Reservo —incluido uno que falla a propósito— corridos con la instrumentación completa del módulo, con RUN_LOG.jsonl real como entregable, y un reporte reconstruido 100% desde ese archivo.

Mapa de progresión

Lección 01 (esta)  → El límite del Módulo 1, la analogía del número de guía
Lección 02         → Por qué print() no alcanza
Lección 03         → JSON estructurado, una línea por evento
Lección 04         → trace_id determinista + abrir/cerrar un run
Lección 05         → Cada tool_use/tool_result, en el instante en que ocurre
Lección 06         → INFO/ERROR/DEBUG: qué capturar en cada nivel
Lección 07         → RUN_LOG.jsonl real, leído y reconstruido
Lección 08         → Mini-proyecto: un lote trazado, con un run que falla

Dificultad: ⭐⭐ ──────────────────▶ ⭐⭐⭐

Qué lograrás en este módulo

Al completar las 8 lecciones, podrás:

Explicar, con ejemplos ejecutados, por qué print() no es una herramienta de observabilidad — y qué le falta exactamente (nivel, estructura, filtrado, separación de la salida real).
Construir un formatter JSON propio sobre logging, con dataclasses para los eventos, de forma que cada línea de log sea un objeto JSON completo y parseable.
Generar un trace_id determinista —con un hash de las entradas del run, nunca uuid4()— y explicar por qué la alternativa obvia (un contador simple) no alcanza en un sistema con más de un proceso.
Instrumentar el loop de un agente ya construido, sin tocar su código, envolviendo la función de despacho desde afuera para capturar cada paso en el instante en que ocurre — incluidos los pasos que sí corrieron antes de que el run entero fallara.
Elegir el nivel de severidad correcto para cada tipo de evento (INFO, ERROR, DEBUG) y explicar qué se pierde cuando se elige mal.
Leer un archivo RUN_LOG.jsonl hacia atrás y reconstruir, únicamente a partir de sus líneas, qué le pasó a un run específico — completado, fallido, o en curso.

El antes y después

ANTES del módulo:
→ "print() ya me deja ver lo que pasa, para qué complicarme"
→ "si el run falla, no hay nada que se pueda hacer para salvar
  la información de los pasos que sí ocurrieron"
→ "un id de run es un id de run, cualquiera alcanza"
→ "logging es una librería para imprimir con más pasos"

DESPUÉS del módulo:
→ print() no tiene nivel, no tiene estructura, y se mezcla con
  la salida real -- cada una de esas tres cosas importa
→ instrumentar el PUNTO DE DESPACHO, no el final del run, es lo
  que permite capturar pasos incluso cuando el run entero falla
→ un trace_id determinista correlaciona miles de runs concurrentes
  sin que ninguno se mezcle con otro -- y es reproducible, no
  aleatorio, porque esta guía necesita que lo sea
→ logging da nivel, estructura, y separación de streams -- tres
  capacidades que print() nunca tuvo

Trampas a evitar al cursar este módulo

1. "Este módulo va a modificar `reservo_agent.py` para que loguee mejor"

No. Ni una línea de reservo_tools.py, reservo_contracts.py, reservo_robust.py ni reservo_agent.py cambia en este módulo, ni en ninguno de los que quedan. La lección 05 muestra, con precisión, cómo instrumentar el punto exacto de despacho de tools desde afuera, sin editar el archivo que lo define — esa es, de hecho, la habilidad central de todo el módulo.

2. "Un `trace_id` es solo un id cualquiera, no hace falta pensarlo"

La lección 04 muestra, ejecutado, por qué un contador simple (itertools.count(1)) falla en cuanto hay más de un proceso corriendo el sistema al mismo tiempo — dos procesos, cada uno con su propio contador, producen el mismo primer id. Un hash determinista de las entradas del run no tiene ese problema, y además es reproducible: el mismo run, corrido de nuevo, produce el mismo trace_id — útil para correlacionar un reintento con el intento original.

3. "DEBUG es solo INFO pero con más ruido"

No es una cuestión de cantidad, es una cuestión de audiencia. INFO es la señal que necesitas para saber, de un vistazo, que el sistema está funcionando — quién llamó a qué, y si salió bien. DEBUG es la señal que necesitas cuando ya sabes que algo salió mal y necesitas el detalle completo para entender por qué. La lección 06 construye ambas capas, deliberadamente separadas, para que puedas subir el nivel de detalle sin tener que cambiar una sola línea de código — solo la configuración del logger.

4. "Si `dispatch_robust` nunca lanza una excepción, no hace falta loguear sus errores"

Confundir "nunca lanza" con "nunca falla" es un error real, y ya lo advirtió agent-fundamentals M8. dispatch_robust devuelve is_error: True con total normalidad frente a un input inválido o un recurso inexistente — y ese tool_result con error es exactamente el tipo de evento que este módulo asegura que sí queda registrado, a nivel ERROR, para que un sistema real pueda alertar sobre él.

5. "El JSON estructurado es solo `print(json.dumps(...))` con pasos extra"

Es más cerca de la verdad de lo que parece —de hecho, json.dumps es literalmente lo que arma cada línea—, pero lo que agrega logging encima no es cosmético: nivel de severidad (para poder filtrar sin borrar código), un espacio de nombres por logger (para poder silenciar una parte del sistema sin silenciar todo), y handlers independientes del stdout del programa (para poder separar la salida real de la operación de logging). La lección 02 demuestra las tres, ejecutadas, antes de que la lección 03 construya el formato.

Cómo trabajar este módulo

Corre cada ejemplo tú mismo, y mira el archivo que produce. Desde la lección 07, varios ejemplos escriben RUN_LOG.jsonl de verdad en tu disco. Ábrelo con un editor de texto después de correr el código — ver una línea de JSON real, generada por tu propia máquina, vale más que leerla en esta página.
No confundas "determinista" con "arbitrario". Cuando una lección dice que el trace_id es determinista, no significa que el valor no importe — significa que depende, exclusivamente, de las entradas del run (la pregunta, un número de secuencia), nunca del reloj ni de una fuente aleatoria.
El mini-proyecto (lección 08) es la prueba final. Ahí vas a correr un lote de runs —incluido uno que falla a propósito— y vas a reconstruir, desde el archivo de logs y solo desde ahí, exactamente qué le pasó a cada uno. Si algo de las siete lecciones anteriores no quedó claro, ahí se va a notar.

Tiempo estimado:

Lección 01 (esta)  →  20 min lectura
Lección 02         →  20 min + correr el ejemplo
Lección 03         →  25 min + correr el ejemplo
Lección 04         →  25 min + correr el ejemplo
Lección 05         →  35 min + correr el ejemplo (la lección central)
Lección 06         →  25 min + correr el ejemplo
Lección 07         →  30 min + generar y leer tu propio RUN_LOG.jsonl
Lección 08         →  40 min + armar el mini-proyecto completo

Total: ~3.5 horas

Evidencia de éxito

Antes de avanzar al Módulo 3 (Medir costo y tokens por run), deberías poder:

✅ Explicar, con un ejemplo ejecutado, al menos tres formas concretas en las que print() no alcanza como herramienta de observabilidad.
✅ Construir una línea de log estructurada como JSON, con logging + dataclasses, y parsearla de vuelta con json.loads.
✅ Generar un trace_id determinista para un run, y explicar por qué no es uuid4().
✅ Instrumentar el despacho de tools de run_reservo_agent desde afuera, sin tocar su código, y confirmar —ejecutando— que un run que falla con RuntimeError sigue dejando un rastro de los pasos que sí corrieron.
✅ Elegir el nivel de severidad correcto (INFO/ERROR/DEBUG) para un evento nuevo, y justificar la elección.
✅ Leer un archivo RUN_LOG.jsonl real y reconstruir, solo a partir de sus líneas, la historia completa de un run específico por su trace_id.

Resumen

Este módulo resuelve, con código ejecutado, el límite exacto que el Módulo 1 dejó abierto en su última lección: un run que falla con RuntimeError deja de perder toda su información, porque este módulo registra cada paso según ocurre, no al final.
La pieza central es doble: logging estructurado (cada evento, una línea de JSON completa y parseable) y un trace_id determinista (nunca uuid4()) que correlaciona todos los eventos de un run, incluso en medio de miles de runs concurrentes — la analogía del número de guía de un paquete.
El artefacto que se construye, lección a lección, es observability/run_logger.py — reusado sin cambios desde el Módulo 3 en adelante.
La técnica central de la lección 05 —envolver dispatch_robust desde afuera, sin tocar su archivo— es la que hace posible capturar cada paso del loop sin reconstruir ni una línea del agente que agent-fundamentals ya entregó.

Siguiente lección: 02 — print no es logging. Antes de construir nada nuevo, confirmamos —con código ejecutado— exactamente qué le falta a la herramienta que probablemente ya usaste para "ver qué está pasando" en un programa de Python.

Recursos adicionales

Python — logging — La librería completa que este módulo desarrolla a fondo, lección a lección, empezando por sus fundamentos en la lección 02.
Python — dataclasses — RunEvent y ToolCallEvent, las estructuras que representan cada evento antes de convertirse en una línea de JSON.
Python — contextlib — contextmanager, la herramienta detrás de open_run (lección 04) y traced_run (lección 05), que garantiza un cierre correcto incluso frente a una excepción.
Anthropic — Building effective agents — Sobre por qué la observabilidad de un agente es una disciplina propia, no un lujo que se agrega al final.
Python 3.14 — What's New — La versión exacta con la que se ejecuta cada línea de código de este módulo.

← AnteriorMini-proyecto: envuelve un run y mira adentro Siguiente →`print` no es logging