Mini-proyecto: un run de Reservo trazado

Descripción

Siete lecciones construyeron, por separado, cada pieza: por qué print() no alcanza (02), el formato JSON estructurado (03), un trace_id determinista que abre y cierra un run (04), la instrumentación de cada paso del loop sin tocar el código del agente (05), los niveles de severidad y qué capturar en cada uno (06), y la lectura de un archivo de logs real hacia atrás (07). Este mini-proyecto las junta todas, sobre un lote de tareas más grande y más realista que cualquiera de los ejemplos anteriores: cuatro runs de Reservo —dos limpios, uno con un error de negocio, y uno que falla del todo—, todos corridos con traced_run, todos escritos al mismo RUN_LOG.jsonl, y un reporte final reconstruido completamente desde ese archivo, sin ninguna referencia a las variables de Python que produjeron los runs originales.

Esa última restricción es deliberada, y es el punto central de todo el mini-proyecto: el reporte no lee history, no lee ningún RunReport en memoria — lee, exclusivamente, las líneas de RUN_LOG.jsonl. Es la prueba definitiva de que el logging estructurado de este módulo captura todo lo que hace falta, sin depender de que el proceso original siga vivo.

Conexión con el módulo

Esta es la síntesis de las ocho lecciones. No hay ninguna pieza nueva de run_logger.py — el mini-proyecto reusa traced_run, load_events y read_trace exactamente como quedaron en las lecciones 06 y 07, y agrega una sola función nueva, summarize_by_trace, que agrupa los eventos de un archivo por trace_id para producir un resumen de lote — la pieza que faltaba para responder, de una vez, la pregunta que abrió todo el módulo: "¿qué pasó con este lote de runs?".

Ejemplo trabajado: cuatro runs, un archivo, un reporte

El lote: dos limpios, uno con error de negocio, uno que falla

import json
import logging

import reservo_agent as ra
import run_logger as rl

_file_handler = logging.FileHandler("RUN_LOG.jsonl", mode="w", encoding="utf-8")
_file_handler.setFormatter(logging.Formatter("%(message)s"))
rl.logger.handlers = [_file_handler]
rl.logger.setLevel(logging.INFO)

script_a = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "list_rooms", "input": {}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_02", "name": "get_quote",
         "input": {"room": "Focus", "tier": "premium", "hours": 3}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_03", "name": "get_quote",
         "input": {"room": "Focus", "tier": "pro", "hours": 3}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_04", "name": "book_room",
         "input": {"room": "Focus", "tier": "pro", "hours": 3, "member": "Ana"}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "Reservé Focus pro por 3 horas para Ana. Total $60.00. Confirmación #1."}]},
]
script_b = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "list_rooms", "input": {}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_02", "name": "get_quote",
         "input": {"room": "Boardroom", "tier": "pro", "hours": 1}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_03", "name": "book_room",
         "input": {"room": "Boardroom", "tier": "pro", "hours": 1, "member": "Sofia"}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "Reservé Boardroom pro por 1 hora para Sofía. Total $64.00. Confirmación #2."}]},
]
script_cancel_missing = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "cancel_booking", "input": {"id": 999}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "No encontré esa reserva."}]},
]
stuck_script = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": f"toolu_0{n}", "name": "list_rooms", "input": {}}]}
    for n in range(1, 4)
]

tasks = [
    ("Reserva Focus pro 3h para Ana", script_a, 10),
    ("Reserva Boardroom pro 1h para Sofia", script_b, 10),
    ("Cancela la reserva 999", script_cancel_missing, 10),
    ("Reserva algo ambiguo", stuck_script, 2),
]

for i, (question, script, max_iter) in enumerate(tasks, start=1):
    try:
        with rl.traced_run(question, i):
            final, history = ra.run_reservo_agent(question, script, max_iterations=max_iter)
        print(f"run {i} OK :", final["content"][0]["text"])
    except RuntimeError as exc:
        print(f"run {i} FALLÓ:", exc)

_file_handler.close()

Qué esperar:

run 1 OK : Reservé Focus pro por 3 horas para Ana. Total $60.00. Confirmación #1.
run 2 OK : Reservé Boardroom pro por 1 hora para Sofía. Total $64.00. Confirmación #2.
run 3 OK : No encontré esa reserva.
run 4 FALLÓ: max_iterations alcanzado (2)

Fíjate en el try/except alrededor de cada tarea: traced_run nunca oculta el RuntimeError del run 4 —lo relanza, exactamente como diseñó la lección 04—, así que el código que llama a traced_run sigue siendo responsable de decidir qué hacer con un run que falla. Aquí, simplemente se reporta y se sigue con la siguiente tarea del lote — un lote real no se detiene porque un run individual haya fallado.

