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

[spring-projects-issues]

Prashant Deva opened SPR-11438 and commented

We are using websockets on tomcat 7.0.50 with an in memory simple spring broker.
Our logs are littered with this exception

3 ERROR MessageBrokerSockJS-1 handler.XhrStreamingTransportHandler$XhrStreamingSockJsSession:276 - Terminating connection after failure to send message to client. This may be because the client has gone away (see https://java.net/jira/browse/SERVLET_SPEC-44) 
Feb 15 12:05:16 apmgui i-04e9bc6a:  ClientAbortException:  java.net.SocketException: Broken pipe 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:371) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:333) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.catalina.connector.Response.flushBuffer(Response.java:570) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.catalina.connector.ResponseFacade.flushBuffer(ResponseFacade.java:307) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.springframework.http.server.ServletServerHttpResponse.flush(ServletServerHttpResponse.java:81) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.springframework.web.socket.sockjs.transport.session.StreamingSockJsSession.writeFrameInternal(StreamingSockJsSession.java:99) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.writeFrame(AbstractSockJsSession.java:273) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.sendHeartbeat(AbstractSockJsSession.java:294) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession$1.run(AbstractSockJsSession.java:309) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.util.concurrent.FutureTask$Sync.innerRun(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.util.concurrent.FutureTask.run(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.lang.Thread.run(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:  Caused by: java.net.SocketException: Broken pipe 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.net.SocketOutputStream.socketWrite0(Native Method) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.net.SocketOutputStream.socketWrite(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at java.net.SocketOutputStream.write(Unknown Source) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.coyote.http11.InternalOutputBuffer.realWriteBytes(InternalOutputBuffer.java:215) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.tomcat.util.buf.ByteChunk.flushBuffer(ByteChunk.java:480) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.coyote.http11.InternalOutputBuffer.flush(InternalOutputBuffer.java:119) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.coyote.http11.AbstractHttp11Processor.action(AbstractHttp11Processor.java:805) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.coyote.Response.action(Response.java:174) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:366) 
Feb 15 12:05:16 apmgui i-04e9bc6a:      ... 17 more 

Either:

1. This is a bug in spring, in which case fix it
2. This is expected behavior, in which case provide a workaround/documentation for it so our logs are not littered by it.

Either way, this behavior is not documented and presence of this issue makes logs very, very heavy. Not to mention we don't know if this is an actual error in our app or one we can ignore.

Either fix this issue or provide an explanation/documentation for it.

---

Affects: 4.0.1

Reference URL: http://stackoverflow.com/questions/21802969/spring-4-websockets-causing-tons-of-exceptions

Issue Links:

• Logs fill with broken pipe when using SockJS [SPR-15802] #20357 Logs fill with broken pipe when using SockJS
• Too many exception stack traces related to disconnected SockJS clients [SPR-11870] #16489 Too many exception stack traces related to disconnected SockJS clients
• Use DEBUG log level for broken WebSocket client connections or write failures [SPR-12155] #16769 Use DEBUG log level for broken WebSocket client connections or write failures

0 votes, 7 watchers

[spring-projects-issues]

Rossen Stoyanchev commented

The exception means that the server failed to write a message to the client. So it is a serious condition to be logged at error level. However as the message states, it may also mean simply the client went away. Unfortunately the Servlet async support -- required for SockJS' HTTP transports (in this case HTTP streaming) -- does not provide a callback when a client goes away. Hence the reference to the Servlet spec issue. Do vote there so it gets fixed, even discussing it may lead to immediate fixes in Tomcat and Jetty.

This is something mentioned in the docs already by the way. See section 20.3.3. However, we can provide more guidance there and explicitly mention the impact on the logs.

We may also be able to make an improvement. We could try to recognize the condition of a client having gone away from the root cause exception type and message and log it at WARNING level. That should allow filtering out such messages while still having the option to see them all if necessary.

[spring-projects-issues]

Rossen Stoyanchev commented

This should now be resolved. For details see the commit message 42382996612825c96c745a593716f31446075a5c.

[spring-projects-issues]

Sachin Parikh commented

I still see this error in my logs. I am running Spring version 4.0.6. I see the exception being thrown at line: 354 (throw new SockJsTransportFailureException("Failed to write " + frame, this.getId(), ex);)

04-Sep-2014 10:16:35.087 SEVERE [http-nio-8443-exec-2] org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.tryCloseWithError Closing due to exception for SockJsSession[id=td_hta6t, state=CLOSED, sinceCreated=20015, sinceLastActive=0]
org.springframework.web.socket.sockjs.SockJsTransportFailureException: Failed to write SockJsFrame content='a["15"]'; nested exception is java.io.IOException: java.util.concurrent.ExecutionException: java.io.IOException: Broken pipe
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.writeFrame(AbstractSockJsSession.java:354)
at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.sendMessageInternal(WebSocketServerSockJsSession.java:213)
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.sendMessage(AbstractSockJsSession.java:252)
at org.springframework.web.socket.WebSocketSession$sendMessage.call(Unknown Source)
at com.ilmn.hadean.handler.SummaryViewHandlerImpl.handleTextMessage(SummaryViewHandlerImpl.groovy:17)
at org.springframework.web.socket.handler.AbstractWebSocketHandler.handleMessage(AbstractWebSocketHandler.java:43)
at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleMessage(WebSocketHandlerDecorator.java:75)
at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleMessage(LoggingWebSocketHandlerDecorator.java:55)
at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.handleMessage(ExceptionWebSocketHandlerDecorator.java:69)
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.delegateMessages(AbstractSockJsSession.java:213)
at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.handleMessage(WebSocketServerSockJsSession.java:195)
at org.springframework.web.socket.sockjs.transport.handler.SockJsWebSocketHandler.handleTextMessage(SockJsWebSocketHandler.java:77)
at org.springframework.web.socket.handler.AbstractWebSocketHandler.handleMessage(AbstractWebSocketHandler.java:43)
at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.handleTextMessage(StandardWebSocketHandlerAdapter.java:112)
at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.access$000(StandardWebSocketHandlerAdapter.java:42)
at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter$3.onMessage(StandardWebSocketHandlerAdapter.java:82)
at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter$3.onMessage(StandardWebSocketHandlerAdapter.java:79)
at org.apache.tomcat.websocket.WsFrameBase.sendMessageText(WsFrameBase.java:375)
at org.apache.tomcat.websocket.WsFrameBase.processDataText(WsFrameBase.java:472)
at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:275)
at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:116)
at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:55)
at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:194)
at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:194)
at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:95)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:653)
at org.apache.coyote.http11.Http11NioProtocol$Http11ConnectionHandler.process(Http11NioProtocol.java:222)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1566)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1523)
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)
Caused by: java.io.IOException: java.util.concurrent.ExecutionException: java.io.IOException: Broken pipe
at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendPartialString(WsRemoteEndpointImplBase.java:218)
at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendPartialString(WsRemoteEndpointImplBase.java:185)
at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:49)
at org.springframework.web.socket.adapter.standard.StandardWebSocketSession.sendTextMessage(StandardWebSocketSession.java:197)
at org.springframework.web.socket.adapter.AbstractWebSocketSession.sendMessage(AbstractWebSocketSession.java:104)
at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.writeFrameInternal(WebSocketServerSockJsSession.java:223)
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.writeFrame(AbstractSockJsSession.java:337)
... 32 more
Caused by: java.util.concurrent.ExecutionException: java.io.IOException: Broken pipe
at org.apache.tomcat.websocket.FutureToSendHandler.get(FutureToSendHandler.java:102)
at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendPartialString(WsRemoteEndpointImplBase.java:214)
... 38 more

