Registro de Python: un tutorial detallado

A medida que las aplicaciones se vuelven más complejas, tener buenos registros puede ser muy útil, no solo durante la depuración, sino también para brindar información sobre los problemas o el rendimiento de la aplicación.

La biblioteca estándar de Python viene con un módulo de registro que proporciona la mayoría de las funciones básicas de registro. Al configurarlo correctamente, un mensaje de registro puede brindar mucha información útil sobre cuándo y dónde se activa el registro, así como el contexto del registro, como el proceso/subproceso en ejecución.

A pesar de las ventajas, el módulo de registro a menudo se pasa por alto, ya que lleva algún tiempo configurarlo correctamente y, aunque completo, en mi opinión, el documento oficial de registro en https://docs.python.org/3/library/logging.html realmente no proporciona las mejores prácticas de registro ni destaca algunas sorpresas de registro.

Este tutorial de registro de Python no pretende ser un documento completo sobre el módulo de registro, sino más bien una guía de "inicio" que presenta algunos conceptos de registro, así como algunos "errores" a tener en cuenta. La publicación terminará con las mejores prácticas y contendrá algunos consejos sobre temas de registro más avanzados.

Tenga en cuenta que todos los fragmentos de código en la publicación suponen que ya ha importado el módulo de registro:

 import logging

Conceptos para el registro de Python

Esta sección ofrece una descripción general de algunos conceptos que se encuentran a menudo en el módulo de registro.

Niveles de registro de Python

El nivel de registro corresponde a la "importancia" que se le da a un registro: un registro de "error" debería ser más urgente que el registro de "advertencia", mientras que un registro de "depuración" debería ser útil solo cuando se depura la aplicación.

Hay seis niveles de registro en Python; cada nivel está asociado con un número entero que indica la gravedad del registro: NOTSET=0, DEBUG=10, INFO=20, WARN=30, ERROR=40 y CRITICAL=50.

Todos los niveles son bastante sencillos (DEBUG < INFO < WARN ) excepto NOTSET, cuya particularidad se abordará a continuación.

Formato de registro de Python

El formateador de registros básicamente enriquece un mensaje de registro al agregarle información de contexto. Puede ser útil saber cuándo se envía el registro, dónde (archivo de Python, número de línea, método, etc.) y contexto adicional, como el subproceso y el proceso (puede ser extremadamente útil al depurar una aplicación multiproceso).

Por ejemplo, cuando se envía un registro "hola mundo" a través de un formateador de registros:

 "%(asctime)s — %(name)s — %(levelname)s — %(funcName)s:%(lineno)d — %(message)s"

Se convertirá

 2018-02-07 19:47:41,864 - abc - WARNING - <module>:1 - hello world 

Controlador de registro de Python

El controlador de registro es el componente que escribe/muestra un registro de manera efectiva: muéstrelo en la consola (a través de StreamHandler), en un archivo (a través de FileHandler), o incluso enviándole un correo electrónico a través de SMTPHandler, etc.

Cada controlador de registro tiene 2 campos importantes:

• Un formateador que agrega información de contexto a un registro.
• Un nivel de registro que filtra los registros cuyos niveles son inferiores. Por lo tanto, un controlador de registros con el nivel INFO no manejará los registros DEBUG.

La biblioteca estándar proporciona varios controladores que deberían ser suficientes para casos de uso comunes: https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers. Los más comunes son StreamHandler y FileHandler:

 console_handler = logging.StreamHandler() file_handler = logging.FileHandler("filename")

Registrador de Python

Logger es probablemente el que se usará directamente con más frecuencia en el código y que también es el más complicado. Se puede obtener un nuevo registrador:

 toto_logger = logging.getLogger("toto")

Un registrador tiene tres campos principales:

• Propagar: decide si un registro debe propagarse al padre del registrador. Por defecto, su valor es True.
• Un nivel: Al igual que el nivel del controlador de registros, el nivel del registrador se usa para filtrar los registros "menos importantes". Excepto que, a diferencia del controlador de registros, el nivel solo se verifica en el registrador "secundario"; una vez que el registro se propaga a sus padres, el nivel no se verificará. Esto es más bien un comportamiento poco intuitivo.
• Controladores: la lista de controladores a los que se enviará un registro cuando llegue a un registrador. Esto permite un manejo de registros flexible; por ejemplo, puede tener un controlador de registros de archivos que registre todos los registros de DEPURACIÓN y un controlador de registros de correo electrónico que solo se usará para los registros CRÍTICOS. En este sentido, la relación registrador-controlador es similar a la de un editor-consumidor: un registro se transmitirá a todos los controladores una vez que pase la verificación del nivel del registrador.

Un registrador es único por su nombre, lo que significa que si se ha creado un registrador con el nombre "toto", las llamadas consiguientes de logging.getLogger("toto") devolverán el mismo objeto:

 assert id(logging.getLogger("toto")) == id(logging.getLogger("toto"))

Como habrás adivinado, los registradores tienen una jerarquía. En la parte superior de la jerarquía se encuentra el registrador raíz, al que se puede acceder a través de logging.root. Este registrador se llama cuando se utilizan métodos como logging.debug() . De forma predeterminada, el nivel de registro raíz es WARN, por lo que se ignorarán todos los registros con un nivel más bajo (por ejemplo, a través de logging.info("info") ). Otra particularidad del registrador raíz es que su controlador predeterminado se creará la primera vez que se registre un registro con un nivel superior a WARN. Por lo general, no se recomienda usar el registrador raíz directa o indirectamente a través de métodos como logging.debug() .

