Hi Randy -
Good catch with the “payloadEncapsulationQueue simliar frame check”, I’ve been wanting to look into the user code problems for some time. I’ll fix that in the next build
Dave
1 Like
dbadia
I am having problem in including the schlage lock BE649.
It is node25
2016-06-04 18:53:25.159 [ERROR] [.p.c.ZWaveSecurityCommandClass:821 ]- NODE 25: Error building derived keys java.security.InvalidKeyException: Invalid AES key length: 512 bytes at com.sun.crypto.provider.AESCipher.engineGetKeySize(AESCipher.java:495) ~[sunjce_provider.jar:1.8.0_60] at javax.crypto.Cipher.passCryptoPermCheck(Cipher.java:1067) ~[na:1.8.0_60] at javax.crypto.Cipher.checkCryptoPerm(Cipher.java:1025) ~[na:1.8.0_60] at javax.crypto.Cipher.implInit(Cipher.java:801) ~[na:1.8.0_60] at javax.crypto.Cipher.chooseProvider(Cipher.java:864) ~[na:1.8.0_60] at javax.crypto.Cipher.init(Cipher.java:1249) ~[na:1.8.0_60] at javax.crypto.Cipher.init(Cipher.java:1186) ~[na:1.8.0_60] at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.setupNetworkKey(ZWaveSecurityCommandClass.java:814) [bundlefile:na] at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.<init>(ZWaveSecurityCommandClass.java:336) [bundlefile:na] at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClassWithInitialization.<init>(ZWaveSecurityCommandClassWithInitialization.java:77) [bundlefile:na] at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [na:1.8.0_65] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) [na:1.8.0_65] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [na:1.8.0_65] at java.lang.reflect.Constructor.newInstance(Constructor.java:422) [na:1.8.0_65] at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass.getInstance(ZWaveCommandClass.java:246) [bundlefile:na] at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass.getInstance(ZWaveCommandClass.java:210) [bundlefile:na] at org.openhab.binding.zwave.internal.protocol.serialmessage.IdentifyNodeMessageClass.handleResponse(IdentifyNodeMessageClass.java:132) [bundlefile:na] at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingResponseMessage(ZWaveController.java:266) [bundlefile:na] at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:207) [bundlefile:na] at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$6(ZWaveController.java:199) [bundlefile:na] at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1247) [bundlefile:na] 2016-06-04 18:53:25.163 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class SECURITY to the list of supported command classes. 2016-06-04 18:53:25.166 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC 2016-06-04 18:53:25.169 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class MANUFACTURER_SPECIFIC to the list of supported command classes. 2016-06-04 18:53:25.172 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class DOOR_LOCK 2016-06-04 18:53:25.175 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class DOOR_LOCK to the list of supported command classes. 2016-06-04 18:53:25.177 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class USER_CODE 2016-06-04 18:53:25.180 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class USER_CODE to the list of supported command classes. 2016-06-04 18:53:25.182 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION 2016-06-04 18:53:25.184 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class VERSION to the list of supported command classes. 2016-06-04 18:53:25.189 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83 ]- Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 19 , callbackid = 0 2016-06-04 18:53:25.192 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84 ]- Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 53 DC 00 04 40 03 , callbackid = 0 2016-06-04 18:53:25.196 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ]- Checking transaction complete: Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 19 , callbackid = 0 2016-06-04 18:53:25.200 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96 ]- Checking transaction complete: Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 53 DC 00 04 40 03 , callbackid = 0 2016-06-04 18:53:25.202 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:99 ]- Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false transaction complete! 2016-06-04 18:53:25.205 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent 2016-06-04 18:53:25.207 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent 2016-06-04 18:53:25.212 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true) 2016-06-04 18:53:25.214 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1. 2016-06-04 18:53:25.218 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0. 2016-06-04 18:53:25.221 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - PROTOINFO: queue length(0), free to send(true) 2016-06-04 18:53:25.226 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1240]- NODE 25: Initialisation retry timer started 5000 2016-06-04 18:53:25.228 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false) 2016-06-04 18:53:25.230 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to NEIGHBORS 2016-06-04 18:53:25.234 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true) 2016-06-04 18:53:25.236 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:366 ]- NODE 25: Node advancer: NEIGHBORS - send RoutingInfo 2016-06-04 18:53:25.241 [DEBUG] [p.s.GetRoutingInfoMessageClass:30 ]- NODE 25: Request routing info
2016-06-04 18:54:38.875 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83 ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 04 02 25 02 , callbackid = 57
2016-06-04 18:54:38.878 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84 ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 39 00 00 04 , callbackid = 0
2016-06-04 18:54:38.880 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ]- Checking transaction complete: Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 04 02 25 02 , callbackid = 57
2016-06-04 18:54:38.883 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96 ]- Checking transaction complete: Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 39 00 00 04 , callbackid = 0
2016-06-04 18:54:38.884 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:107 ]- Checking transaction complete: class=SendData, callback id=57, expected=ApplicationCommandHandler, cancelled=false mismatch
2016-06-04 18:54:39.737 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 0F 00 4A FF 02 19 08 04 40 03 22 72 7A 98 86 25
2016-06-04 18:54:39.741 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-06-04 18:54:39.826 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=0
2016-06-04 18:54:39.744 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 0F 00 4A FF 02 19 08 04 40 03 22 72 7A 98 86 25
2016-06-04 18:54:39.840 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 0F 00 4A FF 02 19 08 04 40 03 22 72 7A 98 86 25
2016-06-04 18:54:39.842 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 02 19 08 04 40 03 22 72 7A 98 86 , callbackid = 0
2016-06-04 18:54:39.844 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:81 ]- Add Node: New node found.
2016-06-04 18:54:39.847 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83 ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 04 02 25 02 , callbackid = 57
2016-06-04 18:54:39.850 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84 ]- Recv message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 02 19 08 04 40 03 22 72 7A 98 86 , callbackid = 0
2016-06-04 18:54:39.852 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ]- Checking transaction complete: Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 04 02 25 02 , callbackid = 57
2016-06-04 18:54:39.855 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96 ]- Checking transaction complete: Recv message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 02 19 08 04 40 03 22 72 7A 98 86 , callbackid = 0
2016-06-04 18:54:39.856 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:107 ]- Checking transaction complete: class=AddNodeToNetwork, callback id=57, expected=ApplicationCommandHandler, cancelled=false mismatch
2016-06-04 18:54:39.861 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 0F 00 4A FF 03 19 08 04 40 03 22 72 7A 98 86 24
2016-06-04 18:54:39.865 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=1
2016-06-04 18:54:39.865 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-06-04 18:54:39.869 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 0F 00 4A FF 03 19 08 04 40 03 22 72 7A 98 86 24
2016-06-04 18:54:39.872 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 0F 00 4A FF 03 19 08 04 40 03 22 72 7A 98 86 24
2016-06-04 18:54:39.876 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 03 19 08 04 40 03 22 72 7A 98 86 , callbackid = 0
2016-06-04 18:54:39.879 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:84 ]- NODE 25: Adding slave.
2016-06-04 18:54:39.881 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveInclusionEvent
2016-06-04 18:54:39.883 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ]- ZwaveIncomingEvent
2016-06-04 18:54:39.886 [DEBUG] [b.z.i.protocol.ZWaveController:683 ]- NODE 25: Including node.
2016-06-04 18:54:39.897 [DEBUG] [b.z.i.protocol.ZWaveController:686 ]- NODE 25: Newly included node already exists - not initialising.
2016-06-04 18:54:39.900 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83 ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 04 02 25 02 , callbackid = 57
2016-06-04 18:54:39.903 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84 ]- Recv message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 03 19 08 04 40 03 22 72 7A 98 86 , callbackid = 0
2016-06-04 18:54:39.905 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ]- Checking transaction complete: Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 04 02 25 02 , callbackid = 57
2016-06-04 18:54:39.908 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96 ]- Checking transaction complete: Recv message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 03 19 08 04 40 03 22 72 7A 98 86 , callbackid = 0
2016-06-04 18:54:39.910 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:107 ]- Checking transaction complete: class=AddNodeToNetwork, callback id=57, expected=ApplicationCommandHandler, cancelled=false mismatch
2016-06-04 18:54:39.915 [DEBUG] [eController$ZWaveReceiveThread:1601]- Receive Message = 01 0F 00 4A FF 05 19 08 04 40 03 22 72 7A 98 86 22
2016-06-04 18:54:39.918 [DEBUG] [eController$ZWaveReceiveThread:1517]- Receive queue ADD: Length=1
2016-06-04 18:54:39.918 [DEBUG] [b.z.i.protocol.ZWaveController:1244]- Receive queue TAKE: Length=0
2016-06-04 18:54:39.921 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ]- Assembled message buffer = 01 0F 00 4A FF 05 19 08 04 40 03 22 72 7A 98 86 22
2016-06-04 18:54:39.923 [DEBUG] [b.z.i.protocol.ZWaveController:1245]- Process Message = 01 0F 00 4A FF 05 19 08 04 40 03 22 72 7A 98 86 22
2016-06-04 18:54:39.925 [DEBUG] [b.z.i.protocol.ZWaveController:200 ]- Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 05 19 08 04 40 03 22 72 7A 98 86 , callbackid = 0
2016-06-04 18:54:39.926 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:94 ]- Add Node: Protocol done.
What do you have set for zwave:networkKey in openhab.cfg?
Can you post your inclusion log (if you still have it) and the log when you attempt to lock / unlock?
Can you usually tell a decent amount from that
as per instruction
edit openhab.cfg and add a new entry in the zwave section YOU MUST REPLACE each ## with random hex digits (GRCs password generator is a good source of random numbers):
zwave:networkKey=0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##, 0x##
zwave:networkKey=DA3D8276859E09FE76F38285FCDD363A81C1C3FED7CCFC97C876B7CEE8716156, 5E2B1D09661C3708A66D25FD9D3B56DDBBDDB4753CAF2CF0636BA1D14F06B5A4, DD76C07FA187C9E50AFA5026310887CACE113E51C9A02ED9E2A5DAD96E0E2773, 6132604C16DE2DFB29015B5F38C374CB72CB5878789F67192202554C706B9DC4, 422470B8BA250E4CAA3D2363DC5BD930249A0C2E1585B655771ED9B454084F0E, 0B1BDEF8BB2D003B460537A3D2A508E7C449D3980CF43696040FDEC6B25A0C9E, 753E3DE7C449B00C077F7F0E6BA2073E11ACD6CBBF6EF536532A35B677494B53, 2CA0D94AF0C59908562FD6771996109CE37729F2A06E500DF607A9A75E0CA3B9, 4CE3323CBAFBCC4916DB009812D5AC560F3D97AE0D3EA935ADBAAA706FE1D71C, 5BACA5D85815599FC932489459A187C6EDFA2AAFF409D78F88B4501FD45288D4, 9081F0FA730A640E2F51A2E52877D87DD9C5AB329FB3B140107DAF37FC1FCAF7, 145313C9AA3A624F613263904659B3C569BB940D08CB9B6EDC08325D3D6DF113, 7D63BDF5C1831AE45EC977B350E1348EF821FE03318C123A7DD3FF1F3AB417EC, F473C245A58101A1958AE0A7E20F293A50BADE974BD0993EFF60E61789A2B89E, D94AA37A1C4D669717A53969CE7775D40304F40CAF3B409CA466F4059A5795C8, 5363D31551D50EC921AF4CCAC23F930B1A914E691D4A9C6DC5FAAB98E9A7AF71
Looks like @dbadia spotted the issue - your network key is set to 512 bytes, or 16 blocks of 64 hex digits when OpenHAB and Z-Wave is expecting only 16 pairs of hex digits (16 blocks * 64 digits / 2 to a byte = 512).
Understandably, you’ve followed the instructions to replace ## with random hex digits from GRC’s Perfect Passwords random number generator to the letter, when what was intended was to take the first 32 characters of (say) the 64 generated by GRC and reformat them into 16 pairs like this:
zwave:networkKey=0xAB, 0xCD, 0xEF, 0x01, 0x23, 0x45, 0x67, 0x89, 0xAB, 0xCD, 0xEF, 0x01, 0x23, 0x45, 0x67, 0x89
I’d suggest going back to GRC, generating a new secret block of 64 digits and using the first 32 hex digits to give 16 fresh bytes (pairs like 0xAB) in the format as above.
Why this strange format? It’s a standard way of representing Hexadecimal in languages such as C and Java - see https://en.wikipedia.org/wiki/0X
I changed the key. I took first 32 digits
zwave:networkKey=
BC449EF0B86D81EDC3B36B2B55E7F383,
46DED5F1DDA21F95DF5A8C8C8EBF454E,
F83B82421F3C94FA09591A99B5756F4F,
1227916C9F549BC8877E50110151620F,
08B6928EE177247FC45B1F41813433FD,
B9B108BF64FF1C9D9DC4A67FE779300C,
34A1E613412AA2965F5A5BE799399FD5,
41028F51E2996E9492196E2EAB828D9B,
0F67977DA76CB23DCE5BD72E294597FF,
27CA3D5AB7315294D16CC4C4A3EC671E,
3FD626CA6B9A873C79282BA8F1C80CA0,
C8B4BC973EF1137FB18E658E1E8DFC3C,
CAEF9B66FAD6D1EF1F74E2A83AF3FAE1,
450599BFFE3BC3C65917FEFB201CC7A2,
C698AF34D0C7751E69ABA3656BC978B1,
F60BB15B4BC8D92652976DD15393BBCF
2016-06-14 10:23:50.784 [INFO ] [.p.c.ZWaveSecurityCommandClass] - NODE 26: setupNetworkKey useSchemeZero=false
2016-06-14 10:23:51.539 [ERROR] [.p.c.ZWaveSecurityCommandClass] - NODE 26: Error building derived keys
java.security.InvalidKeyException: Invalid AES key length: 256 bytes
at com.sun.crypto.provider.AESCipher.engineGetKeySize(AESCipher.java:495) ~[sunjce_provider.jar:1.8.0_60]
at javax.crypto.Cipher.passCryptoPermCheck(Cipher.java:1067) ~[na:1.8.0_60]
at javax.crypto.Cipher.checkCryptoPerm(Cipher.java:1025) ~[na:1.8.0_60]
at javax.crypto.Cipher.implInit(Cipher.java:801) ~[na:1.8.0_60]
at javax.crypto.Cipher.chooseProvider(Cipher.java:864) ~[na:1.8.0_60]
at javax.crypto.Cipher.init(Cipher.java:1249) ~[na:1.8.0_60]
at javax.crypto.Cipher.init(Cipher.java:1186) ~[na:1.8.0_60]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.setupNetworkKey(ZWaveSecurityCommandClass.java:814) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.(ZWaveSecurityCommandClass.java:336) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClassWithInitialization.(ZWaveSecurityCommandClassWithInitialization.java:77) [bundlefile:na]
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) [na:1.8.0_65]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) [na:1.8.0_65]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) [na:1.8.0_65]
at java.lang.reflect.Constructor.newInstance(Constructor.java:422) [na:1.8.0_65]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass.getInstance(ZWaveCommandClass.java:246) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass.getInstance(ZWaveCommandClass.java:210) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.serialmessage.IdentifyNodeMessageClass.handleResponse(IdentifyNodeMessageClass.java:132) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingResponseMessage(ZWaveController.java:266) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:207) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$6(ZWaveController.java:199) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1247) [bundlefile:na]
2016-06-14 10:23:53.708 [INFO ] [.p.c.ZWaveSecurityCommandClass] - NODE 26: setupNetworkKey useSchemeZero=true
2016-06-14 10:23:53.710 [INFO ] [.p.c.ZWaveSecurityCommandClass] - NODE 26: Using Scheme0 Network Key for Key Exchange since we are in inclusion mode.)
2016-06-14 10:23:54.016 [INFO ] [CommandClassWithInitialization] - NODE 26: Setting Network Key to real key after SECURITY_NETWORK_KEY_SET
2016-06-14 10:23:54.017 [INFO ] [.p.c.ZWaveSecurityCommandClass] - NODE 26: setupNetworkKey useSchemeZero=false
2016-06-14 10:23:54.023 [ERROR] [.p.c.ZWaveSecurityCommandClass] - NODE 26: Error building derived keys
java.security.InvalidKeyException: Invalid AES key length: 256 bytes
at com.sun.crypto.provider.AESCipher.engineGetKeySize(AESCipher.java:495) ~[sunjce_provider.jar:1.8.0_60]
at javax.crypto.Cipher.passCryptoPermCheck(Cipher.java:1067) ~[na:1.8.0_60]
at javax.crypto.Cipher.checkCryptoPerm(Cipher.java:1025) ~[na:1.8.0_60]
at javax.crypto.Cipher.implInit(Cipher.java:801) ~[na:1.8.0_60]
at javax.crypto.Cipher.chooseProvider(Cipher.java:864) ~[na:1.8.0_60]
at javax.crypto.Cipher.init(Cipher.java:1249) ~[na:1.8.0_60]
at javax.crypto.Cipher.init(Cipher.java:1186) ~[na:1.8.0_60]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.setupNetworkKey(ZWaveSecurityCommandClass.java:814) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClassWithInitialization.transmitMessage(ZWaveSecurityCommandClassWithInitialization.java:103) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.sendNextMessageUsingDeviceNonce(ZWaveSecurityCommandClass.java:763) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClassWithInitialization.notifyEncapsulationThread(ZWaveSecurityCommandClassWithInitialization.java:122) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.handleApplicationCommandRequest(ZWaveSecurityCommandClass.java:397) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClassWithInitialization.handleApplicationCommandRequest(ZWaveSecurityCommandClassWithInitialization.java:246) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationCommandMessageClass.handleRequest(ApplicationCommandMessageClass.java:115) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:231) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:204) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$6(ZWaveController.java:199) [bundlefile:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1247) [bundlefile:na]
2016-06-14 10:23:54.048 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 26: Sent Data was not placed on stack due to error 0.
2016-06-14 10:23:57.116 [INFO ] [b.z.i.protocol.ZWaveController] - Ending inclusion mode
2016-06-14 10:23:58.451 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 26: Node advancer: Retries exceeded at SECURITY_REPORT
2016-06-14 10:23:59.035 [ERROR] [WaveController$ZWaveSendThread] - NODE 26: Timeout while sending message. Requeueing - 2 attempts left!
2016-06-14 10:23:59.037 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 26: Got an error while sending data. Resending message.
2016-06-14 10:23:59.100 [WARN ] [.i.p.c.ZWaveSecureNonceTracker] - NODE 26: Expiring nonce with id=64
2016-06-14 10:23:59.161 [ERROR] [.z.i.config.ZWaveConfiguration] - Neither inclusion nor exclusion was active!
2016-06-14 10:24:04.052 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer] - NODE 26: Node advancer: Retries exceeded at SECURITY_REPORT
Hi @balmurgan,
I’m sorry, that won’t work - OpenHAB is expecting the networkKey to be 16 comma-separated pairs of hex characters, not (16 * 32 / 2) bytes.
That is why it is giving the error:
java.security.InvalidKeyException: Invalid AES key length: 256 bytes
For example, I went to GRC and generated ‘64 random hexadecimal characters’:
0DC82985DCC2B56D8CB860CB411BFAA6BD5E0CDB3D8429494621285E7DA2BC62
For use in OpenHAB, you only need 32 characters, so as an example here are the first 32 reformatted into pairs with the hex prefix giving:
zwave:networkKey=0x0D, 0xC8, 0x29, 0x85, 0xDC, 0xC2, 0xB5, 0x6D, 0x8C, 0xB8, 0x60, 0xCB, 0x41, 0x1B, 0xFA, 0xA6
Count the digits - 16 pairs of two characters, not the whole, and much longer GRC generated number.
You need to generate your own random digits and reformat them to keep the key secret - it is your Z-Wave password.
1 Like
Thank you. I am able to add my lock
two things
Why no Associatian Groups or Wakeup configuration in habmin for this zwave device
Also log shows
Device message contained nonce that is unknown to us
Appreciate your help
Hi @balmurgan,
Unfortunately, I don’t have any lock devices and have been testing against Fibaro FGD-212 dimmers which can support similar Z-Wave Plus secure comms.
That said, I recognise a few things which might help.
Other Z-Wave battery devices don’t respond to polling from the controller to the device deliberately to save battery (no refresh interval), but some do allow configuration of the time the device sleeps before talking back to the controller - the wakeup interval. Manually changing the device state can also wake it up and trigger comms with the controller (move the handle or press the keypad?)
Your previous logs suggest you are using OpenHAB v1 (1.8.0?), with a Schlage BE649 - have you tried looking in HABmin for config parameters?
The BE649 isn’t in the OpenHAB 2 database, but this is something you can fix for the future…
http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-database-guide
The nonce error messages appeared regularly in my own logs (changed in OH2), and a search with the exact text shows a few other posts which may be helpful:
[col.security.ZWaveSecureNonceTracker] - NODE x: Device message contained nonce that is unknown to us
[DEBUG] [col.security.ZWaveSecureNonceTracker] - NODE x: Generated new nonce for device:
[DEBUG] [col.security.ZWaveSecureNonceTracker] - NODE x: Device message contained nonce id of id=0xXX, found matching nonce of: Nonce GENERATED
Good luck!
Thank you for the help. I am able to view all the details in habmin1.
Thank you for your work in getting the binding to support the secure command classes. I’ve had some very good results using it to associate my Kwikset 910.
However I recently added an Aeotec door sensor (ZW089-A) which seems to declare the SECURITY command class as well, but the association does not complete.
Has anyone had success associating this type of sensor with the secure z-wave binding?
Is there a way to disable the secure association for this particular device?
I see this error in my openhab log if I hit the wake button on the sensor after the inclusion has complete (successfully? I’m not sure):
22:34:29.015 [DEBUG] [eController$ZWaveReceiveThread:1601 ] - Receive Message = 01 04 01 60 01 9B
22:34:29.016 [DEBUG] [eController$ZWaveReceiveThread:1517 ] - Receive queue ADD: Length=1
22:34:29.016 [DEBUG] [b.z.i.protocol.ZWaveController:1244 ] - Receive queue TAKE: Length=0
22:34:29.017 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ] - Assembled message buffer = 01 04 01 60 01 9B
22:34:29.018 [DEBUG] [b.z.i.protocol.ZWaveController:1245 ] - Process Message = 01 04 01 60 01 9B
22:34:29.018 [DEBUG] [b.z.i.protocol.ZWaveController:200 ] - Message: class = RequestNodeInfo (0x60), type = Response (0x01), payload = 01 , callbackid = 0
22:34:29.018 [DEBUG] [.s.RequestNodeInfoMessageClass:41 ] - Request node info successfully placed on stack.
22:34:29.019 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83 ] - Sent message Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 0A , callbackid = 0
22:34:29.020 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84 ] - Recv message Message: class = RequestNodeInfo (0x60), type = Response (0x01), payload = 01 , callbackid = 0
22:34:29.020 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Checking transaction complete: Sent message Message: class = RequestNodeInfo (0x60), type = Request (0x00), payload = 0A , callbackid = 0
22:34:29.021 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96 ] - Checking transaction complete: Recv message Message: class = RequestNodeInfo (0x60), type = Response (0x01), payload = 01 , callbackid = 0
22:34:29.021 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:107 ] - Checking transaction complete: class=RequestNodeInfo, callback id=0, expected=ApplicationUpdate, cancelled=false mismatch
22:34:29.059 [DEBUG] [eController$ZWaveReceiveThread:1601 ] - Receive Message = 01 1A 00 49 84 0A 14 04 07 01 5E 30 80 84 70 85 59 71 86 72 73 7A 98 EF 5A 82 00 D1
22:34:29.061 [DEBUG] [eController$ZWaveReceiveThread:1517 ] - Receive queue ADD: Length=1
22:34:29.061 [DEBUG] [b.z.i.protocol.ZWaveController:1244 ] - Receive queue TAKE: Length=0
22:34:29.062 [DEBUG] [o.b.z.i.protocol.SerialMessage:255 ] - Assembled message buffer = 01 1A 00 49 84 0A 14 04 07 01 5E 30 80 84 70 85 59 71 86 72 73 7A 98 EF 5A 82 00 D1
22:34:29.063 [DEBUG] [b.z.i.protocol.ZWaveController:1245 ] - Process Message = 01 1A 00 49 84 0A 14 04 07 01 5E 30 80 84 70 85 59 71 86 72 73 7A 98 EF 5A 82 00 D1
22:34:29.064 [DEBUG] [b.z.i.protocol.ZWaveController:200 ] - Message: class = ApplicationUpdate (0x49), type = Request (0x00), payload = 84 0A 14 04 07 01 5E 30 80 84 70 85 59 71 86 72 73 7A 98 EF 5A 82 00 , callbackid = 0
22:34:29.065 [DEBUG] [.ApplicationUpdateMessageClass:49 ] - NODE 10: Application update request. Node information received.
22:34:29.065 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:237 ] - NODE 10: Unsupported command class ZWAVE_PLUS_INFO
22:34:29.066 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:237 ] - NODE 10: Unsupported command class ASSOCIATION_GROUP_INFO
22:34:29.067 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:237 ] - NODE 10: Unsupported command class POWERLEVEL
22:34:29.067 [WARN ] [.o.b.z.i.p.c.ZWaveCommandClass:237 ] - NODE 10: Unsupported command class FIRMWARE_UPDATE_MD
22:34:29.068 [DEBUG] [b.z.i.protocol.ZWaveController:668 ] - NODE 10: Notifying event listeners: ZWaveNodeInfoEvent
22:34:29.068 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ] - ZwaveIncomingEvent
22:34:29.068 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164 ] - NODE 10: 10 NIF event during initialisation stage DETAILS
22:34:29.069 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1174 ] - NODE 10: NIF event during initialisation stage DETAILS
22:34:29.069 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ] - NODE 10: Node advancer - DETAILS: queue length(1), free to send(false)
22:34:29.069 [DEBUG] [b.z.i.protocol.ZWaveController:651 ] - Enqueueing message. Queue length = 1
22:34:29.070 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ] - NODE 10: Node advancer - queued packet. Queue length is 1
22:34:29.070 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164 ] - NODE 10: 10 NIF event during initialisation stage SECURITY_REPORT
22:34:29.070 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1174 ] - NODE 10: NIF event during initialisation stage SECURITY_REPORT
22:34:29.071 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ] - NODE 10: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
22:34:29.071 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer:324 ] - NODE 10: Node advancer: Retries exceeded at SECURITY_REPORT
22:34:29.071 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:336 ] - NODE 10: Retry timout: Can’t advance
22:34:29.072 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:449 ] - NODE 10: Is awake with 0 messages in the wake-up queue.
22:34:29.073 [DEBUG] [b.z.i.protocol.ZWaveController:668 ] - NODE 10: Notifying event listeners: ZWaveWakeUpEvent
22:34:29.073 [DEBUG] [.z.internal.ZWaveActiveBinding:455 ] - ZwaveIncomingEvent
22:34:29.074 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1140 ] - NODE 10: Wakeup during initialisation.
22:34:29.074 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ] - NODE 10: Node advancer - DETAILS: queue length(1), free to send(false)
22:34:29.074 [DEBUG] [b.z.i.protocol.ZWaveController:651 ] - Enqueueing message. Queue length = 2
22:34:29.075 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ] - NODE 10: Node advancer - queued packet. Queue length is 1
22:34:29.075 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1140 ] - NODE 10: Wakeup during initialisation.
22:34:29.075 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ] - NODE 10: Node advancer - SECURITY_REPORT: queue length(0), free to send(true)
22:34:29.076 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 10: Node advancer: loop - SECURITY_REPORT try 1: stageAdvanced(false)
22:34:29.076 [DEBUG] [CommandClassWithInitialization:317 ] - NODE 10: call from NodeAdvancer initialize, firstIteration=false, wasThisNodeJustIncluded=true, keyVerifyReceived=false, lastReceivedMessage=1468017269076ms ago, lastSentMessage=1468017269076ms ago
22:34:29.087 [ERROR] [b.z.i.protocol.ZWaveController:1252 ] - Exception during Z-Wave thread: Input.
java.lang.NullPointerException: null
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClassWithInitialization.initialize(ZWaveSecurityCommandClassWithInitialization.java:360) ~[na:na]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer.advanceNodeStage(ZWaveNodeStageAdvancer.java:456) ~[na:na]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer.ZWaveIncomingEvent(ZWaveNodeStageAdvancer.java:1143) ~[na:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:671) ~[na:na]
at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass.setAwake(ZWaveWakeUpCommandClass.java:455) ~[na:na]
at org.openhab.binding.zwave.internal.protocol.serialmessage.ApplicationUpdateMessageClass.handleRequest(ApplicationUpdateMessageClass.java:116) ~[na:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:231) ~[na:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:204) ~[na:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$6(ZWaveController.java:199) ~[na:na]
at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1247) ~[na:na]
Hello;
I am wondering if anyone has come across a set of instructions… I have put debug on and saw a pair… But I cannot for th life of me figure out why I cannot control the device.
Any suggestions on where to start?
Thanks!
There are instructions at https://github.com/openhab/openhab/wiki/ZWave-Security-Testing
That said, I’m running OH1.8.3. What’s the best place to find the most recent zwave binding with the security class support? The link referenced above is to a build that’s 4 months old.
I do have a branch that is merged, but I’m slightly hesitant to actually merge it into master in case it causes problems elsewhere. I’ll have a think about this, and a way to back out again if there are problems reported.
You’d make us happy for sure! Even if a manual download and replace, having the 1.8.3 version with security would be awesome.
info on building your branch would be fine with me as well. we can test for you 
You can get the branch here. Feedback welcome - I know a couple of people are running this so it should be fine - if all’s good then we can look to merge it.