Errores básicos usando log4j

Log4j es una librería open source desarrollada en Java por la Apache Software Foundation. La librería permite a los desarrolladores de software elegir la salida y el nivel de granularidad de los logs a tiempo de ejecución, y no a tiempo de compilación como es comúnmente realizado.

Dicha configuración se hace en tiempo de ejecución mediante el uso de archivos de configuración externos (normalmente, el famoso log4j.properties). Log4J ha sido implementado en otros lenguajes como: C, C++, C#, Perl, Python, Ruby y Eiffel, si bien este artículo se enfoca principalmente en su uso en Java.

Su uso básico es realmente sencillo. Sin profundizar mucho aquí -ya lo haremos en otro post-, sencillamente se agrega la librería al proyecto donde se desee usar, se configura el archivo de configuración para indicar las salidas y el nivel de detalle de los logs deseados, y se modifica en el código los usos de System.out.print y similares por las llamadas apropiadas al logger de log4j (normalmente, log.debug, log.error, etc).

Las trazas en log4j manejan niveles de prioridad. A saber, ALL, TRACE, DEBUG, INFO, WARNING, ERROR, FATAL y OFF. Cada una es "mayor" o "menor" que la anterior o posterior, lo que nos permite configurar "niveles" de granularidad, detalle, o como quieran llamarlo. Por ejemplo, si en mi archivo de configuración de log4j indico que tengo el nivel de trazas seteado en INFO, eso quiere decir que todo lo superior e igual a INFO se mostrará (INFO, WARNING, ERROR y FATAL), mientras que lo inferior (TRACE, DEBUG) no se logueará. Si seteamos el nivel de trazas a ALL se mostrarán todas, y si lo colocamos en OFF no se verá ninguna.

Esto nos permite configurar el nivel de logueo de acuerdo a las necesidades de cada ambiente en particular. Por ejemplo, para nuestro ambiente de Desarrollo o incluso de Prueba, el archivo de configuración de log4j debería estar en nivel DEBUG, TRACE o incluso en ALL, para que podamos ver todas las trazas. Para el ambiente del cliente (Producción), se podría setear INFO, para que les lleguen los mensajes sin información de debugging, o incluso WARNING o ERROR, por cuestiones de performance (no me interesa que me digan que la operación fué un éxito, sólo me interesa enterarme de que falló y por qué).

Para que esto funcione apropiadamente, debemos asegurarnos de usar la prioridad apropiada en cada traza que coloquemos en el sistema. En general, al colocar una traza para información de debug o desarrollo, deberíamos usar el nivel de debug o el de trace:

log.debug("esta es mi traza");

Para colocar una traza con información de un error, deberíamos usar el nivel de error. Es decir, en todos los catch de la aplicación sólo deberíamos loguear usando el nivel error o fatal, y pasarle la excepción al mismo para poder controlar las trazas completamente (no llamar a e.printStackTrace()):

log.error("error haciendo algo", e);

Los demás niveles de logueo son un poco menos usados:

- log.info(...) se usa cuando queremos mostrar información de éxito en la ejecución de un programa. Como comenté arriba, normalmente cuando estamos en producción no nos interesa que nos aparezcan trazas diciendo "todo va como debería", por lo que yo tengo como regla no usar trazas de este nivel.

- log.warn(...) debe usarse cuando se encuentre una situación potencialmente peligrosa. Si no sabes qué es esto, eso quiere decir que no debes usar el nivel warn, por lo que tampoco acostumbro a usarlo. Normalmente, esto refleja una situación en la que algo falló, pero que el sistema pudo manejar de alguna forma, como asumiendo valores por defecto.

