A harmless function node deletes all my flows and I have no idea why

[murraybrandon]

Hi folks,

I've been playing around with trying to get a cool bluetooth Divoom pixel display working to show visual and fun animated statuses.

In order to pre-format the data going to the display I am using a third party node library called node-divoom-timebox-evo which seems pretty complete and well thought out. I've added the library in settings.js (see below) as a global context so I can call the various functions in my node red flow to generate a byte stream to send to the pixel display.

functionGlobalContext: {
NODE_DIVOOM_TIMEBOX_EVO:require('node-divoom-timebox-evo')
}

When I add the following flow to my massive node red configuration it becomes extremely sluggish and eventually deletes all of my flows. Not sure if it deletes the flows because of timeouts doing a [deploy] but the result is always a question if you would like to merge your local changes with those on the server because the server now has 0 nodes.

[{"id":"fcbfa773.a5d038","type":"bt serial in","z":"bc8c518c.a3e29","name":"Divoom Timebox Evo Light","btSerial":"dc55d64a.7c0dc8","x":210,"y":3960,"wires":[["d82151a7.bfac5"]]},{"id":"dc755a35.2b83f8","type":"comment","z":"bc8c518c.a3e29","name":"======< Bluetooth Devices >=====================================================","info":"","x":420,"y":3920,"wires":[]},{"id":"d82151a7.bfac5","type":"debug","z":"bc8c518c.a3e29","name":"BLUETOOTH","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","targetType":"full","x":460,"y":3960,"wires":[]},{"id":"cea96bf.4d75998","type":"inject","z":"bc8c518c.a3e29","name":"","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":180,"y":4020,"wires":[["91d9db81.8aeef8"]]},{"id":"91d9db81.8aeef8","type":"bt serial out","z":"bc8c518c.a3e29","name":"Divoom Timebox Evo Light","btSerial":"dc55d64a.7c0dc8","x":1060,"y":4020,"wires":[]},{"id":"1ef64c61.034c24","type":"function","z":"bc8c518c.a3e29","name":"Build Divoom binary stream","func":"var Divoom = global.get('NODE_DIVOOM_TIMEBOX_EVO');\n\nvar d = (new Divoom.TimeboxEvo()).createRequest('text', {text: \"Hi friends!\"});\nd.paletteFn = d.PALETTE_BLACK_ON_CMY_RAINBOW; // Baked in color palette, but you can define your own\nd.animFn = d.ANIM_HORIZONTAL_GRADIANT_BACKGROUND; // Baked in animation, but you can define your own\n\n// This contains what is required to bootstrap the display on the Timebox\nconsole.log(d.messages.asBinaryBuffer());\nmsg.payload = d.messages.asBinaryBuffer();\n\nreturn msg;\n","outputs":1,"noerr":0,"x":400,"y":4120,"wires":[["59438f38.0ea8"]]},{"id":"2be3d91.a56f326","type":"inject","z":"bc8c518c.a3e29","name":"","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":180,"y":4120,"wires":[["1ef64c61.034c24"]]},{"id":"59438f38.0ea8","type":"splitter","z":"bc8c518c.a3e29","name":"","property":"payload","x":610,"y":4120,"wires":[["5cccabcc.ad2964"]]},{"id":"5cccabcc.ad2964","type":"delay","z":"bc8c518c.a3e29","name":"","pauseType":"rate","timeout":"5","timeoutUnits":"seconds","rate":"30","nbRateUnits":"1","rateUnits":"second","randomFirst":"1","randomLast":"5","randomUnits":"seconds","drop":false,"x":780,"y":4120,"wires":[["91d9db81.8aeef8"]]},{"id":"dc55d64a.7c0dc8","type":"bt-serial-port","z":"","name":"Divoom Timebox Evo Light","btAddress":"11:75:58:48:A8:41","serialReconnectTime":"10"}]

To answer the obvious questions, If I use the bluetooth flows on their own (without the function that calls node-divoom-timebox-evo then everything is stable). A raspbian command line top command shows no more than 20% CPU being used by Node. There's no exceptions or errors relating to the node-divoom-timebox-evo library reported in the system logs or in the debug.

