2

We have a spring boot 2.0.2 application that serves a few things and also some static content from a webjar using the webjar locator core dependency.

This works most of the time, but in approx. 0.5-0.8% of the calls to the same URL I just get an error 500.

I tried pinpointing the problem, but there is no error message at all, just the 500 status in the apache log. When setting the logger of the ResourceHttpRequestHandler to TRACE, I see that it was able to determine the content type of the file and the next I see the access log line.

Has anyone an idea what might be wrong or how I can get more logs that let me find the reason for that?

Here are the only logs I see for these broken calls:

Accesslog looks like this:

10.XXX.XX.XX - - [11/Jun/2018:16:02:50 +0200] "GET /YYY/styles.0cce9718deac950ad0c6.bundle.css HTTP/1.1" 500 198411 "" "" "-:-" correlation_id=Wx6BCgq6AT8AACzd0l8AAAAj duration=159ms

Regular log for that call:

2018-06-11T16:02:50.778+0200;YYY;2732;1.4;https-jsse-nio2-10.XXX.XX.XX-8443-exec-8:32;2018061;Wx6BCgq6AT8AACzd0l8AAAAj;20c40980-6d80-11e8-8dca-02000ab22d32;TRACE;ResourceHttpRequestHandler;Determined media type 'text/css' for class path resource [META-INF/resources/webjars/frontend/0.0.0/styles.0cce9718deac950ad0c6.bundle.css]

The project is a pretty plain spring boot project using embedded tomcat.

[EDIT] I also set the org.apache.tomcat to DEBUG and this doesn't shed some light either. I do see a few exceptions now, but these only complain about close socket and this shouldn't be the problem, because the response has already been sent.

java.lang.Exception: null
    at org.apache.tomcat.util.net.Nio2Endpoint.closeSocket(Nio2Endpoint.java:344)
...
Patrick Cornelissen
  • 7,968
  • 6
  • 48
  • 70

2 Answers2

0

It looks like the reason is HTTP Statuscode 500 in Tomcat AccesLog on ClientAbortException / BrokenPipe

I set the whole application to trace and finally could see the exception:

2018-06-12T09:12:47.409+0200;KTO;21116;1.4;https-jsse-nio2-10.XXX.XX.XX-8443-exec-10:34;2018061;Wx9ybgq6AT8AADruMgAAAAAw;0236d480-6e10-11e8-8085-02000ab22d32;DEBUG;DispatcherServlet;Could not complete request
java.io.IOException: Broken pipe
    at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
    at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
    at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
    at sun.nio.ch.IOUtil.write(IOUtil.java:65)
    at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:691)
    at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:382)
    at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:387)
    at org.apache.tomcat.util.net.SecureNio2Channel$FutureWrite.wrap(SecureNio2Channel.java:816)
    at org.apache.tomcat.util.net.SecureNio2Channel$FutureWrite.<init>(SecureNio2Channel.java:755)
    at org.apache.tomcat.util.net.SecureNio2Channel$FutureWrite.<init>(SecureNio2Channel.java:744)
    at org.apache.tomcat.util.net.SecureNio2Channel.write(SecureNio2Channel.java:831)
    at org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper.doWrite(Nio2Endpoint.java:1258)
    at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670)
    at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:450)
    at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:388)
    at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:623)
    at org.apache.coyote.http11.filters.IdentityOutputFilter.doWrite(IdentityOutputFilter.java:116)
    at org.apache.coyote.http11.Http11OutputBuffer.doWrite(Http11OutputBuffer.java:225)
    at org.apache.coyote.Response.doWrite(Response.java:541)
    at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:351)
    ... 110 common frames omitted
