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

Logueando cada paso del loop

Descripción

open_run, de la lección anterior, resolvió la mitad del problema: ahora sabes, con certeza, si un run empezó y cómo terminó —completado o fallido—, con un trace_id que lo identifica. Pero un run que falla con RuntimeError sigue sin dejar ningún rastro de qué pasó en el medio — cuántas tools sí llegaron a ejecutarse, cuáles, con qué resultado, antes de que el tope de iteraciones lo detuviera. Esta lección resuelve exactamente eso, y es, con precisión, la lección central de todo el módulo.

La dificultad real no es técnica en el sentido de "escribir más código" — es de diseño: run_reservo_agent es una caja negra que solo devuelve algo cuando termina, bien o mal. Si el run falla, la variable history que fue acumulando cada paso nunca sale de la función — se pierde con la excepción, exactamente como confirmó agent-fundamentals M8 en su propia lección sobre integración. Para registrar cada paso según ocurre, hace falta un punto de observación que esté dentro del ciclo de vida de cada tool call, no después de que el run completo termine. Esta lección encuentra ese punto exacto, y lo instrumenta sin tocar una sola línea de reservo_agent.py ni de reservo_robust.py.

Conexión con el módulo

Esta lección completa la pieza central de observability/run_logger.py: ToolCallEvent, la técnica de instrumentación, y traced_run — la versión final de open_run que las lecciones 06, 07 y 08 (y, según el DISEÑO de esta guía, todos los módulos que siguen) reusan sin cambios.


Analogía: el escáner de cada estación, no la pregunta al final del viaje

La lección 04 comparó el trace_id con el número de guía de un paquete. Esta lección agrega la pieza que hace que ese número sirva de algo: el escáner en cada estación. Cuando un paquete pasa por el centro de distribución, un escáner lee su número de guía en ese instante y deja un registro — no al final del viaje completo, cuando alguien en la oficina central pregunta "¿qué pasó con el paquete 4471?" y tiene que reconstruir la respuesta de memoria. Si el camión que lo llevaba se avería a mitad de camino, la empresa de mensajería no pierde toda la información del envío — tiene los registros de cada estación por la que sí pasó, hasta el momento exacto de la avería.

Eso es lo que esta lección construye: un escáner que se activa en el punto exacto por el que cada tool call pasa, sin importar qué le pase al run completo después. Si el run se cae, los escaneos que sí ocurrieron —los pasos que sí se ejecutaron— quedan registrados, con su hora (su seq), su tool, y su resultado.


Ejemplo trabajado: encontrar el punto de observación correcto

Por qué "leer history al final" no alcanza

Antes de construir la solución, vale la pena confirmar, una vez más y con precisión, por qué la idea más obvia —esperar a que run_reservo_agent termine y recorrer history— no puede resolver este problema. history es una variable local dentro de run_reservo_agent: existe mientras la función corre, y se devuelve como parte de su valor de retorno solo si la función retorna normalmente. Si en cambio la función lanza una excepción —el RuntimeError de max_iterations—, Python descarta ese estado local por completo. No hay ningún history parcial que rescatar desde afuera, porque el mecanismo de excepciones de Python no ofrece ninguna forma de leer el estado interno de una función que no terminó de ejecutarse.

Entonces, el punto de observación no puede estar después de la llamada a run_reservo_agent — tiene que estar dentro del ciclo de vida de cada tool call, en el único lugar por el que todas pasan sin excepción: la llamada a dispatch_robust.

El punto exacto: rr.dispatch_robust(block), dentro del loop

Mira, de nuevo, la línea central de run_reservo_agent (de agent-fundamentals M8, sin cambios):

# dentro de reservo_agent.py -- SIN TOCAR
for block in turn["content"]:
    result_block = rr.dispatch_robust(block)          # M7: valida, reintenta, timeout

rr es el módulo reservo_robust importado; rr.dispatch_robust(block) es una búsqueda de atributo sobre el módulo, evaluada de nuevo en cada iteración del for — no una referencia a una función capturada una sola vez al importar. Esa es la propiedad que hace posible toda esta lección: si, desde afuera, reemplazas el atributo dispatch_robust del módulo reservo_robust por una función distinta, la próxima vez que run_reservo_agent ejecute rr.dispatch_robust(block), Python va a resolver rr.dispatch_robust de nuevo — y va a encontrar la función que tú pusiste ahí, no la original. Esto se llama monkeypatching: reemplazar, en tiempo de ejecución, un atributo de un módulo o de un objeto, sin tocar el archivo fuente donde ese atributo se definió.

