记一次异步处理导致Jetty Request对象泄漏

最近排查一个bug,发现了一系列有意思的东西,对「自定义线程池」、「Jetty线程模型」都有了一些新的认识。 

本文预计阅读时间10分钟,包括:

  • 问题表现
  • 常见原因筛查
  • 根因与源码分析
  • 最佳实践
  • 一些小TIPS

1.问题表现

预发环境偶发请求失败异常,服务端显示错误信息为:

Required String parameter 'seriesbaid' is not present

对应controller的api为

@PostMapping
public Object getUserParameter(
           HttpServletRequest request,
           HttpServletResponse response,
           @RequestParam(value = "seriesbaid") String seriesbaid){
}

乍一看,是一个非常简单的异常,请求参数里面没有带seriesbaid,导致失败。

但是,经过确认,前端请求参数已经携带了seriesbaid,而且为“偶发失败”,并不是常见的参数传递问题。

2.常见原因筛查

2.1 网关参数丢失??

由于前端请求到达后端服务中会经过网关,所以一开始怀疑是否网关丢失了传递参数。

经过 调用链分析,在偶发的失败的请求中,也确认已经传递了querystring。所以网关没有丢失参数传递。

2.2 特殊字符导致参数转换失败 ??

既然已经传递了querystring到后端服务,那么一种常见的原因,由于queryString中带有特殊字符而导致解析成queryParam失败了。

会是这个问题吗?

我们通过在服务中继承一个spring-web的OncePerRequestFilter,对请求参数进行打印

@Override
protected void doFilterInternal(
            HttpServletRequest request,
            HttpServletResponse response,
            FilterChain filterChain)
            throws ServletException, IOException {
        if ("/api/swanparameter".equals(request.getServletPath())) {
            LOG.message("shouldLog - swanparameter")
                    .with("traceId", HunterUtils.getTraceId())
                    .with("query", request.getQueryString())
                    .with("parameterMap", JsonUtil.toJsonString(request.getParameterMap()))
                    .info();
        }
}

在偶发的失败的请求中,找到了以下日志

2021-12-29 15:36:05,536 INFO [com.xxx.interceptor.RequestLoggingFilter] - shouldLog - swanparameter:traceId:fb2266d3687911ecb5f3cf045ea19ac3; query:seriesbaid=3FO4K4SLX2IW&x_plugin=custom&x_bz=&locale=zh_CN&x_resourceId=&x_resourceVersion=; parameterMap:{};

比较遗憾,我们确认了请求中确实有querystring而没有成功解析为queryParam,但是这个querystring中,并没有期望的特殊字符,讲道理是可以解析成功的。

既然常见原因无法解释,只能去源码捞一把了。

2.3 去源码捞一把

我们的网络容器使用了jetty,所以HttpServletRequest的实现是jetty的Request类。

记一次异步处理导致Jetty Request对象泄漏

 

Request类中,对queryString的解析是在 getParameters() 的时候。

我们发现,当异常请求进来的时候,这里的判断
_queryParameter竟然不是null,而是一个空对象。

而正常请求,这里判断_queryParameter为null,然后进行解析。

记一次异步处理导致Jetty Request对象泄漏

 

所以,还是要从源码去分析了。

3. 根因与源码分析

3.1_queryParamter为什么不是null了?

我们通过在Request类中设置多个断点,找到了原因。整理过程如下图所示。

记一次异步处理导致Jetty Request对象泄漏

 


1)同步请求A快速完成返回。

当请求A进来,在一次Http请求结束后(controller方法返回客户端),会进行相应的recycle()操作,这里包括Requst对象执行recycle()方法,清理相关参数,包括_queryParameters。

记一次异步处理导致Jetty Request对象泄漏

 

2)异步任务延迟响应,在recycle()后重新设置了_queryParameter属性。

在请求A执行过程中,使用「自定义线程池」异步执行了一个方法B(方法较慢)。方法B中,从RequestContextHolder中获取了HttpServletRequest,然后通过request.getParameter()获取请求头。

记一次异步处理导致Jetty Request对象泄漏

 

因为此时_queryParameters为null,因此extractQueryParameters()方法就解析了一个空的对象放进去。

记一次异步处理导致Jetty Request对象泄漏

 

3)新请求C进入,返回异常。

当新的请求C进入后端服务,拿到了同一个Request对象,由于此时_queryParameters不为null,因此跳过了extractQueryParameters(),导致应该解析的queryString无法被解析,controller抛出异常。

