[C8P ZWJS - 2.4.1.177] Lock Retries

[rob9]

@bcopeland This may be up your alley.

I've enabled "Command Retry" on all my devices and that has been a god-send--things work SO much better now. And, while retrying is involved, I am inclined to think this is NOT an issue with the retry process.

Before the "retry" feature, whenever more than a few devices were changed at once, a number didn't respond. Now that I've enabled "retry", they almost always get properly set (which is great)--but there are indications that the hub isn't receiving the expected response to tell it that the device did what it was supposed to.

I wonder if the "Beaming" process is preventing the hub from receiving messages from the devices for a period of time?

In looking at the logs, a number of devices that DID process the command show as "failed after 5 retries". It's very apparent with my 2 Yale locks because they beep every time they receive a command.

When I arrive home and turn on a number of lights along with unlocking the doors with the Yale locks, they unlock immediately but continue to beep many times after that (and often show as "failing" after 5 retries).

I decided to run a test tonight while monitoring the logs. When I just tested it by doing one lock, the first time I tried one of the locks it beeped/retried many times. But, after that, it seemed to work very well--locking/unlocking and beeping just once.

I then tried the other lock (capturing logging this time, see below)--it beeped twice (once upon the initial command, which worked--then again when the retry came through) before it registered the action completing on the hub. This was with a nearly idle hub, as not much else was going on during this test.

Here's the z-wave log for the second Yale lock where it retried a second time unnecessarily (I zeroed out a number of the hex digits, as I didn't know which might reveal security issues):

