19 Spring Framework Io C and Aop Are the Core of Extension

19 Spring Framework Io C and Aop Are the Core of Extension

19 Spring Framework IoC and AOP Are the Core of Extension #

Today, let’s talk about IoC and AOP in the Spring framework, and the common pitfalls associated with them.

For those familiar with Java, you may know that the Spring family is vast, with popular modules including Spring Data, Spring Security, Spring Boot, and Spring Cloud, among others. However, although the Spring ecosystem is extensive, it revolves around Spring Core, with IoC (Inversion of Control) and AOP (Aspect-Oriented Programming) being its core components.

In a nutshell, the purpose of IoC and AOP is decoupling and extension. Understanding these two core technologies will make your code more flexible, easily replaceable, and facilitate better decoupling between business components. In the next two lectures, I will analyze several relevant case studies with you to help navigate the pitfalls related to implementing IoC and AOP using Spring.

In order to better understand the case studies in these two lectures, let’s review the basics of IoC and AOP.

IoC is actually a design principle. Implementing IoC with Spring means handing over control of your well-designed objects to the Spring container, rather than controlling them directly within the objects themselves. So why should objects be managed by the container? You might think that IoC is convenient and enables decoupling. However, from my perspective, the most important benefit of IoC is that it brings more possibilities.

By using the container to manage all the framework and business objects, we can not only adjust the relationships between objects non-invasively, but we can also adjust the properties of objects non-invasively at any time, or even replace objects entirely. This allows framework developers to implement extensions behind the scenes without any problems, opening up endless possibilities. For example, if the object we want to monitor is a Bean, the implementation becomes extremely simple. Therefore, this container system is not only heavily relied upon by Spring Core and Spring Boot, but also allows seamless integration with external frameworks and Spring.

AOP embodies the essence of loose coupling and high cohesion, implementing cross-cutting concerns (such as caching, security, and logging) in a centralized manner. Then, through pointcut configuration, the code is injected into the appropriate places. Aspects, pointcuts, advice, and joinpoints are fundamental concepts in AOP, and we will frequently mention them in these two lectures.

To facilitate understanding, let’s consider the Spring AOP technology as a procedure for adding cream filling to a cake. If we want to find a suitable place to inject the cream into the cake batter, how should we guide the worker to perform the operation?

Firstly, we need to remind the worker that the cream can only be added inside the cake batter, not on top of it or below it. This is the joinpoint. In terms of Spring AOP, the joinpoint is the execution of methods.

Next, we need to tell the worker at which point to slice the cake and add the cream. For example, we can add a layer of cream in the middle of the cake, making one slice in the middle, or add two layers of cream, making two slices at 1/3 and 2/3 of the cake. This is the pointcut. Spring AOP uses AspectJ-style query expressions by default, running the query expression against joinpoints to match the pointcuts.

Next, and most importantly, we need to tell the worker what to do after slicing the cake, which is adding the cream. This is the advice, also known as the interceptor, which defines how to enhance the code after joining the pointcut, including before, after, and around. In Spring AOP, enhancements are defined as interceptors.

Finally, we need to tell the worker where in the cake batter to find and add the cream. For Spring AOP, the operation of adding cream filling to the cake is called an aspect. An aspect is composed of a pointcut and advice.

Once we understand these core concepts, we can continue with the analysis of the case studies.

First, I want to emphasize that Spring-related issues can be complicated. On one hand, Spring’s IoC and AOP provide flexibility, and on the other hand, the automatic configuration of Spring Boot and the complex modules of Spring Cloud can make troubleshooting more challenging. Therefore, in today’s lecture, I will start by laying a solid foundation, focusing on IoC and AOP through two case studies. In the next lecture, I will share some pitfalls related to Spring with you.

How to Inject Prototype Beans into Singleton Beans? #

Although we know that by default, beans created by Spring are singletons, this point may be overlooked when dealing with inheritance. Why is that? And what impact does overlooking this have? Next, I will share a case of memory leak caused by singleton.

At the beginning, the architect defined an abstract class called SayService, which maintained a field called data of type ArrayList for storing intermediate data during method processing. Each time the say method is called, new data is added to data. It can be considered that SayService has a state, and if SayService is a singleton, it will inevitably lead to an OOM (Out of Memory) error:

