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

Trying some things right now to see if it helps from random things I found on the net like:

  1. Disabling DNS Discovery
  2. Disable Statistics (wasn’t listed by other post but figured why enable it)
  3. Disable Soft Reset

Seeing what impact that has on things.

No joy. Couple days after setting that started acting up again. Odd part is:

  1. If I stop and start ZWaveJS UI when things are working, it has no impact. Keeps working after that.
  2. If I stop and start ZWaveJS UI after things are “slowing down” it starts again but when you open the GUI it shows failed to load the driver.

One thing I’m curious to test as thought it failed but not 100% sure I did this, when I telnet to 3000 I think it fails when things are acting up where it shows the usual blank screen with the flashing cursor when things are fine.

Side question on this. I’m suspecting that the actual problem, and not 100% yet, is that when I open HWInfo 64-bit it’s querying the USB ports and causing some kind of disconnect or inconsistent functionality of the Z-Wave stick? HWInfo says it’s not going to be his app and if it’s happening due to his queries means there is a bug in the device/firmware. Thoughts?

Guess not. Happened this morning and didn’t open HWInfo.

Perhaps unrelated, but I’ve noticed that zwavejs is pretty sensitive to timing disturbances. For example, performing backups of disks on the NAS I run it on. I suspect this is causing saturation of the SATA bus where the USB is connected or contention on the logger writing to disk.

You could try boosting the priority of the zwavejs driver. Perhaps use perfmon logging to see if there are changes in the system dynamics around your failure times.

Thanks not sure in Windows how to prioritize a driver but willing to try if I know how. Note my system is a Ryzen 7950x water cooled so probably not resource constrained. I was curious if a Sigma Designs driver from 2013 is the latest driver for the z-stick as well.

Side note, for me all my drives are NVME and my physical drives are hardware raid SAS drives in an external enclosure. Only drive physically on this new system is an external drive to backup my C: drive but this was happening even before I introduced it into the equation.

What’s odd about the logs if I look at today, 2/23/2023 when I got up in the morning things were hanging or slow responding. Log shows midnight and then records timing out:

2023-02-23T06:00:00.004Z DRIVER   Checking for configuration updates...
2023-02-23T06:00:00.157Z DRIVER   No configuration update available...
2023-02-23T12:37:25.152Z SERIAL » 0x010a001307032501ff254854                                          (12 bytes)
2023-02-23T12:37:25.152Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      72
                                  └─[BinarySwitchCCSet]
                                      target value: true
2023-02-23T12:37:26.154Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-23T12:37:26.263Z SERIAL » 0x010a001307032501ff254854                                          (12 bytes)
2023-02-23T12:37:26.263Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      72
                                  └─[BinarySwitchCCSet]
                                      target value: true
2023-02-23T12:37:27.268Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-23T12:37:28.381Z SERIAL » 0x010a001307032501ff254854                                          (12 bytes)
2023-02-23T12:37:28.381Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      72
                                  └─[BinarySwitchCCSet]
                                      target value: true
2023-02-23T12:37:29.387Z CNTRLR   [Node 007] did not respond after 1/3 attempts. Scheduling next try in 500 ms.
2023-02-23T12:37:29.889Z SERIAL » 0x010a001307032501ff254854                                          (12 bytes)
2023-02-23T12:37:29.889Z DRIVER » [Node 007] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      72
                                  └─[BinarySwitchCCSet]
                                      target value: true
2023-02-23T12:37:30.896Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.

If I pull up the log dated 2/22/2023 it shows some entries from 2/23/2023 also but no failures:

2023-02-23T00:00:03.247Z SERIAL « 0x0112000400050a32022174000003060000c60040                          (20 bytes)
2023-02-23T00:00:03.247Z SERIAL » [ACK]                                                                   (0x06)
2023-02-23T00:00:03.247Z CNTRLR   [Node 005] [~] [Meter] value[66049]: 0.772 => 0.774               [Endpoint 0]
2023-02-23T00:00:03.248Z DRIVER « [Node 005] [REQ] [ApplicationCommand]
                                  └─[MeterCCReport]
                                      type:       Electric
                                      scale:      W
                                      rate type:  Consumed
                                      value:      0.774
                                      time delta: 0 seconds
2023-02-23T00:00:08.402Z SERIAL « 0x0112000400060a320221740000033b0000c3007b                          (20 bytes)
2023-02-23T00:00:08.402Z SERIAL » [ACK]                                                                   (0x06)
2023-02-23T00:00:08.402Z CNTRLR   [Node 006] [~] [Meter] value[66049]: 0.831 => 0.827               [Endpoint 0]
2023-02-23T00:00:08.403Z DRIVER « [Node 006] [REQ] [ApplicationCommand]
                                  └─[MeterCCReport]
                                      type:       Electric
                                      scale:      W
                                      rate type:  Consumed
                                      value:      0.827
                                      time delta: 0 seconds

