Spring (Grails) WebSocket logs instantly an error: SubProtocolWebSocketHandler - No messages received after *** ms

Question

Having Grails 3.2.11 (Spring 4.3.1, Spring Websocket 4.3.9) I receive log error message that websocket session is idle.

2017-08-09 14:06:45,820 ERROR org.springframework.web.socket.messaging.SubProtocolWebSocketHandler - No messages received after 62082 ms. Closing EventSourceStreamingSockJsSession[id=bka1ui0i].

Observation:

• This happens only in production (https, AWS with load balancer as a proxy).
• This happens only if I open WebSocket client. If I close it, the error disappears.
• This error occurs every minute precisely (my heartbeat is set to 10 sec).
• Websocket session id are random (I don't see any connect message for these ids).
• More websocket I open and close, more errors appears.

Larger log for inspection:

2017-08-09 14:37:57,157 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[0], headers={simpMessageType=CONNECT, stompCommand=CONNECT, nativeHeaders={Authorization=[Bearer eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsImtpZCI6Ik9FUkRRVEF5TVVKQlJrRkRPVFl3TTBNd1JUTXhSRVk0TVVaRFF6aERNVUpGUmpJME5EY3pRdyJ9.eyJpc3MiOiJodHRwczovL2FtaW8uZXUuYXV0aDAuY29tLyIsInN1YiI6ImF1dGgwfDU5NWI2M2UxYTE3ZDM1MTNlMjliYWNjMyIsImF1ZCI6Imh0dHBzOi8vYXBwLmFtaW8uaW8iLCJhenAiOiIwRmFoQlJSSkp0WW5LN2xDb0dIZHV3SEJGNHNiSGVjWiIsImV4cCI6MTUwMjI4OTU1MiwiaWF0IjoxNTAyMjAzMTUyLCJzY29wZSI6IiIsImd0eSI6InBhc3N3b3JkIiwiaHR0cHM6Ly9hcHAuYW1pby5pby9vcmdhbml6YXRpb25JZCI6IjYyMDQ2MzA0NDIifQ.RqeXHDwcTmuj9h5pCYWh6DXyRKrycA5id6G-fJ4SXIdnjEBE6eukm-emXGG5S4RZ-zCR_2DJGaVXSp9UXd6j3lnvO-b6U7exOzLg6Mku4-jQmeDy0vGaCnYZfVrSqtzCSZ-WVt4k-lzgfPqWiMlvHxC5C9q5uaeBkiUXrYt5Xv9QuMzeWdvhwrfyfILZLhSByBXTYHmT-0a0dIsFMpNGBZy7nPVKTdOILKRSNtpJZ6riiYFTJGTzKYj1RnAym7oT-uIJZF2i1BYfTqSPAdx9iiXnFV0AjswFs-Lby5DbMR50J8zfpWWfVQ4HBsQZTi3hkacctQ9PHU90o81UySh3vw], accept-version=[1.2,1.1,1.0], heart-beat=[10000,10000]}, simpSessionAttributes={}, simpHeartbeat=[J@517fa790, simpSessionId=xypqdnz2}]
2017-08-09 14:37:57,242 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[0], headers={simpMessageType=SUBSCRIBE, stompCommand=SUBSCRIBE, nativeHeaders={Authorization=[Bearer eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsImtpZCI6Ik9FUkRRVEF5TVVKQlJrRkRPVFl3TTBNd1JUTXhSRVk0TVVaRFF6aERNVUpGUmpJME5EY3pRdyJ9.eyJpc3MiOiJodHRwczovL2FtaW8uZXUuYXV0aDAuY29tLyIsInN1YiI6ImF1dGgwfDU5NWI2M2UxYTE3ZDM1MTNlMjliYWNjMyIsImF1ZCI6Imh0dHBzOi8vYXBwLmFtaW8uaW8iLCJhenAiOiIwRmFoQlJSSkp0WW5LN2xDb0dIZHV3SEJGNHNiSGVjWiIsImV4cCI6MTUwMjI4OTU1MiwiaWF0IjoxNTAyMjAzMTUyLCJzY29wZSI6IiIsImd0eSI6InBhc3N3b3JkIiwiaHR0cHM6Ly9hcHAuYW1pby5pby9vcmdhbml6YXRpb25JZCI6IjYyMDQ2MzA0NDIifQ.RqeXHDwcTmuj9h5pCYWh6DXyRKrycA5id6G-fJ4SXIdnjEBE6eukm-emXGG5S4RZ-zCR_2DJGaVXSp9UXd6j3lnvO-b6U7exOzLg6Mku4-jQmeDy0vGaCnYZfVrSqtzCSZ-WVt4k-lzgfPqWiMlvHxC5C9q5uaeBkiUXrYt5Xv9QuMzeWdvhwrfyfILZLhSByBXTYHmT-0a0dIsFMpNGBZy7nPVKTdOILKRSNtpJZ6riiYFTJGTzKYj1RnAym7oT-uIJZF2i1BYfTqSPAdx9iiXnFV0AjswFs-Lby5DbMR50J8zfpWWfVQ4HBsQZTi3hkacctQ9PHU90o81UySh3vw], accept-version=[1.2,1.1,1.0], heart-beat=[10000,10000], id=[sub-0], destination=[/topic/organizations/6204630442/conversations]}, simpSessionAttributes={}, simpHeartbeat=[J@57ba18ca, simpSubscriptionId=sub-0, simpSessionId=xypqdnz2, simpDestination=/topic/organizations/6204630442/conversations}]
2017-08-09 14:38:07,204 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[1], headers={simpMessageType=HEARTBEAT, simpSessionAttributes={}, simpHeartbeat=[J@1d3ca02c, simpSessionId=xypqdnz2}]
2017-08-09 14:38:17,210 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[1], headers={simpMessageType=HEARTBEAT, simpSessionAttributes={}, simpHeartbeat=[J@224a4749, simpSessionId=xypqdnz2}]
2017-08-09 14:38:27,217 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[1], headers={simpMessageType=HEARTBEAT, simpSessionAttributes={}, simpHeartbeat=[J@1e0051d2, simpSessionId=xypqdnz2}]
2017-08-09 14:38:38,653 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[1], headers={simpMessageType=HEARTBEAT, simpSessionAttributes={}, simpHeartbeat=[J@5b3af326, simpSessionId=xypqdnz2}]
2017-08-09 14:38:47,829 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[1], headers={simpMessageType=HEARTBEAT, simpSessionAttributes={}, simpHeartbeat=[J@4f5adbf9, simpSessionId=xypqdnz2}]
2017-08-09 14:38:57,912 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[1], headers={simpMessageType=HEARTBEAT, simpSessionAttributes={}, simpHeartbeat=[J@6864024b, simpSessionId=xypqdnz2}]
2017-08-09 14:39:08,297 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[1], headers={simpMessageType=HEARTBEAT, simpSessionAttributes={}, simpHeartbeat=[J@75abadf2, simpSessionId=xypqdnz2}]
2017-08-09 14:39:17,859 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[1], headers={simpMessageType=HEARTBEAT, simpSessionAttributes={}, simpHeartbeat=[J@10a4573d, simpSessionId=xypqdnz2}]
2017-08-09 14:39:17,860 ERROR org.springframework.web.socket.messaging.SubProtocolWebSocketHandler - No messages received after 81573 ms. Closing HtmlFileStreamingSockJsSession[id=xr1yyksf].
2017-08-09 14:39:17,864 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[0], headers={simpMessageType=DISCONNECT, stompCommand=DISCONNECT, simpSessionAttributes={}, simpSessionId=xr1yyksf}]
2017-08-09 14:39:17,864 ERROR org.springframework.web.socket.messaging.SubProtocolWebSocketHandler - No messages received after 119077 ms. Closing EventSourceStreamingSockJsSession[id=jvccwoe1].
2017-08-09 14:39:17,865 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[0], headers={simpMessageType=DISCONNECT, stompCommand=DISCONNECT, simpSessionAttributes={}, simpSessionId=jvccwoe1}]
2017-08-09 14:39:17,866 ERROR org.springframework.web.socket.messaging.SubProtocolWebSocketHandler - No messages received after 82421 ms. Closing EventSourceStreamingSockJsSession[id=gvbiovyd].
2017-08-09 14:39:17,867 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[0], headers={simpMessageType=DISCONNECT, stompCommand=DISCONNECT, simpSessionAttributes={}, simpSessionId=gvbiovyd}]
2017-08-09 14:39:17,867 ERROR org.springframework.web.socket.messaging.SubProtocolWebSocketHandler - No messages received after 81664 ms. Closing EventSourceStreamingSockJsSession[id=4iygbevw].
2017-08-09 14:39:17,868 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[0], headers={simpMessageType=DISCONNECT, stompCommand=DISCONNECT, simpSessionAttributes={}, simpSessionId=4iygbevw}]
2017-08-09 14:39:17,869 ERROR org.springframework.web.socket.messaging.SubProtocolWebSocketHandler - No messages received after 81653 ms. Closing HtmlFileStreamingSockJsSession[id=bjqd0yjd].
2017-08-09 14:39:17,870 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[0], headers={simpMessageType=DISCONNECT, stompCommand=DISCONNECT, simpSessionAttributes={}, simpSessionId=bjqd0yjd}]
2017-08-09 14:39:17,870 ERROR org.springframework.web.socket.messaging.SubProtocolWebSocketHandler - No messages received after 119082 ms. Closing EventSourceStreamingSockJsSession[id=ytkhjnqa].
2017-08-09 14:39:17,871 DEBUG myapp.websocket.WebSocketConfig - websocket inbout channel received message GenericMessage [payload=byte[0], headers={simpMessageType=DISCONNECT, stompCommand=DISCONNECT, simpSessionAttributes={}, simpSessionId=ytkhjnqa}]

