Depuración y logging

El problema que vamos a resolver

Lo que hace todo el mundo cuando algo sale mal:

def discount(price, rate):
    print("price:", price)
    print("rate:", rate)
    result = price * (1 - rate)
    print("result:", result)
    return result


print(discount(100.0, 0.1))

price: 100.0
rate: 0.1
result: 90.0
90.0

Funciona. El problema es lo que viene después.

Borra las líneas y habrá que volver a escribirlas la próxima vez. Déjalas y se quedan en el código, y un día imprimen en la terminal de otra persona. Y un programa que corre en un servidor no tiene terminal en absoluto: a dónde va print allí, nadie lo sabe.

Este capítulo trata de dos cosas: cómo un programa lleva la cuenta de su propio trabajo, y cómo entrar dentro de él mientras está roto.

Al terminar este capítulo podrás

• Leer un traceback en el orden correcto y encontrar el lugar real del error
• Escribir mensajes con logging, y elegir entre los niveles
• Explicar por qué logging.getLogger(__name__) se escribe así
• Conservar el traceback completo de un error capturado con log.exception
• Explicar por qué los mensajes se escriben con %s y no con una f-string
• Detener un programa en ejecución con breakpoint()

Lo que necesitas primero: Pruebas con pytest.

Un traceback se lee desde abajo

def parse(text):
    return int(text)


def total(rows):
    return sum(parse(row) for row in rows)


print(total(["1", "2", "x"]))

Traceback (most recent call last):
  File "main.py", line 9, in <module>
    print(total(["1", "2", "x"]))
          ^^^^^^^^^^^^^^^^^^^^^^
  File "main.py", line 6, in total
    return sum(parse(row) for row in rows)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "main.py", line 6, in <genexpr>
    return sum(parse(row) for row in rows)
               ^^^^^^^^^^
  File "main.py", line 2, in parse
    return int(text)
           ^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'

Muchísima gente ve esto, se asusta y empieza a leer por arriba. El orden es el contrario.

La última línea es la más importante — qué pasó, y con qué valor. 'x' no es un número.

El bloque justo encima es el segundo — dónde pasó: dentro de parse, línea 2.

La parte de arriba es el camino que llevó hasta allí, leída de arriba abajo: <module> llamó a total, total llamó al generador, y ese llamó a parse. Esta parte hace falta cuando la pregunta es «qué llamada envió el valor incorrecto».

Y las marcas ^^^^ muestran qué parte de la línea falló — lo más útil en una línea larga.

Busca el bloque más bajo que sea código tuyo. Aunque la mitad del traceback sean archivos de librerías, el problema casi siempre está en la última línea que es tuya.

logging en lugar de print

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s - %(message)s")

log = logging.getLogger("shop")

log.debug("this is not shown")
log.info("starting")
log.warning("price is unusually high: %s", 9999)
log.error("could not read the file")

INFO shop - starting
WARNING shop - price is unusually high: 9999
ERROR shop - could not read the file

El mensaje debug no aparece, porque el nivel está fijado en INFO. Esta es la diferencia esencial con print: los mensajes se quedan en el código, y tú decides cuáles se ven.

Hay cinco niveles, y su orden es su definición:

import logging

logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")

log.debug("debug")
log.info("info")
log.warning("warning")
log.error("error")
log.critical("critical")

WARNING - warning
ERROR - error
CRITICAL - critical

Para qué sirve cada uno, en una línea:

• debug — detalle interno, que solo interesa mientras buscas un error
• info — eventos normales: arrancó, se leyeron tantas filas, terminó
• warning — algo es raro, y el trabajo continúa
• error — falló un trabajo, no el programa
• critical — el programa no puede seguir

logging escribe en stderr y print escribe en stdout. En una terminal aparecen los dos, así que la diferencia pasa desapercibida — pero python main.py > out.txt envía al archivo solo la salida de print y deja el log en pantalla. Por eso las salidas de abajo muestran los dos flujos por separado: primero las líneas impresas, luego el log; en tu terminal se mezclan.

__name__ — el nombre del módulo es el nombre del logger

import logging

log = logging.getLogger(__name__)


def line_total(price, quantity):
    log.debug("line_total(%s, %s)", price, quantity)
    return round(price * quantity * 1.15, 2)

Y en main.py:

import logging

