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

Tags: #<Tag:0x00007f1829e1a468> #<Tag:0x00007f1829e1a288>

(G H) #2271

openhab> bundle:list | grep -i zwave
227 │ Active │ 80 │ │ ZWave Binding

That’s the one currently in there. Associations don’t work because a) they aren’t sticky in the UI and b) device-to-device associations don’t get set, and device-to-controller associations also don’t get set. (ie, a switch associated with a light, the switch won’t control the light… and the same switch or remote, etc, don’t update OH’s status either until the next poll happens).

So, that certainly suggests strongly that associations aren’t being set.

(Scott Rushworth) #2272

There is a newer version ( Try that one and see if they work. The UI will still be messy. For me, PaperUI is displaying properly. Good to know you only have the one binding… that could have been causing it if there was an older one in there.

(Scott Rushworth) #2273

This may be an issue. Here is a filtered log of setting the association, the report back (which shows it’s getting set properly), and then a manual turn off of a VRMX1. There’s a HAIL, but there should be more coming in from the switch. This was a problem before, but it had gotten fixed. Maybe this affects more than just this device.

2018-01-03 10:08:58.855 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Configuration update received
2018-01-03 10:08:58.860 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Configuration update group_1 to [node_1_1]
... snip
2018-01-03 10:08:58.879 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - NODE 26: Creating new message for application command ASSOCIATIONCMD_GET group 1
... snip
2018-01-03 10:08:58.945 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Received COMMAND_CLASS_ASSOCIATION V1 ASSOCIATIONCMD_REPORT
2018-01-03 10:08:58.945 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - NODE 26: association group 1 has max associations 232
2018-01-03 10:08:58.945 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - NODE 26: association group 1 includes the following nodes:
2018-01-03 10:08:58.945 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveAssociationEvent
2018-01-03 10:08:58.945 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ASSOCIATION, value = 0
2018-01-03 10:08:58.946 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Update ASSOCIATION group_1
2018-01-03 10:08:58.946 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Update ASSOCIATION group_1: Adding node_1
2018-01-03 10:08:58.946 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Update ASSOCIATION group_1: 1 members
2018-01-03 10:08:58.947 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Config updated
... snip
2018-01-03 10:09:31.365 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 26: Incoming command class COMMAND_CLASS_HAIL, endpoint 0
2018-01-03 10:09:31.365 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 26: SECURITY not supported
2018-01-03 10:09:31.365 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 26: Received COMMAND_CLASS_HAIL V0 HAIL
2018-01-03 10:09:31.365 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveDelayedPollEvent
2018-01-03 10:09:31.366 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling intialised at 86400 seconds - start in 75 milliseconds.
2018-01-03 10:09:31.366 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 26: Commands processed 1.
2018-01-03 10:09:31.366 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 26: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@532de368.
2018-01-03 10:09:31.441 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 26: Polling...

(G H) #2274

Do you actually see the association is set in the UI? I’m not getting either – if I refresh the UI (habmin or paper), and go back into the device there’s nothing listed in them. And I’m not actually seeing associations.

I could buy a device->controller association could work and appear not to if the controller isn’t processing the events properly, but a device->device should work, I’d think.

(Scott Rushworth) #2275

Look into the link for the issue to see what I see in Habmin. It depends on the type of device. But in Habmin, I see this…

I’m on 2.3 snapshot 1159 though, so you may see different. Others were recently reporting seeing nothing in PaperUI too.

Yes, I agree. Did you try the new version? You might want to check the log to see if a report is being sent back from the device after setting the association.

(Chris Jackson) #2276

I’d also suggest to check the log to see what is being sent to the device (if anything). Use the log viewer to display logs.

(Scott Rushworth) #2277

Interesting… looks like there is something more being sent back from the device after manual operation (are there values in there?), but the binding isn’t doing anything with it?

2018-01-03 10:09:30.387 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 15 00 49 84 1A 0F 04 11 04 26 27 2B 2C 85 72 86 91 77 73 EF 82 AC 
2018-01-03 10:09:30.391 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2018-01-03 10:09:30.392 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[0x49], type=Request[0x00], dest=26, callback=132, payload=84 1A 0F 04 11 04 26 27 2B 2C 85 72 86 91 77 73 EF 82 
2018-01-03 10:09:30.392 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationUpdate[0x49], type=Request[0x00], dest=26, callback=132, payload=84 1A 0F 04 11 04 26 27 2B 2C 85 72 86 91 77 73 EF 82 
2018-01-03 10:09:30.393 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[0x49], type=Request[0x00], dest=26, callback=132, payload=84 1A 0F 04 11 04 26 27 2B 2C 85 72 86 91 77 73 EF 82 
2018-01-03 10:09:30.393 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-01-03 10:09:30.393 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2018-01-03 10:09:30.393 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: null
2018-01-03 10:09:30.394 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
2018-01-03 10:09:30.394 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[0x49], type=Request[0x00], dest=26, callback=132, payload=84 1A 0F 04 11 04 26 27 2B 2C 85 72 86 91 77 73 EF 82 
2018-01-03 10:09:30.394 [DEBUG] [otocol.serialmessage.ApplicationUpdateMessageClass] - NODE 26: Application update request. Node information received. Transaction null
2018-01-03 10:09:30.394 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 26: resetResendCount initComplete=true isDead=false
2018-01-03 10:09:30.395 [DEBUG] [otocol.serialmessage.ApplicationUpdateMessageClass] - NODE 26: Application update - no transaction.

(Chris Jackson) #2278

What do you mean? In this log, the binding sends an association SET, then reads back the configuration which shows the group has NODE 1 associated. The binding doesn’t really have too much to do with this - it will store this data, but that’s all.

Or are you talking about the subsequent messages - the NIF and HAIL - they are probably related to a manual switch press… Are you expecting that as a result of this switch press there should have been a message due to the association?

HAIL is used in the binding, but I think it’s only used if there are no associations configured since it’s an old class.

(Scott Rushworth) #2279

Yes, this. At some point this was broken but you fixed it. Looks broken again. States are not being updated with manual operation. Association looks to be set.

(Chris Jackson) #2280

But isn’t this then a problem with the device - not the binding?

(Scott Rushworth) #2281

Not sure what you mean. None of my dimmers or switches are reporting states after manually switching them. So, it isn’t just the one. Or do you mean the device config in the database?

(Chris Jackson) #2282

I mean if you’ve set the association, and the device is still not reporting, then how is this a problem with the binding? It looks like the device isn’t sending anything, even though it has an association set…

However, I don’t know what the device is, what group_1 is meant to report, and what you did that you think should be reported :wink:

(Rob Byrd) #2283

I’m running the 2.2 stable build with the latest z-wave 2.2 snapshot and have also seen this problem with my switches not reporting back a manual change. I have several different Leviton switches DZ6HD DZ15S VRMX1 VRS15. After I have recently updated the Z-Wave Snapshot Binding and added two New DZ6HD Switches they do not report status back. The ones that were added a while ago on a different snapshot work fine. I have tried to remove them and add them back and they may work for a bit then after a reset of OpenHAB they stop. I just updated to the latest snapshot yesterday and they still not not work. I will try to delete them and add them back tonight.

(Chris Jackson) #2284

Can I respectfully request that if people want to help, along with your report please provide the debug log showing (for example) the device initialisation, the setting of the association group, what happens when you trigger an event. Without some sort of debug information there’s basically nothing to go on and I’m unable to help - sorry.

(G H) #2285

I need to go through and better isolate things to get a full round trip.

Interestingly, the node I can’t get working at the moment doesn’t even show up in the Z-wave Log Viewer’s output – Node 7 is completely missing, but there are logs for it…

For example, this is part of the output when I tried to set some associations:

2018-01-03 15:13:59.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Node not awake!
2018-01-03 15:13:59.358 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: listening == false, frequentlyListening == false, awake == false
2018-01-03 15:13:59.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Node not awake!
2018-01-03 15:13:59.360 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 7: listening == false, frequentlyListening == false, awake == false
2018-01-03 15:13:59.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 7: Node not awake!
2018-01-03 15:13:59.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2018-01-03 15:13:59.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2018-01-03 15:14:19.368 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Configuration update received
2018-01-03 15:14:19.373 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Configuration update group_4 to [node_1_1]
2018-01-03 15:14:19.375 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE7: Unknown association group 4
2018-01-03 15:14:19.378 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Configuration update group_1 to [node_1_1]
2018-01-03 15:14:19.380 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE7: Unknown association group 1
2018-01-03 15:14:19.383 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Configuration update group_3 to [node_1_1]
2018-01-03 15:14:19.385 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE7: Unknown association group 3
2018-01-03 15:14:19.387 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Configuration update group_2 to [node_1_1]
2018-01-03 15:14:19.390 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE7: Unknown association group 2
2018-01-03 15:14:27.554 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 4: Requesting IsFailedNode status from controller.
2018-01-03 15:14:27.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@17e8e7b
2018-01-03 15:14:27.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2018-01-03 15:14:27.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2018-01-03 15:14:27.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start

This is a battery powered node, and I’m not sure with the Zwave plugin how to know if its woken up and the configuration change has been forwarded, but even overnight nothing gets set. With HomeSeer, if I set an association on it, it’ll get set the next time I do pretty much anything with the remote, so I assume “waking up” happens when I push any buttons at all.

Notice there’s some output about unknown association groups. Not sure if that might be indicative of the problem or not.

I also can’t figure out why all the other nodes in my test network are picked up by the log viewer, but those aren’t.

(Chris Jackson) #2286

The log viewer shows data that is sent and transmitted - if there’s no messages sent to a node, then the node is probably not awake.

It depends on the device, and some devices do work like this, but typically this is not the case. The binding will only send data to the device if the device sends a wakeup notification to say that it’s awake.

(G H) #2287

I understand that. This particular device, at least behaviorally, does work that way with Homeseer and Vera. Unfortunately all my existing hard-wired devices that have associations are in my “production” network, and the family approval for this OpenHab experiment will vanish if I pull those out and things stop working. :slight_smile:

So I need to dig through my devices and find one I can test with that isn’t battery. The only one I’ve got on the test network that a) has associations and b) is hard wired isn’t communicating anymore since I did the update, and I’ve yet to figure out why. That was one that reliably was working before.

