Logs en Liferay 7

La guía definitiva... o casí

Publicado por Miguel Ángel Júlvez el mié, 03 ago 2016 21:19:00 +0000

Índice

Aspectos básicos de los logs
   Niveles de logs
   Rotado de logs
Logs en Liferay 7
   Gestión desde el panel de control
   Persistiendo el nivel de logs
   Formato de los logs
      La problemática de las fechas
      Configurando el formato de los logs
Logs en un módulo OSGI
   Añadiendo logs en clases java
   Añadiendo logs en jsp
   Cuándo y cómo escribir logs
   Almacenando los logs en ficheros separados
Logs en Apache Tomcat
   Usando log4j en Tomcat
   Contenido fichero log4j.properties

 

Aspectos básicos de los logs

Un fichero de log es un registro que almacena distintos eventos que se producen en nuestras aplicaciones para su posterior análisis.

Niveles de logs

Los ficheros de log pueden contener mucha información por lo que para filtrar esta información, los sistemas de logs suelen poder trabajar en distintos niveles según el grado de detalle de la información que se quiera mostrar.

Cada sistema de log detalla sus propios niveles y suelen permitir crear niveles personalizados, pero en general y por simplificar, podemos encontrar lo siguientes niveles ordenados de menor a mayor grado de detalle:

  • OFF
  • FATAL
  • ERROR
  • WARNING
  • INFO
  • DEBUG
  • TRACE

En este post trabajaremos con log4j , que “casualmente” trabaja exactamente con los mismos niveles que acabamos de ver, y además es el sistema de logs con el que trabaja liferay 7 por defecto.

Rotado de logs

Los ficheros de logs, al poder contener mucha información, pueden llegar a un punto que contengan tanta información que lleguen a ser intratables. Para eso es necesario dividir la información que contienen en, por ejemplo, distintos ficheros que hagan más fácil encontrar la información que necesitamos.

Dependiendo de la política de rotado que se aplique podemos hacer que los logs se creen en fichero separados según la fecha en la que se escribió el log o por ejemplo garantizando que el fichero no llegue a un tamaño muy elevado que haga muy lenta su tratamiento.

Cuando escribimos logs, siempre hay que vigilar su crecimiento porque con el paso de los meses/años es muy probable que nos quedemos sin espacio en disco. Por eso, aparte del rotado de logs, también es imprescindible garantizar que los ficheros de logs no crecen desmesuradamente y almacenarlos en dispositivos secundarios o incluso borrarlos cuando hayan dejado de tener su utilidad.

Logs en Liferay 7

Como ya he mencionado, liferay 7 utiliza log4j como sistema de logs. Más concretamente la versión 1.2.17. Todos los packages java de liferay utilizan esta librería para gestionar la información que escriben en los logs.

Los ficheros de logs de liferay se encuentran en /logs/ rotados por fecha. Liferay también escribe en el log del servidor de aplicaciones (sí, vale. La teoría dice que no hay que escribir aquí) y algunos servidores de aplicaciones no truncan el fichero de log cuando se rotan así que hay que tener especial cuidado en ese fichero ya que puede crecer desmesuradamente. Por ejemplo, estoy pensando en el fichero catalina.out del tomcat.

Para estos casos se puede utilizar alguna herramienta externa de rotado de logs, como por ejemplo logrotate, que puede hacerlo por nosotros y así ahorrarnos muchos problemas en el futuro.

Gestión desde el panel de control

Lo interesante de esto es que podemos gestionar dinámicamente desde la propia interfaz de liferay el nivel de log que queremos ver para los distintos packages.

Para acceder a dicha gestión de logs debes ir a:

Panel de control -> administración del servidor -> Niveles de log

Como puedes ver en la imagen anterior, ahí puedes modificar dinámicamente el nivel de log de cada package

*Estrictamente hablando se establecen los niveles de logs de las categorías indicadas en log4j. Podemos pensar, aunque no necesariamente tenga que ser así, que una categoría de log4j se corresponde con un package o clase de java.

Esto es muy útil sobre todo cuando quieres establecer temporalmente un nivel con más grado de detalle cuando detectas un mal funcionamiento en el producto y quieres ver toda la información posible del componente para intentar averiguar qué está pasando.

