OH2 Z-Wave refactoring and testing... and SECURITY

TheKorn · May 19, 2017, 1:12pm

Good instincts; root cause turned out to be a bug in the controller. I hadn’t seen an update to the Aeon Z-stick 2 in forever so hadn’t even bothered to check for one. Turns out, there is an update (to v3.08), which fixes another communication issue I was having, along with the secure exclusion failing issue. Once I updated the firmware, the lock was more than happy to jump off the z-wave network.

One for the bag’o’tricks, for sure! (At current, there are no updates for the z-stick 5, in case anyone asks…)

https://aeotec.freshdesk.com/support/solutions/articles/6000091809-z-stick-s2-v3-08-firmware-update

robert2 · May 20, 2017, 10:02am

So for all this noise going on here, is there any guestimate when this will be available for stable openhab2 installations? I could not find any kind of roadmap neither for openhab nor for the zwave binding. The main issue is that the current devices database is getting deprecated and switching to a complete development branch of OH2 is not an easy decision for your productive home automation system. This should not come over as rough, but it would be nice to now what to expect from the coming weeks and months.

chris · May 20, 2017, 10:06am

Yes - it’s been posted elsewhere, but I know this thread is getting (very!) long…

I plan to merge this into master after the next stable release of OH2 which I believe will be in June/July timeframe. That would make this available in the following stable release (I can’t tell you when that would be though - sorry).

No - the device database will remain the same. Configurations will need to change, but the database will output the database files that are compatible so there’s not change in the database side.

I hope that helps…

robert2 · May 20, 2017, 10:11am

Thanks, it does! What I meant, though, is that, since the last stable release, several new device definitions have been added as new Zwave devices come up on the market. Or are the device definitions updated automatically by and independently from the binding itself now?

chris · May 20, 2017, 10:18am

Ah, ok… No - the database is included in the binding, so you are right, it will not contain new devices. This is needed to ensure that features added to the database (eg new channel types, or database configuration) is available as well in the code (and it’s required for the way ESH works anyway). So, if you really use the stable branch, then it is fixed at a specific time.

The current zwave snapshot has limited changes from the stable so I would suggest it’s probably fine - most of the major updates are in the development branch.

robert2 · May 20, 2017, 10:53am

That’s good to know, thanks again!

smoofus · May 21, 2017, 6:16pm

Having a heck of a time securely including my Schlage BE469. I searched through the thread and did not run across the messages I’m seeing.

Binding version:
201 | Active | 80 | 2.1.0.201705192246 | ZWave Binding

Log:

13:00:02.772 [INFO ] [he.sshd.server.session.ServerSession] - Start flagging packets as pending until key exchange is done
13:00:04.246 [INFO ] [smarthome.event.BindingEvent        ] - org.openhab.binding.zwave.event.BindingEvent@1fbced6
13:00:04.607 [INFO ] [he.sshd.server.session.ServerSession] - Dequeing pending packets
13:00:10.773 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 17: setupNetworkKey useSchemeZero=false
13:00:13.047 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:aacccdf1:node17' to inbox.
13:00:13.048 [INFO ] [smarthome.event.InboxAddedEvent     ] - Discovery Result with UID 'zwave:device:aacccdf1:node17' has been added.
13:00:13.057 [INFO ] [smarthome.event.BindingEvent        ] - org.openhab.binding.zwave.event.BindingEvent@15585bb
13:00:13.072 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 17: setupNetworkKey useSchemeZero=false
13:00:18.166 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 17: setupNetworkKey useSchemeZero=true
13:00:18.167 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 17: Using Scheme0 Network Key for Key Exchange since we are in inclusion mode.
13:00:18.337 [INFO ] [curityCommandClassWithInitialization] - NODE 17: Setting Network Key to real key after SECURITY_NETWORK_KEY_SET
13:00:18.339 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 17: setupNetworkKey useSchemeZero=false
13:00:18.498 [ERROR] [col.security.ZWaveSecureNonceTracker] - NODE 17: SECURITY_ERROR Device message contained nonce that is unknown to us, id=-113.
13:00:18.591 [WARN ] [mmandclass.ZWaveSecurityCommandClass] - NODE 17: payloadQueue was empty, returning!
13:00:23.593 [ERROR] [col.security.ZWaveSecureNonceTracker] - NODE 17: SECURITY_ERROR Device message contained nonce that was previously used, id=-113.
13:00:23.595 [ERROR] [ssage.ApplicationCommandMessageClass] - NODE 17: Failed to decrypt message out of Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 11 16 98 81 E3 BC 02 EA 89 73 8E 5D AF F7 72 8F 0D 0F D0 3B 7F 8A 0C 72  .
13:00:28.846 [ERROR] [curityCommandClassWithInitialization] - NODE 17: SECURITY_INCLUSION_FAILED Failed at step SECURITY_NETWORK_KEY_SET: 10000ms passed since last request was sent, secure inclusion failed.
13:00:29.225 [INFO ] [ommandclass.ZWaveVersionCommandClass] - NODE 17: Command Class LOCK has version 0!

