OH2 and ZWave Locks

Fundimentally, it looks ok. The device included and completed all the security steps -:

NODE 9: Secure inclusion complete, continuing with inclusion

I think the main (maybe only) issue is that the device isn’t in the database -:

NODE 9: Device could not be resolved to a thingType! 0129:0002:AA00::33.32

You should find an XML file in /userdata/zwave/node9.xml. We need to get this into the database…

Thanks Chris. I realize I made a mistake in not checking the database to verify if the lock was even listed. Thanks for helping a newcomer.

I have node9.xml available (http://pastebin.com/PKzutqgp) and happy to add it to the database. I created account, but looks like perhaps I don’t have permission to submit? I don’t see the add button listed in the instructions.

I’ve updated this, so you should be good to go… Any problems, let me know…

I loaded your XML already since I wanted to make sure it worked ok as it’s one of the first secure devices since I added support for this… It’s created this device and it would be great if you could at least give it a name :slight_smile: - and add anything else (manuals etc would be good).

Great. I’ve updated the device details, filled in what I could, and uploaded a manual.

Another beginner question (and hopefully my last) what steps are next to get my instance to recognize the new database? I see I can generate an xml file for OH2, but am unsure where it goes? And to I need to do a full re-inclusion?

I’ll need to update the binding. So, if you want to compile a version yourself, then you can take the file from the website - otherwise you’ll need to wait for the next release. It might not be tonight though as I need to run some more tests before I push another change…

This should be in tomorrows binding…

Perfect – Thanks for the update.

When the updated binding is released where does it go? /addons? or /runtime/karaf/system/org/openhab/binding/org.openhab.binding.zwave/2.0.0-SNAPSHOT?

I tried compiling via MVN and placing the new jar file in both locations and it didn’t seem to pick it up the new device. I didn’t do an exclude/include. Just delete thing and re-add. Am I missing a step?

Is there documentation I should reference on this? If it doesn’t existing, happy to write something up for other beginners.

If you are compiling a new jar, you will want to put it in the addons directory. Note that the other version may still be cached in maven though when you start up.

Run these steps at the openhab console to clear it out:

  1. bundle:list|grep -i zwave
    If this shows only one bundle (binding) you should be good to go. If there are two (or more), keep going. Each bundle has a bundle ID, which is a sequential number of the order they were loaded. This ID is the number you can use to control them.

  2. bundle:stop ID
    where ID is the bundle ID of the older bundle that you want to remove.

  3. bundle:uninstall ID

At this point, I would recommend a restart. You should be able to just do the uninstall without the stop, but I have found it works better to stop the binding before removing it. If you do not it hangs some times. The restart of openHAB is just to make sure everything is cleaned up and only elements of the new jar are used.

If you are waiting for the new binding in the normal SNAPSHOT, that build can be downloaded after it is built. The build kicks off in about 1/2 hour as I am writing this. You can watch its progress here: Cloudbees Jenkins

You can either grab the jar out of the artifacts of the openHAB2-addons project, or re-install the whole of OH2. If you do the re-install, I would recommend cleaning up the maven cache and downloads to ensure you are using the new stuff. I wrote a script that I try to keep up to date to help with that. You can view/fork/download/hack/point/whatever here: OpenHAB2-Tools

Hope that helps

Perfect – I used the script and am now up and running. For some reason compiling my own bundle didn’t work (it finally recognized the lock, but none of the commands worked).

So now that I’ve been playing with it, I’ve noticed an issue that perhaps is specific to these locks.

OH2 doesn’t get lock status updates. Other sources online indicate that the Yale locks uses an alarm notice to report a lock change instead of the “correct” method. When that lock states change, entries such as the following show up in the log:

NODE 9: Device message contained nonce that is unknown to us, id=0x05, table={}, expiredList=[], usedList=[-67, 99, -78, -126, -30, 0, 104]
NODE 9: Unknown Alarm Type = 24, ignoring report.
NODE 9: Timed out waiting on response for encapsulated message Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=9, payload=09 17 98 81 08 B7 5D CA BC 56 22 44 FD 91 7F 40 BB 51 9B B7 33 C0 BB 12 AD    encapsulates: Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=9, payload=09 03 62 01 FF
NODE 9: Unknown Alarm Type = 22, ignoring report.
2016-03-27 03:58:11.981 [ERROR] [col.security.ZWaveSecureNonceTracker] - NODE 9: Device message contained nonce that is unknown to us, id=0xFE, table={}, expiredList=[], usedList=[-118, -88, -87, -21, -115, -56, 26, 74, -29, -123]

I see other alarm types such as 21 (Lock?), 22 (Unlocked?), 24 (??), and 25 (??).

Should I open an issue on GitHub?

The alarms need updating both in the binding and database - feel free to open an issue.

@chris - I’ve managed to find an online reference for all the device alarm types. Does this get added to the Z-Wave Database? I saw the alarms section of the command classes, but wasn’t sure how to enter it in using the fields provided. For example, alarm type 112 is Code Changed and the Alarm Level indicates which code was changed.

I’ve updated the binding already to include the extra alarms, but there’s a bit more to it than just adding the alarms… I need to have a think about how to add these - probably we’ll add separate channels for each alarm, but there’s potentially a lot, so it needs a bit of thought…

I’ve also implemented the lock logging command class today (untested)… There’s still a bit to do with the security classes :slight_smile:.

I’m working on pairing several of these. The first one came up as “unknown” but the second one paired correctly, so I deleted my post asking about the first one. I’ll exclude it and re-pair and post better logs if I run into more trouble. Let me know if there’s any specific testing that would help with these locks – I have three of them and when using SmartThings, one was mostly reliable and one was mostly unreliable, despite appropriate use of range extenders.

@mishakim Glad you got it working. I too had an issue where even once the device was in the database it came up as unknown. Re-pairing did the trick.

I think the biggest issue is what was mentioned previously in the thread. Since OpenHAB doesn’t see the current state you can’t do to much with it. Seems like it’s a complex change to support it.

I paired the third lock with no trouble, then tried again with the first one. It took a few tries to get it to exclude at all, and then to pair, but eventually did. It again came up unknown, with this:
2016-04-09 12:25:23.911 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 12: Device could not be resolved to a thingType! 0129:0002:0000::33.32

after I rescanned the inbox. Comparing the logs of the pairing process, it looks exactly the same as the ones that worked (but I don’t have debug on).

Comparing the .xml, I see the problem: the one that isn’t working has deviceId 0x0, while the two that are working is 0xaa00. Tried excluding and re-including, didn’t help. Tried changing that manually, which didn’t work (not that I really expected it to)

Never mind - went to PaperUI in a different browser (was using Chrome), and it did have the correct name. Added as thing, assigned channels, and it works.

Not sure what you mean by this - for the two that work (until I moved one of them back to it’s location too far from the controller), I accurately got lock state, and I get battery state for the one that’s still in-range.

When I lock/unlock it from the device itself, that change is not registered in OpenHAB (perhaps it eventually would, but I haven’t monitored it closely). Instead of sending a lock state change, this model lock sends an alarm condition which I can see in the logs is instantly is sent. OpenHAB just doesn’t know what to do with that info.

If you unlock it from the handset, are you seeing that change reflected in OpenHAB right away?

ah, I see. No, it does seem to take a while to update, but I think it does eventually. I haven’t been testing that rigorously, so I could be confusing updates based on system actions with manual actions.

update: one of my three locks, the one physically closest to the controller (~6ft) has stopped working. The logs say the node is not found. The other two, which are farther away but in range of some repeaters are intermittent but remain online. Is there a way to force a network heal?

well, my Yale locks have completely stopped working. After a few days of security payload warnings and no actual control of the locks, with no software updates making any improvement, I unpaired the one closest to the controller (the only one close enough to pair/unpair without moving things), and now cannot successfully complete secure inclusion, always getting the error:
2016-04-22 15:54:10.731 [ERROR] [curityCommandClassWithInitialization] - NODE 19: Secure Inclusion FAILED. at step SECURITY_NETWORK_KEY_SET: 10000ms passed since last request was sent, secure inclusion failed.

@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.