Accumulated Delay

[giuseppe.corti]

It means that the Lightstreamer server receives an update from the Data Adapter for an item name that actually doesn't currently have an active subscription for.

Regards,
Giuseppe

[ManKeer]

Dear Dario,


Would you please take a look on the following log records?

I didn't receive anything as a client????

log4j:WARN No appenders could be found for logger (io.netty.util.internal.logging.InternalLoggerFact ory).
log4j:WARN Please initialize the log4j system properly.
06.أبر.23 10:14:37,141|DEBUG|lightstreamer.protocol|Session Thread <1>|New protocol oid=1
06.أبر.23 10:14:37,147|DEBUG|lightstreamer.heartbeat|Session Thread <1>|rhb max interval 0
06.أبر.23 10:14:37,148|DEBUG|lightstreamer.heartbeat|Session Thread <1>|rhb current interval 0
06.أبر.23 10:14:37,154|DEBUG|lightstreamer.session|Session Thread <1>|New session oid=1
Client property changed: sessionId
06.أبر.23 10:14:37,171|INFO |lightstreamer.actions|Session Thread <1>|Session ID value changed to null
Client property changed: serverSocketName
06.أبر.23 10:14:37,171|INFO |lightstreamer.actions|Session Thread <1>|Server Socket Name value changed to null
Client property changed: clientIp
06.أبر.23 10:14:37,171|INFO |lightstreamer.actions|Session Thread <1>|Client IP value changed to null
Client property changed: serverInstanceAddress
06.أبر.23 10:14:37,171|INFO |lightstreamer.actions|Session Thread <1>|Server Instance Address value changed to null
Client property changed: realMaxBandwidth
06.أبر.23 10:14:37,171|INFO |lightstreamer.session|Session Thread <1>|Opening new session
06.أبر.23 10:14:37,273|INFO |lightstreamer.utils|Session Thread <1>|Setting up custom CookieHandler: java.net.CookieManager@b6ed092
06.أبر.23 10:14:37,274|INFO |lightstreamer.utils|Session Thread <1>|Default CookieStore type: java.net.InMemoryCookieStore
06.أبر.23 10:14:37,274|DEBUG|lightstreamer.utils|Session Thread <1>|While getting cookies for http://etrdwebs02:8282/lightstreamer...col=TLCP-2.1.0
06.أبر.23 10:14:37,274|DEBUG|lightstreamer.utils|Session Thread <1>|Result of getting cookies for http://etrdwebs02:8282/lightstreamer...col=TLCP-2.1.0
06.أبر.23 10:14:37,274|INFO |lightstreamer.utils|Session Thread <1>|Cookies to be inserted for http://etrdwebs02:8282/lightstreamer...ol=TLCP-2.1.0: <none>
06.أبر.23 10:14:37,323|DEBUG|lightstreamer.stream|Session Thread <1>|HTTP transport connection establishing (oid=1): http://etrdwebs02:8282
/lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0
LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwL ri8L7R7q&LS_adapter_set=FEEDERSERVER&LS_user=40252 9&LS_password=PT1239129115&


06.أبر.23 10:14:37,323|DEBUG|lightstreamer.netty.pool|Sessio n Thread <1>|Creating new HTTP channel pool map
06.أبر.23 10:14:37,746|DEBUG|lightstreamer.netty.pool|Sessio n Thread <1>|HTTP channel pool map [1] created and initialized
06.أبر.23 10:14:37,747|DEBUG|lightstreamer.netty.pool|Sessio n Thread <1>|New HTTP channel pool created. Remote address: etrdwebs02:8282
06.أبر.23 10:14:37,961|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): OFF -> CREATING
06.أبر.23 10:14:37,962|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 4000 [currentConnectTimeout]
Connection status changed to CONNECTING
06.أبر.23 10:14:37,992|DEBUG|lightstreamer.netty.pool|Netty Thread 1|HTTP channel created [e4e58556]
06.أبر.23 10:14:38,006|DEBUG|lightstreamer.netty.pool|Netty Thread 1|HTTP channel active [e4e58556]
06.أبر.23 10:14:38,007|DEBUG|lightstreamer.stream|Netty Thread 2|HTTP transport connection established (oid=1): http://etrdwebs02:8282
/lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0
LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwL ri8L7R7q&LS_adapter_set=FEEDERSERVER&LS_user=40252 9&LS_password=PT1239129115&


