Mostrando las entradas con la etiqueta Logback. Mostrar todas las entradas
Mostrando las entradas con la etiqueta Logback. Mostrar todas las entradas

sábado, 3 de marzo de 2018

Tutorial sobre Logback Parte II: Configuración, Formato y Colores

Introducción

En un post anterior se revisaron algunos temas básicos que permiten empezar a usar Logback en un proyecto Java. Ahora se mostrarán algunas opciones para configurar esta librería, según la necesidad.

Se continuará con el proyecto de dicho post anterior: https://github.com/guillermo-varela/jetty-jersey-logback-demo/tree/part-i

Configuración

Logback sigue la siguiente secuencia de verificaciones para realizar su configuración, hasta encontrar una que se cumpla:

  1. Si se tiene la propiedad del sistema "logback.configurationFile", su valor sería la ruta (URL, archivo externo o interno en la aplicación) en que se tiene un archivo XML o Groovy con la configuración, por ejemplo iniciar la aplicación con el parámetro "-Dlogback.configurationFile=/path/config.xml".
  2. Busca un archivo "logback.groovy" en el classpath.
  3. Busca un archivo "logback-test.xml" en el classpath.
  4. Busca un archivo "logback.xml" en el classpath.
  5. Intenta buscar una clase que tenga la configuración de Logback en código. Dicha clase debe implementar la interfaz Configurator y se indica su nombre completo (fully qualified class name) en el archivo "META-INF\services\ch.qos.logback.classic.spi.Configurator".
  6. Finalmente, si ninguna de las opciones anteriores fue posible, se usa la configuración por defecto que se realiza mediante la clase BasicConfigurator de Logback (enviando los logs a la consola).
La configuración usando archivos XML es la más común entre las opciones disponibles, aunque existe una herramienta en la página web de Logback que permite convertir una configuración XML a Groovy, la cual puede ser de utilidad cuando se requiere una configuración más dinámica.

Cuando se utiliza una herramienta como Maven o Gradle para construir y compilar el proyecto se pueden tener carpetas de recursos que se usen durante el desarrollo pero que no hagan parte del paquete final desplegado en producción. Con las dos herramientas mencionadas se tiene por defecto la carpeta "src/test/resources" en la cual se puede crear el archivo "logback-test.xml" con más detalles incluidos en logs que sean de utilidad, mientras que en "src/main/resources" el archivo "logback.xml" contiene sólo los detalles necesarios en producción.

Formato de Logs (Layout)

En Logback, un Layout es un componente que toma los datos de un evento registrado en logs y los convierte en una cadena (String).

Dado que hasta ahora no se ha adicionado ninguna configuración en el proyecto, al ejecutarlo se realiza la configuración por defecto, enviando los datos a la consola:

Figura 1 - Formato de logs por defecto

Los datos mostrados en esta configuración son:
  • Hora del evento, incluyendo milisegundos.
  • Nombre del hilo que ejecutó el evento.
  • Nivel del evento.
  • Nombre completo del Logger. Como se mencionó en el post anterior, la manera más común de obtener una instancia de Logger es usando la clase que registra el evento en logs (LoggerFactory.getLogger(UsersResource.class) por ejemplo), por esta razón no solamente los logs registrados directamente por el código de la aplicación, sino también los de Jetty aparecen con el nombre completo de las clases; sin embargo, si se usará cualquier otra cadena para obtener el Logger sería ese nombre el que aparezca.
  • Mensaje del evento.
Bien sea por preferencias personales, facilidad de visualización o necesidad de información diferente, Logback permite cambiar esta estructura de información en logs mediante el uso de una implementación de la interfaz Layout, de entre las cuales la más usada es PatternLayout.

PatternLayout permite indicar los datos del evento que se enviarán a logs, así como cualquier otro texto libre que se considere necesario. Logback permite representar los datos del evento mediante "Conversion Words", cada uno precedido del símbolo "%" y al procesar el evento serán reemplazados de manera similar a como lo hace la función "printf()" de varios lenguajes de programación. La lista completa de opciones disponibles se puede encontrar en la documentación de Logback.

