Results 1 to 4 of 4
  1. #1

    Unexpected exception for unordered message

    Hello,

    today I was experiencing the following error which unfortunately leads to our application not working properly anymore:

    Got unexpected exception for unordered message UNORDERED_MESSAGES in session S5ee5340a8f7199dfT4504720: Error in message forwarding: com.lightstreamer.interfaces.metadata.Notification Exception

    Can anybody tell me what is causing that?

    Could it be caused by a client that is fast and often switching between http streaming and web socket connection? And why is the client switching all the time (each second) between these modes?

    Best regards,
    Oliver

  2. #2
    Administrator
    Join Date
    Feb 2012
    Location
    Milano
    Posts
    541
    Hi Oliver,

    The exception you report is explicitly thrown by the notifyUserMessage method of your MetaData Adapter.
    You should then verify the conditions under which your implementation throws this exception.

    But sure a client switching continuously between http streaming and web socket connection, and then continuously changing of sessionID, can generate race conditions conducive to the issue.

    In any case, the situation of the client is very strange, indeed once fell back in http streaming is expected to remain stable in that mode.
    If you believe this is the case to investigate further the problem you should repeat the issue with a test server and post here a snippet of server log file after setting this level of logger:


    Regards,
    Giuseppe

  3. #3
    Hi Giuseppe,

    we have changed the logging settings according to your suggestion. And this is what is says in the log:

    14-May-14 09:54:45,417|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 10 |Sending message to session: Sb282503b4a33eaf0T0413676 on "Lightstream
    er HTTPS Server" from 10.20.32.107:21522
    14-May-14 09:54:48,801|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 2 |evaluating KEEPALIVE - no result configured
    14-May-14 09:54:48,801|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 2 |Serving request: /lightstreamer/msg.js --> LS_message=%7B%22type%22%3
    A%22r%22%2C%22userId%22%3A%228763de71-4708-4415-a831-4f4a386839d4%22%7D&LS_session=Sc55170a060cdd7caT53 29097&LS_ack=&LS_msg_prog=2& on "Lightstreamer HTTPS Serv
    er" from xx.xx.xx.xx:30977
    14-May-14 09:54:48,801|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 2 |evaluating use_http_11 - result from base rule: true
    14-May-14 09:54:48,801|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 2 |evaluating use_http_11 - result from base rule: true
    14-May-14 09:54:48,801|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 2 |evaluating USE_CACHE_HEADERS - no result configured
    14-May-14 09:54:48,801|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 2 |Sending message to session: Sc55170a060cdd7caT5329097 on "Lightstream
    er HTTPS Server" from 10.20.32.107:30977
    14-May-14 09:56:37,735|INFO |LightstreamerMonitorText |Timer-0 |Total threads = 126, Total heap = 172490752 (free = 136879856), Sessi
    ons = 8 (max = 13), New sessions = [+0, -0], Connections = 8 (max = 18), New connections = [+1, -1], In-pool threads = 43, Active threads = 0, Available threads
    = 43, Queued tasks = 0, Pool queue wait = 0, NIO write queue = 0, NIO write queue wait = 0, NIO write selectors = 6, NIO total selectors = 48, Subscribed items
    = 1, Inbound throughput = 0 updates/s (pre-filtered = 0), Outbound throughput = 0 updates/s (0 kbit/s, max = 512.7), Lost updates = 0 (total = 0), Total bytes
    sent = 2183768, Client messages throughput = 0 msgs/s (0 kbit/s, max = 2.34), Total messages handled = 210, Extra sleep = 0, Notify delay = 0
    14-May-14 09:57:37,979|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 3 |Serving request: msg -> LS_unq=71&LS_message={"type":"r","userId":"b0
    5cc0d6-5ae9-484b-ab11-6bb882292e72"} on "Lightstreamer HTTPS Server" from 10.20.32.107:29766
    14-May-14 09:57:37,979|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 3 |Sending message to session: Sd23c4cc1bb096547T5107132 on "Lightstream
    er HTTPS Server" from 10.20.32.107:29766
    14-May-14 09:57:38,019|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 10 |Serving request: msg -> LS_unq=71&LS_message=<simple json message> on "Lightstreamer HTTPS Server" from xx.xx.xx.xx:21522
    14-May-14 09:57:38,019|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 10 |Sending message to session: Sb282503b4a33eaf0T0413676 on "Lightstream
    er HTTPS Server" from xx.xx.xx.xx:21522
    14-May-14 09:57:44,324|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 6 |evaluating KEEPALIVE - no result configured
    14-May-14 09:57:44,324|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 6 |Serving request: /lightstreamer/msg.js --> LS_message=%7B%22type%22%3
    A%22r%22%2C%22userId%22%3A%228763de71-4708-4415-a831-4f4a386839d4%22%7D&LS_session=Sc55170a060cdd7caT53 29097&LS_ack=&LS_msg_prog=3& on "Lightstreamer HTTPS Serv
    er" from xx.xx.xx.xx:31745
    14-May-14 09:57:44,324|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 6 |evaluating use_http_11 - result from base rule: true
    14-May-14 09:57:44,324|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 6 |evaluating use_http_11 - result from base rule: true
    14-May-14 09:57:44,324|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 6 |evaluating USE_CACHE_HEADERS - no result configured
    14-May-14 09:57:44,325|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 6 |Sending message to session: Sc55170a060cdd7caT5329097 on "Lightstream
    er HTTPS Server" from 10.20.32.107:31745
    14-May-14 09:57:47,054|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 3 |evaluating KEEPALIVE - no result configured
    14-May-14 09:57:47,054|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 3 |Serving request: /lightstreamer/msg.js --> LS_message=%7B%22type%22%3
    A%22r%22%2C%22userId%22%3A%228763de71-4708-4415-a831-4f4a386839d4%22%7D&LS_session=Sc55170a060cdd7caT53 29097&LS_ack=&LS_msg_prog=3& on "Lightstreamer HTTPS Serv
    er" from xx.xx.xx.xx:31745
    14-May-14 09:57:47,054|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 3 |evaluating use_http_11 - result from base rule: true
    14-May-14 09:57:47,054|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 3 |evaluating use_http_11 - result from base rule: true
    14-May-14 09:57:47,054|DEBUG|LightstreamerLogger.requests |SERVER POOLED THREAD 3 |evaluating USE_CACHE_HEADERS - no result configured
    14-May-14 09:57:47,054|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 3 |Sending message to session: Sc55170a060cdd7caT5329097 on "Lightstream
    er HTTPS Server" from 10.20.32.107:31745
    14-May-14 09:57:47,055|WARN |LightstreamerLogger.pump.messages|SERVER POOLED THREAD 3 |Discarded duplicated message UNORDERED_MESSAGES[3] in session Sc55170a060cdd7caT5329097.
    14-May-14 09:57:47,055|INFO |LightstreamerLogger.requests |SERVER POOLED THREAD 3 |Refused message: Unexpected duplicate phase in message on "Lightstreamer HTTPS Server" from xx.xx.xx.xx:31745

    I don't know if that is related or another problem we are facing, but some of our clients report 307 - temporary redirect errors and due to that cannot connect to Lightstreamer (error appears in lightstreamer.js line 204).

    Best regards,
    Oliver

  4. #4
    Administrator
    Join Date
    Feb 2012
    Location
    Milano
    Posts
    541
    Hi Oliver,

    Thank you for the snippet of server log you posted here.

    In this snippet the NotificationException you mentioned in the first post of this thread is not present but there is a warning for a duplicate message (LS_msg_prog=3 for session ID Sc55170a060cdd7caT5329097).
    In this case the most likely cause is that the client has lost, or received too late, the ack message sent from the server and re-sent the same message. This may highlight poor network conditions for the client.

    Furthermore, from this log we do not notice the switching between http streaming and web socket connection for a specific client.
    Indeed we count several sessions, some working with WebSocket (Sd23c4cc1bb096547T5107132 and Sb282503b4a33eaf0T0413676) and some others in HTTP Streaming (Sc55170a060cdd7caT5329097) but we can not figure out if they belong to the same client or are independent.

    Please can you send us a wider snippet of the log where the life cycle of the clients involved is fully reported, at least since the creation of the session. (If you prefer you could send us the log via mail: support@lightstreamer.com).
    Please can you confirm us that the NotificationException is not involved in the test case of the log you posted?

    Thank you,
    Giuseppe

 

 

Similar Threads

  1. Replies: 7
    Last Post: June 7th, 2010, 10:38 AM
  2. IE - unexpected unsubscribe
    By shayzweig in forum Client APIs
    Replies: 3
    Last Post: April 6th, 2010, 09:46 AM
  3. < WARN> Unexpected null event ???
    By mohamida in forum Adapter APIs
    Replies: 2
    Last Post: December 10th, 2009, 07:57 AM
  4. Unexpected empty selected list
    By shreyaspurohit in forum Adapter APIs
    Replies: 4
    Last Post: April 14th, 2009, 11:38 AM
  5. Unexpected snapshot event for MERGE
    By churrusco in forum General
    Replies: 2
    Last Post: May 4th, 2007, 04:19 PM

Bookmarks

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •  
All times are GMT +1. The time now is 04:38 PM.