`print` Is Not Logging

Description

print() is, almost always, the first tool anyone uses to "see what's happening" inside a program. It works, it's immediate, it requires no configuration — and that's exactly why it's tempting to keep using it once the program stops being a test script and starts being a system running with nobody watching it. This lesson doesn't argue against print() in the abstract — you used it, rightly, in every module of agent-fundamentals and in this guide's Module 1. It argues something more precise: print() is missing exactly what a production system needs, and this lesson demonstrates it with real code, not a list of abstract reasons.

Connection to the module

This lesson is the complete motivation for the rest of the module. Every capability you're going to build in lessons 03 through 06 — JSON structure, a trace_id, severity levels — exists, specifically, because print() doesn't have it. Without seeing the problem first, the following lessons' solution looks like extra work. With the problem seen and run for real, every piece added afterward has a concrete reason to exist.

Analogy: shouting into the kitchen, versus writing in the order pad

A waiter who shouts every order toward the kitchen — "one burger, table 4!" — solves the problem in the instant: the cook hears it, makes it. But that shout leaves no trace behind. If someone asks, half an hour later, how many orders there were between 8 and 9, or which table ordered what, the answer depends entirely on someone remembering it from memory — and on a night with twenty active tables, nobody remembers it precisely. An order pad solves a different problem: every entry has a time, a table, a dish, a status ("ordered," "in prep," "ready") — and that fixed structure is what lets you, later, reconstruct the whole night, filter by table, or count how many burgers went out.

print() is the shout. It solves the instant's problem — seeing something on the screen, right now, while you're coding — but leaves no structure behind. logging, which this lesson starts introducing, is the order pad: every entry has a level, an origin, and — starting in lesson 03 — a fixed structure of fields, which is what later lets you do with the data exactly what a question like "how many orders were there" needs.

Worked example: the same information, with print(), comes out unreadable

Two runs, one after another, with print() sprinkled along the way

Go back to the usual runner — run_reservo_agent, from agent-fundamentals M8, without touching a line — and wrap it with the simplest possible form of "seeing what's happening": a print() for every tool_use and every tool_result that appears in history, after the run finishes.

import reservo_agent as ra

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."}]},
]
script_luis = [
    {"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": "Studio", "tier": "basic", "hours": 2}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_03", "name": "book_room",
         "input": {"room": "Studio", "tier": "basic", "hours": 2, "member": "Luis"}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "Reservé Studio basic 2h para Luis. Confirmación #2."}]},
]


def run_with_prints(question, script):
    """La forma mas obvia de 'observar' un run: un print() por cada
    tool_use y tool_result, despues de que el run termino."""
    final, history = ra.run_reservo_agent(question, script)
    for turn in history:
        content = turn["content"]
        if isinstance(content, str):
            continue
        for block in content:
            if block["type"] == "tool_use":
                print(f"llamando {block['name']} con {block['input']}")
            elif block["type"] == "tool_result":
                print(f"resultado: {block['content']}")
    print("RESPUESTA:", final["content"][0]["text"])
    return final


print("=== procesando dos preguntas, una detrás de otra ===")
run_with_prints("Reserva Focus pro 3h para Ana", script_ana)
run_with_prints("Reserva Studio basic 2h para Luis", script_luis)

What to expect:

=== procesando dos preguntas, una detrás de otra ===
llamando list_rooms con {}
resultado: [{"room": "Focus", "rate_cents": 2500}, {"room": "Studio", "rate_cents": 4000}, {"room": "Boardroom", "rate_cents": 8000}]
llamando get_quote con {'room': 'Focus', 'tier': 'pro', 'hours': 3}
resultado: {"price_cents": 6000}
llamando book_room con {'room': 'Focus', 'tier': 'pro', 'hours': 3, 'member': 'Ana'}
resultado: {"booking_id": 1, "confirmed": true}
RESPUESTA: Reservé Focus pro 3h para Ana. Confirmación #1.
llamando list_rooms con {}
resultado: [{"room": "Focus", "rate_cents": 2500}, {"room": "Studio", "rate_cents": 4000}, {"room": "Boardroom", "rate_cents": 8000}]
llamando get_quote con {'room': 'Studio', 'tier': 'basic', 'hours': 2}
resultado: {"price_cents": 8000}
llamando book_room con {'room': 'Studio', 'tier': 'basic', 'hours': 2, 'member': 'Luis'}
resultado: {"booking_id": 2, "confirmed": true}
RESPUESTA: Reservé Studio basic 2h para Luis. Confirmación #2.

