h1

System.out.println, log4j y la Programacion Orientada a Aspectos

08/29/2009

Wizdoc [Icon By Buuf]  Tips & Tricks.
Al desarrollar sistemas y aplicaciones, independientemente del lenguaje de programación usado es muy común que "imprimamos" los valores de ciertas variables u operaciones con el fin de depurar el código durante su ejecución.

En Java/J2EE, los newbies – desarrolladores de reciente ingreso a la fuerza laboral – con frecuencia realizan esta depuración mediante System.out.println y System.err.println. Sin embargo, el uso de estas instrucciones posee fuertes desventajas y peligros potenciales:

• Este tipo de instrucciones desordena la continuidad del código, disminuyendo su legibilidad. Esto es especialmente evidente cuando se trata de imprimir el detalle de una transacción o el contenido de un objeto complejo.

• A menos que explícitamente se indique lo contrario, todos estos mensajes serán impresos cada vez que se ejecute la sección de código donde se encuentran. De hecho, si añadimos sentencias IF para comprobar si deben o no imprimirse estos mensajes estamos incrementando el problema de limpieza de código. Por ejemplo, en el siguiente fragmento sólo una tercera parte es funcional, mientras lo demás es "peso muerto":

if ((generatedFiles != null) && (generatedFiles.size() > 0)) {
  if (Constants.DEPURACION_ACTIVADA) {
    System.out.println("CDRs procesados (" + generatedFiles.size() + "):");

    for (int i = 0; i < generatedFiles.size(); i++) {
      if (Constants.DEPURACION_ACTIVADA) {
        System.out.println("" + generatedFiles.get(i));
      }
    }
  }

  CDRUtils.deleteFileList(cdrToProcess);
} else {
  System.err.println("No se generaron CDRs de proveedores durante esta ejecucion del proceso.");
}

• System.out y System.err son streams de datos cuya salida se define por el ambiente de ejecución; en el caso de aplicaciones stand-alone, la salida es el prompt del sistema operativo mientras que para componentes contenidos en un web o application server ésta se asocia a un archivo, bitácora o log localizado en el dominio de dicho servidor; generalmente es un archivo de texto denominado server.log. Esto significa que para direccionar salidas customizadas es necesario realizar validaciones adicionales o en su caso configuraciones de seguridad para escribir archivos, restando flexibilidad a la depuración e incrementando la dificultad para encontrar mensajes puntuales en las bitácoras – que en aplicaciones empresariales, pueden consistir de decenas o cientos de Megabytes de información.

• Con frecuencia se requiere información más allá del simple mensaje que estamos imprimiendo. Es decir, podemos necesitar información adicional como la fecha y hora del evento, la clase donde se está imprimiendo el mensaje o el hilo de ejecución que está corriendo en este momento. Esto podría complicar nuestros desarrollos hasta hacerlos completamente ilegibles. Usando el ejemplo anterior:

if ((generatedFiles != null) && (generatedFiles.size() > 0)) {
  if (Constants.DEPURACION_ACTIVADA) {
    System.out.println("Fecha: " + System.currentTimeMillis() + "Caller: " + this.getClass().getName() + "CDRs procesados (" + generatedFiles.size() + "):");

    for (int i = 0; i < generatedFiles.size(); i++) {
      if (Constants.DEPURACION_ACTIVADA) {
        System.out.println("Fecha: " + System.currentTimeMillis() + "Caller: " + this.getClass().getName() + generatedFiles.get(i));
      }
    }
  }

  CDRUtils.deleteFileList(cdrToProcess);
} else {
  System.err.println("Fecha: " + System.currentTimeMillis() + "Caller: " + this.getClass().getName() + "No se generaron CDRs de proveedores durante esta ejecucion del proceso.");
}

• Finalmente, al usar este tipo de instrucciones puede venirse abajo el desempeño de nuestra aplicación. De acuerdo a un reporte de desempeño que presentamos hace algún tiempo, basado en un documento de mejores prácticas publicado por IBM:

Dado a que parece inofensiva, esta práctica legada de desarrollo es muy común, pasando por alto el problema de desempeño que realmente representa. Ya que los enunciados System.out.println y construcciones similares sincronizan el procesamiento durante la escritura en disco, puede disminuirse el desempeño significativamente.

Adicionalmente, System.out y System.err son streams que por defecto no utilizan un búfer de datos. Por ello, para cada byte de información que se desea imprimir en la bitácora, se requiere una llamada al sistema operativo y su correspondiente escritura en disco. Todo ello de manera sincronizada, impidiendo que otros bytes de información puedan ser escritos de manera paralela, desperdiciando procesador y velocidad de I/O por igual.

