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

01av · February 6, 2017, 8:18pm

Thanks for putting your time into all of this Chris!

I’m still getting “unkown device” for the idl101. At first I thought this was because of firmware attribute said version 0.0 (and not 1.0), but this resolved after deletion of xml and rediscovery.

Seeing in the log it is still saying " Device discovery could not resolve to a thingType! 0230:0003:0001::1.0".
I can see that the idlock_idl101_01_000 xml is searched during discovery…so it should be working?? Or am I missing something?

chris · February 6, 2017, 8:20pm

Try deleting the thing (not excluding it) and then click on discover so that it’s added to the inbox and add it again. There seems to be something wrong with the updating of the inbox so this might work.

01av · February 6, 2017, 8:22pm

I’ve been deleting thing, and clicking discover multiple times, no luck. All the attributes show up fine in habmin, but it still shows unknown - and without channels.

shadowmite · February 6, 2017, 8:29pm

01av, when I just had that issue I rebooted and everything came up.

01av · February 6, 2017, 9:10pm

Just tried reboot, delete and discover, no results.
Chris - does the the binding check other things than manufacturer id, manufacturer ref and firmware when searching for the device? I notice the filename of the device defenition is :idlock_idl101_01_000 - but the registered name of the manufacturer is alphonsus tech (and not idlock), does this matter in any way?

chris · February 6, 2017, 9:12pm

No - just the manufacturer ID, device id, device type and version.

Not at all - the name is just a display value. The names used are the official ones from ZWave, but the device only provides the manufacturer ID - not the name.

01av · February 6, 2017, 11:07pm

I’m actually having the same issue with many of my fibaro relays as well, they show up as unknown devices although their id, type and version seem known … I’ve tried restarts of the docker container, and multiple deletes and rediscovers… I’ll let things run the night through and see what happens…

Mike_Bagdanoff · February 6, 2017, 11:12pm

I’ve got an AEOTEC Multisensor Gen6 that worked with the 2.0 and the 1.9 binding but doesn’t seem to be discoverable with this one. No XML is generated. It is USB powered so should always be awake

When I delete the thing and re-add it I get:

15:07:16.284 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Unable to find thing type (0086:0102:0064:1.6)
15:07:16.285 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Controller status changed to ONLINE.
15:07:16.285 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Controller is ONLINE. Starting device initialisation.
15:07:16.291 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bae255ae:node35' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE
15:07:16.301 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Updating node properties.
15:07:16.303 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Updating node properties. MAN=134
15:07:16.305 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 35: Updating node properties. MAN=134. SET. Was 134
15:07:16.321 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:bae255ae:node35' changed from ONLINE to UNINITIALIZED (HANDLER_INITIALIZING_ERROR)
15:07:16.308 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while initializing handler of thing 'zwave:device:bae255ae:node35': java.lang.NullPointerException
java.util.concurrent.ExecutionException: java.lang.NullPointerException
        at java.util.concurrent.FutureTask.report(FutureTask.java:122)[:1.8.0_121]
        at java.util.concurrent.FutureTask.get(FutureTask.java:206)[:1.8.0_121]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.callAsynchronous(SafeMethodCaller.java:188)[99:org.eclipse.smarthome.core:0.9.0.201701192225]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:81)[99:org.eclipse.smarthome.core:0.9.0.201701192225]
        at org.eclipse.smarthome.core.common.SafeMethodCaller.call(SafeMethodCaller.java:65)[99:org.eclipse.smarthome.core:0.9.0.201701192225]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$9.run(ThingManager.java:710)[106:org.eclipse.smarthome.core.thing:0.9.0.201701192225]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_121]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[: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]
