Registro en Python – Guía sencilla con código completo y ejemplos

El módulo de registro te permite monitorizar las ejecuciones de tu código para que cuando éste se cuelgue puedas comprobar los registros e identificar la causa. Los mensajes de registro tienen una jerarquía incorporada – empezando por los mensajes de depuración, informativos, de advertencia, de error y críticos. También se puede incluir información de rastreo. Está diseñado para proyectos python pequeños y grandes con múltiples módulos y es muy recomendable para cualquier programación modular python. Este post es una explicación sencilla y clara de cómo utilizar el módulo de logging.

Logging en Python – Guía simplificada con código completo y ejemplos. Foto de Andrea Reiman.

Contenido

1. 1. ¿Por qué hacer logging?
   2. Un ejemplo básico de logging
   3. Los 5 niveles de logging
   4. Cómo registrar en un archivo en lugar de en la consola
   5. Cómo cambiar el formato de logging
   6. Por qué trabajar con el logger raíz para todos los módulos no es la mejor idea
   7. ¿Cómo crear un nuevo logger?
   8. ¿Qué es y cómo configurar un File Handler y Formatter?
   9. Cómo incluir información de rastreo en los mensajes registrados
   10. Ejercicios
   11. Conclusión

¿Por qué registrar?

Imagina que estás ejecutando un script de python, y quieres saber qué parte del script se ha ejecutado, en qué momento y, en ciertos casos, inspeccionar qué valores tienen las variables.

Usualmente, puede que sólo ‘print()‘ fuera mensajes significativos para poder verlos en la consola. Y esto probablemente es todo lo que necesitas cuando desarrollas programas pequeños.

El problema es: cuando utilizas este enfoque en proyectos más grandes que contienen muchos módulos quieres un enfoque más estructurado y robusto.

¿Por qué?

Porque, el código podría pasar por diferentes etapas como en el desarrollo, la depuración, la revisión, las pruebas o pasa a producción quieres ver diferentes niveles de detalles en los mensajes impresos.

El tipo de mensajes que quieres imprimir durante el desarrollo o la depuración puede ser muy diferente de lo que quieres ver una vez que pasa a producción. Dependiendo del propósito, querrás que el código imprima diferentes tipos de mensajes.

Imagina hacer todo esto con sólo las sentencias if else y print.

Además, hay un cierto nivel de jerarquía necesario en los mensajes impresos.

Es decir, durante una determinada ejecución de ‘prueba’, usted quiere ver sólo advertencias y mensajes de error. Mientras que durante la ‘depuración’, se necesitan mensajes más detallados que ayuden a la depuración. Además, si se quiere imprimir en qué módulo y en qué momento se ejecutaron los códigos, el script de python se vuelve desordenado.

Todos estos problemas se resuelven muy bien con el módulo logging.

Usando el registro, puedes:

1. Controlar el nivel de los mensajes para registrar sólo los necesarios
2. Controlar dónde mostrar o guardar los registros
3. Controlar cómo formatear los registros con plantillas de mensajes incorporadas
4. .en las plantillas de mensajes
5. Saber de qué módulo vienen los mensajes

Podrías decir ‘veo que logging puede ser útil pero parece demasiado técnico y parece un poco difícil de entender’. Pues sí, logging requiere un poco de curva de aprendizaje pero para eso está este post: hacer que el logging sea fácil de aprender.

Sin más dilación, vamos a entrar en materia.

Un ejemplo básico de logging

Python proporciona un módulo logging incorporado que forma parte de la biblioteca estándar de python. Así que no necesitas instalar nada.

Para usar el registro, todo lo que necesitas es establecer la configuración básica usando logging.basicConfig(). En realidad, esto también es opcional. Lo veremos pronto.

Entonces, en lugar de print(), se llama a logging.{level}(message) para mostrar el mensaje en consola.

import logginglogging.basicConfig(level=logging.INFO)def hypotenuse(a, b): """Compute the hypotenuse""" return (a**2 + b**2)**0.5logging.info("Hypotenuse of {a}, {b} is {c}".format(a=3, b=4, c=hypotenuse(a,b)))#> INFO:root:Hypotenuse of 3, 4 is 5.0

