`print` no es logging

Descripción

print() es, casi siempre, la primera herramienta que cualquiera usa para "ver qué está pasando" dentro de un programa. Funciona, es inmediata, no requiere configurar nada — y por eso mismo es tentador seguir usándola cuando el programa deja de ser un script de prueba y empieza a ser un sistema que corre sin que nadie lo esté mirando. Esta lección no argumenta contra print() en abstracto — la usaste, con toda razón, en cada módulo de agent-fundamentals y en el Módulo 1 de esta guía. Argumenta algo más preciso: print() le falta exactamente lo que un sistema en producción necesita, y esta lección lo demuestra con código real, no con una lista de razones abstractas.

Conexión con el módulo

Esta lección es la motivación completa del resto del módulo. Cada capacidad que vas a construir en las lecciones 03 a 06 —estructura JSON, un trace_id, niveles de severidad— existe, específicamente, porque print() no la tiene. Sin ver el problema primero, la solución de las lecciones siguientes parece trabajo de más. Con el problema visto y ejecutado, cada pieza que se agrega después tiene una razón de ser concreta.

Analogía: gritar en la cocina, contra anotar en la libreta de pedidos

Un mesero que grita cada pedido hacia la cocina —"¡una hamburguesa, mesa 4!"— resuelve el problema en el instante: el cocinero lo escucha, lo prepara. Pero ese grito no deja ningún rastro. Si alguien pregunta, media hora después, cuántos pedidos hubo entre las 8 y las 9, o cuál mesa pidió qué, la respuesta depende enteramente de que alguien lo recuerde de memoria — y en una noche con veinte mesas activas, nadie lo recuerda con precisión. Una libreta de pedidos resuelve un problema distinto: cada entrada tiene una hora, una mesa, un plato, un estado ("pedido", "en preparación", "listo") — y esa estructura fija es lo que permite, más tarde, reconstruir la noche completa, filtrar por mesa, o contar cuántas hamburguesas salieron.

print() es el grito. Resuelve el problema del instante —ver algo en la pantalla, ahora mismo, mientras programas—, pero no deja ninguna estructura detrás. logging, que esta lección empieza a introducir, es la libreta: cada entrada tiene un nivel, un origen, y —a partir de la lección 03— una estructura fija de campos, que es lo que permite, más tarde, hacer con los datos exactamente lo que la pregunta de "cuántos pedidos hubo" necesita.

Ejemplo trabajado: la misma información, con print(), sale ilegible

Dos runs, uno detrás de otro, con print() sembrado en el camino

Retoma el runner de siempre — run_reservo_agent, de agent-fundamentals M8, sin tocar una línea— y envuélvelo con la forma más simple posible de "ver qué está pasando": un print() por cada tool_use y cada tool_result que aparece en history, después de que el run termina.

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)

Qué esperar:

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

Mira con cuidado la línea 1 y la línea 9: llamando list_rooms con {} y resultado: [{"room": "Focus", "rate_cents": 2500}, ...] aparecen dos veces, idénticas letra por letra, una para el run de Ana y otra para el run de Luis. Si en vez de ocho líneas tuvieras ocho mil —el volumen real de un sistema en producción, con cientos de runs por hora—, no habría ninguna forma de saber, mirando solo estas líneas, a cuál run pertenece cada una. print() no tiene ningún campo que diga "esto es del run de Ana" — solo imprime lo que le pides, en el orden en que lo pides, sin ninguna otra información.

El problema no es solo de volumen: son cuatro problemas distintos

1. Sin estructura: cada línea es texto libre, no datos

llamando list_rooms con {} es perfectamente legible para un humano leyendo la terminal en el momento. Pero ningún programa puede preguntarle a esa línea "¿qué tool fue?" sin, básicamente, reinventar un parser de texto libre — frágil, y distinto para cada formato de mensaje que alguien haya escrito. Un archivo de logs de print() acumulado durante semanas es, en la práctica, un archivo de texto que solo un humano puede leer con sentido, una línea a la vez.

2. Sin nivel: no se puede filtrar sin borrar código

No hay forma de decirle a print() "muéstrame solo los errores" sin, literalmente, ir a buscar cada llamada a print() que no sea un error y comentarla o borrarla. Confírmalo:

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