Wrapped by: 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:825)
    at org.apache.catalina.connector.OutputBuffer.append(OutputBuffer.java:730)
    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 org.springframework.util.StreamUtils.copy(StreamUtils.java:140)
    at org.springframework.http.converter.ResourceHttpMessageConverter.writeContent(ResourceHttpMessageConverter.java:132)
    at org.springframework.http.converter.ResourceHttpMessageConverter.writeInternal(ResourceHttpMessageConverter.java:124)
    at org.springframework.http.converter.ResourceHttpMessageConverter.writeInternal(ResourceHttpMessageConverter.java:45)
    at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:224)
    at org.springframework.web.servlet.resource.ResourceHttpRequestHandler.handleRequest(ResourceHttpRequestHandler.java:487)
    at org.springframework.web.servlet.mvc.HttpRequestHandlerAdapter.handle(HttpRequestHandlerAdapter.java:53)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:866)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851)
    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.servlet.resource.ResourceUrlEncodingFilter.doFilter(ResourceUrlEncodingFilter.java:60)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at XX.XXXX.XXXX.logging.MdcLoggingFilter.doFilter(MdcLoggingFilter.java:27)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:158)
    at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:126)
    at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:111)
    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 XX.XXXXX.XXXX.logging.filter.ServletLoggingFilter.doFilter(ServletLoggingFilter.java:71)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:84)
    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 XX.XXXXXX.XXXXXX.authorization.security.SpringSecurityFilter.doFilter(SpringSecurityFilter.java:44)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at XX.XXXXXXXX.XXX.securityprovider.filter.TicketServletFilter.doFilter(TicketServletFilter.java:140)
    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:109)
    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:200)
    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:198)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496)
    at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
    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:790)
    at org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRun(Nio2Endpoint.java:1703)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at org.apache.tomcat.util.net.AbstractEndpoint.processSocket(AbstractEndpoint.java:1050)
    at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeWriteCompletionHandler.completed(SecureNio2Channel.java:116)
    at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeWriteCompletionHandler.completed(SecureNio2Channel.java:109)
    at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
    at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
    at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:736)
    at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:382)
    at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:399)
    at java.nio.channels.AsynchronousSocketChannel.write(AsynchronousSocketChannel.java:577)
    at org.apache.tomcat.util.net.SecureNio2Channel.handshakeInternal(SecureNio2Channel.java:280)
    at org.apache.tomcat.util.net.SecureNio2Channel.handshake(SecureNio2Channel.java:205)
    at org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRun(Nio2Endpoint.java:1681)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at org.apache.tomcat.util.net.AbstractEndpoint.processSocket(AbstractEndpoint.java:1050)
    at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeWriteCompletionHandler.completed(SecureNio2Channel.java:116)
    at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeWriteCompletionHandler.completed(SecureNio2Channel.java:109)
    at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
    at sun.nio.ch.Invoker.invokeDirect(Invoker.java:157)
    at sun.nio.ch.UnixAsynchronousSocketChannelImpl.implWrite(UnixAsynchronousSocketChannelImpl.java:736)
    at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:382)
    at sun.nio.ch.AsynchronousSocketChannelImpl.write(AsynchronousSocketChannelImpl.java:399)
    at java.nio.channels.AsynchronousSocketChannel.write(AsynchronousSocketChannel.java:577)
    at org.apache.tomcat.util.net.SecureNio2Channel.handshakeInternal(SecureNio2Channel.java:280)
    at org.apache.tomcat.util.net.SecureNio2Channel.handshake(SecureNio2Channel.java:205)
    at org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRun(Nio2Endpoint.java:1681)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at org.apache.tomcat.util.net.AbstractEndpoint.processSocket(AbstractEndpoint.java:1050)
    at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeReadCompletionHandler.completed(SecureNio2Channel.java:99)
    at org.apache.tomcat.util.net.SecureNio2Channel$HandshakeReadCompletionHandler.completed(SecureNio2Channel.java:92)
    at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)
    at sun.nio.ch.Invoker$2.run(Invoker.java:218)
    at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
Patrick Cornelissen
  • 7,968
  • 6
  • 48
  • 70
0

Cause: This exception can mean that the connection to the client browser is aborted before the response is fully transfer. It is a harmless warning as it can be due to transient network problems or the browser aborts/refreshes the page before it loaded.

A list of other causes are:

The user closed the browser before the page loaded. Their internet connection failed during loading. They went to another page before the page loaded. The browser timed the connection out before the page loaded (would have to be a large page).

Solution: This can be ignored, unless there are other issues that are currently occurring. For example, if the JIRA application server is throwing a lot of these, it might be a sign of a performance problem. See ClientAbortException because of closing a page before it finished loading for further information.

0gam
  • 1,343
  • 1
  • 9
  • 21
  • You are right, the problem is that other people monitor the access log files and complain about the error status in the log and there is no way to easily filter them out, because they look like real errors :-( – Patrick Cornelissen Jun 14 '18 at 13:57
  • Yes, i agree your comment. In fact, we can to increase server side timeout. :) – 0gam Jun 15 '18 at 00:58