Logging en Spring

Hasta ahora hemos estado escribiendo mensajes en consola usando System.out.print*. Sin embargo para conocer el estado de una aplicación no siempre quieren sacarse todos los mensajes por consola. Se puede necesitar aplicar un filtro o realizar otras operaciones como:

• Guardar en un fichero log en disco
• Enviar un mensaje de correo
• Hacer una llamada a un servicio web
• Derivar a una cola de mensajes
• Activar una sirena
• Cualquier cosa mas que se te ocurra

Parece necesario un sistema que permita tomar distintas respuestas cuando se produce un mensaje. La idea de logging es disponer de un registro de mensajes organizados que puedan ser tratados en función de varios factores:

• Gravedad del evento (Level)
• Momento en que se produce (Date Time)
• Componente origen del mensaje (Class del log)
• En qué entorno se ejecute la aplicación (desarrollo, pruebas, producción...)
• Mensaje que incluya
• Otros

De aquí detectamos que sería bueno organizar esos mensajes conteniendo esa información y poder conocer el estado de un sistema en un determinado momento. Existen muchas librerías al respecto:

• slf4j proporciona una interface única para varias implementaciones, lo que lo convierte en algo muy conveniente si se quiere cambiar la implementación en un futuro
• La implementación nativa de java: java.util.logging
• La del famoso log4j de apache
• logback que la usa por defecto Spring Boot con slf4j
• Y muchas otras más

Spring Boot ya dijimos que toma por defecto un conjunto de librerías por defecto en varios subsistemas de la aplicación. En el caso del logging Spring Boot utiliza por defecto slf4j con la implementación logback.

En esta entrada vamos a ver cómo personalizar el formato del log, trabajar con niveles y todo usando nuestras propiedades. Primero vamos a cambiar nuestra clase Test para que deje de usar System.out.println y use su log:

public class Test {
    private final Logger log = LoggerFactory.getLogger(Test.class);

    ...

    public void init() {
        log.info("Llamado init(): {}", testString);
    }
}

Si ejecutamos vemos que nuestro mensaje aparece igual de formateado que el resto de logs producidos por los otros componentes que usa Spring. Cuando queremos registrar un evento con nuestro logger disponemos de distintos niveles para marcar nuestro mensaje (en el ejemplo de arriba hemos usado el nivel INFO). El orden de prioridad de mayor a menor en slf4j es:

1. ERROR
2. WARN
3. INFO
4. DEBUG
5. TRACE

NOTA: Estos niveles dependen de cada librería, no están unificados (ejemplo log4j)

Configurando el log

Ahora vamos a configurar cómo tratar el log con varias propiedades:
Niveles:

• Se puede poner un nivel base para todos los logs (por defecto es INFO):
  

  logging.level.root=WARN

• O especificar el nivel para un dominio concreto (por ejemplo para que los logs propios de nuestra aplicación tengan más detalle):
  

  logging.level.es.lanyu=DEBUG

Formato:

• De fecha/hora: el formato de hora es muy fácil de cambiar como en este ejemplo (eliminamos los segundos):
  

  logging.pattern.dateformat=yyyy-MM-dd HH:mm

• Del mensaje: se puede modificar el formato completo del mensaje con su propiedad. Puede ser distinto el formato de la consola y el archivo. En este ejemplo se cambia el patrón de logback para formatear la consola utilizando otra propiedad que nos hemos creado para dar el formato de la fecha/hora:
  

  lanyu.formatofecha=%date{ddMMM HH:mm:ss, UTC}Z
  logging.pattern.console=${lanyu.formatofecha} [%thread %clr(${PID:- })] %-5level %logger{15} => %msg %n

• Color: que se puede aplicar a los elementos, quedando el formato anterior más enriquecido (necesita una consola que admita color):
  

  logging.pattern.console=${lanyu.formatofecha} [%thread %clr(${PID:- })] %highlight(%-5level) %cyan(%logger{15}) => %msg %n

Destino:

• Se pueden volcar los logs a un fichero o directorio especificándose la ruta por propiedades. Busca el archivo con la ruta del siguiente código para verlo (fíjate que el formato es otro al de consola):
  

  logging.file.name=datosdeportivos.log

• Al final de todo se trata de manejar (usando algo parecido al Handler nativo de Java) los registros del log que cumplan las condiciones que deben desencadenar una acción. Éste sería un ejemplo con logback para enviar un email con unos registros seleccionados. En Internet se pueden encontrar ejemplos con los pasos a seguir para crear nuestra propia implementación y seguir usando la API de SLF4J.

Ejecutando la aplicación en cada paso se puede ver cómo cambia el formato de todo el log con una sola línea en el fichero de propiedades.

Puedes encontrar el código hasta aquí en su repositorio y ver el vídeo del webinar:

En la siguiente entrada empezaremos a inyectar beans con la anotación @Autowired.