06 Spring Aop Common Errors Part 2

06 Spring AOP Common Errors Part 2 #

Hello, I am Fu Jian.

In the last lesson, we discussed several common problems encountered in Spring AOP. Through specific code analysis, I believe you now have a basic understanding of the principles of Spring AOP. However, AOP is one of the core functionalities of Spring and it is not possible to avoid all scattered issues with just two or three of them. So in this lesson, let’s continue to talk about the possible pitfalls in Spring AOP. In fact, as more and more aspects are used in a system, problems caused by execution order will gradually surface. Let’s focus on them below.

Case 1: Mixing Different Types of AOP Enhancements #

Let’s continue with the development scenario of the dormitory management system from the previous lesson.

Let’s first review it so you don’t have to dig into the code. This dormitory management system includes a module for recharging electricity, which consists of a class called ElectricService responsible for recharging the electricity, and a charge() method:

@Service
public class ElectricService {
    public void charge() throws Exception {
        System.out.println("Electric charging ...");
    }
}

To authenticate the caller’s permission before executing charge(), we added an aspect class AopConfig for Electric, which includes a @Before enhancement. This enhancement doesn’t do anything except printing a log line and simulating the permission verification process (takes 1 second).

// omitted imports
@Aspect
@Service
@Slf4j
public class AspectService {
  @Before("execution(* com.spring.puzzle.class6.example1.ElectricService.charge()) ")
  public void checkAuthority(JoinPoint pjp) throws Throwable {
      System.out.println("validating user authority");
      Thread.sleep(1000);
  }
}

After execution, we obtain the following log, and then everything continues as expected:

validating user authority
Electric charging ...

After a while, due to business development, the logic of charge() in ElectricService becomes more complex. Now, we need to perform performance statistics specifically for the charge() method of ElectricService. To avoid affecting the existing business logic, we added another enhancement in AopConfig. The modified code is as follows:

// omitted imports
@Aspect
@Service
public class AopConfig {
    @Before("execution(* com.spring.puzzle.class6.example1.ElectricService.charge()) ")
    public void checkAuthority(JoinPoint pjp) throws Throwable {
        System.out.println("validating user authority");
        Thread.sleep(1000);
    }

    @Around("execution(* com.spring.puzzle.class6.example1.ElectricService.charge()) ")
    public void recordPerformance(ProceedingJoinPoint pjp) throws Throwable {
        long start = System.currentTimeMillis();
        pjp.proceed();
        long end = System.currentTimeMillis();
        System.out.println("charge method time cost: " + (end - start));
    }
}

After execution, we obtain the following logs:

validating user authority- Electric charging …- charge method time cost 1022 (ms)

From the logs, we can see that the execution time of charge() exceeds 1 second. However, this method only prints a log line and its execution should not take that long.

Therefore, we can easily identify the problem: the execution time of charge() in ElectricService includes the time spent on authentication, which includes the time consumed by the checkAuthority() enhancement with @Around. This is not what we intended. We only want to calculate the performance of ElectricService.charge(), excluding the authentication process.

Of course, these observations are made directly from the logs. In fact, the root cause of this problem is related to the execution order of AOP. In the case at hand, if an aspect contains multiple enhancements of different types (Around, Before, After, AfterReturning, AfterThrowing, etc.), their execution order is defined. Let’s analyze this order.

Case Analysis #

In fact, we can find the truth in the source code! In Lesson 04, we mentioned that the general process for initializing singleton classes in Spring is to call getBean()->doGetBean()->getSingleton(). If the Bean does not exist, createBean()->doCreateBean() is called to instantiate it.

