Spring（Grails）WebSocket立即记录错误：SubProtocolWebSocketHandler-***毫秒后未收到任何消息

Question

我使用Grails 3.2.11 (Spring 4.3.1, Spring Websocket 4.3.9)时，收到了websocket会话空闲的日志错误信息。

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

观察：

• 这只发生在生产环境中（https，AWS使用负载均衡器作为代理）。
• 只有当我打开WebSocket客户端时才会出现此问题。如果我关闭它，则错误消失。
• 此错误每分钟精确发生一次（我的心跳设置为10秒）。
• Websocket会话ID是随机的（我没有看到任何这些ID的连接消息）。
• 打开和关闭更多的WebSocket，就会出现更多的错误。

用于检查的较大日志：

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}]

- kuceram

---

愚蠢的问题：你如何配置websocket会话超时？在你的@OnOpen过程中，是否有任何自定义操作？我是Tyrus用户，但我猜主要点都是等效的。 - Al-un

好的，我们只实现了 AbstractWebSocketMessageBrokerConfigurer。虽然我们没有 @OnOpen 过程，但是我们已经实现了 configureClientInboundChannel，在这里我们检查是否允许 SUBSCRIBE 等等。我们也没有实现任何超时，所以我猜我们使用默认超时。我不知道正在发生什么... - kuceram

因此，我们决定将WebSocket实现移植到NodeJS上，因为这似乎更容易，并且您可以更好地控制实现。 - kuceram

感谢回复。很抱歉我无法在Spring方面提供帮助。我们在Tyrus实现中也遇到了同样的问题（同样的事情，只发生在生产环境中），这是一个超时问题，因此我才会问这个问题。您将使用NodeJs作为WebSocket服务器，并将Spring保留为主要后端吗？如果您不介意，您计划如何进行Java <-> NodeJs之间的通信？ - Al-un

是的，这正是我们计划要做的。由于我们正在朝着微服务架构的方向发展，因此这符合我们的方向。我们还希望用一些更轻量级的解决方案（如NodeJS）来替换Grails。关于您的问题，我们将使用RebbitMQ在系统之间传递数据。由于我们在webSockets中使用STOMP，所以这对我们来说是完全有意义的。如果您需要更多细节，请告诉我。 - kuceram

Answer 1

在你的WebsocketConfig类中写入以下内容：

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

- Nguyễn Thanh Tùng