Failed to execute controller command after 1/3 attempts. Scheduling next try

jriker1 · February 1, 2023, 11:52pm

I was going to post this at github but it’s very specific that if you are using HA post here unless told otherwise. Here’s the story.

Been using an Aeotec Z-Wave Gen5 stick (firmware 1.01) for years without issue. There have been no changes physically to my Z-Wave environment or placement. My prior system was running in a VMWare Workstation virtual with the Z-Wave stick passed thru and same Z-WaveJS UI back but in the virtual. Worked fine.

My new environment is a new computer running Windows 2022 with the Hyper-V Role. It is running Z-WaveJS UI on the physical server. Z-Wave JS info:

zwave-js-ui: 8.8.0
zwave-js: 10.4.0

Do not think this is HA related and probably all local because my HA shows nothing in the logs. Ever since moving to the new setup I’m having issues where the Z-Wave devices stop responding or do but slow. My HA screen also do not update anymore when this happens though you can still click the switches even though they may not update and eventually get a reaction from a device. Like 30 seconds later. If I pull the stick out and plug it back in problem goes away for an indeterminate period of time. If I reboot the computer same deal. Believe this is also accurate. If I restart Z-Wave JS UI it doesn’t help. What I’ve tried:

Installing the Aeotec Z-Wave driver in Windows
Change and resetting the COM port speed
Had an external hard drive also plugged into the front USB 2.0 ports and removed that.
Tried healing multiple times which works fine but fails when things aren’t responding.
Updated the stick to 1.02.

Probably tried some other things but at a loss right now. Any thoughts? Thought there was a way to attach logs but not seeing it right now so some examples of what’s going on:

023-02-01T22:42:18.441Z CNTRLR   [Node 007] did not respond after 1/3 attempts. Scheduling next try in 500 ms.
2023-02-01T22:42:18.941Z SERIAL » 0x010a0013070325010025f310                                          (12 bytes)
2023-02-01T22:42:18.941Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      243
                                  └─[BinarySwitchCCSet]
                                      target value: false
2023-02-01T22:42:19.942Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-01T22:42:20.052Z SERIAL » 0x010a0013070325010025f310                                          (12 bytes)
2023-02-01T22:42:20.052Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      243
                                  └─[BinarySwitchCCSet]
                                      target value: false
2023-02-01T22:42:21.068Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-01T22:42:22.169Z SERIAL » 0x010a0013070325010025f310                                          (12 bytes)
2023-02-01T22:42:22.169Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      243
                                  └─[BinarySwitchCCSet]
                                      target value: false
2023-02-01T22:42:23.178Z CNTRLR   [Node 007] did not respond after 2/3 attempts. Scheduling next try in 500 ms.
2023-02-01T22:42:23.695Z SERIAL » 0x010a0013070325010025f310                                          (12 bytes)
2023-02-01T22:42:23.695Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      243
                                  └─[BinarySwitchCCSet]
                                      target value: false
2023-02-01T22:42:24.696Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-01T22:42:24.805Z SERIAL » 0x010a0013070325010025f310                                          (12 bytes)
2023-02-01T22:42:24.805Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      243
                                  └─[BinarySwitchCCSet]
                                      target value: false
2023-02-01T22:42:25.820Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-01T22:42:26.928Z SERIAL » 0x010a0013070325010025f310                                          (12 bytes)
2023-02-01T22:42:26.928Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      243
                                  └─[BinarySwitchCCSet]
                                      target value: false
2023-02-01T22:46:10.490Z SERIAL » 0x010b00130e0426014fff25f4ab                                        (13 bytes)
2023-02-01T22:46:10.491Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      244
                                  └─[MultilevelSwitchCCSet]
                                      target value: 79
                                      duration:     default
2023-02-01T22:46:11.507Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-01T22:46:11.616Z SERIAL » 0x010b00130e0426014fff25f4ab                                        (13 bytes)
2023-02-01T22:46:11.616Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      244
                                  └─[MultilevelSwitchCCSet]
                                      target value: 79
                                      duration:     default
2023-02-01T22:46:12.632Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-01T22:46:13.742Z SERIAL » 0x010b00130e0426014fff25f4ab                                        (13 bytes)
2023-02-01T22:46:13.743Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      244
                                  └─[MultilevelSwitchCCSet]
                                      target value: 79
                                      duration:     default