Caused by: java.lang.NullPointerException
        at org.openhab.binding.zwave.handler.ZWaveThingHandler.updateNodeProperties(ZWaveThingHandler.java:1389)[229:org.openhab.binding.zwave:2.1.0.201702061819]
        at org.openhab.binding.zwave.handler.ZWaveThingHandler.bridgeStatusChanged(ZWaveThingHandler.java:483)[229:org.openhab.binding.zwave:2.1.0.201702061819]
        at org.openhab.binding.zwave.handler.ZWaveThingHandler.initialize(ZWaveThingHandler.java:151)[229:org.openhab.binding.zwave:2.1.0.201702061819]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$9$1.call(ThingManager.java:713)[106:org.eclipse.smarthome.core.thing:0.9.0.201701192225]
        at org.eclipse.smarthome.core.thing.internal.ThingManager$9$1.call(ThingManager.java:1)[106:org.eclipse.smarthome.core.thing:0.9.0.201701192225]
        at org.eclipse.smarthome.core.common.SafeMethodCaller$CallableWrapper.call(SafeMethodCaller.java:179)[99:org.eclipse.smarthome.core:0.9.0.201701192225]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
        ... 3 more

Also, I’m noticing significant lag in the system as it continues running, Here is the log generated by turning a light off from Habmin:

17:48:37.942 [INFO ] [smarthome.event.ItemCommandEvent    ] - Item 'SwitchLivingRoom_Switch' received command OFF
17:48:37.950 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:bae255ae:node5:switch_binary --> OFF
17:48:37.952 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Creating new message for application command SWITCH_BINARY_SET
17:48:37.953 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
17:48:37.954 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Encapsulating message, endpoint 0
17:48:37.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY not supported
17:48:37.957 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
17:48:37.958 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 5: Creating new message for application command SWITCH_BINARY_GET
17:48:37.959 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SWITCH_BINARY
17:48:37.960 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Encapsulating message, endpoint 0
17:48:37.961 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY not supported
17:48:37.962 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
17:48:37.963 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
17:48:37.965 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.966 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Added to queue - size 0
17:48:37.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:48:37.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:48:37.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:48:37.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Feb 06 17:48:48 PST 2017 - 10851ms
17:48:37.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
17:48:37.973 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.974 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.975 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.976 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.977 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.977 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.978 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.979 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.981 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.982 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.983 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.984 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.985 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.986 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.987 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.988 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.989 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.991 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.992 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.993 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.994 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.995 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.997 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.998 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:37.999 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:38.001 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:38.002 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:38.003 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:38.004 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:38.006 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
17:48:38.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Added to queue - size 0
17:48:38.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:48:38.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:48:38.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:48:38.013 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Feb 06 17:48:48 PST 2017 - 10809ms
17:48:38.027 [INFO ] [marthome.event.ItemStateChangedEvent] - SwitchLivingRoom_Switch changed from ON to OFF
17:48:47.589 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 14 03 20 01 00 C4
17:48:47.595 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:48:47.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=20, callback=0, payload=00 14 03 20 01 00
17:48:47.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=20, callback=0, payload=00 14 03 20 01 00
17:48:47.615 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 14 0A 71 05 07 00 00 FF 07 02 00 00 7C
17:48:47.621 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:48:47.626 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=20, callback=0, payload=00 14 0A 71 05 07 00 00 FF 07 02 00 00
17:48:47.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=20, callback=0, payload=00 14 0A 71 05 07 00 00 FF 07 02 00 00
17:48:48.821 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
17:48:48.822 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 26: XXXXXXX Timeout at state ABORTED. 3 retries remaining.
17:48:48.823 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Transaction is current transaction, so clearing!!!!!
17:48:48.824 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 617 CANCELLED
17:48:48.825 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
17:48:48.827 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
17:48:48.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 26: notifyTransactionResponse 617
17:48:48.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
17:48:48.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 84 -- 617
17:48:48.831 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: listening == false, frequentlyListening == false, awake == false
17:48:48.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Node not awake!
17:48:48.833 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
17:48:48.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 94 -- 617
17:48:48.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
17:48:48.836 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 50: listening == false, frequentlyListening == false, awake == false
17:48:48.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 50: Node not awake!
17:48:48.838 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 49: listening == false, frequentlyListening == false, awake == false
17:48:48.839 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 99 -- 617
17:48:48.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 49: Node not awake!
17:48:48.841 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 64: listening == false, frequentlyListening == false, awake == false
17:48:48.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 64: Node not awake!
17:48:48.843 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: listening == true, frequentlyListening == false, awake == false
17:48:48.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 105 -- 617
17:48:48.844 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction payload is the same [[37, 1, 0]] == [[37, 1, 0]]
17:48:48.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
17:48:48.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
17:48:48.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 174 -- 617
17:48:48.849 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 25 01 00 25 4C AD
17:48:48.851 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 25 01 00 25 4C AD
17:48:48.853 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
17:48:48.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 185 -- 617
17:48:48.859 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
17:48:48.854 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type SendData
17:48:48.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:641 [WAIT_RESPONSE] callback: 76
17:48:48.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
17:48:48.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
17:48:48.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 253 -- 617
17:48:48.864 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:48:48.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
17:48:48.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:48:48.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:48:48.871 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Feb 06 17:48:50 PST 2017 - 1999ms
17:48:48.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:641 [WAIT_RESPONSE] callback: 76
17:48:48.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:48:48.875 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Feb 06 17:48:50 PST 2017 - 1995ms
17:48:48.878 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
17:48:48.882 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:48:48.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 302 -- 617
17:48:48.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
17:48:48.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01
17:48:48.887 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 353 -- 617
17:48:48.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 354 -- 617
17:48:48.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 362 -- 617
17:48:48.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 378 -- 617
17:48:48.894 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 4C 00 00 03 A4
17:48:48.896 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 380 -- 617
17:48:48.897 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:48:48.899 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=76, payload=4C 00 00 03
17:48:48.899 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 387 -- 617
17:48:48.901 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=76, payload=4C 00 00 03
17:48:48.902 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 388 -- 617
17:48:48.904 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 389 -- 617
17:48:48.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 401 -- 617
17:48:48.909 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 409 -- 617
17:48:48.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 413 -- 617
17:48:48.913 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 414 -- 617
17:48:48.915 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 418 -- 617
17:48:48.917 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 421 -- 617
17:48:48.919 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 422 -- 617
17:48:48.922 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 501 -- 617
17:48:49.046 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 32 02 84 07 40
17:48:49.049 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
17:48:49.051 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=50, callback=0, payload=00 32 02 84 07
17:48:49.053 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=ApplicationCommandHandler[0x04], type=Request[0x00], dest=50, callback=0, payload=00 32 02 84 07
17:48:50.871 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
17:48:50.872 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 5: XXXXXXX Timeout at state WAIT_RESPONSE. 3 retries remaining.
17:48:50.873 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
17:48:50.874 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 641 ABORTED
17:48:50.876 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA
17:48:50.877 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA
17:48:50.879 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
17:48:50.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
17:48:50.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
17:48:50.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
17:48:50.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Mon Feb 06 17:49:02 PST 2017 - 11992ms
17:48:50.886 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
17:48:50.891 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
17:48:50.895 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=

