2014-11-21 3 views
0

WebSocket 메시지에 Spring WebSocket 버전 4.1.1.RELEASE가 전송되지 않는 문제가 있습니다. 그것은 모든 메시지에 일어나는 것이 아니며, 일부는 내가 이해하지 못하는 이유 때문에 보내지지 않습니다. 메시지의 내용은로드하는 데 약간의 시간이 걸리지 만 때로는 작동하기 때문에 문제의 원인인지는 확실치 않지만 때로는 작동하지만 대부분의 경우에는 그렇지 않습니다.Spring WebSocket - 컨트롤러가 보낸 메시지가 손실되었습니다.

내 웹 응용 프로그램이 성공적으로 채널 /user/queue/overview/reqinfo/events을 구독하고 4 개의 메시지를 보내 정보를 요청합니다. 내 컨트롤러 클래스는 spring-data-jpa 및 Hibernate를 통해 데이터베이스에서 COUNT() 문을 실행하고 요청이 발생한 사용자에게 결과를 메시지로 반환합니다. 네 개의 모든 메시지는 동일한 컨트롤러 방법으로 처리되지만 두 개의 응답 만 보낸 사람에게 전달됩니다. Spring 로그에서 관련 정보를 추출하여 여기에 첨부했습니다. 보시다시피, 마지막 두 메시지는 SimpleBrokerMessageHandler에 의해 처리되지 않으므로 사용자에게 전송되지 않습니다. 이 메시지의 내용을 만드는 데는 1 분 이상이 걸립니다.

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 지원 (SockJS 0.3.4 사용)과 함께 SimpleMessageBroker을 사용하고 있습니다. 내가 수동으로 connecton에 시간 제한을 설정하는 내 웹 소켓 구성 클래스에이 빈을 추가 한이 문제를 해결하기 위해 노력하지만 문제가 해결되지 않았지만 :

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

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

    return container; 
} 

는 다른다면 일부 메시지는 바로 삭제됩니다 것을 할 수있는 방법을 제대로 보냈습니까? 로그 또는 소스 코드에서 더 많은 정보가 필요하면 질문하십시오.

[업데이트] 동작에 몇 가지 추가 정보 :

항목의 가장 작은 수는 항상 반환 카운트 첫 번째 메시지. 두 번째 메시지는 대부분의 시간을 반환하고 마지막 두 개는 약 90 %의 시간을 보내지 못합니다. 그들이 다른보기를로드하지 못한 후에도로드되지 않습니다. 구독 메시지가 수신되어 처리 되더라도 응답 메시지는 웹 인터페이스로 전송되지 않습니다. 페이지를 새로 고치려면 브라우저에서 새로 고침을 누른 다음 메시지가 다시 고정 될 때까지 모든 것이 올바르게 작동합니다.

그러나 백그라운드에서 실행되고 WebSocket을 사용자에게 보내는 메시지를 위해 사용하는 하트 비트 시스템은 항상 작동합니다. 그것은이 문제에 완전히 영향을받지 않는 것 같습니다.

[UPDATE 2

문제는 sockJsScheduler 모든 요청을 처리하지 않은 것 같다 일어난다. WebSocketMessageBrokerStats 로그는 다음과 같은 출력을 제공하는 정보 메시지 :

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 네 대기 작업이 있다는 것을 말한다? 불행히도 로그에서 처리되지 않는 이유에 대한 추가 정보는 없습니다.

답변

2

내 응용 프로그램과 특히 Spring 코드를 집중적으로 디버깅 한 후 그 동작에 대한 이유를 발견했습니다.

문제는 컨트롤러 나 스프링 내부 프로세스가 아니며, 스프링 보안 인증 중에 Principal 객체에 사용하는 클래스입니다.사용자에게 응답 한 마지막 하트 비트 ID를 저장하여 시스템에 메시지를 보내는 사용자가 살아 있는지 또는 세션이 이미 죽은 것으로 간주되었는지 확인합니다. 이 ID는 해당 개체의 equals(), hashCode()toString() 메서드에 포함되었습니다.

스프링은 @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 수준 확인 (또는 WARN 또는 ERROR)하는 DEVS에 제안 . 사실 이것은 오류입니다.

위에서 언급 한 세 가지 방법에서 하트 비트 ID를 제거하면 시스템이 정상적으로 실행되고 더 이상 메시지가 손실되지 않습니다. 그래서 그것은 내 편이 처음에는 실수 였지만 여기서는 toString()의 사용이 최적이라고 생각하지 않습니다. 이제 Spring은 메시지를 올바르게 번역하여 다음 메시지를 생성 할 수 있습니다 (위와 같이 TRACE 대신 DEBUG 레벨 임).

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] 
관련 문제