Spring AOP: logging and nested-methods

Question

I have written a simple Spring2.5 app to demo/test AOP; specifically, I want to log the entry and exit of every method of every class in a specific package. This is what I have...

(note: I am using annotation-controllers; I am omitting details not directly-related to aop because my basic setup works fine -- I am only including aop-related details -- let me know if you need to see more)

---

applicationContext.xml :

(...)
<bean id="loggerInterceptor" class="aspect.LoggerInterceptor" />
(...)

dispatcher-servlet.xml :

(...)
<aop:aspectj-autoproxy proxy-target-class="true" />
(...)

HomeController.java :

public class HomeController() {

    public HomeController() { }

    public ModelAndView get() {
        System.out.println("In HomeController#get()...");

        this.somePrivateMethod();
        this.somePublicMethod();

        return new ModelAndView( "home" );
    }

    private void somePrivateMethod() {
        System.out.println("In HomeController#somePrivateMethod()...");
    }

    public void somePublicMethod() {
        System.out.println("In HomeController#somePublicMethod()...");
    }
}

LoggerInterceptor.java :

public class LoggerInterceptor {

    @Pointcut("execution(* controller.*.*(..))")
    private void anyOperationInControllerPackage() {
        /* nothing to do here;
         * this just defines that we want to catch all methods
         * in the controller-package
         */
    }

    @Around("anyOperationInControllerPackage()")
    public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {

        System.out.println("Entering " + joinPoint.getSignature().getDeclaringTypeName() + "#" + joinPoint.getSignature().getName() + "() using arguments: " + Arrays.toString( joinPoint.getArgs() ) );

        try {

            Object result = joinPoint.proceed();

            System.out.println("Leaving " + joinPoint.getSignature().getDeclaringTypeName() + "#" + joinPoint.getSignature().getName() + "()." );

            return result;

        } catch (Throwable ex) {

            ex.printStackTrace();
            throw ex;

        }

    }

}

---

Here is what I'm getting when HomeController#get() is invoked:

Entering controller.HomeController#get() using arguments: []
In HomeController#get()...
In HomeController#somePrivateMethod()...
In HomeController#somePublicMethod()...
Leaving controller.HomeController#get().

As you can see, the only method that's getting intercepted is HomeController#get(). When #get() calls #somePrivateMethod() or #somePublicMethod(), the interceptor doesn't catch those. I would expect, at the very least, that #somePublicMethod() would also get caught (and since I'm using cglib, I would also expect that #somePrivateMethod() would get caught).

So I guess my question is what do I need to change/add in order to allow (at the very least) all public methods in the controller-package to get caught even when another method in that package called them and was itself caught first???

I hope that makes sense. :D

---

EDIT(25APR2011 @ 1:13PM)

applicationContext.xml :

(...)
<context:load-time-weaver />  <!-- added -->
<bean id="loggerInterceptor"... />
(...)

---

aop.xml :

<!DOCTYPE aspectj PUBLIC
    "-//AspectJ//DTD//EN" "http://www.eclipse.org/aspectj/dtd/aspectj.dtd">
<aspectj>
    <weaver>
        <!-- only weave classes in this package -->
        <include within="controller.*" />
    </weaver>
    <aspects>
        <!-- use only this aspect for weaving -->
        <aspect name="aspect.LoggerInterceptor" />
    </aspects>
</aspectj>

---

In Netbean's "Project Properties" under the "Run" tab I added this line to the "VM Options" :

-javaagent:C:\Users\bgresham\Documents\libraries\spring-framework-2.5\dist\weaving\spring-agent.jar

---

As before, I'm not getting any errors -- I just don't get the "nested"-logging I'm looking for.

???

Answer 1

If you're using Spring AOP, you must only call a method that's had an aspect applied to it via a reference returned by Spring, not through this, and I don't think you can apply pointcuts to private methods either (might be wrong on that last part). That's because Spring AOP applies the pointcuts through the proxy object, not by class rewriting (which is what AspectJ does). The benefit of that heavy restriction is that it is much easier to make it work in containers (I know from experience that Spring AOP works just fine inside Tomcat) because there's no warring over what bits are plugged in where.

The best way of doing this is by splitting the class definition so that you never call a method via this, but if that's not possible then you can always try giving a bean a Spring-derived reference to itself:

private HomeController self;
@Required
public void setSelf(HomeController self) { this.self = self; }

public ModelAndView get() {
    System.out.println("In HomeController#get()...");

    self.somePrivateMethod();
    self.somePublicMethod();

    return new ModelAndView( "home" );
}

(This is pretty neat; self is a keyword in a number of languages but not Java so it's relatively easy to remember what you're using it for.)

Answer 2

You are using spring aop for aspect support. Spring aop will work only on spring beans. So, the pointcut does not work on the actual class instance i.e. when the controller calls any of its public or private method. In order to log all the methods in the controller, you need to use AspectJ for your aop support by enabling either load time or compile time weaving of all the classes that you want to intercept. Edit:

You would need the following for load time weaving :

aop.xml

<!DOCTYPE aspectj PUBLIC "-//AspectJ//DTD//EN" "http://www.eclipse.org/aspectj/dtd/aspectj.dtd">    
<aspectj>    
    <weaver options="-Xset:weaveJavaxPackages=true -verbose -showWeaveInfo -debug">    
        <include within="*"/>
    </weaver>
    <aspects>
        <!-- weave in just this aspect -->
        <aspect name="your.logger.impl.LoggingImpl"/>
    </aspects>
  </aspectj>

This implies weaving in all your files ('within=*', modify as you wish) with the aspect/s specified. On load time you should see verbose information on weaving of classes.

Configurations in the spring configurations :

<context:load-time-weaver aspectj-weaving="autodetect" 

            weaver-class="org.springframework.instrument.classloading.ReflectiveLoadTimeWeaver"/>

Notice the weaving class has to be in the server library path and NOT your application path.

The above configurations should do what you are looking out to do.