Hundreds of connections from single user

colmfield

Hi,

I have a web front-end using Lightstreamer Vivace, connecting to a .Net MetaDataAdapter and DataAdapter running as a Windows service. I am using the RobustNetworkedMetadataProvider.

In my MetadataAdapter I log the fact a user has logged on in the notifyUser method in the database.

For some users (about 5 out of 200), I see that their access has been logged up to 1000 times a day, compared to other users being about 10-15. Any idea what could be causing this? The users themselves report no issues with the data delivery, and I see no errors in the LS logs (with these users).

Cheers,
Colm

Dario Crivelli

Please try to follow the activity of one of such users in the Server log and identify a sequence of "create_session" requests.
If possible, show us a snippet of the original log including such a sequence (of, let's say, 10 requests).

colmfield

Hi Dario,

From yesterday's log:

20-Sep-10 07:48:18,866 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 2     |Serving request: /lightstreamer/create_session.js --> LS_phase=4802&LS_domain=xxx.com&LS_polling=true&LS_polling_millis=0&LS_idle_millis=0&LS_client_version=4.4&LS_adapter_set=PROXY_FIXADAPTER&LS_user=XXX%7C1060311%7C1546239&LS_password=[...]& from XXX.XXX.XXX.XXX:47995
20-Sep-10 07:48:19,101 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 10    |Starting new session: Sfabc90480438aab8T4819101 from XXX.XXX.XXX.XXX:47995
20-Sep-10 07:48:19,257 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 8     |Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=Sfabc90480438aab8T4819101&LS_phase=4803&LS_domain=xxx.com& from XXX.XXX.XXX.XXX:47995
20-Sep-10 07:48:19,257 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 8     |Attaching session: Sfabc90480438aab8T4819101 from XXX.XXX.XXX.XXX:47995
20-Sep-10 07:48:19,913 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 1     |Serving request: /lightstreamer/control.js --> LS_session=Sfabc90480438aab8T4819101&LS_table=0&LS_win_phase=104&LS_op=add&LS_req_phase=886&LS_mode=MERGE&LS_id=X1%20X2%20X3%20X4%20X5&LS_schema=price%20quantity&LS_data_adapter=PRICES_ADAPTER&LS_snapshot=true&LS_unique=1& from XXX.XXX.XXX.XXX:48001
20-Sep-10 07:48:19,913 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 2     |Controlling session: Sfabc90480438aab8T4819101 from XXX.XXX.XXX.XXX:48001
20-Sep-10 07:48:20,054 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 3     |Serving request: /lightstreamer/control.js --> LS_session=Sfabc90480438aab8T4819101&LS_table=1&LS_win_phase=104&LS_op=add&LS_req_phase=887&LS_mode=MERGE&LS_id=Control&LS_schema=item%20message&LS_data_adapter=PRICES_ADAPTER&LS_unique=2& from XXX.XXX.XXX.XXX:48001
20-Sep-10 07:48:20,054 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 4     |Controlling session: Sfabc90480438aab8T4819101 from XXX.XXX.XXX.XXX:48001
20-Sep-10 08:33:40,536 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 7     |Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=Sfabc90480438aab8T4819101&LS_phase=4804&LS_domain=xxx.com& from XXX.XXX.XXX.XXX:48185
20-Sep-10 08:33:40,536 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 7     |Attaching session: Sfabc90480438aab8T4819101 from XXX.XXX.XXX.XXX:48185
20-Sep-10 08:33:44,021 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 1     |Serving request: /lightstreamer/create_session.js --> LS_phase=4805&LS_domain=xxx.com&LS_polling=true&LS_polling_millis=0&LS_idle_millis=0&LS_client_version=4.4&LS_adapter_set=PROXY_FIXADAPTER&LS_user=XXX%7C1060311%7C1546239&LS_password=[...]&LS_old_session=Sfabc90480438aab8T4819101& from XXX.XXX.XXX.XXX:48188
20-Sep-10 08:33:44,271 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 8     |Starting new session: S79e0ab93c467ea19T3344271 from XXX.XXX.XXX.XXX:48188
20-Sep-10 08:33:44,521 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 8     |Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S79e0ab93c467ea19T3344271&LS_phase=4806&LS_domain=xxx.com& from XXX.XXX.XXX.XXX:48188
20-Sep-10 08:33:44,521 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 8     |Attaching session: S79e0ab93c467ea19T3344271 from XXX.XXX.XXX.XXX:48188
20-Sep-10 08:33:56,896 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 3     |Serving request: /lightstreamer/create_session.js --> LS_phase=4807&LS_domain=xxx.com&LS_polling=true&LS_polling_millis=0&LS_idle_millis=0&LS_client_version=4.4&LS_adapter_set=PROXY_FIXADAPTER&LS_user=XXX%7C1060311%7C1546239&LS_password=[...]&LS_old_session=S79e0ab93c467ea19T3344271& from XXX.XXX.XXX.XXX:48192
20-Sep-10 08:33:57,115 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 6     |Starting new session: S914dac92125c69f8T3357115 from XXX.XXX.XXX.XXX:48192
20-Sep-10 08:33:57,271 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 4     |Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S914dac92125c69f8T3357115&LS_phase=4808&LS_domain=xxx.com& from XXX.XXX.XXX.XXX:48192
20-Sep-10 08:33:57,271 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 4     |Attaching session: S914dac92125c69f8T3357115 from XXX.XXX.XXX.XXX:48192
20-Sep-10 08:34:17,615 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 3     |Serving request: /lightstreamer/create_session.js --> LS_phase=4809&LS_domain=xxx.com&LS_polling=true&LS_polling_millis=0&LS_idle_millis=0&LS_client_version=4.4&LS_adapter_set=PROXY_FIXADAPTER&LS_user=XXX%7C1060311%7C1546239&LS_password=[...]&LS_old_session=S914dac92125c69f8T3357115& from XXX.XXX.XXX.XXX:48203
20-Sep-10 08:34:17,850 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 8     |Starting new session: Seda8cc6f1b6e2879T3417850 from XXX.XXX.XXX.XXX:48203
20-Sep-10 08:34:18,084 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 6     |Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=Seda8cc6f1b6e2879T3417850&LS_phase=4810&LS_domain=xxx.com& from XXX.XXX.XXX.XXX:48203
20-Sep-10 08:34:18,084 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 6     |Attaching session: Seda8cc6f1b6e2879T3417850 from XXX.XXX.XXX.XXX:48203
20-Sep-10 08:34:46,491 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 5     |Serving request: /lightstreamer/create_session.js --> LS_phase=4811&LS_domain=xxx.com&LS_polling=true&LS_polling_millis=0&LS_idle_millis=0&LS_client_version=4.4&LS_adapter_set=PROXY_FIXADAPTER&LS_user=XXX%7C1060311%7C1546239&LS_password=[...]&LS_old_session=Seda8cc6f1b6e2879T3417850& from XXX.XXX.XXX.XXX:48208
20-Sep-10 08:34:46,726 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 10    |Starting new session: S1eb9e55ef72c27a3T3446726 from XXX.XXX.XXX.XXX:48208
20-Sep-10 08:34:46,882 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 5     |Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S1eb9e55ef72c27a3T3446726&LS_phase=4812&LS_domain=xxx.com& from XXX.XXX.XXX.XXX:48208
20-Sep-10 08:34:46,882 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 5     |Attaching session: S1eb9e55ef72c27a3T3446726 from XXX.XXX.XXX.XXX:48208
20-Sep-10 08:35:17,164 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 5     |Serving request: /lightstreamer/create_session.js --> LS_phase=4813&LS_domain=xxx.com&LS_polling=true&LS_polling_millis=0&LS_idle_millis=0&LS_client_version=4.4&LS_adapter_set=PROXY_FIXADAPTER&LS_user=XXX%7C1060311%7C1546239&LS_password=[...]&LS_old_session=S1eb9e55ef72c27a3T3446726& from XXX.XXX.XXX.XXX:48211
20-Sep-10 08:35:17,399 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 7     |Starting new session: Se987c80313e52877T3517399 from XXX.XXX.XXX.XXX:48211
20-Sep-10 08:35:17,555 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 8     |Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=Se987c80313e52877T3517399&LS_phase=4814&LS_domain=xxx.com& from XXX.XXX.XXX.XXX:48211
20-Sep-10 08:35:17,555 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 8     |Attaching session: Se987c80313e52877T3517399 from XXX.XXX.XXX.XXX:48211
20-Sep-10 08:35:47,853 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 7     |Serving request: /lightstreamer/create_session.js --> LS_phase=4815&LS_domain=xxx.com&LS_polling=true&LS_polling_millis=0&LS_idle_millis=0&LS_client_version=4.4&LS_adapter_set=PROXY_FIXADAPTER&LS_user=XXX%7C1060311%7C1546239&LS_password=[...]&LS_old_session=Se987c80313e52877T3517399& from XXX.XXX.XXX.XXX:48214
20-Sep-10 08:35:48,056 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 9     |Starting new session: S308e92637b559c81T3548056 from XXX.XXX.XXX.XXX:48214
20-Sep-10 08:35:48,275 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 7     |Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S308e92637b559c81T3548056&LS_phase=4816&LS_domain=xxx.com& from XXX.XXX.XXX.XXX:48214
20-Sep-10 08:35:48,275 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 7     |Attaching session: S308e92637b559c81T3548056 from XXX.XXX.XXX.XXX:48214
20-Sep-10 08:36:18,541 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 4     |Serving request: /lightstreamer/create_session.js --> LS_phase=4817&LS_domain=xxx.com&LS_polling=true&LS_polling_millis=0&LS_idle_millis=0&LS_client_version=4.4&LS_adapter_set=PROXY_FIXADAPTER&LS_user=XXX%7C1060311%7C1546239&LS_password=[...]&LS_old_session=S308e92637b559c81T3548056& from XXX.XXX.XXX.XXX:48217
20-Sep-10 08:36:18,760 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 3     |Starting new session: S765c8a2cde84d2caT3618760 from XXX.XXX.XXX.XXX:48217
20-Sep-10 08:36:18,916 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 10    |Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S765c8a2cde84d2caT3618760&LS_phase=4818&LS_domain=xxx.com& from XXX.XXX.XXX.XXX:48217
20-Sep-10 08:36:18,916 |INFO |LightstreamerLogger.requests     |SERVER POOLED THREAD 10    |Attaching session: S765c8a2cde84d2caT3618760 from XXX.XXX.XXX.XXX:48217

Colm

Dario Crivelli

Unfortunately, we have never noticed a similar pattern.

1) The first session has a normal life until the content length expires. Then, the rebind seems to be unsuccessful: the answer might be either delayed or blocked.
Could you see any "sync error" around 8:33:40/44?
Did you report the original log (which means that only activity from this client happened between 7:48 and 8:35) or did you filter the log by IP?

