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

It’s not available if the node is initialising (maybe I should change that, but that’s the logic at the moment).

Today i apt-get dist-upgraded to the latest, and installed the latests org.openhab.binding.zwave-2.1.0-SNAPSHOT.jar, rebooted;
now my log is showing:

2017-04-19 20:13:21.409 [ERROR] [apache.karaf.shell.support.ShellUtil] - Exception caught while executing command
org.apache.karaf.shell.support.MultiException: Error executing command on bundles:
	Error starting bundle 9: Could not resolve module: org.openhab.binding.zwave [9]
  Unresolved requirement: Import-Package: gnu.io

	at org.apache.karaf.shell.support.MultiException.throwIf(MultiException.java:61)
	at org.apache.karaf.bundle.command.BundlesCommand.doExecute(BundlesCommand.java:69)[39:org.apache.karaf.bundle.core:4.0.8]
	at org.apache.karaf.bundle.command.BundlesCommand.execute(BundlesCommand.java:54)[39:org.apache.karaf.bundle.core:4.0.8]
	at org.apache.karaf.shell.impl.action.command.ActionCommand.execute(ActionCommand.java:83)[56:org.apache.karaf.shell.core:4.0.8]
	at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:67)[56:org.apache.karaf.shell.core:4.0.8]
	at org.apache.karaf.shell.impl.console.osgi.secured.SecuredCommand.execute(SecuredCommand.java:87)[56:org.apache.karaf.shell.core:4.0.8]
	at org.apache.felix.gogo.runtime.Closure.executeCmd(Closure.java:480)[56:org.apache.karaf.shell.core:4.0.8]
	at org.apache.felix.gogo.runtime.Closure.executeStatement(Closure.java:406)[56:org.apache.karaf.shell.core:4.0.8]
	at org.apache.felix.gogo.runtime.Pipe.run(Pipe.java:108)[56:org.apache.karaf.shell.core:4.0.8]
	at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:182)[56:org.apache.karaf.shell.core:4.0.8]
	at org.apache.felix.gogo.runtime.Closure.execute(Closure.java:119)[56:org.apache.karaf.shell.core:4.0.8]
	at org.apache.felix.gogo.runtime.CommandSessionImpl.execute(CommandSessionImpl.java:94)[56:org.apache.karaf.shell.core:4.0.8]
	at org.apache.karaf.shell.impl.console.ConsoleSessionImpl.run(ConsoleSessionImpl.java:274)[56:org.apache.karaf.shell.core:4.0.8]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
Caused by: java.lang.Exception: Error starting bundle 9: Could not resolve module: org.openhab.binding.zwave [9]
  Unresolved requirement: Import-Package: gnu.io

	at org.apache.karaf.bundle.command.BundlesCommand.doExecute(BundlesCommand.java:66)[39:org.apache.karaf.bundle.core:4.0.8]
	... 12 more
Caused by: org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zwave [9]
  Unresolved requirement: Import-Package: gnu.io

	at org.eclipse.osgi.container.Module.start(Module.java:434)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:392)[org.eclipse.osgi-3.10.101.v20150820-1432.jar:]
	at org.apache.karaf.bundle.command.Start.executeOnBundle(Start.java:38)[39:org.apache.karaf.bundle.core:4.0.8]
	at org.apache.karaf.bundle.command.BundlesCommand.doExecute(BundlesCommand.java:64)[39:org.apache.karaf.bundle.core:4.0.8]
	... 12 more

what can i do?

thanks br,
Raymond

Add the Serial binding through PaperUI.

Thanks how?

THANKS! that did the trick

Hi Chris. Not sure what else to provide feedback-wise, but I upgraded my stuff to build 887 and wedged in your 16 April test build. I was successfully able to include a Linear GD00Z-4 in Security mode and interact with the device–which did not work with earlier Z-Wave builds. This was in the logs, which I presume is a Good Thing:

openhab.log:2017-04-18 18:16:15.740 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - NODE 32: Using Scheme0 Network Key for Key Exchange since we are in inclusion mode.
openhab.log:2017-04-18 18:16:16.249 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 32: SECURITY_INC State=COMPLETE

I still need to shim in the latest DB updates for that particular device, but base capability is working.

Thanks for all the great work!

1 Like

You got this working? I have been unsuccessful on the same build so far. In fact I recently updated a ticket with @chris as it seems like security is broken in general in my deployment right now.