@Slf4j
public abstract class SayService {

    List<String> data = new ArrayList<>();

    public void say() {
        data.add(IntStream.rangeClosed(1, 1000000)
                .mapToObj(__ -> "a")
                .collect(Collectors.joining("")) + UUID.randomUUID().toString());
        log.info("I'm {} size:{}", this, data.size());
    }
}

However, during actual development, the developers didn’t think too much and added @Service annotations to the SayHello and SayBye classes, making them beans. They also didn’t consider that the parent class has a state:

@Service
@Slf4j
public class SayHello extends SayService {

    @Override
    public void say() {
        super.say();
        log.info("hello");
    }
}

@Service
@Slf4j
public class SayBye extends SayService {

    @Override
    public void say() {
        super.say();
        log.info("bye");
    }
}

Many developers think that the purpose of the @Service annotation is to let Spring automatically inject objects through the @Autowired annotation, so they can directly use the injected list to get SayHello and SayBye, without considering the lifecycle of the classes:

@Autowired
List<SayService> sayServiceList;

@GetMapping("test")
public void test() {

    log.info("====================");
    sayServiceList.forEach(SayService::say);
}

This point is very easy to overlook. The architect of the base class designed it to have a state, but does not know how the subclasses use the base class. The developers of the subclasses directly marked them with @Service without much thought, making the classes become beans and injecting this service using the @Autowired annotation. But after setting it up like this, the stateful base class may cause memory leaks or thread safety issues.

The correct approach is to assess whether a class has a state before marking it with the @Service annotation and letting the container manage its type, and then set the appropriate scope for the bean. Fortunately, before going live, the architect discovered this memory leak issue, and the developers made changes by marking both SayHello and SayBye classes with the @Scope annotation and setting the PROTOTYPE scope, which means they are prototypes:

@Scope(value = ConfigurableBeanFactory.SCOPE_PROTOTYPE)

However, even after going live, memory leaks still occurred, proving that the modification was ineffective.

From the logs, it can be seen that for both the first and second method calls, the objects for SayBye are 4c0bfe9e, and the same problem occurs for SayHello. From lines 7 to 10 in the log, it can also be seen that after the second call, the number of elements in the list became 2, indicating that the list maintained by the parent class SayService is continuously growing, and calling it repeatedly will eventually lead to an OOM error.

[15:01:09.349] [http-nio-45678-exec-1] [INFO ] [.s.d.BeanSingletonAndOrderController:22  ] - ====================
[15:01:09.401] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo1.SayService         :19  ] - I'm org.geekbang.time.commonmistakes.spring.demo1.SayBye@4c0bfe9e size:1
[15:01:09.402] [http-nio-45678-exec-1] [INFO ] [t.commonmistakes.spring.demo1.SayBye:16  ] - bye
[15:01:09.469] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo1.SayService         :19  ] - I'm org.geekbang.time.commonmistakes.spring.demo1.SayHello@490fbeaa size:1
[15:01:09.469] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo1.SayHello           :17  ] - hello
[15:01:15.167] [http-nio-45678-exec-2] [INFO ] [.s.d.BeanSingletonAndOrderController:22  ] - ====================
[15:01:15.197] [http-nio-45678-exec-2] [INFO ] [o.g.t.c.spring.demo1.SayService         :19  ] - I'm org.geekbang.time.commonmistakes.spring.demo1.SayBye@4c0bfe9e size:2
[15:01:15.198] [http-nio-45678-exec-2] [INFO ] [t.commonmistakes.spring.demo1.SayBye:16  ] - bye
[15:01:15.224] [http-nio-45678-exec-2] [INFO ] [o.g.t.c.spring.demo1.SayService         :19  ] - I'm org.geekbang.time.commonmistakes.spring.demo1.SayHello@490fbeaa size:2
[15:01:15.224] [http-nio-45678-exec-2] [INFO ] [o.g.t.c.spring.demo1.SayHello           :17  ] - hello

