Failed while querying Serial API capabilities

[jamiepenney]

Describe the issue you are experiencing

After updating to 0.1.91, my ZWave controller is no longer responding. The problem persists even if I downgrade. Based on the timestamps of the backup taken before the update, it definitely died just after the upgrade to 0.1.91.
Updating to 0.1.92 did not help, nor did downgrading back to 0.1.89. edit Updating to 0.1.93 did not help either.

My ZWave controller is an Aotec Stick Gen5 and has been running fine for the last 3 years. Nothing else has changed in my setup aside from updating the ZWave JS add-on.

After looking at the supervisor logs, I can see a lot of "add hardware" events coming directly after the ZWave JS add on tries to re-launch.

Was there any firmware updates included in the ZWave JS update? It is possible that it has bricked my Aotec stick?

What type of installation are you running?

Home Assistant OS

Which operating system are you running on?

Other (e.g., Raspbian/Raspberry Pi OS/Fedora)

Which add-on are you reporting an issue with?

Z-Wave JS

What is the version of the add-on?

0.1.93

Steps to reproduce the issue

...

System Health information

System Information

version	core-2023.9.3
installation_type	Home Assistant OS
dev	false
hassio	true
docker	true
user	root
virtualenv	false
python_version	3.11.5
os_name	Linux
os_version	6.1.21-v8
arch	aarch64
timezone	Pacific/Auckland
config_dir	/config

Home Assistant Cloud

logged_in	false
can_reach_cert_server	ok
can_reach_cloud_auth	ok
can_reach_cloud	ok

Home Assistant Supervisor

host_os	Home Assistant OS 10.5
update_channel	stable
supervisor_version	supervisor-2023.09.2
agent_version	1.5.1
docker_version	23.0.6
disk_total	219.4 GB
disk_used	6.8 GB
healthy	true
supported	true
board	rpi4-64
supervisor_api	ok
version_api	ok
installed_addons	Mosquitto broker (6.3.1), Let's Encrypt (4.12.9), File editor (5.6.0), NGINX Home Assistant SSL proxy (3.5.0), Z-Wave JS (0.1.92), Tailscale (0.11.1), MQTT IO (0.2.1), OneDrive Backup (2.1.2)

Dashboards

dashboards	2
resources	0
views	3
mode	storage

Recorder

oldest_recorder_run	September 17, 2023 at 7:36 AM
current_recorder_run	September 27, 2023 at 5:17 PM
estimated_db_size	235.01 MiB
database_engine	sqlite
database_version	3.41.2

Anything in the Supervisor logs that might be useful for us?

9-27 20:43:33 INFO (MainThread) [supervisor.hardware.monitor] Detecting add hardware /dev/ttyACM0 - /dev/serial/by-id/usb-0658_0200-if00
23-09-27 20:44:27 INFO (SyncWorker_5) [supervisor.docker.manager] Cleaning addon_core_zwave_js application
23-09-27 20:44:29 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on homeassistant/aarch64-addon-zwave_js with version 0.1.92
23-09-27 20:44:33 INFO (MainThread) [supervisor.api.middleware.security] /host/info access from core_zwave_js
23-09-27 20:44:51 INFO (MainThread) [supervisor.hardware.monitor] Detecting remove hardware /dev/ttyACM0 - /dev/serial/by-id/usb-0658_0200-if00
23-09-27 20:44:51 INFO (MainThread) [supervisor.hardware.monitor] Detecting remove hardware /dev/bus/usb/001/009 - None
23-09-27 20:44:53 INFO (MainThread) [supervisor.hardware.monitor] Detecting add hardware /dev/bus/usb/001/010 - None
23-09-27 20:44:53 INFO (MainThread) [supervisor.hardware.monitor] Detecting add hardware /dev/ttyACM0 - /dev/serial/by-id/usb-0658_0200-if00
23-09-27 20:44:58 INFO (MainThread) [supervisor.api.middleware.security] /backups access from de91e161_hassio_onedrive_backup
23-09-27 20:44:58 INFO (MainThread) [supervisor.api.middleware.security] /backups access from de91e161_hassio_onedrive_backup
23-09-27 20:44:59 INFO (MainThread) [supervisor.api.middleware.security] /backups access from de91e161_hassio_onedrive_backup
23-09-27 20:45:48 INFO (SyncWorker_2) [supervisor.docker.manager] Cleaning addon_core_zwave_js application
23-09-27 20:45:49 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on homeassistant/aarch64-addon-zwave_js with version 0.1.92
23-09-27 20:45:53 INFO (MainThread) [supervisor.api.middleware.security] /host/info access from core_zwave_js
23-09-27 20:47:08 INFO (SyncWorker_2) [supervisor.docker.manager] Cleaning addon_core_zwave_js application
23-09-27 20:47:09 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on homeassistant/aarch64-addon-zwave_js with version 0.1.92
23-09-27 20:47:14 INFO (MainThread) [supervisor.api.middleware.security] /host/info access from core_zwave_js
23-09-27 20:47:32 INFO (MainThread) [supervisor.hardware.monitor] Detecting remove hardware /dev/ttyACM0 - /dev/serial/by-id/usb-0658_0200-if00
23-09-27 20:47:32 INFO (MainThread) [supervisor.hardware.monitor] Detecting remove hardware /dev/bus/usb/001/010 - None
23-09-27 20:47:34 INFO (MainThread) [supervisor.hardware.monitor] Detecting add hardware /dev/bus/usb/001/011 - None
23-09-27 20:47:34 INFO (MainThread) [supervisor.hardware.monitor] Detecting add hardware /dev/ttyACM0 - /dev/serial/by-id/usb-0658_0200-if00
23-09-27 20:48:28 INFO (SyncWorker_6) [supervisor.docker.manager] Cleaning addon_core_zwave_js application
23-09-27 20:48:29 INFO (MainThread) [supervisor.docker.addon] Starting Docker add-on homeassistant/aarch64-addon-zwave_js with version 0.1.92

