b05t04.md

Registro de sucesos o logging

El logging es la acción de registrar un suceso. La forma más sencilla de hacer esto es con print, como venimos haciendo desde el comienzo del curso.

Sin embargo, conforme crees software más y más complejo te darás cuenta de que print es una solución muy limitada. ¿Qué pasa cuando quieres eliminar los print que pusiste para depurar una función? ¿Los borrarías físicamente del código fuente? ¿Los comentarías?

¿Y si decides informar en un fichero? ¿O informar siguiendo diferentes estrategias en función de la severidad del suceso?

Este problema es tan común en desarrollo de software que Python incluye el completísimo sistema de registro aquí presentado.

Para esta lección, en lugar de una sesión interactiva, utiliza PyCharm como hicistes en la lección anterior. Los ejemplos son más largos pero también autocontenidos, de forma que puedas reemplazar completamente el contenido del fichero de prueba con el del ejemplo.

El registrador de sucesos

1. La funcionalidad de registro se encuentra centralizada en el módulo logging:

   import logging
   logging.warning('Warning, enemy approaching! 🛸')
   logging.info('I am Ziltoid, the Omniscient.')

   Ejecuta el módulo con estos comandos y deberías ver la siguiente línea en la consola:

   WARNING:root:Warning, enemy approaching! 🛸
   

2. El segundo mensaje, proveniente de la función logging.info no se imprime porque el nivel de registro por defecto es WARNING o advertencia. Podemos cambiar el nivel de logging con:

   import logging
   logging.basicConfig(level=logging.DEBUG)
   logging.info('I am Ziltoid, the Omniscient.')
   logging.warning('Warning, enemy approaching! 🛸')
   logging.debug('There should be no more messages after this')

   Ahora podemos ver todos los mensajes, puesto que DEBUG es el nivel más "bajo" e incluye los mensajes procedentes de logging.debug y nieveles "superiores":

   Value	Nivel	Descrición
   50	CRITICAL	Un problema que implica el fin de la ejecución.
   40	ERROR	Un problema que requiere la intervención del usuario.
   30	WARNING	Advierte de un posible problema futuro.
   20	INFO	Confirman que las cosas funcionan como se espera.
   10	DEBUG	Información detallada, por motivos de diagnóstico.

3. Por defecto, Python no configura el nivel de registro respecto de nada. Si queremos hacer depender el nivel de registro de una variable de entorno o de un argumento pasado a nuestro programa tenemos que programarlo explícitamente:

   from collections import defaultdict
   import logging
   import argparse
   import os
   
   _LOG_LEVELS = defaultdict(lambda: logging.WARNING, {
       'DEBUG': logging.DEBUG,
       'INFO': logging.INFO,
       'WARNING': logging.WARNING
   })
   
   # Get level from params
   parser = argparse.ArgumentParser()
   parser.add_argument('-v', '--verbosity', action='count', default=0)
   args = parser.parse_args()
   
   # Get level from environment
   environment_level = os.environ.get('DEBUG', '').upper()
   
   # Decide priority of the level source
   log_level = logging.WARNING
   
   if args.verbosity:
       log_level = max(logging.WARNING - 10 * args.verbosity, 10)
   
   elif environment_level:
       log_level = _LOG_LEVELS[environment_level]
   
   # Config log level
   logging.basicConfig(level=log_level)
   
   # Test
   logging.debug(f'log level set to {log_level}')
   logging.warning('Enemy approaching')
   logging.info('Deploying defences')

4. Sólo la primera llamada a logging.basicConfig tienen efecto, todas las demás no tienen efecto.

   import logging
   
   logging.basicConfig(level=logging.INFO)
   logging.basicConfig(level=logging.DEBUG)
   
   logging.warning('Enemy approaching')
   logging.info('Deploying defences')
   logging.debug('this will never show up')

5. Puedes registrar sucesos desde múltiples registradores con la factoría logging.getLogger(logger_name).

   import logging
   control = logging.getLogger('control')
   defense = logging.getLogger('defense')
   control.warning('Enemy approaching')
   defense.warning('Running out of ammo...')

   Fíjate en que los mensajes han perdido el formato. Los nuevos loggers no tienen ningún formato asociado y, para configurarlo, tienes que llamar a logging.basicConfig.

   import logging
   logging.basicConfig()
   control = logging.getLogger('control')
   defense = logging.getLogger('defense')
   control.warning('Enemy approaching')
   defense.warning('Running out of ammo...')

   No hace falta que logging.basicConfig() aparezca antes de la creación de los registradores pero sí antes de cualquier llamada a uno de los métodos de registro.

6. Un patrón muy extendido es el de asignar al nombre del logger, el nombre del módulo. Así:

   import logging
   logging.basicConfig()
   logger = logging.getLogger(__name__)
   logger.warning('May I have your attention, please?')

   Ahora crea un módulo distinto y copia dentro el mismo código que antes. Modifica el primero para que importe al segunto.

