Structured Logs as JSON

Description

The previous lesson confirmed, with real execution, that print() produces free text: readable for a human, unreadable for a program. This lesson builds the concrete solution: every log event stops being a loose sentence and becomes a complete JSON object, with fixed, named fields, on a single line. A file with one JSON line per event — the format known as JSON Lines or NDJSON — can be read with a text editor like any file, but can also be processed with json.loads line by line, filtered by field, aggregated, or loaded into any tool that understands JSON. That dual nature — readable and parseable at once — is the foundation of everything this module builds from here on.

This lesson doesn't touch run_reservo_agent or any Reservo tool yet — that starts in lesson 05. Here we build, and test, the structured-logging machinery itself: a custom formatter, two event dataclasses, and the function that turns them into a real log line.

Connection to the module

This lesson delivers observability/run_logger.py's first real piece: the JSON formatter and the log_event function, which every lesson that follows — 04 onward — is going to reuse unchanged. RunEvent, the first event dataclass, is completed here; ToolCallEvent, the second, arrives in lesson 05, when there are loop steps to record.

Analogy: an intake form, versus a note in the margin

When someone arrives at a hospital's emergency room, what happened doesn't get written down in a notebook with free-form prose ("a man came in with pain, looked serious"). An intake form gets filled out: fixed fields — name, arrival time, main symptom, urgency level, vital signs — each in its own box, no matter who fills it out or on which shift. That fixed structure is what lets, later, anyone — a different doctor, the hospital's statistics system, an audit — take a hundred intake forms and count how many cases were urgent, without having to read a hundred paragraphs of prose and decide, case by case, what they meant.

A structured log line is that intake form. {"trace_id": "run-abc123", "event": "tool_use", "tool": "get_quote", ...} isn't any more "informative" than the equivalent free-text line from the previous lesson — in fact, it says exactly the same thing. What changes is that any program, not just a human reading carefully, can extract tool unambiguously, with no need to guess where each piece of data starts and ends within a sentence.

Worked example: the formatter, and the first two real JSON lines

The logger, configured to write JSON

import json
import logging
import sys
from dataclasses import dataclass, asdict

logger = logging.getLogger("reservo.observability")
logger.setLevel(logging.DEBUG)
_handler = logging.StreamHandler(sys.stdout)
_handler.setFormatter(logging.Formatter("%(message)s"))  # el message YA es la línea JSON completa
logger.handlers = [_handler]
logger.propagate = False

Notice the design decision: instead of writing a complex logging.Formatter that assembles the JSON by reading attributes off the LogRecord (the internal object logging builds for every call), this guide assembles the JSON before calling the logger, with json.dumps directly, and passes that already-complete line as the message. The formatter, then, becomes trivial — "%(message)s", with no extra field — because the message is already exactly what you want written. This is the "direct json.dumps" option this guide's design leaves open alongside the more elaborate custom-formatter option — simpler to read, easier to test, and with the same final result.

logger.propagate = False keeps this logger from forwarding its messages to Python's root logger (which might have its own configuration, and would duplicate every line). It's a line you almost never notice until it's missing, and then every event shows up twice.

RunEvent, the first event dataclass

@dataclass
class RunEvent:
    """Un evento de nivel de RUN: abre o cierra un run completo."""
    seq: int
    trace_id: str
    event: str            # "run_started" | "run_finished" | "run_failed"
    question: str = ""
    error: str = ""


def log_event(level, event):
    """Serializa CUALQUIER evento (un dataclass) como una sola línea JSON,
    y la emite con el nivel dado. Una línea == un objeto JSON completo: el
    formato NDJSON/JSON Lines, parseable con json.loads línea por línea."""
    logger.log(level, json.dumps(asdict(event), ensure_ascii=False))

seq is the honest replacement for the real clock this module's lesson 01 already flagged: an integer that increments by one for every event generated, so events can be ordered without depending on datetime.now(). It isn't connected to anything yet in this lesson — it arrives with a real counter in lesson 04; here it's passed by hand just to confirm the format works.