2) After the first failed rebind, it seems that all subsequent streaming connection attempts fail.
As a consequence, no subscription requests are issued for the new sessions, hence no data can reach the client in this phase.
You say that the clients reported no issue, but do you have any evidence that the clients also get data?
Again, did you report the original log or could there be other messages in the middle?
By the way, do you configure any specific timeout on your LightstreamerEngine.Policy instance?

colmfield

@DarioCrivelli, Wrote: The first session has a normal life until the content length expires. Then, the rebind seems to be unsuccessful: the answer might be either delayed or blocked.
Could you see any "sync error" around 8:33:40/44?
Did you report the original log (which means that only activity from this client happened between 7:48 and 8:35) or did you filter the log by IP?

I didn't report the full log, but there are no sync errors around those times. There are hundreds of lines between 07:48 and 08:33, so I won't include them here unless you want them. There are sync errors for other users in that time, and immediately before the 08:33:40,536 there is an "SSL read error", but I understand these shouldn't be logged as errors at all.

2) After the first failed rebind, it seems that all subsequent streaming connection attempts fail.
As a consequence, no subscription requests are issued for the new sessions, hence no data can reach the client in this phase.
You say that the clients reported no issue, but do you have any evidence that the clients also get data?

It happens to ca.10 users, some of whom are based in my office, and I've looked at their PCs whilst it is happening and can see the data coming through ok. I haven't obviously checked with all users but am confident they would complain if it wasn't working for them - especially considering the fact they're logged on for such a long period,

By the way, do you configure any specific timeout on your LightstreamerEngine.Policy instance?

Nope, just using the default timeout here.

Dario Crivelli

There must be some key information missing.
Session Sfabc90480438aab8T4819101 is the only one for which subscriptions are requested and it is supposed to terminate at 8:33:44:021, when it is declared as "old" upon opening of session S79e0ab93c467ea19T3344271.
After that time, no data can flow to the client.

Fortunately, you can manage to replicate the issue.
Would it be possible for you to use a slightly modified version of your client page only on one client host in your office (in which the issue can be reproduced)?
This would allow you to collect client side log (we would give you instructions).

Are you using a single Server instance or a cluster?

Just in case any interesting log message were hidden in hundred lines, may you please send us the full log between 8:33:40 and 8:34:20?
You could send it to support@lightstreamer.com