No es un truco frágil ni un hack — es una consecuencia directa y bien documentada de cómo Python resuelve nombres: cada rr.dispatch_robust dentro del for es, literalmente, "ve al objeto módulo rr, y trae lo que tenga guardado ahora mismo bajo el nombre dispatch_robust". Cambiar qué hay guardado ahí, desde otro archivo, es exactamente tan válido como cualquier otra asignación de Python.

ToolCallEvent, y la función que envuelve dispatch_robust

from dataclasses import dataclass, field

@dataclass
class ToolCallEvent:
    """Un evento de nivel de PASO: una tool_use o su tool_result."""
    seq: int
    trace_id: str
    event: str             # "tool_use" | "tool_result"
    step: int
    tool: str
    args: dict = field(default_factory=dict)
    is_error: bool = False
    content: str = ""


def _make_traced_dispatch(original_dispatch, trace_id):
    """Envuelve dispatch_robust (M7, sin tocar su código) con un log ANTES
    y un log DESPUÉS de cada llamada -- así que cada tool_use/tool_result
    queda registrado en el instante en que ocurre, no al final del run."""
    step_counter = itertools.count(1)

    def traced_dispatch(tool_use_block, max_retries=3, timeout=2.0):
        step = next(step_counter)
        log_event(logging.INFO, ToolCallEvent(
            seq=next(_sequence), trace_id=trace_id, event="tool_use", step=step,
            tool=tool_use_block["name"], args=tool_use_block["input"],
        ))
        result_block = original_dispatch(tool_use_block, max_retries=max_retries, timeout=timeout)
        is_error = bool(result_block.get("is_error"))
        log_event(logging.ERROR if is_error else logging.INFO, ToolCallEvent(
            seq=next(_sequence), trace_id=trace_id, event="tool_result", step=step,
            tool=tool_use_block["name"], is_error=is_error, content=result_block["content"],
        ))
        return result_block

    return traced_dispatch

traced_dispatch tiene exactamente la misma firma que dispatch_robust(tool_use_block, max_retries=3, timeout=2.0)— porque tiene que poder ocupar su lugar sin que run_reservo_agent note ninguna diferencia. Adentro: loguea el tool_use antes de ejecutar nada real, llama a original_dispatch —la función real, guardada aparte, para no perderla—, y loguea el tool_result después, con el nivel correcto según si is_error es verdadero. El resultado se devuelve tal cual, sin ninguna modificación — run_reservo_agent sigue recibiendo exactamente el mismo tool_result que siempre recibió, la instrumentación es completamente transparente para el resto del sistema.

traced_run: instalar el parche, y garantizar que se retire

@contextmanager
def traced_run(question, sequence_number):
    """open_run (lección 04) + el parcheo de dispatch_robust (esta
    lección): mientras dura el `with`, CADA llamada que run_reservo_agent
    hace a rr.dispatch_robust queda instrumentada -- sin tocar una línea de
    reservo_agent.py ni de reservo_robust.py."""
    trace_id = make_trace_id(question, sequence_number)
    original_dispatch = rr.dispatch_robust
    rr.dispatch_robust = _make_traced_dispatch(original_dispatch, trace_id)
    log_event(logging.INFO, RunEvent(seq=next(_sequence), trace_id=trace_id, event="run_started", question=question))
    try:
        yield trace_id
    except Exception as exc:
        log_event(logging.ERROR, RunEvent(seq=next(_sequence), trace_id=trace_id, event="run_failed",
                                           question=question, error=f"{type(exc).__name__}: {exc}"))
        raise
    else:
        log_event(logging.INFO, RunEvent(seq=next(_sequence), trace_id=trace_id, event="run_finished", question=question))
    finally:
        rr.dispatch_robust = original_dispatch  # siempre se restaura, pase lo que pase adentro

El único cambio real respecto a open_run es el bloque finally, y las dos líneas que instalan el parche antes del try. finally corre siempre — haya excepción o no, la haya capturado el except o no — así que rr.dispatch_robust = original_dispatch deja el módulo exactamente como estaba, sin importar cómo haya terminado el with. Esta garantía es la razón por la que el parche es seguro de usar: nunca se queda instalado "para siempre" por accidente, incluso si algo sale mal de una forma que esta lección no anticipó.