El mensaje de registro impreso tiene el siguiente formato por defecto: {Nivel}:{Logger}:{Mensaje}.

En el caso anterior, el nivel es info, porque, he llamado a logging.info().

El logger se llama root, porque es el logger por defecto y no he creado uno nuevo, todavía.

Pero, ¿qué es un logger?

Un logger es como una entidad que puedes crear y configurar para que registre diferentes tipos y formatos de mensajes.

Puedes configurar un logger que imprima en la consola y otro logger que envíe los registros a un archivo, tenga un nivel de registro diferente y sea específico para un módulo determinado. Más explicaciones y ejemplos próximamente sobre esto.

Finalmente, el mensaje es la cadena que le pasé a logging.info().

Ahora, ¿qué hubiera pasado si no hubieras configurado logging.basicConfig(level=logging.INFO)?

Respuesta: El log no se hubiera impreso.

¿Por qué?

Para saber eso entendamos los niveles de logging.

Los 5 niveles de logging

logging tiene 5 niveles jerárquicos diferentes de logs a los que se puede configurar un determinado logger.

Veamos qué dice la documentación de python sobre cada nivel:

1. DEBUG: Información detallada, para diagnosticar problemas. Valor=10.
2. INFO: Confirma que las cosas funcionan como se espera. Valor=20.
3. ADVERTENCIA: Ha ocurrido algo inesperado, o indicativo de algún problema. Pero el software sigue funcionando como se esperaba. Valor=30.
4. ERROR: Problema más grave, el software no es capaz de realizar alguna función. Valor=40
5. Crítico: Un error grave, el propio programa puede ser incapaz de seguir funcionando. Valor=50

Ahora, volviendo a la pregunta anterior de qué hubiera pasado si no se hubiera configurado logging.basicConfig(level=logging.INFO) en el ejemplo anterior.

La respuesta es: el log no se hubiera impreso porque, el logger por defecto es el ‘root’ y su nivel basicConfig por defecto es ‘WARNING’. Esto significa que sólo se imprimen los mensajes de logging.warning() y niveles superiores.

Así que el mensaje de logging.info() no se imprimiría. Y por eso la configuración básica se puso como INFO inicialmente (en logging.basicConfig(level=logging.INFO)).

Si hubiera puesto el nivel como logging.ERROR en su lugar, sólo se registrarían los mensajes de logging.error y logging.critical. ¿Está claro?

import logginglogging.basicConfig(level=logging.WARNING)def hypotenuse(a, b): """Compute the hypotenuse""" return (a**2 + b**2)**0.5kwargs = {'a':3, 'b':4, 'c':hypotenuse(3, 4)}logging.debug("a = {a}, b = {b}".format(**kwargs))logging.info("Hypotenuse of {a}, {b} is {c}".format(**kwargs))logging.warning("a={a} and b={b} are equal".format(**kwargs))logging.error("a={a} and b={b} cannot be negative".format(**kwargs))logging.critical("Hypotenuse of {a}, {b} is {c}".format(**kwargs))#> WARNING:root:a=3 and b=3 are equal#> ERROR:root:a=-1 and b=4 cannot be negative#> CRITICAL:root:Hypotenuse of a, b is 5.0

Cómo registrar en un archivo en lugar de la consola

Para enviar los mensajes de registro a un archivo desde el logger raíz, necesitas establecer el argumento archivo en logging.basicConfig()

import logginglogging.basicConfig(level=logging.INFO, file='sample.log')

Ahora todos los mensajes de registro posteriores irán directamente al archivo ‘sample.log’ en su directorio de trabajo actual. Si quieres enviarlo a un archivo en un directorio diferente, da la ruta completa del archivo.

Cómo cambiar el formato de registro

El módulo de registro proporciona atajos para añadir varios detalles a los mensajes registrados. La siguiente imagen de los documentos de Python muestra esa lista.



