Astuces simples pour améliorer la maintenabilité de votre application (Partie 1) : pourquoi les logs cessent d'être utiles dans les systèmes réels

Pourquoi les logs cessent d'être utiles dans les systèmes réels

En bref : les journaux de base fonctionnent bien pour les flux simples, mais dès que la concurrence, les délais et les utilisateurs multiples apparaissent, ils cessent de raconter des histoires complètes.

2025-10-19 22:55:56,577 INFO demo.DemoApplication Starting DemoApplication using Java 24.0.1 with PID 188600 (/home/john-doe/Projects/demo/target/classes started by john_doe in /home/john-doe/Projects/demo) 2025-10-19 22:55:56,581 INFO demo.DemoApplication No active profile set, falling back to 1 default profile: "default" 2025-10-19 22:55:57,198 INFO o.s.boot.web.embedded.tomcat.TomcatWebServer Tomcat initialized with port 8080 (http) 2025-10-19 22:55:57,204 INFO org.apache.coyote.http11.Http11NioProtocol Initializing ProtocolHandler ["http-nio-8080"] 2025-10-19 22:55:57,205 INFO org.apache.catalina.core.StandardService Starting service [Tomcat] 2025-10-19 22:55:57,205 INFO org.apache.catalina.core.StandardEngine Starting Servlet engine: [Apache Tomcat/10.1.46] 2025-10-19 22:55:57,223 INFO o.a.c.c.ContainerBase.[Tomcat].[localhost].[/] Initializing Spring embedded WebApplicationContext 2025-10-19 22:55:57,223 INFO o.s.b.w.s.c.ServletWebServerApplicationContext Root WebApplicationContext: initialization completed in 589 ms 2025-10-19 22:55:57,426 INFO org.apache.coyote.http11.Http11NioProtocol Starting ProtocolHandler ["http-nio-8080"] 2025-10-19 22:55:57,431 INFO o.s.boot.web.embedded.tomcat.TomcatWebServer Tomcat started on port 8080 (http) with context path '/' 2025-10-19 22:55:59,568 INFO o.s.boot.web.embedded.tomcat.GracefulShutdown Commencing graceful shutdown. Waiting for active requests to complete 2025-10-19 22:55:59,571 INFO o.s.boot.web.embedded.tomcat.GracefulShutdown Graceful shutdown complete

Grâce au concept de logs, il est plus facile de comprendre ce qui se passe dans un système en fonctionnement – surtout lorsque les problèmes commencent à apparaître.

L'exemple ci-dessus montre le démarrage et l'arrêt d'un service Spring Framework, une situation très courante dans les applications d'entreprise Java. Logback est souvent utilisé comme moteur de journalisation.

Dans cet article, nous examinerons d'abord la journalisation dans sa forme la plus élémentaire, puis nous améliorerons progressivement la configuration de notre application. L'objectif final est simple : une solution qui réduit le temps nécessaire pour comprendre ce qui a mal tourné.

Bien que les exemples se concentrent sur Logback, les idées ne lui sont pas spécifiques. Des résultats similaires peuvent être obtenus indépendamment de la technologie, du langage de programmation ou du framework.

Comprendre les bases

Le problème fondamental que les journaux devraient aider à résoudre est de déterminer quand et exactement quoi s'est produit.

Examinons de plus près les logs dans leur configuration minimale :

2025-10-18 16:02:35,338 INFO demo.HelloPrinter Hello world 2025-10-18 16:02:35,838 INFO demo.HelloPrinter How are you 2025-10-18 16:02:36,339 INFO demo.HelloPrinter Good bye | | | | | | | +--- the message | | | | | +--- class name | | | +--- log level | +--- timestamp

L'ordre chronologique est garanti de deux manières.

Premièrement, l'horodatage indique l'ordre des événements. Deuxièmement, la structure même des données de journal permet uniquement l'ajout de nouvelles entrées, garantissant que la lecture des journaux de haut en bas préserve la séquence.

Le « niveau de log » distingue le comportement attendu (DEBUG, INFO) des problèmes potentiels (WARN, ERROR). Le « nom de classe » nous indique où dans le code le log a été produit. « Le message » est un texte personnalisé préparé par le développeur.

Vérifions que cela correspond au code :

package demo; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.stereotype.Component; @Component public class HelloPrinter { private static final Logger logger = LoggerFactory.getLogger(HelloPrinter.class); public void print() { logger.info("Hello world"); logger.info("How are you"); logger.info("Good bye"); } }

Jusqu'à présent, tout se comporte exactement comme prévu.

Configuration Logback (minimale mais suffisante)

Pour produire des logs formatés de cette manière avec Logback, la configuration suivante est utilisée :

