how to do logging of method chaining using spring aop

Question

I am using slf4j with Spring AOP for logging and Exception purpose.there are some methods in some classes which formed a method chaining. I am able to log at first method's entry and exit point but when this method called another method then AOP is logging only first method's entry and exit point.I want to log every method's entry and and exit point using @Around annotation here is Pseudo code to explain what i want

package com.sample;
public class Test implements T{

@Override
 public void show() {
   System.out.println("Test.show()");
   test();
  }
  void Test(){
   //Want to log entry and exit point of this method whenever this method called by any other method
   //The method may belongs to same class or different package's different class
  }

spring.xml is something like this

<bean id="exceptionAspect" class="com.sample.ExceptionAspect"/>
<bean id="test" class="com.sample.Test"/>

My Advise class look like

@Aspect
public class LoggingAspect {
@Around(value="execution (* com.sample.*.*(..))||"+
              "execution(* some other package.*.*(..))")
public void logAround(ProceedingJoinPoint joinPoint) throws Throwable {
      final Logger logger = LoggerFactory.getLogger(joinPoint.getTarget().getClass());
      logger.info("Execution of : " + joinPoint.getSignature() + " Started");
      joinPoint.proceed();
      logger.info("Execution of : " + joinPoint.getSignature() + " completed");
  }

}

Client class

package com.test;
public class App {
   public static void main(String[] args) throws Exception {

    ApplicationContext appContext = new ClassPathXmlApplicationContext(
                "classpath:/META-INF/spring.xml");

        T test=(T) appContext.getBean("test");
        test.show();
    }

Any Help is greatly appreciated..

Answer 1

What you are trying to do is not possible with Spring AOP (at least not without some refactoring of the advised methods). The reason for that is that Spring AOP is proxy based, which means for each bean it creates a proxy class and injects it instead of your implementation. A proxy has all the methods of the bean with added aspect functionality. So When you call a method of a bean (actually the proxy of the bean), the aspect code is executed and your method is then called by delegation. So when your method calls other methods the call are performed using the real beans, not the proxies of those - if any are present - hence you don't get the output you are expecting.

You can think of a proxy it looks somehow like that:

class MyBeanProxy implements MyBean {

    MyBeanImpl theBean;

    public void foo() {
        // aspect code
        theBean.foo();
    }
    public void bar() {
        // aspect code
        theBean.bar();
    }
}

Where your bean is something like

interface MyBean {
    foo();
    bar();
}

@Component("my_bean")
class MyBeanImpl implements MyBean {
    public void foo() {
        System.out.println("foo");
        bar();
    }
    public void bar() {
        System.out.println("bar");
    }
}

In the example above, when you call foo() via the proxy then the aspect code is executed, and the delegation to MyBeanImpl#foo() happens, where bar() is being called. Now it becomes obvious that the aspect code for bar() will not be executed.

Now how can you make it work?

1 - Refactor your code in such a way that for methods you want to have the aspect code executed for them the calls happen on the proxy object not on the bean itself. For that you can get the actual proxy and use it to call your methods.

public void foo() {
    System.out.println("foo");
    MyBean myBeanProxy = (MyBean) AopContext.currentProxy();
    myBeanProxy.bar();
}

Note that this method is more of a hack than a clean way to do the job. For example it is obvious that myBeanProxy has no clue of the state of your current object.

2 - Refactor you code in such a way that bar() is in another bean which you can retrieve using your appContext.

3- Use AspectJ: Aspect code is injected into the target classes themselves (The real thing!)

Here is small example using AspectJ

Aspect

package com.aj;

import java.util.Arrays;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;

@Aspect
public class MyAspect {

    @Around("execution( * com.app.services.*.* (..) )")
    public Object callDurationAdvice(ProceedingJoinPoint pjp) throws Throwable {
        Signature signature = pjp.getSignature();
        Object[] args = pjp.getArgs();
        String argList = Arrays.toString(args);
        System.out.println(signature.getDeclaringTypeName() +
                "." + signature.getName() + "(" + argList + ") started");
        long s = System.nanoTime();
        Object proceed = pjp.proceed(args);
        long e = System.nanoTime();
        System.out.println(signature.getDeclaringTypeName() +
                "." + signature.getName() + "(" + argList + ") ended after " +
                ((double)(e-s)/1000000) + " ms");
        return proceed;
    }
}

One class in some package witch should be target for the aspect

package com.app.services;

public class ServicesVersionInfo {

    public static String getVersion() {
        return getVersionNumber() + " " + getVersionStage();
    }

    public static String getVersionNumber() {
        return "1.0.0";
    }

    public static String getVersionStage() {
        return "ALPHA";
    }
}

The App

package com.app;

import com.app.services.ServicesVersionInfo;


public class App {

    public static void main(String[] args) {
        System.out.println("App services version: " + 
            ServicesVersionInfo.getVersion());
    }
}

Ran, this should output something lie that

com.app.services.ServicesVersionInfo.getVersion([]) started
com.app.services.ServicesVersionInfo.getVersionNumber([]) started
com.app.services.ServicesVersionInfo.getVersionNumber([]) ended after 0.004862 ms
com.app.services.ServicesVersionInfo.getVersionStage([]) started
com.app.services.ServicesVersionInfo.getVersionStage([]) ended after 0.005673 ms
com.app.services.ServicesVersionInfo.getVersion([]) ended after 0.378877 ms
App services version: 1.0.0 ALPHA

Finally here are some similar questions and further readings:

Spring AOP not working for method call inside another method

Get AOP proxy from the object itself

Spring AOP top problem #1 - aspects are not applied