¿Cómo utilizar Log4j y MDC en la aplicación Java Spring Boot?

En el contexto de uno de nuestros proyectos, nos enfrentamos a muchos casos de depuración. Los simples mensajes en los registros no siempre son suficientes. Por ejemplo, puede ser necesario tener más información sobre el usuario que ejecutó la acción (su IP, sus permisos, su identificador, …). En nuestro caso, nuestra aplicación estaba construida a partir de varios microservicios y queríamos identificar con precisión el flujo seguido por una petición que pasa de un microservicio a otro. Para ello, se generaba un identificador único que se mostraba en los logs de cada aplicación web. Esto nos ayudó mucho a resolver problemas con aplicaciones de terceros que estábamos utilizando.

• ¿Cómo registrar los mensajes?
• ¿Qué información de contexto añadir a nuestros mensajes?
• ¿Se puede añadir esta información al ejecutar hilos asíncronos?

Este artículo te ayudará a construir una aplicación Java de Spring Boot para registrar mensajes con Log4j y utilizar el MDC de esta librería (Mapping Diagnostic Context) para añadir datos de contextualización además de los mensajes, especialmente para tareas asíncronas.

Comencemos generando una aplicación clásica de Spring Boot con la librería Log4j incorporada. Esta librería nos permite utilizar un logger que genera mensajes de registro de diferentes tipos (info, error, warning, …)

1. En Spring Initializr (https://start.spring.io/), construye un proyecto básico de Spring Boot sin dependencias.
2. Edita el fichero pom.xml para añadir las dependencias necesarias para utilizar la librería Log4j
3. Crea el fichero src/main/resources/log4j2.xml que define el formato de los futuros mensajes de registro

pom.xml

src/main/resources/log4j2.xml

Mostrar nuestro primer mensaje de registro

En el estado actual, si lanzamos la aplicación (a través de un IDE por ejemplo o usando Maven), no aparece ningún mensaje de registro. Vamos a crear un componente que utilice la librería Log4j para registrar un mensaje de información.

Crea un archivo src/main/java/com/sipios/example/mdc/Execute.java con el siguiente código. El nombre del paquete es aquí com.sipios.example.mdc, por supuesto, debe ser sustituido por el suyo 🙂

src/main/java/com/sipios/example/mdc/Execute.java

Si ejecuta la aplicación, ahora se muestra un primer mensaje de registro que respeta el formato definido. También es posible utilizar los métodos error y warning. Se mostrarán los mensajes de log correspondientes a estos tipos.

Utiliza el MDC (Mapping Diagnostic Context) en tu log

Ahora que sabemos utilizar la librería Log4j, podremos utilizar el Mapping Diagnostic Context (MDC) que nos permite asociar un Map de datos a nuestro mensaje. Algunos ejemplos de datos que recomendamos poner en el MDC:

• Datos de la sesión actual (usuario, consulta, petición…)
• Métricas sobre la ejecución del proceso (tiempo inicial y tiempo de ejecución, …)
• Piezas de información sobre la versión de la aplicación
• …

Este Mapa se muestra en los registros si se utiliza la máscara %X en la definición del formato de los mensajes Log4j. Este es el caso aquí en nuestro archivo src/main/resources/log4j2.xml. En la ejecución anterior, vemos {}, que indica un Map vacío.

El uso de MDC es muy sencillo y se utiliza como un Map clásico a través de los métodos put, get, remove, clear… Añadamos dos entradas al MDC y ejecutemos la aplicación.

src/main/java/com/sipios/example/mdc/Execute.java

El MDC es global y se conserva mientras no se modifique. Si se quiere vaciar dejando un componente por ejemplo, basta con utilizar el método clear. Esto daría el siguiente resultado.

¿Cómo funciona con componentes asíncronos?

¡Probemos el MDC con componentes asíncronos (un componente ejecutado en un hilo paralelo al hilo principal)! En primer lugar, tenemos que configurar nuestra aplicación para ejecutar dichos beans. Creamos un servicio con dos métodos, uno es síncrono y el otro asíncrono.

1. Agrega la anotación @EnableAsync a la clase Application
2. Crea un servicio con un método normal y otro @Async
3. Modifica el componente para inyectar y utilizar los métodos del servicio
4. Lanza la aplicación

src/main/java/com/sipios/example/mdc/Application.java

src/main/java/com/sipios/example/mdc/service/Example.java

src/main/java/com/sipios/example/mdc/Execute.java

Añadir taskExecutor en la clase Application

src/main/java/com/sipios/example/mdc/Application.java

Rejecutar :

Como podemos ver, el MDC en el hilo asíncrono está vacío. De hecho, cada tarea asíncrona se inicia en un nuevo hilo. Cada hilo está vinculado a un MDC del Mapa iniciado por el ejecutor de la tarea. Es posible tocar en este ejecutor para obtener el mismo MDC que en el hilo principal. Añadamos un decorador en asyncExecutor para duplicar el MDC!

src/main/java/com/sipios/example/mdc/ExampleTaskDecorator.java

Establezca este decorador en async config

src/main/java/com/sipios/example/mdc/Application.java

Lance la aplicación

¡Ya está! Podemos transmitir en los logs todo el contexto que queramos en tareas síncronas o asíncronas.

Gracias a esto, la depuración de una aplicación se simplifica y es más comprensible. Como parte de nuestro proyecto esto nos ha ahorrado mucho tiempo en los intercambios con nuestros colaboradores. Ahora depende de ti 🙂

Bibliografía

• http://www.baeldung.com/mdc-in-log4j-2-logback
• https://spring.io/guides/gs/async-method/
• https://moelholm.com/2017/07/24/spring-4-3-using-a-taskdecorator-to-copy-mdc-data-to-async-threads/