Look carefully at line 1 and line 9: llamando list_rooms con {} and resultado: [{"room": "Focus", "rate_cents": 2500}, ...] appear twice, identical letter for letter, once for Ana's run and once for Luis's. If instead of eight lines you had eight thousand — a production system's real volume, with hundreds of runs per hour — there'd be no way to know, looking only at these lines, which run each one belongs to. print() has no field that says "this belongs to Ana's run" — it only prints what you ask for, in the order you ask for it, with no other information.

The problem isn't just volume: it's four different problems

1. No structure: every line is free text, not data

llamando list_rooms con {} is perfectly readable for a human reading the terminal in the moment. But no program can ask that line "which tool was it?" without, basically, reinventing a free-text parser — fragile, and different for every message format someone happened to write. A print() log file accumulated over weeks is, in practice, a text file only a human can make sense of, one line at a time.

2. No level: you can't filter without deleting code

There's no way to tell print() "show me only the errors" without, literally, going to find every print() call that isn't an error and commenting it out or deleting it. Confirm it:

def dangerous_dispatch(tool_use_block):
    """Simula un despacho que, a veces, encuentra un error real."""
    if tool_use_block["name"] == "get_quote" and tool_use_block["input"].get("tier") == "premium":
        print("ERROR: tier invalido")
        return {"is_error": True}
    print(f"OK: {tool_use_block['name']} ejecutada")
    return {"is_error": False}


dangerous_dispatch({"name": "list_rooms", "input": {}})
dangerous_dispatch({"name": "get_quote", "input": {"tier": "premium"}})
dangerous_dispatch({"name": "book_room", "input": {}})

OK: list_rooms ejecutada
ERROR: tier invalido
OK: book_room ejecutada

Three lines, all mixed together, with no way to ask Python "show me only the one that starts with ERROR" without going to find, line by line in the source code, every print that generates it. A real system needs to be able to raise or lower how much detail it sees without touching the code — in development, you want to see everything; in production, generally only the errors. print() offers no such control at all.

3. No separation: it mixes with the program's real output

When run_and_observe (Module 1) prints RESPUESTA: Reservé Focus pro 3h para Ana..., that line is the product — it's what a real system would return to the user. If your debug lines use that same print() as that response, both end up in the same place, with no way to separate them. Confirm it with this lesson's example: in the output above, RESPUESTA: Reservé Focus pro 3h para Ana. Confirmación #1. is mixed, in the same stream, with the debug lines from its own internal steps. A system that only needs to show the final response to the user would have to manually filter out which line is which.

logging, on the other hand, writes by default to a different channel (stderr) than the one print() uses (stdout) — two streams separated at the operating-system level, not just by convention. Confirm it:

import logging

logging.basicConfig(level=logging.INFO, format="LOG %(levelname)s: %(message)s")  # sin stream= -> va a stderr
logger = logging.getLogger("reservo")

logger.info("llamando list_rooms")
print("RESPUESTA: Reservé Focus pro 3h para Ana. Confirmación #1.")
logger.info("run terminado")

Run normally, in the same terminal, both streams get mixed together (visually):

LOG INFO: llamando list_rooms
LOG INFO: run terminado
RESPUESTA: Reservé Focus pro 3h para Ana. Confirmación #1.

But run with each stream's output redirected separately — python3 script.py 2>/dev/null discards the logs and leaves only the response; python3 script.py 1>/dev/null discards the response and leaves only the logs — the separation is total:

--- solo stdout (lo que vería un sistema que solo lee la respuesta) ---
RESPUESTA: Reservé Focus pro 3h para Ana. Confirmación #1.

--- solo stderr (solo los logs) ---
LOG INFO: llamando list_rooms
LOG INFO: run terminado

This separation — impossible with plain print(), because every print() always goes to the same place — is exactly what a real system needs: the response to the user through one channel, the internal operation through another, with no developer having to invent their own convention to tell them apart.

4. No origin name: you don't know which part of the system spoke

logging.getLogger("reservo") gives every message a named origin — reservo, in this case. In a system with several pieces (the agent, Module 6's circuit breaker, Module 5's regression harness), each can have its own logger with its own name, and you can silence or amplify one piece without touching the rest. print() has no concept of "origin" at all — every line is anonymous.

A first look at logging: level, filtering, without deleting code

With the problem seen, a first contact with logging — still without lesson 03's JSON structure, just to confirm level-based filtering really works:

import logging
import sys

logging.basicConfig(level=logging.INFO, format="%(levelname)s:%(name)s:%(message)s", stream=sys.stdout)
logger = logging.getLogger("reservo")

logger.debug("detalle interno: parseando model_script")
logger.info("llamando list_rooms con {}")
logger.info("resultado: [{'room': 'Focus', 'rate_cents': 2500}]")
logger.warning("la tool tardó más de lo esperado")
logger.error("get_quote falló: tier inválido")