Otro elemento interesante que ofrece esta pantalla es la posibilidad de añadir nuevas categorías al vuelo. Por ejemplo, imagina que tienes un módulo desarrollado por tí mismo que tiene un package llamado com.yourpackage.portlet y quieres que liferay escriba los logs que has indicado en él (esto lo vamos a ver como se hace un poquito mas abajo en este mismo post). Simplemente añade una categoría con el mismo nombre del package y establécele en nivel de log que quieras y partir de ese momento verás cómo aparecerán tus logs en los ficheros de log de liferay.

Persistiendo el nivel de logs

Los cambios que hemos visto en el punto anterior desde el panel de control no son persistentes. Es decir, que cuando reinicies liferay los perderás y volverán los valores por defecto.

Los valores por defecto son establecidos en el fichero portal-log4j.xml. Este fichero se encuentra dentro de la librería portal-impl.jar de liferay.

*Esta es una de esas cosas que hacen a veces difícil la configuración de liferay, sobre todo cuando empiezas a conocer el producto, porque es un fichero que debería estar más fácilmente accesible, por ejemplo en /WEB-INF/classes/META-INF, para poder consultarlo.

El fichero lo puedes también encontrar en el código fuente de liferay https://github.com/liferay/liferay-portal/blob/master/portal-impl/src/META-INF/portal-log4j.xml

