Reading a Trace Back

Description

Up through this lesson, every log line in this module ended up in the terminal — visible while the program ran, lost as soon as the terminal closed. A real system never works that way: logs get written to a file (or to an aggregation service, but the underlying mechanism is the same), precisely so they can be looked at later, once nobody's watching the terminal in real time. This lesson takes that step: traced_run writes, for the first time, to a real file — RUN_LOG.jsonl — and this lesson builds the functions that read it back.

Reading it back isn't simply "open the file and look at it" — with several runs mixed together in the same file, the real skill is filtering by trace_id and reconstructing, from just those lines, a readable narrative of what happened in a specific run. This lesson does exactly that, over a file that combines a clean run, a run with a corrected tool error, and a run that fails outright — all three, mixed in the same file, with none of them contaminating the reading of the others.

Connection to the module

This lesson doesn't add anything to run_logger.py — it uses lesson 06's final version as is, and builds, separately, the reading functions: load_events, read_trace. These functions, together with traced_run, are what lesson 08's mini-project combines to close the module.

Analogy: a flight's black box

When a plane reports an anomaly, nobody was watching every instrument in real time, seat by seat. What exists is the black box: a continuous record of every instrument reading, written as it happened, available to reconstruct the whole flight after it ended — no matter how it ended. Reconstructing a flight from its black box isn't reading an already-written narrative — it's taking thousands of individual readings, ordering them, and building, from them, the story of what happened, step by step.

RUN_LOG.jsonl is a Reservo agent run's black box. Every line is a reading — an event — recorded while the run was happening. Reading a trace back is, precisely, what an investigator does with a black box: taking the readings that correspond to a specific flight — here, a specific trace_id — and reconstructing, from them and only them, the complete story.

Worked example: a real RUN_LOG.jsonl, with three runs mixed together

Writing to a real file

logging.FileHandler replaces the previous lessons' StreamHandler without any other piece of run_logger.py having to change — the logger neither knows nor cares where its handler writes.

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]   # solo archivo para esta demo -- nada a pantalla
rl.logger.setLevel(logging.INFO)

mode="w" opens the file in write mode, replacing any earlier content — the correct choice for starting a log file from scratch. The alternative, mode="a" (append), doesn't overwrite existing content — you use it in this lesson's Exercise 3.

Three runs, three different outcomes

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": "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 #1."}]},
]
script_luis = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "get_quote",
         "input": {"room": "Studio", "tier": "basic", "hours": 5}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "Studio basic 5h cuesta $200.00."}]},
]
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)
]

with rl.traced_run("Reserva Focus pro 3h para Ana", 1):
    ra.run_reservo_agent("Reserva Focus pro 3h para Ana", script_ana)
with rl.traced_run("¿Cuánto cuesta Studio basic 5h?", 2):
    ra.run_reservo_agent("¿Cuánto cuesta Studio basic 5h?", script_luis)
try:
    with rl.traced_run("Reserva algo ambiguo", 3):
        ra.run_reservo_agent("Reserva algo ambiguo", stuck_script, max_iterations=2)
except RuntimeError:
    pass
_file_handler.close()

with open("RUN_LOG.jsonl", encoding="utf-8") as fh:
    print(f"total de líneas: {sum(1 for _ in fh)}")

What to expect:

total de líneas: 20

_file_handler.close() explicitly closes the file, making sure everything written gets flushed to disk before reading it back — without this close, some lines might remain in the handler's internal buffer without having been written yet. Open RUN_LOG.jsonl with any text editor at this point: you're going to see twenty lines of real JSON, generated by your own machine, with three different trace_ids mixed together in chronological order.

load_events and read_trace: filter and reconstruct

import json


def load_events(path):
    """Lee RUN_LOG.jsonl línea por línea y devuelve la lista de dicts, en
    el mismo orden en que se escribieron -- cada línea es un objeto JSON
    completo, independiente de las demás."""
    events = []
    with open(path, encoding="utf-8") as fh:
        for line in fh:
            events.append(json.loads(line))
    return events


def read_trace(events, trace_id):
    """Filtra por trace_id y reconstruye una narrativa legible de UN run,
    ignorando por completo las líneas de cualquier otro run mezcladas en el
    mismo archivo."""
    own = [e for e in events if e["trace_id"] == trace_id]
    lines = []
    for e in own:
        if e["event"] == "run_started":
            lines.append(f"[{e['seq']}] RUN INICIADO   : {e['question']!r}")
        elif e["event"] == "tool_use":
            lines.append(f"[{e['seq']}] paso {e['step']}: llamando {e['tool']}")
        elif e["event"] == "tool_result":
            tag = " [ERROR]" if e["is_error"] else ""
            lines.append(f"[{e['seq']}] paso {e['step']}: resultado{tag}: {e['content']}")
        elif e["event"] == "run_finished":
            estado = "con errores" if e["tool_errors"] else "limpio"
            lines.append(f"[{e['seq']}] RUN COMPLETADO ({estado}, {e['tool_errors']} tool_errors)")
        elif e["event"] == "run_failed":
            lines.append(f"[{e['seq']}] RUN FALLIDO    : {e['error']}")
    return lines