If we use Spring AOP in our code, the doCreateBean() method ultimately returns a proxy object. As for how the proxy object is created, we briefly outlined the process in the previous lesson. If you have a good memory, you should remember that during the creation process of the proxy object, we presented the following code snippet (refer to AbstractAutoProxyCreator#createProxy):

protected Object createProxy(Class<?> beanClass, @Nullable String beanName,
       @Nullable Object[] specificInterceptors, TargetSource targetSource) {
   // Omitted non-critical code
   Advisor[] advisors = buildAdvisors(beanName, specificInterceptors);
   proxyFactory.addAdvisors(advisors);
   proxyFactory.setTargetSource(targetSource);
   // Omitted non-critical code
   return proxyFactory.getProxy(getProxyClassLoader());
}

The advisors here are the objects for method enhancement, and the order of the advisors determines the execution order when facing multiple enhancements. The collection object itself is built by specificInterceptors, and specificInterceptors is built by the AbstractAdvisorAutoProxyCreator#getAdvicesAndAdvisorsForBean method:

@Override
@Nullable
protected Object[] getAdvicesAndAdvisorsForBean(
      Class<?> beanClass, String beanName, @Nullable TargetSource targetSource) {
   List<Advisor> advisors = findEligibleAdvisors(beanClass, beanName);
   if (advisors.isEmpty()) {
      return DO_NOT_PROXY;
   }
   return advisors.toArray();
}

In short, based on the current beanClass, beanName, and other information, combined with all the candidate advisors, eligible advisors (those that match) are finally found. Why do this? After all, AOP interception points may be configured with multiple points, and the method we execute may not be intercepted by all the interception configurations. The logic for finding matching advisors can be found in AbstractAdvisorAutoProxyCreator#findEligibleAdvisors:

protected List<Advisor> findEligibleAdvisors(Class<?> beanClass, String beanName) {
   // Find candidate advisors
   List<Advisor> candidateAdvisors = findCandidateAdvisors();
   // Calculate matching advisors based on candidate advisors and the current bean
   List<Advisor> eligibleAdvisors = findAdvisorsThatCanApply(candidateAdvisors, beanClass, beanName);
   extendAdvisors(eligibleAdvisors);
   if (!eligibleAdvisors.isEmpty()) {
      // Sort
      eligibleAdvisors = sortAdvisors(eligibleAdvisors);
   }
   return eligibleAdvisors;
}

By studying the code, we can see that the order of Advisors is determined by two points:

  1. The order of candidateAdvisors;
  2. The sorting performed by sortAdvisors.

Here we can focus on the sorting of candidateAdvisors. In fact, its order is determined when the AopConfig bean marked by @Aspect is constructed. Specifically, it sorts its own configured advisors during the initialization process and stores the sorting result in a cache (BeanFactoryAspectJAdvisorsBuilder#advisorsCache).

When creating a proxy for a bean later, the sorted candidate advisors are directly taken out. The sorting of candidate advisors occurs when the conclusion of bean construction is made. We can verify this through the stack information in the construction of the AopConfig bean:

It can be seen that the sorting is performed during bean construction, and the critical code for the final sorting execution is in the following method (refer to ReflectiveAspectJAdvisorFactory#getAdvisorMethods):

private List<Method> getAdvisorMethods(Class<?> aspectClass) {
   final List<Method> methods = new ArrayList<>();
   ReflectionUtils.doWithMethods(aspectClass, method -> {
      // Exclude pointcuts
      if (AnnotationUtils.getAnnotation(method, Pointcut.class) == null) {
         methods.add(method);
      }
   }, ReflectionUtils.USER_DECLARED_METHODS);
   // Sorting
   methods.sort(METHOD_COMPARATOR);
   return methods;
}

The key point of the above code is the methods.sort(METHOD_COMPARATOR) method on the ninth line.

Let’s take a look at the code of METHOD_COMPARATOR, and we’ll find that it is defined in a static block in the ReflectiveAspectJAdvisorFactory class:

static {
   Comparator<Method> adviceKindComparator = new ConvertingComparator<>(
         new InstanceComparator<>(...

The code omitted here provides the actual implementation of the adviceKindComparator.

   @Service
   public class ElectricService {
      @Autowired
      ElectricService electricService;
      public void charge() {
         electricService.doCharge();
      }
      public void doCharge() {
         System.out.println("Electric charging ...");
      }
   }

The ElectricService class is modified to separate the business logic of charging in the doCharge() method and call it in the charge() method.

   //Omitted imports
   @Aspect
   @Service
   public class AopConfig {
      @Before("execution(* com.spring.puzzle.class6.example1.ElectricService.charge()) ")
      public void checkAuthority(JoinPoint pjp) throws Throwable {
         System.out.println("validating user authority");
         Thread.sleep(1000);
      }

      @Around("execution(* com.spring.puzzle.class6.example1.ElectricService.doCharge()) ")
      public void recordPerformance(ProceedingJoinPoint pjp) throws Throwable {
         long start = System.currentTimeMillis();
         pjp.proceed();
         long end = System.currentTimeMillis();
         System.out.println("charge method time cost: " + (end - start));
      }
   }

The aspect code is modified to intercept the doCharge() method for performance statistics and the charge() method for authority validation.

Case 2: Confused Mixing of Same Type Enhancements #

By now, you may still have questions about the order of execution if multiple enhancements in the same aspect have the same enhancement. Let’s continue with the next case.

In this case, the business logic class ElectricService remains unchanged and only contains a charge() method:

import org.springframework.stereotype.Service;

@Service
public class ElectricService {
    public void charge() {
        System.out.println("Electric charging ...");
    }
}

The aspect class AspectService contains two methods, both of which are Before type enhancements.

The first method logBeforeMethod() is designed to print logs before the execution of run(), indicating that the method has been called once for easy future statistics.

The other method validateAuthority() is for authentication. Its purpose is to validate the authority before calling this method. If the authentication requirements are not met, an exception will be thrown. For the convenience of demonstration, this method will directly throw an exception:

// omitted imports
@Aspect
@Service
public class AopConfig {
  @Before("execution(* com.spring.puzzle.class5.example2.ElectricService.charge())")
  public void logBeforeMethod(JoinPoint pjp) throws Throwable {
      System.out.println("step into ->"+pjp.getSignature());
  }
  @Before("execution(* com.spring.puzzle.class5.example2.ElectricService.charge()) ")
  public void validateAuthority(JoinPoint pjp) throws Throwable {
      throw new RuntimeException("authority check failed");
  }
}

Our expected result of the code execution is that when the authentication fails, and ElectricService.charge() is not called, the call log of run() should not be output. In other words, logBeforeMethod() should not be called. However, the actual result is unexpected, as shown below:

step into ->void com.spring.puzzle.class6.example2.Electric.charge()- Exception in thread "main" java.lang.RuntimeException: authority check failed

Although the authentication failed, an exception was thrown and ElectricService.charge() was not called, the log for the call of logBeforeMethod() was still output. This will cause serious distortions in the subsequent call data statistics for ElectricService.charge().

Now we need to understand one question: what is the execution order of multiple enhancements in the same aspect that have the same type when modifying the same method?

Analysis #

Let’s continue searching for the truth in the source code! You should remember the static code block that defines METHOD_COMPARATOR in the above code.

METHOD_COMPARATOR is essentially a continuous comparator. In the previous case, we only looked at the first comparator. If you are attentive, you must have noticed that there is another comparator, methodNameComparator, here. Any two comparators can be connected by thenComparing() to form a continuous comparator, so that we can compare them one by one according to the order of the comparators:

static {
   // the first comparator, used to sort by enhancement type
   Comparator<Method> adviceKindComparator = new ConvertingComparator<>(
         new InstanceComparator<>(
               Around.class, Before.class, After.class, AfterReturning.class, AfterThrowing.class),
         (Converter<Method, Annotation>) method -> {
            AspectJAnnotation<?> annotation =
               AbstractAspectJAdvisorFactory.findAspectJAnnotationOnMethod(method);
            return (annotation != null ? annotation.getAnnotation() : null);
         })
   // the second comparator, used to sort by method name
   Comparator<Method> methodNameComparator = new ConvertingComparator<>(Method::getName);
   METHOD_COMPARATOR = adviceKindComparator.thenComparing(methodNameComparator);
}

As we can see, on line 12 of the code, the second comparator methodNameComparator still uses ConvertingComparator and passes the method name as a parameter. We can basically guess that this comparator sorts by method name. We can further investigate the constructor method and the comparable() method called by the constructor:

public ConvertingComparator(Converter<S, T> converter) {
   this(Comparators.comparable(), converter);
}
// omitted non-key code
public static <T> Comparator<T> comparable() {
   return ComparableComparator.INSTANCE;
}

The ComparableComparator instance in the above code is extremely simple. The code is as follows:

public class ComparableComparator<T extends Comparable<T>> implements Comparator<T> {
 
   public static final ComparableComparator INSTANCE = new ComparableComparator();

   @Override
   public int compare(T o1, T o2) {
      return o1.compareTo(o2);
   }
}

The answer is completely consistent with our guess. The methodNameComparator ultimately calls the compareTo() method of the String class itself:

public int compareTo(String anotherString) {
    int len1 = value.length;
    int len2 = anotherString.value.length;
    int lim = Math.min(len1, len2);
    char v1[] = value;
    char v2[] = anotherString.value;

    int k = 0;
    while (k < lim) {
        char c1 = v1[k];
        char c2 = v2[k];
        if (c1 != c2) {
            return c1 - c2;
        }
        k++;
    }
    return len1 - len2;
}

And now the answer is revealed: if the lengths of the two method names are the same, then each letter’s ASCII code is compared in sequence. The smaller the ASCII code, the earlier it is sorted. If the lengths are different and the shorter method name string is a subset of the longer one, the shorter one will come first in the sorting order.

Issue Resolution #

From the above analysis, we know that in the same aspect configuration class, when there are multiple enhancements of the same type for the same method, the execution order is only related to the name of the current enhancement method, not to the order of the code. Knowing this, we can directly fix the program by adjusting the method name:

// omitted imports
@Aspect
@Service
public class AopConfig {
  @Before("execution(* com.spring.puzzle.class6.example2.ElectricService.charge())")
  public void logBeforeMethod(JoinPoint pjp) throws Throwable {
      System.out.println("step into ->"+pjp.getSignature());
  }
  @Before("execution(* com.spring.puzzle.class6.example2.ElectricService.charge()) ")
  public void checkAuthority(JoinPoint pjp) throws Throwable {
      throw new RuntimeException("authority check failed");
  }
}

We can change the original validateAuthority() to checkAuthority(). In this case, the order of enhancements (advisors) is actually determined by comparing the characters l and c. It is obvious that checkAuthority() will be sorted first and therefore executed first, thus solving the problem.

Key Recap #

Through studying these two cases, I believe you have gained a deeper understanding of the execution order of enhanced methods in Spring AOP. Here, let me summarize the key points:

  • In the same aspect configuration, if there are multiple enhancements of different types, their execution priority is arranged in a specific order based on the enhancement types. The order of enhancements is as follows: Around.class, Before.class, After.class, AfterReturning.class, AfterThrowing.class.
  • In the same aspect configuration, if there are multiple enhancements of the same type, their execution priority is determined by sorting the method names of the enhancements. The sorting is done by comparing each letter of the method name until the first different letter with a smaller ASCII code is found.

At the same time, in this lesson, we also expanded some knowledge related to comparators:

  • Any two comparators (Comparator) can be connected using thenComparing() to compose a new continuous comparator.
  • There is a simple method to help you understand the comparison rules of comparators: ultimately, object-to-object comparison is necessary, and the comparison process must compare the same properties of the two objects. If you grasp these two points: what properties are being compared and what is the result of the comparison, it is enough. If the comparison result is positive, the properties are sorted in ascending order; if it is negative, the properties are sorted in descending order.

Thought question #

In fact, if you review the correction plans for the two cases above, you will find that although they have made minor changes, they are still not very elegant. So is there a slightly more elegant alternative? If so, do you know the principles and key source code behind it? By the way, you can also think about why I didn’t use a more elegant solution?

Looking forward to seeing your thoughts in the comments section. See you next class!