Logging de una aplicación Java mediante Spring AOP

1. Introducción

Al desarrollar aplicaciones debemos tener en mente que los mensajes de log van a ser imprescindibles una vez nuestra aplicación se encuentre en producción, ya que si ésta fallase necesitaremos una traza completa de mensajes de log que nos indiquen qué estaba haciendo la aplicación en el momento de fallar. Sin esos mensajes y sin las trazas de error puede ser muy difícil o incluso imposible averiguar qué ha pasado realmente para que nuestra aplicación haya fallado.

No sólo eso, sino que durante el desarrollo tambien deberemos contolar la ejecución de la aplicación mientras ésta se construye, asegurándonos de que funciona según lo esperado. Es por ello que existen varias técnicas con las que realizar tareas de depuración de código una vez éste se ha ejecutado, entre ellas las siguientes:

1. Usar puntos de ruptura y ejecutar paso a paso.
2. Imprimir mensajes de depuración en la consola.
3. Usar proxys dinámicos
4. Usar herramientas de profiling.
5. Emplear aspectos.

Sin embargo, ¿son estas técnicas excluyentes entre sí?. No necesariamente, podriamos decir que son complementarias, ya que durante el desarrollo puede ser interesante poner, en momentos puntuales, un punto de ruptura o ejecutar paso a paso mientras que en producción esto es impensable.

En este tutorial nos centraremos en la 5ª de las opciones, utilizando para ello Spring AOP. En adictosaltrabajo hemos hablado otras veces de Spring y de aspectos (AOP). En el tutorial voy a usar como ejemplo un DAO, pero podriamos estar logueando cualquier tipo de clase.

¿Qué ventajas vamos a tener al seguir las trazas con AOP?. Varias, entre las que cabe destacar que no tenemos que poner en el código ninguna traza, con lo que al programar podremos centrarnos únicamente en lo que debe hacer el código, «olvidándonos» de qué trazas debe mostrar.

La lista de técnicas la he obtenido de aquí, llegando hasta ahí desde esta noticia de javahispano.

2. Entorno

• Debian GNU/Linux 4.1 (Lenny)
• JDK 6 Update 1
• Spring 2.5

3. ¿Qué necesitamos?

Como vereis necesitamos poca cosa:

1. Un bean normal y corriente de Spring (en este ejemplo un DAO)
2. Un interceptor
3. Hacer un par de cambios en el fichero de contexto de Spring

La idea está en que al invocar al DAO, en realidad invoquemos al interceptor. El interceptor ejecutará el código que queramos, ejecutará el método del DAO que se desee ejecutar, y tras eso ejecutará más código que queramos (donde obviamente entre «el código que queramos» podremos poner una llamada al logger ;-))

3.1 El bean normal y corriente de Spring

Este bean será la «víctima» del interceptor. Como se puede ver es un bean normal y corriente.

3.2 El interceptor

Esta será la clase que hará cosas antes y después de ejecutar los métodos del objeto interceptado.

import org.aopalliance.intercept.MethodInterceptor;
import org.aopalliance.intercept.MethodInvocation;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

/**
 * Clase encargada de interceptar las llamadas al DAO para logear las operaciones realizadas sobre ellos
 */

public class DAOLoggerInterceptor implements MethodInterceptor {

	private final static Log logger = LogFactory.getLog(DAOLoggerInterceptor.class);

	public Object invoke(final MethodInvocation methodInvocation) throws Throwable {

		final long startTime = System.currentTimeMillis();
		try 
		{
			return methodInvocation.proceed();
		} 
		finally 
		{
			// generamos la lista de argumentos que recibe el metodo separados por una coma
			String arguments = new String();			
			for (int i = 0; i < methodInvocation.getArguments().length; i++) {
				arguments += methodInvocation.getArguments()[i] + " ,";				
			}
			
			// el metodo recibe al menos un argumento quitamos el espacio y la coma del final
			if (arguments.length()> 0) {
				arguments = arguments.substring(0, arguments.length() - 2);
			}
			
			logger.debug("[ " +	(System.currentTimeMillis() - startTime) + " ms" + " ] " +
						methodInvocation.getMethod().getDeclaringClass().getSimpleName() + "." +
						methodInvocation.getMethod().getName() + "(" +
						arguments + ")");
		}
	}
}

En este código de ejemplo, el interceptor:

1. Antes de invocar al método, obtiene el número de milisegundos desde 1900 para poder mostrar en la traza cuánto tiempo ha tardado el método en ejcutarse.
2. Ejecuta el método objetivo
3. Muestra el número de milisegundos que ha tardado el método en ejecutarse seguido del nombre de la clase, del nombre del método y de los parámetros recibidos por el método.

Gracias a este interceptor podemos quitar el logger del DAO porque ya no hace falta. Cuando se invoque cualquiera de sus métodos se lanzará el interceptor que ya se encargará del log en lugar de hacerlo el DAO. Con ello el código del DAO queda más limpio.

En este tutorial sólo hay un DAO y un interceptor, pero podria haber más DAO y clases en general que utilizasen el mismo interceptor. Fijaros en que el interceptor extiende de la clase MethodInterceptor

3.3 Cambios en el contexto de Spring

Lo único que falta ahora es configurar el contexto para que se ejecute el interceptor antes que la clase interceptada. Para ello deberemnos hacer los siquientes cambios:

• Declarar el interceptor, que como podéis ver es muy sencillo:
• Remombrar el viejo DAO, poniéndole el sufijo ‘Target’:
• Crear un nuevo bean que se llame igual que el interceptado (autentiaDao) para que la aplicación pase a usar el nuevo en vez del viejo:

        
		
			com.autentia.logspringaop.dao.impl.AutentiaDao
		
		
			
				daoLoggerInterceptor
				autentiaDaoTarget
			
		
	

Fijaros en los 3 campos <value>, y en que en ellos se pone la clase DAO objetivo, el interceptor, y el nuevo nombre que tenga el antiguo DAO.

Tras haber hecho estos cambios ya disfrutareis de un DAO cuyas trazas de log se escriben mediante AOP.

4. Conclusiones

Como ya he ido comentando a lo largo del tutorial, el uso de aspectos para mostrar trazas de log me parece especialmente cómodo ya que al escribir código no hay que preocuparse del log, dejando el código más limpio y permitiendo que los log no distraigan de su lectura.

Aparte, tal y como hemos visto en el tutorial, podemos acceder a todo tipo de información del método, como por ejemplo qué parámetros recibe. Tambien podriamos haber cubierto casos en los cuales los métodos lancen excepciones, pero lo dejaremos para otro tutorial 🙂

Tambien hemos podido ver que es muy sencillo de configurar, ya que sólo deberemos hacer un par de cambios en el contexto de Spring. En definitiva, es una opción muy recomendable.

Espero que os sea de utilidad.