La prueba definitiva: el mismo stuck_script que le ganó al Módulo 1

print("=== run 1: Ana, se completa normalmente, con log de cada paso ===")
script_ana = [
    {"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": "pro", "hours": 3}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_03", "name": "book_room",
         "input": {"room": "Focus", "tier": "pro", "hours": 3, "member": "Ana"}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "Reservé Focus pro 3h para Ana. Confirmación #1."}]},
]
with traced_run("Reserva Focus pro 3h para Ana", 1) as trace_id:
    final, history = ra.run_reservo_agent("Reserva Focus pro 3h para Ana", script_ana)
print("RESPUESTA:", final["content"][0]["text"])

print()
print("=== run 2: se agota max_iterations -- pero los pasos que SÍ corrieron quedan en el log ===")
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)
]
try:
    with traced_run("Reserva algo ambiguo", 2) as trace_id2:
        ra.run_reservo_agent("Reserva algo ambiguo", stuck_script, max_iterations=2)
except RuntimeError as exc:
    print(f"RuntimeError capturado afuera de traced_run: {exc}")

Qué esperar:

=== run 1: Ana, se completa normalmente, con log de cada paso ===
{"seq": 1, "trace_id": "run-8487582448eb", "event": "run_started", "question": "Reserva Focus pro 3h para Ana", "error": ""}
{"seq": 2, "trace_id": "run-8487582448eb", "event": "tool_use", "step": 1, "tool": "list_rooms", "args": {}, "is_error": false, "content": ""}
{"seq": 3, "trace_id": "run-8487582448eb", "event": "tool_result", "step": 1, "tool": "list_rooms", "args": {}, "is_error": false, "content": "[{\"room\": \"Focus\", \"rate_cents\": 2500}, {\"room\": \"Studio\", \"rate_cents\": 4000}, {\"room\": \"Boardroom\", \"rate_cents\": 8000}]"}
{"seq": 4, "trace_id": "run-8487582448eb", "event": "tool_use", "step": 2, "tool": "get_quote", "args": {"room": "Focus", "tier": "pro", "hours": 3}, "is_error": false, "content": ""}
{"seq": 5, "trace_id": "run-8487582448eb", "event": "tool_result", "step": 2, "tool": "get_quote", "args": {}, "is_error": false, "content": "{\"price_cents\": 6000}"}
{"seq": 6, "trace_id": "run-8487582448eb", "event": "tool_use", "step": 3, "tool": "book_room", "args": {"room": "Focus", "tier": "pro", "hours": 3, "member": "Ana"}, "is_error": false, "content": ""}
{"seq": 7, "trace_id": "run-8487582448eb", "event": "tool_result", "step": 3, "tool": "book_room", "args": {}, "is_error": false, "content": "{\"booking_id\": 1, \"confirmed\": true}"}
{"seq": 8, "trace_id": "run-8487582448eb", "event": "run_finished", "question": "Reserva Focus pro 3h para Ana", "error": ""}
RESPUESTA: Reservé Focus pro 3h para Ana. Confirmación #1.

=== run 2: se agota max_iterations -- pero los pasos que SÍ corrieron quedan en el log ===
{"seq": 9, "trace_id": "run-87cd87da52d9", "event": "run_started", "question": "Reserva algo ambiguo", "error": ""}
{"seq": 10, "trace_id": "run-87cd87da52d9", "event": "tool_use", "step": 1, "tool": "list_rooms", "args": {}, "is_error": false, "content": ""}
{"seq": 11, "trace_id": "run-87cd87da52d9", "event": "tool_result", "step": 1, "tool": "list_rooms", "args": {}, "is_error": false, "content": "[{\"room\": \"Focus\", \"rate_cents\": 2500}, {\"room\": \"Studio\", \"rate_cents\": 4000}, {\"room\": \"Boardroom\", \"rate_cents\": 8000}]"}
{"seq": 12, "trace_id": "run-87cd87da52d9", "event": "tool_use", "step": 2, "tool": "list_rooms", "args": {}, "is_error": false, "content": ""}
{"seq": 13, "trace_id": "run-87cd87da52d9", "event": "tool_result", "step": 2, "tool": "list_rooms", "args": {}, "is_error": false, "content": "[{\"room\": \"Focus\", \"rate_cents\": 2500}, {\"room\": \"Studio\", \"rate_cents\": 4000}, {\"room\": \"Boardroom\", \"rate_cents\": 8000}]"}
{"seq": 14, "trace_id": "run-87cd87da52d9", "event": "run_failed", "question": "Reserva algo ambiguo", "error": "RuntimeError: max_iterations alcanzado (2)"}
RuntimeError capturado afuera de traced_run: max_iterations alcanzado (2)

