Z-wave (Schlage) Lock Support on OH1

Update!

After much fiddling I have it fully working. The feedback from the lock works correctly - I just have to be patient, after the refresh period, the status does update as locked or unlocked.

Great news.

Please let me know when there is anew commit, as I would like to keep on top of this.

Thanks!

@Nicholas_Waterton thats promising. I have been holding off from further testing as per @dbadia and will wait till he has a more stable commit.
@dbadi let me know if you need my assistance in more than testing. I know i have mentioned this before but still feeling guilty about letting you deal with this on your own.

The rest of my ZWave items are still flakey with this binding. Aeon MS6 keep having to be woken up on a restart, and my Fibaro RGBW LED Controller stops working. Having a hard time getting everything to work at once.

The ALARM values the Yale lock sends are SENSOR_ALARMS, but so far no luck in intercepting them. It looks like they are passed on to Openhab, but I can’t capture them.

@Nicholas_Waterton thanks for testing. @mganapa saw some general flakiness with other nodes as well. I’m pretty sure the issues you are seeing with the non-secure nodes is just the controller being overwhelmed by the security requests (the code base you are running sends too many, which results in a lot of back and forth. Eventually it clears up, but it takes awhile, hence the delay in the lock status updating, devices appearing to be offline).

I haven’t pushed anything to github lately, but I have been busy on the 1.8 branch:

  • bit the bullet and did a lot of refactoring. It took up a couple hours but it should make the code easier to troubleshoot and maintain going forward.
  • wrote a log parser that makes it easier to visualize what’s going on with the security messages, failures, etc
  • added a gateway to help control the number of security messages and strip out duplicates. The goal being to stop the controller from being bogged down with too many security messages.

I haven’t pushed anything to github yet, as I have a few more changes to make and I want to test the code as much as I can here first.

@Nicholas_Waterton do you happen to have the logs from your failed secure inclusion attempts? Would like to see if there’s anything I can do to sure that up.

Good question, I’ll have to take a look. I have a Yale lock here that I’ve been meaning to try out. Thanks for posting the codes and the meanings

I’d like to. I’m not aware of a timeline for 1.8, but it we could at least get the basics working (and not interfering with other nodes) that would be great!