2025-06-06 12:04:02.310 AMDRIVER « [RES] [SendDataBridge] - was sent: true
2025-06-06 12:04:02.307 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:04:02.305 AMSERIAL « [ACK] (0x06)
2025-06-06 12:04:02.301 AMDRIVER » [Node 184] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 147 - +-[SecurityCCCommandEncapsulation] - ¦ nonce id: 243 - +-[BatteryCCGet]
2025-06-06 12:04:02.299 AMSERIAL » 0x00000000000000000000000000000000000000000000000000000000000000000 (38 bytes) - 00000000000
2025-06-06 12:04:02.293 AMDRIVER one or more queues busy
2025-06-06 12:04:02.162 AMCNTRLR [Node 189] [Notification] - type: Access Control - event: RF lock operation
2025-06-06 12:04:02.160 AMCNTRLR [Node 189] [~] [Door Lock] currentMode: 255 => 255 [Endpoint 0]
2025-06-06 12:04:02.158 AMDRIVER « [Node 189] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -78 dBm - +-[SecurityCCCommandEncapsulation] - ¦ sequenced: false - +-[NotificationCCReport] - V1 alarm type: 24 - V1 alarm level: 1 - notification type: Access Control - notification status: 255 - notification event: RF lock operation
2025-06-06 12:04:02.156 AMCNTRLR [Node 189] [~] [Notification] alarmLevel: 1 => 1 [Endpoint 0]
2025-06-06 12:04:02.154 AMCNTRLR [Node 189] [~] [Notification] alarmType: 24 => 24 [Endpoint 0]
2025-06-06 12:04:02.151 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:02.149 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000000 (46 bytes) - 000000000000000000000000000
2025-06-06 12:04:02.071 AMDRIVER all queues idle
2025-06-06 12:04:02.069 AMDRIVER « [REQ] [SendDataBridge] - callback id: 146 - transmit status: OK, took 70 ms - repeater node IDs: 7 - routing attempts: 1 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -79 dBm - ACK RSSI on repeaters: N/A - ACK channel no.: 1 - TX channel no.: 1
2025-06-06 12:04:02.067 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:02.065 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:04:01.994 AMDRIVER « [RES] [SendDataBridge] - was sent: true
2025-06-06 12:04:01.992 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:01.990 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:04:01.987 AMSERIAL « [ACK] (0x06)
2025-06-06 12:04:01.984 AMDRIVER » [Node 189] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x05 - ¦ callback id: 146 - +-[SecurityCCNonceReport] - nonce: 0x2ecf00000000bf70
2025-06-06 12:04:01.982 AMSERIAL » 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:04:01.979 AMDRIVER one or more queues busy
2025-06-06 12:04:01.975 AMDRIVER « [Node 189] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -77 dBm - +-[SecurityCCNonceGet]
2025-06-06 12:04:01.972 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:01.970 AMSERIAL « 0x000000000000000000000000000000000000  (18 bytes)
2025-06-06 12:04:01.355 AMDRIVER all queues idle
2025-06-06 12:04:01.350 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:01.348 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:04:01.108 AMDRIVER « [RES] [SendDataBridge] - was sent: true
2025-06-06 12:04:01.106 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:04:01.104 AMSERIAL « [ACK] (0x06)
2025-06-06 12:04:01.100 AMDRIVER » [Node 189] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 145 - +-[SecurityCCCommandEncapsulation] - ¦ nonce id: 80 - +-[DoorLockCCOperationSet] - target mode: Secured
2025-06-06 12:04:01.097 AMSERIAL » 0x00000000000000000000000000000000000000000000000000000000000000000 (39 bytes) - 0000000000000
2025-06-06 12:04:01.094 AMDRIVER « [Node 189] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -77 dBm - +-[SecurityCCNonceReport] - nonce: 0x50ce00000000feaf
2025-06-06 12:04:01.092 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:01.090 AMSERIAL « 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:04:01.015 AMDRIVER « [REQ] [SendDataBridge] - callback id: 144 - transmit status: OK, took 130 ms - repeater node IDs: 7 - routing attempts: 1 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -81 dBm - ACK RSSI on repeaters: N/A - ACK channel no.: 1 - TX channel no.: 1
2025-06-06 12:04:01.013 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:04:00.884 AMDRIVER « [RES] [SendDataBridge] - was sent: true
2025-06-06 12:04:00.883 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.881 AMSERIAL « 0x010401a90152 (6 bytes)
2025-06-06 12:04:00.879 AMSERIAL « [ACK] (0x06)
2025-06-06 12:04:00.877 AMDRIVER » [Node 189] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 144 - +-[SecurityCCNonceGet]
2025-06-06 12:04:00.875 AMSERIAL » 0x000000000000000000000000000000000000 (18 bytes)
2025-06-06 12:04:00.871 AMDRIVER one or more queues busy
2025-06-06 12:04:00.865 AMDRIVER all queues idle
2025-06-06 12:04:00.862 AMDRIVER « [REQ] [SendDataBridge] - callback id: 143 - transmit status: OK, took 180 ms - repeater node IDs: 7 - routing attempts: 2 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -79 dBm - ACK RSSI on repeaters: N/A - ACK channel no.: 1 - TX channel no.: 1
2025-06-06 12:04:00.858 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:04:00.673 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.671 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:04:00.666 AMSERIAL « [ACK] (0x06)
2025-06-06 12:04:00.662 AMDRIVER » [Node 189] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 143 - +-[SecurityCCCommandEncapsulation] - ¦ nonce id: 145 - +-[DoorLockCCOperationSet] - target mode: Secured
2025-06-06 12:04:00.659 AMSERIAL » 0x00000000000000000000000000000000000000000000000000000000000000000 (39 bytes) - 0000000000000
2025-06-06 12:04:00.654 AMDRIVER « [REQ] [SendDataBridge] - callback id: 142 - transmit status: OK, took 210 ms - repeater node IDs: 7 - routing attempts: 1 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -77 dBm - ACK RSSI on repeaters: N/A - ACK channel no.: 1 - TX channel no.: 1
2025-06-06 12:04:00.653 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.651 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:04:00.486 AMDRIVER « [Node 189] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -79 dBm - +-[SecurityCCNonceReport] - nonce: 0x911d0000000097ff
2025-06-06 12:04:00.484 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.483 AMSERIAL « 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:04:00.437 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.435 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:04:00.433 AMSERIAL « [ACK] (0x06)
2025-06-06 12:04:00.428 AMDRIVER » [Node 189] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 142 - +-[SecurityCCCommandEncapsulation] - ¦ nonce id: 145 - +-[DoorLockCCOperationSet] - target mode: Secured
2025-06-06 12:04:00.426 AMSERIAL » 0x00000000000000000000000000000000000000000000000000000000000000000 (39 bytes) - 0000000000000
2025-06-06 12:04:00.423 AMDRIVER « [Node 189] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -77 dBm - +-[SecurityCCNonceReport] - nonce: 0x911d0000000097ff
2025-06-06 12:04:00.421 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.419 AMSERIAL « 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:04:00.340 AMDRIVER « [REQ] [SendDataBridge] - callback id: 141 - transmit status: OK, took 40 ms - repeater node IDs: 7 - routing attempts: 1 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -77 dBm - ACK RSSI on repeaters: N/A - ACK channel no.: 1 - TX channel no.: 1
2025-06-06 12:04:00.338 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:04:00.291 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.289 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:04:00.285 AMSERIAL « [ACK] (0x06)
2025-06-06 12:04:00.281 AMDRIVER » [Node 189] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 141 - +-[SecurityCCNonceGet]
2025-06-06 12:04:00.279 AMSERIAL » 0x000000000000000000000000000000000000 (18 bytes)
2025-06-06 12:04:00.276 AMDRIVER « [Node 184] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -77 dBm - +-[SecurityCCCommandEncapsulation] - ¦ sequenced: false - +-[DoorLockCCOperationReport] - current mode: Unsecured - active outside handles: false, false, false, false - active inside handles: false, false, false, false - latch status: open - bolt status: unlocked - door status: open
2025-06-06 12:04:00.274 AMCNTRLR [Node 184] [~] [Door Lock] latchStatus: "open" => "open" [Endpoint 0]
2025-06-06 12:04:00.268 AMCNTRLR [Node 184] [~] [Door Lock] boltStatus: "unlocked" => "unlocked" [Endpoint 0]
2025-06-06 12:04:00.266 AMCNTRLR [Node 184] [~] [Door Lock] doorStatus: "open" => "open" [Endpoint 0]
2025-06-06 12:04:00.264 AMCNTRLR [Node 184] [~] [Door Lock] insideHandlesCanOpenDoor: false,false, [Endpoint 0] - false,false => false,false,false,false
2025-06-06 12:04:00.262 AMCNTRLR [Node 184] [~] [Door Lock] outsideHandlesCanOpenDoor: false,false [Endpoint 0] - ,false,false => false,false,false,false
2025-06-06 12:04:00.260 AMCNTRLR [Node 184] [~] [Door Lock] currentMode: 0 => 0 [Endpoint 0]
2025-06-06 12:04:00.258 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.255 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000000 (43 bytes) - 000000000000000000000
2025-06-06 12:04:00.242 AMDRIVER « [REQ] [SendDataBridge] - callback id: 140 - transmit status: OK, took 10 ms - routing attempts: 1 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -77 dBm - ACK channel no.: 1 - TX channel no.: 1
2025-06-06 12:04:00.240 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.238 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:04:00.224 AMDRIVER « [RES] [SendDataBridge] - was sent: true
2025-06-06 12:04:00.223 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.220 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:04:00.218 AMSERIAL « [ACK] (0x06)
2025-06-06 12:04:00.213 AMDRIVER » [Node 184] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x05 - ¦ callback id: 140 - +-[SecurityCCNonceReport] - nonce: 0xf75900000000b6b6
2025-06-06 12:04:00.211 AMSERIAL » 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:04:00.205 AMDRIVER « [Node 184] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -77 dBm - +-[SecurityCCNonceGet]
2025-06-06 12:04:00.203 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.202 AMSERIAL « 0x000000000000000000000000000000000000 (18 bytes)
2025-06-06 12:04:00.064 AMCNTRLR [Node 189] [Notification] - type: Access Control - event: RF lock operation
2025-06-06 12:04:00.061 AMCNTRLR [Node 189] [~] [Door Lock] currentMode: 0 => 255 [Endpoint 0]
2025-06-06 12:04:00.059 AMDRIVER « [Node 189] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -78 dBm - +-[SecurityCCCommandEncapsulation] - ¦ sequenced: false - +-[NotificationCCReport] - V1 alarm type: 24 - V1 alarm level: 1 - notification type: Access Control - notification status: 255 - notification event: RF lock operation
2025-06-06 12:04:00.057 AMCNTRLR [Node 189] [~] [Notification] alarmLevel: 1 => 1 [Endpoint 0]
2025-06-06 12:04:00.055 AMCNTRLR [Node 189] [~] [Notification] alarmType: 25 => 24 [Endpoint 0]
2025-06-06 12:04:00.052 AMSERIAL » [ACK] (0x06)
2025-06-06 12:04:00.050 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000000 (46 bytes) - 000000000000000000000000000
2025-06-06 12:03:59.959 AMDRIVER « [REQ] [SendDataBridge] - callback id: 139 - transmit status: OK, took 70 ms - repeater node IDs: 7 - routing attempts: 1 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -77 dBm - ACK RSSI on repeaters: N/A - ACK channel no.: 1 - TX channel no.: 1
2025-06-06 12:03:59.958 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:59.956 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:03:59.878 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:59.876 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:03:59.873 AMSERIAL « [ACK] (0x06)
2025-06-06 12:03:59.870 AMDRIVER » [Node 189] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x05 - ¦ callback id: 139 - +-[SecurityCCNonceReport] - nonce: 0xf04e000000000738
2025-06-06 12:03:59.869 AMSERIAL » 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:03:59.864 AMDRIVER « [REQ] [SendDataBridge] - callback id: 138 - transmit status: OK, took 20 ms - routing attempts: 1 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -77 dBm - ACK channel no.: 1 - TX channel no.: 1
2025-06-06 12:03:59.862 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:59.861 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:03:59.840 AMDRIVER « [RES] [SendDataBridge] - was sent: true
2025-06-06 12:03:59.839 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:59.838 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:03:59.835 AMSERIAL « [ACK] (0x06)
2025-06-06 12:03:59.830 AMSERIAL » 0x00000000000000000000000000000000000000000000000000000000000000000 (38 bytes) - 00000000000
2025-06-06 12:03:59.828 AMDRIVER » [Node 184] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 138 - +-[SecurityCCCommandEncapsulation] - ¦ nonce id: 210 - +-[DoorLockCCOperationGet]
2025-06-06 12:03:59.747 AMDRIVER « [Node 189] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -70 dBm - +-[SecurityCCNonceGet]
2025-06-06 12:03:59.745 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:59.729 AMDRIVER « [Node 184] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -77 dBm - +-[SecurityCCNonceReport] - nonce: 0xf3410000000065a1
2025-06-06 12:03:59.725 AMCNTRLR Failed to execute controller command after 1/3 attempts. Scheduling next try i - n 100 ms.
2025-06-06 12:03:59.724 AMSERIAL « [CAN] (0x18)
2025-06-06 12:03:59.721 AMSERIAL « 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:03:59.713 AMDRIVER » [Node 184] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 138 - +-[SecurityCCCommandEncapsulation] - ¦ nonce id: 210 - +-[DoorLockCCOperationGet]
2025-06-06 12:03:59.702 AMDRIVER « [REQ] [SendDataBridge] - callback id: 137 - transmit status: OK, took 3480 ms - routing attempts: 3 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -77 dBm - ACK channel no.: 1 - TX channel no.: 1 - beam: 1000 ms
2025-06-06 12:03:59.700 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:59.698 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:03:58.549 AMCNTRLR « [Node 184] received expected response prematurely, remembering it...
2025-06-06 12:03:58.547 AMDRIVER « [Node 184] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -77 dBm - +-[SecurityCCNonceReport] - nonce: 0xd2c6000000004442
2025-06-06 12:03:58.546 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:58.543 AMSERIAL « 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:03:57.406 AMCNTRLR « [Node 184] received expected response prematurely, remembering it...
2025-06-06 12:03:57.403 AMDRIVER « [Node 184] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -77 dBm - +-[SecurityCCNonceReport] - nonce: 0xd753000000007415
2025-06-06 12:03:57.402 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:57.400 AMSERIAL « 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:03:56.203 AMDRIVER « [RES] [SendDataBridge] - was sent: true
2025-06-06 12:03:56.200 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:56.199 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:03:56.197 AMSERIAL « [ACK] (0x06)
2025-06-06 12:03:56.192 AMDRIVER » [Node 184] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 137 - +-[SecurityCCNonceGet]
2025-06-06 12:03:56.190 AMSERIAL » 0x000000000000000000000000000000000000 (18 bytes)
2025-06-06 12:03:56.184 AMDRIVER « [REQ] [SendDataBridge] - callback id: 136 - transmit status: OK, took 110 ms - repeater node IDs: 7 - routing attempts: 1 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -79 dBm - ACK RSSI on repeaters: N/A - ACK channel no.: 1 - TX channel no.: 1
2025-06-06 12:03:56.182 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:56.180 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:03:56.070 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:56.068 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:03:56.063 AMSERIAL « [ACK] (0x06)
2025-06-06 12:03:56.059 AMDRIVER » [Node 189] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 136 - +-[SecurityCCCommandEncapsulation] - ¦ nonce id: 47 - +-[DoorLockCCOperationSet] - target mode: Secured
2025-06-06 12:03:56.056 AMSERIAL » 0x00000000000000000000000000000000000000000000000000000000000000000 (39 bytes) - 0000000000000
2025-06-06 12:03:56.053 AMDRIVER « [Node 189] [REQ] [BridgeApplicationCommand] - ¦ RSSI: -79 dBm - +-[SecurityCCNonceReport] - nonce: 0x2f6f00000000832c
2025-06-06 12:03:56.051 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:56.049 AMSERIAL « 0x0000000000000000000000000000000000000000000000000000 (26 bytes)
2025-06-06 12:03:55.978 AMDRIVER « [REQ] [SendDataBridge] - callback id: 135 - transmit status: OK, took 1370 ms - repeater node IDs: 7 - routing attempts: 1 - protocol & route speed: Z-Wave, 40 kbit/s - routing scheme: LWR - ACK RSSI: -79 dBm - ACK RSSI on repeaters: N/A - ACK channel no.: 1 - TX channel no.: 1 - route failed here: 7 -> 189
2025-06-06 12:03:55.975 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:55.974 AMSERIAL « 0x00000000000000000000000000000000000000000000000000000000000000 (31 bytes)
2025-06-06 12:03:54.596 AMDRIVER « [RES] [SendDataBridge] - was sent: true
2025-06-06 12:03:54.594 AMSERIAL » [ACK] (0x06)
2025-06-06 12:03:54.593 AMSERIAL « 0x000000000000 (6 bytes)
2025-06-06 12:03:54.589 AMSERIAL « [ACK] (0x06)
2025-06-06 12:03:54.586 AMDRIVER » [Node 189] [REQ] [SendDataBridge] - ¦ source node id: 1 - ¦ transmit options: 0x25 - ¦ callback id: 135 - +-[SecurityCCNonceGet]
2025-06-06 12:03:54.584 AMSERIAL » 0x000000000000000000000000000000000000 (18 bytes)
2025-06-06 12:03:54.580 AMDRIVER one or more queues busy

