Zooz 800 series controller enters unresponsive state then every command fails with "Failed to execute controller command"

[protz]

Checklist

• I have read and followed the above instructions

• I have checked the troubleshooting section and my problem is not described there.

• I have read the changelog and my problem was not mentioned there or the fix did not work.

Describe the issue

What is happening?

About once every other week on average, My Zooz 800 series controller gets into an unresponsive state that the zwave-js backend cannot recover from. This is what I see in the logs.

2024-07-31T00:00:03.997Z DRIVER » [REQ] [GetBackgroundRSSI]
2024-07-31T00:00:05.008Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2024-07-31T00:00:05.111Z DRIVER » [REQ] [GetBackgroundRSSI]
2024-07-31T00:00:05.115Z SERIAL » 0x0103003bc7                                                         (5 bytes)
2024-07-31T00:00:06.120Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2024-07-31T00:00:07.221Z DRIVER » [REQ] [GetBackgroundRSSI]
2024-07-31T00:00:07.222Z SERIAL » 0x0103003bc7                                                         (5 bytes)
2024-07-31T00:00:08.224Z CNTRLR   The controller is unresponsive
2024-07-31T00:00:08.226Z DRIVER   Attempting to recover unresponsive controller by restarting it...
2024-07-31T00:00:08.226Z CNTRLR   Performing soft reset...
2024-07-31T00:00:08.231Z SERIAL » 0x01030008f4                                                         (5 bytes)
2024-07-31T00:00:08.232Z DRIVER » [REQ] [SoftReset]
2024-07-31T00:00:09.236Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2024-07-31T00:00:09.338Z DRIVER » [REQ] [SoftReset]
2024-07-31T00:00:09.338Z SERIAL » 0x01030008f4                                                         (5 bytes)
2024-07-31T00:00:10.340Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2024-07-31T00:00:11.442Z DRIVER » [REQ] [SoftReset]
2024-07-31T00:00:11.442Z SERIAL » 0x01030008f4                                                         (5 bytes)
2024-07-31T00:00:12.446Z CNTRLR   Soft reset failed: Timeout while waiting for an ACK from the controller (ZW020
                                  0)
2024-07-31T00:00:12.446Z DRIVER   Attempting to recover unresponsive controller by reopening the serial port...
2024-07-31T00:00:12.447Z DRIVER   all queues idle
2024-07-31T00:00:13.458Z DRIVER   Serial port reopened. Returning to normal operation and hoping for the best...
2024-07-31T00:00:13.458Z CNTRLR   The controller is no longer unresponsive
2024-07-31T00:00:33.985Z DRIVER   all queues busy
2024-07-31T00:00:33.989Z SERIAL » 0x0103003bc7                                                         (5 bytes)
2024-07-31T00:00:33.989Z DRIVER » [REQ] [GetBackgroundRSSI]
2024-07-31T00:00:34.992Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2024-07-31T00:00:35.094Z DRIVER » [REQ] [GetBackgroundRSSI]
2024-07-31T00:00:35.094Z SERIAL » 0x0103003bc7                                                         (5 bytes)
2024-07-31T00:00:36.097Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2024-07-31T00:00:37.199Z DRIVER » [REQ] [GetBackgroundRSSI]
2024-07-31T00:00:37.199Z SERIAL » 0x0103003bc7                                                         (5 bytes)
2024-07-31T00:00:38.206Z CNTRLR   The controller is unresponsive
2024-07-31T00:00:38.209Z DRIVER   Attempting to recover unresponsive controller by restarting it...
2024-07-31T00:00:38.210Z CNTRLR   Performing soft reset...
2024-07-31T00:00:38.219Z SERIAL » 0x01030008f4                                                         (5 bytes)
2024-07-31T00:00:38.219Z DRIVER » [REQ] [SoftReset]
2024-07-31T00:00:39.224Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2024-07-31T00:00:39.325Z DRIVER » [REQ] [SoftReset]
2024-07-31T00:00:39.326Z SERIAL » 0x01030008f4                                                         (5 bytes)
2024-07-31T00:00:40.334Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2024-07-31T00:00:41.439Z DRIVER » [REQ] [SoftReset]
2024-07-31T00:00:41.440Z SERIAL » 0x01030008f4                                                         (5 bytes)
2024-07-31T00:00:42.445Z CNTRLR   Soft reset failed: Timeout while waiting for an ACK from the controller (ZW020
                                  0)
2024-07-31T00:00:42.446Z DRIVER   Attempting to recover unresponsive controller by reopening the serial port...

Restarting the docker container that runs z-wave js does not help, and I have to reboot the whole raspberry pi system to get things back to normal.

What did you expect to happen instead?

Because I followed all of the instructions, including running docker properly, I expected that the zwave-js backend should be able to handle this.

Specifically, I execute docker with the right USB device:

jonathan@raspberrypi:~ $ ps aux | grep by-id
root        2051  0.0  1.2 1419636 49796 ?       Ssl  Jul31   0:35 /usr/bin/docker run --rm --name zwavejs2mqtt.service -p 8091:8091 -p 3000:3000 --device=/dev/serial/by-id/usb-Zooz_800_Z-Wave_Stick_533D004242-if00:/dev/zwave --mount source=zwavejs2mqtt,target=/usr/src/app/store zwavejs/zwave-js-ui:latest
jonathan  506996  0.0  0.0   6012   660 pts/0    S+   04:03   0:00 grep --color=auto by-id
jonathan@raspberrypi:~ $ ls /dev/serial/by-id/usb-Zooz_800_Z-Wave_Stick_533D004242-if00
/dev/serial/by-id/usb-Zooz_800_Z-Wave_Stick_533D004242-if00

which is listed as the thing that typically causes these problems; because I appear to do this right, I expected that the backend would be able to handle a soft reset adequately.

Steps to reproduce the behavior:

I unfortunately have been unable to track this down to something more specific. It seems to happen randomly.

Anything else we should know?

Nope. This is all as seen from the zwave-js web ui, no home assistant involved in this bug report. There seem to be other issues that are vaguely close but nothing like this exactly. Thanks.

Software versions

zwave-js-ui: 9.16.4.394bd02
zwave-js: 13.0.2

Device information

Zooz 800 Series Long Range USB Controller ZST39 LR
FW: v1.30
SDK: v7.21.3

Checklist

• I made sure to provide a driver log on level debug.

• The log includes a re-interview of the problematic device (if applicable).

• The log includes the problematic interaction with the device (if applicable).

• I provided the node ID of the problematic device (if applicable).

Upload Logfile

zwavejs_current.log

[AlCalzone]

Upgrade to firmware 1.40. This contains a bunch of fixes for the instability.
See also #6874

[protz]

Thanks. I reviewed all the issues but didn't realize the action was happening in discussions :(. Thank you!