MQTT traffic but no Node-Red LoRa Net NODE traffic

[Albert Beukman]

MQTT traffic but no Node-Red LoRa Net NODE traffic

***Summary***
MTCDT-LVW2-247A Firmware1.4.3
LNS v1.0.31
MQTT LoRa traffic but no Node-Red LoRa Net NODE traffic
LoRa Net NODE shows connected. Debug entire message object connected directly to LoRa Net node shows nothing.
LoRa network server log shows upstream messages coming in.
Mosquito log shows no activity while MQTT debug shown below is generated.
LoRa Net Downstream NODE and LoRa Net Downstream NODE inputs do not request ACK from end device.

Restarting Node-Red recovers the system, and messages arrive at the LoRa Net NODE.
Publishing flow connected to MQTT node recovers the system, and messages arrive at the LoRa Net NODE.
Issue seems to be cumulative as it works initially after the Node-Red restarts, but stops working with no change in settings, only 2-way traffic.

Any input on why this happens or how to prevent it would be greatly appreciated

***Detail/Logs***

MQTT debug

1/8/2018, 1:38:06 PM[MQTT ALL]
lora/00-04-a3-0b-00-20-e5-f6/packet_recv : [msg] : object
{ "topic": "lora/00-04-a3-0b-00-20-e5-f6/packet_recv", "payload": "{\"chan\":7,\"codr\":\"4/5\",\"data\":\"QAMAAAAA/ADAJO0dG4mqrIdF\",\"datr\":\"SF7BW125\",\"freq\":903.70000000000005,\"lsnr\":8.8000000000000007,\"modu\":\"LORA\",\"rfch\":1,\"rssi\":-71,\"size\":18,\"stat\":1,\"tmst\":640740716}", "qos": 1, "retain": false, "_topic": "lora/00-04-a3-0b-00-20-e5-f6/packet_recv", "_msgid": "419d620b.be629c" }
1/8/2018, 1:38:08 PM[MQTT ALL]
lora/00-04-a3-0b-00-20-e5-f6/up : [msg] : object
{ "topic": "lora/00-04-a3-0b-00-20-e5-f6/up", "payload": "{\"ack\":false,\"adr\":false,\"appeui\":\"88-77-66-55-44-33-22-11\",\"chan\":7,\"cls\":0,\"codr\":\"4/5\",\"data\":\"AgUJBwM=\",\"datr\":\"SF7BW125\",\"deveui\":\"00-04-a3-0b-00-20-e5-f6\",\"freq\":\"903.7\",\"lsnr\":\"8.8\",\"mhdr\":\"400300000000fc00\",\"modu\":\"LORA\",\"opts\":\"\",\"port\":192,\"rfch\":1,\"rssi\":-71,\"seqn\":252,\"size\":8,\"timestamp\":\"2018-01-08T21:38:03.980753Z\",\"tmst\":640740716}", "qos": 1, "retain": false, "_topic": "lora/00-04-a3-0b-00-20-e5-f6/up", "_msgid": "e26911ef.1d96f" }
1/8/2018, 1:38:12 PM[MQTT ALL]
lora/00-04-a3-0b-00-20-8d-5d/packet_recv : [msg] : object
{ "topic": "lora/00-04-a3-0b-00-20-8d-5d/packet_recv", "payload": "{\"chan\":7,\"codr\":\"4/5\",\"data\":\"gAEAAAAARwCg8+OdRbtFMyU9\",\"datr\":\"SF10BW125\",\"freq\":903.70000000000005,\"lsnr\":8.8000000000000007,\"modu\":\"LORA\",\"rfch\":1,\"rssi\":-31,\"size\":18,\"stat\":1,\"tmst\":646510732}", "qos": 1, "retain": false, "_topic": "lora/00-04-a3-0b-00-20-8d-5d/packet_recv", "_msgid": "bdb2cb14.424d38" }
1/8/2018, 1:38:12 PM[MQTT ALL]
lora/00-04-a3-0b-00-20-8d-5d/up : [msg] : object
{ "topic": "lora/00-04-a3-0b-00-20-8d-5d/up", "payload": "{\"ack\":false,\"adr\":false,\"appeui\":\"88-77-66-55-44-33-22-11\",\"chan\":7,\"cls\":0,\"codr\":\"4/5\",\"data\":\"AgUIBgU=\",\"datr\":\"SF10BW125\",\"deveui\":\"00-04-a3-0b-00-20-8d-5d\",\"freq\":\"903.7\",\"lsnr\":\"8.8\",\"mhdr\":\"8001000000004700\",\"modu\":\"LORA\",\"opts\":\"\",\"port\":160,\"rfch\":1,\"rssi\":-31,\"seqn\":71,\"size\":8,\"timestamp\":\"2018-01-08T21:38:09.746390Z\",\"tmst\":646510732}", "qos": 1, "retain": false, "_topic": "lora/00-04-a3-0b-00-20-8d-5d/up", "_msgid": "bf505d2f.40afa" }
1/8/2018, 1:38:13 PM[MQTT ALL]
lora/00-04-a3-0b-00-20-8d-5d/packet_sent : [msg] : object
{ "topic": "lora/00-04-a3-0b-00-20-8d-5d/packet_sent", "payload": "{\"appeui\":\"88-77-66-55-44-33-22-11\",\"codr\":\"4/5\",\"data\":\"YAEAAAAgRwCm/14o\",\"datr\":\"SF10BW500\",\"deveui\":\"00-04-a3-0b-00-20-8d-5d\",\"freq\":927.5,\"ipol\":true,\"modu\":\"LORA\",\"ncrc\":true,\"powe\":29,\"rfch\":0,\"size\":12,\"tmst\":647510732}", "qos": 1, "retain": false, "_topic": "lora/00-04-a3-0b-00-20-8d-5d/packet_sent", "_msgid": "6b452932.94bad8" }
1/8/2018, 1:38:20 PM[MQTT ALL]
lora/00-04-a3-0b-00-1e-8e-21/packet_recv : [msg] : object
{ "topic": "lora/00-04-a3-0b-00-1e-8e-21/packet_recv", "payload": "{\"chan\":3,\"codr\":\"4/5\",\"data\":\"gAQAAAAAEgDAg8jXWPxkKobk\",\"datr\":\"SF10BW125\",\"freq\":902.89999999999998,\"lsnr\":9,\"modu\":\"LORA\",\"rfch\":0,\"rssi\":-62,\"size\":18,\"stat\":1,\"tmst\":654532644}", "qos": 1, "retain": false, "_topic": "lora/00-04-a3-0b-00-1e-8e-21/packet_recv", "_msgid": "f93455f8.06cba8" }
1/8/2018, 1:38:20 PM[MQTT ALL]
lora/00-04-a3-0b-00-1e-8e-21/up : [msg] : object
{ "topic": "lora/00-04-a3-0b-00-1e-8e-21/up", "payload": "{\"ack\":false,\"adr\":false,\"appeui\":\"88-77-66-55-44-33-22-11\",\"chan\":3,\"cls\":0,\"codr\":\"4/5\",\"data\":\"+gUIBwM=\",\"datr\":\"SF10BW125\",\"deveui\":\"00-04-a3-0b-00-1e-8e-21\",\"freq\":\"902.9\",\"lsnr\":\"9\",\"mhdr\":\"8004000000001200\",\"modu\":\"LORA\",\"opts\":\"\",\"port\":192,\"rfch\":0,\"rssi\":-62,\"seqn\":18,\"size\":8,\"timestamp\":\"2018-01-08T21:38:17.776794Z\",\"tmst\":654532644}", "qos": 1, "retain": false, "_topic": "lora/00-04-a3-0b-00-1e-8e-21/up", "_msgid": "301bd4a5.cfe42c" }
1/8/2018, 1:38:21 PM[MQTT ALL]
lora/00-04-a3-0b-00-1e-8e-21/packet_sent : [msg] : object
{ "topic": "lora/00-04-a3-0b-00-1e-8e-21/packet_sent", "payload": "{\"appeui\":\"88-77-66-55-44-33-22-11\",\"codr\":\"4/5\",\"data\":\"YAQAAAAgEwAO9VA6\",\"datr\":\"SF10BW500\",\"deveui\":\"00-04-a3-0b-00-1e-8e-21\",\"freq\":925.10000000000002,\"ipol\":true,\"modu\":\"LORA\",\"ncrc\":true,\"powe\":29,\"rfch\":0,\"size\":12,\"tmst\":655532644}", "qos": 1, "retain": false, "_topic": "lora/00-04-a3-0b-00-1e-8e-21/packet_sent", "_msgid": "bb4f96fd.44b068" }