Detente en el run 2, línea por línea. seq=9: el run empieza. seq=10 y seq=11: el primer list_rooms se registra, con su tool_use y su tool_result, completo. seq=12 y seq=13: el segundo list_rooms también se registra completo. Y recién en seq=14, el run termina con run_failed — porque el for step in range(max_iterations) de run_reservo_agent, con max_iterations=2, procesó exactamente dos turnos (model_script[0] y model_script[1]) y, al no encontrar un end_turn, cayó en el raise RuntimeError(...) final, sin llegar a intentar un tercer dispatch_robust.

Esto es exactamente lo que el Módulo 1 no pudo darte: cuatro líneas de evidencia real —dos pasos completos, tool_use y tool_result cada uno— de lo que pasó antes de que el run entero fallara. run_and_observe, en la misma situación, no producía absolutamente nada.

Confirmando que el parche se retira

print("=== run 3: SIN traced_run -- ninguna línea de log, prueba de que dispatch_robust quedó restaurado ===")
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."}]},
]
final_e, history_e = ra.run_reservo_agent("¿Cuánto cuesta Studio pro 2h?", script_e)
print("RESPUESTA:", final_e["content"][0]["text"], "(sin ninguna línea JSON arriba)")

Qué esperar:

=== run 3: SIN traced_run -- ninguna línea de log, prueba de que dispatch_robust quedó restaurado ===
RESPUESTA: Studio pro 2h cuesta $64.00. (sin ninguna línea JSON arriba)

Ninguna línea de JSON antes de la respuesta — la prueba de que dispatch_robust, tras el RuntimeError del run 2, quedó exactamente como estaba antes de que traced_run lo tocara. Sin el finally de la sección anterior, esta llamada habría generado logs, porque el parche se habría quedado instalado para siempre. El Ejercicio 3 de esta lección demuestra ese escenario roto, a propósito.


Errores comunes

  1. Capturar rr.dispatch_robust en una variable local, y no restaurarlo en el módulo. El patrón correcto guarda el original (original_dispatch = rr.dispatch_robust), lo usa dentro de la función envuelta, y reasigna el atributo del módulo al salir (rr.dispatch_robust = original_dispatch). Olvidar la reasignación final dejaría el parche instalado indefinidamente, afectando a cualquier código que se ejecute después, incluso fuera de cualquier with.

  2. Poner la restauración del parche en el bloque else en vez de en finally. El else de un try/except/else no se ejecuta si el except capturó una excepción — así que un run que falla dejaría el parche instalado. Solo finally garantiza la restauración sin importar el camino que tomó la ejecución.

  3. Pensar que dispatch_robust no volvería a llamar original_dispatch si se reasigna dentro de un loop. original_dispatch es un parámetro capturado por el closure de traced_dispatch, fijado en el momento en que se llama a _make_traced_dispatch — no cambia aunque rr.dispatch_robust se reasigne después. Esto es lo que permite que original_dispatch(tool_use_block, ...), dentro de traced_dispatch, siga llamando a la función real de M7, sin caer en un bucle infinito de "el parche se llama a sí mismo".

  4. Suponer que esta técnica requiere modificar reservo_agent.py para aceptar un "callback" o un "hook". No — precisamente porque rr.dispatch_robust(block) es una búsqueda de atributo sobre el módulo, evaluada en cada llamada, ningún cambio de firma ni de diseño de run_reservo_agent es necesario. Esta es la propiedad concreta que hace posible "envolver sin tocar".

  5. Olvidar que este parche solo instrumenta llamadas hechas a través de rr.dispatch_robust. Si algún otro código llamara directamente a una tool —por ejemplo, rt.get_quote(...) sin pasar por dispatch_robust—, ese llamado no quedaría registrado. Toda la instrumentación de este módulo depende de que run_reservo_agent despache siempre a través de dispatch_robust, algo que agent-fundamentals M8 garantiza por diseño.


Ejercicios