Cambiemos el formato del mensaje de registro para mostrar la HORA, el NIVEL y el MENSAJE. Para ello sólo hay que añadir el formato al argumento format de logging.basiconfig().

import logginglogging.basicConfig(level=logging.INFO, format='%(asctime)s :: %(levelname)s :: %(message)s')logging.info("Just like that!")#> 2019-02-17 11:40:38,254 :: INFO :: Just like that!

6. Por qué trabajar con el logger raíz para todos los módulos no es la mejor idea

Porque todos ellos compartirán el mismo logger ‘raíz’.

Pero, ¿por qué es eso malo?

Miremos el siguiente código:

# 1. code inside myprojectmodule.pyimport logginglogging.basicConfig(file='module.log')#-----------------------------# 2. code inside main.py (imports the code from myprojectmodule.py)import loggingimport myprojectmodule # This runs the code in myprojectmodule.pylogging.basicConfig(file='main.log') # No effect, because!

Imagina que tienes uno o más módulos en tu proyecto. Y estos módulos utilizan el módulo raíz básico. Entonces, al importar el módulo (‘myprojectmodule.py‘), se ejecutará todo el código de ese módulo y se configurará el logger.

Una vez configurado, el logger raíz en el archivo principal (que importó el módulo ‘myprojectmodule‘) ya no podrá cambiar la configuración del logger raíz. Porque, el logging.basicConfig() una vez configurado no se puede cambiar.

Es decir, si quieres registrar los mensajes de myprojectmodule en un archivo y los logs del módulo principal en otro archivo, el root logger no puede eso.

Para ello necesitas crear un nuevo logger.

¿Cómo crear un nuevo logger?

Puedes crear un nuevo logger usando el método logger.getLogger(name). Si existe un logger con el mismo nombre, entonces se utilizará ese logger.

Aunque se puede dar cualquier nombre al registrador, la convención es usar la variable __name__ así:

logger = logging.getLogger(__name__)logger.info('my logging message')

Pero, ¿por qué usar __name__ como nombre del registrador, en lugar de codificar un nombre?

Porque la variable __name__ contendrá el nombre del módulo (archivo python) que llamó al código. Así, cuando se utilice dentro de un módulo, creará un registrador que lleve el valor proporcionado por el atributo __name__ del módulo.

Al hacer esto, si en el futuro acabas cambiando el nombre del módulo (nombre del archivo), no tendrás que modificar el código interno.

Ahora, una vez que hayas creado un nuevo logger, debes recordar registrar todos tus mensajes usando el nuevo logger.info() en lugar del método logging.info() de la raíz.

Otro aspecto a tener en cuenta es que todos los loggers tienen una jerarquía incorporada.

¿Qué quiero decir con esto?

Por ejemplo, si has configurado el logger raíz para que registre los mensajes en un archivo concreto. También tienes un logger personalizado para el que no has configurado el manejador de archivos para que envíe los mensajes a consola o a otro archivo de registro.

En este caso, el logger personalizado retrocederá y escribirá en el archivo configurado por el propio logger raíz. Hasta que y a menos que configure el archivo de registro de su logger personalizado.

Entonces, ¿qué es un manejador de archivos y cómo configurar uno?

¿Qué es y cómo configurar un manejador y formateador de archivos?

Las clases FileHandler() y Formatter() se utilizan para configurar el archivo de salida y el formato de los mensajes para los loggers distintos al logger raíz.

¿Recuerdas cómo configuramos antes el nombre del archivo y el formato del mensaje en el logger raíz (dentro de logging.basicConfig())?

Sólo especificamos los parámetros filename y format en logging.basicConfig() y todos los logs posteriores iban a ese archivo.

Sin embargo, cuando creas un logger separado, necesitas configurarlos individualmente usando los objetos logging.FileHandler() y logging.Formatter().

Un FileHandler se usa para hacer que tu logger personalizado se registre en un archivo diferente. Del mismo modo, un Formatter se utiliza para cambiar el formato de sus mensajes registrados.

