Node-red fails to reconnect to flespi MQTT after Internet breakup

BarbuDor

Hi
I've been using Node-red and Flespi MQTT for a few weeks now and I'm facing a recurrent issue when the Internet connection breaks up.
After recovery, while other IoT devices reconnects seamlessly to Flespi, Node-red fails to reconnect and Flepsi reports unexpected disconnections:

26/12/2021 19:25:04 | mqtt session connection was closed (unexpected disconnect) | node-red_sonnaz | clean: true; expiry_interval: 0; origin_id: 0; origin_type: 14; rejected: 0; session_present: false; token_id: 32288721; version: 4;
26/12/2021 19:25:05 | mqtt session connection was acceptednode-red_sonnaz | clean: true; expiry_interval: 0; origin_id: 0; origin_type: 14; peer: "2.7.144.209"; rejected: 0; session_present: false; token_id: 32288721; version: 4;
26/12/2021 19:25:05 | mqtt session connection was closed (unexpected disconnect)node-red_sonnaz | clean: true; expiry_interval: 0; origin_id: 0; origin_type: 14; rejected: 0; session_present: false; token_id: 32288721; version: 4;
...

Which is not very explicit

On the node-red side, no really usefull logs neither:

26 Dec 19:24:09 - [info] [mqtt-broker:Flespi] Disconnected from broker: node-red_sonnaz@mqtts://mqtt.flespi.io:8883
26 Dec 19:25:05 - [info] [mqtt-broker:Flespi] Connected to broker: node-red_sonnaz@mqtts://mqtt.flespi.io:8883
26 Dec 19:25:05 - [info] [mqtt-broker:Flespi] Disconnected from broker: node-red_sonnaz@mqtts://mqtt.flespi.io:8883
...

Has anyone faced such kind of problem ?
Any suggestion on how I could investigate further ?

I also created a post on node-red's forum (https://discourse.nodered.org/t/mqtt-reconnection-failure-to-flespi-io/55768)

Thanks

Node-RED version: v2.1.4
Node.js version: v14.18.2
Linux 5.4.0-91-generic ia32 LE
Running as docker (alpine based)

dexif

Please check that the token you have used has not expired.

BarbuDor

dexif Nope, tokens are valid for more than a year
If I force Node-red to reconnect by making a chage in the MQTT broker configuration and changing back, it reconnect perfectly.

dexif

BarbuDor Hmm I can't reproduce it on my installation of Node-RED 2.1.4
Are you sure that you don't have another MQTT client with the same client_id?
Can you show us your mqtt client configuration from node-red? You can send it to integrated chat on flespi.io (top right corner)

BarbuDor

dexif

As I said, the problem doesn't appear unless there is a break in the Internet connection. So it is very random
I have 2 other node-red (one is 1.3.7 the other is 2.1.4) on another site connected to Flespi which doesn't show the problem
100% sure each device have a different Client ID

Same event occured this morning again at around 10:06 GMT

I'll check if I can use that TCP Proxy

dexif

You can try to install TCP proxy between broker and client to diagnose what's going on exactly between client and broker. Here is a step by step guide for this: https://flespi.com/kb/how-to-debug-mqtt-session-using-proxy-channel

Please also share the results of investigations.

BarbuDor

Hi @dexif
Proxy is in place. Looks like I just discovered a very nice tool.
Let's see when this happens again.
Thanks for your help.

BarbuDor

The problem occurred again tonight at 19:50 GMT until I restarted the Node-red MQTT node which made Node-red reconnect correctly at 19:53 GMT (time below is CET GMT+1)
The hexdump of the session that was running since this morning and broke:

Then one of the session that is looping connect/disconnect

Data on the 3rd lines are the LWT messages
Data on the 5th lines are the subscripted topics
On the 6th line, it seems to be a disconnect request from Flepsi to Nodered
The flow seems to confirm that disconnection is coming from Flespi

The normal connection scheme is:

Any idea ?

Thanks

BarbuDor

Apparently this time, it occured without any Internet disruption as the other devices remained connected.

BarbuDor

Hi @dexif
Any idea why Flespi broker would reject first ?
Thanks

adsa

We examined the broker's internal logs and found that the single subscription packet contains more than 16 filters causing the broker to drop the connection. This limitation is described on the broker's page https://flespi.com/mqtt-broker under the topic of MQTT limitations.

BarbuDor

Hi all,
Some updates
While diving a little more with the help of the Nodered team, I appears that original subscriptions are sent by Nodered with 1 topic per request.
However, in case of a reconnection, this is the underlying MQTT.js library that reconnect and send the all the subscripted topics in a single request because I checked the Clean Session option.
When Clean Session is not checked, MQTT.js do not resend the subscription as it expects the broker to restore the session.
Tested ok with a 1 minute connection outage.

For now, I will use that configuration but I would like to try with a longer outage.

@dexif adsa Is there a timeout after which the Flespi MQTT broker will cleanup the session so I can make a test with an outage long enough to validate this ?

Thanks for the support

BarbuDor

Hi @adsa
Thanks for your investigation and pointing this limitation
So it may works like when I restart Node-red or not like when trying to reconnect ...
I would be great if the error cause could be reported back in some logs accessible to the user.

I will investigate with Node-red how it is possible to limit this and keep you posted.

Many Thanks

shal

BarbuDor default session expiration period is 365 days or it also can be auto-deleted if overflowed by the accumulated messages data.
You can emulate session expiration by deleting it with REST API: https://flespi.io/docs/#/mqtt/sessions/delete_sessions_sessions_selector