06.أبر.23 10:14:38,009|DEBUG|lightstreamer.stream|Netty Thread 2|HTTP transport sending [e4e58556]: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0
LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=pcYgxptg4pkpW39AN3R4hwL ri8L7R7q&LS_adapter_set=FEEDERSERVER&LS_user=40252 9&LS_password=PT1239129115&


06.أبر.23 10:14:39,045|DEBUG|lightstreamer.stream|Netty Thread 1|Response status: 200
06.أبر.23 10:14:39,049|DEBUG|lightstreamer.stream|Netty Thread 1|HTTP transport receiving [e4e58556]:
CONOK,S22dfab6342ca12c1M160T1438774,50000,0,*
SERVNAME,Lightstreamer HTTP Server
CLIENTIP,10.254.94.75
LOOP,0

[ManKeer]

here's the next lines

06.أبر.23 10:14:39,050|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): CONOK,S22dfab6342ca12c1M160T1438774,50000,0,*
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.session|Session Thread <1>|OK event while CREATING
06.أبر.23 10:14:39,051|INFO |lightstreamer.actions|Session Thread <1>|Session ID value changed to S22dfab6342ca12c1M160T1438774
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.netty.pool|Netty Thread 1|HTTP channel released [e4e58556]
06.أبر.23 10:14:39,051|INFO |lightstreamer.actions|Session Thread <1>|Server Instance Address value changed to http://etrdwebs02:8282/
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.session|Session Thread <1>|Data event while CREATING
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): CREATING -> CREATED
06.أبر.23 10:14:39,051|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 2000 [executionTimeout]
Client property changed: sessionId
06.أبر.23 10:14:39,052|DEBUG|lightstreamer.actions|Session Thread <1>|Subscription 1 ready to be sent to server
06.أبر.23 10:14:39,052|INFO |lightstreamer.subscribe|Session Thread <1>|Preparing subscription: 1
Client property changed: serverInstanceAddress
Connection status changed to CONNECTED:STREAM-SENSING
06.أبر.23 10:14:39,052|INFO |lightstreamer.protocol|Session Thread <1>|Sending subscription request
06.أبر.23 10:14:39,053|DEBUG|lightstreamer.protocol|Session Thread <1>|subscription parameters: LS_reqId=1&LS_op=add&LS_subId=1&LS_mode=MERGE&LS_g roup=LSTOCKS&LS_schema=key command Data&LS_data_adapter=FEEDER_ADAPTER&LS_snapshot=tr ue&LS_requested_max_frequency=1&LS_session=S22dfab 6342ca12c1M160T1438774&
06.أبر.23 10:14:39,054|INFO |lightstreamer.subscribe|Session Thread <1>|Start message handler
06.أبر.23 10:14:39,054|DEBUG|lightstreamer.subscribe|Session Thread <1>|Sending queued messages
06.أبر.23 10:14:39,057|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): SERVNAME,Lightstreamer HTTP Server
Client property changed: serverSocketName
06.أبر.23 10:14:39,057|INFO |lightstreamer.actions|Session Thread <1>|Server Socket Name value changed to Lightstreamer HTTP Server
06.أبر.23 10:14:39,057|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): CLIENTIP,10.254.94.75
Client property changed: clientIp
06.أبر.23 10:14:39,058|INFO |lightstreamer.actions|Session Thread <1>|Client IP value changed to 10.254.94.75
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): LOOP,0
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|Loop event while CREATED
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): CREATED -> FIRST_PAUSE
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|Timeout event [noPause] while FIRST_PAUSE cause=null startRecovery=false
06.أبر.23 10:14:39,058|INFO |lightstreamer.session|Session Thread <1>|Binding session
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|SessionWS state change (1) (sendBind): WS_NOT_CONNECTED -> WS_CONNECTING
06.أبر.23 10:14:39,058|DEBUG|lightstreamer.session|Session Thread <1>|WS connection: opening
06.أبر.23 10:14:39,060|DEBUG|lightstreamer.utils|Session Thread <1>|While getting cookies for http://etrdwebs02:8282/lightstreamer
06.أبر.23 10:14:39,060|DEBUG|lightstreamer.utils|Session Thread <1>|Result of getting cookies for http://etrdwebs02:8282/lightstreamer
06.أبر.23 10:14:39,060|INFO |lightstreamer.utils|Session Thread <1>|Cookies to be inserted for http://etrdwebs02:8282/lightstreamer: <none>
06.أبر.23 10:14:39,064|DEBUG|lightstreamer.netty.pool|Sessio n Thread <1>|New WS channel pool created. Remote address: etrdwebs02:8282
06.أبر.23 10:14:39,065|DEBUG|lightstreamer.netty.pool|Netty Thread 1|HTTP channel acquired [e4e58556]
06.أبر.23 10:14:39,067|DEBUG|lightstreamer.netty.pool|Netty Thread 3|ChannelUpgradeFuture state change [e4e58556]: CONNECTING -> CONNECTION_OK
06.أبر.23 10:14:39,068|DEBUG|lightstreamer.stream|Session Thread <1>|WebSocket transport: CONNECTING
06.أبر.23 10:14:39,068|DEBUG|lightstreamer.stream|Session Thread <1>|WebSocket transport: CONNECTING
06.أبر.23 10:14:39,069|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 4000 [currentConnectTimeoutWS]
06.أبر.23 10:14:39,086|DEBUG|lightstreamer.netty.pool|Netty Thread 1|WS channel handshake [e4e58556]
06.أبر.23 10:14:39,132|DEBUG|lightstreamer.netty.pool|Netty Thread 1|ChannelUpgradeFuture state change [e4e58556]: CONNECTION_OK -> UPGRADE_OK
06.أبر.23 10:14:39,133|DEBUG|lightstreamer.netty.pool|Netty Thread 1|WS channel created [e4e58556]
06.أبر.23 10:14:39,136|DEBUG|lightstreamer.netty|Netty Thread 1|WebSocket handler added [e4e58556]
06.أبر.23 10:14:39,137|DEBUG|lightstreamer.stream|Session Thread <1>|WebSocket transport: CONNECTED
06.أبر.23 10:14:39,137|DEBUG|lightstreamer.session|Session Thread <1>|WS connection: open
06.أبر.23 10:14:39,137|DEBUG|lightstreamer.session|Session Thread <1>|SessionWS state change (1) (ok): WS_CONNECTING -> WS_CONNECTED
06.أبر.23 10:14:39,138|DEBUG|lightstreamer.stream|Session Thread <1>|WS transport sending [e4e58556]: bind_session
LS_cause=loop1&LS_session=S22dfab6342ca12c1M160T14 38774&
06.أبر.23 10:14:39,140|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): FIRST_PAUSE -> FIRST_BINDING
06.أبر.23 10:14:39,141|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 4000 [bindTimeout]
06.أبر.23 10:14:39,142|DEBUG|lightstreamer.stream|Session Thread <1>|WS transport sending [e4e58556]: control
LS_reqId=1&LS_op=add&LS_subId=1&LS_mode=MERGE&LS_g roup=LSTOCKS&LS_schema=key command Data&LS_data_adapter=FEEDER_ADAPTER&LS_snapshot=tr ue&LS_requested_max_frequency=1&LS_session=S22dfab 6342ca12c1M160T1438774&
06.أبر.23 10:14:39,143|DEBUG|lightstreamer.actions|Session Thread <1>|Subscription 1 sent to server
06.أبر.23 10:14:39,143|DEBUG|lightstreamer.heartbeat|Session Thread <1>|rhb updated
06.أبر.23 10:14:39,254|DEBUG|lightstreamer.stream|Netty Thread 1|WS transport receiving [e4e58556]:
CONOK,S22dfab6342ca12c1M160T1438774,50000,5000,*