Anything in the add-on logs that might be useful for us?

s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
cont-init: info: running /etc/cont-init.d/config.sh
[17:26:27] INFO: No 'network_key' detected, setting it to 's0_legacy_key' for backwards compatibility
[17:26:29] INFO: Flushing config to disk due to creation of new key(s)...
[17:26:31] INFO: Virtual Machine not detected, enabling soft-reset
cont-init: info: /etc/cont-init.d/config.sh exited 0
cont-init: info: running /etc/cont-init.d/structure.sh
cont-init: info: /etc/cont-init.d/structure.sh exited 0
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service legacy-services: starting
services-up: info: copying legacy longrun zwave_js (no readiness notification)
s6-rc: info: service legacy-services successfully started
[17:26:33] INFO: Successfully send discovery information to Home Assistant.
2023-09-27T04:26:36.203Z DRIVER   ███████╗ ██╗    ██╗  █████╗  ██╗   ██╗ ███████╗             ██╗ ███████╗
                                  ╚══███╔╝ ██║    ██║ ██╔══██╗ ██║   ██║ ██╔════╝             ██║ ██╔════╝
                                    ███╔╝  ██║ █╗ ██║ ███████║ ██║   ██║ █████╗   █████╗      ██║ ███████╗
                                   ███╔╝   ██║███╗██║ ██╔══██║ ╚██╗ ██╔╝ ██╔══╝   ╚════╝ ██   ██║ ╚════██║
                                  ███████╗ ╚███╔███╔╝ ██║  ██║  ╚████╔╝  ███████╗        ╚█████╔╝ ███████║
                                  ╚══════╝  ╚══╝╚══╝  ╚═╝  ╚═╝   ╚═══╝   ╚══════╝         ╚════╝  ╚══════╝
2023-09-27T04:26:36.214Z DRIVER   version 12.0.0
2023-09-27T04:26:36.215Z DRIVER   
2023-09-27T04:26:37.297Z CONFIG   version 12.0.0
2023-09-27T04:26:39.086Z CNTRLR   querying Serial API capabilities...
2023-09-27T04:26:40.573Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-09-27T04:26:41.685Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-09-27T04:26:43.807Z CNTRLR   The controller is unresponsive
2023-09-27T04:26:43.810Z DRIVER   Attempting to recover unresponsive controller...
2023-09-27T04:26:43.876Z CNTRLR   Performing soft reset...
2023-09-27T04:26:44.895Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-09-27T04:26:46.005Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-09-27T04:26:48.125Z CNTRLR   Soft reset failed: Timeout while waiting for an ACK from the controller (ZW020
                                  0)
