node-red-contrib-aedes icon indicating copy to clipboard operation
node-red-contrib-aedes copied to clipboard

Error stopping node: Close timed out

Open hybuild-project opened this issue 3 years ago • 11 comments

Steps to reproduce the error Import the flow in: https://cookbook.nodered.org/mqtt/connect-to-broker, configure Aedes node (localhost:1883) and deploy

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"

Expected behaviour The MQTT in node would immediately close without errors and the flow would be deployed without error and time wasting, as it happens if you use an external MQTT broker (e.g., Mosquitto)

Environment Node-RED version: 1.3.2 Node.js version: 14.6.1

hybuild-project avatar Apr 15 '21 11:04 hybuild-project

Let me check. It might take some time.

martin-doyle avatar Apr 15 '21 19:04 martin-doyle

Thank you for reporting this issue. I can confirm this error for Node-RED since version 1.3. I checked Node-RED 1.2.9 and everything works as expected. Node-RED made some changes to the MQTT nodes and I need to check what the issue is.

martin-doyle avatar Apr 17 '21 06:04 martin-doyle

Additional observation. This behaviour exists only if you do a "Full" deploy or stop Node-RED. It does not occur when deploy Modified Flows or Modified Nodes only.

martin-doyle avatar Apr 17 '21 06:04 martin-doyle

There is a fix for the Node-RED MQTT node in preparation. See Ensure mqtt-close message is published when closing mqtt nodes. I will check the next Node-RED release and see if this issue is fixed.

martin-doyle avatar Apr 17 '21 07:04 martin-doyle

Many thanks, this is really helpful. Congratulations for your excellent work!

hybuild-project avatar Apr 17 '21 12:04 hybuild-project

Unfortunately, Node-RED 1.3.3 does not fix this issue. Looking at the logs it seems that Node-RED closes the broker first and then the MQTT nodes. The MQTT nodes send a disconnect but the broker is already down. No problem with external brokers since they keep running while Node-RED shuts down. I will ask for a solution in the Node-RED project. By the way, this issue is critical for the project since all test fail now.

martin-doyle avatar Apr 20 '21 18:04 martin-doyle

@martin-doyle I've created a workaround for this issue. Can I issue a PR so that you can review the change? I tested with NR v1.3.5. All mocha tests were passed with the workaround.

dbaba avatar Jun 18 '21 05:06 dbaba

Cool. Yes please do. Thanks a lot.

martin-doyle avatar Jun 18 '21 16:06 martin-doyle

@martin-doyle

I have been working on this problem in node-red core and believe I have managed to stabilise the situation somewhat.

However, you might remember Nick saying the order of close events in node-red changed (so that regular nodes are signalled to close before config nodes) in https://github.com/node-red/node-red/issues/2934 ?

Seeing as your aedes broker node does not use the config mechanism, it can be closed before other MQTT nodes meaning sometimes (depending on position of aedes in the flow file) can prevent close message being published..

I have done a lot of testing (aedes 1st in the flow file JSON, middle of the flow file JSON, end of flow file JSON, restarting node-red, full deploy, modify aedes then partial deploy etc etc etc) and believe there is an elegant solution to resolve the close message part of this problem.

If you delay the code inside node.on('close' by wrapping the content in a nextTick it puts your node to the end of the queue (so to speak) ensuring other nodes are closed first.

Code I used in testing...

    this.on('close', function (done) {
      nextTick(function onCloseDelayed() {
        broker.close(function () {
          node.log('Unbinding aedes mqtt server from port: ' + config.mqtt_port);
          server.close(function () {
            node.debug('after server.close(): ');
            if (node.mqtt_ws_path !== '') {
              node.log('Unbinding aedes mqtt server from ws path: ' + node.fullPath);
              delete listenerNodes[node.fullPath];
              node.server.close();
            }
            if (wss) {
              node.log('Unbinding aedes mqtt server from ws port: ' + config.mqtt_ws_port);
              wss.close(function () {
                node.debug('after wss.close(): ');
                httpServer.close(function () {
                  node.debug('after httpServer.close(): ');
                  done();
                });
              });
            } else {
              done();
            }
          });
        });
      })
    });

This greatly improves the situation ensuring the close message is sent etc.

NOTE: this is only part of the puzzle - I will also be publishing a general overall improvement to node-red core soon.

Steve-Mcl avatar Feb 17 '22 09:02 Steve-Mcl

For those following this thread, if you have the opportunity to update to node-red 2.2.2, this problem should now be improved. The other part will require an update to this node as I described in the previous comment above.

Steve-Mcl avatar Feb 18 '22 15:02 Steve-Mcl

Hi Steve, thank you for providing this fix. Unfortunately, it did not work on my computer with Node-RED V2.2.1. But I can confirm that version 2.2.2 works now.

martin-doyle avatar Feb 18 '22 15:02 martin-doyle