Leyendo un trace hacia atrás

Descripción

Hasta esta lección, cada línea de log de este módulo terminó en la terminal — visible mientras el programa corría, perdida en cuanto la terminal se cerraba. Un sistema real nunca funciona así: los logs se escriben a un archivo (o a un servicio de agregación, pero el mecanismo de base es el mismo), precisamente para poder mirarlos después, cuando ya nadie está viendo la terminal en tiempo real. Esta lección da ese paso: traced_run escribe, por primera vez, a un archivo real —RUN_LOG.jsonl— y esta lección construye las funciones que lo leen de vuelta.

Leer hacia atrás no es simplemente "abrir el archivo y mirarlo" — con varios runs mezclados en el mismo archivo, la habilidad real es filtrar por trace_id y reconstruir, solo a partir de esas líneas, una narrativa legible de qué pasó en un run específico. Esta lección hace exactamente eso, sobre un archivo que combina un run limpio, un run con un error de tool corregido, y un run que falla del todo — los tres, mezclados en el mismo archivo, sin que ninguno contamine la lectura de los otros.

Conexión con el módulo

Esta lección no agrega nada a run_logger.py — usa la versión final de la lección 06 tal cual, y construye, aparte, las funciones de lectura: load_events, read_trace. Son estas funciones, junto con traced_run, las que el mini-proyecto de la lección 08 combina para cerrar el módulo.

Analogía: la caja negra de un vuelo

Cuando un avión reporta una anomalía, nadie estaba mirando cada instrumento en tiempo real, sillón por sillón. Lo que existe es la caja negra: un registro continuo de cada lectura de instrumento, escrita según ocurría, disponible para reconstruir el vuelo completo después de que terminó — sin importar cómo terminó. Reconstruir un vuelo a partir de su caja negra no es leer una narrativa ya escrita — es tomar miles de lecturas individuales, ordenarlas, y armar, con ellas, la historia de lo que pasó, paso por paso.

RUN_LOG.jsonl es la caja negra de un run del agente de Reservo. Cada línea es una lectura — un evento— que quedó registrada mientras el run ocurría. Leer un trace hacia atrás es, con precisión, lo que hace un investigador con una caja negra: tomar las lecturas correspondientes a un vuelo específico —aquí, un trace_id específico— y reconstruir, a partir de ellas y solo de ellas, la historia completa.

Ejemplo trabajado: RUN_LOG.jsonl, real, con tres runs mezclados

Escribiendo a un archivo real

logging.FileHandler reemplaza al StreamHandler de las lecciones anteriores sin que ninguna otra pieza de run_logger.py tenga que cambiar — el logger no sabe ni le importa a dónde escribe su handler.

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" abre el archivo en modo escritura, reemplazando cualquier contenido anterior — la opción correcta para empezar un archivo de logs desde cero. La alternativa, mode="a" (agregar), no pisa el contenido existente — la usas en el Ejercicio 3 de esta lección.

Tres runs, tres destinos distintos

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

Qué esperar:

total de líneas: 20

_file_handler.close() cierra el archivo explícitamente, asegurando que todo lo escrito se vació al disco (flush) antes de leerlo de vuelta — sin este cierre, algunas líneas podrían quedar en el buffer interno del handler sin haberse escrito todavía. Abre RUN_LOG.jsonl con cualquier editor de texto en este punto: vas a ver veinte líneas de JSON real, generadas por tu propia máquina, con tres trace_id distintos mezclados en orden cronológico.

load_events y read_trace: filtrar y reconstruir

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 solo reconoce los eventos de nivel INFO/ERROR/WARNING (run_started, tool_use, tool_result, run_finished, run_failed) — no los _detail de DEBUG, que en este archivo ni siquiera existen porque el logger se configuró en INFO. Si el archivo tuviera eventos _detail, read_trace simplemente los ignoraría (ningún elif los reconoce), lo cual es exactamente el comportamiento correcto para esta narrativa resumida.

Reconstruyendo los tres runs, uno por uno

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

Qué esperar:

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)

Este es el momento en el que las siete lecciones anteriores rinden por completo. Los tres runs quedaron en el mismo archivo, sin ningún separador explícito entre ellos — y aun así, read_trace reconstruye cada uno por separado, sin que ni una sola línea del run de Ana se cuele en la lectura del run de Luis, ni viceversa. El tercer run —el que falla— muestra exactamente lo que el Módulo 1 no podía mostrar nunca: dos pasos completos (list_rooms dos veces, con su resultado cada uno) antes del RUN FALLIDO final. No es una simulación de esa evidencia — es la reconstrucción real, leída de un archivo real, escrito por una ejecución real.

Errores comunes

1. Intentar cargar RUN_LOG.jsonl completo con un solo json.loads(archivo.read()). Como ya advirtió la lección 03, un archivo JSON Lines no es un único documento JSON — es muchos documentos independientes, uno por línea. load_events los parsea uno a la vez, en un bucle; intentar parsear el archivo entero como si fuera un solo objeto o arreglo falla con un json.JSONDecodeError.