What are your controller settings (inclusion mode, security setting, etc)? What controller are you using? How close/far away was your device when you included it?

I’ve got my GD00Z working. I have left everything pretty much default. Network wide inclusion, controller was in the other room. Using the Homeseer controller. The one thing you may want to try is doing a factory reset on the GD00Z before you try including it again. Not sure if that would matter or not, but it might help.

I’ve tried - 5 button presses, wait for short then long beep. Same problems. It may be security in general for me that’s broken. Knowing someone got it working helps me a lot - at least I know my efforts aren’t in vain.

I know there’s a few people using this device, so I don’t think it’s the definition that’s broken.

I’ve added the following to my BE469 locks .xml file within the jar:

<channel id="alarm_number" typeId="alarm_number">
    <label>Alarm (number)</label>
    <properties>
      <property name="binding:*:OnOffType">COMMAND_CLASS_ALARM</property>
    </properties>
</channel>

Which allowed me to have the alarm_number channel. All is working good, it’s reporting the following:
1 = Manual UnLock
2 = Manual lock
5 = Keycode UnLock
6 = Keycode lock
11 = Lock Jam

Although when i unlock the door via openhab (remotely) i don’t get an alarm_number for either the remote lock / unlock.
Should this be reported as an alarm number?

Theres a snip of my DEBUG logs located here for both a remote UNLOCK and LOCK. I tried to post it here but i exceeded the character limit.

https://pastebin.com/BVcx2QgG

@chris,
I am using your latest development binding and the latest snapshot of OH2.
From time to time i see exceptions in my log:

2017-04-21 09:30:35.776 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:30:35.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:30:35.777 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:30:35.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:30:35.778 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:30:35.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:30:35.779 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:30:35.780 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:30:35.781 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:30:35.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:30:35.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-04-21 09:30:35.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-04-21 09:36:39.625 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 1E 02 84 07 6C 
2017-04-21 09:36:39.635 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-21 09:36:39.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=30, callback=0, payload=00 1E 02 84 07 
2017-04-21 09:36:39.663 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=30, callback=0, payload=00 1E 02 84 07 
2017-04-21 09:36:39.671 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=30, callback=0, payload=00 1E 02 84 07 
2017-04-21 09:36:39.675 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-04-21 09:36:39.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Application Command Request (ALIVE:REQUEST_NIF)
2017-04-21 09:36:39.685 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: Incoming command class COMMAND_CLASS_WAKE_UP, endpoint 0
2017-04-21 09:36:39.686 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2017-04-21 09:36:39.687 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 30: Received COMMAND_CLASS_WAKE_UP V0 WAKE_UP_NOTIFICATION
2017-04-21 09:36:39.688 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: Is awake with 0 messages in the queue
2017-04-21 09:36:39.688 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: Creating WakeupTimerTask
2017-04-21 09:36:39.689 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: Creating WakeupTimerTask
2017-04-21 09:36:39.689 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
2017-04-21 09:36:39.690 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2017-04-21 09:36:39.692 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 30: Node Status event - Node is AWAKE
2017-04-21 09:36:39.692 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Commands processed 1.
2017-04-21 09:36:39.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@563108.
2017-04-21 09:36:39.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-04-21 09:36:39.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-04-21 09:36:39.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-21 09:36:39.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-04-21 09:36:39.696 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:36:39.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:36:39.697 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:36:39.697 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:36:39.698 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:36:39.698 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:36:39.699 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:36:39.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:36:39.700 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:36:39.700 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:36:39.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-04-21 09:36:39.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-04-21 09:36:49.698 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: listening == false, frequentlyListening == false, awake == true
2017-04-21 09:36:49.705 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: WakeupTimerTask 0 Messages waiting, state REQUEST_NIF
2017-04-21 09:36:49.710 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: WakeupTimerTask First iteration
2017-04-21 09:36:59.698 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: listening == false, frequentlyListening == false, awake == true
2017-04-21 09:36:59.705 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: WakeupTimerTask 0 Messages waiting, state REQUEST_NIF
2017-04-21 09:36:59.712 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: No more messages, go back to sleep
2017-04-21 09:36:59.731 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 30: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION
2017-04-21 09:36:59.733 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
2017-04-21 09:36:59.736 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: Encapsulating message, endpoint 0
2017-04-21 09:36:59.737 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2017-04-21 09:36:59.740 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: Command Class COMMAND_CLASS_WAKE_UP is NOT required to be secured
2017-04-21 09:36:59.741 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@146798
2017-04-21 09:36:59.745 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
2017-04-21 09:36:59.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Added to queue - size 0
2017-04-21 09:36:59.754 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-04-21 09:36:59.758 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: listening == false, frequentlyListening == false, awake == true
2017-04-21 09:36:59.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
2017-04-21 09:36:59.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-04-21 09:36:59.763 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 1E 02 84 08 25 15 45 
2017-04-21 09:36:59.764 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 30: Sending REQUEST Message = 01 09 00 13 1E 02 84 08 25 15 45 
2017-04-21 09:36:59.765 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-04-21 09:36:59.765 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: Transaction Start type SendData 
2017-04-21 09:36:59.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2922: [WAIT_RESPONSE] requiresResponse=true callback: 21
2017-04-21 09:36:59.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-04-21 09:36:59.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
2017-04-21 09:36:59.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-04-21 09:36:59.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Apr 21 09:37:01 CEST 2017 - 2000ms
2017-04-21 09:36:59.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 2922: [WAIT_RESPONSE] requiresResponse=true callback: 21
2017-04-21 09:36:59.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-21 09:36:59.770 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Apr 21 09:37:01 CEST 2017 - 1998ms
2017-04-21 09:36:59.771 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-04-21 09:36:59.773 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-21 09:36:59.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-21 09:36:59.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-21 09:36:59.777 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2922: [WAIT_RESPONSE] requiresResponse=true callback: 21
2017-04-21 09:36:59.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-04-21 09:36:59.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-21 09:36:59.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-21 09:36:59.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-21 09:36:59.780 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-21 09:36:59.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Apr 21 09:37:01 CEST 2017 - 1987ms
2017-04-21 09:36:59.787 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-04-21 09:36:59.791 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-21 09:36:59.793 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2017-04-21 09:36:59.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2017-04-21 09:36:59.796 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2017-04-21 09:36:59.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2922: [WAIT_RESPONSE] requiresResponse=true callback: 21
2017-04-21 09:36:59.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-04-21 09:36:59.799 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2922: [WAIT_RESPONSE] requiresResponse=true callback: 21
2017-04-21 09:36:59.801 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2017-04-21 09:36:59.802 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 30: Sent Data successfully placed on stack.
2017-04-21 09:36:59.803 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: TransactionAdvance ST: WAIT_RESPONSE
2017-04-21 09:36:59.804 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: TransactionAdvance WT: null {}
2017-04-21 09:36:59.806 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: TransactionAdvance RX: Message: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2017-04-21 09:36:59.807 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: TransactionAdvance TO: WAIT_REQUEST
2017-04-21 09:36:59.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2922: Advanced to WAIT_REQUEST
2017-04-21 09:36:59.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: TID 2922: Transaction not completed
2017-04-21 09:36:59.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-21 09:36:59.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-21 09:36:59.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-21 09:36:59.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-21 09:36:59.815 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Apr 21 09:37:04 CEST 2017 - 4994ms
2017-04-21 09:37:04.810 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
2017-04-21 09:37:04.811 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 30: TID 2922: Timeout at state WAIT_REQUEST. 3 retries remaining.
2017-04-21 09:37:04.812 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2017-04-21 09:37:04.814 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: Transaction ABORTED
2017-04-21 09:37:04.816 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2017-04-21 09:37:04.817 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2017-04-21 09:37:04.818 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-04-21 09:37:04.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-21 09:37:04.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-21 09:37:04.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-21 09:37:04.824 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Apr 21 09:37:16 CEST 2017 - 11992ms
2017-04-21 09:37:04.825 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-04-21 09:37:04.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-21 09:37:04.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-21 09:37:04.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-04-21 09:37:04.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2922: [ABORTED] requiresResponse=true callback: 21
2017-04-21 09:37:04.838 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2017-04-21 09:37:04.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-21 09:37:04.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-21 09:37:04.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-21 09:37:04.843 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 13 15 01 FD 
2017-04-21 09:37:04.843 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-21 09:37:04.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Apr 21 09:37:16 CEST 2017 - 11971ms
2017-04-21 09:37:04.846 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-21 09:37:04.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Request[0x00], dest=1, callback=21, payload=15 01 
2017-04-21 09:37:04.850 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Request[0x00], dest=1, callback=21, payload=15 01 
2017-04-21 09:37:04.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=21, payload=15 01 
2017-04-21 09:37:04.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2922: [ABORTED] requiresResponse=true callback: 21
2017-04-21 09:37:04.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2017-04-21 09:37:04.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2922: [ABORTED] requiresResponse=true callback: 21
2017-04-21 09:37:04.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 2922: (Callback 21)
2017-04-21 09:37:04.857 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2017-04-21 09:37:04.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 2922: callback 21
2017-04-21 09:37:04.860 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=21, payload=15 01 
2017-04-21 09:37:04.861 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 30: SendData Request. CallBack ID = 21, Status = Transmission complete, no ACK received(1)
2017-04-21 09:37:04.862 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 30: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK.
2017-04-21 09:37:04.863 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: TransactionAdvance ST: ABORTED
2017-04-21 09:37:04.864 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: TransactionAdvance WT: null {}
2017-04-21 09:37:04.866 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: TransactionAdvance RX: Message: class=SendData[0x13], type=Request[0x00], dest=1, callback=21, payload=15 01 
2017-04-21 09:37:04.867 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: TransactionAdvance TO: ABORTED
2017-04-21 09:37:04.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: TID 2922: Transaction not completed
2017-04-21 09:37:04.869 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-21 09:37:04.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-04-21 09:37:04.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-04-21 09:37:04.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-21 09:37:04.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Apr 21 09:37:16 CEST 2017 - 11942ms
2017-04-21 09:37:16.827 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
2017-04-21 09:37:16.832 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 30: TID 2922: Timeout at state ABORTED. 3 retries remaining.
2017-04-21 09:37:16.836 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 2922: Transaction is current transaction, so clearing!!!!!
2017-04-21 09:37:16.840 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2922: Transaction CANCELLED
2017-04-21 09:37:16.844 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-04-21 09:37:16.850 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-04-21 09:37:16.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: notifyTransactionResponse TID:2922 CANCELLED
2017-04-21 09:37:16.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-04-21 09:37:16.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2922: Transaction event listener: DONE: CANCELLED -> 
2017-04-21 09:37:16.860 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:37:16.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:37:16.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: -- To notify -- COMPLETE
2017-04-21 09:37:16.865 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:37:16.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:37:16.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 2922 -- 
2017-04-21 09:37:16.869 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:37:16.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:37:16.873 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 30: Went to sleep COMPLETE
2017-04-21 09:37:16.874 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:37:16.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:37:16.877 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:37:16.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:37:16.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-04-21 09:37:16.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-04-21 09:37:16.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-04-21 09:40:16.754 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling...
2017-04-21 09:40:16.765 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Polling aborted due to exception
java.lang.NullPointerException
	at org.openhab.binding.zwave.handler.ZWaveThingHandler$1.run(ZWaveThingHandler.java:374)[9:org.openhab.binding.zwave:2.1.0.201704171736]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)[:1.8.0_121]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)[:1.8.0_121]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)[:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_121]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_121]
	at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-04-21 09:47:10.851 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 1C 02 84 07 6E 
