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][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