Niveles de log y qué capturar

Descripción

traced_run, tal como quedó al final de la lección 05, ya loguea cada paso — pero lo hace todo al mismo nivel de detalle: cada tool_use lleva sus argumentos completos, cada tool_result su contenido completo, siempre. Eso está bien para seguir un ejemplo de esta guía, pero en un sistema real, con miles de runs por hora, esa cantidad de detalle en cada línea es ruido: un dashboard operacional no necesita ver el input completo de cada get_quote para saber que el sistema está funcionando — necesita saber, de un vistazo, qué tool se llamó y si salió bien. El detalle completo hace falta solo cuando algo ya se sabe que salió mal, y hay que entender por qué.

Esta lección resuelve esa tensión con la herramienta que logging ya te dio desde la lección 02: los niveles de severidad. En vez de una sola vista de "todo o nada", esta lección separa cada paso en dos capas —una vista operacional liviana a nivel INFO/ERROR, y una vista de depuración completa a nivel DEBUG— y agrega una tercera señal, a nivel WARNING, para un caso que ni INFO ni ERROR capturan bien: un run que se completó, pero no limpio.

Conexión con el módulo

Esta lección completa la versión final de observability/run_logger.py — la que las lecciones 07 y 08 usan sin ningún cambio adicional, y la que, según el DISEÑO de esta guía, se reusa sin modificar desde el Módulo 3 en adelante.

Analogía: la bitácora del guardia, el reporte del turno, y las cámaras completas

Un edificio con seguridad suele tener tres capas de registro, cada una para una audiencia distinta. La bitácora del guardia anota cada ronda, cada puerta revisada, sin ningún detalle extra — suficiente para confirmar, de un vistazo, que el turno se cumplió (INFO). El reporte de incidentes solo existe cuando algo salió mal —una puerta forzada, una alarma real— y va directo al supervisor (ERROR). Las cámaras de seguridad, en cambio, graban todo, todo el tiempo, con el detalle completo de cada segundo — nadie las revisa a menos que ya sepa que algo pasó y necesite reconstruirlo con precisión (DEBUG). Ninguna de las tres capas reemplaza a las otras: la bitácora sin las cámaras no alcanza para investigar un incidente real; las cámaras sin la bitácora obligan a revisar horas de grabación para confirmar algo tan simple como "¿hizo la ronda de las 3am?".

Esta lección construye exactamente esas tres capas para traced_run.

Ejemplo trabajado: la versión final de run_logger.py

ToolCallDetail, la tercera dataclass

@dataclass
class ToolCallDetail:
    """El detalle COMPLETO de un paso -- solo a nivel DEBUG."""
    seq: int
    trace_id: str
    event: str              # "tool_use_detail" | "tool_result_detail"
    step: int
    tool: str
    block: dict = field(default_factory=dict)

ToolCallDetail es deliberadamente distinta de ToolCallEvent: en vez de campos individuales (args, is_error, content), tiene un solo campo block, que guarda el diccionario completo del tool_use_block o del result_block tal como los produce dispatch_robust — incluido el id/tool_use_id, que la vista INFO omite a propósito por ser un detalle irrelevante para una lectura operacional rápida.

RunEvent, con un campo nuevo: tool_errors

@dataclass
class RunEvent:
    seq: int
    trace_id: str
    event: str
    question: str = ""
    tool_errors: int = 0
    error: str = ""

tool_errors cuenta cuántos pasos de este run terminaron en is_error: True — la señal que decide si el cierre de un run se loguea a INFO o a WARNING, como ves abajo.

traced_dispatch, con dos niveles por evento

def _make_traced_dispatch(original_dispatch, trace_id, stats):
    step_counter = itertools.count(1)

    def traced_dispatch(tool_use_block, max_retries=3, timeout=2.0):
        step = next(step_counter)
        # INFO: la señal operacional -- qué tool, en qué paso.
        log_event(logging.INFO, ToolCallEvent(
            seq=next(_sequence), trace_id=trace_id, event="tool_use", step=step, tool=tool_use_block["name"]))
        # DEBUG: el detalle completo -- el bloque tool_use tal cual llegó.
        log_event(logging.DEBUG, ToolCallDetail(
            seq=next(_sequence), trace_id=trace_id, event="tool_use_detail", step=step,
            tool=tool_use_block["name"], block=dict(tool_use_block)))

        result_block = original_dispatch(tool_use_block, max_retries=max_retries, timeout=timeout)
        is_error = bool(result_block.get("is_error"))
        if is_error:
            stats["tool_errors"] += 1

        # INFO si salió bien, ERROR si falló -- la señal que un dashboard necesita.
        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"]))
        # DEBUG: el tool_result completo, incluido el tool_use_id.
        log_event(logging.DEBUG, ToolCallDetail(
            seq=next(_sequence), trace_id=trace_id, event="tool_result_detail", step=step,
            tool=tool_use_block["name"], block=dict(result_block)))
        return result_block

    return traced_dispatch

Nota que ToolCallEvent, a nivel INFO, ya no lleva args para el tool_use (solo tool y step) — el detalle completo de los argumentos se movió a ToolCallDetail, a nivel DEBUG. Esta es, con precisión, la separación de audiencias de la analogía: la bitácora del guardia dice "ronda del piso 3, hecha"; las cámaras completas muestran cada segundo de esa ronda.

traced_run, con el tool_errors decidiendo el nivel de cierre

@contextmanager
def traced_run(question, sequence_number):
    """Abre un run con un trace_id determinista, instrumenta cada tool_use y
    tool_result de rr.dispatch_robust mientras dura, y garantiza -- con
    try/except/else/finally -- que se loguee run_finished o run_failed al
    salir, y que dispatch_robust quede restaurado, pase lo que pase."""
    trace_id = make_trace_id(question, sequence_number)
    stats = {"tool_errors": 0}
    original_dispatch = rr.dispatch_robust
    rr.dispatch_robust = _make_traced_dispatch(original_dispatch, trace_id, stats)
    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, tool_errors=stats["tool_errors"],
                                           error=f"{type(exc).__name__}: {exc}"))
        raise
    else:
        # WARNING si el run se completó pero tuvo tool errors en el camino;
        # INFO si se completó limpio. "Completo" y "sin problemas" no son
        # lo mismo -- el nivel lo deja ver de un vistazo.
        level = logging.WARNING if stats["tool_errors"] > 0 else logging.INFO
        log_event(level, RunEvent(seq=next(_sequence), trace_id=trace_id, event="run_finished",
                                   question=question, tool_errors=stats["tool_errors"]))
    finally:
        rr.dispatch_robust = original_dispatch

stats es un diccionario mutable, creado dentro de traced_run y capturado por el closure de traced_dispatch — la misma técnica que ya viste con original_dispatch en la lección 05, aplicada ahora para acumular un contador a través de todas las llamadas de un mismo run. Cuando el run termina limpio, traced_run decide el nivel de run_finished mirando ese contador: WARNING si hubo al menos un tool_error en el camino, INFO si no hubo ninguno. Esto responde a una pregunta real que ni INFO ni ERROR, por sí solos, contestan bien: un run puede completarse —el usuario recibió una respuesta— y aun así haber tropezado en el camino, como el guion canónico de Ana, que corrige un tier inválido antes de reservar. Ese run no es un fallo (ERROR), pero tampoco es perfectamente limpio (INFO) — es, con precisión, una advertencia.

Viendo las tres capas en acción

Con el nivel del logger en INFO —una configuración típica de producción, ni completamente silenciosa ni completamente verbosa—, corre el guion de Ana con su error de tier:

rl.logger.setLevel(logging.INFO)
with rl.traced_run("Reserva Focus pro 3h para Ana", 1):
    ra.run_reservo_agent("Reserva Focus pro 3h para Ana", script_a)  # el guion con el tier="premium" rechazado

Qué esperar:

