记一次springboot应用偶发502错误的排查过程

我们有一个系统，自上线以来，总隔三差五有用户反馈偶尔会有请求502 bad gateway的情况产生，但发生频率不高，也没发现有什么规律。经反复测试我们发现如果系统开启了图片水印功能，这个现象就比较容易重现（刷新带有图片的页面的时候）。所以我们初步怀疑这个情况和图片处理肯定是有点关系的。502的error code是nginx返回的，而且返回速度很快，看起来上游要么是直接拒绝连接了，要么是连接上了之后很快返回了。通过直接访问springboot应用尝试，发现是后一种情况，chrome里面提示net::ERR_EMPTY_RESPONE。也死马当活马医，尝试了修改tomcat的线程和连接数配置，但并没有起什么作用（实际使用连接数也远没到default值）。如果增加最小堆内存的大小，这个现象出现的会少一些，但堆内存的使用离最大值也差非常多，内存很充足。所以对这个问题没有什么头绪，只能猜测是不是和图片处理频繁gc有关，但按常理gc也不应该直接返回空，只会导致响应慢一些而已。

为了定位这个问题，我们先把tomcat和catalina的日志级别设到了TRACE级别，试图从中寻找一些规律。经过艰难的调试和重现后发现，每次出现failed的request的时候，都会伴随有这样的日志

2021-11-18 11:42:33,199 DEBUG [http-nio-8080-exec-3] org.apache.coyote.http11.Http11NioProtocol:? - Processing socket [org.apache.tomcat.util.net.NioChannel@418ea230:java.nio.channels.SocketChannel[connected local=/192.168.95.113:8080 remote=/192.168.105.93:60196]] with status [OPEN_READ]
2021-11-18 11:42:33,199 DEBUG [http-nio-8080-exec-3] org.apache.coyote.http11.Http11NioProtocol:? - Found processor [null] for socket [org.apache.tomcat.util.net.NioChannel@418ea230:java.nio.channels.SocketChannel[connected local=/192.168.95.113:8080 remote=/192.168.105.93:60196]]
2021-11-18 11:42:33,199 DEBUG [http-nio-8080-exec-3] org.apache.coyote.http11.Http11NioProtocol:? - Popped processor [org.apache.coyote.http11.Http11Processor@7aea45c9] from cache
2021-11-18 11:42:33,199 DEBUG [http-nio-8080-exec-3] org.apache.coyote.http11.Http11Processor:? - Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1678d428:org.apache.tomcat.util.net.NioChannel@418ea230:java.nio.channels.SocketChannel[connected local=/192.168.95.113:8080 remote=/192.168.105.93:60196]], Status in: [OPEN_READ], State out: [CLOSED]
2021-11-18 11:42:33,199 DEBUG [http-nio-8080-exec-3] org.apache.coyote.http11.Http11NioProtocol:? - Pushed Processor [org.apache.coyote.http11.Http11Processor@7aea45c9]
2021-11-18 11:42:33,199 DEBUG [http-nio-8080-exec-3] org.apache.tomcat.util.net.NioEndpoint:? - Calling [org.apache.tomcat.util.net.NioEndpoint@6eb17ec8].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@1678d428:org.apache.tomcat.util.net.NioChannel@418ea230:java.nio.channels.SocketChannel[connected local=/192.168.95.113:8080 remote=/192.168.105.93:60196]])
java.lang.Exception: nullat org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doClose(NioEndpoint.java:1165)at org.apache.tomcat.util.net.SocketWrapperBase.close(SocketWrapperBase.java:394)at org.apache.tomcat.util.net.NioEndpoint$Poller.cancelledKey(NioEndpoint.java:667)at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)at java.base/java.lang.Thread.run(Thread.java:829)
2021-11-18 11:42:33,199 DEBUG [http-nio-8080-exec-3] org.apache.tomcat.util.threads.LimitLatch:? - Counting down[http-nio-8080-exec-3] latch=7

