Nombre Temporal: Tutorial sobre Logback Parte I: Uso Básico y Niveles de Logs

http://logback.qos.ch/images/logos/lblogo.jpg

Introducción

Logback es una librería de registro de eventos (logging) desarrollada en Java por el mismo autor de la tradicional Log4J con el objetivo de ser su sucesora mediante un rediseño completo de su código y la aplicación de varias mejoras.

Como puede verse en el registro de Maven Central, Logback se encuentra bajo constante trabajo por lo que se puede considerar como un proyecto activo. Requiere como mínimo el JDK 1.6

Para demostrar algunas de sus características se usará como base el proyecto desarrollado en el post sobre "API REST usando Jersey y Jetty Embebido": https://github.com/guillermo-varela/jetty-jersey-example

Proyectos y Dependencias

Logback fue diseñado para ser una implementación de Simple Logging Facade for Java (SLF4J) con el fin de que pueda ser usado dentro o en conjunto con cualquier proyecto que use las interfaces de SLF4J en su código para referenciar las clases encargadas de registrar en logs, es por esto que para usar Logback se requiere slf4j-api.

Aunque se tienen varios proyectos dentro del grupo "ch.qos.logback", la funcionalidad básica de logging se obtiene mediante:

logback-core: Contiene las funcionalidades core de logging de Logback necesarias para los demás módulos.
logback-classic: Implementa las interfaces de SLf4J.

Al adicionar estas librerías al proyecto como dependencias Gradle se debe tener algo como lo siguiente:

gradle.properties

version=1.0.0-SNAPSHOT
 
jettyVersion=9.3.8.v20160314
jerseyVersion=2.22.2
logbackVersion=1.1.7
slf4jVersion=1.7.21
 
org.gradle.daemon=true

build.gradle

plugins {
  id 'net.researchgate.release' version '2.3.5'
}
 
apply plugin: 'java'
apply plugin: 'application'
 
sourceCompatibility = 1.8
targetCompatibility = 1.8
 
mainClassName = 'com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter'
 
jar {
    manifest {
        attributes 'Implementation-Title': 'Jetty, Jersey and Logback Example', 'Implementation-Version': version
        attributes 'Main-Class': mainClassName
    }
}
 
task wrapper(type: Wrapper) {
    gradleVersion = '2.13'
}
 
repositories {
    jcenter()
}
 
dependencies {
    compile "org.eclipse.jetty:jetty-server:$jettyVersion"
    compile "org.eclipse.jetty:jetty-servlet:$jettyVersion"
 
    compile "org.glassfish.jersey.core:jersey-server:$jerseyVersion"
    compile "org.glassfish.jersey.containers:jersey-container-servlet:$jerseyVersion"
    compile "org.glassfish.jersey.media:jersey-media-json-jackson:$jerseyVersion"
 
    compile "org.slf4j:slf4j-api:$slf4jVersion"
    compile "ch.qos.logback:logback-core:$logbackVersion"
    compile "ch.qos.logback:logback-classic:$logbackVersion"
}

En las líneas 5 y 6 de "gradle.properties" y 36-38 de "build.gradle" se indican las versiones de las librerías y se incluyen como dependencias del proyecto.

Ejemplo Básico de Logging

com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter

package com.blogspot.nombre_temp.jetty.jersey.logback.demo;
 
import org.eclipse.jetty.server.Server;
import org.eclipse.jetty.server.ServerConnector;
import org.eclipse.jetty.servlet.ServletContextHandler;
import org.eclipse.jetty.servlet.ServletHolder;
import org.eclipse.jetty.util.thread.QueuedThreadPool;
import org.glassfish.jersey.server.ServerProperties;
import org.glassfish.jersey.servlet.ServletContainer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
 
import com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.HealthResource;
 
public class DemoStarter {
 
    private static Logger logger = LoggerFactory.getLogger(DemoStarter.class);
 