2023-09-27T04:26:48.128Z DRIVER   Recovering unresponsive controller failed. Restarting the driver...
Error in driver ZWaveError: Recovering unresponsive controller failed. Restarting the driver... (ZW0100)
    at Driver.destroyWithMessage (/usr/src/node_modules/zwave-js/src/lib/driver/Driver.ts:2769:17)
    at fail (/usr/src/node_modules/zwave-js/src/lib/driver/Driver.ts:3484:14)
    at /usr/src/node_modules/zwave-js/src/lib/driver/Driver.ts:3533:5 {
  code: 100,
  context: undefined,
  transactionSource: undefined
}
Shutting down
2023-09-27T04:26:48.150Z DRIVER   Failed to initialize the driver: ZWaveError: Timeout while waiting for an ACK 
                                  from the controller (ZW0200)
                                      at Driver.sendMessage (/usr/src/node_modules/zwave-js/src/lib/driver/Drive
                                  r.ts:4981:23)
                                      at ZWaveController.identify (/usr/src/node_modules/zwave-js/src/lib/contro
                                  ller/Controller.ts:897:37)
                                      at Driver.initializeControllerAndNodes (/usr/src/node_modules/zwave-js/src
                                  /lib/driver/Driver.ts:1371:26)
                                      at Immediate.<anonymous> (/usr/src/node_modules/zwave-js/src/lib/driver/Dr
                                  iver.ts:1165:16)
Error in driver ZWaveError: Failed to initialize the driver: ZWaveError: Timeout while waiting for an ACK from the controller (ZW0200)
    at Driver.sendMessage (/usr/src/node_modules/zwave-js/src/lib/driver/Driver.ts:4981:23)
    at ZWaveController.identify (/usr/src/node_modules/zwave-js/src/lib/controller/Controller.ts:897:37)
    at Driver.initializeControllerAndNodes (/usr/src/node_modules/zwave-js/src/lib/driver/Driver.ts:1371:26)
    at Immediate.<anonymous> (/usr/src/node_modules/zwave-js/src/lib/driver/Driver.ts:1165:16) (ZW0100)
    at Immediate.<anonymous> (/usr/src/node_modules/zwave-js/src/lib/driver/Driver.ts:1185:6) {
  code: 100,
  context: undefined,
  transactionSource: undefined
}
[04:26:48] WARNING: Halt add-on
s6-rc: info: service legacy-services: stopping
s6-rc: info: service legacy-services successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped

Additional information

No response

[AlCalzone]

Looks like whatever is behind the port you've configured doesn't respond when Z-Wave JS starts.

Try pulling the stick and plugging it back in, and make sure you're using the port /dev/serial/by-id/usb-0658_0200-if00, not ...tty....
As for your question in the other issue - this is not a 700 series controller, so it is not affected by that firmware bug.

[Mkay505]

I´m having the same issue.
@jamiepenney Are you using "unraid"? I have it. And only a restore of a full backup will heal the zwave.

[jamiepenney]

No but I am running this inside a docker container via Home Assistant OS. I wonder if that's the problem - the logs did say "virtual machine not detected".

[jamiepenney]

And only a restore of a full backup will heal the zwave.

@Mkay505 do you mean a backup of Home Assistant or of the zwave stick? I haven't taken a backup of the stick before.

[sofa74surfer]

I have this issue also since 4 days and cannot remember, that I have done something special on this day. Since 26.9. 09:00, no energy data is recorded from my zwave smart meter. I'm using HA Supervised with Debian as OS. In the meanwhile, I upgraded the Firmware of the Z-Stick 7 to 1.9.3, I also upgraded Debian from Bullseye to Bookworm, because I was Supervisor unsupported. Also I tried Zwave JS UI without success. While I was upgrading the Z-Stick on a windows Machine, I can confirm, that the Stick itself is working fine and I was able to create a backup of the controller before 1.9.3 and after the 1.9.3 upgrade.

[AlCalzone]

zwave-js/node-zwave-js#6341

[jamiepenney]

To add some more debugging steps to this, I have tried the firmware update to 1.2 on my zwave stick and it didn't change anything. I still get the timeout when it tries to refresh the serial capabilities.

[jamiepenney]

More debugging attempts: I tried the Z-Wave JS UI add on instead, and get the same problem:

2023-10-03 16:06:56.218 INFO Z-WAVE: Zwavejs usage statistics ENABLED
2023-10-03 16:06:56.219 WARN Z-WAVE: Zwavejs driver is not ready yet, statistics will be enabled on driver initialization
2023-10-03T03:06:57.227Z CONFIG version 12.0.0
2023-10-03T03:06:58.697Z CNTRLR querying Serial API capabilities...
2023-10-03T03:06:59.717Z CNTRLR Failed to execute controller command after 1/3 attempts. Scheduling next try i
n 100 ms.
2023-10-03T03:07:00.825Z CNTRLR Failed to execute controller command after 2/3 attempts. Scheduling next try i
n 1100 ms.
2023-10-03T03:07:02.936Z CNTRLR The controller is unresponsive
2023-10-03T03:07:02.938Z DRIVER Attempting to recover unresponsive controller...
2023-10-03T03:07:02.942Z CNTRLR The controller does not support soft reset or the soft reset feature has been
disabled with a config option or the ZWAVEJS_DISABLE_SOFT_RESET environment va
riable.
2023-10-03T03:07:02.944Z DRIVER Recovering unresponsive controller failed. Restarting the driver...
2023-10-03 16:07:02.946 INFO Z-WAVE: Controller status: Driver: Recovering unresponsive controller failed. Restarting the driver... (ZW0100)
2023-10-03 16:07:02.948 INFO Z-WAVE: Restarting client in 15 seconds, retry 12
2023-10-03T03:07:02.950Z DRIVER Failed to initialize the driver: ZWaveError: Timeout while waiting for an ACK
from the controller (ZW0200)
at Driver.sendMessage (/opt/node_modules/zwave-js/src/lib/driver/Driver.ts
:4981:23)
at ZWaveController.identify (/opt/node_modules/zwave-js/src/lib/controller
/Controller.ts:897:37)
at Driver.initializeControllerAndNodes (/opt/node_modules/zwave-js/src/lib
/driver/Driver.ts:1371:26)
at Immediate.<anonymous> (/opt/node_modules/zwave-js/src/lib/driver/Driver
.ts:1165:16)
2023-10-03 16:07:02.952 INFO Z-WAVE: Controller status: Driver: Failed to initialize the driver: ZWaveError: Timeout while waiting for an ACK from the controller (ZW0200)
at Driver.sendMessage (/opt/node_modules/zwave-js/src/lib/driver/Driver.ts:4981:23)
at ZWaveController.identify (/opt/node_modules/zwave-js/src/lib/controller/Controller.ts:897:37)
at Driver.initializeControllerAndNodes (/opt/node_modules/zwave-js/src/lib/driver/Driver.ts:1371:26)
at Immediate.<anonymous> (/opt/node_modules/zwave-js/src/lib/driver/Driver.ts:1165:16) (ZW0100)
2023-10-03 16:07:02.953 INFO Z-WAVE: Restarting client in 15 seconds, retry 13

[sofa74surfer]

Tried to use ser2net Option like described in zwave-js/node-zwave-js#6341, one step further but unusable. Completely unstable, a lot of more and other errors and I cannot receive any data of my devices. Controller and network is visible.
I have a 700 controller Aeotec Z-Stick 7. There are a lot of "invalid payload" messages and nearly every minute, a soft reset happens.

Unresponsive ...

2023-10-03 08:48:41.567 INFO APP: GET /health/zwave 301 1.032 ms - 191
2023-10-03T06:49:10.495Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-10-03T06:49:11.599Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-10-03 08:49:11.656 INFO APP: GET /health/zwave 301 1.081 ms - 191
2023-10-03T06:49:13.713Z CNTRLR   The controller is unresponsive
2023-10-03 08:49:13.715 INFO Z-WAVE: Controller status: Controller is unresponsive
2023-10-03T06:49:13.716Z DRIVER   Attempting to recover unresponsive controller...
2023-10-03T06:49:13.719Z CNTRLR   Performing soft reset...
2023-10-03T06:49:14.731Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-10-03T06:49:15.836Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.

Dropping invalid messages ...

2023-10-03T06:48:31.255Z CNTRLR   [Node 003] The node is ready to be used
2023-10-03T06:48:31.256Z CNTRLR « [Node 003] ping successful
2023-10-03 08:48:31.388 INFO Z-WAVE: Next update scheduled for: Wed Oct 04 2023 00:00:00 GMT+0200 (Central European Summer Time)
2023-10-03T06:48:31.688Z DRIVER   Dropping message with invalid payload
2023-10-03 08:48:32.059 INFO Z-WAVE-SERVER: DNS Service Discovery enabled
2023-10-03T06:48:32.308Z DRIVER   Dropping message with invalid payload
2023-10-03T06:48:34.774Z DRIVER   Dropping message with invalid payload
2023-10-03T06:48:35.396Z DRIVER   Dropping message with invalid payload
2023-10-03T06:48:36.024Z DRIVER   Dropping message with invalid payload
2023-10-03T06:48:36.645Z DRIVER   Dropping message with invalid payload
2023-10-03T06:48:37.001Z DRIVER   Dropping message with invalid payload:
                                  0x010e00a800000100050000ad007f7ff0
