Client only in polling mode

EWANG

for client version Lightstreamer Silverlight Client Library version 1.1.3537.25900 user only can poll instead of stream. There is no proxy involved, here is the log entry

15.Apr.10 13:05:40,563 < INFO> Serving request: /lightstreamer/create_session.tx
t?LS_user=3931be67-a465-46c9-ae19-c25d7460ab16&LS_adapter_set=SAdapter&LS_con
tent_length=50000000&LS_polling=true&LS_polling_millis=0&LS_idle_millis=30000&LS
_report_info=true from 10.35.185.113:41159
15.Apr.10 13:05:40,565 < INFO> Starting new session: S78c524cd6a396481T0540564 from 10.35.185.113:41159
15.Apr.10 13:05:40,739 < INFO> Serving request: /lightstreamer/control.txt?LS_session=S78c524cd6a396481T0540564&LS_op=add&LS_table=1&LS_id=S_ADAPTER&LS_mode=RAW&LS_schema=MESSAGEID+DATA+MESSAGE_TS&LS_data_adapter=S_ADAPTER from 10.35.185.113:41159
15.Apr.10 13:05:40,739 < INFO> Controlling session: S78c524cd6a396481T0540564 fr
om 10.35.185.113:41159
15.Apr.10 13:06:10,898 < INFO> Polling (2) to session: S78c524cd6a396481T0540564
from 10.35.185.113:41159

Thanks.

Dario Crivelli

Indeed, the log reports a normal long polling session.

In a normal case, this happens when the isPolling attribute of ConnectionInfo is set as true. Please check that on the source code first.

Note that, even with no proxy, it is always possible that some intermediate node (an antivirus, for instance) causes the Stream-sense mechanism to come into play.
This can be checked in the previous part of the log.

EWANG

The same application I noticed another strange behavior and the developer claims it's not from the application code but from the Silverlight client library. Here is the logs

25-May-10 14:05:08,022 |INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 2 |Serving request: /lightstreamer/create_session.txt?LS_user=LSUser&LS_adapter_set=Adapter&LS_content_length=50000000&LS_polling=true&LS_polling_millis=0&LS_idle_millis=0&LS_report_info=true from 10.35.185.113:52531

(No Bind session request)

25-May-10 14:05:08,070 |INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 9 |Serving request: /lightstreamer/control.txt?LS_session=S737de3212f2fbeeeT0416469&LS_op=destroy from 10.35.185.113:52531

Why the library sent a DESTROY request 50ms after the create session?

Thanks

Dario Crivelli

The Silverlight library may issue DESTROY requests simply to ensure that a session that is no longer needed is closed as soon as possible on the Server side.
In fact, just closing the connection stream on the client side, sometimes is not enough to ensure that.

Hence, if the session mentioned in DESTROY request (i.e. S737de3212f2fbeeeT0416469) is being closed by the client together with the opening of a new session at 14:05:08,022 then the log pattern is correct.
If the session being destroyed were the same opened at 14:05:08,022 there would be something unusual happening.
A full log snippet would be needed to shed full light on the case.

EWANG

On the client side here is the HttpWatch log;
1. <entry method="POST" URL="https://*******.com/lightstreamer/create_session.txt">
<started>00:00:09.860</started>
<startedDateTime>2010-08-11T09:10:58.756</startedDateTime>
<time>1.718</time>
<result>200</result>
<response><content>
<contentLength>149</contentLength>
<text><![CDATA[ OK SessionId:S4abfa93fa2681585T1101270 KeepaliveMillis:0 MaxBandwidth:0.0 RequestLimit:50000 ServerName:AMS3 HTTP Server PROBE LOOP ]]></text>
<mimeType>text/plain; charset=iso-8859-1</mimeType>
</content>
</response>
2. <entry method="GET" URL="https://*******.com/lightstreamer/bind_session.txt?LS_session=S4abfa93fa2681585T1101270&LS_content_length=50000000&LS_report_info=true&LS_silverlight_version=1.0">
<started>00:00:15.250</started>
<startedDateTime>2010-08-11T09:11:04.146</startedDateTime>
<time>4.238</time>
<result>200</result>
<summary>
<response><content>
<contentLength>2074</contentLength>
<text><![CDATA[ OK SessionId:S4abfa93fa2681585T1101270 KeepaliveMillis:2000 MaxBandwidth:0.0 RequestLimit:50000 Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push PROBE PROBE END ]]></text>
<mimeType>text/plain; charset=iso-8859-1</mimeType>
</content>
</response>