Network server shows activity

admin@mtcdt:/var/log# tail -f messages | grep lora
Jan  8 13:45:13 mtcdt user.info lora-network-server: GW:00:80:00:00:a0:00:14:77|UDP-TX|JSON-SIZE:237
Jan  8 13:45:13 mtcdt user.info lora-network-server: GW:00:80:00:00:a0:00:14:77|TX-ACK|OK
Jan  8 13:45:15 mtcdt user.info lora-network-server: GW:00:80:00:00:a0:00:14:77|FRAME-RX|Parsing 1 packets
Jan  8 13:45:15 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-1e-2e-29|CHECK-PKT|FCNT: 000000aa LAST-FCNT: 000000a9 Duplicate: no
Jan  8 13:45:15 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-1e-2e-29|CHECK-MIC|ADDR: 00:00:00:02 passed
Jan  8 13:45:15 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-1e-2e-29|PER|1.117318%
Jan  8 13:45:15 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-1e-2e-29|FCTRL|ADR:0 ADRACK:0 ACK:0 CLASS:A OPTS:0 
Jan  8 13:45:15 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-1e-2e-29|SCHED-TX|Use RX1 TOA:82 ms
Jan  8 13:45:16 mtcdt user.info lora-network-server: GW:00:80:00:00:a0:00:14:77|FRAME-TX|IP: 127.0.0.1:42611 CH: LC7 NODE: 00:00:00:02 FCNT: 000000af REPEAT: 0
Jan  8 13:45:16 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-1e-2e-29|SCHED-TX|Q-SIZE: 0 PKT-SIZE: 416 PKT-ROOM: 242
Jan  8 13:45:16 mtcdt user.info lora-network-server: GW:00:80:00:00:a0:00:14:77|UDP-TX|JSON-SIZE:250
Jan  8 13:45:16 mtcdt user.info lora-network-server: GW:00:80:00:00:a0:00:14:77|TX-ACK|OK
Jan  8 13:45:24 mtcdt user.info lora-network-server: GW:00:80:00:00:a0:00:14:77|FRAME-RX|Parsing 1 packets
Jan  8 13:45:24 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-20-e5-f6|CHECK-PKT|FCNT: 00000103 LAST-FCNT: 00000102 Duplicate: no
Jan  8 13:45:24 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-20-e5-f6|CHECK-MIC|ADDR: 00:00:00:03 passed
Jan  8 13:45:24 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-20-e5-f6|PER|3.409091%
Jan  8 13:45:24 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-20-e5-f6|FCTRL|ADR:0 ADRACK:0 ACK:0 CLASS:A OPTS:0 
Jan  8 13:45:24 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-20-e5-f6|SCHED-TX|Use RX1 TOA:21 ms
Jan  8 13:45:25 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-20-e5-f6|FRAME-TX|Nothing to transmit
Jan  8 13:45:34 mtcdt user.info lora-network-server: GW:00:80:00:00:a0:00:14:77|FRAME-RX|Parsing 1 packets
Jan  8 13:45:34 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-20-8d-5d|CHECK-PKT|FCNT: 0000005b LAST-FCNT: 0000005a Duplicate: no
Jan  8 13:45:34 mtcdt user.info lora-network-server: ED:00-04-a3-0b-00-20-8d-5d|CHECK-MIC|ADDR: 00:00:00:01 passed

