Sync errors in server log

riwang

Hi,

I found the following log output in the LS server log. It seems the LS server created a new session with id Sb50bef2560eac1cbT3950716, but still was trying to control the old session with old id S4040fce00115c0a5T5129274.

When this happened, the browser will show a Javascript alert, saying "Exception thrown and not caught". The LS steaming was stopped afterwards. Can anyone please comment on what could have caused the Sync errors?

Thanks,
Richard

Below are the log output:
------------------------------------------------

2009-08-10 10:39:50,264 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1774&LS_domain=currensee.com& from 82.81.254.65:2397>
2009-08-10 10:39:50,264 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:2397>
2009-08-10 10:39:50,600 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/create_session.js?LS_phase=1775&LS_domain=currensee.com&LS_polling=true&LS_polling_millis=1109&LS_idle_millis=30000&LS_client_version=4.3&LS_adapter=FOREXPERT&LS_user=8&LS_password=[...]&LS_old_session=S4040fce00115c0a5T5129274& from 82.81.254.65:2399>
2009-08-10 10:39:50,716 INFO [LightstreamerLogger.requests] - <Starting new session: Sb50bef2560eac1cbT3950716 from 82.81.254.65:2399>
2009-08-10 10:39:51,084 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/control.html?LS_session=S4040fce00115c0a5T5129274&LS_window=11&LS_win_phase=5&LS_op=add&LS_req_phase=103&LS_mode1=MERGE&LS_id1=FXCMPriceUpdates%20thomsonNewsEvent%20publish-8%20consume-8%20Discussions%20jms.thomson.reports%20PlatformAnnouncements%20economicEventTopic%20publish-59%20publish-321%20publish-457%20publish-227%20publish-1%20publish-296%20publish-200%20publish-429%20publish-10%20publish-373%20publish-872%20publish-160%20publish-135%20publish-416%20publish-598%20publish-3%20publish-48%20publish-247%20publish-214%20publish-313%20publish-427%20publish-21%20publish-418%20publish-195%20publish-33%20publish-507%20publish-228%20publish-1356%20publish-92%20publish-194%20publish-264%20publish-1384%20publish-162%20publish-119%20publish-35%20publish-58%20publish-417%20publish-419%20publish-325%20publish-86%20publish-276%20publish-185%20publish-80%20publish-204%20publish-275%20publish-38%20publish-47%20publish-234%20publish-105%20publish-508%20publish-1073%20publish-331%20publish-145%20publish-350%20publish-362%20publish-611%20publish-215%20publish-232%20publish-613%20publish-188%20publish-211%20publish-473%20publish-30%20publish-502%20publish-1088%20publish-565%20publish-236%20publish-170%20publish-346%20publish-231%20publish-361%20publish-193%20publish-168%20publish-240%20publish-229%20publish-312%20publish-37%20publish-212%20publish-394%20publish-123%20publish-609%20publish-79%20publish-399%20publish-2%20publish-253%20publish-316%20publish-237%20publish-15%20publish-332%20publish-39%20publish-326%20publish-300%20publish-73%20publish-72%20publish-448%20publish-420%20publish-307%20publish-266%20publish-265%20publish-52%20publish-217%20publish-343%20publish-256%20publish-510%20publish-561&LS_schema1=message&LS_unique=13 from 82.81.254.65:2401>
2009-08-10 10:39:51,084 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2401>
2009-08-10 10:39:51,084 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2401>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Serving multiple request: /lightstreamer/control.html?{9 subrequests} from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 1: LS_session=S4040fce00115c0a5T5129274&LS_window=12&LS_win_phase=5&LS_op=add&LS_req_phase=104&LS_mode1=MERGE&LS_id1=feed-1&LS_schema1=message&LS_unique=14 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 2: LS_session=S4040fce00115c0a5T5129274&LS_window=13&LS_win_phase=5&LS_op=add&LS_req_phase=105&LS_mode1=MERGE&LS_id1=feed-2&LS_schema1=message&LS_unique=15 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 3: LS_session=S4040fce00115c0a5T5129274&LS_window=14&LS_win_phase=5&LS_op=add&LS_req_phase=106&LS_mode1=MERGE&LS_id1=feed-3&LS_schema1=message&LS_unique=16 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 4: LS_session=S4040fce00115c0a5T5129274&LS_window=15&LS_win_phase=5&LS_op=add&LS_req_phase=107&LS_mode1=MERGE&LS_id1=feed-4&LS_schema1=message&LS_unique=17 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 5: LS_session=S4040fce00115c0a5T5129274&LS_window=16&LS_win_phase=5&LS_op=add&LS_req_phase=108&LS_mode1=MERGE&LS_id1=feed-6&LS_schema1=message&LS_unique=18 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 6: LS_session=S4040fce00115c0a5T5129274&LS_window=17&LS_win_phase=5&LS_op=add&LS_req_phase=109&LS_mode1=MERGE&LS_id1=feed-8&LS_schema1=message&LS_unique=19 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 7: LS_session=S4040fce00115c0a5T5129274&LS_window=18&LS_win_phase=5&LS_op=add&LS_req_phase=110&LS_mode1=MERGE&LS_id1=feed-9&LS_schema1=message&LS_unique=20 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 8: LS_session=S4040fce00115c0a5T5129274&LS_window=19&LS_win_phase=5&LS_op=add&LS_req_phase=111&LS_mode1=MERGE&LS_id1=feed-15&LS_schema1=message&LS_unique=21 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 9: LS_session=S4040fce00115c0a5T5129274&LS_window=20&LS_win_phase=5&LS_op=add&LS_req_phase=112&LS_mode1=MERGE&LS_id1=feed-16&LS_schema1=message&LS_unique=22 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>

