在spring-boot项目中同时使用shiro和spring-retry产生的问题及排查

本文实际于2022年8月11日开始写作


环境

Windows 10 21H1
JDK 8 Update 161
IDEA 2022.2
Maven 3.5.2

项目相关依赖及版本

spring 5.1.10.RELEASE
spring-boot 2.1.9.RELEASE
spring-cloud 2.1.3.RELEASE
shiro 1.8.0
shiro-spring 1.8.0
spring-retry 1.2.4.RELEASE


现象

业务代码不便透露，测试代码如下

@Slf4j
@Component
public class Certain {

    @Retryable(value = Exception.class, maxAttempts = 3, backoff = @Backoff(value = 5000L, multiplier = 3))
    public int doSomething(int b) {
        int a = 100;
        return Math.floorDiv(a, b);
    }

}

此处@Retryable注解含义：最多重试三次，第一次重试在5秒之后，第二次则是第一次重试失败后的15秒，对于所有的Exception都生效

然后注入到测试类中调用，将org.springframework.retry包的日志级别调整为DEBUG，传0保证能够抛异常，此时观察日志


@RunWith(SpringRunner.class)
@SpringBootTest(properties = {
    "logging.level.org.springframework.retry=DEBUG"
})
public class Tests {
    
    @Autowired
    private Certain certain;
    
    @Test
    public void testDoSomething() {
        int r = certain.doSomething(0);
        
        System.out.println(r);
    }
}

2022-09-06 18:14:23.037 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=0
2022-09-06 18:14:23.041 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=0
2022-09-06 18:14:23.044 DEBUG --- [           main] o.s.r.backoff.ExponentialBackOffPolicy   : Sleeping for 5000
2022-09-06 18:14:28.054 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=1
2022-09-06 18:14:28.054 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=1
2022-09-06 18:14:28.054 DEBUG --- [           main] o.s.r.backoff.ExponentialBackOffPolicy   : Sleeping for 15000
2022-09-06 18:14:43.069 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=2
2022-09-06 18:14:43.069 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=2
2022-09-06 18:14:43.069 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=3
2022-09-06 18:14:43.069 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry failed last attempt: count=3
2022-09-06 18:14:43.069 DEBUG --- [           main] o.s.r.backoff.ExponentialBackOffPolicy   : Sleeping for 5000
2022-09-06 18:14:48.083 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=1
2022-09-06 18:14:48.083 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=1
2022-09-06 18:14:48.083 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=0
2022-09-06 18:14:48.083 DEBUG --- [           main] o.s.r.backoff.ExponentialBackOffPolicy   : Sleeping for 5000
2022-09-06 18:14:53.085 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=1
2022-09-06 18:14:53.085 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=1
2022-09-06 18:14:53.086 DEBUG --- [           main] o.s.r.backoff.ExponentialBackOffPolicy   : Sleeping for 15000
2022-09-06 18:15:08.099 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=2
2022-09-06 18:15:08.099 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=2
2022-09-06 18:15:08.099 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=3
2022-09-06 18:15:08.099 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry failed last attempt: count=3
2022-09-06 18:15:08.099 DEBUG --- [           main] o.s.r.backoff.ExponentialBackOffPolicy   : Sleeping for 15000
2022-09-06 18:15:23.115 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=2
2022-09-06 18:15:23.115 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=2
2022-09-06 18:15:23.115 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=0
2022-09-06 18:15:23.116 DEBUG --- [           main] o.s.r.backoff.ExponentialBackOffPolicy   : Sleeping for 5000
2022-09-06 18:15:28.125 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=1
2022-09-06 18:15:28.125 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=1
2022-09-06 18:15:28.126 DEBUG --- [           main] o.s.r.backoff.ExponentialBackOffPolicy   : Sleeping for 15000
2022-09-06 18:15:43.133 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=2
2022-09-06 18:15:43.133 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry: count=2
2022-09-06 18:15:43.133 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=3
2022-09-06 18:15:43.133 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry failed last attempt: count=3
2022-09-06 18:15:43.133 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Checking for rethrow: count=3
2022-09-06 18:15:43.133 DEBUG --- [           main] o.s.retry.support.RetryTemplate          : Retry failed last attempt: count=3

