Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

MQTT in Node: Error stopping node: Close timed out #2934

Closed
5 tasks
hybuild-project opened this issue Apr 15, 2021 · 61 comments · Fixed by #3451
Closed
5 tasks

MQTT in Node: Error stopping node: Close timed out #2934

hybuild-project opened this issue Apr 15, 2021 · 61 comments · Fixed by #3451

Comments

@hybuild-project
Copy link

hybuild-project commented Apr 15, 2021

What are the steps to reproduce?

Import the flow in: https://cookbook.nodered.org/mqtt/connect-to-broker, start any MQTT broker (e.g. Mosquitto) and deploy
EDIT: The error is not evident with Mosquitto, as initially reported, but e.g. with https://github.com/martin-doyle/node-red-contrib-aedes.

What happens?

Every time the flow is deployed, the MQTT in node gets stuck for a while, then output: "Error stopping node: Close timed out"

What do you expect to happen?

The MQTT in node is immediately closed without errors and the flow is deployed without error and time wasting.

Please tell us about your environment:

  • Node-RED version: 1.3.2
  • Node.js version: 14.6.1
  • npm version:
  • Platform/OS: Win 10
  • Browser: Chrome
@knolleary
Copy link
Member

Hi,

I'm not able to reproduce this issue, so there may be something more specific with your environment that is contributing to it.

I assume you have the broker running locally rather than using a remote broker?

@hardillb
Copy link
Member

Are using mosquito 2.0? And is it on the same machine as node-red?

@hybuild-project
Copy link
Author

hybuild-project commented Apr 17, 2021

The error is connected to 04a3c4b. It happens only with Node-RED v1.3.x and when a full deploy is performed, not an incremental one.
Full credits go to @martin-doyle who I thank again.
I have edited the OP to highlight the error comes out if you use a MQTT broker like Aedes node. External Mosquitto seems to be not affected.
Waiting for v1.3.3.
Thanks for your excellent work!

@martin-doyle
Copy link

Hi,

I am the maintainer of node-red-contrib-aedes. This issue only happens with a broker as part of Node-RED. An external broker is fine.
As far as I can see Node-RED closes the MQTT broker node-red-contrib-aedes first. Then the MQTT nodes send a disconnect which can't be answered anymore since the broker is already down.

20 Apr 20:20:43 - [info] [aedes broker:Standard Broker] Unbinding aedes mqtt server from port: 1885
20 Apr 20:20:43 - [info] [mqtt-broker:localhost:1885] Disconnected from broker: mqtt://localhost:1885
20 Apr 20:20:58 - [error] [mqtt in:80486cfb.0747d] Error stopping node: Close timed out

As mentioned before, everything was fine until version 1.2.9. The issue only happens when Node-RED shuts down i.e. at close and at a full deploy.

Is there anything I can do in order to make the broker close after the MQTT nodes? Or do I have to send a specific signal before close?

No change for version 1.3.3. Any help is welcome.

Martin

@kuema
Copy link

kuema commented Apr 21, 2021

Could the change #2880 be relevant this?

@knolleary
Copy link
Member

Yes, this will be related to the change in order of stopping things.

Previous, the flow/config nodes would be stopped in a somewhat random order - related to the order they were originally added to the workspace.

Now, the flow nodes are stopped first and then the config nodes are stopped.

This originally broke the 'on-close' message sending of the MQTT nodes as it was being handled by the close event of the config node - by which time all of the MQTT nodes would have already been stopped and the connection closed. So the sending of the message was moved to get triggered when the last MQTT node is closed.

If the aedes broker is a flow node, it will getting stopped alongside the MQTT nodes. If the aedes broker node was added first, it will get stopped before all of the MQTT nodes - meaning the connection will be dropping in parallel to the MQTT nodes stopping and trying to send the final on-close message.

To be honest, I'm not sure why you'd have an on-close message configured in the MQTT nodes if your broker is running inside Node-RED as well - the only time they are going to disconnect cleanly is when the flow is restarting or Node-RED is stopping, in which case the broker is going to be restarting/stopping as well.

@martin-doyle
Copy link