Para este ejemplo la configuración se realizará mediante un archivo "logback.xml", inicialmente con lo siguiente:

src/main/resources/logback.xml
<configuration>

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

  <root level="ALL">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>
  • Etiqueta "configuration": Es la raíz del archivo XML de configuración.
  • Etiqueta "appender": Logback usa componentes Appender para escribir el contenido de los logs en diferentes tipos de destino, según la implementación usada. En este ejemplo se usará "ConsoleAppender", que es la misma usada en la configuración por defecto, y se le asigna el nombre "STDOUT" (abreviación de Standard Output), aunque puede ser cualquier otro nombre.
  • Etiqueta "encoder": Encoders son intermediarios que toman el contenido de un evento enviado a logs (String) y convertirlo a un arreglo de bytes para enviarlo mediante un OutputStream al Appender respectivo.
  • Etiqueta "pattern": Al usarla se está indicando que para el layout del contenido de los eventos se usará PatternLayout. En este ejemplo cada uno de los datos del evento (excepto el mensaje) se está encerrando entre corchetes ([ ]) sólo como ayuda visual, no es algo necesario.
    • %-5level: Con el Modificador de Formato "-5" se indica que este campo en la cadena del log tendrá como mínimo 5 caracteres dado que si el contenido es menor, la diferencia será rellenada con espacios a la derecha. En este caso se tiene como Conversion Word el valor "level" para que el log tenga el nivel en que fue registrado. Así por ejemplo se pueden tener valores como [DEBUG] o [INFO ], recordando el espacio al final si no tiene 5 caracteres, lo cual puede ser útil para que al ver los logs se tenga consistencia en su longitud.
    • %d{ISO8601}: "%d" corresponde a la fecha en que se registró el evento, mientras que "{ISO8601}" hace las veces de parámetro que indica el formato en que se mostrará dicha fecha, que en este caso será el estándar "ISO 8601".
    • %logger{36}: Muestra el nombre del Logger usado para registrar el evento, acortando su longitud para que no supere los 36 caracteres, esto con el fin de reducir el contenido del log a sólo lo realmente necesario, aclarando que este límite es opcional. En general los nombres de los Logger se jerarquizan con separación por puntos, siendo la parte más significativa el extremo derecho, así por ejemplo cuando se trata del nombre completo de una clase lo paquetes pueden acotarse a una sola letra para que el total no supere el límite indicado, pero el nombre de la clase (parte más significativa) no será acortado para evitar perder información importante. Así "com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter" puede pasar "c.b.n.j.j.logback.demo.DemoStarter".
    • -: Texto libre que simplemente separa los datos previos del evento del mensaje.
    • %msg%n: Muestra el contenido del mensaje (%msg) y a continuación adiciona un salto de línea (%n), de no hacer esto último todos los eventos se mostrarían en una sola línea de la consola o archivo.
  • Etiqueta "root": Como se mencionaba previamente, las instancias de Logger tienen una jerarquía y la instancia raíz o padre de todos es "root". En caso de no definir configuraciones específicas para otras instancias de Logger se usará la que se defina dentro de esta etiqueta. En la etiqueta como tal sólo se tiene el atributo "level" para indicar el nivel mínimo de eventos a tener en cuenta.
  • Etiqueta "appender-ref": Indica el nombre del Appender configurado que se usará para enviar los eventos. En este ejemplo sólo se tiene uno, pero se pueden tener varias de estas etiquetas para enviar los eventos a varios destinos de ser necesario.
Como pudo verse en los valores indicados en la etiqueta "pattern" cada "Conversion Word" por lo general tiene la siguiente estructura:


Al ejecutar nuevamente el proyecto, ahora con esta configuración se tiene:

Figura 2 - Logs en consola con nuevo formato

Información de Estado de Logback

Para ver el proceso de inicialización de Logback y ver por ejemplo cuál es el archivo de configuración que se usará para la aplicación se debe modificar la etiqueta "configuration" adicionando el atributo debug="true".

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