java.lang.ArithmeticException: / by zero

    at java.lang.Math.floorDiv(Math.java:1052)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:750)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor$1.doWithRetry(RetryOperationsInterceptor.java:91)
    at org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:287)
    at org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:164)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor.invoke(RetryOperationsInterceptor.java:118)
    at org.springframework.retry.annotation.AnnotationAwareRetryOperationsInterceptor.invoke(AnnotationAwareRetryOperationsInterceptor.java:153)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:750)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor$1.doWithRetry(RetryOperationsInterceptor.java:91)
    at org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:287)
    at org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:164)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor.invoke(RetryOperationsInterceptor.java:118)
    at org.springframework.retry.annotation.AnnotationAwareRetryOperationsInterceptor.invoke(AnnotationAwareRetryOperationsInterceptor.java:153)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.springframework.test.context.junit4.statements.RunBeforeTestExecutionCallbacks.evaluate(RunBeforeTestExecutionCallbacks.java:74)
    at org.springframework.test.context.junit4.statements.RunAfterTestExecutionCallbacks.evaluate(RunAfterTestExecutionCallbacks.java:84)
    at org.springframework.test.context.junit4.statements.RunBeforeTestMethodCallbacks.evaluate(RunBeforeTestMethodCallbacks.java:75)
    at org.springframework.test.context.junit4.statements.RunAfterTestMethodCallbacks.evaluate(RunAfterTestMethodCallbacks.java:86)
    at org.springframework.test.context.junit4.statements.SpringRepeat.evaluate(SpringRepeat.java:84)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:251)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:97)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
    at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
    at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:190)
    at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
    at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:69)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38)
    at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11)
    at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
    at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:235)
    at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)

实际加上了@Retryable注解的方法整整执行了9次！


表因

重新跑测试类，debug到重试机制的主要逻辑RetryTemplate.doExecute()方法中，可以看到第一次进断点这里的方法调用（invocation）代理对象和目标对象都被代理了

① proxy和target都是代理后的对象

直到第二次进入断点，目标对象才是原本的bean，这时候调用才会执行方法本身的代码

② target是原本的对象

说明引入spring-retry库后（后面发现问题与此无关），框架中的bean都被二次代理了，而由于代理之后的对象仍然会被增强，从而在方法上再次加上@Retryable注解对应的切面，所以例子中的测试代码才会执行3\times3=9次


根因

查看其他人的博客和文章(1)(2)(3)(4)后发现，实际上问题并非是引入spring retry依赖导致的，而是只要在一部分spring boot项目中集成shiro框架，并按照网上常见的方式配置，就会导致对象的二次代理，从而产生上述问题，只是恰好在加了spring retry库之后问题比较明显

  • 首先shiro的常见配置，大部分文章都会要求加下面这段代码，手动new一个默认的自动代理创建器（auto-proxy creator，下面简称apc）放到spring框架中，并且将代理目标类设置为true，即使用CGLib方式创建代理，实现角色权限控制的功能

    @Bean
@DependsOn({"lifecycleBeanPostProcessor"})
public DefaultAdvisorAutoProxyCreator defaultAdvisorAutoProxyCreator() {
    DefaultAdvisorAutoProxyCreator advisorAutoProxyCreator = new DefaultAdvisorAutoProxyCreator();
    advisorAutoProxyCreator.setProxyTargetClass(true);

    return advisorAutoProxyCreator;
}

  • 但是目前绝大多数情况下，都是在spring boot项目中使用shiro进行权限控制，此时只要项目已经有下面这两个依赖（直接或间接），并且没有作特殊配置，像AutoProxyRegistrar、AspectJAutoProxyRegistrar这类的注册器可以正常运行，其实就已经能够支持shiro的基于代理和切面的权限控制了，不需要再额外添加上述的apc

    <dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
    <version>2.1.9.RELEASE</version>
