[SOLVED] Frequent MQTT disconnections; "Device Already Connected"


#1

Every minute, I seem to disconnect from Structure’s broker. The device connection log is reporting that my client is already connected. I’m trying to determine whether or not this is on Node-Red’s side or Losant’s. Here are some logs:

13 Apr 14:27:10 - [info] Loading palette nodes
13 Apr 14:27:21 - [warn] ------------------------------------------
13 Apr 14:27:21 - [warn] [rpi-gpio] Info : Ignoring Raspberry Pi specific node
13 Apr 14:27:21 - [warn] ------------------------------------------
13 Apr 14:27:21 - [info] Settings file  : /home/boneskull/.node-red/settings.js
13 Apr 14:27:21 - [info] User directory : /home/boneskull/.node-red
13 Apr 14:27:21 - [info] Flows file : /home/boneskull/.node-red/flows_geist.json
13 Apr 14:27:21 - [info] Server now running at http://127.0.0.1:1880/
13 Apr 14:27:21 - [info] Starting flows
1460582841456 Device(s) Firmata
13 Apr 14:27:21 - [info] [inject:left state interval] repeat = 60000
13 Apr 14:27:21 - [info] [inject:right state interval] repeat = 60000
13 Apr 14:27:21 - [info] Started flows
1460582841872 Connected Firmata
13 Apr 14:27:22 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: xxxxx@mqtts://broker.getstructure.io:8883
13 Apr 14:27:26 - [info] [nodebot:dink] io ready
13 Apr 14:28:12 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: xxxxx@mqtts://broker.getstructure.io:8883
13 Apr 14:28:28 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: xxxxx@mqtts://broker.getstructure.io:8883
13 Apr 14:29:18 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: xxxxx@mqtts://broker.getstructure.io:8883
13 Apr 14:29:33 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: xxxxx@mqtts://broker.getstructure.io:8883

What could cause this behavior?


#2

Using TCP vs TLS doesn’t seem to have an effect


#3

Are you able to get the MQTT disconnect code from your client? The “already connected” message on our end is typically caused by an unclean client disconnect and then a reconnect before the TCP timeout window is exceeded.


#4

Thanks Brandon. What does the disconnect code look like? What is the timeout window?


#5

I think I figured it out. The default “reconnection period” in Node-Red is 15000ms; I reduced it to the default of 1000ms and we seem to be in business.


#6

Nope. It does fine for awhile, then the client goes into an infinite loop of disconnection and reconnection. I imagine it has something to do with what you’re saying, but I’m unsure how to debug. The client is mqtt via Node-Red.

I’m fairly certain success w/ reducing the reconnection period was a false positive, as this seems to be the opposite of what should happen. I’m going to increase the reconnection period to 60000ms and see what happens.


#7

I’m not sure how to get the disconnect code from Node-Red, but that underlying client has a error callback that will return the reason for the disconnect. As a test, I will run Node-Red locally and see if I can reproduce the issue.


#8

What is your Losant application ID? I’d like to check the activity on our end.


#9

570de5b4fa885601006fb66d


#10

So after some investigation on our side, we were able to reproduce the issue. It turns out that the default Node-Red keepalive time of 60 seconds (which means the mqtt client would send a ping every 60 seconds) was longer than the tcp connection inactivity timeout of our load balancer (50 seconds). By default, the keepalive time for the node mqtt module is 15 seconds, so we had not hit this issue using the straight node mqtt module.

We have tweaked our mqtt load balancer settings to allow tcp inactivity of 90 seconds - so now the default Node-Red settings work without issue (I’ve had a Node-Red mqtt connections alive without disconnects for multiple hours now).

Let us know if this fixes the issue for you as well!


#11

@spacetc64 Thanks for looking into this.

I had tried reducing the keepalive time in Node-Red below 60s, which should have fixed the problem, correct (it didn’t seem to make a difference at the time)?

These are my settings, which I just modified to use the new domain name:

Anyway, so far so good–but last time I thought it was working, it started crapping out in about 20m. I’ll keep an eye on it.

Chris


#12

No luck:

19 Apr 19:27:13 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:27:17 - [info] [nodebot:dink] io ready
19 Apr 19:43:26 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:44:27 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:45:29 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:46:30 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:47:11 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:48:12 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:48:35 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:49:35 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:50:29 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:51:30 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:52:35 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:53:35 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:54:29 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:55:30 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:56:35 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:57:36 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:58:35 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 19:59:35 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 20:00:29 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 20:01:30 - [info] [mqtt-broker:e3b8d80c.342338] Connected to broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883
19 Apr 20:01:35 - [info] [mqtt-broker:e3b8d80c.342338] Disconnected from broker: 570de60b191e390100fc8747@mqtts://broker.losant.com:8883

#13

As for what happened on the third line; I have no idea. Node-Red is set to publish device status every one (1) minute.

I’m going to try my own test with the mqtt library itself and at least potentially rule out Node-Red as the culprit.


#14

Correct, a keepalive below 60 should have fixed the problem previously (before we changed load balancer settings).

You don’t need the “legacy MQTT 3.1 support” box checked, although I’m not sure that that makes any difference.

According to the connection log for your device (which you can see on your device page in Losant), almost all of your recent disconnects are due to “Message throughput limit exceeded”. It looks like you are sending quite a number of messages very fast - for instance, in the most recent connection, the connection lasted about 43 seconds but the client sent 641 messages, which is well above the 2 per second limit.


#15

Whoa! That’s unintended. Let me check.


#16

I can confirm this. I don’t know why it’s happening, though.


#17

Seems to be a Node-Red bug; I have something set to run every 60000ms but for whatever reason it freaks out and sends at ton at once.


#18

It was user error. :smiley: I accidentally had some code recursively creating functions which would publish messages. Everything works great now.

@losant Thanks for helping!


#19

Awesome! Glad we could get this all figured out.


#20

Hello,

I got a bit of the same issue with my Node-Red sending payload to Losant using MQTT.

I’m using some LORA sensors. They are connected to Node-Red via http and node-red do the payload transcription for losant and send it.

It worked great using a single MQTT output for one device. But since I’ll like to have a single output for all my devices just changing the topic to know witch one it is. It seams like a Gateway and some peripherals will be perfect. But now my MQTT node does not work properly and have a lot of disconnections every 5 secs.

I tried changing the “keep it alive” for more or less that the stock 60s and it didn’t change anything.

Maybe i’m a bit confused with the gateway thing. The topic must be “losant/perippheralID/state” and the MQTT node ID must be the one from the gateway, right?

If someone could help me it will be great