El reporte, reconstruido 100% desde RUN_LOG.jsonl

Sin usar ninguna variable de las que produjo el bloque anterior —ni tasks, ni history, ni final—, lee el archivo desde cero y agrupa por trace_id:

def load_events(path):
    events = []
    with open(path, encoding="utf-8") as fh:
        for line in fh:
            events.append(json.loads(line))
    return events


def summarize_by_trace(events):
    """Agrupa los eventos por trace_id (preservando el orden de aparición)
    y arma un resumen de una línea por run: completo o no, cuántos pasos,
    cuántos tool_errors."""
    order = []
    by_trace = {}
    for e in events:
        tid = e["trace_id"]
        if tid not in by_trace:
            by_trace[tid] = []
            order.append(tid)
        by_trace[tid].append(e)

    summaries = []
    for tid in order:
        own = by_trace[tid]
        question = own[0]["question"]
        steps = sum(1 for e in own if e["event"] == "tool_use")
        tool_errors = sum(1 for e in own if e["event"] == "tool_result" and e["is_error"])
        last = own[-1]
        completed = last["event"] == "run_finished"
        summaries.append({
            "trace_id": tid, "question": question, "steps": steps,
            "tool_errors": tool_errors, "completed": completed,
        })
    return summaries


events = load_events("RUN_LOG.jsonl")
summaries = summarize_by_trace(events)

print("=== resumen por trace_id, reconstruido 100% desde RUN_LOG.jsonl ===")
for s in summaries:
    estado = "completado" if s["completed"] else "FALLIDO"
    print(f"{s['trace_id']}  {estado:10} steps={s['steps']} tool_errors={s['tool_errors']}  {s['question']!r}")

print()
print("=== agregado del lote ===")
print("runs totales        :", len(summaries))
print("runs completados     :", sum(1 for s in summaries if s["completed"]))
print("runs fallidos        :", sum(1 for s in summaries if not s["completed"]))
print("tool_errors totales  :", sum(s["tool_errors"] for s in summaries))

Qué esperar:

=== resumen por trace_id, reconstruido 100% desde RUN_LOG.jsonl ===
run-8487582448eb  completado steps=4 tool_errors=1  'Reserva Focus pro 3h para Ana'
run-c720132bf969  completado steps=3 tool_errors=0  'Reserva Boardroom pro 1h para Sofia'
run-8d26276b0d45  completado steps=1 tool_errors=1  'Cancela la reserva 999'
run-61abb643a67b  FALLIDO    steps=2 tool_errors=0  'Reserva algo ambiguo'

=== agregado del lote ===
runs totales        : 4
runs completados     : 3
runs fallidos        : 1
tool_errors totales  : 2

Lee esta salida con las cinco preguntas que la lección 01 del Módulo 1 dejó sin respuesta bien presentes: ¿cuántos pasos dio cada run? — 4, 3, 1, 2, todos ahí, exactos. ¿Qué herramientas llamó? — reconstruible, paso por paso, con read_trace de la lección 07 sobre cualquiera de estos cuatro trace_id. ¿Algo falló en el camino? — sí, dos veces: el tier inválido de Ana (tool_errors=1), y el cancel_booking sobre un id inexistente (tool_errors=1). ¿Se completó el run? — tres de cuatro sí; el cuarto, no, y el reporte lo sabe con certeza porque su último evento es run_failed, no run_finished. Y el run que falló —run-61abb643a67b— no aparece con steps=0 como le habría pasado a run_and_observe en el Módulo 1: aparece con steps=2, porque los dos list_rooms que sí se ejecutaron antes del RuntimeError quedaron registrados, y summarize_by_trace los cuenta igual que a cualquier otro paso.

Ninguna de estas respuestas dependió de que el proceso de Python que corrió los cuatro runs siguiera vivo. RUN_LOG.jsonl, un archivo de texto plano en tu disco, es toda la evidencia que hizo falta.

El límite que sigue abierto, a propósito, para los módulos que quedan

Vale la pena cerrar con precisión sobre lo que este módulo no resuelve — no por descuido, sino porque son, exactamente, los cinco módulos que quedan de esta guía:

