Z-wave (Schlage) Lock Support on OH1

nolan_garrett · November 18, 2016, 9:47pm

I am using 1.8.3 with the 1.9 build from Cloudbees.

ptmuldoon · November 19, 2016, 9:07pm

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?

nolan_garrett · November 19, 2016, 9:39pm

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

wificordon · November 21, 2016, 3:56pm

Thanks @dbadia.

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

ptmuldoon · November 25, 2016, 6:33pm

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.

carilwang · December 20, 2016, 3:50am

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

nolan_garrett · December 27, 2016, 4:29am

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.

amookkaiah · February 7, 2017, 7:08am

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

JPelletier · March 24, 2017, 12:39am

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

chris · March 24, 2017, 7:19am

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.