import pricing

logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(name)s - %(message)s")

log = logging.getLogger(__name__)

log.info("starting")
print(pricing.line_total(15.0, 3))

51.75

INFO __main__ - starting
DEBUG pricing - line_total(15.0, 3)

El __name__ del capítulo 22 vuelve, con exactamente la misma regla: el archivo que se ejecuta es __main__, y un módulo importado tiene su propio nombre.

El beneficio se ve en el log — cada mensaje dice de dónde viene. En un programa de veinte módulos, eso marca la diferencia.

Hay además un beneficio menos visible: los nombres forman un árbol a través de los puntos, así que el nivel de shop.pricing puede subirse por separado mientras el resto del programa sigue callado.

No llames a basicConfig en una librería. Cada módulo escribe solo getLogger(__name__) y envía mensajes; a dónde van y cuántos son es decisión de main.

La razón viene de dos reglas juntas. Importar significa ejecutar el archivo. Y basicConfig funciona solo la primera vez — una vez configurado el logging, las llamadas posteriores no hacen nada, en silencio. Supón que pricing.py llama a basicConfig por error:

import logging

logging.basicConfig(level=logging.WARNING, format="%(message)s")

log = logging.getLogger(__name__)


def line_total(price, quantity):
    log.debug("line_total(%s, %s)", price, quantity)
    return round(price * quantity * 1.15, 2)

Ejecuta de nuevo el main.py de arriba, sin cambiarlo en absoluto:

51.75

Eso es todo — ni líneas de log, ni tampoco error. main.py hizo primero import pricing, así que el basicConfig de la librería se ejecutó antes y fijó el nivel en WARNING. Después, el basicConfig(level=logging.DEBUG, ...) de main.py fue ignorado en silencio. La librería se apoderó del logging del programa que la importó.

El traceback completo de un error capturado

El capítulo 24 enseñó a capturar errores. Pero capturar no debería significar perder la información.

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")


def parse(text):
    return int(text)


for value in ["1", "x"]:
    try:
        print(parse(value))
    except ValueError:
        log.exception("could not parse %r", value)

print("still running")

1
still running

ERROR - could not parse 'x'
Traceback (most recent call last):
  File "main.py", line 14, in <module>
    print(parse(value))
          ^^^^^^^^^^^^
  File "main.py", line 9, in parse
    return int(text)
           ^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'

log.exception guarda el traceback completo en el log — y el programa sigue.

Esto resuelve el dilema del capítulo 24. except ...: pass pierde la información; no poner ningún except detiene el programa. log.exception da las dos cosas: el trabajo continúa, y queda un relato completo de lo que se rompió.

Cuando solo interesa el mensaje, log.error:

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")

try:
    int("x")
except ValueError as err:
    log.error("could not parse: %s", err)

print("done")

done

ERROR - could not parse: invalid literal for int() with base 10: 'x'

La regla es sencilla: log.exception dentro de un bloque except, log.error fuera de uno. exception solo tiene sentido mientras se está manejando un error.

%s en el mensaje, no una f-string

La forma habitual de escribir un mensaje en logging parece extraña al principio:

log.debug("line_total(%s, %s)", price, quantity)

La razón es la pereza: si el nivel descarta el mensaje, el texto nunca llega a montarse. Escrito como f-string, el montaje ocurriría antes, y el resultado se tiraría a la basura después.

El límite también conviene conocerlo:

import logging

logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")


def expensive():
    print("expensive() was called")
    return 42


log.debug("value is %s", expensive())
log.debug("value is %s", "cheap")
print("done")

expensive() was called
done

El mensaje no se imprimió, y expensive() se ejecutó igualmente. Lo que es perezoso es el formateo, no la evaluación de los argumentos — esos se calculan antes de que se llame a log.debug, porque así funciona cualquier llamada en Python.

Así que cuando algo costoso hace falta solo para depurar, pregunta antes: if log.isEnabledFor(logging.DEBUG):.

Escribir en un archivo

import logging
from pathlib import Path

logging.basicConfig(
    level=logging.INFO,
    format="%(levelname)s %(name)s - %(message)s",
    filename="run.log",
)

log = logging.getLogger("shop")
log.info("starting")
log.warning("something odd")

print("nothing was printed to the screen by logging")
print(Path("run.log").read_text(encoding="utf-8"), end="")

