8

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

 2 years ago
source link: https://my.oschina.net/u/4061399/blog/5395044
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

5a76cbc3-325a-40f8-be2d-a3c03181bb31.gif

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

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

  • 常见原因筛查

  • 根因与源码分析

  • 一些小TIPS

1、问题表现

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

Required String parameter 'seriesbaid' is not present

对应controller的api为

b43e3cb4-a74f-42e4-8dc5-7bec38f748a3.png

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

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

2、常见原因筛查

2.1 网关参数丢失?

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

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

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

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

会是这个问题吗?

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

293cef8c-6db8-40e1-94d0-95e41feb3337.png

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

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类。

a3d64d31-b708-4190-bc4f-3efc8912ba26.png

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

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

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

e8cb5919-4867-4013-bdee-2e71591ae363.png

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

3、根因与源码分析

3.1 _queryParamter为什么不是null了?

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

544343e2-3626-4c57-adcf-7e1bed16b676.png

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

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

10cce53c-53bf-47ba-b590-6e1cdebb3e47.png

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

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

49210ed3-4d54-4748-8047-14709f28dfe8.png

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

19877f35-48c2-4c16-8f73-75073faf22d7.png

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来处理任务。

17aff428-55f9-4361-89df-2e88e6b9cc9f.png

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

9771c017-a5d3-4feb-a76a-b1a199fc30df.png

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

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

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

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

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

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

jetty 9.x整体架构图:

89b117bb-7613-45a2-83f7-5188bf6a20c8.png

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。

14b4789e-9a38-40d1-b81b-1016747412ee.png

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

b4c8fa5e-f94f-473c-9281-064e05134f34.png

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

5.2 「偶发问题」难以复现

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

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

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

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

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

往期热门笔记合集推荐:

原创:阿丸笔记(微信公众号:aone_note),欢迎 分享,转载请保留出处。

扫描下方二维码可以关注我哦~

acd8a73c-d0b0-4f32-ac27-8d58378137df.jpg

                                                                              觉得不错,就点个  再看 吧👇

如果有任何疑问或者建议,欢迎 写留言 或者 微信 和我联系哦~

本文分享自微信公众号 - 阿丸笔记(aone_note)。
如有侵权,请联系 [email protected] 删除。
本文参与“OSC源创计划”,欢迎正在阅读的你也加入,一起分享。


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK