MQTT out node disconnects when topic field is empty

Hi!

I Have a node red installed on my RPi4 that is used to control my home automations. My docker-compose.yml is basically a vanilla configuration, nothing special, docker is up to date currently v2.1.5

version: "3"

services:
  node-red:
    image: nodered/node-red:latest
    container_name: nodered
    group_add:
      - dialout
    devices:
      - "/dev/ttyAMA0:/dev/ttyAMA0"
      - "/dev/ttyAMA2:/dev/ttyAMA2"
      - "/dev/ttyAMA3:/dev/ttyAMA3"
    environment:
      - TZ=Europe/Warsaw
    user: '1000'
    restart: unless-stopped
    ports:
      - 1880:1880
    networks:
      node-red-net:
        aliases:
          - "nodered"
      timescale-net:
      grafana-net:
      mosquitto-net:
    volumes:
      - ./volumes/data:/data

networks:
  node-red-net:
  timescale-net:
    external: true
  grafana-net:
    external: true
  mosquitto-net:
    external: true

My flow for contrlling my floor heaters in which I can see the problem with MQTT out node

node configuration

Screenshot_20220113_195723

logs from docker after deploy

nodered     | 13 Jan 19:43:39 - [info] Stopping modified flows
nodered     | 13 Jan 19:43:39 - [info] Stopped modified flows
nodered     | 13 Jan 19:43:39 - [info] Starting modified flows
nodered     | 13 Jan 19:43:40 - [info] Started modified flows
nodered     | 13 Jan 19:43:41 - [info] [mqtt-broker:MQTT3] Connected to broker: mqtt://mqtt:1883
nodered     | 13 Jan 19:43:41 - [info] [mqtt-broker:MQTT3] Disconnected from broker: mqtt://mqtt:1883

the problem that I am facing is that when I use "dynamic topic" like in the "mqtt" node (on the right) I am unable to connect to more then one source of messages. For example connecting an "MQTT out node" to each output of Heating.FloorHeatingControlBlock node (one mqtt to one control block) will cause the MQTT to disconnect immediately, then go to "connecting" state. The whole "Workoround for MQTT" group is only for MQTT node to be happy that it has only one source of messages and SOMETIMES this will work for some time (like an hour or so) and then disconnect without giving a error or anything. To reconnect I need to dewire (remove wire connecting it to the group) mqtt node, deploy, and wire it back again and delpoy again
Also MQTT2 and MQTT3 configuration differs ONLY with name both are connected to the exact same broker, and those are separated to different configurations because all nodes using this config will disconnect...
Can you guys give me a hint about what is going on here and why this node is disconnectiong? What can I check?
Also this stopped working after updating my nodered instance (this was a crash recovery from backup after my HDD died) so I can't give you exact versions I believe it was something like ~ 2.0.6 to 2.1.5 before I had no issue with MQTT whatsoever

Are you setting a client ID on both connections? If so, why?

Can you share your flow so I can inspect the flow.

List out any non core nodes.

thank you for response @Steve-Mcl I thought that I attached the configuration for the MQTT node... sorry for this!

So no, both have Client ID blank

flows.json (91.0 KB)

Haw can I list any non core nodes?

Did you use any nodes in the exported flow that you had to install?

Ps, there is no need to attach files. You can post your flow like this...

```
paste flow & code between backticks
```

Hi, I have been looking into your MQTT reconnection issue.

Question

Can you tell me what broker type and version are you using? Mosquitto V1.6? V2?

Observations

I can see that your subflow generates an invalid topic...

image

As per MQTT spec the server disconnects the client and a reasonCode of 129 (PUBLISH with malformed UTF-8 String for topic was sent) is generated.


Here is a slimmed down test (about 30 secs, please watch)...
chrome_mBZQOnthHO

↑ As you can see, all the nodes (apart from EMQX) disconnect & dont re-connect.



@knolleary this ↓ looks like it may be a bug in 10-mqtt.js. I have looked back through commits back to before V5 support was added - i don't see where I might have missed this! Very odd.

Reading through the issues in MQTT.JS repo, I suspect we should be calling client.end() before the reconnect event. As it stands, we do, but not when the broker initiates the disconnect (disconnect event).