This is a screenshot of the regular logs for this event (at the top) and previous ones that show a lot more retries:

Note that on my other (Schlage) locks, they don't beep like the Yale locks, but they can take a very long time to register their changed state even though they, also, seem to actually effect the desired action right away. Locks seem to be the most troublesome devices, as related to this issue.

Can you tell if this is an issue rooted in the SiLabs firmware or if there's something else going on?

Thanks!

[jtp10181]

@rob9

I wonder if the "Beaming" process is preventing the hub from receiving messages from the devices for a period of time?

Yes. I always separate my z-wave locks out and have them last in any rules. I also use a Lock Mirror setup which does each lock one at a time and retries them itself.

[rob9]

I'm still at a loss on what's going on with z-wave locks in ZWJS.

I just did a shutdown-power off-wait-reboot on my z-wave hub.

Right now, I'm watching 2 Schlage locks, one is S0, the other S2.

I'm seeing tons of z-wave logging. The batteries keep reporting (in the log) every few minutes, but the device state isn't updating to the actual state of the real locks.

I've done refresh commands, pulled and reconnected the batteries on the locks, etc. I even see z-wave log activity that seems to show the correct state. But, the device state isn't updating to the actual state of the locks in a timely manner (they usually seem to eventually change to the proper state, but it can be a long time).

