Logger

En software, el logging es una técnica de seguimiento y comprobación de resultados a través del registro de sucesos en orden cronológico. Por poner un ejemplo práctico, imaginemos que deseamos instalar un paquete software desde el programa Synaptic que acompaña a Ubuntu. El proceso de instalación incluye varias etapas como descargar, descomprimir, compilar módulos, copiar archivos y eliminar archivos temporales. Cada una de estas etapas, a lo largo de su desarrollo, puede querer advertir al usuario de alguna información de utilidad, advertencia, error o éxito y una forma sencilla de lograr esta comunicación es escribiendo un fichero en disco que contenga todos estos mensajes. Esto es, en pocas palabras, un archivo de log o sencillamente log.

En el desarrollo de software, sobre todo en las fases de desarrollo, es conveniente escribir logs que reflejen los resultados intermedios, errores y advertencias que se generan durante la ejecución de un algoritmo con el fin de seguir su desarrollo más fácilmente.

Logging en Python

En Python existe un módulo llamado logging que se puede importar mediante

import logging

Este módulo permite el uso de varios gestores de log o loggers jerarquizados en forma de árbol y asociados a un nombre. La precedencia se representa mediante un punto '.' en el nombre del logger de manera que el logger hdlorean es el padre de hdlorean.gui, hdlorean.snapshotManager y hdlorean.scheduler. Es posible crear un logger con nombre haciendo uso de la función

getLogger([nombre])

Si el nombre se omite se devuelve un logger considerado la raíz de toda la jerarquía. Es importante notar que dos llamadas a este método con el mismo nombre de logger devolverán el mismo objeto logger. De esta manera es posible utilizar el mismo gestor desde distintas partes de la aplicación sin tener que recurrir a la inicialización previa de todos los gestores y al paso de los mismos.

Para nuestro proyecto propongo que cada uno llame al logger "hdlorean.<nombreDeSuModulo>".

Una vez que tenemos nuestro objeto logger podemos escribir diversos tipos de mensajes mediante el uso de las siguientes funciones que comentaremos en breve

debug(msg[, *args[, **kwargs]])
info(msg[, *args[, **kwargs]])
warning(msg[, *args[, **kwargs]])
error(msg[, *args[, **kwargs]])
critical(msg[, *args[, **kwargs]])
exception(msg[, *args])
log(level, msg[, *args[, **kwargs]])

Un ejemplo rápido

# encoding: utf-8
 
import sys
import os
import logging
 
# Configuración de formato, el nombre del archivo, el modo de apertura del mismo y el nivel del logger raíz
FORMAT = "%(asctime)s (%(module)s:%(filename)s #%(lineno)d) %(levelname)s> %(message)s"
formatter = logging.Formatter(FORMAT)
logging.basicConfig(filename="/tmp/milog.txt", filemode="a", format=FORMAT, level=10)
 
# Prioridad personalizada, el nivel TURRON es uno de los más altos
TURRON = 60
logging.addLevelName(TURRON, "TURRON")
 
#Creamos un handler para que se imprima por pantalla sólo aquellos mensajes de prioridad superior o igual a 50
errHndl = logging.StreamHandler(sys.stderr)
errHndl.setLevel(50)
errHndl.setFormatter(formatter)
 
# Crear el logger o recuperarlo si ya existe
logger = logging.getLogger("hdlorean.allLogging")
logger.addHandler(errHndl)
 
# Niveles predefinidos por loggin además del nuestro
niveles = [10, 20, 30, 40, 50, TURRON]
 
#Escribe algunos mensajes elevando el nivel del logger a cada iteracion
for nivel in niveles:
    logger.setLevel(nivel)
    logger.log(TURRON,"Xixona")
    logger.info("El home de este sistema es: %s", os.getenv("HOME", "~"))
    logger.debug("Aviso de depuración")
    logger.warning("¡Cuidado!: %s", "el cielo puede desplomarse sobre tu cabeza")
    logger.error("Ocurrió un error: %s %s", "no se pudo escribir el archivo", "(por ejemplo)")
    logger.critical("pi es EXACTAMENTE 3!")
    logger.log(61,"---------------") # Este mensaje se imprimirá siempre puesto que su prioridad es la más alta

Prioridades

Para Python, cada mensaje escrito por un logger tiene una prioridad que refleja la importancia del mensaje. Así, a mayor prioridad, mayor importancia.

Esta tabla refleja los niveles preestablecidos de Python.

TIPO o NIVEL	PRIORIDAD
CRITICAL	50
ERROR	40
WARNING	30
INFO	20
DEBUG	10
NOTSET	0

Los logger además pueden tener asociada una prioridad que actúa como filtro dejando llegar sólo los mensajes con mayor o igual prioridad que el logger. Por ejemplo, si el logger hdlorean.allLogging tiene prioridad 40, entonces cualquier intento de guardar un WARNING, INFO o DEBUG en él, será rechazado.