So I added the below code to node.client.on("disconnect", ... in packages/node_modules/@node-red/nodes/core/network/10-mqtt.js ...

  if (node.connected) {
    node.client.end(true, {});
    node.connected = false;
  }

... Resulting in this much better situation (about 30 secs, please watch)...

chrome_krBBSVgfDx

↑ You barely see the disconnection / reconnection - but it does happen....

NOTE: Moqsquito V1.6.x never re-connects - though a manual disconnect/connect does work

chrome_oHaa5QondJ



Request for help from you @bartoszek ...

  1. Please add the below code to node.client.on("disconnect", function(packet) { in packages/node_modules/@node-red/nodes/core/network/10-mqtt.js to include this...
    node.client.on("disconnect", function(packet) {
      if (node.connected) {    //<< add this
        node.client.end(true, {});    //<< add this
        node.connected = false;    //<< add this
      }    //<< add this
    }
    
  2. Restart node-red - does the issue continue or is it fixed?


Handling this issue / fixing your flow...

You should look to curb bad topics entering the MQTT node. As for why you are getting bad topics is not immediately obvious but I would simply use a switch node that checks the topic is not empty and doesnt contain \n, \t etc. Use an otherwise clause to log the (full) bad message for later inspection.



My test flow - if you are interested...

[{"id":"89fef359b4e8deb0","type":"inject","z":"eb81e71f9edd709c","name":"go","props":[{"p":"payload"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":1370,"y":820,"wires":[["27d52903b6159003"]]},{"id":"a20fe7d4ca71f475","type":"mqtt out","z":"eb81e71f9edd709c","name":"PI mosq 2.x","topic":"","qos":"1","retain":"false","respTopic":"","contentType":"","userProps":"","correl":"","expiry":"","broker":"7bab12a9.b04bcc","x":1590,"y":940,"wires":[]},{"id":"ae546d5b2aea26d9","type":"mqtt out","z":"eb81e71f9edd709c","name":"local mosq 1.6x","topic":"","qos":"1","retain":"false","respTopic":"","contentType":"","userProps":"","correl":"","expiry":"","broker":"f03246cf.89b378","x":1600,"y":1000,"wires":[]},{"id":"d1bb24cddfc839b7","type":"mqtt out","z":"eb81e71f9edd709c","name":"broker.emqx.io","topic":"","qos":"1","retain":"false","respTopic":"","contentType":"","userProps":"","correl":"","expiry":"","broker":"63e287c41d3182a5","x":1600,"y":1120,"wires":[]},{"id":"f5ead90074142b07","type":"mqtt out","z":"eb81e71f9edd709c","name":"test.mosquitto.org","topic":"","qos":"1","retain":"false","respTopic":"","contentType":"","userProps":"","correl":"","expiry":"","broker":"a9a4ad4ffe3fe406","x":1610,"y":1060,"wires":[]},{"id":"47ed98a2be139c32","type":"debug","z":"eb81e71f9edd709c","name":"","active":true,"tosidebar":false,"console":false,"tostatus":true,"complete":"topic","targetType":"msg","statusVal":"payload","statusType":"auto","x":1580,"y":820,"wires":[]},{"id":"a7ca9a8a930eed01","type":"debug","z":"eb81e71f9edd709c","name":"","active":true,"tosidebar":true,"console":false,"tostatus":true,"complete":"payload","targetType":"msg","statusVal":"payload","statusType":"auto","x":1590,"y":880,"wires":[]},{"id":"27d52903b6159003","type":"function","z":"eb81e71f9edd709c","name":"replay bad msg","func":"return { \n    \"topic\": \"$join([\\\"homes\\\", $flowContext(\\\"_room\\\"), \\\"floor\\\", \\\"temperature\\\", \\\"get\\\"], \\\"/\\\")\\t\", \n    \"payload\": {}, \n    \"qos\": 1, \n    \"retain\": false, \n    \"_msgid\": \"3bc8639b5aa82cb0\" \n}\n","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":1380,"y":880,"wires":[["47ed98a2be139c32","a7ca9a8a930eed01","a20fe7d4ca71f475","ae546d5b2aea26d9","d1bb24cddfc839b7","f5ead90074142b07","59bddb34689a8e32"]]},{"id":"59bddb34689a8e32","type":"mqtt out","z":"eb81e71f9edd709c","name":"broker.hivemq.com","topic":"","qos":"1","retain":"false","respTopic":"","contentType":"","userProps":"","correl":"","expiry":"","broker":"780d4f68b1c8e137","x":1610,"y":1180,"wires":[]},{"id":"c8f1eb314fb19abb","type":"inject","z":"eb81e71f9edd709c","name":"connect","props":[{"p":"action","v":"connect","vt":"str"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","x":1330,"y":960,"wires":[["ae546d5b2aea26d9"]]},{"id":"65843dd1926d8de7","type":"inject","z":"eb81e71f9edd709c","name":"disconnect","props":[{"p":"action","v":"disconnect","vt":"str"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","x":1330,"y":1000,"wires":[["ae546d5b2aea26d9"]]},{"id":"7bab12a9.b04bcc","type":"mqtt-broker","name":"PI","broker":"192.168.1.61","port":"1883","clientid":"","autoConnect":true,"usetls":false,"compatmode":false,"protocolVersion":"5","keepalive":"59","cleansession":true,"birthTopic":"test/lwt/birth","birthQos":"0","birthPayload":"payload of test/lwt/birth","birthMsg":{"contentType":"application/json","userProps":"{\"prop\":\"birth-prop\"}","respTopic":"test/lwt/birthResponse","correl":"test/lwt/birth:Correl","expiry":"60"},"closeTopic":"","closeQos":"0","closePayload":"","closeMsg":{},"willTopic":"","willQos":"0","willPayload":"","willMsg":{},"sessionExpiry":""},{"id":"f03246cf.89b378","type":"mqtt-broker","name":"","broker":"localhost","port":"1883","clientid":"","autoConnect":true,"usetls":false,"protocolVersion":"5","keepalive":"58","cleansession":true,"birthTopic":"demo/lwt/birth","birthQos":"0","birthPayload":"birth","birthMsg":{"contentType":"application/json","userProps":"{\"lh\":\"value\"}","respTopic":"demo/lwt/birthReply","correl":"correl for demo/lwt/birth","expiry":"123"},"closeTopic":"demo/lwt/close","closeQos":"0","closePayload":"close","closeMsg":{},"willTopic":"demo/lwt/will","willQos":"0","willPayload":"will","willMsg":{},"sessionExpiry":"","credentials":{}},{"id":"63e287c41d3182a5","type":"mqtt-broker","name":"test broker","broker":"broker.emqx.io","port":"1883","clientid":"","autoConnect":true,"usetls":false,"protocolVersion":"5","keepalive":"60","cleansession":true,"birthTopic":"","birthQos":"0","birthPayload":"","birthMsg":{},"closeTopic":"","closeQos":"0","closePayload":"","closeMsg":{},"willTopic":"","willQos":"0","willPayload":"","willMsg":{},"sessionExpiry":""},{"id":"a9a4ad4ffe3fe406","type":"mqtt-broker","name":"","broker":"test.mosquitto.org","port":"1883","clientid":"","autoConnect":true,"usetls":false,"protocolVersion":"5","keepalive":"59","cleansession":true,"birthTopic":"","birthQos":"0","birthPayload":"","birthMsg":{},"closeTopic":"","closeQos":"0","closePayload":"","closeMsg":{},"willTopic":"","willQos":"0","willPayload":"","willMsg":{},"sessionExpiry":""},{"id":"780d4f68b1c8e137","type":"mqtt-broker","name":"broker.hivemq.com","broker":"broker.hivemq.com","port":"1883","clientid":"","autoConnect":true,"usetls":false,"protocolVersion":"5","keepalive":"60","cleansession":true,"birthTopic":"","birthQos":"0","birthPayload":"","birthMsg":{},"closeTopic":"","closeQos":"0","closePayload":"","closeMsg":{},"willTopic":"","willQos":"0","willPayload":"","willMsg":{},"sessionExpiry":""}]
1 Like

Thank you, this is a brilliant answer, indeed I had a bug all the time

spot the bug...

changing to "expression" fixes my issue! and as for your request, sadly I don't have such file in my nodered installation :confused:

pi@raspberrypi:/var/docker/nodered/volumes $ find . -iname "*mqtt.js"
./data/node_modules/mqtt-packet/mqtt.js
./data/node_modules/mqtt/test/mqtt.js
./data/node_modules/mqtt/mqtt.js
./data/node_modules/node-red-contrib-zigbee2mqtt/node_modules/mqtt-packet/mqtt.js
./data/node_modules/node-red-contrib-zigbee2mqtt/node_modules/mqtt/bin/mqtt.js
./data/node_modules/node-red-contrib-zigbee2mqtt/node_modules/mqtt/dist/mqtt.js
./data/node_modules/node-red-contrib-zigbee2mqtt/node_modules/mqtt/mqtt.js

Thanks again for helping, this was a small thing but it would took me a nice couple of evenings to solve :slight_smile:

Hi Nick @knolleary

Did you get a chance to look this ↑ issue over?

I am fairly certain it is something we should look at.

I could raise a PR and point back to this topic for reference?

I also seen another similar post earlier this week: MQTT Time Out / Random Disconnect - #2 by Steve-Mcl - possibly related.

Hi @Steve-Mcl - if you're at the point where you think these is an issue in the code, please do go straight to issue and/or pr as that gets my attention far better :slight_smile:

Will do over the weekend Nick. Ta.