经过查看tomcat源代码并和正常请求比对后发现，在tomcat的Http11Processor中，Status in: OPEN_READ的状态应该是正常的，但State Out: CLOSED是有问题的，正常情况下State Out应该是OPEN。从源代码我们可以看到，State Out是CLOSED意味着Http11Processor的service方法中出现了什么异常情况，所以调用了setErrorState。但service方法中代码比较长，有很多地方调用了setErrorState，一时半会儿也不知道是哪个分支导致的。所以我们采用了arthas的trace命令去跟踪service方法，想看下当返回State是ERROR的时候，调用路径是怎么样的

trace org.apache.coyote.http11.Http11Processor service 'returnObj.toString == "CLOSED"'2021-11-18 19:22:00 [http-nio-8080-exec-8] INFO  result -`---ts=2021-11-18 19:22:00;thread_name=http-nio-8080-exec-8;id=4f;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@1a1d6a08`---[0.028744ms] org.apache.coyote.http11.Http11Processor:service()+---[0.001952ms] org.apache.coyote.Request:getRequestProcessor() #274+---[0.001255ms] org.apache.coyote.RequestInfo:setStage() #275+---[0.003611ms] org.apache.coyote.http11.Http11Processor:setSocketWrapper() #278+---[7.81E-4ms] org.apache.coyote.http11.Http11Processor:getErrorState() #287+---[8.45E-4ms] org.apache.coyote.ErrorState:isError() #287+---[7.97E-4ms] org.apache.coyote.RequestInfo:setStage() #480+---[7.17E-4ms] org.apache.coyote.http11.Http11Processor:getErrorState() #482`---[6.07E-4ms] org.apache.coyote.ErrorState:isError() #482

从这个结果我们可以发现，在service方法最开始的（287行）第一个while循环处的isError()就已经是true了。也就是说这个processor刚进来时errorState状态就是不对的。为了确认这一点，我们使用watch查看他进来时候的errorState值

watch org.apache.coyote.http11.Http11Processor service '{params[0], target.errorState}' -b -f

证实了在进service方法的时候errorState就已经是CLOSE_CONNECTION_NOW的状态了。

这肯定不是一个合理的状态，此时我怀疑会不会是前一个请求把状态设置为失败影响了下一个请求。所以就通过日志里面processor对象的地址找前一次请求，分析他的返回参数，结果发现前一次请求返回的时候errorState是正常的。事实上通过tomcat代码也可以发现，每个processor在用完之后放回cache的时候会调用recycle方法，把errorState重置为None，正常肯定是不会影响下一个请求的。

到这个时候就有点迷茫了，为什么会在两次请求中间，在缓存中没有被别人使用的processor的errorState就发生了变化呢。一度怀疑会不会是tomcat的bug，但搜了issue list并没有什么结果。最后还是通过源代码我们发现，errorState变量改变的入口只有setErrorState方法，所以我们应该可以监控一下setErrorState的调用堆栈，看看将state设成CLOSE_CONNECTION_NOW的时候的调用栈会是怎么样的，就能知道processor的errorState是什么时候和被谁设成了CLOSE_CONNECTION_NOW

stack org.apache.coyote.AbstractProcessor setErrorState  'params[0].toString == "CLOSE_CONNECTION_NOW"'ts=2021-11-18 19:53:53;thread_name=Finalizer;id=3;is_daemon=true;priority=8;TCCL=null@org.apache.coyote.AbstractProcessor.setErrorState()at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:371)at org.apache.coyote.Response.action(Response.java:211)at org.apache.coyote.Response.sendHeaders(Response.java:437)at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:291)at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:272)at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:118)at javax.imageio.stream.MemoryCacheImageOutputStream.flushBefore(MemoryCacheImageOutputStream.java:194)at javax.imageio.stream.MemoryCacheImageOutputStream.close(MemoryCacheImageOutputStream.java:180)at javax.imageio.stream.ImageInputStreamImpl.finalize(ImageInputStreamImpl.java:884)at java.lang.System$2.invokeFinalize(System.java:2125)at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:87)at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:171)

一看这返回结果就恍然大悟了。这是ImageInputStreamImpl的finalize方法被调用的时候，会去调用response的相关方法，而此时response早已经结束了，就会导致IOException的产生，最后会导致processor的state被设置成CLOSE_CONNECTION_NOW。finalize的方法的调用时机是不确定的，这也造成了这个问题出现的随机性。