nothing was printed to the screen by logging
INFO shop - starting
WARNING shop - something odd

Con filename, los mensajes van a un archivo en lugar de a la pantalla — y no cambia ni una línea del código. Aquí es donde print y logging están más lejos el uno del otro: los módulos deciden qué se escribe, y main decide adónde va.

En la práctica, la hora también se pone en el format:

format="%(asctime)s %(levelname)-8s %(name)s - %(message)s"

lo que pone una fecha y una hora al principio de cada línea. Los ejemplos de este capítulo lo omiten, porque la salida sería distinta en cada ejecución — y lo que imprime un curso debería ser lo que imprime tu máquina.

Entrar dentro — breakpoint()

Un log dice qué pasó. A veces lo que se necesita es el estado en este momento.

def discount(price, rate):
    result = price * (1 - rate)
    breakpoint()
    return result


print(discount(100.0, 0.1))

Al llegar a breakpoint(), el programa se detiene y aparece un prompt. Una sesión tiene este aspecto — la primera línea lleva la ruta completa de tu archivo:

> .../main.py(4)discount()
-> return result
(Pdb) p price
100.0
(Pdb) p rate
0.1
(Pdb) p result
90.0
(Pdb) c
90.0

Unos pocos comandos cubren la mayor parte del trabajo:

• p <name> — imprime un valor (pp lo imprime con formato)
• n — la siguiente línea, sin entrar dentro de una función
• s — entra en la función
• c — sigue hasta la próxima parada
• l — muestra el código que rodea la posición actual
• q — sale

La ventaja sobre print es que no tienes que decidir de antemano lo que quieres ver. Una vez detenido, se puede imprimir cualquier nombre y ejecutar cualquier expresión.

Un ejemplo completo

pricing.py:

"""Prices and tax, with logging instead of prints."""

import logging

log = logging.getLogger(__name__)

TAX_RATE = 0.15


def line_total(price, quantity):
    log.debug("line_total(price=%s, quantity=%s)", price, quantity)
    if quantity < 1:
        raise ValueError(f"quantity must be at least 1: {quantity}")
    return round(price * quantity * (1 + TAX_RATE), 2)


def read_order(rows):
    """Returns the usable lines, logging and skipping the rest."""
    lines = []
    for number, row in enumerate(rows, start=1):
        try:
            name, price, quantity = row.split(",")
            lines.append((name, line_total(float(price), int(quantity))))
        except ValueError:
            log.warning("line %d skipped: %r", number, row)
    log.info("%d of %d lines usable", len(lines), len(rows))
    return lines

main.py:

import logging
import os

import pricing

logging.basicConfig(
    level=logging.DEBUG if os.environ.get("SHOP_DEBUG") else logging.INFO,
    format="%(levelname)-8s %(name)s - %(message)s",
)

log = logging.getLogger(__name__)

ROWS = ["pen,15.0,3", "bag,eight,1", "ink,120.0,2", "clip,5.0,0"]


def main():
    log.info("reading %d rows", len(ROWS))
    for name, amount in pricing.read_order(ROWS):
        print(f"{name:<6} {amount:>9.2f}")


if __name__ == "__main__":
    main()

Ejecutado simplemente como python main.py — las filas impresas:

pen        51.75
ink       276.00

Y en el log:

INFO     __main__ - reading 4 rows
WARNING  pricing - line 2 skipped: 'bag,eight,1'
WARNING  pricing - line 4 skipped: 'clip,5.0,0'
INFO     pricing - 2 of 4 lines usable

Ahora ejecútalo con SHOP_DEBUG=1, el mismo código:

INFO     __main__ - reading 4 rows
DEBUG    pricing - line_total(price=15.0, quantity=3)
WARNING  pricing - line 2 skipped: 'bag,eight,1'
DEBUG    pricing - line_total(price=120.0, quantity=2)
DEBUG    pricing - line_total(price=5.0, quantity=0)
WARNING  pricing - line 4 skipped: 'clip,5.0,0'
INFO     pricing - 2 of 4 lines usable

Cinco cosas que conviene mirar.

Un programa, dos volúmenes de salida, sin cambiar el código. Eso es este capítulo en miniatura. Hecho con print, el ciclo de añadir líneas y borrarlas de nuevo no terminaría nunca.