As far as I know, sending the on-close message is the standard behaviour of the MQTT config nodes. There is no additonal message configured. So, the problem is now that the MQTT config node expects an answer of a broker which is already down. Right now, I have no idea how to fix this issue on the broker side.

@knolleary
Copy link
Member

Ah right. I thought this was related to the publishing of the on-close message (which is what the referenced commit fixed).

This is just the node timing out when trying to disconnect.. which is indeed odd. I'll investigate.

@hardillb
Copy link
Member

The message Nick is referring to in the last paragraph is the one configured in the "Messages" tab for the MQTT-in/out's config node that includes the broker connection details.

These are the Birth/Close/LWT messages. It doesn't make much sense to have any (OK, may be the Birth message) of these messages if the broker is in the same process as the client as they will only fire when the broker is very likely to be in the process of restarting as well.

@emc02
Copy link

emc02 commented May 25, 2021

having the same issue on RaspberryPi with:
Node-RED version: v1.3.5
node.js version: v12.22.1
npm version: 6.14.12
Platform/OS: RaspiOS
Browser: Chrome and Firefox

@hardillb
Copy link
Member

@emc02 Just to be clear, what broker are you using?

@emc02
Copy link

emc02 commented May 25, 2021

I am using aedes broker and connecting to zigbee2mqtt
It worked fine till I upgraded yesterday to latest version of nodered and broker.

@daniel-schel
Copy link

I have this problem too, with an external broker on a separate VM. I use for this:

  • vernemq v1.11.0
  • Node-Red v1.3.5

The MQTT broker node is configured with the MQTT protocol version 3.1.1 and there are no messages configured on connection, before disconnecting or unexpected disconnection.

@martin-doyle
Copy link

The issue still exists with Node-RED version 2. Is there any fix available?

@RGNagel
Copy link

RGNagel commented Oct 11, 2021

Same problem here. Any update? Thanks!

@hardillb
Copy link
Member

@RGNagel just to be 100% clear you are using the mqtt broker nodes as well?

If so the best workaround is to one of the following

  1. Use a separate broker (e.g. mosquitto)
  2. Change the deploy type to only deploy changed nodes, because the broker is unlikely to change its settings therefore won't get stopped.

The error is normally because the broker is getting stopped before the client nodes

@denonbw
Copy link

denonbw commented Feb 15, 2022

Hello Together
after updating from 2.2.0 to 2.2.1 I have the same Behavior.
The installation few weeks old and has only this small flow:

[ { "id": "150d20998fc7fe72", "type": "tab", "label": "Flow 1", "disabled": false, "info": "", "env": [] }, { "id": "391e5b8123b3fdc0", "type": "mqtt in", "z": "150d20998fc7fe72", "name": "", "topic": "stepperin/status/stepperrun", "qos": "2", "datatype": "auto", "broker": "98d6b4dad9e2c400", "nl": false, "rap": true, "rh": 0, "inputs": 0, "x": 290, "y": 60, "wires": [ [ "a4fc05cefd74869d" ] ] }, { "id": "a4fc05cefd74869d", "type": "debug", "z": "150d20998fc7fe72", "name": "", "active": true, "tosidebar": true, "console": false, "tostatus": false, "complete": "false", "statusVal": "", "statusType": "auto", "x": 550, "y": 60, "wires": [] }, { "id": "e7d268159853c70f", "type": "mqtt out", "z": "150d20998fc7fe72", "name": "", "topic": "stepperin", "qos": "", "retain": "", "respTopic": "", "contentType": "", "userProps": "", "correl": "", "expiry": "", "broker": "98d6b4dad9e2c400", "x": 520, "y": 180, "wires": [] }, { "id": "3848d22e6f02fa97", "type": "inject", "z": "150d20998fc7fe72", "name": "", "props": [ { "p": "payload" }, { "p": "topic", "vt": "str" } ], "repeat": "", "crontab": "", "once": false, "onceDelay": 0.1, "topic": "", "payload": "{ \"aktion\": \"movestepper\", \"stepps\": \"21968\", \"speed\": \"10000\", \"acceleration\": \"30000\" }", "payloadType": "str", "x": 250, "y": 160, "wires": [ [ "e7d268159853c70f" ] ] }, { "id": "f84e8543482cf0dd", "type": "inject", "z": "150d20998fc7fe72", "name": "", "props": [ { "p": "payload" }, { "p": "topic", "vt": "str" } ], "repeat": "", "crontab": "", "once": false, "onceDelay": 0.1, "topic": "", "payload": "{ \"aktion\": \"movestepper\", \"stepps\": \"-21968\", \"speed\": \"10000\", \"acceleration\": \"30000\" }", "payloadType": "str", "x": 250, "y": 220, "wires": [ [ "e7d268159853c70f" ] ] }, { "id": "98d6b4dad9e2c400", "type": "mqtt-broker", "name": "localhost", "broker": "localhost", "port": "1883", "clientid": "nodered", "autoConnect": true, "usetls": false, "protocolVersion": "4", "keepalive": "60", "cleansession": true, "birthTopic": "", "birthQos": "0", "birthPayload": "", "birthMsg": {}, "closeTopic": "", "closeQos": "0", "closePayload": "", "closeMsg": {}, "willTopic": "", "willQos": "0", "willPayload": "", "willMsg": {}, "sessionExpiry": "" } ]

