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

[spring-projects-issues]

Aaron Lane opened SPR-16528 and commented

Original report on Spring Boot: spring-projects/spring-boot#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

[spring-projects-issues]

vitalyster commented

Still see "broken pipe" errors from SSEEmitter on ERROR level in 5.0.10, associated commits doesn't change anything for these errors

[spring-projects-issues]

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-issues]

Rossen Stoyanchev commented

Please refrain from appending fresh reports to (permanently) closed tickets.