Hi all,
I have tried to securely include yale lock. But it failed at SECURITY_NETWORK_KEY_SET using snapshot 2.4. I have successfully include it in snapshot 2.3.0.201801212218. But it does not work any more in 2.4
Can anyone help? @chris
Here is some logs
12:03:04.811 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 11: Response processed after 2613ms/2613ms.
12:03:04.832 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
12:03:04.855 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 2D 00 13 0B 26 98 81 A1 09 EB 0E 92 65 3E 56 5C 16 37 4A 53 3B 88 65 F1 C7 FF 08 AD 6A C2 7B D0 EB E8 19 B9 B4 63 F3 33 C3 C4 69 25 5B 5E
12:03:04.895 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 2D 00 13 0B 26 98 81 A1 09 EB 0E 92 65 3E 56 5C 16 37 4A 53 3B 88 65 F1 C7 FF 08 AD 6A C2 7B D0 EB E8 19 B9 B4 63 F3 33 C3 C4 69 25 5B 5E
12:03:04.966 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
12:03:04.993 [DEBUG] [ave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
12:03:05.005 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 5B 00 00 03 B3
12:03:05.021 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:05.016 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
12:03:05.119 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(false)
12:03:05.105 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 0B 02 98 40 22
12:03:05.164 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:05.139 [DEBUG] [ave.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
12:03:05.205 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 1: stageAdvanced(false)
12:03:05.223 [DEBUG] [ave.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
12:03:05.248 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=2113ms, lastTxMsg=1220ms
12:03:05.276 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 11: Sent Data successfully placed on stack.
12:03:05.306 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -9287ms, returning null
12:03:05.328 [DEBUG] [ave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=1
12:03:05.356 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:05.374 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 5B 00 00 03 00 00 BD
12:03:05.406 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:05.428 [DEBUG] [ave.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 5B 00 00 03 00 00 BD
12:03:05.472 [DEBUG] [ave.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5B 00 00 03
12:03:05.502 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 11: SendData Request. CallBack ID = 91, Status = Transmission complete and ACK received(0)
12:03:05.532 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=11, callback=91, payload=0B 12 98 06 CC 0C 12 C8 70 68 9D AE 15 AC 12 C2 EA 0B 23 1B
12:03:05.577 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5B 00 00 03
12:03:05.613 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=91, expected=ApplicationCommandHandler, cancelled=false MISMATCH
12:03:05.648 [DEBUG] [ave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
12:03:05.666 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 0B 02 98 40 22
12:03:05.689 [DEBUG] [ave.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 0B 02 98 40 22
12:03:05.710 [DEBUG] [ave.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0B 02 98 40
12:03:05.743 [DEBUG] [essage.ApplicationCommandMessageClass] - NODE 11: Application Command Request (ALIVE:SECURITY_REPORT)
12:03:05.767 [DEBUG] [essage.ApplicationCommandMessageClass] - NODE 11: Incoming command class SECURITY
12:03:05.788 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Received SECURITY command V0
12:03:05.810 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: ZWaveSecurityCommandClass in verifyAndAdvanceState with newstep=SECURITY_NONCE_GET, currentstep=SECURITY_NETWORK_KEY_SET
12:03:05.845 [DEBUG] [ommandclass.ZWaveSecurityCommandClass] - NODE 11: Received SECURITY_NONCE_GET
12:03:05.866 [ERROR] [ocol.security.ZWaveSecureNonceTracker] - NODE 11: SECURITY_ERROR Device message contained nonce that is unknown to us, id=30.
12:03:05.896 [DEBUG] [ocol.security.ZWaveSecureNonceTracker] - NODE 11: Nonce id=30 table={}, expiredList=[], usedList=[]
12:03:05.922 [DEBUG] [ocol.security.ZWaveSecureNonceTracker] - NODE 11: Generated new nonce for device: 1E B2 05 C3 B1 0C 9F 1A
12:03:05.950 [DEBUG] [ave.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
12:03:05.964 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:05.975 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=11, callback=91, payload=0B 12 98 06 CC 0C 12 C8 70 68 9D AE 15 AC 12 C2 EA 0B 23 1B
12:03:06.003 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:06.046 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payloa d=00 0B 02 98 40
12:03:06.069 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:06.115 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=91, expected=ApplicationCommandHandler, cancelled=false transact ion complete!
12:03:06.135 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 2: stageAdvanced(false)
12:03:06.173 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
12:03:06.196 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=351ms, lastTxMsg=2169ms
12:03:06.218 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: updating lastSentMessageTimestamp
12:03:06.255 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -8338ms, returning null
12:03:06.276 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: Transaction complete (SendData:Request) success(true)
12:03:06.332 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - checking initialisation queue. Queue size 0.
12:03:06.303 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:06.359 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - In Security stage, going to advanceNodeStage to get next request.
12:03:06.392 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:06.418 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:06.468 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 400
12:03:06.491 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 3: stageAdvanced(false)
12:03:06.517 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=672ms, lastTxMsg=241ms
12:03:06.550 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -8043ms, returning null
12:03:06.580 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:06.616 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:06.641 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: updating lastSentMessageTimestamp
12:03:06.663 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 11: Response processed after 1727ms/2613ms.
12:03:06.682 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
12:03:06.703 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 11 00 13 0B 0A 98 80 1E B2 05 C3 B1 0C 9F 1A 05 5C EF
12:03:06.729 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 11 00 13 0B 0A 98 80 1E B2 05 C3 B1 0C 9F 1A 05 5C EF
12:03:06.793 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
12:03:06.819 [DEBUG] [ave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
12:03:06.835 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 5C 00 00 02 B5
12:03:06.842 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
12:03:06.868 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1C 00 04 00 0B 16 98 81 21 10 D8 C5 A5 2B A0 16 DE 16 E0 1E 32 ED F5 2D 0E E8 45 7C 19
12:03:06.868 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:06.889 [DEBUG] [ave.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
12:03:06.956 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
12:03:06.943 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:06.985 [DEBUG] [ave.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
12:03:06.962 [DEBUG] [ave.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
12:03:07.031 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
12:03:07.011 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:07.085 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 09 00 00 03 72
12:03:07.057 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 11: Sent Data successfully placed on stack.
12:03:07.129 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 07 00 80 09 00 00 03 72
12:03:07.106 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 4: stageAdvanced(false)
12:03:07.148 [DEBUG] [ave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=1
12:03:07.249 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=1404ms, lastTxMsg=973ms
12:03:07.258 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 5C 00 00 02 00 00 BB
12:03:07.287 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -7306ms, returning null
12:03:07.309 [DEBUG] [ave.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 5C 00 00 02 00 00 BB
12:03:07.357 [DEBUG] [ave.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5C 00 00 02
12:03:07.336 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:07.387 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 11: SendData Request. CallBack ID = 92, Status = Transmission complete and ACK received(0)
12:03:07.418 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:07.446 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=11, callback=92, payload=0B 0A 98 80 1E B2 05 C3 B1 0C 9F 1A
12:03:07.512 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5C 00 00 02
12:03:07.548 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=92, expected=ApplicationCommandHandler, cancelled=false MISMATCH
12:03:07.582 [DEBUG] [ave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
12:03:07.600 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1C 00 04 00 0B 16 98 81 21 10 D8 C5 A5 2B A0 16 DE 16 E0 1E 32 ED F5 2D 0E E8 45 7C 19
12:03:07.631 [DEBUG] [ave.internal.protocol.ZWaveController] - Process Message = 01 1C 00 04 00 0B 16 98 81 21 10 D8 C5 A5 2B A0 16 DE 16 E0 1E 32 ED F5 2D 0E E8 45 7C 19
12:03:07.661 [DEBUG] [ave.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 0B 16 98 81 21 10 D8 C5 A5 2B A 0 16 DE 16 E0 1E 32 ED F5 2D 0E E8 45 7C
12:03:07.702 [DEBUG] [essage.ApplicationCommandMessageClass] - NODE 11: Application Command Request (ALIVE:SECURITY_REPORT)
12:03:07.726 [DEBUG] [essage.ApplicationCommandMessageClass] - NODE 11: Incoming command class SECURITY
12:03:07.747 [DEBUG] [essage.ApplicationCommandMessageClass] - NODE 11: Preparing to decrypt security encapsulated message, messagePayload=00 0B 16 98 81 21 10 D8 C5 A5 2B A0 16 DE 16 E0 1E 32 ED F5 2D 0E E8 45 7C
12:03:07.785 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1C 00 04 00 0B 16 98 81 21 10 D8 C5 A5 2B A0 16 DE 16 E0 1E 32 ED F5 2D 0E E8 45 7C 19
12:03:07.812 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:07.818 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1C 00 04 00 0B 16 98 81 21 10 D8 C5 A5 2B A0 16 DE 16 E0 1E 32 ED F5 2D 0E E8 45 7C 19
12:03:07.842 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:07.873 [DEBUG] [ocol.security.ZWaveSecureNonceTracker] - NODE 11: Device message contained nonce id of id=30, found matching nonce of: Nonce GENERATED 1E B2 05 C3 B1 0C 9F 1A ; time left=8049
12:03:07.901 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:07.940 [DEBUG] [ommandclass.ZWaveSecurityCommandClass] - NODE 11: SECURITY_RECEIVED 00 98 07
12:03:07.961 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 5: stageAdvanced(false)
12:03:07.982 [DEBUG] [ity.SecurityEncapsulatedSerialMessage] - NODE 11: securityTransactionComplete=false, payload=(0B 12 98 06 CC 0C 12 C8 70 68 9D AE 15 AC 12 C2 EA 0B 23 1B ), transmitted=true, msSinceTransm itted=3046, ackWaiting=true
12:03:08.009 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=2164ms, lastTxMsg=1733ms
12:03:08.051 [DEBUG] [ity.SecurityEncapsulatedSerialMessage] - NODE 11: securityReponseReceived=true for 00 98 07 . Class: want=SECURITY,got=SECURITY; Command: want=ANY,got=07
12:03:08.080 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -6513ms, returning null
12:03:08.112 [WARN ] [ommandclass.ZWaveSecurityCommandClass] - NODE 11: payloadQueue was empty, returning!
12:03:08.140 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:08.161 [DEBUG] [essage.ApplicationCommandMessageClass] - NODE 11: Unknown command class 0xffffff98
12:03:08.192 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:08.701 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:08.727 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:08.752 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:08.775 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: Retries exceeded at SECURITY_REPORT
12:03:08.797 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Retry timout: Can't advance
12:03:09.552 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 1600
12:03:09.577 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:09.602 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 1600
12:03:09.622 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 1: stageAdvanced(false)
12:03:09.646 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=3801ms, lastTxMsg=3370ms
12:03:09.675 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -4918ms, returning null
12:03:09.703 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:09.734 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:11.201 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:11.225 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:11.249 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:11.268 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 2: stageAdvanced(false)
12:03:11.280 [DEBUG] [ave.internal.protocol.ZWaveController] - Ending inclusion mode.
12:03:11.302 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=5457ms, lastTxMsg=5026ms
12:03:11.309 [DEBUG] [ave.internal.protocol.ZWaveController] - Stopping inclusion timer.
12:03:11.341 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -3252ms, returning null
12:03:11.355 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
12:03:11.382 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:11.397 [DEBUG] [ave.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
12:03:11.427 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:11.444 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWave controller end inclusion
12:03:11.759 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
12:03:11.791 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message.
12:03:11.812 [DEBUG] [ave.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
12:03:11.832 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
12:03:11.853 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 11 00 13 0B 0A 98 80 1E B2 05 C3 B1 0C 9F 1A 05 5D EE
12:03:11.877 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 11: Sending REQUEST Message = 01 11 00 13 0B 0A 98 80 1E B2 05 C3 B1 0C 9F 1A 05 5D EE
12:03:11.913 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
12:03:11.951 [DEBUG] [ave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
12:03:11.970 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
12:03:11.990 [DEBUG] [ave.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
12:03:12.009 [DEBUG] [ave.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
12:03:12.036 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 11: Sent Data successfully placed on stack.
12:03:12.050 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:12.082 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:12.151 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:12.172 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 3: stageAdvanced(false)
12:03:12.196 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=6351ms, lastTxMsg=5920ms
12:03:12.219 [DEBUG] [tocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=GetRoutingInfo[0x80], type=Request[0x00], priority=High, dest=255, callback=0, paylo ad=09 00 00 03
12:03:12.226 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -2367ms, returning null
12:03:12.287 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:12.318 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:12.951 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:12.976 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:13.001 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:13.021 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 4: stageAdvanced(false)
12:03:13.047 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=7202ms, lastTxMsg=6771ms
12:03:13.077 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -1516ms, returning null
12:03:13.105 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:13.142 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:13.197 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 5D 00 00 81 37
12:03:13.224 [DEBUG] [ave.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
12:03:13.244 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 5D 00 00 81 00 00 39
12:03:13.269 [DEBUG] [ave.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 5D 00 00 81 00 00 39
12:03:13.291 [DEBUG] [ave.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5D 00 00 81
12:03:13.321 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 11: SendData Request. CallBack ID = 93, Status = Transmission complete and ACK received(0)
12:03:13.351 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=11, callback=93, payload=0B 0A 98 8 0 1E B2 05 C3 B1 0C 9F 1A
12:03:13.389 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=5D 00 00 81
12:03:13.425 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=93, expected=ApplicationCommandHandler, cancelled=false MISMATCH
12:03:13.801 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:13.826 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:13.849 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:13.869 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 5: stageAdvanced(false)
12:03:13.893 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=8048ms, lastTxMsg=7617ms
12:03:13.923 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: -670ms, returning null
12:03:13.950 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:13.981 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, just included, handing back message=[]
12:03:14.649 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 800
12:03:14.674 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:14.698 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 800
12:03:14.718 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: Retries exceeded at SECURITY_REPORT
12:03:14.740 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Retry timout: Can't advance
12:03:15.499 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Stage SECURITY_REPORT. Initialisation retry timer triggered. Increased to 1600
12:03:15.523 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
12:03:15.546 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Initialisation retry timer started 1600
12:03:15.565 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer: loop - SECURITY_REPORT try 1: stageAdvanced(false)
12:03:15.588 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: SECURITY_INITIALIZE Initialising=false, Inclusion=true, Paired=false, lastRxMsg=9743ms, lastTxMsg=9312ms
12:03:15.616 [DEBUG] [rity.ZWaveSecureInclusionStateTracker] - NODE 11: in InclusionStateTracker.getNextRequest() time left for reply: 1023ms, returning null
12:03:15.642 [DEBUG] [ecurityCommandClassWithInitialization] - NODE 11: Security.initialize, inclusion flow, get the next message or wait for a response to the current one, nextMessage=null
12:03:15.673 [ERROR] [ecurityCommandClassWithInitialization] - NODE 11: **SECURITY_INCLUSION_FAILED Failed at step SECURITY_NETWORK_KEY_SET: 10000ms passed since last request was sent, secure inclusion failed.**
12:03:15.705 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Since secure inclusion failed, the node must be manually excluded via habmin
12:03:15.729 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 11: Node advancer - advancing to APP_VERSION