Curso Jakarta EE 9 (4). Logging en WildFly.

logo Jakarta EE

Hemos comprobado que la bitácora (logs) de WildFly se muestra en la salida estándar y en un fichero. El uso del sistema de logging del servidor y, por extensión, en nuestro código, es fundamental en la detección y corrección de problemas. Se utiliza para registrar mensajes que contienen trazas de errores e información de cierta relevancia gracias a los que podemos conocer qué está haciendo nuestra aplicación en cada momento. Sin estos mensajes, iremos a ciegas cuando tengamos que comprobar su funcionamiento.

>>>> ÍNDICE <<<<

Y, por favor, que a nadie se le ocurra escribir directamente en la salida estándar de la jvm con System.out o Systen.err, pues los sistemas de logs tienen características avanzadas para administrarlos con una gran flexibilidad. Lo comprobaremos en este capítulo.

Configuración

En standalone.xml, el fichero de configuración general de WildFly, encontramos la configuración del subsistema de logging.

 <subsystem xmlns="urn:jboss:domain:logging:8.0">
      <console-handler name="CONSOLE">
          <level name="INFO"/>
          <formatter>
              <named-formatter name="COLOR-PATTERN"/>
          </formatter>
      </console-handler>
      <periodic-rotating-file-handler name="FILE" autoflush="true">
          <formatter>
              <named-formatter name="PATTERN"/>
          </formatter>
          <file relative-to="jboss.server.log.dir" path="server.log"/>
          <suffix value=".yyyy-MM-dd"/>
          <append value="true"/>
      </periodic-rotating-file-handler>
      <logger category="com.arjuna">
          <level name="WARN"/>
      </logger>
      <logger category="io.jaegertracing.Configuration">
          <level name="WARN"/>
      </logger>
      <logger category="org.jboss.as.config">
          <level name="DEBUG"/>
      </logger>
      <logger category="sun.rmi">
         <level name="WARN"/>
      </logger>
      <root-logger>
          <level name="INFO"/>
          <handlers>
              <handler name="CONSOLE"/>
              <handler name="FILE"/>
          </handlers>
      </root-logger>
      <formatter name="PATTERN">
          <pattern-formatter pattern="%d{yyyy-MM-dd HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>
      </formatter>
      <formatter name="COLOR-PATTERN">
          <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%e%n"/>
      </formatter>
 </subsystem>

Contamos de forma predeterminada con dos handlers o gestores, pero hay muchos más. El primero de ellos, console-handler, escribe los mensajes en la salida estándar. El segundo (periodic-rotating-file-handler) hace lo propio en un fichero que se va creando para cada día, conservándose los antiguos.

Los mensajes a mostrar se formatean según la expresión PATTERN e incluyen la fecha exacta con una precisión de milisegundos, además del nombre de la clase desde la que se ha enviado el mensaje. Las opciones están descritas en este documento. Es posible configurar un patrón específico para un handler en concreto.

2021-06-12 17:27:13,324 INFO  [org.jboss.modules] (main) JBoss Modules version 1.11.0.Final
2021-06-12 17:27:13,855 INFO  [org.jboss.msc] (main) JBoss MSC version 1.4.12.Final
2021-06-12 17:27:13,863 INFO  [org.jboss.threads] (main) JBoss Threads version 2.4.0.Final
2021-06-12 17:27:13,995 INFO  [org.jboss.as] (MSC service thread 1-2) WFLYSRV0049: WildFly Preview 22.0.0.Final (WildFly Core 14.0.0.Final) starting
2021-06-12 17:27:14,001 DEBUG [org.jboss.as.config] (MSC service thread 1-2) Configured system properties:

Estos mensajes siempre se filtran según su nivel de detalle o importancia, siendo los más habituales, ordenados de menor a mayor importancia, DEBUG, INFO, WARN y ERROR. Pasan el filtro aquellos que tengan el nivel indicado o uno más relevante. Por ejemplo, con INFO se mostrarán los mensajes de tipo INFO, WARN y ERROR.

El nivel predeterminado para todo el sistema (servidor y aplicaciones desplegadas) se establece en el bloque root-logger y se afina mediante categorías para paquetes Java concretos. Téngase en cuenta que un handler nunca muestra mensajes con un nivel inferior al indicado en su definición (línea 3) Así, vemos (línea 22) que para los mensajes cuyo origen sean las clases de los paquetes situados bajo org.jboss.as.config se ha establecido el nivel DEBUG, algo que podemos comprobar en la traza anterior. La categoría se aplica a los handlers que se indiquen. Si no se especifican, se usan los del root-logger (línea 28).

Con este fragmento, estamos enviando a FILE los mensajes con un nivel DEBUG o superior provenientes de las clases en com.danielme.jakartaee.