Así, al principio, en la salida estándar se debe tener un contenido similar al siguiente cuando se inicia la aplicación:
01:48:34,005 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
01:48:34,005 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
01:48:34,005 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/workspace/jetty-jersey-logback-demo/bin/logback.xml]
01:48:34,110 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
01:48:34,112 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
01:48:34,123 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
01:48:34,155 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to ALL
01:48:34,155 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
01:48:34,155 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
01:48:34,158 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@1bc6a36e - Registering current configuration as safe fallback point
...

Colores

Cuando se está trabajando con sistemas operativos basados en Unix (Mac y Linux por ejemplo), es posible adicionar colores al resultado de los logs registrados, tanto en Consola como en los archivos, usando Códigos de Escape ANSI.

Estos colores son visibles en herramientas texto que muestran el contenido directamente en Terminal (por ejemplo cat, tail y more), pero editores de texto propiamente como por ejemplo vim mostrarán el contenido en texto de los códigos de escape en lugar de los colores (aunque para el caso particular de vim existe el plugin AnsiEsc que permite interpretar dichos códigos)

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="ALL">
    <appender-ref ref="STDOUT" />
  </root>
</configuration>

  • %highlight([%-5level]): Los niveles de logs ya tienen asociados colores en Logback, por lo que la instrucción "highlight" simplemente hace que aparezcan.
  • %cyan([%logger{36}]): Hace que el nombre del Logger aparezca en color cian (cyan, azul claro). Cabe aclarar que se dispone de más colores y se pueden aplicar a otros campos del evento enviado a logs.

Para quienes usen Eclipse, deberán instalar el plugin "ANSI Escape in Console" para que los colores sean visibles en consola.
Figura 3 - Colores en logs

Nota: En sistemas Windows la consola de Eclipse funciona sin necesidad de dicha librería, sólo con el plugin antes mencionado, pero fuera de esta los colores sólo serán visibles usando Jansi, como lo indica la documentación de Logback.

Múltiples Archivos de Configuración

Cuando se tiene una aplicación muy grande, con muchos módulos o funcionalidades es posible que cada una de estas requiera su propia configuración de Logback y para evitar tener un solo archivo igualmente grande con todas las configuraciones, es posible tener un archivo para cada módulo/funcionalidad e importarlos en un archivo principal.

Este ejemplo es muy pequeño para dicha demostración, pero la documentación oficial de Logback ilustra muy bien esta opción: http://logback.qos.ch/manual/configuration.html#fileInclusion

Conclusión

Se ha logrado avanzar un poco en las posibilidades de configuración para extender un poco más la información que se tiene sobre los eventos en logs y personalizarla según se necesite.

En un próximo post se mostrará la configuración específica para las instancias de Logger. Por lo pronto el proyecto hasta este punto se puede descargar en: https://github.com/guillermo-varela/jetty-jersey-logback-demo/tree/part-ii

Referencias

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

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 1 comentario:
Etiquetas: , , , , , ,

lunes, 16 de mayo de 2016

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!
16:58:49.697 [main] DEBUG com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
16:58:49.735 [main] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
16:58:49.735 [main] WARN com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
16:58:49.735 [main] ERROR com.blogspot.nombre_temp.jetty.jersey.logback.demo.DemoStarter - Starting!
16: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
16:58:49.917 [main] INFO org.eclipse.jetty.util.log - Logging initialized @1721ms
16:58:49.967 [main] DEBUG org.eclipse.jetty.util.DecoratedObjectFactory - Adding Decorator: org.eclipse.jetty.util.DeprecationWarning@53bd815b
16: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}
16: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}
16: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}
16: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);
        }
    }
}

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:
18:31:32.640 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Creating user: User[id=1,name=Test 1]
18:31:32.672 [qtp963601816-20] DEBUG com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Trying to add user with id: 1
18:31:32.672 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User created
18: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:
18:53:50.441 [qtp963601816-20] INFO com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Creating user: User[id=1,name=Test 1]
18:53:50.441 [qtp963601816-20] DEBUG com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - Trying to add user with id: 1
18:53:50.441 [qtp963601816-20] WARN com.blogspot.nombre_temp.jetty.jersey.logback.demo.resource.UsersResource - User repeated
18: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

Publicadas por a la/s No hay comentarios.:
Etiquetas: , , , , , ,
Suscribirse a: Entradas (Atom)