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

Posted 2023-05-07

【中文标题】Spring（Grails）WebSocket 立即记录错误：SubProtocolWebSocketHandler - *** ms 后未收到消息

【英文标题】：Spring (Grails) WebSocket logs instantly an error: SubProtocolWebSocketHandler - No messages received after *** ms

【发布时间】：2018-01-17 12:50:05

【问题描述】：

拥有 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]

【问题讨论】：

愚蠢的问题：你如何配置你的 websocket 会话超时？您在@OnOpen 过程中是否有任何自定义操作？我是 Tyrus 用户，但我想主要观点是等价的

好吧，我们只实现AbstractWebSocketMessageBrokerConfigurer。我们没有@OnOpen 进程，但是我们已经实现了configureClientInboundChannel，如果允许SUBSCRIBE 等，我们会在其中进行检查。我们也没有实现任何超时，所以我想我们使用默认的超时。我不知道发生了什么......

因此，我们决定将 websocket 实现移至 nodeJS，因为它似乎更容易，并且您可以更好地控制实现。

感谢您回来。对不起，我帮不上春天。我们实际上在 Tyrus 实现中遇到了同样的问题（同样的事情，只发生在生产中），这是一个超时问题，因此是我的问题。您将使用 NodeJs 作为您的 websocket 服务器并将 Spring 作为主要后端？如果你不介意，你打算如何进行通信 Java NodeJs？

是的，这正是我们计划做的。当我们走向微服务架构时，它就朝着我们的方向发展。我们还想用一些更轻量级的解决方案来替换 Grails，比如 NodeJS。关于您的问题，我们将使用 RebbitMQ 在系统之间传递数据。当我们在 webSockets 中使用 STOMP 时，它对我们来说完全有意义。如果您需要更多详细信息，请告诉我。

【参考方案1】：

在你的 WebsocketConfig 类中写下：

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