Gestion des logs Python

Introduction : logs Python

La journalisation des évènements appelée Logging en anglais est une pratique très utilisée en développement informatique quelque soit le langage de programmation. Elle permet d’avoir un historique des évènements normaux et anormaux survenus au cours du fonctionnement d’une application. Pendant tout le cycle de vie d’une application, l’utilisation des logs est très utile et recommandée :

• Pendant la phase de développement, les logs permettent de comprendre le fonctionnement d’une application en suivant l’exécution des différentes fonctions complexes. Ils sont complémentaires au debugger
• Pendant la phase d’intégration de l’application, ils permettent de mieux analyser des anomalies remontées
• Pendant la phase de production, ils peuvent faciliter le diagnostic des problèmes de prod remontés par les utilisateurs.

Au vu de l’importance des logs dans la vie d’un logiciel / application informatique, il est important d’utiliser les bonnes pratiques pour le logging et aussi des APIs / modules riches en fonctionnalités. Dans cet article, je vais parler du module « Logging » intégré de Python et conçu pour vous donner une visibilité critique sur vos applications avec une configuration simple et minimale.  Les principaux points qui sont présentés dans cet article sont :

• Les bases du module « logging » de Python
• La collection et la priorisation des logs
• La sauvegarde des logs
• L’utilisation avancée du module Logging de Python avec plusieurs loggeurs

1. Les bases du “logging” de Python

Le module logging est directement inclus dans les librairies standard de Python. La fonction magique / clée / principale de ce module est la fonction « basicConfig() » qui représente un moyen très rapide pour configurer votre journaliseur – logger. Cependant, la manière recommandée en Python est de créer un logger pour chaque module de votre application et il peut être difficile de faire une configuration de logger par module en utilisant uniquement basicConfig(). Par conséquent, la plupart des applications utilisent automatiquement une configuration de journalisation basée sur des fichiers ou des dictionnaires.

La fonction basicConfig() possède trois paramètres principaux qui sont le niveau de sévérité des logs – level, le handler et le format.

1.1 Niveau de sévérité des logs Python

La définition des niveaux de sévérité des logs est très importante et c’est une bonne pratique que je préconise et je recommande fortement. En effet, la génération des logs a un impact sur les performances de l’application et l’espacedisque nécessaire à leur rétention. Trop de logs noient les logs importants et saturent le système, trop peu de logs nuit à l’exploitabilité de l’application. D’où un compromis à trouver entre verbosité des logs et espace disque en définissant les niveaux de sévérité des logs en fonction de l’environnement et donc de la charge. La charge est différente d’un environnement à l’autre : sur l’environnement de développement, le développeur est seul alors qu’en production il peut y avoir plusieurs utilisateurs.

Par ordre d’alerte croissant, les niveaux de sévérité des logs disponibles dans le module logs Python sont : DEBUG, INFO, WARNING, ERROR et CRITICAL. Afin d’afficher ces différents types de niveau, le module logging fournit les fonctions suivantes : debug(), info(), warning(), error() et critical().

Voici un tableau récapitulatif sur les niveaux de sévérité, les fonctions correspondantes ainsi que leurs usages :

Par défaut, le niveau de sévérité est défini sur WARNING, ce qui signifie que le module de logs Python filtrera tous les messages de niveau de sévérité inférieur à celui de WARNING, c’est-à-dire les logs de niveau DEBUG ou INFO ne seront pas affichés. Voici un premier exemple d’utilisation du module logging avec les deux niveaux de sévérité INFO et WARNING :

import logging

logging.warning('This warning message will be logged!')
logging.info('This is an info message')

Voici la sortie de cet exemple :

WARNING:root:Watch out!

C’est uniquement le log de niveau de sévérité WARNING qui a été affiché.

1.2. Handler

Les handlers vous permettent de configurer vos propres loggers et envoyer les logs à plusieurs endroits lorsqu’ils sont générés. Les handlers envoient les messages de logs à des destinations configurées comme le flux de sortie standard qui est la console via StreamHandler, un fichier, via HTTP ou à votre e-mail via SMTP.

Un logger peut posséder plusieurs handlers, ce qui signifie que vous pouvez le configurer pour qu’il redirige les messages de logs dans un fichier et les envoyer également par e-mail.

Comme les loggers, les handlers possèdent des niveaux de sévérité que vous pouvez définir lors de votre configuration. Ceci est utile quand vous créez plusieurs handlers pour un même logger avec des niveaux de sévérité différents pour chaque type de sortie. Par exemple, vous pouvez afficher les logs de niveau WARNING uniquement sur la console, alors que les logs de niveau ERROR, vous les enregistrez aussi dans un fichier.

1.3. Format