print()
print("--- ahora subimos el nivel a WARNING: INFO y DEBUG desaparecen, sin borrar una línea de código ---")
print()
logger.setLevel(logging.WARNING)
logger.debug("detalle interno: parseando model_script")
logger.info("llamando list_rooms con {}")
logger.warning("la tool tardó más de lo esperado")
logger.error("get_quote falló: tier inválido")

What to expect:

INFO:reservo:llamando list_rooms con {}
INFO:reservo:resultado: [{'room': 'Focus', 'rate_cents': 2500}]
WARNING:reservo:la tool tardó más de lo esperado
ERROR:reservo:get_quote falló: tier inválido

--- ahora subimos el nivel a WARNING: INFO y DEBUG desaparecen, sin borrar una línea de código ---

WARNING:reservo:la tool tardó más de lo esperado
ERROR:reservo:get_quote falló: tier inválido

Notice three things: first, logger.debug(...) never shows up — the default level for logging.basicConfig in this example is INFO, and DEBUG is below it (numerically: DEBUG=10 < INFO=20 < WARNING=30 < ERROR=40), so it's filtered out from the start, without the line of code being touched. Second, with logger.setLevel(logging.WARNING), the INFO lines disappear without deleting or commenting out a single logger.info(...) call — the filtering happens in the logger, not in the source code. Third, that stream=sys.stdout in logging.basicConfig(...) is a deliberate choice for this lesson, just so this example's output appears in a single, orderly stream — logging's default, without that argument, is to write to stderr, as the previous section confirmed.

This level-based control — raising or lowering how much you see, without touching the code — is the first of several capabilities print() never had, and it's the foundation lesson 06 builds a complete policy on top of, for which level to use for which type of event.

Common mistakes

1. Thinking print()'s problem is "it looks ugly." It isn't aesthetic — it's functional. A print() log can't be filtered by level, can't be separated from the program's real output, and has no structure a program can read. All three are capability problems, not presentation problems.

2. Believing that adding a manual label to every print() is enough to solve the ambiguity of mixed-up runs. It's a patch that works as long as the whole team always remembers to add the label — and it only takes one print() call forgetting it (something no mechanism prevents) for that point in the log to become ambiguous again. This lesson's Exercise 2 puts it to the test, run for real.

3. Configuring logging.basicConfig more than once expecting the format to change. basicConfig only takes effect the first time it's called in a process — unless force=True is passed; calling it again with a different format, without that argument, does nothing. This can be very confusing while experimenting in an interactive Python session.

4. Forgetting that logger.setLevel() affects ALL of THAT logger's messages, not just one in particular. Lowering the level to ERROR doesn't selectively hide one annoying message — it hides any INFO/WARNING message from that logger, for good, until the level is raised again.

5. Confusing stream=sys.stdout (used in this lesson so the example comes out orderly) with the recommended production configuration. logging's default — without passing stream= — writes to stderr, precisely to keep the logs separated from the program's real output. This lesson uses stdout only so the demonstration is readable in a single block.

Exercises

Exercise 1: Confirm the ambiguity with identical arguments (Easy)

Using the worked example's run_with_prints, run two bookings for the same room, the same tier, and the same hours, but for two different members (Diego and Marta, Studio basic 1h). Compare both runs' get_quote lines and confirm they're identical letter for letter.

script_diego = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "get_quote",
         "input": {"room": "Studio", "tier": "basic", "hours": 1}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_02", "name": "book_room",
         "input": {"room": "Studio", "tier": "basic", "hours": 1, "member": "Diego"}}]},
    {"stop_reason": "end_turn", "content": [{"type": "text", "text": "Reservé Studio basic 1h para Diego."}]},
]
script_marta = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "get_quote",
         "input": {"room": "Studio", "tier": "basic", "hours": 1}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_02", "name": "book_room",
         "input": {"room": "Studio", "tier": "basic", "hours": 1, "member": "Marta"}}]},
    {"stop_reason": "end_turn", "content": [{"type": "text", "text": "Reservé Studio basic 1h para Marta."}]},
]
run_with_prints("Reserva Studio basic 1h para Diego", script_diego)
run_with_prints("Reserva Studio basic 1h para Marta", script_marta)

llamando get_quote con {'room': 'Studio', 'tier': 'basic', 'hours': 1}
resultado: {"price_cents": 4000}
llamando book_room con {'room': 'Studio', 'tier': 'basic', 'hours': 1, 'member': 'Diego'}
resultado: {"booking_id": 1, "confirmed": true}
RESPUESTA: Reservé Studio basic 1h para Diego.
llamando get_quote con {'room': 'Studio', 'tier': 'basic', 'hours': 1}
resultado: {"price_cents": 4000}
llamando book_room con {'room': 'Studio', 'tier': 'basic', 'hours': 1, 'member': 'Marta'}
resultado: {"booking_id": 2, "confirmed": true}
RESPUESTA: Reservé Studio basic 1h para Marta.

