Baldwin door lock: interpreting z-wave errors and not updating state

Configuration Z-Wave
1

zwave-js-ui: 9.33.0
zwave-js: 14.3.12

I have an automation that locks a door. The door is physically locking, but the state frequently is not updated.

I need help understanding what the logs are saying. The automation reports that it locked the door at 21:31:22Z. Then the automation delays 30 seconds and then checks if the state is not locked. That happens at 21:31:53Z.

Automation snippet 
          - metadata: {}
            data: {}
            target:
              entity_id: lock.front_door_deadbolt
            action: lock.lock
          - metadata: {}
            data:
              message: Front door locking.
              title: Left unlocked?
            action: notify.our_phones
          - delay:
              hours: 0
              minutes: 0
              seconds: 30
              milliseconds: 0
          - alias: >-
              After locking and a delay, check that it is reported as being
              locked.
            if:
              - alias: Check if door is still not locked and then notify
                condition: not
                conditions:
                  - condition: state
                    entity_id: lock.front_door_deadbolt
                    state: locked
            then:
              - metadata: {}
                data:
                  message: The front door didn't lock
                  title: Ruh Roh!
                action: notify.our_phones

Again, the physical door did lock. But the state still reports unlocked:

image
image1764×286 28.9 KB

Here’s what I can find in the zwave logs. I don’t always know if a log line is related to a given node.

I would like to understand what the logs are indicating, and if they are providing me with any hints to solve the issue.

2025-04-01T21:31:22.029Z DRIVER .. [Node 004] [REQ] [SendDataBridge]
                                  ... source node id:   1
                                  ... transmit options: 0x25
                                  ... callback id:      114
                                  ......[SecurityCCNonceGet]
2025-04-01T21:31:22.034Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:22.037Z SERIAL .. 0x010401a90152                                                       (6 bytes)
2025-04-01T21:31:22.038Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:22.040Z DRIVER .. [RES] [SendDataBridge]
                                    was sent: true
2025-04-01T21:31:22.329Z SERIAL .. 0x012400a80000010030169f0340008eb64908f58cc6f344c65a2b9b927227871a0 (38 bytes)
                                  0a7007f7f28

2025-04-01T21:31:23.408Z DRIVER .. [Node 004] [REQ] [BridgeApplicationCommand]
                                  ... RSSI: -78 dBm
                                  ......[SecurityCCNonceReport]
                                      nonce: 0xeba29a629872544e
2025-04-01T21:31:23.416Z SERIAL .. 0x012500a90001000417988118a28172f3a2ca2b35f6cf85eb0020cb0eb6b17e992 (39 bytes)
                                  50000000073b0
2025-04-01T21:31:23.418Z DRIVER .. [Node 004] [REQ] [SendDataBridge]
                                  ... source node id:   1
                                  ... transmit options: 0x25
                                  ... callback id:      115
                                  ......[SecurityCCCommandEncapsulation]
                                    ... nonce id: 235
                                    ......[DoorLockCCOperationSet]
                                        target mode: Secured
2025-04-01T21:31:23.426Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:23.430Z SERIAL .. 0x010401a90152                                                       (6 bytes)
2025-04-01T21:31:23.431Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:23.432Z DRIVER .. [RES] [SendDataBridge]
                                    was sent: true

I assume that last one is the command to lock the door. Next, it looks like the door (Node 004) is reporting its RSSI.

2025-04-01T21:31:28.712Z DRIVER .. [Node 004] [REQ] [BridgeApplicationCommand]
                                  ... RSSI: -79 dBm
                                  ......[SecurityCCNonceGet]
2025-04-01T21:31:28.719Z DRIVER   one or more queues busy
2025-04-01T21:31:28.721Z SERIAL .. 0x011800a9000100040a9880d7c06db71622cab2050000000074a9              (26 bytes)
2025-04-01T21:31:28.722Z DRIVER .. [Node 004] [REQ] [SendDataBridge]
                                  ... source node id:   1
                                  ... transmit options: 0x05
                                  ... callback id:      116
                                  ......[SecurityCCNonceReport]
                                      nonce: 0xd7c06db71622cab2
