La journalisation de Django, la bonne façon

Une bonne journalisation est essentielle pour déboguer et résoudre les problèmes. Non seulement c’est utile dans le développement local, mais en production c’est indispensable. Lors de l’examen des journaux pour un problème, il est rare d’entendre quelqu’un dire :  » Nous avons trop de journalisation dans notre application « , mais courant d’entendre l’inverse. Donc, avec cela en tête, commençons.

A Crash Course in Python Loggers

Au sommet de chaque fichier, vous devriez avoir quelque chose comme ceci:

import logginglogger = logging.getLogger(__name__)

__name__ sera évalué au chemin Python en pointillés du module, par exemple myproject/myapp/views.py utilisera myproject.myapp.views. Maintenant, nous pouvons utiliser ce logger dans tout le fichier comme suit :

# A simple string logged at the "warning" levellogger.warning("Your log message is here")# A string with a variable at the "info" levellogger.info("The value of var is %s", var)# Logging the traceback for a caught exceptiontry: function_that_might_raise_index_error()except IndexError: # equivalent to logger.error(msg, exc_info=True) logger.exception("Something bad happened")

Note : les loggers de Python se chargeront d’insérer des variables dans votre message de log si vous les passez comme arguments dans la fonction de logging. Si le journal n’a pas besoin d’être émis, la substitution de variables ne se produira jamais, ce qui permet d’éviter un petit coup de performance pour un journal qui ne sera jamais utilisé.

Parsemez généreusement votre code de ces déclarations de journalisation. Voici la règle empirique que j’utilise pour les niveaux de journalisation:

• debug : Info non nécessaire pour le fonctionnement régulier, mais utile dans le développement.
• info : Info qui est utile pendant le fonctionnement régulier.
• warning : Info qui pourrait être problématique, mais qui n’est pas urgente.
• error : Info qui est importante et nécessite probablement une attention rapide.
• critical : Je ne me retrouve pas à l’utiliser dans la pratique, mais si vous avez besoin d’un plus haut que error, le voici

Où enregistrer

Votre application ne devrait pas se préoccuper de l’endroit où ses journaux vont. Au lieu de cela, elle devrait tout enregistrer dans la console (stdout/stderr) et laisser le serveur décider de ce qu’il faut en faire à partir de là. Typiquement, cela est mis dans un fichier dédié (et logoté), capturé par le journal Systemd ou Docker, envoyé à un service séparé comme ElasticSearch, ou une combinaison de ces éléments. Le stockage des journaux est une préoccupation de déploiement, pas une préoccupation d’application.

La seule chose dont votre application doit se préoccuper est le format des journaux. Typiquement, c’est juste une chaîne avec les données pertinentes, mais si votre serveur ajoute déjà un horodatage au journal, vous voulez probablement l’exclure de votre propre formatter. De même, si votre agrégateur de logs peut accepter JSON, un formateur comme python-json-logger peut être plus approprié.

Configuration du logger

Écrire aux loggers en Python est facile. Les configurer pour qu’ils aillent au bon endroit est plus difficile que vous ne le pensez. Je vais commencer par contourner la journalisation par défaut de Django, comme décrit dans mon post précédent. Cela nous fournira une ardoise vierge avec laquelle travailler.

Setting up Sentry

Les services de rapport d’erreurs sont critiques pour tout site non trivial. Par défaut, ceux-ci attrapent les exceptions non attrapées, vous notifient du problème (une seule fois par incident) et fournissent une interface agréable pour voir l’état de l’app lorsque l’exception s’est produite. Mon service préféré pour cela est Sentry.

Nous pouvons pousser Sentry un cran plus loin en envoyant également au service tous les messages de log qui sont warning ou plus. Ceux-ci seraient autrement perdus dans une mer de fichiers journaux qui, en pratique, sont rarement examinés. Pour ce faire, nous allons ajouter un logger « root » qui servira de fourre-tout pour tous les logs envoyés par n’importe quel module Python. Cela ressemble à quelque chose comme ceci dans les paramètres de Django,

