El run instrumentado

Descripción

Con la capa de operación calibrada en la Lección 2, esta lección pone en marcha la primera de las cuatro disciplinas sobre tráfico real: observar. traced_run (M2, Altura 1 del mapa de la lección anterior) envuelve dispatch_robust sin tocar una sola línea de su código, y produce, por cada paso del loop, un evento JSON completo — no al final del run, sino en el instante exacto en que cada tool call ocurre. Esta lección corre un lote de cuatro tareas reales de Reservo —dos que se completan bien, una con un error de negocio esperado, y una que se agota del todo—, todas escritas al mismo archivo, RUN_LOG.jsonl, y reconstruye un resumen del lote leyendo exclusivamente ese archivo, sin ninguna referencia a las variables de Python que produjeron los runs.

Esta es, con precisión, la misma demostración que M2 (Lección 8) ya ejecutó a fondo — este capstone la reusa sin cambiar una línea, porque es exactamente el punto de partida que las Lecciones 4, 5 y 6 de este módulo necesitan: un RUN_LOG.jsonl real, con trace_ids reales, sobre el cual construir costo, latencia y el gate de regresión.

Conexión con el módulo

Esta lección entrega el primer artefacto real del capstone: RUN_LOG.jsonl, escrito a disco por el mismo lote de cuatro tareas que acompaña esta lección. Las Lecciones 4, 5 y 6 de este módulo van a leer el history de estos mismos runs para calcular costo, latencia, y correr el gate — nunca van a re-ejecutar el lote desde cero.

Analogía: el escáner de cada estación, aplicado a una noche completa de servicio

M2 (Lección 5) construyó la analogía del escáner de cada estación de un centro de distribución: un paquete que pasa por una estación deja un registro en ese instante, no al final del viaje completo. Esta lección aplica esa misma idea a una noche completa de servicio en el restaurante de Reservo, no a un solo pedido: cuatro clientes distintos llegan, uno detrás del otro, cada uno con su propio pedido — dos se resuelven bien, uno pide cancelar algo que nunca existió, y uno hace una pregunta tan ambigua que la cocina nunca logra resolverla dentro del tiempo permitido. El escáner de cada estación no distingue entre estos cuatro casos mientras ocurren — registra cada uno, con el mismo detalle, sin importar si el cliente se va satisfecho o si su pedido se queda sin resolver. Al final de la noche, el libro de registro —RUN_LOG.jsonl— cuenta la historia completa de los cuatro, sin que nadie tenga que recordar de memoria qué pasó con cada uno.

Ejemplo trabajado: cuatro runs, un archivo, reconstruido desde cero

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

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)

Cuatro runs, con destinos genuinamente distintos: run 1 y run 2 se completan bien; run 3 "se completa" en el sentido de que el agente respondió con end_turn, pero el resultado de negocio es un cancelled: False (id: 999 nunca existió) — un caso negativo, tan válido como uno positivo; run 4 agota max_iterations y run_reservo_agent lanza RuntimeError, que traced_run deja pasar sin ocultarlo, exactamente como diseñó M2. El try/except alrededor de cada tarea es responsabilidad de quien llama a traced_run — un lote real no se detiene porque un run individual haya fallado.

El reporte, reconstruido 100% desde RUN_LOG.jsonl

Sin usar ninguna variable del 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")
print("eventos totales en RUN_LOG.jsonl:", len(events))
print()
for s in summarize_by_trace(events):
    status = "completado" if s["completed"] else "FALLÓ"
    print(f"{s['trace_id']}  {status:10}  {s['steps']} pasos  {s['tool_errors']} tool_errors  -- {s['question']}")

Qué esperar:

eventos totales en RUN_LOG.jsonl: 28

run-8487582448eb  completado  4 pasos  0 tool_errors  -- Reserva Focus pro 3h para Ana
run-c720132bf969  completado  3 pasos  0 tool_errors  -- Reserva Boardroom pro 1h para Sofia
run-8d26276b0d45  completado  1 pasos  0 tool_errors  -- Cancela la reserva 999
run-61abb643a67b  FALLÓ       2 pasos  0 tool_errors  -- Reserva algo ambiguo

