Z-wave (Schlage) Lock Support on OH1

Awesome! I’ll see if I can figure out how to get a working binary.

Just use the nightly snapshot version from cloudbees.

1 Like

Really great news about the merge Chris! I will give it a shot as I am prepping my house for holiday automation

@wificordon
I will look into this. I remember working a similar bug was fixed awhile back, not sure if I ever committed it

I got my Kwikset 910 paired, having issues with actual control. Logs make it seem like it is working. Will be messing with it more today.

I have an existing KwikSet 916 Zwave lock that I have previously paired with OZCP, and added that security key into my OH1 Binding zwave.cfg file.

Like Nolan above, it appears correct, but can’t get control of it. And I can control it if I turn off OH and use OZCP.

Here is some log info when using the 1.x binding in OH2 (with the 2.0 binding uninstalled of course)

2016-11-13 16:36:04.222 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2016-11-13 16:36:04.228 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2016-11-13 16:36:04.236 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x00.
2016-11-13 16:36:04.236 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x11.
2016-11-13 16:36:04.237 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x02.
2016-11-13 16:36:04.237 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x84.
2016-11-13 16:36:04.291 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x07.
2016-11-13 16:36:04.292 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Protocol error (OOF). Got 0x63.
2016-11-13 16:36:04.481 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2016-11-13 16:36:04.481 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2016-11-13 16:36:08.117 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2016-11-13 16:36:08.123 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2016-11-13 16:36:08.123 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2016-11-13 16:36:08.123 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 4: Node found
2016-11-13 16:36:08.123 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 5: Node found
2016-11-13 16:36:08.124 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2016-11-13 16:36:08.124 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 7: Node found
2016-11-13 16:36:08.124 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 8: Node found
2016-11-13 16:36:08.124 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 9: Node found
2016-11-13 16:36:08.124 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 10: Node found
2016-11-13 16:36:08.124 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 11: Node found
2016-11-13 16:36:08.125 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 12: Node found
2016-11-13 16:36:08.125 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 13: Node found
2016-11-13 16:36:08.125 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 14: Node found
2016-11-13 16:36:08.125 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 15: Node found
2016-11-13 16:36:08.125 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 16: Node found
2016-11-13 16:36:08.125 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 17: Node found
2016-11-13 16:36:08.126 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2016-11-13 16:36:08.126 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2016-11-13 16:36:08.126 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2016-11-13 16:36:08.126 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 17
2016-11-13 16:36:08.126 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2016-11-13 16:36:08.235 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Initialising Thing Node...
2016-11-13 16:36:08.235 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Initialising Thing Node...
2016-11-13 16:36:08.235 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Initialising Thing Node...
2016-11-13 16:36:08.235 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Initialising Thing Node...
2016-11-13 16:36:08.235 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Initialising Thing Node...
2016-11-13 16:36:08.276 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Initialising Thing Node...
2016-11-13 16:36:08.277 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Initialising Thing Node...
2016-11-13 16:36:08.278 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 17: Initialising Thing Node...
2016-11-13 16:36:08.283 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Initialising Thing Node...
2016-11-13 16:36:08.284 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Initialising Thing Node...
2016-11-13 16:36:08.284 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Initialising Thing Node...
2016-11-13 16:36:08.284 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Initialising Thing Node...
2016-11-13 16:36:08.285 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Initialising Thing Node...
2016-11-13 16:36:08.286 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Initialising Thing Node...
2016-11-13 16:36:08.284 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node...
2016-11-13 16:36:08.291 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Initialising Thing Node...
2016-11-13 16:36:08.936 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 8: Device discovery could not resolve to a thingType! 001D:1001:0334::0.7
2016-11-13 16:36:09.093 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 2: setupNetworkKey useSchemeZero=false
2016-11-13 16:36:09.222 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 2: setupNetworkKey useSchemeZero=false

And then further below trying to control it