    public static void main(String[] args) {
        System.out.println("Starting!");
        logger.trace("Starting!");
        logger.debug("Starting!");
        logger.info("Starting!");
        logger.warn("Starting!");
        logger.error("Starting!");
 
        ServletContextHandler contextHandler = new ServletContextHandler(ServletContextHandler.NO_SESSIONS);
        contextHandler.setContextPath("/");
 
        QueuedThreadPool queuedThreadPool = new QueuedThreadPool(10, 1);
        final Server jettyServer = new Server(queuedThreadPool);
 
        int acceptors = Runtime.getRuntime().availableProcessors();
 
        ServerConnector serverConnector = new ServerConnector(jettyServer, acceptors, -1);
        serverConnector.setPort(8080);
        serverConnector.setAcceptQueueSize(10);
 
        jettyServer.addConnector(serverConnector);
        jettyServer.setHandler(contextHandler);
 
        ServletHolder jerseyServlet = contextHandler.addServlet(ServletContainer.class, "/*");
        jerseyServlet.setInitOrder(0);
        jerseyServlet.setInitParameter(ServerProperties.PROVIDER_PACKAGES, HealthResource.class.getPackage().getName());
 
        try {
            jettyServer.start();
 
            Runtime.getRuntime().addShutdownHook(new Thread() {
                @Override
                public void run() {
                    try {
                        logger.info("Stopping!");
 
                        jettyServer.stop();
                        jettyServer.destroy();
                    } catch (Exception e) {
                        e.printStackTrace();
                    }
                }
            });
 
            jettyServer.join();
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

Línea 17: Se obtiene una referencia de un Logger asociado a la clase actual mediante LoggerFactory. También es posible obtener un Logger a partir de un nombre personalizado para el Logger, pero usar la clase de la clase en la que se encuentra es la forma más común. Cabe anotar que cada vez que se use "LoggerFactory.getLogger()" con el mismo nombre o clase como parámetro se obtendrá la misma instancia del Logger, por lo que no hay necesidad de preocuparse de llenar la memoria de instancias repetidas.

Línea 20: A manera de ejemplo se deja imprimiendo en consola el texto "Starting!".

Líneas 21-25: Para cada nivel de logging se tiene un método disponible en Logger, los cuales también están enviando el texto "Starting!". Se detallará el tema los niveles más adelante.

Por defecto Logback envía las entradas en logs a la consola (standard output) por lo que al ejecutar la aplicación se debe tener un resultado similar al siguiente:

Starting!
58:49.697 [main] DEBUG com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
58:49.735 [main] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
58:49.735 [main] WARN com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
58:49.735 [main] ERROR com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
58:49.825 [main] DEBUG org.eclipse.jetty.util.log - Logging to Logger[org.eclipse.jetty.util.log] via org.eclipse.jetty.util.log.Slf4jLog
58:49.917 [main] INFO org.eclipse.jetty.util.log - Logging initialized @1721ms
58:49.967 [main] DEBUG org.eclipse.jetty.util.DecoratedObjectFactory - Adding Decorator: org.eclipse.jetty.util.DeprecationWarning@53bd815b
58:50.008 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - o.e.j.s.ServletContextHandler@48cf768c{/,null,null} added {org.eclipse.jetty.servlet.ServletHandler@59f95c5d,MANAGED}
58:50.019 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - org.eclipse.jetty.server.Server@2aae9190 added {qtp125130493{STOPPED,1<=0<=10,i=0,q=0},AUTO}
58:50.149 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HttpConnectionFactory@3339ad8e[HTTP/1.1] added {HttpConfiguration@555590{32768/8192,8192/8192,https://:0,[]},POJO}
58:50.161 [main] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ServerConnector@3419866c{null,[]}{0.0.0.0:0} added {org.eclipse.jetty.server.Server@2aae9190,UNMANAGED}

Con este ejemplo se puede ver la ventaja de usar una librería de logging con respecto a usar simplemente "System.out". En la línea 1 se ve simplemente el texto "Starting!", mientras que entre las líneas 2 y 5 adicional a "Starting!" Logback ha adicionado:

Hora en que se presentó el evento enviado a logs.
Nombre del hilo que procesó la instrucción.
Nivel de log.
Nombre asignado al Logger, en este caso es el nombre completo de la clase.

Toda esta información quedó disponible sin tener que adicionarla manualmente en el código de la aplicación, lo cual no sólo deja el código más sencillo de leer mientras que en logs aparece información más completa que permita diagnosticar o hacer seguimiento de lo que hizo un usuario en la aplicación o de los errores generados.

Cabe anotar que los mensajes "Starting!" enviados a logs no apareció el que se reportó con el nivel "TRACE" (logger.trace()), esto se debe a que por defecto el nivel mínimo que se tendrá en cuenta para los logs es "DEBUG". Es posible tener por ejemplo que para ambientes de desarrollo o pruebas se envíen los mensajes desde "DEBUG" pero en producción tener sólo desde "INFO" sin modificar el código de la aplicación.

Desde la línea 6 en adelante empiezan a aparecer registros de logs generados por Jetty, los cuales no salían antes de agregar las librerías de logging. Esto se debe a que al momento de iniciar Jetty intenta buscar si SLf4J se encuentra presente, en cuyo caso usará este API para generar los logs.

Nótese también que en el código no se están usando clases de Logback, sólo se usa la interfaz Logger y la clase LoggerFactory, ambas de SLF4J; internamente esta librería tratará de encontrar una librería de logging que implemente sus interfaces en el classpath de la aplicación.

Niveles de Log

Logback, al igual que otras librerías de logging, permiten asignar un nivel de importancia a los eventos (logs) registrados. De esta manera se pueden clasificar los mensajes, determinar cuáles se deben ignorar según la configuración usada e inclusive en caso de usar escritura asíncrona determinar que mensajes descartar cuando la cola de mensajes para enviar se llena.

Los niveles en Logback se encuentran definidos como constantes de la clase Level y en orden de menor a mayor importancia se tienen:

TRACE: Mensajes de importancia mínima, usado generalmente sólo en ambientes de desarrollo.

DEBUG: Mensajes que son de utilidad sólo durante el desarrollo o las pruebas de una aplicación para verificar el comportamiento de la aplicación. Aunque la configuración por defecto tiene este nivel como el mínimo a usar, normalmente se deshabilita en ambientes de producción.

INFO: Mensajes que muestran las actividades de los usuarios y/o el progreso de una tarea dentro de la aplicación que se consideran normales (parte del flujo esperado). Dependiendo del tipo de aplicación la legislación de algunos países puede exigir el registro y almacenamiento de logs, en dichos casos se recomienda que los mensajes a almacenar estén en este nivel en adelante.

WARN: Como su nombre (en inglés) lo indica, en este nivel se deben asociar los mensajes que representen una advertencia, mas no un error.

ERROR: Es el nivel más alto disponible y corresponde a mensajes que señalan un error, bien sea cometido por el usuario o excepciones internas de la aplicación. Es recomendable incluir el objeto de la excepción generada (en caso de haberlo) junto con el mensaje del error, esto con el fin de que Logback incluya su traza en el log y se pueda determinar más fácilmente la causa del error, lo cual se explicará más adelante.

Adicionalmente se tienen los valores ALL y OFF, los cuales no son realmente niveles disponibles para los mensajes sino que se pueden configurar para indicar que se deben tener en cuenta todos los niveles de logs o descartar todos los mensajes respectivamente.

Registrar Eventos (Logs)

Para cada nivel de log se tienen varios métodos usando el mismo nombre del nivel en la interfaz Logger, como se pudo ver en el ejemplo de la clase "DemoStarter". Aunque estos métodos están sobrecargados (overloading) los más comúnmente usados son:

<nivel>(String mensaje): Registra un mensaje en el nivel indicado por el nombre del método.

<nivel>(String plantilla, Object... parámetros): El primer parámetro es una plantilla para el mensaje que se registrará mientras que el segundo contiene los valores que se incluirán usando vargars; los valores se incluyen en la plantilla usando llaves vacías "{}" como marcadores de posición (placeholders). Por ejemplo, si la plantilla es "User {} sent the value: {}" y los valores son "test" y "123", el mensaje registrado será "User test sent the value: 123".

La ventaja de usar el método con la plantilla en lugar de concatenar todo en una sola cadena manualmente, aparte de que el código queda más claro, es que Logback verifica si el mensaje con el nivel usado debe o no registrarse antes de procesar la plantilla con sus valores. De esta manera si por ejemplo se trata de un mensaje de nivel "DEBUG" pero este no se está teniendo en cuenta, al no concatenar ni procesar la plantilla se tiene un ahorro en rendimiento, ya que el procesamiento constante de cadenas puede impactar la aplicación en ese aspecto.

Ejemplo Práctico

Para tener un ejemplo un poco más cercano a un uso real de registro de logs, se incluirá un servicio que permite adicionar usuarios al sistema, validando que se envíen datos y que no sean repetidos.

build.gradle

plugins {
  id 'net.researchgate.release' version '2.3.5'
}
 
apply plugin: 'java'
apply plugin: 'application'
 
sourceCompatibility = 1.8
targetCompatibility = 1.8
 
mainClassName = 'com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter'
 
jar {
    manifest {
        attributes 'Implementation-Title': 'Jetty, Jersey and Logback Example', 'Implementation-Version': version
        attributes 'Main-Class': mainClassName
    }
}
 
task wrapper(type: Wrapper) {
    gradleVersion = '2.13'
}
 
repositories {
    jcenter()
}
 
dependencies {
    compile "org.eclipse.jetty:jetty-server:$jettyVersion"
    compile "org.eclipse.jetty:jetty-servlet:$jettyVersion"
 
    compile "org.glassfish.jersey.core:jersey-server:$jerseyVersion"
    compile "org.glassfish.jersey.containers:jersey-container-servlet:$jerseyVersion"
    compile "org.glassfish.jersey.media:jersey-media-json-jackson:$jerseyVersion"
 
    compile "org.slf4j:slf4j-api:$slf4jVersion"
    compile "ch.qos.logback:logback-core:$logbackVersion"
    compile "ch.qos.logback:logback-classic:$logbackVersion"
 
    compile "org.apache.commons:commons-lang3:3.4"
}

Línea 40: Se incluye la librería "Apache Commons" para usar un par de métodos que serán de utilidad para este ejemplo.

com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter

package com.blogspot.nombre_temp.jetty.jersey.logback.demo;
 
import org.apache.commons.lang3.builder.ReflectionToStringBuilder;
import org.apache.commons.lang3.builder.ToStringStyle;
import org.eclipse.jetty.server.Server;
import org.eclipse.jetty.server.ServerConnector;
import org.eclipse.jetty.servlet.ServletContextHandler;
import org.eclipse.jetty.servlet.ServletHolder;
import org.eclipse.jetty.util.thread.QueuedThreadPool;
import org.glassfish.jersey.server.ServerProperties;
import org.glassfish.jersey.servlet.ServletContainer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
 
import com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.HealthResource;
 
public class DemoStarter {
 
    private static Logger logger = LoggerFactory.getLogger(DemoStarter.class);
 
    public static void main(String[] args) {
        logger.info("Starting!");
        ReflectionToStringBuilder.setDefaultStyle(ToStringStyle.SHORT_PREFIX_STYLE);
 
        ServletContextHandler contextHandler = new ServletContextHandler(ServletContextHandler.NO_SESSIONS);
        contextHandler.setContextPath("/");
 
        QueuedThreadPool queuedThreadPool = new QueuedThreadPool(10, 1);
        final Server jettyServer = new Server(queuedThreadPool);
 
        int acceptors = Runtime.getRuntime().availableProcessors();
 
        ServerConnector serverConnector = new ServerConnector(jettyServer, acceptors, -1);
        serverConnector.setPort(8080);
        serverConnector.setAcceptQueueSize(10);
 
        jettyServer.addConnector(serverConnector);
        jettyServer.setHandler(contextHandler);
 
        ServletHolder jerseyServlet = contextHandler.addServlet(ServletContainer.class, "/*");
        jerseyServlet.setInitOrder(0);
        jerseyServlet.setInitParameter(ServerProperties.PROVIDER_PACKAGES, HealthResource.class.getPackage().getName());
 
        try {
            jettyServer.start();
 
            Runtime.getRuntime().addShutdownHook(new Thread() {
                @Override
                public void run() {
                    try {
                        logger.info("Stopping!");
 
                        jettyServer.stop();
                        jettyServer.destroy();
                    } catch (Exception e) {
                        logger.error("Error on shutdown", e);
                    }
                }
            });
 
            jettyServer.join();
        } catch (Exception e) {
            logger.error("Error starting", e);
        }
    }
}

Línea 23: Se usará la clase "ReflectionToStringBuilder" de la librería "Apache Commons" para los métodos "toString()" de las clases a usar en el ejemplo. Indicando que se usará "ToStringStyle.SHORT_PREFIX_STYLE" al iniciar la aplicación no será necesario volver a indicar este estilo al generar el valor del "toString()" correspondiente.

com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.DemoResponse

package com.blogspot.nombre_temp.jetty.jersey.logback.demo.model;
 
import java.util.Date;
 
import org.apache.commons.lang3.builder.ReflectionToStringBuilder;
 
public class DemoResponse {
 
    private Date date;
    private boolean error;
    private String message;
 
    public DemoResponse() {
        date = new Date();
    }
 
    public DemoResponse(boolean error) {
        this();
        this.error = error;
    }
 
    public Date getDate() {
        return date;
    }
 
    public void setDate(Date date) {
        this.date = date;
    }
 
    public boolean isError() {
        return error;
    }
 
    public void setError(boolean error) {
        this.error = error;
    }
 
    public String getMessage() {
        return message;
    }
 
    public void setMessage(String message) {
        this.message = message;
    }
 
    @Override
    public String toString() {
        return ReflectionToStringBuilder.toString(this);
    }
}

Esta clase representa la respuesta base que se dará en los servicios de la aplicación. En la implementación del método "toString()" se está usando la antes mencionada clase "ReflectionToStringBuilder" la cual tomará todos los atributos de la instancia e incluirá sus valores en la cadena retornada.

En este caso aunque "DemoResponse" sólo tiene 3 atributos y no sería mayor problema concatenar manualmente sus valores, pero se muestra el uso de "ReflectionToStringBuilder" que también puede ser de utilidad para clases de más atributos y no será necesario modificar el método "toString()" al adicionar, eliminar o modificar los atributos disponibles.

com.blogspot.nombre_temp.jetty.jersey.logback.demo.model.User

package com.blogspot.nombre_temp.jetty.jersey.logback.demo.model;
 
import org.apache.commons.lang3.builder.HashCodeBuilder;
import org.apache.commons.lang3.builder.ReflectionToStringBuilder;
 
public class User {
 
    private Integer id;
    private String name;
    private String password;
 
    public Integer getId() {
        return id;
    }
 
    public void setId(Integer id) {
        this.id = id;
    }
 
    public String getName() {
        return name;
    }
 
    public void setName(String name) {
        this.name = name;
    }
 
    public String getPassword() {
        return password;
    }
 
    public void setPassword(String password) {
        this.password = password;
    }
 
    @Override
    public int hashCode() {
        return new HashCodeBuilder().append(id).build();
    }
 
    @Override
    public boolean equals(Object object) {
        if (object instanceof User) {
            User other = (User) object;
            if (id == null) {
                if (other.getId() == null) {
                    return true;
                }
            } else if (id.equals(other.getId())) {
                return true;
            }
        }
        return false;
    }
 
    @Override
    public String toString() {
        return ReflectionToStringBuilder.toStringExclude(this, "password");
    }
}

Ahora se tiene una clase que represente los datos de los usuarios que se agregarán. Los métodos "equals()" y "hashCode()" están basados en el ID del usuario, mientras que en "toString()" se muestra como se pueden excluir atributos con datos sensibles que no deben incluirse en logs, en este caso "password".

com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource

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<User> USERS = new HashSet<User>();
 
    @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;
    }
}

Línea 19: Se define que la ruta (path) del nuevo servicio será "users".

Línea 24: Se obtiene una instancia de Logger para registrar los eventos en este servicio (resource).

Línea 26: Para mantener el ejemplo sencillo, los usuarios se almacenarán en un Set de la misma clase.

Línea 30: Se registra la recepción de un nuevo usuario en el nivel "INFO". Nótese que para registrar los datos del nuevo usuario no se está obteniendo atributo por atributo sino que se deja como parámetro la variable "user", de esta manera Java usará automáticamente el método "toString()" el cual ya fue definido previamente para precisamente retornar el valor de los atributos; esto permite tener un código un poco más limpio/claro al momento de usar logs.

Línea 34: En caso de enviar un POST sin cuerpo/contenido, la variable "user" será null, en cuyo caso "Validate.notNull()" lanzará una excepción con el mensaje indicado.

Línea 35: Para efectos de la demostración, se registra el ID del nuevo usuario con nivel "DEBUG".

Líneas 37-43: En caso de adicionar exitosamente el usuario se registra un mensaje de éxito, de lo contrario se envía un mensaje con nivel "WARN" y se indica esto en la respuesta a retornar.

Líneas 44-48: Si se genera una excepción (por ejemplo una llamada sin datos) se registra el error generado en logs y se da indicación de esto en la respuesta. En la invocación de "logger.error()" puede verse que sólo se tiene un placeholder en la plantilla del mensaje, pero dos parámetros luego de esta: la variable con los datos del usuario y la excepción generada. Logback se encargará automáticamente de incluir sólo los datos del usuario en el mensaje y luego dejar la traza de la excepción en logs.

Usando una herramienta que permita enviar peticiones HTTP Post (Postman en este caso) podrá verse el resultado en logs al enviarse una petición sin cuerpo:

17:11:01.411 [qtp963601816-17] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Creating user: null
17:11:01.421 [qtp963601816-17] ERROR com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Error creating the user: null
java.lang.NullPointerException: The user cannot be null
 at org.apache.commons.lang3.Validate.notNull(Validate.java:222)
 at com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource.create(UsersResource.java:34)
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
 at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
 at java.lang.reflect.Method.invoke(Method.java:483)
...

Figura 1 - Respuesta a petición sin cuerpo

En la primera línea del log puede verse que aparece el mensaje "Creating user: null", lo cual en un ambiente de producción puede indicar fue el usuario/cliente quien desde un principio no envió los datos necesarios.

Ya en la segunda línea aparece el mensaje con el error, seguido de la traza de la excepción generada como se comentaba anteriormente lo haría Logback por su cuenta.

Al enviar los datos completos de un nuevo usuario el resultado es el siguiente:

31:32.640 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Creating user: User[id=1,name=Test 1]
31:32.672 [qtp963601816-20] DEBUG com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Trying to add user with id: 1
31:32.672 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User created
31:32.672 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User processed with response: DemoResponse[date=Sun May 15 18:31:32 COT 2016,error=false,message=<null>]

Figura 2 - Petición y respuesta de un nuevo usuario

Puede verse que la secuencia de mensajes en logs es la esperada, inclusive la primera línea no está mostrando el valor del atributo "password" que se indicó se debía excluir en el método "toString()" de "User".

Cuando se intenta almacenar un usuario con un ID repetido se debe obtener lo siguiente:

53:50.441 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Creating user: User[id=1,name=Test 1]
53:50.441 [qtp963601816-20] DEBUG com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Trying to add user with id: 1
53:50.441 [qtp963601816-20] WARN com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User repeated
53:50.441 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User processed with response: DemoResponse[date=Sun May 15 18:53:50 COT 2016,error=true,message=User repeated]

Figura 3 - Petición y respuesta de un usuario repetido

En la línea 3 puede verse el registro de log esperado con el nivel "WARN" indicando que el usuario está repetido.

Conclusiones

En esta primera parte se ha querido dar simplemente una introducción al uso de Logback con su configuración por defecto y los niveles de logs disponibles para categorizar (o priorizar) los mensajes.

En un próximo post se mostrarán algunas de las opciones de configuración disponibles en Logback, por lo pronto el proyecto desarrollado hasta aquí se puede descargar desde: https://github.com/guillermo-varela/jetty-jersey-logback-demo/tree/part-i

Referencias

http://logback.qos.ch

http://logback.qos.ch/reasonsToSwitch.html
http://www.slf4j.org/manual.html
http://www.eclipse.org/jetty/documentation/current/configuring-logging.html

Nombre Temporal

lunes, 16 de mayo de 2016

Tutorial sobre Logback Parte I: Uso Básico y Niveles de Logs