The broker runs on the same pi and is mosquitto (2.0.11).
The update was done by script:
https://nodered.org/docs/getting-started/raspberrypi

I have already completely deleted the flow and recreated by hand. The first 4 or 5 deploys were fast. After that the behavior happened again.

@hardillb
Copy link
Member

hardillb commented Feb 15, 2022

@denonbw This issue is all about using node-red-contrib-aedes.

If you have a problem when using an external broker (mosquitto) then it is very unlikely to be related to this as it is caused by the broker (aedes) being shutdown before the mqtt node connected to it tries to send it's last message.

Given your flow doesn't appear to be using birth or close messages again not likely to be related to this issue. I suggest you open a new issue and include all the relevant data (including the Node-RED log output covering the period before and after the deploy and mosquitto logs for the same period)

@sanyafifa
Copy link

sanyafifa commented Feb 15, 2022

Same problem after update

2.2.0 to 2.2.1

mosquitto version 2.0.13
nodejs v16.14.0

@hardillb
Copy link
Member

@sanyafifa can you supply Node-RED logs from before and after a deploy and the broker logs from the same period. Along with the type of deploy (full, changed flows, changed nodes).

@Steve-Mcl
Copy link
Contributor

@sanyafifa

As well as you logs, can you describe you setup (OS, Hardware, direct connection to internet? behind proxy?)
AND
provide a list of installed contrib nodes

@Paul-Reed
Copy link

Paul-Reed commented Feb 15, 2022

Same here since updating from v2.2.0 to v2.2.1.

mqtt

Raspberry Pi 3b
Raspbian Buster
Not behind proxy
Contrib nodes installed:

    "@searis/node-red-contrib-clarify": "~1.0.1",
    "bcryptjs": "^2.4.3",
    "dayjs": "^1.10.6",
    "fs-extra": "^8.1.0",
    "is-ip": "^3.1.0",
    "needle": "^2.8.0",
    "node-red-contrib-cast": "~0.2.17",
    "node-red-contrib-counter": "~0.1.6",
    "node-red-contrib-cron-plus": "~1.5.6",
    "node-red-contrib-dsm": "~0.14.1",
    "node-red-contrib-finite-statemachine": "~2.1.3",
    "node-red-contrib-flogger-now": "~1.0.0",
    "node-red-contrib-google-smarthome": "~0.2.10",
    "node-red-contrib-msg-profiler": "git+https://github.com/bartbutenaers/node-red-contrib-msg-profiler.git",
    "node-red-contrib-msg-speed": "~2.1.0",
    "node-red-contrib-pushover": "~0.2.0",
    "node-red-contrib-queue-gate": "~1.5.5",
    "node-red-contrib-rf-decode": "0.0.2",
    "node-red-contrib-simple-gate": "~0.5.2",
    "node-red-contrib-simpletime": "~2.10.3",
    "node-red-contrib-telegrambot": "~11.2.4",
    "node-red-contrib-ui-multistate-switch": "git+https://github.com/bartbutenaers/node-red-contrib-ui-multistate-switch.git",
    "node-red-contrib-vcgencmd": "~1.0.3",
    "node-red-contrib-virtual-smart-home": "~2.13.1",
    "node-red-contrib-watt2kwh": "~0.1.2",
    "node-red-contrib-webhookrelay": "~0.3.0",
    "node-red-dashboard": "~3.1.5",
    "node-red-debugger": "~1.1.1",
    "node-red-node-dropbox": "~1.0.2",
    "node-red-node-pushover": "~0.1.1",
    "node-red-node-serialport": "~0.15.0",
    "node-red-node-smooth": "~0.1.2",
    "node-red-node-ui-table": "~0.3.12",
    "ping": "^0.4.1"

