ZWave secure lock inclusion after upgrade - not adding securely

bdm · August 24, 2020, 8:18pm

CIrcumstance: recently upgraded to OH 2.5.7, most of the zwave devices continue to work, but none of my schlage BE469 zwave locks worked (all of my battery sensors and wired light switches work, though).
I figured it was due a likely binding change, and so excluded one of the locks and re-included it.
Unfortunately, while the lock re-included, it was not secured (per the attributes) - this is in contrast to the other (old) BE469 lock profiles.
The batterhy level updates, but the lock status doesn’t change when I manually toggle the lock, nor can I lock/unlock the device from PaperUI or HabMin. I am assuming this is due to the security class not being used.
I have sat beside the lock and toggled it locked/unlocked manually several times to allow the device to be awoken multiple times for full inclusion. I then removed the device and re-included it with debug logging. Still the locking channel doesn’t seem to work. Looking at the log, my read is that it seems that OH thinks the device doesn’t need secure inclusion. All the device details should be in the log.

2020-08-24 12:45:36.069 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - NODE 42: Adding slave.
2020-08-24 12:45:36.075 [DEBUG] [al.protocol.ZWaveInclusionController] - NODE 42: Including node.
2020-08-24 12:46:22.387 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - NODE 42: Add Node: Protocol done.
2020-08-24 12:46:22.393 [DEBUG] [al.protocol.ZWaveInclusionController] - NODE 42: Inclusion protocol completed.
2020-08-24 12:46:22.394 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2020-08-24 12:46:22.395 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2020-08-24 12:46:22.397 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Version = 1, version set. Enabling extra functionality.
2020-08-24 12:46:22.398 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2020-08-24 12:46:22.399 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Creating new instance of command class COMMAND_CLASS_BASIC
2020-08-24 12:46:22.400 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2020-08-24 12:46:22.401 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2020-08-24 12:46:22.402 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Creating new instance of command class COMMAND_CLASS_APPLICATION_STATUS
2020-08-24 12:46:22.403 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Command class COMMAND_CLASS_APPLICATION_STATUS, endpoint 0 created
2020-08-24 12:46:22.404 [DEBUG] [al.protocol.ZWaveInclusionController] - NODE 42: Inclusion is adding command class COMMAND_CLASS_APPLICATION_STATUS.
2020-08-24 12:46:22.405 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Adding command class COMMAND_CLASS_APPLICATION_STATUS to the list of supported command classes.
2020-08-24 12:46:22.406 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Creating new instance of command class COMMAND_CLASS_MANUFACTURER_SPECIFIC
2020-08-24 12:46:22.407 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created
2020-08-24 12:46:22.408 [DEBUG] [al.protocol.ZWaveInclusionController] - NODE 42: Inclusion is adding command class COMMAND_CLASS_MANUFACTURER_SPECIFIC.
2020-08-24 12:46:22.409 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Adding command class COMMAND_CLASS_MANUFACTURER_SPECIFIC to the list of supported command classes.
2020-08-24 12:46:22.410 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Creating new instance of command class COMMAND_CLASS_FIRMWARE_UPDATE_MD
2020-08-24 12:46:22.411 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created
2020-08-24 12:46:22.412 [DEBUG] [al.protocol.ZWaveInclusionController] - NODE 42: Inclusion is adding command class COMMAND_CLASS_FIRMWARE_UPDATE_MD.
2020-08-24 12:46:22.413 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Adding command class COMMAND_CLASS_FIRMWARE_UPDATE_MD to the list of supported command classes.
2020-08-24 12:46:22.414 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Creating new instance of command class COMMAND_CLASS_SECURITY
2020-08-24 12:46:22.415 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Command class COMMAND_CLASS_SECURITY, endpoint 0 created
2020-08-24 12:46:22.416 [DEBUG] [al.protocol.ZWaveInclusionController] - NODE 42: Inclusion is adding command class COMMAND_CLASS_SECURITY.
2020-08-24 12:46:22.417 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 42: Updated networkKey
2020-08-24 12:46:22.418 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 42: setupNetworkKey useSchemeZero=false
2020-08-24 12:46:22.420 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Adding command class COMMAND_CLASS_SECURITY to the list of supported command classes.
2020-08-24 12:46:22.421 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Creating new instance of command class COMMAND_CLASS_VERSION
2020-08-24 12:46:22.422 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Command class COMMAND_CLASS_VERSION, endpoint 0 created
2020-08-24 12:46:22.423 [DEBUG] [al.protocol.ZWaveInclusionController] - NODE 42: Inclusion is adding command class COMMAND_CLASS_VERSION.
2020-08-24 12:46:22.424 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Adding command class COMMAND_CLASS_VERSION to the list of supported command classes.
2020-08-24 12:46:22.426 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 42: ZWaveController include node
2020-08-24 12:46:22.426 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Starting initialisation from INCLUSION_START
2020-08-24 12:46:22.428 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: Node just included (3386811)
2020-08-24 12:46:22.430 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer - advancing to IDENTIFY_NODE
2020-08-24 12:46:22.432 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: Initialisation starting from inclusion
2020-08-24 12:46:30.020 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: ProtocolInfo
2020-08-24 12:46:30.022 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: Listening = false
2020-08-24 12:46:30.048 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: Routing   = true
2020-08-24 12:46:30.055 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: Beaming   = true
2020-08-24 12:46:30.068 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: Version   = 4
2020-08-24 12:46:30.072 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: FLIRS     = true
2020-08-24 12:46:30.078 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: Security  = false
2020-08-24 12:46:30.081 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: Max Baud  = 40000
2020-08-24 12:46:30.083 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: Basic    = BASIC_TYPE_ROUTING_SLAVE
2020-08-24 12:46:30.085 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: Generic  = GENERIC_TYPE_ENTRY_CONTROL
2020-08-24 12:46:30.087 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 42: Specific = SPECIFIC_TYPE_SECURE_KEYPAD_DOOR_LOCK
2020-08-24 12:46:30.090 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
2020-08-24 12:46:30.092 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
2020-08-24 12:46:30.095 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Version = 1, version set. Enabling extra functionality.
2020-08-24 12:46:30.097 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
2020-08-24 12:46:30.100 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Creating new instance of command class COMMAND_CLASS_BASIC
2020-08-24 12:46:30.102 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Command class COMMAND_CLASS_BASIC, endpoint 0 created
2020-08-24 12:46:30.104 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
2020-08-24 12:46:30.138 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1e0205c
2020-08-24 12:46:30.140 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init transaction completed with response COMPLETE
2020-08-24 12:46:30.308 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 42: Device discovered
2020-08-24 12:46:31.142 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer - advancing to SECURITY_REPORT
2020-08-24 12:46:31.144 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 42: Updated networkKey
2020-08-24 12:46:31.146 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 42: setupNetworkKey useSchemeZero=false
2020-08-24 12:46:31.148 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Performing secure inclusion.
2020-08-24 12:46:31.150 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: SECURITY_INC State=GET_SCHEME
2020-08-24 12:46:31.156 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: ZWaveCommandClassTransactionPayload - send to node
2020-08-24 12:46:31.158 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY check internal
2020-08-24 12:46:31.160 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Command Class COMMAND_CLASS_SECURITY is NOT required to be secured
2020-08-24 12:46:31.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@1dfbf38
2020-08-24 12:46:31.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Bump transaction 537 priority from Immediate to Immediate
2020-08-24 12:46:31.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Adding to device queue
2020-08-24 12:46:31.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Added 537 to queue - size 32
2020-08-24 12:46:35.394 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 42: Sending REQUEST Message = 01 0A 00 13 2A 03 98 04 00 25 E7 91
2020-08-24 12:46:35.470 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: sentData successfully placed on stack.
2020-08-24 12:46:35.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 537: Transaction not completed
2020-08-24 12:46:35.504 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: SendData Request. CallBack ID = 231, Status = Transmission complete and ACK received(0)
2020-08-24 12:46:35.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 537: Transaction not completed
2020-08-24 12:46:40.506 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 42: TID 537: Timeout at state WAIT_DATA. 3 retries remaining.
2020-08-24 12:46:40.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: notifyTransactionResponse TID:537 CANCELLED
2020-08-24 12:46:40.513 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@dd2a67
2020-08-24 12:46:40.514 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: No data from device, but it was ACK'd. Possibly not supported? (Try 0)
2020-08-24 12:46:40.516 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: ZWaveCommandClassTransactionPayload - send to node
2020-08-24 12:46:40.519 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY check internal
2020-08-24 12:46:40.520 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Command Class COMMAND_CLASS_SECURITY is NOT required to be secured
2020-08-24 12:46:40.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@1dfbf38
2020-08-24 12:46:40.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Bump transaction 540 priority from Immediate to Immediate
2020-08-24 12:46:40.552 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Adding to device queue
2020-08-24 12:46:40.554 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Added 540 to queue - size 32
2020-08-24 12:46:48.846 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 42: Sending REQUEST Message = 01 0A 00 13 2A 03 98 04 00 25 E9 9F
2020-08-24 12:46:48.894 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: sentData successfully placed on stack.
2020-08-24 12:46:48.897 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 540: Transaction not completed
2020-08-24 12:46:50.220 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: SendData Request. CallBack ID = 233, Status = Transmission complete and ACK received(0)
2020-08-24 12:46:50.223 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 540: Transaction not completed
2020-08-24 12:46:55.223 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 42: TID 540: Timeout at state WAIT_DATA. 3 retries remaining.
2020-08-24 12:46:55.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: notifyTransactionResponse TID:540 CANCELLED
2020-08-24 12:46:55.229 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init response (1) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1352820
2020-08-24 12:46:55.230 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: No data from device, but it was ACK'd. Possibly not supported? (Try 1)
2020-08-24 12:46:55.232 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: timed out after 24075914095 / 20000000000
2020-08-24 12:46:55.233 [INFO ] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: SECURITY_INC State=FAILED, Reason=GET_SCHEME
2020-08-24 12:46:55.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer - advancing to MANUFACTURER
2020-08-24 12:46:55.237 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: MANUFACTURER - send ManufacturerSpecific
2020-08-24 12:46:55.238 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 42: Creating new message for command MANUFACTURER_SPECIFIC_GET
2020-08-24 12:46:55.243 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: ZWaveCommandClassTransactionPayload - send to node
2020-08-24 12:46:55.245 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_MANUFACTURER_SPECIFIC
2020-08-24 12:46:55.247 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Command Class COMMAND_CLASS_MANUFACTURER_SPECIFIC is NOT required to be secured
2020-08-24 12:46:55.252 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@10b149a
2020-08-24 12:46:55.255 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Bump transaction 541 priority from Config to Immediate
2020-08-24 12:46:55.262 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Adding to device queue
2020-08-24 12:46:55.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Added 541 to queue - size 32
2020-08-24 12:46:59.233 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: MANUFACTURER not set
2020-08-24 12:46:59.235 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Controller status changed to ONLINE.
2020-08-24 12:46:59.237 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Controller is ONLINE. Starting device initialisation.
2020-08-24 12:46:59.479 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Updating node properties.
2020-08-24 12:46:59.480 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Updating node properties. MAN=2147483647
2020-08-24 12:46:59.483 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Properties synchronised
2020-08-24 12:46:59.492 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Initialising Thing Node...
2020-08-24 12:46:59.494 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Polling initialised at 1800 seconds - start in 111600 milliseconds.
2020-08-24 12:46:59.495 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Device initialisation complete.
2020-08-24 12:47:02.085 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 42: Sending REQUEST Message = 01 09 00 13 2A 02 72 04 25 EC 72
2020-08-24 12:47:02.166 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: sentData successfully placed on stack.
2020-08-24 12:47:02.170 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 541: Transaction not completed
2020-08-24 12:47:03.447 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: SendData Request. CallBack ID = 236, Status = Transmission complete and ACK received(0)
2020-08-24 12:47:03.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 541: Transaction not completed
2020-08-24 12:47:03.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Application Command Request (ALIVE:MANUFACTURER)
2020-08-24 12:47:03.457 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Incoming command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0
2020-08-24 12:47:03.458 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_MANUFACTURER_SPECIFIC
2020-08-24 12:47:03.459 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Received COMMAND_CLASS_MANUFACTURER_SPECIFIC V0 MANUFACTURER_SPECIFIC_REPORT
2020-08-24 12:47:03.461 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 42: Manufacturer ID = 0x3b
2020-08-24 12:47:03.462 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 42: Device Type     = 0x6341
2020-08-24 12:47:03.463 [DEBUG] [WaveManufacturerSpecificCommandClass] - NODE 42: Device ID       = 0x5044
2020-08-24 12:47:03.465 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Commands processed 1.
2020-08-24 12:47:03.466 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@128b7c9.
2020-08-24 12:47:03.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@128b7c9.
2020-08-24 12:47:03.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: notifyTransactionResponse TID:541 DONE
2020-08-24 12:47:03.470 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-08-24 12:47:03.475 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@109487c
2020-08-24 12:47:03.478 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init transaction completed with response COMPLETE
2020-08-24 12:47:03.480 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer - advancing to APP_VERSION
2020-08-24 12:47:03.481 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2020-08-24 12:47:03.483 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: APP_VERSION - send VersionMessage
2020-08-24 12:47:03.485 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Creating new message for command VERSION_GET
2020-08-24 12:47:03.486 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: ZWaveCommandClassTransactionPayload - send to node
2020-08-24 12:47:03.490 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_VERSION
2020-08-24 12:47:03.492 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Command Class COMMAND_CLASS_VERSION is NOT required to be secured
2020-08-24 12:47:03.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@f2d528
2020-08-24 12:47:03.502 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Bump transaction 542 priority from Config to Immediate
2020-08-24 12:47:03.512 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Adding to device queue
2020-08-24 12:47:03.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Added 542 to queue - size 31
2020-08-24 12:47:10.253 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 42: Sending REQUEST Message = 01 09 00 13 2A 02 86 11 25 EE 91
2020-08-24 12:47:10.319 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: sentData successfully placed on stack.
2020-08-24 12:47:10.323 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 542: Transaction not completed
2020-08-24 12:47:11.544 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: SendData Request. CallBack ID = 238, Status = Transmission complete and ACK received(0)
2020-08-24 12:47:11.548 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 542: Transaction not completed
2020-08-24 12:47:11.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Application Command Request (ALIVE:APP_VERSION)
2020-08-24 12:47:11.658 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Incoming command class COMMAND_CLASS_VERSION, endpoint 0
2020-08-24 12:47:11.660 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_VERSION
2020-08-24 12:47:11.661 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Received COMMAND_CLASS_VERSION V0 VERSION_REPORT
2020-08-24 12:47:11.663 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Process Version Report
2020-08-24 12:47:11.664 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Library Type        = 6 (Routing Slave)
2020-08-24 12:47:11.666 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Protocol Version    = 3.42
2020-08-24 12:47:11.667 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Application Version = 128.22
2020-08-24 12:47:11.669 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Commands processed 1.
2020-08-24 12:47:11.671 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@c660ca.
2020-08-24 12:47:11.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@c660ca.
2020-08-24 12:47:11.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: notifyTransactionResponse TID:542 DONE
2020-08-24 12:47:11.676 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-08-24 12:47:11.680 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@de86be
2020-08-24 12:47:11.682 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init transaction completed with response COMPLETE
2020-08-24 12:47:11.684 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer - advancing to DISCOVERY_COMPLETE
2020-08-24 12:47:11.686 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 42: Device discovery completed
2020-08-24 12:47:11.695 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 42: Device discovery resolved to thingType zwave:schlage_be469_00_000
2020-08-24 12:47:11.735 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2020-08-24 12:47:11.736 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 42: Serialise aborted as static stages not complete
2020-08-24 12:47:11.738 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer - advancing to VERSION
2020-08-24 12:47:11.739 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveInitializationStateEvent
2020-08-24 12:47:11.761 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: VERSION - checking COMMAND_CLASS_SECURITY, version is 0
2020-08-24 12:47:11.762 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: VERSION - queued   COMMAND_CLASS_SECURITY
2020-08-24 12:47:11.764 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Creating new message for application command VERSION_COMMAND_CLASS_GET command class COMMAND_CLASS_SECURITY
2020-08-24 12:47:11.766 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: ZWaveCommandClassTransactionPayload - send to node
2020-08-24 12:47:11.768 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_VERSION
2020-08-24 12:47:11.770 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Command Class COMMAND_CLASS_VERSION is NOT required to be secured
2020-08-24 12:47:11.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@104e97b
2020-08-24 12:47:11.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Bump transaction 546 priority from Config to Immediate
2020-08-24 12:47:11.776 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Adding to device queue
2020-08-24 12:47:11.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Added 546 to queue - size 32
2020-08-24 12:47:25.415 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 42: Sending REQUEST Message = 01 0A 00 13 2A 03 86 13 98 25 F3 14
2020-08-24 12:47:25.488 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: sentData successfully placed on stack.
2020-08-24 12:47:25.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 546: Transaction not completed
2020-08-24 12:47:26.743 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: SendData Request. CallBack ID = 243, Status = Transmission complete and ACK received(0)
2020-08-24 12:47:26.748 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 546: Transaction not completed
2020-08-24 12:47:26.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Application Command Request (ALIVE:VERSION)
2020-08-24 12:47:26.765 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Incoming command class COMMAND_CLASS_VERSION, endpoint 0
2020-08-24 12:47:26.766 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_VERSION
2020-08-24 12:47:26.768 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Received COMMAND_CLASS_VERSION V0 VERSION_COMMAND_CLASS_REPORT
2020-08-24 12:47:26.769 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Process Version Command Class Report
2020-08-24 12:47:26.771 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Requested Command Class = COMMAND_CLASS_SECURITY, Version = 1
2020-08-24 12:47:26.772 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Version = 1, version set. Enabling extra functionality.
2020-08-24 12:47:26.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Commands processed 1.
2020-08-24 12:47:26.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@c588d3.
2020-08-24 12:47:26.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@c588d3.
2020-08-24 12:47:26.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: notifyTransactionResponse TID:546 DONE
2020-08-24 12:47:26.781 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-08-24 12:47:26.784 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@d018f
2020-08-24 12:47:26.785 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init transaction completed with response COMPLETE
2020-08-24 12:47:26.787 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: VERSION - checking COMMAND_CLASS_BASIC, version is 0
2020-08-24 12:47:26.788 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: VERSION - queued   COMMAND_CLASS_BASIC
2020-08-24 12:47:26.789 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Creating new message for application command VERSION_COMMAND_CLASS_GET command class COMMAND_CLASS_BASIC
2020-08-24 12:47:26.791 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: ZWaveCommandClassTransactionPayload - send to node
2020-08-24 12:47:26.792 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_VERSION
2020-08-24 12:47:26.793 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Command Class COMMAND_CLASS_VERSION is NOT required to be secured
2020-08-24 12:47:26.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@bccd73
2020-08-24 12:47:26.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Bump transaction 550 priority from Config to Immediate
2020-08-24 12:47:26.831 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Adding to device queue
2020-08-24 12:47:26.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Added 550 to queue - size 31
2020-08-24 12:47:33.719 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 42: Sending REQUEST Message = 01 0A 00 13 2A 03 86 13 20 25 F6 A9
2020-08-24 12:47:33.787 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: sentData successfully placed on stack.
2020-08-24 12:47:33.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 550: Transaction not completed
2020-08-24 12:47:35.054 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: SendData Request. CallBack ID = 246, Status = Transmission complete and ACK received(0)
2020-08-24 12:47:35.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 550: Transaction not completed
2020-08-24 12:47:35.092 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Application Command Request (ALIVE:VERSION)
2020-08-24 12:47:35.094 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Incoming command class COMMAND_CLASS_VERSION, endpoint 0
2020-08-24 12:47:35.095 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_VERSION
2020-08-24 12:47:35.096 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Received COMMAND_CLASS_VERSION V0 VERSION_COMMAND_CLASS_REPORT
2020-08-24 12:47:35.098 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Process Version Command Class Report
2020-08-24 12:47:35.100 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Requested Command Class = COMMAND_CLASS_BASIC, Version = 1
2020-08-24 12:47:35.101 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 42: Version = 1, version set. Enabling extra functionality.
2020-08-24 12:47:35.103 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Commands processed 1.
2020-08-24 12:47:35.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@e78840.
2020-08-24 12:47:35.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@e78840.
2020-08-24 12:47:35.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: notifyTransactionResponse TID:550 DONE
2020-08-24 12:47:35.109 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-08-24 12:47:35.111 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@874fac
2020-08-24 12:47:35.112 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init transaction completed with response COMPLETE
2020-08-24 12:47:35.113 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: VERSION - checking COMMAND_CLASS_APPLICATION_STATUS, version is 0
2020-08-24 12:47:35.115 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node advancer: VERSION - queued   COMMAND_CLASS_APPLICATION_STATUS
2020-08-24 12:47:35.116 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 42: Creating new message for application command VERSION_COMMAND_CLASS_GET command class COMMAND_CLASS_APPLICATION_STATUS
2020-08-24 12:47:35.119 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: ZWaveCommandClassTransactionPayload - send to node
2020-08-24 12:47:35.121 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: SECURITY NOT required on COMMAND_CLASS_VERSION
2020-08-24 12:47:35.123 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 42: Command Class COMMAND_CLASS_VERSION is NOT required to be secured
2020-08-24 12:47:35.125 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@be34f6
2020-08-24 12:47:35.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Bump transaction 554 priority from Config to Immediate
2020-08-24 12:47:35.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Adding to device queue
2020-08-24 12:47:35.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: Added 554 to queue - size 32
2020-08-24 12:47:48.813 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 42: Sending REQUEST Message = 01 0A 00 13 2A 03 86 13 22 25 FA A7
2020-08-24 12:47:48.877 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: sentData successfully placed on stack.
2020-08-24 12:47:48.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 42: TID 554: Transaction not completed
2020-08-24 12:47:50.128 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 42: SendData Request. CallBack ID = 250, Status = Transmission complete and ACK received(0)
[snip, max size of attachment]