Le format par défaut des messages de logs du module « logging » est <LEVEL>:<LOGGER_NAME>:<MESSAGE>. C’est le format de sortie de notre log de l’exemple ci-dessus. Vous pouvez personnaliser le format de vos logs pour inclure des horodatages et d’autres informations utiles pour l’identification de certains problèmes, c’est-à-dire pour le débogage.

2. Collection des logs Python avec le module “logging”

Après avoir défini dans la section précédente les principaux paramètres de configuration d’un logger qui sont le level, le handler et le format, nous illustrons dans cette sections des exemples d’utilisation de ces paramètres avec le module logging et la fonction basicConfig().

2.1. Exemple d’utilisation du paramètre level

Voici un exemple qui configure le paramètre level de la fonction basicConfig() :

import logging

logging.basicConfig(level=logging.INFO)
logging.info('This will be logged')

La sortie de ces lignes de code est :

INFO:root:This will be logged

Donc, maintenant tous les logs qui ont un level INFO et plus seront affichés.

2.2. Exemple d’utilisation du paramètre handler / filename

Comme nous l’avons indiqué dans la section précédente, nous pouvons rediriger les logs vers des fichiers avec le handler en utilisant les paramètres filename et filemode, sachant que ce dernier est par défaut à « append ». Ceci est illustré dans l’exemple ci-dessous :

import logging

logging.basicConfig(filename='log.txt')
logging.warning('This will get logged to a file')

Un fichier nommé « log.txt » a été créé contenant ce message :

WARNING:root:This will get logged to a file

2.3. Exemple d’utilisation du paramètre format

Nous pouvons personnaliser le format de sortie de nos logs en le configurant via le paramètre format. Nous pouvons passer des variables de notre programme sous forme de chaîne de caractères au format de sortie de nos logs afin qu’elles soient affichées dans nos messages de logs. Nous pouvons également utiliser certains éléments de base qui sont intégrés dans LogRecord et qui peuvent être facilement ajoutés au format de sortie de nos logs. Pour information, LogRecord est une instance crée automatiquement à partir du message de log dès que le logger enregistre un évènement.

Voici un exemple de personnalisation de format en affichant des informations sur la date, l’heure, le niveau et le message à passer :

import logging

logging.basicConfig(format='%(asctime)s - %(levelname)s - %(message)s', datefmt='%d-%b-%y %H:%M:%S')
logging.warning('User logged in')

Voici le résultat :

20-Oct-21 14:49:07 - WARNING - User logged in

Comme nous pouvons le constater dans notre exemple ci-dessus, %(asctime)s ajoute la date et l’heure de création du LogRecord, %(levelname)s affiche le niveau de sévérité du log et l’attribut datefmt permet de préciser le format d’affichage de la date, similaire à la fonction datetime.strftime() du module datetime.

Nous utilisons souvent les logs avec du multithreading pour suivre les exécutions de différents threads. Voici un exemple qui sauvegarde les logs d’exécution de la fonction worker(args) par chaque thread dans le fichier « output.log » en affichant des logs personnalisés avec le paramètre format :

import threading
import logging

logging.basicConfig(format='%(levelname)s %(threadName)s: Ceci est le %(message)s-ième message du %(threadName)s', filename='output.log', level=logging.DEBUG)


def worker(n):
    for i in range( n+1 ):
        logging.debug(i)
    
t = threading.Thread(name='thread1', target=worker, args=(100000,))
s = threading.Thread(name='thread2', target=worker, args=(50000,))
t.start()
s.start()

Voici un extrait du résultat sauvegardé dans le fichier « output.log » :

DEBUG thread1: Ceci est le 0-ième message du thread1
DEBUG thread1: Ceci est le 1-ième message du thread1
DEBUG thread2: Ceci est le 0-ième message du thread2
DEBUG thread1: Ceci est le 2-ième message du thread1
DEBUG thread2: Ceci est le 1-ième message du thread2
DEBUG thread1: Ceci est le 3-ième message du thread1
DEBUG thread2: Ceci est le 2-ième message du thread2

Ces logs contiennent des informations sur le level, le nom du thread et le message passé dans le fonction logging.debug(). Le nom du thread « threadName », comme le levelname et le message, est intégré dans LogRecord.

2.4. Exemple d’utilisation de variable dynamique dans les logs Python

Nous souhaitons souvent inclure des données dynamiques dans l’affichage de nos logs, en particulier pendant le débogage d’une application. Comme nous l’avons constaté dans les exemples ci-dessus, les fonctions de logging prennent comme argument des chaînes de caractères. Les chaînes de caractères peuvent être facilement formattées avec des variables / données dynamiques en utilisant par exemple le style de formatage f-string, qui permet de garder un formatage court et simple à lire.

Voici un exemple qui montre l’affichage d’une variable dynamique qui correspond à la longueur de la variable phrase :

import logging

logging.basicConfig(level=logging.DEBUG)

