Please Note This forum exists for community support for the Mango product family and the Radix IoT Platform. Although Radix IoT employees participate in this forum from time to time, there is no guarantee of a response to anything posted here, nor can Radix IoT, LLC guarantee the accuracy of any information expressed or conveyed. Specific project questions from customers with active support contracts are asked to send requests to support@radixiot.com.
Dashboard refresh speed?
-
Brian,
You could try adding this line to the classes/log4j2.xml file to enlighten us as to why/when they are closing. There is a debug log message anytime a point value web socket is closed explaining why.
In the
<Loggers> ... </Loggers>section add this logger:<AsyncLogger includeLocation="true" name="com.serotonin.m2m2.web.mvc.rest.v1.websockets.pointValue" level="debug"/>You will need to either reload the log4j configuration from the system setting page or restart Mango for the changes to take effect.
-
Hello Jared,
Thank you. I have sent the details as requested. I have also followed Terry's advice and edited the line. I have also put the edited log4j2.xml file in the overrides/classes folder.Cheers
Brian
-
Brian,
Please Post/Send some of the DEBUG log messages generated when the websocket stops updating the page.
In terms of settings you can change, the defaults in your env properties seem fine:
# Ping timeout for response from browser web.websocket.pingTimeoutMs=10000 #Time socket can be idle before being closed (ms) web.socketIdleTimeout=70000Basically the socket will ping/pong back and forth every 10s so that the 70s idle timeout is never hit. However if the ping/pong messages are lost the connection may be closed. That information should come out in the DEBUG messages.
-
Hello Terry,
Thank you for your reply. I won't send the entire ma.log for today since it is 157 pages long, Unless you rally wan it of course. :)There are a lot of logged events from my template creations and normal run of the mill log entries.
I did look through though and found the following items that may help:
2 occasions of:
(com.serotonin.m2m2.web.mvc.rest.v1.websockets.pointValue.PointValueWebSocketHandler.afterConnectionClosed:72) - Websocket connection closed, status code: 1006, reason: WebSocket Read EOF28 occasions of:
(com.serotonin.m2m2.web.mvc.rest.v1.websockets.pointValue.PointValueWebSocketHandler.afterConnectionClosed:72) - Websocket connection closed, status code: 4500, reason: Didn't receive Pong from Endpoint within 10000 ms.17 ocasions of:
(com.serotonin.m2m2.web.mvc.rest.v1.websockets.pointValue.PointValueWebSocketHandler.afterConnectionClosed:72) - Websocket connection closed, status code: 1001, reason: null1 occasion of this after the Mango restart this morning:
ERROR 2018-12-12T09:18:00,593 error.tryCloseWithError:90) - Closing session due to exception for JettyWebSocketSession[id=26978505-c5f1-2ae3-3372-ec1cdbe0b184, uri=ws://redacted.extension:8080/rest/v1/websocket/events] java.lang.IllegalStateException: WebSocketHandler not found for JettyWebSocketSession[id=26978505-c5f1-2ae3-3372-ec1cdbe0b184, uri=ws://redacted.extension:8080/rest/v1/websocket/events] at org.springframework.web.socket.handler.PerConnectionWebSocketHandler.getHandler(PerConnectionWebSocketHandler.java:113) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.handler.PerConnectionWebSocketHandler.handleTransportError(PerConnectionWebSocketHandler.java:91) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleTransportError(WebSocketHandlerDecorator.java:80) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleTransportError(LoggingWebSocketHandlerDecorator.java:64) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.handleTransportError(ExceptionWebSocketHandlerDecorator.java:68) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.adapter.jetty.JettyWebSocketHandlerAdapter.onWebSocketError(JettyWebSocketHandlerAdapter.java:131) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_161] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_161] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_161] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_161] at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:71) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onError(JettyAnnotatedEventDriver.java:157) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingError(AbstractEventDriver.java:96) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.WebSocketSession.incomingError(WebSocketSession.java:460) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.WebSocketSession.notifyError(WebSocketSession.java:521) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:573) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:391) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) ~[jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) ~[jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161]These were the ones i found searching through the log for: closed or error.
Please let me know if you want more information or if you need me to search through the logs for specific strings.Cheers
Brian
Edited by Phil for host scrubbing and formatting triple backticks, ```
-
Hello Terry,
I also just wanted to add that since I have been working from home tonight on my templates, I have not seen the dashboards stop updating.Cheers
Brian
-
Thanks Brian,
It looks like the ping/pong failure is the problem. The other messages are expected during normal operation.
FYI on the status code meanings:
Status Code 1001 (Going Away) - This is normal behavior when a page is navigated away from
Status Code 1006 (No Close Frame) - Connection was terminated in an unclean way, it appears the socket was broken.I find it odd that 10s is not long enough to send/receive the messages so I'm thinking you have a network with packet loss. If you can I would suggest pinging the Mango server to see if that is correct. If not then perhaps increasing the env.properties value of
web.websocket.pingTimeoutMswill help.
-
Hello Terry,
Thank you (and your team) for looking into this. Your explanation makes sense now. Our office is on an industrial estate that has a fairly dodgy broadband connection and my home broadband is fine. The packet loss will explain why I am seeing this issue at work. I don't often work on this from home but am making a push to get our Mango 3 implemented.I will do some ping tests from home and from work to confirm that is the problem. and make the recommended changes to the timeouts.
Again, thank you.
CheersBrian
p.s. I wish you all a Merry Christmas.
-
Hello Terry,
Unfortunately that has not solved my problem. I have checked the ping and packet loss on our broadband here at work and while it shows some delays there is not packet loss between my desktop and the Mango 3 server.I have increased the timeout to 30 seconds but am still seeing the page stop updating after a few minutes.
I can't roll this out to our customers until I am sure the connection to the Mango server is reliable and robust.
Any other suggestion would be greatly appreciated.
Cheers
Brian
-
Here is the last log entry at the time of the last disconnect we had:
// ```DEBUG 2018-12-13T15:23:14,983 (com.serotonin.m2m2.web.mvc.rest.v1.websockets.pointValue.PointValueWebSocketHandler.afterConnectionClosed:72) - Websocket connection closed, status code: 4500, reason: Didn't receive Pong from Endpoint within 30000 ms. ERROR 2018-12-13T15:23:15,063 (org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.tryCloseWithError:90) - Closing session due to exception for JettyWebSocketSession[id=28f6a996-f2fd-ee33-ddea-d87d7d51f60e, uri=ws://dataloggersonline.uk:8080/rest/v1/websocket/point-value] java.lang.IllegalStateException: WebSocketHandler not found for JettyWebSocketSession[id=28f6a996-f2fd-ee33-ddea-d87d7d51f60e, uri=ws://dataloggersonline.uk:8080/rest/v1/websocket/point-value] at org.springframework.web.socket.handler.PerConnectionWebSocketHandler.getHandler(PerConnectionWebSocketHandler.java:113) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.handler.PerConnectionWebSocketHandler.handleTransportError(PerConnectionWebSocketHandler.java:91) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleTransportError(WebSocketHandlerDecorator.java:80) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleTransportError(LoggingWebSocketHandlerDecorator.java:64) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.handleTransportError(ExceptionWebSocketHandlerDecorator.java:68) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at org.springframework.web.socket.adapter.jetty.JettyWebSocketHandlerAdapter.onWebSocketError(JettyWebSocketHandlerAdapter.java:131) ~[spring-websocket-5.0.10.RELEASE.jar:5.0.10.RELEASE] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_161] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_161] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_161] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_161] at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:71) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onError(JettyAnnotatedEventDriver.java:157) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingError(AbstractEventDriver.java:96) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.WebSocketSession.incomingError(WebSocketSession.java:460) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.WebSocketSession.notifyError(WebSocketSession.java:521) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:573) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:391) ~[websocket-common-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) ~[jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) ~[jetty-io-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) ~[jetty-util-9.4.12.v20180830.jar:9.4.12.v20180830] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_161] -
Hello Terry,
I think I finally found the culprit. Our anti-virus is causing the drop outs. I turned it off and have run now for 30 minutes with no connection issues.I am sorry to have bugged you guys about it but thank you for your help and patience.
Cheers
Brian
-
Brian,
I replicated the closing of a websocket due to the ping/pong timeout and found that my system handles it gracefully without throwing that java.lang.IllegalStateException. The page stops updating but no errors are produced and I get the same log message about "Didn't receive Pong from Endpoint within..." I replicated this by making the Mango server delay to read the pong message.
I'm wondering if your browser isn't sending the pong message... (This should happen automatically by most every browser and isn't something you need to code into your page)
For yet more information on the connection failure you can add this to your log4j2.xml file
<AsyncLogger includeLocation="true" name="org.eclipse.jetty.websocket.common.io" level="debug"/>Ah Ok I just got you latest post while drafting this. I'm posting it anyway since I put a little time into it and it could be helpful to someone else in the future.