Mosquito log

1515442510: mosquitto version 1.4 (build date 2017-06-05 08:47:44-0500) starting
1515442510: Config loaded from /etc/mosquitto/mosquitto.conf.
1515442510: Opening ipv4 listen socket on port 1883.
1515442510: Warning: Mosquitto should not be run as root/administrator.
1515442546: New connection from 127.0.0.1 on port 1883.
1515442546: New client connected from 127.0.0.1 as 8877665544332211 (c1, k60).
1515442705: New connection from 127.0.0.1 on port 1883.
1515442705: New client connected from 127.0.0.1 as mqtt_c2985d15.3d67a (c1, k15).
1515442706: New connection from 127.0.0.1 on port 1883.
1515442707: New connection from 127.0.0.1 on port 1883.
1515442707: New client connected from 127.0.0.1 as mqttjs_d9f2106ad7082b84 (c1, k60).
1515442708: New client connected from 127.0.0.1 as mqttjs_b0c923ae36c117fe (c1, k60).
1515443745: Client mqtt_c2985d15.3d67a has exceeded timeout, disconnecting.
1515443745: Socket error on client mqtt_c2985d15.3d67a, disconnecting.
1515443803: New connection from 127.0.0.1 on port 1883.
1515443807: New client connected from 127.0.0.1 as mqtt_c2985d15.3d67a (c1, k15).
1515445029: Client mqtt_c2985d15.3d67a has exceeded timeout, disconnecting.
1515445029: Socket error on client mqtt_c2985d15.3d67a, disconnecting.
1515445088: New connection from 127.0.0.1 on port 1883.
1515445117: New client connected from 127.0.0.1 as mqtt_c2985d15.3d67a (c1, k15).
1515445190: Client mqtt_c2985d15.3d67a has exceeded timeout, disconnecting.
1515445190: Socket error on client mqtt_c2985d15.3d67a, disconnecting.
1515445223: New connection from 127.0.0.1 on port 1883.
1515445225: New client connected from 127.0.0.1 as mqtt_c2985d15.3d67a (c1, k15).
1515445351: Client mqtt_c2985d15.3d67a has exceeded timeout, disconnecting.
1515445351: Socket error on client mqtt_c2985d15.3d67a, disconnecting.
1515445408: Client mqttjs_b0c923ae36c117fe has exceeded timeout, disconnecting.
1515445408: Socket error on client mqttjs_b0c923ae36c117fe, disconnecting.
1515445434: New connection from 127.0.0.1 on port 1883.
1515445434: New client connected from 127.0.0.1 as mqtt_c2985d15.3d67a (c1, k15).
1515445440: New connection from 127.0.0.1 on port 1883.
1515445442: New client connected from 127.0.0.1 as mqttjs_b0c923ae36c117fe (c1, k60).