至此还有一个疑问是，为什么ImageInputStreamImpl的finalize会调用MemoryCacheImageOutputStream的close呢？查看代码发现MemoryCacheImageOutputStream实际上是继承自他的，继承链为：MemoryCacheImageOutputStream=>ImageOutputStreamImpl=>ImageInputStreamImpl。所以此处回收的其实是MemoryCacheImageOutputStream类的实例。

所以这个问题最终的解决方案有两个

不使用这些Image相关的输入输出类（实际上这些类是在javax.desktop模块里面的，从名字也可以看出来，可能并不适合在server环境使用），可以考虑使用opencv之类的工具。
在服务端处理的时候不能把response的OutputStream直接传给MemoryCacheImageOutputStream，需要先写到某个临时文件，然后再通过普通的IO copy到response中。

通过这次得到两个经验

arthas真的还是挺好用的，是debug的一个利器
finalize方法还是不要用的好，这里出现问题实在是太难debug了

记一次springboot应用偶发502错误的排查过程相关推荐

记一次.Net Core程序启动失败的排查过程
阅文时长 | 2分钟字数统计 | 3212字符主要内容 | 1.引言&背景 2.排查.NetCore启动失败详细过程 3.声明与参考资料『记一次.Net Core程序启动失败的排查过程』 ...
一次segfault错误的排查过程
原文地址::http://blog.csdn.net/zhaohaijie600/article/details/45246569 相关文章 1.LINUX 段错误查找记录 -- segfault a ...
weblogic请求服务端超时后重发一次请求_记一次后端服务偶发502的排错之旅
现象最近线上业务反馈,服务不定时的出现502报错.登陆到网关日志平台查询httpcode等于502的,还真的发现同一个服务出现的概率还是蛮高的.所以开始了502的排查之旅. 抓包吧为了复现问题,直 ...
记一次kafka集群频繁crash的排查过程
01 概述 kafka集群中的某些broker会随机重启,并且重启没有什么规律.broker重启对于client端使用层面是无感知的,但是在数据一致性.稳定性方面存在风险.broker重启时,连接在这 ...
记一次 Kubernetes 集群 Pod Eviction 问题排查过程
声明: 本博客欢迎转发,但请保留原作者信息! 新浪微博:@Lingxian_kong; 微信公众号:飞翔的尘埃; 内容系本人学习.研究和总结,如有雷同,实属荣幸! 现象:一个普通的 k8s 集群,3 ...
java gc full gc_记一次Java服务频繁Full GC的排查过程
现象从监控来看,堆内存是够用的,但是频繁触发Full GC,每秒钟三次,每次耗时三四秒. image.png 结合Young GC的信息和堆内存的使用情况,可以发现新生代的内存够用,老生代的内存不够 ...
记一次线上cpu飙升100%的排查过程
大家好,我是烤鸭: 最近没怎么写技术文章,还是得回归下初心,正好前几天出现个线上问题,记录下排查过程. 问题描述某个时间点,接收到接口响应慢报警. 过一会收到服务器cpu可用率低(<10%)报 ...
SpringBoot连接超时导致的502错误案例
1.问题描述内部系统之间通过Nginx来实现路由转发. 但最近发现有一个系统,经常报502错误,每天达到上百次,完全无法忍受. 2. 原因排查于是进行排查, 发现配置人员把连接超时时间(serve ...
20201215记一次502错误
文章目录环境: 解决路线 Step1:检查是否PHP代码错误 Step2:postman测试 Step3:尝试处理502 总结 502错误是什么查错路线更新参考文档日期:2020.12.15 ...
java 502错误,Spring Boot连接超时导致502错误的实战案例
1.问题描述内部系统之间通过Nginx来实现路由转发. 但最近发现有一个系统,经常报502错误,每天达到上百次,完全无法忍受. 2. 原因排查于是进行排查, 发现配置人员把连接超时时间(serve ...

记一次springboot应用偶发502错误的排查过程

记一次springboot应用偶发502错误的排查过程相关推荐

最新文章

热门文章