Journalisation Python : un didacticiel approfondi

À mesure que les applications deviennent plus complexes, disposer de bons journaux peut être très utile, non seulement lors du débogage, mais également pour fournir des informations sur les problèmes/performances des applications.

La bibliothèque standard Python est livrée avec un module de journalisation qui fournit la plupart des fonctionnalités de journalisation de base. En le configurant correctement, un message de journal peut apporter de nombreuses informations utiles sur le moment et l'endroit où le journal est déclenché, ainsi que sur le contexte du journal, tel que le processus/thread en cours d'exécution.

Malgré les avantages, le module de journalisation est souvent négligé car il faut un certain temps pour s'installer correctement et, bien que complet, à mon avis, la doc officielle de journalisation sur https://docs.python.org/3/library/logging.html ne donne pas vraiment les meilleures pratiques de journalisation ni ne met en évidence certaines surprises de journalisation.

Ce didacticiel de journalisation Python n'est pas censé être un document complet sur le module de journalisation, mais plutôt un guide de «démarrage» qui présente certains concepts de journalisation ainsi que certains «pièges» à surveiller. Le message se terminera par les meilleures pratiques et contiendra des pointeurs vers des sujets de journalisation plus avancés.

Veuillez noter que tous les extraits de code de l'article supposent que vous avez déjà importé le module de journalisation :

 import logging

Concepts pour la journalisation Python

Cette section donne un aperçu de certains concepts souvent rencontrés dans le module de journalisation.

Niveaux de journalisation Python

Le niveau de log correspond à « l'importance » qu'on donne à un log : un log « error » doit alors être plus urgent qu'un log « warn », alors qu'un log « debug » ne doit servir qu'au débogage de l'application.

Il existe six niveaux de journalisation en Python ; chaque niveau est associé à un entier qui indique la gravité du journal : NOTSET=0, DEBUG=10, INFO=20, WARN=30, ERROR=40 et CRITICAL=50.

Tous les niveaux sont assez simples (DEBUG < INFO < WARN ) sauf NOTSET, dont la particularité sera abordée ensuite.

Formatage de journalisation Python

Le formateur de journal enrichit essentiellement un message de journal en y ajoutant des informations de contexte. Il peut être utile de savoir quand le journal est envoyé, où (fichier Python, numéro de ligne, méthode, etc.) et un contexte supplémentaire tel que le thread et le processus (peut être extrêmement utile lors du débogage d'une application multithread).

Par exemple, lorsqu'un journal "hello world" est envoyé via un formateur de journal :

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

ça va devenir

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

Gestionnaire de journalisation Python

Le log handler est le composant qui écrit/affiche effectivement un log : Affichez-le dans la console (via StreamHandler), dans un fichier (via FileHandler), ou encore en vous envoyant un email via SMTPHandler, etc.

Chaque gestionnaire de journaux a 2 champs importants :

• Un formateur qui ajoute des informations de contexte à un journal.
• Un niveau de journal qui filtre les journaux dont les niveaux sont inférieurs. Ainsi, un gestionnaire de journaux avec le niveau INFO ne gérera pas les journaux DEBUG.

La bibliothèque standard fournit une poignée de gestionnaires qui devraient suffire pour les cas d'utilisation courants : https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers. Les plus courants sont StreamHandler et FileHandler :

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

Enregistreur Python

Logger est probablement celui qui sera utilisé directement le plus souvent dans le code et qui est aussi le plus compliqué. Un nouvel enregistreur peut être obtenu en :

 toto_logger = logging.getLogger("toto")

Un logger a trois champs principaux :

• Propager : décide si un journal doit être propagé au parent du journal. Par défaut, sa valeur est True.
• Niveau A : comme le niveau du gestionnaire de journaux, le niveau de journalisation est utilisé pour filtrer les journaux "moins importants". Sauf que, contrairement au gestionnaire de journaux, le niveau n'est vérifié qu'au niveau du logger "enfant" ; une fois le journal propagé à ses parents, le niveau ne sera pas vérifié. C'est plutôt un comportement non intuitif.
• Gestionnaires : la liste des gestionnaires auxquels un journal sera envoyé lorsqu'il arrivera à un enregistreur. Cela permet une gestion flexible des journaux. Par exemple, vous pouvez avoir un gestionnaire de journaux de fichiers qui consigne tous les journaux DEBUG et un gestionnaire de journaux de courrier électronique qui ne sera utilisé que pour les journaux CRITICAL. À cet égard, la relation logger-handler est similaire à une relation éditeur-consommateur : un journal sera diffusé à tous les handlers une fois qu'il aura passé la vérification au niveau du logger.

Un logger est unique par son nom, ce qui signifie que si un logger portant le nom « toto » a été créé, les appels consécutifs de logging.getLogger("toto") le même objet :

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

Comme vous l'avez peut-être deviné, les enregistreurs ont une hiérarchie. Au sommet de la hiérarchie se trouve le root logger, accessible via logging.root. Ce journal est appelé lorsque des méthodes telles que logging.debug() sont utilisées. Par défaut, le niveau de journal racine est WARN, donc chaque journal de niveau inférieur (par exemple via logging.info("info") ) sera ignoré. Une autre particularité du root logger est que son gestionnaire par défaut sera créé la première fois qu'un journal avec un niveau supérieur à WARN sera journalisé. L'utilisation directe ou indirecte du root logger via des méthodes telles que logging.debug() n'est généralement pas recommandée.

Par défaut, lorsqu'un nouveau logger est créé, son parent sera défini sur le logger racine :

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

Cependant, l'enregistreur utilise la "notation par points", ce qui signifie qu'un enregistreur avec le nom "ab" sera l'enfant de l'enregistreur "a". Cependant, cela n'est vrai que si le logger "a" a été créé, sinon le parent "ab" est toujours la racine.

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

Lorsqu'un enregistreur décide si un journal doit réussir en fonction du contrôle de niveau (par exemple, si le niveau du journal est inférieur au niveau de l'enregistreur, le journal sera ignoré), il utilise son « niveau effectif » au lieu du niveau réel. Le niveau effectif est le même que le niveau du logger si le niveau n'est pas NOTSET, c'est-à-dire toutes les valeurs de DEBUG à CRITICAL ; cependant, si le niveau de l'enregistreur est NOTSET, le niveau effectif sera le premier niveau ancêtre qui a un niveau non-NOTSET.

