The Instrumented Run

Description

With the operations layer calibrated in Lesson 2, this lesson sets the first of the four disciplines in motion over real traffic: observing. traced_run (M2, Height 1 from the previous lesson's map) wraps dispatch_robust without touching a single line of its code, and produces, for every step of the loop, a complete JSON event — not at the end of the run, but at the exact instant every tool call happens. This lesson runs a batch of four real Reservo tasks — two that complete fine, one with an expected business error, and one that runs out entirely — all written to the same file, RUN_LOG.jsonl, and reconstructs a batch summary reading exclusively that file, with no reference at all to the Python variables that produced the runs.

This is, precisely, the same demonstration M2 (Lesson 8) already ran in depth — this capstone reuses it without changing a line, because it's exactly the starting point Lessons 4, 5, and 6 of this module need: a real RUN_LOG.jsonl, with real trace_ids, to build cost, latency, and the regression gate on.

Connection to the module

This lesson delivers the capstone's first real artifact: RUN_LOG.jsonl, written to disk by this lesson's same four-task batch. Lessons 4, 5, and 6 of this module are going to read these same runs' history to calculate cost, latency, and run the gate — they're never going to re-run the batch from scratch.

Analogy: the scanner at every station, applied to a complete night of service

M2 (Lesson 5) built the analogy of the scanner at every station of a distribution center: a package passing through a station leaves a record at that instant, not at the end of the complete journey. This lesson applies that same idea to a complete night of service at Reservo's restaurant, not a single order: four different customers arrive, one after another, each with their own order — two get resolved fine, one asks to cancel something that never existed, and one asks such an ambiguous question the kitchen never manages to resolve it within the allowed time. The scanner at every station doesn't distinguish between these four cases as they happen — it records each one, with the same detail, regardless of whether the customer leaves satisfied or their order stays unresolved. By the end of the night, the log book — RUN_LOG.jsonl — tells all four's complete story, with nobody having to remember from memory what happened with each one.

Worked example: four runs, one file, rebuilt from scratch

The batch: two clean, one with a business error, one that fails entirely

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

What to expect:

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)

Four runs, with genuinely different outcomes: run 1 and run 2 complete fine; run 3 "completes" in the sense that the agent responded with end_turn, but the business result is a cancelled: False (id: 999 never existed) — a negative case, just as valid as a positive one; run 4 runs out of max_iterations and run_reservo_agent raises RuntimeError, which traced_run lets pass through unhidden, exactly as M2 designed. The try/except around each task is whoever calls traced_run's responsibility — a real batch doesn't stop because one individual run failed.

The report, rebuilt 100% from RUN_LOG.jsonl

Without using any variable from the previous block — not tasks, not history, not final — read the file from scratch and group by 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']}")

What to expect:

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 is a hash of (question, sequence_number) — these four values are deterministic: running this block on your own machine produces exactly these same four trace_ids, always. The total event count — 28 — is the exact sum of two parts: run_started + run_finished/run_failed (two per run, eight in total) plus a tool_use/tool_result pair for every tool call that genuinely ran. run 4 didn't fail on the first attempt — as steps=2 confirms, stuck_script's script gets to complete two real list_rooms iterations (each with its tool_use and its tool_result, no error at all) before the third triggers RuntimeError from max_iterations=2 — the same behavior M2 (Lesson 5) already showed with an equivalent script. Adding up the steps that genuinely happened — 4 + 3 + 1 + 2 = 10 real tool calls, 20 step events — plus the eight open/close events, the total is 20 + 8 = 28. None of this summary read history, final, or any Python variable that existed before this cell — every field came, exclusively, from parsing RUN_LOG.jsonl line by line.

Why this is the foundation for everything that follows in the capstone

It's worth saying, precisely, why this lesson — which builds no new function — is the most important one to prepare well in the entire module. Lessons 4, 5, and 6 each need the same kind of input: a real history, produced by run_reservo_agent, correlated by a deterministic trace_id. cost_for_run (Lesson 4) walks run 1's same history to calculate how much booking Focus pro 3h for Ana cost. total_run_latency_ms (also Lesson 4) walks that same history to calculate, modeled, how long it took. The regression gate (Lesson 5) runs its own scripts, with traced_run's same discipline wrapping every case. Without this lesson, each of those pieces would have to rebuild its own batch of runs from scratch — with this lesson, they all share the same starting point, with the same trace_id serving as the thread connecting "what happened" (M2), "how much it cost" (M3), and "how long it took" (M4).

