dslink stops working after a few days

[RainerMueller82]

I'm using DG Solution Builder and my mqtt dslink is not working after a few days. In fact I have to remove all subscriptions and re-add them to get it running again. otherwise I just cannot see new incoming mqtt messages anymore. Does anybode have the same problem here? Log is not showing anything suspicious ...

[ilyatsarev]

Hi @RainerMueller82, could you change log level in server.json to "serverLogLevel": "DEBUG" and try to reproduce it again? Also did you check both server and dslink logs?

[RainerMueller82]

Hello! Sorry for the really late answer, the problem still exists. It looks like only our "state" subscription is affected. This is a retain message sent by the devices holding the connection state. We also use the last will retain in order to be able to track a connection loss. The messages are suddenly not received in the GUI anymore. The only thing that helps, is to unsubscribe and re-subscribe to the "state" topic. The problem is, this happens again after 1-2 days only. I made a log of the mqtt dslink in debug mode. There are a few exceptions that may give some idea whats going wrong.

[2019-06-14 04:58:30.158290] 2019-06-14 04:58:30.158 [Thread-9] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Making backup [2019-06-14 04:58:30.158329] 2019-06-14 04:58:30.158 [Thread-9] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Backup complete [2019-06-14 04:58:53.488140] 2019-06-14 04:58:53.487 [Thread-17] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {} [2019-06-14 04:58:53.488165] 2019-06-14 04:58:53.487 [Thread-17] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent ping [2019-06-14 04:58:53.488170] 2019-06-14 04:58:53.488 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=4 [2019-06-14 04:59:02.441355] 2019-06-14 04:59:02.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 04:59:02.441382] 2019-06-14 04:59:02.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=6 [2019-06-14 04:59:02.441385] 2019-06-14 04:59:02.441 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"msg":5954} [2019-06-14 04:59:10.162621] 2019-06-14 04:59:10.162 [Thread-5] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Making backup [2019-06-14 04:59:10.162648] 2019-06-14 04:59:10.162 [Thread-5] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Backup complete [2019-06-14 04:59:23.488335] 2019-06-14 04:59:23.488 [Thread-9] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {} [2019-06-14 04:59:23.488357] 2019-06-14 04:59:23.488 [Thread-9] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent ping [2019-06-14 04:59:23.488359] 2019-06-14 04:59:23.488 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=4 [2019-06-14 04:59:30.166729] 2019-06-14 04:59:30.166 [Thread-13] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Making backup [2019-06-14 04:59:30.166771] 2019-06-14 04:59:30.166 [Thread-13] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Backup complete [2019-06-14 04:59:42.441209] 2019-06-14 04:59:42.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 04:59:42.441230] 2019-06-14 04:59:42.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=6 [2019-06-14 04:59:42.441246] 2019-06-14 04:59:42.441 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"msg":5955} [2019-06-14 04:59:53.488472] 2019-06-14 04:59:53.488 [Thread-14] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {} [2019-06-14 04:59:53.488505] 2019-06-14 04:59:53.488 [Thread-14] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent ping [2019-06-14 04:59:53.488517] 2019-06-14 04:59:53.488 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=4 [2019-06-14 05:00:22.441291] 2019-06-14 05:00:22.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:00:22.441317] 2019-06-14 05:00:22.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=6 [2019-06-14 05:00:22.441321] 2019-06-14 05:00:22.441 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"msg":5956} [2019-06-14 05:00:23.488712] 2019-06-14 05:00:23.488 [Thread-12] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {} [2019-06-14 05:00:23.488737] 2019-06-14 05:00:23.488 [Thread-12] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent ping [2019-06-14 05:00:23.488739] 2019-06-14 05:00:23.488 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=4 [2019-06-14 05:00:30.172325] 2019-06-14 05:00:30.172 [Thread-3] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Making backup [2019-06-14 05:00:30.172352] 2019-06-14 05:00:30.172 [Thread-3] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Backup complete [2019-06-14 05:00:40.176895] 2019-06-14 05:00:40.176 [Thread-16] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Making backup [2019-06-14 05:00:40.176919] 2019-06-14 05:00:40.176 [Thread-16] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Backup complete [2019-06-14 05:00:53.488989] 2019-06-14 05:00:53.488 [Thread-14] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {} [2019-06-14 05:00:53.489016] 2019-06-14 05:00:53.488 [Thread-14] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent ping [2019-06-14 05:00:53.489020] 2019-06-14 05:00:53.488 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=4 [2019-06-14 05:01:02.441274] 2019-06-14 05:01:02.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:01:02.441295] 2019-06-14 05:01:02.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=6 [2019-06-14 05:01:02.441306] 2019-06-14 05:01:02.441 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"msg":5957} [2019-06-14 05:01:17.545607] 2019-06-14 05:01:17.545 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[124,"{\"ts\":\"2019-06-14T05:01:17.5344118Z\",\"49\":\"24.773|30\"}","2019-06-14T05:01:17.544Z"]]}],"msg":2429} [2019-06-14 05:01:17.545629] 2019-06-14 05:01:17.545 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=34 [2019-06-14 05:01:17.546320] 2019-06-14 05:01:17.546 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:01:17.546338] 2019-06-14 05:01:17.546 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=9 [2019-06-14 05:01:17.546340] 2019-06-14 05:01:17.546 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"ack":2429,"msg":5958} [2019-06-14 05:01:20.182263] 2019-06-14 05:01:20.182 [Thread-11] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Making backup [2019-06-14 05:01:20.182320] 2019-06-14 05:01:20.182 [Thread-11] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Backup complete [2019-06-14 05:01:30.185988] 2019-06-14 05:01:30.185 [Thread-6] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Making backup [2019-06-14 05:01:30.186014] 2019-06-14 05:01:30.185 [Thread-6] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Backup complete [2019-06-14 05:01:38.888962] 2019-06-14 05:01:38.888 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[124,"{\"ts\":\"2019-06-14T05:01:38.8753765Z\",\"52\":\"0.599999999999909|134\"}","2019-06-14T05:01:38.888Z"]]}],"msg":2430} [2019-06-14 05:01:38.889070] 2019-06-14 05:01:38.889 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=34 [2019-06-14 05:01:38.889663] 2019-06-14 05:01:38.889 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:01:38.889675] 2019-06-14 05:01:38.889 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=10 [2019-06-14 05:01:38.889677] 2019-06-14 05:01:38.889 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"ack":2430,"msg":5959} [2019-06-14 05:01:40.193820] 2019-06-14 05:01:40.193 [Thread-8] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Making backup [2019-06-14 05:01:40.193860] 2019-06-14 05:01:40.193 [Thread-8] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Backup complete [2019-06-14 05:02:02.441282] 2019-06-14 05:02:02.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:02:02.441306] 2019-06-14 05:02:02.441 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=7 [2019-06-14 05:02:02.441319] 2019-06-14 05:02:02.441 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"msg":5960} [2019-06-14 05:02:23.489473] 2019-06-14 05:02:23.489 [Thread-17] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {} [2019-06-14 05:02:23.489497] 2019-06-14 05:02:23.489 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=4 [2019-06-14 05:02:23.489499] 2019-06-14 05:02:23.489 [Thread-17] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent ping [2019-06-14 05:02:28.926881] 2019-06-14 05:02:28.917 [MQTT Rec: dglux2] ERROR org.dsa.iot.mqtt.Mqtt - Lost connection to MQTT [2019-06-14 05:02:28.926911] Connection lost (32109) - java.io.EOFException [2019-06-14 05:02:28.926920] at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:181) [2019-06-14 05:02:28.926922] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [2019-06-14 05:02:28.926924] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [2019-06-14 05:02:28.926926] at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [2019-06-14 05:02:28.926934] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [2019-06-14 05:02:28.926935] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [2019-06-14 05:02:28.926937] at java.base/java.lang.Thread.run(Thread.java:834) [2019-06-14 05:02:28.926940] Caused by: java.io.EOFException [2019-06-14 05:02:28.926941] at java.base/java.io.DataInputStream.readByte(DataInputStream.java:272) [2019-06-14 05:02:28.926942] at org.eclipse.paho.client.mqttv3.internal.wire.MqttInputStream.readMqttWireMessage(MqttInputStream.java:92) [2019-06-14 05:02:28.926944] at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:133) [2019-06-14 05:02:28.926947] ... 6 more [2019-06-14 05:02:28.926948] [2019-06-14 05:02:28.926949] 2019-06-14 05:02:28.917 [MQTT Rec: dglux2] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for 'in' [2019-06-14 05:02:28.926950] 2019-06-14 05:02:28.918 [MQTT Rec: dglux2] ERROR org.dsa.iot.mqtt.utils.ClientReceiver - Connection died (32104) [2019-06-14 05:02:29.042742] 2019-06-14 05:02:29.042 [Thread-14] INFO org.dsa.iot.mqtt.utils.ClientReceiver - Opened connection to MQTT at tcp://10.0.0.50 [2019-06-14 05:02:29.055174] 2019-06-14 05:02:29.054 [MQTT Rec: dglux2] ERROR org.dsa.iot.commons.GuaranteedReceiver - Unhandled exception [2019-06-14 05:02:29.055199] java.lang.RuntimeException: MqttException (0) - java.lang.InterruptedException [2019-06-14 05:02:29.055201] at org.dsa.iot.mqtt.Mqtt$4.handle(Mqtt.java:298) [2019-06-14 05:02:29.055203] at org.dsa.iot.mqtt.Mqtt$4.handle(Mqtt.java:292) [2019-06-14 05:02:29.055206] at org.dsa.iot.commons.GuaranteedReceiver.get(GuaranteedReceiver.java:180) [2019-06-14 05:02:29.055207] at org.dsa.iot.commons.GuaranteedReceiver.get(GuaranteedReceiver.java:135) [2019-06-14 05:02:29.055209] at org.dsa.iot.commons.GuaranteedReceiver.get(GuaranteedReceiver.java:195) [2019-06-14 05:02:29.055211] at org.dsa.iot.commons.GuaranteedReceiver.get(GuaranteedReceiver.java:135) [2019-06-14 05:02:29.055213] at org.dsa.iot.mqtt.Mqtt.get(Mqtt.java:188) [2019-06-14 05:02:29.055214] at org.dsa.iot.mqtt.Mqtt.subscribe(Mqtt.java:292) [2019-06-14 05:02:29.055216] at org.dsa.iot.mqtt.Mqtt.restoreSubscriptions(Mqtt.java:218) [2019-06-14 05:02:29.055221] at org.dsa.iot.mqtt.Mqtt.connectionLost(Mqtt.java:329) [2019-06-14 05:02:29.055223] at org.eclipse.paho.client.mqttv3.internal.CommsCallback.connectionLost(CommsCallback.java:292) [2019-06-14 05:02:29.055224] at org.eclipse.paho.client.mqttv3.internal.ClientComms.shutdownConnection(ClientComms.java:423) [2019-06-14 05:02:29.055225] at org.eclipse.paho.client.mqttv3.internal.CommsReceiver.run(CommsReceiver.java:181) [2019-06-14 05:02:29.055228] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [2019-06-14 05:02:29.055229] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [2019-06-14 05:02:29.055230] at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [2019-06-14 05:02:29.055234] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [2019-06-14 05:02:29.055235] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [2019-06-14 05:02:29.055236] at java.base/java.lang.Thread.run(Thread.java:834) [2019-06-14 05:02:29.055237] Caused by: MqttException (0) - java.lang.InterruptedException [2019-06-14 05:02:29.055240] at org.eclipse.paho.client.mqttv3.internal.Token.waitForResponse(Token.java:148) [2019-06-14 05:02:29.055241] at org.eclipse.paho.client.mqttv3.internal.Token.waitForCompletion(Token.java:108) [2019-06-14 05:02:29.055243] at org.eclipse.paho.client.mqttv3.MqttToken.waitForCompletion(MqttToken.java:67) [2019-06-14 05:02:29.055245] at org.eclipse.paho.client.mqttv3.MqttClient.subscribe(MqttClient.java:432) [2019-06-14 05:02:29.055247] at org.eclipse.paho.client.mqttv3.MqttClient.subscribe(MqttClient.java:424) [2019-06-14 05:02:29.055248] at org.dsa.iot.mqtt.Mqtt$4.handle(Mqtt.java:296) [2019-06-14 05:02:29.055249] ... 18 more [2019-06-14 05:02:29.055252] Caused by: java.lang.InterruptedException [2019-06-14 05:02:29.055253] at java.base/java.lang.Object.wait(Native Method) [2019-06-14 05:02:29.055254] at java.base/java.lang.Object.wait(Object.java:328) [2019-06-14 05:02:29.055257] at org.eclipse.paho.client.mqttv3.internal.Token.waitForResponse(Token.java:143) [2019-06-14 05:02:29.055258] ... 23 more [2019-06-14 05:02:29.055259] [2019-06-14 05:02:29.055261] 2019-06-14 05:02:29.054 [MQTT Rec: dglux2] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for 'state' [2019-06-14 05:02:29.059182] 2019-06-14 05:02:29.058 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[123,"{\"Con\":1,\"ChHash\":\"E0F763E2B7022DFA7C6EAC84534B6050\"}","2019-06-14T05:02:29.058Z"]]}],"msg":2431} [2019-06-14 05:02:29.059215] 2019-06-14 05:02:29.058 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=20 [2019-06-14 05:02:29.065025] 2019-06-14 05:02:29.059 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:02:29.065051] 2019-06-14 05:02:29.059 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=9 [2019-06-14 05:02:29.065056] 2019-06-14 05:02:29.060 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[121,"0","2019-06-14T05:02:29.060Z"]]}],"msg":2432} [2019-06-14 05:02:29.065058] 2019-06-14 05:02:29.061 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[119,"{\"Con\":1,\"ChHash\":\"E0F763E2B7022DFA7C6EAC84534B6050\"}","2019-06-14T05:02:29.060Z"]]}],"msg":2433} [2019-06-14 05:02:29.065795] 2019-06-14 05:02:29.065 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"ack":2431,"msg":5961} [2019-06-14 05:02:29.065805] 2019-06-14 05:02:29.065 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=16 [2019-06-14 05:02:29.065808] 2019-06-14 05:02:29.065 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=13 [2019-06-14 05:02:29.065916] 2019-06-14 05:02:29.065 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:02:29.065919] 2019-06-14 05:02:29.065 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=9 [2019-06-14 05:02:29.065921] 2019-06-14 05:02:29.065 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"ack":2433,"msg":5962} [2019-06-14 05:02:29.073838] 2019-06-14 05:02:29.072 [MQTT Rec: dglux2] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for '86105/in' [2019-06-14 05:02:29.073862] 2019-06-14 05:02:29.072 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[123,"{\"Con\":1,\"ChHash\":\"E0F763E2B7022DFA7C6EAC84534B6050\"}","2019-06-14T05:02:29.072Z"]]}],"msg":2434} [2019-06-14 05:02:29.073864] 2019-06-14 05:02:29.072 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=12 [2019-06-14 05:02:29.073866] 2019-06-14 05:02:29.072 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[121,"0","2019-06-14T05:02:29.072Z"]]}],"msg":2435} [2019-06-14 05:02:29.073870] 2019-06-14 05:02:29.072 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=9 [2019-06-14 05:02:29.073872] 2019-06-14 05:02:29.072 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[119,"{\"Con\":1,\"ChHash\":\"E0F763E2B7022DFA7C6EAC84534B6050\"}","2019-06-14T05:02:29.072Z"]]}],"msg":2436} [2019-06-14 05:02:29.073873] 2019-06-14 05:02:29.072 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=9 [2019-06-14 05:02:29.080031] 2019-06-14 05:02:29.079 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:02:29.080063] 2019-06-14 05:02:29.079 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=9 [2019-06-14 05:02:29.080066] 2019-06-14 05:02:29.079 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"ack":2436,"msg":5963} [2019-06-14 05:02:29.106951] 2019-06-14 05:02:29.106 [MQTT Rec: dglux2] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for '86105/state' [2019-06-14 05:02:29.109060] 2019-06-14 05:02:29.108 [MQTT Rec: dglux2] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for '86188/in' [2019-06-14 05:02:29.110776] 2019-06-14 05:02:29.110 [MQTT Rec: dglux2] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for '86188/state' [2019-06-14 05:02:29.112510] 2019-06-14 05:02:29.112 [MQTT Rec: dglux2] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for '85308/in' [2019-06-14 05:02:29.115479] 2019-06-14 05:02:29.115 [MQTT Rec: dglux2] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for '85308/state' [2019-06-14 05:03:07.414923] == Executing bash with arguments [/usr/local/dsa/dsa-server/dslinks/mqtt/bin/dslink-java-mqtt, --name, mqtt, --nodes, nodes.json, --key, .key, --log, debug, --broker, http://127.0.0.1:45331/conn, --token, p7Pc4YndvBLezA5VFpldMNvsYsUYLzz09WPoIVzgliv8SW65] (pid: 2730) == [2019-06-14 05:03:12.471298] 2019-06-14 05:03:12.469 [Thread-1] DEBUG org.dsa.iot.dslink.connection.ConnectionManager - Initiating connection sequence [2019-06-14 05:03:12.518903] 2019-06-14 05:03:12.518 [Thread-1] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework [2019-06-14 05:03:12.520912] 2019-06-14 05:03:12.520 [Thread-1] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024 [2019-06-14 05:03:12.521339] 2019-06-14 05:03:12.520 [Thread-1] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096 [2019-06-14 05:03:12.546785] 2019-06-14 05:03:12.545 [Thread-1] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 4 [2019-06-14 05:03:12.590028] 2019-06-14 05:03:12.589 [Thread-1] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false [2019-06-14 05:03:12.590462] 2019-06-14 05:03:12.590 [Thread-1] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512 [2019-06-14 05:03:12.620558] 2019-06-14 05:03:12.620 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false [2019-06-14 05:03:12.621018] 2019-06-14 05:03:12.620 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 11 [2019-06-14 05:03:12.626770] 2019-06-14 05:03:12.626 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available [2019-06-14 05:03:12.628248] 2019-06-14 05:03:12.627 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available [2019-06-14 05:03:12.629172] 2019-06-14 05:03:12.628 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available [2019-06-14 05:03:12.637210] 2019-06-14 05:03:12.636 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent0 - direct buffer constructor: unavailable [2019-06-14 05:03:12.637294] java.lang.UnsupportedOperationException: Reflective setAccessible(true) disabled [2019-06-14 05:03:12.637308] at io.netty.util.internal.ReflectionUtil.trySetAccessible(ReflectionUtil.java:31) [2019-06-14 05:03:12.637320] at io.netty.util.internal.PlatformDependent0$4.run(PlatformDependent0.java:224) [2019-06-14 05:03:12.637334] at java.base/java.security.AccessController.doPrivileged(Native Method) [2019-06-14 05:03:12.637345] at io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:218) [2019-06-14 05:03:12.637360] at io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:208) [2019-06-14 05:03:12.637372] at io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:79) [2019-06-14 05:03:12.637385] at io.netty.channel.nio.NioEventLoop.newTaskQueue(NioEventLoop.java:258) [2019-06-14 05:03:12.637397] at io.netty.util.concurrent.SingleThreadEventExecutor.<init>(SingleThreadEventExecutor.java:165) [2019-06-14 05:03:12.637409] at io.netty.channel.SingleThreadEventLoop.<init>(SingleThreadEventLoop.java:58) [2019-06-14 05:03:12.637423] at io.netty.channel.nio.NioEventLoop.<init>(NioEventLoop.java:141) [2019-06-14 05:03:12.637434] at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:127) [2019-06-14 05:03:12.637446] at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:36) [2019-06-14 05:03:12.637457] at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:84) [2019-06-14 05:03:12.637471] at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:58) [2019-06-14 05:03:12.637484] at io.netty.channel.MultithreadEventLoopGroup.<init>(MultithreadEventLoopGroup.java:52) [2019-06-14 05:03:12.638247] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:87) [2019-06-14 05:03:12.638296] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:82) [2019-06-14 05:03:12.638312] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:63) [2019-06-14 05:03:12.638322] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:51) [2019-06-14 05:03:12.638331] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:43) [2019-06-14 05:03:12.638345] at org.dsa.iot.shared.SharedObjects.getLoop(SharedObjects.java:38) [2019-06-14 05:03:12.638355] at org.dsa.iot.dslink.provider.netty.DefaultHttpProvider.post(DefaultHttpProvider.java:38) [2019-06-14 05:03:12.638364] at org.dsa.iot.dslink.util.http.HttpClient.post(HttpClient.java:33) [2019-06-14 05:03:12.638374] at org.dsa.iot.dslink.handshake.RemoteHandshake.generate(RemoteHandshake.java:101) [2019-06-14 05:03:12.638385] at org.dsa.iot.dslink.connection.ConnectionManager.generateHandshake(ConnectionManager.java:163) [2019-06-14 05:03:12.638394] at org.dsa.iot.dslink.connection.ConnectionManager.access$300(ConnectionManager.java:20) [2019-06-14 05:03:12.638404] at org.dsa.iot.dslink.connection.ConnectionManager$1.run(ConnectionManager.java:64) [2019-06-14 05:03:12.638413] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [2019-06-14 05:03:12.638425] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [2019-06-14 05:03:12.638434] at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [2019-06-14 05:03:12.638444] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [2019-06-14 05:03:12.638453] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [2019-06-14 05:03:12.639615] at java.base/java.lang.Thread.run(Thread.java:834) [2019-06-14 05:03:12.639643] [2019-06-14 05:03:12.643299] 2019-06-14 05:03:12.640 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: unavailable true [2019-06-14 05:03:12.645959] 2019-06-14 05:03:12.644 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable [2019-06-14 05:03:12.646022] java.lang.IllegalAccessException: class io.netty.util.internal.PlatformDependent0$6 cannot access class jdk.internal.misc.Unsafe (in module java.base) because module java.base does not export jdk.internal.misc to unnamed module @10511838 [2019-06-14 05:03:12.646034] at java.base/jdk.internal.reflect.Reflection.newIllegalAccessException(Reflection.java:361) [2019-06-14 05:03:12.646043] at java.base/java.lang.reflect.AccessibleObject.checkAccess(AccessibleObject.java:591) [2019-06-14 05:03:12.646051] at java.base/java.lang.reflect.Method.invoke(Method.java:558) [2019-06-14 05:03:12.646060] at io.netty.util.internal.PlatformDependent0$6.run(PlatformDependent0.java:315) [2019-06-14 05:03:12.646067] at java.base/java.security.AccessController.doPrivileged(Native Method) [2019-06-14 05:03:12.646075] at io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:306) [2019-06-14 05:03:12.646083] at io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:208) [2019-06-14 05:03:12.646092] at io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:79) [2019-06-14 05:03:12.646100] at io.netty.channel.nio.NioEventLoop.newTaskQueue(NioEventLoop.java:258) [2019-06-14 05:03:12.646107] at io.netty.util.concurrent.SingleThreadEventExecutor.<init>(SingleThreadEventExecutor.java:165) [2019-06-14 05:03:12.646115] at io.netty.channel.SingleThreadEventLoop.<init>(SingleThreadEventLoop.java:58) [2019-06-14 05:03:12.646124] at io.netty.channel.nio.NioEventLoop.<init>(NioEventLoop.java:141) [2019-06-14 05:03:12.646131] at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:127) [2019-06-14 05:03:12.646139] at io.netty.channel.nio.NioEventLoopGroup.newChild(NioEventLoopGroup.java:36) [2019-06-14 05:03:12.646146] at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:84) [2019-06-14 05:03:12.646161] at io.netty.util.concurrent.MultithreadEventExecutorGroup.<init>(MultithreadEventExecutorGroup.java:58) [2019-06-14 05:03:12.646168] at io.netty.channel.MultithreadEventLoopGroup.<init>(MultithreadEventLoopGroup.java:52) [2019-06-14 05:03:12.646177] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:87) [2019-06-14 05:03:12.646185] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:82) [2019-06-14 05:03:12.646192] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:63) [2019-06-14 05:03:12.646200] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:51) [2019-06-14 05:03:12.646209] at io.netty.channel.nio.NioEventLoopGroup.<init>(NioEventLoopGroup.java:43) [2019-06-14 05:03:12.646216] at org.dsa.iot.shared.SharedObjects.getLoop(SharedObjects.java:38) [2019-06-14 05:03:12.646224] at org.dsa.iot.dslink.provider.netty.DefaultHttpProvider.post(DefaultHttpProvider.java:38) [2019-06-14 05:03:12.646231] at org.dsa.iot.dslink.util.http.HttpClient.post(HttpClient.java:33) [2019-06-14 05:03:12.646240] at org.dsa.iot.dslink.handshake.RemoteHandshake.generate(RemoteHandshake.java:101) [2019-06-14 05:03:12.646248] at org.dsa.iot.dslink.connection.ConnectionManager.generateHandshake(ConnectionManager.java:163) [2019-06-14 05:03:12.646255] at org.dsa.iot.dslink.connection.ConnectionManager.access$300(ConnectionManager.java:20) [2019-06-14 05:03:12.646263] at org.dsa.iot.dslink.connection.ConnectionManager$1.run(ConnectionManager.java:64) [2019-06-14 05:03:12.646272] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [2019-06-14 05:03:12.646279] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [2019-06-14 05:03:12.646287] at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [2019-06-14 05:03:12.646294] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [2019-06-14 05:03:12.646303] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [2019-06-14 05:03:12.646311] at java.base/java.lang.Thread.run(Thread.java:834) [2019-06-14 05:03:12.646318] [2019-06-14 05:03:12.646326] 2019-06-14 05:03:12.645 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): unavailable [2019-06-14 05:03:12.646335] 2019-06-14 05:03:12.645 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available [2019-06-14 05:03:12.753982] 2019-06-14 05:03:12.751 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent - maxDirectMemory: 2092957696 bytes (maybe) [2019-06-14 05:03:12.754473] 2019-06-14 05:03:12.754 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: /tmp (java.io.tmpdir) [2019-06-14 05:03:12.754799] 2019-06-14 05:03:12.754 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model) [2019-06-14 05:03:12.755794] 2019-06-14 05:03:12.755 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false [2019-06-14 05:03:12.756268] 2019-06-14 05:03:12.756 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: -1 bytes [2019-06-14 05:03:12.756878] 2019-06-14 05:03:12.756 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1 [2019-06-14 05:03:12.757247] 2019-06-14 05:03:12.757 [Thread-1] DEBUG io.netty.util.internal.CleanerJava9 - java.nio.ByteBuffer.cleaner(): available [2019-06-14 05:03:12.764261] 2019-06-14 05:03:12.763 [Thread-1] DEBUG io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available [2019-06-14 05:03:12.870626] 2019-06-14 05:03:12.869 [Thread-1] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 2730 (auto-detected) [2019-06-14 05:03:12.873391] 2019-06-14 05:03:12.873 [Thread-1] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false [2019-06-14 05:03:12.873492] 2019-06-14 05:03:12.873 [Thread-1] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false [2019-06-14 05:03:12.877108] 2019-06-14 05:03:12.876 [Thread-1] DEBUG io.netty.util.NetUtil - Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo) [2019-06-14 05:03:12.878424] 2019-06-14 05:03:12.878 [Thread-1] DEBUG io.netty.util.NetUtil - /proc/sys/net/core/somaxconn: 128 [2019-06-14 05:03:12.880549] 2019-06-14 05:03:12.880 [Thread-1] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 00:50:56:ff:fe:b2:fb:8b (auto-detected) [2019-06-14 05:03:12.893217] 2019-06-14 05:03:12.892 [Thread-1] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple [2019-06-14 05:03:12.893604] 2019-06-14 05:03:12.893 [Thread-1] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4 [2019-06-14 05:03:12.915953] 2019-06-14 05:03:12.915 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 4 [2019-06-14 05:03:12.916092] 2019-06-14 05:03:12.915 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 4 [2019-06-14 05:03:12.916106] 2019-06-14 05:03:12.915 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192 [2019-06-14 05:03:12.916114] 2019-06-14 05:03:12.915 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11 [2019-06-14 05:03:12.916127] 2019-06-14 05:03:12.915 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216 [2019-06-14 05:03:12.916135] 2019-06-14 05:03:12.915 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512 [2019-06-14 05:03:12.916196] 2019-06-14 05:03:12.916 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256 [2019-06-14 05:03:12.916208] 2019-06-14 05:03:12.916 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64 [2019-06-14 05:03:12.917339] 2019-06-14 05:03:12.916 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768 [2019-06-14 05:03:12.917401] 2019-06-14 05:03:12.916 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192 [2019-06-14 05:03:12.917412] 2019-06-14 05:03:12.916 [Thread-1] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true [2019-06-14 05:03:12.928116] 2019-06-14 05:03:12.927 [Thread-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled [2019-06-14 05:03:12.928868] 2019-06-14 05:03:12.927 [Thread-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0 [2019-06-14 05:03:12.928903] 2019-06-14 05:03:12.928 [Thread-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384 [2019-06-14 05:03:13.050989] 2019-06-14 05:03:13.050 [nioEventLoopGroup-2-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.bytebuf.checkAccessible: true [2019-06-14 05:03:13.055420] 2019-06-14 05:03:13.052 [nioEventLoopGroup-2-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@6e400232 [2019-06-14 05:03:13.100824] 2019-06-14 05:03:13.100 [Thread-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096 [2019-06-14 05:03:13.100909] 2019-06-14 05:03:13.100 [Thread-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2 [2019-06-14 05:03:13.100918] 2019-06-14 05:03:13.100 [Thread-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16 [2019-06-14 05:03:13.100931] 2019-06-14 05:03:13.100 [Thread-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8 [2019-06-14 05:03:13.475858] 2019-06-14 05:03:13.474 [Thread-2] DEBUG org.dsa.iot.dslink.serializer.SerializationManager - Restored nodes.json [2019-06-14 05:03:13.554454] 2019-06-14 05:03:13.553 [Thread-3] INFO org.dsa.iot.mqtt.Mqtt - Restoring connection to server 'emq' [2019-06-14 05:03:13.567038] 2019-06-14 05:03:13.565 [Thread-2] INFO org.dsa.iot.mqtt.Main - Initialized [2019-06-14 05:03:13.572529] 2019-06-14 05:03:13.571 [Thread-3] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for 'in' [2019-06-14 05:03:13.582745] 2019-06-14 05:03:13.580 [Thread-3] INFO org.dsa.iot.mqtt.Mqtt - Restoring subscription for 'state' [2019-06-14 05:03:13.585315] 2019-06-14 05:03:13.584 [Thread-1] DEBUG org.dsa.iot.dslink.connection.QueuedWriteManager - -Ddslink.dispatchDelay: 10 [2019-06-14 05:03:13.661905] 2019-06-14 05:03:13.660 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.compression.ZlibCodecFactory - -Dio.netty.noJdkZlibDecoder: false [2019-06-14 05:03:13.661986] 2019-06-14 05:03:13.660 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.compression.ZlibCodecFactory - -Dio.netty.noJdkZlibEncoder: false [2019-06-14 05:03:13.695163] 2019-06-14 05:03:13.694 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocketClientHandshaker13 - WebSocket version 13 client handshake key: 6GzE+y2cMrSYfD+FRCUgwg==, expected response: GcTO3fWNs5apf04ecAlVFo4akIU= [2019-06-14 05:03:13.798580] 2019-06-14 05:03:13.797 [Thread-3] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {} [2019-06-14 05:03:13.798680] 2019-06-14 05:03:13.797 [Thread-3] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent ping [2019-06-14 05:03:13.839101] 2019-06-14 05:03:13.821 [nioEventLoopGroup-2-2] INFO org.dsa.iot.mqtt.Main - Connected [2019-06-14 05:03:13.843705] 2019-06-14 05:03:13.841 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:03:13.843790] 2019-06-14 05:03:13.841 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=4 [2019-06-14 05:03:13.893613] 2019-06-14 05:03:13.893 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {} [2019-06-14 05:03:13.894068] 2019-06-14 05:03:13.893 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame opCode=1 [2019-06-14 05:03:13.894386] 2019-06-14 05:03:13.894 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameDecoder - Decoding WebSocket Frame length=204 [2019-06-14 05:03:13.901991] 2019-06-14 05:03:13.900 [Thread-4] INFO org.dsa.iot.mqtt.utils.ClientReceiver - Opened connection to MQTT at tcp://10.0.0.50 [2019-06-14 05:03:13.902070] 2019-06-14 05:03:13.901 [nioEventLoopGroup-2-2] DEBUG org.dsa.iot.dslink.connection.DataHandler - Received data (json): {"salt":"qB0waDbYKswXkB0kc6cc","requests":[{"method":"list","path":"/emq/data","rid":1},{"method":"subscribe","paths":[{"path":"/emq/data/86188/state","sid":3},{"path":"/emq/data/85308/in","sid":6},{"path":"/emq/data/86105/state","sid":7},{"path":"/emq/data/86188/in","sid":4},{"path":"/dglux/data/23456/in","sid":2},{"path":"/emq/data/85308/state","sid":5},{"path":"/dglux/data/23456/state","sid":1},{"path":"/emq/data/86105/in","sid":8}],"rid":2},{"method":"unsubscribe","sids":[3,4,5,6,7,8],"rid":3}],"msg":1} [2019-06-14 05:03:13.913531] 2019-06-14 05:03:13.913 [Thread-1] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":1,"stream":"open","updates":[["86188",{"$is":"node"}]]}],"msg":1} [2019-06-14 05:03:13.914100] 2019-06-14 05:03:13.913 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=4 [2019-06-14 05:03:13.916710] 2019-06-14 05:03:13.915 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=78 [2019-06-14 05:03:13.919122] 2019-06-14 05:03:13.918 [Thread-1] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":1,"stream":"open","updates":[["85308",{"$is":"node"}]]}],"msg":2} [2019-06-14 05:03:13.921677] 2019-06-14 05:03:13.921 [Thread-1] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":1,"stream":"open","updates":[["86105",{"$is":"node"}]]}],"msg":3} [2019-06-14 05:03:13.927653] 2019-06-14 05:03:13.927 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[3,null,"2019-06-14T05:03:13.913Z"]]}],"msg":4} [2019-06-14 05:03:13.928312] 2019-06-14 05:03:13.928 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[6,null,"2019-06-14T05:03:13.918Z"]]}],"msg":5} [2019-06-14 05:03:13.930839] 2019-06-14 05:03:13.929 [nioEventLoopGroup-2-2] DEBUG io.netty.handler.codec.http.websocketx.WebSocket08FrameEncoder - Encoding WebSocket Frame opCode=1 length=12 [2019-06-14 05:03:13.930881] 2019-06-14 05:03:13.929 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[7,null,"2019-06-14T05:03:13.921Z"]]}],"msg":6} [2019-06-14 05:03:13.930894] 2019-06-14 05:03:13.930 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[4,null,"2019-06-14T05:03:13.924Z"]]}],"msg":7} [2019-06-14 05:03:13.933364] 2019-06-14 05:03:13.930 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[5,null,"2019-06-14T05:03:13.929Z"]]}],"msg":8} [2019-06-14 05:03:13.935107] 2019-06-14 05:03:13.934 [Subscription Writer] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"responses":[{"rid":0,"updates":[[8,null,"2019-06-14T05:03:13.933Z"]]}],"msg":9} [2019-06-14 05:03:13.937363] 2019-06-14 05:03:13.935 [Thread-1] DEBUG org.dsa.iot.dslink.connection.connector.WebSocketConnector - Sent data (json): {"ack":1}

[ketanvh]

@RainerMueller82 could you please report your issue to support@atrius-iot.com