The `trace_id`: Correlating a Run

Description

Lesson 03 left RunEvent with a trace_id field, but filled it by hand — "run-demo", written literally in the code. This lesson builds the missing piece: a function that generates a real trace_id, a different one for each run, always the same for the same run — deterministic, never random. With that piece in place, the second half of the lesson builds open_run, a contextlib.contextmanager that opens a run with its trace_id, and — this is what really matters — guarantees that a closing event gets recorded, even when whatever runs inside the with ends in an uncontrolled exception.

This is the first lesson in the module where Module 1's limit really starts to give way: by the end of this lesson, a real RuntimeError, triggered by the same stuck_script that beat run_and_observe, is going to leave a trail — still without each step's detail (that's lesson 05), but already with an event that says, unambiguously, "this run, with this trace_id, failed, and this was the reason."

Connection to the module

This lesson builds observability/run_logger.py's second piece: make_trace_id and open_run. Both get completed and extended in lesson 05 — open_run becomes traced_run — but the trace_id-based correlation logic established here doesn't change again.

Analogy: the tracking number, now with code

This module's lesson 01 introduced the central analogy: a trace_id is a package's tracking number, the identifier that lets you follow one specific shipment through every station it passes through, without it blending into the thousands of other shipments the company is moving at the same time. This lesson puts code to that idea, and adds a nuance the analogy, as it stands, doesn't cover: a courier company can generate tracking numbers at random with no problem at all — nobody needs number 4471 to never repeat. This guide, on the other hand, has a need no real courier company has: every example has to produce the same output, always, so you can confirm it on your own machine. A random trace_id would break that — every time you ran the code, the trace_id would be different, and no "What to expect" in this guide could cite a fixed value.

That's why this module's trace_id isn't random: it's a deterministic hash of the run's inputs. The same run — the same question, the same sequence number — always produces the same trace_id, on your machine and on mine, today and a year from now.

Worked example: make_trace_id, truly deterministic

The function

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 produces a 64-character hexadecimal hash from any text — always the same hash for the same input text, never the same for two different texts (in practice; a real SHA-256 collision has never been observed). This function takes only the first 12 characters of that hash — enough for collisions to be, in practice, irrelevant at this guide's run volume — and prepends the "run-" prefix, just so it's recognizable at a glance as a trace_id in any log line.

Confirming determinism

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)

What to expect:

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 and t1_again are the same string, calculated in two separate calls, because their inputs — "Reserva Focus pro 3h para Ana" and 1 — are identical. This is the exact trace_id you're going to see repeat throughout every lesson remaining in this module, every time the same run is run with the same question and the same sequence number — a fixed, citable value, not a placeholder.

open_run: guaranteeing the close, even in the face of an exception

With make_trace_id in place, the piece that really matters: a contextlib.contextmanager that opens the run (logs run_started), and uses try/except/else to ensure a closing event always gets logged — run_finished if everything went well, run_failed if something raised an exception — no matter what happened inside the 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))

Read the try/except/else carefully, because it's this lesson's whole mechanism: yield trace_id is the point where the code inside the with block runs. If that code finishes without raising anything, execution continues into the else block — run_finished. If it raises any exception, Python re-injects it right at the yield point, the except block catches it, logs run_failed with the exception's type and message, and — this is crucial — re-raises it with raise (with no arguments, which re-raises the original exception exactly as it was, without losing its traceback). The with never "swallows" the error; it only makes sure a record is left before the error continues on its normal course.

Running both cases: one clean, one that fails

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)

What to expect:

=== 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

Compare this with what you saw at Module 1's close: run_and_observe("Reserva algo", stuck_script, max_iterations=2) produced zero trace when the RuntimeError fired — not a RunReport, not a log line. Here, that same kind of failure produces two real JSON lines: run_started at seq=3, and run_failed at seq=4, with the exception's exact message ("RuntimeError: max_iterations alcanzado (2)") and the correct trace_id. The RuntimeError still propagates — open_run never hides it — but it no longer carries all the information away with it.

This still is not the complete solution: notice run 2 left no record that list_rooms did get called twice before the iteration cap stopped it — you only know the run started and that it failed, not what happened in between. That piece — every step's detail, including the ones that ran before the failure — is exactly lesson 05's job.

Why a simple counter isn't enough

It's worth confirming, with code, why the most obvious alternative to a hash — a simple counter, itertools.count(1) — doesn't solve the same problem in a real system with more than one process.

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

Two independent counters — representing two Python processes running at the same time, perfectly normal in a real system with several workers handling requests — each produce the same first value: 1. Without external coordination (a shared database, an id-assignment service), a trace_id based on a local counter collides between processes. A hash of the run's inputs doesn't have that exact problem — two different questions produce different hashes — although it does depend on the (question, sequence_number) pair being unique for every real run; the lesson builds that uniqueness carefully in the exercises.