import logging# Gets or creates a loggerlogger = logging.getLogger(__name__) # set log levellogger.setLevel(logging.WARNING)# define file handler and set formatterfile_handler = logging.FileHandler('logfile.log')formatter = logging.Formatter('%(asctime)s : %(levelname)s : %(name)s : %(message)s')file_handler.setFormatter(formatter)# add file handler to loggerlogger.addHandler(file_handler)# Logslogger.debug('A debug message')logger.info('An info message')logger.warning('Something is not right.')logger.error('A Major error has happened.')logger.critical('Fatal error. Cannot continue')

Nota cómo establecemos el formateador en el file_handler y no en el logger directamente.

Suponiendo que el código anterior se ejecuta desde el programa principal, si se mira dentro del directorio de trabajo, se creará un fichero llamado logfile.log si no existe y contendría los siguientes mensajes.

#> 2019-02-17 12:40:14,797 : WARNING : __main__ : Something is not right.#> 2019-02-17 12:40:14,798 : ERROR : __main__ : A Major error has happened.#> 2019-02-17 12:40:14,798 : CRITICAL : __main__ : Fatal error. Cannot continue

Nota de nuevo, el Formatter se establece en el objeto FileHandler y no directamente en el logger. Algo a lo que quizás quieras acostumbrarte.

Cómo incluir información de rastreo en los mensajes registrados

Además de ‘debuginfowarningerror‘, y ‘critical‘ mensajes, puedes registrar excepciones que incluirán cualquier información de rastreo asociada.

Con logger.exception, puedes registrar información de rastreo si el código encuentra algún error. logger.exception registrará el mensaje proporcionado en sus argumentos, así como la información de rastreo del mensaje de error.

A continuación se muestra un buen ejemplo.

import logging# Create or get the loggerlogger = logging.getLogger(__name__) # set log levellogger.setLevel(logging.INFO)def divide(x, y): try: out = x / y except ZeroDivisionError: logger.exception("Division by zero problem") else: return out# Logslogger.error("Divide {x} / {y} = {c}".format(x=10, y=0, c=divide(10,0)))#> ERROR:__main__:Division by zero problem#> Traceback (most recent call last):#> File "<ipython-input-16-a010a44fdc0a>", line 12, in divide#> out = x / y#> ZeroDivisionError: division by zero#> ERROR:__main__:None

Ejercicios

1. Crea un nuevo directorio de proyecto y un nuevo archivo python llamado ‘example.py‘. Importa el módulo de logging y configura el logger raíz al nivel de mensajes ‘debug’. Registra un mensaje ‘info’ con el texto: «¡Este es el mensaje de registro del root logger!».
2. Configure el root logger para que formatee el mensaje «¡Este es el mensaje de registro del root logger!» como el siguiente:

#> 2019-03-03 17:18:32,703 :: INFO :: Module <stdin> :: Line No 1 :: This is root logger's logging message!

Mostrar solución

import logginglogging.basicConfig(level=logging.INFO, format='%(asctime)s :: %(levelname)s :: Module %(module)s :: Line No %(lineno)s :: %(message)s')logging.info("This is root logger's logging mesage!")

1. Crea otro archivo python en el mismo directorio llamado ‘mymod.py‘ y crea un nuevo logger que lleve el nombre del módulo. Configúralo al nivel de mensajes de ‘error’ y haz que envíe las salidas del log a un fichero llamado «mymod_{current_date}.log».
2. Desde el logger ‘mymod’ creado anteriormente, registra el siguiente mensaje ‘crítico’ en dicho fichero de log: «¡Este es un mensaje crítico!. Don’t ignore it».

Conclusión

¡Muchas felicidades si has sido capaz de resolver los ejercicios!

Ha sido bastante útil y sencillo no?

El logging es una gran herramienta pero no es popular es los flujos de trabajo de la ciencia de datos como debería ser. Espero que los conceptos de logging queden claros y la próxima vez que trabajes en un proyecto basado en python, mi amable petición es que recuerdes darle una oportunidad al módulo logging.

¡Feliz logging!