Remember a program bug caused by @Async

foreword

The cause of the incident is that microservice A calls an interface of microservice B through feign, and the following exception is reported

 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"}]

Xiao Zhang, the engineer in charge of microservice A, found Xiao Li, the engineer responsible for providing the interface, and asked Xiao Li if he had changed the interface. Xiao Li said innocently that he had not made any changes to the interface recently, but Xiao Li still said that he Check it out.

Troubleshooting process

The process of Xiao Li's investigation is as follows. He first uses swagger to check whether the service interface he provided to A exists. After checking, he found that he could not see the interface he provided to service A on swagger. So he wondered if someone moved his code, so he went to look up the latest git commit record, and found that no one moved his code, because the project has not been released yet, it is still in the testing phase, so he based on the git-commit integrated by the project The -id-maven-plugin plugin locates which version of the test is currently released. (ps: yes
Friends who are interested in git-commit-id-maven-plugin, you can check the previous article to talk about how to verify that the online version is the expected version ). Then he downloaded this version of the code locally for debugging. He found that the interface provided to A in the code was still there, and the class under the target also had the interface class provided to A, but the strange thing was that swagger did not display the interface he provided. , he once thought that there was a problem with swagger, so he used postman to directly request him to provide the interface of A, and found that a 404 was reported. Then he asked Xiao Wang, his colleague in charge of the same microservice B, to try it out, and found that the result was 404. There was no move later, so Xiao Li went to help Xiao Lin, a senior colleague of their project.

Xiaolin's investigation idea is as follows. He first went to check Xiaoli's interface code and found that @Async was added to the method of the interface implementation layer provided by him. The example is as follows

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

    }

Based on years of experience, Xiaolin intuitively told Xiao Li that it should be caused by @Async. Xiao Li firmly said it was impossible. He added @Async very early, and the previous interface was accessible. Xiao Lin saw that Xiao Li said it so definitely, and he was not good at attacking Xiao Li. So he next did the following operations, first configure the following parameters in yml in the project, and open the spring web log

 logging:
  level:
    org.springframework.web: trace

Then add the following code to the project to track the type of interface bean

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

Start the console and see the log as follows

 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 [text/html]}: 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 [text/html]}: errorHtml(HttpServletRequest,HttpServletResponse)

It is found that the relevant requestMapping mapping information is not printed out, which can indicate that Xiao Li's interface is not bound to the springmvc mapping, which is the reason for the 404. Then observe the bean printed by the console, the content is as follows

 asyncTestServiceImpl=class com.sun.proxy.$Proxy127

It is obvious that this interface bean has been replaced by jdk dynamic proxy. Xiao Li thought about the information printed on the console, and then said, I will try to remove @Async. After Xiao Li removed @Async, observe the console again

 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

It can be found through the console that the interface has been bound to the springmvc mapping at this time, and the printed bean type is the real object bean. Xiao Li was also puzzled when he saw this phenomenon. He said that he did add @Async before, and the interface could be accessed normally. So Xiaolin asked, are you sure that you have added @Async, is the asynchrony effective? Xiaoli said that when spring async is enabled, isn't it all adding @Async? Xiaolin asked again, if you enable asynchrony in your project, is there anything else to do besides adding @Async? Xiaoli said no, he used async in the project before adding @Async, and it can be used well Yes, as soon as Xiaolin heard it, he basically knew why Xiaoli was @Async before, and the interface can still be accessed normally. In order to verify the idea, Xiaolin asked Xiao Wang, who was also in charge of the project, and said, have you added any asynchronous operations recently, Xiao Wang Saying yes, Xiaolin further asked, how did you do it, Xiao Wang said, he first added @EnabledAsyn to enable asynchronous, and then added @Async annotation to the method on the business logic layer. When Xiao Li heard it, he said that using @Async had to cooperate with @EnabledAsyn. He didn't know that before.

Then Xiao Li said that the @Async annotation cannot be used in the controller? , Xiaolin said that it is best to move the logic of adding @Async to the service layer for processing, but it is not the controller that cannot use the @Async annotation. Then, in order to verify this idea, Xiaolin removed the originally implemented interface class, as follows

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

    }

After startup, view the console

 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 -

At this point the type of the bean is as follows

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

Access the interface, the print content is as follows

 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....

It can be found from the console that it is triggered by the http-nio-8080-exec-1 thread, indicating that the asynchrony does not take effect, that is, @Async fails. The following modifications were made to the controller later

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

    }

Access the interface, the print content is as follows

 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.....

This shows that @Async can actually be used in the controller, but additional processing is required. So the suggestion is to extract @Async from the controller and process it in a new class. The example is as follows

 @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";
    }
}

access interface, print content

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

Description Asynchronous take effect

Analysis of investigation results

1. Interface 404

log from 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 :

We can know that the controller mapping processing is in the class RequestMappingHandlerMapping, but which method is used to process it? We can use the information printed in the log to push backwards, or we can add breakpoint debugging based on the characteristics of spring, such as through afterPropertiesSet. As soon as you start the extension point debugging, you will find that the mapping processing of RequestMappingHandlerMapping is in

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

Process, specifically through 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);
        }
    }

Finally, it is processed through 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);
            });
        }
    }

This is where the actual registration is done. The premise of executing detectHandlerMethods is

 beanType != null && isHandler(beanType)

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

That is, only the class with @Controller or @RequestMapping will be processed, and why is @RestController also processed, click
@RestController found

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

Its essence is @Controller. But we look for annotations through reflection, normally only one layer is looked up, such as

 AsynTestController.class.getAnnotation(RestController.class)

He finds the layer of @RestController, instead of continuing to find @Controller in @RestController, and AnnotatedElementUtils.hasAnnotation, this annotation method is different, he can find merge annotations, even if using
@RestController, he will continue to find the @Controller inside. So this method is useful for finding composite annotations

When we use jdk dynamic proxy, because there is no @Controller or @RequestMapping added to the parent class, it will not be mapped by mvc, resulting in 404. When using cglib, because he inherits the target class as a subclass, he will inherit the annotations on the target class, so when it is a proxy for cglib, he will be mapped by mvc normally.

2. Why does adding @Asyn to the controller fail asynchronously?

This is because after adding @Async, the controller becomes a proxy, and when using this asynchronously, it uses the target object instead of the proxy object. This is basically the same as the eight-legged essay on why the business of the interview is invalid.

Summarize

This article mainly talks about the reason why @Async causes controller 404 and also makes @Async invalid. The recommended solution is to extract @Async from the controller and create a new service class for processing.