This introduces the question of how a singleton Bean can inject a prototype Bean. The Controller is annotated with @RestController, and the @RestController annotation is actually @Controller annotation combined with the @ResponseBody annotation. Since the @Controller annotation is annotated with @Component, the @RestController annotation is also a Spring Bean:

//@RestController annotation = @Controller annotation + @ResponseBody annotation
@Target(ElementType.TYPE)
@Retention(RetentionPolicy.RUNTIME)
@Documented
@Controller
@ResponseBody
public @interface RestController {}

//@Controller is also annotated with @Component
@Target({ElementType.TYPE})
@Retention(RetentionPolicy.RUNTIME)
@Documented
@Component
public @interface Controller {}

By default, a Bean is a singleton, so the Service injected by the singleton Controller is also created only once, even if the Service itself is marked as prototype.

The fix is to let the Service be injected as a proxy. This way, even though the Controller itself is a singleton, the Service can be obtained from the proxy each time. Only then can the prototype scope configuration take effect:

@Scope(value = ConfigurableBeanFactory.SCOPE_PROTOTYPE, proxyMode = ScopedProxyMode.TARGET_CLASS)

You can confirm that this fix works by checking the logs:

[15:08:42.649] [http-nio-45678-exec-1] [INFO ] [.s.d.BeanSingletonAndOrderController:22  ] - ====================
[15:08:42.747] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo1.SayService         :19  ] - I'm org.geekbang.time.commonmistakes.spring.demo1.SayBye@3fa64743 size:1
[15:08:42.747] [http-nio-45678-exec-1] [INFO ] [t.commonmistakes.spring.demo1.SayBye:17  ] - bye
[15:08:42.871] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo1.SayService         :19  ] - I'm org.geekbang.time.commonmistakes.spring.demo1.SayHello@2f0b779 size:1
[15:08:42.872] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo1.SayHello           :17  ] - hello
[15:08:42.932] [http-nio-45678-exec-2] [INFO ] [.s.d.BeanSingletonAndOrderController:22  ] - ====================
[15:08:42.991] [http-nio-45678-exec-2] [INFO ] [o.g.t.c.spring.demo1.SayService         :19  ] - I'm org.geekbang.time.commonmistakes.spring.demo1.SayBye@7319b18e size:1
[15:08:42.992] [http-nio-45678-exec-2] [INFO ] [t.commonmistakes.spring.demo1.SayBye:17  ] - bye
[15:08:43.046] [http-nio-45678-exec-2] [INFO ] [o.g.t.c.spring.demo1.SayService         :19  ] - I'm org.geekbang.time.commonmistakes.spring.demo1.SayHello@77262b35 size:1
[15:08:43.046] [http-nio-45678-exec-2] [INFO ] [o.g.t.c.spring.demo1.SayHello           :17  ] - hello

If you debug it, you can also see that the injected Services are generated by Spring as proxy classes:

Of course, if you don’t want to use a proxy, another way is to directly get the Bean from the ApplicationContext each time:

@Autowired
private ApplicationContext applicationContext;

@GetMapping("test2")
public void test2() {
    applicationContext.getBeansOfType(SayService.class).values().forEach(SayService::say);
}

If you are careful, you may notice another potential issue. When injecting the List of SayService beans, the first element is SayBye and the second element is SayHello. However, we would prefer to execute Hello first and then Bye. Therefore, when injecting a List Bean, it is necessary to consider the order or priority of the Beans.

In most cases, the order is not that important, but for AOP, the order can cause fatal issues. Let’s continue to explore this problem.

Monitoring Aspect Causes Spring Transaction Failure #

Implementing cross-cutting concerns is a common application of AOP (Aspect-Oriented Programming). I once came across a good AOP practice that implemented a unified aspect integrating logging, exception handling, and method timing. However, later it was discovered that after using the AOP aspect, the declarative transaction handling of this application was actually ineffective. You can review the possibilities of Spring transaction failure mentioned in Lesson 6.

Now let’s take a look at this case and analyze the relationship between the monitoring component implemented by AOP and the transaction failure, as well as any other pitfalls of implementing a monitoring component through AOP.

First, let’s define a custom annotation called Metrics. Methods annotated with this annotation can implement various monitoring functionalities:

@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE})
public @interface Metrics {

