Openhab2 and Schlage Be469 NX

The Schlage BE469NX is connected to OpenHab2 on Raspberry 3 with node4, but not see node4.xml file in /var/lib/openhab2/zwave.

So I cannot receive any state of the Lock and cannot send command to lock.

Any issue for me, please help me to control it.

Lock security is a fairly recent addition to the zwave binding. What version do you have?

I just upgrade to zwave biding 2.1.snapshot, after connect to lock, I got the error in log

2017-05-14 18:01:45.950 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 4: setupNetworkKey useSchemeZero=false
2017-05-14 18:01:51.313 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 4: setupNetworkKey useSchemeZero=false
2017-05-14 18:01:51.388 [ERROR] [curityCommandClassWithInitialization] - NODE 4: SECURITY_ERROR Invalid state! Secure inclusion has not completed and we are not in inclusion mode. Aborting
2017-05-14 18:02:00.000 [INFO ] [ommandclass.ZWaveVersionCommandClass] - NODE 4: Command Class LOCK has version 0!

Do we need config anything for security lock ?

You might start with the Thing deletion mentioned here as a requirement

It looks like you are using the OH1 binding? Is this correct?

I am using OH2 snapshot 2.1.0~20170513100

I don’t mean the overall runtime - clearly this is going to be OH2 - I meant the binding. It looks like you are using OH1 version of ZWave. If this isn’t what you want, then you might want to check the installation.

If you want to use OH2 with secure devices, then you need to manually install the development binding as @rossko57 said above.

Hi Chris,

I am using the lastest OH2 snapshot.

Ok, then as above, it won’t work. You need to use the one that is referenced in the security thread.

How do you connect the lock to openhab?

You need to use the development version of the binding - see this thread for more information (the first 10 messages or so should give you the installation information).

Thanks! I already installed manually the binding but I can not discover the lock when I scan for a thing in Paper UI. Nothing shows up.zwave_binding

What do the debug logs show?


```php
pi@raspberrypi:/var/log/openhab2 $ tail openhab.log
2018-01-30 15:26:49.485 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-01-30 15:30:05.733 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-01-30 15:42:39.843 [WARN ] [shd.server.session.ServerSessionImpl] - exceptionCaught(ServerSessionImpl[openhab@/127.0.0.1:38626])[state=Opened] InterruptedByTimeoutException: null
2018-01-30 15:43:30.751 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-01-30 15:43:59.430 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-01-30 15:44:44.485 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-01-30 15:56:53.277 [WARN ] [age.RequestNetworkUpdateMessageClass] - RequestNetworkUpdate not placed on stack.
2018-01-30 16:10:01.538 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-01-30 16:11:39.205 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0
2018-01-30 16:16:47.210 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovery could not resolve to a thingType! 7FFFFFFF:7FFFFFFF:7FFFFFFF::0.0



```php
pi@raspberrypi:/var/log/openhab2 $ tail events.log
2018-01-30 16:11:39.254 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@14d3ded
2018-01-30 16:12:01.950 [vent.ItemStateChangedEvent] - Date changed from 2018-01-30T16:11:01.932-0500 to 2018-01-30T16:12:01.936-0500
2018-01-30 16:13:01.953 [vent.ItemStateChangedEvent] - Date changed from 2018-01-30T16:12:01.936-0500 to 2018-01-30T16:13:01.939-0500
2018-01-30 16:14:01.959 [vent.ItemStateChangedEvent] - Date changed from 2018-01-30T16:13:01.939-0500 to 2018-01-30T16:14:01.943-0500
2018-01-30 16:15:01.970 [vent.ItemStateChangedEvent] - Date changed from 2018-01-30T16:14:01.943-0500 to 2018-01-30T16:15:01.947-0500
2018-01-30 16:16:01.969 [vent.ItemStateChangedEvent] - Date changed from 2018-01-30T16:15:01.947-0500 to 2018-01-30T16:16:01.951-0500
2018-01-30 16:16:06.765 [vent.ItemStateChangedEvent] - prediccion_lluvia changed from 1 to 0
2018-01-30 16:16:47.257 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@18ac0b4
2018-01-30 16:17:02.729 [vent.ItemStateChangedEvent] - Date changed from 2018-01-30T16:16:01.951-0500 to 2018-01-30T16:17:02.712-0500
2018-01-30 16:18:02.733 [vent.ItemStateChangedEvent] - Date changed from 2018-01-30T16:17:02.712-0500 to 2018-01-30T16:18:02.718-0500

