Updates dropped when restart is performed

ctranfd

Hi,

I have been working on a remote protocol server which sends updates to Lightstreamer and have come across a problem when there is a restart of the application which sends the updates to Lightstreamer. The browser which was subscribed to Lightstreamer remains open, and when the application restarts and attempts to send an update, the update gets lost.

Also, I'm using the RobustNetworkedDataProvider.

This seems to be happening when the browser is opened before the application connects to Lightstreamer.

This is the sequence of what happens
1. Start Lightstreamer
2. Start the application
3. Open browser (subscription is registered on Lightstreamer)
4. Application sends update, the update is reflected on the client browser
5. Restart the application. When the application is connected to Lightstreamer, the browser sends a subscription request (with a new ID) to Lightstreamer.
6. Application sends an update. The page does not get updated and Lighstreamer log does not register the update.

I notice that this also happens with the following scenario (using the sockets example to remotely connect to Lightstreamer - using ports 9000 and 9001)
1. Start Lighstreamer
2. Open the browser
3. Connect telnet client to port 9000, connect telnet client to port 9001.
Telnet client connected on 9000 receives SUB request (100000121a3858292|SUB|S|STATION).
4. Submit an updated on the telnet client window connected on 9001
5. The page does not receive the update.

The only way updates are showing on the page is when the page is closed and then opened again - i.e. the following happens: subscribe (when browser is opened) -> subscribe (on restart of the application) -> unsubscribe (when browser is closed) -> subscribe (when new browser window is opened).

I've attached the log below as well

03.Jun.09 09:30:35,576 < INFO> Events pool size set by default at 2
03.Jun.09 09:30:35,591 < INFO> Lightstreamer Server 3.5 build 1428.4 starting...