Ejercicio 1: Cuenta las líneas de un run de una sola tool call (Fácil)

Sin ejecutar nada: para un run con una sola tool call exitosa (sin errores), ¿cuántas líneas de JSON produce traced_run? Cuenta: run_started, tool_use, tool_result, run_finished. Después, corre el ejemplo de "¿Cuánto cuesta Boardroom pro 1h?" con traced_run y confirma.

Ver solución

Sin ejecutar: run_started (1) + tool_use (1) + tool_result (1) + run_finished (1) = 4 líneas.

script_sofia = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "get_quote",
         "input": {"room": "Boardroom", "tier": "pro", "hours": 1}}]},
    {"stop_reason": "end_turn", "content": [{"type": "text", "text": "Boardroom pro 1h cuesta $64.00."}]},
]
with traced_run("¿Cuánto cuesta Boardroom pro 1h?", 3):
    ra.run_reservo_agent("¿Cuánto cuesta Boardroom pro 1h?", script_sofia)

Salida esperada (4 líneas):

{"seq": 15, "trace_id": "run-c720132bf969", "event": "run_started", "question": "¿Cuánto cuesta Boardroom pro 1h?", "error": ""}
{"seq": 16, "trace_id": "run-c720132bf969", "event": "tool_use", "step": 1, "tool": "get_quote", "args": {"room": "Boardroom", "tier": "pro", "hours": 1}, "is_error": false, "content": ""}
{"seq": 17, "trace_id": "run-c720132bf969", "event": "tool_result", "step": 1, "tool": "get_quote", "args": {}, "is_error": false, "content": "{\"price_cents\": 6400}"}
{"seq": 18, "trace_id": "run-c720132bf969", "event": "run_finished", "question": "¿Cuánto cuesta Boardroom pro 1h?", "error": ""}

Explicación: cada tool call agrega exactamente dos eventos (tool_use + tool_result), sin importar si tuvo éxito o falló — la diferencia entre éxito y fallo está en el campo is_error y en el nivel del segundo evento, no en la cantidad de líneas. Con n tool calls, la fórmula es 2 + 2n líneas totales.

Ejercicio 2: Confirma la fórmula 2 + 2n con un run de tres tool calls y un error (Medio)

Usando el guion canónico de Ana —list_roomsget_quote (premium, rechazado) → get_quote (pro, corregido) → book_roomend_turn, cuatro tool calls en total—, corre traced_run y cuenta las líneas totales. Confirma que coincide con 2 + 2*4 = 10.

Ver solución
script_ana_error = [
    {"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 3h para Ana. Confirmación #4."}]},
]
with traced_run("Reserva Focus pro 3h para Ana (con error)", 4):
    ra.run_reservo_agent("Reserva Focus pro 3h para Ana (con error)", script_ana_error)

Salida esperada (10 líneas: run_started + 4×(tool_use+tool_result) + run_finished):

{"seq": 19, ..., "event": "run_started", ...}
{"seq": 20, ..., "event": "tool_use", "step": 1, "tool": "list_rooms", ...}
{"seq": 21, ..., "event": "tool_result", "step": 1, "tool": "list_rooms", ...}
{"seq": 22, ..., "event": "tool_use", "step": 2, "tool": "get_quote", ...}
{"seq": 23, ..., "event": "tool_result", "step": 2, "tool": "get_quote", "is_error": true, ...}
{"seq": 24, ..., "event": "tool_use", "step": 3, "tool": "get_quote", ...}
{"seq": 25, ..., "event": "tool_result", "step": 3, "tool": "get_quote", ...}
{"seq": 26, ..., "event": "tool_use", "step": 4, "tool": "book_room", ...}
{"seq": 27, ..., "event": "tool_result", "step": 4, "tool": "book_room", ...}
{"seq": 28, ..., "event": "run_finished", ...}

Explicación: diez líneas, exactamente 2 + 2*4. La línea seq=23 es la única con "is_error": true — el intento de get_quote con tier="premium", rechazado por check_input_v2 antes de que la función real se ejecute. La fórmula no distingue entre pasos exitosos y fallidos porque ambos generan el mismo par tool_use/tool_result — la única diferencia es el contenido de esos eventos, no su cantidad.

Ejercicio 3: Provoca la fuga de instrumentación al omitir finally (Difícil)

