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

[chris (Chris Jackson)]

@Matt77

but i have strange things in my log, including entries like “Node dead” or “Is currently marked as failed by the controller!”.

This means that the controller thinks the device is no communicating. There was a long discussion on this earlier (somewhere!) in this thread. I don’t really know why the controller sets this state on devices that are working - according to the docs, it shouldn’t. This version of the binding uses the controller status to decide if the device is dead or not rather than doing something internally - this is why the older version works.

[vossivossi]

@chris

This version of the binding uses the controller status to decide if the device is dead or not rather than doing something internally - this is why the older version works.

Yes, there was a discussion here on this. But I remember that you planned to change this as the controller status seemed not to be reliable. Do you still plan to do this?
At the moment my “workaround” for main powered nodes (230V, no battery devices) that are marked as “dead” is to change an unimportant configuration parameter in Habmin. In this case the binding apparently seems to ignore the dead status, sends the parameter and gets a confirmation. Immediately the system starts the mesh update for the node and it works again. It is silly that these 2 clicks immediately “cure” each main powered node while the binding will show it for hours or days as “dead”.
However, for battery powered devices this does not work. I have a couple of sensative strips door/window sensors which are dead since more than several months (according to the binding and also according to the last time stamp of the xml-File in the Z-Wave folder). However, they report their status several times a day reliably to OH.
So I would like a solution that does not ignore these facts but states a “real” status of the devices (as in former times, eg. OH1, OH2 etc.)

[chris (Chris Jackson)]

@vossivossi

Do you still plan to do this?

Yes - clearly the current system doesn’t work well . I will try and look at this soon.

[chris (Chris Jackson)]

@vossivossi

So I would like a solution that does not ignore these facts but states a “real” status of the devices

I’m not sure I understand this? What is the “Real” status? The theory is that the controller has the best information, and therefore it knows the “real” status better than anyone else. The binding can try to evaluate the status, but I’m not sure what you refer to as a “real” status? I guess you are asking to ignore the controller? Either way, we have to ignore some “facts”?

Can you explain what you mean? (sorry for my lack of understanding with this).

[Matt77 (Matt)]

@chris

@Matt77

but i have strange things in my log, including entries like “Node dead” or “Is currently marked as failed by the controller!”.

This means that the controller thinks the device is no communicating. There was a long discussion on this earlier (somewhere!) in this thread. I don’t really know why the controller sets this state on devices that are working - according to the docs, it shouldn’t. This version of the binding uses the controller status to decide if the device is dead or not rather than doing something internally - this is why the older version works.

as per my previous post it seems that the controller is now not thinking any more the Node would be dead and as it looks like i receive messages from the node when the contact gets opened/closed.

2017-10-23 23:32:42.637 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 13 00 04 00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 32 
2017-10-23 23:32:42.646 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-23 23:32:42.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-10-23 23:32:42.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-10-23 23:32:42.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=33, callback=0, payload=00 21 0D 60 0D 00 00 71 05 00 00 00 FF 06 16 00 
2017-10-23 23:32:42.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-10-23 23:32:42.667 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 33: Application Command Request (ALIVE:DONE)
2017-10-23 23:32:42.672 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: resetResendCount initComplete=true isDead=false
2017-10-23 23:32:42.676 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2017-10-23 23:32:42.681 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 33: COMMAND_CLASS_MULTI_CHANNEL not found
2017-10-23 23:32:42.685 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-23 23:32:42.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-23 23:32:42.694 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.702 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.707 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.711 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.717 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.721 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.724 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 26: listening == false, frequentlyListening == false, awake == false
2017-10-23 23:32:42.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: Node not awake!
2017-10-23 23:32:42.732 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-23 23:32:42.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing

“binary sensor” and “battery level” are receiving status changes/values but not the important one “Door Sensor”

[brononius (Ben)]

Hey,

Following another topic, I’ve installed the latest zwave binding. In short, after a while, my zwave setup stops working, all other things (knx, weather, pushover…) worked.
No idea why zwave goes dead. I’m running OH2 on Ubuntu17.10 as VM under proxmox. And I’m using 2(!) GEN5 USB sticks. This worked for about 1 year without problems. It’s possible that it’s a hardware/KV issue. But after 4 complete reinstalls (OS and OH), reset of 30 zwave nodes, I don’t have any clue more how to proceed.

I did following steps right now:

1. Remove zwave binding from paperUI
2. cd /etc/openhab2/addons/
3. wget http://www.cd-jackson.com/downloads/openhab2/org.openhab.binding.zwave-2.2.0-SNAPSHOT.jar
4. ssh openhab@localhost -p8101
    feature:install openhab-transport-serial
    bundle:start org.openhab.binding.zwave
    bundle:list
       215 | Installed |  80 | 2.2.0.201710172006     | ZWave Binding

