I’m starting this topic to troubleshoot and log my journey.
Recently my Zooz USB 800 LR ZST39 stick keeps going unresponsive. The only solution is unplugging it and re-inserting it. Rebooting doesn’t even work.
Sample error logs that repeat:
2024-06-24 09:07:15.720 INFO APP: GET /health/zwave 301 0.487 ms - 191
2024-06-24T13:07:18.307Z CNTRLR Failed to execute controller command after 1/3 attempts. Scheduling next try i
n 100 ms.
2024-06-24T13:07:19.408Z CNTRLR Failed to execute controller command after 2/3 attempts. Scheduling next try i
n 1100 ms.
2024-06-24T13:07:21.510Z CNTRLR The controller is unresponsive
2024-06-24 09:07:21.510 INFO Z-WAVE: Controller status: Controller is unresponsive
2024-06-24T13:07:21.511Z DRIVER Attempting to recover unresponsive controller by restarting it...
2024-06-24T13:07:21.511Z CNTRLR Performing soft reset...
2024-06-24T13:07:22.514Z CNTRLR Failed to execute controller command after 1/3 attempts. Scheduling next try i
n 100 ms.
2024-06-24T13:07:23.615Z CNTRLR Failed to execute controller command after 2/3 attempts. Scheduling next try i
n 1100 ms.
2024-06-24T13:07:25.718Z CNTRLR Soft reset failed: Timeout while waiting for an ACK from the controller (ZW020
0)
2024-06-24T13:07:25.719Z DRIVER Attempting to recover unresponsive controller by reopening the serial port...
2024-06-24T13:07:26.723Z DRIVER Serial port reopened. Returning to normal operation and hoping for the best...
2024-06-24T13:07:26.723Z CNTRLR The controller is no longer unresponsive
2024-06-24 09:07:26.723 INFO Z-WAVE: Controller status: Controller is Ready
My setup:
HA VM in Proxmox with USB pass-through.
Troubleshooting steps done:
- I use the USB stick on an extension cable. I tried removing it, no difference.
- I moved the VM to another box I have, and moved the USB sticks. Still happens.
Everything worked fine for a while, until 3 things happened:
- I switched to Z-Wave JS UI (not convinced this is the problem, just coincidental)
- I upgraded the firmware on the Zooz USB stick from 1.20 to 1.30 (actually bricked it the first time, had to manually push the firmware out directly on my PC)
- I added two Minoston 800 Series Z-Wave Plug Dimmer Smart Plugs ( MP21ZD ) ( )
That 3rd one is when the problems started, in fact it was immediately after adding them when I started adjusting the dimming rate.
It happened a 2nd time after moving the VM and USB stick while also trying to adjust the brightness on the Minoston plugs.
I brought up the first 2 items because they were suggested as culprits - someone said downgrading back to V1.20 fixed it for them. Someone else blamed USB pass-through suggesting problems don’t happen on bare-metal.
To support my blame of the Minoston devices, I looked at some logs and see this when I turn on/off/adjust dimming of the Minoston devices (they are nodes 011 and 012).
011:
2024-06-24 09:25:22.408 INFO Z-WAVE: [Node 005] Value updated: 38-0-duration 0s => 0s
2024-06-24 09:25:22.409 INFO Z-WAVE: [Node 005] Value updated: 38-0-currentValue 0 => 0
2024-06-24 09:25:28.643 INFO Z-WAVE: [Node 011] Value updated: 38-0-targetValue 99 => 0
2024-06-24T13:25:30.580Z CNTRLR « [Node 011] Received update for a Supervision session
2024-06-24 09:25:30.581 INFO Z-WAVE: [Node 011] Value updated: 38-0-currentValue 99 => 0
2024-06-24 09:25:30.629 INFO Z-WAVE: [Node 011] Value updated: 38-0-targetValue 0 => 0
2024-06-24 09:25:30.631 INFO Z-WAVE: [Node 011] Value updated: 38-0-duration 0s => 0s
2024-06-24 09:25:30.632 INFO Z-WAVE: [Node 011] Value updated: 38-0-currentValue 0 => 0
2024-06-24 09:25:38.046 INFO Z-WAVE: [Node 011] Value updated: 38-0-targetValue 0 => 255
2024-06-24 09:25:39.409 INFO Z-WAVE: [Node 003] Metadata updated: 50-0-value-66049
2024-06-24 09:25:39.410 INFO Z-WAVE: [Node 003] Value updated: 50-0-value-66049 0 => 0
2024-06-24T13:25:39.983Z CNTRLR « [Node 011] Received update for a Supervision session
2024-06-24 09:25:40.289 INFO Z-WAVE: [Node 011] Value updated: 38-0-targetValue 255 => 99
2024-06-24 09:25:40.290 INFO Z-WAVE: [Node 011] Value updated: 38-0-duration 0s => 0s
2024-06-24 09:25:40.291 INFO Z-WAVE: [Node 011] Value updated: 38-0-currentValue 0 => 99
2024-06-24T13:25:40.443Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:41.124Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:41.607Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:42.190Z DRIVER Dropping message with invalid payload
2024-06-24 09:25:42.373 INFO APP: GET /health/zwave 301 0.365 ms - 191
2024-06-24T13:25:45.298Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:45.533Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:45.686Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:45.709Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:45.863Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:45.925Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:45.964Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:45.977Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:46.109Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:46.131Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:46.157Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:46.197Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:46.280Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:46.575Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:46.681Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:48.399Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:48.448Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:52.251Z DRIVER Dropping message with invalid payload
2024-06-24T13:25:54.714Z CNTRLR [Node 011] failed to decode the message, retrying with SPAN extension...
2024-06-24T13:25:55.023Z CNTRLR [Node 011] failed to decode the message after re-transmission with SPAN extens
ion, dropping the message.
2024-06-24 09:26:09.463 INFO Z-WAVE: [Node 003] Metadata updated: 50-0-value-66049
2024-06-24 09:26:09.464 INFO Z-WAVE: [Node 003] Value updated: 50-0-value-66049 0 => 0
2024-06-24 09:26:12.404 INFO APP: GET /health/zwave 301 0.670 ms - 191
012:
2024-06-24 09:28:52.499 INFO Z-WAVE-SERVER: Stopping logging event forwarder
2024-06-24 09:29:06.728 INFO Z-WAVE: [Node 012] Value updated: 38-0-targetValue 0 => 255
2024-06-24T13:29:08.664Z CNTRLR « [Node 012] Received update for a Supervision session
2024-06-24 09:29:09.094 INFO Z-WAVE: [Node 012] Value updated: 38-0-targetValue 255 => 99
2024-06-24 09:29:09.095 INFO Z-WAVE: [Node 012] Value updated: 38-0-duration 0s => 0s
2024-06-24 09:29:09.095 INFO Z-WAVE: [Node 012] Value updated: 38-0-currentValue 0 => 99
2024-06-24T13:29:09.228Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:09.737Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:09.921Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:09.943Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:10.366Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:10.472Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:10.615Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:10.763Z DRIVER Dropping message with invalid payload
2024-06-24 09:29:12.575 INFO APP: GET /health/zwave 301 0.392 ms - 191
2024-06-24T13:29:15.050Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:15.262Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:15.470Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:15.960Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:16.207Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:17.922Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:18.169Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:18.343Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:18.851Z DRIVER Dropping message with invalid payload
2024-06-24T13:29:22.026Z CNTRLR [Node 012] failed to decode the message, retrying with SPAN extension...
2024-06-24 09:29:22.184 INFO Z-WAVE: [Node 012] Value updated: 38-0-targetValue 99 => 99
2024-06-24 09:29:22.185 INFO Z-WAVE: [Node 012] Value updated: 38-0-duration 0s => 0s
2024-06-24 09:29:22.186 INFO Z-WAVE: [Node 012] Value updated: 38-0-currentValue 99 => 99
Fortunately, the controller didn’t crash but I never see these dropped messages with any other devices in my network.
To troubleshoot, I’ll change the USB pass-through mechanism, do some tests, and perhaps also try v1.20 of the Zooz stick.
I did just find firmware updates for the Minoston MP21ZD http://files.nielink.com:3002/index.php?mod=shares&sid=SGZLT1V1UlA4SF9BcWpDU1hRWDBFRE5fZWZOUDRuLXQ4b0xseVpn (from https://minoston.com/pages/minoston-firmware-drive ) so I’ll try those real quick. Looks like I’m on 8.00 and the Z-Wave firmware database thinks it is up-to-date.