MQTT In: Disconnect after Re-Deploy

michael-b · 1 December 2022 09:17

Hi all, I'm new to Node-RED but I think I'm facing a bug, or I'm misunderstanding something completely.

I am using MQTT-In to subscribe to a MQTT topic. I'm using Mosquitto 2.0 and MQTT 5.0 which I read is supported by Mosquitto 2.0. However, the same behavior can be observed when using MQTT 3.1.1 (I haven't tried 3.1 legacy). Both are in Docker containers.

With every re-deployment of my flow, if I change something within the flow itself (moving nodes is not enough), my MQTT-In node either connects or disconnects (if it's connected, it will disconnect, if it's disconnected, it will re-connect).

My flow looks as follows:

In the screenshot, it's connected. I then changed the debug node (re-named it) and triggered a re-deployment of the changed flow (I disabled all other flows for testing). This leads to the MQTT-In disconnecting:

Screenshot from 2022-12-01 09-04-09

For debugging, I increased Node-REDs log level to trace and Mosquittos log type to all.

Node-RED Logs:

[ === showing last few events for reference === ]
1 Dec 08:37:25 - [trace] [flow:8fe02e49cbc1e1e3]  e426ca5edb464827 | debug        |
1 Dec 08:37:25 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:37:25 - [trace] runtime event: {"id":"runtime-state","payload":{"state":"start","deploy":true},"retain":true}
1 Dec 08:37:25 - [info] Started modified flows
1 Dec 08:37:25 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"1cf16b3e9fa0bb14fde3cf71614001c7"},"retain":true}
1 Dec 08:37:25 - [info] [mqtt-broker:main] Connected to broker: mqtt://192.168.0.24:1883
[ === EVENT: RE-DEPLOY 1 - leading to disconnect === ]
1 Dec 08:46:56 - [trace] utils.writeFile - copied /data/flows.json TO /data/.flows.json.backup
1 Dec 08:46:56 - [trace] utils.writeFile - written content to /data/flows.json.$$$
1 Dec 08:46:56 - [trace] utils.writeFile - renamed /data/flows.json.$$$ to /data/flows.json
1 Dec 08:46:56 - [debug] saved flow revision: aec89413f9c5c5862827576f6d44d909
1 Dec 08:46:56 - [info] Stopping modified flows
1 Dec 08:46:56 - [debug] red/nodes/flows.stop : stopping flow : 8fe02e49cbc1e1e3
1 Dec 08:46:56 - [trace] [flow:8fe02e49cbc1e1e3] stop flow
1 Dec 08:46:56 - [trace] Stopping node debug:e426ca5edb464827
1 Dec 08:46:56 - [trace] Stopping node mqtt in:98eda388285104a1
1 Dec 08:46:56 - [debug] red/nodes/flows.stop : stopping flow : global
1 Dec 08:46:56 - [trace] [flow:global] stop flow
1 Dec 08:46:56 - [trace] Stopped node debug:e426ca5edb464827 (1ms)
1 Dec 08:46:56 - [trace] Stopped node mqtt in:98eda388285104a1 (1ms)
1 Dec 08:46:56 - [info] Stopped modified flows
1 Dec 08:46:56 - [trace] runtime event: {"id":"runtime-state","payload":{"state":"stop","deploy":true},"retain":true}
1 Dec 08:46:56 - [info] Updated flows
1 Dec 08:46:56 - [info] Starting modified flows
1 Dec 08:46:56 - [debug] red/nodes/flows.start : not starting disabled flow : 404a5fc31d9bfebc
1 Dec 08:46:56 - [debug] red/nodes/flows.start : not starting disabled flow : 80c0daf0d6dc14e8
1 Dec 08:46:56 - [debug] red/nodes/flows.start : not starting disabled flow : fefe4cc15c24e3f0
1 Dec 08:46:56 - [trace] [flow:global] start flow [global]
1 Dec 08:46:56 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:46:56 - [trace] [flow:global]  id               | type         | alias
1 Dec 08:46:56 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:46:56 - [trace] [flow:global]  ec6252675c95ed29 | server       |
1 Dec 08:46:56 - [trace] [flow:global]  09a1213024a9a03b | influxdb     |
1 Dec 08:46:56 - [trace] [flow:global]  d50d0c9f.31e858  | tls-config   |
1 Dec 08:46:56 - [trace] [flow:global]  5d7e54ca.019d44  | influxdb     |
1 Dec 08:46:56 - [trace] [flow:global]  5a4cacde8bbbdebd | mqtt-broker  |
1 Dec 08:46:56 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:46:56 - [trace] [flow:8fe02e49cbc1e1e3] start flow [8fe02e49cbc1e1e3]
1 Dec 08:46:56 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:46:56 - [trace] [flow:8fe02e49cbc1e1e3]  id               | type         | alias
1 Dec 08:46:56 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:46:56 - [trace] [flow:8fe02e49cbc1e1e3]  98eda388285104a1 | mqtt in      |
1 Dec 08:46:56 - [trace] [flow:8fe02e49cbc1e1e3]  e426ca5edb464827 | debug        |
1 Dec 08:46:56 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:46:56 - [trace] runtime event: {"id":"runtime-state","payload":{"state":"start","deploy":true},"retain":true}
1 Dec 08:46:56 - [info] Started modified flows
1 Dec 08:46:56 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"aec89413f9c5c5862827576f6d44d909"},"retain":true}
1 Dec 08:46:56 - [info] [mqtt-broker:main] Disconnected from broker: mqtt://192.168.0.24:1883
[ === EVENT: RE-DEPLOY 2 - leading to re-connect === ]
1 Dec 08:47:05 - [trace] utils.writeFile - copied /data/flows.json TO /data/.flows.json.backup
1 Dec 08:47:05 - [trace] utils.writeFile - written content to /data/flows.json.$$$
1 Dec 08:47:05 - [trace] utils.writeFile - renamed /data/flows.json.$$$ to /data/flows.json
1 Dec 08:47:05 - [debug] saved flow revision: 1cf16b3e9fa0bb14fde3cf71614001c7
1 Dec 08:47:05 - [info] Stopping modified flows
1 Dec 08:47:05 - [debug] red/nodes/flows.stop : stopping flow : 8fe02e49cbc1e1e3
1 Dec 08:47:05 - [trace] [flow:8fe02e49cbc1e1e3] stop flow
1 Dec 08:47:05 - [trace] Stopping node debug:e426ca5edb464827
1 Dec 08:47:05 - [trace] Stopping node mqtt in:98eda388285104a1
1 Dec 08:47:05 - [debug] red/nodes/flows.stop : stopping flow : global
1 Dec 08:47:05 - [trace] [flow:global] stop flow
1 Dec 08:47:05 - [trace] Stopped node debug:e426ca5edb464827 (0ms)
1 Dec 08:47:05 - [trace] Stopped node mqtt in:98eda388285104a1 (0ms)
1 Dec 08:47:05 - [info] Stopped modified flows
1 Dec 08:47:05 - [trace] runtime event: {"id":"runtime-state","payload":{"state":"stop","deploy":true},"retain":true}
1 Dec 08:47:05 - [info] Updated flows
1 Dec 08:47:05 - [info] Starting modified flows
1 Dec 08:47:05 - [debug] red/nodes/flows.start : not starting disabled flow : 404a5fc31d9bfebc
1 Dec 08:47:05 - [debug] red/nodes/flows.start : not starting disabled flow : 80c0daf0d6dc14e8
1 Dec 08:47:05 - [debug] red/nodes/flows.start : not starting disabled flow : fefe4cc15c24e3f0
1 Dec 08:47:05 - [trace] [flow:global] start flow [global]
1 Dec 08:47:05 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:47:05 - [trace] [flow:global]  id               | type         | alias
1 Dec 08:47:05 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:47:05 - [trace] [flow:global]  ec6252675c95ed29 | server       |
1 Dec 08:47:05 - [trace] [flow:global]  09a1213024a9a03b | influxdb     |
1 Dec 08:47:05 - [trace] [flow:global]  d50d0c9f.31e858  | tls-config   |
1 Dec 08:47:05 - [trace] [flow:global]  5d7e54ca.019d44  | influxdb     |
1 Dec 08:47:05 - [trace] [flow:global]  5a4cacde8bbbdebd | mqtt-broker  |
1 Dec 08:47:05 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:47:05 - [trace] [flow:8fe02e49cbc1e1e3] start flow [8fe02e49cbc1e1e3]
1 Dec 08:47:05 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:47:05 - [trace] [flow:8fe02e49cbc1e1e3]  id               | type         | alias
1 Dec 08:47:05 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:47:05 - [trace] [flow:8fe02e49cbc1e1e3]  98eda388285104a1 | mqtt in      |
1 Dec 08:47:05 - [trace] [flow:8fe02e49cbc1e1e3]  e426ca5edb464827 | debug        |
1 Dec 08:47:05 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:47:05 - [trace] runtime event: {"id":"runtime-state","payload":{"state":"start","deploy":true},"retain":true}
1 Dec 08:47:05 - [info] Started modified flows
1 Dec 08:47:05 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"1cf16b3e9fa0bb14fde3cf71614001c7"},"retain":true}
1 Dec 08:47:05 - [info] [mqtt-broker:main] Connected to broker: mqtt://192.168.0.24:1883
[ === EVENT: RE-DEPLOY 3 - leading to disconnect === ]
1 Dec 08:47:15 - [trace] utils.writeFile - copied /data/flows.json TO /data/.flows.json.backup
1 Dec 08:47:15 - [trace] utils.writeFile - written content to /data/flows.json.$$$
1 Dec 08:47:15 - [trace] utils.writeFile - renamed /data/flows.json.$$$ to /data/flows.json
1 Dec 08:47:15 - [debug] saved flow revision: aec89413f9c5c5862827576f6d44d909
1 Dec 08:47:15 - [info] Stopping modified flows
1 Dec 08:47:15 - [debug] red/nodes/flows.stop : stopping flow : 8fe02e49cbc1e1e3
1 Dec 08:47:15 - [trace] [flow:8fe02e49cbc1e1e3] stop flow
1 Dec 08:47:15 - [trace] Stopping node debug:e426ca5edb464827
1 Dec 08:47:15 - [trace] Stopping node mqtt in:98eda388285104a1
1 Dec 08:47:15 - [debug] red/nodes/flows.stop : stopping flow : global
1 Dec 08:47:15 - [trace] [flow:global] stop flow
1 Dec 08:47:15 - [trace] Stopped node debug:e426ca5edb464827 (1ms)
1 Dec 08:47:15 - [trace] Stopped node mqtt in:98eda388285104a1 (1ms)
1 Dec 08:47:15 - [info] Stopped modified flows
1 Dec 08:47:15 - [trace] runtime event: {"id":"runtime-state","payload":{"state":"stop","deploy":true},"retain":true}
1 Dec 08:47:15 - [info] Updated flows
1 Dec 08:47:15 - [info] Starting modified flows
1 Dec 08:47:15 - [debug] red/nodes/flows.start : not starting disabled flow : 404a5fc31d9bfebc
1 Dec 08:47:15 - [debug] red/nodes/flows.start : not starting disabled flow : 80c0daf0d6dc14e8
1 Dec 08:47:15 - [debug] red/nodes/flows.start : not starting disabled flow : fefe4cc15c24e3f0
1 Dec 08:47:15 - [trace] [flow:global] start flow [global]
1 Dec 08:47:15 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:47:15 - [trace] [flow:global]  id               | type         | alias
1 Dec 08:47:15 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:47:15 - [trace] [flow:global]  ec6252675c95ed29 | server       |
1 Dec 08:47:15 - [trace] [flow:global]  09a1213024a9a03b | influxdb     |
1 Dec 08:47:15 - [trace] [flow:global]  d50d0c9f.31e858  | tls-config   |
1 Dec 08:47:15 - [trace] [flow:global]  5d7e54ca.019d44  | influxdb     |
1 Dec 08:47:15 - [trace] [flow:global]  5a4cacde8bbbdebd | mqtt-broker  |
1 Dec 08:47:15 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:47:15 - [trace] [flow:8fe02e49cbc1e1e3] start flow [8fe02e49cbc1e1e3]
1 Dec 08:47:15 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:47:15 - [trace] [flow:8fe02e49cbc1e1e3]  id               | type         | alias
1 Dec 08:47:15 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:47:15 - [trace] [flow:8fe02e49cbc1e1e3]  98eda388285104a1 | mqtt in      |
1 Dec 08:47:15 - [trace] [flow:8fe02e49cbc1e1e3]  e426ca5edb464827 | debug        |
1 Dec 08:47:15 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:47:15 - [trace] runtime event: {"id":"runtime-state","payload":{"state":"start","deploy":true},"retain":true}
1 Dec 08:47:15 - [info] Started modified flows
1 Dec 08:47:15 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"aec89413f9c5c5862827576f6d44d909"},"retain":true}
1 Dec 08:47:15 - [info] [mqtt-broker:main] Disconnected from broker: mqtt://192.168.0.24:1883
[ === EVENT: RE-DEPLOY 4 - leading to re-connect === ]
1 Dec 08:47:25 - [trace] utils.writeFile - copied /data/flows.json TO /data/.flows.json.backup
1 Dec 08:47:25 - [trace] utils.writeFile - written content to /data/flows.json.$$$
1 Dec 08:47:25 - [trace] utils.writeFile - renamed /data/flows.json.$$$ to /data/flows.json
1 Dec 08:47:25 - [debug] saved flow revision: 1cf16b3e9fa0bb14fde3cf71614001c7
1 Dec 08:47:25 - [info] Stopping modified flows
1 Dec 08:47:25 - [debug] red/nodes/flows.stop : stopping flow : 8fe02e49cbc1e1e3
1 Dec 08:47:25 - [trace] [flow:8fe02e49cbc1e1e3] stop flow
1 Dec 08:47:25 - [trace] Stopping node debug:e426ca5edb464827
1 Dec 08:47:25 - [trace] Stopping node mqtt in:98eda388285104a1
1 Dec 08:47:25 - [debug] red/nodes/flows.stop : stopping flow : global
1 Dec 08:47:25 - [trace] [flow:global] stop flow
1 Dec 08:47:25 - [trace] Stopped node debug:e426ca5edb464827 (0ms)
1 Dec 08:47:25 - [trace] Stopped node mqtt in:98eda388285104a1 (0ms)
1 Dec 08:47:25 - [info] Stopped modified flows
1 Dec 08:47:25 - [trace] runtime event: {"id":"runtime-state","payload":{"state":"stop","deploy":true},"retain":true}
1 Dec 08:47:25 - [info] Updated flows
1 Dec 08:47:25 - [info] Starting modified flows
1 Dec 08:47:25 - [debug] red/nodes/flows.start : not starting disabled flow : 404a5fc31d9bfebc
1 Dec 08:47:25 - [debug] red/nodes/flows.start : not starting disabled flow : 80c0daf0d6dc14e8
1 Dec 08:47:25 - [debug] red/nodes/flows.start : not starting disabled flow : fefe4cc15c24e3f0
1 Dec 08:47:25 - [trace] [flow:global] start flow [global]
1 Dec 08:47:25 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:47:25 - [trace] [flow:global]  id               | type         | alias
1 Dec 08:47:25 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:47:25 - [trace] [flow:global]  ec6252675c95ed29 | server       |
1 Dec 08:47:25 - [trace] [flow:global]  09a1213024a9a03b | influxdb     |
1 Dec 08:47:25 - [trace] [flow:global]  d50d0c9f.31e858  | tls-config   |
1 Dec 08:47:25 - [trace] [flow:global]  5d7e54ca.019d44  | influxdb     |
1 Dec 08:47:25 - [trace] [flow:global]  5a4cacde8bbbdebd | mqtt-broker  |
1 Dec 08:47:25 - [trace] [flow:global] ------------------|--------------|-----------------
1 Dec 08:47:25 - [trace] [flow:8fe02e49cbc1e1e3] start flow [8fe02e49cbc1e1e3]
1 Dec 08:47:25 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:47:25 - [trace] [flow:8fe02e49cbc1e1e3]  id               | type         | alias
1 Dec 08:47:25 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:47:25 - [trace] [flow:8fe02e49cbc1e1e3]  98eda388285104a1 | mqtt in      |
1 Dec 08:47:25 - [trace] [flow:8fe02e49cbc1e1e3]  e426ca5edb464827 | debug        |
1 Dec 08:47:25 - [trace] [flow:8fe02e49cbc1e1e3] ------------------|--------------|-----------------
1 Dec 08:47:25 - [trace] runtime event: {"id":"runtime-state","payload":{"state":"start","deploy":true},"retain":true}
1 Dec 08:47:25 - [info] Started modified flows
1 Dec 08:47:25 - [trace] runtime event: {"id":"runtime-deploy","payload":{"revision":"1cf16b3e9fa0bb14fde3cf71614001c7"},"retain":true}
1 Dec 08:47:25 - [info] [mqtt-broker:main] Connected to broker: mqtt://192.168.0.24:1883

