Thanks Mark!
Here is the Really long Debug file
Yes I took it off the door an it is setting next to openhab
This log doesn’t include the discovery of the device. Assuming you did another inclusion, does the lock show as Using Security in Habmin, under Attributes?
And just to make sure… what do you get from:
bundle:list | grep -i zwaveHey I am sorry! I didnt get the whole log. I have updated the doc it is really long. None 17 was the lock
Ran the command here is the output
openhab> bundle:list | grep -i zwave
228 │ Active │ 80 │ 2.3.0.201803111809 │ ZWave Binding
openhab>
update I am seeing this alot.
NODE 17: SECURITY NOT required on COMMAND_CLASS_VERSION
This is a very interesting log (thanks 
). I need to understand it better, but there are some delays following the inclusion that probably are too long, and this is probably screwing up the secure inclusion.
Secure inclusion needs to happen within a number of seconds of the initial inclusion (10 to 15). There is at least a 10 second delay here, so at best we’re border line.
It looks to me like the stick is not responding as I’m expecting to the “end inclusion mode” command, and this is causing the delay. I need to have a look to see if there’s a better way to handle this - I could probably (safely) change this to not wait for the response from the stick, although maybe that causes other issues…
I’ll have a think about this over the next day or so and probably propose a change.
As a matter of interest, what stick do you have? You said “Z-Stick Gen 5”, but I’m not sure what manufacturer that means as there are a lot of Gen 5 sticks out there…
@Clinton_Johnson can you provide another log please - same sort of thing as before. I’d like to see if the same thing happens.
Also, please provide the raw log - something is truncating lines in the log that you provided earlier, so long lines are all uniform length with a $ on the end and I loose a lot of information.
Thanks.
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!
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
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.
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
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 
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
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 
).
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)
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.
IT WORKED!! thank you!
1 Like
Cool - thanks. Hopefully this might be the reason some others are having trouble as well . Let’s see .
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.
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.
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.