Dario Crivelli

The outdated control requests for the first session occur a very short time after the session has been dismissed, hence they can just be late.
This would not be a problem, provided that the client were able to switch to the new session.
However, you say this is not the case.
Is there any way to replicate the problem and get more information on the javascript exception received?

What's strange in this log snippet is that the first session is replaced just after being successfully rebound. Normally, a session is replaced after it has not been available for several seconds.
Is it possible that all the logged requests have been delayed on the network for some time?
May you please attach a longer log snippet, with the whole story of session S4040fce00115c0a5T5129274?

Which version/build of the web client library are you using?

riwang

We are using Lightstreamer Moderato Server version 3.5 build 1422. I don't have a way to reproduce this issue either. It just happened intermittently. But I found hundreds of such <Sync error> log statements in the daily LS server log file.

Here are the relevant log entries related to the particular user.

2009-08-10 08:51:29,250 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/create_session.js?LS_phase=1702&LS_domain=currensee.com&LS_polling=true&LS_polling_millis=0&LS_idle_millis=30000&LS_client_version=4.3&LS_adapter=FOREXPERT&LS_user=8&LS_password=[...]& from 82.81.254.65:4605>
2009-08-10 08:51:29,274 INFO [LightstreamerLogger.requests] - <Starting new session: S4040fce00115c0a5T5129274 from 82.81.254.65:4605>
2009-08-10 08:51:29,942 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/control.html?LS_session=S4040fce00115c0a5T5129274&LS_window=1&LS_win_phase=4&LS_op=add&LS_req_phase=93&LS_mode1=MERGE&LS_id1=FXCMPriceUpdates%20thomsonNewsEvent%20publish-8%20consume-8%20Discussions%20jms.thomson.reports%20PlatformAnnouncements%20economicEventTopic%20publish-59%20publish-321%20publish-457%20publish-227%20publish-1%20publish-296%20publish-200%20publish-429%20publish-10%20publish-373%20publish-872%20publish-160%20publish-135%20publish-416%20publish-598%20publish-3%20publish-48%20publish-247%20publish-214%20publish-313%20publish-427%20publish-21%20publish-418%20publish-195%20publish-33%20publish-507%20publish-228%20publish-1356%20publish-92%20publish-194%20publish-264%20publish-1384%20publish-162%20publish-119%20publish-35%20publish-58%20publish-417%20publish-419%20publish-325%20publish-86%20publish-276%20publish-185%20publish-80%20publish-204%20publish-275%20publish-38%20publish-47%20publish-234%20publish-105%20publish-508%20publish-1073%20publish-331%20publish-145%20publish-350%20publish-362%20publish-611%20publish-215%20publish-232%20publish-613%20publish-188%20publish-211%20publish-473%20publish-30%20publish-502%20publish-1088%20publish-565%20publish-236%20publish-170%20publish-346%20publish-231%20publish-361%20publish-193%20publish-168%20publish-240%20publish-229%20publish-312%20publish-37%20publish-212%20publish-394%20publish-123%20publish-609%20publish-79%20publish-399%20publish-2%20publish-253%20publish-316%20publish-237%20publish-15%20publish-332%20publish-39%20publish-326%20publish-300%20publish-73%20publish-72%20publish-448%20publish-420%20publish-307%20publish-266%20publish-265%20publish-52%20publish-217%20publish-343%20publish-256%20publish-510%20publish-561&LS_schema1=message&LS_unique=1 from 82.81.254.65:4605>
2009-08-10 08:51:29,942 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4605>
2009-08-10 08:51:30,214 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1703&LS_domain=currensee.com& from 82.81.254.65:4609>
2009-08-10 08:51:30,214 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:4609>
2009-08-10 08:52:59,383 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1704&LS_domain=currensee.com& from 82.81.254.65:4715>
2009-08-10 08:52:59,383 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:4715>
2009-08-10 08:54:19,412 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/control.html?LS_session=S4040fce00115c0a5T5129274&LS_window=2&LS_win_phase=4&LS_op=add&LS_req_phase=94&LS_mode1=MERGE&LS_id1=feed-1&LS_schema1=message&LS_unique=2 from 82.81.254.65:4803>
2009-08-10 08:54:19,412 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Serving multiple request: /lightstreamer/control.html?{8 subrequests} from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Subrequest 1: LS_session=S4040fce00115c0a5T5129274&LS_window=3&LS_win_phase=4&LS_op=add&LS_req_phase=95&LS_mode1=MERGE&LS_id1=feed-2&LS_schema1=message&LS_unique=3 from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Subrequest 2: LS_session=S4040fce00115c0a5T5129274&LS_window=4&LS_win_phase=4&LS_op=add&LS_req_phase=96&LS_mode1=MERGE&LS_id1=feed-3&LS_schema1=message&LS_unique=4 from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Subrequest 3: LS_session=S4040fce00115c0a5T5129274&LS_window=5&LS_win_phase=4&LS_op=add&LS_req_phase=97&LS_mode1=MERGE&LS_id1=feed-4&LS_schema1=message&LS_unique=5 from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Subrequest 4: LS_session=S4040fce00115c0a5T5129274&LS_window=6&LS_win_phase=4&LS_op=add&LS_req_phase=98&LS_mode1=MERGE&LS_id1=feed-6&LS_schema1=message&LS_unique=6 from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Subrequest 5: LS_session=S4040fce00115c0a5T5129274&LS_window=7&LS_win_phase=4&LS_op=add&LS_req_phase=99&LS_mode1=MERGE&LS_id1=feed-8&LS_schema1=message&LS_unique=7 from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Subrequest 6: LS_session=S4040fce00115c0a5T5129274&LS_window=8&LS_win_phase=4&LS_op=add&LS_req_phase=100&LS_mode1=MERGE&LS_id1=feed-9&LS_schema1=message&LS_unique=8 from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Subrequest 7: LS_session=S4040fce00115c0a5T5129274&LS_window=9&LS_win_phase=4&LS_op=add&LS_req_phase=101&LS_mode1=MERGE&LS_id1=feed-15&LS_schema1=message&LS_unique=9 from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Subrequest 8: LS_session=S4040fce00115c0a5T5129274&LS_window=10&LS_win_phase=4&LS_op=add&LS_req_phase=102&LS_mode1=MERGE&LS_id1=feed-16&LS_schema1=message&LS_unique=10 from 82.81.254.65:4803>
2009-08-10 08:54:20,680 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:21,112 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:21,540 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:22,036 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:22,484 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:22,896 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:23,348 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:23,908 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:26,992 INFO [LightstreamerLogger.requests] - <Serving multiple request: /lightstreamer/control.html?{2 subrequests} from 82.81.254.65:4803>
2009-08-10 08:54:26,992 INFO [LightstreamerLogger.requests] - <Subrequest 1: LS_session=S4040fce00115c0a5T5129274&LS_window=9&LS_win_phase=4&LS_op=add&LS_req_phase=101&LS_mode1=MERGE&LS_id1=feed-15&LS_schema1=message&LS_unique=11 from 82.81.254.65:4803>
2009-08-10 08:54:26,992 INFO [LightstreamerLogger.requests] - <Subrequest 2: LS_session=S4040fce00115c0a5T5129274&LS_window=10&LS_win_phase=4&LS_op=add&LS_req_phase=102&LS_mode1=MERGE&LS_id1=feed-16&LS_schema1=message&LS_unique=12 from 82.81.254.65:4803>
2009-08-10 08:54:26,992 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:27,396 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:54:38,185 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1705&LS_domain=currensee.com& from 82.81.254.65:4803>
2009-08-10 08:54:38,185 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:4803>
2009-08-10 08:56:07,874 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1706&LS_domain=currensee.com& from 82.81.254.65:4875>
2009-08-10 08:56:07,874 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:4875>
2009-08-10 08:57:33,919 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1707&LS_domain=currensee.com& from 82.81.254.65:4942>
2009-08-10 08:57:33,919 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:4942>