Mosquitto Logs:

[ === showing last few events for reference === ]
08:46:53 | 1669884413: Received PUBLISH from mqttjs_a23a0c39 (d0, q0, r0, m0, 'zigbee2mqtt/bridge/logging', ... (212 bytes))
08:46:53 | 1669884413: Sending PUBLISH to mqttjs_a23a0c39 (d0, q0, r0, m0, 'zigbee2mqtt/bridge/logging', ... (212 bytes))
08:46:53 | 1669884413: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r0, m0, 'zigbee2mqtt/bridge/logging', ... (212 bytes))
08:46:53 | 1669884413: Received PUBLISH from mqttjs_a23a0c39 (d0, q0, r0, m0, 'zigbee2mqtt/Bedroom Window', ... (111 bytes))
08:46:53 | 1669884413: Sending PUBLISH to 7cIL6MUkpu61IzJvwMcuDH (d0, q0, r0, m0, 'zigbee2mqtt/Bedroom Window', ... (111 bytes))
08:46:53 | 1669884413: Sending PUBLISH to mqttjs_a23a0c39 (d0, q0, r0, m0, 'zigbee2mqtt/Bedroom Window', ... (111 bytes))
08:46:53 | 1669884413: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r0, m0, 'zigbee2mqtt/Bedroom Window', ... (111 bytes))
[ === EVENT: RE-DEPLOY 1 - leading to disconnect === ]
08:46:56 | 1669884416: Received UNSUBSCRIBE from nodered_bdc64086c6f62d72
08:46:56 | 1669884416:         zigbee2mqtt/#
08:46:56 | 1669884416: nodered_bdc64086c6f62d72 zigbee2mqtt/#
08:46:56 | 1669884416: Sending UNSUBACK to nodered_bdc64086c6f62d72
08:46:56 | 1669884416: Received DISCONNECT from nodered_bdc64086c6f62d72
08:46:56 | 1669884416: Client nodered_bdc64086c6f62d72 disconnected.
08:46:59 | 1669884419: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51668, 'hass-states/sensor/router_packets_received/state', ... (9 bytes))
08:46:59 | 1669884419: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51668, rc0)
08:46:59 | 1669884419: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51669, 'hass-states/sensor/router_packets_sent/state', ... (8 bytes))
08:46:59 | 1669884419: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51669, rc0)
[ === ... snipping unrelated home assistant events like the ones above and below ... === ]
08:47:02 | 1669884422: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51784, 'hass-states/binary_sensor/ping_outside/device_class', ... (14 bytes))
08:47:02 | 1669884422: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51784, rc0)
08:47:02 | 1669884422: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51785, 'hass-states/binary_sensor/ping_outside/friendly_name', ... (18 bytes))
08:47:02 | 1669884422: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51785, rc0)
[ === EVENT: RE-DEPLOY 2 - leading to re-connect === ]
08:47:05 | 1669884425: New connection from 192.168.16.1:58698 on port 1883.
08:47:05 | 1669884425: New client connected from 192.168.16.1:58698 as nodered_bdc64086c6f62d72 (p5, c1, k60).
08:47:05 | 1669884425: No will message specified.
08:47:05 | 1669884425: Sending CONNACK to nodered_bdc64086c6f62d72 (0, 0)
08:47:05 | 1669884425: Received SUBSCRIBE from nodered_bdc64086c6f62d72
08:47:05 | 1669884425:         zigbee2mqtt/# (QoS 2)
08:47:05 | 1669884425: nodered_bdc64086c6f62d72 2 zigbee2mqtt/#
08:47:05 | 1669884425: Sending SUBACK to nodered_bdc64086c6f62d72
08:47:05 | 1669884425: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/state', ... (18 bytes))
08:47:05 | 1669884425: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/info', ... (21051 bytes))
08:47:05 | 1669884425: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/devices', ... (38987 bytes))
08:47:05 | 1669884425: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/groups', ... (2 bytes))
08:47:05 | 1669884425: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/extensions', ... (2 bytes))
08:47:06 | 1669884426: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51786, 'hass-states/sensor/mt1_wired_clients/state', ... (1 bytes))
08:47:06 | 1669884426: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51786, rc0)
08:47:06 | 1669884426: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51787, 'hass-states/sensor/mt1_wired_clients/last_updated', ... (32 bytes))
08:47:06 | 1669884426: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51787, rc0)
[ === ... snipping unrelated home assistant events like the ones above and below ... === ]
08:47:12 | 1669884432: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51829, 'hass-states/binary_sensor/ping_outside/device_class', ... (14 bytes))
08:47:12 | 1669884432: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51829, rc0)
08:47:12 | 1669884432: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51830, 'hass-states/binary_sensor/ping_outside/friendly_name', ... (18 bytes))
08:47:12 | 1669884432: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51830, rc0)
[ === EVENT: RE-DEPLOY 3 - leading to disconnect === ]
08:47:15 | 1669884435: Received UNSUBSCRIBE from nodered_bdc64086c6f62d72
08:47:15 | 1669884435:         zigbee2mqtt/#
08:47:15 | 1669884435: nodered_bdc64086c6f62d72 zigbee2mqtt/#
08:47:15 | 1669884435: Sending UNSUBACK to nodered_bdc64086c6f62d72
08:47:15 | 1669884435: Received DISCONNECT from nodered_bdc64086c6f62d72
08:47:15 | 1669884435: Client nodered_bdc64086c6f62d72 disconnected.
08:47:22 | 1669884442: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51831, 'hass-states/binary_sensor/ping_mt2/state', ... (2 bytes))
08:47:22 | 1669884442: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51831, rc0)
08:47:22 | 1669884442: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51832, 'hass-states/binary_sensor/ping_mt2/last_updated', ... (32 bytes))
08:47:22 | 1669884442: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51832, rc0)
[ === ... snipping unrelated home assistant events like the ones above and below ... === ]
08:47:22 | 1669884442: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51868, 'hass-states/binary_sensor/ping_outside/device_class', ... (14 bytes))
08:47:22 | 1669884442: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51868, rc0)
08:47:22 | 1669884442: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51869, 'hass-states/binary_sensor/ping_outside/friendly_name', ... (18 bytes))
08:47:22 | 1669884442: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51869, rc0)
[ === EVENT: RE-DEPLOY 4 - leading to re-connect === ]
08:47:25 | 1669884445: New connection from 192.168.16.1:58044 on port 1883.
08:47:25 | 1669884445: New client connected from 192.168.16.1:58044 as nodered_bdc64086c6f62d72 (p5, c1, k60).
08:47:25 | 1669884445: No will message specified.
08:47:25 | 1669884445: Sending CONNACK to nodered_bdc64086c6f62d72 (0, 0)
08:47:25 | 1669884445: Received SUBSCRIBE from nodered_bdc64086c6f62d72
08:47:25 | 1669884445:         zigbee2mqtt/# (QoS 2)
08:47:25 | 1669884445: nodered_bdc64086c6f62d72 2 zigbee2mqtt/#
08:47:25 | 1669884445: Sending SUBACK to nodered_bdc64086c6f62d72
08:47:25 | 1669884445: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/state', ... (18 bytes))
08:47:25 | 1669884445: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/info', ... (21051 bytes))
08:47:25 | 1669884445: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/devices', ... (38987 bytes))
08:47:25 | 1669884445: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/groups', ... (2 bytes))
08:47:25 | 1669884445: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r1, m0, 'zigbee2mqtt/bridge/extensions', ... (2 bytes))
08:47:25 hostname zigbee2mqtt.sh[984327]: zigbee2mqtt    | Zigbee2MQTT:info  2022-12-01 09:47:25: MQTT publish: topic 'zigbee2mqtt/Office Window', payload '{"battery":100,"contact":true,"device_temperature":23,"linkquality":65,"power_outage_count":8,"voltage":3205}'
08:47:25 | 1669884445: Received PUBLISH from mqttjs_a23a0c39 (d0, q0, r0, m0, 'zigbee2mqtt/bridge/logging', ... (209 bytes))
08:47:25 | 1669884445: Sending PUBLISH to mqttjs_a23a0c39 (d0, q0, r0, m0, 'zigbee2mqtt/bridge/logging', ... (209 bytes))
08:47:25 | 1669884445: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r0, m0, 'zigbee2mqtt/bridge/logging', ... (209 bytes))
08:47:25 | 1669884445: Received PUBLISH from mqttjs_a23a0c39 (d0, q0, r0, m0, 'zigbee2mqtt/Office Window', ... (109 bytes))
08:47:25 | 1669884445: Sending PUBLISH to 7cIL6MUkpu61IzJvwMcuDH (d0, q0, r0, m0, 'zigbee2mqtt/Office Window', ... (109 bytes))
08:47:25 | 1669884445: Sending PUBLISH to mqttjs_a23a0c39 (d0, q0, r0, m0, 'zigbee2mqtt/Office Window', ... (109 bytes))
08:47:25 | 1669884445: Sending PUBLISH to nodered_bdc64086c6f62d72 (d0, q0, r0, m0, 'zigbee2mqtt/Office Window', ... (109 bytes))
08:47:25 | 1669884445: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51870, 'hass-states/sensor/office_window_device_temperature/state', ... (2 bytes))
08:47:25 | 1669884445: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51870, rc0)
08:47:25 | 1669884445: Received PUBLISH from 7cIL6MUkpu61IzJvwMcuDH (d0, q1, r1, m51871, 'hass-states/sensor/office_window_device_temperature/last_updated', ... (32 bytes))
08:47:25 | 1669884445: Sending PUBACK to 7cIL6MUkpu61IzJvwMcuDH (m51871, rc0)
[ === ... snipping unrelated home assistant events like the ones above ... === ]

