Logging

Aunque la aplicación consiste en una interfaz gráfica, hay mucha información de errores, debug, o simplemente de notificación que debe logearse bien a la salida estandar, bien a un fichero. Sirviendo para detectar errores y analizar comportamientos inesperados del sistema. Bueno, que voy a ponerme a contar ahora que no sepan.

Hasta ahora este tipo de información la mostraba sencillamente haciendo prints
El método era un poco pobre ya que permitía muy poco control sobre que mensajes deben imprimirse o no, el formato es a la buena de dios, no queda claro en cada momento a qué parte del programa pertenece cada mensaje y si en algún momento decidía redirigirlo todo a un fichero las iba a pasar canutas.

Resumiendo, lo que buscaba era:

• Mostrar/Ocultar la información de debug sin inflarme a borrar prints ni añadir lógica manualmente.
• Mantener un formato unificado en toda la aplicación a la hora de imprimir mensajes.
• Especificar sin procedimientos tediosos desde que parte de la aplicación se muestra cada mensaje.
• Posibilidad de redirigirlo todo a un fichero sin grandes problemas.

Felizmente, Python incluye en su biblioteca estandar un pequeño módulo de logging, que incluye más funcionalidades de las que necesito incluyendo no ya sólo ficheros, sino logs por red (HTTP, SMTP…), rotación de logs y más cosas, ya saben, batteries included.

A pesar de lo completo que es el módulo, su funcionamiento básico no puede ser más obvio:

1. Se inicializa un objeto log con el nombre del módulo.
2. Imprimir con log.debug() , log.info(), log.warning()…

Un pequeño ejemplo:

import logging
log = logging.getLogger('modulo')

log.error("No se pudo leer el fichero de configuración %s " % self.config)
log.info("Proyectos disponibles: %s" % str(self.lista_proyectos))

Los niveles de logging son debug,info,warning,error y critical.
La diferencia entre ellos es el nivel de prioridad que tienen, siendo debug el más bajo y critical el más alto. Puede fácilmente seleccionarse el nivel, esto es, la prioridad mínima que deben tener los mensajes para que se impriman.
Mediante:

logging.setLevel( logging.DEBUG )

Por ejemplo, estableceríamos la mínima prioridad, de manera que se mostrarían todos los mensajes, desde los de debug a los crítical.
Sin embargo realizando

logging.setLevel( logging.WARNING )

Se ignorarían los mensajes realizados con log.debug y log.info que tienen menor nivel.

El formato también puede ser ajustado mediante una cadena de formato. En mi caso empleo la siguiente:

FORMAT = "%(levelname)s    \t%(name)s:  %(message)s"
logging.basicConfig(format=FORMAT)

La cadena imprime el nivel (DEBUG, INFO…), el nombre del módulo desde donde se llama y el mensaje en si.

La redirección a un fichero puede hacerse mediante un FileHandler añadiéndolo al log (esto no lo he probado aún).

h = FileHandler('fichero.log')
logging.getlogger('modulo').addHandler(h)

Todo esto, en lugar de realizarlo en cada módulo, se concentra en una única función en un módulo aparte de utilidades que importan todos los demás con una sencilla función llamada getlog que devuelve un log bien configurado y listo para usar:

def getlog(name, level = ""):
"""@brief Devuelve un objeto logger estandar bien configurado
@param name Nombre del módulo que hace logging.
@param level Nivel de logging."""

# DEBUG por defecto si no se especifica, en otro caso, INFO
LEVEL = logging.DEBUG if not level else logging.INFO

# Formato para el log
FORMAT = "%(levelname)s    \t%(name)s:  %(message)s"

logging.basicConfig(format=FORMAT, level=LEVEL)
return logging.getLogger(name)

Que se usaría así:

import util.logger
log = util.logger.getlog('modulo')
log.debug('esto huele a chamusquina...')

La salida que obtengo es de esta guisa:

WARNING    	idg.main:  Usando locale en directorio local. ./locale No instaladas las locales.
DEBUG    	idiginBPEL:  Ejecutable en /home/arl/Dropbox/soft/takuan/cusl4-idigin/trunk
DEBUG    	idiginBPEL:  Buscando config en: /home/arl/.idiginbpel/config.xml
INFO    	idg.main:  Usando fichero de configuración: /home/arl/.idiginbpel/config.xml
ERROR    	idg.main:  No se encuentra el directorio: /home/arl/dbx/takuan/idiginBPEL/trunk/share
WARNING    	idg.main:  Se usará el valor por defecto para: share
INFO    	idg.main:  Home: /home/arl/.idiginbpel
INFO    	idg.main:  Share: ./share
INFO    	idg.main:  Takuan: /home/arl/takuan
INFO    	idg.main:  Proyectos disponibles: [u'p1', u'p2']

Así se consigue de una manera bastante sencilla solucionar todos los puntos que buscaba.

• Puedo ocultar la info de debug usando los niveles.
• Pongo una sola vez de donde provienen los mensajes
• Mantengo un formato unificado.
• Puedo redirigirlo a un fichero añadiendo solo algo más de código.

Rico rico y sobre todo facilísimo.