An extra advantage the hash has that the counter doesn't: it's reproducible on demand. If you need to recalculate a retry's trace_id — the same run, run again after a transient failure — a hash with the same inputs gives the same result with no shared state needed:

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

Honesty note, explicit: in a real production system, the most common way to get a trace_id is neither of the above two — it's usually assigned by the system that originated the request (an API gateway's request-id, or a uuid4() generated once when the request comes in, which is random in that context, because reproducibility isn't a requirement there). This guide uses a deterministic hash specifically because it needs its printed examples to be byte-for-byte reproducible — it's a declared pedagogical simplification, not a recommendation that hashing (question, sequence_number) is the best trace_id scheme for any real system.

Common mistakes

1. Using raise exc instead of raise inside the except. Both re-raise the exception, but raise exc partially rebuilds the traceback, losing the exact point where the error originally happened — much harder to debug. raise with no arguments, inside an except block, always re-raises the active exception with its original traceback intact.

2. Forgetting the else and putting run_finished's log_event after the try/except instead of inside the else. Without the else, that log would run even when the except caught and re-raised an exception — because the code after a try/except block does run, unless the except ends with raise or return; in this specific case it wouldn't cause a visible bug because the except does have raise, but it's a source of subtle bugs if someone modifies the flow later without noticing the dependency.

3. Calculating the trace_id with only the question, without the sequence number. This lesson's Exercise 3 confirms, with real execution, that two runs with the same question produce the same trace_id without the sequence number — a real collision that would break all correlation between different runs that, by coincidence, share the same question (like the two attempts to book "Focus pro 3h for Ana" that show up several times in this guide).

4. Thinking open_run already solves the whole Module 1 problem. As noted above, open_run leaves a record that the run started and how it ended (well or badly) — but not yet each intermediate step's detail. Confusing this with the complete solution is jumping ahead to lesson 05.

5. Reusing the same sequence number for two different questions, expecting different trace_ids from the difference in question. It's true it works — make_trace_id does produce different ids if question differs — but mixing the source of uniqueness (sometimes the question, sometimes the number) makes the whole scheme harder to reason about. This guide's convention, from here on, is that sequence_number is always the run's index within a batch — the primary, reliable source of uniqueness.

Exercises

Exercise 1: Confirm two runs with the same question and different sequence numbers don't collide (Easy)

Generate trace_ids for three runs, all with the question "Reserva Focus pro 3h para Ana" but with sequence_number 1, 2, and 3. Confirm all three trace_ids are different from each other.

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

Exercise 2: Simulate two processes colliding with a counter (Medium)

Simulate three "processes" (three independent itertools.count(1) objects) each handling the first run that comes to them. Print each one's first value and confirm all three collide at 1. Then, show that using make_trace_id with a different question for each "process" (simulating each one receiving a different request) doesn't collide.

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

Exercise 3: Trigger the collision from omitting sequence_number (Hard)

Write a "broken" version of make_trace_id that only uses question (without sequence_number). Generate the trace_id for two different runs that, by coincidence, share the same question ("Reserva Focus pro 3h para Ana" — the same task that appears more than once throughout this guide, with different turn scripts). Confirm the broken version merges them into a single trace_id, and that the correct version (with sequence_number) tells them apart.

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

Summary and next step

• We built make_trace_id: a deterministic hash of (question, sequence_number), never uuid4() — the same run always produces the same trace_id.
• We built open_run, a contextlib.contextmanager that opens a run and guarantees — with try/except/else — a closing event (run_finished or run_failed) no matter what happens inside the with.
• We confirmed, with real execution, that the same RuntimeError that left zero trace in Module 1 now produces two real JSON lines: the run started, and the run failed, with its correct trace_id and the exception's exact message.
• We confirmed, with real execution, why a simple counter collides between processes, and why a deterministic hash doesn't have that problem — with the explicit honesty that, in real production, a trace_id is almost always assigned by the system that originated the request.

Next lesson: 05 — Logging Each Step of the Loop. We close, with real executed code, Module 1's exact limit: we instrument dispatch_robust from outside, without touching its file, so every tool_use and tool_result gets recorded the instant it happens — including the steps that did run before an entire run failed.

Additional resources

1. Python — hashlib — sha256 and the rest of the standard library's hash functions, the foundation of make_trace_id.
2. Python — contextlib — @contextmanager, and the try/except/else/finally pattern inside a generator, the complete foundation of open_run.
3. Python — itertools.count — The infinite counter that replaces the real clock for every event's seq field.
4. RFC 4122 — UUID — The specification for the random identifier this guide prohibits in its examples, precisely because of its lack of reproducibility.
5. Python 3.14 — What's New — The version every line of code in this lesson ran on.