I know this place has its share of posts on Z-Wave issues, and more it seems with Schlage locks. All the ones I can find, however, seem to be about things not working. Everything I’m about to say works…eventually. It’s just that it shouldn’t take 10 seconds.
My goal is to have my front lights turn on when I unlock the door to let the dog out (at certain times of night, but that’s not the issue) and then turn back off when I lock the door.
This was working perfectly on SmartThings before I made the jump to Home Assistant, but now there’s a delay of ~10 seconds. Same door lock, same light switch.
The setup:
- Schlage BE469ZP Connect Smart Deadbolt
- GE (Jasco) 14292 In-Wall Smart Toggle Switch
- Home Assistant 0.118.5 on Raspberry Pi 4, HassOS 4.17
- Z-Wave integration with GoControl HUSBZB-1 stick
Things I tried:
- I tried healing the network, and then looking at each node’s neighbors to map it out on paper. Everything is pretty much connected to everything. 6 total devices - 5 light switches and the lock. Each device has many neighbors - lots of ways to get from point A to point B.
- I checked the Home Assistant status of the lock after locking/unlocking. It updates in the Home Assistant UI immediately. Asking it to lock or unlock from Home Assistant is also quick.
- I checked the responsiveness of the in-wall switch in isolation. When I ask it to turn on/off from Home Assistant, it does so immediately.
- I tried removing conditions from the automation to make sure none of them were stalling the automation. No effect.
- I tried using a ZigBee button as the automation trigger. Light toggles immediately.
- I tried using the lock as the automation trigger but having it toggle the Christmas tree (on a ZigBee plug) and that was instant.
- I tried using a different Z-Wave light switch as the target of the automation. Same delay.
This led me to conclude that the problem was specifically the event from the Z-Wave lock followed by an attempt to update a Z-Wave device.
Time to go to the OZW log. I wasn’t sure if any of the byte values in the log could be used to reverse engineer the security key, so I zeroed them out. Node004 is the Schlage lock. Node003 is the light switch. Note the ##### separators (inserted by me) surrounding the Node 4 error, corresponding with a 10-second period of absolutely nothing happening.
2020-12-09 17:15:10.991 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.991 Info, Node004, Received SecurityCmd_NonceGet from node 4
2020-12-09 17:15:10.991 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.991 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.991 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.991 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.991 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.991 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.991 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.991 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.991 Info, Node004, Sending (Send) message (Callback ID=0x00, Expected Reply=0x00) - Nonce_Report - 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00:
2020-12-09 17:15:10.998 Detail, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:10.998 Detail, ZW_SEND_DATA delivered to Z-Wave stack
2020-12-09 17:15:11.019 Detail, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.020 Detail, ZW_SEND_DATA Request with callback ID 0x00 received (expected 0x00)
2020-12-09 17:15:11.048 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.048 Info, Raw: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.049 Detail, Node004, Decrypted Packet: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.049 Detail,
2020-12-09 17:15:11.049 Info, Node004, Received Alarm report: type=21, level=1, sensorSrcID=0, type:Access Control event:1, status=255
2020-12-09 17:15:11.049 Detail, Node004, Refreshed Value: old value=22, new value=21, type=byte
2020-12-09 17:15:11.049 Detail, Node004, Changes to this value are not verified
2020-12-09 17:15:11.049 Detail, Node004, Setting Encryption Flag on Message For Command Class COMMAND_CLASS_DOOR_LOCK
2020-12-09 17:15:11.049 Detail, Node004, Queuing (Send) DoorLockCmd_Get (Node=4): 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.049 Detail, Node004, Refreshed Value: old value=1, new value=1, type=byte
2020-12-09 17:15:11.049 Detail, Node004, Changes to this value are not verified
2020-12-09 17:15:11.049 Detail, Node004, Refreshed Value: old value=0, new value=0, type=byte
2020-12-09 17:15:11.049 Detail, Node004, Changes to this value are not verified
2020-12-09 17:15:11.049 Detail, Node004, Refreshed Value: old value=2, new value=1, type=byte
2020-12-09 17:15:11.049 Detail, Node004, Changes to this value are not verified
2020-12-09 17:15:11.049 Detail, Node004, Notification: ValueChanged
2020-12-09 17:15:11.055 Detail, Node004, Notification: ValueChanged
2020-12-09 17:15:11.060 Detail, Node004, Notification: ValueChanged
2020-12-09 17:15:11.065 Detail, Node004, Notification: ValueChanged
2020-12-09 17:15:11.068 Detail,
2020-12-09 17:15:11.068 Info, Node004, Processing (Send) Nonce Request message (Callback ID=0x00, Expected Reply=0x00)
2020-12-09 17:15:11.068 Info, Node004, Sending (Send) message (Callback ID=0x00, Expected Reply=0x00) - Nonce_Get(DoorLockCmd_Get) - 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00:
2020-12-09 17:15:11.073 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.073 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack
2020-12-09 17:15:11.093 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.093 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x00 received (expected 0x00)
2020-12-09 17:15:11.093 Info, Node004, Request RTT 24 Average Request RTT 61
2020-12-09 17:15:11.112 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.112 Info, Node004, Received SecurityCmd_NonceReport from node 4
2020-12-09 17:15:11.112 Info, Node004, Sending (Send) message (Callback ID=0x00, Expected Reply=0x00) - DoorLockCmd_Get (Node=4): 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.121 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.121 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack
2020-12-09 17:15:11.131 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.131 Info, Node004, Received SecurityCmd_NonceGet from node 4
2020-12-09 17:15:11.131 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.131 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.131 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.131 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.131 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.131 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.131 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.131 Info, NONCES: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.131 Info, Node004, Sending (Send) message (Callback ID=0x00, Expected Reply=0x00) - Nonce_Report - 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00:
2020-12-09 17:15:11.138 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.138 Detail, Node004, ZW_SEND_DATA delivered to Z-Wave stack
2020-12-09 17:15:11.162 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.162 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x00 received (expected 0x00)
2020-12-09 17:15:11.162 Info, Node004, Request RTT 93 Average Request RTT 77
2020-12-09 17:15:11.183 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.183 Detail, Node004, ZW_SEND_DATA Request with callback ID 0x00 received (expected 0x00)
2020-12-09 17:15:11.183 Info, Node004, Request RTT 114 Average Request RTT 95
2020-12-09 17:15:11.213 Detail, Node004, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.213 Info, Raw: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.213 Detail, Node004, Decrypted Packet: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.213 Detail,
2020-12-09 17:15:11.213 Info, Node004, Response RTT 144 Average Response RTT 228
2020-12-09 17:15:11.213 Info, Node004, Received DoorLock report: DoorLock is Secured
2020-12-09 17:15:11.213 Detail, Node004, Refreshed Value: old value=false, new value=true, type=bool
2020-12-09 17:15:11.213 Detail, Node004, Changes to this value are not verified
2020-12-09 17:15:11.213 Detail, Node004, Notification: ValueChanged
2020-12-09 17:15:11.352 Info, Node003, Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - False
2020-12-09 17:15:11.352 Info, Node003, SwitchBinary::Set - Setting node 3 to Off
2020-12-09 17:15:11.352 Detail, Node003, Queuing (Send) SwitchBinaryCmd_Set (Node=3): 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:11.352 Detail, Node003, Queuing (Send) SwitchBinaryCmd_Get (Node=3): 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
###############################################
2020-12-09 17:15:21.069 Error, Node004, ERROR: Dropping command, expected response not received after 1 attempt(s)
###############################################
2020-12-09 17:15:21.069 Detail, Node004, Removing current message
2020-12-09 17:15:21.070 Detail, Node004, Notification: Notification - TimeOut
2020-12-09 17:15:21.072 Detail,
2020-12-09 17:15:21.073 Info, Node003, Sending (Send) message (Callback ID=0x00, Expected Reply=0x00) - SwitchBinaryCmd_Set (Node=3): 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:21.078 Detail, Node003, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:21.079 Detail, Node003, ZW_SEND_DATA delivered to Z-Wave stack
2020-12-09 17:15:21.093 Detail, Node003, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:21.093 Detail, Node003, ZW_SEND_DATA Request with callback ID 0x00 received (expected 0x00)
2020-12-09 17:15:21.093 Info, Node003, Request RTT 20 Average Request RTT 20
2020-12-09 17:15:21.094 Detail, Expected callbackId was received
2020-12-09 17:15:21.094 Detail, Expected reply was received
2020-12-09 17:15:21.094 Detail, Message transaction complete
2020-12-09 17:15:21.094 Detail,
2020-12-09 17:15:21.094 Detail, Node003, Removing current message
2020-12-09 17:15:21.094 Detail,
2020-12-09 17:15:21.094 Info, Node003, Sending (Send) message (Callback ID=0x00, Expected Reply=0x00) - SwitchBinaryCmd_Get (Node=3): 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:21.100 Detail, Node003, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:21.100 Detail, Node003, ZW_SEND_DATA delivered to Z-Wave stack
2020-12-09 17:15:21.114 Detail, Node003, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:21.114 Detail, Node003, ZW_SEND_DATA Request with callback ID 0x00 received (expected 0x00)
2020-12-09 17:15:21.114 Info, Node003, Request RTT 20 Average Request RTT 20
2020-12-09 17:15:21.114 Detail, Expected callbackId was received
2020-12-09 17:15:21.124 Detail, Node003, Received: 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00
2020-12-09 17:15:21.124 Detail,
2020-12-09 17:15:21.125 Info, Node003, Response RTT 30 Average Response RTT 30
2020-12-09 17:15:21.125 Info, Node003, Received SwitchBinary report from node 3: level=Off
2020-12-09 17:15:21.125 Detail, Node003, Refreshed Value: old value=true, new value=false, type=bool
2020-12-09 17:15:21.125 Detail, Node003, Changes to this value are not verified
2020-12-09 17:15:21.125 Detail, Node003, Expected reply and command class was received
2020-12-09 17:15:21.125 Detail, Node003, Message transaction complete
2020-12-09 17:15:21.125 Detail,
2020-12-09 17:15:21.125 Detail, Node003, Removing current message
2020-12-09 17:15:21.125 Detail, Node003, Notification: ValueChanged
This is actually the second log. I did this once, and after looking at it I was like what are all these sensor values I don’t care about?
So I went to the Z-Wave Node Management and saw how the door lock exposed nearly a dozen different entities including Alarm Type, Alarm Level… For each of these I checked the Exclude this entity from Home Assistant except for the ones I cared about, the lock status and the battery level.
My hope was this would cut down on the extraneous cross-traffic, making it more likely the lock would get done allowing the light switch to get its time.
It didn’t work. The result is the log above. I forgot to keep the old one so I don’t actually know if it’s shorter or not.
So, not sure what to do, and while I can make some educated guesses from the logs, but that’s about it. The thing that really gets me is that it worked fine on SmartThings. (Of course maybe SmartThings just included the lock in insecure mode which is faster and I just never knew.)