2014-11-21 51 views
0

我有一个WebSocket消息没有与Spring WebSocket版本4.1.1.RELEASE一起发送的问题。它不会发生在每封邮件中,只是有些邮件不会因为我不明白的原因而发送。消息的内容需要一些时间才能加载,但我不确定这是否是问题的原因,因为有时可以使用,但大多数情况下不会。Spring WebSocket - 被控制器发送后丢失的消息

我的web应用程序成功订阅了频道/user/queue/overview/reqinfo/events,然后发送四条消息以请求信息。我的控制器类通过spring-data-jpa和Hibernate在数据库上触发COUNT()语句,并将结果作为消息返回给用户请求来自。所有四个消息都由相同的控制器方法处理,但只有两个响应被传递给发送者。我从Spring日志中提取相关信息并将它们附加在这里。正如你所看到的,最后两条消息没有被SimpleBrokerMessageHandler处理,因此不会发送给用户。创建这些消息的内容需要一分多钟。

12:50:54,953 DEBUG clientInboundChannel-12 user.UserDestinationMessageHandler:187 - Translated /user/queue/overview/reqinfo/events -> [/queue/overview/reqinfo/events-user8178efnd] 
12:50:54,953 DEBUG clientInboundChannel-12 broker.SimpleBrokerMessageHandler:175 - Processing SUBSCRIBE /queue/overview/reqinfo/events-user8178efnd id=sub-7 session=8178efnd 
[...] 
12:50:54,957 DEBUG clientInboundChannel-2 support.SimpAnnotationMethodMessageHandler:348 - Searching methods to handle SEND /app/overview/reqinfo/events session=8178efnd 
12:50:54,957 DEBUG clientInboundChannel-1 support.SimpAnnotationMethodMessageHandler:348 - Searching methods to handle SEND /app/overview/reqinfo/events session=8178efnd 
12:50:54,957 DEBUG clientInboundChannel-16 support.SimpAnnotationMethodMessageHandler:348 - Searching methods to handle SEND /app/overview/reqinfo/events session=8178efnd 
12:50:54,959 DEBUG clientInboundChannel-10 support.SimpAnnotationMethodMessageHandler:348 - Searching methods to handle SEND /app/overview/reqinfo/events session=8178efnd 
[...] 
12:50:54,959 DEBUG clientInboundChannel-16 support.SimpAnnotationMethodMessageHandler:446 - Invoking de.d.i.g.websocket.OverviewController#requestOverviewEvents[2 args] 
12:50:54,959 DEBUG clientInboundChannel-10 support.SimpAnnotationMethodMessageHandler:446 - Invoking de.d.i.g.websocket.OverviewController#requestOverviewEvents[2 args] 
12:50:54,959 DEBUG clientInboundChannel-2 support.SimpAnnotationMethodMessageHandler:446 - Invoking de.d.i.g.websocket.OverviewController#requestOverviewEvents[2 args] 
12:50:54,959 DEBUG clientInboundChannel-1 support.SimpAnnotationMethodMessageHandler:446 - Invoking de.d.i.g.websocket.OverviewController#requestOverviewEvents[2 args] 
[...] 
12:50:55,006 DEBUG clientInboundChannel-1 websocket.OverviewController:196 - requestOverviewEvents, incoming message: MsgOverviewEventsRequest(timeframe=THIS_WEEK) 
12:50:55,006 DEBUG clientInboundChannel-10 websocket.OverviewController:196 - requestOverviewEvents, incoming message: MsgOverviewEventsRequest(timeframe=LAST_WEEK) 
12:50:55,006 DEBUG clientInboundChannel-2 websocket.OverviewController:196 - requestOverviewEvents, incoming message: MsgOverviewEventsRequest(timeframe=YESTERDAY) 
12:50:55,006 DEBUG clientInboundChannel-16 websocket.OverviewController:196 - requestOverviewEvents, incoming message: MsgOverviewEventsRequest(timeframe=TODAY) 
[...] 
12:50:55,032 DEBUG clientInboundChannel-16 websocket.OverviewController:225 - requestOverviewEvents, outgoing message: MsgOverviewEvents(timeframe=TODAY, count=31, error=false) 
12:50:55,035 DEBUG clientInboundChannel-16 broker.SimpleBrokerMessageHandler:152 - Processing MESSAGE destination=/queue/overview/reqinfo/events-user8178efnd session=null payload={"timeframe":"TODAY","count":31,"error":false} 
12:50:55,035 DEBUG clientInboundChannel-16 broker.SimpleBrokerMessageHandler:196 - Broadcasting to 1 sessions. 
[...] 
12:51:01,018 DEBUG clientInboundChannel-2 websocket.OverviewController:225 - requestOverviewEvents, outgoing message: MsgOverviewEvents(timeframe=YESTERDAY, count=190292, error=false) 
12:51:01,020 DEBUG clientInboundChannel-2 broker.SimpleBrokerMessageHandler:152 - Processing MESSAGE destination=/queue/overview/reqinfo/events-user8178efnd session=null payload={"timeframe":"YESTERDAY","count":190292,"error":false} 
12:51:01,020 DEBUG clientInboundChannel-2 broker.SimpleBrokerMessageHandler:196 - Broadcasting to 1 sessions. 
[...] 
12:51:19,081 DEBUG clientInboundChannel-1 websocket.OverviewController:225 - requestOverviewEvents, outgoing message: MsgOverviewEvents(timeframe=THIS_WEEK, count=845956, error=false) 
12:51:19,088 DEBUG clientInboundChannel-10 websocket.OverviewController:225 - requestOverviewEvents, outgoing message: MsgOverviewEvents(timeframe=LAST_WEEK, count=1421118, error=false) 