Somehow, I think the drivers may be misreading things with locks when ZWJS is used.

My Yale z-wave locks have similar issues, so it's not just a Schlage issue.

I did see some log entries about nonce errors and S2 things timing out that flew by. Also various packets being discarded because they weren't understood.

I'm hoping the next release addresses this.

Sometime just isn't quite working and it's particularly impacting locks from my experience.

@bobbyd Any thoughts? It would be helpful to get an occasional acknowledgement that issues like this are seen by the appropriate staff.

Thanks

[jtp10181]

@rob9

Somehow, I think the drivers may be misreading things with locks when ZWJS is used.

Sort of, it is probably the messages from the lock are not getting parsed correctly by the back end before they get fed to the driver.

Turn on debug logging for the device and then post a screenshot of the system logs, and text of the z-wave logs. Even if you have no idea whats going on in the logs the devs can sort it out. If you point out what timestamps correspond to any actions on the lock (like unlocking) that would also help. You can even download the zwave log to a text file and post it on pastebin.com if needed.

[rob9]

I'm working on that.

Just like your car--as soon as you have all the diagnostic tools out, it stops misbehaving.

I spent 1-2 hours trying to get my locks to sync their physical and hub states before it finally worked last night. This afternoon, they worked instantly.

Which leads me to ponder about hub load, traffic, etc,. types of issues--which means a bit more work on reproducing it.

[jtp10181]

@rob9

I spent 1-2 hours trying to get my locks to sync their physical and hub states before it finally worked last night. This afternoon, they worked instantly.

Did you reboot or shut down in there anywhere? There was issues in the past with states getting out of sync and a reboot would clear whatever cache ZWJS has going on and then it would sync back up correctly. I think it was fixed for 2.4.0 but maybe something similar is back.

@croweflight

causes the driver to step from code storage number to storage number erring out so retrying many times

Debug logs in a separate report for this would be very helpful, so staff can see what message is coming into the driver to cause the error. I assume you mean there is a red error in the logs?

[rob9]

As I said,

@rob9

I just did a shutdown-power off-wait-reboot on my z-wave hub

[rob9]

About this. A few things going on for me now (esp. being summer and all).

But, the big deal is probably 2.4.2. There were def some ZWJS issues worked on--so I wanna see if that helps (fingers crossed!!) before I spend more time on this. So, Ima pause this a bit to let that shake out.