Spring WebSocket - messages lost after being sent by controller

Question

I have a problem with WebSocket messages not getting sent with Spring WebSocket version 4.1.1.RELEASE. It does not happen to every message, just some are not sent for a reason I do not understand. The content of the messages takes some time to load but I am not sure if that is the reason for the issue since sometimes it works but most of the time it does not.

My web application successfully subscribes to a channel /user/queue/overview/reqinfo/events and then sends four messages to request information. My controller class fires a COUNT() statement on a database via spring-data-jpa and Hibernate and returns the result as a message to the user the request came from. All four messages are handled by the same controller method but only two responses get delivered to the sender. I extracted the relevant information from the Spring logs and attached them here. As you can see the last two messages are not being processed by the SimpleBrokerMessageHandler and are thus not sent to the user. Creating the content of these messages takes more than a minute.

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)

This is a sample case where the problem occurs often. I have other views with other messages and controllers that suffer by the same issue and their messages do not take a minute to build, only some seconds or even less. I am using the SimpleMessageBroker with SockJS support (using SockJS 0.3.4). While trying to fix this issue I added this bean to my WebSocket configuration class to manually set timeouts on the connecton but it did not solve the problem:

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

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

    return container;
}

How can it be that some messages are just dropped while other get sent properly? If you need any more information from the logs or source code please ask.

[UPDATE] Some additional information on the behavior:

The first message that counts the smallest number of items always returns. The second message returns most of the time and the last two fail to be sent about 90% of the time. After they failed to load other views won't load as well, the response messages are just not sent to the web interface even though the subscription is received and processed. After hitting refresh in the browser to reload the page everything works fine until a message gets stuck again.

However, the heartbeat system that runs in the background and uses the WebSocket as well for its messages to the users works all the time. It seems to be completely unaffected by the issue.

[UPDATE 2]

When the issue occurs it seems that the sockJsScheduler is not processing all requests. The INFO message that the WebSocketMessageBrokerStats logs gives the following output:

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]

It says that there are four queued tasks for the sockJsScheduler that are not being processed, maybe these are the messages that are not sent properly? Unfortunately there is no further information on why they are not processed in the logs.

Answer 1

After intensive debugging of my application and especially the Spring code that handles I found the reason for that behavior.

The issue was neither the controller nor the Spring internal processes, it was the class that I use for Principal objects during Spring Security authentication. It stores the last heartbeat ID that the user answered successfully to check if a user that send a message to the system is alive or if the session was already considered dead. This ID was included in the equals(), hashCode() and toString() methods of that object.

Spring uses one of these methods (after some testing I guess it is toString(), which is not a good choice in my opinion) to translate destination paths for @SendToUser operations. If the string changes, which was the case for my application when a new heartbeat ID was answered, Spring cannot translate the destination path and does not send the message. The log entry that states this is hidden as a TRACE level message, which is why I did not find it in the first place. The message looks like this:

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

I would suggest to the devs to make this message at least DEBUG level (or even WARN or ERROR), since this information is hard to spot when searching for issues during the sending process. In fact this is an error.

After removing the heartbeat ID from the three mentioned methods the systems runs well, no more lost messages. So it was a mistake on my side in the first place but I think the use of toString() is not optimal here. Now Spring can translate the messages correctly, producing these messages (which are DEBUG level instead of TRACE as the above):

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]