Logging with Spring AOP

Posted in: Spring IoC

One of the questions that arise time and again during project development is logging. As its already known a good way to handle it, is using aspects and our favorite Java framework, Spring.  

If you search a little you can find several tutorials about logging and AOP but, at least in my opinion, their authors were more interested in explaining AOP than resolving the logging concern. Meanwhile I was considering a topic for this, my first blog entry..so let this be it!

As I have mentioned there already are some tutorials that can help you creating a logging interceptor (see this for example). I wanted a little twist so I decided to go with the Java5 path. Our first task then is to create an annotation that will later be used in a method (can be modifed to be applied to classes if you wish) to declare our logging needs. Take in account that, as in a JEE container, Spring can only manage and proxy beans in its context, so only methods managed by Spring directly should be annotated. No more considerations, let's do it!

@Documented
@Retention(value=RetentionPolicy.RUNTIME)
@Target(value={ElementType.METHOD})
public @interface LogDebug
{
   Class loggerClass();
}

The code above is very simple. It just defines an annotation which accepts a parameter of type java.lang.Class. This parameter will be of use as it will determine the class that should be written in the output.

The next step should be creating the aspect. We can start creating an skeleton of the class:

@Aspect
public class LogDebugInterceptor {

   @Before("@annotation(com.indra.rfef.annotations.LogDebug)")
   public void beforeLog(JoinPoint jp) {
      ...
   }

   @AfterReturning(
      pointcut="@annotation(LogDebug)",
      returning="retVal")
   public void afterLog(JoinPoint jp, Object retVal) {
      ...
   }
}

I'm going to try to explain the above code in detail. First of all, we have annotated our class as an Aspect, this means Spring will recognize it as such and create the needed proxies. We have then annotated two methods, one with @Before and the second as @AfterReturning. With this two annotations, called Advices, we are declaring when we expect the interceptor to start working. In our case just before entering the method and just after it has finished. Another useful times are covered by @AfterThrowing (for exception handling), @After (finally) or @Around (more complex advice that can work before and after with a powerful configuration). We have set the time but not the place where this interceptor is supposed to fire. This is done defining a PointCut. Pointcuts can be complex to be defined (AspectJ Pointcuts) but not in our case where we just need to stop when you have a method annotated with our previously defined LogDebug interface. Notice that the second method defines a value to store the result of the execution.

Finally we have to complete the logging code. First we need to obtained the method that was called in runtime and was annotated with @LogDebug. As you can see the code is a little bit more complicated than it should look. This is because methods can be declared somewhere (an interface for example) and be overriden/implemented later. We are interested in the actual (called) method.

protected Method getMethod(JoinPoint jp) {
   Method invoked = null;
   try {
      MethodSignature met = (MethodSignature) jp.getSignature();
      invoked = jp.getSourceLocation().getWithinType().getMethod(
                 met.getMethod().getName(),
                 met.getMethod().getParameterTypes());
   } finally {
      return invoked;
   }
}

protected Log getLog(JoinPoint jp) {
   Log log = null;
   try {
      LogDebug logdebug = this.getMethod(jp).getAnnotation(LogDebug.class);
      Class clazz = logdebug.loggerClass();
      if (clazz == null) clazz = LogDebugInterceptor.class;
      log = LogFactory.getLog(clazz);
   } finally {
      if (log == null) log = LogFactory.getLog(LogDebugInterceptor.class);
   }
   return log;
}

public void beforeLog(JoinPoint jp) {
   Log log = this.getLog(jp);
   if (log.isDebugEnabled()) {
      log.debug(this.getMethod(jp));
      for (Object o : jp.getArgs()) {
         if (o != null) {
            log.debug("PARAMETER " + o.getClass().getSimpleName());
            log.debug(o.toString());
         }
      }
   }
}

public void afterLog(JoinPoint jp, Object retVal)
{
   Log log = this.getLog(jp);
   if (log.isDebugEnabled()) log.debug(retVal);
}

<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.0.xsd
http://www.springframework.org/schema/aop
http://www.springframework.org/schema/aop/spring-aop-2.0.xsd">

   <aop:aspectj-autoproxy proxy-target-class="false" />

   <bean id="logInterceptor" class="es.internna.spring.LogDebugInterceptor" />

</beans>