Logging con Python

Logging con Python

Joaquín Amat Rodrigo
Mayo, 2020

Más sobre ciencia de datos: cienciadedatos.net

Introducción


El siguiente notebook contiene ejemplos de cómo registrar logs con python emplenado el modulo logging.

Por defecto, esto módulo tiene predefinidos 5 niveles para los logs, ordenados de menor a mayor criticidad:

  • DEBUG
  • INFO
  • WARNING
  • ERROR
  • CRITICAL

Una vez establecido un determinado nivel, solo se muestran logs de esa criticidad o superior.

Logging dentro de un único script


Hacer logging dentro de un único script es la situación más sencilla, ya que solo es necesario crear un único logger.

Salida por consola

In [17]:
# El siguiente script genera un array con 100 números aleatorios y calcula la suma de todos ellos
# ===============================================================================================
import logging
import numpy as np

# Creación del logger que muestra la información únicamente por consola.
logging.basicConfig(
    format = '%(asctime)-5s %(name)-15s %(levelname)-8s %(message)s', 
    level  = logging.INFO, # Nivel de los eventos que se registran en el logger
)

logging.info('Inicio main script')
numeros = np.random.rand(1,100)
logging.info('Números aleatorios simulados')
numeros.sum()
logging.info('Suma calculada')
logging.info('Fin main script')
logging.shutdown()
2020-10-26 10:40:49,393 root            INFO     Inicio main script
2020-10-26 10:40:49,394 root            INFO     Números aleatorios simulados
2020-10-26 10:40:49,395 root            INFO     Suma calculada
2020-10-26 10:40:49,396 root            INFO     Fin main script

Salida por fichero

In [18]:
# Se eliminan los handlers anteriores
if logging.getLogger('').hasHandlers():
    logging.getLogger('').handlers.clear()
In [19]:
# El siguiente script genera un array con 100 números aleatorios y calcula la suma de todos ellos
# ===============================================================================================
import logging
import numpy as np

# Creación del logger que muestra la información únicamente por fichero.
logging.basicConfig(
    format = '%(asctime)-5s %(name)-15s %(levelname)-8s %(message)s',
    level  = logging.INFO,      # Nivel de los eventos que se registran en el logger
    filename = "logs_info.log", # Fichero en el que se escriben los logs
    filemode = "a"              # a ("append"), en cada escritura, si el archivo de logs ya existe,
                                # se abre y añaden nuevas lineas.
)

logging.info('Inicio main script')
numeros = np.random.rand(1,100)
logging.info('Números aleatorios simulados')
numeros.sum()
logging.info('Suma calculada')
logging.info('Fin main script')
logging.shutdown()

Salida por consola y varios fichero


Cada logger puede tener uno o varios handlers. Los handlers son los encargados de gestionar dónde se dirige cada tipo de log. Si se quiere que los logs vayan a varios destinos, se tiene que añadir un handler por cada uno de ellos.

In [20]:
import logging
import numpy as np 

# Creación del logger que muestra la información únicamente por fichero.
# -----------------------------------------------------------------------------
logging.basicConfig(
    format = '%(asctime)-5s %(name)-15s %(levelname)-8s %(message)s',
    level  = logging.INFO,      # Nivel de los eventos que se registran en el logger
    filename = "logs_info.log", # Fichero en el que se escriben los logs
    filemode = "a"              # a ("append"), en cada escritura, si el archivo de logs ya existe,
                                # se abre y añaden nuevas lineas.
)

# Nuevos handlers
# -----------------------------------------------------------------------------
# Se añaden dos nuevos handlers al root logger, uno para los niveles de debug o
# superiores y otro para que se muestre por pantalla los niveles de info o
# superiores.

# Si el root logger ya tiene handlers, se eliminan antes de añadir los nuevos.
# Esto es importante para que los logs no empiezen a duplicarse.
if logging.getLogger('').hasHandlers():
    logging.getLogger('').handlers.clear()

