El `trace_id`: correlacionando un run

Descripción

La lección 03 dejó RunEvent con un campo trace_id, pero lo llenó a mano —"run-demo", escrito literalmente en el código—. Esta lección construye la pieza que falta: una función que genera un trace_id real, uno distinto para cada run, siempre el mismo para el mismo run — determinista, nunca aleatorio. Con esa pieza en su lugar, la segunda mitad de la lección construye open_run, un contextlib.contextmanager que abre un run con su trace_id, y —esto es lo que realmente importa— garantiza que se registre un evento de cierre, incluso cuando lo que corre adentro del with termina en una excepción sin control.

Esta es la primera lección del módulo donde el límite del Módulo 1 empieza a ceder de verdad: al final de esta lección, un RuntimeError real, provocado por el mismo stuck_script que le ganó a run_and_observe, va a dejar un rastro — todavía sin el detalle de cada paso (eso es la lección 05), pero ya con un evento que dice, sin ambigüedad, "este run, con este trace_id, falló, y esta fue la razón".

Conexión con el módulo

Esta lección construye la segunda pieza de observability/run_logger.py: make_trace_id y open_run. Ambas se completan y se extienden en la lección 05 —open_run se convierte en traced_run—, pero la lógica de correlación por trace_id que se establece aquí no vuelve a cambiar.

Analogía: el número de guía, ahora con código

La lección 01 de este módulo presentó la analogía central: un trace_id es el número de guía de un paquete, el identificador que te deja seguir un envío específico a través de todas las estaciones por las que pasa, sin que se mezcle con los miles de otros envíos que la empresa mueve al mismo tiempo. Esta lección le pone código a esa idea, y agrega un matiz que la analogía, tal como está, no cubre: una empresa de mensajería puede generar números de guía al azar sin ningún problema —nadie necesita que el número 4471 se repita nunca—. Esta guía, en cambio, tiene una necesidad que ninguna empresa de mensajería real tiene: cada ejemplo tiene que producir la misma salida, siempre, para que puedas confirmarla en tu propia máquina. Un trace_id aleatorio rompería eso — cada vez que corrieras el código, el trace_id sería distinto, y ningún "Qué esperar" de esta guía podría citar un valor fijo.

Por eso el trace_id de este módulo no es aleatorio: es un hash determinista de las entradas del run. El mismo run —la misma pregunta, el mismo número de secuencia— produce, siempre, el mismo trace_id, en tu máquina y en la mía, hoy y dentro de un año.

Ejemplo trabajado: make_trace_id, determinista de verdad

La función

import hashlib


def make_trace_id(question, sequence_number):
    """trace_id determinista: un hash de la pregunta + un número de
    secuencia lógico. NUNCA uuid4() -- mismo input, siempre el mismo
    trace_id, sin ningún estado compartido entre procesos."""
    raw = f"{question}|{sequence_number}".encode("utf-8")
    return "run-" + hashlib.sha256(raw).hexdigest()[:12]

hashlib.sha256 produce un hash de 64 caracteres hexadecimales a partir de cualquier texto — siempre el mismo hash para el mismo texto de entrada, nunca el mismo para dos textos distintos (en la práctica; una colisión real de SHA-256 nunca se ha observado). Esta función toma solo los primeros 12 caracteres de ese hash —suficiente para que las colisiones sean, en la práctica, irrelevantes para el volumen de runs de esta guía— y le agrega el prefijo "run-", solo para que sea reconocible a simple vista como un trace_id en cualquier línea de log.

Confirmando el determinismo

t1 = make_trace_id("Reserva Focus pro 3h para Ana", 1)
t2 = make_trace_id("Reserva Studio basic 2h para Luis", 2)
t1_again = make_trace_id("Reserva Focus pro 3h para Ana", 1)

print("trace_id run 1         :", t1)
print("trace_id run 2         :", t2)
print("trace_id run 1 de nuevo:", t1_again)
print("run 1 es reproducible :", t1 == t1_again)
print("run 1 y run 2 difieren:", t1 != t2)

Qué esperar:

trace_id run 1         : run-8487582448eb
trace_id run 2         : run-cc8754906a42
trace_id run 1 de nuevo: run-8487582448eb
run 1 es reproducible : True
run 1 y run 2 difieren: True

t1 y t1_again son el mismo string, calculados en dos llamadas separadas, porque las entradas —"Reserva Focus pro 3h para Ana" y 1— son idénticas. Este es el trace_id exacto que vas a ver repetirse en cada lección que queda de este módulo, cada vez que se corra el mismo run con la misma pregunta y el mismo número de secuencia — un valor fijo, citable, no un placeholder.

