SLF4J: Multiple bindings were found on the class path logback

En el proyecto que estoy trabajando utilizamos SLF4J como framework de logging. Estaba teniendo un problema en el cual mis llamados para registrar entradas en el log no estaban apareciendo. Al principio pensé que era un problema con el archivo de log4j ya que esta era la implentación final que se estaba utilizando. Sin embargo luego me dí cuenta de unos mensajes apareciendo al principio del arranque de la aplicación:

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/home/atg-dev/.m2/repository/ch/qos/logback/logback-classic/0.9.28/logback-classic-0.9.28.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/home/atg-dev/.m2/repository/org/slf4j/slf4j-log4j12/1.6.2/slf4j-log4j12-1.6.2.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
2014-03-13 21:30:46.718:INFO:/search-indexer:Initializing Spring root WebApplicationContext

Los mensajes estaban indicando que habían varios bindings, es decir, varias implementaciones de logging dentro del classpath. En específico pude ver que aparte de Log4j estaba LogBack, el cual no encontré ninguna referencia en el pom.xml. Había que descubrir la dependencia indirecta/transitiva.

La mejor manera para hallar la dependencia transitiva fue una idea de un compañero de utilizar el plugin de Maven en Eclipse que permite ver la jerarquía de dependencias.

De esa manera pude ubicar la dependencia que incluía al logback y agregar la exclusión:

        <dependency>
            <groupId>com.xxx.content</groupId>
            <artifactId>content-dao-jar</artifactId>
            <version>xx.xx.x.x</version>
            <exclusions>                
                <exclusion>
                    <groupId>ch.qos.logback</groupId>
                    <artifactId>logback-classic</artifactId>
                </exclusion>
            </exclusions>
        </dependency>

Excepciones Amigables con las Bitácoras

Es usual para un programador novato y con prisa, resolver el tema de las excepciones simplemente suprimiéndolas o atrapándolas para únicamente registrarlas en bitácoras (logs) y lanzarla hacia arriba para repetir el proceso en las clases subsecuentes. Puedo afirmar esto porque yo mismo solía manejar las excepciones de esta manera. Uno puede pensar al principio que esto es lo más considerado, "loguiemos por si acaso".

public class A {
public void callB() throws Exception{
 try {
  new B().doSomething();
 } catch (Exception exception) {
  exception.printStackTrace();
  throw Exception;
 } 
}
}

public class B{
public void doSomething() throws Exception {
 try {
  // Code potentially exception throwing.
 } catch (Exception exception) {
  exception.printStackTrace();
  throw Exception;
 }
}
}

Esta es una práctica común que parece inofensiva al principio en las etapas de desarrollo, pero no es hasta que nos encontramos analizando un problema de la aplicación corriendo en producción que nos damos cuenta de la mala idea que es tirar excepciones a lo loco. Cuando tenemos que investigar un problema de la aplicación que require ir a buzear en los archivos de bitácora, las múltiples apariciones de una sola excepción en varias clases produce un colocho mental para aquel que tiene que interpretar los registros de excepciones.

Además esto agrega ruido para cualquier actividad de monitoreo de las bitácoras. La excepción es multiplicada por el número de clases que invocan el método originador de esta, y cada clase no agrega ninguna información adicional de relevancia. Este confeti de excepciones crea la percepción de que el problema mostrado por la excepción es más grave de lo que parece. Esto dificulta la tarea de dirigir los esfuerzos al problema real.

Sugiero dos opciones para mejorar esto dependiendo de las necesidades de la aplicación:

1. Registrar en bitácoras solamente en la capa donde la excepción es producida y arrojar una excepción de tipo RuntimeException. Una excepción de tipo RuntimeException no necesita ser atrapada.

public class B{
public void doSomething() throws Exception {
 try {
  // Code potentially exception throwing.
 } catch (Exception exception) {
  exception.printStackTrace();
  throw new RuntimeException(exception);
 }
}
}

2. Lo otro que podemos hacer, sobre todo si las capas de arriba necesitan enterarse de que una excepción ocurrió, es crear nuevas excepciones (conocidas también como "wrappers") acuerdo con un grupo de categorias que facilitan la lectura de las bitácoras. En el siguiente código muestro un ejemplo con dos excepciones personalizadas: una cuando la culpa recae en el usuario debido a una mala especificación de los parámetros, y otra para encapsular las excepciones que se deben a una invocación remota.

public class ConfigurationException extends Exception {

}

public class RemoteServiceException extends Exception {

}