También pueden definirse prioridades personalizadas (como TURRON en el ejemplo) mediante la función

addLevelName(lvl, levelName)

que asocia el nivel de prioridad lvl al nombre levelName.

O bien pueden emitirse mensajes de nivel personalizado mediante el uso de la función

log(level, msg[, *args[, **kwargs]])

donde el parámetro level indica el nivel de prioridad del mensaje. El resto de parámetros se discutirán próximamente.

Es necesario notar que las prioridades afectan a toda la jerarquía de manera descendente comenzando por la raíz así que si hemos definido esta en 50, por mucho que digamos que el logger hdlorean.allLogging tiene prioridad 10, jamás conseguiremos mostrar un mensaje INFO en él puesto que se ve filtrado por la prioridad del raíz.

Por esto precisamente en la función

basicConfig([**kwargs])

encargada de establecer la configuración inicial del módulo logging se indica el nivel de prioridad del logger raíz como el más bajo predeterminado (con prioridad 0 suprimen todos los mensajes) mediante el parámetro level.

Manejadores

En Python los mensajes no se escriben por defecto en ningún lado sino que se almacenan en una estructura LogRecord y pueden disparar un evento que desvía el mensaje a algún destino dependiendo del tipo de manejador o Handler, así, los que más nos interesan son

StreamHandler
FileHandler
SMTPHandler

que permiten la escritura a un flujo, a disco y el envío de logs por e-mail respectivamente.

Para añadir un handler primero debemos crearlo. Las clases StreamHandler y FileHandler se encuentran directamente en el módulo logging mientras que el resto se encuentran el logging.handlers. Cada constructora tiene uno o varios parámetros para inicializar el manejador convenientemente. Así, StreamHandler permite indicar el flujo dónde redirigir los mensajes; FileHandler, el archivo dónde se escribirán los mensajes y SMTPHandler, el servidor de correo, el remitente, el destinatario y el asunto del mensaje.

Un manejador también puede tener una prioridad de manera que se active sólo si los mensajes superan o igualan el nivel del manejador. En nuestro caso hemos utilizado la función

setLevel(lvl)

donde lvl es la prioridad del manejador para establecer este nivel en 50 y de esta manera mostrar por el flujo de errores del sistema sólo los mensajes cuya prioridad sea igual o superior a 50, a saber: CRITICAL y TURRON en nuestro ejemplo.

Es conveniente notar como la prioridad de un manejador sólo actúa sobre los mensajes previamente filtrados por el logger teniendo en cuenta la jerarquía. De esta forma, en la última iteración del bucle, el nivel del logger es de 60 y por tanto el handler sólo actúa para los mensajes de tipo TURRON.

El módulo logging permite definir un manejador de flujos o archivos en su función

basicConfig([**kwargs])

Esto se consigue mediante los parámetros filename, filemode y stream.

Formato

El formato de la salida de un mensaje del log puede ser configurada mediante la clase Formatter. Al constructor de la clase es necesario pasarle una cadena que utiliza uno o varios de los siguientes especificadores de formato.

Formato	Descripcion
%(name)s	Nombre del logger (canal de logging).
%(levelno)s	Tipo de mensaje en forma numérica (DEBUG, INFO, WARNING, ERROR, CRITICAL).
%(levelname)s	Tipo de mensaje en forma de texto ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL').
%(pathname)s	Ruta completa del archivo fuente que emitió el mensaje (si está disponible).
%(filename)s	Nombre del archivo parte de la ruta
%(module)s	Módulo (parte del nombre del archivo).
%(funcName)s (para 2.5)	Nombre de la función que emitió el mensaje.
%(lineno)d	Número de línea en el archivo fuente donde se emitió el mensaje (si está disponible).
%(created)f	Instante en el que la estructura LogRecord fue creada (devuelta como lo haría la función time.time()).
%(asctime)s	Momento en un formato inteligible cuando la estructura LogRecord fue creada. Por defecto es de la forma "2003-07-08 16:49:45,896'' (los números desués de la coma son milisegundos).
%(msecs)d	Milisegundos parte del instante en el que la estructura LogRecord fue creada.
%(thread)d	Identificador del thread (si es posible).
%(threadName)s	Nombre del thread (si está disponible).
%(process)d	Identificador del proceso (si está disponible).
%(message)s	El mensaje emitido, a partir de los argumentos % del parámetro msg de la función que emite el mensaje.

De esta forma podemos definir cómo debe presentarse cada entrada del fichero de log. En este caso mi propuesta es la siguiente.

FORMAT = "%(asctime)s (%(module)s:%(filename)s #%(lineno)d) %(levelname)s> %(message)s"

Que produciría una salida de la forma

