miércoles, 1 de junio de 2016

Tutorial sobre Logback Parte III: Loggers

Introducción

En post anteriores se revisado la librería Logback para registrar eventos (logs) en proyecto Java así como algunas de sus opciones de configuración.

Ahora se explicará un poco mejor el funcionamiento de los Loggers y su configuración.

Interfaz Logger

Ya se había indicado en previos posts que el registro de los eventos se realiza mediante instancias de implementaciones la interfaz de SLF4J Logger, las cuales se pueden obtener mediante la clase LoggerFactory (encargada de encontrar la implementación de Logback), también de SLF4J, mediante sus métodos:

static Logger getLogger(String name)
static Logger getLogger(Class clazz)

El primer método obtiene un Logger basado directamente en el nombre indicado como parámetro. Dicho nombre se busca en la configuración de Logback (bien sea XML, Groovy o código Java) y en caso de no encontrarse, la instancia obtenida tendrá la misma configuración que el Logger root.

El segundo método a su vez usa el nombre completo de la clase (fully qualified class name) que se tiene como parámetro como el nombre del Logger y la instancia se obtiene de la misma manera que el primero. Lo más común es que la clase indicada sea la misma desde la cual se registra el evento.

Ambos métodos retornan siempre la misma instancia para un nombre de Logger indicado y se pueden usar de manera segura en aplicaciones de múltiples hilos (thread safe). Esta última característica es la que permite que se puedan tener Loggers como variables (o constantes) estáticas, en lugar de crear una nueva variable para cada instancia o método que registra el evento.

src/main/java/com/blogspot/nombre_temp/jetty/jersey/logback/demo/resource/UsersResource.java
package com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource;

import java.util.HashSet;
import java.util.Set;

import javax.ws.rs.Consumes;
import javax.ws.rs.POST;
import javax.ws.rs.Path;
import javax.ws.rs.Produces;
import javax.ws.rs.core.MediaType;

import org.apache.commons.lang3.Validate;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.DemoResponse;
import com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.User;

@Path("/users")
@Consumes(MediaType.APPLICATION_JSON)
@Produces(MediaType.APPLICATION_JSON)
public class UsersResource {

    private static Logger logger = LoggerFactory.getLogger(UsersResource.class);

    private static final Set USERS = new HashSet();

    @POST
    public DemoResponse create(User user) {
        logger.info("Creating user: {}", user);
        DemoResponse response = new DemoResponse();

        try {
            Validate.notNull(user, "The user cannot be null");
            logger.debug("Trying to add user with id: {}", user.getId());

            if (USERS.add(user)) {
                logger.info("User created");
            } else {
                logger.warn("User repeated");
                response.setError(true);
                response.setMessage("User repeated");
            }
        } catch (Exception e) {
            logger.error("Error creating the user: {}", user, e);
            response.setError(true);
            response.setMessage(e.getMessage());
        }

        logger.info("User processed with response: {}", response);
        return response;
    }
}

En este ejemplo puede verse que sólo se está obtenido una instancia de Logger y se asigna como constante privada de la clase "UsersResource" y se usa varias veces en el método "create" registrando eventos en los diferentes niveles de log disponibles.

En aquel primer post también se mencionaban los métodos que expone Logger para registrar eventos en cada nivel y su funcionamiento usando vargars como parámetros para construir la cadena a enviar a logs.

Configuración de Loggers

Al ejecutar la aplicación los logs en consola tienen eventos no sólo del código de la aplicación, sino también de Jetty en modo DEBUG, lo cual hace que sea muy difícil de leer.

Figura 1 - Logs de la aplicación y las librerías

Lo que se hará ahora es configurar Logback para que sólo los eventos de la aplicación aparezcan desde el nivel DEBUG, pero los de Jetty desde INFO.