markus7017 · February 7, 2017, 10:39am

Hi Chris, good to hear that you are focusing on refactoring and stabilisation. I have the same expectation on the retry behaviour of the binding. When looking to the logs I suppose it creates more problems that it fixes.
Please go ahead and open a branch / supply the .jar.

What does that mean to existing installations? Do we need to update all thing configurations? even when using the Paper UI?

Are you also working on removal all dead battery driven devices. During lifetime and testing some devices I have several dead ones (no longer existing), which are still popup on the controller and I can’t remove them, because they are never in dead mode (which is a pre-requisite to let the binding remove them from the controller, correct? Instead the binding reports them as “not found”).

chris · February 7, 2017, 4:24pm

Maybe they aren’t in the database. Please can you say exactly what these devices are as I don’t see anything with this device type in the database already.[quote=“markus7017, post:160, topic:21653”]
Please go ahead and open a branch / supply the .jar.
[/quote]

Already done - that’s what this thread is all about :).

I would suggest to read the top of this thread, but the short answer is yes - you need to delete your things and add them back in.

01av · February 7, 2017, 5:24pm

The fgs221 from Fibaro show up as unknown. (the fgs211 however show up fine). Previously they have been detected properly!
They are listed here, and all the attributes seem to match: http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/121

chris · February 7, 2017, 5:34pm