Common mistakes

1. Running this batch more than once over the same RUN_LOG.jsonl without mode="w". This example's FileHandler opens the file in "w" mode (overwrite), on purpose — if it instead opened in "a" (append) and this block ran twice, RUN_LOG.jsonl would have double the events, and summarize_by_trace would report double the runs, all with repeated, confusing trace_ids between one run and the other.

2. Forgetting _file_handler.close() at the end of the batch. Without closing the handler, Python's write buffer might not have flushed to disk yet when load_events tries to read the file — a timing bug producing a file with fewer lines than expected, not an explicit error.

3. Thinking run 4 (the one that fails) "left no trace at all." It did leave one — two events: run_started and run_failed, with the exception's exact message. What it didn't leave was any step event (tool_use/tool_result), because that run's script never got to complete any tool call before running out of max_iterations=2. Confusing "no step events" with "no trace at all" is losing exactly the improvement M2 built over M1's limit.

4. Calculating tool_errors by counting is_error over tool_use events instead of tool_result. The is_error field only exists, meaningfully, on tool_result events — a tool_use is the request, not the response. summarize_by_trace explicitly filters e["event"] == "tool_result" before looking at is_error, for this exact reason.

5. Assuming RUN_LOG.jsonl's trace_id order is alphabetical or numeric. It's, exclusively, the order every run opened — order.append(tid) in summarize_by_trace preserves that appearance order, never reorders it. Two runs whose hashes happen to sort differently alphabetically still appear in the summary in the real order they happened.

Exercises

Exercise 1: Count how many tool_result events have is_error: true across the batch (Easy)

Using events (already loaded in the worked example), count how many tool_result events have is_error: true in total, adding up all four 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

Exercise 2: Add a fifth run with an invalid tier and confirm it does show up in tool_errors (Medium)

Add a fifth element to tasks: the question "How much does Focus premium 3h cost?", with a script that first tries get_quote with tier="premium" (invalid) and then self-corrects to tier="pro". Run the complete batch again (reopening RUN_LOG.jsonl in "w" mode) and confirm summarize_by_trace reports tool_errors=1 for that 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}

Exercise 3: Detect, only from RUN_LOG.jsonl, which run took the most steps before failing (Hard)

Without looking at tasks's or stuck_script's code: using exclusively events (or events_v2), write a function identifying, among runs with completed=False, which one has the highest number of tool_use events before run_failed — and confirm it does correspond to the "book something ambiguous" run.

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'

Summary and next step

• We ran a real batch of four Reservo tasks, with traced_run (M2) wrapping each one, producing RUN_LOG.jsonl — this capstone's first real artifact, with 20 JSON events, one for every step of the four runs.
• We rebuilt a complete batch summary — summarize_by_trace — reading exclusively the file, with no Python variable from what produced the original batch: proof M2's structured logging captures everything needed, with no dependency on the original process staying alive.
• We confirmed this RUN_LOG.jsonl and its deterministic trace_ids are the shared starting point Lessons 4, 5, and 6 of this module are going to reuse, without ever running the batch from scratch again.

Next lesson: 04 — The Cost and Latency Report. With these same runs' history already available, we calculate how much each one cost and how long it took, and aggregate the complete batch into a single metrics report.

Additional resources

1. Python — logging.FileHandler — The handler that writes RUN_LOG.jsonl to disk, with the "w"/"a" mode that decides whether a file gets overwritten or accumulated.
2. Python — JSON Lines / NDJSON, via json.loads line by line — RUN_LOG.jsonl's exact format, and load_events's technique for reading it back.
3. Anthropic — Tool use error handling — The is_error protocol summarize_by_trace counts per run, inherited from agent-fundamentals M7.
4. sre-and-incident-response-guide — for when this same trace_id needs correlating with infrastructure logs (Lambda, API, database), not just agent events — this module's Lesson 7 traces that boundary precisely.