Spurious ERROR-level logging when using SSEEmitter

[ajlane]

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]

[wilkinsona]

Thanks for the report but the error logging is done in Spring Framework code. Please open a Jira ticket if you’d like to pursue this.

[ajlane]

Raised with Spring Framework here: https://jira.spring.io/browse/SPR-16528