<logger category="com.danielme.jakartaee">
   <level name="DEBUG"/>
   <handlers>
       <handler name="FILE"/>
   </handlers>
</logger>

La API SLF4J

La cuestión es: ¿cómo enviamos datos a la bitácora de WildFly desde, por ejemplo, la aplicación hello? Con carácter general, en Java la mejor opción es recurrir a SLF4J, una capa de abstracción que permite usar con una sola API varios sistemas de logging mediante unas librerías adaptadoras que traducen las llamadas a esta API a las de cada sistema concreto. Con ella ganamos comodidad (siempre usamos la misma API) y portabilidad.

La existencia SLF4J es consecuencia de lo repartido que está el mercado entre varios productos. Destacan Log4j, Logback (habitual en Spring) y JUL, el ofrecido por Java en java.util.logging. Todos ellos cuentan con adaptadores.

WildFly, que usa JUL, ya está integrado con SLF4J y no hay que configurar nada. Es suficiente con añadir su dependencia a nuestros proyectos.

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.30</version>
    <scope>provided</scope>
 </dependency>

El módulo slf4j-api se encuentra en WildFly, así que lo importamos como provided. La versión 1.7.30 es la que incluye WildFly 22, pero a medida que vayamos actualizando el servidor tendremos que estar atento para cambiarla. Esta tarea resulta más sencilla si en lugar de hacerlo a mano recurrimos al bom de WildFly, un pom especial en el que se declaran las librerías que incluye el servidor para cada versión del mismo.

<dependencyManagement>
      <dependencies>
          <dependency>
              <groupId>org.wildfly.bom</groupId>
              <artifactId>wildfly-jakartaee8-with-tools</artifactId>
              <scope>import</scope>
              <type>pom</type>
              <version>22.0.0.Final</version>
          </dependency>
      </dependencies>
 </dependencyManagement>

<dependencies>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <scope>provided</scope>
        </dependency>

Ahora, la versión de slf4j-api es la establecida en el bom. Ya no tenemos que averiguar y revisar la versión empaquetada en el servidor, simplemente nos aseguramos de importar el bom adecuado. Seguiremos esta estrategia con todas las librerías de WildFly que necesitemos.

De momento, tal y como se aprecia en el ejemplo, no está todavía disponible el bom para las versiones Preview de WildFly que son las compatibles con Jakarta EE 9. No supone un gran problema porque la aplicación cuando se despliegue y ejecute usará las librerías del servidor, pero sí podemos encontrar algunas dificultades con ciertas dependencias causadas por el cambio del nombre de los paquetes de javax a jakarta. Nos pasará más adelante con la configuración de Hibernate.

Con las dependencias en el proyecto, escribamos un mensaje.

package com.danielme.jakartaee.hello;

import jakarta.servlet.ServletException;
import jakarta.servlet.annotation.WebServlet;
import jakarta.servlet.http.HttpServlet;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.io.IOException;
import java.io.PrintWriter;

@WebServlet("/helloServlet")
public class HelloServlet extends HttpServlet {

    private static final Logger log =
            LoggerFactory.getLogger(HelloServlet.class);

    private static final String HELLO_MESSAGE = "Jakarta EE rocks!!";

    @Override
    protected void doGet(HttpServletRequest request, HttpServletResponse response)
            throws ServletException, IOException {
        PrintWriter printWriter = response.getWriter();
        response.setContentType("text/plain;charset=UTF-8");
        log.debug("returning the message {}", HELLO_MESSAGE);
        printWriter.print(HELLO_MESSAGE);
    }

}

Creamos una instancia estática de org.slf4j.Logger específica para la clase. Si disponemos de Lombok, contamos con la anotación @Slf4j.

Registrar mensajes en el log es tan sencillo como invocar a sus numerosos métodos en función del propósito que queremos para el mensaje.

  • debug. Mensajes de mayor detalle que info destinados a depurar la aplicación. Lo habitual es que solo se muestren cuando queremos comprobar algo en concreto y\o estamos intentando “cazar” las posibles causas de un error. En condiciones normales, no queremos ver tanta información; si se muestran muchos mensajes, el rendimiento de la aplicación se verá afectado.
  • info. El nivel predeterminado en la configuración de WildFly. Son mensajes informativos de cierta importancia que indican, grosso modo, que la aplicación funciona correctamente. Un buen ejemplo son los mensajes mostrados por WildFly durante el arranque.
  • warn. Es una alerta que indica que la aplicación no está funcionando todo lo bien que debería por un problema que no es lo suficientemente grave como para considerarlo un error. Un ejemplo típico son las excepciones que están bien controladas y no abortan la ejecución normal de un caso de uso, pero que han de tenerse en cuenta. Como regla general, recomiendo que todos los bloques catch registren la excepción, aunque sea en DEBUG si no son importantes.
  • error. Se trata de un error que impide el correcto funcionamiento de la aplicación, y suele ser una excepción. Cuando registremos el mensaje, el cual debería darnos una pista sobre la causa del error, también incluiremos la excepción.
 catch (BussinessException ex) {
     log.error("cannot create the user " + user, ex);
  }

