Tutorial de logging en Python

Si acabas de empezar con Python y quieres aprender más, haz el curso Introduction to Data Science in Python de DataCamp.

En general, el logging es una forma de mantener un registro generado por un programa informático. Un archivo de log suele contener un conjunto de eventos que ocurren en tu código (por ejemplo, un script de Python) o en un sistema operativo. Estos eventos o mensajes se escriben en un archivo de log; un mensaje o evento también puede ser una comunicación entre distintos usuarios.

Normalmente depende de los desarrolladores decidir cómo quieren generar los logs. Puede que quieran registrar cada operación de una aplicación que han desarrollado, hacerlo solo cuando ocurre un error, o monitorizar y registrar operaciones clave realizadas por un usuario. Una operación esencial podría ser comprobar qué usuario final o dirección IP accedió a la aplicación o al servidor y, en caso de intento fallido, el desarrollador podría apoyarse en los logs para obtener información mucho más útil que un simple stack trace.

Un buen ejemplo es cuando intentas instalar algo en Linux como usuario sudo sin serlo. Verás el mensaje "Xyz is not in the sudoers file. This incident will be reported", que se escribe en un archivo de log.

La buena noticia es que Python incluye un módulo de logging y puedes usarlo tal cual, sin instalar nada.

¿En qué se diferencia el logging de la función Print?

El logging se parece en espíritu a una Print Function. Sin embargo, una función print carece de mucha información que puede ser útil para un desarrollador. El logging, en cambio, puede incluir marcas de tiempo y el número de línea donde ocurrió el error. Puede enviar errores o cualquier información a archivos, sockets, etc., y te ofrece cinco niveles de severidad para diferenciar tus registros.

Los cinco niveles de logging, como se muestra aquí, son:

• Debug (10): útil para diagnosticar problemas en el código.

• Info (20): puede actuar como confirmación de que no hay errores en el código. Un buen caso de uso a nivel Info es el progreso del entrenamiento de un modelo de machine learning.

• Warning (30): indica un problema que podría aparecer en el futuro. Por ejemplo, el aviso de que un módulo va a quedar obsoleto o una alerta de memoria RAM baja.

• Error (40): un fallo serio en el código; puede ser un error de sintaxis, falta de memoria, excepciones, etc.

• Critical (50): un error por el que el programa puede dejar de funcionar o cerrarse de forma abrupta.

Suficiente teoría, ¿verdad?

Veamos ahora cómo implementar logging en un script de Python.

Pero antes, revisa la tabla de atributos de logging: usarás algunos de los siguientes en este tutorial.

import logging

Ahora vas a llamar al método basicConfig(), que te ayuda a crear una configuración básica para que el sistema de logging funcione sin problemas.

Te permite definir los siguientes parámetros:

• la severidad del logging: los cinco niveles de logging.
• guardar los eventos en un archivo.
• registrar solo los logs actuales sobrescribiendo los anteriores mediante filemode.
• el formato en el que se almacenan los logs.

Recuerda que el método basicConfig() es opcional y podrías omitirlo.

logging.basicConfig()

Vamos a construir ahora los cinco niveles de severidad.

logging.debug("A Debug Logging Message")

logging.info("A Info Logging Message")

logging.warning("A Warning Logging Message")

WARNING:root:A Warning Logging Message

logging.error("An Error Logging Message")

ERROR:root:An Error Logging Message

logging.critical("A Critical Logging Message")

CRITICAL:root:A Critical Logging Message

Como puedes observar en las salidas anteriores, solo se registran las que tienen un nivel de severidad mayor que 20, ya que esa es la configuración por defecto del logging en Python.

No obstante, como hemos comentado, puedes modificar los niveles de severidad con el método basicConfig(). Aquí cambiamos el nivel a 20, lo que significa que se registrarán los niveles con severidad mayor que 10.

Nota: reinicia el kernel antes de ejecutar las celdas de abajo para ver la salida correcta.

import logging

logging.basicConfig(level=logging.INFO)

logging.debug("A Debug Logging Message")

logging.info("A Info Logging Message")

INFO:root:A Info Logging Message

logging.warning("A Warning Logging Message")

WARNING:root:A Warning Logging Message

logging.error("An Error Logging Message")

ERROR:root:An Error Logging Message

logging.critical("A Critical Logging Message")

CRITICAL:root:A Critical Logging Message

Ahora vamos a guardar las salidas anteriores en un archivo de log. Para ello, usarás el método basicConfig().

import logging

logging.basicConfig(level = logging.INFO, filename = 'datacamp.log')

logging.debug("A Debug Logging Message")

logging.info("A Info Logging Message")

logging.warning("A Warning Logging Message")

logging.error("An Error Logging Message")

logging.critical("A Critical Logging Message")

Como ves, ahora los logs se generan en el archivo datacamp.log. Si ejecutas las celdas anteriores varias veces, notarás que los logs se irán añadiendo al archivo cada vez. Por defecto, el archivo se abre en modo append.