Par défaut, un nouveau logger a le niveau NOTSET, et comme le logger racine a un niveau WARN, le niveau effectif du logger sera WARN. Ainsi, même si un nouveau logger a des gestionnaires attachés, ces gestionnaires ne seront pas appelés à moins que le niveau de journalisation ne dépasse 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

Par défaut, le niveau de journalisation sera utilisé pour décider des passes d'un journal : si le niveau de journalisation est inférieur au niveau de journalisation, le journal sera ignoré.

Bonnes pratiques de journalisation Python

Le module de journalisation est en effet très pratique, mais il contient quelques bizarreries qui peuvent causer de longues heures de casse-tête même aux meilleurs développeurs Python. Voici les bonnes pratiques d'utilisation de ce module selon moi :

• Configurez le root logger mais ne l'utilisez jamais dans votre code, par exemple, n'appelez jamais une fonction comme logging.info() , qui appelle en fait le root logger derrière la scène. Si vous souhaitez intercepter les messages d'erreur des bibliothèques que vous utilisez, assurez-vous de configurer le root logger pour qu'il écrive dans un fichier, par exemple, pour faciliter le débogage. Par défaut, le root logger ne sort que vers stderr , donc le journal peut se perdre facilement.
• Pour utiliser la journalisation, assurez-vous de créer un nouveau journal en utilisant logging.getLogger(logger name) . J'utilise généralement __name__ comme nom de l'enregistreur, mais tout peut être utilisé, tant qu'il est cohérent. Pour ajouter plus de gestionnaires, j'ai généralement une méthode qui renvoie un enregistreur (vous pouvez trouver l'essentiel sur 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

Après vous pouvez créer un nouveau logger et l'utiliser :

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

• Utilisez les classes RotatingFileHandler, telles que TimedRotatingFileHandler utilisé dans l'exemple au lieu de FileHandler, car il fera automatiquement pivoter le fichier pour vous lorsque le fichier atteint une taille limite ou le fera tous les jours.
• Utilisez des outils tels que Sentry, Airbrake, Raygun, etc., pour capturer automatiquement les journaux d'erreurs pour vous. Ceci est particulièrement utile dans le contexte d'une application Web, où le journal peut être très détaillé et les journaux d'erreurs peuvent se perdre facilement. Un autre avantage de l'utilisation de ces outils est que vous pouvez obtenir des détails sur les valeurs des variables dans l'erreur afin de savoir quelle URL déclenche l'erreur, quel utilisateur est concerné, etc.

Si vous êtes intéressé par d'autres bonnes pratiques, lisez Les 10 erreurs les plus courantes commises par les développeurs Python par un collègue Toptaler Martin Chikilian.