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

最新推荐文章于 2025-04-21 22:48:22 发布

帅帅兔子

最新推荐文章于 2025-04-21 22:48:22 发布

阅读量8.7k

点赞数 7

分类专栏： java 文章标签： Java debug

本文链接：https://blog.youkuaiyun.com/sqlxx/article/details/121429478

版权

java 专栏收录该内容

11 篇文章

订阅专栏

我们有一个系统，自上线以来，总隔三差五有用户反馈偶尔会有请求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: null
        at 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中。

通过这次得到两个经验