Using Spring AOP to Trace Invocation

The idea behind the proposed solution is to wrap the bean, which invocations you are going to trace, with a proxy that has SimpleTraceInterceptor or DebugInterceptor in the interceptorNames property. The interceptors mentioned are implementations of around advice that will write all the invocations' details to some logger (the way we choose our logger is discussed later on). This Interceptors are provided with Spring core library along with CustomizableTraceInterceptor, PerformanceMonitorInterceptor and few others. I guess, an example is the best way to show how it works.

Consider this simple program: two beans, one Spring context config, and one entry-point class, that just calls the first bean's method( so it is omitted on this page).

Bean1:

package com.blogspot.mikler.java;

import org.apache.log4j.Logger;

public class Bean1 {

    Logger logger = Logger.getLogger(Bean1.class);

    Bean2 bean2;

    public void entryPoint(){
        bean2.importantMethod();
        bean2.doSomethingQuick("a job");
        logger.info("All jobs done");
    }

    public void setBean2(Bean2 bean2) {
        this.bean2 = bean2;
    }

}

 Bean2:

package com.blogspot.mikler.java;

import org.apache.log4j.Logger;

import java.text.MessageFormat;

public class Bean2 {
    Logger logger = Logger.getLogger(Bean2.class);

    public void importantMethod(){
        logger.info("Doing job for 3 seconds");
        try {
            Thread.sleep(3000);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
    }

    public void doSomethingQuick(String param1) {
        logger.info(MessageFormat.format("doing something quick with param = {0}",param1));
    }
}

The Spring Context:

<?xml version="1.0" encoding="UTF-8"?>
<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.xsd">

    <bean id="simpleTraceInterceptor" class="org.springframework.aop.interceptor.SimpleTraceInterceptor">
        <property name="useDynamicLogger" value="true"/>
    </bean>
    <bean id="debugInterceptor" class="org.springframework.aop.interceptor.DebugInterceptor">
        <property name="useDynamicLogger" value="true"/>
    </bean>

    <bean id="bean1" class="org.springframework.aop.framework.ProxyFactoryBean">
        <property name="target">
            <bean class="com.blogspot.mikler.java.Bean1">
                <property name="bean2" ref="bean2"/>
            </bean>
        </property>
        <property name="interceptorNames" value="simpleTraceInterceptor"/>
    </bean>

    <bean id="bean2" class="org.springframework.aop.framework.ProxyFactoryBean">
        <property name="target">
            <bean class="com.blogspot.mikler.java.Bean2"/>
        </property>
        <property name="interceptorNames" value="simpleTraceInterceptor"/>
    </bean>

</beans>

Running this code we get the following output:

23:13:04,348 TRACE [com.blogspot.mikler.java.Bean1] - Entering method 'entryPoint' of class [com.blogspot.mikler.java.Bean1]
23:13:04,349 TRACE [com.blogspot.mikler.java.Bean2] - Entering method 'importantMethod' of class [com.blogspot.mikler.java.Bean2]
23:13:04,349 INFO [com.blogspot.mikler.java.Bean2] - Doing job for 3 seconds
23:13:07,349 TRACE [com.blogspot.mikler.java.Bean2] - Exiting method 'importantMethod' of class [com.blogspot.mikler.java.Bean2]
23:13:07,350 TRACE [com.blogspot.mikler.java.Bean2] - Entering method 'doSomethingQuick' of class [com.blogspot.mikler.java.Bean2]
23:13:07,351 INFO [com.blogspot.mikler.java.Bean2] - doing something quick with param = a job
23:13:07,351 TRACE [com.blogspot.mikler.java.Bean2] - Exiting method 'doSomethingQuick' of class [com.blogspot.mikler.java.Bean2]
23:13:07,351 INFO [com.blogspot.mikler.java.Bean1] - All jobs done
23:13:07,351 TRACE [com.blogspot.mikler.java.Bean1] - Exiting method 'entryPoint' of class [com.blogspot.mikler.java.Bean1]

I hope the source code tells the story.

Several points that should be stressed:

• One should decide to use Dynamic Logger or not (see use DynamicLogger property of the DebugInterceptor). If the dynamic logger is used, then invocations' log messages will be written to the logger of respective bean class (log4j.logger.com.blogspot.mikler.java.* loggers in our case). Otherwise the logger of the respective Interceptor will be used, one for all of the beans.
• Make sure you enable the trace level for the selected logger. Because for optimization purposes the Interceptors don't make any job, saving your operation time, if this logging level for the logger they look up is not enabled.

 Instructions about how to check out the source code for this article you can find in the original post.