Verbesserte Java-Protokollierung mit MDC (Mapped Diagnostic Context)

1. Übersicht

In diesem Artikel werden wir die Verwendung von MDC ( Mapped Diagnostic Context ) zur Verbesserung der Anwendungsprotokollierung untersuchen.

Die Grundidee von Mapped Diagnostic Context besteht darin, eine Möglichkeit bereitzustellen, Protokollnachrichten mit Informationen anzureichern, die in dem Bereich, in dem die Protokollierung tatsächlich stattfindet, möglicherweise nicht verfügbar sind. Dies kann jedoch hilfreich sein, um die Ausführung des Programms besser zu verfolgen.

2. Warum MDC verwenden?

Beginnen wir mit einem Beispiel. Nehmen wir an, wir müssen Software schreiben, die Geld überweist. Wir haben eine Übertragungsklasse eingerichtet , um einige grundlegende Informationen darzustellen: eine eindeutige Übertragungs-ID und den Namen des Absenders:

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; } } 

Um die Übertragung durchzuführen, müssen wir einen Dienst verwenden, der von einer einfachen API unterstützt wird:

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); } 

Die Methoden beforeTransfer () und afterTransfer () können überschrieben werden, um benutzerdefinierten Code unmittelbar vor und unmittelbar nach Abschluss der Übertragung auszuführen.

Wir werden beforeTransfer () und afterTransfer () nutzen , um einige Informationen über die Übertragung zu protokollieren .

Lassen Sie uns die Service-Implementierung erstellen:

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 + "."); } } 

Das Hauptproblem, das hier zu beachten ist, ist, dass beim Erstellen der Protokollnachricht nicht auf das Übertragungsobjekt zugegriffen werden kann - nur auf den Betrag kann zugegriffen werden, sodass weder die Transaktions-ID noch der Absender protokolliert werden können.

Lassen Sie uns die übliche Datei log4j.properties einrichten , um sich an der Konsole anzumelden:

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 

Lassen Sie uns endlich eine kleine Anwendung einrichten, die mehrere Übertragungen gleichzeitig über einen ExecutorService ausführen kann :

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(); } }

Wir stellen fest, dass wir zur Ausführung des ExecutorService die Ausführung des Log4JTransferService in einen Adapter packen müssen, da executor.submit () eine ausführbare Datei erwartet :

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

Wenn wir unsere Demo-Anwendung ausführen, die mehrere Übertragungen gleichzeitig verwaltet, stellen wir sehr schnell fest, dass das Protokoll nicht so nützlich ist, wie wir es uns wünschen . Es ist komplex, die Ausführung jeder Übertragung zu verfolgen, da die einzigen nützlichen Informationen, die protokolliert werden, der überwiesene Geldbetrag und der Name des Threads sind, der diese bestimmte Übertragung ausführt.

Darüber hinaus ist es unmöglich, zwischen zwei verschiedenen Transaktionen desselben Betrags zu unterscheiden, die von demselben Thread ausgeführt werden, da die zugehörigen Protokollzeilen im Wesentlichen gleich aussehen:

... 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$. ... 

Zum Glück kann MDC helfen.

3. MDC in Log4j

Lassen Sie uns MDC vorstellen .

Mit MDC in Log4j können wir eine kartenähnliche Struktur mit Informationen füllen, auf die der Appender zugreifen kann, wenn die Protokollnachricht tatsächlich geschrieben wird.

Die MDC-Struktur wird intern an den ausführenden Thread angehängt, so wie es eine ThreadLocal- Variable wäre.

Die Idee auf hoher Ebene lautet also:

  1. das MDC mit Informationen zu füllen, die wir dem Appender zur Verfügung stellen möchten
  2. Protokollieren Sie dann eine Nachricht
  3. und schließlich das MDC löschen

Das Muster des Appenders sollte offensichtlich geändert werden, um die im MDC gespeicherten Variablen abzurufen.

Ändern wir dann den Code gemäß den folgenden Richtlinien:

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(); } } 

Es überrascht nicht, dass MDC.put () verwendet wird, um einen Schlüssel und einen entsprechenden Wert in der MDC hinzuzufügen, während MDC.clear () die MDC leert.

Lassen Sie uns nun die log4j.properties ändern , um die Informationen zu drucken, die wir gerade im MDC gespeichert haben. Es reicht aus, das Konvertierungsmuster zu ändern, indem der Platzhalter % X {} für jeden Eintrag in der MDC verwendet wird, die protokolliert werden soll:

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

Wenn wir nun die Anwendung ausführen, werden wir feststellen, dass jede Zeile auch die Informationen über die zu verarbeitende Transaktion enthält, was es uns erheblich erleichtert, die Ausführung der Anwendung zu verfolgen:

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 in Log4j2