[spring-projects-issues]

Rossen Stoyanchev commented

Are you able to debug it? If you look at AbstractSockJsSession in the logWriteFrameFailure it should be obvious what we are trying to do there. There is also an explanation in the javadoc. Perhaps you can help narrow down why this stack trace is getting logged in full?

[spring-projects-issues]

Sachin Parikh commented

Thanks for a quick response. Yes I am able to debug it and I see the control going to logWriteFrameFailure method. But even before it processes the method, I already have the broken pipe error log entry in the logs. Also, after the control goes through the writeFrame() method, I see the following error in the log:

04-Sep-2014 12:51:08.601 SEVERE [http-nio-8443-exec-2] org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleTransportError Transport error for SockJsSession[id=55_fssmm, state=OPEN, sinceCreated=275108, sinceLastActive=275108]
java.io.IOException: java.util.concurrent.ExecutionException: java.io.IOException: Key must be cancelled
at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.startMessageBlock(WsRemoteEndpointImplBase.java:242)
at org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:486)
at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:417)
at org.apache.tomcat.websocket.WsSession.close(WsSession.java:394)
at org.springframework.web.socket.adapter.standard.StandardWebSocketSession.closeInternal(StandardWebSocketSession.java:217)
at org.springframework.web.socket.adapter.AbstractWebSocketSession.close(AbstractWebSocketSession.java:139)
at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.disconnect(WebSocketServerSockJsSession.java:229)
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.writeFrame(AbstractSockJsSession.java:343)
at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.sendMessageInternal(WebSocketServerSockJsSession.java:213)
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.sendMessage(AbstractSockJsSession.java:252)
at org.springframework.web.socket.WebSocketSession$sendMessage.call(Unknown Source)
Finally, the following error is logged:

04-Sep-2014 12:52:18.527 SEVERE [http-nio-8443-exec-1] org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.tryCloseWithError Closing due to exception for SockJsSession[id=tdkvxjhq, state=CLOSED, sinceCreated=335180, sinceLastActive=69923]
java.lang.IllegalArgumentException: Cannot send a message when session is closed
at org.springframework.util.Assert.isTrue(Assert.java:65)
at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.sendMessage(AbstractSockJsSession.java:250)
at org.springframework.web.socket.WebSocketSession$sendMessage.call(Unknown Source)
at com.ilmn.hadean.handler.SummaryViewHandlerImpl.handleTextMessage(SummaryViewHandlerImpl.groovy:17)
at org.springframework.web.socket.handler.AbstractWebSocketHandler.handleMessage(AbstractWebSocketHandler.java:43)
at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleMessage(WebSocketHandlerDecorator.java:75)
at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleMessage(LoggingWebSocketHandlerDecorator.java:55)
at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.handleMessage(ExceptionWebSocketHandlerDecorator.java:69)

Please note that we are using Logback for our logging Not sure if this has anything to do with the log messages.

Thanks!

[spring-projects-issues]

Rossen Stoyanchev commented

Sachin Parikh #16769 is now fixed. If you could please give 4.1.1.BUILD-SNAPSHOT a try.

[spring-projects-issues]

Florian GOURMELEN commented

Hi I'm also having the same kind of issue

Im using spring-boot-starter-websocket with spring boot 1.5.3.RELEASE And I get tons of logs when sockjs is trying to perform a heartbeat Task

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.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [na:1.8.0] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [na:1.8.0] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0] at java.lang.Thread.run(Thread.java:744) [na:1.8.0] }