{"seq": 1, "trace_id": "run-8487582448eb", "event": "run_started", "question": "Reserva Focus pro 3h para Ana", "tool_errors": 0, "error": ""}
{"seq": 2, "trace_id": "run-8487582448eb", "event": "tool_use", "step": 1, "tool": "list_rooms", "is_error": false, "content": ""}
{"seq": 4, "trace_id": "run-8487582448eb", "event": "tool_result", "step": 1, "tool": "list_rooms", "is_error": false, "content": "[{\"room\": \"Focus\", \"rate_cents\": 2500}, {\"room\": \"Studio\", \"rate_cents\": 4000}, {\"room\": \"Boardroom\", \"rate_cents\": 8000}]"}
{"seq": 6, "trace_id": "run-8487582448eb", "event": "tool_use", "step": 2, "tool": "get_quote", "is_error": false, "content": ""}
{"seq": 8, "trace_id": "run-8487582448eb", "event": "tool_result", "step": 2, "tool": "get_quote", "is_error": true, "content": "'tier'='premium' no está en enum ['basic', 'pro']"}
{"seq": 10, "trace_id": "run-8487582448eb", "event": "tool_use", "step": 3, "tool": "get_quote", "is_error": false, "content": ""}
{"seq": 12, "trace_id": "run-8487582448eb", "event": "tool_result", "step": 3, "tool": "get_quote", "is_error": false, "content": "{\"price_cents\": 6000}"}
{"seq": 14, "trace_id": "run-8487582448eb", "event": "tool_use", "step": 4, "tool": "book_room", "is_error": false, "content": ""}
{"seq": 16, "trace_id": "run-8487582448eb", "event": "tool_result", "step": 4, "tool": "book_room", "is_error": false, "content": "{\"booking_id\": 1, \"confirmed\": true}"}
{"seq": 18, "trace_id": "run-8487582448eb", "event": "run_finished", "question": "Reserva Focus pro 3h para Ana", "tool_errors": 1, "error": ""}

Fíjate en dos cosas. Primero, seq salta —de 2 a 4, de 4 a 6— en vez de crecer de a uno: cada tool call generó también un evento DEBUG (tool_use_detail, tool_result_detail) que consumió un número de secuencia, pero quedó filtrado por el nivel INFO del logger — el seq cuenta todos los eventos generados, no solo los que se imprimieron. Este detalle importa, y la lección 07 lo retoma. Segundo, el run_finished final trae "tool_errors": 1 — y, aunque en este formato compacto no se ve el nombre del nivel, ese evento se logueó a WARNING, no a INFO, porque stats["tool_errors"] era 1 al momento de cerrarse. El run se completó (no es run_failed), pero no limpio.

Ahora, el mismo run con el nivel del logger en ERROR — una configuración agresiva, para un sistema que solo quiere ser interrumpido cuando algo realmente falla:

rl.logger.setLevel(logging.ERROR)
with rl.traced_run("Reserva Focus pro 3h para Ana", 1):
    ra.run_reservo_agent("Reserva Focus pro 3h para Ana", script_a)

Qué esperar:

{"seq": 8, "trace_id": "run-8487582448eb", "event": "tool_result", "step": 2, "tool": "get_quote", "is_error": true, "content": "'tier'='premium' no está en enum ['basic', 'pro']"}

Una sola línea. run_started (INFO) desaparece. Los tres pasos limpios (INFO) desaparecen. Y —esto es lo revelador— run_finished también desaparece, a pesar de haberse logueado a WARNING (nivel 30): WARNING sigue estando por debajo de ERROR (nivel 40), así que un filtro tan agresivo también lo oculta. Un sistema configurado así vería que algo falló en el paso 2, pero no vería que el run, en conjunto, terminó de forma degradada — un matiz real de cómo la elección del nivel de filtrado cambia qué historia cuenta el log.

Y con el nivel en DEBUG —la vista completa, las cámaras encendidas— sobre un run limpio de una sola tool call:

rl.logger.setLevel(logging.DEBUG)
with rl.traced_run("Reserva Boardroom pro 1h para Sofía", 2):
    ra.run_reservo_agent("Reserva Boardroom pro 1h para Sofía", script_sofia)

Qué esperar:

{"seq": 19, "trace_id": "run-c720132bf969", "event": "run_started", "question": "Reserva Boardroom pro 1h para Sofía", "tool_errors": 0, "error": ""}
{"seq": 20, "trace_id": "run-c720132bf969", "event": "tool_use", "step": 1, "tool": "get_quote", "is_error": false, "content": ""}
{"seq": 21, "trace_id": "run-c720132bf969", "event": "tool_use_detail", "step": 1, "tool": "get_quote", "block": {"type": "tool_use", "id": "toolu_01", "name": "get_quote", "input": {"room": "Boardroom", "tier": "pro", "hours": 1}}}
{"seq": 22, "trace_id": "run-c720132bf969", "event": "tool_result", "step": 1, "tool": "get_quote", "is_error": false, "content": "{\"price_cents\": 6400}"}
{"seq": 23, "trace_id": "run-c720132bf969", "event": "tool_result_detail", "step": 1, "tool": "get_quote", "block": {"type": "tool_result", "tool_use_id": "toolu_01", "content": "{\"price_cents\": 6400}"}}
{"seq": 24, "trace_id": "run-c720132bf969", "event": "run_finished", "question": "Reserva Boardroom pro 1h para Sofía", "tool_errors": 0, "error": ""}