Conurbation

Silly question: how do you configure your websocket session timeout? Do you have any custom action during your @OnOpen process? I'm a Tyrus user but I guess that the main points are equivalent – Angwantibo

Well, we only implement AbstractWebSocketMessageBrokerConfigurer. We have no @OnOpen process however we've implemented configureClientInboundChannel where we chack if i.e. SUBSCRIBE is allowed, etc. We also didn't implemented any timeout so I guess we use the default one. I have no clue what is happening... – Conurbation

So as a result, we decided to move the websocket implementation to nodeJS as it seems to be easier and you have more control over the implementation. – Conurbation

Thanks for getting back. Sorry I couldn't help on Spring. We actually have the same issue on our Tyrus implementation (same thing, only happen in production) and it was a timeout issue, hence my question. You'll use NodeJs as your websocket server and keep Spring as main back-end? If you don't mind, how do you plan to do the communication Java <-> NodeJs? – Angwantibo

Yes, this is exactly what we plan to do. As we are heading to micro-services architecture, it goes our direction. We also would like to replace Grails with some more lightweight solutions like NodeJS is. Regarding your question, we will use RebbitMQ for delivering data between systems. As we use STOMP within webSockets, it makes total sense for us. Let me know if you need more details. – Conurbation

Answer 1

In your WebsocketConfig Class write this:

@Override
public void configureWebSocketTransport(WebSocketTransportRegistration registration) {
    registration.setTimeToFirstMessage(99999); // Time
}

Errancy