Node-Red logs around time of recovery by publishing new node mentioned in summary

8 Jan 13:02:54 - [mqtt] [f9af2bcb.0650d8] connection lost to broker tcp://localhost:1883
8 Jan 13:03:54 - [mqtt] [f9af2bcb.0650d8] connected to broker tcp://localhost:1883
8 Jan 13:03:56 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 13:04:00 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 13:04:02 - [info] [lora in:LoRa Net Up] Connected to MQTT for LoRa in node.
8 Jan 13:05:58 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 13:06:02 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 13:07:58 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 13:08:00 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 13:10:57 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 13:11:03 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 13:37:07 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 13:37:12 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
//Period of inactivity where activity expected
8 Jan 14:00:13 - [info] [lora out:LoRa Net Downstream] Published downstream lora packet
8 Jan 14:02:23 - [info] Stopping modified flows
8 Jan 14:02:23 - [info] [lora in:LoRa Net Up] LoRa in node closing...
8 Jan 14:02:23 - [info] [udp out:d3d09100.2c2f7] udp output stopped
8 Jan 14:02:23 - [info] [lora out:LoRa Net Downstream] LoRa out node closing...
8 Jan 14:02:23 - [info] [udp in:af15b462.50ea48] udp listener stopped
8 Jan 14:02:23 - [info] Stopped modified flows
8 Jan 14:02:25 - [info] Starting modified flows
8 Jan 14:02:25 - [info] [lora out:LoRa Net Downstream] lora out node created
8 Jan 14:02:25 - [info] [udp out:d3d09100.2c2f7] node-red:udp.errors.ready-nolocal
8 Jan 14:02:35 - [info] [lora in:LoRa Net Up] lora in node created
8 Jan 14:02:52 - [info] Started modified flows
8 Jan 14:02:52 - [info] [udp in:af15b462.50ea48] udp listener at 0.0.0.0:20203
8 Jan 14:02:55 - [mqtt] [f9af2bcb.0650d8] connection lost to broker tcp://localhost:1883
8 Jan 14:02:55 - [info] [lora out:LoRa Net Downstream] mcard: true
8 Jan 14:02:55 - [info] [lora in:LoRa Net Up] mcard: true
8 Jan 14:02:55 - [info] [lora out:LoRa Net Downstream] Connected to MQTT for LoRa out node.
8 Jan 14:02:55 - [info] [lora in:LoRa Net Up] Connected to MQTT for LoRa in node.

