2014-11-21 304 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]