Tres líneas, mezcladas, sin ninguna forma de pedirle a Python "muéstrame solo la que empieza con ERROR" sin ir a buscar, línea por línea del código fuente, cada print que la genera. Un sistema real necesita poder subir o bajar cuánto detalle ve sin tocar el código — en desarrollo, quieres ver todo; en producción, generalmente solo los errores. print() no ofrece ese control en absoluto.

3. Sin separación: se mezcla con la salida real del programa

Cuando run_and_observe (Módulo 1) imprime RESPUESTA: Reservé Focus pro 3h para Ana..., esa línea es el producto — es lo que un sistema real le devolvería al usuario. Si tus líneas de depuración usan el mismo print() que esa respuesta, ambas terminan en el mismo lugar, sin ninguna forma de separarlas. Confírmalo con el ejemplo de esta lección: en la salida de arriba, RESPUESTA: Reservé Focus pro 3h para Ana. Confirmación #1. está mezclada, en el mismo flujo, con las líneas de depuración de sus propios pasos internos. Un sistema que solo necesita mostrarle la respuesta final al usuario tendría que filtrar manualmente cuál línea es cuál.

logging, en cambio, escribe por defecto a un canal distinto (stderr) del que usa print() (stdout) — dos flujos separados a nivel del sistema operativo, no solo por convención. Confírmalo:

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

Corrido normalmente, en la misma terminal, ambos flujos se mezclan (visualmente):

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

Pero corrido con la salida de cada flujo redirigida por separado —python3 script.py 2>/dev/null descarta los logs y deja solo la respuesta; python3 script.py 1>/dev/null descarta la respuesta y deja solo los logs—, la separación es 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

Esta separación —imposible con print() puro, porque todo print() va siempre al mismo lugar— es exactamente lo que un sistema real necesita: la respuesta al usuario por un canal, la operación interna por otro, sin que un desarrollador tenga que inventar su propia convención para distinguirlas.

4. Sin nombre de origen: no se sabe qué parte del sistema habló

logging.getLogger("reservo") le da a cada mensaje un origen con nombre —reservo, en este caso—. En un sistema con varias piezas (el agente, el circuit breaker del Módulo 6, el harness de regresión del Módulo 5), cada una puede tener su propio logger con su propio nombre, y se puede silenciar o amplificar una pieza sin tocar las demás. print() no tiene ningún concepto de "origen" — cada línea es anónima.

Un primer vistazo a logging: nivel, filtrado, sin borrar código

Con el problema visto, un primer contacto con logging — todavía sin la estructura JSON de la lección 03, solo para confirmar que el filtrado por nivel funciona de verdad:

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

Qué esperar:

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

Nota tres cosas: primero, logger.debug(...) nunca aparece — el nivel por defecto de logging.basicConfig en este ejemplo es INFO, y DEBUG está por debajo (numéricamente: DEBUG=10 < INFO=20 < WARNING=30 < ERROR=40), así que queda filtrado desde el principio, sin que la línea de código se haya tocado. Segundo, con logger.setLevel(logging.WARNING), las líneas INFO desaparecen sin borrar ni comentar ninguna llamada a logger.info(...) — el filtrado ocurre en el logger, no en el código fuente. Tercero, ese stream=sys.stdout en logging.basicConfig(...) es una elección deliberada de esta lección, solo para que la salida de este ejemplo aparezca en un único flujo, ordenada — el valor por defecto de logging, sin ese argumento, es escribir a stderr, como confirmó la sección anterior.

Este control por nivel —bajar o subir cuánto se ve, sin tocar el código— es la primera de varias capacidades que print() nunca tuvo, y es la base sobre la que la lección 06 construye una política completa de qué nivel usar para qué tipo de evento.

Errores comunes

1. Pensar que el problema de print() es "se ve feo". No es estético — es funcional. Un log de print() no se puede filtrar por nivel, no se puede separar de la salida real del programa, y no tiene ninguna estructura que un programa pueda leer. Los tres son problemas de capacidad, no de presentación.

