一个 Spring AOP 代理问题的排查

680 阅读9分钟

这是我参与8月更文挑战的第1天,活动详情查看:8月更文挑战

起因

起因是线上的一个 bug :项目某个列表页面的分页功能不生效。该列表数据大致有 300 多个,按照每页 100 的方式,至少也有三页,但是页数展示只有一页。

image

可能性分析

1.首先查看是不是页面处理问题,这只需要确认后端传来的数据是否有分页信息。(因为没有权限查看,所以被告知,是后端返回数据的问题)

2.后端返回的总页数只有 1 页,说明分页没有起作用。

3.定位问题代码,该列表数据的分页管理是基于内部封装的一个切面处理实现的,说明这个地方出现了问题。嗯,由于造数据需要涉及多个服务,直接本地 debug 定位出来的。

代码分析

1.vjooq的PaginationAspect

image-20190829164821162

image-20190829164130350

可以看到,这么一个切面设置,处理过程大致就是,获取事先存放在 PageBuilder 中的 dsl 对象和 sql 语句, dsl 执行 sql 获取到一个临时表,并统计总数。

* com.xingren..*.*ByPage(..),理论上是可以应用于当前项目中所有以 ByPage 结尾的方法。

然后以返回值类型 PageBuilder 作为校验条件,仅作用于 Repository 的方法。

题外话:由于 PageBuilder 的特殊性,该类应该只能应用于 Repository 层返回给 service ,不允许 service 层之间或者再往上传递。

2.调用的数据分页列表方法

再看看实际调用的分页方法

image-20190829164638556

除去路径不谈,方法名的格式是符合切面表达式的,并且该方法以及调用方的逻辑最近都无改动。却在近几个月内导致分页失效。

程序员的直觉告诉我:这没有问题。(能有什么问题,这段代码都用了几年了,就没怎么改过。。。)

可惜,它这回就是不好使,于是我 debug 了一下。

3. ClinicDoctorUserRepository

image-20190829165152888

由于存在会应用切面的方法,所以作为一个注定要被加 buff 的 Repository 类,它应该是长上面这样子的。(切面增强的话,产生代理类会将原方法和 advice 的方法,根据 advice 的类型组成一个调用链(责任链模式)。实际调用时就是一个被代理的链式方法的调用过程。比如说 Before -> method -> After。)

但是在这次实际调用过程中,它是下面这样子的。

image-20190829170246849很遗憾,没有产生动态代理类。所以很自然的,也无法被加 buff。

因为前段时间刚好研究了 Spring 容器启动的源码,所以想探究一下为什么 ClinicDoctorUserRepository 初始化时没有被切面增强而产生代理类。

初始化分析

1.断点设置

由于切面或者 Spring 的缓存 @Cacheable (是的,项目中的缓存就是基于这个注解做的)都是基于 Spring Aop,所以在项目依赖中一定会存在 Spring Aop 的 jar 包。

那么如果在 Spring Boot 中开启 Aop 的功能,Spring 在启动时给容器注入一个 BeanPostProcessor 以增强相应的对象。这个BeanPostProcessor 就是 AnnotationAwareAspectJAutoProxyCreator

这个注入的方式,大致就是 @EnableAspectJAutoProxy -> @Import(AspectJAutoProxyRegistrar.class) -> AopConfigUtils.registerAspectJAnnotationAutoProxyCreatorIfNecessary(registry);

那 debug 到 Spring 容器启动时,增强原对象以生成动态代理类的地方看看。

内部过程比较复杂,直接说明这个地方大致在 AbstractAutowireCapableBeanFactory#createBean(String, RootBeanDefinition, Object[]) 中。

image-20190829172902454

可以看到,打断点的两个地方是两种生成 bean 的途径:前一种是允许特殊 BeanPostProcessor 事先生成代理的 bean ;后一种是在正常初始化流程中,在应用 BeanPostProcessor 时,封装传入初始化的对象,以生成代理的 bean 。

image-20190829173159553断点加上条件,只关注 ClinicDoctorUserRepository , BeanName 一般就是类名的首字母小写。

2.开始 debug !!

启动项目,首先进到第一个断点。

image.png

然后跳过这一步,得到 null ,说明该类可能在这一步不会生成,继续到下一个断点。

DoCreateBean 是一个 bean 完整的初始化过程,对应如下的生命周期(图源来自网上,具体参考的地方我忘了):

image

而 bean 如果还有机会被 BeanPostProcessor增强,那么只有在对象初始化以后,应用 BeanPostProcessor 后置处理的时候了。

所以,跳过其他生命周期的步骤,直接到关键位置:应用 BeanPostProcessor 的后置处理。

image-20190829175430768

进入到这个方法,就是获取当前容器中注册的所有 BeanPostProcessor ,并应用他们的 postProcessAfterInitialization 方法。当前容器的 BeanPostProcessor 是存放在只存储 BeanPostProcessor 的集合中。

后面讲到的注册 BeanPostProcessor 步骤,除了注册到统一的集合中外,也会注册到这个特殊的集合中。