[...] Skipped many repetition of STREAMING_IN_PROGRESS log entries

2009-08-10 10:33:30,707 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1770&LS_domain=currensee.com& from 82.81.254.65:2315>
2009-08-10 10:33:30,707 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:2315>
2009-08-10 10:35:06,508 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1771&LS_domain=currensee.com& from 82.81.254.65:2337>
2009-08-10 10:35:06,508 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:2337>
2009-08-10 10:36:43,742 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1772&LS_domain=currensee.com& from 82.81.254.65:2353>
2009-08-10 10:36:43,742 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:2353>
2009-08-10 10:38:16,423 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1773&LS_domain=currensee.com& from 82.81.254.65:2377>
2009-08-10 10:38:16,423 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:2377>
2009-08-10 10:39:50,264 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S4040fce00115c0a5T5129274&LS_phase=1774&LS_domain=currensee.com& from 82.81.254.65:2397>
2009-08-10 10:39:50,264 INFO [LightstreamerLogger.requests] - <Attaching session: S4040fce00115c0a5T5129274 from 82.81.254.65:2397>
2009-08-10 10:39:50,600 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/create_session.js?LS_phase=1775&LS_domain=currensee.com&LS_polling=true&LS_polling_millis=1109&LS_idle_millis=30000&LS_client_version=4.3&LS_adapter=FOREXPERT&LS_user=8&LS_password=[...]&LS_old_session=S4040fce00115c0a5T5129274& from 82.81.254.65:2399>
2009-08-10 10:39:50,716 INFO [LightstreamerLogger.requests] - <Starting new session: Sb50bef2560eac1cbT3950716 from 82.81.254.65:2399>
2009-08-10 10:39:51,084 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/control.html?LS_session=S4040fce00115c0a5T5129274&LS_window=11&LS_win_phase=5&LS_op=add&LS_req_phase=103&LS_mode1=MERGE&LS_id1=FXCMPriceUpdates%20thomsonNewsEvent%20publish-8%20consume-8%20Discussions%20jms.thomson.reports%20PlatformAnnouncements%20economicEventTopic%20publish-59%20publish-321%20publish-457%20publish-227%20publish-1%20publish-296%20publish-200%20publish-429%20publish-10%20publish-373%20publish-872%20publish-160%20publish-135%20publish-416%20publish-598%20publish-3%20publish-48%20publish-247%20publish-214%20publish-313%20publish-427%20publish-21%20publish-418%20publish-195%20publish-33%20publish-507%20publish-228%20publish-1356%20publish-92%20publish-194%20publish-264%20publish-1384%20publish-162%20publish-119%20publish-35%20publish-58%20publish-417%20publish-419%20publish-325%20publish-86%20publish-276%20publish-185%20publish-80%20publish-204%20publish-275%20publish-38%20publish-47%20publish-234%20publish-105%20publish-508%20publish-1073%20publish-331%20publish-145%20publish-350%20publish-362%20publish-611%20publish-215%20publish-232%20publish-613%20publish-188%20publish-211%20publish-473%20publish-30%20publish-502%20publish-1088%20publish-565%20publish-236%20publish-170%20publish-346%20publish-231%20publish-361%20publish-193%20publish-168%20publish-240%20publish-229%20publish-312%20publish-37%20publish-212%20publish-394%20publish-123%20publish-609%20publish-79%20publish-399%20publish-2%20publish-253%20publish-316%20publish-237%20publish-15%20publish-332%20publish-39%20publish-326%20publish-300%20publish-73%20publish-72%20publish-448%20publish-420%20publish-307%20publish-266%20publish-265%20publish-52%20publish-217%20publish-343%20publish-256%20publish-510%20publish-561&LS_schema1=message&LS_unique=13 from 82.81.254.65:2401>
2009-08-10 10:39:51,084 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2401>
2009-08-10 10:39:51,084 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2401>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Serving multiple request: /lightstreamer/control.html?{9 subrequests} from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 1: LS_session=S4040fce00115c0a5T5129274&LS_window=12&LS_win_phase=5&LS_op=add&LS_req_phase=104&LS_mode1=MERGE&LS_id1=feed-1&LS_schema1=message&LS_unique=14 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 2: LS_session=S4040fce00115c0a5T5129274&LS_window=13&LS_win_phase=5&LS_op=add&LS_req_phase=105&LS_mode1=MERGE&LS_id1=feed-2&LS_schema1=message&LS_unique=15 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 3: LS_session=S4040fce00115c0a5T5129274&LS_window=14&LS_win_phase=5&LS_op=add&LS_req_phase=106&LS_mode1=MERGE&LS_id1=feed-3&LS_schema1=message&LS_unique=16 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 4: LS_session=S4040fce00115c0a5T5129274&LS_window=15&LS_win_phase=5&LS_op=add&LS_req_phase=107&LS_mode1=MERGE&LS_id1=feed-4&LS_schema1=message&LS_unique=17 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 5: LS_session=S4040fce00115c0a5T5129274&LS_window=16&LS_win_phase=5&LS_op=add&LS_req_phase=108&LS_mode1=MERGE&LS_id1=feed-6&LS_schema1=message&LS_unique=18 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 6: LS_session=S4040fce00115c0a5T5129274&LS_window=17&LS_win_phase=5&LS_op=add&LS_req_phase=109&LS_mode1=MERGE&LS_id1=feed-8&LS_schema1=message&LS_unique=19 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 7: LS_session=S4040fce00115c0a5T5129274&LS_window=18&LS_win_phase=5&LS_op=add&LS_req_phase=110&LS_mode1=MERGE&LS_id1=feed-9&LS_schema1=message&LS_unique=20 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 8: LS_session=S4040fce00115c0a5T5129274&LS_window=19&LS_win_phase=5&LS_op=add&LS_req_phase=111&LS_mode1=MERGE&LS_id1=feed-15&LS_schema1=message&LS_unique=21 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Subrequest 9: LS_session=S4040fce00115c0a5T5129274&LS_window=20&LS_win_phase=5&LS_op=add&LS_req_phase=112&LS_mode1=MERGE&LS_id1=feed-16&LS_schema1=message&LS_unique=22 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,204 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Controlling session: S4040fce00115c0a5T5129274 from 82.81.254.65:2403>
2009-08-10 10:39:51,208 INFO [LightstreamerLogger.requests] - <Sync error (transient): Can't find session from 82.81.254.65:2403>