Log4j: un repaso

La Fundación de Software Apache ha desarrollado varios frameworks que justamente atacan las deficiencias presentadas por System.out y otros métodos legados de depuración. Incluyendo las versiones para Microsoft .Net (log4net), C++ (log4cxx) y Java (log4j), estos frameworks se han convertido en el estándar defacto para la industria.

Para usar log4j en su forma más simple, debemos incluir la librería log4j.jar en nuestro classpath y agregar las líneas correspondientes en nuestro código:

import org.apache.log4j.Logger;

public static Logger logger = Logger.getLogger("WORKERS");

if ((generatedFiles != null) && (generatedFiles.size() > 0)) {
  if (logger.isDebugEnabled()) {
    logger.debug("CDRs procesados (" + generatedFiles.size() + "):");

    for (int i = 0; i < generatedFiles.size(); i++) {
      logger.debug("" + generatedFiles.get(i));
    }
  }

  CDRUtils.deleteFileList(cdrToProcess);
} else {
  logger.warn("No se generaron CDRs de proveedores durante esta ejecucion del proceso.");
}

Este fragmento de código muestra las características más importantes del framework:

• Se puede definir un logger o bitácora puntual por cada clase o grupo de clases. Incluso puede definirse una jerarquía de bitácoras heredando propiedades tales como nivel de depuración (DEBUG, WARN, ERROR) o el formato de salida (por ejemplo: Fecha%Clase%Mensaje).

• De acuerdo a una propiedad obtenida de los parámetros del sistema, argumentos de la JVM o de un archivo de propiedades, es posible preguntar si se quieren imprimir los mensajes de nivel más fino a través de la instrucción logger.isDebugEnabled().

• Finalmente, la clase org.apache.log4j.Logger posee diferentes métodos de impresión de acuerdo al nivel de depuración: Desde el detalle fino con logger.debug() hasta el temido logger.fatal() que sólo deberíamos incluir al encontrar excepciones de tipo java.lang.Error.

Un par de detalles…

Resulta que con todo y los beneficios de log4j, no nos salvamos de tener que incluir cierto código muerto en nuestros desarrollos con el único fin de imprimir los mensajes en la bitácora. A continuación describo un par de ejemplos que llamaron mi atención:

De primera instancia, en el post Logging with log4J isDebugEnabled del Shaaf’s Blog (hoy difunto), el autor comenta que existen ciertos mensajes que una vez comprobada su validez nos conviene desactivar, sobre todo aquellos que son particularmente detallados, complejos o que impactan en el desempeño de la aplicación. Para ello hace referencia a la instrucción logger.isDebugEnabled() usada para desactivar este tipo de mensajes. Entre los comentarios del post hacen hincapié en que esta instrucción es muy tediosa de implementar y que llega a saturar el código con declaraciones de este tipo.

Lo que nos lleva al blog Coding Horror, donde el autor nos presenta el caso contra el logueo en The Problem With Logging, reflexionando que aunque imprimir mensajes aquí y allá es una buena práctica de programación, debemos hacerlo con moderación pues podemos terminar con un monstruo sin pies ni cabeza y afectando de paso el desempeño – o peor aún, la estabilidad – de nuestra aplicación.

… y sus workarounds

Creo que muchos de los problemas descritos en ambos posts tienen que ver más con el uso de patrones de diseño y paradigmas de programación que de la implementación de la tecnología, pues si lo que nos hace sentir frío es llenar nuestro código de instrucciones de depuración, podemos tomar dos caminos:

El primero implica seguir el mantra "la mejor forma de reducir la complejidad de un problema es agregar una capa de abstracción". Para este caso, si en cada debug() debemos incluir un isDebugEnabled() ¿por qué no mejor creamos una clase intermedia que ya incluya esta estructura? usando el ejemplo que hemos venido mostrando:

MyLogger.java

class MyLogger extends org.apache.log4j.Logger {
  …
  public void debug(java.lang.Object message) {
    if(this.isDebugEnabled()) {
      super.debug(message);
    }
  }
}


MyDebuggedClass.java

public static MyLogger logger = MyLogger.getLogger("WORKERS");

if ((generatedFiles != null) && (generatedFiles.size() > 0)) {
  logger.debug("CDRs procesados (" + generatedFiles.size() + "):");

  for (int i = 0; i < generatedFiles.size(); i++) {
    logger.debug("" + generatedFiles.get(i));
  }

}

  CDRUtils.deleteFileList(cdrToProcess);
} else {
  logger.warn("No se generaron CDRs de proveedores durante esta ejecucion del proceso.");
}

