How can I implement nested logging within a Spring component with AspectJ?

Question

I'm working on a Spring Boot Gradle project with Java, where logging is done manually in every function that needs to be logged. In each function that requires logging, a new instance of a custom logger is initialized with the help of Lombok's @Cleanup annotation. The custom logger implements the AutoCloseable interface, so the @Cleanup annotation automatically closes the resource when the function ends. It works like this:

public void someFuction(String str) {
    @Cleanup var logging = new CustomLogger(log, "someFuction", str); //NOSONAR
    logging.startLogging();
    ....
    Some logic
    .....
}

The @Cleanup annotation essentially puts the code in a try/finally block, so it works something like this under the hood:

public void someFuction(String str) {
    try{
        CustomLogger logging = new CustomLogger(log, "someFuction", str); //NOSONAR
        logging.startLogging();
        ....
        Some logic
        .....
    } finally(){
        logging.close();
    }
}

This approach works fine, but having to copy two lines into every function that needs to be logged and manually passing the function name, logger, and parameters of the function every time does not seem like a "clean" solution, and it introduces critical Sonar problems as well.

So, I thought I could achieve the same effect easily with a custom annotation and with the help of Spring AOP, more specifically, the AspectJ library.

import lombok.extern.slf4j.Slf4j; 
import org.aspectj.lang.JoinPoint; 
import org.aspectj.lang.annotation.AfterReturning; 
import org.aspectj.lang.annotation.AfterThrowing; 
import org.aspectj.lang.annotation.Aspect; 
import org.aspectj.lang.annotation.Before; 
import org.springframework.stereotype.Component;

@Aspect 
@Component 
@Slf4j 
public class LoggingAspect {
    private ThreadLocal<CustomLogger> businessLoggingThreadLocal = new ThreadLocal<>();

    @Before("@annotation(Loggable)")
    public void logMethodStart(JoinPoint joinPoint) {
        String methodName = joinPoint.getSignature().getName();
        Object[] args = joinPoint.getArgs();

        CustomLogger businessLogging = new CustomLogger(log, methodName, args);
        businessLoggingThreadLocal.set(businessLogging);
        businessLogging.logMethodStart();
    }

    @AfterReturning(pointcut = "@annotation(Loggable)", returning = "result")
    public void logMethodEnd(JoinPoint joinPoint, Object result) {
        CustomLogger businessLogging = businessLoggingThreadLocal.get();
        if (businessLogging != null) {
            businessLogging.close();
            businessLoggingThreadLocal.remove();
        }
    }

    @AfterThrowing(pointcut = "@annotation(Loggable)", throwing = "exception")
    public void logMethodException(JoinPoint joinPoint, Throwable exception) {
        CustomLogger businessLogging = businessLoggingThreadLocal.get();
        if (businessLogging != null) {
            businessLogging.close();
            businessLoggingThreadLocal.remove();
        }
    }
}

This is my custom annotation:

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Loggable {}

This "wrapper" around the existing logging mechanism seems fine at first glance, but it cannot perform nested logging within the same Spring component. If a method calls a method in another component, the logging works fine, but if it were to call a method in the same component, it simply does not log the other method.

For example:

@Service 
public class ExampleService { 
    .... 

    @Loggable 
    public void someMethod(){ 
        .... 
        some logic 
        .... 
        anOtherMethod(); 
    }

    @Loggable
    public void anOtherMethod(){
        ....
        some logic
        ....
    }
}

The expected logging would be:

Method started: someMethod()
Method started: anOtherMethod()
Method ended: anOtherMethod()
Method ended: someMethod()

But the actual logging, when both of the fuctions are in the same component, is:
(It works fine, the above mentioned way, if the anOtherMethod() in an a different component)

Method started: someMethod()
Method ended: someMethod()

I'm using this gradle plugin:
id("io.freefair.aspectj") version "8.0.1"

and this dependency:
implementation("org.aspectj:aspectjrt:1.9.7")

It is possible to do nested logging in the same component with AspectJ?If not or if it is not recommended are there better ways to approach this problem?

Answer 1

It is like Spring AOP works. Aspects are not called when you call a method inside the same class, but only from outside of the class. However, if you want to enforce to have the Aspect called inside the same class, you can do something like this:

@Resource
private ExampleService self = this;

public void someMethod() {
    self.method2();
}

public void anOtherMethod() {

}

Check this out for more info: https://docs.spring.io/spring/docs/current/spring-framework-reference/core.html#aop-understanding-aop-proxies

Answer 2

@kriegaex Thank you, your comment definitely help a lot. Since then I've managed to get the post comple weaving get to work and now the nested logging works. The only thing is that the logs at the start of a fuctions are printed twice.

As a previous Spring AOP user, you might be used to the fact that Spring AOP only knows execution joinpoints, but native AspectJ knows several more, most prominently call ones. I.e., for the same method, it can intercept the method call (in the calling method) and the method execution (in the called method).

The end of the function log is only once.

That would surprise me. For the same method call/execution, the result should be consistent. Probably you overlooked or misinterpreted something in your log.

In order to see the difference, simply add something like

System.out.println("[ENTER] " + joinPoint);

and

System.out.println("[EXIT] " + joinPoint);

to your advice methods.

You can fix the problem in several ways, e.g. like this:

@Before("@annotation(Loggable) && execution(* *(..))")

If you do not wish to repeat the same pointcut expression in 3 separate advice methods, simply factor them out into one @Pointcut expression, referring to the same pointcut in all advice methods.