make_trace_id es un hash de (question, sequence_number) — estos cuatro valores son deterministas: correr este bloque en tu propia máquina produce exactamente los mismos cuatro trace_id, siempre. El total de eventos —28— es la suma exacta de dos partes: run_started + run_finished/run_failed (dos por run, ocho en total) más un par tool_use/tool_result por cada tool call que sí se ejecutó. run 4 no falló en el primer intento — como confirma steps=2, el guion de stuck_script alcanza a completar dos iteraciones reales de list_rooms (cada una con su tool_use y su tool_result, sin ningún error) antes de que la tercera dispare RuntimeError por max_iterations=2 — el mismo comportamiento que M2 (Lección 5) ya mostró con un guion equivalente. Sumando los pasos que sí ocurrieron —4 + 3 + 1 + 2 = 10 tool calls reales, 20 eventos de paso— más los ocho eventos de apertura/cierre, el total es 20 + 8 = 28. Nada de este resumen leyó history, final, ni ninguna variable de Python que existiera antes de esta celda — cada campo salió, exclusivamente, de parsear RUN_LOG.jsonl línea por línea.

Por qué esta es la base de todo lo que sigue en el capstone

Vale la pena decir, con precisión, por qué esta lección —que no construye ninguna función nueva— es la más importante de preparar bien en todo el módulo. Las Lecciones 4, 5 y 6 necesitan, cada una, el mismo tipo de insumo: un history real, producido por run_reservo_agent, correlacionado por un trace_id determinista. cost_for_run (Lección 4) recorre el mismo history del run 1 para calcular cuánto costó reservar Focus pro 3h para Ana. total_run_latency_ms (también Lección 4) recorre ese mismo history para calcular cuánto tardó, modelado. El gate de regresión (Lección 5) corre sus propios guiones, con la misma disciplina de traced_run envolviendo cada caso. Sin esta lección, cada una de esas piezas tendría que reconstruir su propio lote de runs desde cero — con esta lección, todas comparten el mismo punto de partida, con el mismo trace_id sirviendo de hilo conductor entre "qué pasó" (M2), "cuánto costó" (M3) y "cuánto tardó" (M4).

Errores comunes

1. Correr este lote más de una vez sobre el mismo RUN_LOG.jsonl sin mode="w". El FileHandler de este ejemplo abre el archivo en modo "w" (sobrescribir), a propósito — si en cambio se abriera en "a" (append) y este bloque se corriera dos veces, RUN_LOG.jsonl tendría el doble de eventos, y summarize_by_trace reportaría el doble de runs, todos con trace_ids repetidos y confusos entre una corrida y la otra.

2. Olvidar _file_handler.close() al final del lote. Sin cerrar el handler, el buffer de escritura de Python puede no haberse volcado a disco todavía cuando load_events intenta leer el archivo — un error de timing que produce un archivo con menos líneas de las esperadas, no un error explícito.

3. Pensar que run 4 (el que falla) "no dejó ningún rastro". Sí lo dejó — dos eventos: run_started y run_failed, con el mensaje exacto de la excepción. Lo que no dejó fue ningún evento de paso (tool_use/tool_result), porque el guion de ese run nunca llegó a completar ningún tool call antes de agotar max_iterations=2. Confundir "sin eventos de paso" con "sin ningún rastro en absoluto" es perder exactamente la mejora que M2 construyó sobre el límite de M1.

4. Calcular tool_errors contando is_error sobre eventos tool_use en vez de tool_result. El campo is_error solo existe, con sentido, en los eventos tool_result — un tool_use es la petición, no la respuesta. summarize_by_trace filtra explícitamente e["event"] == "tool_result" antes de mirar is_error, por esta misma razón.

5. Asumir que el orden de los trace_id en RUN_LOG.jsonl es alfabético o numérico. Es, exclusivamente, el orden en que cada run se abrió — order.append(tid) en summarize_by_trace preserva ese orden de aparición, nunca lo reordena. Dos runs con hashes que, por coincidencia, ordenarían distinto alfabéticamente, siguen apareciendo en el resumen en el orden real en que ocurrieron.

Ejercicios

Ejercicio 1: Cuenta cuántos eventos tool_result tienen is_error: true en todo el lote (Fácil)

Usando events (ya cargado en el ejemplo trabajado), cuenta cuántos eventos de tipo tool_result tienen is_error: true en total, sumando los cuatro runs.

total_errors = sum(1 for e in events if e["event"] == "tool_result" and e["is_error"])
print("tool_results con is_error=true en todo el lote:", total_errors)

tool_results con is_error=true en todo el lote: 0

Ejercicio 2: Agrega un quinto run con un tier inválido y confirma que sí aparece en tool_errors (Medio)

Agrega un quinto elemento a tasks: la pregunta "¿Cuánto cuesta Focus premium 3h?", con un guion que primero intenta get_quote con tier="premium" (inválido) y después se auto-corrige a tier="pro". Vuelve a correr el lote completo (reabriendo RUN_LOG.jsonl en modo "w") y confirma que summarize_by_trace reporta tool_errors=1 para ese run.

script_e = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "get_quote",
         "input": {"room": "Focus", "tier": "premium", "hours": 3}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_02", "name": "get_quote",
         "input": {"room": "Focus", "tier": "pro", "hours": 3}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "Focus pro 3h cuesta $60.00."}]},
]
tasks_v2 = tasks + [("Cuanto cuesta Focus premium 3h", script_e, 10)]

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

for i, (question, script, max_iter) in enumerate(tasks_v2, start=1):
    try:
        with rl.traced_run(question, i):
            ra.run_reservo_agent(question, script, max_iterations=max_iter)
    except RuntimeError:
        pass
_fh2.close()

events_v2 = load_events("RUN_LOG.jsonl")
for s in summarize_by_trace(events_v2):
    if s["question"] == "Cuanto cuesta Focus premium 3h":
        print(s)

{'trace_id': 'run-b2eff980df66', 'question': 'Cuanto cuesta Focus premium 3h', 'steps': 2, 'tool_errors': 1, 'completed': True}

Ejercicio 3: Detecta, solo desde RUN_LOG.jsonl, cuál run tardó más pasos antes de fallar (Difícil)

Sin mirar el código de tasks ni de stuck_script: usando exclusivamente events (o events_v2), escribe una función que identifique, entre los runs con completed=False, cuál tiene el mayor número de eventos tool_use antes del run_failed — y confirma que corresponde, en efecto, al run de "Reserva algo ambiguo".

def failed_runs_by_steps(events):
    summaries = summarize_by_trace(events)
    failed = [s for s in summaries if not s["completed"]]
    return sorted(failed, key=lambda s: s["steps"], reverse=True)


ranking = failed_runs_by_steps(events)
for s in ranking:
    print(f"{s['steps']} pasos antes de fallar -- {s['question']!r}")

2 pasos antes de fallar -- 'Reserva algo ambiguo'

Resumen y siguiente paso

• Corrimos un lote real de cuatro tareas de Reservo, con traced_run (M2) envolviendo cada una, produciendo RUN_LOG.jsonl — el primer artefacto real de este capstone, con 20 eventos JSON, uno por cada paso de los cuatro runs.
• Reconstruimos un resumen del lote completo —summarize_by_trace— leyendo exclusivamente el archivo, sin ninguna variable de Python de las que produjo el lote original: la prueba de que el logging estructurado de M2 captura todo lo necesario, sin depender de que el proceso original siga vivo.
• Confirmamos que este RUN_LOG.jsonl y sus trace_id deterministas son el punto de partida compartido que las Lecciones 4, 5 y 6 de este módulo van a reusar, sin volver a correr el lote desde cero.

Siguiente lección: 04 — El reporte de costo y latencia. Con el history de estos mismos runs ya disponible, calculamos cuánto costó y cuánto tardó cada uno, y agregamos el lote completo en un solo reporte de métricas.

Recursos adicionales

1. Python — logging.FileHandler — El handler que escribe RUN_LOG.jsonl a disco, con el modo "w"/"a" que decide si un archivo se sobrescribe o se acumula.
2. Python — JSON Lines / NDJSON, vía json.loads línea por línea — El formato exacto de RUN_LOG.jsonl, y la técnica de load_events para leerlo de vuelta.
3. Anthropic — Tool use error handling — El protocolo is_error que summarize_by_trace cuenta por run, heredado de agent-fundamentals M7.
4. sre-and-incident-response-guide — cuando este mismo trace_id necesite correlacionarse con logs de infraestructura (Lambda, API, base de datos), no solo con eventos del agente — la Lección 7 de este módulo traza esa frontera con precisión.