关于java:记一次因Async引发的程序bug

1次阅读

共计 10315 个字符，预计需要花费 26 分钟才能阅读完成。

事件的起因是微服务 A 通过 feign 调用微服务 B 的某个接口，报了形如下的异样

feign.FeignException$NotFound: [404] during [GET] to [http://feign-provider/test/async] [AyncTestServiceClient#testAsync()]: [{"timestamp":"2022-05-28T01:16:36.283+0000","status":404,"error":"Not Found","message":"No message available","path":"/test/async"}]

负责微服务 A 的工程师小张就找到负责提供该接口的工程师小李，问小李是不是改变了接口，小李一脸无辜说他最近没对这个接口做任何改变，不过小李还是说道他排查一下。

小李排查的过程如下，他先通过 swagger 查看他提供给 A 服务接口是否存在，他一查发现他在 swagger 上看不到他提供给 A 服务的接口。于是他狐疑是不是有人动了他的代码，他就去查找最近的 git 提交记录，发现没人动他的代码，因为我的项目还没公布，都在测试阶段，他就依据我的项目集成的 git-commit-id-maven-plugin 插件定位到测试目前公布具体是哪个版本。（ps：对
git-commit-id-maven-plugin 感兴趣的敌人，能够查看之前的文章聊聊如何验证线上的版本是合乎预期的版本）。而后他将该版本的代码下到本地进行调试，他发现代码中提供给 A 的接口还在，target 下的 class 也有提供给 A 的接口 class，但诡异的是 swagger 就是没显示他提供进来的接口，他一度认为是 swagger 出了问题，于是他用 postman 间接申请他提供 A 的接口，发现报了 404。而后他就叫负责同个微服务 B 的共事小王，也帮忙试一下，发现后果就是 404。前面没招，小李就去求助他们我的项目资深共事小林。

小林的排查思路如下，他先走查一下小李的接口代码，发现他提供的接口实现层的办法上加了一个 @Async，示例形如下

@RestController
@RequestMapping(AsyncTestService.INTER_NAME)
public class AsyncTestServiceImpl implements AsyncTestService{@GetMapping("async")
    @Override
    public String testAsync() {System.out.println("testAsync start....");
        this.doAsynBiz();
        System.out.println("testAsync end....");
        return "hello async";
    }

    @Async
    public void doAsynBiz(){System.out.println("doAsynBiz.....");
        }

    }

小林凭多年的教训直觉通知小李说，应该是 @Async 引起。小李很斩钉截铁的说不可能啊，他 @Async 很早就加了，之前接口都能够拜访的，小林一看小李说得那么必定，他也不好打击小李。于是他接下来做了如下操作，先在我的项目中 yml 配置如下参数，开启 springweb 日志

logging:
  level:
    org.springframework.web: trace

而后在我的项目中加了形如下代码，来跟踪接口 bean 的类型

  for (String beanDefinitionName : applicationContext.getBeanDefinitionNames()) {if(beanDefinitionName.toLowerCase().startsWith("AsyncTestService".toLowerCase())){System.err.println(beanDefinitionName + "=" + applicationContext.getBean(beanDefinitionName).getClass());
            }
        }

启动控制台，看日志形如下

c.d.f.c.ConfigController:
    {GET /config/test}: test()
09:15:04 [main] TRACE o.s.w.s.m.m.a.RequestMappingHandlerMapping - 
    c.d.f.c.ConfigController:
    {GET /config/test}: test()
2022-05-28 09:15:04.564 TRACE 10120 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    c.d.f.i.UserServiceImpl:
    {GET /user/{id}}: getUserById(Long)
09:15:04 [main] TRACE o.s.w.s.m.m.a.RequestMappingHandlerMapping - 
    c.d.f.i.UserServiceImpl:
    {GET /user/{id}}: getUserById(Long)
2022-05-28 09:15:04.577 TRACE 10120 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    s.d.s.w.ApiResourceController:
    {/swagger-resources/configuration/ui}: uiConfiguration()
    {/swagger-resources}: swaggerResources()
    {/swagger-resources/configuration/security}: securityConfiguration()
09:15:04 [main] TRACE o.s.w.s.m.m.a.RequestMappingHandlerMapping - 
    s.d.s.w.ApiResourceController:
    {/swagger-resources/configuration/ui}: uiConfiguration()
    {/swagger-resources}: swaggerResources()
    {/swagger-resources/configuration/security}: securityConfiguration()
2022-05-28 09:15:04.590 TRACE 10120 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    o.s.b.a.w.s.e.BasicErrorController:
    {/error}: error(HttpServletRequest)
    {/error, produces}: errorHtml(HttpServletRequest,HttpServletResponse)
09:15:04 [main] TRACE o.s.w.s.m.m.a.RequestMappingHandlerMapping - 
    o.s.b.a.w.s.e.BasicErrorController:
    {/error}: error(HttpServletRequest)
    {/error, produces}: errorHtml(HttpServletRequest,HttpServletResponse)

发现的确没打印出相干 requestMapping 映射信息，这能够阐明一点就是小李那个接口没有绑定到 springmvc 映射，也就是呈现 404 的起因。接着察看控制台打印的 bean，内容形如下

asyncTestServiceImpl=class com.sun.proxy.$Proxy127

这很显著这个接口 bean 曾经被 jdk 动静代理给替换。小李看到控制台打印的信息，若有所思，而后说，我把 @Async 去掉试下。小李把 @Async 去掉后，再察看下控制台

2022-05-28 10:09:40.814 TRACE 13028 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    c.d.f.c.AsyncTestServiceImpl:
    {GET /test/async}: testAsync()
10:09:40 [main] TRACE o.s.w.s.m.m.a.RequestMappingHandlerMapping - 
    c.d.f.c.AsyncTestServiceImpl:
    {GET /test/async}: testAsync()
2022-05-28 10:09:40.817 TRACE 13028 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    c.d.f.c.ConfigController:
    {GET /config/test}: test()
10:09:40 [main] TRACE o.s.w.s.m.m.a.RequestMappingHandlerMapping - 
    c.d.f.c.ConfigController:
    {GET /config/test}: test()
2022-05-28 10:09:40.820 TRACE 13028 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    c.d.f.i.UserServiceImpl:
    {GET /user/{id}}: getUserById(Long)

asyncTestServiceImpl=class com.demo.feign.controller.AsyncTestServiceImpl

通过控制台能够发现，此时接口曾经绑定到 springmvc 映射，而且打印出 bean 类型是实在对象 bean。小李看到这个景象，也百思不得其解，他说道他之前的确是加了 @Async，接口也能失常拜访。于是小林就问一句，你确定你加了 @Async，异步失效了吗，小李说开启 spring 异步，不都是加 @Async 吗。小林又问了一句，你在我的项目中开启异步，除了加 @Async，还有做什么解决吗，小李说没了，他之前在我的项目应用异步就都是加了 @Async，也能用了好好的，小林一听，基本上晓得为什么小李之前 @Async，接口还能失常拜访了，小林为了验证想法，就问同负责该项目标小王，说你最近有加什么异步操作吗，小王说有，小林进一步问，你是怎么做的，小王说，他先加 @EnabledAsyn，开启异步，而后在业务逻辑层上的办法上加 @Async 注解。小李一听，说原来应用 @Async 还要配合 @EnabledAsyn 啊，他之前都不晓得

接着小李说 那在 controller 是不是就不能应用 @Async 注解了？，小林说最好是把加 @Async 的逻辑挪到 service 层去解决，不过也不是 controller 就不能应用 @Async 注解了，接着小林为了验证这个想法，他把原来实现的接口类去掉，形如下

@RestController
@RequestMapping(AsyncTestService.INTER_NAME)
public class AsyncTestServiceImpl{@GetMapping("async")
    public String testAsync() {System.out.println(Thread.currentThread().toString() + "-----testAsync start....");
        this.doAsynBiz();
        System.out.println(Thread.currentThread().toString() + "-----testAsync end....");
        return "hello async";
    }

    @Async
    public void doAsynBiz(){System.out.println(Thread.currentThread().toString() + "-----doAsynBiz.....");
        }

    }

启动后，查看控制台

2022-05-28 10:41:31.624 TRACE 5068 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    c.d.f.c.AsyncTestServiceImpl:
    {GET /test/async}: testAsync()
10:41:31 [main] TRACE o.s.w.s.m.m.a.RequestMappingHandlerMapping - 
    c.d.f.c.AsyncTestServiceImpl:
    {GET /test/async}: testAsync()
2022-05-28 10:41:31.627 TRACE 5068 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    c.d.f.c.ConfigController:
    {GET /config/test}: test()
10:41:31 [main] TRACE o.s.w.s.m.m.a.RequestMappingHandlerMapping -

此时 bean 的类型如下

asyncTestServiceImpl=class com.demo.feign.controller.AsyncTestServiceImpl$$EnhancerBySpringCGLIB$$a285a21c

拜访接口，打印内容如下

Thread[http-nio-8080-exec-1,5,main]-----testAsync start....
Thread[http-nio-8080-exec-1,5,main]-----doAsynBiz.....
Thread[http-nio-8080-exec-1,5,main]-----testAsync end....

从控制台能够发现，都是 http-nio-8080-exec- 1 线程触发，阐明异步没失效，即 @Async 生效。前面对 controller 做了如下革新

@RestController
@RequestMapping(AsyncTestService.INTER_NAME)
public class AsyncTestServiceImpl{


    @Autowired
    private ObjectProvider<AsyncTestServiceImpl> asyncTestServices;


    @GetMapping("async")
    public String testAsync() {System.out.println(Thread.currentThread().toString() + "-----testAsync start....");
        asyncTestServices.getIfAvailable().doAsynBiz();
        System.out.println(Thread.currentThread().toString() + "-----testAsync end....");
        return "hello async";
    }

    @Async
    public void doAsynBiz(){System.out.println(Thread.currentThread().toString() + "-----doAsynBiz.....");
        }

    }

拜访接口，打印内容如下

Thread[http-nio-8080-exec-2,5,main]-----testAsync start....
Thread[http-nio-8080-exec-2,5,main]-----testAsync end....
Thread[task-1,5,main]-----doAsynBiz.....

这阐明在 controller 其实也是能够用 @Async，只是要额定做解决。所以倡议是把 @Async 从 controller 中抽离进来，在新类中进行解决，示例如下

@Service
public class AysncService {

    @Async
    public void doAsynBiz(){System.out.println(Thread.currentThread().getName() + "-----doAsynBiz.....");
    }
}

@RestController
@RequestMapping(AsyncTestService.INTER_NAME)
@RequiredArgsConstructor
public class AsyncTestServiceImpl implements AsyncTestService {

    private final AysncService aysncService;


    @Override
    public String testAsync() {System.out.println(Thread.currentThread().getName() + "-----testAsync start....");
        aysncService.doAsynBiz();
        System.out.println(Thread.currentThread().getName() + "-----testAsync end....");
        return "hello async";
    }
}

拜访接口，打印内容

http-nio-8080-exec-1-----testAsync start....
http-nio-8080-exec-1-----testAsync end....
task-1-----doAsynBiz.....

阐明异步失效

1、接口 404

从 mvc 日志

2022-05-28 10:59:50.394 TRACE 14152 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping : 
    c.d.f.c.AsyncTestServiceImpl:
    {GET /test/async}: testAsync()
10:59:50 [main] TRACE o.s.w.s.m.m.a.RequestMappingHandlerMapping - 
    c.d.f.c.AsyncTestServiceImpl:
    {GET /test/async}: testAsync()
2022-05-28 10:59:50.397 TRACE 14152 --- [main] s.w.s.m.m.a.RequestMappingHandlerMapping :

咱们能够晓得，controller 映射解决是在 RequestMappingHandlerMapping 这个类中，但具体是哪个办法进行解决呢，咱们能够通过日志打印的信息，进行倒推，也能够基于 spring 的个性加断点调试，比方通过 afterPropertiesSet 这一启动扩大点调试起，就会发现 RequestMappingHandlerMapping 的映射解决是在

    protected void initHandlerMethods() {for (String beanName : getCandidateBeanNames()) {if (!beanName.startsWith(SCOPED_TARGET_NAME_PREFIX)) {processCandidateBean(beanName);
            }
        }
        handlerMethodsInitialized(getHandlerMethods());
    }

进行解决，具体是通过 processCandidateBean 进行解决

    protected void processCandidateBean(String beanName) {
        Class<?> beanType = null;
        try {beanType = obtainApplicationContext().getType(beanName);
        }
        catch (Throwable ex) {
            // An unresolvable bean type, probably from a lazy bean - let's ignore it.
            if (logger.isTraceEnabled()) {logger.trace("Could not resolve type for bean'" + beanName + "'", ex);
            }
        }
        if (beanType != null && isHandler(beanType)) {detectHandlerMethods(beanName);
        }
    }

最终是通过 detectHandlerMethods 进行解决

protected void detectHandlerMethods(Object handler) {
        Class<?> handlerType = (handler instanceof String ?
                obtainApplicationContext().getType((String) handler) : handler.getClass());

        if (handlerType != null) {Class<?> userType = ClassUtils.getUserClass(handlerType);
            Map<Method, T> methods = MethodIntrospector.selectMethods(userType,
                    (MethodIntrospector.MetadataLookup<T>) method -> {
                        try {return getMappingForMethod(method, userType);
                        }
                        catch (Throwable ex) {
                            throw new IllegalStateException("Invalid mapping on handler class [" +
                                    userType.getName() + "]:" + method, ex);
                        }
                    });
            if (logger.isTraceEnabled()) {logger.trace(formatMappings(userType, methods));
            }
            methods.forEach((method, mapping) -> {Method invocableMethod = AopUtils.selectInvocableMethod(method, userType);
                registerHandlerMethod(handler, invocableMethod, mapping);
            });
        }
    }

这个外面就是做了理论注册。而执行 detectHandlerMethods 的前提是

beanType != null && isHandler(beanType)

    @Override
    protected boolean isHandler(Class<?> beanType) {return (AnnotatedElementUtils.hasAnnotation(beanType, Controller.class) ||
                AnnotatedElementUtils.hasAnnotation(beanType, RequestMapping.class));
    }

即只有加了 @Controller 或者 @RequestMapping 的类会进行解决，而 @RestController 为啥也解决，点击
@RestController 发现

@Target(ElementType.TYPE)
@Retention(RetentionPolicy.RUNTIME)
@Documented
@Controller
@ResponseBody
public @interface RestController {

他实质就是 @Controller。但咱们通过反射查找注解，失常只会查找一层，比方

 AsynTestController.class.getAnnotation(RestController.class)

他找到 @RestController 这一层，而不会找持续再找 @RestController 外面的 @Controller，而 AnnotatedElementUtils.hasAnnotation，这个注解办法就不一样，他是能够找到合并注解，即便是应用
@RestController，他还会持续找到外面的 @Controller。因而这个办法对于找复合型注解很有用

当咱们应用 jdk 动静代理时，因为父类上没加 @Controller 或者 @RequestMapping，因而他不会被 mvc 进行映射解决，导致 404。而应用 cglib 时，因为他是作为子类继承了指标类，因而他会继承指标类上的注解，因而当为 cglib 代理时，他会失常被 mvc 进行映射解决