From the logs, it looks like the MQTT-In node is willingly disconnecting from the broker. I especially noted the Received UNSUBSCRIBE events in the Mosquitto logs when Node-RED disconnected.

Am I right in assuming that this is not intended behavior? Is there anything else I can do to diagnose the issue further?

This is a bit annoying to me because with every second re-deployment the MQTT node is disabled.

Thanks for any help!

Best,
Michael

Steve-Mcl · 1 December 2022 11:46

Hi, without getting too deep into the details and logs, I think this is related to this issue: MQTT not reconnecting on edit if only only one mqtt node using the config node · Issue #3927 · node-red/node-red · GitHub which started here: MQTT not reconnecting if only only one mqtt node using it

And here is a PR that fixes it: fix single subscription mqtt node status by Steve-Mcl · Pull Request #3928 · node-red/node-red · GitHub

Please let me know if adding a 2nd subscription to some other topic fixes this

michael-b · 1 December 2022 12:44

Hi, thanks for the pointer! I did some searching but didn't find this thread specifically, sorry about that.

Just adding a second node to the same flow didn't help (neither did a close or will message, by the way), but adding another node to a second flow (which is then unaffected by the re-deploy) did.

Just as a side node, I'm not sure why adding another node in the same flow should resolve this issue. From what I understood, the problem is too quick close/reregister, which also happens when I have two or three nodes in the same flow. The only way to reliable avoid the issue is to have another node in a different flow, which makes sure it's not closed.