• run-8487582448eb costó algo, y tardó algo — pero este módulo no lo calculó. El campo content de cada tool_result tiene el texto suficiente para estimarlo (con len(texto)//4 y el pricing fijo de claude-sonnet-5, como adelantó el Módulo 1), pero hacerlo de verdad, con desglose por tool call y agregación sobre lotes, es el Módulo 3 (costo) y el Módulo 4 (latencia).
• ¿Es aceptable que tool_errors=2 en este lote? Este módulo no tiene ningún criterio para decidirlo — solo mide y registra. Convertir esa pregunta en un PASS/FAIL determinista, contra un umbral fijo, es el Módulo 5.
• Si cancel_booking sigue fallando en los próximos cien runs, ¿debería el agente dejar de intentarlo? Este módulo registra cada fallo individual, pero no tiene memoria entre runs — cada traced_run es independiente. Un circuit breaker que sí recuerde fallos repetidos, a través de runs, es el Módulo 6.
• ¿Este comportamiento es el mismo que la versión anterior del agente, o cambió algo? Comparar dos versiones del sistema con el mismo criterio es el Módulo 7.

Cada uno de esos módulos parte, literalmente, de observability/run_logger.py tal como quedó al final de esta lección — el mismo traced_run, sin cambios, reusado como cimiento.

Errores comunes

1. Calcular el resumen del lote a partir de las variables de Python del bloque que corrió los runs, en vez de leer RUN_LOG.jsonl. Funcionaría igual de bien mientras el mismo proceso siga vivo — pero pierde exactamente la propiedad que este mini-proyecto existe para demostrar: que la información sobrevive al proceso que la generó. Un sistema real reinicia sus procesos constantemente; su archivo de logs, no.

2. Contar steps sumando tool_use y tool_result por separado. summarize_by_trace cuenta solo los eventos tool_use (e["event"] == "tool_use") — contar también los tool_result duplicaría el número de pasos, porque cada tool call genera exactamente un evento de cada tipo.

3. Olvidar que completed depende del último evento, no de la ausencia de run_failed. La implementación de esta lección usa last["event"] == "run_finished" — mirar el último evento del trace_id, no buscar si existe algún run_failed en cualquier posición. Para el formato de esta guía ambos criterios dan el mismo resultado (un run tiene, como mucho, un evento de cierre), pero el criterio del último evento es más robusto si el esquema de eventos creciera.

4. Promediar tool_errors por run en vez de sumar antes de dividir, si se quisiera calcular una tasa de fallo por herramienta del lote completo — el mismo error que ya advirtió el Módulo 1, lección 08: sumar tool_errors y sumar steps de todos los runs primero, y dividir después, da una tasa distinta (y más correcta) que promediar las tasas individuales de cada run.

5. Pensar que este mini-proyecto "ya es" el Módulo 3 o el Módulo 5. No mide costo ni latencia (Módulo 3/4), y no aplica ningún criterio de PASS/FAIL (Módulo 5) — solo observa y registra, con precisión completa. Esa es, deliberadamente, toda la responsabilidad de este módulo.

Ejercicios

Ejercicio 1: Agrega un quinto run limpio y recalcula el agregado (Fácil)

Con mode="a", agrega un quinto run —una cotización simple, sin ningún error— al mismo RUN_LOG.jsonl. Vuelve a cargar el archivo completo y recalcula el resumen agregado del lote (runs totales, completados, fallidos, tool_errors totales).

fh = logging.FileHandler("RUN_LOG.jsonl", mode="a", encoding="utf-8")
fh.setFormatter(logging.Formatter("%(message)s"))
rl.logger.handlers = [fh]
rl.logger.setLevel(logging.INFO)

script_e = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "get_quote",
         "input": {"room": "Studio", "tier": "pro", "hours": 2}}]},
    {"stop_reason": "end_turn", "content": [{"type": "text", "text": "Studio pro 2h cuesta $64.00."}]},
]
with rl.traced_run("¿Cuánto cuesta Studio pro 2h?", 5):
    ra.run_reservo_agent("¿Cuánto cuesta Studio pro 2h?", script_e)
fh.close()

events = load_events("RUN_LOG.jsonl")
summaries = summarize_by_trace(events)
print("runs totales      :", len(summaries))
print("runs completados   :", sum(1 for s in summaries if s["completed"]))
print("runs fallidos       :", sum(1 for s in summaries if not s["completed"]))
print("tool_errors totales :", sum(s["tool_errors"] for s in summaries))

runs totales      : 5
runs completados   : 4
runs fallidos       : 1
tool_errors totales : 2

Ejercicio 2: Encuentra el run con más pasos del lote (Medio)

Usando los summaries del Ejercicio 1 (cinco runs), escribe código que encuentre el trace_id con el mayor número de steps, sin asumir de antemano cuál es.

busiest = max(summaries, key=lambda s: s["steps"])
print(f"run con más pasos: {busiest['trace_id']} ({busiest['steps']} pasos) -- {busiest['question']!r}")

run con más pasos: run-8487582448eb (4 pasos) -- 'Reserva Focus pro 3h para Ana'

Ejercicio 3: Verifica la integridad del archivo — ningún tool_use sin su tool_result (Difícil)