03.Jun.09 09:30:35,669 < INFO> Server "Lightstreamer HTTP Server" listening to *:8090 ...
03.Jun.09 09:32:23,810 < INFO> Connected on port 9000
03.Jun.09 09:32:28,841 < INFO> Connected on port 9001
03.Jun.09 09:32:28,841 < INFO> Connected
03.Jun.09 09:32:28,857 < INFO> Inner Proxy Adapter loaded
03.Jun.09 09:32:28,872 < INFO> Notify receiver '#9' starting...
03.Jun.09 09:32:28,872 < INFO> Request sender '#9' starting...
03.Jun.09 09:32:28,888 < INFO> Reply receiver '#9' starting...
03.Jun.09 09:36:01,997 < INFO> Serving request: /lightstreamer/create_session.js?LS_phase=5802&LS_domain=test.com.au&LS_polling=true&LS_polling_millis=0&LS_idle_millis=30000&LS_client_version=4.3&LS_adapter=TEST& from 127.0.0.1:257603.Jun.09 09:36:02,044 < INFO> Starting new session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2576
03.Jun.09 09:36:02,091 < INFO> Serving request: /lightstreamer/control.html?LS_session=S66c4d40cb0b72668T3602029&LS_window=7&LS_win_phase=4&LS_op=add&LS_req_phase=20&LS_mode1=MERGE&LS_id1=STATION&LS_schema1=NowPlaying&LS_data_adapter1=TEST_ADAPTER_1&LS_snapshot1=true&LS_unique=1 from 127.0.0.1:2576
03.Jun.09 09:36:02,091 < INFO> Controlling session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2576
03.Jun.09 09:36:02,138 < INFO> Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S66c4d40cb0b72668T3602029&LS_phase=5803&LS_domain=test.com.au& from 127.0.0.1:2579
03.Jun.09 09:36:02,138 < INFO> Attaching session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2579
03.Jun.09 09:36:02,169 <TRACE> Subscribing item STATION on TEST.TEST_ADAPTER_1
03.Jun.09 09:36:02,169 <DEBUG> Manager: com.lightstreamer.c.fb@31f2a7
03.Jun.09 09:36:02,201 < INFO> Serving multiple request: /lightstreamer/control.html?{6 subrequests} from 127.0.0.1:2578
03.Jun.09 09:36:02,201 < INFO> Subrequest 1: LS_session=S66c4d40cb0b72668T3602029&LS_window=8&LS_win_phase=4&LS_op=add&LS_req_phase=21&LS_mode1=MERGE&LS_id1=STATION&LS_schema1=NowPlaying&LS_data_adapter1=TEST_ADAPTER_2&LS_snapshot1=true&LS_unique=2 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 < INFO> Subrequest 2: LS_session=S66c4d40cb0b72668T3602029&LS_window=9&LS_win_phase=4&LS_op=add&LS_req_phase=22&LS_mode1=MERGE&LS_id1=STATION&LS_schema1=NowPlaying&LS_data_adapter1=TEST_ADAPTER_3&LS_snapshot1=true&LS_unique=3 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 < INFO> Subrequest 3: LS_session=S66c4d40cb0b72668T3602029&LS_window=10&LS_win_phase=4&LS_op=add&LS_req_phase=23&LS_mode1=MERGE&LS_id1=STATION&LS_schema1=NowPlaying&LS_data_adapter1=TEST_ADAPTER_4&LS_snapshot1=true&LS_unique=4 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 < INFO> Subrequest 4: LS_session=S66c4d40cb0b72668T3602029&LS_window=11&LS_win_phase=4&LS_op=add&LS_req_phase=24&LS_mode1=MERGE&LS_id1=STATION&LS_schema1=NowPlaying&LS_data_adapter1=TEST_ADAPTER_5&LS_snapshot1=true&LS_unique=5 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 < INFO> Subrequest 5: LS_session=S66c4d40cb0b72668T3602029&LS_window=12&LS_win_phase=4&LS_op=add&LS_req_phase=25&LS_mode1=MERGE&LS_id1=STATION&LS_schema1=NowPlaying&LS_data_adapter1=TEST_ADAPTER_6&LS_snapshot1=true&LS_unique=6 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 < INFO> Subrequest 6: LS_session=S66c4d40cb0b72668T3602029&LS_window=13&LS_win_phase=4&LS_op=add&LS_req_phase=26&LS_mode1=MERGE&LS_id1=STATION&LS_schema1=NowPlaying&LS_data_adapter1=TEST_ADAPTER_7&LS_snapshot1=true&LS_unique=7 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 < INFO> Controlling session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 <TRACE> Subscribing item STATION on TEST.TEST_ADAPTER_2
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@82751
03.Jun.09 09:36:02,201 <TRACE> INCOMING END OF SNAPSHOT NOTIFY for STATION
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@82751
03.Jun.09 09:36:02,201 < INFO> Controlling session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 <TRACE> Subscribing item STATION on TEST.TEST_ADAPTER_3
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@7cd37a
03.Jun.09 09:36:02,201 <TRACE> INCOMING END OF SNAPSHOT NOTIFY for STATION
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@7cd37a
03.Jun.09 09:36:02,201 < INFO> Controlling session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 <TRACE> Subscribing item STATION on TEST.TEST_ADAPTER_4
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@1202d69
03.Jun.09 09:36:02,201 <TRACE> INCOMING END OF SNAPSHOT NOTIFY for STATION
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@1202d69
03.Jun.09 09:36:02,201 < INFO> Controlling session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 <TRACE> Subscribing item STATION on TEST.TEST_ADAPTER_5
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@1855562
03.Jun.09 09:36:02,201 <TRACE> INCOMING END OF SNAPSHOT NOTIFY for STATION
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@1855562
03.Jun.09 09:36:02,201 < INFO> Controlling session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 <TRACE> Subscribing item STATION on TEST.TEST_ADAPTER_6
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@a89ce3
03.Jun.09 09:36:02,201 <TRACE> INCOMING END OF SNAPSHOT NOTIFY for STATION
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@a89ce3
03.Jun.09 09:36:02,201 < INFO> Controlling session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2578
03.Jun.09 09:36:02,201 <TRACE> Subscribing item STATION on TEST.TEST_ADAPTER_7
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@1d439fe
03.Jun.09 09:36:02,201 <TRACE> INCOMING END OF SNAPSHOT NOTIFY for STATION
03.Jun.09 09:36:02,201 <DEBUG> Manager: com.lightstreamer.c.fb@1d439fe
03.Jun.09 09:37:09,982 <TRACE> INCOMING DATA for STATION --> {NowPlaying={"field":"NowPlaying","list" :Smile_Ah: {"title":"song","album":"an album","artist":"blah","status":"playing"}]}, UpComing={"field":"UpComing","list" :Smile_Ah: ]}, LastPlayed={"field":"LastPlayed","list" :Smile_Ah: ]}}
03.Jun.09 09:37:09,982 <DEBUG> Manager: com.lightstreamer.c.fb@31f2a7
03.Jun.09 09:37:57,201 < INFO> Request sender '#9' stopped
03.Jun.09 09:37:57,201 <ERROR> Got fatal error from the inner Proxy Adapter
com.lightstreamer.adapters.remote.RemotingException: Unexpected end of notify stream reached
        at com.lightstreamer.adapters.remote.request_reply.NotifyReceiver.run(NotifyReceiver.java:77)