Anyway, thanks again and thanks for that PR Hope it'll go through soon so others aren't affected.

Cheers!

Steve-Mcl · 1 December 2022 12:48

What deploy type do you do?

Full, modified flows or modified nodes?

The issue is related to internal state & how deploying flow/node changes occur.
When a single subscription exists and you re-deploy that node, it first gets destroyed (meaning there are no longer any subscriptions & thus it disconnects) - the fix in the PR handles this situation a bit more elegantly.

michael-b · 1 December 2022 13:09

Ah, I forgot to mention: I'm doing modified flows.

Now it makes sense. If I just add another MQTT node to the same flow, the issue persists because I effectively still reload both nodes. When using "modified nodes", the issue is actually resolved by adding another node (because that node is not destroyed).

Thanks so much

system · 30 January 2023 13:09

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
MQTT Out Node Constantly Disconnecting General	10	6872	16 November 2020
MQTT & node-red-contrib-tuya-smart-device Node Problems General	22	2014	5 July 2021
MQTT connection to AWS IoT Core disconnecting and not reconnecting without restarting flows General mqtt	22	3564	11 April 2022
Do Node-red MQTT nodes and CLI mosquitto_pub interfere with each other? General	6	163	1 March 2023
MQTT in node not working properly in Node-Red 2.2.1 General mqtt	5	1348	20 February 2022

MQTT In: Disconnect after Re-Deploy

Related Topics