先直接跳过循环,直接查看处理完的结果,是否会生成代理类。然而,结果显示只是原有的对象。

这说明要么不满足被切面增强的条件;这个可能性排除了,对于该类以及切面的设置最近不存在改动,不会因此突然在近几个月失效。

或者 AnnotationAwareAspectJAutoProxyCreator 的一些条件没有满足,比如内部的一些 Bean 还没被初始化,因为依赖一些工具对象去进行增强的过程;

或者当前容器还没注册 AnnotationAwareAspectJAutoProxyCreator (理论上,这个可能性最小)。

不过一一排查吧。

image-20190829180205357于是我先在 AnnotationAwareAspectJAutoProxyCreator#postProcessAfterInitialization 的方法内第一行打了一个断点,准备 debug 对象的增强过程。重新启动应用,然后它就这么过去了。。。。

定位获取容器的 BeanPostProcessor 看一下,如下:

意外发现,当前容器中并没有 AnnotationAwareAspectJAutoProxyCreator

一般来说,大部分单例对象都会在所有的 BeanPostProcessor 都注入容器之后才会初始化。

除非这些对象是被 BeanPostProcessor 所依赖的,才会被关联导致提前初始化。

所以是不是 ClinicDoctorUserRepository 被提前初始化了?

顺着这个思路,看一下调用栈,当前方法是在 AbstractApplicationContext#refresh 中的 registerBeanPostProcessor 方法:

image

结合下图看一下,一般来说,容器初始化会调用 AbstractApplicationContext#refresh ,内部会有几个步骤。而会大部分对象的初始化在第二个红框的方法中( finishiBeanFactoryInitialization ),但是 ClinicDoctorUserRepository 却在第一个红框( registerBeanPostProcessor )就被初始化,这说明在注册 BeanPostProcessor ,项目工程的类被依赖导致提前初始化了。

但是即使这样,对象依然是有机会被 AnnotationAwareAspectJAutoProxyCreator 增强的,只要在依赖项目工程类的 BeanPostProcessor 在初始化时,AnnotationAwareAspectJAutoProxyCreator 已经被注册到容器中。

Spring 即使在第一个红框注册所有的 BeanPostProcessor 时,内部也会根据规则,对所有的 BeanPostProcessor 进行分组、排序。然后按照既定的顺序,初始化一组类后统一注册到容器中

image-20190829181617459

顺着调用栈,继续进入 registerBeanPostProcessor 方法查看。

可以看到下图情况,当前是正在在初始化 MethodValidationPostProcessor

而 Spring 初始化 BeanPostProcessor 时,是根据是否实现 PriorityOrderedOrdered 接口,分为三组。

每一组都是全部初始化完成才会统一注册容器中上述所说的特殊集合中。

MethodValidationPostProcessorAnnotationAwareAspectJAutoProxyCreator 都实现了 Ordered ,所以在初始化 MethodValidationPostProcessor 及依赖的 Bean 时,是无法应用 AnnotationAwareAspectJAutoProxyCreator 的。

image.png

但是为什么我们的 Repository 会被这个 MethodValidationPostProcessor 依赖呢,毕竟这个 MethodValidationPostProcessor 是依赖的开源类。那么就有可能是声明的原因。

继续顺着调用栈,就发现依赖初始化了 ClinciWebConfig,而初始化 ClinciWebConfig 会初始化其中依赖的很多 Interceptor ,其中有些 Interceptor 就间接依赖了这个 ClinicDoctorUserRepository

是的,MethodValidationPostProcessor 就声明在这个 ClinciWebConfig

image-20190829180536070

3.结论

到了这里,基本就真相大白了

根本原因:由于 MethodValidationPostProcessor 和 AOP 功能的

AnnotationAwareAspectJAutoProxyCreator 是会一起初始化完成后才注册到容器中,所以被 MethodValidationPostProcessor 所依赖的 Bean 都是无法被 AOP 增强的,甚至无法被 MethodValidationPostProcessor 增强。

而由于 MethodValidationPostProcessorWebConfig 中声明,所以会间接初始化 WebConfig 以及其中依赖的 bean。很不幸的是,该列表分页查询的 ClinciDoctorUserRepository 就在其中。

讲道理,我不禁在想,不止这些被依赖的 Bean 的分页功能、缓存功能,估计甚至方法级别的校验功能可能都是摆设。

但是这个情况实际以前是好的,这说明之前肯定有过处理。

所以,又看了看,于是发现。

直接原因:WebConfig的 Interceptor 依赖的 service 或者 Repository 都是懒加载的,但是最近几个月添加的却落下了 @Lazy。

image

处理方法

1.补上 @Lazy,并且将 MethodValidationPostProcessor 的声明独立为一个 Config 类

补上 @Lazy 基本能解决问题了,但是我觉得为了防止下次可能遗忘,不如将这个配置独立出去。

@Configuration
public class MethodValidationConfig {

    @Bean
    public MethodValidationPostProcessor methodValidationPostProcessor() {
        // 启用方法层面(参数,返回值)的校验,跟@Validated注解配合使用
        MethodValidationPostProcessor processor = new MethodValidationPostProcessor();
        processor.setProxyTargetClass(true);
        return processor;
    }
}