phrase = 'Programmez est le seul magazine écrit par et pour les développeurs'
logging.debug(f'Votre phrase contient {len(phrase)} caractères')

Voici le résultat :

DEBUG:root:Votre phrase contient 66 caractères

2.5. Exemple de capture des traces de pile avec le module logging (logs Python)

Le module de logging vous permet également de capturer les traces complètes de la pile d’exécution d’une application. Dans ce cas, les fonctions de logging sont généralement utilisées dans un bloc de gestion d’exception, tel que le cas pour l’exemple ci-dessous :

import logging
a, b = 100, 0
try:
  c = a / b
except Exception as e:
  logging.error(f"Exception occurred: {e}")

Voici le résultat :

ERROR:root:Exception occurred: division by zero

Si nous souhaitons afficher les informations sur l’exception, nous devons mettre le paramètre exc_info de la fonction logging.error() à True afin de capturer ces informations. Voici le code correspondant :

import logging
a, b = 100, 0
try:
  c = a / b
except Exception as e:
  logging.error(f"Exception occurred: {e}", exc_info=True)

Voici les informations complètes sur l’exception :

ERROR:root:Exception occurred: division by zero
Traceback (most recent call last):
  File "exception_log.py", line 5, in <module>
    c = a / b
ZeroDivisionError: division by zero

3. Utilisation avancée du module « logging »

Nous avons bien couvert dans les parties précédentes les bases du module logging et en particulier la fonction basicConfig(), qui est un moyen rapide pour configurer un logger par défaut appelé root. Néanmoins, la méthode recommandée pour la journalisation consiste à créer un logger par module. En effet, au fur et à mesure que votre application évolue et devient complexe, vous aurez besoin d’un moyen plus robuste et évolutif pour configurer un logger spécifique par module et pour capturer le nom du logger dans chaque message. Dans cette partie, nous allons découvrir comment configurer plusieurs loggers et capturer automatiquement le nom du logger.

Configuration de plusieurs loggers et capture automatique du nom du logger

Une bonne pratique de création d’un nouvel logger pour chaque module de votre application est d’utiliser la fonction intégrée getLogger() de la librairie « logging » pour définir dynamiquement le nom du logger afin qu’il corresponde au nom de votre module. Voici un exemple de création d’un logger avec cette fonction :

logger = logging.getLogger(__name__)

Dans cet exemple, nous avons mis « __name__ » pour l’attribut nom du logger de la fonction getLogger() afin qu’il corresponde au nom qualifié complet du module à partir duquel cette méthode est appelée. Cela vous permet de voir exactement quel module de votre application a généré chaque message de vos logs, pour que vous puissiez les interpréter plus facilement.

Par exemple, si votre application comporte un module birthdatemodule.py, qui est appelé depuis un autre module, save_data_users.py, la fonction getLogger() mettra le nom du logger au nom du module associé.  On peut visualiser cette information quand on modifie le format du logger pour intégrer le nom « %(name)s » dans les messages de logs. Un exemple avec deux modules dont chacun contient un logger défini avec le même format est illustré ci-dessus. Cet exemple consiste à récupérer des informations sur des utilisateurs, qui sont le nom, prénom et date de naissance, à partir d’un fichier texte et les sauvegarder dans un fichier csv avec un format datetime pour le champ date de naissance.

Voici le code du premier module birthdatemodule.py qui permet de convertir une chaîne de caractères indiquant la date au format / type datetime. Comme la chaîne de caractère de date précisée dans le fichier texte peut avoir plusieurs formats, dans notre code nous allons essayer de la convertir en prenant en compte deux formats possibles. Ces deux formats sont indiqués dans le premier et second bloc try/except de la fonction get_birth_date() de ce module. Hors ces deux formats, la date ne sera pas convertie et elle ne sera pas affichée dans le fichier csv qui va être généré.

# birthdatemodule.py

from datetime import datetime
from typing import Optional
import logging

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(name)s %(levelname)s:%(message)s')
logger = logging.getLogger(__name__)


def get_birth_date(date) -> Optional[datetime]:
    if date:
        try:
            return (date if isinstance(date, datetime)
                    else datetime.strptime(date, '%Y-%m-%d'))
        except ValueError:
            logger.debug(f"{date} is not in the format yyyy-mm-dd. Will try to convert it to the format yyyy/mm/dd")
            try:
                return datetime.strptime(date, '%Y/%m/%d')
            except ValueError:
                logger.debug(f"Unable to convert date. Should be in format yyyy-mm-dd or yyyy/mm/dd")
            return

Comme nous pouvons le constater dans notre code ci-dessus, nous gérons la conversion la date  de avec des blocs de try/except et en utilisant des logs affichant les traitements et les avertissements importants  pour le développeur / utilisateur.