Si quieres hacer algún cambio en este fichero lo que tienes que hacer es lo siguiente:

  1. Crea este fichero vacío tomcat-8.0.32/webapps/ROOT/WEB-INF/classes/META-INF/portal-log4j-ext.xml (date cuenta del -ext añadido al final)
  2. Añade el dtd de log4j en el mismo directorio. Es decir, aquí tomcat-8.0.32/webapps/ROOT/WEB-INF/classes/META-INF/ (el log4j.dtd lo puedes descargar aquí https://github.com/apache/logging-log4j2/blob/master/log4j-core/src/test/resources/log4j.dtd)

Ahora añade al fichero creado portal-log4j-ext.xml aquello que quieras hacer persistente.

Por ejemplo, imagina que quieres poner a DEBUG la primera categoría que aparece en la captura de pantalla anterior:

<?xml version="1.0"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

        <category name="com.browseengine.bobo">
             <priority value="DEBUG" />
        </category>

</log4j:configuration>

Ahora, reinicia el servidor de aplicaciones y accede nuevamente al panel de control. Verás como ahora aparece el nivel que has indicado en el fichero anterior.

Por ejemplo imagina que además de lo anterior, ahora quieres hacer que liferay no escriba en los logs del servidor de aplicaciones y que no escriba los logs .xml. Solo que escriba en los .log.

<?xml version="1.0"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

       <category name="com.browseengine.bobo">
             <priority value="DEBUG" />
        </category>

        <root>
                <priority value="INFO" />
                <appender-ref ref="TEXT_FILE" />
        </root>

</log4j:configuration>

Reinicia nuevamente y listo. Se acabó el problema de no rotado del catalina.out.

Formato de los logs

Una de las cosas básicas que facilita el desarrollo de los proyectos, es tener unos logs con un formato adecuado que permita mezclar la información ofrecida por los logs de las distintas aplicaciones para su análisis combinado.

Hay muchas teorías de lo que deben escribir los logs, cómo se deben escribir, dónde hacerlo, … así que voy a explicar cómo lo hago yo y por qué. Es decir, una teoría más ^_^

La problemática de las fechas

Lo normal de las aplicaciones que operan y almacenan fechas en bases de datos es que tengan configurado su timezone en el timezone GMT ya que históricamente los distintos conectores JDBC han tratado de distinta manera, o incluso ignorado, el timezone de las fechas. De esta forma, todas las fechas que están almacenadas en la base de datos están en GMT y cuando se le muestra la información al usuario, se realiza el offset del timezone GMT con respecto al timezone donde se encuentra cada usuario, mostrando así las fechas correctas para las distintas zonas horarias. Esta es la justo la forma en la que trabaja Liferay.

Este es el motivo por el cual, cuando vemos los logs de nuestro servidor de aplicaciones sobre el que corre Liferay y nuestro servidor está configurado con el timezone de España, vemos que la hora que muestran los mensajes de log es distinta que la hora de nuestro servidor. España dispone de dos husos horarios: GMT+1 en invierno, por lo que los mensajes de log los veremos con una hora menos que la del reloj de nuestro sistema, y GMT+2 en verano, por lo que los logs los veremos con dos horas menos.

Una “solución” que recomiendan en distintos foros de internet es establecer el parámetro user.timezone de la jvm sobre la que corre el servidor de aplicaciones al valor del huso horario en el que se encuentra el servidor. Yo esto no lo recomendaría, sobre todo si ya se ha levantado el portal y se han creado contenidos con fechas, porque Liferay dejaría de trabajar en GMT y habría contenidos con fechas en GMT y otros con fechas en otro timezone aunque realmente no sabrías cual es cual.

Yo prefiero que mis aplicaciones corran siempre en GMT y luego presentar los logs con el timezone donde se encuentra la máquina.

Para mí lo esencial es que todos los logs usen el mismo formato de fecha y que la fecha muestre además su timezone. Esto permitirá que si tenemos un servidor en Australia, otro en Estados Unidos y el análisis de los logs lo estamos haciendo en España, cuando combinemos los logs podamos ajustarles el offset a la hora de España y ver toda la información de los logs con el huso horario unificado.

Es decir, el objetivo es conseguir que todos nuestros logs escriban el formato fecha en este formato (o similar):

2016-07-24T11:21:01.252+0200 -- yyyy-MM-dd’T’HH:mm:ss.SSSZZZZ

Como puedes ver, después del símbolo ‘+’ viene el offset respecto GMT del mensaje de log. Esto es muy interesante ya que si queremos analizar datos de logs de aplicaciones en distintos husos horarios, este formato contiene toda la información necesaria para mover la fecha entre los distintos husos.

Configurando el formato de los logs

Si queremos que liferay use el formato de logs que acabo de describir, lo que tendrás que hacer es añadir el siguiente contenido al fichero portal-log4j-ext.xml

<?xml version="1.0"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

        <appender class="org.apache.log4j.ConsoleAppender" name="CONSOLE">
                <layout class="org.apache.log4j.EnhancedPatternLayout">
                        <param name="ConversionPattern" value="%d{yyyy-MM-dd'T'HH:mm:ss.SSSZZZZ}{Europe/Madrid} %-5p [%t][%c{1}:%L] %m%n" />
                </layout>
        </appender>

        <appender class="org.apache.log4j.rolling.RollingFileAppender" name="TEXT_FILE">
                <rollingPolicy class="org.apache.log4j.rolling.TimeBasedRollingPolicy">
                        <param name="FileNamePattern" value="@liferay.home@/logs/[email protected]@.%d{yyyy-MM-dd}.log" />
                </rollingPolicy>

                <layout class="org.apache.log4j.EnhancedPatternLayout">
                        <param name="ConversionPattern" value="%d{yyyy-MM-dd'T'HH:mm:ss.SSSZZZZ}{Europe/Madrid} %-5p [%t][%c{1}:%L] %m%n" />
                </layout>
        </appender>

        <root>
                <priority value="INFO" />
                <appender-ref ref="CONSOLE" />
                <appender-ref ref="TEXT_FILE" />
        </root>

</log4j:configuration>

Ahora reinicia el servidor de aplicaciones y verás como liferay escribe los logs con un formato mucho más interesantes y con la hora correcta.

Logs en un módulo OSGI

Hasta ahora hemos visto cómo gestionar los logs que liferay ofrece. Pero ¿cómo hacemos para incorporar logs a nuestros desarrollos? Bien. Para esto Liferay ofrece unas utilidades que simplifican mucho esta tarea.

Añadiendo logs en clases java

import com.liferay.portal.kernel.log.Log;
import com.liferay.portal.kernel.log.LogFactoryUtil;

private static Log _log = LogFactoryUtil.getLog(MyClassName.class);

Y luego ya úsalos en tu código java donde quieras.

Añadiendo logs en jsp

<%@ page import="com.liferay.portal.kernel.log.LogFactoryUtil" %>
<%@ page import="com.liferay.portal.kernel.log.Log" %>
<%! private static Log _log = LogFactoryUtil.getLog("mypackage.html.myfile_jsp"); %>

Cuándo y cómo escribir logs

El cuándo y cómo escribir los logs es algo muy personal ya que cada uno tenemos nuestras manías.

Por ejemplo:

public void addFoo(ActionRequest actionRequest, ActionResponse) {
    _log.debug("Entrando en addFoo");

    try {
        if (_log.isTraceEnabled()) {
            _log.trace("Añadiendo Foo: " + FooObject);
        }
        //Añadir Foo
        _log.info("Nuevo objeto Foo añadido");
        } catch (Exception e) {
            _log.error("No he podido insertar Foo", e);
        }
    }
}