2. Olvidar cerrar (o hacer flush de) el FileHandler antes de leer el archivo. Los handlers de logging pueden mantener contenido en un buffer interno antes de escribirlo físicamente a disco. Sin un close() (o al menos un flush()) explícito, leer el archivo inmediatamente después de escribir puede devolver menos líneas de las que en realidad se generaron.

3. Comparar trace_id de forma parcial o insensible a mayúsculas. read_trace usa e["trace_id"] == trace_id, una comparación exacta de strings. Un hash SHA-256 truncado, como el de esta guía, es siempre en minúsculas hexadecimales — pero copiar un trace_id a mano desde una terminal y cometer un error de transcripción (una letra de más, una de menos) hace que el filtro no encuentre ningún evento, silenciosamente, sin ningún error.

4. Pensar que read_trace reconstruye TODO lo que pasó, incluido el detalle DEBUG. Como se nota arriba, read_trace, tal como está escrita en esta lección, solo reconoce los cinco tipos de evento de nivel INFO/ERROR/WARNING. Si el archivo contuviera eventos _detail (por haberse logueado con el nivel en DEBUG), esta versión de read_trace los ignoraría silenciosamente — una limitación real, y una extensión natural para quien necesite ese nivel de detalle en la reconstrucción.

5. Asumir que el orden de trace_ids en un set refleja el orden cronológico. Un set de Python no garantiza ningún orden. El código de esta lección ordena explícitamente los trace_id por el seq más bajo de cada uno (key=lambda t: next(...)) — sin ese paso, el orden de reconstrucción sería arbitrario, aunque el contenido de cada reconstrucción individual seguiría siendo correcto.

Ejercicios

Ejercicio 1: Reconstruye un solo trace por su id exacto (Fácil)

Usando el RUN_LOG.jsonl ya generado, llama a read_trace directamente con el trace_id del run de Luis ("run-ea4e21ce8f78"), sin pasar por el bucle que recorre los tres. Confirma que obtienes solo las cuatro líneas de ese run.

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)

Ejercicio 2: Encuentra todos los runs fallidos de un archivo (Medio)

Escribe una función find_failed_traces(events) que devuelva el conjunto de trace_id cuyo último evento (o cualquier evento) sea run_failed. Aplícala sobre RUN_LOG.jsonl y confirma que devuelve exactamente el trace_id del run de "Reserva algo ambiguo".

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'}

Ejercicio 3: Agrega un cuarto run al archivo con mode="a", y encuentra qué tools fallaron en todo el lote (Difícil)

Reabre el FileHandler con mode="a" (agregar, sin pisar el contenido existente) y corre un cuarto run: cancel_booking sobre un id que no existe (999), que produce un tool_result con error. Confirma que el archivo ahora tiene 24 líneas (las 20 originales más 4 nuevas). Después, escribe tool_with_most_errors(events), que cuente los is_error: True por nombre de tool en todo el archivo, y confirma que ahora aparecen dos tools con errores: get_quote (del run de Ana) y cancel_booking (del run nuevo).

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}

Resumen y siguiente paso

• Escribimos, por primera vez en este módulo, RUN_LOG.jsonl a un archivo real en disco, con logging.FileHandler — el mismo traced_run de la lección 06, sin ningún cambio, solo apuntando a un destino distinto.
• Construimos load_events (parsear el archivo línea por línea) y read_trace (filtrar por trace_id y reconstruir una narrativa legible), y las probamos sobre un archivo con tres runs mezclados: uno limpio, uno con un error corregido, y uno que falla del todo.
• Confirmamos, ejecutado, que read_trace reconstruye correctamente cada uno de los tres runs, sin que ninguno contamine la lectura de los otros — incluido el run que falla, cuyos dos pasos parciales aparecen exactamente donde deberían, seguidos del evento RUN FALLIDO.

Siguiente lección: 08 — Mini-proyecto: un run de Reservo trazado. Cerramos el módulo con un lote más grande de runs —incluido uno que falla a propósito—, todos corridos con la instrumentación completa, y un reporte agregado, reconstruido 100% desde el archivo de logs.

Recursos adicionales

1. Python — logging.FileHandler — El handler que escribe cada línea a disco, incluida la diferencia entre mode="w" y mode="a".
2. Python — leer archivos línea por línea — El patrón for line in fh: que recorre un archivo sin cargarlo completo en memoria de una vez, relevante para archivos de logs que pueden crecer mucho.
3. JSON Lines — El formato de archivo que RUN_LOG.jsonl usa, y por qué se parsea línea por línea en vez de como un solo documento.
4. Python — json.JSONDecodeError — La excepción que se dispara al intentar parsear un archivo JSON Lines completo como si fuera un único documento JSON.
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, incluida la escritura y lectura real de RUN_LOG.jsonl.