    /**
     * Record method execution time and send it to the metrics system after a successful execution. Enabled by default.
     *
     * @return
     */
    boolean recordSuccessMetrics() default true;

    /**
     * Record method execution time and send it to the metrics system after a successful or failed execution. Enabled by default.
     *
     * @return
     */
    boolean recordFailMetrics() default true;

    /**
     * Log request parameters. Enabled by default.
     *
     * @return
     */
    boolean logParameters() default true;

    /**
     * Log method return value. Enabled by default.
     *
     * @return
     */
    boolean logReturn() default true;

    /**
     * Log exception information if an exception occurs. Enabled by default.
     *
     * @return
     */
    boolean logException() default true;

    /**
     * Ignore exception and return default value if an exception occurs. Disabled by default.
     *
     * @return
     */
    boolean ignoreException() default false;

}

Next, implement an aspect to provide the functionalities defined by the Metrics annotation. This aspect can automatically intercept web controllers annotated with @RestController, and if you need to intercept more beans, you can annotate them with @Metrics yourself.

Note: This code is a bit long and uses some tricks. You need to read the comments in the code carefully.

@Aspect
@Component
@Slf4j
public class MetricsAspect {

    // Let Spring inject the ObjectMapper for us, so that we can use JSON serialization to record method input and output
    @Autowired
    private ObjectMapper objectMapper;

    // Implement a utility that returns the default value for Java primitive types. Actually, you can manually set the default values by writing a lot of if-else statements for each type. Here, a small trick is used to reduce the amount of code, which is to initialize an array with one element and then use the value of that element to obtain the default value of the primitive type.
    private static final Map<Class<?>, Object> DEFAULT_VALUES = Stream
            .of(boolean.class, byte.class, char.class, double.class, float.class, int.class, long.class, short.class)
            .collect(toMap(clazz -> (Class<?>) clazz, clazz -> Array.get(Array.newInstance(clazz, 1), 0)));

    public static <T> T getDefaultValue(Class<T> clazz) {
        return (T) DEFAULT_VALUES.get(clazz);
    }

    //@annotation indicator matches methods annotated with Metrics
   @Pointcut("within(@org.geekbang.time.commonmistakes.springpart1.aopmetrics.Metrics *)")
    public void withMetricsAnnotation() {

    }

    //within indicator matches methods on types annotated with RestController
    @Pointcut("within(@org.springframework.web.bind.annotation.RestController *)")

Note: The code above is incomplete and the remaining part is missing.

public void controllerBean() {

}

@Around("controllerBean() || withMetricsAnnotation())")
public Object metrics(ProceedingJoinPoint pjp) throws Throwable {
    //通过连接点获取方法签名和方法上Metrics注解，并根据方法签名生成日志中要输出的方法定义描述
    MethodSignature signature = (MethodSignature) pjp.getSignature();
    Metrics metrics = signature.getMethod().getAnnotation(Metrics.class);

    String name = String.format("【%s】【%s】", signature.getDeclaringType().toString(), signature.toLongString());

    //因为需要默认对所有@RestController标记的Web控制器实现@Metrics注解的功能，在这种情况下方法上必然是没有@Metrics注解的，我们需要获取一个默认注解。虽然可以手动实例化一个@Metrics注解的实例出来，但为了节省代码行数，我们通过在一个内部类上定义@Metrics注解方式，然后通过反射获取注解的小技巧，来获得一个默认的@Metrics注解的实例
    if (metrics == null) {
        @Metrics
        final class c {}
        metrics = c.class.getAnnotation(Metrics.class);
    }
    //尝试从请求上下文（如果有的话）获得请求URL，以方便定位问题
    RequestAttributes requestAttributes = RequestContextHolder.getRequestAttributes();
    if (requestAttributes != null) {
        HttpServletRequest request = ((ServletRequestAttributes) requestAttributes).getRequest();
        if (request != null)
            name += String.format("【%s】", request.getRequestURL().toString());
    }

    //实现的是入参的日志输出
    if (metrics.logParameters())
        log.info(String.format("【入参日志】调用 %s 的参数是：【%s】", name, objectMapper.writeValueAsString(pjp.getArgs())));
    //实现连接点方法的执行，以及成功失败的打点，出现异常的时候还会记录日志
    Object returnValue;
    Instant start = Instant.now();
    try {
        returnValue = pjp.proceed();
        if (metrics.recordSuccessMetrics())
            //在生产级代码中，我们应考虑使用类似Micrometer的指标框架，把打点信息记录到时间序列数据库中，实现通过图表来查看方法的调用次数和执行时间，在设计篇我们会重点介绍
            log.info(String.format("【成功打点】调用 %s 成功，耗时：%d ms", name, Duration.between(start, Instant.now()).toMillis()));
    } catch (Exception ex) {
        if (metrics.recordFailMetrics())
            log.info(String.format("【失败打点】调用 %s 失败，耗时：%d ms", name, Duration.between(start, Instant.now()).toMillis()));
        if (metrics.logException())
            log.error(String.format("【异常日志】调用 %s 出现异常！", name), ex);
        //忽略异常的时候，使用一开始定义的getDefaultValue方法，来获取基本类型的默认值
        if (metrics.ignoreException())
            returnValue = getDefaultValue(signature.getReturnType());
        else
            throw ex;
    }
    //实现了返回值的日志输出
    if (metrics.logReturn())
        log.info(String.format("【出参日志】调用 %s 的返回是：【%s】", name, returnValue));
    return returnValue;
}
}

