Journalisation Java améliorée avec contexte de diagnostic mappé (MDC)

1. Vue d'ensemble

Dans cet article, nous explorerons l'utilisation du contexte de diagnostic mappé (MDC) pour améliorer la journalisation des applications.

L'idée de base du contexte de diagnostic mappé est de fournir un moyen d'enrichir les messages du journal avec des informations qui pourraient ne pas être disponibles dans la portée où la journalisation se produit réellement, mais qui peuvent en effet être utiles pour mieux suivre l'exécution du programme.

2. Pourquoi utiliser MDC

Commençons par un exemple. Supposons que nous devions écrire un logiciel qui transfère de l'argent. Nous avons mis en place une classe Transfer pour représenter certaines informations de base: un identifiant de transfert unique et le nom de l'expéditeur:

public class Transfer { private String transactionId; private String sender; private Long amount; public Transfer(String transactionId, String sender, long amount) { this.transactionId = transactionId; this.sender = sender; this.amount = amount; } public String getSender() { return sender; } public String getTransactionId() { return transactionId; } public Long getAmount() { return amount; } } 

Pour effectuer le transfert, nous devons utiliser un service soutenu par une simple API:

public abstract class TransferService { public boolean transfer(long amount) { // connects to the remote service to actually transfer money } abstract protected void beforeTransfer(long amount); abstract protected void afterTransfer(long amount, boolean outcome); } 

Les méthodes beforeTransfer () et afterTransfer () peuvent être remplacées pour exécuter du code personnalisé juste avant et juste après la fin du transfert.

Nous allons utiliser beforeTransfer () et afterTransfer () pour enregistrer certaines informations sur le transfert .

Créons l'implémentation du service:

import org.apache.log4j.Logger; import com.baeldung.mdc.TransferService; public class Log4JTransferService extends TransferService { private Logger logger = Logger.getLogger(Log4JTransferService.class); @Override protected void beforeTransfer(long amount) { logger.info("Preparing to transfer " + amount + "$."); } @Override protected void afterTransfer(long amount, boolean outcome) { logger.info( "Has transfer of " + amount + "$ completed successfully ? " + outcome + "."); } } 

Le principal problème à noter ici est que lorsque le message de journal est créé, il n'est pas possible d'accéder à l' objet de transfert - seul le montant est accessible, ce qui rend impossible l'enregistrement de l'identifiant de transaction ou de l'expéditeur.

Configurons le fichier habituel log4j.properties pour nous connecter à la console:

log4j.appender.consoleAppender=org.apache.log4j.ConsoleAppender log4j.appender.consoleAppender.layout=org.apache.log4j.PatternLayout log4j.appender.consoleAppender.layout.ConversionPattern=%-4r [%t] %5p %c %x - %m%n log4j.rootLogger = TRACE, consoleAppender 

Configurons enfin une petite application capable d'exécuter plusieurs transferts en même temps via un ExecutorService :

public class TransferDemo { public static void main(String[] args) { ExecutorService executor = Executors.newFixedThreadPool(3); TransactionFactory transactionFactory = new TransactionFactory(); for (int i = 0; i < 10; i++) { Transfer tx = transactionFactory.newInstance(); Runnable task = new Log4JRunnable(tx); executor.submit(task); } executor.shutdown(); } }

Nous notons que pour utiliser l' ExecutorService , nous devons encapsuler l'exécution du Log4JTransferService dans un adaptateur car executor.submit () attend un Runnable :

public class Log4JRunnable implements Runnable { private Transfer tx; public Log4JRunnable(Transfer tx) { this.tx = tx; } public void run() { log4jBusinessService.transfer(tx.getAmount()); } } 

Lorsque nous exécutons notre application de démonstration qui gère plusieurs transferts en même temps, nous découvrons très rapidement que le journal n'est pas utile comme nous le souhaiterions . Il est complexe de suivre l'exécution de chaque transfert car les seules informations utiles enregistrées sont le montant d'argent transféré et le nom du thread qui exécute ce transfert particulier.

De plus, il est impossible de faire la distinction entre deux transactions différentes du même montant exécutées par le même thread car les lignes de journal associées se ressemblent essentiellement:

... 519 [pool-1-thread-3] INFO Log4JBusinessService - Preparing to transfer 1393$. 911 [pool-1-thread-2] INFO Log4JBusinessService - Has transfer of 1065$ completed successfully ? true. 911 [pool-1-thread-2] INFO Log4JBusinessService - Preparing to transfer 1189$. 989 [pool-1-thread-1] INFO Log4JBusinessService - Has transfer of 1350$ completed successfully ? true. 989 [pool-1-thread-1] INFO Log4JBusinessService - Preparing to transfer 1178$. 1245 [pool-1-thread-3] INFO Log4JBusinessService - Has transfer of 1393$ completed successfully ? true. 1246 [pool-1-thread-3] INFO Log4JBusinessService - Preparing to transfer 1133$. 1507 [pool-1-thread-2] INFO Log4JBusinessService - Has transfer of 1189$ completed successfully ? true. 1508 [pool-1-thread-2] INFO Log4JBusinessService - Preparing to transfer 1907$. 1639 [pool-1-thread-1] INFO Log4JBusinessService - Has transfer of 1178$ completed successfully ? true. 1640 [pool-1-thread-1] INFO Log4JBusinessService - Preparing to transfer 674$. ... 

Heureusement, MDC peut vous aider.

3. MDC dans Log4j

Présentons MDC .

MDC dans Log4j nous permet de remplir une structure en forme de carte avec des informations accessibles à l'appender lorsque le message de journal est réellement écrit.

La structure MDC est attachée en interne au thread en cours d'exécution de la même manière qu'une variable ThreadLocal le serait.

Et donc, l'idée de haut niveau est:

  1. pour remplir le MDC avec des informations que nous voulons mettre à disposition de l'appender
  2. puis enregistrez un message
  3. et enfin, effacez le MDC

Le modèle de l'appender doit évidemment être changé afin de récupérer les variables stockées dans le MDC.

Alors changeons le code selon ces directives:

import org.apache.log4j.MDC; public class Log4JRunnable implements Runnable { private Transfer tx; private static Log4JTransferService log4jBusinessService = new Log4JTransferService(); public Log4JRunnable(Transfer tx) { this.tx = tx; } public void run() { MDC.put("transaction.id", tx.getTransactionId()); MDC.put("transaction.owner", tx.getSender()); log4jBusinessService.transfer(tx.getAmount()); MDC.clear(); } } 

Sans surprise, MDC.put () est utilisé pour ajouter une clé et une valeur correspondante dans le MDC tandis que MDC.clear () vide le MDC.

Modifions maintenant le log4j.properties pour imprimer les informations que nous venons de stocker dans le MDC. Il suffit de changer le modèle de conversion, en utilisant l' espace réservé % X {} pour chaque entrée contenue dans le MDC que nous souhaitons être journalisé:

log4j.appender.consoleAppender.layout.ConversionPattern= %-4r [%t] %5p %c{1} %x - %m - tx.id=%X{transaction.id} tx.owner=%X{transaction.owner}%n

Maintenant, si nous exécutons l'application, nous noterons que chaque ligne contient également les informations sur la transaction en cours de traitement, ce qui nous permet de suivre beaucoup plus facilement l'exécution de l'application:

638 [pool-1-thread-2] INFO Log4JBusinessService - Has transfer of 1104$ completed successfully ? true. - tx.id=2 tx.owner=Marc 638 [pool-1-thread-2] INFO Log4JBusinessService - Preparing to transfer 1685$. - tx.id=4 tx.owner=John 666 [pool-1-thread-1] INFO Log4JBusinessService - Has transfer of 1985$ completed successfully ? true. - tx.id=1 tx.owner=Marc 666 [pool-1-thread-1] INFO Log4JBusinessService - Preparing to transfer 958$. - tx.id=5 tx.owner=Susan 739 [pool-1-thread-3] INFO Log4JBusinessService - Has transfer of 783$ completed successfully ? true. - tx.id=3 tx.owner=Samantha 739 [pool-1-thread-3] INFO Log4JBusinessService - Preparing to transfer 1024$. - tx.id=6 tx.owner=John 1259 [pool-1-thread-2] INFO Log4JBusinessService - Has transfer of 1685$ completed successfully ? false. - tx.id=4 tx.owner=John 1260 [pool-1-thread-2] INFO Log4JBusinessService - Preparing to transfer 1667$. - tx.id=7 tx.owner=Marc 

4. MDC dans Log4j2

La même fonctionnalité est également disponible dans Log4j2, voyons donc comment l'utiliser.

Commençons par configurer une sous-classe TransferService qui se connecte à l'aide de Log4j2:

import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; public class Log4J2TransferService extends TransferService { private static final Logger logger = LogManager.getLogger(); @Override protected void beforeTransfer(long amount) { logger.info("Preparing to transfer {}$.", amount); } @Override protected void afterTransfer(long amount, boolean outcome) { logger.info("Has transfer of {}$ completed successfully ? {}.", amount, outcome); } } 

Modifions ensuite le code qui utilise le MDC, qui est en fait appelé ThreadContext dans Log4j2:

import org.apache.log4j.MDC; public class Log4J2Runnable implements Runnable { private final Transaction tx; private Log4J2BusinessService log4j2BusinessService = new Log4J2BusinessService(); public Log4J2Runnable(Transaction tx) { this.tx = tx; } public void run() { ThreadContext.put("transaction.id", tx.getTransactionId()); ThreadContext.put("transaction.owner", tx.getOwner()); log4j2BusinessService.transfer(tx.getAmount()); ThreadContext.clearAll(); } } 

Là encore, ThreadContext.put () ajoute une entrée dans le MDC et ThreadContext.clearAll () supprime toutes les entrées existantes.

Nous manquons toujours le fichier log4j2.xml pour configurer la journalisation. Comme nous pouvons le noter, la syntaxe pour spécifier les entrées MDC à journaliser est la même que celle utilisée dans Log4j:

Encore une fois, exécutons l'application et nous verrons les informations MDC imprimées dans le journal:

1119 [pool-1-thread-3] INFO Log4J2BusinessService - Has transfer of 1198$ completed successfully ? true. - tx.id=3 tx.owner=Samantha 1120 [pool-1-thread-3] INFO Log4J2BusinessService - Preparing to transfer 1723$. - tx.id=5 tx.owner=Samantha 1170 [pool-1-thread-2] INFO Log4J2BusinessService - Has transfer of 701$ completed successfully ? true. - tx.id=2 tx.owner=Susan 1171 [pool-1-thread-2] INFO Log4J2BusinessService - Preparing to transfer 1108$. - tx.id=6 tx.owner=Susan 1794 [pool-1-thread-1] INFO Log4J2BusinessService - Has transfer of 645$ completed successfully ? true. - tx.id=4 tx.owner=Susan 

5. MDC dans SLF4J / Logback

MDC est également disponible dans SLF4J, à condition qu'il soit pris en charge par la bibliothèque de journalisation sous-jacente.

Logback et Log4j prennent en charge MDC comme nous venons de le voir, nous n'avons donc besoin de rien de spécial pour l'utiliser avec une configuration standard.

Préparons la sous-classe habituelle TransferService , cette fois en utilisant la façade de journalisation simple pour Java:

import org.slf4j.Logger; import org.slf4j.LoggerFactory; final class Slf4TransferService extends TransferService { private static final Logger logger = LoggerFactory.getLogger(Slf4TransferService.class); @Override protected void beforeTransfer(long amount) { logger.info("Preparing to transfer {}$.", amount); } @Override protected void afterTransfer(long amount, boolean outcome) { logger.info("Has transfer of {}$ completed successfully ? {}.", amount, outcome); } } 

Utilisons maintenant la saveur MDC du SLF4J. Dans ce cas, la syntaxe et la sémantique sont les mêmes que celles de log4j:

import org.slf4j.MDC; public class Slf4jRunnable implements Runnable { private final Transaction tx; public Slf4jRunnable(Transaction tx) { this.tx = tx; } public void run() { MDC.put("transaction.id", tx.getTransactionId()); MDC.put("transaction.owner", tx.getOwner()); new Slf4TransferService().transfer(tx.getAmount()); MDC.clear(); } } 

Nous devons fournir le fichier de configuration Logback , logback.xml :

