Logs fill with broken pipe when using SockJS [SPR-15802]

[spring-projects-issues]

Florian GOURMELEN opened SPR-15802 and commented

following this jira that has been closed #16064

I still have a similar issue, lots of log while sockjs is trying to perform a heartbeat task, Im using spring-boot-starter-websocket with spring boot 1.5.3.RELEASE
Here is my config

@Configuration 
@EnableWebSocketMessageBroker 
public class WebSocketConfig extends AbstractWebSocketMessageBrokerConfigurer {
 
            @Bean
            WebSocketHandler getWsHandler() {
                return new WebSocketHandler();
            }
 
            @Override
            public void configureMessageBroker(MessageBrokerRegistry config) {
                config.enableSimpleBroker("/topic");
            }
 
            @Override
            public void registerStompEndpoints(StompEndpointRegistry registry) {
                registry.addEndpoint("/ws").setAllowedOrigins("*").withSockJS();
            } 
}

And my log

2017-07-11 15:10:23.753 INFO 7574 --- [MessageBroker-4] o.apache.coyote.http11.Http11Processor : An error occurred in processing while on a non-container thread. The connection will be closed immediately 
java.io.IOException: Broken pipe at sun.nio.ch.FileDispatcherImpl.write0(Native Method) 
~[na:1.8.0] at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) 
~[na:1.8.0] at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) 
~[na:1.8.0] at sun.nio.ch.IOUtil.write(IOUtil.java:65) 
~[na:1.8.0] at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:466) 
~[na:1.8.0] at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:134) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1259) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:607) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:597) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.coyote.http11.Http11OutputBuffer.flushBuffer(Http11OutputBuffer.java:581) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:272) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1506) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:279) 
~[tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.coyote.Response.action(Response.java:172) 
 [tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:317) 
 [tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:284) 
 [tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.catalina.connector.Response.flushBuffer(Response.java:541) 
 [tomcat-embed-core-8.5.14.jar:8.5.14] at org.apache.catalina.connector.ResponseFacade.flushBuffer(ResponseFacade.java:312) 
 [tomcat-embed-core-8.5.14.jar:8.5.14] at javax.servlet.ServletResponseWrapper.flushBuffer(ServletResponseWrapper.java:176) 
 [tomcat-embed-core-8.5.14.jar:8.5.14] at javax.servlet.ServletResponseWrapper.flushBuffer(ServletResponseWrapper.java:176) 
 [tomcat-embed-core-8.5.14.jar:8.5.14] at org.springframework.security.web.util.OnCommittedResponseWrapper.flushBuffer(OnCommittedResponseWrapper.java:159) 
 [spring-security-web-4.2.2.RELEASE.jar:4.2.2.RELEASE] at org.springframework.http.server.ServletServerHttpResponse.flush(ServletServerHttpResponse.java:96) 
 [spring-web-4.3.8.RELEASE.jar:4.3.8.RELEASE] at org.springframework.web.socket.sockjs.transport.session.AbstractHttpSockJsSession.writeFrameInternal(AbstractHttpSockJsSession.java:350) 
 [spring-websocket-4.3.8.RELEASE.jar:4.3.8.RELEASE] at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.writeFrame(AbstractSockJsSession.java:322) 
 [spring-websocket-4.3.8.RELEASE.jar:4.3.8.RELEASE] at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.sendHeartbeat(AbstractSockJsSession.java:255) 
 [spring-websocket-4.3.8.RELEASE.jar:4.3.8.RELEASE] at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession$HeartbeatTask.run(AbstractSockJsSession.java:456) 
 [spring-websocket-4.3.8.RELEASE.jar:4.3.8.RELEASE] at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) 
 [spring-context-4.3.8.RELEASE.jar:4.3.8.RELEASE] at java.

---

Affects: 4.3.8

Issue Links:

• Logs fill with unnecessary stack traces when using SockJS streaming transports [SPR-11438] #16064 Logs fill with unnecessary stack traces when using SockJS streaming transports

Referenced from: commits 7e232f9, 5f07434

[spring-projects-issues]

Rossen Stoyanchev commented

In this case, a very generic IOException and maybe the message changed in Tomcat. Currently we're checking for "Broken pipe" as the complete message but it the full message here is "Broken pipe at sun.nio.ch.FileDispatcherImpl.write0". We can change to "contains" check.

[spring-projects-issues]

Rossen Stoyanchev commented

This should be resolved now in both 4.3.x and master (5.0).

[spring-projects-issues]

Florian GOURMELEN commented

The initial code was fine, the exception still was "Broken pipe" its the formatting when I copied the stacktrace that made it look otherwise in jira.
If I put a breakpoint in your class AbstractSockJsException, the exception is still written in the log somewhere in apache processor I guess.

not formatted log:

2017-07-31 18:23:17.759 INFO 70244 --- [MessageBroker-1] o.apache.coyote.http11.Http11Processor : An error occurred in processing while on a non-container thread. The connection will be closed immediately

java.io.IOException: Broken pipe
at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_121]
at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_121]
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_121]
at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_121]
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_121]
at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:134) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]