Next, define the simplest Controller, Service, and Repository respectively to test the functionality of MetricsAspect.

In Service, transaction processing is performed when creating a user, and an exception is thrown causing the transaction to be rolled back when the username contains the word “test”. At the same time, we mark @Metrics annotation for the createUser method in Service. In this way, we can manually mark the @Metrics annotation for classes or methods to achieve automatic monitoring of other components outside the Controller.

@Slf4j
@RestController // Enable automatic monitoring
@RequestMapping("metricstest")
public class MetricsController {

    @Autowired
    private UserService userService;

    @GetMapping("transaction")
    public int transaction(@RequestParam("name") String name) {
        try {
            userService.createUser(new UserEntity(name));
        } catch (Exception ex) {
            log.error("create user failed because {}", ex.getMessage());
        }

        return userService.getUserCount(name);
    }
}

@Service
@Slf4j
public class UserService {

    @Autowired
    private UserRepository userRepository;

    @Transactional
    @Metrics // Enable method monitoring

        public void createUser(UserEntity entity) {
            userRepository.save(entity);
            if (entity.getName().contains("test"))
                throw new RuntimeException("invalid username!");
        }
    
        public int getUserCount(String name) {
            return userRepository.findByName(name).size();
        }
    }
    
    @Repository
    public interface UserRepository extends JpaRepository<UserEntity, Long> {
    
        List<UserEntity> findByName(String name);
    
    }
    

Test the registration functionality using the username "test":

