Identificar todas las trazas de una petición en una aplicación web Java con Log4j

Escrito por el 30/07/2018, actualizado el 30/07/2018.
java planeta-codigo programacion
Enlace permanente Comentarios

Java

En una aplicación web hay múltiples usuarios realizando peticiones al servidor de modo que al usar una librería de logging como Log4j las trazas de información de los diferentes usuarios aparecerán intercaladas. En esta maraña de trazas resulta difícil obtener la secuencia de trazas de una petición siendo la diferencia entre descubrir la causa de un error o pasar varias horas revisando trazas sin encontrar nada significativo en la inmensa cantidad de ellas relativas a otras peticiones. La librería Log4j proporciona un mecanismo para seguir la secuencia completa de trazas de una petición con el concepto denominado fish tagging.

En el contexto de una aplicación web para seguir la secuencia de trazas de una petición consiste en asignar variables con información al thread que ejecuta la petición, el contenido de estas variables está disponible para emitirse en la traza. Asignando a cada petición un identificativo aleatorio único cuando se inicia la petición, en una aplicación web Java podría ser en un filtro, las trazas emitidas de cada petición quedarán relacionadas por compartir el mismo identificativo de contexto. Este identificativo significa que encontrada una relevante es posible obtener el resto de las peticiones muy fácilmente con un filtro usando ese identificativo.

El filtro podría ser el siguiente, el identificativo se genera de forma aleatoria con la clase UUID del JDK de Java, se asigna al ThreadContext y al finalizar se limpia de información la variable de contexto en la cláusula finally de un try-catch.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31


package io.github.picodotdev.plugintapestry.misc;

import java.io.IOException;
import java.util.UUID;
import javax.servlet.*;

import org.apache.logging.log4j.ThreadContext;

public class AppFilter implements Filter {

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {
    }

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        try {
            ThreadContext.put("uuid", UUID.randomUUID().toString());
            Globals.HOST.set(request.getServerName());

            chain.doFilter(request, response);
        } finally {
            Globals.HOST.remove();
            ThreadContext.clearAll();
        }
    }

    @Override
    public void destroy() {
    }
}

AppFilter.java

El emitir trazas no cambia en absoluto si utilizamos esta técnica para identificar trazas.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37


package io.github.picodotdev.plugintapestry.pages;

...

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

...

public class Index {

	private static final Logger logger = LogManager.getLogger(Index.class);

	...

	// Ciclo de vida
	Object onActivate(Object[] context) {
		logger.info("Activating page {}", Index.class.getSimpleName());
		if (context != null && context.length > 0) {
			return Error404.class;
		}
		return null;
	}

	/**
	 * Método del ciclo de vida de la página que es llamado por Tapestry al inicio de la
	 * renderización de la página.
	 */
	void setupRender() {
		logger.info("Rendering page {}", Index.class.getSimpleName());
		logger.info("Host {}", Globals.HOST.get()); // ThreadLocal example

	...
	}

  ...
}

Index.java

En el formato usado para determinar el contenido de la trazas se pueden referenciar las variables deseadas a incluir en la traza.

%X muestra el contenido completo del Map.
%X{key} muestra el valor de una clave especifica del Map.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14


configuration:
  status: warn

  appenders:
    console:
      name: STDOUT
      patternLayout:
        Pattern: "%d{DEFAULT} %X{uuid} %-5level %60.60logger %msg%n"

  loggers:
    root:
      level: info
      appenderRef:
        ref: STDOUT

log4j2.yaml

Y este es el resultado de emitir varias trazas habiendo establecido un identificativo en el ThreadContext, todas las trazas emitidas por ese Thread incluirán el mismo identificativo.

En este conjunto las tres primeras corresponden a la petición de una página en la siguiendo el ciclo de vida de una página de Apache Tapestry se llama primero al método activate y posteriormente al método setupRender, estas tres poseen el mismo UUID ya que se ejecutan en la misma petición. Las otras dos corresponden cada una de ellas a una petición AJAX que realiza la página Index al cargarse en el navegador del cliente, cada una de estas dos peticiones AJAX se procesan en un nuevo hilo y por consiguiente poseen un UUID diferente.

1
2
3
4
5


2018-07-30 20:15:24,498 91733457-5a70-460c-a931-6bb1886d4070 INFO               io.github.picodotdev.plugintapestry.pages.Index Activating page Index
2018-07-30 20:15:24,506 91733457-5a70-460c-a931-6bb1886d4070 INFO               io.github.picodotdev.plugintapestry.pages.Index Rendering page Index
2018-07-30 20:15:24,512 91733457-5a70-460c-a931-6bb1886d4070 INFO               io.github.picodotdev.plugintapestry.pages.Index Host localhost
2018-07-30 20:15:28,175 d0fb5955-f5fc-406c-9fb3-e9f853b64222 INFO               io.github.picodotdev.plugintapestry.pages.Index Activating page Index
2018-07-30 20:15:28,604 3d7525ba-09d6-48a0-89cc-958f1b6ab2a2 INFO               io.github.picodotdev.plugintapestry.pages.Index Activating page Index

System.out

Para emitir trazas de forma relacionada esta no es la única posibilidad, también puede interesar identificar con marcadores las trazas relacionadas emitidas en diferentes clases de una aplicación en diferentes clases pero pertenecientes a la misma funcionalidad, contexto delimitado o bounded context.

El código fuente completo del ejemplo puedes descargarlo del repositorio de ejemplos de Blog Bitix alojado en GitHub y probarlo en tu equipo ejecutando siguiente comando:
./gradlew run