[Albert Beukman]

Upgraded the LNS to v1.0.43.

Was unable to recreate using Conduit MTCDT-LVW2-247A v1.4.3 and LNS v1.0.43. Attempted to increase traffic as this tended to correlate with the symptom reported above (using LNSv1.0.31).

Possible contributors from LNS change logs (http://www.multitech.net/developer/software/mlinux/lora-network-server-changelog/).
* Bug (known issue) in v1.0.31 (came by default) : Downlink will not be scheduled with uplink counter rolls over 16-bit max
** v1.0.26 good version
** > v1.0.32 good version.
* Bug (known issue) in v1.0.37. Multiple packets for first downlink to set end-device channels and datarates through ADR or AddChannel commands may be scheduled multiple times. Downlink packets will not be cleared until ACK’d by end-device
** > v1.0.41 bug fix : Only one packet will be scheduled with Channel Mask or Additional Channels in first downlink. This packet will be sent until device ACK’s receipt.

[Jason Reiss]

We have an update for AEP soon to be released.
It has a fix to reconnect the lora-in node

See /opt/node-red/nodes/core/lora/lora.js

The current release has this line outside of the ‘connect’ handler
client.subscribe(mqttTopic);

The fixed code for SetupLoraInNode function:

  function SetupLoraInNode(node, config) {
    var mqttTopic = 'lora/+/up';
    var client = mqtt.connect(mqttServer).on('error', function(error) {
      node.error("LoRa in node MQTT error: " + error);
      setStatus(node, "error");
    }).on('connect', function() {
      node.log("Connected to MQTT for LoRa in node.");
      setStatus(node, "connected");
      client.subscribe(mqttTopic);
    }).on("reconnect", function() {
      node.log("LoRa-IN node reconnect");
      setStatus(node, "disconnected");
    }).on("error", function() {
      node.log("LoRa-IN node error");
      setStatus(node, "disconnected");
    }).on('message', function(topic, message) {
      var arr = topic.split("/");
      var obj = JSON.parse(message);
      var data;
      if (config.datatype === "utf8") {
        data = new Buffer(obj.data, 'base64').toString('utf-8');
      } else if (config.datatype === "bytes") {
        data = new Buffer(obj.data, 'base64');
      } else {
        node.error("Invalid datatype.");
        return;
      }
      if (obj.data) { // moving the data to the payload for use in Node-RED
        obj.payload = data;
        delete obj.data;
      }
      obj.eui = arr[1];
      node.send(obj);
    });
            
    node.on("close", function() {
      node.log("LoRa in node closing...");
      setStatus(node, "disconnected");
      client.end();
    });
  }

[Author]

Posts