¿Y las excepciones que no se capturen y “escapen” de nuestra aplicación? No se perderán y veremos toda la traza en la bitácora.

Antes de continuar, una recomendación: evitemos mostrar información delicada como contraseñas o datos personales de usuarios reales.

Volvamos a HelloServlet. El método doGet registra la respuesta que devuelve. En vez de crear el mensaje concatenando cadenas, he usado una versión del método debug que permite utilizar placeholders ({}) y reemplazarlos con una lista de parámetros. Con la configuración predeterminada, no lo veremos a menos que activemos el nivel DEBUG, así que creamos la siguiente categoría para que aparezca en todos los handlers de root-logger. Esto es mejor que poner root-logger en DEBUG porque inundaría los handlers con miles de trazas, lentificando el servidor.

<logger category="com.danielme.jakartaee.hello">
   <level name="DEBUG"/>   
</logger>

Sin embargo, el mensaje solo aparecerá en el handler FILE porque CONSOLE, recordemos, tiene declarado de forma explícita el nivel INFO.

<console-handler name="CONSOLE">
       <level name="INFO"/>

Si cambiamos esto, veremos en CONSOLE el mensaje cada vez que se llame al servlet. La siguiente captura pertenece a IntelliJ y resulta curiosa: los mensajes de DEBUG salen en verde porque así se ha configurado COLOR-PATTERN y la vista Output del IDE soporta coloreado ANSI.

Cambios en caliente

Modificar el fichero standalone.xml exige reiniciar el servidor para que se apliquen los cambios. Un contratiempo importante si está en ejecución y hay otras personas usando sus aplicaciones, o bien estas tardan minutos en arrancar e iniciar sus componentes.

Con CLI se pueden realizar en caliente muchas configuraciones, y entre ellas se incluyen las relativas al registro de la bitácora. Recordemos que CLI es la interfaz de línea de comandos de WildFly y que consiste en un script .bat o .sh situado en la carpeta bin del servidor. Cuando lo ejecutamos, tenemos que usar el comando connect para conectarnos a una instancia del servidor y poder lanzar órdenes de forma interactiva. A connect lo acompañamos de la dirección del servidor y su puerto de administración, aunque si no indicamos nada, CLI se intentará conectar a un WildFly local con el puerto predeterminado (9990). Si la conexión se realiza a otra máquina, WildFly deberá tener activado un usuario administrador y aceptar conexiones remotas.

Hagamos con CLI la configuración de la sección anterior. Una vez conectada la consola al servidor, ejecutaremos estos tres comandos para ver nuestra traza de DEBUG en CONSOLE.

  • Crear la categoría.
/subsystem=logging/logger=com.danielme.jakartaee.hello:add
  • Declarar su nivel.
/subsystem=logging/logger=com.danielme.jakartaee.hello:write-attribute(name="level", value="DEBUG") 
  • Establecer el nivel de CONSOLE a DEBUG.
/subsystem=logging/console-handler=CONSOLE:write-attribute(name="level", value="DEBUG")

Para más información sobre las posibilidades de CLI, remito al lector a la documentación oficial de JBoss EAP.

Consulta de ficheros

Los ficheros creados por los distintos handlers de tipo FILE pueden consultarse con las herramientas de administración de WildFly. Con CLI podemos ver cuáles son esos ficheros.

/subsystem=logging:read-children-names(child-type=log-file)

Vemos las últimas líneas de uno de ellos con este comando.

/subsystem=logging/log-file=server.log:read-log-file(lines=20)

El contenido de los archivos también se puede ver (y descargar) en la consola web de administración.

Código de ejemplo

El código de ejemplo para este capítulo se encuentra en GitHub (todos los proyectos están en un único repositorio). Para más información sobre cómo utilizar GitHub, consultar este artículo.

>>>> ÍNDICE <<<<

Responder

Introduce tus datos o haz clic en un icono para iniciar sesión:

Logo de WordPress.com

Estás comentando usando tu cuenta de WordPress.com. Salir /  Cambiar )

Google photo

Estás comentando usando tu cuenta de Google. Salir /  Cambiar )

Imagen de Twitter

Estás comentando usando tu cuenta de Twitter. Salir /  Cambiar )

Foto de Facebook

Estás comentando usando tu cuenta de Facebook. Salir /  Cambiar )

Conectando a %s

Este sitio usa Akismet para reducir el spam. Aprende cómo se procesan los datos de tus comentarios .