2025-04-01T21:31:28.727Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:28.730Z SERIAL .. 0x010401a90152                                                       (6 bytes)
2025-04-01T21:31:28.732Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:28.733Z DRIVER .. [RES] [SendDataBridge]
                                    was sent: true
2025-04-01T21:31:30.057Z SERIAL .. 0x012400a81400010030169f0340008eb64908f58cc6f344c65a2b9b927227871a0 (38 bytes)
                                  0b200000029

But then it gives what seems to be an error, and I assume because it’s invalid it doesn’t know what node sent it?

2025-04-01T21:31:30.062Z DRIVER   Dropping message with invalid payload

Then it continues and there’s more errors.

2025-04-01T21:31:33.224Z DRIVER .. [Node 004] [REQ] [SendDataBridge]
                                  ... source node id:   1
                                  ... transmit options: 0x25
                                  ... callback id:      117
                                  ......[SecurityCCNonceGet]
2025-04-01T21:31:33.230Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:33.232Z SERIAL .. 0x010401a90152                                                       (6 bytes)
2025-04-01T21:31:33.233Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:33.234Z DRIVER .. [RES] [SendDataBridge]
                                    was sent: true
2025-04-01T21:31:36.959Z SERIAL .. 0x012800a800000100521a9f0373003fd40357d8c86ab91782e06cada000168bfd7 (42 bytes)
                                  5eba00500b2007f7f58
2025-04-01T21:31:36.968Z SERIAL .. [ACK]                                                                   (0x06)

2025-04-01T21:31:37.724Z DRIVER .. [Node 004] [REQ] [BridgeApplicationCommand]
                                  ... RSSI: -90 dBm
                                  ......[SecurityCCCommandEncapsulation] [INVALID]
                                      error: Nonce 0xd7 expired, cannot decode security encapsulated command.
2025-04-01T21:31:37.725Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:37.868Z SERIAL .. 0x012800a800000100521a9f0373003fd40357d8c86ab91782e06cada000168bfd7 (42 bytes)
                                  5eba00500ab007f7f41
2025-04-01T21:31:37.875Z DRIVER   Dropping message with invalid payload
2025-04-01T21:31:37.724Z DRIVER .. [Node 004] [REQ] [BridgeApplicationCommand]
                                  ... RSSI: -90 dBm
                                  ......[SecurityCCCommandEncapsulation] [INVALID]
                                      error: Nonce 0xd7 expired, cannot decode security encapsulated command.
2025-04-01T21:31:37.725Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:37.868Z SERIAL .. 0x012800a800000100521a9f0373003fd40357d8c86ab91782e06cada000168bfd7 (42 bytes)
                                  5eba00500ab007f7f41
2025-04-01T21:31:37.875Z DRIVER   Dropping message with invalid payload
2025-04-01T21:31:37.724Z DRIVER .. [Node 004] [REQ] [BridgeApplicationCommand]
                                  ... RSSI: -90 dBm
                                  ......[SecurityCCCommandEncapsulation] [INVALID]
                                      error: Nonce 0xd7 expired, cannot decode security encapsulated command.
2025-04-01T21:31:37.725Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:37.868Z SERIAL .. 0x012800a800000100521a9f0373003fd40357d8c86ab91782e06cada000168bfd7 (42 bytes)
                                  5eba00500ab007f7f41
2025-04-01T21:31:37.875Z DRIVER   Dropping message with invalid payload
                                                              (0x06)
2025-04-01T21:31:38.145Z SERIAL .. 0x011800a800000100040a9880b23eca5a7134f80700b2007f7f4c              (26 bytes)
2025-04-01T21:31:38.150Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:38.154Z DRIVER .. [Node 004] [REQ] [BridgeApplicationCommand]
                                  ... RSSI: -78 dBm
                                  ......[SecurityCCNonceReport]
                                      nonce: 0xb23eca5a7134f807
2025-04-01T21:31:38.157Z CNTRLR .. [Node 004] received expected response prematurely, remembering it...
2025-04-01T21:31:38.575Z SERIAL .. 0x011800a800000100040a9880b23eca5a7134f80700b1007f7f4f              (26 bytes)
2025-04-01T21:31:38.580Z SERIAL .. [ACK]                                                                   (0x06)
2025-04-01T21:31:38.584Z DRIVER .. [Node 004] [REQ] [BridgeApplicationCommand]
                                  ... RSSI: -79 dBm
                                  ......[SecurityCCNonceReport]
                                      nonce: 0xb23eca5a7134f807