3. <entry method="POST" URL="https://*******.com/lightstreamer/create_session.txt">
<started>00:00:18.031</started>
<startedDateTime>2010-08-11T09:11:06.927</startedDateTime>
<time>0.529</time>
<result>200</result>
<response><content>
<contentLength>146</contentLength>
<text><![CDATA[ OK SessionId:S92957313c3dc0a6eT1108268 KeepaliveMillis:30000 MaxBandwidth:0.0 RequestLimit:50000 ServerName:AMSATBTP3 HTTP Server LOOP ]]></text>

4. <entry method="POST" URL="https://ecaalerts.fidelity.com/lightstreamer/control.txt">
<started>00:00:18.047</started>
<startedDateTime>2010-08-11T09:11:06.943</startedDateTime>
<time>1.436</time>
<result>200</result>
<summary>
5. <entry method="POST" URL="https://*****.com/lightstreamer/bind_session.txt">
<started>00:00:19.610</started>
<startedDateTime>2010-08-11T09:11:08.506</startedDateTime>
<time>31.093</time>
<result>200</result>
<summary>
<response><content>
<contentLength>119</contentLength>
<text><![CDATA[ OK SessionId:S92957313c3dc0a6eT1108268 KeepaliveMillis:30000 MaxBandwidth:0.0 RequestLimit:50000 PROBE LOOP ]]></text>
<mimeType>text/plain; charset=iso-8859-1</mimeType>
</content>
</response>