Dario Crivelli

The history of session S4040fce00115c0a5T5129274, until it is replaced by session Sb50bef2560eac1cbT3950716, is normal.
The high number of STREAMING_IN_PROGRESS requests may be due to a huge amount of pushed data against a short content-length setting in the Server configuration file (can you confirm?).

However, the replicated control request at 08:54:26,992 refers to subscriptions that were processed by the Server several seconds before;
this confirms that some delays occur in the client-server communication
(for instance, do you notice any CPU overload on the client side?).
If a similar delay had affected the rebind request at 10:39:50,264
this would explain the replacement of the session
(which is the setting for <session_timeout_millis> in the Server configuration file?).
Moreover, if a similar delay had affected the subsequent control requests,
this would explain the sync errors.

I'm afraid we need to identify the javascript error that occurred after the establishment of session Sb50bef2560eac1cbT3950716,
in order to understand what caused the new session not to start correctly.

riwang

The content length was changed from the default 300,000 to 1,000,000.

<content_length>
<default>1000000</default>
</content_length>

The session_timeout_millis was changed from the default 5000 to 60000.

<session_timeout_millis>60000</session_timeout_millis>

We do push a lot of data to the client. The client CPU load is often quite high, sometimes 80% of CPU usage.

Unfortunately, I don't have more info about the JS exception.