I do not know what is the NODE 2: Device discovery event… because before I tested with all my zwave devices off and still have that event on the log.

Please also describe what you are doing. To include a lock, you must include it directly through HABmin (or PaperUI) - reset the lock, put the binding into include mode, then see what happens. I really suggest to use HABmin as it will provide more feedback.

We also need a debug log - this really doesn’t provide a lot of information. Put the binding into debug mode with log:set DEBUG opr.openhab.binding.zwave.

My steps are:

  1. Reset lock
  2. Open Habmin
  3. Go to Things and Start searching devices
  4. In the lock. Initialize the inclousion mode by following the manual steps.
    This is the debug log.
18:29:00.793 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:29:00.794 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:00.796 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00
18:29:00.798 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:29:00.798 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:00.801 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:05 ECT 2018 - 5000ms
18:29:00.804 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 39: [WAIT_REQUEST] requiresResponse=true callback: 7
18:29:00.807 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:00.810 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:05 ECT 2018 - 4991ms
18:29:00.813 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:00.816 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:00.818 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:05 ECT 2018 - 4983ms
18:29:00.821 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00
18:29:00.823 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 39: [WAIT_REQUEST] requiresResponse=true callback: 7
18:29:00.824 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18:29:00.826 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 39: [WAIT_REQUEST] requiresResponse=true callback: 7
18:29:00.827 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 39: (Callback 7)
18:29:00.829 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - NO callback match! (7 <> 1)
18:29:00.830 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
18:29:00.832 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=1, payload=01 01 00 00
18:29:00.834 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
18:29:00.835 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
18:29:00.854 [INFO ] [smarthome.event.BindingEvent         ] - org.openhab.binding.zwave.event.BindingEvent@69f906
18:29:00.853 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
18:29:00.857 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:00.859 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:00.860 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:00.862 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:00.863 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:05 ECT 2018 - 4938ms
18:29:05.801 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
18:29:05.805 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 39: Timeout at state WAIT_REQUEST. 3 retries remaining.
18:29:05.809 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 39: Transaction is current transaction, so clearing!!!!!
18:29:05.813 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 39: Transaction CANCELLED
18:29:05.817 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:29:05.820 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:39 CANCELLED
18:29:05.825 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:05.832 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:29:05.836 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:29:05.841 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:29:05.845 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:29:05.849 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:29:05.853 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
18:29:05.857 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.546 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
18:29:22.551 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
18:29:22.555 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
18:29:22.559 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
18:29:22.563 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:22.567 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
18:29:22.573 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 4A 05 01 08 BF
18:29:22.579 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 4A 05 01 08 BF
18:29:22.583 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
18:29:22.585 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18:29:22.587 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 40: Transaction Start type AddNodeToNetwork
18:29:22.589 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:22.591 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 40: [WAIT_REQUEST] requiresResponse=true callback: 8
18:29:22.594 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:22.596 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
18:29:22.599 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:22.601 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:29:22.603 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
18:29:22.605 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:29:22.608 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
18:29:22.610 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 5000ms
18:29:22.612 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:22.615 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 40: [WAIT_REQUEST] requiresResponse=true callback: 8
18:29:22.617 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:22.620 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.625 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 4985ms
18:29:22.632 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:22.635 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.639 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 4971ms
18:29:22.674 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 06 00 00 B5
18:29:22.678 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 00 00
18:29:22.681 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 00 00
18:29:22.684 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 00 00
18:29:22.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 40: [WAIT_REQUEST] requiresResponse=true callback: 8
18:29:22.688 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18:29:22.690 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 40: [WAIT_REQUEST] requiresResponse=true callback: 8
18:29:22.692 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 40: (Callback 8)
18:29:22.694 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - NO callback match! (8 <> 1)
18:29:22.696 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ****************** Transaction not correlated
18:29:22.699 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=1, payload=01 06 00 00
18:29:22.701 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Add Node: Done.
18:29:22.703 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
18:29:22.705 [DEBUG] [nal.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
18:29:22.707 [DEBUG] [col.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
18:29:22.709 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to priority controller queue
18:29:22.711 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
18:29:22.713 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:22.715 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:22.717 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.719 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 4891ms
18:29:22.722 [DEBUG] [nal.protocol.ZWaveInclusionController] - ZWave controller end exclusion
18:29:22.724 [DEBUG] [ave.internal.protocol.ZWaveController] - ZWaveController include done
18:29:22.726 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:22.728 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:22.730 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:22.731 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:22.734 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:27 ECT 2018 - 4877ms
18:29:27.610 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
18:29:27.615 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 40: Timeout at state WAIT_REQUEST. 3 retries remaining.
18:29:27.618 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 40: Transaction is current transaction, so clearing!!!!!
18:29:27.622 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 40: Transaction CANCELLED
18:29:27.627 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:29:27.631 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:40 CANCELLED
18:29:27.640 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:27.645 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
18:29:27.650 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 06 00 4A 05 00 09 BF
18:29:27.654 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 06 00 4A 05 00 09 BF
18:29:27.658 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
18:29:27.660 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18:29:27.661 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 41: Transaction Start type AddNodeToNetwork
18:29:27.663 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:27.664 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 41: [WAIT_REQUEST] requiresResponse=true callback: 9
18:29:27.667 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:27.668 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
18:29:27.670 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:27.676 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
18:29:27.679 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
18:29:27.680 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:29:27.682 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:27.686 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:27.687 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:29:27.693 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:27.699 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:32 ECT 2018 - 4994ms
18:29:27.704 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 41: [WAIT_REQUEST] requiresResponse=true callback: 9
18:29:27.709 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:27.715 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:32 ECT 2018 - 4979ms
18:29:27.720 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:27.722 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:27.725 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:32 ECT 2018 - 4968ms
18:29:28.505 [DEBUG] [erialmessage.IsFailedNodeMessageClass] - NODE 3: Requesting IsFailedNode status from controller.
18:29:28.508 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@72c789
18:29:28.511 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
18:29:28.514 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
18:29:28.516 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
18:29:28.519 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:28.522 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:28.525 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:32 ECT 2018 - 4168ms
18:29:32.693 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
18:29:32.698 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - NODE 255: TID 41: Timeout at state WAIT_REQUEST. 3 retries remaining.
18:29:32.703 [DEBUG] [nsactionManager$ZWaveTransactionTimer] - TID 41: Transaction is current transaction, so clearing!!!!!
18:29:32.708 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 41: Transaction CANCELLED
18:29:32.714 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:29:32.719 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:41 CANCELLED
18:29:32.725 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:32.737 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:29:32.743 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:29:32.749 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:29:32.754 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:29:32.760 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:29:32.765 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
18:29:32.772 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 03 9A
18:29:32.779 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 03 9A
18:29:32.785 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
18:29:32.787 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18:29:32.792 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:32.793 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:32.795 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:29:32.797 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
18:29:32.792 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: Transaction Start type IsFailedNodeID
18:29:32.799 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
18:29:32.801 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 42: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:29:32.802 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:32.805 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
18:29:32.804 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99
18:29:32.808 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:29:32.810 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.806 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:32.813 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.811 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:29:32.817 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:32.820 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:34 ECT 2018 - 1998ms
18:29:32.822 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 42: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:29:32.824 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:32.826 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:34 ECT 2018 - 1991ms
18:29:32.828 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
18:29:32.830 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:29:32.832 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:29:34 ECT 2018 - 1985ms
18:29:32.834 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.836 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 42: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:29:32.837 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18:29:32.839 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 42: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:29:32.841 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.843 [DEBUG] [erialmessage.IsFailedNodeMessageClass] - NODE 3: Is currently marked as failed by the controller!
18:29:32.845 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: Transaction COMPLETED
18:29:32.847 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: TransactionAdvance ST: DONE
18:29:32.849 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: TransactionAdvance WT: null {}
18:29:32.850 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: TransactionAdvance RX: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:29:32.852 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 42: TransactionAdvance TO: DONE
18:29:32.854 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 62ms
18:29:32.856 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 42: Transaction completed
18:29:32.857 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:42 DONE
18:29:32.860 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:29:32.861 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 42: Transaction event listener: DONE: DONE ->
18:29:32.863 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:29:32.864 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
18:29:32.865 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:29:32.877 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 42 --
18:29:32.878 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:29:32.879 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@d56a74
18:29:32.880 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:29:32.882 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE
18:29:32.883 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:29:32.885 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:29:32.887 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:29:32.889 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
18:29:32.890 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:30:02.885 [DEBUG] [erialmessage.IsFailedNodeMessageClass] - NODE 3: Requesting IsFailedNode status from controller.
18:30:02.888 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1136df3
18:30:02.892 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
18:30:02.895 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
18:30:02.899 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:30:02.904 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:30:02.909 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:30:02.914 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:30:02.919 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:30:02.924 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:30:02.929 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
18:30:02.935 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 03 9A
18:30:02.942 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 03 9A
18:30:02.948 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
18:30:02.947 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
18:30:02.954 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:30:02.955 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: Transaction Start type IsFailedNodeID
18:30:02.958 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:30:02.961 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 43: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:30:02.962 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
18:30:02.964 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
18:30:02.964 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99
18:30:02.968 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
18:30:02.966 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
18:30:02.970 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:02.970 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
18:30:02.973 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:02.972 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
18:30:02.976 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:30:04 ECT 2018 - 2000ms
18:30:02.978 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:02.980 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 43: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:30:02.980 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 43: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:30:02.984 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer
18:30:02.988 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Jan 30 18:30:04 ECT 2018 - 1987ms
18:30:02.990 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
18:30:02.992 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 43: [WAIT_RESPONSE] requiresResponse=true callback: 0
18:30:02.994 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:02.996 [DEBUG] [erialmessage.IsFailedNodeMessageClass] - NODE 3: Is currently marked as failed by the controller!
18:30:02.998 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: Transaction COMPLETED
18:30:03.000 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: TransactionAdvance ST: DONE
18:30:03.001 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: TransactionAdvance WT: null {}
18:30:03.003 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: TransactionAdvance RX: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01
18:30:03.005 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 43: TransactionAdvance TO: DONE
18:30:03.007 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 52ms
18:30:03.009 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: TID 43: Transaction completed
18:30:03.010 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:43 DONE
18:30:03.012 [DEBUG] [ave.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
18:30:03.015 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 43: Transaction event listener: DONE: DONE ->
18:30:03.017 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
18:30:03.019 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
18:30:03.019 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
18:30:03.021 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
18:30:03.027 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 43 --
18:30:03.028 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
18:30:03.030 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1f16e13
18:30:03.031 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
18:30:03.032 [DEBUG] [ialization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE
18:30:03.034 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
18:30:03.036 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
18:30:03.038 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
18:30:03.040 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - STOP transaction timer

It seams that when i use the inclousion mode or not. I have the same log.

There is no sign of a device being included into the network from the log, so you need to resolve this first. Check the device manual, make sure it is close to the computer running openhab (let’s say within 5m). Until the device is initiating an inclusion, there’s not much that the binding can do.

I just tested with a vera lite hub. It does not work either. It seems that the z.wave module of the lock is damage.
**I can confirm that my that the z.wave module of the lock is not working.
Thanks for your help.

Hey folks not sure if I should open a new post or not. I was able to get the latest Beta z-wave binding and included my lock with security. I thought all was well but noticed that although I can control my lock, I can’t get updates from the lock when it is manually switched. I have 4 of these and all are doing the same thing so I am pretty sure the locks are not the problem. I also had them working properly in Vera before moving over to openhab. There is nothing in the karaf logs even if I put them in debug when I manually open or close the locks. When I control it from OH, I do see the proper messages indicating ON to OFF and vice versa. I also see the Alarm raw log update. Is there anything I need to set for the lock to communicate back when manually locker or unlocked? When I lock or unlock from sitemap the response is within seconds so I don’t believe there to be a communication issue. My mesh looks pretty well established as seen below.

The one lock I am doing my constant testing with just because it is closer is node 37. There are another two z-wave light switches within 5 feet of it along with my thermostat so I doubt that it has anything to do with being able to reach the controller. I’m thinking its something I haven’t set up. Is there anything I can upload here that can help with the troubleshooting?