OK, some more update (and if you can let me know when you have a new update to try I’d appreciate it.

I have the ALARMS working. If you add:

        MLOCK(21, "Manual Lock"),
        MUNLOCK(22, "Manual UnLock"),
        ALOCK(24, "Auto Lock"),
        AUNLOCK(25, "Auto UnLock");

to ZWaveAlarmCommandClass.java in the enumerated list of supported alarm types, then you can catch the alarms in the items list like this:

Number Door_Status2a "Front door lock status ALARM Received [%d]" <lock> (gGF, Doors, Yale) {zwave="27:command=alarm"}
Number Door_Status2ag "Front door lock status General Alarm Received [%d]" <lock> (gGF, Doors, Yale) {zwave="27:command=alarm, alarm_type=0"}
Number Door_Status21a "Front door lock Manual Lock [%d]" <lock> (gGF, Doors, Yale) {zwave="27:command=alarm,alarm_type=21"}
Number Door_Status22a "Front door lock Manual UnLock [%d]" <lock> (gGF, Doors, Yale) {zwave="27:command=alarm,alarm_type=22"}
Number Door_Status24a "Front door lock Auto Lock [%d]" <lock> (gGF, Doors, Yale) {zwave="27:command=alarm,alarm_type=24"}
Number Door_Status25a "Front door lock Auto UnLock [%d]" <lock> (gGF, Doors, Yale) {zwave="27:command=alarm,alarm_type=25"}

You can use Contact, Switch or whatever. I did see an alarm type of 0 (General) once, not sure what that was for, and of course there may be other types of alarm I haven’t seen (tamper? lockout?). The alarms are in the form of a trigger - ie it sends a “1” (ON, CLOSED depending on item type), but doesn’t reset it. It’s easy enough to intercept this in a rule though.

If I don’t have the door lock status polling, the lock behaves oddly. when you switch the command=door_lock item, sometimes the lock locks, sometimes it unlocks (irrespective of if you send an ON or OFF). With polling on, it seems to work, but there are reams of network traffic, and it takes a while to update the lock status. Not sure why this is (the lock must know it’s own status right?

Anyway, the rest of my zwave items are in a dismal state, BASIC stuff works, but my Fibaro RGBW LED controller is hit and miss, sometimes it initializes OK, sometimes not (mostly not). My Aeon Multi Sensor 6 motion sensors keep dropping off the network, and one managed to use up all it’s battery (from 100%) overnight! The lock works every time now though…

I was using the latest 1.8 binding, and everything worked flawlessly with that. I may try it without the polling (which seems to do endless retries for some reason), see if it makes a difference.

I do have an Aeon Home Energy Monitor, which does generate quite a lot of traffic (updates every 5 seconds, if the house load changes), so that might be a factor also.

As to logs, I don’t have the ones from the failed inclusion attempts, I just kept at it until I got success (for some odd reason I did get a log of the successful inclusion, I think I just decided to keep a log of the Inclusion attempts for analysis, and then it worked!). The failed ones are probably in my zwave.zip logs (my zwave log is always on debug), but it would take a while to find them. You don’t seem to be able to post logs here anyway (unless you have some tips?).

For the database entry I added:

                <Product>
                        <Reference>
                                <Type>0002</Type>
                                <Id>0000</Id>
                        </Reference>
                        <Model>YRLD220</Model>
                        <Label lang="en">Touch Screen Deadbolt</Label>
                        <ConfigFile>yale/yrld220.xml</ConfigFile>
                </Product>

to products.xml in the Yale section, yrld220.xml is a copy of yrd210.xml as they seem to be the same, but I copied it in case there turn out to be differences.

Anyway, let me know when you have a new binding to try.

Some more info,

I managed to extract my logs, node 20 is (one of) the failed one(s) , node 27 is the successful one.

https://www.dropbox.com/sh/o3niantzw3gixvz/AACARFkYuEiKVbeuLk2LubgJa?dl=0

I also found this:

http://www.pepper1.net/zwavedb/uploads/resources/513c90984733a978c86885d00c0a99ef40dd8b72.pdf

Which explains all the alarms and commands. This will help me out testing.

I commited some more changes - I think this will help with the other nodes appearing as failed.

Couple other thoughts:

  • Status updates are still a bit slow, taking up to 20 seconds. Have a few ideas on how to make this faster in the future. I’ve also noticed that occasionally, the status doesn’t update at all. This appears to be a bug between the UI and zwave level, as doing a simple refresh of the UI shows the proper status
  • I’d suggest setting ,refresh_interval=43200 for battery and ,refresh_interval=120 for lock status. The battery level won’t change very often and doing so more frequently does nothing but drain the battery
  • As I mentioned before, there are a lot of changes here, but this code has been the most stable of all for me so far

Go ahead and give it try

Thanks
Dave

Thanks for the logs and the doc @Nicholas_Waterton, I’ll take a look

@dbadia I will try this out by tomorrow night. Thanks for the updates!

I have the lock working now (but will download the latest commit to compare).

I ended up adding this to ZwaveAlarmCommandClass.java to catch the alarms the lock sends. If this was 100% reliable, I wouldn’t need to poll the lock so often (as it sends an ALARM for every type of lock/unlock). but it’s only 80% reliable so far. Sometimes the response is instant, even with quick lock/unlock cycles, sometimes it never arrives. I haven’t been polling the battery, as it seems to send that from time to time, when there is activity.

          public enum AlarmType {
		GENERAL(0, "General"), 
		SMOKE(1, "Smoke"),
		CARBON_MONOXIDE(2, "Carbon Monoxide"), 
		CARBON_DIOXIDE(3, "Carbon Dioxide"), 
		HEAT(4, "Heat"),
		FLOOD(5, "Flood"),
		ACCESS_CONTROL(6, "Access Control"),
		BURGLAR(7, "Burglar"),
		POWER_MANAGEMENT(8, "Power Management"),
		SYSTEM(9, "System"),
		EMERGENCY(10, "Emergency"),
		COUNT(11, "Count"),
        ADDED(112, "User Added"),
        TAMPER(161, "Tamper Alarm"),
        MLOCK(21, "Manual Lock"),
        MUNLOCK(22, "Manual UnLock"),
        RFLOCK(24, "RF Lock"),
        RFUNLOCK(25, "RF UnLock"),
        PADLOCK(18, "Keypad Lock"),
        PADUNLOCK(19, "Keypad Unlock"),
        JAMMED(9, "Deadbolt Jammed"),
        BATTFAIL(169, "Battery Empty"),
        BATTCRIT(168, "Battery Critical"),
        BATTLOW(167, "Battery Low"),
        AUTORELOCK(27, "Auto relock"),
        DUPLICATE(113, "Duplicate PIN"),
        POWER(130, "Power Cycle"),
        DELETED(33, "User Deleted");
        
        /**
         * Yale Locks Alarms:
         * 112 (0x70) User added - value is user that had code changed or added. 0 is master code
         * 161 (0xA1) Tamper Alarm - Cable connecting front and rear disconnected (value 2) or keypad attempts exceeded (value 1)
         * 22 (0x16) Manual unlock - key or thumb turn (value 1)
         * 25 (0x19) RF unlock (value 1)
         * 21 (0x15) Manual Lock - key or thumb turn (value 1) by keypad touch - lock and leave (value 2)
         * 24 (0x18) RF lock (value 1)
         * 18 (0x12) Keypad lock - value is user number
         * 19 (0x13) Keypad unlock - value is user number
         * 9 (0x9) Deadbolt Jammed - value 0
         * 169 (0xA9) Low Battery Alarm - too low to operate (value 1)
         * 168 (0xA8) Low Battery Alarm - critical low battery (value 1)
         * 167 (0xA7) Low Battery Alarm - Low battery (value 1)
         * 27 (0x1B) Auto relock cycle completed (value 1)
         * 113 (0x71) Duplicate pin number entered (value is user)
         * 130 (0x82) Power Cycle (value 1) sent on battery power restored
         * 33 (0x21) User Deleted (value is user)
         */

should this not be in the device .xml file? can we add supported alarms to the xml? not sure of the format for the device .xml in the database. This seems to be the same for all Yale locks.

I have some complicated rules to deal with all this - but they work!

The rest of my zwave stuff is hit and miss. I actually have everything working right now, but when I restart…

I have to reinitialize the nodes when they stop responding (after a few hours) - then they pick up again. If we could solve this, then we would be well on the way. As I said everything is solid in the regular 1.8 binding, so it can work. As a minor thing, my Everspring Siren (SE812) does not report it’s battery level. This was a problem in 1.7.1 binding, and was somehow fixed in the later 1.8 bindings (as of a few weeks ago). I don’t know what was done, but there is something different about the battery reporting on this device.

Also, My Aeon Multi sensor 6 devices have been draining their batteries like crazy (also dropping off the network every few hours). I’m thinking that the lock is using them as routers, and thus draining the batteries. I have replaced all the batteries, and have a Zwave repeater arriving today. I’m hoping that will fix the problem.

I’ll download the latest commit right now, and see how it goes.

Thanks!

OK, so far no-go.

I tried the new binding (but forgot to add the lock to the database), so added it and tried again. Still no. Tried re-initializing the node. No. Took a deeper look, and see the message:

2015-11-13 11:40:09.010 [ERROR] [CommandClassWithInitialization:379 ]- NODE 27: Invalid state! secure inclusion has not completed and we are not in inclusion mode, aborting

Hmm - not good.

Went back to the old binding, restored my old node27.xml from backup - and good! all works as expected - had lost my association for alarms, so re added it. Alarms working OK.

went back to the new binding. Still no go.

This is the crucial problem I think:

2015-11-13 11:34:35.619 [INFO ] [rialApiGetInitDataMessageClass:57  ]- NODE 27: Node found
2015-11-13 11:34:35.741 [DEBUG] [b.z.i.protocol.ZWaveController:461 ]- NODE 27: Init node thread start
2015-11-13 11:34:35.781 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 27: Serializing from file /var/lib/openhab/zwave/node27.xml
2015-11-13 11:34:35.817 [ERROR] [b.z.i.protocol.ZWaveController:475 ]- NODE 27: Restore from config: Error deserialising XML file. com.thoughtworks.xstream.converters.ConversionException: Cannot construct org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass : org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass : Cannot construct org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass : org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass

I have added the complete log from this to my dropbox logs folder. I will see if I can fix this in the meantime.

OK,

I did a cut and paste between the old node27.xml file and the new one (different order, but otherwise the same), made sure securePairingComplete true /securePairingComplete was correct (goes to false if you reinitialize the node), and Bingo! we are live again.

I’ll continue with testing and let you know the results.

I should say in the cut and paste operation, the new node27.xml file was missing the secure command classes - that is what I copied from the old one to the new.

in a quick 5 minutes of testing, everything is working! even the old zwave stuff is all responding (for now). Wait a few hours (or overnight though) and we’ll see. Lock is responding well, and fast. Alarms are instant, and remote lock/unlock are within a second or so.

Still waiting for my repeater, but Aeon MS6 sensors survived last night with the batteries intact.

Will update in a few hours.

Assuming you didn’t include the MS with USB power applied, it shouldn’t do this. Battery devices can’t be used as routers.

I would have though so too, but after changing the binding, and adding the lock, the battery levels started dropping like crazy. They were all added on battery. Habmin info reports “routing” as true (but then it says that for everything). I’ll check with habmin2 see if that says the same (probably, it’s the same xml file).

Having been at 100% for about 6 weeks (one for over two months), they were dropping 5% per hour. The oldest one hit zero overnight.

I replaced the batteries on the dead one, but it wouldn’t work. Tried several batteries - nothing - no lights or anything. Connected it to mains, and voila! life. Tried batteries again - nothing. So I hooked it up on mains power, removed and re added it to the zwave network, and now it happily reports all the time (also says battery 100%, but whatever).

Two others dropped to 25% so I replaced the batteries on those (didn’t want to leave them overnight again after the last one), The fourth was down to 79%, but then went back up to 89%, so I left that.

Today (after leaving them all night) they are the same as yesterday. So unless this is one of those things where they are at 100% until the last few days, when they drop like mad, we are still OK.

Could this be something to do with zwave beaming? they all claim to support beaming, and I don’t have much else that does. does zwave beaming work differently?

Right now the lock node has just gone dead, but I did change my lock polling to 300 (trying to avoid polling if I can), so maybe I should change my zwave:aliveCheckPeriod (currently at 360000). Lock still responds to commands though. Not sure how the node can be marked dead when it’s responding to polls/commands?

I’ll let you know how it goes later.

Did have things working, the other zwave nodes are better (MS6 stays on the network!).

Lock node keeps going dead (have my repeater in now too). Then it “rises from the DEAD” (funny!), then all sorts of messages not being sent because the node is dead (which it really isn’t).

So working - then dies, working then dies.

lots and lots of these messages:

2015-11-13 19:07:56.247 [DEBUG] [urityEncapsulatedSerialMessage:63  ]- NODE 27: securityTransactionComplete=false, payload=(1B 02 62 02 ), transmitted=true, msSinceTransmitted=2487
2015-11-13 19:07:56.248 [DEBUG] [urityEncapsulatedSerialMessage:63  ]- NODE 27: securityTransactionComplete=false, payload=(1B 02 62 02 ), transmitted=true, msSinceTransmitted=2488

Lots and lots of these (which usually can be ignored):

2015-11-13 19:08:01.740 [DEBUG] [ApplicationCommandMessageClass:117 ]- NODE 27: Transaction not completed: node address inconsistent.  lastSent=255, incoming={}

I assume {} is a bug - should be something?

I’ll keep at it.

It’s been working for a few hours now, but everything seems really slow. Not just the lock, regular zwave stuff takes a long time to respond (5-10 seconds which is a long time for a light switch), The lock responds, eventually, but it can be 20-30 seconds or more (much more).

lots of these messages in the log:

=REQUESTED  expired=false  getTimeLeft=10997]
2015-11-13 21:16:34.714 [DEBUG] [.i.p.c.ZWaveSecureNonceTracker:103 ]- NODE 27: already waiting for nonce
2015-11-13 21:16:35.714 [DEBUG] [.i.p.c.ZWaveSecureNonceTracker:81  ]- NODE 27: getUseableDeviceNonce() lastDeviceNonce=
2015-11-13 21:16:35.714 [DEBUG] [.i.p.c.ZWaveSecureNonceTracker:92  ]- NODE 27: getUseableDeviceNonce() requestNonceTimer=NonceTimer [type=REQUESTED  expired=false  getTimeLeft=9997]
2015-11-13 21:16:35.714 [DEBUG] [.i.p.c.ZWaveSecureNonceTracker:103 ]- NODE 27: already waiting for nonce
2015-11-13 21:16:36.714 [DEBUG] [.i.p.c.ZWaveSecureNonceTracker:81  ]- NODE 27: getUseableDeviceNonce() lastDeviceNonce=
2015-11-13 21:16:36.714 [DEBUG] [.i.p.c.ZWaveSecureNonceTracker:92  ]- NODE 27: getUseableDeviceNonce() requestNonceTimer=NonceTimer [type=REQUESTED  expired=false  getTimeLeft=8997]

Regards,

Update,

After an interesting night configuring zwave devices, this morning all seems to be working well.

Last night odd things were happening. Took forever to add a new MS6 (to replace the one that will not work on batteries anymore). Had to keep waking it up to try to get configuration to complete. The new zwave binding seems to take a long time to get the device configuration - kept failing with “Static configurations not complete” - then it would start all over again on the next wake up.

Fibaro LED controller responded very slowly (i think it was downloading configurations again) - then suddenly started working normally! One of the devices that always previously worked started acting oddly. It’s a MIMO I/O module (mains powered) which switches my extractor fan light on and off. When switched the light switched on and off rapidly 10 times or so, then stopped in a random state. Looking at the log, I can see that the node was “DEAD” (it’s not), and so the switch command was sent several times with no “ACK”. Feedback always worked though, and quickly. Today - back to working normally.

As to the lock, last night, responding very slowly, or sometimes fast. feedback (alarms coming in mostly) working sporadically. Today - working well. usually takes 4 seconds to lock/unlock, feedback instant. The occasional ALARM does not show up (so the state is captured by polling, set to 120 seconds). about 85% on receiving alarms, even when they come quickly (ie unlock - exit relock in the space of 2-5 seconds works).

Here is the “Alarm” log since last night for example:

2015-11-13 23:04:30.133 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-13 23:04:30.133 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 0
2015-11-13 23:04:30.133 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = General (0)
2015-11-13 23:04:30.133 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@2d86fde3
2015-11-13 23:06:31.409 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 27: Polling list: item Door_Status_Alarm is not completed initialisation
2015-11-13 23:06:33.634 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 27: Polling list: item Door_Status_Alarm is not completed initialisation
2015-11-13 23:08:23.851 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 27: Polling list: item Door_Status_Alarm is not completed initialisation
2015-11-13 23:19:00.998 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-13 23:19:00.998 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-13 23:19:00.999 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = RF UnLock (25)
2015-11-13 23:19:00.999 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@4abad873
2015-11-13 23:35:41.575 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-13 23:35:41.575 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-13 23:35:41.576 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = RF Lock (24)
2015-11-13 23:35:41.576 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@6447138f
2015-11-13 23:36:21.577 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-13 23:36:21.577 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-13 23:36:21.577 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = Manual UnLock (22)
2015-11-13 23:36:21.577 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@5a40c712
2015-11-13 23:41:27.002 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-13 23:41:27.002 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-13 23:41:27.002 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = RF Lock (24)
2015-11-13 23:41:27.002 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@415552de
2015-11-14 00:54:57.906 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 00:54:57.906 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 00:54:57.906 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = RF UnLock (25)
2015-11-14 00:54:57.906 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@1d966f95
2015-11-14 01:00:04.397 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 01:00:04.397 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 01:00:04.397 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = RF Lock (24)
2015-11-14 01:00:04.397 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@5161dd28
2015-11-14 01:03:59.054 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 01:03:59.054 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 01:03:59.054 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = RF UnLock (25)
2015-11-14 01:03:59.054 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@6a93edf
2015-11-14 01:04:53.857 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 01:04:53.857 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 01:04:53.857 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = RF Lock (24)
2015-11-14 01:04:53.857 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@6c1f4adc
2015-11-14 07:41:46.780 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 07:41:46.780 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 07:41:46.780 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = Manual UnLock (22)
2015-11-14 07:41:46.780 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@1ba24a2f
2015-11-14 07:46:55.992 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 07:46:55.992 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 07:46:55.992 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = RF Lock (24)
2015-11-14 07:46:55.992 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@f8fe4ef
2015-11-14 09:21:12.008 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 09:21:12.008 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 09:21:12.008 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = Manual UnLock (22)
2015-11-14 09:21:12.008 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@14b91f9d
2015-11-14 09:22:34.038 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 09:22:34.038 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 09:22:34.038 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = Keypad Unlock (19)
2015-11-14 09:22:34.038 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@17e59e18
2015-11-14 09:26:45.744 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 09:26:45.744 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 2
2015-11-14 09:26:45.744 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = Manual Lock (21)
2015-11-14 09:26:45.744 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@6a529d2e

If you see, at 2015-11-14 09:21:12.008, the wife left for her morning run. Locked the door, then came back in (for something), then left again.

Detail:

2015-11-14 09:21:12.008 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 09:21:12.008 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 09:21:12.008 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = Manual UnLock (22)
2015-11-14 09:21:12.008 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@14b91f9d
2015-11-14 09:22:34.038 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 09:22:34.038 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 1
2015-11-14 09:22:34.038 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = Keypad Unlock (19)
2015-11-14 09:22:34.038 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@17e59e18
2015-11-14 09:26:45.744 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 27: Received Alarm Request
2015-11-14 09:26:45.744 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 27: Alarm report - Value = 2
2015-11-14 09:26:45.744 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:112 ]- NODE 27: Alarm Type = Manual Lock (21)
2015-11-14 09:26:45.744 [DEBUG] [b.z.i.protocol.ZWaveController:616 ]- NODE 27: Notifying event listeners: ZWaveAlarmValueEvent: org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveAlarmCommandClass$ZWaveAlarmValueEvent@6a529d2e

There are 3 Alarms, captured, but there were actually 4 events. Between the “Manual unlock” and the “Keypad unlock” there should have been a “Touch Lock” Alarm. This is captured at other times, so the lock sends it, and I capture it. I’m assuming the binding missed it somehow (timing? not long between the unlock and the lock). Maybe the lock didn’t send it (but then we’re in La La land) - have to assume it did and we missed it.

Here is my openhab.log output (filtered to capture “Front Door” events - this captures the output of my rules (hopefully I’ve got all the bugs out of the rules).

09:21:12.010 [INFO ] [penhab.model.script.Front Door:53   ] - Door Lock Alarm Received: 1
09:21:12.011 [INFO ] [penhab.model.script.Front Door:53   ] - Door Lock Alarm 22 (Manual Unlock) Received: 1
09:21:12.013 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Front Door Lock Notifications'
09:21:12.014 [INFO ] [o.model.script.Front Door Lock:53   ] - Front Door Lock trigger Value is: true
09:21:12.215 [INFO ] [o.model.script.Front Door Lock:53   ] - Front Door Lock Status updated to CONFIRMED Unlocked by: Manual Unlock
09:21:12.216 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Auto Unlock Cancelled (Door is already unlocked)
09:21:17.209 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Opened - sending Hallway Motion trigger
09:21:38.120 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Autolock Front Door'
09:21:38.135 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Closed: Setting autolock timer
09:22:34.224 [INFO ] [penhab.model.script.Front Door:53   ] - Door Lock Alarm Received: 1
09:22:34.276 [INFO ] [penhab.model.script.Front Door:53   ] - Door Lock Alarm 19 (Keypad Unlock) User: 1
09:22:34.383 [INFO ] [penhab.model.script.Front Door:53   ] - Door Lock Alarm User: 1 is Nick/Jill
09:22:36.084 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Opened - sending Hallway Motion trigger
09:22:39.450 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Autolock Front Door'
09:22:39.450 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Closed: Setting autolock timer
09:26:45.750 [INFO ] [penhab.model.script.Front Door:53   ] - Door Lock Alarm Received: 2
09:26:45.791 [INFO ] [penhab.model.script.Front Door:53   ] - Door Lock Alarm 21 (Manual Lock) Received: 2
09:26:45.816 [INFO ] [penhab.model.script.Front Door:53   ] - Door Lock Alarm 21 Touch Lock
09:26:45.950 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Front Door Lock Notifications'
09:26:45.955 [INFO ] [o.model.script.Front Door Lock:53   ] - Front Door Lock trigger Value is: true
09:26:46.250 [INFO ] [o.model.script.Front Door Lock:53   ] - Front Door Lock Status updated to CONFIRMED Locked by: Touch Lock
09:26:46.252 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Auto Relock Cancelled (Door is already locked)
09:29:02.302 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Presence Detection Unlock Front Door Jill'
10:49:33.441 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Presence Detection Unlock Front Door Jill'
10:50:32.930 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Opened - sending Hallway Motion trigger
10:50:33.103 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Front Door Lock Notifications'
10:50:33.180 [INFO ] [o.model.script.Front Door Lock:53   ] - Front Door Lock trigger Value is: false
10:50:34.239 [INFO ] [o.model.script.Front Door Lock:53   ] - Front Door Lock Status updated to CONFIRMED Unlocked
10:50:34.655 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Auto Unlock Cancelled (Door is already unlocked)
10:50:37.002 [DEBUG] [m.r.internal.engine.RuleEngine:305  ] - Executing rule 'Autolock Front Door'
10:50:37.030 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Closed: Setting autolock timer
10:55:37.520 [INFO ] [penhab.model.script.Front Door:53   ] - Front Door Locked by: Auto

You can see the missed “Touch Lock” here (ie there should be two, but there is only one). Other triggers work well though. There is only one missed trigger in the list today (she got back at 10:50). There should have been an unlock at 10:50:32.930, but I had just updated my rules, so that is captured in a “lock initialize” rule, but I did get the notification (just in case you’re wondering how she opened a locked door).

Right now, after leaving it overnight, everything is working normally, and lock is working well. The lock is sometimes fast (4 seconds) sometimes slow (up to 30 seconds or more) - seems to be waiting for the “nonce” security hash I guess.

Once I’m happy that it’s stable (no more fiddling/restarts), I’ll capture some logs of normal operation, then (fingers crossed) I’ll restart openhab, and capture the startup logs - this seems to be the most problematical part of the whole thing. Once everything is going, all is well, getting everything going…

If we can get the ALARM capture to 100% I can reduce polling to a minimum, and that should reduce traffic to/from the lock. The big delay seems to be the “nonce” handshake, and as a the lock mostly sits there and does nothing, but does need to wake up, handshake, and respond quickly, this may be the main problem.

Battery is reporting (not sure how often, I’m not polling), and it’s up to 71% now (from 70%) - maybe just minor fluctuations (these are not new batteries, from the old lock, which initially reported at 75% 2 days ago - but I have been testing a lot).

Aeon sensors are still at 100% - so that may not have been related. The one that was dropping (was 85% is now up to 91% climbed slowly yesterday 1% at a time). Weird.

I now have an Aeon ZSD37-ZW Range Extender a couple of feet from the lock. Not sure if it’s doing anything, but it can’t hurt.

I’ll post some logs later this afternoon.

Zwave boot logs posted to my dropbox folder. They are the zwave* files (2 of them). This is from a standing restart of openhab. I left the zwave device alone for a while, then tested various items (after 45 minutes or so). Everything checks out OK. Lock is working perfectly (with the limited tests I did at 8:44). Node 27 is the zwave log filterd for just the lock. the other is the full zwave log for all devices.

Logs cover a period of just over 1 hour.

So far it’s good!

I wonder what the trick is to speed up the status. I tested my Schlage lock with Homeseer, and the status reports back almost instantly (1 second?). Do all requests have to use the security command class? I thought that locks could send some commands outside of the security class.

Thanks for working on this btw! I will try to test with my Schlage soon.