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

chris · March 17, 2018, 1:40pm

Ok, so don’t worry about another log right now. I’ll post an update at some point today - let’s see if it solves the issue.

I’m not 100% sure why I don’t see this issue with every inclusion, but there is a transaction matching issue at the end of the inclusion. This wastes 10 seconds and I guess different devices implement the security timeout slightly differently and 10 seconds may, or may not, work.

Hopefully I’ve fixed this now and it will be a bit more deterministic!

stefan.hoehn · March 17, 2018, 2:36pm

@chris

Can you elaborate a bit about inclusion time of the controller?

On your website it is said that inclusion duration is about 30 seconds (at least this is what I understood).

However, when I look at my stick (Z-Wave USB Stick (ZMEEUZB1)) the blue lamp only starts flashing after 20 seconds of pressing the discover-icon in habmin and then continues for about 10 seconds only…

What I notice is that exactly at the time when the blue led starts blink the green notification on habmin appears telling that the “inclusion has started” and the next green notification telling about “inclusion has ended” is in sync with the ending of the blue blinking.

So that leads me to the thinking that inclusion only happens for a time of 10 seconds which is a very short time frame to be successful especially with devices that are on battery.

Here are the filtered logs of the inclusion controller which point into the same direction:

2018-03-17 14:53:52.460 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart

2018-03-17 14:54:03.047 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart

2018-03-17 14:54:03.050 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.

2018-03-17 14:54:03.259 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent

2018-03-17 14:54:03.273 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got an event from Z-Wave network: ZWaveInclusionEvent

2018-03-17 14:54:03.276 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone

2018-03-17 14:54:03.282 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.

2018-03-17 14:54:03.300 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion

The background is that I try to include a “sensitive strip” which alone takes about 10 seconds to wake up, so the overlap might be my issue.

Any thoughts on this?
Stefan

chris · March 17, 2018, 3:17pm

This is different.

When the controller is put into inclusion mode, it stays there for 30 seconds. The secure inclusion time is a different time - once a device is included, it has around 10 to 15 seconds to complete the secure inclusion (basically the key exchange) - after this, it’s impossible to securely use the device.

I have no idea about the flashing LEDs, but the inclusion timer is 30 seconds - not 10 seconds.

Please don’t filter the logs - I have no idea what is going on without the full log. It’s probable that something else was happening that blocked the start command being sent even though the timer was started. I really have no clue though without the logs - sorry.

stefan.hoehn · March 17, 2018, 3:36pm

Ok, sure I can provide the full logs and from what I can see (by browsing also uploading to your viewer) I see the new device never appearing.

note that I had to rename the filename to .json - otherwise it wouldn’t have let me uploaded it.

zwavelog.json (34.8 KB)

cheers
Stefan

chris · March 17, 2018, 3:47pm

Please provide the logs from the time the inclusion starts - the log you’ve provided is already after the inclusion starts.

Well, that’s a different issue than how long the timer is

Clinton_Johnson · March 17, 2018, 5:34pm

HAHA Yes!! there are a lot of them! so sorry i thought I had linked in what it was! it is an Aeotec Z-Stick Gen5

chris · March 17, 2018, 6:33pm

I’ve updated the binding - let me know if there’s any improvement, and if not, please provide a log (without the line truncation if possible ).

chris · March 17, 2018, 7:21pm

Maybe this helps -:

stefan.hoehn · March 17, 2018, 7:50pm

Probably not a good idea to strip it down, sorry.

From what I can see, Inclusion starts at 2018-03-17 17:32:07.537

I had to pack it as a zip-file and rename it from .zip to .json to be able to upload it. Rename it back to .zip after download.

And you are right: it starts at :07 and ends at :37, which is 30 seconds. it seems that “Wave controller start inclusion - mode 2”, which starts at :25 only last about 10 seconds in the end.

I am really wondering what exactly then blue blinking is
and why habmin only brings up the notification 10 seconds before the end (and then telling that inclusion is over after 10 seconds).

tia
Stefanopenhab.json (117.1 KB)

chris · March 17, 2018, 8:11pm

The issue is that before the discovery, the binding runs through a check to see if any devices the controller already knows about need to be added to the system. This is taking quite a long time on your system and this is eating into the time.

I guess you have a very slow computer? I’ll have to have a look at this, but it’s not obvious how to improve this within the limitations of ESH.

Are you using HABmin? If so, you will get notifications when inclusion actually starts and stops.

2018-03-17 17:32:07.537 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Starting ZWave inclusion scan for zwave:serial_zstick:16117d1edc0
2018-03-17 17:32:37.748 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.

Clinton_Johnson · March 17, 2018, 8:22pm

IT WORKED!! thank you!

chris · March 17, 2018, 8:24pm

Cool - thanks. Hopefully this might be the reason some others are having trouble as well . Let’s see .

Doc · March 18, 2018, 3:15am

I just did a new OpenHABian install and used the test binding dated 17th March. I couldn’t get my ZCOMBO smoke detectors to be recognized. After several hours of trying to wake them up, etc. … I gave up. I tried the previous binding (March 3rd I believe was when I downloaded it) and all of my ZCOMBOs are working.

chris · March 18, 2018, 8:54am

I would be surprised if it was related to the binding as fundamentally there is no change to the inclusion itself, but please provide the debug logs from the failed attempts and I’ll take a look.

stefan.hoehn · March 18, 2018, 10:15am

I have raspberry pi3. Should be fast enough I would say but a good point.

Yes I am using habmin and I start he inclusion from habmin
I waited until the load is quite low (about 0.1)
I then started the inclusion process and what I see is
- Java (OH) goes up quite a lot (which is probably not a surprise): 110-120% cpu
- What is also very much rising is NODE which I am not sure what is doing: 40%
- And also influxdb goes up to: 40%
- in total the load is never higher than 0.75 which is not to bad though