<configuration> <appender name="Console" class="ch.qos.logback.core.ConsoleAppender"> <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder"> <pattern> %d{ISO8601} %highlight(%-5level) %yellow(%-48logger{48}) %msg %n%throwable </pattern> </encoder> </appender> <!-- root level="INFO" signifie que je ne souhaite pas voir DEBUG ou TRACE. Sans cela, au démarrage du serveur Spring, nous verrions de nombreux logs DEBUG liés aux internes du Spring Framework --> <root level="INFO"> <appender-ref ref="Console"/> </root> </configuration>

Éléments clés :

• timestamp,
• niveau de journalisation (largeur fixe pour la lisibilité),
• classe / nom du logger,
• message,
• trace de pile facultative.

%d{ISO8601} %-5level %-48logger{48} %msg %n%throwable | | | | | | | | | | | +--- trace de pile joliment imprimée | | | | | …en cas d'exception | | | | | | | | | +--- nouvelle ligne pour séparer la ligne de log | | | | | | | +--- le message | | | | | +--- nom de classe / logger | | …pointe vers un endroit dans le code source produisant ce log | | …longueur exactement de 48 caractères, pour une lecture facile | | | +--- niveau de log | …longueur exactement de 5 caractères | …ERROR fait 5 caractères, mais INFO seulement 4 | …et nous voulons garder la cohérence | +--- horodatage

Cette configuration est propre, lisible et fonctionne bien –jusqu'à ce que la réalité rattrape. 

❌ Problème : les utilisateurs simultanés brouillent le récit

Examinons maintenant un scénario un peu plus réaliste.

Trois utilisateurs modifient des commandes en même temps. La quantité, le prix de l'article et le prix total sont enregistrés à différents endroits :

2025-10-18 16:56:28,415 INFO demo.PrintingDemo Prix de l'article = 15 2025-10-18 16:56:28,465 INFO demo.PrintingDemo Prix de l'article = 36 2025-10-18 16:56:28,571 INFO demo.PrintingDemo Articles de la commande = [1] 2025-10-18 16:56:28,581 INFO demo.PrintingDemo Prix de l'article = 47 2025-10-18 16:56:28,611 INFO demo.PrintingDemo Articles de la commande = [5] 2025-10-18 16:56:28,640 INFO demo.PrintingDemo Prix total = 75 2025-10-18 16:56:28,714 INFO demo.PrintingDemo Prix total = 36 2025-10-18 16:56:28,715 INFO demo.PrintingDemo Articles de la commande = [3] 2025-10-18 16:56:28,746 INFO demo.PrintingDemo Prix total = 141

À ce stade, les journaux ne sont plus utiles. Nous ne pouvons pas dire :

• quels événements appartiennent à la même commande,
• si les totaux sont calculés correctement,
• ou quel utilisateur a déclenché quelle séquence.

✅ Solution envisagée : PID et ID de thread

Si vous utilisez Spring Boot (qui utilise Logback par défaut), la configuration par défaut inclut déjà :

• un identifiant de processus (PID),
• un identifiant de thread.

Rendons-les explicites dans le modèle :

%d{ISO8601} %-5level ${PID} [t=%thread] %-48logger{48} %msg %n%throwable | | | +--- identifiant du thread | …avec une légère amélioration visuelle | …ressemblera à ceci : [t=Thread-1] | +--- PID

Le PID aide à distinguer :

• instances de service différentes,
• redémarrages,
• déploiements multi-instances.

L'ID de thread permet d'afficher :

• quelles requêtes sont traitées simultanément,
• quels chemins d'exécution s'exécutent en parallèle.

Avec ce changement, le même scénario devient plus facile à suivre :

2025-10-18 17:02:51,199 INFO 151993 [t=Thread-2] demo.PrintingDemo Price of item = 63 2025-10-18 17:02:51,206 INFO 151993 [t=Thread-1] demo.PrintingDemo Price of item = 34 2025-10-18 17:02:51,223 INFO 153222 [t=Thread-1] demo.PrintingDemo Price of item = 58 2025-10-18 17:02:51,246 INFO 151993 [t=Thread-5] demo.PrintingDemo Price of item = 94 2025-10-18 17:02:51,331 INFO 151993 [t=Thread-2] demo.PrintingDemo Items in order = [1] 2025-10-18 17:02:51,354 INFO 151993 [t=Thread-2] demo.PrintingDemo Total price = 63 2025-10-18 17:02:51,355 INFO 153222 [t=Thread-1] demo.PrintingDemo Items in order = [4] 2025-10-18 17:02:51,355 INFO 151993 [t=Thread-4] demo.PrintingDemo Price of item = 68 2025-10-18 17:02:51,358 INFO 151993 [t=Thread-5] demo.PrintingDemo Items in order = [2] 2025-10-18 17:02:51,367 INFO 151993 [t=Thread-1] demo.PrintingDemo Items in order = [2] 2025-10-18 17:02:51,371 INFO 151993 [t=Thread-1] demo.PrintingDemo Total price = 68 2025-10-18 17:02:51,429 INFO 153222 [t=Thread-1] demo.PrintingDemo Total price = 232 2025-10-18 17:02:51,456 INFO 151993 [t=Thread-5] demo.PrintingDemo Total price = 188 2025-10-18 17:02:51,460 INFO 151993 [t=Thread-4] demo.PrintingDemo Items in order = [5] 2025-10-18 17:02:51,629 INFO 151993 [t=Thread-4] demo.PrintingDemo Total price = 340