2. Creer que basta con agregar una etiqueta manual a cada print() para resolver la ambigüedad de runs mezclados. Es un parche que funciona mientras todo el equipo recuerde, siempre, agregar la etiqueta — y basta que una sola llamada a print() la olvide (algo que ningún mecanismo evita) para que ese punto del log vuelva a ser ambiguo. El Ejercicio 2 de esta lección lo pone a prueba, ejecutado.

3. Configurar logging.basicConfig más de una vez esperando que cambie el formato. basicConfig solo tiene efecto la primera vez que se llama en un proceso —a menos que se pase force=True—; llamarlo de nuevo con un formato distinto, sin ese argumento, no hace nada. Esto puede confundir mucho al experimentar en una sesión interactiva de Python.

4. Olvidar que logger.setLevel() afecta a TODOS los mensajes de ESE logger, no a uno en particular. Bajar el nivel a ERROR no oculta selectivamente un mensaje molesto — oculta cualquier mensaje INFO/WARNING de ese logger, para siempre, hasta que el nivel se vuelva a subir.

5. Confundir stream=sys.stdout (usado en esta lección para que el ejemplo salga ordenado) con la configuración recomendada para producción. El valor por defecto de logging —sin pasar stream=— escribe a stderr, precisamente para mantener separados los logs de la salida real del programa. Esta lección usa stdout solo para que la demostración sea legible en un solo bloque.

Ejercicios

Ejercicio 1: Confirma la ambigüedad con argumentos idénticos (Fácil)

Usando run_with_prints del ejemplo trabajado, corre dos reservas para la misma sala, el mismo tier y las mismas horas, pero para dos miembros distintos (Diego y Marta, Studio basic 1h). Compara las líneas de get_quote de ambos runs y confirma que son idénticas letra por letra.

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.

Ejercicio 2: Etiqueta manual, y la fragilidad de que alguien la olvide (Medio)

Modifica run_with_prints para que reciba un tercer parámetro label y lo agregue al principio de cada línea (f"[{label}] ..."). Corre dos runs con etiquetas "A" y "B". Después, agrega una línea de print() de depuración sin la etiqueta (por ejemplo, print("debug: entrando al bloque de tool_result")) y observa cómo esa línea rompe la convención sin que Python la marque de ninguna forma.

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

Ejercicio 3: Un error logueado al nivel incorrecto, invisible en producción (Difícil)

Configura un logger con nivel WARNING (una configuración típica de producción, para reducir ruido). Loguea un fallo real —"get_quote falló: tier inválido"— usando logger.info(...) en vez de logger.error(...), un error de criterio fácil de cometer. Confirma que, con el nivel en WARNING, ese fallo real no aparece en ningún lado. Después, corrígelo a logger.error(...) y confirma que sí aparece.

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

Resumen y siguiente paso

• Confirmamos, ejecutado, que print() le falta estructura (texto libre, no parseable), nivel (no se puede filtrar sin borrar código), y separación (se mezcla con la salida real del programa por el mismo flujo).
• Vimos, con dos runs procesados uno detrás de otro, que sin ningún identificador en cada línea, eventos idénticos de runs distintos son indistinguibles — el problema que el trace_id de la lección 04 resuelve.
• Confirmamos, ejecutado, que logging sí ofrece filtrado por nivel (sin tocar el código fuente) y separación de flujos (stdout para la salida real, stderr por defecto para los logs) — dos capacidades que print() nunca tuvo.

Siguiente lección: 03 — Logs estructurados como JSON. Con el problema de la falta de estructura confirmado, construimos la primera pieza de run_logger.py: un formatter que convierte cada evento en una línea de JSON completa, parseable por cualquier programa, no solo legible por un humano.

Recursos adicionales

1. Python — logging — La referencia completa del módulo que esta lección empieza a usar, y que el resto de este módulo desarrolla a fondo.
2. Python — logging HOWTO — La guía oficial sobre cuándo usar cada nivel de severidad, la base de la lección 06.
3. Python — logging.handlers — Los distintos destinos a los que un logger puede escribir (archivo, red, stdout/stderr) — la base de la persistencia a archivo de la lección 07.
4. Python 3.14 — What's New — La versión con la que se ejecutó cada línea de código de esta lección.