Exercise 2: A manual label, and the fragility of someone forgetting it (Medium)

Modify run_with_prints to receive a third parameter, label, and prepend it to every line (f"[{label}] ..."). Run two runs with labels "A" and "B". Then, add one debug print() line without the label (for example, print("debug: entrando al bloque de tool_result")) and observe how that line breaks the convention with Python marking it in no way at all.

def run_with_labeled_prints(question, script, label):
    final, history = ra.run_reservo_agent(question, script)
    for turn in history:
        content = turn["content"]
        if isinstance(content, str):
            continue
        for block in content:
            if block["type"] == "tool_use":
                print(f"[{label}] llamando {block['name']} con {block['input']}")
            elif block["type"] == "tool_result":
                print(f"[{label}] resultado: {block['content']}")
    print(f"[{label}] RESPUESTA:", final["content"][0]["text"])


script_a = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "get_quote",
         "input": {"room": "Studio", "tier": "basic", "hours": 1}}]},
    {"stop_reason": "end_turn", "content": [{"type": "text", "text": "Studio basic 1h cuesta $40.00."}]},
]
run_with_labeled_prints("¿Cuánto cuesta Studio basic 1h?", script_a, "A")
run_with_labeled_prints("¿Cuánto cuesta Studio basic 1h?", script_a, "B")
print("--- un tercer desarrollador agrega un print de depuración sin la convención ---")
print("debug: entrando al bloque de tool_result")

[A] llamando get_quote con {'room': 'Studio', 'tier': 'basic', 'hours': 1}
[A] resultado: {"price_cents": 4000}
[A] RESPUESTA: Studio basic 1h cuesta $40.00.
[B] llamando get_quote con {'room': 'Studio', 'tier': 'basic', 'hours': 1}
[B] resultado: {"price_cents": 4000}
[B] RESPUESTA: Studio basic 1h cuesta $40.00.
--- un tercer desarrollador agrega un print de depuración sin la convención ---
debug: entrando al bloque de tool_result

Exercise 3: A failure logged at the wrong level, invisible in production (Hard)

Configure a logger with level WARNING (a typical production configuration, to reduce noise). Log a real failure — "get_quote falló: tier inválido" — using logger.info(...) instead of logger.error(...), an easy mistake of judgment to make. Confirm that, with the level at WARNING, that real failure shows up nowhere. Then fix it to logger.error(...) and confirm it does show up.

import logging
import sys

logging.basicConfig(level=logging.WARNING, format="%(levelname)s: %(message)s", stream=sys.stdout)
logger = logging.getLogger("reservo.buggy")

print("=== producción, nivel WARNING (config típica para reducir ruido) ===")
logger.info("get_quote falló: tier inválido")   # BUG: esto es un error real, logueado como INFO
print("(silencio arriba -- el fallo real nunca apareció en los logs de producción)")

print()
print("=== versión corregida: el fallo real se loguea a nivel ERROR ===")
logger.error("get_quote falló: tier inválido")

=== producción, nivel WARNING (config típica para reducir ruido) ===
(silencio arriba -- el fallo real nunca apareció en los logs de producción)

=== versión corregida: el fallo real se loguea a nivel ERROR ===
ERROR: get_quote falló: tier inválido

Summary and next step

• We confirmed, with real execution, that print() is missing structure (free text, not parseable), level (can't filter without deleting code), and separation (mixes with the program's real output through the same stream).
• We saw, with two runs processed one after another, that with no identifier on each line, identical events from different runs are indistinguishable — the problem lesson 04's trace_id solves.
• We confirmed, with real execution, that logging does offer level-based filtering (without touching the source code) and stream separation (stdout for the real output, stderr by default for the logs) — two capabilities print() never had.

Next lesson: 03 — Structured Logs as JSON. With the lack-of-structure problem confirmed, we build run_logger.py's first piece: a formatter that turns every event into a complete JSON line, parseable by any program, not just readable by a human.

Additional resources

1. Python — logging — The complete reference for the module this lesson starts using, and that the rest of this module develops in depth.
2. Python — logging HOWTO — The official guide on when to use each severity level, the foundation of lesson 06.
3. Python — logging.handlers — The different destinations a logger can write to (file, network, stdout/stderr) — the foundation of lesson 07's persistence to a file.
4. Python 3.14 — What's New — The version every line of code in this lesson ran on.