Die gleiche Funktion ist auch in Log4j2 verfügbar. Schauen wir uns also an, wie sie verwendet wird.

Lassen Sie uns zunächst eine TransferService- Unterklasse einrichten , die mit Log4j2 protokolliert:

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); } } 

Lassen Sie uns dann den Code ändern, der den MDC verwendet, der in Log4j2 tatsächlich ThreadContext heißt:

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(); } } 

Wiederum fügt ThreadContext.put () einen Eintrag im MDC hinzu und ThreadContext.clearAll () entfernt alle vorhandenen Einträge.

Wir vermissen immer noch die Datei log4j2.xml , um die Protokollierung zu konfigurieren. Wie wir feststellen können, ist die Syntax zum Festlegen, welche MDC-Einträge protokolliert werden sollen, dieselbe wie die in Log4j verwendete:

Führen Sie die Anwendung erneut aus, und die MDC-Informationen werden im Protokoll gedruckt:

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 in SLF4J / Logback

MDC ist auch in SLF4J verfügbar, sofern es von der zugrunde liegenden Protokollierungsbibliothek unterstützt wird.

Sowohl Logback als auch Log4j unterstützen MDC, wie wir gerade gesehen haben. Daher benötigen wir nichts Besonderes, um es mit einem Standard-Setup zu verwenden.

Bereiten wir die übliche TransferService- Unterklasse vor, diesmal mithilfe der Simple Logging Facade für 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); } } 

Verwenden wir jetzt den MDC-Geschmack des SLF4J. In diesem Fall sind Syntax und Semantik mit denen in log4j identisch:

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(); } } 

Wir müssen die Logback-Konfigurationsdatei logback.xml bereitstellen :

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

Wieder werden wir sehen, dass die Informationen im MDC ordnungsgemäß zu den protokollierten Nachrichten hinzugefügt werden, obwohl diese Informationen in der Methode log.info () nicht explizit angegeben werden:

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

Es ist erwähnenswert, dass für den Fall, dass wir das SLF4J-Backend für ein Protokollierungssystem einrichten, das MDC nicht unterstützt, alle zugehörigen Aufrufe einfach ohne Nebenwirkungen übersprungen werden.

6. MDC- und Thread-Pools

MDC-Implementierungen verwenden normalerweise ThreadLocal s, um die Kontextinformationen zu speichern. Dies ist ein einfacher und vernünftiger Weg, um Fadensicherheit zu erreichen. Wir sollten jedoch vorsichtig sein, MDC mit Thread-Pools zu verwenden.

Mal sehen, wie gefährlich die Kombination von ThreadLocal- basierten MDCs und Thread-Pools sein kann:

  1. Wir bekommen einen Thread aus dem Thread-Pool.
  2. Anschließend speichern wir einige Kontextinformationen in MDC mithilfe von MDC.put () oder ThreadContext.put () .
  3. Wir verwenden diese Informationen in einigen Protokollen und haben irgendwie vergessen, den MDC-Kontext zu löschen.
  4. Der ausgeliehene Thread wird in den Thread-Pool zurückgeführt.
  5. Nach einer Weile erhält die Anwendung denselben Thread aus dem Pool.
  6. Da wir den MDC beim letzten Mal nicht bereinigt haben, besitzt dieser Thread noch einige Daten aus der vorherigen Ausführung.

Dies kann zu unerwarteten Inkonsistenzen zwischen den Ausführungen führen. Eine Möglichkeit, dies zu verhindern, besteht darin, immer daran zu denken, den MDC-Kontext am Ende jeder Ausführung zu bereinigen. Dieser Ansatz erfordert normalerweise eine strenge menschliche Überwachung und ist daher fehleranfällig.

Ein anderer Ansatz besteht darin, ThreadPoolExecutor- Hooks zu verwenden und nach jeder Ausführung die erforderlichen Bereinigungen durchzuführen. Dazu können wir die ThreadPoolExecutor- Klasse erweitern und den afterExecute () - Hook überschreiben :

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(); } }

Auf diese Weise würde die MDC-Bereinigung nach jeder normalen oder außergewöhnlichen Ausführung automatisch erfolgen. Es ist also nicht erforderlich, dies manuell zu tun:

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

Jetzt können wir dieselbe Demo mit unserer neuen Executor-Implementierung neu schreiben:

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. Fazit

MDC hat viele Anwendungen, hauptsächlich in Szenarien, in denen die Ausführung mehrerer verschiedener Threads verschachtelte Protokollnachrichten verursacht, die sonst schwer zu lesen wären.

Und wie wir gesehen haben, wird es von drei der am häufigsten verwendeten Protokollierungsframeworks in Java unterstützt.

Wie üblich finden Sie die Quellen auf GitHub.