OH2, Z-Wave, Yale Door Lock, Security Inclusion is Failing

I’ve been trying to read what I can and finally figured out how to add my lock with Security enabled by enabling Inclusion mode from within HABmin. I turned on debugging and it seems the communication is timing out before it finishes. Here’s a portion of the openhab.log showing Node 13. Any ideas? I don’t know where to go from here. Thanks in advance.

2017-09-23 20:30:25.790 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: Sent Data successfully placed on stack.
2017-09-23 20:30:26.493 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 1600
2017-09-23 20:30:26.493 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
2017-09-23 20:30:26.493 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Initialisation retry timer started 1600
2017-09-23 20:30:26.493 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node advancer: loop - SECURITY_REPORT try 1: stageAdvanced(false)
2017-09-23 20:30:26.493 [DEBUG] [curityCommandClassWithInitialization] - NODE 13: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=10715ms, lastTxMsg=10714ms
2017-09-23 20:30:26.493 [DEBUG] [ity.ZWaveSecureInclusionStateTracker] - NODE 13: in InclusionStateTracker.getNextRequest() time left for reply: 805ms, returning null
2017-09-23 20:30:26.493 [DEBUG] [curityCommandClassWithInitialization] - NODE 13: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
2017-09-23 20:30:26.493 [ERROR] [curityCommandClassWithInitialization] - NODE 13: SECURITY_INCLUSION_FAILED Failed at step SECURITY_NETWORK_KEY_SET: 10000ms passed since last request was sent, secure inclusion failed.
2017-09-23 20:30:26.493 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Since secure inclusion failed, the node must be manually excluded via habmin
2017-09-23 20:30:26.493 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node advancer - advancing to APP_VERSION
2017-09-23 20:30:26.494 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2017-09-23 20:30:26.494 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node advancer: loop - APP_VERSION try 0: stageAdvanced(true)
2017-09-23 20:30:26.494 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node advancer: APP_VERSION - send VersionMessage
2017-09-23 20:30:26.494 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 13: Creating new message for command VERSION_GET
2017-09-23 20:30:26.494 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 13: Node advancer - queued packet. Queue length is 1
2017-09-23 20:30:26.494 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 34. Queue={}
2017-09-23 20:30:27.073 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 5C 00 00 80 37 
2017-09-23 20:30:27.074 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-09-23 20:30:27.074 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 5C 00 00 80 00 00 39 
2017-09-23 20:30:27.074 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 5C 00 00 80 00 00 39 
2017-09-23 20:30:27.074 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5C 00 00 80 
2017-09-23 20:30:27.074 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: SendData Request. CallBack ID = 92, Status = Transmission complete and ACK received(0)
2017-09-23 20:30:27.074 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=13, callback=92, payload=0D 0A 98 80 69 79 8F 20 13 62 87 1A 
2017-09-23 20:30:27.074 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5C 00 00 80 
2017-09-23 20:30:27.074 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=92, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-09-23 20:30:30.782 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Timeout while sending message. Requeueing - 0 attempts left!
2017-09-23 20:30:30.782 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: Got an error while sending data. Resending message.
2017-09-23 20:30:30.782 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 35. Queue={}
2017-09-23 20:30:30.782 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 34
2017-09-23 20:30:30.782 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 11 00 13 0D 0A 98 80 69 79 8F 20 13 62 87 1A 05 5E EA 
2017-09-23 20:30:30.782 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 13: Sending REQUEST Message = 01 11 00 13 0D 0A 98 80 69 79 8F 20 13 62 87 1A 05 5E EA 
2017-09-23 20:30:30.790 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-09-23 20:30:30.791 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-09-23 20:30:30.791 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2017-09-23 20:30:30.791 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2017-09-23 20:30:30.791 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2017-09-23 20:30:30.791 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: Sent Data successfully placed on stack.
2017-09-23 20:30:30.933 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
2017-09-23 20:30:30.933 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2017-09-23 20:30:30.933 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 35. Queue={}
2017-09-23 20:30:30.933 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller end inclusion
2017-09-23 20:30:32.073 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 5E 00 00 80 35 
2017-09-23 20:30:32.074 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-09-23 20:30:32.074 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 5E 00 00 80 00 00 3B 
2017-09-23 20:30:32.074 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 5E 00 00 80 00 00 3B 
2017-09-23 20:30:32.074 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5E 00 00 80 
2017-09-23 20:30:32.074 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 13: SendData Request. CallBack ID = 94, Status = Transmission complete and ACK received(0)
2017-09-23 20:30:32.074 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=13, callback=94, payload=0D 0A 98 80 69 79 8F 20 13 62 87 1A 
2017-09-23 20:30:32.074 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5E 00 00 80 
2017-09-23 20:30:32.074 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=94, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Stage DYNAMIC_VALUES. Initialisation retry timer triggered. Increased to 10000
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer - DYNAMIC_VALUES: queue length(0), free to send(false)
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Initialisation retry timer started 10000
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: loop - DYNAMIC_VALUES try 1: stageAdvanced(false)
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking NO_OPERATION
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking VERSION
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking BASIC
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking APPLICATION_STATUS
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking ALARM
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - found    ALARM
2017-09-23 20:30:34.235 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Found 1 instances of ALARM
2017-09-23 20:30:34.235 [DEBUG] [.commandclass.ZWaveAlarmCommandClass] - NODE 7: Creating new message for application command NOTIFICATION_GET V2
2017-09-23 20:30:34.236 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer - queued packet. Queue length is 1
2017-09-23 20:30:34.236 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 36. Queue={}
2017-09-23 20:30:34.236 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking SWITCH_BINARY
2017-09-23 20:30:34.236 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - found    SWITCH_BINARY
2017-09-23 20:30:34.236 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Found 1 instances of SWITCH_BINARY
2017-09-23 20:30:34.236 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 7: Creating new message for application command SWITCH_BINARY_GET
2017-09-23 20:30:34.236 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking MANUFACTURER_SPECIFIC
2017-09-23 20:30:34.236 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - checking CONFIGURATION
2017-09-23 20:30:34.236 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node advancer: DYNAMIC_VALUES - queued 2 frames
2017-09-23 20:30:35.784 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 13: Too many retries. Discarding message: Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=13, callback=94, payload=0D 0A 98 80 69 79 8F 20 13 62 87 1A 
2017-09-23 20:30:35.784 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 35
2017-09-23 20:30:35.784 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 01 B4 
2017-09-23 20:30:35.784 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 01 B4 
2017-09-23 20:30:35.835 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 06 0D 00 B8 
2017-09-23 20:30:35.836 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-09-23 20:30:35.836 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 06 0D 00 B8 
2017-09-23 20:30:35.836 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 06 0D 00 B8 
2017-09-23 20:30:35.836 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 0D 00 
2017-09-23 20:30:35.836 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2017-09-23 20:30:35.836 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2017-09-23 20:30:35.837 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 13: Device already known.
2017-09-23 20:30:35.837 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 13: Newly included node already initialising at APP_VERSION
2017-09-23 20:30:35.837 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 01 
2017-09-23 20:30:35.837 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 0D 00 
2017-09-23 20:30:35.837 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false        transaction complete!
2017-09-23 20:30:35.837 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-09-23 20:30:35.837 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 53ms/1167ms.
2017-09-23 20:30:35.837 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 34
2017-09-23 20:30:35.837 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 13 07 04 71 04 00 07 25 5F EC 
2017-09-23 20:30:35.837 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 7: Sending REQUEST Message = 01 0B 00 13 07 04 71 04 00 07 25 5F EC 
2017-09-23 20:30:35.845 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-09-23 20:30:35.845 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-09-23 20:30:35.845 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2017-09-23 20:30:35.845 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2017-09-23 20:30:35.846 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2017-09-23 20:30:35.846 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: Sent Data successfully placed on stack.
2017-09-23 20:30:35.884 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 5F 00 00 04 B0 
2017-09-23 20:30:35.884 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-09-23 20:30:35.884 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 5F 00 00 04 00 00 BE 
2017-09-23 20:30:35.884 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 5F 00 00 04 00 00 BE 
2017-09-23 20:30:35.884 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5F 00 00 04 
2017-09-23 20:30:35.884 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: SendData Request. CallBack ID = 95, Status = Transmission complete and ACK received(0)
2017-09-23 20:30:35.884 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=7, callback=95, payload=07 04 71 04 00 07 
2017-09-23 20:30:35.884 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5F 00 00 04 
2017-09-23 20:30:35.884 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=95, expected=ApplicationCommandHandler, cancelled=false      MISMATCH
2017-09-23 20:30:40.838 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 7: Timeout while sending message. Requeueing - 2 attempts left!
2017-09-23 20:30:40.838 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: Got an error while sending data. Resending message.
2017-09-23 20:30:40.838 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 35. Queue={}
2017-09-23 20:30:40.838 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 34
2017-09-23 20:30:40.838 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 13 07 04 71 04 00 07 25 60 D3 
2017-09-23 20:30:40.838 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 7: Sending REQUEST Message = 01 0B 00 13 07 04 71 04 00 07 25 60 D3 
2017-09-23 20:30:40.846 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-09-23 20:30:40.846 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-09-23 20:30:40.846 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2017-09-23 20:30:40.846 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2017-09-23 20:30:40.846 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2017-09-23 20:30:40.846 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: Sent Data successfully placed on stack.
2017-09-23 20:30:40.884 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 60 00 00 05 8E 
2017-09-23 20:30:40.885 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-09-23 20:30:40.885 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 60 00 00 05 00 00 80 
2017-09-23 20:30:40.885 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 60 00 00 05 00 00 80 
2017-09-23 20:30:40.885 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=60 00 00 05 
2017-09-23 20:30:40.885 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 7: SendData Request. CallBack ID = 96, Status = Transmission complete and ACK received(0)
2017-09-23 20:30:40.885 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Get, dest=7, callback=96, payload=07 04 71 04 00 07 
2017-09-23 20:30:40.885 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=60 00 00 05 
2017-09-23 20:30:40.885 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=96, expected=ApplicationCommandHandler, cancelled=false      MISMATCH

Easiest thing to test first is to make sure you are running the test binding from here:

The default OH2 zwave binding doesn’t include security at the moment.

2 Likes

Dude, thank you! I assumed since this one and the default one were both ver. 2.1.0 that they were the same. This got it working for me! Thank you so much! Now I need to figure out how to configure all the items. lol