Logging Each Step of the Loop

Description

open_run, from the previous lesson, solved half the problem: now you know, with certainty, whether a run started and how it ended — completed or failed — with a trace_id that identifies it. But a run that fails with RuntimeError still leaves no trace of what happened in between — how many tools did get to run, which ones, with what result, before the iteration cap stopped it. This lesson solves exactly that, and it is, precisely, the module's central lesson.

The real difficulty isn't technical in the sense of "write more code" — it's a matter of design: run_reservo_agent is a black box that only returns something when it finishes, well or badly. If the run fails, the history variable that was accumulating every step never leaves the function — it's lost with the exception, exactly as agent-fundamentals M8 confirmed in its own lesson on integration. To record every step as it happens, you need an observation point that sits inside each tool call's lifecycle, not after the whole run finishes. This lesson finds that exact point, and instruments it without touching a single line of reservo_agent.py or reservo_robust.py.

Connection to the module

This lesson completes observability/run_logger.py's central piece: ToolCallEvent, the instrumentation technique, and traced_run — the final version of open_run that lessons 06, 07, and 08 (and, per this guide's DISEÑO, every module that follows) reuse unchanged.

Analogy: the scanner at every station, not the question at the end of the trip

Lesson 04 compared the trace_id to a package's tracking number. This lesson adds the piece that makes that number actually useful: the scanner at every station. When a package passes through the distribution center, a scanner reads its tracking number at that instant and leaves a record — not at the end of the entire trip, when someone at headquarters asks "what happened to package 4471?" and has to reconstruct the answer from memory. If the truck carrying it breaks down halfway there, the courier company doesn't lose all the shipment's information — it has the records from every station it did pass through, up to the exact moment of the breakdown.

That's what this lesson builds: a scanner that fires at the exact point every tool call passes through, no matter what happens to the whole run afterward. If the run crashes, the scans that did happen — the steps that did run — stay recorded, with their time (their seq), their tool, and their result.

Worked example: finding the correct observation point

Why "reading history at the end" isn't enough

Before building the solution, it's worth confirming, once more and precisely, why the most obvious idea — waiting for run_reservo_agent to finish and walking history — can't solve this problem. history is a local variable inside run_reservo_agent: it exists while the function runs, and gets returned as part of its return value only if the function returns normally. If instead the function raises an exception — max_iterations's RuntimeError — Python discards that local state entirely. There's no partial history to rescue from outside, because Python's exception mechanism offers no way to read the internal state of a function that didn't finish running.

So the observation point can't be after the call to run_reservo_agent — it has to be inside each tool call's lifecycle, at the one place every tool call passes through without exception: the call to dispatch_robust.

The exact point: rr.dispatch_robust(block), inside the loop

Look, again, at run_reservo_agent's central line (from agent-fundamentals M8, unchanged):

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

rr is the imported reservo_robust module; rr.dispatch_robust(block) is an attribute lookup on the module, re-evaluated on every iteration of the for — not a reference to a function captured once at import time. That's the property that makes this whole lesson possible: if, from outside, you replace the reservo_robust module's dispatch_robust attribute with a different function, the next time run_reservo_agent runs rr.dispatch_robust(block), Python is going to resolve rr.dispatch_robust again — and it's going to find the function you put there, not the original one. This is called monkeypatching: replacing, at runtime, an attribute of a module or an object, without touching the source file where that attribute was defined.

It isn't a fragile trick or a hack — it's a direct, well-documented consequence of how Python resolves names: every rr.dispatch_robust inside the for is, literally, "go to module object rr, and fetch whatever's stored right now under the name dispatch_robust." Changing what's stored there, from another file, is exactly as valid as any other Python assignment.

ToolCallEvent, and the function that wraps 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 has exactly the same signature as dispatch_robust — (tool_use_block, max_retries=3, timeout=2.0) — because it has to be able to take its place without run_reservo_agent noticing any difference. Inside: it logs the tool_use before running anything real, calls original_dispatch — the real function, saved separately so it isn't lost — and logs the tool_result after, at the correct level depending on whether is_error is true. The result is returned unchanged, with no modification at all — run_reservo_agent keeps receiving exactly the same tool_result it always received, the instrumentation is completely transparent to the rest of the system.

traced_run: installing the patch, and guaranteeing it gets removed

@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

The only real change from open_run is the finally block, and the two lines that install the patch before the try. finally runs always — exception or not, caught by the except or not — so rr.dispatch_robust = original_dispatch leaves the module exactly as it was, no matter how the with ended. This guarantee is why the patch is safe to use: it never stays installed "forever" by accident, even if something goes wrong in a way this lesson didn't anticipate.

The definitive test: the same stuck_script that beat Module 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}")

What to expect:

=== 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)

Stop at run 2, line by line. seq=9: the run starts. seq=10 and seq=11: the first list_rooms gets recorded, with its tool_use and its tool_result, complete. seq=12 and seq=13: the second list_rooms also gets recorded complete. And only at seq=14 does the run end with run_failed — because run_reservo_agent's for step in range(max_iterations), with max_iterations=2, processed exactly two turns (model_script[0] and model_script[1]) and, finding no end_turn, fell into the final raise RuntimeError(...), without even attempting a third dispatch_robust.

