Cómo Usar el Registro en Python 3

Introducción

El módulo logging forma parte de la biblioteca estándar de Python y proporciona seguimiento de eventos que ocurren mientras se ejecuta el software. Puedes agregar llamadas de registro a tu código para indicar qué eventos han ocurrido.

El módulo logging permite tanto el registro de diagnóstico que registra eventos relacionados con la operación de una aplicación, como el registro de auditoría que registra los eventos de las transacciones de un usuario para su análisis. Se utiliza especialmente para registrar eventos en un archivo.

Prerrequisitos

Debes tener instalado Python 3 y configurado un entorno de programación en tu computadora o servidor. Si no tienes configurado un entorno de programación, puedes consultar las guías de instalación y configuración para un entorno de programación local o para un entorno de programación en tu servidor apropiado para tu sistema operativo (Ubuntu, CentOS, Debian, etc.).

Por qué usar el módulo logging

El módulo logging mantiene un registro de los eventos que ocurren dentro de un programa, lo que permite ver la salida relacionada con cualquiera de los eventos que ocurren durante la ejecución de un software.

Es posible que estés más familiarizado con verificar que los eventos estén ocurriendo mediante el uso de la declaración print() en todo tu código. La declaración print() proporciona una forma básica de depurar tu código para resolver problemas. Si bien incrustar declaraciones print() en todo tu código puede rastrear el flujo de ejecución y el estado actual de tu programa, esta solución resulta ser menos mantenible que usar el módulo logging por algunas razones:

• Se vuelve difícil distinguir entre la salida de depuración y la salida normal del programa porque ambas están mezcladas
• Cuando se usan declaraciones print() dispersas en el código, no hay una manera eficiente de desactivar las que proporcionan salida de depuración
• Se vuelve difícil eliminar todas las declaraciones print() cuando hayas terminado de depurar
• No hay un registro de registro que contenga información diagnóstica disponible fácilmente

Es una buena idea adquirir el hábito de usar el módulo logging en tu código, ya que esto es más adecuado para aplicaciones que crecen más allá de simples scripts de Python y proporciona un enfoque sostenible para la depuración.

Porque los registros pueden mostrar comportamientos y errores a lo largo del tiempo, también pueden ofrecerte una imagen general mejor de lo que está ocurriendo en tu proceso de desarrollo de aplicaciones.

Impresión de mensajes de depuración en la consola

Si estás acostumbrado a usar la declaración print() para ver lo que está ocurriendo en un programa, es posible que estés acostumbrado a ver un programa que define una clase e instancia objetos que genera algo como esto:

class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        print("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        print("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        print("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("artichoke", 15)
pizza_01.make()
pizza_01.eat()

pizza_02 = Pizza("margherita", 12)
pizza_02.make(2)
pizza_02.eat()

El código anterior tiene un método __init__ para definir el nombre y el precio de un objeto de la clase Pizza. Luego tiene dos métodos, uno llamado make() para hacer pizzas, y otro llamado eat() para comer pizzas. Estos dos métodos toman como parámetro cantidad, que se inicializa en 1.

Ahora vamos a ejecutar el programa:

python pizza.py

Recibiremos la siguiente salida:

Output
Pizza created: artichoke ($15)
Made 1 artichoke pizza(s)
Ate 1 pizza(s)
Pizza created: margherita ($12)
Made 2 margherita pizza(s)
Ate 1 pizza(s)

Mientras que la declaración print() nos permite ver que el código está funcionando, podemos usar el módulo logging para hacer esto en su lugar.

Vamos a eliminar o comentar las declaraciones print() a lo largo del código, y agregar import logging en la parte superior del archivo:

import logging


class Pizza():
    def __init__(self, name, value):
        self.name = name
        self.value = value
...

El módulo logging tiene un nivel predeterminado de WARNING, que es un nivel superior a DEBUG. Dado que vamos a utilizar el módulo logging para depurar en este ejemplo, necesitamos modificar la configuración para que el nivel de logging.DEBUG devuelva información a la consola para nosotros. Podemos hacer eso agregando la siguiente línea debajo de la declaración de importación:

import logging

logging.basicConfig(level=logging.DEBUG)


class Pizza():
...

Este nivel de logging.DEBUG se refiere a un valor entero constante que referenciamos en el código anterior para establecer un umbral. El nivel de DEBUG es 10.

Ahora, vamos a reemplazar todas las declaraciones print() con declaraciones logging.debug() en su lugar. A diferencia de logging.DEBUG que es una constante, logging.debug() es un método del módulo logging. Al trabajar con este método, podemos hacer uso de la misma cadena pasada a print(), como se muestra a continuación:

import logging

logging.basicConfig(level=logging.DEBUG)


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("artichoke", 15)
pizza_01.make()
pizza_01.eat()

pizza_02 = Pizza("margherita", 12)
pizza_02.make(2)
pizza_02.eat()

En este punto, cuando ejecutemos el programa con el comando python pizza.py, recibiremos esta salida:

Output
DEBUG:root:Pizza created: artichoke ($15)
DEBUG:root:Made 1 artichoke pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: margherita ($12)
DEBUG:root:Made 2 margherita pizza(s)
DEBUG:root:Ate 1 pizza(s)

Los mensajes de registro tienen el nivel de gravedad DEBUG así como la palabra root incrustada en ellos, lo que se refiere al nivel de su módulo de Python. El módulo logging se puede usar con una jerarquía de registradores que tienen diferentes nombres, para que pueda usar un registrador diferente para cada uno de sus módulos.

Por ejemplo, puede establecer registradores iguales a diferentes registradores que tienen nombres y salidas diferentes:

logger1 = logging.getLogger("module_1")
logger2 = logging.getLogger("module_2")

logger1.debug("Module 1 debugger")
logger2.debug("Module 2 debugger")

Output
DEBUG:module_1:Module 1 debugger
DEBUG:module_2:Module 2 debugger

Ahora que entendemos cómo usar el módulo logging para imprimir mensajes en la consola, pasemos a usar el módulo logging para imprimir mensajes en un archivo.

Registro de mensajes en un archivo

El propósito principal del módulo logging es registrar mensajes en un archivo en lugar de en una consola. Mantener un archivo de mensajes le proporciona datos con el tiempo que puede consultar y cuantificar para ver qué cambios deben hacerse en su código.

Para comenzar a registrar en un archivo, podemos modificar el método logging.basicConfig() para incluir un parámetro filename. En este caso, llamemos al archivo test.log:

import logging

logging.basicConfig(filename="test.log", level=logging.DEBUG)


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("artichoke", 15)
pizza_01.make()
pizza_01.eat()

pizza_02 = Pizza("margherita", 12)
pizza_02.make(2)
pizza_02.eat()

El código anterior es el mismo que estaba en la sección anterior, excepto que ahora agregamos el nombre de archivo para que el registro se imprima en él. Una vez que ejecutemos el código con el comando python pizza.py, deberíamos tener un nuevo archivo en nuestro directorio llamado test.log.

Abramos el archivo test.log con nano (o el editor de texto que prefieras):

nano test.log

Al abrir el archivo, recibiremos lo siguiente:

DEBUG:root:Pizza created: artichoke ($15)
DEBUG:root:Made 1 artichoke pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: margherita ($12)
DEBUG:root:Made 2 margherita pizza(s)
DEBUG:root:Ate 1 pizza(s)

Esto es similar a la salida de la consola que encontramos en la sección anterior, excepto que ahora está en el archivo test.log.

Cerremos el archivo con CTRL + x y volvamos al archivo pizza.py para que podamos modificar el código.

Mantendremos gran parte del código igual, pero modificaremos los parámetros en las dos instancias de pizza, pizza_01 y pizza_02:

import logging

logging.basicConfig(filename="test.log", level=logging.DEBUG)


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

# Modificar los parámetros del objeto pizza_01
pizza_01 = Pizza("Sicilian", 18)
pizza_01.make(5)
pizza_01.eat(4)

# Modificar los parámetros del objeto pizza_02
pizza_02 = Pizza("quattro formaggi", 16)
pizza_02.make(2)
pizza_02.eat(2)

Con estos cambios, ejecutemos el programa nuevamente con el comando python pizza.py.

Una vez que el programa se haya ejecutado, podemos abrir nuestro archivo test.log nuevamente con nano:

nano test.log

Al revisar el archivo, veremos que se agregaron varias líneas nuevas y que las líneas anteriores de la última vez que se ejecutó el programa se conservaron:

DEBUG:root:Pizza created: artichoke ($15)
DEBUG:root:Made 1 artichoke pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: margherita ($12)
DEBUG:root:Made 2 margherita pizza(s)
DEBUG:root:Ate 1 pizza(s)
DEBUG:root:Pizza created: Sicilian ($18)
DEBUG:root:Made 5 Sicilian pizza(s)
DEBUG:root:Ate 4 pizza(s)
DEBUG:root:Pizza created: quattro formaggi ($16)
DEBUG:root:Made 2 quattro formaggi pizza(s)
DEBUG:root:Ate 2 pizza(s)

Aunque esta información ciertamente es útil, podemos hacer que el registro sea más informativo agregando atributos adicionales de LogRecord. Principalmente, nos gustaría agregar una marca de tiempo legible por humanos que nos indique cuándo se creó el LogRecord.

Podemos agregar ese atributo a un parámetro llamado format, haciendo referencia a él como se muestra en la tabla con la cadena %(asctime)s. Además, para mantener el nombre del nivel DEBUG, necesitaremos incluir la cadena %(levelname)s y para mantener el mensaje que solicitamos al registrador que imprima, incluiremos %(message)s. Cada uno de estos atributos estará separado por dos puntos (colon), como se muestra en el código añadido:

import logging

logging.basicConfig(
    filename="test.log",
    level=logging.DEBUG,
    format="%(asctime)s:%(levelname)s:%(message)s"
    )


class Pizza():
    def __init__(self, name, price):
        self.name = name
        self.price = price
        logging.debug("Pizza created: {} (${})".format(self.name, self.price))

    def make(self, quantity=1):
        logging.debug("Made {} {} pizza(s)".format(quantity, self.name))

    def eat(self, quantity=1):
        logging.debug("Ate {} pizza(s)".format(quantity, self.name))

pizza_01 = Pizza("Sicilian", 18)
pizza_01.make(5)
pizza_01.eat(4)

pizza_02 = Pizza("quattro formaggi", 16)
pizza_02.make(2)
pizza_02.eat(2)

Cuando ejecutamos el código anterior con los atributos añadidos con el comando python pizza.py, obtendremos nuevas líneas añadidas a nuestro archivo test.log que incluyen la marca de tiempo legible por humanos además del nombre del nivel DEBUG y los mensajes asociados que se pasan al registrador como cadenas.

DEBUG:root:Pizza created: Sicilian ($18)
DEBUG:root:Made 5 Sicilian pizza(s)
DEBUG:root:Ate 4 pizza(s)
DEBUG:root:Pizza created: quattro formaggi ($16)
DEBUG:root:Made 2 quattro formaggi pizza(s)
DEBUG:root:Ate 2 pizza(s)
2021-08-19 23:31:34,484:DEBUG:Pizza created: Sicilian ($18)
2021-08-19 23:31:34,484:DEBUG:Made 5 Sicilian pizza(s)
2021-08-19 23:31:34,484:DEBUG:Ate 4 pizza(s)
2021-08-19 23:31:34,484:DEBUG:Pizza created: quattro formaggi ($16)
2021-08-19 23:31:34,484:DEBUG:Made 2 quattro formaggi pizza(s)
2021-08-19 23:31:34,484:DEBUG:Ate 2 pizza(s)

Dependiendo de sus necesidades, es posible que desee hacer uso de atributos adicionales de registros de eventos (LogRecord) en su código para que los registros de archivos de su programa sean relevantes para usted.

Registrar mensajes de depuración y otros mensajes en archivos separados le proporciona una comprensión holística de su programa Python a lo largo del tiempo, brindándole la oportunidad de solucionar problemas y modificar su código de manera que esté informada por el trabajo histórico realizado en el programa, así como los eventos y transacciones que ocurran.

Tabla de Niveles de Registro

Como desarrollador, puedes asignar un nivel de importancia al evento capturado en el registro agregando un nivel de gravedad. Los niveles de gravedad se muestran en la tabla a continuación.

Los niveles de registro son técnicamente enteros (una constante), y todos están en incrementos de 10, comenzando con NOTSET, que inicializa el registro en el valor numérico de 0.

También puedes definir tus propios niveles relativos a los niveles predefinidos. Si defines un nivel con el mismo valor numérico, sobrescribirás el nombre asociado con ese valor.

La siguiente tabla muestra los diversos nombres de nivel, su valor numérico, qué función puedes usar para llamar al nivel y para qué se utiliza ese nivel.

El módulo logging establece el nivel predeterminado en WARNING, por lo que WARNING, ERROR y CRITICAL se registrarán todos de forma predeterminada. En el ejemplo anterior, modificamos la configuración para incluir el nivel DEBUG con el siguiente código:

logging.basicConfig(level=logging.DEBUG)

Puedes obtener más información sobre los comandos y cómo trabajar con el depurador desde la documentación oficial de logging.

Conclusión

La depuración es un paso importante de cualquier proyecto de desarrollo de software. El módulo logging es parte de la biblioteca estándar de Python, proporciona seguimiento de eventos que ocurren mientras el software se ejecuta y puede generar estos eventos en un archivo de registro separado para permitirte realizar un seguimiento de lo que ocurre mientras se ejecuta tu código. Esto te brinda la oportunidad de depurar tu código basándote en la comprensión de los diversos eventos que ocurren al ejecutar tu programa con el tiempo.