(De ahora en adelante, por comodidad y para ahorrar bits, todos los ejemplos del documento serán dados usando el nivel de debug/DEBUG, dado que este es el caso más común. Sin embargo, debemos notar que en general, todos aplican a los demás niveles indicados arriba (cuando hablamos de log.debug aplica también a log.info y log.error; cuando hablamos de isDebugEnabled() hablamos también de isInfoEnabled(), etc).

Validación del nivel de la traza:

A veces hemos visto que se acostumbra en las trazas validar a mano si el nivel de trazas usado permite o no que se muestre la traza en cuestión. Ejemplo:

if (log.isDebugEnabled())
    log.debug("Traza del objeto ", this);

Si revisamos la implementación del método isDebugEnabled() vemos que lo que revisa es que las trazas del nivel indicado (en el caso del ejemplo, DEBUG) estén permitidas, y que el nivel de traza configurado acepte el nivel indicado:

public boolean isDebugEnabled() {
    if(repository.isDisabled( Level.DEBUG_INT))
        return false;
    return Level.DEBUG.isGreaterOrEqual(
                        this.getEffectiveLevel());
}

Si revisamos la implementación del método debug(...) vemos que hace exactamente las mismas validaciones antes de imprimir la traza indicada:

public void debug(Object message) {
    if(repository.isDisabled(Level.DEBUG_INT))
        return;
    if(Level.DEBUG.isGreaterOrEqual(
                        this.getEffectiveLevel())) {
        forcedLog(FQCN, Level.DEBUG, message, null);
    }
}

Por ende, llamando al método isDebugEnabled() no solo agregamos líneas de más a la clase, haciéndola más ilegible, sino que además agregamos procesamiento innecesario, causando mayores tiempos de respuesta sin necesidad (sí, es sólo un if, pero es un if en cada llamada al log del sistema). Después de todo, es precisamente de ello de lo que se encarga la librería log4j!

No se me ocurren muchas utilidades para que tengamos que llamar alguna vez al método isDebugEnabled(), aunque estoy seguro de que alguna habrá (de hecho, hay una justo más abajo. Sigan leyendo). Como todo método, se puede usar, pero normalmente su uso será redundante, por lo que no lo recomendamos.

Performance

log4j nos da la facilidad de "apagar" las trazas como creamos necesario, de acuerdo a lo hablado en la primera parte de este documento. Sin embargo, esto no es del todo cierto, pues las concatenaciones necesarias para formar el mensaje a mostrar aún se realizan, por lo que -si las trazas están apagadas- forzamos al sistema a realizar operaciones de más, que afectan el performance general de la misma, para nada. Ver, por ejemplo, lo siguiente:

log.debug("Se cambio la propiedad '" + entry.name +
          "', del valor anterior '" + prevValue +
          "' al nuevo valor '" + entry.value + "'.");

Es deseable pensar en usar, en lugar de los métodos de logueo que reciben como parámetro un único String formado por la concatenación de varios, una solución alterna, como StringBuffers, o una lista o arreglo con todos los parámetros a imprimir, y que sea el método de logueo en nuestra clase logger (que hereda del Logger de log4j) el que -luego de validar que el nivel de traza es el apropiado para que la misma aparezca- concatene el mensaje. Una implementación sencilla de la solución con arreglos podría ser algo como:

public String buildMessage(String[] message) {
    // Deberíamos usar un StringBuffer o alguna
    // otra solución aquí...
    String result = "";
    for (int ii = 0; ii < message.length; ii++) {
        result += message[ii];
    }
    return result;
}

Que luego podría ser usado por los métodos de logueo en nuestra clase logger:

public void debug(String[] message) {
    if (repository.isDisabled(Level.DEBUG_INT)) {
        return;
    }
    if (Level.DEBUG.isGreaterOrEqual(
                        this.getEffectiveLevel())) {
        forcedLog(FQCN, Level.DEBUG,
                  buildMessage(message), null);
    }
}

Este es un cambio seguro y fácil de realizar, pero no rápido, pues habría que cambiar todas las llamadas a métodos de logueo (debug(...), error(...), etc) ya existentes en nuestras aplicaciones. Es una prueba interesante, para analizar su uso en los desarrollos venideros, hacer una prueba sencilla para validar el performance de dicho cambio.

Para realizar dicho cambio habría que cambiar las llamadas actuales al log:

log.debug("Se cambio la propiedad '" + entry.name +
          "', del valor anterior '" + prevValue +
          "' al nuevo valor '" + entry.value + "'.");

Por:

log.debug(new String[] {"Se cambio la propiedad '",
                        entry.name,
                        "', del valor anterior '",
                        prevValue,
                        "' al nuevo valor '",
                        entry.value, "'."});

O:

String[] message = {"Se cambio la propiedad '",
                    entry.name,
                    "', del valor anterior '",
                    prevValue,
                    "' al nuevo valor '",
                    entry.value, "'."}
log.debug(message);

La mejora en el performance es notoria, pero la aplicación pierde algo de legibilidad, por lo que este punto debe analizarse con cuidado. Siempre queda la opción de usar unos métodos de logueo en las aplicaciones donde el performance no es significativo, y usar otros cuando sí lo sea.