Registrazione Java migliorata con Mapped Diagnostic Context (MDC)

1. Panoramica

In questo articolo, esploreremo l'uso del Mapped Diagnostic Context (MDC) per migliorare la registrazione dell'applicazione.

L'idea di base di Mapped Diagnostic Context è di fornire un modo per arricchire i messaggi di log con parti di informazioni che potrebbero non essere disponibili nell'ambito in cui si verifica effettivamente la registrazione, ma che possono essere effettivamente utili per monitorare meglio l'esecuzione del programma.

2. Perché utilizzare MDC

Cominciamo con un esempio. Supponiamo di dover scrivere software che trasferisce denaro. Abbiamo impostato una classe Transfer per rappresentare alcune informazioni di base: un ID di trasferimento univoco e il nome del mittente:

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

Per eseguire il trasferimento, dobbiamo utilizzare un servizio supportato da una semplice 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); } 

I metodi beforeTransfer () e afterTransfer () possono essere sovrascritti per eseguire codice personalizzato subito prima e subito dopo il completamento del trasferimento.

Faremo leva su beforeTransfer () e afterTransfer () per registrare alcune informazioni sul trasferimento .

Creiamo l'implementazione del servizio:

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

Il problema principale da notare qui è che quando viene creato il messaggio di log, non è possibile accedere all'oggetto Transfer - solo l'importo è accessibile, rendendo impossibile registrare l'ID della transazione o il mittente.

Configuriamo il solito file log4j.properties per accedere alla 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 

Configuriamo finalmente una piccola applicazione in grado di eseguire più trasferimenti contemporaneamente tramite 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(); } }

Notiamo che per utilizzare ExecutorService , dobbiamo avvolgere l'esecuzione del Log4JTransferService in un adattatore perché executor.submit () si aspetta un Runnable :

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

Quando eseguiamo la nostra applicazione demo che gestisce più trasferimenti contemporaneamente, scopriamo molto rapidamente che il registro non è utile come vorremmo che fosse . È complesso tenere traccia dell'esecuzione di ogni trasferimento perché le uniche informazioni utili registrate sono la quantità di denaro trasferita e il nome del thread che sta eseguendo quel particolare trasferimento.

Inoltre, è impossibile distinguere tra due diverse transazioni dello stesso importo eseguite dallo stesso thread perché le relative righe di registro sembrano essenzialmente le stesse:

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

Fortunatamente, MDC può aiutare.

3. MDC in Log4j

Introduciamo MDC .

MDC in Log4j ci consente di riempire una struttura simile a una mappa con informazioni accessibili all'appender quando il messaggio di log viene effettivamente scritto.

La struttura MDC è collegata internamente al thread in esecuzione nello stesso modo in cui lo sarebbe una variabile ThreadLocal .

E quindi, l'idea di alto livello è:

  1. per riempire l'MDC con le informazioni che vogliamo mettere a disposizione dell'appender
  2. quindi registra un messaggio
  3. e infine, cancella l'MDC

Ovviamente il pattern dell'appender dovrebbe essere cambiato per poter recuperare le variabili memorizzate nell'MDC.

Quindi cambiamo quindi il codice secondo queste linee guida:

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

Non sorprende che MDC.put () venga utilizzato per aggiungere una chiave e un valore corrispondente nell'MDC mentre MDC.clear () svuota l'MDC.

Cambiamo ora log4j.properties per stampare le informazioni che abbiamo appena memorizzato in MDC. È sufficiente modificare lo schema di conversione, utilizzando il segnaposto % X {} per ogni voce contenuta nell'MDC che vorremmo fosse loggata:

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

Ora, se eseguiamo l'applicazione, noteremo che ogni riga contiene anche le informazioni sulla transazione in corso di elaborazione rendendo molto più facile per noi tracciare l'esecuzione dell'applicazione:

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

La stessa funzionalità è disponibile anche in Log4j2, quindi vediamo come usarla.

Per prima cosa configuriamo una sottoclasse TransferService che registra utilizzando 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); } } 

Cambiamo quindi il codice che utilizza MDC, che in realtà si chiama ThreadContext in 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(); } } 

Ancora una volta, ThreadContext.put () aggiunge una voce in MDC e ThreadContext.clearAll () rimuove tutte le voci esistenti.

Ci manca ancora il file log4j2.xml per configurare la registrazione. Come possiamo notare, la sintassi per specificare quali voci MDC devono essere registrate è la stessa di quella utilizzata in Log4j:

Ancora una volta, eseguiamo l'applicazione e vedremo le informazioni MDC stampate nel registro:

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 è disponibile anche in SLF4J, a condizione che sia supportato dalla libreria di registrazione sottostante.

Sia Logback che Log4j supportano MDC come abbiamo appena visto, quindi non abbiamo bisogno di niente di speciale per usarlo con una configurazione standard.

Prepariamo la solita sottoclasse TransferService , questa volta utilizzando Simple Logging Facade per 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); } } 

Usiamo ora il sapore di MDC di SLF4J. In questo caso, la sintassi e la semantica sono le stesse di 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(); } } 

Dobbiamo fornire il file di configurazione Logback , logback.xml :

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

Di nuovo, vedremo che le informazioni nell'MDC vengono aggiunte correttamente ai messaggi registrati, anche se queste informazioni non sono fornite esplicitamente nel metodo 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

Vale la pena notare che nel caso in cui configuriamo il back-end SLF4J su un sistema di registrazione che non supporta MDC, tutte le chiamate correlate verranno semplicemente saltate senza effetti collaterali.

6. MDC e pool di thread

Le implementazioni MDC utilizzano solitamente ThreadLocal per archiviare le informazioni contestuali. Questo è un modo semplice e ragionevole per ottenere la sicurezza dei thread. Tuttavia, dovremmo stare attenti usando MDC con i pool di thread.

Vediamo come la combinazione di MDC basati su ThreadLocal e pool di thread può essere pericolosa:

  1. Otteniamo un thread dal pool di thread.
  2. Quindi memorizziamo alcune informazioni contestuali in MDC utilizzando MDC.put () o ThreadContext.put () .
  3. Usiamo queste informazioni in alcuni log e in qualche modo ci siamo dimenticati di cancellare il contesto MDC.
  4. Il thread preso in prestito torna al pool di thread.
  5. Dopo un po ', l'applicazione ottiene lo stesso thread dal pool.
  6. Poiché l'ultima volta non abbiamo ripulito l'MDC, questo thread possiede ancora alcuni dati dell'esecuzione precedente.

Ciò potrebbe causare alcune incongruenze impreviste tra le esecuzioni. Un modo per evitare ciò è ricordarsi sempre di pulire il contesto MDC alla fine di ogni esecuzione. Questo approccio di solito richiede una rigorosa supervisione umana e, pertanto, è soggetto a errori.

Un altro approccio consiste nell'utilizzare gli hook ThreadPoolExecutor ed eseguire le pulizie necessarie dopo ogni esecuzione. Per farlo, possiamo estendere la classe ThreadPoolExecutor e sovrascrivere l' hook afterExecute () :

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

In questo modo, la pulizia MDC avverrebbe automaticamente dopo ogni esecuzione normale o eccezionale. Quindi, non è necessario farlo manualmente:

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

Ora possiamo riscrivere la stessa demo con la nostra nuova implementazione esecutore:

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

MDC ha molte applicazioni, principalmente in scenari in cui l'esecuzione di diversi thread causa messaggi di registro interleaved che sarebbero altrimenti difficili da leggere.

E come abbiamo visto, è supportato da tre dei framework di registrazione più utilizzati in Java.

Come al solito, troverai i sorgenti su GitHub.