I don’t think that’s correct -:

This one should be ok though -:

http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/123

01av · February 7, 2017, 5:35pm

Sorry
http://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/123

shadowmite · February 7, 2017, 6:12pm

There is definitely some bug with this binding (running the 2-5 now); I just tried to add a pretty common device (GE binary switch) and it goes into the same unknown device state. I have 11 others of these working that were previously added.

Stopped and restarted the openhab2 service and still unknown device. Deleted and rediscovered device and then it worked fine.

chris · February 7, 2017, 6:17pm

Yes - this seems to be the workaround. It looks like the second stage of discovery where the inbox gets updated with the ‘full’ information isn’t working correctly. I’ll look at it when I get some time - not right now though I’m afraid…

01av · February 7, 2017, 6:53pm

I can’t get this workaround working though -

chris · February 7, 2017, 6:55pm

I don’t know why - if you can provide a log I’ll try and take a look. It may be something completely different…

shawnmix · February 8, 2017, 3:27am

Ok finally got around to loading this up and taking it for a spin - needed to freshen up my zwave inclusion so far anyhow after the last lock mishap, so this is a fresh setup. Unfortunately some negative happenings to report here:

When I was adding the items from the thing screen in HABmin, I noticed there was a weird ghost item appearing for many of them as I added. A simple refresh fixed this. Not sure if this is a HABmin thing or a ZWave thing. (not in the sense of openhanded Things).
I can’t seem to get my lock to even talk to the ZStick it seems. I know it’s functionally connecting to ZWave devices, but unfortunately I can’t seem to make the lock work with it. I hate “attempts” at pairing since I have to dislodge the lock from the front door everytime. So hopefully someone can give me some educated pointers on how to identify my bottleneck?

I took the time to learn my way around getting to the Karaf Console for my Docker container, and then changed logs over to Debug level. I was able to validate that the logs were now kicking out DEBUG level messages. There is a lot of chatter at regular intervals, but I can’t make heads/tails of anything specific that looks like communication with this device. Any particular lines I should be looking for?
Happy to try and supply the logs if it would help to let someone else more trained view it.

I’m ending up with a few of the Unknown Device errors as well. The devices were successfully included with the regular binding without issue. For some reason this time, I’m getting stuck.

First attempt, I was given 2 devices (identical devices), and 1 had the Initialise option under Advanced Options, while the second didn’t. They also did not show any of the data I believe for the attributes section other than Node and Neighbors.
Second attempt (I removed the devices, and re-enrolled them), I was left with the same Unknown Devices, yet I can see this time in the Attributes I’m getting the name, model, detailed info, etc, just not the channels and successful addition.

Screen Shot 2017-02-07 at 10.21.03 PM.png758×376 42.2 KB

daemonalec · February 8, 2017, 4:01am

First, a question; am I really running your binding? Listing the installed bundles shows

209 | Active   |  80 | 2.1.0.201702061819    | ZWave Binding

Second, I’ve noticed delays in reacting to commands; it seems that the first command to a device will work immediately, but a subsequent one won’t. Here’s a chunk of logs between when I sent the command (to NODE 51) and when the node actually reacted:

2017-02-07 21:58:19.426 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 51: Command received zwave:device:69d7d64d:node51:switch_dimmer --> ON
2017-02-07 21:58:19.426 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 51: Creating new message for command SWITCH_MULTILEVEL_SET
2017-02-07 21:58:19.427 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
2017-02-07 21:58:19.427 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: Encapsulating message, endpoint 0
2017-02-07 21:58:19.427 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: SECURITY not supported
2017-02-07 21:58:19.427 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2017-02-07 21:58:19.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Adding to device queue
2017-02-07 21:58:19.427 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
2017-02-07 21:58:19.427 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction node Id is different
2017-02-07 21:58:19.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 51: Added to queue - size 27
2017-02-07 21:58:19.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-02-07 21:58:19.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-02-07 21:58:19.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-02-07 21:58:19.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Feb 07 21:58:35 CST 2017 - 15579ms
2017-02-07 21:58:26.060 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 25: Requesting IsFailedNode status from controller.
2017-02-07 21:58:26.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@6e575513
2017-02-07 21:58:26.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-02-07 21:58:26.061 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction payload is NOT the same
2017-02-07 21:58:26.061 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 28
2017-02-07 21:58:26.061 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-02-07 21:58:26.061 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-02-07 21:58:26.061 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-02-07 21:58:26.061 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Feb 07 21:58:35 CST 2017 - 8946ms
2017-02-07 21:58:35.007 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
2017-02-07 21:58:35.008 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 65: XXXXXXX Timeout at state WAIT_DATA. 3 retries remaining.
2017-02-07 21:58:35.008 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Transaction is current transaction, so clearing!!!!!
2017-02-07 21:58:35.008 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 265 CANCELLED
2017-02-07 21:58:35.008 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-02-07 21:58:35.008 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 65: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-02-07 21:58:35.008 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: notifyTransactionResponse 265
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 9 -- 265
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 10 -- 265
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 11 -- 265
2017-02-07 21:58:35.009 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 51: listening == true, frequentlyListening == false, awake == false
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 12 -- 265
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 13 -- 265
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 14 -- 265
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 15 -- 265
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 16 -- 265
2017-02-07 21:58:35.009 [DEBUG] [e.internal.protocol.ZWaveTransaction] - >>>>> transaction payload is the same [[38, 1, -1]] == [[38, 1, -1]]
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 17 -- 265
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 18 -- 265
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-02-07 21:58:35.009 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 19 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 20 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 21 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 22 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 23 -- 265
2017-02-07 21:58:35.010 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 33 03 26 01 FF 25 B1 9A 
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 24 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 25 -- 265
2017-02-07 21:58:35.010 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 51: Sending REQUEST Message = 01 0A 00 13 33 03 26 01 FF 25 B1 9A 
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 26 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 36 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 37 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 38 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 39 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 40 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 41 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 42 -- 265
2017-02-07 21:58:35.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 264 -- 265
2017-02-07 21:58:35.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 265 -- 265
2017-02-07 21:58:35.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 265 -- DONE -- CANCELLED WAIT_DATA
2017-02-07 21:58:35.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: -- To notify -- TIMEOUT_WAITING_FOR_DATA
2017-02-07 21:58:35.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 266 -- 265
2017-02-07 21:58:35.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 267 -- 265
2017-02-07 21:58:35.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 268 -- 265
2017-02-07 21:58:35.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction event listener 270 -- 265
2017-02-07 21:58:35.011 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-02-07 21:58:35.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete 265 -- 
2017-02-07 21:58:35.011 [DEBUG] [e.internal.protocol.ZWaveTransaction] - transactionStart type SendData 
2017-02-07 21:58:35.011 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID:269 [WAIT_RESPONSE] callback: 177
2017-02-07 21:58:35.011 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 65: Node Init response (0) TIMEOUT_WAITING_FOR_DATA
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-02-07 21:58:35.012 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 65: No data from device, but it was ACK'd. Possibly not supported? (Try 0)
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Feb 07 21:58:37 CST 2017 - 2000ms
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID:269 [WAIT_RESPONSE] callback: 177
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Feb 07 21:58:37 CST 2017 - 2000ms
2017-02-07 21:58:35.012 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-02-07 21:58:35.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-02-07 21:58:35.018 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2017-02-07 21:58:35.018 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-02-07 21:58:35.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2017-02-07 21:58:35.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Response[0x01], dest=255, callback=0, payload=01 
2017-02-07 21:58:35.036 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 B1 00 00 03 59 
2017-02-07 21:58:35.038 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-02-07 21:58:35.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=177, payload=B1 00 00 03 
2017-02-07 21:58:35.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=SendData[0x13], type=Request[0x00], dest=0, callback=177, payload=B1 00 00 03 
2017-02-07 21:58:36.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@6ec2b270
2017-02-07 21:58:36.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Adding to device queue
2017-02-07 21:58:36.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 65: Added to queue - size 28
2017-02-07 21:58:36.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-02-07 21:58:36.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-02-07 21:58:36.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-02-07 21:58:36.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Feb 07 21:58:37 CST 2017 - 664ms
2017-02-07 21:58:37.012 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
2017-02-07 21:58:37.013 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 51: XXXXXXX Timeout at state WAIT_RESPONSE. 3 retries remaining.
2017-02-07 21:58:37.013 [DEBUG] [sactionManager$ZWaveTransactionTimer] - Aborting Transaction!
2017-02-07 21:58:37.013 [DEBUG] [e.internal.protocol.ZWaveTransaction] - Transaction 269 ABORTED
2017-02-07 21:58:37.013 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 16 EA 
2017-02-07 21:58:37.013 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 16 EA 
2017-02-07 21:58:37.014 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-02-07 21:58:37.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2017-02-07 21:58:37.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2017-02-07 21:58:37.015 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-02-07 21:58:37.015 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-02-07 21:58:37.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage inputMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-02-07 21:58:37.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Feb 07 21:58:49 CST 2017 - 11998ms
2017-02-07 21:58:37.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lockMessage: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
^C