Dario Crivelli

Do you mean that the session_timeout_millis and the content-length had already been increased when the reported log was produced?

riwang

Yes. We changed the configuration about 6 months ago. The Sync Errors have been in the LS server logs always.

Dario Crivelli

About the content-length:
Continuously rebinding after about one and a half minute
may still be consistent with your setting.
It means 1 MB of update traffic within 90 seconds.

About the session_timeout_millis:
I was mistaken. If a rebind request is affected by a delay,
the first timeout involved is on the client side.
After a reconnection request has not provided an answer in 4 seconds,
the client gives up and retries with a new connection request,
which, however, would open a new session.

Hence, the unexpected replacement of the session
is still consistent with the assumption of a delay
in the client-server communication.
For instance, the brwser might have been overwhelmed by the updates
and might hava not been able to elaborate the Server answer in time.
And, as said, any trailing control request that was also delayed
would have experienced the "sync error".

The exception after the session replacement is the only event
that cannot be explained in terms of overload.
Let us know if the issue happens again.

pmthiagu

I am getting a similar case of 'Sync error: Can't find session from '

I am not able to identify if the client or server delay causes the session get closed and create new session.

From this thread, I understood that client server communication delay may cause this issue and can be solved by changing content-length and session_timeout_millis

I have tried both and getting same issue still. I am attaching server log with default configurations and config changes.

