MQTT & node-red-contrib-tuya-smart-device Node Problems

I have just recently started having problems with MQTT and my node-red-contrib-tuya-smart-device nodes.

The issue is, whenever I send an MQTT message to the Tuya node ALL the MQTT nodes on the relevant Node-Red instance disconnect, and only reconnect after I update & redeploy the MQTT broker in any MQTT node.

Mosquitto is running on a Raspberry Pi and I have MQTT nodes connected to the same broker on other instances of Node-Red (both 1.35 & 2.0). The MQTT disconnect ONLY occurs on the Node-Red instance with the Tuya node when connecting to the Tuya node

I have included below a small flow that I am using to show the problem.

[{"id":"dea00b1a.380558","type":"debug","z":"7fdabd9.f693544","name":"Tuya State","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":450,"y":600,"wires":[]},{"id":"3b94404c.0fca2","type":"debug","z":"7fdabd9.f693544","name":"Tuya Port 1","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":730,"y":400,"wires":[]},{"id":"e85c8439.922c38","type":"mqtt out","z":"7fdabd9.f693544","name":"Tuya Study Light State","topic":"tuya/+/device_state/study/smart_bulb_04/state","qos":"1","retain":"","respTopic":"","contentType":"","userProps":"","correl":"","expiry":"","broker":"ee05e0d9.9118e","x":760,"y":440,"wires":[]},{"id":"601fbd68.4e01d4","type":"tuya-smart-device","z":"7fdabd9.f693544","deviceName":"Study Light","disableAutoStart":false,"deviceId":"bfed04c9d469db879doe2y","deviceKey":"20120ede82e21064","deviceIp":"","retryTimeout":1000,"findTimeout":1000,"tuyaVersion":"3.1","eventMode":"event-both","x":470,"y":460,"wires":[["e85c8439.922c38","3b94404c.0fca2"],[]]},{"id":"c9a075ff.ce0788","type":"mqtt in","z":"7fdabd9.f693544","name":"Tuya Study Light Control","topic":"tuya/+/device_control/study/smart_bulb_04/command","qos":"2","datatype":"json","broker":"ee05e0d9.9118e","nl":false,"rap":true,"rh":0,"x":150,"y":460,"wires":[["601fbd68.4e01d4","a24d0969.15f918"]]},{"id":"a24d0969.15f918","type":"debug","z":"7fdabd9.f693544","name":"MQTT In","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","statusVal":"","statusType":"auto","x":460,"y":400,"wires":[]},{"id":"bc510cda.15ba7","type":"mqtt out","z":"7fdabd9.f693544","name":"Tuya Study Light Command","topic":"tuya/NRCTD/device_control/study/smart_bulb_04/command","qos":"1","retain":"false","respTopic":"","contentType":"","userProps":"","correl":"","expiry":"","broker":"ee05e0d9.9118e","x":500,"y":540,"wires":[]},{"id":"f6432cc0.d3e0f","type":"inject","z":"7fdabd9.f693544","name":"","props":[{"p":"payload"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"{\"dps\":20,\"set\":true}","payloadType":"json","x":150,"y":540,"wires":[["bc510cda.15ba7","dea00b1a.380558"]]},{"id":"ee05e0d9.9118e","type":"mqtt-broker","name":"MQTT","broker":"192.168.1.21","port":"1883","clientid":"","usetls":false,"compatmode":false,"protocolVersion":"4","keepalive":"60","cleansession":true,"birthTopic":"","birthQos":"0","birthPayload":"","birthMsg":{},"closeTopic":"","closeQos":"0","closePayload":"","closeMsg":{},"willTopic":"","willQos":"0","willPayload":"","willMsg":{},"sessionExpiry":""}]

If anyone is willing to test this to either prove that it is a problem with my setup, or a problem somewhere else, I would be grateful and look forward to the results.

If anyone is already aware of a possible fix I would also like to know

your tuya study light state mqtt out node is using the topic

tuya/+/device_state/study/smart_bulb_04/state

You can not use wildcards in out topic's. You would need to use a function node or change node before to construct the topic dynamically. Then leave topic field blank and feed in the newly constructed topic in the msg.topic

Hi, thank you, that was indeed the problem.

On testing this I find that mosquitto does indeed disconnect the client (node-red) when it gets the invalid topic. In the mosquitto log it reports
Client mqtt_9ed82080.0f0cd disconnected due to protocol error.
However after about 15 seconds node-red automaticaly reconnects. @Buckskin, were you not seeing that?

Hi Colin. Just tried this and after 15sec shows 'connecting'. Shows this for at least 5 mins. So may reconnect but I am too impatient to wait.

E1cid - apologies for not ticking 'solution'

That is odd. Does your flow repeatedly send the invalid data? If so does it recover if you stop it from repeating it?

No, only sends it once. Sample flow is run from an inject node - repeat none, after time none.

Apart from removing the offending '+' the only way to get it to recover is to update & redeploy the MQTT broker in any MQTT node.

How do you get to view the mosquitto log? I will have a look and see if that has any clues

What version of mosquito are you running?

I am sure google would have told you that much quicker than asking here. On linux it is usually /var/log/mosquitto/mosquitto.log. I don't know about Windows.

Also stop node red and start it in a terminal and post the result here (from the start to after it fails).

Also as Steve asked tell us the mosquitto version.

Did you actually mean that? You seem to be suggesting that if you remove the + and deploy just the relevant node then it recovers without deploying the MQTT node.

I have tested a malformed topic like you had against 5 different brokers.

They all disconnect and reconnect after a few seconds. (note: that is not the 100% true, in fact when sending /test/+/b/c/1 to an networked RPi running mosquitto V2.0.11 it crashes the localhost node-red - it is a known issue in MQTT.JS V4.2.6)

Sorry, no. If I meant that if I remove the '+' the problem does not occur in the first place. If the '+' is in an MQTT out node once the MQTT nodes disconnect the only way to recover is to select any MQTT node and update & redeploy the MQTT broker.

Mosquitto version is 2.0.11

Start Node-RED

Once Node-RED has started, point a browser at http://192.168.1.21:1880
On Pi Node-RED works better with the Firefox or Chrome browser

Use   node-red-stop                          to stop Node-RED
Use   node-red-start                         to start Node-RED again
Use   node-red-log                           to view the recent log output
Use   sudo systemctl enable nodered.service  to autostart Node-RED at every boot
Use   sudo systemctl disable nodered.service to disable autostart on boot

To find more nodes and example flows - go to http://flows.nodered.org

Starting as a systemd service.
21 Jun 10:19:07 - [info]
Welcome to Node-RED
===================
21 Jun 10:19:07 - [info] Node-RED version: v1.3.5
21 Jun 10:19:07 - [info] Node.js  version: v14.17.1
21 Jun 10:19:07 - [info] Linux 5.10.17-v7l+ arm LE
21 Jun 10:19:08 - [info] Loading palette nodes
21 Jun 10:19:11 - [info] +-----------------------------------------------------
21 Jun 10:19:11 - [info] | uibuilder initialised:
21 Jun 10:19:11 - [info] |   Using Node-RED's webserver
21 Jun 10:19:11 - [info] |   root folder: /home/pi/.node-red/uibuilder
21 Jun 10:19:11 - [info] |   version . .: 3.3.1
21 Jun 10:19:11 - [info] |   packages . : jquery,socket.io,vue,bootstrap,bootstrap-vue
21 Jun 10:19:11 - [info] +-----------------------------------------------------
21 Jun 10:19:12 - [info] Worldmap version 2.15.3
21 Jun 10:19:12 - [info] Dashboard version 2.29.3 started at /ui
21 Jun 10:19:13 - [info] Settings file  : /home/pi/.node-red/settings.js
21 Jun 10:19:13 - [info] HTTP Static    : /home/pi/.node-red/public
21 Jun 10:19:13 - [info] Context store  : 'memoryOnly' [module=memory]
21 Jun 10:19:13 - [info] Context store  : 'file' [module=localfilesystem]
21 Jun 10:19:13 - [info] User directory : /home/pi/.node-red
21 Jun 10:19:13 - [warn] Projects disabled : editorTheme.projects.enabled=false
21 Jun 10:19:13 - [info] Flows file     : /home/pi/.node-red/flows.json
21 Jun 10:19:13 - [info] Server now running at http://127.0.0.1:1880/
21 Jun 10:19:13 - [info] Starting flows
21 Jun 10:19:13 - [info] [tuya-smart-device:Study Light] Recieved the config {"id":"601fbd68.4e01d4","type":"tuya-smart-device","z":"7fdabd9.f693544","deviceName":"Study Light","disableAutoStart":false,"deviceId":"bfed04c9d469db879doe2y","deviceKey":"20120ede82e21064","deviceIp":"","retryTimeout":1000,"findTimeout":1000,"tuyaVersion":"3.1","eventMode":"event-both","x":470,"y":460,"wires":[["3b94404c.0fca2","e85c8439.922c38"],[]],"moduleVersion":"4.1.1"}
21 Jun 10:19:13 - [info] [tuya-smart-device:Study Light] Event subscription : shouldSubscribeData=>true , shouldSubscribeRefreshData=>true
21 Jun 10:19:13 - [info] [tuya-smart-device:Study Light] Auto start probe on connect...
21 Jun 10:19:13 - [info] [tuya-smart-device:Study Light] closeComm(): Cleaning up the state
21 Jun 10:19:13 - [info] [tuya-smart-device:Study Light] closeComm(): Clearing the find timeout handler
21 Jun 10:19:13 - [info] [tuya-smart-device:Study Light] closeComm(): Disconnecting from Tuya Device
21 Jun 10:19:13 - [info] Started flows
21 Jun 10:19:14 - [info] [sqlitedb:7ef7e7da.8bc2b8] opened /media/usbDrive/HomeAutomation.db ok
21 Jun 10:19:14 - [info] [zigbee2mqtt-server:83162ab9.755208] MQTT Connected
21 Jun 10:19:14 - [info] [zigbee2mqtt-server:83162ab9.755208] Refreshing devices
21 Jun 10:19:14 - [info] [mqtt-broker:MQTT] Connected to broker: mqtt://192.168.1.21:1883
21 Jun 10:19:14 - [info] [zigbee2mqtt-server:83162ab9.755208] MQTT Subscribed to: "zigbee2mqtt/#
21 Jun 10:19:14 - [info] [zigbee2mqtt-server:83162ab9.755208] Refreshing devices
21 Jun 10:19:14 - [info] [tuya-smart-device:Study Light] startComm(): Connecting to Tuya with params {"id":"bfed04c9d469db879doe2y","key":"20120ede82e21064","ip":"","issueGetOnConnect":false,"nullPayloadOnJSONError":false,"version":"3.1"} , findTimeout :  1000 , retryTimeout:  1000
21 Jun 10:19:14 - [info] [tuya-smart-device:Study Light] findDevice(): Initiating the find command
21 Jun 10:19:15 - [error] [tuya-smart-device:Study Light] find() timed out. Is the device powered on and the ID or IP correct?
21 Jun 10:19:15 - [info] [tuya-smart-device:Study Light] findDevice(): Cannot find the device, re-trying...
21 Jun 10:19:16 - [info] [tuya-smart-device:Study Light] findDevice(): Initiating the find command
21 Jun 10:19:17 - [info] [tuya-smart-device:Study Light] findDevice(): Found device, going to connect
21 Jun 10:19:17 - [info] [tuya-smart-device:Study Light] Connected to device! bfed04c9d469db879doe2y
21 Jun 10:19:29 - [info] Stopping modified nodes
21 Jun 10:19:29 - [info] Stopped modified nodes
21 Jun 10:19:29 - [info] Starting modified nodes
21 Jun 10:19:29 - [info] Started modified nodes
21 Jun 10:19:32 - [info] [tuya-smart-device:Study Light] Recieved input : {"topic":"tuya/NRCTD/device_control/study/smart_bulb_04/command","payload":{"dps":20,"set":true},"qos":1,"retain":false,"_msgid":"f995190d.bf5af8"}
21 Jun 10:19:32 - [info] [tuya-smart-device:Study Light] Data from device  [event:dp-refresh]: {"dps":{"20":true},"t":1624267172}
21 Jun 10:19:32 - [info] [mqtt-broker:MQTT] Disconnected from broker: mqtt://192.168.1.21:1883

and there it sits until reset

21 Jun 10:21:28 - [info] Stopping modified nodes
21 Jun 10:21:28 - [info] Stopped modified nodes
21 Jun 10:21:28 - [info] Starting modified nodes
21 Jun 10:21:28 - [info] Started modified nodes
21 Jun 10:21:28 - [info] [mqtt-broker:MQTT] Connected to broker: mqtt://192.168.1.21:1883

Please note that MQTT nodes running on other Node-Red instances do NOT disconnect and continue to communicate.

It would seem that my system matches Steve's known issue

I don't think so. Node-red has not crashed.

What does the mosquitto log show?

Just after the MQTT nodes disconnect

-- Subject: A new session 5 has been created for user pi
-- Defined-By: systemd
-- Support: https://www.debian.org/support
-- Documentation: https://www.freedesktop.org/wiki/Software/systemd/multiseat
--
-- A new session with the ID 5 has been created for the user pi.
--
-- The leading process of the session is 1198.
Jun 21 10:51:25 PiSSD systemd[1]: Started Session 5 of user pi.
-- Subject: A start job for unit session-5.scope has finished successfully
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit session-5.scope has finished successfully.
--
-- The job identifier is 716.
Jun 21 10:51:25 PiSSD sshd[1200]: Accepted password for pi from 192.168.1.234 port 1040 ssh2
Jun 21 10:51:25 PiSSD sshd[1200]: pam_unix(sshd:session): session opened for user pi by (uid=0)
Jun 21 10:51:25 PiSSD systemd-logind[404]: New session 6 of user pi.
-- Subject: A new session 6 has been created for user pi
-- Defined-By: systemd
-- Support: https://www.debian.org/support
-- Documentation: https://www.freedesktop.org/wiki/Software/systemd/multiseat
--
-- A new session with the ID 6 has been created for the user pi.
--
-- The leading process of the session is 1200.
Jun 21 10:51:25 PiSSD sshd[1206]: error: Failed to allocate internet-domain X11 display socket.
Jun 21 10:51:25 PiSSD systemd[1]: Started Session 6 of user pi.
-- Subject: A start job for unit session-6.scope has finished successfully
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit session-6.scope has finished successfully.
--
-- The job identifier is 779.
Jun 21 10:53:01 PiSSD Node-RED[381]: 21 Jun 10:53:01 - [info] [tuya-smart-device:Study Light] Recieved input : {"topic":"tuya/NRCTD/device_control/study/smart_b
Jun 21 10:53:01 PiSSD Node-RED[381]: 21 Jun 10:53:01 - [info] [tuya-smart-device:Study Light] Data from device  [event:dp-refresh]: {"dps":{"20":false},"type":"
Jun 21 10:53:01 PiSSD Node-RED[381]: 21 Jun 10:53:01 - [info] [mqtt-broker:MQTT] Disconnected from broker: mqtt://192.168.1.21:1883

and the added bit after restart

-- The job identifier is 779.
Jun 21 10:53:01 PiSSD Node-RED[381]: 21 Jun 10:53:01 - [info] [tuya-smart-device:Study Light] Recieved input : {"topic":"tuya/NRCTD/device_control/study/smart_b
Jun 21 10:53:01 PiSSD Node-RED[381]: 21 Jun 10:53:01 - [info] [tuya-smart-device:Study Light] Data from device  [event:dp-refresh]: {"dps":{"20":false},"type":"
Jun 21 10:53:01 PiSSD Node-RED[381]: 21 Jun 10:53:01 - [info] [mqtt-broker:MQTT] Disconnected from broker: mqtt://192.168.1.21:1883
Jun 21 10:53:53 PiSSD Node-RED[381]: 21 Jun 10:53:53 - [info] Stopping modified nodes
Jun 21 10:53:53 PiSSD Node-RED[381]: 21 Jun 10:53:53 - [info] Stopped modified nodes
Jun 21 10:53:53 PiSSD Node-RED[381]: 21 Jun 10:53:53 - [info] Starting modified nodes
Jun 21 10:53:53 PiSSD Node-RED[381]: 21 Jun 10:53:53 - [info] Started modified nodes
Jun 21 10:53:53 PiSSD Node-RED[381]: 21 Jun 10:53:53 - [info] [mqtt-broker:MQTT] Connected to broker: mqtt://192.168.1.21:1883

Which log is that? It doesn't look like the mosquitto log.

I do apologise but I know WHERE the Mosquitto logs are but I have no idea how to view them.

I have been on Google and got absolutely nowhere. 'how to view mosquitto log files on pi' has revealed nothing. So if you wouldn't mind would you explain how it is done.

(having reviewed what I did find and did, I think that the above info is from journal)

I use mc

sudo apt install mc

3c9SUXBSef

but you could just as easily enter sudo nano /var/log/mosquitto/mosquitto.log

Or
sudo cat /var/log/mosquitto/mosquitto.log
which will show it all or
sudo tail -n 100 /var/log/mosquitto/mosquitto.log
which will show the last 100 lines or
sudo tail -f /var/log/mosquitto/mosquitto.log
which will show the end of the log and keep updating the output as more information is logged.

Thank you. I had tried the sudo nano line but got a message about there not being enough data. So I thought that I had got something wrong. However, when I tried it again (with a bit more confidence thanks to your help) I got this'

Prior to disconnection

1624270271: Client NodeRed-f1e36c8.683d39-tmp closed its connection.
1624271409: Client mqttjs_cfd1f0de disconnected.
1624271409: Client mqtt_aeac94b79a7d61d4 disconnected.
1624271483: New connection from 192.168.1.26:53670 on port 1883.
1624271483: New client connected from 192.168.1.26:53670 as mqtt_287dfd258a7006de (p2, c1, k60, u'jeff').
1624271542: Saving in-memory database to /var/lib/mosquitto//mosquitto.db.
1624271558: New connection from 192.168.1.26:53684 on port 1883.
1624271558: New client connected from 192.168.1.26:53684 as mqttjs_dfafed52 (p2, c1, k60, u'jeff').
1624271558: New connection from 192.168.1.21:38576 on port 1883.
1624271558: New client connected from 192.168.1.21:38576 as NodeRed-83162ab9.755208-tmp (p2, c1, k60, u'jeff').
1624271558: New connection from 192.168.1.80:60028 on port 1883.
1624271558: New client connected from 192.168.1.80:60028 as NodeRed-f1e36c8.683d39-tmp (p2, c1, k60, u'jeff').
1624271558: Client NodeRed-f1e36c8.683d39-tmp closed its connection.
1624271558: Client NodeRed-83162ab9.755208-tmp closed its connection.
1624273026: Client mqtt_c6804372.606bd disconnected due to protocol error.
1624273041: New connection from 192.168.1.21:38590 on port 1883.
1624273041: New client connected from 192.168.1.21:38590 as mqtt_c6804372.606bd (p2, c1, k60, u'jeff').
1624273041: Client mqtt_c6804372.606bd disconnected due to protocol error.

After reconnection

1624271558: Client NodeRed-83162ab9.755208-tmp closed its connection.
1624273026: Client mqtt_c6804372.606bd disconnected due to protocol error.
1624273041: New connection from 192.168.1.21:38590 on port 1883.
1624273041: New client connected from 192.168.1.21:38590 as mqtt_c6804372.606bd (p2, c1, k60, u'jeff').
1624273041: Client mqtt_c6804372.606bd disconnected due to protocol error.
1624273056: New connection from 192.168.1.21:38592 on port 1883.
1624273056: New client connected from 192.168.1.21:38592 as mqtt_c6804372.606bd (p2, c1, k60, u'jeff').
1624273056: Client mqtt_c6804372.606bd disconnected due to protocol error.
1624273071: New connection from 192.168.1.21:38594 on port 1883.
1624273071: New client connected from 192.168.1.21:38594 as mqtt_c6804372.606bd (p2, c1, k60, u'jeff').
1624273071: Client mqtt_c6804372.606bd disconnected due to protocol error.
1624273086: New connection from 192.168.1.21:38596 on port 1883.
1624273086: New client connected from 192.168.1.21:38596 as mqtt_c6804372.606bd (p2, c1, k60, u'jeff').
1624273086: Client mqtt_c6804372.606bd disconnected due to protocol error.
1624273101: New connection from 192.168.1.21:38598 on port 1883.
1624273101: New client connected from 192.168.1.21:38598 as mqtt_c6804372.606bd (p2, c1, k60, u'jeff').
1624273101: Client mqtt_c6804372.606bd disconnected due to protocol error.
1624273112: New connection from 192.168.1.21:38600 on port 1883.
1624273112: New client connected from 192.168.1.21:38600 as mqtt_17a858a9.00ffc7 (p2, c1, k60, u'jeff').

Do you mean the second bit is what happened while it was continually reconnecting? If so then since the numbers are the timestamp in milliseconds, it appears that the mqtt node is continually trying to republish to the topic. Are you sure you have got Clean Session selected in the MQTT broker node settings?

Also are you absolutely sure that the flow is not continually resending the invalid topic? Check with debug nodes showing all messages going to the MQTT nodes.

Not sure what a 'Clean Session' is but there are definitely no reconnect messages going via an MQTT node. However, on this instance of Node-Red I also have a few node-red-contrib-zigbee2mqtt nodes and I am not sure exactly how they work with MQTT.

OK, tried this on another instance of Node-Red connected to the same mosquitto broker but with no zigbee2mqtt nodes and got the same result (same connect / disconnect message in the log)