Configurar los logs Spring 4.0 + slf4j + logback

Ahora vamos a configurar los logs de nuestro proyecto.

• Configuración del sistema de logs.
• Marcar las diferentes peticiones request que recibe el sistema para poder asociarlas.

Elección de la librería de logs

En java actualmente se usan dos librerias una que realiza de patron de fachada de los logs, que nos independiza de la implementación del sistema de logs y una segunda que se encarga de la gestión de logs.

• Primero seleccionaremos la librería que nos hará de fachada a la implementación. Actualmente hay dos librerias commons-loggins y slf4j.

Aquí la elección para mi es facil, slf4j, actualmente es algo mas eficiente, por otro lado nos da la posibilidad de evitar la concatenación en los logs, al pasar parámetros que esto mejora el performace y actualmente spring y otros frameworks la usan. Aparte tambien la forma que tiene de funcionar frente a la implementación, en este articulo lo esplica bastante bien (http://jayunit100.blogspot.com.es/2013/10/simplifying-distinction-between-sl4j.html).

• Segundo utilizaremos una de las implementaciones, log4j, logback, Jul.

Aquí la elección, la tengo bastante clara utilizo logback, frente a log4j,  la razon es que por un lado una implementación bastante estable (llevo usándola varios años y no he dado ningún problema)  y lo ha creado parte de la gente que participo en la creación de log4j. En el siguiente enlace la gente de logback te cuentan sus ventajas (http://logback.qos.ch/reasonsToSwitch.html)

Ademas a nivel de libreria, esta mas cuidada que log4j por ejemplo la clase logger es de tipo final para que nadie la puede rescribir, y complique las migraciones, ademas con herramientas como MDC, no es necesario rescribir la clase de logger.

En resumen usaremos slf4j + logback.

Ojo: Importante en nuestra aplicación usaremos solo los mecanismos que nos proporciona slf4j, para no acoplar la aplicación a la implementación.

 Configurar el sistema de logs.

Ahora vamos a ver como configurar el sistema de logs, en este caso vamos a trabajar con la implementación seleccionado, en nuestro caso hemos optado por logback.

Logback, nos proporciona dos mecanismos, de configuración:

• Un fichero xml. logback.xml
• Un fichero tipo grooby. logback.grooby

A continuación os adjunto la configuración de ejemplo par que los logs salgan en cosola /src/main/resources/logback.xml

<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>
  <root level="debug">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

Ejemplo de uso

Por una lado creamos el logger, usando una factorio y por norma general se le pasa la clase en la que se va a utilizar.

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
...
private static Logger logger = LoggerFactory.getLogger(InicioController.class);

Ahora vamos a ver como se utiliza el sistema de logger.

logger.info("Metodo {}","inicio");

Ejemplo de uso en un controlador de spring:

package org.dbp.controller;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.RequestMapping;

@Controller
@RequestMapping("inicio")
public class InicioController {

 private static Logger logger = LoggerFactory.getLogger(InicioController.class);
 
 @RequestMapping
 public String inicio(){
  logger.info("Metodo {}","inicio");
  return "inicio";
 }
 
}

Como marcar las peticiones.

Para poder seguir o asociar logs en un servidor web, es muy interesante marcar las peticiones del servidor con un número. De esta manera podemos saber todas las trazas que están asociadas a una única petición y ademas si en los errores asociados este número nos ayudara a buscar los detalles del error, en el logs de nuestra aplicación.

Para poder implementar esta historia utilizaremos 2 mecanimos, por una lado un interceptor de spring que sera en encargado de alimementar la marca que pondremos en todas las trazas de esa petición y por otro lado usaremos el MDC de slf4j, para guardar esa información (Tenemos que tener en cuenta que el MDC asocia las varibles al hilo de ejecución (utiliza en ThreadLocal).

A continuación os adjunto un diagrama explicando como funciona este mecanismo.

Creamos el interceptor que se va a encargar de esto:

Usaremos el interceptor, para crear la marca de tiempo y pasársela al sistema de logs, y cuando el controlador nos devuelva el control, el sistema se encarga de borrar la marca de tiempo. Para transmitir la información a slf4j usaremos el mecanismo MDC.

MDC, se apoya en una variable de tipo thearlocal, lo cual asocia los valores al hilo de ejecución, este implica que se puede reutilizar, por lo cual es recomendable una vez terminada el procesamiento de la request tenemos que eliminarlo. Es importante tener en cuenta ya que va condicionado por la JVM y el servidor web que utilicemos.

Guardaremos la marca de tiempo en la variable de MDC (MarcaTiempo)

package org.dbp.conf.interceptor;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

import org.slf4j.MDC;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;

public class LogInterceptor 
implements HandlerInterceptor{

 @Override
 public boolean preHandle(HttpServletRequest request,
   HttpServletResponse response, Object handler) throws Exception {
  MDC.put("MarcaTiempo", ""+System.currentTimeMillis());
  return true;
 }

 @Override
 public void postHandle(HttpServletRequest request,
   HttpServletResponse response, Object handler,
   ModelAndView modelAndView) throws Exception {
  MDC.remove("MarcaTiempo");
 }

 @Override
 public void afterCompletion(HttpServletRequest request,
   HttpServletResponse response, Object handler, Exception ex)
   throws Exception {
 }

}

Configurar logBack para utilizar la variable de MDC.

Ahora veremos como le indicamos a logBack, para que nos pinte la marca de tiempo. Simplemente
 tendremos que modificar el patrón de pintar la linea y para referencia a una variable del MDC, utilizaremos la siguiente sintaxis: %X{<nombre de la variable>}

<configuration>
  <appender class="ch.qos.logback.core.ConsoleAppender" name="STDOUT">
    <encoder>
      <pattern>%d{HH:mm:ss.SSS} [%thread] [%X{MarcaTiempo}] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
  </appender>
  <root level="debug">
    <appender-ref ref="STDOUT">
  </appender-ref></root>
</configuration>

Configurar un aspecto, para el log de los métodos

Vamos a configurar un aspecto, para tener una herramienta que nos permite hacer log de los métodos que se utilizan.

Configurar las librerias:

Lo primero que vamos hacer es añadir al proyecto la libreia de aspectJ.

 compile 'org.aspectj:aspectjrt:1.8.5'
 compile 'org.aspectj:aspectjweaver:1.8.5'

Crear el aspecto en spring.

Vamos a definir como va a trabajar el aspecto, por lo cual tenemos que definir el mecanismo para que se lance, en este caso tenemos varias alternativas:

• Marcar el lanzamiento por una anotación.
• Establecer un conjunto de paquetes o métodos genericos.

En mi caso voy a utilizar la anotación para que el lanzamiento del aspecto sea declarativo, pero si quisieramos que se traquearan todas las invocaciones de los métodos optariamos por la segunda configuración.

Cómo hemos elegido usar una anotación, empezaremos por definir la anotación.

package org.dbp.conf.aop.log;

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Retention(RetentionPolicy.RUNTIME)
@Target({ ElementType.METHOD, ElementType.TYPE })
public @interface DbpLog {

}

Ahora vamos a definir el aspecto:

• Antes de llamar al método si  tiene la anotación @DbpLog pintamos un log de debug.
• Despues de llamar al método si es un return y tiene la anotación @DbpLog pintar el valor devuelto.
• Despues de llamar al método y tiene la anotación @DbpLog trakeamos el valor devuelto.
• En caso de lanzar una excepción, mostramos los valores de entrada, el método y la excepción.

ackage org.dbp.conf.aop.log;

import java.util.Arrays;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
/**
 * 
 * Configuración de los los aspecto para el sistema de logs.
 * 
 *  - Por un lado logeamos los métodos que esten anotados por @DpbLog.
 *  - Y Siempre que tengamos una excepción, este o no anotado en los siguientes paquetes: org.dbp.controller
 * 
 * @author david
 *
 */
@Aspect
public class LogAspect {

 private static Logger logger=LoggerFactory.getLogger(LogAspect.class);
 /**
  * 
  * Antes de ejecutar el método.
  * 
  * @param joinPoint Es el punto de union.
  */
 @Before("execution(* *(..)) && @annotation(org.dbp.conf.aop.log.DbpLog)")
 public void antes(final JoinPoint joinPoint){
  logger.debug(" Antes: [{}] argumentos [{}]"
    ,joinPoint.getSignature().toString()
    ,Arrays.toString(joinPoint.getArgs()));
 }
 /**
  * 
  * Despues de ejecutar un método que tiene return.
  * 
  * @param joinPoint Es el punto de union.
  * @param valdev El valor devuelto por el método.
  */
 @AfterReturning(
   pointcut="execution(* *(..)) && @annotation(org.dbp.conf.aop.log.DbpLog)"
   ,returning="valdev"
   )
 public void despuesReturn(final JoinPoint joinPoint,Object valdev){
  logger.debug(" [{}] valdev: [{}]"
     ,joinPoint.getSignature().toString()
     ,valdev);
 }
 /**
  * 
  * Despues de ejecutar un metodo que tiene void.
  * 
  * Nota: Se ejecutara si procede, despuest de la traza de debug.
  * 
  * @param joinPoint Es el punto de union.
  * 
  */
 @After("execution(* *(..)) && @annotation(org.dbp.conf.aop.log.DbpLog)")
 public void despues(final JoinPoint joinPoint){
  logger.debug(" Despues: [{}] argumentos [{}]"
    ,joinPoint.getSignature().toString()
    ,Arrays.toString(joinPoint.getArgs()));
 }
 /**
  * 
  * Se ejecutara siempre que tengamos una exceptión, para el paquete controller.
  * 
  * @param joinPoint Es el punto de union.
  * @param ex  La excpeción que se ha ejecutado.
  */
 @AfterThrowing(
   pointcut="execution(* org.dbp.controller.*.*(..))  "
   ,throwing="ex"
   )
 public void despuesExcepcion(final JoinPoint joinPoint,final Throwable ex){
  logger.warn(" [{}] argumentos [{}] "
    ,joinPoint.getSignature().toString()
    ,Arrays.toString(joinPoint.getArgs()));
  logger.error(" Error [{}] "
    ,joinPoint.getSignature().toString()
    ,ex);
 }
 
}

Ejemplo de uso de los logs:

En nuestro ejemplo lo vamos a ver en el controlador:

• Vamos anotar un método y poner un log.
• El otro lanza una excepción.

package org.dbp.controller;

import javax.servlet.http.HttpServletRequest;

import org.dbp.conf.aop.log.DbpLog;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.PathVariable;
import org.springframework.web.bind.annotation.RequestMapping;

@Controller
@RequestMapping("inicio")
public class InicioController {

 private static Logger logger = LoggerFactory.getLogger(InicioController.class);
 @DbpLog
 @RequestMapping
 public String inicio(){
  logger.info("Metodo {}","inicio");
  return "inicio";
 }
 

 
 @RequestMapping("excepcion/{param}")
 public String excepcion(HttpServletRequest  request,@PathVariable(value="param") String param) throws Exception{
  throw new Exception("Error de prueba");
 }
 
}

La invocación del primer método nos devolverá la siguiente traza.

La invocación del segundo método nos devolverá la siguiente traza.

Como podemos ver toda la traza de la petición request, esta asociada con un solo número lo cual nos indica todas las trazas que se han ejecutado en la misma petición.