Giuseppe Corti
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:
[SYNTAX=XML]<logger name="LightstreamerLogger.requests" level="DEBUG"/>[/SYNTAX]
Regards,
Giuseppe
oliverwetterau
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=Sc55170a060cdd7caT5329097&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=Sc55170a060cdd7caT5329097&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=Sc55170a060cdd7caT5329097&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
Giuseppe Corti
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