2023-10-03T06:48:37.276Z DRIVER   Dropping message with invalid payload
2023-10-03T06:48:37.896Z DRIVER   Dropping message with invalid payload
2023-10-03T06:48:38.523Z DRIVER   Dropping message with invalid payload
2023-10-03T06:48:39.139Z DRIVER   Dropping message with invalid payload
2023-10-03T06:48:39.768Z DRIVER   Dropping message with invalid payload

Undefined values ... Unknown ...

2023-10-03T06:50:16.725Z CNTRLR   [Node 003] The node is alive.
2023-10-03 08:50:16.735 INFO Z-WAVE: [Node 003] Value added 3-50-0-reset => undefined
2023-10-03 08:50:16.735 INFO Z-WAVE: [Node 003] Value added 3-114-0-manufacturerId => undefined
2023-10-03 08:50:16.736 INFO Z-WAVE: [Node 003] Value added 3-114-0-productType => undefined
2023-10-03 08:50:16.737 INFO Z-WAVE: [Node 003] Value added 3-114-0-productId => undefined
2023-10-03 08:50:16.737 INFO Z-WAVE: [Node 003] Value added 3-134-0-firmwareVersions => undefined
2023-10-03 08:50:16.738 INFO Z-WAVE: [Node 003] Value added 3-134-0-libraryType => undefined
2023-10-03 08:50:16.738 INFO Z-WAVE: [Node 003] Value added 3-134-0-protocolVersion => undefined
2023-10-03 08:50:16.741 INFO Z-WAVE: [Node 003] Ready: Unknown manufacturer 0xXXXX - Unknown product 0xXXXX (0xXXXX)
2023-10-03T06:50:16.742Z CNTRLR   Retrieving priority route to node 3...

Every Node (not only one) is shown as Unknown Manufacturer, Product and Product Code, but before all this crap with 12.0.0 happens, everything was well integrated and known. I have one Qubino 3-Phase Smart Meter and two Aeotec Multisensor 7.

Unknown manufacturer 0xXXXX | 0xXXXX | Unknown product 0xXXXX

[Mkay505]

@jamiepenney I did restore the full backup of home assistant. After that everything is working fine. Sorry for the late reply.

[jamiepenney]

That suggests that the problem is in Home Assistant rather than ZWave JS, I wonder if they've changed something in the way the docker containers work?

[AlCalzone]

Does anyone here have a driver log on loglevel debug? All log snippets I see have a too low loglevel.

[jamiepenney]

zwavejs_2023-10-05.log
Yep, here's one with loglevel debug.

[jamiepenney]

No change after updating to the latest versions of ZWave JS UI and today's Home Assistant 2023.10.0 release

[AlCalzone]

zwavejs_2023-10-05.log
Yep, here's one with loglevel debug.

There's no reaction/response at all from the stick. From your previous logs it looks like you already have disabled soft-reset, so that's not the problem unlike the other issues that have popped up.
Firmware upgrade means you've also unplugged the stick at least once.

I'm afraid that's nothing I can help with, as node-zwave-js never even gets to talk to the stick.

[jamiepenney]

Ok so it's looking more like hardware failure at this point then? It happened exactly when I did the 0.1.91 update, up until that point the nodes were still reporting back to HA. Is it possible that something in the Z Wave JS upgrade bricked the stick?

[AlCalzone]

Is it possible that something in the Z Wave JS upgrade bricked the stick?

No.

Do you have any way to run Z-Wave JS UI "barebones", or on a different machine?

[jamiepenney]

I can have a crack at using the library directly on my windows machine. I'll get back to you with results.

[github-actions]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[sofa74surfer]

This Issue isn't resolved for my Aeotec Z-Stick 7. it's dead since over 3 month, i buyed a new one, but it also din't work. Tried id on a second machine and it doesn't work at all. Downgraded the Stick, but this also not works. Same Issue "Failed to execute controller command after 1/3 attempts." all the time. It stopped working somewhere in September 23 with a update of HA or Zwave.

[AlCalzone]

@sofa74surfer please open a new issue and share driver logs of the startup

[jamiepenney]

@sofa74surfer I thought home-assistant/operating-system#3224 might help, but it doesn't seem to have. Looking through the linked issue it looks like there's a USB driver issue.