Install log:

/usr/bin/node-red-pi -> /usr/lib/node_modules/node-red/bin/node-red-pi

> bcrypt@5.0.1 install /usr/lib/node_modules/node-red/node_modules/bcrypt
> node-pre-gyp install --fallback-to-build

node-pre-gyp ERR! install response status 404 Not Found on https://github.com/kelektiv/node.bcrypt.js/releases/download/v5.0.1/bcrypt_lib-v5.0.1-napi-v3-linux-arm-glib$
node-pre-gyp WARN Pre-built binaries not installable for bcrypt@5.0.1 and node@14.19.0 (node-v83 ABI, glibc) (falling back to source compile with node-gyp)
node-pre-gyp WARN Hit error response status 404 Not Found on https://github.com/kelektiv/node.bcrypt.js/releases/download/v5.0.1/bcrypt_lib-v5.0.1-napi-v3-linux-arm-gl$
make: Entering directory '/usr/lib/node_modules/node-red/node_modules/bcrypt/build'
  CC(target) Release/obj.target/nothing/../node-addon-api/nothing.o
  AR(target) Release/obj.target/../node-addon-api/nothing.a
  COPY Release/nothing.a
  CXX(target) Release/obj.target/bcrypt_lib/src/blowfish.o
  CXX(target) Release/obj.target/bcrypt_lib/src/bcrypt.o
  CXX(target) Release/obj.target/bcrypt_lib/src/bcrypt_node.o
  SOLINK_MODULE(target) Release/obj.target/bcrypt_lib.node
  COPY Release/bcrypt_lib.node
  COPY /usr/lib/node_modules/node-red/node_modules/bcrypt/lib/binding/napi-v3/bcrypt_lib.node
  TOUCH Release/obj.target/action_after_build.stamp
make: Leaving directory '/usr/lib/node_modules/node-red/node_modules/bcrypt/build'
+ node-red@2.2.1
added 290 packages from 374 contributors in 310.139s
2.2.1
Now create basic package.json for the user and move any global nodes
Now add the shortcut and start/stop/log scripts to the menu
Now add systemd script and configure it for pi:pi @ /home/pi
ln: failed to create symbolic link '/usr/bin/python': File exists
Now add launcher to top bar, add cpu temp example, make sure ping works
The user `pi' is already a member of `gpio'.

WARNING: apt does not have a stable CLI interface. Use with caution in scripts.

Reading package lists...
Building dependency tree...
Reading state information...
python3-rpi.gpio is already the newest version (0.7.0-0.1~bpo10+4).
0 upgraded, 0 newly installed, 0 to remove and 2 not upgraded.
Memory  : 1.0G
Started :  Tue 15 Feb 2022 08:42:53 PM GMT
Finished:  Tue 15 Feb 2022 08:48:59 PM GMT

@Steve-Mcl
Copy link
Contributor

@Paul-Reed

Hi Paul, I see aedes in your screenshot but I don't say it listed in your nodes.

What gives?

Are you using aedes as a broker in your node-red?

@Paul-Reed
Copy link

Paul-Reed commented Feb 16, 2022

I should have made this clear, apologies.

Aedes broker is running on a cloud server, which has not been edited, or even the server accessed during the past few weeks.
The client is running on my local Pi, using the default MQTT 'in node'
The error message occurred immediately after updating my local Pi from v2.2.0 to v2.2.1 (in the local Pi debug), and every time I restart flows.
The node-RED log shows this problem when my local Pi closes down;