import logging.configLOGGING_CONFIG = Nonelogging.config.dictConfig({ 'version': 1, 'disable_existing_loggers': False, 'formatters': { 'console': { # exact format is not important, this is the minimum information 'format': '%(asctime)s %(name)-12s %(levelname)-8s %(message)s', }, }, 'handlers': { 'console': { 'class': 'logging.StreamHandler', 'formatter': 'console', }, # Add Handler for Sentry for `warning` and above 'sentry': { 'level': 'WARNING', 'class': 'raven.contrib.django.raven_compat.handlers.SentryHandler', }, }, 'loggers': { # root logger '': { 'level': 'WARNING', 'handlers': , }, },})

Logging de votre application

Bien que vous puissiez seulement vouloir connaître les avertissements et les erreurs de vos dépendances tierces, vous voulez généralement un aperçu beaucoup plus profond du code de votre application. Idéalement, votre code vit tous sous un seul espace de noms afin qu’il puisse être capturé avec un seul ajout à la loggers. Supposons que votre projet utilise l’espace de noms myproject, en se basant sur le code ci-dessus, vous ajouteriez ceci :

logging.config.dictConfig({ # ... 'loggers': { '': { 'level': 'WARNING', 'handlers': , }, 'myproject': { 'level': 'INFO', 'handlers': , # required to avoid double logging with root logger 'propagate': False, }, },})

Mais que se passe-t-il si vous voulez enquêter plus profondément sur quelque chose dans votre application avec la journalisation debug ? Avoir à commettre un nouveau code et à le déployer semble être une surcharge. C’est un excellent cas d’utilisation des variables d’environnement. Nous pouvons modifier la strophe précédente pour qu’elle ressemble à ceci:

import osLOGLEVEL = os.environ.get('LOGLEVEL', 'info').upper()logging.config.dictConfig({ # ... 'loggers': { '': { 'level': 'WARNING', 'handlers': , }, 'myproject': { 'level': LOGLEVEL, 'handlers': , # required to avoid double logging with root logger 'propagate': False, }, },})

Maintenant, la journalisation de notre application sera par défaut de info, mais peut facilement être augmentée temporairement en définissant la variable d’environnement LOGLEVEL=debug. Alternativement, si le stockage des journaux n’est pas un problème, considérez toujours la journalisation au niveau debug. Ils sont assez faciles à filtrer avec un simple grep ou via votre outil de visualisation des journaux, par exemple Kibana.

Cutting out the Noise

Une fois que vous avez votre journalisation configurée et en cours d’exécution, vous pouvez constater que certains modules enregistrent des informations dont vous ne vous souciez pas vraiment et ne servent qu’à créer du bruit supplémentaire (je vous regarde newrelic). Pour ces modules, nous pouvons ajouter un autre logger pour les désactiver. La première option est de les enregistrer dans la console, mais d’éviter de les propager au logger racine qui les enverrait à Sentry:

logging.config.dictConfig({ # ... 'loggers': { '': { 'level': 'WARNING', 'handlers': , }, 'myproject': { 'level': LOGLEVEL, 'handlers': , # required to avoid double logging with root logger 'propagate': False, }, # Don't send this module's logs to Sentry 'noisy_module': { 'level':'ERROR', 'handlers': , 'propagate': False, }, },})

Si vous trouvez qu’ils sont trop bruyants, même pour la console, nous pouvons les laisser tomber complètement:

logging.config.dictConfig({ # ... 'loggers': { # ... # Don't log this module at all 'noisy_module': { 'level': 'NOTSET', 'propagate': False, }, },})

Local Request Logging

Une nicety dans la configuration par défaut de Django est l’enregistrement des requêtes avec runserver. En écrasant la configuration de Django, nous le perdons, mais il est assez facile de le rajouter :

from django.utils.log import DEFAULT_LOGGINGlogging.config.dictConfig({ # ... 'formatters': { # ... 'django.server': DEFAULT_LOGGING, }, 'handlers': { # ... 'django.server': DEFAULT_LOGGING, }, 'loggers': { # ... 'django.server': DEFAULT_LOGGING, },})

.