My question is, what's happening here? I can only assume the library is doing something completely incompatible to the way Node Red is architected. If so, is there any internals of Node Red I can look at to debug or identify issues such as this? I only found the root cause because it was the single flow I have added recently. It because I use a split without a subsequent join? The binary buffers are being generated in the form I would expect according to my logs, so the Divoom library is being called successfully.

As you can see below, the function doesn't do anything special:

var Divoom = global.get('NODE_DIVOOM_TIMEBOX_EVO');

var d = (new Divoom.TimeboxEvo()).createRequest('text', {text: "Hi friends!"});
d.paletteFn = d.PALETTE_BLACK_ON_CMY_RAINBOW; // Baked in color palette, but you can define your own
d.animFn = d.ANIM_HORIZONTAL_GRADIANT_BACKGROUND; // Baked in animation, but you can define your own

// This contains what is required to bootstrap the display on the Timebox
console.log(d.messages.asBinaryBuffer());
msg.payload = d.messages.asBinaryBuffer();

return msg;

My query is not for people to look into the source code of node-divoom-timebox-evo (although I won't stop you if you would like to, because it looks promising!) because I can live without a programmable pixel display. My query is really about finding root cause of these kind of serious issues through instrumentation in Node JS or Node Red somehow, and plugging the gap in my understanding of things to be careful of when using functions.

[Steve-Mcl]

@murraybrandon

When I add the following flow to my massive node red configuration it becomes extremely sluggish and eventually deletes all of my flows

When you say deletes - is the actual flow_xxx.json file deleted or is it just an in memory issue?

[knolleary]

Also, what does the Node-RED log show? Is it restarting at all?

[murraybrandon]

Thanks for your suggestions folks, I had some spare time over the weekend to switch off various parts to look for the cause. Turns out it isn't the inclusion of the harmless function node, but appears to be the code in node-red-contrib-bluetooth-serial-port sometimes preventing the new flows from being installed (waiting for proper shutdown of a bluetooth connection perhaps?). The reason I suspect this is usually when I deploy my flows I hear an audible disconnection tone from my bluetooth device. But when the flows are not going to be deployed properly (or deleted!) there is no audible disconnection tone and the Node Red flow editing dashboard times out with the deploy, leaving nodes still marked as not deployed. At the backend you can clearly see the deploy request coming in.

This is the bluetooth node:

node-red-contrib-bluetooth-serial-port

[{"id":"648570f8.fe2c6","type":"debug","z":"bc8c518c.a3e29","name":"DIVOOM PAYLOAD","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"payload","targetType":"msg","x":920,"y":4060,"wires":[]},{"id":"d10dbf12.1a2fd","type":"bt serial in","z":"bc8c518c.a3e29","name":"DIVOOM","btSerial":"7360ab36.341fc4","x":200,"y":4060,"wires":[["648570f8.fe2c6"]]},{"id":"535d71b3.c820d","type":"bt serial out","z":"bc8c518c.a3e29","name":"DIVOOM","btSerial":"7360ab36.341fc4","x":860,"y":4160,"wires":[]},{"id":"cc9b0834.9f1f48","type":"function","z":"bc8c518c.a3e29","name":"Divoom Brightness 5","func":"//msg.payload = toHex(msg.payload)\n//msg.payload = \"4503 04\"\n\n// 0x74 is set brightness (116)\nvar text = \"04007405\"\nvar crc = getCRC(text);\n\nmsg.payload = Buffer.from([0x01, 0x04, 0x00, 0x74, 0x05, 0x7d, 0x00, 0x02]);\n\nreturn msg;\n\n// Format of all Divoom messages is like this:\n//\n// 01 LLLL PAYLOAD CRCR 02\n//\n// All the messages will start with 01 and end with 02\n// LLLL is the length of the PAYLOAD string + the length of the CRC (4) in number of bytes (FF is one byte for example) in LSB First\n// CRCR is the CRC of the message including the length (LLLL PAYLOAD) in LSB First\n//\n// Split the message every 1332 characters and send that as a binary buffer too\n\n// 4503 TT (e.g. 4503 04) for setting theme\n\nfunction toHex(d) {\n    return  (\"0\"+(Number(d).toString(16))).slice(-2).toUpperCase()\n}\n\nfunction int2hexlittle(value) {\n    const byte1 = (value & 0xFF).toString(16).padStart(2, \"0\");\n    const byte2 = ((value >> 8) & 0xFF).toString(16).padStart(2, \"0\");\n    return `${byte1}${byte2}`;\n}\n\nfunction getLength (payload) {\n  // CRC is 4 characters\n  // We divide by 2 because 1 byte is 2 Hex char\n  const lenght = (payload.length + 4) / 2;\n  return int2hexlittle(length);\n}\n\nfunction getCRC(str) {\n  let sum = 0;\n  for (i = 0, l = str.length; i < l; i += 2) {\n    sum += parseInt(str.substr(i, 2), 16)\n  }\n  return int2hexlittle(sum);\n}\n\nfunction map(x, in_min, in_max, out_min, out_max) {\n  return (x - in_min) * (out_max - out_min) / (in_max - in_min) + out_min;\n}\n","outputs":1,"noerr":0,"x":420,"y":4120,"wires":[["535d71b3.c820d"]]},{"id":"e6de22af.ae584","type":"inject","z":"bc8c518c.a3e29","name":"","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":220,"y":4120,"wires":[["cc9b0834.9f1f48"]]},{"id":"f753c258.821e4","type":"function","z":"bc8c518c.a3e29","name":"Divoom Brightness 99","func":"//msg.payload = toHex(msg.payload)\n//msg.payload = \"4503 04\"\n\n// 0x74 is set brightness (116)\nvar text = \"04007463\"\nvar crc = getCRC(text);\n\nmsg.payload = Buffer.from([0x01, 0x04, 0x00, 0x74, 0x63, 0xDB, 0x00, 0x02]);\n\nreturn msg;\n\n// Format of all Divoom messages is like this:\n//\n// 01 LLLL PAYLOAD CRCR 02\n//\n// All the messages will start with 01 and end with 02\n// LLLL is the length of the PAYLOAD string + the length of the CRC (4) in number of bytes (FF is one byte for example) in LSB First\n// CRCR is the CRC of the message including the length (LLLL PAYLOAD) in LSB First\n//\n// Split the message every 1332 characters and send that as a binary buffer too\n\n// 4503 TT (e.g. 4503 04) for setting theme\n\nfunction toHex(d) {\n    return  (\"0\"+(Number(d).toString(16))).slice(-2).toUpperCase()\n}\n\nfunction int2hexlittle(value) {\n    const byte1 = (value & 0xFF).toString(16).padStart(2, \"0\");\n    const byte2 = ((value >> 8) & 0xFF).toString(16).padStart(2, \"0\");\n    return `${byte1}${byte2}`;\n}\n\nfunction getLength (payload) {\n  // CRC is 4 characters\n  // We divide by 2 because 1 byte is 2 Hex char\n  const lenght = (payload.length + 4) / 2;\n  return int2hexlittle(length);\n}\n\nfunction getCRC(str) {\n  let sum = 0;\n  for (i = 0, l = str.length; i < l; i += 2) {\n    sum += parseInt(str.substr(i, 2), 16)\n  }\n  return int2hexlittle(sum);\n}\n\nfunction map(x, in_min, in_max, out_min, out_max) {\n  return (x - in_min) * (out_max - out_min) / (in_max - in_min) + out_min;\n}\n","outputs":1,"noerr":0,"x":420,"y":4160,"wires":[["535d71b3.c820d"]]},{"id":"2c93c0fb.22aa8","type":"inject","z":"bc8c518c.a3e29","name":"","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":220,"y":4160,"wires":[["f753c258.821e4"]]},{"id":"7360ab36.341fc4","type":"bt-serial-port","z":"","name":"Divoom","btAddress":"11:75:58:48:A8:41","serialReconnectTime":"10"}]

Here are the logs showing the request coming in:

Sep  7 10:07:47 raspberrypi Node-RED[339]: 7 Sep 10:07:47 - [audit] {"event":"flows.set","type":"full","level":98,"user":{"username":"xxx","permissions":"*"},"path":"/flows","ip":"192.168.1.218","timestamp":1630973267623}
Sep  7 10:07:48 raspberrypi Node-RED[339]: 7 Sep 10:07:48 - [info] Stopping flows
Sep  7 10:07:48 raspberrypi Node-RED[339]: 7 Sep 10:07:48 - [info] BTSerial - Closed
Sep  7 10:07:48 raspberrypi Node-RED[339]: 7 Sep 10:07:48 - [info] BTSerial - Closed
Sep  7 10:07:48 raspberrypi Node-RED[339]: 7 Sep 10:07:48 - [info] Stopped flows
Sep  7 10:07:48 raspberrypi Node-RED[339]: 7 Sep 10:07:48 - [info] Starting flows
Sep  7 10:07:49 raspberrypi Node-RED[339]: 7 Sep 10:07:49 - [info] Started flows
Sep  7 10:07:53 raspberrypi Node-RED[339]: 7 Sep 10:07:53 - [info] [pushover api:Pushover Notify HTTPS Restarted] pushover POST succeeded:
Sep  7 10:07:53 raspberrypi Node-RED[339]: "{\"status\":1,\"request\":\"aa665c95-9938-427c-81ab-e36f4b5a858f\"}"
Sep  7 10:08:00 raspberrypi Node-RED[339]: 7 Sep 10:08:00 - [info] BTSerial - Open
Sep  7 10:08:02 raspberrypi bluetoothd[527]: 11:75:58:48:A8:41: error updating services: Connection refused (111)
Sep  7 10:09:10 raspberrypi Node-RED[339]: 7 Sep 10:09:10 - [audit] {"event":"flows.set","type":"full","level":98,"user":{"username":"xxx","permissions":"*"},"path":"/flows","ip":"192.168.1.218","timestamp":1630973350815}
Sep  7 10:09:13 raspberrypi Node-RED[339]: 7 Sep 10:09:13 - [error] BTSerial - Didn't find a Serial Port on 'DF:C9:7C:88:8B:46'
Sep  7 10:09:13 raspberrypi Node-RED[339]: 7 Sep 10:09:13 - [info] Stopping flows
Sep  7 10:09:13 raspberrypi Node-RED[339]: 7 Sep 10:09:13 - [info] BTSerial - Closed
Sep  7 10:09:13 raspberrypi Node-RED[339]: 7 Sep 10:09:13 - [info] BTSerial - Closed
Sep  7 10:09:13 raspberrypi Node-RED[339]: 7 Sep 10:09:13 - [info] Stopped flows
Sep  7 10:09:13 raspberrypi Node-RED[339]: 7 Sep 10:09:13 - [info] Starting flows
Sep  7 10:09:14 raspberrypi Node-RED[339]: 7 Sep 10:09:14 - [info] Started flows
Sep  7 10:09:25 raspberrypi Node-RED[339]: 7 Sep 10:09:25 - [info] BTSerial - Open
Sep  7 10:09:25 raspberrypi Node-RED[339]: 7 Sep 10:09:25 - [info] [pushover api:Pushover Notify HTTPS Restarted] pushover POST succeeded:
Sep  7 10:09:25 raspberrypi Node-RED[339]: "{\"status\":1,\"request\":\"e6da88ce-4883-4d5a-8cc3-9715d6d7dc31\"}"
Sep  7 10:09:26 raspberrypi bluetoothd[527]: 11:75:58:48:A8:41: error updating services: Connection refused (111)
Sep  7 10:10:17 raspberrypi Node-RED[339]: 7 Sep 10:10:17 - [audit] {"event":"flows.set","type":"full","level":98,"user":{"username":"xxx","permissions":"*"},"path":"/flows","ip":"192.168.1.218","timestamp":1630973417579}
Sep  7 10:10:59 raspberrypi systemd[1]: Created slice User Slice of UID 1000.
Sep  7 10:10:59 raspberrypi systemd[1]: Starting User Runtime Directory /run/user/1000...
Sep  7 10:10:59 raspberrypi systemd[1]: Started User Runtime Directory /run/user/1000.
Sep  7 10:10:59 raspberrypi systemd[1]: Starting User Manager for UID 1000...
Sep  7 10:10:59 raspberrypi systemd[10239]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Sep  7 10:10:59 raspberrypi systemd[10239]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Sep  7 10:10:59 raspberrypi systemd[10239]: Listening on GnuPG network certificate management daemon.
Sep  7 10:10:59 raspberrypi systemd[10239]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Sep  7 10:10:59 raspberrypi systemd[10239]: Listening on GnuPG cryptographic agent and passphrase cache.
Sep  7 10:10:59 raspberrypi systemd[10239]: Reached target Paths.
Sep  7 10:10:59 raspberrypi systemd[10239]: Reached target Sockets.
Sep  7 10:10:59 raspberrypi systemd[10239]: Reached target Timers.
Sep  7 10:10:59 raspberrypi systemd[10239]: Reached target Basic System.
Sep  7 10:10:59 raspberrypi systemd[10239]: Reached target Default.
Sep  7 10:10:59 raspberrypi systemd[10239]: Startup finished in 140ms.
Sep  7 10:10:59 raspberrypi systemd[1]: Started User Manager for UID 1000.
Sep  7 10:10:59 raspberrypi systemd[1]: Started Session c2 of user pi.

At this point no matter how many deploys you do to Node Red no more succeed.
If you reboot with a power cycle, all your nodes are deleted. e.g.

This is what a "good" deploy log looks like:

Sep  7 10:40:02 raspberrypi systemd[1]: Started Session c1 of user pi.
Sep  7 10:40:29 raspberrypi Node-RED[313]: 7 Sep 10:40:29 - [audit] {"event":"flows.set","type":"full","level":98,"user":{"username":"xxx","permissions":"*"},"path":"/flows","ip":"192.168.1.218","timestamp":1630975229085}
Sep  7 10:40:29 raspberrypi Node-RED[313]: 7 Sep 10:40:29 - [info] Stopping flows
Sep  7 10:40:30 raspberrypi Node-RED[313]: 7 Sep 10:40:30 - [info] BTSerial - Closed
Sep  7 10:40:30 raspberrypi Node-RED[313]: 7 Sep 10:40:30 - [info] BTSerial - Closed
Sep  7 10:40:30 raspberrypi Node-RED[313]: 7 Sep 10:40:30 - [info] Stopped flows
Sep  7 10:40:30 raspberrypi Node-RED[313]: 7 Sep 10:40:30 - [info] Starting flows
Sep  7 10:40:31 raspberrypi Node-RED[313]: 7 Sep 10:40:31 - [info] Started flows
Sep  7 10:40:32 raspberrypi Node-RED[313]: 7 Sep 10:40:32 - [info] [pushover api:Pushover Notify HTTPS Restarted] pushover POST succeeded:
Sep  7 10:40:32 raspberrypi Node-RED[313]: "{\"status\":1,\"request\":\"04a68c03-22fe-4ddc-a2ec-00f8aaa18aac\"}"

So I suspect there is some kind of thread locking issue in the Bluetooth code preventing a reinstall of the new flows. I'll hunt around for a different Bluetooth node however my question is more around debugging.

How can I look at Node internals to see where threading problems might be?
Is there an equivalent of a stack dump?
Sorry for delays in replying. Due to work commitments I really only have time to look at it on weekends.

Thanks,
Murray

[murraybrandon]

So when the problem happens, it never gets to the Stopping flows log event below. The old flows are still running away merrily because I can still see current messages flowing in the Node Red debug tab.
But on SD card, the flows are deleted

Sep  7 11:25:51 raspberrypi Node-RED[329]: 7 Sep 11:25:51 - [audit] {"event":"flows.set","type":"full","level":98,"user":{"username":"xxx","permissions":"*"},"path":"/flows","ip":"192.168.1.218","timestamp":1630977951238}
Sep  7 11:25:05 raspberrypi Node-RED[329]: 7 Sep 11:25:05 - [info] Stopping flows
Sep  7 11:25:05 raspberrypi Node-RED[329]: 7 Sep 11:25:05 - [info] BTSerial - Closed
Sep  7 11:25:05 raspberrypi Node-RED[329]: 7 Sep 11:25:05 - [info] Stopped flows
Sep  7 11:25:05 raspberrypi Node-RED[329]: 7 Sep 11:25:05 - [info] Starting flows
Sep  7 11:25:06 raspberrypi Node-RED[329]: 7 Sep 11:25:06 - [info] Started flows