Escribe una versión de traced_run sin finally (la restauración del parche va, incorrectamente, después del yield, al mismo nivel que el try). Corre el stuck_script con esa versión rota y confirma que, después del RuntimeError, rr.dispatch_robust sigue parcheado — demuéstralo corriendo un run completamente nuevo, sin pedir ningún trazado, y observando que igual produce líneas de log.

Ver solución
@contextmanager
def leaky_traced_run(question, sequence_number):
    """A propósito SIN finally: si algo lanza, dispatch_robust queda
    parcheado para siempre."""
    trace_id = make_trace_id(question, sequence_number)
    original = rr.dispatch_robust
    rr.dispatch_robust = _make_traced_dispatch(original, trace_id)
    log_event(logging.INFO, RunEvent(seq=next(_sequence), trace_id=trace_id, event="run_started", question=question))
    yield trace_id
    rr.dispatch_robust = original   # esta línea NUNCA corre si el with lanza

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)
]
try:
    with leaky_traced_run("Reserva algo ambiguo (fuga)", 5):
        ra.run_reservo_agent("Reserva algo ambiguo (fuga)", stuck_script, max_iterations=2)
except RuntimeError:
    print("(RuntimeError capturado -- pero dispatch_robust quedó parcheado)")

print()
print("=== un run completamente nuevo, sin pedir ningún trazado -- pero sigue logueando ===")
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."}]},
]
ra.run_reservo_agent("¿Cuánto cuesta Studio pro 2h?", script_e)
print("(la línea de log de arriba NO debería existir -- es la fuga)")

Salida esperada:

(RuntimeError capturado -- pero dispatch_robust quedó parcheado)

=== un run completamente nuevo, sin pedir ningún trazado -- pero sigue logueando ===
{"seq": ..., "trace_id": "run-...", "event": "tool_use", "step": 1, "tool": "get_quote", ...}
(la línea de log de arriba NO debería existir -- es la fuga)

Explicación: sin finally, rr.dispatch_robust = original solo se ejecuta si el with termina sin lanzar — y el stuck_script sí lanza, así que esa línea nunca corre. El parche queda instalado indefinidamente en el módulo reservo_robust, y cualquier código posterior que llame a run_reservo_agent —incluido código que nunca pidió ningún trazado— termina generando logs sin que nadie lo haya solicitado. Este es, con precisión, el motivo por el que el finally de traced_run no es una formalidad — es la única garantía real de que el parche no sobrevive más allá del with que lo instaló.


Resumen y siguiente paso

  • Identificamos el punto de observación correcto: rr.dispatch_robust(block), dentro del for de run_reservo_agent, es una búsqueda de atributo sobre el módulo — reemplazable desde afuera, sin tocar reservo_agent.py ni reservo_robust.py.
  • Construimos ToolCallEvent y _make_traced_dispatch: cada tool call queda registrada con un tool_use antes de ejecutar y un tool_result después, con el nivel correcto según is_error.
  • Construimos traced_run, que instala el parche antes del run y lo garantiza restaurado con finally, sin importar cómo termine el with.
  • Confirmamos, ejecutado, el cierre real del límite del Módulo 1: el mismo stuck_script que antes no dejaba ningún rastro ahora deja dos pasos completos registrados —tool_use y tool_result de cada list_rooms— antes del evento run_failed final.

Siguiente lección: 06 — Niveles de log y qué capturar. Con cada paso ya registrado, refinamos qué nivel de detalle corresponde a cada tipo de evento: una vista operacional liviana a nivel INFO, y una vista de depuración completa a nivel DEBUG, sin duplicar el mecanismo de instrumentación que esta lección ya construyó.


Recursos adicionales

  1. Python — Modules — Cómo Python resuelve modulo.atributo en cada acceso, la base técnica exacta de por qué el monkeypatching de esta lección funciona.
  2. Python — contextlib.contextmanager — El generador con try/except/else/finally detrás de traced_run.
  3. Anthropic — Tool use (function calling) overview — El protocolo tool_use/tool_result que cada ToolCallEvent de esta lección refleja, sin alterarlo.
  4. Python — unittest.mock — La librería estándar que formaliza esta misma técnica de reemplazar atributos temporalmente, usada sobre todo en pruebas automatizadas.
  5. Python 3.14 — What's New — La versión con la que se ejecutó cada línea de código de esta lección, incluido el RuntimeError real que cierra el límite del Módulo 1.