Ahora seq no tiene huecos —19, 20, 21, 22, 23, 24, consecutivos— porque DEBUG es el nivel más bajo posible: nada queda filtrado. Y las líneas _detail muestran lo que la vista INFO omitía a propósito: el id exacto del tool_use (toolu_01), y el tool_use_id del tool_result correspondiente — el tipo de detalle que solo hace falta cuando ya sabes que necesitas reconstruir algo con precisión.

Errores comunes

1. Pensar que subir el nivel a DEBUG "agrega información nueva". No agrega nada que no existiera ya — la instrumentación de la lección 05 siempre generó ambos niveles de evento; DEBUG simplemente deja de filtrarlos. El costo de tener DEBUG disponible no es de cómputo (los eventos ya se calculaban) sino de volumen: el doble de líneas por cada tool call, razón suficiente para no dejarlo activado por defecto en producción.

2. Confundir "el run terminó" con "el run terminó bien". Un RunEvent con event="run_finished" significa, únicamente, que run_reservo_agent retornó sin lanzar una excepción — no que cada paso haya salido limpio. El campo tool_errors y el nivel (INFO vs WARNING) son los que distinguen ambos casos; leer solo el event sin mirar ninguno de los dos es perder exactamente la señal que esta lección agregó.

3. Filtrar en ERROR esperando ver el resumen de cada run. Como confirmó el ejemplo trabajado, un filtro en ERROR oculta también los eventos WARNING —incluido un run_finished degradado—, porque WARNING (30) está por debajo de ERROR (40) en la jerarquía de niveles. Un sistema que necesita ver "el run terminó, aunque con problemas" tiene que filtrar, como mínimo, en WARNING.

4. Loguear el detalle completo (block de ToolCallDetail) a nivel INFO "por si acaso". Esto anula exactamente la separación que esta lección construye: si todo el detalle vive en INFO, subir o bajar el nivel deja de tener ningún efecto sobre el volumen de las líneas más pesadas. La disciplina de "INFO liviano, DEBUG completo" solo funciona si se respeta en cada evento nuevo que se agregue al sistema.

5. Olvidar que seq cuenta eventos generados, no eventos impresos. Un hueco en la secuencia de seq (como 2 → 4 en el primer ejemplo de esta lección) no es un error ni un evento perdido — es la prueba de que algo se generó y se filtró. El Ejercicio 3 de esta lección construye un detector explícito de estos huecos.

Ejercicios

Ejercicio 1: Confirma qué sobrevive a un filtro ERROR puro (Fácil)

Con rl.logger.setLevel(logging.ERROR), corre el guion de Ana (con el error de tier) bajo traced_run. Antes de ejecutar, predice cuántas líneas vas a ver. Después, confirma.

import logging
rl.logger.setLevel(logging.ERROR)
with rl.traced_run("Reserva Focus pro 3h para Ana", 1):
    ra.run_reservo_agent("Reserva Focus pro 3h para Ana", script_a)

{"seq": 8, "trace_id": "run-8487582448eb", "event": "tool_result", "step": 2, "tool": "get_quote", "is_error": true, "content": "'tier'='premium' no está en enum ['basic', 'pro']"}

Ejercicio 2: Cuenta las líneas INFO contra DEBUG de un run de tres tool calls limpio (Medio)

Con rl.logger.setLevel(logging.DEBUG), corre el guion de Sofía (list_rooms → get_quote → book_room, sin errores, tres tool calls) bajo traced_run, capturando la salida. Cuenta cuántas líneas empiezan efectivamente como eventos de nivel INFO (run_started, tool_use, tool_result, run_finished) contra cuántas son eventos _detail (DEBUG). Confirma la fórmula: INFO = 2 + 2n, DEBUG = 2n, para n tool calls.

import io
import logging