Voici le second module save_data_users.py qui permet de lire les fichiers textes précisés dans la variable FILES et de sauvegarder les informations extraites dans des fichiers csv avec la fonction save_users_data(). Comme le module birthdatamodule.py, ce module utilise un logger affichant le nom du module, le niveau de sévérité du message, la date et l’heure d’exécution. La fonction save_users_data() gère l’exception de non-existence d’un fichier avec un bloc try/except et en utilisant la fonction logger.error() pour afficher l’erreur OSError et la fonction logger.warning() pour avertir l’utilisateur de la non-existence d’un fichier.

# save_data_users

import re
import logging
import birthdatemodule

logging.basicConfig(level=logging.DEBUG, format='%(asctime)s% (name)s %(levelname)s:%(message)s')
logger = logging.getLogger(__name__)

FILES = ('Python_users.txt', 'C#_users.txt')

def save_users_data():
    logger.info("starting users data processing")
    for file in FILES:
        try:
            with open(file[:-4] + '.csv', 'a') as csv_file:
                print(*['Birthdate', 'User'], file=csv_file)
                try:
                    with open(file, 'r') as txt_file:
                        logger.info(f"reading {file}")
                        i = 0
                        for line in txt_file:
                            data = get_users_data(line)
                            print(*data, file=csv_file)
                            i += 1
                    logger.debug(f"finish processing {i} users for the file {file}")
                except OSError as e:
                    logger.error(f"error reading the file {e}")
        except:
            logger.warning(f"The file {file} doesn't exist")
        finally:
            logger.debug(f"The function is executed for the file {file}")
def get_users_data(line):
    line = line.rstrip()
    user_name = re.findall('([a-zA-Z]+)\s', line)
    d = re.findall('([0-9].*)', line)[0]
    date = birthdatemodule.get_birth_date(d)
    return [date, user_name]

if __name__ == "__main__":
    save_users_data()

Si nous exécutons le module save_data_users.py, sachant que le fichier « Python_users.txt » est accessible mais le fichier « C#_users.txt » n’existe pas, le module logging générera la sortie suivante :

2021-10-26 11:58:35,743 __main__ INFO:starting users data processing
2021-10-26 11:58:35,744 __main__ INFO:reading Python_users.txt
2021-10-26 11:58:35,749 birthdatemodule DEBUG:1984/05/14 is not in the format yyyy-mm-dd. Will try to convert it to the format yyyy/mm/dd
2021-10-26 11:58:35,749 birthdatemodule DEBUG:1955/10/28 is not in the format yyyy-mm-dd. Will try to convert it to the format yyyy/mm/dd
2021-10-26 11:58:35,750 __main__ DEBUG:finish processing 5 users for the file Python_users.txt
2021-10-26 11:58:35,750 __main__ DEBUG:The function is executed for the file Python_users.txt
2021-10-26 11:58:35,750 __main__ ERROR:error reading the file [Errno 2] No such file or directory: 'C#_users.txt'
2021-10-26 11:58:35,751 __main__ DEBUG:The function is executed for the file C#_users.txt

Le nom du logger est inclus juste après la date et l’heure d’exécution, afin que vous puissiez voir quel module exactement a généré chaque message. Si vous ne définissez pas le logger avec la fonction getLogger(), les messages de tous les loggers s’afficheront avec le nom root, ce qui rend l’analyse des logs difficile pour faire la différence entre les messages de chaque module. Les messages qui ont été enregistrés à partir du module save_data_users.py auront le nom « __main__ » affiché dans les messages du log, car ce module a été exécuté en tant que script de niveau supérieur. Les messages du logger du module birthdatamodule.py ont été affichés avec son nom qui est « birthdatamodule».

Conclusion

Nous avons vu que la journalisation / logging est un outil très utile dans la boîte à outils d’un développeur. Cela peut vous aider à mieux comprendre le déroulement d’une application / d’un programme et à découvrir des scénarios auxquels vous n’avez peut-être pas pensé lors de la phase du développement. Dans cet article, nous avons parlé de quelques bonnes pratiques pour configurer la librairie standard « logging » de Python (logs Python), qui est une librairie très flexible et qui permet de générer des logs riches en contexte et à capturer des traces d’exceptions.

Avec cette librairie, comme nous pouvons configurer rapidement un logger de base avec la fonction « basicConfig() » pour un petit projet, nous pouvons aussi configurer nos propres niveaux de sévérité de journalisation, de handlers et de formats personnalisés sur un grand projet avec la création de plusieurs loggeus en utilisant la fonction « getLogger() ».  Dans cet article, nous avons illustré des exemples d’utilisation basique de logger et aussi des exemples d’utilisation avancée avec la création de plusieurs loggers ayant des formats personnalisés.

Si vous voulez en apprendre plus sur la programmation Python, vous pouvez consulter notre blog. Notre expertise Python est très active dans la rédaction d’article Python, comme par exemple la mise en cache et ses utilisations en Python.