2025-04-01T21:31:38.587Z CNTRLR .. [Node 004] received expected response prematurely, remembering it...

I do seem to get a series of:

[Node 004] received expected response prematurely, remembering it...

and

2025-04-01T21:32:05.241Z CNTRLR   [Node 004] Timed out while waiting for a response from the node (ZW0201)

Any ideas?

Thanks.

2

Is your lock node4?

Yourlock >> Device info >> 3dots next to configure

Look at stats and provide those details

3

Yes, node 004 as in the logs.

image
image970×1110 46.7 KB

Here’s stats on the “Hallway Lights”:

image
image928×756 33.6 KB

And the nice graph:

image
image688×1002 24.8 KB

4

Maybe try rebuild route on lock

What type of light is it connecting with? Is this bulb in recessed housing or enclosure made with metal?

5

Thanks for taking time to respond. To answer your question:

The “Hall Lights” is a Zooz wall switch, in a plastic wall box. Rebuilding doesn’t change the routing – those Hall Lights (switch) is line-of-sight to the door lock, and almost the same to the controller. A logical hop. Other z-wave devices use the Hall Lights as their hop.

Looking at stats of other devices the ratio of dropped RX to received is similar with other devices that seem to be working fine.

Note that the lock is battery operated, and I have no idea how old (or good) its z-wave radio and code is compared to newer devices. The round-trip-time seems very high, but is that due to slow, underpowered hardware in the lock or a network issue? Or maybe the device is just not reporing its new state and instead going back to sleep. All wild guess. I only have logs to give me a hint.

I’m very curious what the message in the zwave logs mean. Maybe due to the RTT being long the z-wave driver (or the ZST39 controller) is timing-out too early?

Unclear if this setting only applies to inclusion.

image
image1192×150 8.89 KB

Or what “error: Nonce 0xd7 expired, cannot decode security encapsulated command” means – is that another timeout issue?

I’ve got about 80 z-wave devices, and it appears that “error: Nonce” error is always with Node 004:

root@a0d7b954-zwavejs2mqtt:/data/store/logs$ zcat zwavejs_2025-04-01.log.gz | grep -B 4 'error: Nonce' | grep 'Node '
2025-04-01T15:09:52.099Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-01T15:09:52.226Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-01T19:05:36.020Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-01T19:05:36.630Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-01T19:05:36.700Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-01T21:31:37.724Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-02T01:25:28.805Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-02T01:25:29.691Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-02T01:25:30.129Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-02T01:26:35.437Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-02T01:26:35.971Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-02T02:05:36.031Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]
2025-04-02T02:11:00.421Z DRIVER « [Node 004] [REQ] [BridgeApplicationCommand]

Perhaps this is a better question for the zwave-js github discussion list, as it’s not really an HA issue.

6

Locks are typically Z-wave FLIRS devices (Frequently Listening Routing Slave). They wake every second. Google has a lot of good information like this Controlling FLiRS via Associations – DrZWave

7

Yeah

Maybe ask at zwavejs GitHub

RTT is high but other than that all looks OK. I’m guessing it’s timing out while communicating since I think one of the log messages said “time out”. Did these problems just start?

What’s battery %?
Maybe replace battery :person_shrugging:

8

I considered the battery. It’s a 40%, but w/o any measurements (radio strength?) who knows what that means?

And w/o any changes (battery or otherwise) my RTT is now showing much better. Although I don’t know over what time period that RTT is averaging.

image
image1074×138 4.62 KB

All so hard w/o a way to measure. I added counters to track how often the door is instructed to lock and how often HA does not show it locked after a timeout. But, sample size is so small (a few locks per day)… Learning a tool like Zniffer might be a wise investment in time.

Trying to understand the logs better is probably the best way forward – or changing the batteries and ignoring it…

Thanks,

9

With improved RTT did errors go away?

Some of my battery devices become weird under 40% battery.