Please help me to identify the casue of the issue.

Thanks & Regards,
Krishna

Dario Crivelli

First of all, in the attached file you mention a value of 10 ms for <session_timeout_millis>, but I assume you mean 10 seconds.

Indeed, your client seems to be receiving a lot of data to be elaborated, about 300KB in 15 seconds at least.
This may cause the browser to be overwhelmed. May you please confirm that by direct observation of the client machine?
This would explain the "Sync error", as the page would issue the request of rebinding to the session long time after the previous connection has closed.

Note that you might increase the <session_timeout_millis> and the content-length, but that would just postpone the problem. In fact, in the third case (with the increased content-length), before the whole content-length has been consumed, the client opens a new session in polling mode. This is a recovery mechanism adopted by Lightstreamer web client library when it detects that the update processing is slower than the incoming update rate.

Just in case, the log shows that you have not configured a free license properly.
This causes the Server to work with some annoying limitations.

krishnamani

@DarioCrivelli, Wrote: First of all, in the attached file you mention a value of 10 ms for <session_timeout_millis>, but I assume you mean 10 seconds.

Yes it is 10 seconds. not 10 ms.

@DarioCrivelli, Wrote:
Indeed, your client seems to be receiving a lot of data to be elaborated, about 300KB in 15 seconds at least.
This may cause the browser to be overwhelmed. May you please confirm that by direct observation of the client machine?

This would explain the "Sync error", as the page would issue the request of rebinding to the session long time after the previous connection has closed.

Server is sending approximately 80 KB in first control request

and After adding tables to page, it is expected upto 170 KB of data to be pushed in second request.

In such case, If we use default 5 seconds session_timeout_millis and 300 KB of content-length will be ok?