# Handler nivel debug con salida a fichero
file_debug_handler = logging.FileHandler('logs_debug.log')
file_debug_handler.setLevel(logging.DEBUG)
file_debug_format = logging.Formatter('%(asctime)s-%(name)s-%(levelname)s-%(message)s')
file_debug_handler.setFormatter(file_debug_format)
logging.getLogger('').addHandler(file_debug_handler)

# Handler nivel info con salida a consola
consola_handler = logging.StreamHandler()
consola_handler.setLevel(logging.INFO)
consola_handler_format = logging.Formatter('%(asctime)s-%(name)s-%(levelname)s-%(message)s')
consola_handler.setFormatter(consola_handler_format)
logging.getLogger('').addHandler(consola_handler)


# El siguiente script genera un array con 100 números aleatorios y calcula la suma de todos ellos
# ===============================================================================================
logging.info('Inicio main script')
numeros = np.random.rand(1, 100)
logging.info('Números aleatorios simulados')
numeros.sum()
logging.info('Suma calculada')
logging.info('Fin main script')
logging.shutdown()
2020-10-26 10:40:49,413-root-INFO-Inicio main script
2020-10-26 10:40:49,414-root-INFO-Números aleatorios simulados
2020-10-26 10:40:49,414-root-INFO-Suma calculada
2020-10-26 10:40:49,415-root-INFO-Fin main script

Logging entre varios scripts


Para almacenar en un mismo fichero los logs que genera un script y todas las funciones/clases que se importan en él (cada una con un su propio logger), es necesario que los loggers se comuniquen entre ellos de forma jerárquica.

Para este ejemplo se emplea un main script en el que se importa la función suma(), que a su vez contiene varios logs.

Opción 1: Utilizar solo el logger root del main script


En el main script se crea un logger root (es el que crea logging.basicConfig() por defecto) al que se le añaden nuevos handlers. En cada función o clases se importa la librería logging y se emplean sus métodos.

Esta aproximación presenta la ventaja de que no es necesario crear un logger nuevo en cada función-clase ya que todos los logs son recopilados por el logger root creado en el main script. La desventaja es que, como todos los logs son recopilados por el root, no es posible identificar de qué función-clase proceden (a no ser que se identifique por el cuerpo del mensaje).

In [21]:
# El contenido del archivo funcion_suma.py es:

#import logging
#def suma(a,b):
#    if not isinstance(a, (int, float)) \
#    or not isinstance(b, (int, float)): 
#        raise Exception(
#            logging.error("a y b deben ser números")
#        )
#    logging.info('función suma ejecutada')
#    return(a+b)
In [22]:
# ======================= MAIN SCRIPT ============================================

import logging
from funcion_suma import suma # Esta función tiene sus propios logs

# Definición del logger root
# -----------------------------------------------------------------------------
logging.basicConfig(
    format = '%(asctime)-5s %(name)-15s %(levelname)-8s %(message)s',
    level  = logging.INFO,
    filemode = "a"
    )

# Nuevos handlers
# -----------------------------------------------------------------------------
# Si el root logger ya tiene handlers, se eliminan antes de añadir los nuevos.
# Esto es importante para que los logs no empiezen a duplicarse.
if logging.getLogger('').hasHandlers():
    logging.getLogger('').handlers.clear()
    
# Se añaden dos nuevos handlers al root logger, uno para los niveles de debug o
# superiores y otro para que se muestre por pantalla los niveles de info o
# superiores.
file_debug_handler = logging.FileHandler('logs_debug.log')
file_debug_handler.setLevel(logging.DEBUG)
file_debug_format = logging.Formatter('%(asctime)-5s %(name)-15s %(levelname)-8s %(message)s')
file_debug_handler.setFormatter(file_debug_format)
logging.getLogger('').addHandler(file_debug_handler)

consola_handler = logging.StreamHandler()
consola_handler.setLevel(logging.INFO)
consola_handler_format = logging.Formatter('%(asctime)-5s %(name)-15s %(levelname)-8s %(message)s')
consola_handler.setFormatter(consola_handler_format)
logging.getLogger('').addHandler(consola_handler)

# ======================= MAIN SCRIPT ============================================
logging.debug('Inicio main script')
logging.info('Inicio main script')

