Logging levels

| Publicado: | Código fuente

Cuando empecé con el concepto de loguear, me parecía demasiado tener niveles. Con el tiempo y la experiencia me di cuenta que son imprescindibles, :)

En la biblioteca estándar de Python hay un módulo logging que trae varios niveles prefijados. Son estos, con una pequeña anotación de cómo los uso, más un ejemplo de la vida real (tomados de mi programa de Encuentro o de fades).

  • CRITICAL: creo que nunca lo usé :)

  • ERROR: problemas de todo tipo; cosas que no deberían pasar, y si pasan son un inconveniente; muchas veces el programa no continúa, o continua de forma parcial o limitada, luego de este tipo de linea logueada. En este ejemplo logueo que no se pudo bajar la lista de los backends durante una actualización (también en este caso se le avisa al usuario mediante una ventanita, y el programa sigue, aunque la actualización no se concretó):

    try:
    _, backends_file = yield utils.download(BACKENDS_URL)
except Exception, e:
    logger.error("Problem when downloading backends: %s", e)
    tell_user("Hubo un PROBLEMA al bajar la lista de backends:", e)
    return

  • WARNING: para indicar que sucedió algo que en general no debería pasar; en general no son cosas malas, sino más bien anómalas, y no presentan una situación problemática. En el siguiente ejemplo estoy dejando registro que ignoro la opción 'quiet' que pasó el usuario (porque también pasó la opción 'verbose', que es más importante):

    if verbose and quiet:
    logger.warning("Overriding 'quiet' option ('verbose' also requested)")

  • INFO: información general del funcionamiento del programa, cosas que son imprescindibles saber y que siempre queremos que sean registradas; en general no involucran gran cantidad de lineas, pero permite seguir el flujo de ejecución del programa desde un nivel alto. Normalmente los programas que se entregan a los usuarios o corren en los servidores están configurados para realmente mandar a disco desde este nivel. En las siguientes dos lineas muestro lo primero que loguea Encuentro al arrancar: con qué versión de Python está siendo ejecutado y qué versión de sí mismo es:

    log.info("Running Python %s on %r", sys.version_info, sys.platform)
log.info("Encuentro version: %r", version)

  • DEBUG: toda la información necesaria para analizar en detalle la ejecución del programa. Puede involucrar grandes cantidades de información, y hasta ser un problema con respecto al uso de disco o afectar la performance, pero en general no se corren los programas en este nivel, sólo durante el desarrollo o en casos de tratar de analizar un problema específico. No es raro, por ejemplo, pedirle al usuario que ejecute el programa con un parámetro especial que configura los logs en este nivel y que trate de reproducir el problema que tuvo, para luego hacer un análisis forense de la situación. En el siguiente ejemplo estoy dejando constancia que fades tuvo que instalar pip a mano en el virtualenv:

    logger.debug("Installing PIP manually in the virtualenv")

Me ha pasado en sistemas muy complejos de necesitar un nivel más abajo que DEBUG para loguear toda aquella información que podría llegar a ser útil para un análisis del comportamiento del programa, pero que normalmente sería un exceso de datos (lo cual complica desde la lectura de los registros hasta el mismo manejo de los archivos). Entonces, usábamos un nivel TRACE, que casi nunca se prendía, para este propósito.

La macana es que el módulo de logging no tiene un nivel TRACE, pero lo creábamos a mano:

TRACE = 5
logging.addLevelName('TRACE', TRACE)

Fíjense el 5 ese: es que DEBUG es 10, entonces queda "más abajo". Claro, para que funcione todo, teníamos que usar un Logger custom:

class Logger(logging.Logger):
    """Logger that support our custom levels."""

    def trace(self, msg, *args, **kwargs):
        """log at TRACE level"""
        if self.isEnabledFor(TRACE):
            self._log(TRACE, msg, args, **kwargs)

Para más información sobre la infrastructura de logging de Python y consejos generales sobre qué, cómo, o cuándo dejar registro de lo que sucede, pueden ver mi charla sobre el tema (estos son los slides, y en algún momento se publicará acá el video de esta misma charla que dí en la PyCon de Rafaela).

Comentarios Imprimir