bag,eight,1 y clip,5.0,0 se saltaron por dos razones distintas, y un solo except ValueError capturó las dos. float("eight") lanza un ValueError, y line_total lanza uno por su cuenta cuando quantity=0. El diseño del capítulo 24 en acción: la función de abajo lanza el error, la de arriba lo captura y decide qué hacer.

El log de depuración muestra lo que el log normal no puede mostrar. Para la fila clip, line_total sí se llamó — la línea DEBUG ... quantity=0 lo demuestra — y luego lanzó el error. La fila bag no tiene línea DEBUG, porque float("eight") se rompió antes. Las dos filas aparecen como «saltadas», y se rompieron en lugares distintos, algo que solo el nivel debug revela.

El nivel viene del entorno, no del código. Para un programa que corre en un servidor, esa es la forma normal — cambiar una variable y volver a ejecutar, en lugar de editar un archivo y publicarlo de nuevo.

pricing.py no llama a basicConfig en ningún sitio. Solo escribe getLogger(__name__) y envía mensajes. A dónde van y cuántos son es decisión exclusiva de main. Por eso probar pricing, o usarlo en otro programa, no le quita el logging a nadie.

Cuando falla

No aparece nada en el log No se llamó a basicConfig, o el nivel es demasiado alto. El nivel por defecto es WARNING, así que log.info es invisible por defecto.

Llamé a basicConfig y no cambió nada Solo tiene efecto una vez — si el logging ya se ha iniciado en algún sitio, una llamada posterior se ignora en silencio. Llámalo una vez al principio de todo, o pasa force=True.

El nivel o el formato de main no tienen efecto, y no hay ningún error Una librería importada llamó a basicConfig por su cuenta, y eso se ejecutó antes que la llamada de main. Así que el basicConfig de main se ignora en silencio. Quita basicConfig de la librería — una librería usa solo getLogger(__name__).

El log no va al archivo El logging ya se había iniciado antes de que se diera filename. La regla del «una vez» otra vez.

Usé log.exception y no hay traceback Solo tiene traceback dentro de un bloque except. Fuera de uno, usa log.error.

Ejecuté python main.py > out.txt y el log no está en el archivo logging escribe en stderr. Usa 2> log.txt, o filename.

El traceback es largo y todo son archivos de librerías Léelo de abajo arriba, y busca el bloque más bajo que sea código tuyo. El problema casi siempre está ahí.

breakpoint() no hace nada Tienes la variable PYTHONBREAKPOINT=0 definida. Elimínala.

Tu turno

Toma el library.py que probaste en el capítulo 28 y sustituye cada print por logging.

• log = logging.getLogger(__name__) al principio del módulo
• Un mensaje debug en add(), con el título del libro
• Un warning cuando se salten datos incorrectos
• Un main.py que llame a basicConfig y tome el nivel de una variable de entorno
• Ningún basicConfig en library.py

Luego seis experimentos:

• Ejecuta con el nivel INFO, y después con DEBUG. ¿Hubo que cambiar algún código?
• Añade filename="run.log" a basicConfig. ¿Qué queda en pantalla?
• Llama también a basicConfig en library.py, con un nivel distinto al de main.py. ¿De quién es ahora el nivel que se usa — y por qué?
• Provoca un KeyError a propósito, y en el bloque except escribe una vez log.error(err) y una vez log.exception("..."). ¿Cuál es más útil, y por qué?
• Escribe log.debug("%s", expensive()), donde expensive() imprime algo, y deja el nivel en WARNING. ¿Se ejecuta expensive()?
• Pon un breakpoint() y explora con p, n y c.

El cuarto experimento es la última palabra de este capítulo. Cómo le va a un programa se sabe por lo que deja tras de sí — y un bloque except que no deja nada tras de sí solo ha aplazado la pregunta.

Qué sigue

Eso es el final del curso de Python. Después de 29 capítulos, puedes escribir un programa, manejar lo que se rompe, probarlo y ver lo que está haciendo — y esos últimos tres son los que lo mantienen vivo más allá de su primer día.

El siguiente paso ya no es aprender el lenguaje, sino hacer algo con él. El curso de pandas empieza justo ahí: los archivos CSV del capítulo 25, pero con miles de filas, y preguntas para las que un bucle ya no es una forma razonable de responder.