2023-02-01T22:46:14.744Z CNTRLR   [Node 014] did not respond after 1/3 attempts. Scheduling next try in 500 ms.
2023-02-01T22:46:15.260Z SERIAL » 0x010b00130e0426014fff25f4ab                                        (13 bytes)
2023-02-01T22:46:15.261Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      244
                                  └─[MultilevelSwitchCCSet]
                                      target value: 79
                                      duration:     default
2023-02-01T22:46:16.271Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-01T22:46:16.381Z SERIAL » 0x010b00130e0426014fff25f4ab                                        (13 bytes)
2023-02-01T22:46:16.381Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      244
                                  └─[MultilevelSwitchCCSet]
                                      target value: 79
                                      duration:     default
2023-02-01T22:46:17.395Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-01T22:46:18.505Z SERIAL » 0x010b00130e0426014fff25f4ab                                        (13 bytes)
2023-02-01T22:46:18.505Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      244
                                  └─[MultilevelSwitchCCSet]
                                      target value: 79
                                      duration:     default
2023-02-01T22:46:19.521Z CNTRLR   [Node 014] did not respond after 2/3 attempts. Scheduling next try in 500 ms.
2023-02-01T22:46:20.024Z SERIAL » 0x010b00130e0426014fff25f4ab                                        (13 bytes)
2023-02-01T22:46:20.024Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      244
                                  └─[MultilevelSwitchCCSet]
                                      target value: 79
                                      duration:     default
2023-02-01T22:46:21.039Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-01T22:46:21.148Z SERIAL » 0x010b00130e0426014fff25f4ab                                        (13 bytes)
2023-02-01T22:46:21.149Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      244
                                  └─[MultilevelSwitchCCSet]
                                      target value: 79
                                      duration:     default
2023-02-01T22:46:22.149Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-01T22:46:23.259Z SERIAL » 0x010b00130e0426014fff25f4ab                                        (13 bytes)
2023-02-01T22:46:23.259Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      244
                                  └─[MultilevelSwitchCCSet]
                                      target value: 79
                                      duration:     default
2023-02-01T22:47:22.038Z SERIAL » 0x010b00130e04260128ff25f5cd                                        (13 bytes)
2023-02-01T22:47:22.038Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      245
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
                                      duration:     default
2023-02-01T22:47:23.047Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-01T22:47:23.157Z SERIAL » 0x010b00130e04260128ff25f5cd                                        (13 bytes)
2023-02-01T22:47:23.157Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      245
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
                                      duration:     default
2023-02-01T22:47:24.172Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-01T22:47:25.282Z SERIAL » 0x010b00130e04260128ff25f5cd                                        (13 bytes)
2023-02-01T22:47:25.282Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      245
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
                                      duration:     default
2023-02-01T22:47:26.298Z CNTRLR   [Node 014] did not respond after 1/3 attempts. Scheduling next try in 500 ms.
2023-02-01T22:47:26.815Z SERIAL » 0x010b00130e04260128ff25f5cd                                        (13 bytes)
2023-02-01T22:47:26.815Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      245
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
                                      duration:     default
2023-02-01T22:47:27.825Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-01T22:47:27.934Z SERIAL » 0x010b00130e04260128ff25f5cd                                        (13 bytes)
2023-02-01T22:47:27.934Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      245
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
                                      duration:     default
2023-02-01T22:47:28.936Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-01T22:47:30.045Z SERIAL » 0x010b00130e04260128ff25f5cd                                        (13 bytes)
2023-02-01T22:47:30.046Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      245
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
                                      duration:     default
2023-02-01T22:47:31.047Z CNTRLR   [Node 014] did not respond after 2/3 attempts. Scheduling next try in 500 ms.
2023-02-01T22:47:31.562Z SERIAL » 0x010b00130e04260128ff25f5cd                                        (13 bytes)
2023-02-01T22:47:31.563Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      245
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
                                      duration:     default
2023-02-01T22:47:32.579Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-01T22:47:32.688Z SERIAL » 0x010b00130e04260128ff25f5cd                                        (13 bytes)
2023-02-01T22:47:32.688Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      245
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
                                      duration:     default
2023-02-01T22:47:33.689Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-01T22:47:34.804Z SERIAL » 0x010b00130e04260128ff25f5cd                                        (13 bytes)
2023-02-01T22:47:34.805Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      245
                                  └─[MultilevelSwitchCCSet]
                                      target value: 40
                                      duration:     default

Adding a picture. When it’s like this you see ACK timeouts and heals fail

petro · February 2, 2023, 12:05am

Pretty sure I warned you a month ago about trying to use hyper-v with hardware USB devices.

