监控切面因为顺序问题导致 Spring 事务失效

实现横切关注点，是 AOP 非常常见的一个应用。我曾看到过一个不错的 AOP 实践，通过 AOP 实现了一个整合日志记录、异常处理和方法耗时打点为一体的统一切面。但后来发现，使用了 AOP 切面后，这个应用的声明式事务处理居然都是无效的。

现在我们来看下这个案例，分析下 AOP 实现的监控组件和事务失效有什么关系，以及通过 AOP 实现监控组件是否还有其他坑。

首先，定义一个自定义注解 Metrics，打上了该注解的方法可以实现各种监控功能：

@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE})
public @interface Metrics {
    /**
     * 在方法成功执行后打点，记录方法的执行时间发送到指标系统，默认开启
     *
     * @return
     */
    boolean recordSuccessMetrics() default true;
    /**
     * 在方法成功失败后打点，记录方法的执行时间发送到指标系统，默认开启
     *
     * @return
     */
    boolean recordFailMetrics() default true;
    /**
     * 通过日志记录请求参数，默认开启
     *
     * @return
     */
    boolean logParameters() default true;
    /**
     * 通过日志记录方法返回值，默认开启
     *
     * @return
     */
    boolean logReturn() default true;
    /**
     * 出现异常后通过日志记录异常信息，默认开启
     *
     * @return
     */
    boolean logException() default true;
    /**
     * 出现异常后忽略异常返回默认值，默认关闭
     *
     * @return
     */
    boolean ignoreException() default false;
}

然后，实现一个切面完成 Metrics 注解提供的功能。这个切面可以实现标记了 @RestController 注解的 Web 控制器的自动切入，如果还需要对更多 Bean 进行切入的话，再自行标记 @Metrics 注解。

@Aspect
@Component
@Slf4j
public class MetricsAspect {
    //让Spring帮我们注入ObjectMapper，以方便通过JSON序列化来记录方法入参和出参
    @Autowired
    private ObjectMapper objectMapper;

    // 实现一个返回Java基本类型默认值的工具。其实，你也可以逐一写很多if-else判断类型，
    // 然后手动设置其默认值。这里为了减少代码量用了一个小技巧，即通过初始化一个具有1个元素的数组，然后通过获取这个数组的值来获取基本类型默认值
    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(Function.identity(), clazz -> Array.get(Array.newInstance(clazz, 1), 0)));

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

    //@annotation指示器实现对标记了Metrics注解的方法进行匹配
    @Pointcut("@annotation(com.shoto.error.aop.Metrics)")
    public void withMetricsAnnotation() {
    }

    //within指示器实现了匹配那些类型上标记了@RestController注解的方法
    @Pointcut("within(@org.springframework.web.bind.annotation.RestController *)")
    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;
    }

}

接下来，分别定义最简单的 Controller、Service 和 Repository，来测试 MetricsAspect 的功能。

其中，Service 中实现创建用户的时候做了事务处理，当用户名包含 test 字样时会抛出异常，导致事务回滚。同时，我们为 Service 中的 createUser 标记了 @Metrics 注解。这样一来，我们还可以手动为类或方法标记 @Metrics 注解，实现 Controller 之外的其他组件的自动监控。

@Slf4j
@RestController //自动进行监控
@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 //启用方法监控
    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);
}
@Entity
@Data
public class UserEntity {
    @Id
    @GeneratedValue(strategy = AUTO)
    private Long id;
    private String name;

    public UserEntity() {
    }

    public UserEntity(String name) {
        this.name = name;
    }
}

使用用户名“test”测试一下注册功能：

2022-09-03 14:02:02.422  INFO 13648 --- [nio-8080-exec-2] com.shoto.error.aop.MetricsAspect        : 【入参日志】调用 【class com.shoto.error.aop.MetricsController】【public int com.shoto.error.aop.MetricsController.transaction(java.lang.String)】【http://localhost:8080/metricstest/transaction】 的参数是：【["test"]】
2022-09-03 14:02:15.321  INFO 13648 --- [nio-8080-exec-2] com.shoto.error.aop.MetricsAspect        : 【入参日志】调用 【class com.shoto.error.aop.UserService】【public void com.shoto.error.aop.UserService.createUser(com.shoto.error.transactional.UserEntity)】【http://localhost:8080/metricstest/transaction】 的参数是：【[{"id":null,"name":"test"}]】
2022-09-03 14:02:18.913  INFO 13648 --- [nio-8080-exec-2] com.shoto.error.aop.MetricsAspect        : 【失败打点】调用 【class com.shoto.error.aop.UserService】【public void com.shoto.error.aop.UserService.createUser(com.shoto.error.transactional.UserEntity)】【http://localhost:8080/metricstest/transaction】 失败，耗时：3150 ms
2022-09-03 14:02:18.914 ERROR 13648 --- [nio-8080-exec-2] com.shoto.error.aop.MetricsAspect        : 【异常日志】调用 【class com.shoto.error.aop.UserService】【public void com.shoto.error.aop.UserService.createUser(com.shoto.error.transactional.UserEntity)】【http://localhost:8080/metricstest/transaction】 出现异常！
java.lang.RuntimeException: invalid username!
    at com.shoto.error.aop.UserService.createUser(UserService.java:22) ~[classes/:na]
