Log4j: Un framework para mostrar logs de aplicaciones

Introducción

¿Quién no ha utilizado System.out.println() para saber qué está haciendo en ese momento el programa? A veces ponemos mensajes como “estoy en 'calcularMonto'”, quizás mostrando la hora actual, o quizás el tiempo que pasó entre un proceso y otro, o mostrando el valor que tiene una variable. El problema sucede cuando el programa tiene que estar en producción y estos mensajes pueden resultar incómodos. Se torna una tarea tediosa buscar estas instrucciones para “comentarlas”. Y si hay error después ¿dónde está? ¡voy a tener que editar y recompilar el código para ver lo que pasa!. Afortunadamente programadores como nosotros han tenido el mismo problema y han desarrollado un framework que permite administrar estos mensajes – en inglés el término utilizado es logging – de tal manera que nuestros programas no tengan que pasar por el quirófano cada vez que esté “enfermo”. Este framework es el muy utilizado Log4j.

Log4j permite registrar eventos de nuestro programa sin necesidad de modificar el código a cada instante. Estos eventos (o logs) pueden ser mostrados en pantalla, guardados en un archivo, enviados por correo electrónico, etc. Por ejemplo, cuando nuestra aplicación web se levantó correctamente deseamos que se guarde en un log la hora y fecha con un mensaje “success”, pero cuando nuestra misma aplicación que atiende a más quinientos mil usuarios al día tenga un error crítico queremos que nos avise por correo electrónico a nuestro celular. Todo esto puede ser posible gracias a Log4j.

Manos a la obra: Log4j en acción

Desarrollaremos un ejemplo y a medida que lo hagamos iremos explicando cada parte del Log4j.

Paso 1: Obteniendo, instalando y configurando

Naturalmente para poder utilizar Log4j debemos obtenerlo de algún lado. Este framework se encuentra en http://logging.apache.org/. Descomprimimos su contenido en un directorio¹. Al descomprimir se habrá creado un subdirectorio con un nombre como logging-log4j-1.2.12. Este subdirectorio tiene otros subdirectorios que incluye la documentación, ejemplos, el código fuente y las bibliotecas necesarias. Dentro del subdirectorio “dist/lib” hay un archivo .jar que no pesa más de 400KB. Este es un nuestro framework que usaremos en nuestros programas.

Para usarlo recomiendo crear una biblioteca² (Library) en nuestro IDE para así poderlo reutilizar en otros proyectos. Solo bastaría con agregar a nuestra biblioteca el archivo .jar del framework.

Recordemos que al crear un proyecto con nuestro IDE favorito, este crea una estructura de directorios especial. Generalmente crea el directorio src donde estarán todos los .java, un directorio class para nuestras .class, y un directorio build donde está la aplicación lista para ejecutar. Esto varía dependiendo de nuestro IDE.

Paso 2: Haciendo nuestro ejemplo

Crearemos la clase demolog4j.Main (es decir, la clase Main dentro del paquete demolog4j)

package demolog4j;

import org.apache.log4j.Logger;

public class Main {
  static final Logger log = Logger.getLogger(Main.class);

  public static void main(String[] args) {
    log.info("iniciando aplicación");

    for (int i = 10; i >= 0; i--) {
      try {
        double n = 100 / i * 1.0;
        log.debug("el valor de n=" + n);
    }
      catch (Exception ex) {
      log.error(ex);
    }
  }
}
}

Es un ejemplo bastante forzado para mostrar tres de los cinco niveles de mensajes: info, debug y error. El nivel más detallado es el debug, que nos será de mucha utilidad al momento de depuración. Esto sirve, por ejemplo, para mostrar el nuevo valor de una variable. No debería estar activado cuando se encuentre el producción.

El siguiente nivel es info. Este nivel es para informarnos de cosas que ya se hizo algo concreto, tal como haberse conectado a la base de datos, el inicio satisfactorio de un servlet o un thread, etc. Es similar al modo “verbose” de las aplicaciones.

