Logging usando marcadores con slf4j y logback

Un sistema de logging en una aplicación es indispensable para saber lo que está sucediendo en la aplicación en el mismo momento o pasado un tiempo. Es de gran utilidad tanto para en el momento de desarrollar la aplicación como para una vez puesta en producción. Con el registro de las trazas podemos obtener información que nos permitirá descubrir un error o averiguar más fácilmente y rápidamente porque sucede algún comportamiento que no es como se espera.

En Java hay varios sistemas de logging entre los más utilizados están Log4j, logback, java.util.logging y la capa de abstracción slf4j sobre varios de estas librerías. En estas librerías de logging las trazas se emiten a través de un logger que normalmente se corresponde con el nombre de la clase en la que se emite la traza. De esta forma las trazas se pueden filtrar por el nivel de importancia de la traza (debug, info, warn, …) y por el nombre del logger de forma que podemos obtener un registro de las trazas emitidas por los loggers que deseamos.

Sin embargo, el nivel de trazas y nombre de logger no son los más adecuados para determinadas necesidades. En algún caso nos puede interesar solo algunas trazas asociadas a determinada funcionalidad, el resto de trazas podríamos querer filtrarlas, pero únicamente con los filtros por nivel y nombre de logger no podríamos. Además, una funcionalidad puede estar dispersa entre varias clases con lo que si el nombre del logger es el nombre de la clase deberíamos especificar todos los logger que queremos individualmente y aunque los loggers tienen una relación jerárquica no es útil para obtener lo que queremos.

Para obtener las trazas específicas que queremos y que pueden estar dispersas en varias clases podemos usar los filtros de logback, una posibilidad es usar los marcadores pero hay otra buena cantidad de posibilidades dependiendo de nuestras necesidades.

Por ejemplo, para la siguientes clases nos podría interesar obtener las trazas asociadas a la funcionalidad de importación pero si indicamos que queremos la trazas del logger Importador y de nivel INFO obtendríamos todas la trazas de la clase incluidas las trazas de persistencia.

 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

package io.github.picodotdev.log.markers;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;

public class Main {

	// Loggers
	private static final Logger logger = LoggerFactory.getLogger(Main.class);

	// Marcadores
	public static Marker importacion = MarkerFactory.getMarker("IMP");
	public static Marker importacionUtils = MarkerFactory.getMarker("UTL");
	public static Marker persistencia = MarkerFactory.getMarker("PER");
	
	static {
		// Incluir en un marcador las trazas de otro 
		importacionUtils.add(importacion);
	}

	public static void main(String[] args) {
		logger.info("Iniciando...");
		
		logger.info(Main.importacion, "Comenzando importación...");
		new Importador().importar();
		logger.info(Main.importacion, "Importación finalizada");
	}
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22

package io.github.picodotdev.log.markers;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Importador {

	private static final Logger logger = LoggerFactory.getLogger(Importador.class);
	
	public Importador() {		
	}
	
	public void importar() {
		logger.info(Main.importacion, "Realizando importación...");

		Utils.importar();
		
		logger.info(Main.persistencia, "Persistiendo algo...");
		
		Utils.save();
	}
}

 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

package io.github.picodotdev.log.markers;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Utils {

	private static final Logger logger = LoggerFactory.getLogger(Utils.class);
	
	public static void save() {
		logger.info("Comenzando persistencia (utils)...");
		
		// ...
		
		logger.info(Main.persistencia, "Persistido algo (utils)...");
	}
	
	public static void importar() {
		logger.info("Comenzando importación (utils)...");
		
		// ...
		
		logger.info(Main.importacionUtils, "Importado algo (utils)...");
	}	
}

Este sería el resultado:

Para conseguir solo las trazas de una funcionalidad se pueden utilizar los marcadores («markers») de forma que además de por el nivel del mensaje de traza y el logger podamos filtrar por el marcador asociado a la traza. El marcador de una traza es una etiqueta por la que posteriormente podemos filtrar. Si una funcionalidad estuviese repartida por varias clases podríamos usar el mismo marcador en todas esas trazas de forma que podamos filtrar luego por él. El resultado del ejemplo completo sería el siguiente:

En ambos resultados puede verse el nombre del marcador (IMP de importación, PER de persistencia, UTL de utilidad) asociado a la traza, en el segundo solo se muestran las trazas con el marcador IMP de la funcionalidad de importación.

Utilizando la combinación slf4j y logback, la configuración para de logback y usando un filtro para obtener las trazas con el marcador asociado que deseamos es la siguiente:

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

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="io.github.picodotdev.log.markers.ImportacionFilter"></filter>
        <encoder>
            <pattern>%-23d{ISO8601} %-5p %-17marker %-17t %40.40C %-15M %m%n</pattern>
        </encoder>
    </appender>

    <logger name="io.github.picodotdev.log.markers" level="INFO"/>

    <root level="debug">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

Este sería el código del filtro que nos permitiría obtener las trazas de una determinada funcionalidad, en el caso del ejemplo las trazas relativas a la funcionalidad de importación.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20

package io.github.picodotdev.log.markers;

import org.slf4j.Marker;

import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.filter.Filter;
import ch.qos.logback.core.spi.FilterReply;

public class ImportacionFilter extends Filter<ILoggingEvent> {

	@Override
	public FilterReply decide(ILoggingEvent event) {
		Marker marker = event.getMarker();
		if (Main.importacion.equals(marker) || marker.contains(Main.importacion)) {
			return FilterReply.ACCEPT;
		} else {
			return FilterReply.DENY;
		}
	}
}

Puedes obtener el código fuente completo del ejemplo de su repositorio de GitHub y probarlo en tu equipo.

¿Conocías y has usado alguna vez esta funcionalidad?