It's all about logging

April 16, 2016 slf4j logging log4j

En las incumbencias de un desarrollador, muchas veces el saber loguear es poco valorada. Siempre es posible copiar de algún lado un log y listo. Establecer bien el nivel de log ya es considerada una habilidad reservada sólo para algunos elegidos. Ni hablar a la hora de elegir el framework de logging. En general son pocos los que se adentran en este "obscuro" mundo y conocen realmente de qué se trata.

Muestras de esto son algunos errores que veo repetirse a diario en diferentes proyectos. Acá voy a dejar algunas cuestiones a tener en cuenta (los ejemplos usan SLF4J):

Tener en cuenta la performance

Algunos frameworks de logging no tienen soporte para el pasaje de parámetros a los mensajes de log y entonces un log se ve como esto:

String msg = ...
List aList = ...
LOGGER.info("Printing this useful message: "+msg+" for the posterity "+aList);

Esto va a generar el string a loguear ya sea que nuestro nivel de log imprima el mensaje o no. Esto es porque Java no es lazy. Una forma de resolver esto es agregando un if:

if (LOGGER.isInfoEnabled()){
	LOGGER.info("Printing this useful message: "+msg+" for the posterity "+aList);	
}

Pero estamos sumando el chequeo de esa condición siempre. SLF4J en particular permite pasar como parámetro las variables para el log, de manera que estas no son evaluadas si el log no se va a imprimir:

LOGGER.info("Printing this useful message: {} for the posterity {}", msg, aList);

Además es más fácil de escribir y hasta 30 veces más eficiente.

Loguear el trace de las excepciones

Cuando se trata de loguear excepciones hay que tener cuidado. Es un error muy común por no prestar atención a la signatura de los métodos: Logger method signature Si no tenemos cuidad podríamos escribir:

try{
	
} catch (Exception e){
	LOGGER.warn("An exception occurrend with {}: {}", msg, e);	
}

Esto convertirá la exepción a un String cuando se le aplique el formato al mensaje dejándonos poca información acerca de la misma. Como se ve en la signatura del método, puede ser invocado con un String y una lista (varargs) de objetos como mencioné anteriormente (en este caso estamos matcheando con esta signatura, con lo cual la excepción será interpretada como un Object y no como la excepción que es). Necesitamos que el método reciba un tipo de exepción (para que sepa cómo imprimirlo), para lo cual la api nos provee info(String arg0, Throwable arg1). Entonces la forma de arreglarlo es pasar sólo 2 parámetros, siendo el primero un String y el segundo una instancia de Throwable.

Por ejemplo podríamos modificar lo anterior de esta manera:

try{
	
} catch (Exception e){
	LOGGER.warn(String.format("An exception occurrend with %s", msg), e);
}

NOTA: No olvidar cambiar {} por %s

Prestar atención a los imports

Dado que muchos frameworks de log tienen clases similares, es importante prestar atención al utilizar el autoimport de nuestra IDE preferida.

Por ejemplo la clase Logger la encontramos en: java.util.logging, ch.qos.logback.classic, org.apache.log4j y org.slf4j entre otros. También podemos encontrarnos con varias variantes de LoggerFactory. Elegir correctamente qué clase usar es muy importante. En el caso que estemos usando SLF4J debemos elegir:

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

Simple Logging Facade for Java (SLF4J)

Hace ya varios meses que migramos todas nuestras aplicaciones a usar SLF4J, pero todavía no había podido hacerme el tiempo para leer y conocer un poco los trafondos de este cambio. Hoy pude dedicarle tiempo y quería puntualizar algunos puntos que me parecieron importantes.

Lo primero que me sirvió y mucho es el manual de usuario que llamativamente es muy escueto, pero gratamente útil. De ahí entendí de qué manera SLF4J provee una interfaz a diferentes frameworks de logging. Luego llegué a otra página donde se explica de qué manera hacer un puente con otras librerías de logging ya que muchas veces nuestros proyectos tienen dependencias con estos frameworks de logging y es bueno poder consolidar el log dentro de nuestra app.

Tuve un caso particular usando Spring ya que hace uso de commons-logging (ref). Y eso fue lo que me permitió entender mejor como funcionan estos puentes. Excluir commons-logging por si sólo causa que Spring no funcione, pero al reemplazarlo por el "puente" provisto por SLF4J, reemplaza las clases de commons-logging con otras que hacen pasar los logs por SLF4J. Así quedaría con Maven:

<dependency>
	<groupId>org.springframework</groupId>
	<artifactId>spring-core</artifactId>
	<version>${spring.version}</version>
	<exclusions>
		<exclusion>
			<artifactId>commons-logging</artifactId>
			<groupId>commons-logging</groupId>
		</exclusion>
	</exclusions>
</dependency>
<!-- replacement for commons-logging -->
<dependency>
	<groupId>org.slf4j</groupId>
	<artifactId>jcl-over-slf4j</artifactId>
	<version>${slf4j.version}</version>
</dependency>

Eligiendo el framework de logging

Por último hay que entender que SLF4J es sólo un facade. Podríamos describirlo como interfaz común para los frameworks de logs. Es decir que depende de una implementación concreta que efectúe los logs. Por defecto SLF4J provee una implementación que no loguea (no-operation o NOP), por lo que es recomendable asignar una. Quizás si ya estás usando algunas librerías en tu proyecto SLF4J podría encontrar algún binding que llega transitivamente a tu proyecto, por esto es importante revisar con cuidado las dependencias transitivas que tienen nuestras librerías.

Frameworks de log hay algunos, pero los más comunes son Jakarta Commons Logging o JCL (commons-logging), Log4J y Logback. De estos 3, el mejor parece ser Logback (al menos al compararlo con Log4J, ya que está basado en él y por el mismo desarrollador). Varias de las razones para migrar de Log4J a Logback son muy interesantes (como por ejemplo configuraciones condicionales) y nos dan una idea de lo que nos provee el framework (que nada tiene que ver con SLF4J).

La configuración de cómo queremos loguear debemos proveersela al framework. SLF4J no necesita configuración más que poder encontrar en el classpath los bindings necesarios para los diferentes frameworks de logging, pero es importante no mezclarlos. Si es posible tener logback-classic en nuestro classpath el cual será el framework de log y jcl-over-slf4j que es sólo un bridge o reemplazo para JCL. De mantener JCL, las librerías que usen ese framework para loguear no pasarán (en este caso) por logback.


Profile picture

Written by Gastón Fournier Software Engineer at @getunleash working from Cunit, Tarragona, Spain, where I live with my wife and 2 dogs. Find me on Twitter Github LinkedIn