Puedes usar la palabra clave filemode para evitar que el archivo de log acumule múltiples copias de los registros (modo append). Puedes cambiar filemode a modo write, que sobrescribirá los logs anteriores y guardará solo los actuales. Como filemode está establecido en w, el archivo de log se abrirá en write mode cada vez que se ejecute basicConfig(), sobrescribiendo el archivo.

La funcionalidad de file mode en logging es similar al manejo de archivos estándar que ofrece Python.

import logging

logging.basicConfig(level = logging.INFO, filename = 'datacamp.log', filemode = 'w')

logging.debug("A Debug Logging Message")
logging.info("A Info Logging Message")
logging.warning("A Warning Logging Message")
logging.error("An Error Logging Message")
logging.critical("A Critical Logging Message")

Ejecuta varias veces las líneas de código anteriores. Verás que ahora solo se guardan las entradas actuales y las anteriores se sobrescriben, como se muestra abajo.

Veamos más atributos de logging como la fecha, la hora o el número de línea en el que se generó un warning o un error. Estarás de acuerdo en que todo esto son ventajas frente a un simple print y que logging es mucho más potente.

Para conseguirlo, vas a pasar los atributos asctime y lineno. También pasarás el atributo message, que será un marcador de posición para el mensaje que quieras mostrar en los logs. Todos estos atributos se pasan al parámetro format.

import logging

logging.basicConfig(format='Date-Time : %(asctime)s : Line No. : %(lineno)d - %(message)s', \
                    level = logging.DEBUG)

logging.debug("A Debug Logging Message")
logging.info("A Info Logging Message")
logging.warning("A Warning Logging Message")
logging.error("An Error Logging Message")
logging.critical("A Critical Logging Message")

Date-Time : 2020-03-18 23:58:12,429 : Line No. : 1 - A Debug Logging Message
Date-Time : 2020-03-18 23:58:12,436 : Line No. : 2 - A Info Logging Message
Date-Time : 2020-03-18 23:58:12,437 : Line No. : 3 - A Warning Logging Message
Date-Time : 2020-03-18 23:58:12,440 : Line No. : 4 - An Error Logging Message
Date-Time : 2020-03-18 23:58:12,441 : Line No. : 5 - A Critical Logging Message

Veamos las definiciones de cada atributo directamente de esta tabla.

• asctime: hora legible por humanos cuando se generó el LogRecord. Por defecto tiene el formato 2020-03-18 22:24:42,670 (los números tras la coma son los milisegundos). Como este atributo es una cadena, se usa la marca s después.

• lineno: número de línea fuente donde se invocó la llamada a logging. Como es un entero, se usa la marca d después.

• message: el mensaje registrado, calculado como msg % args. Se establece al invocar Formatter.format(). Si no especificas este atributo al usar el parámetro format(), no se generarán los mensajes que quieras registrar. Del mismo modo, para message se usa s porque es una cadena.

• funcName: muestra el módulo o el nombre de la función en la que se genera el log. Es útil cuando tienes muchas funciones en tu código y quieres separar los logs según la función o método al que pertenecen.

Veamos un ejemplo sencillo para sustituir la función print por logging a nivel debug.

import logging

logging.basicConfig(format='%(asctime)s :: %(levelname)s :: %(funcName)s :: %(lineno)d \
:: %(message)s', level = logging.INFO)

def addition(x, y):
    add = x + y
    return add


def subtract(x, y):
    sub = x - y
    return sub


def multiply(x, y):
    mul = x * y
    return mul


def divide(x, y):
    div = x / y
    return div

def exponent(x, y):
    exp = x ** y
    return exp


num1 = 20
num2 = 2

def main():
    add_result = addition(num1, num2)
    logging.info('Add: {} + {} = {}'.format(num1, num2, add_result))

    sub_result = subtract(num1, num2)
    logging.info('Sub: {} - {} = {}'.format(num1, num2, sub_result))

    mul_result = multiply(num1, num2)
    logging.info('Mul: {} * {} = {}'.format(num1, num2, mul_result))

    div_result = divide(num1, num2)
    logging.info('Div: {} / {} = {}'.format(num1, num2, div_result))

    exp_result = exponent(num1, num2)
    logging.info('Exp: {} ** {} = {}'.format(num1, num2, exp_result))


main()

2020-03-19 00:01:27,372 :: INFO :: main :: 35 :: Add: 20 + 2 = 22
2020-03-19 00:01:27,376 :: INFO :: main :: 38 :: Sub: 20 - 2 = 18
2020-03-19 00:01:27,377 :: INFO :: main :: 41 :: Mul: 20 * 2 = 40
2020-03-19 00:01:27,378 :: INFO :: main :: 44 :: Div: 20 / 2 = 10.0
2020-03-19 00:01:27,379 :: INFO :: main :: 47 :: Exp: 20 ** 2 = 400

Conclusión

Enhorabuena por completar el tutorial.

Te animamos a probar otros atributos de logging y entender cómo puedes aprovecharlos en tu código.

No dudes en dejar cualquier pregunta relacionada con este tutorial en los comentarios de abajo.

Si acabas de empezar con Python y quieres aprender más, haz el curso Introduction to Data Science in Python de DataCamp.