Error message "Subscribe request come too late"

tomas.walek-ext@sgcib.com

Recently we started receiving following error messages, which we think come from the Lightstreamer library:

29-Dec-20 07:10:03,867|ERROR|Adapters.OURPROXYNAME.DEFAULT|pter.DEFAULT Reply Receiver|Exception caught while subscribing to item 'OUR_PRODUCT_IDENTIFIER'
com.lightstreamer.interfaces.data.SubscriptionException: Subscribe request come too late
at com.lightstreamer.adapters.proxy.data.DataProviderProtocol.readSubscribe(DataProviderProtocol.java:144)
at com.lightstreamer.adapters.proxy.data.RemoteDataProvider$2.onReplyReceived(RemoteDataProvider.java:218)
at com.lightstreamer.adapters.proxy.request_reply.RequestSender.onNotifyReceived(RequestSender.java:389)
at com.lightstreamer.adapters.proxy.request_reply.NotifyReceiver.onNotifyReceived(NotifyReceiver.java:244)
at com.lightstreamer.adapters.proxy.request_reply.NotifyReceiver.run(NotifyReceiver.java:115)

Would you be able to tell us what may be the cause of the error above?
We were not seeing those errosr before and we think it may be related to the performance of the infrastructure.
LS version used: 7.2.0

Giuseppe Corti

Hi Tomas,

Yes I can confirm that this kind of error may be due to slowdowns in the execution of client requests.
In particular this specific error means that a subscribe request from a client was processed once the client session involved was already closed.

You could also double check the server log looking for messages like this: "Current delay for tasks scheduled on thread pool ... is ... seconds".
And also look at the "Queued tasks" metric in the MonitorText lines: if the values are consistently greater than zero then client requests are accumulating delays.

Then you should look for the causes of these delays, they could be due to external slowdowns such as calls to external services in your adapters which sometimes take longer than normal.
Or the load is simply too high for the environment deployed. But for this type of analysis it is necessary to have more information.

Please also confirm that there is a typo in the Lightstreamer server version in use, did you mean 7.1.2?

Regards,
Giuseppe

tomas.walek-ext@sgcib.com

Good morning Giuseppe,
thank you very much for your fast reply.
I checked the log files from the particular days and the Queued tasks value is always in the range 0 - 100, while it rarely grows over 40, mostly it is 0. I checked all cases before this error message appeared and only in one case the Queued tasks value was 8, otherwise it was 8. The number of threads is roughly around 300, almost throughout the whole day.
I did not find the other message about "Current delay" you mentioned. Is it supposed to be in the same logfile?
However, I found this:

Granted time expired for session Se2d7c076a1d1975fM507T1447423: requesting a rebind

and the other log entry which appears after such an error is:

Session S1e5c2fce3ae39e30M507T1826214 resumed from 104

So that confirms very much your answer.

I can also confirm that I made a typo in the version number. It is Version: 7.0.3 build 1885.8. Should we potentially to a higher version? Can it have impact on the error message mentioned in my previous message?

Could you also tell me what is the lifetime of a client session? Is this value configurable?

Thank you in advance.
Best regards,
Tomas

Giuseppe Corti

Hi Tomas,

Yes, the "Current delay" messages are printed in the same log file (unless special customizations), so we can assume that your Lightstreamer is not suffering from generalized delays due to overload.
But, please could you confirm the log level of LightstreamerMonitorText logger? Because, with INFO level you have a Monitor line every 2 minutes, so any episodes of short crises, less than 1 minute, can be completely missed or not clearly identifiable.
In the case, you can switch to TRACE level, that means a Monitor line every 2 seconds, without excessively increasing the verbosity of the log it allows analysis of problems like this more accurately.

A client session is considered closed by the Lightstreamer server under various circumstances.
The most obvious is when it receives an explicit disconnect request from the client.
In other cases it is the server that takes the initiative, particularly when it detects network problems on the client session's streaming connection.
In some of these circumstances the server holds the client session for a few seconds for the possible rebind request from the client that would allow the session to be recovered.
And that's what actually happened with the message you attached: "Session S1e5c2fce3ae39e30M507T1826214 resumed from 104 ".
If messages like these recur frequently it is possible that the issue is due to temporary network outages (client-side or server-side).

Actually the recovery timeout can be configured, please refer to these parameters in the lightstreamer_conf.xml:

<session_recovery_millis>
<max_recovery_length>
<max_recovery_poll_length>

Upgrading at your earliest convenience to the latest available version is something we always recommend, but in this specific case I don't think it will impact your issue.

Regards,
Giuseppe

tomas.walek-ext@sgcib.com

Hello Giuseppe,
thank you kindly for your reply.
We have been using the level INFO so far, but we will switch to TRACE to extract a more exact timing information and use this information for further investigation. I will come back to you once I have some results.
Have a nice day.
Best regards,
Tomas