2016-11-13 17:16:15.892 [DEBUG] [l.ZWaveController$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2016-11-13 17:16:15.895 [DEBUG] [l.ZWaveController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2016-11-13 17:16:15.895 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-11-13 17:16:15.895 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2016-11-13 17:16:15.895 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2016-11-13 17:16:15.895 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class = SendData (0x13), type = Response (0x01), payload = 01 , callbackid = 0
2016-11-13 17:16:15.895 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.
2016-11-13 17:16:17.300 [DEBUG] [l.ZWaveController$ZWaveReceiveThread] - Receive Message = 01 07 00 13 3D 00 00 8D 5B 
2016-11-13 17:16:17.304 [DEBUG] [l.ZWaveController$ZWaveReceiveThread] - Receive queue ADD: Length=1
2016-11-13 17:16:17.304 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-11-13 17:16:17.304 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 3D 00 00 8D 00 00 55 
2016-11-13 17:16:17.304 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 3D 00 00 8D 00 00 55 
2016-11-13 17:16:17.304 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class = SendData (0x13), type = Request (0x00), payload = 3D 00 00 8D , callbackid = 0
2016-11-13 17:16:17.304 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: SendData Request. CallBack ID = 61, Status = Transmission complete and ACK received(0)
2016-11-13 17:16:17.304 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 02 02 62 02 , callbackid = 61
2016-11-13 17:16:17.304 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 3D 00 00 8D , callbackid = 0
2016-11-13 17:16:17.304 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 02 02 62 02 , callbackid = 61
2016-11-13 17:16:17.304 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 3D 00 00 8D , callbackid = 0
2016-11-13 17:16:17.305 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=61, expected=ApplicationCommandHandler, cancelled=false      mismatch

I got my 910 working, but can’t get my 916 working. Logs here. Nodes 95-100 are all attempts.

Got the 916’s working as well. The trick? Just keep trying and keep the lock assembly as close to the z-wave controller as possible. Touching might not be close enough, you may need to touch them together at the right point. Don’t be discouraged - it took me 14 attempts to successfully pair 2 916 locks.

@wificordon @Nicholas_Waterton

The user code issue (only last being applied) has been fixed in this PR

That’s interesting that you got them working. That is with OH2 and the 1.9 binding? My 916 is actually already secured paired to the controller being done with open zwave control panel. And I can control and lock/unlock the door using open zwave control panel as well. All I need (or should need to do) to use with OpenHab is add the network key to the 1.9 binding zwave.cfg file which I did do but could not control the door.

I can give it another try later tonight. But I should not actually need to remove and reinclude the device, although I can give that a try as well.

I am using 1.8.3 with the 1.9 build from Cloudbees.

@nolan_garrett

Nolan. Were you able to get the Battery Level to show up on the 916? I tested out with same as you using 1.8.3 and 1.9 and got control of the door and status easily enough.

But I see in the log an error on the battery of:

And when I looked in Habmin on OH1, it is showing the lock power as MAINS and not as battery powered. Do you see the same?

I am getting battery level. I’ll check on the MAINS issue when I get home.

Thanks @dbadia.

I’ll test the change ASAP and will give feedback after testing.

Was anyone able to get the locks to work in OH2 when using the OH1 binding?

I tried by both using the PaperUI to install the OH1 legacy, and also by having both binding uninstalled in the PaperUI and then manually adding the 1.9 binding from cloudbees. But in both cases could not get the lock to work in OH2. I remember the logs saying it was still not included but would need to try it again if anyones to see the errors.

But for now, I’m in no rush to control the lock until we have the ability to password protect or other the OH2 user interface to prohibit and protect from outside intrusions.

I am using the OH1.8.3 and the zwave-1.9.0.jar. I can’t get my schlage to pair.

below is the debug log
2016-12-20 03:41:14.643 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1138]- NODE 12: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2016-12-20 03:41:14.675 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 12: Node advancer - checking initialisation queue. Queue size 1.
2016-12-20 03:41:14.707 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 12: Node advancer - message removed from queue. Queue size 0.
2016-12-20 03:41:14.740 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 12: Node advancer - NEIGHBORS: queue length(0), free to send(true)
2016-12-20 03:41:14.779 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1262]- NODE 12: Initialisation retry timer started 5000
2016-12-20 03:41:14.811 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
2016-12-20 03:41:14.844 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:994 ]- NODE 12: Node advancer - advancing to FAILED_CHECK
2016-12-20 03:41:14.878 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2016-12-20 03:41:14.909 [DEBUG] [i.p.s.IsFailedNodeMessageClass:32 ]- NODE 12: Requesting IsFailedNode status from controller.
2016-12-20 03:41:14.958 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 255: Creating empty message of class = IsFailedNodeID (0x62), type = Request (0x00)
2016-12-20 03:41:14.991 [DEBUG] [b.z.i.protocol.ZWaveController:651 ]- Enqueueing message. Queue length = 1
2016-12-20 03:41:15.025 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 12: Node advancer - queued packet. Queue length is 1
2016-12-20 03:41:15.059 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 255: Response processed for callback id 0 after 3274ms/4958ms.
2016-12-20 03:41:15.089 [DEBUG] [WaveController$ZWaveSendThread:1295]- Took message from queue for sending. Queue length = 0
2016-12-20 03:41:15.158 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 04 00 62 0C 95
2016-12-20 03:41:15.220 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 255: Sending REQUEST Message = 01 04 00 62 0C 95
2016-12-20 03:41:15.284 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 04 01 62 00 98
2016-12-20 03:41:15.360 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-12-20 03:41:15.365 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=0
2016-12-20 03:41:15.459 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 04 01 62 00 98
2016-12-20 03:41:15.518 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 04 01 62 00 98
2016-12-20 03:41:15.574 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 00 , callbackid = 0
2016-12-20 03:41:15.609 [DEBUG] [i.p.s.IsFailedNodeMessageClass:56 ]- NODE 12: Is currently marked as healthy by the controller
2016-12-20 03:41:15.661 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83 ]- Sent message Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 0C , callbackid = 0
2016-12-20 03:41:15.715 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84 ]- Recv message Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 00 , callbackid = 0
2016-12-20 03:41:15.772 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ]- Checking transaction complete: Sent message Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 0C , callbackid = 0
2016-12-20 03:41:15.829 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96 ]- Checking transaction complete: Recv message Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 00 , callbackid = 0
2016-12-20 03:41:15.862 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:99 ]- Checking transaction complete: class=IsFailedNodeID, callback id=0, expected=IsFailedNodeID, cancelled=false transaction complete!
2016-12-20 03:41:15.895 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-12-20 03:41:15.924 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2016-12-20 03:41:15.956 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1138]- NODE 12: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
2016-12-20 03:41:15.996 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 12: Node advancer - checking initialisation queue. Queue size 1.
2016-12-20 03:41:16.028 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 12: Node advancer - message removed from queue. Queue size 0.
2016-12-20 03:41:16.061 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 12: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
2016-12-20 03:41:16.093 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1262]- NODE 12: Initialisation retry timer started 5000
2016-12-20 03:41:16.126 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
2016-12-20 03:41:16.174 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:994 ]- NODE 12: Node advancer - advancing to WAIT
2016-12-20 03:41:16.226 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - WAIT try 0: stageAdvanced(true)
2016-12-20 03:41:16.282 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:390 ]- NODE 12: Node advancer: WAIT - Listening=false, FrequentlyListening=true
2016-12-20 03:41:16.313 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:394 ]- NODE 12: Node advancer: WAIT - Advancing
2016-12-20 03:41:16.345 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:994 ]- NODE 12: Node advancer - advancing to PING
2016-12-20 03:41:16.381 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - PING try 0: stageAdvanced(true)
2016-12-20 03:41:16.415 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:427 ]- NODE 12: Node advancer: PING - send NoOperation
2016-12-20 03:41:16.445 [DEBUG] [c.ZWaveNoOperationCommandClass:72 ]- NODE 12: Creating new message for command No Operation
2016-12-20 03:41:16.492 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 12: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-12-20 03:41:16.525 [DEBUG] [b.z.i.protocol.ZWaveController:976 ]- Callback ID = 8
2016-12-20 03:41:16.558 [DEBUG] [b.z.i.protocol.ZWaveController:651 ]- Enqueueing message. Queue length = 1
2016-12-20 03:41:16.592 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 12: Node advancer - queued packet. Queue length is 1
2016-12-20 03:41:16.627 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 255: Response processed for callback id 0 after 1375ms/4958ms.
2016-12-20 03:41:16.655 [DEBUG] [WaveController$ZWaveSendThread:1295]- Took message from queue for sending. Queue length = 0
2016-12-20 03:41:16.740 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 08 00 13 0C 01 00 25 08 C4
2016-12-20 03:41:16.826 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 12: Sending REQUEST Message = 01 08 00 13 0C 01 00 25 08 C4
2016-12-20 03:41:16.881 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 04 01 13 01 E8
2016-12-20 03:41:16.945 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-12-20 03:41:16.950 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=0
2016-12-20 03:41:17.049 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 04 01 13 01 E8
2016-12-20 03:41:17.161 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 04 01 13 01 E8
2016-12-20 03:41:17.262 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 , callbackid = 0
2016-12-20 03:41:17.321 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39 ]- NODE 12: Sent Data successfully placed on stack.
2016-12-20 03:41:18.066 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 05 00 13 08 00 E1
2016-12-20 03:41:18.171 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-12-20 03:41:18.178 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=0
2016-12-20 03:41:18.306 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 07 00 13 08 00 00 00 E3
2016-12-20 03:41:18.422 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 07 00 13 08 00 00 00 E3
2016-12-20 03:41:18.477 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 08 00 , callbackid = 0
2016-12-20 03:41:18.510 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74 ]- NODE 12: SendData Request. CallBack ID = 8, Status = Transmission complete and ACK received(0)
2016-12-20 03:41:18.587 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83 ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0C 01 00 , callbackid = 8
2016-12-20 03:41:18.649 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84 ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 08 00 , callbackid = 0
2016-12-20 03:41:18.749 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ]- Checking transaction complete: Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0C 01 00 , callbackid = 8
2016-12-20 03:41:18.838 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96 ]- Checking transaction complete: Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 08 00 , callbackid = 0
2016-12-20 03:41:18.904 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:99 ]- Checking transaction complete: class=SendData, callback id=8, expected=SendData, cancelled=false transaction complete!
2016-12-20 03:41:18.951 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 12: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-12-20 03:41:18.985 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2016-12-20 03:41:19.020 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1138]- NODE 12: Node advancer - PING: Transaction complete (SendData:Request) success(true)
2016-12-20 03:41:19.055 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 12: Node advancer - checking initialisation queue. Queue size 1.
2016-12-20 03:41:19.088 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 12: Node advancer - message removed from queue. Queue size 0.
2016-12-20 03:41:19.121 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 12: Node advancer - PING: queue length(0), free to send(true)
2016-12-20 03:41:19.158 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1262]- NODE 12: Initialisation retry timer started 5000
2016-12-20 03:41:19.190 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - PING try 1: stageAdvanced(false)
2016-12-20 03:41:19.227 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:994 ]- NODE 12: Node advancer - advancing to SECURITY_REPORT
2016-12-20 03:41:19.259 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - SECURITY_REPORT try 0: stageAdvanced(true)
2016-12-20 03:41:19.293 [DEBUG] [CommandClassWithInitialization:317 ]- NODE 12: call from NodeAdvancer initialize, firstIteration=true, wasThisNodeJustIncluded=true, keyVerifyReceived=false, lastReceivedMessage=1482205279290ms ago, lastSentMessage=1482205279290ms ago
2016-12-20 03:41:19.326 [INFO ] [.p.c.ZWaveSecurityCommandClass:806 ]- NODE 12: setupNetworkKey useSchemeZero=true
2016-12-20 03:41:19.358 [INFO ] [.p.c.ZWaveSecurityCommandClass:808 ]- NODE 12: Using Scheme0 Network Key for Key Exchange since we are in inclusion mode.)
2016-12-20 03:41:19.434 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 12: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-12-20 03:41:19.511 [DEBUG] [CommandClassWithInitialization:390 ]- NODE 12: call from NodeAdvancer initialize, just included, handing back message=[Message: class = SendData (0x13), type = Request (0x00), payload = 0C 03 98 04 00 , callbackid = 0]
2016-12-20 03:41:19.549 [DEBUG] [b.z.i.protocol.ZWaveController:976 ]- Callback ID = 9
2016-12-20 03:41:19.582 [DEBUG] [b.z.i.protocol.ZWaveController:651 ]- Enqueueing message. Queue length = 1
2016-12-20 03:41:19.616 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 12: Node advancer - queued packet. Queue length is 1
2016-12-20 03:41:19.649 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 12: Response processed for callback id 8 after 2792ms/4958ms.
2016-12-20 03:41:19.679 [DEBUG] [WaveController$ZWaveSendThread:1295]- Took message from queue for sending. Queue length = 0
2016-12-20 03:41:19.776 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 0A 00 13 0C 03 98 04 00 25 09 59
2016-12-20 03:41:19.877 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 98 04 00 25 09 59
2016-12-20 03:41:19.943 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 04 01 13 01 E8
2016-12-20 03:41:20.020 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-12-20 03:41:20.024 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=0
2016-12-20 03:41:20.136 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 04 01 13 01 E8
2016-12-20 03:41:20.201 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 04 01 13 01 E8
2016-12-20 03:41:20.254 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 , callbackid = 0
2016-12-20 03:41:20.286 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39 ]- NODE 12: Sent Data successfully placed on stack.
2016-12-20 03:41:21.116 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 05 00 13 09 00 E0
2016-12-20 03:41:21.200 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-12-20 03:41:21.204 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=0
2016-12-20 03:41:21.314 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 07 00 13 09 00 00 00 E2
2016-12-20 03:41:21.388 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 07 00 13 09 00 00 00 E2
2016-12-20 03:41:21.447 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 09 00 , callbackid = 0
2016-12-20 03:41:21.484 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74 ]- NODE 12: SendData Request. CallBack ID = 9, Status = Transmission complete and ACK received(0)
2016-12-20 03:41:21.559 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83 ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0C 03 98 04 00 , callbackid = 9
2016-12-20 03:41:21.620 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84 ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 09 00 , callbackid = 0
2016-12-20 03:41:21.697 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ]- Checking transaction complete: Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0C 03 98 04 00 , callbackid = 9
2016-12-20 03:41:21.755 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96 ]- Checking transaction complete: Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 09 00 , callbackid = 0
2016-12-20 03:41:21.788 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:107 ]- Checking transaction complete: class=SendData, callback id=9, expected=ApplicationCommandHandler, cancelled=false mismatch
2016-12-20 03:41:24.158 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1230]- NODE 12: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
2016-12-20 03:41:24.189 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 12: Node advancer - SECURITY_REPORT: queue length(0), free to send(false)
2016-12-20 03:41:24.225 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1262]- NODE 12: Initialisation retry timer started 800
2016-12-20 03:41:24.258 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - SECURITY_REPORT try 1: stageAdvanced(false)
2016-12-20 03:41:24.296 [DEBUG] [CommandClassWithInitialization:317 ]- NODE 12: call from NodeAdvancer initialize, firstIteration=false, wasThisNodeJustIncluded=true, keyVerifyReceived=false, lastReceivedMessage=1482205284292ms ago, lastSentMessage=4645ms ago
2016-12-20 03:41:24.329 [DEBUG] [aveSecureInclusionStateTracker:139 ]- NODE 12: in InclusionStateTracker.getNextRequest() time left for reply: -5091ms, returning null
2016-12-20 03:41:24.361 [DEBUG] [CommandClassWithInitialization:362 ]- NODE 12: call from NodeAdvancer initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
2016-12-20 03:41:24.393 [DEBUG] [CommandClassWithInitialization:390 ]- NODE 12: call from NodeAdvancer initialize, just included, handing back message=[]
2016-12-20 03:41:24.911 [ERROR] [WaveController$ZWaveSendThread:1413]- NODE 12: Timeout while sending message. Requeueing - 0 attempts left!
2016-12-20 03:41:24.939 [ERROR] [b.z.i.p.s.SendDataMessageClass:159 ]- NODE 12: Got an error while sending data. Resending message.
2016-12-20 03:41:24.976 [DEBUG] [b.z.i.protocol.ZWaveController:651 ]- Enqueueing message. Queue length = 1
2016-12-20 03:41:25.006 [DEBUG] [WaveController$ZWaveSendThread:1295]- Took message from queue for sending. Queue length = 0
2016-12-20 03:41:25.026 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1230]- NODE 12: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
2016-12-20 03:41:25.086 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 12: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
2016-12-20 03:41:25.144 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1262]- NODE 12: Initialisation retry timer started 800
2016-12-20 03:41:25.202 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - SECURITY_REPORT try 2: stageAdvanced(false)
2016-12-20 03:41:25.211 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 0A 00 13 0C 03 98 04 00 25 09 59
2016-12-20 03:41:25.276 [DEBUG] [CommandClassWithInitialization:317 ]- NODE 12: call from NodeAdvancer initialize, firstIteration=false, wasThisNodeJustIncluded=true, keyVerifyReceived=false, lastReceivedMessage=1482205285260ms ago, lastSentMessage=5613ms ago
2016-12-20 03:41:25.291 [DEBUG] [.z.i.config.ZWaveConfiguration:1370]- Ending inclusion mode.
2016-12-20 03:41:25.371 [DEBUG] [aveSecureInclusionStateTracker:139 ]- NODE 12: in InclusionStateTracker.getNextRequest() time left for reply: -9031ms, returning null
2016-12-20 03:41:25.372 [DEBUG] [.z.i.config.ZWaveConfiguration:1393]- Stopping inclusion timer.
2016-12-20 03:41:25.456 [DEBUG] [CommandClassWithInitialization:362 ]- NODE 12: call from NodeAdvancer initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
2016-12-20 03:41:25.481 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 98 04 00 25 09 59
2016-12-20 03:41:25.467 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:60 ]- Ending INCLUSION mode.
2016-12-20 03:41:25.542 [DEBUG] [CommandClassWithInitialization:390 ]- NODE 12: call from NodeAdvancer initialize, just included, handing back message=[]
2016-12-20 03:41:25.611 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 255: Creating empty message of class = AddNodeToNetwork (0x4A), type = Request (0x00)
2016-12-20 03:41:25.647 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 04 01 13 01 E8
2016-12-20 03:41:25.677 [DEBUG] [b.z.i.protocol.ZWaveController:651 ]- Enqueueing message. Queue length = 1
2016-12-20 03:41:25.735 [INFO ] [b.z.i.protocol.ZWaveController:862 ]- Ending inclusion mode
2016-12-20 03:41:25.801 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-12-20 03:41:25.806 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=0
2016-12-20 03:41:25.904 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 04 01 13 01 E8
2016-12-20 03:41:25.942 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1230]- NODE 12: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
2016-12-20 03:41:26.000 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 04 01 13 01 E8
2016-12-20 03:41:25.999 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 12: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
2016-12-20 03:41:26.069 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1262]- NODE 12: Initialisation retry timer started 800
2016-12-20 03:41:26.106 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 , callbackid = 0
2016-12-20 03:41:26.127 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - SECURITY_REPORT try 3: stageAdvanced(false)
2016-12-20 03:41:26.176 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39 ]- NODE 12: Sent Data successfully placed on stack.
2016-12-20 03:41:26.203 [DEBUG] [CommandClassWithInitialization:317 ]- NODE 12: call from NodeAdvancer initialize, firstIteration=false, wasThisNodeJustIncluded=true, keyVerifyReceived=false, lastReceivedMessage=1482205286195ms ago, lastSentMessage=6548ms ago
2016-12-20 03:41:26.258 [DEBUG] [aveSecureInclusionStateTracker:139 ]- NODE 12: in InclusionStateTracker.getNextRequest() time left for reply: -9276ms, returning null
2016-12-20 03:41:26.294 [DEBUG] [CommandClassWithInitialization:362 ]- NODE 12: call from NodeAdvancer initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
2016-12-20 03:41:26.326 [DEBUG] [CommandClassWithInitialization:390 ]- NODE 12: call from NodeAdvancer initialize, just included, handing back message=[]
2016-12-20 03:41:26.800 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 05 00 13 09 00 E0
2016-12-20 03:41:26.867 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1230]- NODE 12: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
2016-12-20 03:41:26.918 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 12: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
2016-12-20 03:41:26.962 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-12-20 03:41:26.966 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=0
2016-12-20 03:41:26.984 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1262]- NODE 12: Initialisation retry timer started 800
2016-12-20 03:41:27.086 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - SECURITY_REPORT try 4: stageAdvanced(false)
2016-12-20 03:41:27.196 [DEBUG] [CommandClassWithInitialization:317 ]- NODE 12: call from NodeAdvancer initialize, firstIteration=false, wasThisNodeJustIncluded=true, keyVerifyReceived=false, lastReceivedMessage=1482205287175ms ago, lastSentMessage=7528ms ago
2016-12-20 03:41:27.227 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 07 00 13 09 00 00 00 E2
2016-12-20 03:41:27.294 [DEBUG] [aveSecureInclusionStateTracker:139 ]- NODE 12: in InclusionStateTracker.getNextRequest() time left for reply: -9034ms, returning null
2016-12-20 03:41:27.382 [DEBUG] [CommandClassWithInitialization:362 ]- NODE 12: call from NodeAdvancer initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
2016-12-20 03:41:27.475 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 07 00 13 09 00 00 00 E2
2016-12-20 03:41:27.477 [DEBUG] [CommandClassWithInitialization:390 ]- NODE 12: call from NodeAdvancer initialize, just included, handing back message=[]
2016-12-20 03:41:27.624 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 09 00 , callbackid = 0
2016-12-20 03:41:27.687 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74 ]- NODE 12: SendData Request. CallBack ID = 9, Status = Transmission complete and ACK received(0)
2016-12-20 03:41:27.783 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1230]- NODE 12: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
2016-12-20 03:41:27.872 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 12: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
2016-12-20 03:41:27.871 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83 ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0C 03 98 04 00 , callbackid = 9
2016-12-20 03:41:27.961 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1262]- NODE 12: Initialisation retry timer started 800
2016-12-20 03:41:28.037 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 12: Node advancer: loop - SECURITY_REPORT try 5: stageAdvanced(false)
2016-12-20 03:41:28.055 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84 ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 09 00 , callbackid = 0
2016-12-20 03:41:28.123 [DEBUG] [CommandClassWithInitialization:317 ]- NODE 12: call from NodeAdvancer initialize, firstIteration=false, wasThisNodeJustIncluded=true, keyVerifyReceived=false, lastReceivedMessage=1482205288101ms ago, lastSentMessage=8454ms ago
2016-12-20 03:41:28.197 [DEBUG] [aveSecureInclusionStateTracker:139 ]- NODE 12: in InclusionStateTracker.getNextRequest() time left for reply: -9280ms, returning null
2016-12-20 03:41:28.226 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ]- Checking transaction complete: Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 0C 03 98 04 00 , callbackid = 9
2016-12-20 03:41:28.261 [DEBUG] [CommandClassWithInitialization:362 ]- NODE 12: call from NodeAdvancer initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
2016-12-20 03:41:28.329 [DEBUG] [CommandClassWithInitialization:390 ]- NODE 12: call from NodeAdvancer initialize, just included, handing back message=[]
2016-12-20 03:41:28.365 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96 ]- Checking transaction complete: Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 09 00 , callbackid = 0
2016-12-20 03:41:28.412 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:107 ]- Checking transaction complete: class=SendData, callback id=9, expected=ApplicationCommandHandler, cancelled=false mismatch
2016-12-20 03:41:28.813 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1230]- NODE 12: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
2016-12-20 03:41:28.861 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 12: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
2016-12-20 03:41:28.899 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1262]- NODE 12: Initialisation retry timer started 800
2016-12-20 03:41:28.969 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer:324 ]- NODE 12: Node advancer: Retries exceeded at SECURITY_REPORT
2016-12-20 03:41:29.026 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:336 ]- NODE 12: Retry timout: Can’t advance