   %-4r [%t] %5p %c{1} - %m - tx.id=%X{transaction.id} tx.owner=%X{transaction.owner}%n       

Encore une fois, nous verrons que les informations du MDC sont correctement ajoutées aux messages journalisés, même si ces informations ne sont pas explicitement fournies dans la méthode log.info () :

1020 [pool-1-thread-3] INFO c.b.m.s.Slf4jBusinessService - Has transfer of 1869$ completed successfully ? true. - tx.id=3 tx.owner=John 1021 [pool-1-thread-3] INFO c.b.m.s.Slf4jBusinessService - Preparing to transfer 1303$. - tx.id=6 tx.owner=Samantha 1221 [pool-1-thread-1] INFO c.b.m.s.Slf4jBusinessService - Has transfer of 1498$ completed successfully ? true. - tx.id=4 tx.owner=Marc 1221 [pool-1-thread-1] INFO c.b.m.s.Slf4jBusinessService - Preparing to transfer 1528$. - tx.id=7 tx.owner=Samantha 1492 [pool-1-thread-2] INFO c.b.m.s.Slf4jBusinessService - Has transfer of 1110$ completed successfully ? true. - tx.id=5 tx.owner=Samantha 1493 [pool-1-thread-2] INFO c.b.m.s.Slf4jBusinessService - Preparing to transfer 644$. - tx.id=8 tx.owner=John

Il est à noter que si nous configurons le back-end SLF4J sur un système de journalisation qui ne prend pas en charge MDC, toutes les invocations associées seront simplement ignorées sans effets secondaires.

6. MDC et pools de threads

MDC implementations are usually using ThreadLocals to store the contextual information. That's an easy and reasonable way to achieve thread-safety. However, we should be careful using MDC with thread pools.

Let's see how the combination of ThreadLocal-based MDCs and thread pools can be dangerous:

  1. We get a thread from the thread pool.
  2. Then we store some contextual information in MDC using MDC.put() or ThreadContext.put().
  3. We use this information in some logs and somehow we forgot to clear the MDC context.
  4. The borrowed thread comes back to the thread pool.
  5. After a while, the application gets the same thread from the pool.
  6. Since we didn't clean up the MDC last time, this thread still owns some data from the previous execution.

This may cause some unexpected inconsistencies between executions. One way to prevent this is to always remember to clean up the MDC context at the end of each execution. This approach usually needs rigorous human supervision and, therefore, is error-prone.

Another approach is to use ThreadPoolExecutor hooks and perform necessary cleanups after each execution. To do that, we can extend the ThreadPoolExecutor class and override the afterExecute() hook:

public class MdcAwareThreadPoolExecutor extends ThreadPoolExecutor { public MdcAwareThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue workQueue, ThreadFactory threadFactory, RejectedExecutionHandler handler) { super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler); } @Override protected void afterExecute(Runnable r, Throwable t) { System.out.println("Cleaning the MDC context"); MDC.clear(); org.apache.log4j.MDC.clear(); ThreadContext.clearAll(); } }

This way, the MDC cleanup would happen after each normal or exceptional execution automatically. So, there is no need to do it manually:

@Override public void run() { MDC.put("transaction.id", tx.getTransactionId()); MDC.put("transaction.owner", tx.getSender()); new Slf4TransferService().transfer(tx.getAmount()); }

Maintenant, nous pouvons réécrire la même démo avec notre nouvelle implémentation d'exécuteur:

ExecutorService executor = new MdcAwareThreadPoolExecutor(3, 3, 0, MINUTES, new LinkedBlockingQueue(), Thread::new, new AbortPolicy()); TransactionFactory transactionFactory = new TransactionFactory(); for (int i = 0; i < 10; i++) { Transfer tx = transactionFactory.newInstance(); Runnable task = new Slf4jRunnable(tx); executor.submit(task); } executor.shutdown();

7. Conclusion

MDC a de nombreuses applications, principalement dans des scénarios dans lesquels l'exécution de plusieurs threads différents provoque des messages de journal entrelacés qui seraient autrement difficiles à lire.

Et comme nous l'avons vu, il est pris en charge par trois des frameworks de journalisation les plus utilisés en Java.

Comme d'habitude, vous trouverez les sources sur GitHub.