A lot of logs passes by, but all my zwave nodes stay UNINITIALIZED.
I would guess that the outlet powered devices come online after 1 hour?

2017-10-24 09:40:19.620 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-24 09:40:19.620 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Oct 24 09:40:21 CEST 2017 - 2000ms
2017-10-24 09:40:19.622 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1101: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-24 09:40:19.622 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Oct 24 09:40:21 CEST 2017 - 1998ms
2017-10-24 09:40:19.626 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99 
2017-10-24 09:40:19.630 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-10-24 09:40:19.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-24 09:40:19.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-24 09:40:19.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-24 09:40:19.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1101: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-24 09:40:19.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-10-24 09:40:19.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1101: [WAIT_RESPONSE] requiresResponse=true callback: 0
2017-10-24 09:40:19.632 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-24 09:40:19.632 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1101: Transaction COMPLETED
2017-10-24 09:40:19.632 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1101: TransactionAdvance ST: DONE
2017-10-24 09:40:19.632 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1101: TransactionAdvance WT: null {}
2017-10-24 09:40:19.632 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1101: TransactionAdvance RX: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01 
2017-10-24 09:40:19.632 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1101: TransactionAdvance TO: DONE
2017-10-24 09:40:19.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 12ms
2017-10-24 09:40:19.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 1101: Transaction completed
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1101 DONE
2017-10-24 09:40:19.633 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 23: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 23: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: listening == false, frequentlyListening == false, awake == false
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Node not awake!
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 1101: Transaction event listener: DONE: DONE -> 
2017-10-24 09:40:19.633 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
2017-10-24 09:40:19.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 1101 -- 
2017-10-24 09:40:19.637 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node Init response (0) COMPLETE
2017-10-24 09:40:19.637 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node Init transaction completed with response COMPLETE

[5iver (Scott Rushworth)]

You came over from the 2.1.0 binding, so you will need to delete your Things and then rediscover them.

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

I’ve created a test version of the binding here. You should uninstall the existing Z-Wave binding and manually install this file into the addons folder. It seems that OH comes with the serial bundle installed now so hopefully you shouldn’t need to manage that… Points to note -: Firstly - use at own risk You MUST delete your existing things and add them back. Current definitions are not compatible due to a number of breaking changes. You don’t need to re-initialise the network or re-i…

[chris (Chris Jackson)]

@Matt77

as per my previous post it seems that the controller is now not thinking any more the Node would be dead

I can’t see this from the logs though - the last logs you posted say it’s failed.

What I see in the logs is that a command class isn’t found - this might be because the initialisation hasn’t completed due to the FAILED step timing out. Without a full log it’s hard to say why this class is not found.

You could try a complete init of this node to see if that fixes the issue. If not send me the full logs.

@Matt77

“binary sensor” and “battery level” are receiving status changes/values but not the important one “Door Sensor”

Again, without logs I’m just guessing, but possibly these commands are sent to the root node and the command classes get added even if the initialisation didn’t detect them. It doesn’t necessarily mean the initialisation completed.

[vossivossi]

@chris

Can you explain what you mean? (sorry for my lack of understanding with this).

My impression is that the current status handling of dead nodes in the dev binding is not reliable while old versions (OH1 or OH2 non dev versions) appeared to be more reliable. I understood that you implemented your “own” status handling on the binding side in these old versions while you rely on the controller information in the dev binding.
So I would suggest to reimplement your “own status handling” if possible as from my experience it used to be superior to the current one.

[chris (Chris Jackson)]

@vossivossi

So I would suggest to reimplement your “own status handling”

That’s what I said I was going to do…

[Matt77 (Matt)]

@chris thanks for looking into this.
i attached the log from today. i tried several times to reinitialize the node (node 33) but the
COMMAND_CLASS_MULTI_CHANNEL is still showing as not found.

events.xml (486.8 KB)

[chris (Chris Jackson)]

@Matt77

i attached the log from today.

The log doesn’t really have much in it. It’s just an event log rather than an actual log… What I’d like to see is the initialisation - delete the xml and restart, or perform an initialisation so we can see what’s happening.

Thanks.

[Matt77 (Matt)]

@chris

@Matt77

i attached the log from today.

The log doesn’t really have much in it. It’s just an event log rather than an actual log… What I’d like to see is the initialisation - delete the xml and restart, or perform an initialisation so we can see what’s happening.

Thanks.

So here the log aver a full new initializing of Node 33.

openhab.xml (804.0 KB) (ZIP File)

[chris (Chris Jackson)]