El siguiente nivel es el warn. Este es para advertir de eventos que no necesariamente pueda ser un error. Por ejemplo el que no haya definido un archivo de configuración pero se puede cargar valores por omisión,

El nivel error está relacionado para informar errores.

Y un nivel mucho más crítico es el fatal. Este es para informar de eventos que no tienen solución. Por ejemplo cuando una aplicación está a punto de cerrarse a causa de un error.

Para que nuestro ejemplo funcione crearemos un archivo llamado log4j.properties que debe estar en la raíz de los código fuente. Es decir, en el directorio src de nuestro proyecto. Debe encontrarse aquí ya que cada vez que el IDE construya el proyecto se copiará al directorio junto con las .classes.

El archivo log4j.properties deberá tener el siguiente contenido:

log4j.rootLogger=DEBUG, A1

log4j.appender.A1=org.apache.log4j.ConsoleAppender

log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n

Y ejecutamos el programa. Lo que mostrará es algo similar a esto:

0    [main] INFO  demolog4j.Main  - iniciando aplicación
15   [main] DEBUG demolog4j.Main  - el valor de n=10.0
15   [main] DEBUG demolog4j.Main  - el valor de n=11.0
15   [main] DEBUG demolog4j.Main  - el valor de n=12.0
15   [main] DEBUG demolog4j.Main  - el valor de n=14.0
15   [main] DEBUG demolog4j.Main  - el valor de n=16.0
15   [main] DEBUG demolog4j.Main  - el valor de n=20.0
15   [main] DEBUG demolog4j.Main  - el valor de n=25.0
15   [main] DEBUG demolog4j.Main  - el valor de n=33.0
15   [main] DEBUG demolog4j.Main  - el valor de n=50.0
15   [main] DEBUG demolog4j.Main  - el valor de n=100.0
15   [main] ERROR demolog4j.Main  - java.lang.ArithmeticException: / by zero

Puedes editar la primera línea del log4.properties cambiando el texto “debug” por alguno de los demás niveles: info, warn, error o fatal para ver los resultados.

Estructura de Log4j.

Log4j tiene tres componentes principales: loggers, appenders y layouts. Estos tres tipos de componentes trabajan juntos para permitir a los desarrolladores registrar mensajes según el tipo y nivel de estos, y controlarlos en tiempo de ejecución para mostrarlos de acuerdo a un formato que le especifiquemos.

Loggers

La principal ventaja del Log4j comparado con el tradicional System.out.println() es su capacidad para habilitar o deshabilitar los registradores de mensajes sin afectar a los demás. Un registrador de mensajes (Logger) son entidades autónomas con configuración independiente, de tal manera que uno tenga cierta funcionalidad que otro no lo tenga. Los nombres de los loggers son sensibles a mayúsculas.

Appenders

La habilidad para activar o desactivar cualquier logger es solo una parte de Log4j. El framework permite registrar los eventos en varios destinos. Para Log4j una salida (pantalla, archivo, etc) es un appender. Actualmente, existe appenders para consola (como hemos visto), archivos, componentes visuales, servidores de sockets, JMS, Registro de Eventos de NT, y demonios de registro Unix.

Layouts

El layout es el responsable de formatear los mensajes de acuerdo a criterio del programador. Existen dos tipos de Layout: SimpleLayout, que básicamente muestra el nivel del mensaje y el mensaje en sí, y el PatternLayout que consiste en formatear la salida.

Paso 3: Personalizando los mensajes

Veremos un ejemplo más avanzado para ilustrar estos conceptos. Modifiquemos el archivo .properties para que tenga el siguiente contenido:

log4j.rootLogger=debug, stdout, R

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout

log4j.appender.stdout.layout.ConversionPattern=%5p [%t] (%F:%L) - %m%n

log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=example.log
log4j.appender.R.Append=false