jriker1 · February 2, 2023, 12:07am

Hey petro, yes but I am not. I am installing Z-WaveJS UI on the main Windows 2022 server and using IP to communicate to HA with the Z-Wave integration.

freshcoast · February 2, 2023, 12:13am

You’re not using HA, you’re using Z-Wave JS UI. They don’t want you posting HA bugs, that’s all it means.

Try the troubleshooting docs, esp. Connectivity issues.

To start with, make sure your stick is on a short extension cord.

jriker1 · February 2, 2023, 12:15am

Its on a bit longer than a short one (32 feet) else it would be sitting in the crawlspace however it’s always worked and is an active cable.

freshcoast · February 2, 2023, 12:24am

You’ve only provided a log snippet. Do you have logs from Z-Wave JS startup?

jriker1 · February 2, 2023, 12:25am

Should I paste them all in the message?

freshcoast · February 2, 2023, 12:25am

Sure, just startup is enough.

jriker1 · February 2, 2023, 12:44am

Guess I can’t do a pastebin to much info.

This is zwavejs_2023-02-01.log. I pulled the device and put it back in after 7:00AM this morning and later started acting up again, Times seem odd so guess GMT:

The z-ui_2023-02-01.log file:

freshcoast · February 2, 2023, 12:54am

Your errors appear when the driver starts up. Sorry to say but I think the Windows version of Z-Wave JS is just broken at this time. Which is a bit disappointing because it used to work. See GH issue #5024.

The issue was logged for Windows 11, but others–including myself just now–have reproduced it with Windows 10. For me it completely fails on Windows in a similar (but not exact) manner as yours, but works perfectly on a Linux box in the same room.

Unfortunately, you’re either going to have to wait for a fix, or continue on the path of finding a non-Windows solution.

jriker1 · February 2, 2023, 1:02am

Thanks for the reply and looking into the logs. Can you share where you are seeing it fail to initialize the driver in my logs? Also why would it work at all? Is it working and then the driver re-initializing at some point and having issues?

freshcoast · February 2, 2023, 1:08am

Same errors you posted above. They just start when the driver loads.

jriker1 · February 2, 2023, 1:15am

Just weird that it works and the eventually it kind of works. Reading that issue sounds like even if I moved this to my other Windows 10 workstation it would still be an issue. Guess the question is could I go back to an older version and if so would it have to be on Windows 10 not I guess in my case Windows 2022 which is perhaps more Windows 11ish?

freshcoast · February 2, 2023, 1:16am

Didn’t catch you’re using 2022. You might add that information to the GH issue, seems to be affecting multiple versions.

jriker1 · February 2, 2023, 1:18am

Is that issue being considered anymore? Looks like it’s been sitting for a bit but will post there. I don’t really have any other options other than to move it to my Windows 10 computer and setup a VMware Workstation instance with Linux there. Feel like I’m going backwards as that’s where my old HA system was at.

freshcoast · February 2, 2023, 1:23am

The issue is still open, if it weren’t being considered it would be closed. There’s no reason to assume Z-Wave JS has suddenly dropped support for Windows just because there hasn’t been any activity on that issue for a short time. The developer was away for some time and issues are being worked through as quickly as possible.

jriker1 · February 6, 2023, 5:30pm

Think the thought may be it’s different as mine works and at some random time it stops but that issue seems like it’s completely non functional and never loading the driver.

freshcoast · February 6, 2023, 7:01pm

Well, your claim was that it was working for years in a Linux environment. Now you are seeing problems but in a Windows environment. A logical conclusion based on those statements is Windows is the problem.

However, maybe something else changed during the time you switched. The only way you’re going to confirm that is if you switch back to Linux, install the same version of Z-Wave JS, and see whether it fails in the same way or not.

jriker1 · February 6, 2023, 7:33pm

Right but just because someone else is having a windows problem doesn’t mean mine is the same issue. Per the dev the other individuals doesn’t load at all in Windows 11. Anyway, going to give it some time again to see what happens. Disabled some things in the GUI so curious if it will help. Guess worst case can setup VMware Workstation again and passthru the stick like I did for the last several years to ZWaveJS UI only setup and see what happens.

PeteRage · February 6, 2023, 9:57pm

While I’m sure this can eventually work. A challenge is not being on a typical deployment environment; its hard to know if this is issue 1 of 1 or issue 1 of 100.

I’d look at getting an inexpensive NUC, put Linux/Docker/zwavejs on it.