</dependency>
<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-autoconfigure</artifactId>
    <version>2.1.9.RELEASE</version>
</dependency>

  • 既然提到了自动代理创建器，其中比较重要的类有

    • InfrastructureAdvisorAutoProxyCreator，基础架构advisor自动代理创建器，主要用于为spring框架内的advisor所匹配的bean创建代理，除此之外，当项目不依赖spring-boot-autoconfigure时，是不会有TransactionAutoConfiguration这个自动配置类的，要实现事务管理或者异步方法执行等功能，就依靠这个apc
    • AnnotationAwareAspectJAutoProxyCreator，AspectJ注解感知式自动代理创建器，这也是目前的spring boot项目中最常使用的apc，相比于之前其他的apc增加了对AspectJ注解的探测支持，例如@Before、@After、@Around等

    以上实现类都继承自AbstractAutoProxyCreator这个抽象类，这里也包含了主要的代码逻辑，关键方法有wrapIfNecessary()、shouldSkip()、findEligibleAdvisors()、createProxy()，感兴趣的话可以自行探索

  • 需要注意的是若要集成shiro，下面这个advisor是必须要注册到框架中的，用于匹配合适的bean（例如加上了@RequiresPermissions或者@RequiresRoles注解），并且在创建代理对象的时候添加shiro的切面逻辑

    @Bean
public AuthorizationAttributeSourceAdvisor authorizationAttributeSourceAdvisor(SecurityManager securityManager){
    AuthorizationAttributeSourceAdvisor authorizationAttributeSourceAdvisor = new AuthorizationAttributeSourceAdvisor();
    authorizationAttributeSourceAdvisor.setSecurityManager(securityManager);

    return authorizationAttributeSourceAdvisor;
}


方案

把自定义配置类中注册DefaultAdvisorAutoProxyCreator的那段代码去掉就可以了，但是有些情况下依然会存在二次代理的现象

  1. 项目依赖了shiro-spring-boot-starter，下面有很多默认的自动配置类，其中的一个自动配置类会注册一个默认的apc，可以通过设置spring boot启动注解的exclude参数，将不需要的自动配置排除掉

    <dependency>
    <groupId>org.apache.shiro</groupId>
    <artifactId>shiro-spring-boot-starter</artifactId>
    <version>1.9.1</version>
</dependency>

    由于我的项目自定义了shiro相关的配置，所以启动类注解设置如下便可以起效

    @SpringBootApplication(exclude = {
        ShiroAnnotationProcessorAutoConfiguration.class,
        ShiroWebAutoConfiguration.class,
        org.apache.shiro.spring.boot.autoconfigure.ShiroAutoConfiguration.class
})

  2. 项目没有依赖shiro-spring-boot-starter，但是shiro-spring包中存在ShiroAnnotationProcessorConfiguration配置类，可能在集成shiro框架的时候扫描了这个包路径，去掉就可以了

    package org.apache.shiro.spring.config;

@Configuration
public class ShiroAnnotationProcessorConfiguration extends AbstractShiroAnnotationProcessorConfiguration{

    @Bean
    @DependsOn("lifecycleBeanPostProcessor")
    protected DefaultAdvisorAutoProxyCreator defaultAdvisorAutoProxyCreator() {
        return super.defaultAdvisorAutoProxyCreator();
    }

    ...
}

  3. 另外，还有一种方法(3)是将usePrefix属性设置为true，可以保留这个apc，同时避免没有添加shiro权限注解的类对应的bean被创建代理，采取这种方案时需要注意，shiro的AuthorizationAttributeSourceAdvisor注册到spring框架中的bean名称也需要修改，格式是apc名称.advisor名称，以达到apc和advisor匹配的效果

    @Bean
@DependsOn({"lifecycleBeanPostProcessor"})
public DefaultAdvisorAutoProxyCreator defaultAdvisorAutoProxyCreator() {
    DefaultAdvisorAutoProxyCreator advisorAutoProxyCreator = new DefaultAdvisorAutoProxyCreator();
    advisorAutoProxyCreator.setUsePrefix(true);

    return advisorAutoProxyCreator;
}