De forma predeterminada, cuando se crea un nuevo registrador, su principal se establecerá en el registrador raíz:

 lab = logging.getLogger("ab") assert lab.parent == logging.root # lab's parent is indeed the root logger

Sin embargo, el registrador usa la "notación de puntos", lo que significa que un registrador con el nombre "ab" será el hijo del registrador "a". Sin embargo, esto solo es cierto si se ha creado el registrador "a", de lo contrario, el padre "ab" sigue siendo la raíz.

 la = logging.getLogger("a") assert lab.parent == la # lab's parent is now la instead of root

Cuando un registrador decide si un registro debe pasar de acuerdo con la verificación de nivel (por ejemplo, si el nivel de registro es más bajo que el nivel del registrador, el registro se ignorará), utiliza su "nivel efectivo" en lugar del nivel real. El nivel efectivo es el mismo que el nivel del registrador si el nivel no está NO ESTABLECIDO, es decir, todos los valores desde DEBUG hasta CRITICAL; sin embargo, si el nivel del registrador NO ES ESTABLECIDO, entonces el nivel efectivo será el primer nivel de antepasado que tenga un nivel NO ESTABLECIDO.

De manera predeterminada, un registrador nuevo tiene el nivel NOTSET, y como el registrador raíz tiene un nivel WARN, el nivel efectivo del registrador será WARN. Entonces, incluso si un nuevo registrador tiene algunos controladores adjuntos, estos controladores no se llamarán a menos que el nivel de registro exceda WARN:

 toto_logger = logging.getLogger("toto") assert toto_logger.level == logging.NOTSET # new logger has NOTSET level assert toto_logger.getEffectiveLevel() == logging.WARN # and its effective level is the root logger level, ie WARN # attach a console handler to toto_logger console_handler = logging.StreamHandler() toto_logger.addHandler(console_handler) toto_logger.debug("debug") # nothing is displayed as the log level DEBUG is smaller than toto effective level toto_logger.setLevel(logging.DEBUG) toto_logger.debug("debug message") # now you should see "debug message" on screen

De forma predeterminada, el nivel del registrador se utilizará para decidir si se pasa un registro: si el nivel del registro es inferior al nivel del registrador, se ignorará el registro.

Mejores prácticas de registro de Python

El módulo de registro es muy útil, pero contiene algunas peculiaridades que pueden causar largas horas de dolor de cabeza incluso a los mejores desarrolladores de Python. Aquí están las mejores prácticas para usar este módulo en mi opinión:

• Configure el registrador raíz pero nunca lo use en su código; por ejemplo, nunca llame a una función como logging.info() , que en realidad llama al registrador raíz en segundo plano. Si desea detectar mensajes de error de las bibliotecas que utiliza, asegúrese de configurar el registrador raíz para escribir en un archivo, por ejemplo, para facilitar la depuración. De forma predeterminada, el registrador raíz solo envía a stderr , por lo que el registro puede perderse fácilmente.
• Para usar el registro, asegúrese de crear un nuevo registrador usando logging.getLogger(logger name) . Usualmente uso __name__ como el nombre del registrador, pero se puede usar cualquier cosa, siempre que sea consistente. Para agregar más controladores, generalmente tengo un método que devuelve un registrador (puede encontrar la esencia en https://gist.github.com/nguyenkims/e92df0f8bd49973f0c94bddf36ed7fd0).

 import logging import sys from logging.handlers import TimedRotatingFileHandler FORMATTER = logging.Formatter("%(asctime)s — %(name)s — %(levelname)s — %(message)s") LOG_FILE = "my_app.log" def get_console_handler(): console_handler = logging.StreamHandler(sys.stdout) console_handler.setFormatter(FORMATTER) return console_handler def get_file_handler(): file_handler = TimedRotatingFileHandler(LOG_FILE, when='midnight') file_handler.setFormatter(FORMATTER) return file_handler def get_logger(logger_name): logger = logging.getLogger(logger_name) logger.setLevel(logging.DEBUG) # better to have too much log than not enough logger.addHandler(get_console_handler()) logger.addHandler(get_file_handler()) # with this pattern, it's rarely necessary to propagate the error up to parent logger.propagate = False return logger

Después de que pueda crear un nuevo registrador y usarlo:

 my_logger = get_logger("my module name") my_logger.debug("a debug message")

• Use clases RotatingFileHandler, como TimedRotatingFileHandler que se usó en el ejemplo en lugar de FileHandler, ya que rotará el archivo automáticamente cuando el archivo alcance un límite de tamaño o lo hará todos los días.
• Utilice herramientas como Sentry, Airbrake, Raygun, etc., para capturar los registros de errores automáticamente. Esto es especialmente útil en el contexto de una aplicación web, donde el registro puede ser muy detallado y los registros de errores pueden perderse fácilmente. Otra ventaja de usar estas herramientas es que puede obtener detalles sobre los valores de las variables en el error para que pueda saber qué URL desencadena el error, a qué usuario se refiere, etc.

Si está interesado en más prácticas recomendadas, lea Los 10 errores más comunes que cometen los desarrolladores de Python por el compañero Toptaler Martin Chikilian.