log4j.appender.R.MaxFileSize=100KB
log4j.appender.R.MaxBackupIndex=1

log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%p %t %c - %m%n

Destallaremos cada línea de esta configuración

log4j.rootLogger=debug, stdout, R

Aquí estamos definiendo que nuestro Logger serán stdout y R. Ambos serán para atender el nivel debug.

log4j.appender.stdout=org.apache.log4j.ConsoleAppender

En esta línea el appender stdout será de tipo ConsoleAppender. Esta clase se encargará de mostrar los mensajes a la pantalla.

log4j.appender.stdout.layout=org.apache.log4j.PatternLayout

La clase “PatternLayout” nos permite configurar nuestro appender por una cadena. En el API del framework podemos ver más detalle de estas clases.

log4j.appender.stdout.layout.ConversionPattern=%5p [%t] (%F:%L) - %m%n

Aquí ya estamos definiendo nuestro formato el cual consiste en mostrar en un espacio de 5 caracteres (%5) el nivel del mensaje (p). Luego sigue de un espacio. Entre llaves mostrará el hilo que generó el mensaje (%t). Luego de un espacio, entre paréntesis el nombre del archivo fuente (%F) y después de dos puntos muestra la línea dentro del código fuente (%L). Después sigue un guión y luego muestra el mensaje que se ha mandado desde el programa. Finaliza con un salto de línea.

Tenemos otro appender que es el R. Este es de clase RollingFileAppender. Esta clase permite agregar a un archivo y si este llega a un límite especificado es renombrado y el registro seguirá en un archivo nuevo. Esto es muy útil si queremos mantener todos los registros de eventos partidos en archivos de un tamaño manejable.

log4j.appender.R=org.apache.log4j.RollingFileAppender
log4j.appender.R.File=example.log
log4j.appender.R.Append=false

Aquí estamos diciendo que el archivo que creará será “example.log”y que sobreescriba los mensajes cada vez que se ejecute la aplicación.

log4j.appender.R.MaxFileSize=100KB

Que tendrá un tamaño máximo de 100KB

log4j.appender.R.MaxBackupIndex=2

Y cuantos backups deberá crear antes de que el más antiguo deba borrarse.

log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%p %t %c - %m%n

Aquí estamos definiendo el formato de salida que tendrá: la prioridad del evento (%p) seguido del nombre del thread que generó el evento (%t), el nombre completo de la clase incluyendo el paquete (%c) seguido de un guión y luego mensaje. Termina con una línea nueva.
Por último, agregaremos estas líneas a la configuración para enviar un email cuando suceda un error.

log4j.rootLogger=debug, stdout, R,email

....
log4j.appender.email.Threshold=error
log4j.appender.email=org.apache.log4j.net.SMTPAppender
log4j.appender.email.SMTPHost=smtp.provider.com
log4j.appender.email.From=events@jugperu.com
log4j.appender.email.To=user@jugperu.com
log4j.appender.email.Subject=Mensaje de Log4j!
log4j.appender.email.layout=org.apache.log4j.PatternLayout
log4j.appender.email.layout.ConversionPattern=%5p [%t] (%F:%L) - %m%n

Para que este funcione deberemos de agregar la biblioteca de JavaMail.

Conclusiones

Cómo hemos visto, el cambio de la manera de registrar los eventos fue solo en el archivo .properties y no en nuestro programa. Muchas aplicaciones hechas en Java que utilizamos – como el Tomcat – utilizan este framework de registro de mensajes. Puedes personalizar sus mensajes de acuerdo a tus exigencias. Piensa qué tan útil puede ser para tus proyectos.

Tips

1 Recomiendo que todas las bibliotecas en general se guarden en un directorio llamado “lib”

2 Comúnmente cometemos el error de decir 'librería' para referirnos a 'library'. La traducción correcta de 'library' es biblioteca. 'librería' significa “tienda de libros”.