(Austris V) #2288

is it just me or looks like with this (Jan2) version the latest device db not used? e.g. Vemmio MT-100 (#760) reports as could not resolve to a thingType!
is working fine in 1230 version.

For both - 1230 and 0102 it’s interesting to see ERROR level for kind of positive COMPLETE message (also in the habmin the green secureinclusioncompleted is shown, seems like no errors) when adding back the Danalock key (sorry I did not have zwave debug switched on - can repeat it tomorrow if it’s crucial and not a known cause)
2018-01-04 00:13:13.866 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 40: Using Scheme0 Network Key for Key Exchange since we are in inclusion mode. 2018-01-04 00:13:14.114 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 40: SECURITY_INC State=COMPLETE 2018-01-04 00:13:17.976 [INFO ] [ommandclass.ZWaveVersionCommandClass] - NODE 40: Command Class COMMAND_CLASS_BASIC has version 0!

(Chris Jackson) #2289

The database was synchronised a few days ago -:

and then updated for this version -:

I don’t think this has changed, but the logging levels need to be updated. Good to see the inclusion worked though :wink:

(Kevin) #2290

Hi Chris, I for some reason can’t get my Sclange BE469 lock to work with the binding. Is there something I’m doing wrong?

I’m using your binding from the first post, and can add unsecure things.

This is one of the last pieces I’m trying to figure out to get rid of my vera (which would be a joy!!!)