Lo que quiero remarcar en el anterior pseudocódigo es que al final es el desarrollador quien decide los niveles de log a usar y cómo usarlos.

Si te das cuenta, en la línea 5 hay una comprobación de si el nivel de debug TRACE está habilitado. Esta comprobación, completamente opcional, se suele realizar cuando la ejecución del log que enmarca es costosa. Por ejemplo, cuando hacemos concatenaciones de cadenas, operaciones matemáticas, etc no queremos que ese código se ejecute si finalmente no va a ser escrito en nuestros logs. Es un tema de performance, ya digo que completamente opcional, pero no está de más tenerlo en mente a la hora de escribir nuestro código.

Almacenando los logs en ficheros separados

Para lograr que los logs de un módulo OSGI se escriben en un fichero diferente al fichero de los de liferay, crea un fichero dentro del módulo llamado module-log4j.xml en la ruta src/main/resources/META-INF y añádele el siguiente contenido:

<?xml version="1.0"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

   <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
       <param name="Threshold" value="DEBUG"/>
       <layout class="org.apache.log4j.EnhancedPatternLayout">
           <param name="ConversionPattern" value="%d{yyyy-MM-dd'T'HH:mm:ss.SSSZZZZ}{Europe/Madrid} %-5p [%t][%c{1}:%L] %m%n" />
       </layout>
   </appender>

   <appender name="TEXT_FILE" class="org.apache.log4j.rolling.RollingFileAppender">
       <param name="Threshold" value="TRACE"/>
       <rollingPolicy class="org.apache.log4j.rolling.TimeBasedRollingPolicy">
           <param name="FileNamePattern" value="${catalina.home}/logs/my-portlet.%d{yyyy-MM-dd}.log" />
       </rollingPolicy>

       <layout class="org.apache.log4j.EnhancedPatternLayout">
           <param name="ConversionPattern" value="%d{yyyy-MM-dd'T'HH:mm:ss.SSSZZZZ}{Europe/Madrid} %-5p [%t][%c{1}:%L] %m%n" />
       </layout>
   </appender>

   <logger name="your.package.module" additivity="false">
       <level value="TRACE" />
       <appender-ref ref="CONSOLE" />
       <appender-ref ref="TEXT_FILE" />
   </logger>

</log4j:configuration>

*Date cuenta que no he utilizado la palabra especial @liferay.home@ que sí hemos utilizado previamente en el fichero portal-log4-ext.xml. Esto se debe a que Liferay no hace la sustitución de esa variable. No se si es un error o una característica pero de todas formas lo he reportado aquí https://issues.liferay.com/browse/LPS-67262

Como puedes ver, esta configuración lo que hará es escribir en un fichero específico todos los logs hasta el nivel TRACE mientras que en la console escribirá hasta el nivel DEBUG. De esta forma es todavía asequible tener los logs del servidor de aplicaciones abiertos y no morirse con la cantidad de información que muestra.

Bueno, en teoría no debería escribir en la console del servidor de aplicaciones. Pero bueno, a mi me gusta hacerlo durante el desarrollo ya que me facilita mucho ver lo que está pasando teniendo todos los logs centralizados. De todas formas también depende de lo que escribas en los logs de tu aplicación, pero bueno, eso ya es otra historia.

Otra cosa interesante es tener este fichero parametrizado por entornos. Es decir, si estoy desarrollando, esta configuración puede ser perfectamente válida. Pero si estamos desplegando el módulo en un entorno productivo, seguramente querremos no escribir nunca en la console y subir el nivel INFO en los logs que se escriben en el fichero. Me apunto esto para otro post para explicar como hacer esto en gradle.

Logs en Apache Tomcat

Apache Tomcat usa por defecto java.util.logging. Yo la verdad es que no me siento cómodo con ese sistema ya que hay cosas que todavía no he conseguido hacer, como por ejemplo mostrar la hora de los logs en el timezone que yo quiero. Así que lo que hago es configurar el Tomcat para usar log4j y así usar el mismo patrón de conversión que hemos utilizado hasta ahora.

Usando log4j en Tomcat

Para configurar Apache Tomcat con log4j hay que hacer una serie de pasos:

  1. Borrar el fichero conf/logging.properties
  2. Crear el fichero lib/log4j.properties con este contenido (ver siguiente punto)
  3. Copiar la librería log4j v1.2.17 al directorio lib
  4. De los extras del tomcat, descargar tomcat-utils-adapter.jar y copiarlo al directorio lib
  5. De los extras del tomcat, descargar tomcat-juli.jar y copiarlo al directorio bin (hay un fichero ya con ese nombre, así que tendrás que sobreescribir el fichero al copiarlo)