En filtrant par thread et PID, nous pouvons enfin reconstituer une commande unique.

2025-10-18 17:02:51,206 INFO 151993 [t=Thread-1] demo.PrintingDemo Price of item = 34 2025-10-18 17:02:51,367 INFO 151993 [t=Thread-1] demo.PrintingDemo Items in order = [2] 2025-10-18 17:02:51,371 INFO 151993 [t=Thread-1] demo.PrintingDemo Total price = 68

❌ Problème : le temps et l'échelle brisent cette approche

Cette solution ne fonctionne que lorsque nous savons exactement quand le problème s'est produit.

Dans les systèmes réels :

• les utilisateurs signalent des problèmes des heures plus tard,
• les threads sont réutilisés,
• des centaines d'exécutions se chevauchent.

Considérez des logs comme celui-ci :

2025-10-19 18:29:53,428 INFO 169232 [t=Thread-2] demo.PrintingDemo Price of item = 2 2025-10-19 18:29:53,467 INFO 169232 [t=Thread-3] demo.PrintingDemo Price of item = 9 2025-10-19 18:29:53,484 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 26 2025-10-19 18:29:53,493 INFO 169232 [t=Thread-2] demo.PrintingDemo Items in order = [2] 2025-10-19 18:29:53,529 INFO 169232 [t=Thread-3] demo.PrintingDemo Items in order = [5] 2025-10-19 18:29:53,545 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [3] 2025-10-19 18:29:53,631 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 78 2025-10-19 18:29:53,645 INFO 169232 [t=Thread-2] demo.PrintingDemo Total price = 4 2025-10-19 18:29:53,694 INFO 169232 [t=Thread-3] demo.PrintingDemo Total price = 45 2025-10-19 18:29:53,720 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 26 2025-10-19 18:29:53,797 INFO 169232 [t=Thread-3] demo.PrintingDemo Price of item = 27 2025-10-19 18:29:53,801 INFO 169232 [t=Thread-2] demo.PrintingDemo Price of item = 89 2025-10-19 18:29:53,847 INFO 169232 [t=Thread-2] demo.PrintingDemo Items in order = [5] 2025-10-19 18:29:53,895 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [2] 2025-10-19 18:29:53,919 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 52 2025-10-19 18:29:53,970 INFO 169232 [t=Thread-3] demo.PrintingDemo Items in order = [2] 2025-10-19 18:29:53,990 INFO 169232 [t=Thread-2] demo.PrintingDemo Total price = 445 2025-10-19 18:29:54,057 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 47 2025-10-19 18:29:54,109 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [4] 2025-10-19 18:29:54,163 INFO 169232 [t=Thread-3] demo.PrintingDemo Total price = 54 2025-10-19 18:29:54,298 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 188

Même si nous filtrons par ID de thread = Thread-1…

2025-10-19 18:29:53,484 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 26 2025-10-19 18:29:53,545 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [3] 2025-10-19 18:29:53,631 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 78 2025-10-19 18:29:53,720 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 26 2025-10-19 18:29:53,895 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [2] 2025-10-19 18:29:53,919 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 52 2025-10-19 18:29:54,057 INFO 169232 [t=Thread-1] demo.PrintingDemo Price of item = 47 2025-10-19 18:29:54,109 INFO 169232 [t=Thread-1] demo.PrintingDemo Items in order = [4] 2025-10-19 18:29:54,298 INFO 169232 [t=Thread-1] demo.PrintingDemo Total price = 188

Le même thread gère désormais plusieurs exécutions sans lien entre elles. Le filtrage par ID de thread ou PID produit désormais des histoires mélangées.

À ce stade, tenter de regrouper efficacement les journaux de cette manière devient fastidieux – ce qui signifie que nous perdons un temps précieux.

Où cela nous mène

À ce stade, les logs sont techniquement corrects, bien formatés, et toujours incomplets. Ils décrivent des événements, mais pas des exécutions. Ils nous disent ce qui s'est passé — mais pas à quelle histoire ces événements appartenaient.

Prochaines étapes

Au lieu d'extraire davantage de sens des threads et des horodatages, nous avons besoin que les journaux se souviennent du contexte.

Dans la partie suivante, nous verrons comment attacher le contexte utilisateur aux journaux sans transmettre d'identifiants via chaque méthode :

→ Partie 2 : Contexte utilisateur sans compromettre votre design

Et plus tard, lorsque les utilisateurs n'existent pas et que les threads ne suffisent pas :

→ Partie 3 : Identifiants de corrélation et traçabilité de bout en bout