2017-04-21 09:47:10.856 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-04-21 09:47:10.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=28, callback=0, payload=00 1C 02 84 07 
2017-04-21 09:47:10.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=28, callback=0, payload=00 1C 02 84 07 
2017-04-21 09:47:10.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=28, callback=0, payload=00 1C 02 84 07 
2017-04-21 09:47:10.869 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2017-04-21 09:47:10.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: Application Command Request (ALIVE:DONE)
2017-04-21 09:47:10.873 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 28: resetResendCount initComplete=true isDead=false
2017-04-21 09:47:10.876 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 28: Incoming command class COMMAND_CLASS_WAKE_UP, endpoint 0
2017-04-21 09:47:10.879 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 28: SECURITY not supported
2017-04-21 09:47:10.881 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 28: Received COMMAND_CLASS_WAKE_UP V2 WAKE_UP_NOTIFICATION
2017-04-21 09:47:10.883 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 28: Node is listening - ignore wakeup
2017-04-21 09:47:10.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: Commands processed 1.
2017-04-21 09:47:10.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1512d54.
2017-04-21 09:47:10.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-04-21 09:47:10.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2017-04-21 09:47:10.896 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2017-04-21 09:47:10.898 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-04-21 09:47:10.900 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:47:10.901 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:47:10.903 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:47:10.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:47:10.911 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:47:10.915 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:47:10.920 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:47:10.926 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:47:10.926 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: listening == false, frequentlyListening == false, awake == false
2017-04-21 09:47:10.927 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 29: Node not awake!
2017-04-21 09:47:10.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-04-21 09:47:10.928 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-04-21 09:47:21.373 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Polling...
2017-04-21 09:47:25.009 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 29: Polling...
2017-04-21 09:47:25.016 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 29: Polling zwave:device:126c07f3:node29:alarm_motion
2017-04-21 09:47:25.022 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 29: Generating poll message for COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2017-04-21 09:47:25.028 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 29: Creating new message for command SENSOR_MULTI_LEVEL_GET
2017-04-21 09:47:25.034 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SENSOR_MULTILEVEL
2017-04-21 09:47:25.040 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: Encapsulating message, endpoint 0
2017-04-21 09:47:25.042 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: SECURITY not supported
2017-04-21 09:47:25.044 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 29: Command Class COMMAND_CLASS_SENSOR_MULTILEVEL is NOT required to be secured