7. Si el formato del mensaje no te gusta, puedes cambiarlo con:

   import logging
   logging.basicConfig(
       format='%(asctime)s [%(levelname)s] %(name)s: %(message)s')
   logger = logging.getLogger(__name__)
   logger.warning('May I have your attention, please?')

   Hay otros valores que puedes usar el la cadena de formato.

8. Como has comprobado, el destino de los logs es la consola, aunque podría ser un fichero:

   import logging
   logging.basicConfig(filename='application.log')
   logger = logging.getLogger(__name__)
   logger.warning('May I have your attention, please?')

   Esta modalidad añade logs al final de los que ya había, sin vacíar nunca el fichero.

• Documentación de basicConfig

Registrando excepciones

Puedes imprimir una excepción, con su traza incluída, si desde un manejador de excepciónes, llamas a Logger.exception():

```python
import logging

logger = logging.getLogger(__name__)

try:
    print(1/0)
except ZeroDivisionError:
    logger.exception('Someone tried to divide between 0')
```

La jerarquía de loggers

Los distintos loggers siguen una jerarquía especificada por sus nombres separados por puntos. Por ello, utilizar el nombre del módulo es una buena idea, puesto que los puntos que reflejan la jerarquía paquete-módulo sirve para definir la jerarquía de loggers.

El logger raíz, o 'root' es aquel al que se puede acceder a través de logging.info, o logging.warning o cualquiera de las otras funciones en el módulo.

Configuración avanzada

La función logging.basicConfig cubre la mayoría de casos sencillos pero Python es capaz de hacer más. Los loggers se pueden configurar individualmente, por ejemplo, para enviar ciertos registros por e-mail, mientras que otros se muestran por consola o para establecer niveles distintos por módulo.

Los módulos admiten manejadores (handlers) y estos, formateadores (formatters). El manejador envía un registro a un destino (por ejmplo, la consola, un fichero, un tweet, una issue en GitHub...) y el formateador decide el formato de salida (texto plano, formato binario, JSON, Markdown...).

1. Los distintos loggers pueden configurarse de maneras distintas.

   import logging
   
   default_formatter = logging.Formatter(
       '%(asctime)s:[%(levelname)s]:%(name)s:%(message)s')
   
   control = logging.getLogger('control')
   control.setLevel(logging.INFO)
   to_control_log_file_handler = logging.FileHandler('control.log')
   to_control_log_file_handler.setFormatter(default_formatter)
   control.addHandler(to_control_log_file_handler)
   
   defense = logging.getLogger('defense')
   defense.setLevel(logging.WARNING)
   to_defense_log_file_handler = logging.FileHandler('defense.log')
   to_defense_log_file_handler.setFormatter(default_formatter)
   defense.addHandler(to_defense_log_file_handler)
   
   control.info('No news, good news')
   control.warning('Enemy, incoming')
   
   defense.info('Cleaning out the enemy')
   defense.warning('Running out of ammo')

   Observa los registros en control.log y defense.log.

2. Si los loggers siguen una jerarquía, los manejadores de los padres también manejan todos los registros envíados a los hijos.

   import logging
   
   default_formatter = logging.Formatter(
       '%(asctime)s:[%(levelname)s]:%(name)s:%(message)s')
   
   control = logging.getLogger('control')
   control.setLevel(logging.INFO)
   to_control_log_file_handler = logging.FileHandler('control.log')
   to_control_log_file_handler.setFormatter(default_formatter)
   control.addHandler(to_control_log_file_handler)
   
   # now defense is a child of control
   defense = logging.getLogger('control.defense')
   defense.setLevel(logging.WARNING)
   to_defense_log_file_handler = logging.FileHandler('defense.log')
   to_defense_log_file_handler.setFormatter(default_formatter)
   defense.addHandler(to_defense_log_file_handler)
   
   control.info('No news, good news')
   control.warning('Enemy, incoming')
   
   defense.info('Cleaning out the enemy')
   defense.warning('Running out of ammo')

   Observa atentamente control.log para ver qué ha pasado.

3. Lo cual es útil porque, en escenarios no muy complicados, permite una configuración más granular que basicConfig, sin excesiva complejidad, configurando únicamente el logger raíz.

   import logging
   
   default_formatter = logging.Formatter(
       '%(asctime)s:[%(levelname)s]:%(name)s:%(message)s')
   
   root_logger = logging.getLogger('root')
   root_logger.setLevel(logging.DEBUG)
   log_file_handler = logging.FileHandler('everything.log')
   log_file_handler.setFormatter(default_formatter)
   root_logger.addHandler(log_file_handler)
   
   control = logging.getLogger('root.control')
   control.setLevel(logging.INFO)
   
   defense = logging.getLogger('root.defense')
   defense.setLevel(logging.WARNING)
   
   control.info('No news, good news')
   control.warning('Enemy, incoming')
   
   defense.info('Cleaning out the enemy')
   defense.warning('Running out of ammo')

