OH3 & Schlage Locks Not Showing Secure or Responding

pillbug22 · March 27, 2021, 7:05pm

Platform information:
- Hardware: RPi3B+
- OS: Openhabian (updated 3.25.2021) (Linux/5.10.17-v8+ (aarch64))
- Java Runtime Environment: 11.0.10 (Zulu11.45+27-CA)
- openHAB version: 3.0.1 release
Issue of the topic:
Successfully ran OH2.x for a few years, and this week decided to test a migration to OH3. New SD card w/ fresh Openhabian install, not any sort of in-place upgrade from OH2 to 3. Most devices are all getting added back in without issue. Only issue so far is z-wave/Schlage locks. I have a few, but focusing on one of them, a BE469 deadbolt.

The z-wave binding scan finds the lock OK and adds the thing, and I can add the equipment to model w/ 3 channels (lock switch, raw alarm message, and battery level). However, once the lock is added, the switch does not function (does not trigger the deadbolt to move), and the alarm and battery strings never update, always stating NULL.

The thing status itself does say “Online”, just none of the channels appear to communicate. The thing properties also show other data points that seem to indicate it’s OK, such as showing several other z-wave nodes as neighbors, zwave routing and beaming are all ok, etc. Have been at this for about a day and a half, removing and added the thing a few times and letting it sit for several hours to make sure it’s not just a delay in updating.

The z-wave binding/controller → Advanced → Secure Inclusion Mode is set to Entry Control Devices, but when checking the properties for the lock “thing” itself, it shows secure mode = false. Not sure if this is preventing the correction function/updates, and what proper remediation steps would be to switch it to secure mode? I don’t remember needing to do anything special to add it under secure mode for OH2.x, but it’s been setup for so long I could have forgotten… :-/

Thanks in advance!

rpwong · March 27, 2021, 7:45pm

You need to boot up your old OH2 installation and copy the Network Security Key from the Z-Wave Serial Controller thing, then paste it into the same spot in OH3. Then remove and rediscover the Schlage lock.

Right now, security is false because OH3 generated a new security key and your lock doesn’t know it.

pillbug22 · March 31, 2021, 3:49pm

First, thank you for the suggestion. Apologies on the delay to test, but I have now

removed the deadbolt thing from OH
shut down the OH3 instance
booted back up the OH2 instance
connected to the OH2 instance, copied the security key form the z-wave binding
booted back into OH3, and pasted the key into the z-wave binding
rebooted for good measure
re-added the deadbolt as a thing
still seeing secure mode = false under the thing properties

When adding the deadbolt back as a thing, events.log:

2021-03-31 17:40:51.250 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:a4553a67ea:node12' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline
2021-03-31 17:40:51.266 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zwave:device:a4553a67ea:node12' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

Is there another log or info you might know of to check and possibly verify if there is a message along the lines of “security key mis-match” or if something else is blocking?

pillbug22 · March 31, 2021, 4:11pm

Deleted the lock thing again, bumped up the logging level to DEBUG for z-wave, and here is what the log captures when adding the lock again:

2021-03-31 18:05:46.001 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:a4553a67ea:node12.
2021-03-31 18:05:46.006 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller status changed to ONLINE.
2021-03-31 18:05:46.009 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller is ONLINE. Starting device initialisation.
2021-03-31 18:05:46.024 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties.
2021-03-31 18:05:46.029 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties. MAN=59
2021-03-31 18:05:46.031 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating node properties. MAN=59. SET. Was 59
2021-03-31 18:05:46.033 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Properties synchronised
2021-03-31 18:05:46.063 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2021-03-31 18:05:46.065 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising Thing Node...
2021-03-31 18:05:46.067 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:a4553a67ea:node12:lock_door for OnOffType
2021-03-31 18:05:46.069 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:a4553a67ea:node12:lock_door for OnOffType
2021-03-31 18:05:46.071 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:a4553a67ea:node12:alarm_raw for StringType
2021-03-31 18:05:46.073 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:a4553a67ea:node12:alarm_raw for StringType
2021-03-31 18:05:46.077 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising cmd channel zwave:device:a4553a67ea:node12:battery-level for PercentType
2021-03-31 18:05:46.079 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising state channel zwave:device:a4553a67ea:node12:battery-level for PercentType
2021-03-31 18:05:46.081 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling initialised at 1800 seconds - start in 756000 milliseconds.
2021-03-31 18:05:46.082 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Device initialisation complete.
2021-03-31 18:06:37.363 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:a4553a67ea
2021-03-31 18:06:37.366 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
2021-03-31 18:06:37.369 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2021-03-31 18:06:37.371 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 310 to queue - size 1
2021-03-31 18:06:37.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-31 18:06:37.375 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 D6 63 
2021-03-31 18:06:37.377 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 D6 63 
2021-03-31 18:06:37.381 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2021-03-31 18:06:37.382 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2021-03-31 18:06:37.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 310: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 214
2021-03-31 18:06:37.384 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-31 18:06:37.387 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-31 18:06:37.391 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 310: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 214
2021-03-31 18:06:37.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2021-03-31 18:06:37.394 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-31 18:06:37.397 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-03-31 18:06:37.470 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A D6 06 00 00 62 
2021-03-31 18:06:37.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=214, payload=D6 06 00 00 
2021-03-31 18:06:37.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=214, payload=D6 06 00 00 
2021-03-31 18:06:37.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 310: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 214
2021-03-31 18:06:37.477 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2021-03-31 18:06:37.479 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 310: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 214
2021-03-31 18:06:37.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 310: (Callback 214)
2021-03-31 18:06:37.482 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2021-03-31 18:06:37.483 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 310: callback 214
2021-03-31 18:06:37.485 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=214, payload=D6 06 00 00 
2021-03-31 18:06:37.487 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2021-03-31 18:06:37.490 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
2021-03-31 18:06:37.492 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2021-03-31 18:06:37.495 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 311 to queue - size 1
2021-03-31 18:06:37.496 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-03-31 18:06:37.498 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2021-03-31 18:06:37.500 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2021-03-31 18:06:37.501 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 310: Advanced to DONE
2021-03-31 18:06:37.503 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 119ms
2021-03-31 18:06:37.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 310: Transaction completed
2021-03-31 18:06:37.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:310 DONE
2021-03-31 18:06:37.510 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-31 18:06:37.511 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-31 18:06:37.513 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
2021-03-31 18:06:37.515 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
2021-03-31 18:06:37.518 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2021-03-31 18:06:37.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 311: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2021-03-31 18:06:37.521 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2021-03-31 18:06:37.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-31 18:06:37.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2021-03-31 18:06:37.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 311: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2021-03-31 18:06:37.529 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2021-03-31 18:06:37.531 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2021-03-31 18:06:37.533 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2021-03-31 18:06:42.523 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 311: Timeout at state WAIT_REQUEST. 3 retries remaining.
2021-03-31 18:06:42.528 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 311: Transaction is current transaction, so clearing!!!!!
2021-03-31 18:06:42.530 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 311: Transaction CANCELLED
2021-03-31 18:06:42.533 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:311 CANCELLED
2021-03-31 18:06:42.536 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-31 18:07:17.315 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Polling...
2021-03-31 18:07:24.129 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Polling...
2021-03-31 18:07:33.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Polling...
2021-03-31 18:07:48.747 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Polling...
2021-03-31 18:08:34.472 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised
2021-03-31 18:09:13.670 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling...

rpwong · March 31, 2021, 4:43pm

I’m trying to remember what I had to do when I made this same mistake upon upgrading to OH3. I think I just had to wake up the lock multiple times before the secure inclusion succeeded, but I may also have deleted the XML file for that node from the ZWave folder to give it a clean slate.

pillbug22 · March 31, 2021, 5:01pm

Good input - I started a re-initilize on the device and let it sit for a while. Didn’t seem to make a difference, so decided to remove and re-add one more time. This time, it only shows as a generic zwave device (not detecting the specific device type/model), BUT, it did add as secure, and even now allows me to set user codes.

