[Bug]: Serial port becomes unusable until node-red restart w/ newer versions

svdasein commented 9 months ago

What happened?

A few days ago I updated nodejs and node-red on a raspi4. Prior to the upgrade all was well. Subsequent to the upgrade I'm seeing an issue that I believe I've narrowed down to serial port logic in node-red-contrib-zwave-js:

If I leave the zwave js controller node enabled when I do a "deploy" or "restart nodes", that port will subsequently become unavailable due to some problem with port locking. The controller node emits messages about being unable to lock the usb port.

ZWaveError: Failed to open the serial port: Error Resource temporarily unavailable Cannot lock port (ZW0100)

The only way I have found to recover from this is to restart node-red itself. Once I do that, the controller node works properly again.

I have managed to work around this by being sure to disable + deploy the disable before doing other work. If I do that I can reliably bring the controller back up by enabling the controller node + deploy.

I looked at a LOT of stuff tracking this down, so I'm pretty sure it's somewhere in your stuff. Briefly:

I ensured that nothing else is competing for access to the port (using lsof etc)
I upgraded raspian to the latest - everything at the os level is up to date
I upgraded all node modules in node-red and did an npm rebuild. same for node red itself.
At one point I was seeing an identical looking problem with the the serial port thing that comes with node-red (I think it does anyway). I installed several versions of node-red-node-serialport and found that the problem was gone after I installed 2.0.2. When I say "identical" I mean "I got a message about failing to lock a port that was only correctable by restarting node-red" which went away after the nod-red-node-serialport upgrade
Looking at your stuff - it looks like you're bundling your own serial logic
I get a sense (I'm not a nodejs coder - I just plink around a bit) that there was some kind of breaking change that might be related directly or indirectly to what's going on with your serial logic. I got rather deep into that such that at one point I was looking at some stuff about what looked like a google contribution to nodejs, but I can't seem to find it in my browser history - my apologies. It was C++ stuff and they were talking about deprecating something for a couple of versions - and it looks like by nodejs 20 they had removed it.

I'm just guessing, but it seems like the issue might be sort of in one of these ballparks:

A lock that used to get released on deploy no longer gets released
A lock that is presumed to have been let go no longer needs to be treated as such

Versions:

PRETTY_NAME="Raspbian GNU/Linux 11 (bullseye)"
NAME="Raspbian GNU/Linux"
VERSION_ID="11"
VERSION="11 (bullseye)"

Linux nodered 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr  3 17:24:16 BST 2023 aarch64 GNU/Linux

root@nodered:/usr/lib/node_modules# node --version
v20.5.1
root@nodered:/usr/lib/node_modules# npm ls
/usr/lib
├── corepack@0.19.0 extraneous
├── node-red@3.1.3 extraneous
└── npm@9.8.0 extraneous

nodered@nodered:~/.node-red $ npm ls
node-red-project@0.0.1 /home/nodered/.node-red
├── @flowforge/node-red-dashboard@0.6.1
├── @meowwolf/node-red-contrib-amqp@2.4.2
├── @node-red-contrib-themes/theme-collection@3.0.6
├── @studiobox/node-red-contrib-ui-widget-thermometer@0.7.7
├── lodash@4.17.21
├── node-red-contrib-bool-gate@1.0.2
├── node-red-contrib-boolean-logic-ultimate@1.1.1
├── node-red-contrib-buffer-parser@3.2.2
├── node-red-contrib-cache@2.0.3
├── node-red-contrib-calc@1.0.6
├── node-red-contrib-chroma@0.0.3
├── node-red-contrib-colorspace@1.0.3
├── node-red-contrib-combine@1.8.1
├── node-red-contrib-cron-plus@2.1.0
├── node-red-contrib-cron@0.0.4
├── node-red-contrib-cubic-range@1.0.0
├── node-red-contrib-dir2files@0.3.0
├── node-red-contrib-excursion@0.1.7
├── node-red-contrib-eztimer@1.2.7
├── node-red-contrib-filter@0.1.4
├── node-red-contrib-hysteresis@0.3.0
├── node-red-contrib-latching-router@1.0.3
├── node-red-contrib-logger@0.0.8
├── node-red-contrib-map@1.0.4
├── node-red-contrib-play-audio@2.5.0
├── node-red-contrib-presence-faker@1.8.8
├── node-red-contrib-rate-avg@0.0.3
├── node-red-contrib-redis@1.3.9
├── node-red-contrib-splitter@0.0.16
├── node-red-contrib-state-machine@1.2.0
├── node-red-contrib-string@1.0.0
├── node-red-contrib-throttle@0.1.7
├── node-red-contrib-ui-actions@0.1.8
├── node-red-contrib-ui-areyousure@0.1.0
├── node-red-contrib-ui-artless-gauge@0.3.12
├── node-red-contrib-ui-button_state@0.2.2
├── node-red-contrib-ui-contextmenu@2.0.1
├── node-red-contrib-ui-countdown-timer-switch@1.4.1
├── node-red-contrib-ui-digital-clock@1.0.0
├── node-red-contrib-ui-digital-display@1.0.3
├── node-red-contrib-ui-iro-color-picker@0.1.6
├── node-red-contrib-ui-led@0.4.11
├── node-red-contrib-ui-level@0.1.46
├── node-red-contrib-ui-media@1.2.0
├── node-red-contrib-ui-multistate-switch@1.2.3
├── node-red-contrib-ui-simple-level@1.0.0
├── node-red-contrib-ui-state-trail@1.0.2
├── node-red-contrib-ui-statechart@0.2.0
├── node-red-contrib-ui-svg@2.3.3
├── node-red-contrib-ui-time-scheduler@1.17.2
├── node-red-contrib-ui-timelines-chart@0.1.9
├── node-red-contrib-uuid@0.0.4
├── node-red-contrib-visualmapper@0.5.0
├── node-red-contrib-web-worldmap@4.5.2
├── node-red-contrib-zabbix-sender@1.0.0
├── node-red-contrib-zabbix@1.0.2
├── node-red-contrib-zwave-js@9.0.3
├── node-red-dashboard@3.6.2
├── node-red-node-mysql@2.0.0
├── node-red-node-pi-gpio@2.0.6
├── node-red-node-ping@0.3.3
├── node-red-node-random@0.4.1
├── node-red-node-serialport@2.0.2
├── node-red-node-smooth@0.1.2
├── node-red-node-ui-iframe@0.2.1
├── node-red-node-ui-lineargauge@0.3.7
├── node-red-node-ui-list@0.3.6
├── node-red-node-ui-table@0.4.3
└── openapi-red@1.2.5

How to reproduce?

Upgrade to latest raspian
Upgrade node-red to latest
Upgrade all node modules to latest
Modify a flow and deploy it

Version

9.0.3

Node-RED Version

3.1.3

What hardware are you seeing the problem on?

Raspberry Pi

Relevant Z-Wave-JS log as a text file

ZWaveError: Failed to open the serial port: Error Resource temporarily unavailable Cannot lock port (ZW0100)

marcus-j-davies commented 9 months ago

@svdasein

Looking at your stuff - it looks like you're bundling your own serial logic

This package doesn't do anything with the serial port - other then list what's available on the system- it's all managed by the zwave-js library, that this module uses, and zwave-js is using the popular serialnode package for all serial interaction.

ZWaveError: Failed to open the serial port: Error Resource temporarily unavailable Cannot lock port (ZW0100)

Log file please to capture all events leading up to and including this event - you can enable logging in the Controller Node (set to File, Debug) - the log will be in ~/.node-red

Please don't edit the log file - just upload the file as is.

whilst I wait for the log file, I'll ping @AlCalzone, to see if he has any immediate input with any known issues with Node 20 and the serilaport package - But he is on parental leave currently - so please allow some time

This module will bring down the driver (and in doing so, will release the serial port - see below) - so my guess is, this is an issue with serilaport and node 20 - its already been reported by another user -> https://github.com/serialport/node-serialport/issues/2735

https://github.com/zwave-js/node-red-contrib-zwave-js/blob/716eeb7347521dd2e4ba28077228a7843680bc26/zwave-js/zwave-js.js#L604

svdasein commented 9 months ago

zwave-js.log

AlCalzone commented 9 months ago

No known issues from my side, but the linked issue seems to be a reasonable explanation for the behavior. Does the node-red serialport plug in also use this library?

marcus-j-davies commented 9 months ago

it does

marcus-j-davies commented 9 months ago

Everything is being closed down according to log.

2023-12-10T20:32:19.536Z DRIVER   all queues idle
2023-12-10T20:32:26.757Z NDERED   [SHUTDOWN] [RESTART] Cleaning up...
2023-12-10T20:32:26.759Z DRIVER   destroying driver instance...
2023-12-10T20:32:26.901Z DRIVER   driver instance destroyed

2023-12-10T20:32:27.671Z NDERED   [options] [interview.queryAllUserCodes] Disabled
2023-12-10T20:32:27.672Z NDERED   [options] [disableOptimisticValueUpdate] Disabled
2023-12-10T20:32:27.672Z NDERED   [options] [enableSoftReset] Disabled
2023-12-10T20:32:27.672Z NDERED   [options] [storage.cacheDir] /home/nodered/.node-red/zwave-js-cache
2023-12-10T20:32:27.672Z NDERED   [options] [storage.throttle] normal
2023-12-10T20:32:27.672Z NDERED   [options] [preferences.scales.temperature] 0x00
2023-12-10T20:32:27.673Z NDERED   [options] [preferences.scales.humidity] 0x00
2023-12-10T20:32:27.673Z NDERED   [FWUS] Open source license applied
2023-12-10T20:32:27.673Z NDERED   Initializing driver...
2023-12-10T20:32:27.678Z NDERED   [TELEMETRY] Disabling...
2023-12-10T20:32:27.678Z NDERED   Starting driver...
2023-12-10T20:32:27.679Z DRIVER   ███████╗        ██╗    ██╗  █████╗  ██╗   ██╗ ███████╗          ██╗ ███████╗
                                  ╚══███╔╝        ██║    ██║ ██╔══██╗ ██║   ██║ ██╔════╝          ██║ ██╔════╝
                                    ███╔╝  █████╗ ██║ █╗ ██║ ███████║ ██║   ██║ █████╗            ██║ ███████╗
                                   ███╔╝   ╚════╝ ██║███╗██║ ██╔══██║ ╚██╗ ██╔╝ ██╔══╝       ██   ██║ ╚════██║
                                  ███████╗        ╚███╔███╔╝ ██║  ██║  ╚████╔╝  ███████╗     ╚█████╔╝ ███████║
                                  ╚══════╝         ╚══╝╚══╝  ╚═╝  ╚═╝   ╚═══╝   ╚══════╝      ╚════╝  ╚══════╝
2023-12-10T20:32:27.679Z DRIVER   version 12.4.0
2023-12-10T20:32:27.679Z DRIVER   
2023-12-10T20:32:27.679Z DRIVER   starting driver...
2023-12-10T20:32:27.679Z DRIVER   opening serial port /dev/serial/by-id/usb-Silicon_Labs_CP2102N_USB_to_UART_Bri
                                  dge_Controller_a42420fe1da4eb118cc928259da30875-if00-port0
2023-12-10T20:32:37.031Z DRIVER   Failed to open the serial port: Error Resource temporarily unavailable Cannot 
                                  lock port
2023-12-10T20:32:37.033Z DRIVER   destroying driver instance...
2023-12-10T20:32:37.034Z NDERED   [ERROR] [DRIVER] Failed to open the serial port: Error Resource temporarily un
                                  available Cannot lock port (ZW0100)
2023-12-10T20:32:37.037Z DRIVER   driver instance destroyed

svdasein commented 9 months ago

It may be the case that whatever is wrong is something that was fixed by whoever maintains node-red-node-serialport - as I mentioned, when I upgraded that the problem with port locks that use that node went away.

├── node-red-node-serialport@2.0.2

fyi I actually walked the version of node-red-node-serialport upwards 'til the problem went away. I believe 2.0.2 is the very latest version.

marcus-j-davies commented 9 months ago

@svdasein

My suggestion is to downgrade to Node 18 for the time being (its still preferred for Node RED at this stage) Or if you don't want to do that - Just only publish modified nodes - instead of a full deploy, to stop everything re-starting

Nothing in this module will be responsible for the error, as I believe it to be upstream somewhere.

svdasein commented 9 months ago

@marcus-j-davies - thanks - I will try that.

svdasein commented 9 months ago

After a downgrade to node v18.17.1 the problem no longer occurs. Thanks for your help!

zwave-js / node-red-contrib-zwave-js