2022-09-03 14:02:18.915 DEBUG 13648 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction rollback
2022-09-03 14:02:18.915 DEBUG 13648 --- [nio-8080-exec-2] o.s.orm.jpa.JpaTransactionManager        : Rolling back JPA transaction on EntityManager [SessionImpl(759978323<open>)]
2022-09-03 14:02:18.915 ERROR 13648 --- [nio-8080-exec-2] com.shoto.error.aop.MetricsController    : create user failed because invalid username!
2022-09-03 14:02:24.814  INFO 13648 --- [nio-8080-exec-2] com.shoto.error.aop.MetricsAspect        : 【成功打点】调用 【class com.shoto.error.aop.MetricsController】【public int com.shoto.error.aop.MetricsController.transaction(java.lang.String)】【http://localhost:8080/metricstest/transaction】 成功，耗时：21917 ms
2022-09-03 14:02:26.440  INFO 13648 --- [nio-8080-exec-2] com.shoto.error.aop.MetricsAspect        : 【出参日志】调用 【class com.shoto.error.aop.MetricsController】【public int com.shoto.error.aop.MetricsController.transaction(java.lang.String)】【http://localhost:8080/metricstest/transaction】 的返回是：【0】

看起来这个切面很不错，日志中打出了整个调用的出入参、方法耗时：

第 1、9、10 和 11 行分别是 Controller 方法的入参日志、调用 Service 方法出错后记录的错误信息、成功执行的打点和出参日志。因为 Controller 方法内部进行了 try-catch 处理，所以其方法最终是成功执行的。出参日志中显示最后查询到的用户数量是 0，表示用户创建实际是失败的。正是因为 Service 方法的异常抛到了 Controller，所以整个方法才能被@Transactional 声明式事务回滚。在这里，MetricsAspect 捕获了异常又重新抛出，记录了异常的同时又不影响事务回滚。

一段时间后，开发同学觉得默认的 @Metrics 配置有点不合适，希望进行两个调整：

对于 Controller 的自动打点，不要自动记录入参和出参日志，否则日志量太大；
对于 Service 中的方法，最好可以自动捕获异常。

于是，他就为 MetricsController 手动加上了 @Metrics 注解，设置 logParameters 和 logReturn 为 false；然后为 Service 中的 createUser 方法的 @Metrics 注解，设置了 ignoreException 属性为 true：

@Metrics(logParameters = false, logReturn = false) //改动点1
public class MetricsController {
    //...
}
@Service
@Slf4j
public class UserService {
    @Transactional
    @Metrics(ignoreException = true) //改动点2
    public void createUser(UserEntity entity) {
        //...
    }
    //...
}

代码上线后发现日志量并没有减少，更要命的是事务回滚失效了，从输出看到最后查询到了名为 test 的用户：

2022-09-03 14:12:06.459  INFO 9596 --- [nio-8080-exec-1] com.shoto.error.aop.MetricsAspect        : 【入参日志】调用 【class com.shoto.error.aop.MetricsController】【public int com.shoto.error.aop.MetricsController.transaction(java.lang.String)】【http://localhost:8080/metricstest/transaction】 的参数是：【["test"]】
2022-09-03 14:12:08.632  INFO 9596 --- [nio-8080-exec-1] com.shoto.error.aop.MetricsAspect        : 【入参日志】调用 【class com.shoto.error.aop.UserService】【public void com.shoto.error.aop.UserService.createUser(com.shoto.error.transactional.UserEntity)】【http://localhost:8080/metricstest/transaction】 的参数是：【[{"id":null,"name":"test"}]】
2022-09-03 14:12:09.763  INFO 9596 --- [nio-8080-exec-1] com.shoto.error.aop.MetricsAspect        : 【失败打点】调用 【class com.shoto.error.aop.UserService】【public void com.shoto.error.aop.UserService.createUser(com.shoto.error.transactional.UserEntity)】【http://localhost:8080/metricstest/transaction】 失败，耗时：1130 ms
2022-09-03 14:12:09.766 ERROR 9596 --- [nio-8080-exec-1] com.shoto.error.aop.MetricsAspect        : 【异常日志】调用 【class com.shoto.error.aop.UserService】【public void com.shoto.error.aop.UserService.createUser(com.shoto.error.transactional.UserEntity)】【http://localhost:8080/metricstest/transaction】 出现异常！
java.lang.RuntimeException: invalid username!
    at com.shoto.error.aop.UserService.createUser(UserService.java:22) ~[classes/:na]