[16:27:52.586] [http-nio-45678-exec-3] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect :85 ] - [Input Log] The parameters for calling [class org.geekbang.time.commonmistakes.spring.demo2.MetricsController][public int org.geekbang.time.commonmistakes.spring.demo2.MetricsController.transaction(java.lang.String)][http://localhost:45678/metricstest/transaction] are: [[“test”]] [16:27:52.590] [http-nio-45678-exec-3] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect :85 ] - [Input Log] The parameters for calling [class org.geekbang.time.commonmistakes.spring.demo2.UserService][public void org.geekbang.time.commonmistakes.spring.demo2.UserService.createUser(org.geekbang.time.commonmistakes.spring.demo2.UserEntity)][http://localhost:45678/metricstest/transaction] are: [[{“id”:null,“name”:“test”}]] [16:27:52.609] [http-nio-45678-exec-3] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect :96 ] - [Failure Log] The call to [class org.geekbang.time.commonmistakes.spring.demo2.UserService][public void org.geekbang.time.commonmistakes.spring.demo2.UserService.createUser(org.geekbang.time.commonmistakes.spring.demo2.UserEntity)][http://localhost:45678/metricstest/transaction] failed, took 19 ms [16:27:52.610] [http-nio-45678-exec-3] [ERROR] [o.g.t.c.spring.demo2.MetricsAspect :98 ] - [Exception Log] An exception occurred while calling [class org.geekbang.time.commonmistakes.spring.demo2.UserService][public void org.geekbang.time.commonmistakes.spring.demo2.UserService.createUser(org.geekbang.time.commonmistakes.spring.demo2.UserEntity)][http://localhost:45678/metricstest/transaction]! java.lang.RuntimeException: invalid username! at org.geekbang.time.commonmistakes.spring.demo2.UserService.createUser(UserService.java:18) at org.geekbang.time.commonmistakes.spring.demo2.UserService$$FastClassBySpringCGLIB$$9eec91f.invoke() [16:27:52.614] [http-nio-45678-exec-3] [ERROR] [g.t.c.spring.demo2.MetricsController:21 ] - create user failed because invalid username! [16:27:52.617] [http-nio-45678-exec-3] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect :93 ] - [Success Log] The call to [class org.geekbang.time.commonmistakes.spring.demo2.MetricsController][public int org.geekbang.time.commonmistakes.spring.demo2.MetricsController.transaction(java.lang.String)][http://localhost:45678/metricstest/transaction] was successful, took 31 ms [16:27:52.618] [http-nio-45678-exec-3] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect :108 ] - [Output Log] The return value of [class org.geekbang.time.commonmistakes.spring.demo2.MetricsController][public int org.geekbang.time.commonmistakes.spring.demo2.MetricsController.transaction(java.lang.String)][http://localhost:45678/metricstest/transaction] is: [0]


It seems that this aspect is very good. The log prints the entire call's input parameters, method execution time, and output parameters:

Lines 1, 8, 9, and 10 respectively show the input log of the Controller method, the error message recorded after the failure of the Service method call, the success log, and the output log. The Controller method is ultimately successful because it handles exceptions with a try-catch block. The output log shows that the last query for the user count is 0, indicating that the user creation failed.

Lines 2, 3, and 4-7 respectively show the input log of the Service method, the failure log, and the exception log. Because the Service method throws an exception that propagates to the Controller, the entire method can be rolled back by the @Transactional declarative transaction. In this case, the MetricsAspect catches and rethrows the exception, recording the exception without affecting the transaction rollback.

After some time, the developer feels that the default @Metrics configuration is not suitable and wants to make two adjustments:

1. For automatic logging of Controller methods, do not automatically record input and output logs to avoid excessive log volume.
It is better to automatically catch exceptions in the methods of a Service.

Therefore, he manually added the @Metrics annotation to the MetricsController, with logParameters and logReturn set to false; and then added the @Metrics annotation to the createUser method in the Service, with the ignoreException attribute set to true:

```java
@Metrics(logParameters = false, logReturn = false) //change point 1
public class MetricsController {

@Service
@Slf4j
public class UserService {

    @Transactional
    @Metrics(ignoreException = true) //change point 2
    public void createUser(UserEntity entity) {

    ...

After the code went live, it was found that the log volume did not decrease, and even worse, the transaction rollback did not work. From the output, it can be seen that the last queried user was named “test”:

[17:01:16.549] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect      :75  ] - 【Parameter Logging】The parameters of the method 【class org.geekbang.time.commonmistakes.spring.demo2.MetricsController】【public int org.geekbang.time.commonmistakes.spring.demo2.MetricsController.transaction(java.lang.String)】【http://localhost:45678/metricstest/transaction】 are: 【["test"]】
[17:01:16.670] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect      :75  ] - 【Parameter Logging】The parameters of the method 【class org.geekbang.time.commonmistakes.spring.demo2.UserService】【public void org.geekbang.time.commonmistakes.spring.demo2.UserService.createUser(org.geekbang.time.commonmistakes.spring.demo2.UserEntity)】【http://localhost:45678/metricstest/transaction】 are: 【[{"id":null,"name":"test"}]】
[17:01:16.885] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect      :86  ] - 【Failed Metrics】The method 【class org.geekbang.time.commonmistakes.spring.demo2.UserService】【public void org.geekbang.time.commonmistakes.spring.demo2.UserService.createUser(org.geekbang.time.commonmistakes.spring.demo2.UserEntity)】【http://localhost:45678/metricstest/transaction】 failed, spent: 211 ms
[17:01:16.899] [http-nio-45678-exec-1] [ERROR] [o.g.t.c.spring.demo2.MetricsAspect      :88  ] - 【Exception Logging】An exception occurred while calling 【class org.geekbang.time.commonmistakes.spring.demo2.UserService】【public void org.geekbang.time.commonmistakes.spring.demo2.UserService.createUser(org.geekbang.time.commonmistakes.spring.demo2.UserEntity)】【http://localhost:45678/metricstest/transaction】 !
java.lang.RuntimeException: invalid username!
  at org.geekbang.time.commonmistakes.spring.demo2.UserService.createUser(UserService.java:18)
  at org.geekbang.time.commonmistakes.spring.demo2.UserService$$FastClassBySpringCGLIB$$9eec91f.invoke(<generated>)
[17:01:16.902] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect      :98  ] - 【Return Logging】The return of the method 【class org.geekbang.time.commonmistakes.spring.demo2.UserService】【public void org.geekbang.time.commonmistakes.spring.demo2.UserService.createUser(org.geekbang.time.commonmistakes.spring.demo2.UserEntity)】【http://localhost:45678/metricstest/transaction】 is: 【null】
[17:01:17.466] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect      :83  ] - 【Success Metrics】The method 【class org.geekbang.time.commonmistakes.spring.demo2.MetricsController】【public int org.geekbang.time.commonmistakes.spring.demo2.MetricsController.transaction(java.lang.String)】【http://localhost:45678/metricstest/transaction】 succeeded, spent: 915 ms
[17:01:17.467] [http-nio-45678-exec-1] [INFO ] [o.g.t.c.spring.demo2.MetricsAspect      :98  ] - 【Return Logging】The return of the method 【class org.geekbang.time.commonmistakes.spring.demo2.MetricsController】【public int org.geekbang.time.commonmistakes.spring.demo2.MetricsController.transaction(java.lang.String)】【http://localhost:45678/metricstest/transaction】 is: 【1】

When we introduced database transactions, we analyzed that Spring implements transactions through the TransactionAspectSupport class. By setting a breakpoint in the invokeWithinTransaction method, we can find that TransactionAspectSupport did not catch the exception when executing the createUser method in the Service, so the transaction cannot be rolled back naturally. The reason is that the exception was swallowed by the MetricsAspect.

We know that an aspect itself is a Bean, and the execution order of different aspects enhanced by Spring is determined by the priority of Beans. The specific rules are:

Entry operations (Around (before the join point) and Before): the higher the aspect’s priority, the earlier it is executed. A subsequent aspect will only be executed after the entry operation of the previous aspect is completed. All entry operations of aspects must be completed before the join point (method) starts execution.

Exit operations (Around (after the join point), After, AfterReturning, and AfterThrowing): the lower the aspect’s priority, the earlier it is executed. A subsequent aspect will only be executed after the exit operation of the previous aspect is completed. The execution flow continues until it returns to the calling point.

Regarding Beans, the priority can be set using the @Order annotation. By checking the @Order annotation and the Ordered interface source code, we can find that by default, the priority of a Bean is the lowest priority, with the maximum value of Integer. In fact, the larger the value, the lower the priority, which is counterintuitive.

@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.TYPE, ElementType.METHOD, ElementType.FIELD})
@Documented
public @interface Order {

   int value() default Ordered.LOWEST_PRECEDENCE;

}

public interface Ordered {
   int HIGHEST_PRECEDENCE = Integer.MIN_VALUE;
   int LOWEST_PRECEDENCE = Integer.MAX_VALUE;
   
   int getOrder();
}


Let's use another example to understand the execution order of enhancements. Create a TestAspectWithOrder10 aspect and set the priority to 10 using the @Order annotation. Define @Before, @After, and @Around enhancements inside, and the logic of the three enhancements is simply logging output. The pointcut is all methods in the TestController. Then define a similar TestAspectWithOrder20 aspect and set the priority to 20:

```java
@Aspect
@Component
@Order(10)
@Slf4j
public class TestAspectWithOrder10 {

    @Before("execution(* org.geekbang.time.commonmistakes.springpart1.aopmetrics.TestController.*(..))")
    public void before(JoinPoint joinPoint) throws Throwable {
        log.info("TestAspectWithOrder10 @Before");
    }

    @After("execution(* org.geekbang.time.commonmistakes.springpart1.aopmetrics.TestController.*(..))")
    public void after(JoinPoint joinPoint) throws Throwable {
        log.info("TestAspectWithOrder10 @After");
    }

    @Around("execution(* org.geekbang.time.commonmistakes.springpart1.aopmetrics.TestController.*(..))")
    public Object around(ProceedingJoinPoint pjp) throws Throwable {
        log.info("TestAspectWithOrder10 @Around before");
        Object o = pjp.proceed();
        log.info("TestAspectWithOrder10 @Around after");
        return o;
    }

}

@Aspect
@Component
@Order(20)
@Slf4j
public class TestAspectWithOrder20 {

  ...

}

After calling the method of the TestController, the log output shows that the execution order of the enhancements conforms to the three rules of aspect execution order:

Because Spring’s transaction management is also based on AOP, by default, the lowest priority means that the reconciliation operation is executed first, but the custom aspect MetricsAspect is also the lowest priority. At this time, problems may occur: If the reconciliation operation is executed first and an exception is caught, Spring’s transaction processing will not be able to catch the exception, resulting in the transaction not being rolled back.

The solution is to clearly specify the priority of MetricsAspect, which can be set to the highest priority, that is, execute the reconciliation operation first and the exit operation last:

// Set the priority of the MetricsAspect bean to the highest
@Order(Ordered.HIGHEST_PRECEDENCE)
public class MetricsAspect {

    ...

}

In addition, we need to know that the interception point is a method, and annotations defined on a class cannot directly get the annotations from the method. The fix is to change to get from the method first, and if it cannot be obtained, get it from the class, and if it still cannot be obtained, use the default annotation:

Metrics metrics = signature.getMethod().getAnnotation(Metrics.class);
if (metrics == null) {
    metrics = signature.getMethod().getDeclaringClass().getAnnotation(Metrics.class);
}

After these two modifications, the transaction can finally be rolled back, and the monitoring logs of the Controller no longer include input and output parameter information.

Let me summarize this case again. When using reflection + annotations + Spring AOP to implement unified cross-cutting log concerns, the problem of Spring transaction failure we encountered was caused by the execution order of the custom aspects. This also makes us realize that because Spring internally uses IoC and AOP to implement various components, when using IoC and AOP, we must consider whether it will affect other internal components.

Key Review #

Today, I shared with you the basic concepts of Spring IoC and AOP through 2 cases, as well as three points that are prone to mistakes.

First, when letting Spring container manage objects, you should consider whether the default singleton scope is suitable. For stateful types, singletons may cause memory leak issues.

Second, if you want to inject a prototype bean into a singleton bean, it is not as simple as modifying the scope attribute. Since singleton beans are initialized once when the container starts, the simplest solution is to set the prototype bean to be injected through proxy, that is, set the proxyMode attribute to TARGET_CLASS.

Third, if a group of beans of the same type have a specific order, you need to explicitly use the @Order annotation to set the order. You can review the execution order of the three types of advices (@Before, @After, and @Around) in two different priority aspects.

Lastly, I want to mention that the second case in the article is a complete unified logging monitoring case. By further modification, you can implement a comprehensive, production-level method invocation monitoring platform. These modifications mainly include two aspects: replacing log point with integration with a metrics monitoring system, and changing the monitoring switches of various functions from annotation attributes to real-time configuration system.

The code used today is all available on GitHub. You can click here to view it.

Reflection and Discussion #

In addition to injecting beans using @Autowired, you can also use @Inject or @Resource. Do you know the differences between these three approaches?

When a bean has a circular dependency, for example, when BeanA’s constructor depends on BeanB as a member that needs to be injected, and BeanB also depends on BeanA, what problems do you think may arise? What are the possible solutions?

In the next lecture, I will continue to explore other core issues of Spring with you. I am Zhu Ye. Feel free to leave your thoughts in the comments section. You are also welcome to share today’s content with your friends or colleagues for further discussion.