Stai scrivendo dei servizi web in Java e vorresti sempre loggare l’utente collegato e l’IP del chiamante in modo automatico e trasparente per darli in pasto a ELK? O assegnare un identificativo univoco ad un batch multithread perché non capisci più cosa sta loggando ogni thread? In realtà è una cosa più semplice di quanto si pensi perché è una feature supportata da tempo dalla maggior parte dei sistemi di logging in Java come Log4j, Log4j2 o Logback, e, ovviamente da loro “padre” SLF4J!

Mapped Diagnostic Context

Questa feature è sempre stata lì, bastava sapere che si chiamava Mapped Diagnostic Context (MDC): come dice il nome, non è altro che una mappa contestuale al thread corrente che serve proprio per raccogliere le informazioni che si vuole presentare ad ogni riga di log, secondo il layout pattern del framework che stiamo usando. Non c’è bisogno quindi di ricordarsi di aggiungerle ogni volta che si logga qualcosa: una volta nella mappa, sarà il framework a stampare le informazioni per noi secondo il pattern specificato.

Facciamo un esempio: la riga di codice

LOGGER.info("Payment accepted");

normalmente si traduce in una cosa del tipo:

2017-12-31 23:59:59.999 -- INFO: Payment accepted

Ci fa capire che il pagamento è andato a buon fine, ma niente più. Se volessimo fare delle statistiche sarebbe interessante sapere da che IP viene (in modo da geolocalizzarlo) e magari associare questa informazione con i log del sistema di pagamento, accoppiando le chiamate con un request ID, per ottenere un log più informativo:

2017-12-31 23:59:59.999 [IP: 10.242.10.111 | REQ_ID: nbb4sqq553-2dss510] -- INFO: Payment accepted

Come si fa ad ottenere un log di questo tipo? Servono solo 2 cose:

Scrivere nella mappa MDC

Impostare il layout pattern della configurazione del log in modo da richiamare le chiavi inserite nella mappa: sarà il framework di log poi a leggere la mappa e comporre il prefisso secondo il layout. Un esempio concreto Quello di cui abbiamo bisogno è:

un progetto qualsiasi in Java, che sia una web application Java EE o una applicazione standalone Java SE un framework di logging che supporti MDC, come SLF4J: se si una JUL o JCL, conviene usare dei bridge verso SLF4J

Prendiamo un progetto di esempio su GitHub (mdc-poc) basato su Spring Boot (ma non è necessario che lo sia, è solo per la comodità di avere velocemente un web server).

Il posto migliore per recuperare l’IP del chiamante è un Web Filter:

import org.slf4j.MDC; @WebFilter(urlPatterns = "*") public class LogEnricherFilter implements Filter { @Override public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException { try { String logData = String.format("[IP: %s | REQ_ID: %s]", servletRequest.getRemoteAddr(), UUID.randomUUID().toString()); MDC.put("logData", logData); filterChain.doFilter(servletRequest, servletResponse); } finally { MDC.clear(); } }

Ogni chiamata HTTP viene quindi filtrata: viene recuperato l’IP del chiamante e viene generato un request ID univoco per chiamata (tramite un UUID casuale). Questi vengono composti nella stringa logData e aggiunti alla mappa MDC , a cui si accede in modo statico (riga 13). Dietro le quinte ovviamente c’è un ThreadLocal, quindi meglio svuotarlo (riga 16) perché probabilmente il thread fa parte di un pool.

A questo punto il framework di log ha una nuova informazione (la chiave logData ) pronta per essere stampata. In Spring Boot è molto semplice, grazie alla property logging.pattern.level , definire un nuovo pattern per i log:

logging.pattern.level=%X{logData}%5p

Basta quindi usare %X{...} per referenziare una chiave della mappa MDC da usare nel layout e il gioco è fatto! Il branch “plain-mdc” del progetto di prova ne è un esempio.

E ora non rimane che sbizzarrirsi! Da un Web Filter possiamo ricavare un sacco di informazioni, come l’utente autenticato nel sistema, o una serie di informazioni dettagliate della richiesta in corso come fa MDCInsertingServletFilter di Logback.

Nel caso del mondo multithread invece, è necessario ricopiare la mappa MDC dal thread padre a quello figlio, come specificato sempre nella documentazione di Logback. Se usiamo gli Executors di Java, potremmo scriverci un adapter che fa proprio questo lavoro:

public class ApplicationExecutorService { public void execute(Runnable runnable) { Map<String, String> contextMap = MDC.getCopyOfContextMap(); this.executorService.execute(() -> { MDC.setContextMap(contextMap); runnable.run(); }); } }

L’MDC viene copiata e reimpostata nel nuovo thread prima di eseguire il Runnable . In questo caso non occorre svuotarla, tanto il thread pool è gestito da noi e l’MDC viene sovrascritto ogni volta. Il codice completo è su GitHub

Spring Boot, Spring Sleuth e MDC

Se stiamo usando Spring Sleuth, i nostri log sono già arricchiti con qualche informazione in più, come avevamo detto in un post precedente quando parlavamo di Spring Cloud.

Ovviamente anche Spring Sleuth usa dietro le quinte MDC, come si vede da Slf4jSpanLogger . Il problema a questo punto è che se aggiungiamo Spring Sleuth al classpath di un progetto che già faceva uso della MDC, con molta probabilità non vedremo le informazioni che ci aspetteremmo dal framework, o magari perderemo le nostre, perché ci stiamo sovrascrivendo i layout pattern a vicenda!

Questo empasse si risolve facilmente riscrivendo un pattern che tenga conto delle nostre chiavi nel MDC e di quelle di Sleuth, come per esempio:

logging.pattern.level=[%X{X-Ip:-}]::[${spring.application.name:-},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}]%5p

Dove X-Ip è una nostra chiave, generata in un filtro tipo il precedente, mentre le altre sono quelle di default di Spring Sleuth. E’ disponibile un esempio nel branch “spring-sleuth” del progetto su GitHub.

Conclusioni