2008-01-10 02:59:50,420 (logger-example:logger-example.py #33) WARNING> ¡Cuidado!: el cielo puede desplomarse sobre tu cabeza

El formato también se especifica mediante la función

basicConfig([**kwargs])

esta vez mediante el parámetro format para el manejador previamente establecido.

Para establecer el formato de algún otro handler usaremos la función

setFormatter(form)

donde /form/ es un objeto de la clase Formatter.

Parámetros de las funciones

Todas las funciones de la clase logger toman tres argumentos y son de la forma

nombreFuncion(msg [, *args [, **kargs]])

Exceptuando la función

log(lvl, msg [, *args [, **kargs]])

que toma como primer argumento la prioridad del mensaje para permitir niveles de mensajes personalizados.

Pese a todo, el parámetro msg junto con *args presentan el mismo comportamiento que los parámetros de la función printf. Es decir, una cadena con formato para msg y una lista de valores de sustitución para *args.

El parámetro **kargs contiene dos valores: exc_info que no discutiremos aquí y extra que toma un diccionario y permite extender el conjunto de claves de la cadena de formato. Por ejemplo, si a nuestro formato quisiéramos añadir el mail de contacto del autor del módulo tendríamos que reescribir la cadena de formato a:

FORMAT = "%(asctime)s (%(module)s:%(filename)s #%(lineno)d) %(levelname)s mail=%(mailAutor)s> %(message)s"

Nótese la inclusión del parámetro %(mailAutor). Ahora necesitamos un diccionario que incluya el valor para la nueva clave como

dict = {'mailAutor' : '[e-mail]'}

Y ahora una llamada a la función warning podría ser

logger.warning("¡Cuidado!: %s", "el cielo puede desplomarse sobre tu cabeza", extra=dict)

Esta llamada imprimiría algo como

2008-01-10 03:38:48,098 (logger-example:logger-example.py #35) WARNING mail=[e-mail]> ¡Cuidado!: el cielo puede desplomarse sobre tu cabeza

A continuación se muestra el código asociado a esta última modificación:

# encoding: utf-8
 
import sys
import os
import logging
 
# Configuración de formato, el nombre del archivo, el modo de apertura del mismo y el nivel del logger raíz
FORMAT = "%(asctime)s (%(module)s:%(filename)s #%(lineno)d) %(levelname)s mail=%(mailAutor)s> %(message)s"
formatter = logging.Formatter(FORMAT)
logging.basicConfig(filename="/tmp/milog.txt", filemode="a", format=FORMAT, level=10)
 
# Prioridad personalizada, el nivel TURRON es uno de los más altos
TURRON = 60
logging.addLevelName(TURRON, "TURRON")
 
#Creamos un handler para que se imprima por pantalla sólo aquellos mensajes de prioridad superior o igual a 50
errHndl = logging.StreamHandler(sys.stderr)
errHndl.setLevel(50)
errHndl.setFormatter(formatter)
 
# Crear el logger o recuperarlo si ya existe
logger = logging.getLogger("hdlorean.allLogging")
logger.addHandler(errHndl)
 
# DICCIONARIO CON LAS CLAVES RESTANTES
dict = {'mailAutor' : '[e-mail]'}
 
# Niveles predefinidos por loggin además del nuestro
niveles = [10, 20, 30, 40, 50, TURRON]
 
#Escribe algunos mensajes elevando el nivel del logger a cada iteracion
for nivel in niveles:
    logger.setLevel(nivel)
    logger.log(TURRON,"Xixona",extra=dict)
    logger.info("El home de este sistema es: %s", os.getenv("HOME", "~"),extra=dict)
    logger.debug("Aviso de depuración",extra=dict)
    logger.warning("¡Cuidado!: %s", "el cielo puede desplomarse sobre tu cabeza",extra=dict)
    logger.error("Ocurrió un error: %s %s", "no se pudo escribir el archivo", "(por ejemplo)",extra=dict)
    logger.critical("pi es EXACTAMENTE 3!",extra=dict)
    logger.log(61,"---------------",extra=dict) # Este mensaje se imprimirá siempre puesto que su prioridad es la más alta

La función basicConfig

Como dijimos al principio, la función

basicConfig([**kwargs])

establece la configuración inicial del módulo logging. Posee pocos parámetros y la siguiente tabla los recoge explicando el significado de cada uno de ellos.

FORMATO	DESCRIPCIÓN
filename	Especifica que un manejador FileHandler debe ser creado, usando el nombre especificado, en vez del manejador StreamHandler.
filemode	Especifica el modo de apertura del archivo si el nombre ha sido especificado (por defecto es 'a', append, añadir).
format	Usa el formato especificado para el manejador.
datefmt	Usa el formato definido como formato de fechas.
level	Establece el nivel del logger raíz.
stream	Usa el flujo especificado en un manejador StreamHandler. Nótese que este parámetro es incompatible con el formato filename - si ambos están presentes stream será ignorado.

Comentarios