15 Feb 23:49:42 - [info] Stopping flows
15 Feb 23:49:42 - [info] serial port /dev/ttyAMA0 closed
15 Feb 23:49:57 - [error] [mqtt in:Aedes test] Error stopping node: Close timed out
15 Feb 23:49:57 - [error] [mqtt in:Dummy] Error stopping node: Close timed out
15 Feb 23:49:57 - [error] [mqtt in:3e51925c4519d148] Error stopping node: Close timed out
15 Feb 23:49:57 - [info] Stopped flows

When node_RED restarts, If I search amongst my Cron+ log entries... 🔇
The only Aedes entry I see is;

15 Feb 23:49:59 - [info] [mqtt-broker:aedes mqtt] Connected to broker: mqtt://140.238.65.67:1883

I am also running mosquitto version 1.5.7 on my local Pi which is working without issue, and handling most of my MQTT traffic.

@Paul-Reed
Copy link

In fact, it's not confined to Aedes.
In the stopping flows log (my last post above) the entry;
15 Feb 23:49:57 - [error] [mqtt in:Dummy] Error stopping node: Close timed out
That is a standard MQTT 'in node', which is connected to the remote cloudmqtt.com broker on port 15069.

Both Aedes & cloudmqtt have been happily working for a number of months, and these errors have only started after updating to node-RED v2.2.1, and worked fine under v2.2.0.

@knolleary
Copy link
Member

We updated the underlying MQTT.js library in 2.2.1. It went from 4.3.4 to 4.3.5. The changelog doesn't reveal anything suspicious that could be causing this sudden influx of problems. But it is a change nonetheless.

We have the option to rollback that update and release 2.2.2 - that would be a quick and pragmatic (and temporary) solution.

The alternative is we try to diagnose the actual issue and see if there's a change needed in how the mqtt-broker node uses the mqtt.js library.

@Paul-Reed
Copy link

If you can't replicate, I'm around today, and will gladly help wherever I can.

@denonbw
Copy link

denonbw commented Feb 16, 2022

For me it is not an pressing problem, so I can wait until the problem is found. The deploy works, it just takes a long time and returns an error.
Maybe it will become a problem when more and more instances are updated to 2.2.1 and more people have the bug.

Sorry for not opening a new issues and posting it here in the wrong one.

@Xploder
Copy link

Xploder commented Feb 16, 2022

I'm also encountering this issue since updating to the newest docker container. nodered 2.2.1
Reverting to 2.2.0 fixes it.

@Steve-Mcl
Copy link
Contributor

@Paul-Reed did you leave off the -g

@Paul-Reed
Copy link

Yes. sudo npm install mqtt@4.3.4
I've also double checked the downgraded version number in it's package.json - (4.3.4)

@sanyafifa
Copy link