这是一个经常发生问题的示例。我对其他消息和控制器也有其他看法,这些消息和控制器受到相同问题的困扰,并且他们的消息不需要一分钟即可构建,只需几秒甚至更少。我使用支持SockJS的SimpleMessageBroker(使用SockJS 0.3.4)。在试图解决这个问题,我加入这个bean到我的WebSocket配置类手动设置在connecton超时,但它并没有解决这个问题:

@Bean 
public ServletServerContainerFactoryBean createWebSocketContainer() { 
    long tenMinutesInMillis = 10 * 60 * 1000; 

    ServletServerContainerFactoryBean container = new ServletServerContainerFactoryBean(); 
    container.setAsyncSendTimeout(tenMinutesInMillis); 
    container.setMaxSessionIdleTimeout(tenMinutesInMillis); 

    return container; 
} 

这怎么可能,有些消息只是下降,而其他获得正确发送?如果您需要更多来自日志或源代码的信息,请询问。

[更新]上的行为的一些附加信息:

计数的项目最少数量始终返回的第一个消息。大部分时间返回第二条消息,而最后两条消息大约90%未能发送。在加载失败后,其他视图也无法加载,即使接收和处理订阅,响应消息也不会发送到Web界面。在浏览器中刷新刷新以重新加载页面后,一切正常,直到消息再次卡住。

但是,在后台运行并使用WebSocket以及向用户发送消息的心跳系统始终工作。这似乎完全不受这个问题的影响。

[更新2]

出现问题时似乎sockJsScheduler不处理所有请求。该WebSocketMessageBrokerStats日志提供了以下输出INFO消息:

INFO MessageBrokerSockJS-2 config.WebSocketMessageBrokerStats:113 - WebSocketSession[1 current WS(1)-HttpStream(0)-HttpPoll(0), 1 total, 0 closed abnormally (0 connect failure, 0 send limit, 0 transport error)], stompSubProtocol[processed CONNECT(1)-CONNECTED(1)-DISCONNECT(0)], stompBrokerRelay[null], inboundChannel[pool size = 16, active threads = 0, queued tasks = 0, completed tasks = 120], outboundChannelpool size = 16, active threads = 0, queued tasks = 0, completed tasks = 16], sockJsScheduler[pool size = 8, active threads = 1, queued tasks = 4, completed tasks = 18] 

它说,有一些没有被处理,也许这些都是未正确发送的消息为sockJsScheduler 4个排队的任务是什么?遗憾的是,没有关于为什么不在日志中处理的更多信息。

回答

2

经过我的应用程序的密集调试,特别是处理的Spring代码后,我找到了该行为的原因。

该问题既不是控制器也不是Spring内部过程,它是Spring Security身份验证期间用于Principal对象的类。它存储用户成功应答的最后一次心跳ID,以检查向系统发送消息的用户是否还活着,或者该会话是否已被视为死亡。该ID包含在该对象的equals(),hashCode()toString()方法中。

Spring为使用@SendToUser操作转换目标路径,使用这些方法之一(经过一些测试后,我认为它是toString(),这在我看来不是一个好的选择)。如果字符串发生变化,那么当我的应用程序出现新的心跳ID时,Spring将无法翻译目标路径并且不会发送消息。说明这一点的日志条目隐藏为TRACE级别的消息,这就是为什么我没有首先找到它的原因。消息是这样的:

14:29:00,260 TRACE clientInboundChannel-16 user.UserDestinationMessageHandler:175 - No user destinations found for /user/RtAuthorizedUser(super=AuthorizedUser(username=SIEM-User 1, authenticated=true, lastAnsweredHeartbeat=9971f9ea-8e64-4c24-823b-f7e6e277c775, alive=true), rtSessionId=RT_SID_iMonitor.443=782acc747aac01b9e0a7ece3ab2d27bd)/queue/overview/reqinfo/events 

我建议给开发者,使这个消息至少DEBUG级别(甚至字迹模糊或错误),因为这些信息是很难的问题搜索时发现在发送过程。其实这是一个错误。

从上述三种方法中删除心跳ID后,系统运行良好,没有更多丢失的消息。所以这首先是我的错误,但我认为toString()在这里并不是最佳选择。现在Spring可以正确地翻译消息,生成这些消息(它们是DEBUG级别而不是TRACE,如上所示):

14:37:35,661 DEBUG clientInboundChannel-3 user.UserDestinationMessageHandler:187 - Translated /user/RtAuthorizedUser(super=AuthorizedUser(username=SIEM-User 1, authenticated=true, alive=true), rtSessionId=RT_SID_iMonitor.443=bf3adbaa858932b64a03724b6137e95d)/queue/overview/reqinfo/events -> [/queue/overview/reqinfo/events-user_qtca5il]