I had this exact issue. The only solution for me was to continuously retry by resetting the lock, excluding the device, then trying to include again until it worked. I literally had to have the lock touching the Z-Stick in just the right place to get a secure pair.

Hello,
I could not successfully pair OpenHAB2.1, Zwave binding 2.1 and Aeon Z-Stick GEN5. I have tried mose of suggestions from the forum here.

throw some lights pls . I think lock is getting out of passion and times-out before openHAB completes secure pairing …? I’m relatively new, Am I missing something?

2017-02-06 20:56:16.870 [ZWaveController ] - ZWave controller start inclusion - mode 2
… ,
2017-02-06 20:56:30.840 [ZWaveController ] - ZWave controller end inclusion
… ,
2017-02-06 20:56:30.840 [ZWaveController ] - NODE 9: Including node.
… ,

2017-02-06 20:57:06.579 [ZWaveNodeInitStageAdvancer] - NODE 9: Initialisation retry timer started 400
2017-02-06 20:57:06.579 [ZWaveNodeInitStageAdvancer] - NODE 9: Node advancer: loop - SECURITY_REPORT try 2: stageAdvanced(false)
2017-02-06 20:57:06.579 [ZWaveNodeInitStageAdvancer] - NODE 9: Since secure inclusion failed, the node must be manually excluded via habmin
2017-02-06 20:57:06.579 [ZWaveNodeInitStageAdvancer] - NODE 9: Node advancer - advancing to APP_VERSION
… ,
2017-02-06 20:57:06.623 [ZWaveNodeInitStageAdvancer] - NODE 9: Initialisation retry timer started 5000
2017-02-06 20:57:06.623 [ZWaveNodeInitStageAdvancer] - NODE 9: Node advancer: loop - APP_VERSION try 1: stageAdvanced(false)
2017-02-06 20:57:06.623 [ZWaveNodeInitStageAdvancer] - NODE 9: Node advancer - advancing to DISCOVERY_COMPLETE
2017-02-06 20:57:06.623 [ZWaveController ] - Notifying event listeners: ZWaveInitializationStateEvent
2017-02-06 20:57:06.623 [ZWaveDiscoveryService ] - NODE 9: Device discovery completed

I just installed openHabian, z-wave binding for my aeon controller and discovered my Schlage Connect lock but it shows as “Unknown device”. Is there a way to make it work?

thanks

Note that this thread is specifically related to the OH1 binding and I think recent posts are probably really asking about OH2 which doesn’t currently support security. There is a test binding which does include security and that’s discussed in a separate thread.