Caused by: java.io.EOFException
        ... 1 more
03.Jun.09 09:37:57,201 <TRACE> INCOMING END OF SNAPSHOT NOTIFY for STATION
03.Jun.09 09:37:57,201 <DEBUG> Manager: com.lightstreamer.c.fb@31f2a7
03.Jun.09 09:37:57,201 < INFO> Notify receiver '#9' stopped
03.Jun.09 09:37:57,201 < INFO> Reloading inner Proxy Adapter for recovery
03.Jun.09 09:37:57,201 < INFO> Connecting...
03.Jun.09 09:37:57,216 < INFO> Waiting for a connection on port 9001...
03.Jun.09 09:37:57,216 < INFO> Waiting for a connection on port 9000...
03.Jun.09 09:37:57,404 < INFO> Reply receiver '#9' stopped
03.Jun.09 09:38:30,779 < INFO> Connected on port 9000
03.Jun.09 09:38:34,341 < INFO> Connected on port 9001
03.Jun.09 09:38:34,341 < INFO> Connected
03.Jun.09 09:38:34,341 < INFO> Inner Proxy Adapter loaded
03.Jun.09 09:38:34,341 < INFO> Notify receiver '#10' starting...
03.Jun.09 09:38:34,341 < INFO> Request sender '#10' starting...
03.Jun.09 09:38:34,341 < INFO> Reply receiver '#10' starting...
03.Jun.09 09:39:23,997 < INFO> Serving request: /lightstreamer/STREAMING_IN_PROGRESS?LS_session=S66c4d40cb0b72668T3602029&LS_phase=5804&LS_domain=test.com.au& from 127.0.0.1:2635
03.Jun.09 09:39:24,013 < INFO> Attaching session: S66c4d40cb0b72668T3602029 from 127.0.0.1:2635

Is there a way that I can resolve this? Does this require a change on the javascript?

Many Thanks,

C

Dario Crivelli

We can't replicate the behavior. After relaunching the Remote Data Adapter, we always see the new updates reaching the client page, even with the telnet simulation.
Please, clarify a couple of points:

You say

Restart the application. When the application is connected to Lightstreamer, the browser sends a subscription request (with a new ID) to Lightstreamer.

Do you mean that you manually restart the browser?
Or do you mean that Lightstreamer Server issues new subscription requests to the Remote Server? (For the latter, a client restart is not required)

Is the log referred to the first case or to the telnet case?
In the telnet case, the log should at least report that a line has been received. Please, try with an incorrect line and see if it is logged.

What's the setting of the "events_recovery" parameter in adapters.xml for the involved Data Adapter?

ctranfd

Hi Dario,

Thanks for your reply.

For the telnet example I made a mistake when I wrote down the steps - points 1) and 2) should be reversed. So this happens when the browser is open before Lightstreamer starts up.

Restart the application. When the application is connected to Lightstreamer, the browser sends a subscription request (with a new ID) to Lightstreamer.

Sorry for not being clear, this is the application which sends updates to Lighstreamer. In our scenario, the application receives feeds every X minutes, the application processes the feed and forwards a formatted update to Lightstreamer.
There may be times when the application that sends updates to Lightstreamer needs to be restarted, and so in this case - browsers may be open and Lighstreamer is still running.

Is the log referred to the first case or to the telnet case?
In the telnet case, the log should at least report that a line has been received. Please, try with an incorrect line and see if it is logged.

The log refers to the telnet example. When I submit a valid message, the line is not received in the log. When I submit an invalid message, the line is received in the log.

What's the setting of the "events_recovery" parameter in adapters.xml for the involved Data Adapter?

We actually had this on the default setting - since changing this to use_snapshot this seems to fix the problem.

Thanks so much for your help! :Smile_Ab:

Dario Crivelli

Ok.
If the first event sent by the Remote Adapter after a restart is marked as a snapshot, it is ignored, unless "events_recovery" is set to "use_snapshot". Note that this setting may not work in all cases, as explained in the sample configuration file.
Note that further events sent by the Remote Adapter and not marked as snapshot should have been forwarded normally.