open_run: garantizando el cierre, incluso frente a una excepción

Con make_trace_id en su lugar, la pieza que realmente importa: un contextlib.contextmanager que abre el run (loguea run_started), y usa try/except/else para asegurar que siempre se loguee un evento de cierre —run_finished si todo salió bien, run_failed si algo lanzó una excepción— sin importar qué haya pasado adentro del with.

import itertools
from contextlib import contextmanager

_sequence = itertools.count(1)  # reemplaza el reloj real: orden lógico del stream de logs


@contextmanager
def open_run(question, sequence_number):
    """Abre un run: le asigna un trace_id determinista, loguea run_started,
    y GARANTIZA (try/except/else) que se loguee run_finished o run_failed
    al salir -- incluso si lo que corre adentro del `with` lanza."""
    trace_id = make_trace_id(question, sequence_number)
    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))

Lee el try/except/else con cuidado, porque es el mecanismo completo de esta lección: yield trace_id es el punto donde el código que está dentro del bloque with se ejecuta. Si ese código termina sin lanzar nada, la ejecución sigue por el bloque else —run_finished—. Si lanza cualquier excepción, Python la reinyecta exactamente en el punto del yield, el bloque except la captura, loguea run_failed con el tipo y el mensaje de la excepción, y —esto es crucial— la vuelve a lanzar con raise (sin argumentos, lo que relanza la excepción original tal cual, sin perder su traceback). El with nunca "traga" el error; solo se asegura de que quede un registro antes de que el error siga su curso normal.

Corriendo los dos casos: uno limpio, uno que falla

print("=== run 1: se completa normalmente ===")
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 open_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("trace_id de este run:", trace_id)

print()
print("=== run 2: se agota max_iterations y lanza RuntimeError ===")
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 open_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 del context manager: {exc}")
print("trace_id de este run:", trace_id2)

Qué esperar:

=== run 1: se completa normalmente ===
{"seq": 1, "trace_id": "run-8487582448eb", "event": "run_started", "question": "Reserva Focus pro 3h para Ana", "error": ""}
{"seq": 2, "trace_id": "run-8487582448eb", "event": "run_finished", "question": "Reserva Focus pro 3h para Ana", "error": ""}
trace_id de este run: run-8487582448eb

=== run 2: se agota max_iterations y lanza RuntimeError ===
{"seq": 3, "trace_id": "run-87cd87da52d9", "event": "run_started", "question": "Reserva algo ambiguo", "error": ""}
{"seq": 4, "trace_id": "run-87cd87da52d9", "event": "run_failed", "question": "Reserva algo ambiguo", "error": "RuntimeError: max_iterations alcanzado (2)"}
RuntimeError capturado afuera del context manager: max_iterations alcanzado (2)
trace_id de este run: run-87cd87da52d9

Compara esto con lo que viste al cierre del Módulo 1: run_and_observe("Reserva algo", stuck_script, max_iterations=2) producía cero rastro cuando el RuntimeError se disparaba — ni un RunReport, ni una línea de log. Aquí, el mismo tipo de fallo produce dos líneas de JSON reales: run_started en seq=3, y run_failed en seq=4, con el mensaje exacto de la excepción ("RuntimeError: max_iterations alcanzado (2)") y el trace_id correcto. El RuntimeError sigue propagándose —open_run nunca lo oculta—, pero ya no se lleva toda la información con él.

Esto todavía no es la solución completa: fíjate que el run 2 no dejó ningún registro de que list_rooms sí se llegó a ejecutar dos veces antes de que el tope de iteraciones lo detuviera — solo sabes que el run empezó y que falló, no qué pasó en el medio. Esa pieza —el detalle de cada paso, incluso los que corrieron antes del fallo— es exactamente el trabajo de la lección 05.

Por qué un contador simple no alcanza

Vale la pena confirmar, con código, por qué la alternativa más obvia a un hash —un contador simple, itertools.count(1)— no resuelve el mismo problema en un sistema real con más de un proceso.

counter_proc1 = itertools.count(1)
counter_proc2 = itertools.count(1)
print("proceso 1, primer run:", next(counter_proc1))
print("proceso 2, primer run:", next(counter_proc2))

proceso 1, primer run: 1
proceso 2, primer run: 1