总结:一旦主线程执行完毕,完成recycle过程,而异步线程执行较慢,异步线程中的任何request.getParameter()行为会破坏Request对象的recycle,导致_queryParameters属性为空对象而不是null,从而导致新的请求失败。

3.2 异步线程中,RequestContextHolder还能拿到Request对象?(根本原因)

我们知道RequestContextHolder是基于ThreadLocal实现的。因此,在异步线程中,是无法直接通过
RequestContextHolder.getRequestAttributes()获取主线程的HttpServletRequest。
问题出在了「自定义线程池」
ThreadPoolExecutorWithMonitor中。

里面自定义实现了一个内部类DecorateRunnableTask来处理任务。

记一次异步处理导致Jetty Request对象泄漏

 

内部类DecorateRunnableTask继承了内部类DecorateTask,保存了主线程的RequestAttributes对象。

记一次异步处理导致Jetty Request对象泄漏

 

然后在异步线程执行前,通过before()方法设置到了当前线程的RequestContextHolder中。

总结:给异步线程传递RequestAttributes对象,是造成Request对象泄漏的根本原因!

3.3 两个请求,为什么会共享一个Request对象?

本来上面的分析基本已经找到了Bug的原因,但是我仔细想了下,又觉得有点奇怪。

两个请求,为什么会共享一个Request对象?

如果是使用了相关池化技术,那怎么能在两个请求找到同一个对象,然后稳定复现呢?因此,又继续去研究了下jetty的相关内容。

jetty 9.x整体架构图:

记一次异步处理导致Jetty Request对象泄漏

 

SelectorManager + ManagedSelector +QueuedThreadPool 组成了「Reactor线程模型」。对于一个http请求,SelectorManager分配给某一个ManagedSelector创建HttpConnection对象,然后在QueuedThreadPool中执行相应的IO操作。

HttpConnection对象持有HttpChannel对象,HttpChannel中持有了Request对象(就是HttpServletRequest)。

网关到后端服务之间使用的是Http请求,默认为长连接,因此,在短时间内的新的请求(长连接结束前),会复用同一个HttpConnection对象。

4.最佳实践

1)不要给异步线程传递RequestAttributes对象并进行保存
2)如果需要相关请求参数,可以新建上下文对象存储参数后进行传递。或者使用TransmittableThreadLocal。

5.一些小TIPS

5.1 jetty源码不匹配

在对jetty的Request类进行debug时,一开始这里遇到一个小坑,

idea一直源码匹配不上。从github上把 jetty源码拉下来,按照引入的jetty版本进行本地mvn install,还是不一致。

根据pom的依赖分析,可以看到引入的jetty版本为9.4.12。

记一次异步处理导致Jetty Request对象泄漏

 

后来突然想起来,这个项目虽然是springboot项目,但是并不是打成jar包通过内置jetty容器启动的。而是打成了war包,本地通过jetty-maven-plugin的jetty:run启动的。这里使用的jetty版本为9.4.9。

记一次异步处理导致Jetty Request对象泄漏

 

所以,我们需要按照jetty-maven-plugin的版本来选择jetty的源码。

5.2「偶发问题」难以复现

考虑到篇幅原因与阅读体验,本文在排查过程中,没有展开说明一个非常困难的地方————本地如何稳定复现「偶发问题」异常请求。

真实排查过程中,本地稳定复现耗费了大量时间。如果不是本地可以稳定复现,后面的debug也无从谈起。

后面主要根据代码的近期变更情况,发现了一个异步请求的引入,将异步改为同步后,发现就不会再出现这个问题了。

所以才从异步请求出发,多次尝试后,进行了稳定复现。

所以本次排查的一个重要收获,就是对于一些故障的排查,可以考虑从近期的「各种变更」中去寻找线索。

 

都看到最后了,原创不易,点个关注,点个赞吧~
文章持续更新,可以微信搜索「阿丸笔记 」第一时间阅读,回复【笔记】获取Canal、MySQL、HBase、JAVA实战笔记,回复【资料】获取一线大厂面试资料。
知识碎片重新梳理,构建Java知识图谱:github.com/saigu/JavaK…(历史文章查阅非常方便)
上一篇:Mybatis的CRUD操作【包含查询记录总条数、模糊查找】(完整代码演示)


下一篇:基于springboot、vue、mybatis-plus、mysql、element实现的前后端分离的CRUD功能