Module 2: Structured Logging and Tracing a Run

Description

Module 1 closed with a concrete warning, not a vague promise. In its last lesson, run_and_observe — this guide's first instrumentation wrapper — measured four complete signals over a batch of real runs: steps, tool calls, errors, cost, latency. It worked fine, until it was given a script that exhausts max_iterations. In that case, run_reservo_agent raises a RuntimeError, the exception propagates before run_and_observe can build a single RunReport, and everything that run did — every tool that did get to run, every result that did get produced — disappears with it. Not a print, not a RunReport, not a trace. Lesson 08 of that module said it with precision: "Truly solving this — recording every step as it happens, not at the end — is, precisely, the problem Module 2 builds from its first lesson."

This module solves exactly that. Not with a trick or a rewrite of reservo_agent.py — this guide never touches that logic, in any module — but with two ideas that, together, completely change what can be known about a run: structured logging (each event as a complete, parseable JSON line, with fixed fields) and a trace_id that correlates each of those events with the exact run it belongs to, end to end, even when that run ends badly. By the end of lesson 05 — the halfway point of the module — you're going to see, running for real, the same script that beat run_and_observe in Module 1: a real RuntimeError, and this time, a complete trail of what happened before everything came crashing down.

Hard rule for this guide (inherited, unchanged)

Module 1's hard rule stays exactly the same: the model's decision is never executed. When a lesson says "the model (claude-sonnet-5, concept) requested get_quote," that's still a hand-written turn script. What this module adds is a layer of honesty of its own, because the topic now is how what happens gets recorded, and recording it wrong is as dangerous as not recording it at all:

Structured logging really does run, for real, with the standard library's logging plus a custom JSON formatter. Every line you'll see in a "What to expect" block in this module is the real output of having run that code — never a hand-made example.
The trace_id is always deterministic. Never uuid4(), never any other source of randomness. Lesson 04 builds one with a hash of the run's inputs — the question and a logical sequence number — precisely so the same run always produces the same trace_id, on your machine and on mine.
No real clock in the data. No datetime.now(), no time.time(). When an event needs something like a timestamp to be ordered, this module uses a logical sequence counter (seq, an integer that increments by one for each event generated) — never the real wall-clock time. This is a deliberate simplification, and every lesson that uses it says so explicitly: in real production, every log line carries a real timestamp (logging's %(asctime)s, or an explicit datetime.utcnow().isoformat()); here it's omitted so every example's output is reproducible, line by line, no matter what time of day you run it.
Cost and latency still aren't this module's topic. You'll see both logged as fields inside some events — when it applies — but their full calculation, their aggregation over batches, their percentiles: that's Module 3 (cost) and Module 4 (latency). Here the job is to record, not to measure.

Hold onto this sentence, because you'll use it in every lesson that follows: an event with no trace_id is noise; a trace_id with no event at every step of the loop is a broken promise. This module builds both pieces together, because neither one, on its own, solves the problem Module 1 left open.

Where we are in the ecosystem

Agents in production — operating the Reservo agent
├── Module 1: Why Operating Is Different From Building
├── Module 2: Structured Logging and Tracing a Run  ← YOU ARE HERE
│   → Structured JSON, a deterministic trace_id, every step
│     of the loop recorded as it happens, a real RUN_LOG.jsonl
├── Module 3: Measuring Cost and Tokens per Run
├── Module 4: Measuring Latency Honestly
├── Module 5: Regression Evals as a Production Gate
├── Module 6: Failures at Scale — Backoff, Circuit Breakers, and Rate Limits
├── Module 7: Versioning and Safe Rollout
└── Module 8: Project — the Reservo Agent in Production

This is the first of the seven modules that build, one by one, the four disciplines Module 1 named: observe → measure → gate → harden+version. That lesson 01's diagram was explicit about the order: you can't measure meaningfully what you can't observe first. This module is the observe layer — the foundation the remaining six modules stand on. observability/run_logger.py, the artifact you'll build lesson by lesson, gets reused unchanged from Module 3 onward: every time a future lesson says "we log this event," it's going to be using literally the same traced_run that finishes taking shape in this module's lesson 06.

This module's central analogy: a package's tracking number

When you ship a package through a courier company, you get a tracking number. That number doesn't move the package — it does nothing physical — but it does something just as important: it lets you follow that particular package, and only that one, through every station it passes through — the origin distribution center, the truck, the airport, customs, the destination distribution center, the final courier — even though the company is moving, at the same time, thousands of other packages through those same stations. Without that number, each station still records something — "a package arrived," "a package left" — but those records, all mixed together, tell you nothing about your particular package. With the number, you filter: you ask the system "show me only the events with this tracking number," and what it hands back is the complete story of one shipment, with no other shipment mixed in.

A trace_id is exactly that number, applied to a Reservo agent run instead of a box. Every step of the loop — every tool_use, every tool_result, the start and end of the run itself — is a "station" that run passes through, and each one leaves a record. If ten users ask Reservo for something in the same minute — ten runs, one after another, or even interleaved in a real system handling several requests at once — their events are going to end up in the same place: the same log file, the same terminal output. Without a trace_id on every line, those ten runs blend into one indistinguishable stream. With a deterministic trace_id on every line, you can ask the system — with a simple filter, as you're going to do in lesson 07 — "show me only this run's events," and reconstruct, start to finish, exactly what happened, with no other run slipping in between.

The difference between a tracking number and this module's trace_id is a single one, and it's what the hard rule above already hinted at: a courier company can afford to generate tracking numbers at random — nobody needs to reproduce the same number twice. This guide can't: every example has to produce, always, the same output, so you can confirm it on your own machine byte for byte. That's why this module's trace_id is never random — it's a deterministic hash of the run's inputs, built in lesson 04.

What Module 1 couldn't solve, and this module does

It's worth being precise about the exact limit that gets closed here, because it isn't an abstract limit — you saw it run, with your own eyes, in Module 1's last lesson:

stuck_script = [...]  # tres tool_use de list_rooms, sin end_turn
try:
    final, report = run_and_observe("Reserva algo", stuck_script, max_iterations=2)
except RuntimeError as exc:
    print("RuntimeError capturado en run_and_observe:", exc)

RuntimeError capturado en run_and_observe: max_iterations alcanzado (2)

Not a RunReport, not a single logging.info, no trace of the attempt at all. The cause isn't a bug in run_and_observe — it's a design decision that any wrapper that only measures "at the end" automatically inherits: all the counting logic lives after the call that can fail, so if that call fails before returning anything, there's nothing left to count.

This module changes the point where recording happens: instead of waiting for run_reservo_agent to finish (well or badly) and only then looking back, this module instruments the exact point every tool call passes through — before the possibility even exists for the entire run to crash — and leaves a trail the instant each event happens. By the time you reach lesson 05, you're going to run that same stuck_script from above, with the same trap (max_iterations=2), and instead of "no trace of the attempt at all," you're going to have a file with the exact lines for the two steps that did get to run, before the third one triggered the RuntimeError. That is, precisely, the difference between "measuring at the end" and "observing as it happens" — and it's this module's whole argument, resolved with real code.

The case that keeps accompanying the guide: Reservo, without rebuilding anything

The four tools are the same as always — list_rooms(), get_quote(room, tier, hours), book_room(room, tier, hours, member), cancel_booking(id) — and the two price anchors remain intact: Focus basic 3h = 7500 cents, Focus pro 3h = 6000 cents (20% pro discount, * 80 // 100, integer arithmetic). This module doesn't declare a single new tool or a new business case — it reuses, without touching a line, reservo_tools.py, reservo_contracts.py, reservo_robust.py, and reservo_agent.py, exactly as they stood in agent-fundamentals-and-tool-calling-guide M8.

What's new in this module is an artifact that lives around those files, never inside them: observability/run_logger.py. It gets built in layers, one per lesson:

Lesson 03 puts together the JSON formatter and the first two event dataclasses (RunEvent, for the whole-run level).
Lesson 04 adds make_trace_id (deterministic) and open_run, a contextlib.contextmanager that opens and closes a run with its trace_id.
Lesson 05 is where the interesting part happens: it adds ToolCallEvent and an instrumentation technique — wrapping reservo_robust.dispatch_robust from outside, without editing its file — so that every tool_use/tool_result gets recorded the exact instant it happens.
Lesson 06 completes the severity levels (INFO, ERROR, DEBUG, and when to use each) and two layers of detail: a lightweight operational view and a complete view for deep debugging.
Lessons 07-08 persist all of this to a real file, RUN_LOG.jsonl, and read it back to reconstruct a run — or a whole batch of runs — from its logs.

As in every module of this guide: identifiers and code in English; prose and comments in Spanish; money, whenever it appears, in int cents.

Prerequisites

Required knowledge:

✅ Having completed Module 1 of this guide, especially lessons 03 (what you cannot see without instrumentation) and 08 (run_and_observe's limit). This module assumes you already saw that limit run, and solves it directly.
✅ Having completed (or knowing well) agent-fundamentals-and-tool-calling-guide M8: run_reservo_agent(question, model_script, max_iterations=10, summarize=None)'s signature, history's format (user/assistant turns, tool_use/tool_result/text blocks), and that dispatch_robust never lets an uncontrolled exception through — it always returns a tool_result, with is_error: True when something went wrong.
✅ Python: functions, dictionaries, try/except/finally, a basic grasp of decorators (a function that wraps another and adds behavior to it). This module uses the standard library's contextlib.contextmanager, dataclasses, and logging — if you don't know them in depth, that's fine: each one gets explained the first time it appears.

NOT required:

❌ You don't need an API key or an internet connection: the model's decision is still concept, and all of this module's logging runs 100% locally, over files on your own disk.
❌ You don't need to know an infrastructure observability stack (Datadog, LangSmith, Sentry, Prometheus). This module builds, by hand, the mechanism those products wrap — so you understand exactly what they do before you delegate it to one.
❌ You don't need to know anything about SRE, SLI/SLO, or an incident's lifecycle: that belongs to sre-and-incident-response-guide, a neighboring guide that operates infrastructure, not the agent. This module logs one application, not a distributed system.

Environment:

✅ Python 3.14.0 with its standard library (logging, json, dataclasses, contextlib, hashlib, itertools). Nothing to install.
✅ A text editor and a terminal. You're going to create at least one real file (RUN_LOG.jsonl) on your disk starting in lesson 07.

Module roadmap

Lesson 01 — Module introduction (this one)

Module 1's exact limit that this module solves, the tracking-number analogy, and the map of the eight lessons.

Lesson 02 — `print` is not logging

Why the most obvious tool for "seeing what's happening" is precisely the one that fails in every way that's going to matter: it has no level, no structure, can't be filtered, and mixes in with the program's real output.

Lesson 03 — Structured logs as JSON

A custom formatter on top of logging that turns every event into a complete, parseable JSON line — the first block of run_logger.py, tested with simple events before touching the agent.

Lesson 04 — The `trace_id`: correlating a run

A deterministic identifier — never uuid4() — that follows a run end to end, and a contextlib.contextmanager (open_run) that guarantees a closing event even when the run ends in an exception.

Lesson 05 — Logging each step of the loop

The module's central lesson: instrumenting dispatch_robust from outside — without touching its code — so every tool_use and tool_result gets recorded the instant it happens. Here, with real executed code, Module 1's limit closes.

Lesson 06 — Log levels and what to capture

INFO for the steps, ERROR for tool failures, DEBUG for the full detail — and why mixing all three into a single level is as bad as having none.

Lesson 07 — Reading a trace back

Persisting RUN_LOG.jsonl to disk for real, and reconstructing — from its lines, and only from them — exactly what happened to a run, without having watched it happen.

Lesson 08 — Mini-project: a traced Reservo run

A batch of Reservo runs — including one that fails on purpose — run with the module's complete instrumentation, with a real RUN_LOG.jsonl as the deliverable, and a report reconstructed 100% from that file.

Progression map

Lesson 01 (this)  → Module 1's limit, the tracking-number analogy
Lesson 02         → Why print() falls short
Lesson 03         → Structured JSON, one line per event
Lesson 04         → Deterministic trace_id + opening/closing a run
Lesson 05         → Every tool_use/tool_result, the instant it happens
Lesson 06         → INFO/ERROR/DEBUG: what to capture at each level
Lesson 07         → A real RUN_LOG.jsonl, read and reconstructed
Lesson 08         → Mini-project: a traced batch, with one run that fails

Difficulty: ⭐⭐ ──────────────────▶ ⭐⭐⭐

What you'll achieve in this module

By completing the 8 lessons, you'll be able to:

Explain, with run examples, why print() is not an observability tool — and exactly what it's missing (level, structure, filtering, separation from real output).
Build a custom JSON formatter on top of logging, with dataclasses for the events, so every log line is a complete, parseable JSON object.
Generate a deterministic trace_id — with a hash of the run's inputs, never uuid4() — and explain why the obvious alternative (a simple counter) falls short in a system with more than one process.
Instrument an already-built agent's loop without touching its code, wrapping the dispatch function from outside to capture every step the instant it happens — including the steps that did run before the whole run failed.
Choose the correct severity level for each type of event (INFO, ERROR, DEBUG) and explain what's lost when it's chosen wrong.
Read a RUN_LOG.jsonl file back and reconstruct, using only its lines, what happened to a specific run — completed, failed, or in progress.

Before and after

BEFORE the module:
→ "print() already lets me see what's happening, why complicate it"
→ "if the run fails, there's nothing that can be done to save
  the information from the steps that did happen"
→ "a run id is a run id, any one will do"
→ "logging is a library for printing with extra steps"

AFTER the module:
→ print() has no level, no structure, and mixes in with the
  real output -- each of those three things matters
→ instrumenting the DISPATCH POINT, not the run's end, is what
  lets you capture steps even when the whole run fails
→ a deterministic trace_id correlates thousands of concurrent
  runs without any of them blending into another -- and it's
  reproducible, not random, because this guide needs it to be
→ logging gives you level, structure, and stream separation --
  three capabilities print() never had

Traps to avoid in this module

1. "This module is going to modify `reservo_agent.py` to log better"

No. Not a single line of reservo_tools.py, reservo_contracts.py, reservo_robust.py, or reservo_agent.py changes in this module, nor in any of the ones that remain. Lesson 05 shows, with precision, how to instrument the exact tool-dispatch point from outside, without editing the file that defines it — that is, in fact, this whole module's central skill.

2. "A `trace_id` is just any old id, no need to think about it"

Lesson 04 shows, with real execution, why a simple counter (itertools.count(1)) fails as soon as more than one process is running the system at the same time — two processes, each with its own counter, produce the same first id. A deterministic hash of the run's inputs doesn't have that problem, and it's reproducible too: the same run, run again, produces the same trace_id — useful for correlating a retry with the original attempt.

3. "DEBUG is just INFO with more noise"

It's not a matter of quantity, it's a matter of audience. INFO is the signal you need to know, at a glance, that the system is working — who called what, and whether it went well. DEBUG is the signal you need when you already know something went wrong and need the full detail to understand why. Lesson 06 builds both layers, deliberately separate, so you can raise the detail level without changing a single line of code — only the logger's configuration.

4. "If `dispatch_robust` never raises an exception, there's no need to log its errors"

Confusing "never raises" with "never fails" is a real mistake, and agent-fundamentals M8 already warned about it. dispatch_robust returns is_error: True perfectly normally in the face of invalid input or a nonexistent resource — and that error-carrying tool_result is exactly the kind of event this module makes sure does get recorded, at ERROR level, so a real system can alert on it.

5. "Structured JSON is just `print(json.dumps(...))` with extra steps"

It's closer to the truth than it looks — in fact, json.dumps is literally what builds each line — but what logging adds on top isn't cosmetic: a severity level (so you can filter without deleting code), a per-logger namespace (so you can silence one part of the system without silencing everything), and handlers independent of the program's stdout (so you can separate the real output of the operation from the logging). Lesson 02 demonstrates all three, run for real, before lesson 03 builds the format.

How to work through this module

Run every example yourself, and look at the file it produces. Starting in lesson 07, several examples write a real RUN_LOG.jsonl to your disk. Open it with a text editor after running the code — seeing a real JSON line, generated by your own machine, is worth more than reading it on this page.
Don't confuse "deterministic" with "arbitrary." When a lesson says the trace_id is deterministic, it doesn't mean the value doesn't matter — it means it depends exclusively on the run's inputs (the question, a sequence number), never on the clock or a random source.
The mini-project (lesson 08) is the final test. There you're going to run a batch of runs — including one that fails on purpose — and reconstruct, from the log file and only from it, exactly what happened to each one. If anything from the previous seven lessons didn't land, it's going to show there.

Estimated time:

Lesson 01 (this)  →  20 min reading
Lesson 02         →  20 min + running the example
Lesson 03         →  25 min + running the example
Lesson 04         →  25 min + running the example
Lesson 05         →  35 min + running the example (the central lesson)
Lesson 06         →  25 min + running the example
Lesson 07         →  30 min + generating and reading your own RUN_LOG.jsonl
Lesson 08         →  40 min + building the complete mini-project

Total: ~3.5 hours

Evidence of success

Before moving on to Module 3 (Measuring Cost and Tokens per Run), you should be able to:

✅ Explain, with a run example, at least three concrete ways print() falls short as an observability tool.
✅ Build a structured JSON log line, with logging + dataclasses, and parse it back with json.loads.
✅ Generate a deterministic trace_id for a run, and explain why it isn't uuid4().
✅ Instrument run_reservo_agent's tool dispatch from outside, without touching its code, and confirm — by running it — that a run failing with RuntimeError still leaves a trail of the steps that did run.
✅ Choose the correct severity level (INFO/ERROR/DEBUG) for a new event, and justify the choice.
✅ Read a real RUN_LOG.jsonl file and reconstruct, using only its lines, the complete story of a specific run by its trace_id.

Summary

This module solves, with real executed code, the exact limit Module 1 left open in its last lesson: a run that fails with RuntimeError stops losing all its information, because this module records every step as it happens, not at the end.
The central piece is twofold: structured logging (every event, a complete, parseable JSON line) and a deterministic trace_id (never uuid4()) that correlates every event of a run, even in the middle of thousands of concurrent runs — the package-tracking-number analogy.
The artifact built, lesson by lesson, is observability/run_logger.py — reused unchanged from Module 3 onward.
Lesson 05's central technique — wrapping dispatch_robust from outside, without touching its file — is what makes it possible to capture every step of the loop without rebuilding a single line of the agent agent-fundamentals already delivered.

Next lesson: 02 — print Is Not Logging. Before building anything new, we confirm — with real executed code — exactly what's missing from the tool you've probably already used to "see what's happening" in a Python program.

Additional resources

Python — logging — The complete library this module develops in depth, lesson by lesson, starting with its fundamentals in lesson 02.
Python — dataclasses — RunEvent and ToolCallEvent, the structures that represent each event before it turns into a JSON line.
Python — contextlib — contextmanager, the tool behind open_run (lesson 04) and traced_run (lesson 05), which guarantees a correct close even in the face of an exception.
Anthropic — Building effective agents — On why an agent's observability is a discipline of its own, not a luxury added at the end.
Python 3.14 — What's New — The exact version every line of code in this module runs on.

← PreviousMini-Project: Wrap a Run and See Inside Next →`print` Is Not Logging