[spring-projects-issues]

Rossen Stoyanchev commented

Are you saying an exception i still logged from AbstractSockJsSession? Please provide exact, formatted logs with the complete stack trace.

[spring-projects-issues]

Florian GOURMELEN commented

Please find the complete logs here https://ufile.io/qbh4r

[spring-projects-issues]

Rossen Stoyanchev commented

Thanks for the logs.

So this is logged from Tomcat at INFO level. I don't see anything we can do. You might need to set the log level for org.apache.coyote.http11.Http11Processor:

2017-07-31 18:23:17.759  INFO 70244 --- [MessageBroker-1] o.apache.coyote.http11.Http11Processor   : An error occurred in processing while on a non-container thread. The connection will be closed immediately

java.io.IOException: Broken pipe
	at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_121]
	at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_121]
	at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_121]
	at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_121]
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_121]
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:134) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1259) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:607) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:597) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.coyote.http11.Http11OutputBuffer.flushBuffer(Http11OutputBuffer.java:581) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:272) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1506) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:279) ~[tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.coyote.Response.action(Response.java:172) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:317) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:284) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.catalina.connector.Response.flushBuffer(Response.java:541) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.apache.catalina.connector.ResponseFacade.flushBuffer(ResponseFacade.java:312) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at javax.servlet.ServletResponseWrapper.flushBuffer(ServletResponseWrapper.java:176) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at javax.servlet.ServletResponseWrapper.flushBuffer(ServletResponseWrapper.java:176) [tomcat-embed-core-8.5.14.jar!/:8.5.14]
	at org.springframework.security.web.util.OnCommittedResponseWrapper.flushBuffer(OnCommittedResponseWrapper.java:159) [spring-security-web-4.2.2.RELEASE.jar!/:4.2.2.RELEASE]
	at org.springframework.http.server.ServletServerHttpResponse.flush(ServletServerHttpResponse.java:96) [spring-web-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
	at org.springframework.web.socket.sockjs.transport.session.AbstractHttpSockJsSession.writeFrameInternal(AbstractHttpSockJsSession.java:350) [spring-websocket-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.writeFrame(AbstractSockJsSession.java:322) [spring-websocket-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.sendHeartbeat(AbstractSockJsSession.java:255) [spring-websocket-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession$HeartbeatTask.run(AbstractSockJsSession.java:456) [spring-websocket-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) [spring-context-4.3.8.RELEASE.jar!/:4.3.8.RELEASE]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_121]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_121]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0_121]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_121]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_121]

[spring-projects-issues]

Allen Y commented

Hi， 

Is this issue fixed?  I am using sprint boot 1.4.0 with spring 4.3.2 and still have same issue 

[spring-projects-issues]

Rossen Stoyanchev commented

See the "Fix Version(s)" field above: 4.3.11 and 5.0 RC4. So you need 4.3.11 at least, but it should actually be the latest maintenance version, always, (currently that's 4.3.19) for security reasons.

[DFYPY]

i am using springboot 2.6.6. spring-websocket version is 5.3.18 and still got this log.
my log:
11:47:46.826 [MessageBroker-3] TRACE org.springframework.web.socket.sockjs.transport.handler.XhrStreamingTransportHandler$XhrStreamingSockJsSession - Writing to HTTP response: h

11:47:46.826 [MessageBroker-3] TRACE org.springframework.web.socket.sockjs.DisconnectedClient - Looks like the client has gone away
org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe
at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:310)
at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:273)
at org.apache.catalina.connector.Response.flushBuffer(Response.java:500)
at org.apache.catalina.connector.ResponseFacade.flushBuffer(ResponseFacade.java:312)
at javax.servlet.ServletResponseWrapper.flushBuffer(ServletResponseWrapper.java:181)
at org.springframework.http.server.ServletServerHttpResponse.flush(ServletServerHttpResponse.java:104)
at org.springframework.web.socket.sockjs.transport.session.AbstractHttpSockJsSession.writeFrameInternal(AbstractHttpSockJsSession.java:361)
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.writeFrame(AbstractSockJsSession.java:326)
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.sendHeartbeat(AbstractSockJsSession.java:259)
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession$HeartbeatTask.run(AbstractSockJsSession.java:488)
at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.io.IOException: Broken pipe
at java.base/sun.nio.ch.FileDispatcherImpl.write0(Native Method)
at java.base/sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:113)
at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:79)
at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:50)
at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:462)
at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:136)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1424)
at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:768)
at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:732)
at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:716)
at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.flush(Http11OutputBuffer.java:573)
at org.apache.coyote.http11.filters.ChunkedOutputFilter.flush(ChunkedOutputFilter.java:157)
at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:221)
at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1253)
at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:402)
at org.apache.coyote.Response.action(Response.java:209)
at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:306)
... 16 common frames omitted
11:47:46.827 [MessageBroker-3] DEBUG org.springframework.web.socket.sockjs.transport.handler.XhrStreamingTransportHandler$XhrStreamingSockJsSession - Closing SockJS session qpfongpv with CloseStatus[code=1011, reason=null]

what can i do