And there is a node 0 ?
Could you please chime a light on this :slight_smile: ?
Thanks
br,
Raymond

Hmm…
I am not able to get all values from my FIBARO Smoke Detector. Temperatur is reported but all Binary Alarms are in state ON all the time. But be shure my livingroom is not on fire :slight_smile:

If i wake up the device (push the button) i get this…

What im worried about…

19:53:03.869 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 32: Transaction not completed: node address inconsistent.  lastSent=32, incoming=255

I am running stable 2.0. Any chance for me to update just zwave database?

So, I found out that one of my problems is that OH2 was running two Z-Wave bindings. I thought I had removed the original, but I hadn’t. I am finally, for sure, running the latest binding (Apr 16) from the top of this thread.

I was able to securely include my NGD00Z-4 controller. I am presented with only one channel named Barrier Position. I have been unable to use this channel to control the door, but it does sense state (I get CLOSED when the door is closed, and UNDEF when the door is open?). Any thoughts on this?

Still working on re-including my Kwikset 914TRL. It fails secure inclusion every time, even in Low Power inclusion mode.

@nolan_garrett - as long as you’ve got it securely included, then you should be set to be able to control it. It’s a bit counter intuitive from what you would expect for the Open/Close states. If you breeze through this thread somewhere, I asked about this as well, and someone asked in another thread. @whwkins was able to help guide me to understand. The barrier position correctly controls the door. But it’s funky in that it doesn’t have a simple open/close or on/off state. It has a number value state. The important numbers are 0 for closed, 255 for open. If you want to “test” it’s functioning status - fire up the API interface and just send a 0 or 255 to the barrier position item. This should trigger the opening/closing functionality.

Beware there is a limitation to how frequently you can actually fire the open/close commands. It’s a safety feature, and of course there is that wonderful beeping that happens first to warn you it’s about to do something. As long as it’s secure included, you should be in good shape. Just a good idea to validate this by checking the Attributes section and validating you have the green checkmark.

This works! Changed my Switch to a Number, set a mapping… thank you! It’s easy to miss items in this thread, it has become far too long!

Just gotta get this stupid Kwikset lock to re-include securely and I’m golden.

Since you’re not using the development version that is discussed in this thread, can I ask you start a separate thread.

Is there anyway to confirm if the Aeotec ZW089 Recessed Door Sensor is in the development version?

It’s been showing (for a while I think) as not fully discovered by the binding, although the device shows as Online.

I am going to try and wake it up a few times, but I know have opened and closed the door a few times as well and see it lighting up.

Sure - just view the list of things in the binding page.

What does “not fully discovered” mean?

That is what Habmin was showing for the device although it did shows online in Habmin.

But I pulled the device out the door jam and manually reset it. It looks like it being found now in OH2, although both Habmin and PaperUI show “Node initialising: REQUEST_NIF”, and PaperUI seems to toss a 404 not found when trying enable a channel. I’ll leave it for a bit and see what it finishes.

So pretty sure its an issue with the device itself and nothing to do with either OH2 or the binding. This recessed door sensor seems to consistently difficult to work with.