文章目录今天排查一个线上问题，然后查看了error日志，发现了一系列java.io.IOException: Broken pipe异常，然后咨询了接口的调用方，发现网络请求连接超时时间为3秒，这时候由于server端建立的网络连接并没有完整的写完毕，而client端就直接关闭了http connection，就会出现此异常。
- 场景
- OutputBuffer#realWriteBytes
- 分析
- 结论
[http-nio-5000-exec-5] ERROR 2021-12-07 08:08:51.973 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe Caused by: java.io.IOException: Broken pipe [http-nio-5000-exec-3] ERROR 2021-12-07 08:08:58.863 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe Caused by: java.io.IOException: Broken pipe [http-nio-5000-exec-1] ERROR 2021-12-07 08:09:06.815 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe Caused by: java.io.IOException: Broken pipe [http-nio-5000-exec-4] ERROR 2021-12-07 08:09:10.952 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe Caused by: java.io.IOException: Broken pipe [http-nio-5000-exec-2] ERROR 2021-12-07 08:13:52.377 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe Caused by: java.io.IOException: Broken pipe [http-nio-5000-exec-6] ERROR 2021-12-07 08:13:59.701 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe Caused by: java.io.IOException: Broken pipe [http-nio-5000-exec-5] ERROR 2021-12-07 08:14:08.216 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe Caused by: java.io.IOException: Broken pipe [http-nio-5000-exec-3] ERROR 2021-12-07 08:14:11.823 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe Caused by: java.io.IOException: Broken pipe [http-nio-5000-exec-9] ERROR 2021-12-07 08:40:17.476 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe Caused by: java.io.IOException: Broken pipe
完整的堆栈日志如下：
[http-nio-5000-exec-5] ERROR 2021-12-07 08:08:51.973 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:356) at org.apache.catalina.connector.OutputBuffer.flushByteBuffer(OutputBuffer.java:815) at org.apache.catalina.connector.OutputBuffer.append(OutputBuffer.java:720) at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:391) at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:369) at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:96) at com.fasterxml.jackson.core.json.UTF8JsonGenerator._flushBuffer(UTF8JsonGenerator.java:2136) at com.fasterxml.jackson.core.json.UTF8JsonGenerator._writeStringSegments(UTF8JsonGenerator.java:1279) at com.fasterxml.jackson.core.json.UTF8JsonGenerator.writeString(UTF8JsonGenerator.java:502) at com.fasterxml.jackson.databind.ser.std.StringSerializer.serialize(StringSerializer.java:41) at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:727) at com.fasterxml.jackson.databind.ser.std.BeanSerializerbase.serializeFields(BeanSerializerbase.java:721) at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:166) at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider._serialize(DefaultSerializerProvider.java:480) at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializevalue(DefaultSerializerProvider.java:319) at com.fasterxml.jackson.databind.ObjectWriter$Prefetch.serialize(ObjectWriter.java:1433) at com.fasterxml.jackson.databind.ObjectWriter.writevalue(ObjectWriter.java:921) at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.writeInternal(AbstractJackson2HttpMessageConverter.java:286) at org.springframework.http.converter.AbstractGenericHttpMessageConverter.write(AbstractGenericHttpMessageConverter.java:106) at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:231) at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.handleReturnValue(RequestResponseBodyMethodProcessor.java:174) at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:81) at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:113) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901) at org.springframework.web.servlet.frameworkServlet.processRequest(frameworkServlet.java:970) at org.springframework.web.servlet.frameworkServlet.doPost(frameworkServlet.java:872) at javax.servlet.http.HttpServlet.service(HttpServlet.java:661) at org.springframework.web.servlet.frameworkServlet.service(frameworkServlet.java:846) at javax.servlet.http.HttpServlet.service(HttpServlet.java:742) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) at org.apache.catalina.authenticator.Authenticatorbase.invoke(Authenticatorbase.java:478) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) at org.apache.catalina.core.StandardEnginevalve.invoke(StandardEnginevalve.java:87) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1459) at org.apache.tomcat.util.net.SocketProcessorbase.run(SocketProcessorbase.java:49) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:748)OutputBuffer#realWriteBytes
从上述堆栈代码行数可以看出异常发生在OutputBuffer#realWriteBytes这个方法中
public void realWriteBytes(ByteBuffer buf) throws IOException {
if (closed) {
return;
}
if (coyoteResponse == null) {
return;
}
// If we really have something to write
if (buf.remaining() > 0) {
// real write to the adapter
try {
coyoteResponse.doWrite(buf);
} catch (IOException e) {
// An IOException on a write is almost always due to
// the remote client aborting the request. Wrap this
// so that it can be handled better by the error dispatcher.
throw new ClientAbortException(e);
}
}
}
如上图代码，调用coyoteResponse.doWrite(buf);方法时，会抛出ClientAbortException异常
org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe
我们仔细阅读以下上述注释：
分析An IOException on a write is almost always due to the remote client aborting the request. Wrap this so that it can be handled better by the error dispatcher.
写操作上的IOException几乎总是由于远程客户端中止了请求。对其进行包装，以便错误分派器能够更好地处理它。
我们通过StopWatch，来对接口进行计时统计，日志如下
00041 001% 步骤1:JSON数据解析转换 03625 099% 步骤2:特征解析提取处理 // 超时3秒 00071 002% 步骤1:JSON数据解析转换 03263 098% 步骤2:特征解析提取处理 // 超时3秒 00021 002% 步骤1:JSON数据解析转换 01221 098% 步骤2:特征解析提取处理 00006 001% 步骤1:JSON数据解析转换 00720 099% 步骤2:特征解析提取处理 00030 001% 步骤1:JSON数据解析转换 03435 099% 步骤2:特征解析提取处理 // 超时3秒 00029 001% 步骤1:JSON数据解析转换 03501 099% 步骤2:特征解析提取处理 // 超时3秒 00032 001% 步骤1:JSON数据解析转换 04706 099% 步骤2:特征解析提取处理 // 超时3秒 00041 001% 步骤1:JSON数据解析转换 04068 099% 步骤2:特征解析提取处理 // 超时3秒 00014 003% 步骤1:JSON数据解析转换 00500 097% 步骤2:特征解析提取处理 00010 001% 步骤1:JSON数据解析转换 00683 099% 步骤2:特征解析提取处理 00008 001% 步骤1:JSON数据解析转换 00547 099% 步骤2:特征解析提取处理 00022 004% 步骤1:JSON数据解析转换 00535 096% 步骤2:特征解析提取处理 00018 002% 步骤1:JSON数据解析转换 01055 098% 步骤2:特征解析提取处理
完整的日志
[http-nio-5000-exec-5] INFO 2021-12-07 08:08:51.933 c.c.i.c.f.SimpleForestInterceptor[38] - [SimpleForestInterceptor|onSuccess],method=resolve,duration=3576ms,url=http://127.0.0.1:8080/feature [http-nio-5000-exec-5] INFO 2021-12-07 08:08:51.933 c.c.i.f.PbocFacade[63] - StopWatch 'PBOC特征解析提取': running time (millis) = 3730 ----------------------------------------- ms % Task name ----------------------------------------- 00068 002% 步骤1:JSON数据解析转换 03662 098% 步骤2:特征解析提取处理 [http-nio-5000-exec-5] INFO 2021-12-07 08:08:51.968 c.c.i.c.PbocController[102] - StopWatch '征信特征解析提取安全计算：【数据解密==>数据转换==>特征提取==>数据加密】': running time (millis) = 3797 ----------------------------------------- ms % Task name ----------------------------------------- 03797 100% securityComputing [http-nio-5000-exec-5] ERROR 2021-12-07 08:08:51.973 c.c.i.e.GlobalExceptionHandler[32] - java.io.IOException: Broken pipe org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:356) at org.apache.catalina.connector.OutputBuffer.flushByteBuffer(OutputBuffer.java:815) at org.apache.catalina.connector.OutputBuffer.append(OutputBuffer.java:720) at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:391) at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:369) at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:96) at com.fasterxml.jackson.core.json.UTF8JsonGenerator._flushBuffer(UTF8JsonGenerator.java:2136) at com.fasterxml.jackson.core.json.UTF8JsonGenerator._writeStringSegments(UTF8JsonGenerator.java:1279) at com.fasterxml.jackson.core.json.UTF8JsonGenerator.writeString(UTF8JsonGenerator.java:502) at com.fasterxml.jackson.databind.ser.std.StringSerializer.serialize(StringSerializer.java:41) at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:727) at com.fasterxml.jackson.databind.ser.std.BeanSerializerbase.serializeFields(BeanSerializerbase.java:721) at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:166) at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider._serialize(DefaultSerializerProvider.java:480) at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializevalue(DefaultSerializerProvider.java:319) at com.fasterxml.jackson.databind.ObjectWriter$Prefetch.serialize(ObjectWriter.java:1433) at com.fasterxml.jackson.databind.ObjectWriter.writevalue(ObjectWriter.java:921) at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.writeInternal(AbstractJackson2HttpMessageConverter.java:286)
从上述，如果task securityComputing 统计耗时超过3秒，就会紧接着出现 broken pipe 异常，这说明server端正在响应写buffer时，客户端突然关闭连接就会出现如上异常。
结论如上图：
调用方通过restTemplate封装的http连接池，这时候连接设置connectTimeout=3000,readTimeout=3000，然后网络请求http请求+端口调用到服务方，然后调用一个api（uri），这时候响应的时候，然后Spring框架对响应进行JSON序列化，然后写入Socket，这时候调用方（客户端）突然Socket端中断连接，而Server端正在进行输出流写，导致如上异常问题。
然后针对当前业务场景，看了今天300个请求，有不到10个出现这种问题，超时大多3、4秒样子，我们通知调用方增大连接池的超时时间，就不再出现这个问题。