rpwong · March 31, 2021, 7:05pm

Okay, hopefully waking it a few more times will get it to complete the process.

pillbug22 · April 1, 2021, 4:37pm

Anything special you did for your wake up process? I’ve temporarily decreased the polling interval and also done both Heal and re-initialize, but it’s still showing as generic device. I know the notes in the OH screen for the thing mention to check for device-specific wake up process, but I pulled out the user guide on the lock and didn’t see anything listed (just inclusion and exclusion).

rpwong · April 1, 2021, 4:45pm

I think I just disconnected and reconnected the battery holder.

pillbug22 · April 1, 2021, 4:47pm

Makes sense - thanks. I’ve done that, but will give it a few more tries over the rest of the day as well.

chris · April 1, 2021, 8:23pm

This device will not require waking up - it’s not a sleepy device I assume (locks don’t tend to be sleepy devices, otherwise they can’t be controlled).

pillbug22 · April 2, 2021, 10:09pm

Removed and re-added the front door lock again, still same. It added as secure, but still not detected by device model, which means also no channels available when adding as equipment.

I have been able to add our back door lock (same deadbolt), and it works correctly. Secure connection, detected manufacturer/model, able to add as equipment with all 3 channels.

Starting to think it’s “stuck” somewhere I might need to try and completely remove/re-add it to the controller?

kjssaari · April 4, 2021, 2:47pm

I’m having the same problem with a Yale 220 Zwave lock. Fresh install of OH3 rather than migrating, the lock is found and shows as ‘Online’ but is not controllable, does not update the controller when something happens, and the channels show NULL.

I went back to my OH2 instance and excluded the device from the controller so I could bring it back in fresh but it still gives me the same issue. Mine is still shows as ‘zwave_secure=false’ though.

I’ll let you know if I have any luck, glad to see I’m not alone!

pillbug22 · April 5, 2021, 7:18pm

I’m pretty sure @rpwong 's comment above got me to where our locks connect now as secure - needing to copy the security key over. However, I would think that if you excluded it from the controller on OH2, including it under OH3 should be acting as a new device and just use whatever security key was generated on your OH3 instance.

I still haven’t been able to get 1 of our 2 working fully. The back door lock is connected all the way without any issues, but the front door lock continues to be a generic z-wave device. I might try excluding and starting fresh with it.

Good part about starting fresh on OH3 was I could go back to OH2 pretty easily and was able to do screenshots of all the z-wave devices to know which node was what, and then even mark down all the user codes we had configured on the lock some can add them back if excluding and adding it back does the trick.

rpwong · April 5, 2021, 10:51pm

Yep, if you exclude the device, then the network security key no longer matters.

Out of curiousity, when you go back to OH2 do both of your locks work? If so, then I’d suggest starting OH3 over with a new SD card to see if you can get the lock to be recognized off the bat (with the network security key in place). If so, it’s relatively easy to copy over your configuration from your “old” OH3.

If the lock doesn’t work in the new instance, then that tells us something else is up.

kjssaari · April 7, 2021, 4:26pm

Thank you for the thought starter on OH2 still controlling the lock! I was thinking excluding the device from OH2 and giving it a fresh inclusion in OH3 would adopt the new Network Security Key but this is not the case.

Everything works nicely after: Excluding the device, copying over the OH2 Security Key, Including the device again.

pillbug22 · April 27, 2021, 8:33pm

Finally back around to working on this. I did an exclude on the trouble lock, then re-included it. The good news it that is now correctly shows up in OH as the correct device and model number instead of generic device. Now just some patience and tinkering to get it to show up as “secure” again.

cailleute · February 5, 2022, 5:31pm

I have two Locks. Same issue, both were included without “secure”. The trick for me was first to change the security key for the one running on OH2, as @rpwong said. After that I had to Reinitialise the device by the way of the UI and finally remove the Thing and include it again. Work for both lock at first attemp.