asdict(event) turns the dataclass into a normal Python dictionary — {"seq": 1, "trace_id": "...", "event": "...", ...} — and json.dumps(..., ensure_ascii=False) turns it into the text line logger.log ends up emitting. The ensure_ascii=False parameter matters: without it, any accent in the prose ("Sofía", for example) comes out escaped as í, valid but much harder to read at a glance.

The first two real lines

log_event(logging.INFO, RunEvent(seq=1, trace_id="run-demo", event="run_started", question="Reserva Focus pro 3h para Ana"))
log_event(logging.INFO, RunEvent(seq=2, trace_id="run-demo", event="run_finished", question="Reserva Focus pro 3h para Ana"))

What to expect:

{"seq": 1, "trace_id": "run-demo", "event": "run_started", "question": "Reserva Focus pro 3h para Ana", "error": ""}
{"seq": 2, "trace_id": "run-demo", "event": "run_finished", "question": "Reserva Focus pro 3h para Ana", "error": ""}

Two lines, each a complete, self-contained JSON object — you don't need the previous line or the next to understand what one of them says. Confirm they're valid, parseable JSON, back into a Python dictionary, with the same standard library that wrote them:

parsed = json.loads('{"seq": 1, "trace_id": "run-demo", "event": "run_started", "question": "Reserva Focus pro 3h para Ana", "error": ""}')
print(parsed["trace_id"], "->", parsed["event"])

run-demo -> run_started

This is, precisely, the difference with lesson 02: that print() line — llamando list_rooms con {} — is also text, but no json.loads can parse it as an object with fields. This line can.

Why this isn't just print(json.dumps(...))

It's worth noting, precisely, what logging adds on top of simply printing JSON by hand — because in this example, the line that comes out on screen is, byte for byte, the same one print(json.dumps(asdict(event), ensure_ascii=False)) would produce. The difference isn't in the line's format — it's in the machinery around it:

• Severity level, inherited from lesson 02: logger.log(logging.DEBUG, ...) can get filtered out without touching a single line of code, something print() can never do.
• Destination-independent handlers: the same logger can write to the terminal (as here) and, without changing log_event or any dataclass, also to a file — exactly what lesson 07 does with RUN_LOG.jsonl.
• A namespace ("reservo.observability"), which lets you silence or amplify this part of the system without affecting other loggers.

json.dumps assembles the line; logging decides whether that line gets emitted, and where. Both pieces together are what's needed — neither is enough alone.

Common mistakes

1. Forgetting ensure_ascii=False. Without that argument, json.dumps is technically correct — the JSON is still valid — but any accent comes out escaped (Sofía instead of Sofía), much harder to read at a glance in a log file. Confirm it:

   print(json.dumps({"question": "Reserva Boardroom pro 1h para Sofía"}, ensure_ascii=False))
   print(json.dumps({"question": "Reserva Boardroom pro 1h para Sofía"}, ensure_ascii=True))

   {"question": "Reserva Boardroom pro 1h para Sofía"}
   {"question": "Reserva Boardroom pro 1h para Sofía"}
   

2. Forgetting logger.propagate = False. Without that line, if Python's root logger also has a handler configured (common if another part of the program called logging.basicConfig()), every event can show up duplicated — once through "reservo.observability"'s own handler, once through the handler inherited from the root logger.

3. Trying to log an object json.dumps doesn't know how to serialize. A dataclass with only str/int/bool/dict/list in its fields is always serializable — but if someone adds a field with a non-standard type (a set, an instance of a custom class, a datetime object), json.dumps raises a TypeError at the moment of logging, not before. This lesson's Exercise 3 confirms it.

4. Thinking a JSON line "is already" a functional trace_id. The trace_id field on RunEvent in this example is the fixed string "run-demo", written by hand — not a real, deterministic identifier calculated from the run's inputs. That is, precisely, lesson 04's job.

5. Confusing the JSON Lines format (one line, one object) with a normal JSON file. A typical .json file contains a single object or array, which can span many indented lines. A .jsonl file (or RUN_LOG.jsonl, as in lesson 07) contains many independent objects, one per line, with no comma or bracket joining them — each line gets parsed separately. Trying to load a complete .jsonl file with a single json.loads(archivo.read()) fails, because it isn't a single valid JSON document.