This is exactly what Module 1 couldn't give you: four lines of real evidence — two complete steps, tool_use and tool_result each — of what happened before the whole run failed. run_and_observe, in the same situation, produced absolutely nothing.

Confirming the patch gets removed

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)")

What to expect:

=== 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)

Not a single JSON line before the response — proof that dispatch_robust, after run 2's RuntimeError, ended up exactly as it was before traced_run touched it. Without the previous section's finally, this call would have generated logs, because the patch would have stayed installed forever. This lesson's Exercise 3 demonstrates that broken scenario, on purpose.

Common mistakes

1. Capturing rr.dispatch_robust into a local variable, and not restoring it on the module. The correct pattern saves the original (original_dispatch = rr.dispatch_robust), uses it inside the wrapped function, and reassigns the module's attribute on exit (rr.dispatch_robust = original_dispatch). Forgetting the final reassignment would leave the patch installed indefinitely, affecting any code that runs afterward, even outside any with.

2. Putting the patch's restoration in the else block instead of finally. A try/except/else's else does not run if the except caught an exception — so a run that fails would leave the patch installed. Only finally guarantees the restoration no matter which path execution took.

3. Thinking dispatch_robust wouldn't keep calling original_dispatch if it gets reassigned inside a loop. original_dispatch is a parameter captured by traced_dispatch's closure, fixed at the moment _make_traced_dispatch is called — it doesn't change even if rr.dispatch_robust gets reassigned later. This is what lets original_dispatch(tool_use_block, ...), inside traced_dispatch, keep calling the real M7 function, without falling into an infinite loop of "the patch calls itself."

4. Assuming this technique requires modifying reservo_agent.py to accept a "callback" or a "hook." No — precisely because rr.dispatch_robust(block) is an attribute lookup on the module, re-evaluated on every call, no change to run_reservo_agent's signature or design is needed. This is the concrete property that makes "wrap without touching" possible.

5. Forgetting this patch only instruments calls made through rr.dispatch_robust. If some other code called a tool directly — for example, rt.get_quote(...) without going through dispatch_robust — that call would go unrecorded. This module's entire instrumentation depends on run_reservo_agent always dispatching through dispatch_robust, something agent-fundamentals M8 guarantees by design.

Exercises

Exercise 1: Count the lines for a run with a single tool call (Easy)

Without running anything: for a run with a single successful tool call (no errors), how many JSON lines does traced_run produce? Count: run_started, tool_use, tool_result, run_finished. Then run the "how much does Boardroom pro 1h cost?" example with traced_run and confirm.

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)

{"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": ""}

Exercise 2: Confirm the 2 + 2n formula with a three-tool-call run and one error (Medium)

Using Ana's canonical script — list_rooms → get_quote (premium, rejected) → get_quote (pro, corrected) → book_room → end_turn, four tool calls total — run traced_run and count the total lines. Confirm it matches 2 + 2*4 = 10.

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)

{"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", ...}

Exercise 3: Trigger an instrumentation leak by omitting finally (Hard)

Write a version of traced_run without finally (the patch's restoration goes, incorrectly, after the yield, at the same level as the try). Run the stuck_script with that broken version and confirm that, after the RuntimeError, rr.dispatch_robust is still patched — demonstrate it by running a completely new run, without requesting any tracing, and observing that it still produces log lines.

@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)")

(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)

Summary and next step

• We identified the correct observation point: rr.dispatch_robust(block), inside run_reservo_agent's for, is an attribute lookup on the module — replaceable from outside, without touching reservo_agent.py or reservo_robust.py.
• We built ToolCallEvent and _make_traced_dispatch: every tool call gets recorded with a tool_use before running and a tool_result after, at the correct level based on is_error.
• We built traced_run, which installs the patch before the run and guarantees it's restored with finally, no matter how the with ends.
• We confirmed, with real execution, the true closing of Module 1's limit: the same stuck_script that used to leave no trace now leaves two complete steps recorded — tool_use and tool_result for each list_rooms — before the final run_failed event.

Next lesson: 06 — Log Levels and What to Capture. With every step now recorded, we refine which level of detail belongs to each type of event: a lightweight operational view at INFO level, and a complete debugging view at DEBUG level, without duplicating the instrumentation mechanism this lesson already built.

Additional resources

1. Python — Modules — How Python resolves module.attribute on every access, the exact technical basis for why this lesson's monkeypatching works.
2. Python — contextlib.contextmanager — The generator with try/except/else/finally behind traced_run.
3. Anthropic — Tool use (function calling) overview — The tool_use/tool_result protocol every ToolCallEvent in this lesson reflects, unaltered.
4. Python — unittest.mock — The standard library that formalizes this same technique of temporarily replacing attributes, used mostly in automated testing.
5. Python 3.14 — What's New — The version every line of code in this lesson ran on, including the real RuntimeError that closes Module 1's limit.