Multiple control.html requests

[riwang]

Hi,

When a user opens my web page that contains the LS javascript client, my web app establishes a LS connection for streaming.

In firebug, I saw multiple requests, sometimes 3 or more, were sent to fetch control.html during the connection time. I found log entries in the LS server log file to confirm that multiple requests were retrieved for control.html.

Can anyone please explain why this is happening? Is it behavior expected?

Thanks,
Richard

[DarioCrivelli]

The requests for control.html are used to issue subscription requests.
You can find multiple requests in a few seconds, but the arguments should be different.
You could see multiple requests with the same arguments in case something is slowing down the network or Server processing; in this case, the client may reissue requests for which it hasn't received any answer.

The web client library tries to collect multiple subscription requests
that are issued by the pages nearly at the same time,
into a single control.html request.
Hence, subsequent control.html requests should be separated by a short time interval.

[riwang]

In the following case, there were two control.html requests. The only difference between them was LS_unique: the first control.html has LS_unique=1, while the second has LS_unique=5. Sometimes I saw 5 control.html requests when establishing a LS session. Do you see anything unusual?

Thanks,
Richard

2009-08-12 09:58:50,705 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/create_session.js?LS_phase=6802&LS_domain=currense e.com&LS_polling=true&LS_polling_millis=0&LS_idle_ millis=30000&LS_client_version=4.3&LS_adapter=FORE XPERT&LS_user=1&LS_password=[...]& from 192.168.10.144:54660>
2009-08-12 09:58:50,753 INFO [LightstreamerLogger.requests] - <Starting new session: S3a724a0d57b379cT5850749 from 192.168.10.144:54660>
2009-08-12 09:58:50,906 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/control.html?LS_session=S3a724a0d57b379cT5850749&L S_window=4&LS_win_phase=4&LS_op=add&LS_req_phase=7 8&LS_mode1=MERGE&LS_id1=FXCMPriceUpdates%20thomson NewsEvent%20publish-1%20consume-1%20Discussions%20jms.thomson.reports%20PlatformAn nouncements%20economicEventTopic%20publish-10%20publish-105%20publish-110%20publish-111%20publish-112%20publish-113%20publish-119%20publish-123%20publish-127%20publish-13%20publish-130%20publish-135%20publish-14%20publish-140%20publish-145%20publish-149%20publish-15%20publish-158%20publish-160%20publish-162%20publish-167%20publish-168%20publish-170%20publish-176%20publish-179%20publish-18%20publish-182%20publish-185%20publish-188%20publish-193%20publish-195%20publish-197%20publish-2%20publish-203%20publish-206%20publish-21%20publish-214%20publish-215%20publish-217%20publish-22%20publish-221%20publish-228%20publish-229%20publish-231%20publish-232%20publish-234%20publish-236%20publish-246%20publish-249%20publish-25%20publish-252%20publish-253%20publish-254%20publish-256%20publish-258%20publish-263%20publish-264%20publish-265%20publish-269%20publish-270%20publish-275%20publish-28%20publish-296%20publish-3%20publish-30%20publish-300%20publish-307%20publish-309%20publish-312%20publish-313%20publish-316%20publish-317%20publish-318%20publish-319%20publish-321%20publish-322%20publish-324%20publish-325%20publish-326%20publish-327%20publish-33%20publish-331%20publish-333%20publish-340%20publish-343%20publish-346%20publish-35%20publish-355%20publish-358%20publish-361%20publish-362%20publish-37%20publish-38%20publish-39%20publish-394%20publish-399%20publish-4%20publish-41%20publish-416%20publish-417%20publish-418%20publish-419%20publish-427%20publish-428%20publish-429%20publish-43%20publish-44%20publish-448%20publish-45%20publish-457%20publish-46%20publish-47%20publish-48%20publish-49%20publish-507%20publish-52%20publish-53%20publish-539%20publish-543%20publish-551%20publish-564%20publish-565%20publish-569%20publish-57%20publish-573%20publish-58%20publish-582%20publish-586%20publish-59%20publish-604%20publish-611%20publish-613%20publish-628%20publish-636%20publish-65%20publish-67%20publish-68%20publish-69%20publish-696%20publish-7%20publish-712%20publish-72%20publish-73%20publish-74%20publish-741%20publish-79%20publish-8%20publish-80%20publish-82%20publish-84%20publish-85%20publish-86%20publish-87%20publish-90%20publish-92%20publish-98&LS_schema1=message&LS_unique=1 from 192.168.10.144:54660>
2009-08-12 09:58:50,906 INFO [LightstreamerLogger.requests] - <Controlling session: S3a724a0d57b379cT5850749 from 192.168.10.144:54660>
2009-08-12 09:58:50,957 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S3a724a0d57b379cT 5850749&LS_phase=6803&LS_domain=currensee.com& from 192.168.10.144:54663>
2009-08-12 09:58:51,021 INFO [LightstreamerLogger.requests] - <Attaching session: S3a724a0d57b379cT5850749 from 192.168.10.144:54663>
2009-08-12 09:58:51,190 INFO [LightstreamerLogger.requests] - <Serving multiple request: /lightstreamer/control.html?{3 subrequests} from 192.168.10.144:54665>
2009-08-12 09:58:51,191 INFO [LightstreamerLogger.requests] - <Subrequest 1: LS_session=S3a724a0d57b379cT5850749&LS_window=5&LS _win_phase=4&LS_op=add&LS_req_phase=79&LS_mode1=ME RGE&LS_id1=feed-1&LS_schema1=message&LS_unique=2 from 192.168.10.144:54665>
2009-08-12 09:58:51,192 INFO [LightstreamerLogger.requests] - <Subrequest 2: LS_session=S3a724a0d57b379cT5850749&LS_window=6&LS _win_phase=4&LS_op=add&LS_req_phase=80&LS_mode1=ME RGE&LS_id1=feed-3&LS_schema1=message&LS_unique=3 from 192.168.10.144:54665>
2009-08-12 09:58:51,192 INFO [LightstreamerLogger.requests] - <Subrequest 3: LS_session=S3a724a0d57b379cT5850749&LS_window=7&LS _win_phase=4&LS_op=add&LS_req_phase=81&LS_mode1=ME RGE&LS_id1=feed-16&LS_schema1=message&LS_unique=4 from 192.168.10.144:54665>
2009-08-12 09:58:51,193 INFO [LightstreamerLogger.requests] - <Controlling session: S3a724a0d57b379cT5850749 from 192.168.10.144:54665>
2009-08-12 09:58:54,301 INFO [LightstreamerLogger.requests] - <Serving multiple request: /lightstreamer/control.html?{3 subrequests} from 192.168.10.144:54668>
2009-08-12 09:58:54,302 INFO [LightstreamerLogger.requests] - <Subrequest 1: LS_session=S3a724a0d57b379cT5850749&LS_window=5&LS _win_phase=4&LS_op=add&LS_req_phase=79&LS_mode1=ME RGE&LS_id1=feed-1&LS_schema1=message&LS_unique=6 from 192.168.10.144:54668>
2009-08-12 09:58:54,303 INFO [LightstreamerLogger.requests] - <Subrequest 2: LS_session=S3a724a0d57b379cT5850749&LS_window=6&LS _win_phase=4&LS_op=add&LS_req_phase=80&LS_mode1=ME RGE&LS_id1=feed-3&LS_schema1=message&LS_unique=7 from 192.168.10.144:54668>
2009-08-12 09:58:54,303 INFO [LightstreamerLogger.requests] - <Subrequest 3: LS_session=S3a724a0d57b379cT5850749&LS_window=7&LS _win_phase=4&LS_op=add&LS_req_phase=81&LS_mode1=ME RGE&LS_id1=feed-16&LS_schema1=message&LS_unique=8 from 192.168.10.144:54668>
2009-08-12 09:58:54,304 INFO [LightstreamerLogger.requests] - <Controlling session: S3a724a0d57b379cT5850749 from 192.168.10.144:54668>
2009-08-12 09:58:59,603 INFO [com.currensee.platform.commons.stats.StatisticsLog ger] - <wrote 2 statistics to output file>
2009-08-12 09:59:06,167 INFO [LightstreamerLogger.requests] - <Controlling session: S3a724a0d57b379cT5850749 from 192.168.10.144:54665>
2009-08-12 09:59:06,259 INFO [LightstreamerLogger.requests] - <Serving request: /lightstreamer/control.html?LS_session=S3a724a0d57b379cT5850749&L S_window=4&LS_win_phase=4&LS_op=add&LS_req_phase=7 8&LS_mode1=MERGE&LS_id1=FXCMPriceUpdates%20thomson NewsEvent%20publish-1%20consume-1%20Discussions%20jms.thomson.reports%20PlatformAn nouncements%20economicEventTopic%20publish-10%20publish-105%20publish-110%20publish-111%20publish-112%20publish-113%20publish-119%20publish-123%20publish-127%20publish-13%20publish-130%20publish-135%20publish-14%20publish-140%20publish-145%20publish-149%20publish-15%20publish-158%20publish-160%20publish-162%20publish-167%20publish-168%20publish-170%20publish-176%20publish-179%20publish-18%20publish-182%20publish-185%20publish-188%20publish-193%20publish-195%20publish-197%20publish-2%20publish-203%20publish-206%20publish-21%20publish-214%20publish-215%20publish-217%20publish-22%20publish-221%20publish-228%20publish-229%20publish-231%20publish-232%20publish-234%20publish-236%20publish-246%20publish-249%20publish-25%20publish-252%20publish-253%20publish-254%20publish-256%20publish-258%20publish-263%20publish-264%20publish-265%20publish-269%20publish-270%20publish-275%20publish-28%20publish-296%20publish-3%20publish-30%20publish-300%20publish-307%20publish-309%20publish-312%20publish-313%20publish-316%20publish-317%20publish-318%20publish-319%20publish-321%20publish-322%20publish-324%20publish-325%20publish-326%20publish-327%20publish-33%20publish-331%20publish-333%20publish-340%20publish-343%20publish-346%20publish-35%20publish-355%20publish-358%20publish-361%20publish-362%20publish-37%20publish-38%20publish-39%20publish-394%20publish-399%20publish-4%20publish-41%20publish-416%20publish-417%20publish-418%20publish-419%20publish-427%20publish-428%20publish-429%20publish-43%20publish-44%20publish-448%20publish-45%20publish-457%20publish-46%20publish-47%20publish-48%20publish-49%20publish-507%20publish-52%20publish-53%20publish-539%20publish-543%20publish-551%20publish-564%20publish-565%20publish-569%20publish-57%20publish-573%20publish-58%20publish-582%20publish-586%20publish-59%20publish-604%20publish-611%20publish-613%20publish-628%20publish-636%20publish-65%20publish-67%20publish-68%20publish-69%20publish-696%20publish-7%20publish-712%20publish-72%20publish-73%20publish-74%20publish-741%20publish-79%20publish-8%20publish-80%20publish-82%20publish-84%20publish-85%20publish-86%20publish-87%20publish-90%20publish-92%20publish-98&LS_schema1=message&LS_unique=5 from 192.168.10.144:54660>
2009-08-12 09:59:06,279 INFO [LightstreamerLogger.requests] - <Controlling session: S3a724a0d57b379cT5850749 from 192.168.10.144:54660>
2009-08-12 09:59:08,185 INFO [LightstreamerLogger.requests] - <Controlling session: S3a724a0d57b379cT5850749 from 192.168.10.144:54665>
2009-08-12 09:59:08,219 INFO [LightstreamerLogger.requests] - <Controlling session: S3a724a0d57b379cT5850749 from 192.168.10.144:54668>
2009-08-12 09:59:09,162 INFO [LightstreamerLogger.requests] - <Controlling session: S3a724a0d57b379cT5850749 from 192.168.10.144:54668>

[DarioCrivelli]

Something is slowing down the accomplishment of subscription requests.
This is put into evidence by the compound requests:
After the log of:

<Subrequest 1: ....
<Subrequest 2: ....
<Subrequest 3: ....

in a normal case, you should see

<Controlling session: ....
<Controlling session: ....
<Controlling session: ....

in rapid sequence.
However, in your case, after the first occurrence, there is a significant time gap.
Such delays may cause the client to reissue some subscription requests
(just in case they got lost) until it eventually gets an answer.

The observed delays must have been introduced by some calls to the Metadata Adapter or in the "subscribe" calls to the Data Adapter.
In the forthcoming (3.6) release, the Server will be more robust to delays in Adapter calls;
for now, you should ensure that most of them don't introduce delays,
by following the guidelines suggested in the Adapter javadocs.