i downgraded the mqtt version to 4.3.4.
sudo npm install mqtt@4.3.4
The error is still there :(
image

@Steve-Mcl
Copy link
Contributor

Steve-Mcl commented Feb 16, 2022

An update for those waiting a solution.

I now understand the issue (race condition between in/out nodes closing vs broker disconnecting -AND- the MQTT lib change of when it calls the callback in the end() function between client v4.2 and v4.3) and I am working on a number of angles / solutions.

TBH: I rarely use full deploy so hadn't noticed this however I suspect the issue has been present since I added Dynamic subscriptions to MQTT 4 months ago 😱

Should have an update for you today or tomorrow 🤞

@Paul-Reed
Copy link

Thanks Steve, however I'd be surprised if it has been present 4 months, as I updated to node-RED v2.2.0 on 29th Jan, and this problem did not occur until I updated to v2.2.1 yesterday.
Of late, I've been rebooting my Pi quite a lot, and am confident that I would have noticed.

@Steve-Mcl
Copy link
Contributor

Have you recently started using FULL DEPLOY? Or recently started changing MQTT nodes?

The issue is related to when either a FULL DEPLOY or a PARTIAL/NODE DEPLOY causes all MQTT in/out nodes to be closed

In other words, if you have been moving flows around and happened to affect all MQTT in/out nodes that are related to 1 broker, you can trigger this timing issue.

No matter anyhow. Perhaps it is better to say, all the elements of the problem have been in place since dynamic MQTT however a number of other factors (MQTT client internal changes) have highlighted the issue.

@sanyafifa
Copy link

mosqutto log using FULL DEPLOY NR:
1645025868: Client mqttjs_24e6b775 disconnected. 1645025884: New connection from 127.0.0.1:60960 on port 1883. 1645025884: New connection from 127.0.0.1:60962 on port 1883. 1645025884: New client connected from 127.0.0.1:60960 as mqttjs_ad2fe142 (p2, c1, k60). 1645025884: New client connected from 127.0.0.1:60962 as nodered_897808d04322b0bc (p2, c1, k15).

Have you recently started using FULL DEPLOY?

This issue was introduced in v2.2.1 . i always use full deploy

@Steve-Mcl
Copy link
Contributor

This issue was introduced in v2.2.1 . i always use full deploy

As I said above...

No matter anyhow. Perhaps it is better to say, all the elements of the problem have been in place since dynamic MQTT however a number of other factors (MQTT client internal changes) have highlighted the issue.

So, instead of expending efforts on when / how, I am concentrating on a more stable solution. Shouldn't be too long.

@Steve-Mcl
Copy link
Contributor

Update: I have a working fix but I will be spending a lot more time trying various scenarios, including the aedes issue mentioned earlier in this thread before I publish. Possibly tomorrow or Friday.

In the meantime, please sit tight (or avoid full deploys if you can)

@goxofy
Copy link

goxofy commented Feb 18, 2022

Same problem. Thanks!

@denonbw
Copy link

denonbw commented Feb 18, 2022

2.2.2 Works great! Thanks for the quick fix

@quadhammer
Copy link

I'm using the Home Assistant Node Red plugin. I get the error if I go from nodered_11.0.2 to 11.0.3.

I'm using https://www.home-assistant.io/integrations/mqtt as my broker.

@Steve-Mcl
Copy link
Contributor

@quadhammer those version numbers are home assistant versions not node-red versions. What version number of node-red do you see if you look in the nodes hamburger menu?

@jonascoenen005
Copy link

when is v2.2.2 being released in home assistant?

@hardillb
Copy link
Member

@jonascoenen005 that is not a question the Node-RED community can answer, we have no input into when Home Assistant release things

@quadhammer
Copy link

@quadhammer those version numbers are home assistant versions not node-red versions. What version number of node-red do you see if you look in the nodes hamburger menu?

Node-RED v2.2.0

@Steve-Mcl
Copy link
Contributor

I get the error if I go from nodered_11.0.2 to 11.0.3.

Node-RED v2.2.0

@quadhammer hopefully now you can see you are not on 2.2.2 which contains this fix. The node-red community has no control or influence on when HA release updates.

In the short term, until HA release an update, I suggest you stick to node deploys (instead of full deploys) to reduce the occurrence of this timeout.

@quadhammer
Copy link

now you can see you are not on 2.2.2 which contains this fix.

Yes, thanks. The latest one is: "Bump node-red from 2.2.0 to 2.2.1 in /node-red" so it shouldn't be too far behind. I'm sticking with 2.2.0 which doesn't seem to have the problem, even with full deploys.

Cheers!

@Mark-Muc
Copy link

Mark-Muc commented Jun 9, 2022

I do have the same problem
Error stopping node: Close timed out
using:

node-red-contrib-tasmota
0.9.12
Tasmota Button
Tasmota Generic
Tasmota Light
Tasmota Sensor
Tasmota Switch
**tasmota-mqtt-broker**

some Tasmotadevices won't be found anymore.
2.2.2: Maintenance Release
Nodes
Fix "close timed out" error when performing full deploy or modifying broker node. (#3451) @Steve-Mcl

looks like this:
image

In Mosquitto the devices are normal visibe

@Steve-Mcl
Copy link
Contributor

@Mark-Muc this is more likely an issue with that node & you should raise it on the tasmota nodes repository.

@Steve-Mcl
Copy link
Contributor

Also, @Mark-Muc to minimise / reduce the problem, use "modified nodes" instead of "full deploy" where possible.

image

@Mark-Muc
Copy link

Mark-Muc commented Jun 9, 2022

@Steve-Mcl
that's what i do normaly . but to geht the devices online i habe to use "Full"
Mark_Muc

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.