4. Recordando el patrón de nombrar tu logger como tus paquetes, ¿podrías trasladar el ejemplo anterior a una estructura de módulos como esta? Crea el paquete airdefense dentro de tu paquete de alumno.

   airdefense
   ├── __init__.py
   ├── control.py
   └── defense.py

   Lo que ahora es la configuración de root, ponlo en __init__.py pero recuerda obtener el nombre del logger a partir del nombre del módulo:

   import logging
   logger = logging.getLogger(__name__)

   El logger llamado control y su configuración muévelo dentro de control.py. El logger llamado defense y su configuración llévalo al fichero defense.py. Recuerda nombrar esos loggers como sus módulos.

   Cuando termines abre una sesión interactiva en la carpeta padre de airdefense e importa los módulos. ¿Qué ha pasado?

5. Múltiples handlers son posibles por logger. Por ejemplo: registrar todos los sucesos por consola y únicamente dejar en un fichero los de nivel ERROR:

   import sys
   import logging
   
   default_formatter = logging.Formatter(
       '%(asctime)s:[%(levelname)s]:%(name)s:%(message)s')
   
   root_logger = logging.getLogger('root')
   root_logger.setLevel(logging.DEBUG)
   
   log_file_handler = logging.FileHandler('error.log')
   log_file_handler.setLevel(logging.ERROR)
   log_file_handler.setFormatter(default_formatter)
   
   stdout_handler = logging.StreamHandler(sys.stdout)
   stdout_handler.setFormatter(default_formatter)
   
   root_logger.addHandler(log_file_handler)
   root_logger.addHandler(stdout_handler)
   
   root_logger.info('No news, good news.')
   root_logger.info('Everything is fine.')
   root_logger.warning('Enemy, incoming!')
   root_logger.error('Communication tower destroyed!')
   root_logger.critical('HQ destroyed!')

   Fíjate en las dos apariciones del método setLevel. La primera opera sobre el logger, e indica qué niveles de mensaje alcanzan los distintos manejadores. La segunda aparición opera sobre el manejador e indica qué mensajes alcanzan el destino. Es decir, que actúa como un filtro.

• Libro de recetas para prácticas populares de logging en Python*
• Guía de Python sobre el uso avanzado del módulo logging.
• Configuración declarativa con diccionarios y ficheros

Advertencias

Además del registro de sucesos, Python proporciona el módulo warnings para informar de ciertos aspectos al usuario. Su diferencia con el método warning radica en que la información va dirijida al usuario, no al desarrollador de la aplicación.

Esto quiere decir, en esencia, que el usuario puede hacer algo para eliminar la advertencia, sin tener que alterar el código de la biblioteca que produce la advertencia.

Quizá, el más famoso de los warnings sea el DeprecationWarning, que indica que una característica es obsoleta y se retirará en un futuro cercano:

import warnings

def new_api(*args, **kwargs):
    ...

def old_api(*args, **kwargs):
    warnings.warn('Use `new_api()`', DeprecationWarning)
    return new_api(*args, **kwargs)

old_api()

PyCharm, por ejemplo, detecta el uso de DeprecationWarning y lo indica en el editor.

Las advertencias pueden ser reinterpretadas por el sistema de registro de sucesos como sucesos de nivel WARNING si se activa la opción:

import logging
import warnings
logging.basicConfig()
logging.captureWarnings(True)
warnings.warn('Be prepared!')

• Documentación del módulo warnings

¿Cuándo usar qué?

A lo largo del curso te has encontrado con muchas formas de notificar información: print, excepciones, y ahora registros y advertencias. Esta tabla es una recomendación para cuándo usar qué característica:

Qué quieres hacer	Qué usar
Comunicar información al usuario	print()
Informar al desarrollador de que todo va bien	logging.info()
Asistir al desarrollador con el diagnóstico	logging.debug()
Advertir al usuario de algo	warnings.warn()
Advertir al desarrollador de algo	logging.warning()
Informar de un error en tiempo de ejecución	lanzar una excepción
Informar de un error sin interrumpir la ejecución de un programa	logging.error()

Buenas prácticas en el registro de sucesos

Cuando hablamos de información para el desarrollador, nos referimos a quienes han creado el software que otros usan, bien en forma de programa, bien en forma de biblioteca. Este otro es el usuario.

Cuando hablamos del desarrollador no nos referimos a un individuo en particular sino a un potencial equipo de desarrollo, incluyendo personas y herramientas de desarrollo.

Es conveniente cuidar el formato, la organización y el grado de detalle de los registros de eventos porque son la principal ayuda que tendrás a la hora de diagnosticar problemas y solventarlos.

Recuerda siempre que tu eres el principal consumidor de estos registros. Tú y tus herramientas de desarrollo. Por ejemplo, aunque no es común, no descartes registrar los eventos en formatos como YAML o JSON, que son fáciles de leer tanto para máquinas como para personas.

Dicho ingenuamente, "ponte las cosas fáciles".

• The Art of Logging*
• Guía de integración con software cliente