Migliora i tuoi log con il Mapped Diagnostic Context (MDC)

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 è:

    1. un progetto qualsiasi in Java, che sia una web application Java EE o una applicazione standalone Java SE
    2. 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

    Abbiamo scoperto quindi che personalizzare le informazioni che possiamo mettere automaticamente in ogni riga di log è estremamente semplice, basta trovare il “punto di ingresso” giusto dove collezionare questi dati (come nel caso del Web Filter) o propagarli nei thread figli (come nel caso degli Executors).
    A cosa serve fare una cosa del genere? In un sistema distribuito, per esempio, è importante riuscire a ricollegare il filo di una chiamata che attraversa diversi sistemi per capire cosa succede, soprattutto quando ci sono problemi: generare un requestID diverso per chiamata diventa quindi fondamentale. Oppure, se vogliamo sapere da dove vengono le chiamate, è importante conoscerne l’IP. O ancora, se vogliamo tracciare cosa sta facendo un certo utente, possiamo stampare il suo username in ogni riga. Tutte queste informazioni però non servono a niente se non si riesce ad aggregarle e analizzarle: per questo, usare l’MDC è il primo passo necessario per avere dati sufficienti da dare in pasto ad aggregatori come ELK, Loggly, Splunk (o altri) che a partire da queste informazioni, riescono a dare un quadro più ad alto livello di quello che succede nella vita di un sistema.

Andrea Como

Sono un software engineer focalizzato nella progettazione e sviluppo di applicazioni web in Java. Presso OmniaGroup ricopro il ruolo di Tech Leader sulle tecnologie legate alla piattaforma Java EE 5 (come WebSphere 7.0, EJB3, JPA 1 (EclipseLink), JSF 1.2 (Mojarra) e RichFaces 3) e Java EE 6 con JBoss AS 7, in particolare di CDI, JAX-RS, nonché di EJB 3.1, JPA2, JSF2 e RichFaces 4. Al momento mi occupo di ECM, in particolar modo sulla customizzazione di Alfresco 4 e sulla sua installazione con tecnologie da devops come Vagrant e Chef. In passato ho lavorato con la piattaforma alternativa alla enterprise per lo sviluppo web: Java SE 6, Tomcat 6, Hibernate 3 e Spring 2.5. Nei ritagli di tempo sviluppo siti web in PHP e ASP. Per maggiori informazioni consulta il mio curriculum pubblico. Follow me on Twitter - LinkedIn profile - Google+

  • Antonio Musarra

    È un componente davvero comodo che ho utilizzato una miriade di volte ma che purtroppo non tutti conoscono.