@DarioCrivelli, Wrote:
Note that you might increase the <session_timeout_millis> and the content-length, but that would just postpone the problem. In fact, in the third case (with the increased content-length), before the whole content-length has been consumed, the client opens a new session in polling mode. This is a recovery mechanism adopted by Lightstreamer web client library when it detects that the update processing is slower than the incoming update rate.

Because as you said, increasing session_timeout_millis and the content-length just postpones the issue.

Please giude me to handle this situation.

Dario Crivelli

If you confirm that the client page is slow at elaborating the huge amount of data, then that is the main problem.
The bottleneck may not involve Lightstreamer library at all, depending on which kind of elaboration the page performs.

Does your page only display pushed data on the screen through one of the provided Visual Tables?
Is the big flow of pushed data limited to the snapshots or is it continuous?

As a first attempt, you may force POLLING mode from your client. In polling, the client asks the Server for new updates only after it has finished elaborating the updates already received, thus forcing more filtering on the server side.
However, this is only beneficial if filtering is allowed by your subscriptions (i.e. RAW mode or the "unfiltered" flag are not used by the client).

krishnamani

Actually I am trying to use NotifySessionClose event to logoff the user in LS. But due to above problem, the user getting logged on and off continuously.

To solve this, I need your guidance to find proper place where and how I can identify Browser close.

Or I have to solve this session getting closed continuously when server push this data subscribed by user.

@DarioCrivelli, Wrote: If you confirm that the client page is slow at elaborating the huge amount of data, then that is the main problem.
The bottleneck may not involve Lightstreamer library at all, depending on which kind of elaboration the page performs.

Does your page only display pushed data on the screen through one of the provided Visual Tables?
Is the big flow of pushed data limited to the snapshots or is it continuous?

My client page has single push engine which has 2 Non-Visual tables to get subscriptions. Subscriptions are sent and received with DISTINCT mode. In each subscription maximum of 10KB of data is transferred.

We cant say big flow of data. Max 10 KB of data pushed continuously. Not using shapshots.

But anyway status changed to Polling when we start subscription by default.
Do you mean we have to use POLLING mode during engine creation?

Thanks & Regards,
Krishna

krishnamani

Thanks DarioCrivelli.

Creating lsengine with POLLING mode solved the issue of session close and create new session and Sync Error.

But Can you confirm me if this is right place to handle Browser Close event at NotifySessionClose?

Dario Crivelli

The browser can close abruptly and LS does not try to trace the event.

When a browser closes, the Server eventually notices that the client has disappeared and closes the session by timeout. This may happen quite a long time after the browser close (in the next release of LS, more effort will be spent in order to close the session as soon as possible after a browser close).

Nevertheless, the notifySessionClose is the only place where the event can be hooked.
As you have experienced, a session can be closed also for other reasons and in some cases a new session has just replaced it, so you cannot directly relate session close and browser close.

As, according to your log, a content-length of 300 KB was consumed in less than 15 seconds, the load on the client may be higher than you think.
Note that if there were any bottleneck that you could remove, regarding the data elaboration on the page, then you could restore streaming mode.

krishnamani

Hi DarioCrivelli,

I have created a page with lsengine and 2 non-visual push tables.

When user login successfully, about 900KB of data pushed to first push table in single subscription. Then 10 to 120 of market watch details of 10 KB each are subscribed through second non-visual table. Market watch details are pushed one by one each of 10 KB when received by the server (Not altogether).

Streaming mode works fine when only 10 market watch details are subscribed. For more than that, I was getting Sync error as mentioned in above posts.

Polling mode works when it subscribes more, but still, it also doesn't work for 120 market watch details subscription.

Hope it ends up with bottleneck at client. If this can be handled by changing content-length? Is there any other way to handle this case in such way to remove the bottleneck at client?

Dario Crivelli

The content-length setting should play no role in your streaming issue.

In polling, the content-length may limit the size of the response to a poll. This doesn't happen in a normal case, but if you handle such big data, this limitation may come into play.
This may cause the Server to need more or less polls to dequeue the snapshots.
Yours is an uncommon case and, honestly, I can't guess whether limiting the size of a polling response could be beneficial.
Anyway, if a single event were responsible for the 900KB of snapshot data caused by your first subscription, they would be sent in a single poll, regardless of the content-length configuration.