Escribe una función find_orphan_tool_use(events) que, para cada trace_id, confirme que cada evento tool_use tenga un evento tool_result con el mismo step. Aplícala sobre el RUN_LOG.jsonl real de este mini-proyecto —debería no encontrar ninguno, porque traced_dispatch siempre loguea ambos eventos de forma consecutiva—. Después, aplícala sobre este fragmento hipotético, escrito a mano para poner a prueba tu función: representa un proceso que murió (por ejemplo, un kill -9) justo después de loguear el tool_use del paso 2, sin llegar a loguear su tool_result.

def find_orphan_tool_use(events):
    """Para cada trace_id, confirma que cada tool_use tenga su tool_result
    con el mismo step. Si no lo tiene, el run murió a la mitad de un paso
    -- el proceso terminó ENTRE el log del tool_use y el log del
    tool_result (por ejemplo, un kill -9)."""
    by_trace = {}
    for e in events:
        by_trace.setdefault(e["trace_id"], []).append(e)
    orphans = []
    for trace_id, own in by_trace.items():
        uses = {e["step"] for e in own if e["event"] == "tool_use"}
        results = {e["step"] for e in own if e["event"] == "tool_result"}
        missing = uses - results
        if missing:
            orphans.append((trace_id, sorted(missing)))
    return orphans

real_events = load_events("RUN_LOG.jsonl")
print("log real (completo):", find_orphan_tool_use(real_events))

# Fragmento hipotético, escrito a mano: un proceso que murió justo después
# de loguear el tool_use del paso 2, antes de que dispatch_robust
# devolviera el resultado -- nunca llegó a loguear el tool_result de ese
# paso.
synthetic_crash = [
    {"trace_id": "run-hipotetico", "event": "run_started", "step": 0},
    {"trace_id": "run-hipotetico", "event": "tool_use", "step": 1},
    {"trace_id": "run-hipotetico", "event": "tool_result", "step": 1},
    {"trace_id": "run-hipotetico", "event": "tool_use", "step": 2},
    # -- el proceso murió aquí; nunca se escribió el tool_result del paso 2 --
]
print("fragmento hipotético (proceso muerto a la mitad):", find_orphan_tool_use(synthetic_crash))

log real (completo): []
fragmento hipotético (proceso muerto a la mitad): [('run-hipotetico', [2])]

Resumen y siguiente paso

• Cerramos el módulo con un lote de cuatro runs de Reservo —dos limpios, uno con un error de negocio corregido a medias, uno que falla del todo— todos corridos con traced_run y escritos al mismo RUN_LOG.jsonl.
• Construimos summarize_by_trace, la pieza final: agrupa eventos por trace_id y produce un resumen de lote —completado/fallido, pasos, tool_errors— reconstruido exclusivamente desde el archivo de logs, sin depender de ninguna variable del proceso que generó los runs.
• Confirmamos, con evidencia real y citada, que las cinco preguntas que el Módulo 1 dejó sin respuesta —pasos, herramientas, fallos, y ahora también "¿se completó?"— tienen, todas, una respuesta exacta, incluso para el run que terminó en RuntimeError.
• Nombramos, con precisión, lo que este módulo deliberadamente no resuelve —costo, latencia, un criterio de PASS/FAIL, memoria entre runs, comparación de versiones— y qué módulo de esta guía resuelve cada uno.

Con esto se cierra el Módulo 2. Tienes observability/run_logger.py completo —el formatter JSON, el trace_id determinista, traced_run con sus tres niveles de severidad, y las funciones de lectura hacia atrás—, y la evidencia ejecutada de que resuelve, de raíz, el límite que el Módulo 1 dejó abierto.

Siguiente módulo: Módulo 3 — Medir costo y tokens por run. Con cada paso del loop ya registrado y disponible en RUN_LOG.jsonl, ese módulo retoma la convención honesta de estimación de tokens (len(texto)//4) y el pricing fijo de claude-sonnet-5 para calcular, de verdad, cuánto costó cada uno de los runs que este módulo ya sabe observar.

Recursos adicionales

1. Python — logging — El módulo completo que este mini-proyecto termina de ejercitar, desde el nivel más básico (lección 02) hasta la persistencia a archivo (esta lección).
2. Python — json — json.dumps/json.loads, el par de funciones detrás de cada línea de RUN_LOG.jsonl y de cada lectura hacia atrás de este módulo.
3. Python — funciones max/min con key — El patrón usado en el Ejercicio 2 para encontrar el elemento con el valor más alto de una lista sin ordenarla completa.
4. Anthropic — Building effective agents — Sobre por qué la observabilidad completa de un sistema agentic es la base sobre la que se construye cualquier otra disciplina de operación — el argumento completo de este módulo, cerrado.
5. Python 3.14 — What's New — La versión con la que se ejecutó cada línea de código de este módulo, incluida la evidencia real del lote final.