2022-09-03 14:12:09.766  INFO 9596 --- [nio-8080-exec-1] com.shoto.error.aop.MetricsAspect        : 【出参日志】调用 【class com.shoto.error.aop.UserService】【public void com.shoto.error.aop.UserService.createUser(com.shoto.error.transactional.UserEntity)】【http://localhost:8080/metricstest/transaction】 的返回是：【null】
2022-09-03 14:12:09.766 DEBUG 9596 --- [nio-8080-exec-1] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2022-09-03 14:12:10.432  INFO 9596 --- [nio-8080-exec-1] com.shoto.error.aop.MetricsAspect        : 【成功打点】调用 【class com.shoto.error.aop.MetricsController】【public int com.shoto.error.aop.MetricsController.transaction(java.lang.String)】【http://localhost:8080/metricstest/transaction】 成功，耗时：3973 ms
2022-09-03 14:12:10.432  INFO 9596 --- [nio-8080-exec-1] com.shoto.error.aop.MetricsAspect        : 【出参日志】调用 【class com.shoto.error.aop.MetricsController】【public int com.shoto.error.aop.MetricsController.transaction(java.lang.String)】【http://localhost:8080/metricstest/transaction】 的返回是：【1】

在介绍数据库事务时，我们分析了 Spring 通过 TransactionAspectSupport 类实现事务。在 invokeWithinTransaction 方法中设置断点可以发现，在执行 Service 的 createUser 方法时，TransactionAspectSupport 并没有捕获到异常，所以自然无法回滚事务。原因就是，异常被 MetricsAspect 吃掉了。

我们知道，切面本身是一个 Bean，Spring 对不同切面增强的执行顺序是由 Bean 优先级决定的，具体规则是：

入操作（Around（连接点执行前）、Before），切面优先级越高，越先执行。一个切面的入操作执行完，才轮到下一切面，所有切面入操作执行完，才开始执行连接点（方法）。
出操作（Around（连接点执行后）、After、AfterReturning、AfterThrowing），切面优先级越低，越先执行。一个切面的出操作执行完，才轮到下一切面，直到返回到调用点。
同一切面的 Around 比 After、Before 先执行。

对于 Bean 可以通过 @Order 注解来设置优先级，查看 @Order 注解和 Ordered 接口源码可以发现，默认情况下 Bean 的优先级为最低优先级，其值是 Integer 的最大值。其实，值越大优先级反而越低，这点比较反直觉：

@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();
}

我们再通过一个例子，来理解下增强的执行顺序。新建一个 TestAspectWithOrder10 切面，通过 @Order 注解设置优先级为 10，在内部定义 @Before、@After、@Around 三类增强，三个增强的逻辑只是简单的日志输出，切点是 TestController 所有方法；然后再定义一个类似的 TestAspectWithOrder20 切面，设置优先级为 20：

@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 {
    // ...
}

调用 TestController 的方法后，通过日志输出可以看到，增强执行顺序符合切面执行顺序的三个规则：

因为 Spring 的事务管理也是基于 AOP 的，默认情况下优先级最低也就是会先执行出操作，但是自定义切面 MetricsAspect 也同样是最低优先级，这个时候就可能出现问题：如果出操作先执行捕获了异常，那么 Spring 的事务处理就会因为无法捕获到异常导致无法回滚事务。

解决方式是，明确 MetricsAspect 的优先级，可以设置为最高优先级，也就是最先执行入操作最后执行出操作：

@Order(Ordered.HIGHEST_PRECEDENCE)
public class MetricsAspect {
    //...
}

此外，我们要知道切入的连接点是方法，注解定义在类上是无法直接从方法上获取到注解的。修复方式是，改为优先从方法获取，如果获取不到再从类获取，如果还是获取不到再使用默认的注解：

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

经过这 2 处修改，事务终于又可以回滚了，并且 Controller 的监控日志也不再出现入参、出参信息。

我再总结下这个案例。利用反射 + 注解 + Spring AOP 实现统一的横切日志关注点时，我们遇到的 Spring 事务失效问题，是由自定义的切面执行顺序引起的。这也让我们认识到，因为 Spring 内部大量利用 IoC 和 AOP 实现了各种组件，当使用 IoC 和 AOP 时，一定要考虑是否会影响其他内部组件。