(#5 repeats until the app was closed)

Eric

EWANG

continued from above thread
09:11:01,270 |DEBUG|Logger.METADATA |SERVER POOLED THREAD 10 |New Session S4abfa93fa2681585T1101270 for user ad04d127-55a3-454a-a628-cd00fe3408be from 10.41.220.7
09:11:01,270 |INFO |Logger.METADATA |SERVER POOLED THREAD 10 |User ad04d127-55a3-454a-a628-cd00fe3408be has 1 concurrent session(s) after this new session S4abfa93fa2681585T1101270 added.
09:11:09,195 |DEBUG|Logger.METADATA |SERVER POOLED THREAD 8 |notifySessionClose: session id is S4abfa93fa2681585T1101270
server-3.log:09:11:01,272 |INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 10 |Starting new session: S4abfa93fa2681585T1101270 from 10.41.220.7:44852
server-3.log:11-Aug-10 09:11:05,188 |INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 9 |Serving request: /lightstreamer/bind_session.txt?LS_session=S4abfa93fa2681585T1101270&LS_content_length=50000000&LS_report_info=true&LS_silverlight_version=1.0 from 10.41.220.7:44852
server-3.log:11-Aug-10 09:11:05,190 |INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 9 |Attaching session: S4abfa93fa2681585T1101270 from 10.41.220.7:44852
server-3.log:11-Aug-10 09:11:09,194 |INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 8 |Serving request: /lightstreamer/control.txt?LS_session=S4abfa93fa2681585T1101270&LS_op=destroy from 10.41.220.7:44878
atbt-ams-server-3.log:11-Aug-10 09:11:09,194 |INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 8 |Destroying session: S4abfa93fa2681585T1101270 from 10.41.220.7:44878
second session started
09:11:08,268 |DEBUG|ATBTLogger.METADATA
|SERVER POOLED THREAD 5 |New Session S92957313c3dc0a6eT1108268 for user
ad04d127-55a3-454a-a628-cd00fe3408be from 10.41.220.7

server-3.log:11-Aug-10 09:11:08,268 |INFO |LightstreamerLogger.requests
|SERVER POOLED THREAD 5 |Starting new session: S92957313c3dc0a6eT110826
8 from 10.41.220.7:44878
server-3.log:11-Aug-10 09:11:11,136 |INFO |LightstreamerLogger.requests
|SERVER POOLED THREAD 6 |Serving request: /lightstreamer/control.txt?LS
_session=S92957313c3dc0a6eT1108268&LS_op=add&LS_table=1&LS_id=ADAPTER&L
S_mode=RAW&LS_schema=MESSAGEID+DATA+MESSAGE_TS&LS_data_adapter=ADAPTER from 10.41.220.7:44889
server-3.log:11-Aug-10 09:11:11,137 |INFO |LightstreamerLogger.requests
|SERVER POOLED THREAD 6 |Controlling session: S92957313c3dc0a6eT1108268
from 10.41.220.7:44889
server-3.log:11-Aug-10 09:11:40,461 |INFO |LightstreamerLogger.requests
|SERVER POOLED THREAD 9 |Polling (2) to session: S92957313c3dc0a6eT1108
268 from 10.41.220.7:44878
-server-3.log:11-Aug-10 09:12:10,702 |INFO |LightstreamerLogger.requests
|SERVER POOLED THREAD 9 |Polling (3) to session: S92957313c3dc0a6eT1108
268 from 10.41.220.7:44878
server-3.log:11-Aug-10 09:12:40,880 |INFO |LightstreamerLogger.requests
|SERVER POOLED THREAD 9 |Polling (4) to session: S92957313c3dc0a6eT1108
268 from 10.41.220.7:44878
.....

EWANG

Dario Crivelli

The pattern is the typical one when the Stream-sense mechanism comes into action.

1. Even though the first session goes on well on the Server, the answer of the first bind_session, which is in streaming, doesn't reach the client, because of some intermediate node which does not support streaming.
Eventually, the client library detects that and opens a new session in smart polling.
You may notice that the client, just in case, also sends a "destroy" request related to the first session.

2. Note that, in general, all requests are in POST; only streaming requests, in Silverlight, have to be issued in GET (note that those requests don't carry user credentials).

3. About subscriptions, note that in LS Silverlight library all the connection phase is atomic and blocking. Hence, if the Stream-sense needs to perform a second connection attempt, until it has finished and openConnection has returned, you are not allowed to perform subscription requests.
Hence, the first session cannot receive subscription requests and all you requests pertain to the second one.
Nevertheless, if you, then, explicitly open a new session by invoking openConnection, the subscription requests must be reissued.

EWANG

For #1, the client received the response based on HttpWatch "OK SessionId:S4abfa93fa2681585T1101270 KeepaliveMillis:2000 MaxBandwidth:0.0 RequestLimit:50000 Preamble: preparing push Preamble: preparing push Preamble: preparing push
.......
Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push Preamble: preparing push PROBE PROBE END" . So why the client API thought this is not streaming?

One more question, how does Lightstreamer handles the messages between POLLING requests? Will client receive them?

Thanks

Eric

Dario Crivelli

Ok, sorry, the first log was taken on the client machine, so no intermediate nodes could be involved.
It is still possible that the response did not reach LS library, though this is not the normal case and some additional element has to be identified.
Can you make any hypothesis on a possible cause based on your environment?

For instance, as found in this thread, if the Silverlight application code forces the use of ClientHttp in place of BrowserHttp, streaming is no longer supported by the Silverlight runtime.

Another possibility is the presence of an antivirus tightly integrated with the browser; some antiviruses may buffer the response wholly or in blocks; I don't know if https can also be handled in this way.

Your client-side sniffer might block streaming. Can you ensure that the client-side behavior with and without the sniffer are exactly the same?

Unfortunately, LS Silverlight Client library offers no log support, so we can't check and confirm in a clear way that the streaming answer is not read by the library.
Would it be feasible for you setting up a test in your application, by performing a request to LS Server?
Can you see our online Silverlight demo in https in streaming? (Use this url).

Once the library has recovered with polling, it uses smart polling, hence the client does not wait between subsequent requests: it always reissues polls immediately and it is the Server which may hold the request until events are available.
Anyway, no events are lost; events that reach the Server while the new request has not come yet are queued and may be merged, depending on the configuration.

EWANG

Sorry, I forgot to clarify the issue more clearly.
The issue was first reported that the user was always in polling mode. We found out it was caused by infrastructure configuration issue and was fixed. Now majority users were in streaming mode.
The same user was in streaming mode most of the time, with or without HtppWatch. But if polling happened it is alsways the same pattern, with or without HttpWatch. The pattern is like this. On client side, create_session, bind_session, 4-5 seconds later create_session, control_session (to kill the previous session), bind_session (polling). On the server side, first bind_session seems fine.

Thanks

Eric

Dario Crivelli

If the client can usually work in streaming, then clearly none of the suggested possible constraints applies.
I confirm that the described pattern corresponds to the Stream-sense mechanism, which opens a polling session when the first bind_session yields no answer to the application for more than 5 seconds.

Now, the most likely explaination is that there are delays either in the client machine or in the network.
In fact, the request times reported in your logs are quite separated; by the way, do you know if the server and client clocks were in sync when you took the logs?
Can you see the exact times of the single outbound and inbound packets of the requests to the Server on the client machine? They could help discriminating where the delays are produced.

EWANG

Is it possible to config the client wait for more than 4 seconds? Thanks

Dario Crivelli

I have to correct myself, as the default timeout is 5 seconds rather than 4 seconds (I have also fixed my post above).
Anyway, the StreamingTimeoutMillis property of the ConnectionInfo instance allows you to change the setting.
If you are not using the latest version of the Silverlight API, the setting may be different.