Dos contadores independientes —que representan dos procesos de Python corriendo al mismo tiempo, algo perfectamente normal en un sistema real con varios workers atendiendo solicitudes— producen, cada uno, el mismo primer valor: 1. Sin coordinación externa (una base de datos compartida, un servicio de asignación de ids), un trace_id basado en un contador local colisiona entre procesos. Un hash de las entradas del run no tiene ese problema exacto —dos preguntas distintas producen hashes distintos—, aunque sí depende de que el par (question, sequence_number) sea único para cada run real; la lección construye esa unicidad con cuidado en los ejercicios.

Una ventaja adicional del hash que el contador no tiene: es reproducible bajo demanda. Si necesitas volver a calcular el trace_id de un reintento —el mismo run, corrido de nuevo tras un fallo transitorio—, un hash con las mismas entradas da el mismo resultado sin necesitar ningún estado compartido:

print("intento 1 de un reintento:", make_trace_id("Reserva Focus pro 3h para Ana", 7))
print("intento 2 del MISMO reintento:", make_trace_id("Reserva Focus pro 3h para Ana", 7))

intento 1 de un reintento: run-8663a55cce87
intento 2 del MISMO reintento: run-8663a55cce87

Nota de honestidad, explícita: en un sistema real de producción, la forma más común de obtener un trace_id no es ninguna de las dos anteriores — normalmente lo asigna el sistema que originó la solicitud (un request-id de un API gateway, o un uuid4() generado una sola vez al recibir la petición, que sí es aleatorio en ese contexto, porque ahí la reproducibilidad no es un requisito). Esta guía usa un hash determinista específicamente porque necesita que sus ejemplos impresos sean reproducibles byte a byte — es una simplificación pedagógica declarada, no una recomendación de que el hash de (pregunta, número de secuencia) sea el mejor esquema de trace_id para cualquier sistema real.

Errores comunes

1. Usar raise exc en vez de raise dentro del except. Ambos vuelven a lanzar la excepción, pero raise exc reconstruye parcialmente el traceback, perdiendo el punto exacto donde ocurrió originalmente el error — mucho más difícil de depurar. raise sin argumentos, dentro de un bloque except, siempre relanza la excepción activa con su traceback original intacto.

2. Olvidar el else y poner el log_event de run_finished después del try/except en vez de dentro del else. Sin el else, ese log se ejecutaría incluso cuando el except capturó y relanzó una excepción —porque el código después de un bloque try/except sí corre, salvo que el except termine con raise o return—; en este caso específico no causaría un bug visible porque el except sí tiene raise, pero es una fuente de errores sutiles si alguien modifica el flujo más adelante sin notar la dependencia.

3. Calcular el trace_id solo con la pregunta, sin el número de secuencia. El Ejercicio 3 de esta lección confirma, ejecutado, que dos runs con la misma pregunta producen el mismo trace_id sin el número de secuencia — una colisión real que rompería toda correlación entre runs distintos que, por coincidencia, comparten la misma pregunta (como los dos intentos de reservar "Focus pro 3h para Ana" que aparecen varias veces en esta guía).

4. Pensar que open_run ya resuelve todo el problema del Módulo 1. Como se nota arriba, open_run deja un registro de que el run empezó y de cómo terminó (bien o mal) — pero no todavía del detalle de cada paso intermedio. Confundir esto con la solución completa es adelantarse a la lección 05.

5. Reusar el mismo número de secuencia para dos preguntas distintas, esperando trace_ids distintos por la diferencia en question. Es cierto que funciona —make_trace_id sí produce ids distintos si question difiere—, pero mezclar la fuente de unicidad (a veces la pregunta, a veces el número) hace que el esquema completo sea más difícil de razonar. La convención de esta guía, desde aquí en adelante, es que sequence_number es siempre el índice del run dentro de un lote — la fuente principal y confiable de unicidad.

Ejercicios

Ejercicio 1: Confirma que dos runs con la misma pregunta y distinto número de secuencia no colisionan (Fácil)

Genera trace_ids para tres runs, todos con la pregunta "Reserva Focus pro 3h para Ana" pero con sequence_number 1, 2 y 3. Confirma que los tres trace_id son distintos entre sí.

ids = [make_trace_id("Reserva Focus pro 3h para Ana", n) for n in [1, 2, 3]]
for n, tid in zip([1, 2, 3], ids):
    print(f"sequence_number={n}: {tid}")
print("los tres son distintos:", len(set(ids)) == 3)