public class B{
public void doSomething(String mathFormula) {
 try {
  // Code to execute formula.  
 } catch (Exception exception) {
  throw new ConfigurationException(exception);
 }
}

public void doSomethingRemotely() {
 try {
  // Code to read Web Service.  
 } catch (Exception exception) {
  throw new RemoteServiceException(exception);
 }
}
}

public class A {
public void callB() {
 try {
  B b = new B();
  b.doSomething("filePath");
  b.doSomethingRemotely();
 } catch (ConfigurationException configurationException) {
  System.out.println("There was a configuration error!");
  exception.printStackTrace();  
 } catch (RemoteServiceExceptionremote) {
  System.out.println("There is no connectivity with remote services!");
  exception.printStackTrace();  
 }   
}
}

Al agregar otro nivel de abstracción ayudamos en las actividades de CSI (escena del crimen), especialmente cuando la gente que le toca esto no es la misma que la gente del equipo de desarrollo.

Análisis Gráfico de Excepciones Java en Bitácoras (Logs)

En ocasiones nos va tocar analizar qué está sucendiendo con nuestra aplicación en vivo porque aparentemente estamos teniendo "muchas" excepciones. Entrecomillo "muchas" porque como desarrolladores o encargados del monitoreo de la aplicación, alguien puede reportarnos que está viendo muchas excepciones en las bitácoras (logs) pero en realidad no sabemos si son muchas hasta que las contemos y veamos cuál es el promedio normal de apariciones de cierta excepción; en otras palabras, ver cuál es la tendencia de cierto tipo de excepciones. Si tenemos que analizar bitácoras enormes donde el comando buscar del editor de texto ("CTRL + F") no es suficiente para tener una perspectiva a gran escala, es entonces donde tenemos que atacar el problema de una forma más automatizada.

Quiero compartir en este artículo la fórmula que he utilizado en el pasado para analizar grandes cantidades de excepciones en grandes extenciones de bitácoras. Para generar el gráfico que vamos analizar uso un script de Perl para formatear los datos de una manera resumida y adecuada para luego procesarlos en una hoja de cálculo. En mi caso uso Calc de Open Office pero una hoja de Excel podría ser usada de igual manera.

El siguiente script de Perl extrae el nombre de la excepción y la fecha con la hora en que fue lanzada, y salva estos dos datos en dos columnas separadas por el carácter "~":

#!/usr/local/bin/perl

my $dir = $ARGV[0];

print "\n\n\t\tReading directory: " . $dir . " ...\n\n";
opendir(DIR, $dir);

my @files = readdir(DIR);
my $output = $dir."_results.txt";
closedir(DIR);

open (RESULTS, '>'.$output);
print RESULTS "date~exception\n";
$exception_counter = 0;

foreach $file( @files){
unless ( ($file eq ".") || ($file eq "..") ) {
my $total_size_read = 0;
my $file_path = $dir . '\\' . $file;
my $filesize;
{
use strict;
use warnings;
$filesize = -s $file_path ;
$filesize = $filesize / 1000; #Kbytes
}

print "\nReading file " .$file_path . "(" . $filesize . " kb)\n";
open (LOG, $file_path) || die "couldn't open the file!"; 

$line_number = 1;

while ($record = ) {

if ($record =~ m/([a-zA-Z1-9\.]*Exception)+/) {
$exception_description = $1;

if ($record =~ m/(((\d{4})-(\d{2})-(\d{2})\s(\d{2}))(:\d{2}:\d{2}))/) {    
 $year= $3;
 $month=$4;
 $day=$5;
 $hour=$6;     
 print RESULTS  $year . "-". $month . "-" . $day . " "  .  $hour . ":00~" . $exception_description ."\n" ;
 $exception_counter++; 
}
} 

$line_number++;
if ($line_number % 1000 eq 0) {
my $progress = sprintf("%.2f",(($total_size_read /1000) / $filesize) * 100);
print "\rTotal lines read: " . $line_number . " | Exceptions found: " . $exception_counter . " | Progress:" . $progress . "%";

}
{
use bytes;
my $byte_size = length($record);
$total_size_read = $total_size_read + $byte_size;
}
}

close(LOG);
}
}

close (RESULTS);

No voy a detallar mucho la lógica del script la cual de todas maneras es bastante simple. Recibe como argumento el nombre de un directorio y procesa todos los archivos que hayan dentro de él para extraer las aparaciones de excepciones de cada archivo.



El resultado final del script es un archivo con el siguiente formato:

date~exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~java.lang.NullPointerException
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 22:00~Exception
2009-08-16 22:00~Exception
2009-08-16 22:00~Exception
2009-08-16 22:00~Exception
2009-08-16 22:00~java.lang.NullPointerException

En este punto abrimos Calc de Open Office, seleccionamos los resultados del script, los copiamos y pegamos en la hoja de cálculo. Automáticamente se abrirá una caja de dialogo como la siguiente en la cual marcamos la caja de otros ("others") y escribimos el carácter de "raba de chancha" para separar los datos en dos columnas.

Una vez hecho esto es recomendable ordenar los datos de manera ascendente acorde con la columna de fecha para tener una secuencia cronológica de las excepciones. Seleccionamos las dos columnas excepto por la primera fila y usamos la opción de ordenamiento (Data->Sort...).



Seguidamente usamos, en mi opinión, una de las herramientas más poderosas de una hoja de cálculo: el DataPilot o Tabla Pivot en lenguaje Excel. El DataPilot nos permite agrupar datos de distintas columnas y contar o sumar el número de apariciones de acuerdo a las categorias que definimos con las columnas que seleccionamos. Seleccionamos las dos columnas, Data->DataPilot->Start...


En el diálogo que se abre arrastramos la caja "date" en los campos de columna, y la caja "exception" en los campos de fila. Tomamos nuevamente la caja "exception" y la arrastramos en el medio y damos clic en opciones. La opción por defecto es "Sum"; la cambiamos por "Count" para contar el número de apariciones por fecha y excepción. Más abajo hay otras opciones útiles que debemos usar:

1. Resultados en una nueva hoja: "Results to - new sheet -".
   
2. Ignorar filas vacias: "Ignore empty rows".
   

A partir de este momento podemos comenzar a analizar la línea cronológica de excepciones, o verificar un punto discreto de nuestra línea de tiempo si sabemos de antemano que algo sucedió en determinado día u hora. Para completar nuestro análisis vamos a generar un gráfico con la tabla que recien generamos.

Seleccionamos el rango de nuestra tabla para adelantarnos en uno de los pasos en la creación de nuestro gráfico. Buscamos el icono de gráfico ("chart") y lo presionamos.


1. Lo primero que tenemos que hacer es seleccionar el tipo de gráfico. En este caso uso el de puntos y líneas:


2. Dado que ya había seleccionado el rango de datos, la primera caja ya contiene nuestra selección previa. Debemos seleccionar la opción de series de datos en filas ("data series in rows") y chequear las dos opciones de primera fila y columna como etiquetas.


3. En las series de datos no hay mucho que modificar. Podemos quitar la serie de "Total Result " si nos causa algún ruido en nuestro análisis. Siempre podemos regresar a modificar esta sección después de generado el gráfico.

4. En elementos del gráfico no cambiamos nada relevante. En mi caso me gusta cambiar la posición de las leyendas del eje Y, o sea cada uno de los nombre de excepción, para situarlas arriba del gráfico, de otra manera quedan posicionados a la derecha y resulta a veces que son demasiadas leyendas con nombres extensos que acortan el área del gráfico que nos interesa analizar.

Generamos finalmente nuestro gráfico el cual como podrán notar, sale un poco desordenado por la gran cantidad de elementos en el eje X. Para solucionar esto podemos editar el gráfico en las propiedades del eje X.

Clic derecho al gráfico -> Edit -> Clic derecho al eje X -> Object Properties
Vamos a la sección de etiqueta ("label") y rotamos el texto desde su posición de 0° hasta algún nivel de inclinación que nos permita apreciar mejor nuestro gráfico. En mi caso uso 45°. 90° sería también útil para no escalar tanto nuestro gráfico.

Finalmente quedamos con un producto final del cual podemos sacar algunas conclusiones interesantes. Por ejemplo podemos ver una tendencia hasta cierto punto normal de número de excepciones desde el periodo del 14 Agosto pero después súbitamente el número de excepciones de NullPointerException se disparan el 17 del mismo mes. ¿Habrá sucedido algún evento especial en esa fecha?


Como ven el gráfico a escala nos permite iniciar nuestro análisis de manera más focalizada sin comenzar a dar tumbos a ciegas. De aquí en adelante nos tocará tomar otros pasos para continuar la investigación, pero te aseguro que si presentas en una reunión a tu jefe y/0 cliente un gráfico de este tipo, vas a lucir mucho más profesional que simplemente decir:

-"Tenemos muchas excepciones de NullPointer"