But does show it a bit before that:

2023-02-22T12:48:56.590Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.
2023-02-22T12:48:56.699Z SERIAL » 0x010b00130e042601ffff259a75                                        (13 bytes)
2023-02-22T12:48:56.700Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      154
                                  └─[MultilevelSwitchCCSet]
                                      target value: 255
                                      duration:     default
2023-02-22T12:48:57.715Z CNTRLR   Failed to execute controller command after 2/3 attempts. Scheduling next try i
                                  n 1100 ms.
2023-02-22T12:48:58.824Z SERIAL » 0x010b00130e042601ffff259a75                                        (13 bytes)
2023-02-22T12:48:58.824Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      154
                                  └─[MultilevelSwitchCCSet]
                                      target value: 255
                                      duration:     default
2023-02-22T12:48:59.832Z CNTRLR   [Node 014] did not respond after 1/3 attempts. Scheduling next try in 500 ms.
2023-02-22T12:49:00.341Z SERIAL » 0x010b00130e042601ffff259a75                                        (13 bytes)
2023-02-22T12:49:00.341Z DRIVER » [Node 014] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      154
                                  └─[MultilevelSwitchCCSet]
                                      target value: 255
                                      duration:     default
2023-02-22T12:49:01.357Z CNTRLR   Failed to execute controller command after 1/3 attempts. Scheduling next try i
                                  n 100 ms.

From what I can see in theory this started 2023-02-22T12:48:56.590Z

Which I believe is CST

2/22/2023 at 6:48AM

So in theory something happened at that time originally? If so went thru every event log and nothing happened at that time.

The biggest issue in the log is that there is no data coming in at all. Then the commands timeout. This is a problem with the stack from OS → USB stick. I’d start swapping out components, pc, cable, stick. Based on your topology I’d start with the Active Cable (maybe it’s developed a low voltage) or swapping out the windows host.

Thanks for the thoughts. Brand new water cooled rack mount server so not going to swap that out. Running Hyper-V on the Windows 2022 host so can’t swap that out. Have 13 virtuals running on it. I can swap the cable and stick but as they are mounted in the rafters not going to assume that they magically stopped working when swapping the computer. My take would in theory be that it’s Windows itself but more specifically the Z-WaveJS UI application running on Windows as others have stated due to it not being used by more than a couple individuals apparently.

Think I’ll try setting this up on another computer but also Windows and see if I have the same issue. Since it’s running IP based doesn’t matter where it sits for now.

Sounds like a good plan. Lots of variables. Windows, zwavejs, server usb interface/driver, active usb, zwave stick, zwave stick driver, zwave network.

If trying the other windows machine fails. I’d try putting zwavejs on Linux to see if everything from the active usb outward is functioning. That would be a test, it maybe the stick is bad, or the USB voltage is too low, or like you suspect zwavejs doesn’t work on windows, or the old driver for the stick has bugs….

Thanks I’m on it. Any possibility the voltage from the USB 2.0 port on one computer and another would be different? I know I can power a USB hard drive all day on that port with no other power and it backs up my system without an issue. Or getting a different active USB cable would work better if they are being powered by the same USB port as the other one is?

Is there recommendations if I should stick with USB 2.0 ports or 3.0 or 3.1 or USB-C ports? Also any input on extension cables? The one I have is 32 feet long and an Amazon Basics USB 2.0 active extension and is exactly the length I need to get it from the basement staircase area to the front port on my server.

It’s certainly possible. One guy I was working with had similar problems to yours, he put in a powered USB 2.0 hub in and his problems went away. The stick was on 6’ cable plugged into a PI - and putting this is the middle solved it. Zwave doesn’t need a lot of bandwidth - fundamentally it’s a serial port operating at 155kbaud. USB 2 seems to be what is recommended.

I had my stick on a 3meter extension cable, and had a bunch of issues, move it to a 6’ cable and it works well. I have the Aoetech Gen 5 stick like you. My conclusion is it’s finicky.

I may try just plugging it straight in for a test without the extension. The computer is in a crawlspace in the basement but there are several powered Z-Wave devices in range. Also thinking of getting one of those USB-A / USB-C power testers. Oddly only time I’ve seen Klein Tools selling anything for less than 3 to 4 figures.

https://www.amazon.com/gp/product/B07GXZHPVR/ref=ox_sc_act_title_1?smid=ATVPDKIKX0DER&psc=1