@chris, I tried the latest build as I saw you were working on some of the alarm processing related to locks. When I unlock manually from the handset, I’m getting an exception trying to decrypt the packet.
Log snippet:
2016-04-28 19:08:09.401 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 09 02 98 40 20
2016-04-28 19:08:09.404 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-04-28 19:08:09.405 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 09 02 98 40 20
2016-04-28 19:08:09.407 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 09 02 98 40 20
2016-04-28 19:08:09.408 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 09 02 98 40
2016-04-28 19:08:09.409 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Application Command Request (ALIVE:DYNAMIC_VALUES)
2016-04-28 19:08:09.410 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Incoming command class SECURITY
2016-04-28 19:08:09.411 [DEBUG] [curityCommandClassWithInitialization] - NODE 9: Received Security Message 0x40 SECURITY_NONCE_GET
2016-04-28 19:08:09.412 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 9: Received SECURITY_NONCE_GET
2016-04-28 19:08:09.413 [ERROR] [col.security.ZWaveSecureNonceTracker] - NODE 9: Device message contained nonce that is unknown to us, id=0x85, table={}, expiredList=[], usedList=[79, 120, 81, 50, 0, 80, 51, -91, -44, -120]
2016-04-28 19:08:09.414 [DEBUG] [col.security.ZWaveSecureNonceTracker] - NODE 9: Generated new nonce for device: 85 FC 4E 0D 11 2E F6 6A
2016-04-28 19:08:09.416 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2016-04-28 19:08:09.416 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2016-04-28 19:08:09.418 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=9, callback=27, payload=09 0A 98 80 88 07 12 15 78 83 99 AC
2016-04-28 19:08:09.418 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 11 00 13 09 0A 98 80 85 FC 4E 0D 11 2E F6 6A 05 1F 65
2016-04-28 19:08:09.420 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 9: Sending REQUEST Message = 01 11 00 13 09 0A 98 80 85 FC 4E 0D 11 2E F6 6A 05 1F 65
2016-04-28 19:08:09.421 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 09 02 98 40
2016-04-28 19:08:09.422 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=27, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2016-04-28 19:08:09.426 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-04-28 19:08:09.429 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2016-04-28 19:08:09.432 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-04-28 19:08:09.434 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 9: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2016-04-28 19:08:09.435 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 9: Node advancer - checking initialisation queue. Queue size 3.
2016-04-28 19:08:09.437 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-04-28 19:08:09.437 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 9: Response processed after 16ms/1623ms.
2016-04-28 19:08:09.440 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2016-04-28 19:08:09.442 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2016-04-28 19:08:09.443 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2016-04-28 19:08:09.446 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: Sent Data successfully placed on stack.
2016-04-28 19:08:09.448 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 1F 00 00 02 F6
2016-04-28 19:08:09.451 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-04-28 19:08:09.453 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 1F 00 00 02 00 00 F8
2016-04-28 19:08:09.456 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 1F 00 00 02 00 00 F8
2016-04-28 19:08:09.458 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=1F 00 00 02
2016-04-28 19:08:09.459 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: SendData Request. CallBack ID = 31, Status = Transmission complete and ACK received(0)
2016-04-28 19:08:09.462 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=9, callback=31, payload=09 0A 98 80 85 FC 4E 0D 11 2E F6 6A
2016-04-28 19:08:09.463 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=1F 00 00 02
2016-04-28 19:08:09.465 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=31, expected=ApplicationCommandHandler, cancelled=false MISMATCH
2016-04-28 19:08:09.471 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 04 00 09 18 98 81 9A 51 35 2E 9A 17 EA 7A 96 F3 F0 25 52 85 37 A0 95 51 EB 63 AB DA ED
2016-04-28 19:08:09.475 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2016-04-28 19:08:09.478 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1E 00 04 00 09 18 98 81 9A 51 35 2E 9A 17 EA 7A 96 F3 F0 25 52 85 37 A0 95 51 EB 63 AB DA ED
2016-04-28 19:08:09.480 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 1E 00 04 00 09 18 98 81 9A 51 35 2E 9A 17 EA 7A 96 F3 F0 25 52 85 37 A0 95 51 EB 63 AB DA ED
2016-04-28 19:08:09.483 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 09 18 98 81 9A 51 35 2E 9A 17 EA 7A 96 F3 F0 25 52 85 37 A0 95 51 EB 63 AB DA
2016-04-28 19:08:09.484 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Application Command Request (ALIVE:DYNAMIC_VALUES)
2016-04-28 19:08:09.486 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Incoming command class SECURITY
2016-04-28 19:08:09.488 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Preparing to decrypt security encapsulated message, messagePayload=00 09 18 98 81 9A 51 35 2E 9A 17 EA 7A 96 F3 F0 25 52 85 37 A0 95 51 EB 63 AB DA
2016-04-28 19:08:09.490 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1E 00 04 00 09 18 98 81 9A 51 35 2E 9A 17 EA 7A 96 F3 F0 25 52 85 37 A0 95 51 EB 63 AB DA ED
2016-04-28 19:08:09.493 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 1E 00 04 00 09 18 98 81 9A 51 35 2E 9A 17 EA 7A 96 F3 F0 25 52 85 37 A0 95 51 EB 63 AB DA ED
2016-04-28 19:08:09.495 [DEBUG] [col.security.ZWaveSecureNonceTracker] - NODE 9: Device message contained nonce id of id=0x85, found matching nonce of: Nonce GENERATED 85 FC 4E 0D 11 2E F6 6A ; time left=9919
2016-04-28 19:08:09.497 [ERROR] [mmandclass.ZWaveSecurityCommandClass] - NODE 9: Error decrypting packet
java.security.InvalidKeyException: No installed provider supports this key: (null)
at javax.crypto.Cipher.chooseProvider(Cipher.java:888)[:1.8.0]
at javax.crypto.Cipher.init(Cipher.java:1370)[:1.8.0]
at javax.crypto.Cipher.init(Cipher.java:1301)[:1.8.0]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.decryptMessage(ZWaveSecurityCommandClass.java:505)[164:org.openhab.binding.zwave:2.0.0.201604262000]
at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:75)[164:org.openhab.binding.zwave:2.0.0.201604262000]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:247)[164:org.openhab.binding.zwave:2.0.0.201604262000]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:213)[164:org.openhab.binding.zwave:2.0.0.201604262000]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$6(ZWaveController.java:207)[164:org.openhab.binding.zwave:2.0.0.201604262000]
at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1091)[164:org.openhab.binding.zwave:2.0.0.201604262000]
2016-04-28 19:08:09.500 [ERROR] [ssage.ApplicationCommandMessageClass] - NODE 9: Failed to decrypt message out of Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 09 18 98 81 9A 51 35 2E 9A 17 EA 7A 96 F3 F0 25 52 85 37 A0 95 51 EB 63 AB DA .
2016-04-28 19:08:09.502 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Immediate, dest=9, callback=31, payload=09 0A 98 80 85 FC 4E 0D 11 2E F6 6A
2016-04-28 19:08:09.504 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 09 18 98 81 9A 51 35 2E 9A 17 EA 7A 96 F3 F0 25 52 85 37 A0 95 51 EB 63 AB DA
2016-04-28 19:08:09.506 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=31, expected=ApplicationCommandHandler, cancelled=false transaction complete!
2016-04-28 19:08:09.507 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2016-04-28 19:08:09.508 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2016-04-28 19:08:09.509 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 9: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2016-04-28 19:08:09.510 [DEBUG] [nitialization.ZWaveNodeStageAdvancer] - NODE 9: Node advancer - checking initialisation queue. Queue size 3.