I have a problem with the handling of on('close') when node-red is stopped or my node is restarted. My understanding is that node-red should wait for on close to return before closing down (subject to timeouts possibly but this is all happening within fractions of a second). It appears that it I am getting half way through my cleanup and then just being summarily killed off. I have liberally distributed console.log messages about and with adjacent log messages, with no code in between, I can get the situation where it logs the one but not the one immediately following it.
Am I misunderstanding what should happen?
This is node-red 1.1.0 with nodejs 10.21 on Ubuntu.
It depends how Node-RED is being stopped, or if it's being killed.
How are you doing it?
node-red-stop with the standard systemd script. It isn't right using Restart Flows from the Deploy button either, but not quite the same, I am just investigating exactly what happens in that case.
This doesn't make any sense, it seems to be something to do with the logging. With this as on close it seems to be ok (though it isn't doing anything except logging).
node.on('close', function() {
//node.log("Closing " + msgQueue.length)
// kill the current process if any
/*if (currentProcess) {
node.log("killing")
currentProcess.kill()
currentProcess = null
}*/
node.log("Closing")
node.log("stopping watchdog1")
node.log("stopping watchdog2")
node.log("stopping watchdog3")
node.log("stopping watchdog4")
node.log("stopping watchdog5")
node.log("stopping watchdog6")
node.log("stopping watchdog7")
node.log("stopping watchdog8")
node.log("stopping watchdog9")
node.log("stopping watchdoga")
node.log("stopping watchdogb")
node.log("stopping watchdogc")
node.log("stopping watchdogd")
node.log("stopping watchdoge")
node.log("stopping watchdogf")
node.log("stopping watchdogg")
node.log("stopping watchdogh")
node.log("stopping watchdogi")
node.log("really about to stop it")
// stop the timer if active
//stopWatchdog()
node.log("stopped")
// empty the queue
//msgQueue.length = 0 // yes, this is valid javascript
//node.log("Length now " + msgQueue.length)
node.log("returning now")
});
and in the log, when I do a restart flows, I see
4 Jul 15:17:30 - [info] Stopping flows
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] Closing
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdog1
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdog2
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdog3
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdog4
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdog5
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdog6
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdog7
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdog8
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdog9
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdoga
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdogb
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdogc
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdogd
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdoge
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdogf
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdogg
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdogh
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopping watchdogi
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] really about to stop it
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] stopped
4 Jul 15:17:30 - [info] [influxdb backup:44adefc9.17833] returning now
4 Jul 15:17:30 - [info] [mqtt-broker:e3d45312.a3103] Disconnected from broker: mqtt://owl2.local:1883
4 Jul 15:17:30 - [info] Stopped flows
But if I have this in on close (the difference being the repeated text in the logs)
node.on('close', function() {
//node.log("Closing " + msgQueue.length)
// kill the current process if any
/*if (currentProcess) {
node.log("killing")
currentProcess.kill()
currentProcess = null
}*/
node.log("Closing")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("stopping watchdog")
node.log("really about to stop it")
// stop the timer if active
//stopWatchdog()
node.log("stopped")
// empty the queue
//msgQueue.length = 0 // yes, this is valid javascript
//node.log("Length now " + msgQueue.length)
node.log("returning now")
});
then I see
4 Jul 15:23:21 - [info] Stopping flows
4 Jul 15:23:21 - [info] [influxdb backup:44adefc9.17833] Closing
4 Jul 15:23:21 - [info] [influxdb backup:44adefc9.17833] stopping watchdog
4 Jul 15:23:21 - [info] [influxdb backup:44adefc9.17833] stopping watchdog
4 Jul 15:23:21 - [info] [influxdb backup:44adefc9.17833] stopping watchdog
4 Jul 15:23:21 - [info] [influxdb backup:44adefc9.17833] really about to stop it
4 Jul 15:23:21 - [info] [influxdb backup:44adefc9.17833] stopped
4 Jul 15:23:21 - [info] [influxdb backup:44adefc9.17833] returning now
4 Jul 15:23:21 - [info] [mqtt-broker:e3d45312.a3103] Disconnected from broker: mqtt://owl2.local:1883
4 Jul 15:23:21 - [info] Stopped flows
where the number of 'stopping' messages logged is variable.
Now that I have taken all the code out except logging it is getting to the return ok, so there may be two issues, the logging problem confusing things and whatever is preventing it getting to the return when I do have some executable code, which I am having another look at now. It is tricky when I can't trust the logging though.
are you doing any async function calls in the close handler?
No. In the example above there isn't anything except node.log calls. In the real one just straightforward stuff.
Actually, perhaps I am, perhaps node.log() is async, I don't know.
Right, as I suspected there were two things going on. It appears that node.log() will, depending on the phase of the moon or something similar, silently discard duplicated messages, which is what was happening in the example above. I had put the extra messages in to change the timing to see if my original problem was timing related, and all I succeeded in doing was to add further confusion into the mix.
The next thing is that if there is an attempt to call an undefined function from within on close then this fails silently and immediately returns from on close. I can at least partly understand the logic here but it doesn't make debugging easy. Perhaps @dceejay can comment on whether this is expected behaviour.
This was the underlying cause of the problem. The function I was trying to call was out of scope so my on close method terminated early with no error in the log. Now, having corrected the error, I just need to put the real code back in and see if it actually works as it should.
Hi @Colin, what is the result if you try to use the new feature on 1.1.0 that allows you to add code to the Close tab in the node’s edit dialog (instead of using on('close')?
It isn't actually a function node, it is a contrib node that I am developing.
This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.