sequence_number=1: run-8487582448eb
sequence_number=2: run-08de67885d70
sequence_number=3: run-b8248189b0d1

Ejercicio 2: Simula la colisión de dos procesos con contador (Medio)

Simula tres "procesos" (tres objetos itertools.count(1) independientes) atendiendo el primer run que les llega cada uno. Imprime el primer valor de cada uno y confirma que los tres colisionan en 1. Después, muestra que usando make_trace_id con una pregunta distinta para cada "proceso" (simulando que cada uno recibió una solicitud distinta) no colisiona.

counters = [itertools.count(1) for _ in range(3)]
counter_ids = [next(c) for c in counters]
print("ids por contador (colisionan):", counter_ids)

questions = ["Reserva Focus pro 3h para Ana", "¿Cuánto cuesta Studio basic 2h?", "Cancela la reserva 5"]
hash_ids = [make_trace_id(q, 1) for q in questions]
print("ids por hash (no colisionan):", hash_ids)
print("todos distintos:", len(set(hash_ids)) == 3)

ids por contador (colisionan): [1, 1, 1]
ids por hash (no colisionan): ['run-8487582448eb', 'run-e6d379c8d5c4', 'run-9df310ffbfd5']

Ejercicio 3: Provoca la colisión de omitir sequence_number (Difícil)

Escribe una versión "rota" de make_trace_id que solo use question (sin sequence_number). Genera el trace_id de dos runs distintos que, por coincidencia, comparten la misma pregunta ("Reserva Focus pro 3h para Ana" — la misma tarea que aparece más de una vez a lo largo de esta guía, con distintos guiones de turnos). Confirma que la versión rota los mezcla en un solo trace_id, y que la versión correcta (con sequence_number) los distingue.

def make_trace_id_broken(question):
    raw = question.encode("utf-8")
    return "run-" + hashlib.sha256(raw).hexdigest()[:12]

q = "Reserva Focus pro 3h para Ana"
print("=== version ROTA: dos runs distintos, mismo trace_id ===")
print("run A (roto):", make_trace_id_broken(q))
print("run B (roto):", make_trace_id_broken(q))
print("son el mismo id aunque son runs distintos:", make_trace_id_broken(q) == make_trace_id_broken(q))

print()
print("=== version CORRECTA: con sequence_number, cada run es distinguible ===")
print("run A:", make_trace_id(q, 1))
print("run B:", make_trace_id(q, 2))

=== version ROTA: dos runs distintos, mismo trace_id ===
run A (roto): run-4139827c3210
run B (roto): run-4139827c3210
son el mismo id aunque son runs distintos: True

=== version CORRECTA: con sequence_number, cada run es distinguible ===
run A: run-8487582448eb
run B: run-08de67885d70

Resumen y siguiente paso

• Construimos make_trace_id: un hash determinista de (question, sequence_number), nunca uuid4() — el mismo run produce, siempre, el mismo trace_id.
• Construimos open_run, un contextlib.contextmanager que abre un run y garantiza —con try/except/else— un evento de cierre (run_finished o run_failed) sin importar qué pase adentro del with.
• Confirmamos, ejecutado, que el mismo RuntimeError que dejaba cero rastro en el Módulo 1 ahora produce dos líneas de JSON reales: el run empezó, y el run falló, con su trace_id correcto y el mensaje exacto de la excepción.
• Confirmamos, ejecutado, por qué un contador simple colisiona entre procesos, y por qué un hash determinista no tiene ese problema — con la honestidad explícita de que, en producción real, un trace_id casi siempre lo asigna el sistema que originó la solicitud.

Siguiente lección: 05 — Logueando cada paso del loop. Cerramos, con código ejecutado, el límite exacto del Módulo 1: instrumentamos dispatch_robust desde afuera, sin tocar su archivo, para que cada tool_use y tool_result quede registrado en el instante en que ocurre — incluidos los pasos que sí corrieron antes de que un run entero fallara.

Recursos adicionales

1. Python — hashlib — sha256 y el resto de las funciones hash de la librería estándar, la base de make_trace_id.
2. Python — contextlib — @contextmanager, y el patrón try/except/else/finally dentro de un generador, la base completa de open_run.
3. Python — itertools.count — El contador infinito que reemplaza al reloj real para el campo seq de cada evento.
4. RFC 4122 — UUID — La especificación del identificador aleatorio que esta guía prohíbe en sus ejemplos, precisamente por su falta de reproducibilidad.
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.