read_trace only recognizes the INFO/ERROR/WARNING-level events (run_started, tool_use, tool_result, run_finished, run_failed) — not DEBUG's _detail ones, which in this file don't even exist because the logger was configured at INFO. If the file did have _detail events, read_trace would simply ignore them (no elif recognizes them), which is exactly the correct behavior for this summarized narrative.

Reconstructing all three runs, one by one

events = load_events("RUN_LOG.jsonl")
trace_ids = sorted({e["trace_id"] for e in events}, key=lambda t: next(e["seq"] for e in events if e["trace_id"] == t))

print(f"trace_ids distintos en el archivo: {len(trace_ids)}")
print()
for trace_id in trace_ids:
    print(f"=== reconstruyendo {trace_id} ===")
    for line in read_trace(events, trace_id):
        print(" ", line)
    print()

What to expect:

trace_ids distintos en el archivo: 3

=== reconstruyendo run-8487582448eb ===
  [1] RUN INICIADO   : 'Reserva Focus pro 3h para Ana'
  [2] paso 1: llamando list_rooms
  [4] paso 1: resultado: [{"room": "Focus", "rate_cents": 2500}, {"room": "Studio", "rate_cents": 4000}, {"room": "Boardroom", "rate_cents": 8000}]
  [6] paso 2: llamando get_quote
  [8] paso 2: resultado [ERROR]: 'tier'='premium' no está en enum ['basic', 'pro']
  [10] paso 3: llamando get_quote
  [12] paso 3: resultado: {"price_cents": 6000}
  [14] paso 4: llamando book_room
  [16] paso 4: resultado: {"booking_id": 1, "confirmed": true}
  [18] RUN COMPLETADO (con errores, 1 tool_errors)

=== reconstruyendo run-ea4e21ce8f78 ===
  [19] RUN INICIADO   : '¿Cuánto cuesta Studio basic 5h?'
  [20] paso 1: llamando get_quote
  [22] paso 1: resultado: {"price_cents": 20000}
  [24] RUN COMPLETADO (limpio, 0 tool_errors)

=== reconstruyendo run-327ad4677ded ===
  [25] RUN INICIADO   : 'Reserva algo ambiguo'
  [26] paso 1: llamando list_rooms
  [28] paso 1: resultado: [{"room": "Focus", "rate_cents": 2500}, {"room": "Studio", "rate_cents": 4000}, {"room": "Boardroom", "rate_cents": 8000}]
  [30] paso 2: llamando list_rooms
  [32] paso 2: resultado: [{"room": "Focus", "rate_cents": 2500}, {"room": "Studio", "rate_cents": 4000}, {"room": "Boardroom", "rate_cents": 8000}]
  [34] RUN FALLIDO    : RuntimeError: max_iterations alcanzado (2)

This is the moment where the previous seven lessons fully pay off. All three runs ended up in the same file, with no explicit separator between them — and yet, read_trace reconstructs each one separately, with not a single line of Ana's run slipping into Luis's reading, or vice versa. The third run — the one that fails — shows exactly what Module 1 could never show: two complete steps (list_rooms twice, each with its result) before the final RUN FALLIDO. It isn't a simulation of that evidence — it's the real reconstruction, read from a real file, written by a real execution.

Common mistakes

1. Trying to load the complete RUN_LOG.jsonl with a single json.loads(archivo.read()). As lesson 03 already warned, a JSON Lines file isn't a single JSON document — it's many independent documents, one per line. load_events parses them one at a time, in a loop; trying to parse the whole file as if it were a single object or array fails with a json.JSONDecodeError.

2. Forgetting to close (or flush) the FileHandler before reading the file. logging handlers can keep content in an internal buffer before physically writing it to disk. Without an explicit close() (or at least a flush()), reading the file right after writing can return fewer lines than were actually generated.

3. Comparing trace_id partially or case-insensitively. read_trace uses e["trace_id"] == trace_id, an exact string comparison. A truncated SHA-256 hash, like this guide's, is always lowercase hexadecimal — but copying a trace_id by hand from a terminal and making a transcription error (one letter too many, one too few) makes the filter find no events at all, silently, with no error.

