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

When I try to include a Fibaro FGS-223 it throws an exception in the log

2018-03-13 08:51:40.462 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 9: setupNetworkKey useSchemeZero=false
2018-03-13 08:51:40.544 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:controller:node9' to inbox.
2018-03-13 08:51:53.744 [ERROR] [ve.internal.protocol.ZWaveController] - Exception during ZWave thread: Input 2. {}
java.lang.ArrayIndexOutOfBoundsException: 3
	at org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveSecurityCommandClass.isSecurityNonceReportMessage(ZWaveSecurityCommandClass.java:1067) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.SerialMessage$SerialMessageComparator.compare(SerialMessage.java:692) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.SerialMessage$SerialMessageComparator.compare(SerialMessage.java:1) [211:org.openhab.binding.zwave:]
	at java.util.concurrent.PriorityBlockingQueue.siftUpUsingComparator(Unknown Source) [?:?]
	at java.util.concurrent.PriorityBlockingQueue.offer(Unknown Source) [?:?]
	at java.util.concurrent.PriorityBlockingQueue.add(Unknown Source) [?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.enqueue(ZWaveController.java:546) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.sendMessage(ZWaveNodeInitStageAdvancer.java:260) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.addToQueue(ZWaveNodeInitStageAdvancer.java:1170) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.advanceNodeStage(ZWaveNodeInitStageAdvancer.java:1082) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.handleNodeQueue(ZWaveNodeInitStageAdvancer.java:230) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.ZWaveIncomingEvent(ZWaveNodeInitStageAdvancer.java:1306) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.notifyEventListeners(ZWaveController.java:567) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingRequestMessage(ZWaveController.java:250) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.handleIncomingMessage(ZWaveController.java:214) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.access$7(ZWaveController.java:208) [211:org.openhab.binding.zwave:]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1324) [211:org.openhab.binding.zwave:]

And in the attributes, it have the following look

This is normally caused by a corrupt frame received from the device - or at least a frame that is not what the binding expects. Possibly it’s an invalid Nonce, but that’s just a guess and I’d need to see a debug log showing the received frame to say more.

Those with kwikset door locks: Does anyone have the current status (locked vs unlocked) reporting reliably in OH? I find mine is typically incorrect, even when soley using OH to lock/unlock (that is, no one has manually changed it’s state).

Here is my config:

Switch DoorLock_Back_Door 			<lockdy> 			(gDoorLocks, gIndoor)  {channel="zwave:device:15bfa0704b9:node10:lock_door"}
Switch item=DoorLock_Back_Door label="Deck Door Lock"


Seems my previus error was solved by reboot. Almost like i need to reboot ophab after updating the binding ?

Posting incase others did the same dump thing :slight_smile:

@chris the codebase for this thread, is it the development branch?
Would like to submit a PR for minor logging issue I see in my logs

Hi Dave,
Yes, that’s correct - please feel free to submit any PR :slight_smile: .


NOOB here looking for some help. I have tried everything I have found in the 2590 post before me to get a Schlage BE469WK setup but for the life of me i keep getting “NODE 9: SECURITY_INC State=FAILED, Reason=GET_SCHEME”

I have done the following
Inclusion = High Power Inclusion
Security inclusion mode = all devices
Network Key = is set
I have reset the Lock and reinstalled openhab

I am using a Z-Stick Gen5

2018-03-15 21:12:26.072 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:1622c7d4dc8' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE): Controller is offline

==> /var/log/openhab2/openhab.log <==

2018-03-15 21:12:26.087 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized

2018-03-15 21:12:26.123 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller

2018-03-15 21:12:26.127 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

2018-03-15 21:12:29.348 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found

2018-03-15 21:12:29.352 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API

2018-03-15 21:12:29.355 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller

2018-03-15 21:12:29.361 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------

2018-03-15 21:12:29.364 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 1

2018-03-15 21:12:29.367 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------

==> /var/log/openhab2/events.log <==