Exercises

Exercise 1: Parse a line back and extract a field (Easy)

Generate a log line with log_event for a RunEvent with event="run_failed" and error="RuntimeError: max_iterations alcanzado (2)". Capture the line it produces (you can use json.dumps(asdict(...)) directly for this, without going through the logger, since the result is the same string), parse it back with json.loads, and extract just the error field.

event = RunEvent(seq=5, trace_id="run-xyz", event="run_failed", question="Reserva algo", error="RuntimeError: max_iterations alcanzado (2)")
line = json.dumps(asdict(event), ensure_ascii=False)
print("línea generada:", line)

parsed = json.loads(line)
print("campo error   :", parsed["error"])

línea generada: {"seq": 5, "trace_id": "run-xyz", "event": "run_failed", "question": "Reserva algo", "error": "RuntimeError: max_iterations alcanzado (2)"}
campo error   : RuntimeError: max_iterations alcanzado (2)

Exercise 2: Confirm the ensure_ascii=True problem with real Reservo data (Medium)

Using RunEvent, generate an event with question="Reserva Boardroom pro 1h para Sofía" (note the accent). Serialize it twice: once with ensure_ascii=False and once with ensure_ascii=True (the default value for json.dumps if unspecified). Compare the two lines.

event = RunEvent(seq=1, trace_id="run-sofia", event="run_started", question="Reserva Boardroom pro 1h para Sofía")

legible = json.dumps(asdict(event), ensure_ascii=False)
escapado = json.dumps(asdict(event))  # ensure_ascii=True por defecto
print("legible :", legible)
print("escapado:", escapado)
print("ambas son JSON valido, se parsean igual:", json.loads(legible) == json.loads(escapado))

legible : {"seq": 1, "trace_id": "run-sofia", "event": "run_started", "question": "Reserva Boardroom pro 1h para Sofía", "error": ""}
escapado: {"seq": 1, "trace_id": "run-sofia", "event": "run_started", "question": "Reserva Boardroom pro 1h para Sofía", "error": ""}
ambas son JSON valido, se parsean igual: True

Exercise 3: Trigger the TypeError for a non-serializable field (Hard)

Define a BadEvent dataclass with a trace_id: str field and a weird: set field. Create an instance with weird={1, 2, 3} and try to log it with log_event. Confirm the TypeError, and explain in one sentence why this module's dataclasses (RunEvent, and ToolCallEvent from lesson 05) are deliberately restricted to str/int/bool/dict/list.

from dataclasses import dataclass, asdict

@dataclass
class BadEvent:
    trace_id: str
    weird: set

event = BadEvent(trace_id="run-x", weird={1, 2, 3})
try:
    json.dumps(asdict(event))
except TypeError as exc:
    print(f"TypeError: {exc}")

TypeError: Object of type set is not JSON serializable

Summary and next step

• We built observability/run_logger.py's first real piece: a logger configured for JSON (_handler + Formatter("%(message)s")), the RunEvent dataclass, and log_event, the function that turns any event into a complete JSON line.
• We ran this module's first two real log lines, and confirmed, with json.loads, that they're parseable back into a Python dictionary — the central difference with the previous lesson's print() free text.
• We confirmed, with real execution, why ensure_ascii=False matters for Spanish prose, and why a non-serializable field produces a TypeError at the moment of logging.

Next lesson: 04 — The trace_id: Correlating a Run. With the JSON format solved, we build the piece that makes every line know which run it belongs to: a deterministic identifier, never uuid4(), and the contextlib.contextmanager that opens and closes a run with that id.

Additional resources

1. Python — json — json.dumps/json.loads, the pair of functions behind every line in this module, including ensure_ascii and this lesson's TypeError.
2. Python — dataclasses — @dataclass and asdict, the way this module represents every event before serializing it.
3. Python — logging.Formatter — The class behind _handler.setFormatter(...), and why "%(message)s" is enough when the message already arrives fully assembled.
4. JSON Lines — The "one line, one JSON object" format this module uses starting in this lesson, and that RUN_LOG.jsonl (lesson 07) adopts as its file format.
5. Python 3.14 — What's New — The version every line of code in this lesson ran on.