4. Thinking read_trace reconstructs EVERYTHING that happened, including DEBUG detail. As noted above, read_trace, as written in this lesson, only recognizes the five INFO/ERROR/WARNING-level event types. If the file contained _detail events (from having been logged with the level at DEBUG), this version of read_trace would silently ignore them — a real limitation, and a natural extension for anyone who needs that level of detail in the reconstruction.

5. Assuming the order of trace_ids in a set reflects chronological order. A Python set guarantees no order at all. This lesson's code explicitly sorts the trace_ids by each one's lowest seq (key=lambda t: next(...)) — without that step, the reconstruction order would be arbitrary, although the content of each individual reconstruction would still be correct.

Exercises

Exercise 1: Reconstruct a single trace by its exact id (Easy)

Using the already-generated RUN_LOG.jsonl, call read_trace directly with Luis's run's trace_id ("run-ea4e21ce8f78"), without going through the loop that walks all three. Confirm you get only that run's four lines.

events = load_events("RUN_LOG.jsonl")
lines = read_trace(events, "run-ea4e21ce8f78")
for line in lines:
    print(line)

[19] RUN INICIADO   : '¿Cuánto cuesta Studio basic 5h?'
[20] paso 1: llamando get_quote
[22] paso 1: resultado: {"price_cents": 20000}
[24] RUN COMPLETADO (limpio, 0 tool_errors)

Exercise 2: Find every failed run in a file (Medium)

Write a find_failed_traces(events) function that returns the set of trace_ids whose last event (or any event) is run_failed. Apply it to RUN_LOG.jsonl and confirm it returns exactly the trace_id for the "Reserva algo ambiguo" run.

def find_failed_traces(events):
    failed = set()
    for e in events:
        if e["event"] == "run_failed":
            failed.add(e["trace_id"])
    return failed

events = load_events("RUN_LOG.jsonl")
print("traces fallidos:", find_failed_traces(events))

traces fallidos: {'run-327ad4677ded'}

Exercise 3: Add a fourth run to the file with mode="a", and find which tools failed across the whole batch (Hard)

Reopen the FileHandler with mode="a" (append, without overwriting existing content) and run a fourth run: cancel_booking over an id that doesn't exist (999), which produces an error tool_result. Confirm the file now has 24 lines (the original 20 plus 4 new ones). Then write tool_with_most_errors(events), which counts is_error: True by tool name across the whole file, and confirm two tools now show up with errors: get_quote (from Ana's run) and cancel_booking (from the new run).

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

script_cancel = [
    {"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."}]},
]
with rl.traced_run("Cancela la reserva 999", 4):
    ra.run_reservo_agent("Cancela la reserva 999", script_cancel)
fh.close()

events = load_events("RUN_LOG.jsonl")
print("total de líneas ahora:", len(events))

def tool_with_most_errors(events):
    counts = {}
    for e in events:
        if e["event"] == "tool_result" and e["is_error"]:
            counts[e["tool"]] = counts.get(e["tool"], 0) + 1
    return counts

print("errores por tool:", tool_with_most_errors(events))

total de líneas ahora: 24
errores por tool: {'get_quote': 1, 'cancel_booking': 1}

Summary and next step

• For the first time in this module, we wrote RUN_LOG.jsonl to a real file on disk, with logging.FileHandler — the same traced_run from lesson 06, unchanged, just pointed at a different destination.
• We built load_events (parse the file line by line) and read_trace (filter by trace_id and reconstruct a readable narrative), and tested them over a file with three mixed-together runs: one clean, one with a corrected error, and one that fails outright.
• We confirmed, with real execution, that read_trace correctly reconstructs each of the three runs, with none contaminating another's reading — including the run that fails, whose two partial steps appear exactly where they should, followed by the RUN FALLIDO event.

Next lesson: 08 — Mini-Project: A Traced Reservo Run. We close the module with a larger batch of runs — including one that fails on purpose — all run with the complete instrumentation, and an aggregate report, reconstructed 100% from the log file.

Additional resources

1. Python — logging.FileHandler — The handler that writes every line to disk, including the difference between mode="w" and mode="a".
2. Python — reading files line by line — The for line in fh: pattern that walks a file without loading it entirely into memory at once, relevant for log files that can grow quite large.
3. JSON Lines — The file format RUN_LOG.jsonl uses, and why it's parsed line by line instead of as a single document.
4. Python — json.JSONDecodeError — The exception raised when trying to parse a complete JSON Lines file as if it were a single JSON document.
5. Python 3.14 — What's New — The version every line of code in this lesson ran on, including the real writing and reading of RUN_LOG.jsonl.