Cómo crear un logger AOP con Spring2

Una de las muchas ventajas de Spring es lo mucho que te facilita usar Programación Orientada a Aspectos (AOP)en tus proyectos. En este post explicaré como implementar un aspecto que realice la funcionalidad de logging con Log4j y Spring2. En resumen, se trata de asociar 2 trozos de código, uno se ejecutará antes y el otro justo después, a los métodos Java que se requiera para realizar la función de logging.

Preliminares

Lo primero es preparar el proyecto. Para ello hace falta realizar las siguientes acciones:
  • Copiar a la carpeta lib del proyecto al menos los módulos spring-aop.jar, spring-beans.jar, spring-context.jar y spring-core.jar, localizados en la carpeta dist/modules de tu instalación de Spring framework.
  • Copiar a la carpeta lib del proyecto las dependencias aopalliance.jar, aspectjweaver.jar, cglib-nodep-xxx.jar. Éste último puede que ya lo tengas incluido si estás usando Hibernate. Las encontrarás todas en la carpeta lib de tu instalación de Spring framework con dependencias.

Implementar el aspecto

El siguiente paso es implementar el aspecto con la funcionalidad de logging antes y después de la ejecución de los métodos objetivo (target). Para ello basta con crear una clase Java que implemente los interfaces org.springframework.aop.MethodBeforeAdvice y org.springframework.aop.AfterReturningAdvice de Spring AOP para sobreescribir así los métodos before y afterReturning que se ejecutarán antes y depués, respectivamente, de los métodos objetivo y mediante un logger de Log4j realizarán el logging.

Un ejemplo muy sencillo de esta clase, llamémosla example.util.AopLogger, sería el siguiente:
public class AopLogger implements MethodBeforeAdvice, AfterReturningAdvice {

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

public void before(Method method, Object[] args, Object target) throws Throwable {
logger.debug(method.getDeclaringClass().getName()
+ "." + method.getName() + "...");
}

public void afterReturning(Object returnValue, Method method, Object[] args, Object target) throws Throwable {
logger.info(method.getDeclaringClass().getName()
+ "." + method.getName() + "... OK");
}
}

Configurar AOP en Spring2

El último paso es configurar el aspecto en Spring para asociarlo a los métodos de las clases Java que se requiera. Este paso es muy sencillo si utilizamos el namespace aop de Spring2. El siguiente fragmento de un fichero de configuración Spring 2.5 muestra como configurar la clase AopLogger para hacer logging de los métodos públicos de todas las clases del paquete example.services del proyecto.
<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:aop="http://www.springframework.org/schema/aop"
xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.5.xsd
http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-2.5.xsd">

<aop:config>
<aop:advisor pointcut="execution(* example.services..*.*(..))"
advice-ref="aopLogger" />
</aop:config>

<bean id="aopLogger" class="example.util.AopLogger" />
[...]
</beans>

La consecuencia de usar AOP es clara, te evitas escribir el código de ejecución de un servicio transversal por todas tus clases Java, en este caso ha sido el logging pero también auditoria, autenticación, autorización, control transaccional, etc. Las ventajas son inmediatas, mayor modularidad, separación de conceptos y comprensión del código.

Puedes consultar más información sobre AOP y Spring, incluyendo otros ejemplos de puntos de ejecución, aquí.

4 comentarios :: Cómo crear un logger AOP con Spring2

  1. Muchas gracias, llevaba queriendo probar esto desde hace tiempo.

    ¿Sabes si supone una penalización sensible al rendimiento, ya que usa Reflection y las guardas de código (logger.isDebugEnabled) no se pueden aplicar a la propia llamada al before y al after?

    Por otra parte, quizás sea complicado llegar a tomar el log totalmente como un aspecto, pues casi siempre habrá llamadas muy ligadas al código interno del método. Sin embargo, con tu solución ya nos ahorramos código que no tiene ningún significado en el negocio.

    Enhorabuena por el blog.

  2. Hola Javier.

    Gracias a ti por tu interés y tu comentario.

    No entiendo lo de: las guardas de código (logger.isDebugEnabled) no se pueden aplicar a la propia llamada al before y al after.
    ¿Quieres decir que los mensajes de log (logger.debug(o.construyeMsg()))son construidos igualmente uses o no el isDebugEnabled?
    Si estas en lo cierto, si que podria llegar a ser una grave penalizacion ya no solo en tiempo de ejecucion, sino en consumo de memoria!

    Comparto tu opinion que si bien el ejemplo de log es un ejemplo muy inmediado y facil de ver, no es el mejor ejemplo practico. Yo lo uso para capas especificas como la de services o dao o las llamadas a los Stubs de webservices para imprimir las peticiones y respuestas. Para otras cosas sigo haciendo log 'a mano'.

  3. Sí, a lo que me refiero es que, si bien la ejecución del logging puede controlarse según el nivel de log configurado, Spring siempre va a invocar los métodos before y after, independientemente de dicho nivel. Esos métodos son los que hacen uso de Reflection, que es un API algo costoso.
    ¿Se podría configurar el AOP de Spring para que, al igual que sólo funciona con los métodos de paquetes example.services.*, sólo se invocasen en el caso de que el nivel de log4j fuera debug? Eso sería interesante.

    El ejemplo es muy bueno, sobre todo para casos como el que comentas, donde puedes volcar toda la comunicación al log, cosa que es bastante útil.

    Gracias otra vez.

  4. Ah vale! Ahora te entiendo. Si es cierto que el reflection dicen que tiene su coste. No lo he medido, creo que se usa una especie de cache para que no sea tan costoso. Pero seria interesante medirlo. A ver si saco tiempo...

    Para lo que quieres puedes usar parametros en la declaracion del pointcut. Entonces podrias crear un metodo isDebugEnabled en el aspecto que delegue en el logger y usarlo en la declaracion del pointcut con un &&.

    Puedes ver ejemplos en el enlace al final del post.

Publicar un comentario