06.أبر.23 10:14:39,255|DEBUG|lightstreamer.protocol|Session Thread <1>|New message (1): CONOK,S22dfab6342ca12c1M160T1438774,50000,5000,*
06.أبر.23 10:14:39,255|DEBUG|lightstreamer.session|Session Thread <1>|OK event while FIRST_BINDING
06.أبر.23 10:14:39,255|INFO |lightstreamer.actions|Session Thread <1>|Keepalive Interval value changed to 5000
06.أبر.23 10:14:39,256|INFO |lightstreamer.actions|Session Thread <1>|Session ID value changed to S22dfab6342ca12c1M160T1438774
06.أبر.23 10:14:39,256|INFO |lightstreamer.actions|Session Thread <1>|Server Instance Address value changed to http://etrdwebs02:8282/
06.أبر.23 10:14:39,256|DEBUG|lightstreamer.session|Session Thread <1>|Data event while FIRST_BINDING
06.أبر.23 10:14:39,256|DEBUG|lightstreamer.session|Session Thread <1>|Session state change (1): FIRST_BINDING -> RECEIVING
06.أبر.23 10:14:39,256|DEBUG|lightstreamer.session|Session Thread <1>|Status timeout in 5000 [keepaliveInterval]
Client property changed: keepaliveInterval
Client property changed: sessionId
Client property changed: serverInstanceAddress
Connection status changed to CONNECTED:WS-STREAMING
06.أبر.23 10:14:39,257|DEBUG|lightstreamer.mpn|Session Thread <1>|MpnManager state change (null) on 'onSessionStart': NoSessionState -> SessionOkState
06.أبر.23 10:14:39,259|DEBUG|lightstreamer.session|Session Thread <1>|Reset currentRetryDelay: 4000
06.أبر.23 10:14:39,259|DEBUG|lightstreamer.session|Session Thread <1>|Reset currentConnectTimeout: 4000
06.أبر.23 10:14:39,264|DEBUG|lightstreamer.stream|Netty Thread 1|WS transport receiving [e4e58556]:
CONS,unlimited

