Log Levels and What to Capture

Description

traced_run, as it stood at the end of lesson 05, already logs every step — but it does it all at the same level of detail: every tool_use carries its full arguments, every tool_result its full content, always. That's fine for following one of this guide's examples, but in a real system, with thousands of runs per hour, that amount of detail on every line is noise: an operational dashboard doesn't need to see every get_quote's full input to know the system is working — it needs to know, at a glance, which tool was called and whether it went well. The full detail is needed only when something is already known to have gone wrong, and you need to understand why.

This lesson resolves that tension with the tool logging already gave you back in lesson 02: severity levels. Instead of a single "all or nothing" view, this lesson splits every step into two layers — a lightweight operational view at INFO/ERROR, and a complete debugging view at DEBUG — and adds a third signal, at WARNING level, for a case neither INFO nor ERROR captures well: a run that completed, but not cleanly.

Connection to the module

This lesson completes observability/run_logger.py's final version — the one lessons 07 and 08 use with no further changes, and the one that, per this guide's DISEÑO, gets reused unmodified from Module 3 onward.

Analogy: the guard's log, the shift report, and the full camera footage

A building with security typically has three layers of record-keeping, each for a different audience. The guard's log notes every round, every door checked, with no extra detail — enough to confirm, at a glance, that the shift was done (INFO). The incident report only exists when something went wrong — a forced door, a real alarm — and goes straight to the supervisor (ERROR). The security cameras, on the other hand, record everything, all the time, with the full detail of every second — nobody reviews them unless they already know something happened and need to reconstruct it precisely (DEBUG). None of the three layers replaces the others: the log without the cameras isn't enough to investigate a real incident; the cameras without the log force you to review hours of footage to confirm something as simple as "did the 3am round happen?"

This lesson builds exactly those three layers for traced_run.

Worked example: run_logger.py's final version

ToolCallDetail, the third 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 is deliberately different from ToolCallEvent: instead of individual fields (args, is_error, content), it has a single block field, which stores the complete dictionary of the tool_use_block or the result_block exactly as dispatch_robust produces them — including the id/tool_use_id, which the INFO view deliberately omits for being an irrelevant detail for a quick operational read.

RunEvent, with a new field: tool_errors

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

tool_errors counts how many of this run's steps ended in is_error: True — the signal that decides whether a run's close gets logged at INFO or at WARNING, as you'll see below.

traced_dispatch, with two levels per event

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

Notice that ToolCallEvent, at INFO level, no longer carries args for the tool_use (just tool and step) — the full argument detail moved to ToolCallDetail, at DEBUG level. This is, precisely, the analogy's audience separation: the guard's log says "3rd-floor round, done"; the full camera footage shows every second of that round.

traced_run, with tool_errors deciding the closing level

@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 is a mutable dictionary, created inside traced_run and captured by traced_dispatch's closure — the same technique you already saw with original_dispatch in lesson 05, now applied to accumulate a counter across all of one run's calls. When the run finishes cleanly, traced_run decides run_finished's level by looking at that counter: WARNING if there was at least one tool_error along the way, INFO if there wasn't any. This answers a real question neither INFO nor ERROR, on their own, answer well: a run can complete — the user got a response — and still have tripped up along the way, like Ana's canonical script, which corrects an invalid tier before booking. That run isn't a failure (ERROR), but it isn't perfectly clean either (INFO) — it is, precisely, a warning.

Watching the three layers in action

With the logger's level at INFO — a typical production configuration, neither completely silent nor completely verbose — run Ana's script with its tier error:

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

What to expect:

{"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": ""}

Notice two things. First, seq skips — from 2 to 4, from 4 to 6 — instead of growing by one: every tool call also generated a DEBUG event (tool_use_detail, tool_result_detail) that consumed a sequence number, but got filtered out by the logger's INFO level — seq counts all the events generated, not just the ones printed. This detail matters, and lesson 07 picks it back up. Second, the final run_finished carries "tool_errors": 1 — and, although this compact format doesn't show the level's name, that event was logged at WARNING, not INFO, because stats["tool_errors"] was 1 at the moment of closing. The run completed (it's not run_failed), but not cleanly.

Now, the same run with the logger's level at ERROR — an aggressive configuration, for a system that only wants to be interrupted when something truly fails:

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)

What to expect:

{"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']"}

A single line. run_started (INFO) disappears. The three clean steps (INFO) disappear. And — this is the revealing part — run_finished also disappears, despite having been logged at WARNING (level 30): WARNING is still below ERROR (level 40), so a filter that aggressive hides it too. A system configured this way would see something failed at step 2, but it would not see that the run, overall, ended up in a degraded state — a real nuance of how choosing the filtering level changes which story the log tells.