*Los extras del tomcat lo puedes descargar aquí https://archive.apache.org/dist/tomcat/tomcat-8/v8.0.32/bin/extras/

*El jar de la librería lo puedes descargar aquí https://archive.apache.org/dist/logging/log4j/1.2.17/

Contenido fichero log4j.properties

log4j.rootLogger = INFO, CATALINA

# Define all the appenders
log4j.appender.CATALINA = org.apache.log4j.DailyRollingFileAppender
log4j.appender.CATALINA.File = ${catalina.base}/logs/catalina.out
log4j.appender.CATALINA.Append = true
log4j.appender.CATALINA.Encoding = UTF-8

# Roll-over the log once per day
log4j.appender.CATALINA.DatePattern = '.'yyyy-MM-dd'.log'
log4j.appender.CATALINA.layout = org.apache.log4j.EnhancedPatternLayout
log4j.appender.CATALINA.layout.ConversionPattern = %d{yyyy-MM-dd'T'HH:mm:ss.SSSZZZZ}{Europe/Madrid} %-5p [%t][%c{1}:%L] %m%n

log4j.appender.LOCALHOST = org.apache.log4j.DailyRollingFileAppender
log4j.appender.LOCALHOST.File = ${catalina.base}/logs/localhost.out
log4j.appender.LOCALHOST.Append = true
log4j.appender.LOCALHOST.Encoding = UTF-8
log4j.appender.LOCALHOST.DatePattern = '.'yyyy-MM-dd'.log'
log4j.appender.LOCALHOST.layout = org.apache.log4j.EnhancedPatternLayout
log4j.appender.LOCALHOST.layout.ConversionPattern = %d [%t] %-5p %c- %m%n

log4j.appender.MANAGER = org.apache.log4j.DailyRollingFileAppender
log4j.appender.MANAGER.File = ${catalina.base}/logs/manager.out
log4j.appender.MANAGER.Append = true
log4j.appender.MANAGER.Encoding = UTF-8
log4j.appender.MANAGER.DatePattern = '.'yyyy-MM-dd'.log'
log4j.appender.MANAGER.layout = org.apache.log4j.EnhancedPatternLayout
log4j.appender.MANAGER.layout.ConversionPattern = %d [%t] %-5p %c- %m%n

log4j.appender.HOST-MANAGER = org.apache.log4j.DailyRollingFileAppender
log4j.appender.HOST-MANAGER.File = ${catalina.base}/logs/host-manager.out
log4j.appender.HOST-MANAGER.Append = true
log4j.appender.HOST-MANAGER.Encoding = UTF-8
log4j.appender.HOST-MANAGER.DatePattern = '.'yyyy-MM-dd'.log'
log4j.appender.HOST-MANAGER.layout = org.apache.log4j.EnhancedPatternLayout
log4j.appender.HOST-MANAGER.layout.ConversionPattern = %d [%t] %-5p %c- %m%n

log4j.appender.CONSOLE = org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.Encoding = UTF-8
log4j.appender.CONSOLE.layout = org.apache.log4j.EnhancedPatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern = %d{yyyy-MM-dd'T'HH:mm:ss.SSSZZZZ}{Europe/Madrid} %-5p [%t][%c{1}:%L] %m%n

# Configure which loggers log to which appenders
log4j.logger.org.apache.catalina.core.ContainerBase.[Catalina].[localhost] = INFO, LOCALHOST
log4j.logger.org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager] = INFO, MANAGER
log4j.logger.org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/host-manager] = INFO, HOST-MANAGER

 

Arrancamos tomcat y veremos cómo todos los logs mostrados por parte del tomcat, liferay y nuestros módulos desarrollados son consistentes tanto en formato como en huso horario lo que facilita enormemente su análisis y seguimiento.

 

 

Y esto es todo. Bueno, no. Una última cosa. Es obvio pero no deja de sorprenderme. Ten siempre los ficheros de logs abiertos!! Si. Cuando arranque el servidor de aplicaciones asegúrate de tener una ventana con sus logs. Y míralos!! La información que ahí se muestra es esencial para saber lo que está pasando. No hagas pruebas y repruebas y más repruebas sin mirar lo que pasa en los logs. Ahorrarás muchíiiiisimo tiempo ;-)

Cargando comentarios...