@Bean(name = "defaultAdvisorAutoProxyCreator.authorizationAttributeSourceAdvisor")
public AuthorizationAttributeSourceAdvisor authorizationAttributeSourceAdvisor(SecurityManager securityManager){
    AuthorizationAttributeSourceAdvisor authorizationAttributeSourceAdvisor = new AuthorizationAttributeSourceAdvisor();
    authorizationAttributeSourceAdvisor.setSecurityManager(securityManager);

    return authorizationAttributeSourceAdvisor;
}

    但是那些已经加上shiro权限注解的类的bean，仍然会被创建两次代理

最后再强调一点，上面提到的方案只适用于已经正常加载并使用spring aop的项目，但是对于其他类型的项目暂未测试，请谨慎修改


后记

后面又对经过二次代理的对象进行了测试，发现除了spring retry的重试机制之外，其他几种常见的基于AOP的机制都没有明显的问题

  • shiro的权限控制，执行时确实会获取两次授权信息AuthorizingRealm.doGetAuthorizationInfo()并进行校验，但是对于大部分应用来说，根据密钥、令牌获取授信信息的操作应该是幂等的，多次调用也不会有什么影响，也就是多打印几行日志

    而且在权限不足时，第一次获取授权信息校验阶段就已经抛出异常了，不会再走第二次
    权限切面获取到的方法调用，两者均为代理对象


  • spring的事务管理，执行方法时也会创建两次事务TransactionAspectSupport.invokeWithinTransaction()，并且第二次创建事务时，会把上一次的事务信息放到oldTransactionInfo这个字段中，尚不清楚这种情况下，传播模式和隔离级别等参数的设置是否会对事务管理产生影响，需要后续测试验证

    至少在采用默认设置时，事务的提交和回滚是正常的
    txInfo包含前一次的事务信息


  • spring的异步方法执行，这个机制的生效方式，相比前两个通过框架中已有的apc创建代理的方式有所不同，启用后不会向spring框架中注入advisor的bean，导致被多个apc重复探测，而是利用AbstractAdvisingBeanPostProcessor这个后处理器，针对性的处理加了@Async注解的bean，只处理一次

    而且处理的方式也很精细，如果传入的bean已经被代理过了，则将异步切面放到第一个，而当传入的bean没有被代理过，才会创建代理对象

        ...
    if (bean instanceof Advised) {
        Advised advised = (Advised) bean;
        if (!advised.isFrozen() && isEligible(AopUtils.getTargetClass(bean))) {
            // Add our local Advisor to the existing proxy's Advisor chain...
            if (this.beforeExistingAdvisors) {
                advised.addAdvisor(0, this.advisor);
            }
            else {
                advised.addAdvisor(this.advisor);
            }
            return bean;
        }
    }

    if (isEligible(bean, beanName)) {
        ProxyFactory proxyFactory = prepareProxyFactory(bean, beanName);
        if (!proxyFactory.isProxyTargetClass()) {
            evaluateProxyInterfaces(bean.getClass(), proxyFactory);
        }
        proxyFactory.addAdvisor(this.advisor);
        customizeProxyFactory(proxyFactory);
        return proxyFactory.getProxy(getProxyClassLoader());
    }
    ...

    所以异步方法执行的切面，任何情况下都只会执行一次，不会因为对象是否被二次代理所影响


参考

(1) ShiroAutoConfiguration加入DefaultAdvisorAutoProxyCreator造成的二次代理

(2) Spring-retry set to try again 6 times the results of retry 36 times

(3) Shiro权限注解与Aop冲突问题的前世今生

(4) 由于整合shiro导致的BeanNotOfRequiredTypeException：Caused by: but was actually of type 'com.sun.proxy.$Proxy

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
平台声明：文章内容（如有图片或视频亦包括在内）由作者上传并发布，文章内容仅代表作者本人观点，简书系信息发布平台，仅提供信息存储服务。

推荐阅读更多精彩内容