Run @Before advice before @Around advice in Spring Boot AOP

I'm building a Spring Boot v3.1.1 application and I want to use AOP to do certain things, for example, print logs to the console.

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

With this custom annotation, I print to the console when the execution enters and exit from the method in my service.

@LogAround
public String getName(@Long userId) {
   return "Lorem";
}

// Prints to console:
03:54PM INFO MyService : getName started.
03:55PM INFO MyService : getName finished.

See implementation of the LogAround below.

The @LogAround is optional in my code and just a few methods has it.

Now, I have the need of creating another advice to run on all methods (those who uses a custom execution annotation) to put some data to MDC.

// Pointcut expressions.
@Pointcut("execution(@UserIdRestricted * *(..))")
    public void userIdRestricted() {
}

@Pointcut("@annotation(LogAround)")
    public void logAround() {
}

// Pointcut signatures.
@Around("userIdRestricted()")
public Object verifyUserIdRestriction(ProceedingJoinPoint joinPoint) throws Throwable {}

@Around("logAround()")
public Object logAroundImpl(ProceedingJoinPoint joinPoint) throws Throwable {
   Logger logger = LoggerFactory.getLogger(joinPoint.getSignature().getDeclaringType());
   String methodName = joinPoint.getSignature().getName();

   logger.info("{} started", methodName);

   Object proceed;
   try {
       proceed = joinPoint.proceed();
   } catch (Throwable ignored) {}

   logger.info("{} finished", methodName);

   return proceed;
}

// The new one
@Before("userIdRestricted()")
public void putUserIdToMdc(JoinPoint joinPoint) throws Throwable {
   log.info("putUserIdToMdc");
   MDC.put("userId", String.valueOf(1234));
}

The result of this in the console is:

03:54PM INFO MyService  : {} getName started. // <== It was run first and has no MDC data
03:54PM INFO AspectImpl : {} putUserIdToMdc
03:54PM INFO MyService  : {userId=1234} getName finished.

The advice putUserIdToMdc() is running after the logAroundImpl(). This means that the first log from logAroundImpl() won't have the MDC data.

I'm not very skilled in the ways to configure an advice with some strange conditions.

I have tried to find a way on another topics that let me describe this way of thinking:

Run this advice, but if you encounter a @LogAround, then run this first.

No luck....

How can I set the putUserIdToMdc() to run first?

Thanks in advance and any help on this topic would be highly appreciated.

Solution

I did your job by fixing and amending your fragmentary code, which was quite a bit of work, just to be able to reproduce the situation and offer a solution.

Please read the Spring manual chapter on Advice Ordering in order to understand my answer better.

The gist of it is that you need to split your aspect into two separate aspects, each one doing one thing only. Then use @Order to determine which aspects have higher or lower precedence.

package de.scrum_master.spring.q76700254;

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 LogAround {}

package de.scrum_master.spring.q76700254;

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 UserIdRestricted {}

package de.scrum_master.spring.q76700254;

import org.springframework.stereotype.Component;

@Component
public class MyComponent {
  @LogAround
  @UserIdRestricted
  public String getName(Long userId) {
    return "Lorem";
  }
}

package de.scrum_master.spring.q76700254;

import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;

@Aspect
@Component
@Order(2)
public class LogAspect {
  @Pointcut("@annotation(LogAround)")
  public void logAround() {}

  @Around("logAround()")
  public Object logAroundImpl(ProceedingJoinPoint joinPoint) throws Throwable {
    Logger logger = LoggerFactory.getLogger(joinPoint.getSignature().getDeclaringType());
    String methodName = joinPoint.getSignature().getName();
    logger.info("{} {} started", MDC.get("userId"), methodName);
    Object proceed = null;
    try {
      proceed = joinPoint.proceed();
    }
    catch (Throwable ignored) {}
    logger.info("{} {} finished", MDC.get("userId"), methodName);
    return proceed;
  }
}

package de.scrum_master.spring.q76700254;

import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.core.annotation.Order;
import org.springframework.stereotype.Component;

@Aspect
@Component
@Order(1)
public class UserIdAspect {
  private static final Logger log = LoggerFactory.getLogger(UserIdAspect.class);

  @Pointcut("execution(@UserIdRestricted * *(..))")
  public void userIdRestricted() {}

  @Before("userIdRestricted()")
  public void putUserIdToMdc() {
    log.info("putUserIdToMdc");
    MDC.put("userId", String.valueOf(1234));
  }
}

package de.scrum_master.spring.q76700254;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.context.ConfigurableApplicationContext;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.EnableAspectJAutoProxy;

@SpringBootApplication
@Configuration
@EnableAspectJAutoProxy
public class DemoApplication {
  public static void main(String[] args) {
    try (ConfigurableApplicationContext context = SpringApplication.run(DemoApplication.class, args)) {
      System.out.println(context.getBean(MyComponent.class).getName(123L));
    }
  }
}

Console log:

... d.s.spring.q76700254.DemoApplication     : Started DemoApplication in 6.241 seconds (JVM running for 7.431)
... d.s.spring.q76700254.UserIdAspect        : putUserIdToMdc
... d.s.spring.q76700254.MyComponent         : 1234 getName started
... d.s.spring.q76700254.MyComponent         : 1234 getName finished
Lorem