[DarioCrivelli]

The log seems truncated before any data could be received.
Really this is the only log collected and after 10:14:39,264 nothing else is logged?
In this case the whole application would be frozen.

[ManKeer]

Hi giuseppe,

Unfortunately, the accumulated delay problem back again.

Some clients face this issue too much and they're big customers.

the delay keep accumulated, starting from seconds up to minutes.

In the code we:

setRequestedMaxFrequency("unlimited");
setRequestedSnapshot("yes");

Could this cause that issue? this adapter works in MERGE mode.

How can I eliminate queueing in case there's a queue of messages for that customer.

Is there's a way to enable the pumps log on PRODUCTION for specific users ?
Your help is appreciated..

[giuseppe.corti]

Hi ManKeer,

Delays can have two different origins, either on the server-side or on the client-side.

If the origin is on the server-side, it would affect all clients indiscriminately first and should be relatively easily traceable in the server log.
Could you please send us (support@lightstreamer.com) an excerpt from the lightstreamer.log of a server to which these clients who experienced the issue were connected?
A portion covering approximately one hour of time should be ok.

If the issue is on the client-side, the right way to avoid data queuing is to use the MERGE mode.
In this way, the server does not maintain a data buffer, and for each user subscription, only the most recent image is retained.
However, this mechanism does not exclude the possibility that the client itself, in its TCP buffer, may accumulate some data, assuming it is slow in processing and presenting this data delays can still occur in this case.
In this scenario, it may be useful to reduce the update frequency on the client side, by replacing setRequestedMaxFrequency("unlimited"); with a lower frequency setting. For example, you can request only 1 or 2 updates per second and check if the problem is mitigated.

setRequestedMaxFrequency(1);

or

setRequestedMaxFrequency(2);

On the other hand, requesting the snapshot should not make any difference during the data streaming unless it is an extremely large amount of data that triggers a delay in the application from the beginning. However, I would tend to exclude this.