Finally I got the device synced by waiting exactly when the log says it is starting the inclusion. Luckily I was also able to wake up / start inclusion and therefore it worked.

I am still surprised why OH, node and influxdb together using almost 200% CPU during that time.

dawys · March 18, 2018, 1:17pm

Hi, I have the following problem. I have a Z-Wave dual switch Fibaro FGS223. when I turn it on, the current consumption (Electric meter in watts) is transmitted and output by item.

I also have also a Z-Wave Dimmer Fibaro FGD212. If I turn this on unfortunately no current consumption is transmitted.

Do you know the reason?

MrWendal · March 25, 2018, 9:10am

Hello,

After restarting my Linux server I am also getting a similar InvalidKeyException for a couple (but not all) devices:

25-Mar-2018 09:37:41.560 [ERROR] [al.protocol.commandclass.ZWaveSecurityCommandClass] - NODE 46: Error decapsulating security message
java.security.InvalidKeyException: No installed provider supports this key: (null)
        at javax.crypto.Cipher.chooseProvider(Cipher.java:893) [?:?]
        at javax.crypto.Cipher.init(Cipher.java:1249) [?:?]
        at javax.crypto.Cipher.init(Cipher.java:1186) [?:?]
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.generateMAC(ZWaveSecurityCommandClass.java:501) [212:org.openhab.binding.zwave:2.3.0.201803171831]
        at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.getSecurityMessageDecapsulation(ZWaveSecurityCommandClass.java:303) [212:org.openhab.binding.zwave:2.3.0.201803171831]
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.processCommand(ZWaveNode.java:1170) [212:org.openhab.binding.zwave:2.3.0.201803171831]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$ZWaveReceiveThread.run(ZWaveTransactionManager.java:440) [212:org.openhab.binding.zwave:2.3.0.201803171831]

I’ve seen this for Fibaro Door Sensors (old and new models), Fibaro Motion Sensor and a Fibaro Dimmer 2.

Please let me know if you would like me to collect any logs (alas I had logging turned down when I’ve seen this so far) and what scenarios to get them in.

Thanks,
Steve.

MrWendal · March 25, 2018, 1:15pm

To follow up the InvalidKeyException, I’ve taken a quick look at the files in /var/lib/openhab2/zwave and have noticed a couple of things:

I have files with names network_00000002__node_<XX>.xml and files with names network_<YYYYYYYY>__node_<XX>.xml, where is the same for all files and I assume the ZWave network identity.
For the the nodes which started failing with InvalidKeyException there is only an xml file with network_00000002__node_<XX>.xml name. These nodes had been working successfully for a few days (possibly a week or 2).

In addition, I’ve tried excluding and including a test node (a Fibaro motion sensor in this case) a few times and noticed the following:

Following inclusion in HABmin I can see “Using Security” ticked and things are working as expected (for example in this case motion events are generated).
Only the 00000002 version of the xml file is generated.
I stop OH2 and there is no serializing debug messages relating the the relevant test node.
I start OH2 and the exception occur. In HABmin “Using Security” is now unticked.
Waking the node multiple times before shutting down OH2 does not make a difference.
Stopping OH2, copying over the network_00000002__node_<XX>.xml XML file to a network_<YYYYYYYY>__node_<XX>.xml XML and restarting OH2 makes no difference (as expected, as the contents for working nodes is quite different anyway).

Hopefully the above notes and observations are useful. I have debug logs for at least a couple of the test tries if they are also useful.

Thanks,
Steve.

chris · March 25, 2018, 4:01pm

I don’t really know why this is happening. It’s telling me that your system doesn’t support some sort of decryption, but I’m not really sure what. I can guess that you have reset your stick recently and that might be somehow related since you have two sets of XML files. The 0000002 number is pretty strange, but as this comes from the stick, I guess it’s ok…

Given that the network ID has changed, I would suggest to remove the XML files, exclude the devices and add them back into the network to resolve the issues with the apparent network Id change.

MrWendal · March 25, 2018, 6:06pm

I’ve not reset the Aeon Gen5 Z-Stick for a while now. I’ve thought it strange to have 2 sets of XML files created.

I’ve checked the Network ID in the Zensys tools for this stick and it comes up matching the number.

It seems that somehow the 00000002 ones get created when I include devices even though that is not the Network ID. In the logs I can see logging like this (I only have 1 Z-Stick connected to the PC) when I shutdown OH2:

25-Mar-2018 14:02:51.765 [DEBUG] [org.openhab.binding.zwave                         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=296, service.bundleid=212, service.scope=singleton} - org.openhab.binding.zwave
25-Mar-2018 14:02:51.769 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
25-Mar-2018 14:02:51.779 [DEBUG] [ternal.protocol.initialization.ZWaveNodeSerializer] - NODE 55: Serializing to file /var/lib/openhab2/zwave/network_00000002__node_55.xml
25-Mar-2018 14:02:51.795 [DEBUG] [org.openhab.binding.zwave                         ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=365, service.bundleid=212, service.scope=singleton} - org.openhab.binding.zwave
25-Mar-2018 14:02:51.799 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - Handler disposed. Unregistering listener.
25-Mar-2018 14:02:51.809 [DEBUG] [ternal.protocol.initialization.ZWaveNodeSerializer] - NODE 33: Serializing to file /var/lib/openhab2/zwave/network_<YYYYYYYY>__node_33.xml

Node 55 in this example is the node I was testing with where there are problems are restarting OH2.

Interesting you mention it comes from the controller, I wonder whether something has gone a bit, erm, wobbly with it.

Thanks,
Steve.