And with the level at DEBUG — the complete view, cameras on — over a clean, single-tool-call run:

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)

What to expect:

{"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": ""}

Now seq has no gaps — 19, 20, 21, 22, 23, 24, consecutive — because DEBUG is the lowest possible level: nothing gets filtered. And the _detail lines show what the INFO view deliberately omitted: the tool_use's exact id (toolu_01), and its corresponding tool_result's tool_use_id — the kind of detail only needed once you already know you need to reconstruct something precisely.

Common mistakes

1. Thinking raising the level to DEBUG "adds new information." It adds nothing that didn't already exist — lesson 05's instrumentation always generated both event levels; DEBUG simply stops filtering them out. The cost of having DEBUG available isn't computational (the events were already being calculated) but one of volume: double the lines for every tool call, reason enough not to leave it on by default in production.

2. Confusing "the run finished" with "the run finished well." A RunEvent with event="run_finished" means, only, that run_reservo_agent returned without raising an exception — not that every step came out clean. The tool_errors field and the level (INFO vs WARNING) are what tell the two cases apart; reading only the event without looking at either is losing exactly the signal this lesson added.

3. Filtering at ERROR expecting to see every run's summary. As the worked example confirmed, a filter at ERROR also hides WARNING events — including a degraded run_finished — because WARNING (30) is below ERROR (40) in the level hierarchy. A system that needs to see "the run finished, though with problems" has to filter at, at minimum, WARNING.

4. Logging the full detail (ToolCallDetail's block) at INFO level "just in case." This exactly cancels out the separation this lesson builds: if all the detail lives at INFO, raising or lowering the level stops having any effect on the volume of the heaviest lines. The "lightweight INFO, complete DEBUG" discipline only works if it's respected for every new event added to the system.

5. Forgetting that seq counts events generated, not events printed. A gap in the seq sequence (like 2 → 4 in this lesson's first example) isn't an error or a lost event — it's proof that something was generated and filtered out. This lesson's Exercise 3 builds an explicit detector for these gaps.

Exercises

Exercise 1: Confirm what survives a pure ERROR filter (Easy)

With rl.logger.setLevel(logging.ERROR), run Ana's script (with the tier error) under traced_run. Before running it, predict how many lines you're going to see. Then confirm.

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

Exercise 2: Count INFO versus DEBUG lines for a clean three-tool-call run (Medium)

With rl.logger.setLevel(logging.DEBUG), run Sofía's script (list_rooms → get_quote → book_room, no errors, three tool calls) under traced_run, capturing the output. Count how many lines are actually INFO-level events (run_started, tool_use, tool_result, run_finished) versus how many are _detail events (DEBUG). Confirm the formula: INFO = 2 + 2n, DEBUG = 2n, for 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

Exercise 3: Build a gap detector for seq (Hard)

Run a run under traced_run with the logger's level at INFO (no DEBUG), capturing the output as a list of parsed events. Write a find_gaps(events) function that, given the list of seq values present, reports the gaps: consecutive pairs where the difference is greater than 1, along with how many numbers are missing in each gap. Confirm every gap corresponds exactly to one filtered-out DEBUG event.

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

Summary and next step

• We split every step of the loop into two layers: ToolCallEvent at INFO/ERROR (a lightweight operational view, no arguments or full content) and ToolCallDetail at DEBUG (the complete block, ids included).
• We added tool_errors to RunEvent, and decided run_finished's level based on that counter: INFO if the run was clean, WARNING if it completed but with at least one tool error along the way.
• We confirmed, with real execution, with the same run under three different filter levels (INFO, ERROR, DEBUG), that each one tells a different story — and that a filter at ERROR also hides WARNING events, including a degraded run_finished.
• We confirmed, with real execution, that gaps in seq are a legitimate signal that something got filtered out, with no need to know the exact content of what was hidden.

Next lesson: 07 — Reading a Trace Back. With run_logger.py complete, we persist RUN_LOG.jsonl to a real file for the first time, and build the functions that read that file back to reconstruct, from scratch, exactly what happened to a specific run.

Additional resources

1. Python — logging levels — The complete level table (DEBUG=10, INFO=20, WARNING=30, ERROR=40, CRITICAL=50) and its numeric hierarchy, the foundation of every filter in this lesson.
2. Python — logging HOWTO: when to use each level — The official criteria guide, the same one this lesson applies to traced_run's design.
3. Python — dataclasses.field — field(default_factory=dict), used in ToolCallEvent and ToolCallDetail to avoid the classic shared-mutable-default-value bug.
4. Anthropic — Building effective agents — On why telling "completed" apart from "completed with no problems" matters for an agentic system's real reliability.
5. Python 3.14 — What's New — The version every line of code in this lesson ran on.