SockJs heartbeat during message send closes socket [SPR-14356]

[spring-projects-issues]

William Hoyle opened SPR-14356 and commented

In the following log the heartbeat thread is SockJsScheduler-8 and the client thread is Broadcaster-3.

There appears to be a race condition between the heartbeat task and the send thread. The send thread attempts to cancel the heartbeat task before sending, but the heartbeat task has already started.

2016-06-13T00:14:22.288Z [TRACE] [] [SockJsScheduler-8] [WebSocketServerSockJsSession] Preparing to write SockJsFrame content='h'
2016-06-13T00:14:22.288Z [TRACE] [] [Broadcaster-3] [UserWebSocket] Session[fair3vq5]: Tx 'h' to user 76042
2016-06-13T00:14:22.288Z [TRACE] [] [SockJsScheduler-8] [WebSocketServerSockJsSession] Writing SockJsFrame content='h'
2016-06-13T00:14:22.288Z [TRACE] [] [Broadcaster-3] [WebSocketServerSockJsSession] Cancelling heartbeat in session fair3vq5
2016-06-13T00:14:22.288Z [TRACE] [] [SockJsScheduler-8] [NativeWebSocketSession] Sending TextMessage payload=[h], byteCount=1, last=true], StandardWebSocketSession[id=83, uri=/ajax/watch/websocket/029/fair3vq5/websocket]
2016-06-13T00:14:22.288Z [TRACE] [] [Broadcaster-3] [WebSocketServerSockJsSession] Preparing to write SockJsFrame content='a["h"]'
2016-06-13T00:14:22.288Z [TRACE] [] [Broadcaster-3] [WebSocketServerSockJsSession] Writing SockJsFrame content='a["h"]'
2016-06-13T00:14:22.288Z [TRACE] [] [Broadcaster-3] [NativeWebSocketSession] Sending TextMessage payload=[a["h"]], byteCount=6, last=true], StandardWebSocketSession[id=83, uri=/ajax/watch/websocket/029/fair3vq5/websocket]
2016-06-13T00:14:22.289Z [TRACE] [] [SockJsScheduler-8] [WebSocketServerSockJsSession] Scheduled heartbeat in session fair3vq5
2016-06-13T00:14:22.289Z [DEBUG] [] [Broadcaster-3] [WebSocketServerSockJsSession] 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:1064)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase$StateMachine.textPartialStart(WsRemoteEndpointImplBase.java:1022)
	at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendPartialString(WsRemoteEndpointImplBase.java:184)
	at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:49)

---

Affects: 4.2.5

Issue Links:

• Memory leak on STOMP broker connections that fail before heartbeats start [SPR-14266] #18838 Memory leak on STOMP broker connections that fail before heartbeats start
• SockJS heartbeat is causing application send Message to fail similar to (SPR-14356) [SPR-14564] #19133 SockJS heartbeat is causing application send Message to fail similar to (SPR-14356)

Referenced from: commits 5075dd4, 91387a5, 4c87167, 16879a2, ba885f3

Backported to: 4.2.7

[spring-projects-issues]

Rossen Stoyanchev commented

Note that in general when using WebSocket/SockJS directly, i.e. without the STOMP messaging on top, you're expected to synchronize writing to the session. You can use the ConcurrentWebSocketSessionDecorator for that.

That said it does look like we need to introduce a lock for heartbeats specifically which are are internal behavior of SockJS sessions.

[spring-projects-issues]

Rossen Stoyanchev commented

There is a fix now for 4.2.7 and 4.3.1 snapshots. If you're able to give this a try that would be very helpful. Thanks for reporting the issue.

[spring-projects-issues]

Nilesh Rao commented

Hi ,
I tried this with version 4.2.7 release and still getting this error. I am running a scheduler which runs for every 20 seconds and writes data to socket using ConcurrentWebSocketSessionDecorator also the sockjs heartbeat is running for every 10 seconds.

[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)

[spring-projects-issues]

Rossen Stoyanchev commented

Can you confirm if the above occurs around the time of the heartbeat being written? I did add a lock to prevent the sending of a heartbeat from overlapping with the cancellation of heartbeat which occurs right before the sending a message. Perhaps I missed something. If so please create a new ticket since we can't reopen this one.