Spurious ERROR-level logging when using SSEEmitter [SPR-16528]

Aaron Lane opened SPR-16528 and commented

Original report on Spring Boot: https://github.com/spring-projects/spring-boot/issues/12168

Example project: https://github.com/ajlane/spring-boot-sse-example

Steps to reproduce:

Start the application and navigate to http://localhost:8080.
Wait for the client connection to time out or just refresh the page.

Expected behaviour:

Clients disconnecting and reconnecting through normal use is logged at DEBUG level or lower.

Actual behaviour:

Timeouts and Broken pipe IOExceptions are logged at ERROR level, with no clear way to isolate and suppress them.

2018-02-22 13:26:01.855 ERROR 34241 --- [nio-8080-exec-1] .w.s.m.s.DefaultHandlerExceptionResolver : Async timeout for GET [/clock]
2018-02-22 13:26:34.945 ERROR 34241 --- [nio-8080-exec-7] .w.s.m.s.DefaultHandlerExceptionResolver : Async timeout for GET [/clock]
2018-02-22 13:27:08.036 ERROR 34241 --- [nio-8080-exec-5] .w.s.m.s.DefaultHandlerExceptionResolver : Async timeout for GET [/clock]
2018-02-22 13:27:12.614 ERROR 34241 --- [nio-8080-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] threw exception

java.io.IOException: Broken pipe
    at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_66]
    at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_66]
    at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_66]
    at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_66]
    at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_66]
    at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:134) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1267) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:607) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:597) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.flush(Http11OutputBuffer.java:646) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.coyote.http11.filters.ChunkedOutputFilter.flush(ChunkedOutputFilter.java:169) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:252) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1560) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:285) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.coyote.Response.action(Response.java:173) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:317) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:284) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:118) ~[tomcat-embed-core-8.5.27.jar:8.5.27]
    at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:297) ~[na:1.8.0_66]
    at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141) ~[na:1.8.0_66]
    at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229) ~[na:1.8.0_66]
    at org.springframework.util.StreamUtils.copy(StreamUtils.java:119) ~[spring-core-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:106) ~[spring-web-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:41) ~[spring-web-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:227) ~[spring-web-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.sendInternal(ResponseBodyEmitterReturnValueHandler.java:207) ~[spring-webmvc-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.send(ResponseBodyEmitterReturnValueHandler.java:200) ~[spring-webmvc-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal(ResponseBodyEmitter.java:166) ~[spring-webmvc-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send(ResponseBodyEmitter.java:159) ~[spring-webmvc-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:126) ~[spring-webmvc-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:107) ~[spring-webmvc-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at au.id.ajlane.examples.springsse.ClockController.tick(ClockController.java:31) ~[classes/:na]
    at sun.reflect.GeneratedMethodAccessor31.invoke(Unknown Source) ~[na:na]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_66]
    at java.lang.reflect.Method.invoke(Method.java:497) ~[na:1.8.0_66]
    at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65) ~[spring-context-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-4.3.14.RELEASE.jar:4.3.14.RELEASE]
    at java.util.concurrent.Executors$RunnableAdapter.call$$$capture(Executors.java:511) ~[na:1.8.0_66]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java) ~[na:1.8.0_66]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[na:1.8.0_66]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_66]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[na:1.8.0_66]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_66]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_66]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_66]

Affects: 4.3.14

Backported to: 4.3.15

vitalyster commented

2018-10-17 10:14:31.430 ERROR 29463 --- [http-nio-8080-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] threw exception``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.SocketChannelImpl.write(SocketChannelImpl.java:471) at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:134) at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1306) at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:726) at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:679) at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:669) at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.flush(Http11OutputBuffer.java:646) at org.apache.coyote.http11.filters.ChunkedOutputFilter.flush(ChunkedOutputFilter.java:169) at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:252) at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1561) at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:380) at org.apache.coyote.Response.action(Response.java:173) at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:317) at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:284) at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:118) at org.springframework.security.web.util.OnCommittedResponseWrapper$SaveContextServletOutputStream.flush(OnCommittedResponseWrapper.java:514) at com.fasterxml.jackson.core.json.UTF8JsonGenerator.flush(UTF8JsonGenerator.java:1100) at com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:915) at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.writeInternal(AbstractJackson2HttpMessageConverter.java:285) at org.springframework.http.converter.AbstractGenericHttpMessageConverter.writeInternal(AbstractGenericHttpMessageConverter.java:111) at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:226) at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.sendInternal(ResponseBodyEmitterReturnValueHandler.java:200) at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.send(ResponseBodyEmitterReturnValueHandler.java:190) at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal(ResponseBodyEmitter.java:189) at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send(ResponseBodyEmitter.java:183) at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:133) at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:116) at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:95)

spring-projects / spring-framework

Spurious ERROR-level logging when using SSEEmitter [SPR-16528] #21071