SockJS heartbeat is causing application send Message to fail similar to (SPR-14356) [SPR-14564]

[spring-projects-issues]

Nilesh Rao opened SPR-14564 and commented

I was able to reproduce the error message from Bug " #18928". Here is the scenario for testing also I am not using STOMP framework

1. Created a scheduler which runs for every 5 seconds. configured the sockjs heartbeat at the same time and was getting this error :

2016-08-05 19:28:04,963 TRACE [MessageBroker-1] o.s.w.s.s.t.s.WebSocketServerSockJsSession [AbstractSockJsSession.java:346] Preparing to write SockJsFrame content='h'
2016-08-05 19:28:04,964 TRACE [MessageBroker-1] o.s.w.s.s.t.s.WebSocketServerSockJsSession [WebSocketServerSockJsSession.java:219] Writing SockJsFrame content='h'
2016-08-05 19:28:04,964 TRACE [MessageBroker-1] o.s.w.s.a.NativeWebSocketSession [AbstractWebSocketSession.java:100] Sending TextMessage payload=[h], byteCount=1, last=true], StandardWebSocketSession[id=0, uri=/statchat-app-0.0.1-SNAPSHOT/onetoone/987/30pkeppn/websocket?email=statchat@hfhs.org&access_token=Bearer%20cwt=AAEBHAEFAAAAAAAFFQAAAHsAXEbHxgEhNpSCuUzpBQCBEPG03KmKqGVYoJGm-eyP8YKCAobPgyA44vbuH0LIQOXZWk_ou7d_oKHnFHrE_rxhUVcuhHL73oYIw6qBWsi90wgNEICZY2jjhKJSpjrDqcajWYI]
2016-08-05 19:28:04,965 TRACE [MessageBroker-4] o.s.w.s.s.t.s.WebSocketServerSockJsSession [AbstractSockJsSession.java:301] Cancelling heartbeat in session 30pkeppn
2016-08-05 19:28:04,966 TRACE [MessageBroker-4] o.s.w.s.s.t.s.WebSocketServerSockJsSession [AbstractSockJsSession.java:346] Preparing to write SockJsFrame content='a["{\"data\":\"ping from server 17\",\"type\":\"ping\"}"]'
2016-08-05 19:28:04,967 TRACE [MessageBroker-4] o.s.w.s.s.t.s.WebSocketServerSockJsSession [WebSocketServerSockJsSession.java:219] Writing SockJsFrame content='a["{\"data\":\"ping from server 17\",\"type\":\"ping\"}"]'
2016-08-05 19:28:04,967 TRACE [MessageBroker-4] o.s.w.s.a.NativeWebSocketSession [AbstractWebSocketSession.java:100] Sending TextMessage payload=[a["{\"data..], byteCount=57, last=true], StandardWebSocketSession[id=0, uri=/statchat-app-0.0.1-SNAPSHOT/onetoone/987/30pkeppn/websocket?email=statchat@hfhs.org&access_token=Bearer%20cwt=AAEBHAEFAAAAAAAFFQAAAHsAXEbHxgEhNpSCuUzpBQCBEPG03KmKqGVYoJGm-eyP8YKCAobPgyA44vbuH0LIQOXZWk_ou7d_oKHnFHrE_rxhUVcuhHL73oYIw6qBWsi90wgNEICZY2jjhKJSpjrDqcajWYI]
2016-08-05 19:28:04,970 TRACE [MessageBroker-1] o.s.w.s.s.t.s.WebSocketServerSockJsSession [AbstractSockJsSession.java:288] Scheduled heartbeat in session 30pkeppn
2016-08-05 19:28:05,032 DEBUG [MessageBroker-4] o.s.w.s.s.t.s.WebSocketServerSockJsSession [AbstractSockJsSession.java:387] Terminating connection after failure to send message to client
java.lang.IllegalStateException: The remote endpoint was in state [TEXT_PARTIAL_WRITING] which is an invalid state for called method
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$StateMachine.checkState(WsRemoteEndpointImplBase.java:1177)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$StateMachine.textPartialStart(WsRemoteEndpointImplBase.java:1135)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendPartialString(WsRemoteEndpointImplBase.java:226)
	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:222)
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.writeFrame(AbstractSockJsSession.java:349)
	at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.sendMessageInternal(WebSocketServerSockJsSession.java:212)
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.sendMessage(AbstractSockJsSession.java:165)
	at org.springframework.web.socket.handler.ConcurrentWebSocketSessionDecorator.tryFlushMessageBuffer(ConcurrentWebSocketSessionDecorator.java:131)
	at org.springframework.web.socket.handler.ConcurrentWebSocketSessionDecorator.sendMessage(ConcurrentWebSocketSessionDecorator.java:104)
	at com.visionit.statchat.stomp.CustomStompSubProtocolHandler.handleMessageFromClient(CustomStompSubProtocolHandler.java:31)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.handleMessage(SubProtocolWebSocketHandler.java:307)
	at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleMessage(WebSocketHandlerDecorator.java:75)
	at com.visionit.statchat.stomp.WebSocketSessionCapturingHandlerDecorator.handleMessage(WebSocketSessionCapturingHandlerDecorator.java:60)
	at com.visionit.statchat.stomp.WebSocketSessionCapturingHandlerDecorator.sendToAll(WebSocketSessionCapturingHandlerDecorator.java:154)
	at com.visionit.statchat.service.impl.RedisMessageListener.pingClients(RedisMessageListener.java:90)
	at sun.reflect.GeneratedMethodAccessor81.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
2016-08-05 19:28:05,034 DEBUG [MessageBroker-4] o.s.w.s.a.NativeWebSocketSession [AbstractWebSocketSession.java:137] Closing StandardWebSocketSession[id=0, uri=/statchat-app-0.0.1-SNAPSHOT/onetoone/987/30pkeppn/websocket?email=statchat@hfhs.org&access_token=Bearer%20cwt=AAEBHAEFAAAAAAAFFQAAAHsAXEbHxgEhNpSCuUzpBQCBEPG03KmKqGVYoJGm-eyP8YKCAobPgyA44vbuH0LIQOXZWk_ou7d_oKHnFHrE_rxhUVcuhHL73oYIw6qBWsi90wgNEICZY2jjhKJSpjrDqcajWYI]

---

Affects: 4.2.7

Issue Links:

• SockJs heartbeat during message send closes socket [SPR-14356] #18928 SockJs heartbeat during message send closes socket
• StompSubProtocolHandler responds with ERROR (Session closed.) on DISCONNECT when using SimpleBrokerMessageHandler [SPR-14568] #19137 StompSubProtocolHandler responds with ERROR (Session closed.) on DISCONNECT when using SimpleBrokerMessageHandler

Referenced from: commits 977b67e

Backported to: 4.2.8

[spring-projects-issues]

Rossen Stoyanchev commented

Nilesh Rao, can you give 4.2.8.BUILD-SNAPSHOT a try to confirm a potential fix? It's available via repo.spring.io/snapshot.

[spring-projects-issues]

Nilesh Rao commented

thank you very much. I'll try and let you know

[spring-projects-issues]

Nilesh Rao commented

Hi.
I tried with the version " spring-websocket-4.2.8.BUILD-20160809.014506-17.jar" but still getting the same error. Do I need to use any other jar or Am I doing something in wrong way ?

2016-08-12 11:55:56,558 TRACE [MessageBroker-1] o.s.w.s.s.t.s.WebSocketServerSockJsSession [AbstractSockJsSession.java:350] Preparing to write SockJsFrame content='h'
2016-08-12 11:55:56,558 TRACE [MessageBroker-1] o.s.w.s.s.t.s.WebSocketServerSockJsSession [WebSocketServerSockJsSession.java:219] Writing SockJsFrame content='h'
2016-08-12 11:55:56,558 TRACE [MessageBroker-1] o.s.w.s.a.NativeWebSocketSession [AbstractWebSocketSession.java:100] Sending TextMessage payload=[h], byteCount=1, last=true], StandardWebSocketSession[id=4, uri=/statchat-app-0.0.1-SNAPSHOT/group/494/ql5czyhx/websocket?email=statchat@hfhs.org&access_token=Bearer%20cwt=AAEBHAEFAAAAAAAFFQAAAHsAXEbHxgEhNpSCuUzpBQCBEBONrz77G8VQgKkPR33-Gn-CAhF0gyB9AN9wJEP5W5A6ia837WnhzrhrZt_hgGwCbAacApORTIYIQvrLw_XC0wgNEICZY2jjhKJSpjrDqcajWYI]
2016-08-12 11:55:56,558 TRACE [MessageBroker-3] o.s.w.s.s.t.s.WebSocketServerSockJsSession [AbstractSockJsSession.java:305] Cancelling heartbeat in session ql5czyhx
2016-08-12 11:55:56,559 TRACE [MessageBroker-3] o.s.w.s.s.t.s.WebSocketServerSockJsSession [AbstractSockJsSession.java:350] Preparing to write SockJsFrame content='a["{\"data\":\"ping from server 93\",\"type\":\"ping\"}"]'
2016-08-12 11:55:56,559 TRACE [MessageBroker-3] o.s.w.s.s.t.s.WebSocketServerSockJsSession [WebSocketServerSockJsSession.java:219] Writing SockJsFrame content='a["{\"data\":\"ping from server 93\",\"type\":\"ping\"}"]'
2016-08-12 11:55:56,559 TRACE [MessageBroker-3] o.s.w.s.a.NativeWebSocketSession [AbstractWebSocketSession.java:100] Sending TextMessage payload=[a["{\"data..], byteCount=57, last=true], StandardWebSocketSession[id=4, uri=/statchat-app-0.0.1-SNAPSHOT/group/494/ql5czyhx/websocket?email=statchat@hfhs.org&access_token=Bearer%20cwt=AAEBHAEFAAAAAAAFFQAAAHsAXEbHxgEhNpSCuUzpBQCBEBONrz77G8VQgKkPR33-Gn-CAhF0gyB9AN9wJEP5W5A6ia837WnhzrhrZt_hgGwCbAacApORTIYIQvrLw_XC0wgNEICZY2jjhKJSpjrDqcajWYI]
2016-08-12 11:55:56,559 DEBUG [MessageBroker-3] o.s.w.s.s.t.s.WebSocketServerSockJsSession [AbstractSockJsSession.java:391] Terminating connection after failure to send message to client
java.lang.IllegalStateException: The remote endpoint was in state [TEXT_PARTIAL_WRITING] which is an invalid state for called method
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$StateMachine.checkState(WsRemoteEndpointImplBase.java:1177)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$StateMachine.textPartialStart(WsRemoteEndpointImplBase.java:1135)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendPartialString(WsRemoteEndpointImplBase.java:226)
	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:222)
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.writeFrame(AbstractSockJsSession.java:353)
	at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.sendMessageInternal(WebSocketServerSockJsSession.java:212)
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.sendMessage(AbstractSockJsSession.java:165)
	at org.springframework.web.socket.handler.ConcurrentWebSocketSessionDecorator.tryFlushMessageBuffer(ConcurrentWebSocketSessionDecorator.java:131)
	at org.springframework.web.socket.handler.ConcurrentWebSocketSessionDecorator.sendMessage(ConcurrentWebSocketSessionDecorator.java:104)
	at com.visionit.statchat.websocket.WebSocketMsgSubProtocolHandler.handleMessageFromClient(WebSocketMsgSubProtocolHandler.java:32)
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.handleMessage(SubProtocolWebSocketHandler.java:307)
	at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleMessage(WebSocketHandlerDecorator.java:75)
	at com.visionit.statchat.websocket.WebSocketSessionConnectionHandlerDecorator.handleMessage(WebSocketSessionConnectionHandlerDecorator.java:60)
	at com.visionit.statchat.websocket.WebSocketSessionConnectionHandlerDecorator.sendToAll(WebSocketSessionConnectionHandlerDecorator.java:166)
	at com.visionit.statchat.service.impl.RedisMessageListener.pingClients(RedisMessageListener.java:85)
	at sun.reflect.GeneratedMethodAccessor158.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:65)
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)

[spring-projects-issues]

Nilesh Rao commented

Hello, Just wanted to check .. what is the next step for this .

[spring-projects-issues]

Rossen Stoyanchev commented

hi sorry for the slow response. I will have another look.

[spring-projects-issues]

Rossen Stoyanchev commented

Nilesh Rao I think this coming from an incorrect assumption in AbstractionSockJsSession about the return value of ScheduledFuture#cancel(). In short a return value of true does not mean the task won't run.

Unfortunately I was unable to reproduce the issue in my environment so I can't confirm myself the fix but I will have something later today that hopefully you can try and thanks for your patience!

[spring-projects-issues]

Rossen Stoyanchev commented

Okay I have a fix that should address this properly. Would you mind giving 4.2.8.BUILD-SNAPSHOT a try when this build completes? Thanks!

[spring-projects-issues]

Rossen Stoyanchev commented

Nilesh Rao, I'm marking this resolved but would be great to have confirmation it works for you.

[spring-projects-issues]

Nilesh Rao commented

Thank you. Surely, I'll test it some time later and will update you if I see any issue.