I’ve excluded, factory reset the lock and included again 5 times now and it fails every time with the above SECURITY_ERROR. Does anybody have any suggestions?

Mike_Bagdanoff · May 22, 2017, 5:56am

I’ve finally got my be469 included (by going back to my old oh1.8.1 machine, including it there and then moving the stick and security key back to my OH2 install) and I can now lock/unlock the door. I was going to need around with the user codes but I have an error value on the Thing config page

User Slot Status: has a value of 50331648 and it falls if I try to change it. Also the first two codes are set to 2A 2A 2A, etc. Anyone else get this working or should I delve deeper?

The error in the logs when I try to change this value is

2017-05-21 22:53:39.481 [ERROR] [ome.io.rest.core.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:027c523a:node94/config' for thing 'zwave:device:027c523a:node94': null

chris · May 22, 2017, 6:30am

Interesting. @dbadia do I recall seeing something in the past that some lock (maybe this one?) needed some sort of delay after initial inclusion, but before secure inclusion started? Timing is rather tight during this phase so I’m a bit hesitant to add too much delay, but maybe there’s a need for some sort of delay on this lock?

Mike_Bagdanoff · May 22, 2017, 1:55pm

I don’t think it’s a large delay as I was actually surprised when the inclusion finished because the whole process took about 10 seconds.

chris · May 22, 2017, 3:19pm

No, it can’t be a “large” delay as the secure inclusion must start within 10 seconds of the main inclusion finishing. This only seems to be an issue with this device though.

Mike_Bagdanoff · May 22, 2017, 3:24pm

I was able to get a log of the user codes issue, I set the “user slot status” to 1 and set the first code in paperui to a value, the error in the logs is:

08:19:21.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
08:19:21.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
08:19:31.750 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 94: Configuration update received
08:19:31.829 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 94: Configuration update usercode_code_27 to null
08:19:31.829 [ERROR] [ome.io.rest.core.thing.ThingResource] - Exception during HTTP PUT request for update config at 'things/zwave:device:027c523a:node94/config' for thing 'zwave:device:027c523a:node94': null

I’ll try Habmin later today

chris · May 22, 2017, 4:01pm

Probably the issue is the null. Please use HABmin and see if that works.

Mike_Bagdanoff · May 22, 2017, 4:43pm

I was able to set the “user slot status” field in habmin and the code change seems to work as I can now enter my code in the lock and it works. I guess I was thrown by the field just showing “2A 2A 2A 2A 2A 2A 2A 2A 2A 2A” when i refresh the config page. Though after consideration that seems reasonable, it shows its set but doesn’t let someone grab the code from the interface. Not sure if that was intentional or my lock doesn’t allow retrieval of the codes but i’m happy with the result.

It might be a bit much to ask the average user to figure out the bitmask for the “user slot status”, is that something that will be automatically calculated (or is it and I’m just overzealous).

Mike_Bagdanoff · May 23, 2017, 1:09am

Is this working with the current release or is it only if you munge up the. Jar?. I have an alarm number and an alarm access channel, neither of which seem to change values.

The current values are set to 6 but nothing I do changes them.

Mike_Bagdanoff · May 23, 2017, 2:43am

This may be a problem with my setup, I just noticed this in my log:

2017-05-22 19:32:59.417 [WARN ] [ome.core.thing.internal.ThingManager] - Cannot delegate update '100' for item 'LockFrontDoor_BatteryLevel' to handler for channel 'zwave:device:027c523a:node73:battery-level', because no thing with the UID 'zwave:device:027c523a:node73' could be found.

which is odd because my lock is at node 94. I’ve included & reincluded this thing so many times with the same zstick, from oh 1.8 to now that I’m fairly sure I should probably just wipe the stick and restart, though that is 65 devices that would need to be re-included.

chris · May 23, 2017, 8:31am

It is working on some devices at least - if it’s not configured for some devices, then it won’t work. I have no idea what “munge up the JAR” means.

chris · May 23, 2017, 8:34am

Presumably you have something linked incorrectly somewhere?

I don’t think wiping the stick will make any difference. You could try deleting the thing and adding it back to see if that helps.

BuckFitty · May 23, 2017, 2:52pm

I also have a be469 and it took many attempts, including 3 or 4 after a reset of my controller, lock and a new install of openhab. Eventually I was able to get it to pair properly after a bunch of futzing and it mostly works. It took some time for the user codes to be set in the lock via habmin but they all seem to be set in the lock now. Some user codes would be set when updated, while others took just leaving things pending until they eventually were accepted. The problem I am having, aside from the huge pain to get the lock to pair properly (i have 2 others I don’t feel like fighting with atm) is that when you manually unlock or lock the door either via the keypad or the manual deadbolt, openhab seems to fail when excepting the update from the lock so rules don’t fire nor is the UI updated when the state changes. Through the UI it seems to work fine, although at times there is a bit of a delay in locking or unlocking via the UI switch.

2017-05-23 08:36:01.418 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-05-23 08:36:01.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=  ApplicationCommandHandler[0x04], type=Request[0x00], dest=2, callback=0, payload=00 02 02 98 40
2017-05-23 08:36:01.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: cl  ass=ApplicationCommandHandler[0x04], type=Request[0x00], dest=2, callback=0, payload=00 02 02 98 40
2017-05-23 08:36:01.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCom  mandHandler[0x04], type=Request[0x00], dest=2, callback=0, payload=00 02 02 98 40
2017-05-23 08:36:01.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-05-23 08:36:01.418 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE  :DONE)
2017-05-23 08:36:01.418 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true   isDead=false
2017-05-23 08:36:01.419 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLA  SS_SECURITY, endpoint 0
2017-05-23 08:36:01.419 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY check internal
2017-05-23 08:36:01.419 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_SECURITY V1   SECURITY_NONCE_GET
2017-05-23 08:36:01.419 [DEBUG] [andclass.impl.CommandClassSecurityV1] - Creating command message SECURITY_NONCE_RE  PORT version 1
2017-05-23 08:36:01.419 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
2017-05-23 08:36:01.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Added to secure queue - size 1
2017-05-23 08:36:01.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2017-05-23 08:36:01.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.bindi  ng.zwave.internal.protocol.ZWaveCommandClassPayload@7e8d2f6b.
2017-05-23 08:36:01.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransac  tions 0
2017-05-23 08:36:01.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransac  tions 0
2017-05-23 08:36:01.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-05-23 08:36:01.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-05-23 08:36:01.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from secureQueue
2017-05-23 08:36:01.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-05-23 08:36:01.419 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 11 00 13 02   0A 98 80 F2 3C CE 12 36 30 C6 90 25 69 E3
2017-05-23 08:36:01.419 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 11 00   13 02 0A 98 80 F2 3C CE 12 36 30 C6 90 25 69 E3
2017-05-23 08:36:01.423 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-05-23 08:36:01.423 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 43398: Transaction Start type SendData  
2017-05-23 08:36:01.423 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-05-23 08:36:01.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4  3398: [WAIT_RESPONSE] requiresResponse=true callback: 105
2017-05-23 08:36:01.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expec  ted cmd class: null
2017-05-23 08:36:01.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=  null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-05-23 08:36:01.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expec  ted cmd: 0
2017-05-23 08:36:01.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: cl  ass=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-05-23 08:36:01.423 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions o  utstanding: 1
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 23 08:3  6:03 MDT 2017 - 2000ms
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransactio  n: TID 43398: [WAIT_RESPONSE] requiresResponse=true callback: 105
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 23 08:3  6:03 MDT 2017 - 1999ms
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], ty  pe=ACK[0x02], dest=255, callback=0, payload=
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 43398: [WAIT_RESPONSE]   requiresResponse=true callback: 105
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-05-23 08:36:01.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 23 08:3  6:03 MDT 2017 - 1999ms
2017-05-23 08:36:01.449 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-05-23 08:36:01.455 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-05-23 08:36:01.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=  SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
2017-05-23 08:36:01.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: cl  ass=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
2017-05-23 08:36:01.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13]  , type=Response[0x01], dest=255, callback=0, payload=01
2017-05-23 08:36:01.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 43398: [WAIT_RESPONSE]   requiresResponse=true callback: 105
2017-05-23 08:36:01.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-05-23 08:36:01.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 43398: [WAIT_RESPONS  E] requiresResponse=true callback: 105
2017-05-23 08:36:01.455 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[  0x13], type=Response[0x01], dest=255, callback=0, payload=01
2017-05-23 08:36:01.455 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on s  tack.
2017-05-23 08:36:01.455 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 43398: TransactionAdvance ST: WAIT_RES  PONSE
2017-05-23 08:36:01.455 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 43398: TransactionAdvance WT: null {}
2017-05-23 08:36:01.455 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 43398: TransactionAdvance RX: Message:   class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
2017-05-23 08:36:01.456 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 43398: TransactionAdvance TO: WAIT_REQ  UEST
2017-05-23 08:36:01.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 43398: Advanced to WAIT_REQUEST
2017-05-23 08:36:01.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: TID 43398: Transaction not complet  ed
2017-05-23 08:36:01.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-05-23 08:36:01.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-05-23 08:36:01.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-05-23 08:36:01.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-05-23 08:36:01.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue May 23 08:3  6:06 MDT 2017 - 5000ms

BuckFitty · May 23, 2017, 3:04pm

I thought I would add some info on what I did to get the lock to pair finally.

Reset Controller
Reset Lock
Fresh OH2
Manually add the May 12th version of the test binding to the addons directory and configure the controller
Attempt to pair the lock a first time. It does not pair according to the lock but OH2 sees the lock so I added the lock and then search for other Zwave Things again right away and attempt running the pairing setup on the lock again and this time I get a Paired response from the lock.
At this point the lock is operational mostly and the next fight is adding all the user codes.