然后登录就会失败。。。。。原因就是用户信息的缓存生效了

/**
 * 查找loginId对应的User并缓存
 */
@Cacheable(value = CACHE_USER, key = KEY_LOGINID + "#loginId", unless = UNLESS_NULL)
public User findByLoginId(@NotNull Long loginId) {}

原因是用户信息反序列化时,反序列 User 类型的 created 或者 updated 会报错。

jodatime 的 DateTime 序列化的信息很特殊,会序列化为下面这串东西

{
	"millisOfDay": 47936000,
	"secondOfDay": 47936,
	"minuteOfDay": 798,
	"centuryOfEra": 20,
	"yearOfEra": 2016,
	"yearOfCentury": 16,
	"weekyear": 2016,
	"monthOfYear": 3,
	"weekOfWeekyear": 10,
	"hourOfDay": 13,
	"minuteOfHour": 18,
	"secondOfMinute": 56,
	"millisOfSecond": 0,
	"era": 1,
	"dayOfYear": 70,
	"dayOfWeek": 4,
	"dayOfMonth": 10,
	"year": 2016,
	"chronology": {
		"@class": "org.joda.time.chrono.ISOChronology",
		"zone": {
			"@class": "org.joda.time.tz.CachedDateTimeZone",
			"uncachedZone": {
				"@class": "org.joda.time.tz.DateTimeZoneBuilder$PrecalculatedZone",
				"cachable": true,
				"fixed": false,
				"id": "Asia/Shanghai"
			},
			"fixed": false,
			"id": "Asia/Shanghai"
		}
	},
	"zone": {
		"@class": "org.joda.time.tz.CachedDateTimeZone",
		"uncachedZone": {
			"@class": "org.joda.time.tz.DateTimeZoneBuilder$PrecalculatedZone",
			"cachable": true,
			"fixed": false,
			"id": "Asia/Shanghai"
		},
		"fixed": false,
		"id": "Asia/Shanghai"
	},
	"millis": 1457587136000,
	"afterNow": false,
	"beforeNow": true,
	"equalNow": false
}

而 Redis 使用的 Jackson 反序列的默认方式是,根据无参构造器生成对象,再按照 json 的 key ,一一设置值,但是上面这串东西在DateTime是没有相应的属性值的。

这个情况是好的,是因为原先代码中 Redis 的valueSerializer使用的是 RedisTemplate 的默认序列化器,即JdkSerializationRedisSerializer

if (defaultSerializer == null) {

   defaultSerializer = new JdkSerializationRedisSerializer(
         classLoader != null ? classLoader : this.getClass().getClassLoader());
}

if (enableDefaultSerializer) {

   if (keySerializer == null) {
      keySerializer = defaultSerializer;
      defaultUsed = true;
   }
   if (valueSerializer == null) {
      valueSerializer = defaultSerializer;
      defaultUsed = true;
   }
   if (hashKeySerializer == null) {
      hashKeySerializer = defaultSerializer;
      defaultUsed = true;
   }
   if (hashValueSerializer == null) {
      hashValueSerializer = defaultSerializer;
      defaultUsed = true;
   }
}

2.解决 Redis 反序列化问题

第一种:自定义 ObjectMapper,增加处理 jodatime 的配置

需要依赖 jar,并且自定义 Redis 序列化器的 ObjectMapper

<dependency>
    <groupId>com.fasterxml.jackson.datatype</groupId>
    <artifactId>jackson-datatype-joda</artifactId>
    <version>2.8.10</version>
</dependency>
ObjectMapper mapper = new ObjectMapper();
mapper.enableDefaultTyping(ObjectMapper.DefaultTyping.NON_FINAL, JsonTypeInfo.As.PROPERTY);
mapper.registerModule(new JodaModule());
redisTemplate.setValueSerializer(new GenericJackson2JsonRedisSerializer(mapper));

这样的处理方式,会将时间默认反序列化一个时间戳的值。

{
	"@class": "com.xxxx.clinic.domain.tables.pojos.User",
	"id": -1,
	"loginid": -1,
	"type": "DOCTOR",
	"name": "\xe5\xb0\x8fD",
	"password": "",
	"thumbnail": "http://img.xxxx.com/7xxxxx",
	"serial": "xxxxx",
	"test": false,
	"created": 1457587136000,
	"updated": 1565580579000,
	"deleted": false
}

由于这个缓存使用时,是会直接反序列化为 pojo 。但是 jackson 默认是反序列化 LinkedHashMap ,因此在使用自定义 ObjectMapper ,需要有这段配置,这也是 GenericJackson2JsonRedisSerializer 内部的默认配置。

mapper.enableDefaultTyping(ObjectMapper.DefaultTyping.NON_FINAL, JsonTypeInfo.As.PROPERTY);

这段配置会在生成的 json ,存储一份 pojo 的类型信息,就是上面 json 中的 @class。

参考资料

jackson多态类型数据绑定

Jackson jodatime 序列化