Third, I have three Kwikset locks which have worked with OpenHAB 1.8, but aren’t doing well with OpenHAB 2.x. I’ve tried repairing them, with limited success… help?

shawnmix · February 8, 2017, 4:43am

Ok, posting an update here relative to the lock woes (being the target of this binding). It seems I had a few things in my way that were causing issues, and to help anyone who may have similar issues, listing the problems (or potential problems) and the resolution.

Initial problem of even getting any real communication - The ZStick (Aeon 5th Gen) has a weird (to me, coming from Vera world) issue where if you have included the device even once, it basically won’t talk to the device again when you try to do inclusion. It turns out, the one thing I forgot to fully exclude, was the lock.
Now I started getting somewhere and the lock actually took a little longer and then would error out. I was having some interference from a recent update I made to the host where-in I was mapping the ZStick with the right permissions and such using a udev rule (etc/udev/rules.d/) for mapping a symlink. Well I recently plugged in another device, that got in the mix.

first attempt to resolve this was remove the rules file in the udev/rules location. well this was a bust as now I started getting i/o write error messages.
second attempt was to put the file back but remove the new rule for the second new device - no dice here as we still had the error on inclusion with the lock
third attempt - revert to known good condition, remove the extra rule, and unplug the extra USB device, now we’re getting somewhere

Finally - I got to go back and include the device again, and this time I saw positive news in the logs. Indication of the secure inclusion completed, device was added, and thing discovered. Yay!

now I did have to wait for a bit for the device initialization to kick in, and I’m glad I waited around before trying to kick it and start over again before calling it quits for the night - in defeat - but about a moment before I was ready to do it, I deleted the Thing and then hit the include/discover button again … what did appear but a message that a device was added with the actual name instead of Unknown Device!! Woohoo!!

As a side note, DEBUG logs were giving me WAY too much stuff. So I dropped down to INFO level logs instead. This gave me enough information to see that stuff was happening, but not every individual thing the ZWave binding is doing and communicating. That was too difficult to follow or make heads/tails of. INFO logs helped me start to pick out the issues and chase them down 1 by 1.

@chris - I say it many times over, and I can’t thank you enough for your work on this binding. It’s made OH extremely operable and the core thing we can’t live without in our house. Screencap below of a working BE469 - Schlage Camelot Keypad. Now, just need the unknown device issue for the others fixed and I’ll be in mint shape. Will let you know how the binding goes overall - PIN entries, lock/unlock stats, rules, etc.