2018-03-15 21:12:29.469 [hingStatusInfoChangedEvent] - 'zwave:serial_zstick:1622c7d4dc8' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2018-03-15 21:12:29.493 [me.event.ThingUpdatedEvent] - Thing 'zwave:serial_zstick:1622c7d4dc8' has been updated.

2018-03-15 21:12:35.767 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@210e50

==> /var/log/openhab2/openhab.log <==

2018-03-15 21:12:51.846 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:1622c7d4dc8:node9' to inbox.

==> /var/log/openhab2/events.log <==

2018-03-15 21:12:51.848 [home.event.InboxAddedEvent] - Discovery Result with UID 'zwave:device:1622c7d4dc8:node9' has been added.

2018-03-15 21:12:51.854 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@e6f3e4

2018-03-15 21:13:09.959 [me.event.InboxRemovedEvent] - Discovery Result with UID 'zwave:device:1622c7d4dc8:node9' has been removed.

2018-03-15 21:13:10.024 [hingStatusInfoChangedEvent] - 'zwave:device:1622c7d4dc8:node9' changed from UNINITIALIZED to INITIALIZING

2018-03-15 21:13:10.031 [hingStatusInfoChangedEvent] - 'zwave:device:1622c7d4dc8:node9' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2018-03-15 21:13:10.047 [hingStatusInfoChangedEvent] - 'zwave:device:1622c7d4dc8:node9' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2018-03-15 21:13:10.056 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:1622c7d4dc8:node9' has been updated.

2018-03-15 21:13:10.060 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:1622c7d4dc8:node9' has been updated.

==> /var/log/openhab2/openhab.log <==

2018-03-15 21:13:18.047 [INFO ] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: SECURITY_INC State=FAILED, Reason=GET_SCHEME

==> /var/log/openhab2/events.log <==

2018-03-15 21:13:18.048 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@1fefee

2018-03-15 21:13:18.478 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:1622c7d4dc8:node9' has been updated.

2018-03-15 21:13:18.558 [hingStatusInfoChangedEvent] - 'zwave:device:1622c7d4dc8:node9' changed from ONLINE to UNINITIALIZED

2018-03-15 21:13:18.578 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@126c82

2018-03-15 21:13:18.627 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:1622c7d4dc8:node9' has been updated.

2018-03-15 21:13:18.657 [hingStatusInfoChangedEvent] - 'zwave:device:1622c7d4dc8:node9' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)

2018-03-15 21:13:18.684 [hingStatusInfoChangedEvent] - 'zwave:device:1622c7d4dc8:node9' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING

2018-03-15 21:13:18.689 [hingStatusInfoChangedEvent] - 'zwave:device:1622c7d4dc8:node9' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2018-03-15 21:13:18.692 [hingStatusInfoChangedEvent] - 'zwave:device:1622c7d4dc8:node9' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2018-03-15 21:13:18.711 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:1622c7d4dc8:node9' has been updated.

2018-03-15 21:13:19.203 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@19e9740

2018-03-15 21:13:19.217 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:1622c7d4dc8:node9' has been updated.

Unless you have a reason for this, go with NWI. Shouldn’t affect the lock though.

Unless you have a reason for this, go with Entry Control Devices. This won’t affect the lock either.

It looks as though you’re not logging the zwave binding in debug mode, which might help in troubleshooting. Have you been excluding the lock between attempts? Are you running inclusion through OH, with the lock close to the controller?

Hey 5iver!
thanks for the reply! I dont fully understand how to turn on the debug mode. Can you point me some were I can read about it and how to do it? As for excluding it, each time yes.

Also thank you i will switch back to NWI and Entry Control Devices


When in the console, use this to enable debug logging for the zwave binding

log:set DEBUG org.openhab.binding.zwave

And this to go to the default log level.

log:set INFO org.openhab.binding.zwave

OK, then it looks like the lock just hasn’t securely included then. What about this?

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 zwave

Hey 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 │     │ ZWave Binding

update I am seeing this alot.


This is a very interesting log (thanks :slight_smile: ). 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.


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?

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)