backend / python
Logging structuré pour la production
Explication
Ce que vous allez apprendre
- Comprendre pourquoi
print()ne suffit plus dès qu'une application tourne en production - Distinguer les rôles de Logger, Handler et Formatter dans l'architecture du module
logging - Choisir le bon niveau de gravité (DEBUG, INFO, WARNING, ERROR, CRITICAL) pour chaque message
- Produire des logs structurés en JSON, exploitables par un outil d'observabilité
- Utiliser le formatage paresseux (
logger.info("%s", valeur)) pour éviter un coût inutile
Dans quel contexte ?
Un développeur reçoit un ticket de support décrivant une erreur intermittente en production, sans pouvoir la reproduire localement. Les seuls indices disponibles sont des print() éparpillés dans le code, dont la sortie s'est perdue dans les logs bruts du conteneur Docker, mélangée à des milliers d'autres lignes sans structure ni horodatage précis. Remplacer ces print() par un logger correctement configuré, avec un identifiant de corrélation par requête, aurait permis de retrouver en quelques secondes tous les événements liés à cette requête précise.
Pourquoi print() ne suffit plus en production
print() est parfait pour déboguer localement, mais devient inutilisable à l'échelle d'une application en production : impossible de filtrer par gravité, de router vers un fichier ou un service distant, ou d'exploiter automatiquement les messages. Le module logging répond à ces besoins avec une architecture en trois pièces.
Logger, Handler, Formatter : qui fait quoi
Un Logger est le point d'entrée que votre code appelle (logger.info(...)) ; il décide, selon son niveau configuré, si un message mérite d'être traité. Un Handler décide où le message part (console, fichier, réseau) ; un même logger peut avoir plusieurs handlers avec des niveaux différents. Un Formatter décide comment le message est mis en forme avant d'être écrit. Cette séparation permet, par exemple, d'envoyer tout en détail vers un fichier tout en n'affichant que l'essentiel en console.
| Niveau | Valeur numérique | Usage typique |
|---|---|---|
DEBUG | 10 | Détail technique utile uniquement en diagnostic |
INFO | 20 | Déroulement normal de l'application |
WARNING | 30 | Anomalie non bloquante (cache proche de la saturation) |
ERROR | 40 | Échec d'une opération précise |
CRITICAL | 50 | Service globalement indisponible |
Les niveaux de gravité, un vocabulaire commun
DEBUG, INFO, WARNING, ERROR, CRITICAL forment une échelle standard qui permet de filtrer le bruit : en production, on affiche souvent INFO et plus, en gardant DEBUG disponible pour le diagnostic ponctuel.
Le logging structuré : des logs que les machines peuvent lire
Un message en texte libre est difficile à interroger automatiquement. Formater les logs en JSON (avec des champs comme niveau, message, duree_ms) permet à des outils d'observabilité (ELK, Loki, Datadog) de les indexer et de les requêter comme une base de données.
Propager le contexte sans le repasser partout
ContextVar permet d'attacher un identifiant de corrélation (par exemple, un identifiant de requête) au début d'un traitement, puis de le retrouver automatiquement dans tous les logs émis plus loin dans l'appel, sans le passer explicitement en paramètre à chaque fonction — utile pour retracer une requête à travers plusieurs couches d'une application.
Un piège fréquent : logger.info(f"...") évalue toujours la chaîne, même si le niveau est filtré ; logger.info("%s", valeur) est paresseux et évite ce coût inutile.
Piège fréquent
logger.info(f"Utilisateur {nom} connecté") construit la chaîne complète à chaque appel, même si le niveau INFO est filtré et que le message ne sera jamais écrit. logger.info("Utilisateur %s connecté", nom) ne formate la chaîne que si le message est effectivement émis, ce qui compte sur un chemin de code appelé des millions de fois.
Commandes & code
Logging structuré pour la production
Remplacer les print() par des logs exploitables par une stack d'observabilite.
import logging
import json
import sys
import time
import uuid
from contextvars import ContextVar
# --- Configuration de base : niveaux, handlers, formatters ---
logger = logging.getLogger("mon_application")
logger.setLevel(logging.DEBUG)
# Un handler decide OU les logs partent (console, fichier, reseau...)
handler_console = logging.StreamHandler(sys.stdout)
handler_console.setLevel(logging.INFO) # ce handler ignore DEBUG, meme si le logger l'accepte
handler_fichier = logging.FileHandler("app.log", encoding="utf-8")
handler_fichier.setLevel(logging.DEBUG)
formatter_texte = logging.Formatter(
"%(asctime)s [%(levelname)s] %(name)s: %(message)s"
)
handler_console.setFormatter(formatter_texte)
handler_fichier.setFormatter(formatter_texte)
logger.addHandler(handler_console)
logger.addHandler(handler_fichier)
logger.debug("Detail technique, invisible en console (niveau INFO)")
logger.info("Application demarree")
logger.warning("Cache proche de la saturation")
logger.error("Echec de connexion a la base de donnees")
logger.critical("Service indisponible")
# --- Les 5 niveaux standards, du plus au moins verbeux ---
# CRITICAL(50) > ERROR(40) > WARNING(30) > INFO(20) > DEBUG(10)
# --- Logger un traceback complet ---
try:
1 / 0
except ZeroDivisionError:
logger.exception("Erreur lors du calcul") # inclut automatiquement le traceback
# --- Logging structure : sortir du JSON exploitable par ELK/Datadog/Loki ---
class FormatterJSON(logging.Formatter):
def format(self, record: logging.LogRecord) -> str:
payload = {
"timestamp": self.formatTime(record, "%Y-%m-%dT%H:%M:%S"),
"niveau": record.levelname,
"logger": record.name,
"message": record.getMessage(),
"module": record.module,
"ligne": record.lineno,
}
# Champs additionnels attaches via logger.info(msg, extra={...})
for cle, valeur in getattr(record, "champs_extra", {}).items():
payload[cle] = valeur
if record.exc_info:
payload["exception"] = self.formatException(record.exc_info)
return json.dumps(payload, ensure_ascii=False)
class AdaptateurExtra(logging.LoggerAdapter):
"""Permet de passer des champs structures sans repeter extra={...} partout."""
def process(self, msg, kwargs):
kwargs.setdefault("extra", {})["champs_extra"] = self.extra
return msg, kwargs
logger_json = logging.getLogger("api")
logger_json.setLevel(logging.INFO)
handler_json = logging.StreamHandler(sys.stdout)
handler_json.setFormatter(FormatterJSON())
logger_json.addHandler(handler_json)
logger_json.propagate = False # evite la duplication vers le root logger
log_requete = AdaptateurExtra(logger_json, {"service": "api-utilisateurs"})
log_requete.info("Requete traitee", extra={"champs_extra": {"duree_ms": 42, "statut": 200}})
# --- Correlation de requetes avec contextvars : tracer une requete a travers plusieurs couches ---
id_correlation: ContextVar[str] = ContextVar("id_correlation", default="-")
class FiltreCorrelation(logging.Filter):
def filter(self, record: logging.LogRecord) -> bool:
record.correlation_id = id_correlation.get()
return True
logger_correle = logging.getLogger("service.commandes")
logger_correle.addFilter(FiltreCorrelation())
formatter_correle = logging.Formatter(
"[%(correlation_id)s] %(asctime)s %(levelname)s %(message)s"
)
handler_correle = logging.StreamHandler(sys.stdout)
handler_correle.setFormatter(formatter_correle)
logger_correle.addHandler(handler_correle)
def traiter_requete_http(id_requete: str | None = None):
jeton = id_correlation.set(id_requete or str(uuid.uuid4())[:8])
try:
logger_correle.info("Debut du traitement")
valider_commande()
logger_correle.info("Fin du traitement")
finally:
id_correlation.reset(jeton) # nettoie le contexte, meme en cas d'exception
def valider_commande():
# tout log ici herite AUTOMATIQUEMENT du meme correlation_id, sans le repasser en parametre
logger_correle.info("Validation de la commande en cours")
traiter_requete_http()
# --- RotatingFileHandler / TimedRotatingFileHandler : eviter des logs illimites en taille ---
from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler
handler_rotatif = RotatingFileHandler(
"app_rotatif.log", maxBytes=10_000_000, backupCount=5 # 10 Mo x 5 fichiers max
)
handler_quotidien = TimedRotatingFileHandler(
"app_quotidien.log", when="midnight", backupCount=14 # 14 jours d'historique
)
# --- structlog : librairie tierce qui structure TOUT nativement (context binding) ---
# pip install structlog
'''
import structlog
structlog.configure(
processors=[
structlog.contextvars.merge_contextvars,
structlog.processors.TimeStamper(fmt="iso"),
structlog.processors.JSONRenderer(),
],
)
log = structlog.get_logger()
structlog.contextvars.bind_contextvars(correlation_id="abc-123", utilisateur_id=42)
log.info("commande_creee", montant=99.90, devise="EUR")
# Sortie JSON : {"event": "commande_creee", "montant": 99.9, "correlation_id": "abc-123", ...}
'''
# --- Anti-patterns a eviter ---
# 1. logger.info(f"Utilisateur {nom} connecte") -- f-string TOUJOURS evaluee, meme si niveau filtre
# 2. logger.info("Utilisateur %s connecte", nom) -- BON : le formatage est LAZY (evalue seulement si loggue)
# 3. Ne jamais logger de secrets (mots de passe, tokens) meme en DEBUGRésumé
- Un
Handlerdecide la destination des logs, unFormatterdecide leur mise en forme ; unLoggerpeut avoir plusieurs handlers. - Le logging structuré (JSON) rend les logs exploitables par une stack d'observabilité (ELK, Loki, Datadog).
ContextVarpropage un identifiant de corrélation à travers tout un traitement, sans le repasser en paramètre partout.- Toujours utiliser le formatage paresseux (
logger.info("%s", valeur)) plutôt qu'un f-string, évalué même si le niveau est filtré.
Exercices pratiques
Mission : retrouver une requête perdue dans des milliers de lignes de logs
Objectif : Corriger un logging coûteux basé sur des f-strings, puis mettre en place un identifiant de corrélation pour retracer une requête à travers plusieurs fonctions.
Contexte
Un développeur reçoit un ticket décrivant une erreur intermittente en production, mais les logs actuels utilisent logger.debug(f"Traitement de la commande {commande.id} avec {len(commande.articles)} articles") des millions de fois par jour, y compris quand le niveau DEBUG est désactivé en production. De plus, impossible de relier les logs entre eux : aucun identifiant ne permet de savoir quelles lignes appartiennent à la même requête HTTP.
Tu dois corriger le coût du formatage inutile, puis mettre en place un identifiant de corrélation propagé automatiquement à travers plusieurs fonctions.