Thanks…

Interesting stuff (unfortunately!). Give me a day or two to think about this one - it’s linked with the multi-instance-association configuration I think…

[Matt77 (Matt)]

thanks again. also i noticed, and i thing i have read a similar case somewhere, that after a restart the battery nodes are not getting fully initialized till the next wakeup. however they never get fully re-initialized automatically.

for example, after the restart my node 26 (fibaro motion sensor) is reporting all alarms without any issue but Battery state, temperature, … are not getting updated. even after the 7200 sec wakeup interval not. actually i have to manually wake it up, which is OK as long as i have only one. but should that not happened automatically? in the snapshot binding the same was working fine.

[chris (Chris Jackson)]

@Matt77

Battery state, temperature, … are not getting updated.

Battery state is polled, so if the device isn’t waking up, then it won’t get updated. However temperature should be sent unsolicited so shouldn’t be related to wakeup.

@Matt77

in the snapshot binding the same was working fine.

The wakeup shouldn’t be related to the binding - it’s a device function. Check the logs to see if it’s waking up - if it is, then let’s see what it’s doing.

[vossivossi]

@chris

That’s what I said I was going to do…

Great!

[stevenazari]

I get notifications about this thread every day…

so I’m going to give you all a notification.

Nothing to add but here you go.

[gundark2 (Sean Morrison)]

Hoping there is help out there, I cant seem to get my Yale lock to work, this is starting with the Yale lock factory settings, and I keep the lock on, by pressing the screen the whole time during inclusion and while I set it up in the paperui.
Best example of an error, as nothing seems to work, when I turn the lock manually I get this in my logs:

Receive Message = 01 04 01 13 01 E8 
[DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
[DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
[DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
[DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
[DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 121: [WAIT_RESPONSE] requiresResponse=true callback: 75
[DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
[DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 121: [WAIT_RESPONSE] requiresResponse=true callback: 75
[DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
[DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: sentData successfully placed on stack.
[DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance ST: WAIT_RESPONSE
[DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance WT: null {}
[DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
[DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance TO: WAIT_REQUEST
[DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 121: Advanced to WAIT_REQUEST
[DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: TID 121: Transaction not completed
[DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
[DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
[DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
[DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
[DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Oct 24 34 MDT 2017 - 5000ms
[DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 4B 00 00 02 A2 
[DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
[DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=75, payload=4B 00 00 02 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=75, payload=4B 00 00 02 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=75, payload=4B 00 00 02 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 121: [WAIT_REQUEST] requiresResponse=true callback: 75
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 121: [WAIT_REQUEST] requiresResponse=true callback: 75
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 121: (Callback 75)
 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 121: callback 75
 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=75, payload=4B 00 00 02 
 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: SendData Request. CallBack ID = 75, Status = Transmission complete and ACK received(0)
 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: Transaction COMPLETED
 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance ST: DONE
 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance WT: null {}
 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=0, callback=75, payload=4B 00 00 02 
 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 121: TransactionAdvance TO: DONE
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Response processed after 29ms
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: TID 121: Transaction completed
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: notifyTransactionResponse TID:121 DONE
 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 04 00 09 18 98 81 C5 13 79 F1 24 C9 E4 1E 4A 5D 35 BA DC EE D2 7A 7B 9C 9F E5 A5 DA 44 
 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=9, callback=0, payload=00 09 18 98 81 C5 13 79 F1 24 C9 E4 1E 4A 5D 35 BA DC EE D2 7A 7B 9C 9F E5 A5 DA 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=9, callback=0, payload=00 09 18 98 81 C5 13 79 F1 24 C9 E4 1E 4A 5D 35 BA DC EE D2 7A 7B 9C 9F E5 A5 DA 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=9, callback=0, payload=00 09 18 98 81 C5 13 79 F1 24 C9 E4 1E 4A 5D 35 BA DC EE D2 7A 7B 9C 9F E5 A5 DA 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 9: Application Command Request (ALIVE:DYNAMIC_VALUES)
 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Decapsulating COMMAND_CLASS_SECURITY
 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 9: SECURITY_ERR Failed authentication! [C7 B3 05 83 64 26 F4 15 ]<>[D2 7A 7B 9C 9F E5 A5 DA ]
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing

Here is some of the inclusion logs, i think:

 [INFO ] [smarthome.event.BindingEvent        ] - org.openhab.binding.zwave.event.BindingEvent@420f65e3
 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 2D 02 00 00 9D 
 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=2, callback=45, payload=2D 02 00 00 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=2, callback=45, payload=2D 02 00 00 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=2, callback=45, payload=2D 02 00 00 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=2, callback=45, payload=2D 02 00 00 
 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: New node found.
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 4A 2D 03 09 06 04 40 03 72 86 98 B2 
 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=3, callback=45, payload=2D 03 09 06 04 40 03 72 86 98 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=3, callback=45, payload=2D 03 09 06 04 40 03 72 86 98 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=3, callback=45, payload=2D 03 09 06 04 40 03 72 86 98 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=3, callback=45, payload=2D 03 09 06 04 40 03 72 86 98 
 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - NODE 9: Adding slave.
 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 2E 9B 
 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 2E 9B 
 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 75: Transaction Start type AddNodeToNetwork 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 75: [WAIT_REQUEST] requiresResponse=true callback: 46
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Oct 24 17:57:01 MDT 2017 - 5000ms
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 75: [WAIT_REQUEST] requiresResponse=true callback: 46
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Oct 24 17:57:01 MDT 2017 - 5000ms
 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller end inclusion
 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 9: Including node.
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Creating new instance of command class COMMAND_CLASS_NO_OPERATION
 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Command class COMMAND_CLASS_NO_OPERATION, endpoint 0 created
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Version = 1, version set. Enabling extra functionality.
 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Adding command class COMMAND_CLASS_NO_OPERATION to the list of supported command classes.
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Creating new instance of command class COMMAND_CLASS_BASIC
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Command class COMMAND_CLASS_BASIC, endpoint 0 created
 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Adding command class COMMAND_CLASS_BASIC to the list of supported command classes.
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Creating new instance of command class COMMAND_CLASS_MANUFACTURER_SPECIFIC
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created
 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 9: Inclusion is adding command class COMMAND_CLASS_MANUFACTURER_SPECIFIC.
 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Adding command class COMMAND_CLASS_MANUFACTURER_SPECIFIC to the list of supported command classes.
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Creating new instance of command class COMMAND_CLASS_VERSION
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Command class COMMAND_CLASS_VERSION, endpoint 0 created
 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 9: Inclusion is adding command class COMMAND_CLASS_VERSION.
 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Adding command class COMMAND_CLASS_VERSION to the list of supported command classes.
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Creating new instance of command class COMMAND_CLASS_SECURITY
 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 9: Command class COMMAND_CLASS_SECURITY, endpoint 0 created
 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 9: Inclusion is adding command class COMMAND_CLASS_SECURITY.
 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 9: Updated networkKey
 [DEBUG] [mmandclass.ZWaveSecurityCommandClass] - NODE 9: setupNetworkKey useSchemeZero=false
 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 2E 06 09 00 93 
 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=6, callback=46, payload=2E 06 09 00 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=6, callback=46, payload=2E 06 09 00 
 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 9: Adding command class COMMAND_CLASS_SECURITY to the list of supported command classes.
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 75: [WAIT_REQUEST] requiresResponse=true callback: 46
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=6, callback=46, payload=2E 06 09 00 
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 75: [WAIT_REQUEST] requiresResponse=true callback: 46
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 75: [WAIT_REQUEST] requiresResponse=true callback: 46
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 75: (Callback 46)
 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 75: callback 46
 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], dest=6, callback=46, payload=2E 06 09 00 
 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 9: Device discovered
 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:controller:node9' to inbox.
 [INFO ] [smarthome.event.InboxAddedEvent     ] - Discovery Result with UID 'zwave:device:controller:node9' has been added.
 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
 [INFO ] [smarthome.event.BindingEvent        ] - org.openhab.binding.zwave.event.BindingEvent@

Other stuff:

[ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: SECURITY_INC State=COMPLETE


var/lib/openhab2/zwave$ ls -la
Oct 24 18:02 network_d53343a1__node_1.xml
Oct 24 18:03 network_d53343a1__node_2.xml
Oct 24 18:03 network_d53343a1__node_3.xml
Oct 24 18:03 network_d53343a1__node_4.xml
Oct 24 18:03 network_d53343a1__node_5.xml
Oct 24 18:00 network_d53343a1__node_9.xml
Oct 22 00:11 node1.xml
Oct 22 00:11 node2.xml
Oct 22 00:11 node3.xml
Oct 22 00:11 node4.xml
Oct 22 00:12 node5.xml

[5iver (Scott Rushworth)]

Here are a handful of questions that will help in troubleshooting. Which version of Yale lock, and how many other secure devices do you have included? Are you using the jar from the first post, with no other zwave bindings installed (bundle:list |grep -i zwave)? Is security enabled in the controller settings? Do you see SECURITY_INCLUSION_FAILED anywhere in your logs? When selecting the lock’s Thing in Habmin, under Attributes> Security, do you see a red X or green checkmark?