记一次因@Async引发的程序bug

2022-07-19 11:33:45 浏览数 (1)

前言

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

代码语言:java复制
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,示例形如下

代码语言:java复制
@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日志

代码语言:yaml复制
logging:
  level:
    org.springframework.web: trace

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

代码语言:java复制
  for (String beanDefinitionName : applicationContext.getBeanDefinitionNames()) {
            if(beanDefinitionName.toLowerCase().startsWith("AsyncTestService".toLowerCase())){
                System.err.println(beanDefinitionName   "="   applicationContext.getBean(beanDefinitionName).getClass());
            }
        }

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

代码语言:java复制
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)

发现确实没打印出相关requestMapping映射信息,这可以说明一点就是小李那个接口没有绑定到springmvc映射,也就是出现404的原因。接着观察控制台打印的bean,内容形如下

代码语言:java复制
asyncTestServiceImpl=class com.sun.proxy.$Proxy127

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

代码语言:java复制
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)
代码语言:java复制
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注解了,接着小林为了验证这个想法,他把原来实现的接口类去掉,形如下

代码语言:java复制
@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.....");
        }

    }

启动后,查看控制台

代码语言:java复制
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的类型如下

代码语言:java复制
asyncTestServiceImpl=class com.demo.feign.controller.AsyncTestServiceImpl$$EnhancerBySpringCGLIB$$a285a21c

访问接口,打印内容如下

代码语言:java复制
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做了如下改造

代码语言:java复制
@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.....");
        }

    }

访问接口,打印内容如下

代码语言:java复制
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中抽离出去,在新类中进行处理,示例如下

代码语言:java复制
@Service
public class AysncService {

    @Async
    public void doAsynBiz(){
        System.out.println(Thread.currentThread().getName()   "-----doAsynBiz.....");
    }
}
代码语言:java复制
@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";
    }
}

访问接口,打印内容

代码语言:java复制
http-nio-8080-exec-1-----testAsync start....
http-nio-8080-exec-1-----testAsync end....
task-1-----doAsynBiz.....

说明异步生效

排查结果分析

1、接口404

从mvc日志

代码语言:java复制
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的映射处理是在

代码语言:java复制
	protected void initHandlerMethods() {
		for (String beanName : getCandidateBeanNames()) {
			if (!beanName.startsWith(SCOPED_TARGET_NAME_PREFIX)) {
				processCandidateBean(beanName);
			}
		}
		handlerMethodsInitialized(getHandlerMethods());
	}

进行处理,具体是通过processCandidateBean进行处理

代码语言:java复制
	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进行处理

代码语言:java复制
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的前提是

代码语言:java复制
beanType != null && isHandler(beanType)
代码语言:java复制
	@Override
	protected boolean isHandler(Class<?> beanType) {
		return (AnnotatedElementUtils.hasAnnotation(beanType, Controller.class) ||
				AnnotatedElementUtils.hasAnnotation(beanType, RequestMapping.class));
	}

即只有加了@Controller或者@RequestMapping的类会进行处理,而@RestController为啥也处理,点击

@RestController发现

代码语言:java复制
@Target(ElementType.TYPE)
@Retention(RetentionPolicy.RUNTIME)
@Documented
@Controller
@ResponseBody
public @interface RestController {

他本质就是@Controller。但我们通过反射查找注解,正常只会查找一层,比如

代码语言:java复制
 AsynTestController.class.getAnnotation(RestController.class)

他找到@RestController这一层,而不会找继续再找@RestController里面的@Controller,而AnnotatedElementUtils.hasAnnotation,这个注解方法就不一样,他是可以找到合并注解,即使是使用

@RestController,他还会继续找到里面的@Controller。因此这个方法对于找复合型注解很有用

当我们使用jdk动态代理时,因为父类上没加@Controller或者@RequestMapping,因此他不会被mvc进行映射处理,导致404。而使用cglib时,因为他是作为子类继承了目标类,因此他会继承目标类上的注解,因此当为cglib代理时,他会正常被mvc进行映射处理

2、为何controller里面加了@Asyn异步就失效了

这是因为加了@Async后,controller变成代理了,而当要异步处理方法,用this时,他使用的是目标对象,而非代理对象。这跟现在面试事务为啥事务失效的八股文基本是一个套路

总结

本文主要讲@Async导致controller 404,同时也使@Async失效的原因。解决的推荐方法就是将@Async抽离出controller,新建一个service类进行处理。

0 人点赞