What does it happen with 120 market watch detail subscriptions in long polling?
Do you still notice "sync error" messages? Or is it just too slow to be acceptable?

With 120 market watch detail subscriptions, the processing of the updates in your custom code may be heavy; I suppose that the client CPU usage is at 100%.
However, Lightstreamer library itself may need a lot of processing time. Please try removing all your callbacks from the NonVisualTables and see if the client CPU usage is still at 100%.

krishnamani

@DarioCrivelli, Wrote:
What does it happen with 120 market watch detail subscriptions in long polling?
Do you still notice "sync error" messages? Or is it just too slow to be acceptable?

By Long Polling do you mean increased Polling interval (max_polling_millis)?
If yes, I have tried increasing max_polling_millis, even with 60 seconds, I am getting same Sync Error when market watch details are pushed.

@DarioCrivelli, Wrote:
With 120 market watch detail subscriptions, the processing of the updates in your custom code may be heavy; I suppose that the client CPU usage is at 100%.
However, Lightstreamer library itself may need a lot of processing time. Please try removing all your callbacks from the NonVisualTables and see if the client CPU usage is still at 100%.

Even with 120 market watch details, it takes maximum of 50% of CPU. It takes 0 to 2% normally, and 50% while processing and showing it.

Dario Crivelli

I wrote "Long Polling" as another name for the "Asynchronous Polling", which, in an Ajax context, can be named as just "Polling".
So, I just referred to your previous post, in which you had reported the behavior of the polling case.
In polling mode, we expect that the browser, if overwhelmed by the processing of the outcome of a poll request, delays the next poll request (but we have no control on what the browser actually chooses to delay).
This would avoid that the updates queue up on the client: they would try to queue up on the Server, which, however, can conflate them.

If the next request is delayed too long, the Server will have discarded the Session and will get a "sync error".
The client tries heuristically to measure its own processing delay and may request the Server to delay the Session discarding. Your setting of <max_polling_millis> is correct, because it avoids that the Server refuses to obey a client delay request which is too long.
However, the client heuristic may be underestimating the delay.

May we check your Server log taken during a polling run with 120 market watch details?
You should set the priority of the LightstreamerLogger.requests.polling logger to INFO.

If you see the CPU usage steadily at 50%, it may be that only half of the available processors can be used by the browser; hence, this would still represent a bottleneck.
You could still try removing all your callbacks from the NonVisualTables and see if the client CPU usage is still at 50%.

krishnamani

@DarioCrivelli, Wrote: I wrote "Long Polling" as another name for the "Asynchronous Polling", which, in an Ajax context, can be named as just "Polling".
So, I just referred to your previous post, in which you had reported the behavior of the polling case.
In polling mode, we expect that the browser, if overwhelmed by the processing of the outcome of a poll request, delays the next poll request (but we have no control on what the browser actually chooses to delay).
This would avoid that the updates queue up on the client: they would try to queue up on the Server, which, however, can conflate them.

We are ok even if the updates are queued up in client and process it in sequence, but we need to handle the browser close event.

How is to be coded at both client and LS side to handle the delay at client side?

@DarioCrivelli, Wrote:
If the next request is delayed too long, the Server will have discarded the Session and will get a "sync error".
The client tries heuristically to measure its own processing delay and may request the Server to delay the Session discarding. Your setting of <max_polling_millis> is correct, because it avoids that the Server refuses to obey a client delay request which is too long.
However, the client heuristic may be underestimating the delay.

May we check your Server log taken during a polling run with 120 market watch details?
You should set the priority of the LightstreamerLogger.requests.polling logger to INFO.

I will be sending you the Server log files as early as possible.

@DarioCrivelli, Wrote:
If you see the CPU usage steadily at 50%, it may be that only half of the available processors can be used by the browser; hence, this would still represent a bottleneck.
You could still try removing all your callbacks from the NonVisualTables and see if the client CPU usage is still at 50%.

We are using Firefox for testing purpose. But it allows more than 50% for Firefox and it goes 52% or 56% for this case but in an average of 50%.

Can you please let me know what you mean by callbacks and how to clear it at client side?