Is there something I’ve missed? Did secure inclusion change with the 3.5.4 to 2.5.7 zwave/OH update?

bdm · August 24, 2020, 8:22pm

And for visualization with Chris’ z-wave log viewer:

bdm · August 24, 2020, 9:37pm

Potentially also useful (after removal and re-adding again, resulting in the node number change:

2020-08-24 14:35:58.748 [ome.event.ItemCommandEvent] - Item 'zwave_device_a204e4d4_node45_lock_door' received command OFF

2020-08-24 14:35:58.751 [nt.ItemStatePredictedEvent] - zwave_device_a204e4d4_node45_lock_door predicted to become OFF

2020-08-24 14:35:58.765 [vent.ItemStateChangedEvent] - zwave_device_a204e4d4_node45_lock_door changed from NULL to OFF

2020-08-24 14:35:58.765 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Command received zwave:device:a204e4d4:node45:lock_door --> OFF [OnOffType]

2020-08-24 14:35:58.768 [WARN ] [nal.converter.ZWaveDoorLockConverter] - NODE 45: Command class COMMAND_CLASS_DOOR_LOCK not found

2020-08-24 14:35:58.770 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: No messages returned from converter

Bruce_Osborne · August 24, 2020, 10:51pm

To include securely you need to exclude, reset the device & then include

bdm · August 25, 2020, 4:07am

Ah, resetting the device was the fix. Thank you!

As usual, a summary for anyone following this problem:

Exclude the device (Habmin, things, z-wave controller, settings (top right), show-advanced settings, then click on setting again, and click exclude.

then on the lock keypad, type in the programming code on the device and press zero (the inclusion/exclusion procedure for the schlage lock)

unplug the battery on the lock, wait 30 seconds, reconnect it.
before including the device, in the z-wave controller settings, after advanced settings is enabled, look at the ‘Z-wave Network Settings’ portion and ensure inclusion specifies entry control devices (or perhaps ‘all’, not sure).
Include the lock using your favourite UI. I used habmin since I was in that - click what looks like a magnifying glass with a dot in the centre, and choose z-wave devices

then again type in the programming code and then zero on the schlage lock, or whatever the inclusion procedure is for your particular lock.

Wait for the checkmark/successful inclusion. It may take a couple attempts. Once included, I found it took about 5-10 minutes, with periodic manual locking/unlocking (waking the device) until it had all the security features enabled and I was able to toggle the lock successfully. I had been watching the log (zwave set to debug at the time), but you could simply keep refreshing the view every couple minutes until you see the lock channels correctly populated, then start trying to toggle the lock. If it doesn’t eventually show security enabled in the properties of the lock, you may need to again exclude, reset, and re-include the lock.

Bruce_Osborne · August 25, 2020, 6:28am

Resetting before inclusion is needed for all secure device inclusions.

system · October 5, 2020, 10:28pm

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.