buf = io.StringIO()
handler = logging.StreamHandler(buf)
handler.setFormatter(logging.Formatter("%(levelname)s %(message)s"))
rl.logger.handlers = [handler]
rl.logger.setLevel(logging.DEBUG)

script_sofia_full = [
    {"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 1h para Sofía."}]},
]
with rl.traced_run("Reserva Boardroom pro 1h para Sofia", 2):
    ra.run_reservo_agent("Reserva Boardroom pro 1h para Sofia", script_sofia_full)

lines = buf.getvalue().splitlines()
info_lines = [l for l in lines if l.startswith("INFO")]
debug_lines = [l for l in lines if l.startswith("DEBUG")]
print("total líneas:", len(lines))
print("líneas INFO :", len(info_lines))
print("líneas DEBUG:", len(debug_lines))

total líneas: 14
líneas INFO : 8
líneas DEBUG: 6

Ejercicio 3: Construye un detector de huecos en seq (Difícil)

Corre un run bajo traced_run con el nivel del logger en INFO (sin DEBUG), capturando la salida como una lista de eventos parseados. Escribe una función find_gaps(events) que, dada la lista de seq presentes, reporte los huecos: pares consecutivos donde la diferencia es mayor que 1, junto con cuántos números faltan en cada hueco. Confirma que cada hueco corresponde exactamente a un evento DEBUG filtrado.

import io
import json
import logging

buf = io.StringIO()
handler = logging.StreamHandler(buf)
handler.setFormatter(logging.Formatter("%(message)s"))
rl.logger.handlers = [handler]
rl.logger.setLevel(logging.INFO)   # sin DEBUG -> quedan huecos en seq

script_ana_gap = [
    {"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": "end_turn", "content": [{"type": "text", "text": "listo"}]},
]
with rl.traced_run("Reserva Focus pro 3h para Ana (gap)", 6):
    ra.run_reservo_agent("Reserva Focus pro 3h para Ana (gap)", script_ana_gap)

events = [json.loads(l) for l in buf.getvalue().splitlines()]

def find_gaps(events):
    seqs = sorted(e["seq"] for e in events)
    gaps = []
    for a, b in zip(seqs, seqs[1:]):
        if b - a > 1:
            gaps.append((a, b, b - a - 1))
    return gaps

print("huecos detectados (seq_antes, seq_después, cuántos faltan):", find_gaps(events))

huecos detectados (seq_antes, seq_después, cuántos faltan): [(1, 3, 1), (3, 5, 1), (5, 7, 1), (7, 9, 1)]

Resumen y siguiente paso

• Separamos cada paso del loop en dos capas: ToolCallEvent a nivel INFO/ERROR (una vista operacional liviana, sin argumentos ni contenido completo) y ToolCallDetail a nivel DEBUG (el bloque completo, incluidos los ids).
• Agregamos tool_errors a RunEvent, y decidimos el nivel de run_finished según ese contador: INFO si el run fue limpio, WARNING si se completó pero con al menos un error de tool en el camino.
• Confirmamos, ejecutado, con el mismo run bajo tres niveles de filtro distintos (INFO, ERROR, DEBUG), que cada uno cuenta una historia distinta — y que un filtro en ERROR oculta también los eventos WARNING, incluido un run_finished degradado.
• Confirmamos, ejecutado, que los huecos en seq son una señal legítima de que algo se filtró, sin necesidad de conocer el contenido exacto de lo que se ocultó.

Siguiente lección: 07 — Leyendo un trace hacia atrás. Con run_logger.py completo, persistimos por primera vez RUN_LOG.jsonl a un archivo real, y construimos las funciones que leen ese archivo de vuelta para reconstruir, desde cero, exactamente qué le pasó a un run específico.

Recursos adicionales

1. Python — logging levels — La tabla completa de niveles (DEBUG=10, INFO=20, WARNING=30, ERROR=40, CRITICAL=50) y su jerarquía numérica, la base de cada filtro de esta lección.
2. Python — logging HOWTO: cuándo usar cada nivel — La guía oficial de criterio, la misma que esta lección aplica al diseño de traced_run.
3. Python — dataclasses.field — field(default_factory=dict), usado en ToolCallEvent y ToolCallDetail para evitar el error clásico de un valor por defecto mutable compartido.
4. Anthropic — Building effective agents — Sobre por qué distinguir "completado" de "completado sin problemas" importa para la confiabilidad real de un sistema agentic.
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.