src/main/resources/logback.xml
<configuration debug="true">

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%highlight([%-5level]) [%d{ISO8601}] %cyan([%logger{36}]) - %msg%n</pattern>
    </encoder>
  </appender>

  <logger name="org.eclipse.jetty" level="INFO">
  </logger>

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

Figura 2 - Logs de la aplicación con eventos de Jetty en INFO

Al ejecutar la aplicación con esta configuración puede verse que ya aparecen menos eventos de Jetty en la consola, sólo los que tienen nivel INFO, lo cual permite ver de una manera mucho más clara los logs que de verdad son de interés.

Jerarquía de Loggers

En uno de los eventos de Jetty aparece que el nombre del Logger que registró en logs es "org.eclipse.jetty.util.log", pero en el archivo "logback.xml" en la etiqueta "logger" sólo se indicó el nombre "org.eclipse.jetty". Igualmente se tienen otros logs de Jetty con diferentes nombres de Logger en la consola y otros que ya no aparecen, es decir también se vieron afectados por la restricción del nivel (atributo "level").

Esto se debe a que la configuración de los Logger se realiza de manera jerárquica, en donde el Logger "padre" de todos los demás es "root". Cada Logger adicional se jerarquiza basado en su nombre y usando puntos como separador, así un Logger de nombre "org.eclipse.jetty" es "padre" de "org.eclipse.jetty.util.log" por lo que este último hereda la configuración definida en "logback.xml" para su Logger "padre" (en este caso el límite del nivel de logs a INFO).

De la misma manera el Logger "org.eclipse.jetty" (y todos sus "hijos") hereda la configuración del Logger "root" por lo cual los eventos registrados van a la consola.

Loggers para Pruebas y Producción

Normalmente en ambientes de producción sólo se requieren los logs hasta el nivel INFO, mientras que en ambientes de desarrollo o pruebas sí se muestran los niveles DEBUG o TRACE.

En el post anterior se explicaba que es posible tener un archivo "logback-test.xml" con la configuración necesaria para pruebas y "logback.xml" para producción.

src/test/resources/logback-test.xml
<configuration debug="true">

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%highlight([%-5level]) [%d{ISO8601}] %cyan([%logger{36}]) - %msg%n</pattern>
    </encoder>
  </appender>

  <logger name="org.eclipse.jetty" level="INFO">
  </logger>

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

src/main/resources/logback.xml
<configuration debug="true">

  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%highlight([%-5level]) [%d{ISO8601}] %cyan([%logger{36}]) - %msg%n</pattern>
    </encoder>
  </appender>

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

Teniendo claro el funcionamiento de las jerarquías en los Loggers puede verse que en "logback-test.xml" se define el Logger "root" para que incluya todos los niveles y en el caso de Jetty (así como cualquier otra librería que genere demasiados logs) de tiene un Logger aparte con nivel INFO, mientras que en "logback.xml" dado que sólo tiene un Appender sólo es necesario definir el Logger "root" con el nivel INFO.

Conclusión

Configurar y usar los Loggers mediante SLF4J y Logback es bastante fácil, una vez se entiende el concepto de la herencia o jerarquías entre los Loggers, ya que al tener la posibilidad de compartir configuraciones se evita la duplicación de las configuraciones.

Adicionalmente, dado que en el código se están usando las clases e interfaces de SLF4J se facilita el que en un futuro se cambie la implementación de las clases de Logging (bien sea para usar una librería diferente de Logback o simplemente cambiar su versión), sin necesidad de cambiar el código de la aplicación, sólo la configuración en caso de ser necesario.

En un próximo post se mostrarán algunos Appenders adicionales que tiene Logback, para enviar los eventos registrados a destinos diferentes de la consola. Por lo pronto el proyecto hasta este punto se puede descargar desde: https://github.com/guillermo-varela/jetty-jersey-logback-demo/tree/part-iii

Referencias

Publicadas por a la/s
Etiquetas: , , , , , ,

1 comentario:

Suscribirse a: Comentarios de la entrada (Atom)