suma(1,3)

logging.debug('Fin main script')
logging.info('Fin main script')

logging.shutdown()
2020-10-26 10:40:49,426 root            INFO     Inicio main script
2020-10-26 10:40:49,426 root            INFO     función suma ejecutada
2020-10-26 10:40:49,427 root            INFO     Fin main script

Opción 2: Utilizar el logger root creado en el main script y logger hijos en el resto de scripts


Esta forma tiene las mismas ventajas que el anterior ejemplo pero, además, permite saber de qué script procede cada log.

In [23]:
# El contenido del archivo funcion_suma_1.py es:

#import logging
#logger = logging.getLogger("").getChild(__name__)

#def suma(a,b):
#    if not isinstance(a, (int, float)) \
#    or not isinstance(b, (int, float)): 
#        raise Exception(
#            logger.error("a y b deben ser números")
#        )
#    logger.info('función suma ejecutada')
#    return(a+b)
In [24]:
# ======================= MAIN SCRIPT ============================================

import logging
from funcion_suma_1 import suma # Esta función tiene sus propios logs

# Definición del logger root
# -----------------------------------------------------------------------------
logging.basicConfig(
    format = '%(asctime)-5s %(name)-15s %(levelname)-8s %(message)s',
    level  = logging.INFO,
    filemode = "a"
    )

# Nuevos handlers
# -----------------------------------------------------------------------------
# Si el root logger ya tiene handlers, se eliminan antes de añadir los nuevos.
# Esto es importante para que los logs no empiezen a duplicarse.
if logging.getLogger('').hasHandlers():
    logging.getLogger('').handlers.clear()
    
# Se añaden dos nuevos handlers al root logger, uno para los niveles de debug o
# superiores y otro para que se muestre por pantalla los niveles de info o
# superiores.
file_debug_handler = logging.FileHandler('logs_debug.log')
file_debug_handler.setLevel(logging.DEBUG)
file_debug_format = logging.Formatter('%(asctime)-5s %(name)-15s %(levelname)-8s %(message)s')
file_debug_handler.setFormatter(file_debug_format)
logging.getLogger('').addHandler(file_debug_handler)

consola_handler = logging.StreamHandler()
consola_handler.setLevel(logging.INFO)
consola_handler_format = logging.Formatter('%(asctime)-5s %(name)-15s %(levelname)-8s %(message)s')
consola_handler.setFormatter(consola_handler_format)
logging.getLogger('').addHandler(consola_handler)

logging.debug('Inicio main script')
logging.info('Inicio main script')

suma(1,3)

logging.debug('Fin main script')
logging.info('Fin main script')

logging.shutdown()
2020-10-26 10:40:49,439 root            INFO     Inicio main script
2020-10-26 10:40:49,439 funcion_suma_1  INFO     función suma ejecutada
2020-10-26 10:40:49,440 root            INFO     Fin main script

Información de sesión

In [25]:
from sinfo import sinfo
sinfo()
-----
funcion_suma_1      NA
numpy               1.19.2
sinfo               0.3.1
-----
IPython             7.18.1
jupyter_client      6.1.2
jupyter_core        4.6.3
jupyterlab          2.1.3
notebook            6.0.3
-----
Python 3.8.6 (default, Oct 10 2020, 07:54:55) [GCC 5.4.0 20160609]
Linux-5.4.0-1028-aws-x86_64-with-glibc2.2.5
8 logical CPU cores, x86_64
-----
Session information updated at 2020-10-26 10:40

¿Cómo citar este documento?

Logging con Python by Joaquín Amat Rodrigo, available under a Attribution 4.0 International (CC BY 4.0) at https://www.cienciadedatos.net/documentos/py05_logging_con_python.html


¿Te ha gustado el artículo? Tu ayuda es importante

Mantener un sitio web tiene unos costes elevados, tu contribución me ayudará a seguir generando contenido divulgativo gratuito. ¡Muchísimas gracias! 😊


Creative Commons Licence
This work by Joaquín Amat Rodrigo is licensed under a Creative Commons Attribution 4.0 International License.