¡Voila! Tenemos como resultado un código más limpio pero igual de detallado al depurarlo. Por cierto, como buena práctica de desarrollo es indispensable que al haber comprobado la funcionalidad de nuestra aplicación en los ambientes de desarrollo y preproducción, deben desactivarse los mensajes de nivel DEBUG al pasar a un ambiente productivo.

Por otro lado, podemos tomar el camino más complejo pero de mayor alcance. Éste implica un cambio en nuestra forma de programar y se le denomina Programación Orientada a Aspectos (Aspect Oriented Programming – AOP). Este paradigma de reciente creación merece un post largo y tendido, pero de momento lo podemos simplificar a lo siguiente:

En todas nuestras aplicaciones existe cierto código que es de copy & paste pero que no puede ser movido, abstraído ni externalizado fácilmente. Por ejemplo, las dos funciones más representativas de esto son la seguridad y el logueo en bitácoras:

• En muchas aplicaciones, cada vez que se llaman los métodos relacionados a transacciones o persistencia en base de datos es necesario llamar al módulo de seguridad para verificar que el cliente cuenta con los permisos correspondientes.

• En otras tantas aplicaciones, ya sea por buena práctica de programación, controles anti-fraude o políticas y leyes regulatorias – como la Ley Sarabanes-Oxley – toda interacción con cierto tipo de registros requiere que el detalle de la operación sea almacenado en una bitácora.

Así, imaginemos lo tedioso y propenso a errores que significa incluir una llamada a la seguridad y una impresión de los parámetros en la bitácora para todos los métodos de nuestra aplicación:

Foobar.java

public String doSomething(String param) {
  SecurityModule.isUserEnabled(param);

  Logger.debug(user + ":doSomething():" + param);
  …
  //Do Something
}

public String doSomethingElse(String param, int param2) {
  SecurityModule.isUserEnabled(param);

  Logger.debug(user + ":doSomethingElse():" + param + ":" + param2);
  …
  //Do something else
}

Entonces, las llamadas al módulo de seguridad y logger de la bitácora son aspectos que se replican a través de muchos puntos dentro de nuestra aplicación. Extraer estas llamadas programáticamente definidas del código e implementarlas por separado, al mismo tiempo que configuramos declarativamente dónde y bajo qué circunstancias deben ejecutarse es el punto focal del AOP. Sin detallar demasiado en este tema, baste decir que frameworks de desarrollo como Spring y AspectJ facilitan su implementación de forma adecuada. Por ejemplo, usando Spring 2.0 con Anotaciones de Java, el ejemplo anterior pasaría a ser algo así:

Foobar.java

public String doSomething(String param) {
  //Do Something
}

public String doSomethingElse(String param, int param2) {
  //Do something else
}


SecurityModule.java

@Aspect
public class SecurityModule {

  @Pointcut("execution(public * *(..)) && args(String,..)" )
  public void isUserEnabled(String param) throws SecurityException {
    //Valida permisos de usuario
  }
  …
}


Logger.java

@Aspect
public class Logger {

  @Pointcut("execution(public * *(..)) && args(String,..)" )
  public void debug(String message){
    //Imprime el mensaje en la bitacora
  }
  …
}

Nótese cómo el código de la aplicación queda 100% dedicado a funcionalidad, dejando al framework el trabajo de resolver cuándo y dónde se realizan las llamadas a los módulos de seguridad y logger.

Como conclusión, al menos en el caso de aplicaciones desplegadas en un contenedor de servlets o EJBs, nunca deben usarse las instrucciones System.out.println ó System.err.println para depurar nuestro código. Para eso existen frameworks como log4j. Y aún así hay que usar estas herramientas con moderación.

Por otro lado, si la limpieza del código es un tema crítico, podemos "despegar" un poco la implementación mediante patrones de diseño; si queremos implementar la solución más efectiva posible es necesario cambiar la forma en que programamos y usar frameworks que implementen la Programación Orientada a Aspectos para separar por completo la lógica aplicativa de la "lógica de soporte".

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. Cerrar sesión / Cambiar )

Imagen de Twitter

Estás comentando usando tu cuenta de Twitter. Cerrar sesión / Cambiar )

Foto de Facebook

Estás comentando usando tu cuenta de Facebook. Cerrar sesión / Cambiar )

Google+ photo

Estás comentando usando tu cuenta de Google+. Cerrar sesión / Cambiar )

Conectando a %s

A %d blogueros les gusta esto: