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

[mstormi (Markus Storm)]

Using version 2.4.0.201807242215 on latest snapshot #1316, I got the same error. Didn’t seem to have impact, though.

2018-07-25 10:17:28.687 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 120: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-07-25 10:17:28.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-07-25 10:17:28.693 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 120: SECURITY not supported
2018-07-25 10:17:28.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 10:17:28.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 116ms
2018-07-25 10:17:28.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
2018-07-25 10:17:28.702 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 120: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2018-07-25 10:17:28.707 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-07-25 10:17:28.711 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 120: Creating new message for application command SWITCH_BINARY_GET
2018-07-25 10:17:28.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 10:17:28.716 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SWITCH_BINARY
2018-07-25 10:17:28.719 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 120: Encapsulating message, endpoint 1
2018-07-25 10:17:28.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Adding to device queue
2018-07-25 10:17:28.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-07-25 10:17:28.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-25 10:17:28.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 87ms
2018-07-25 10:17:28.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 83ms
2018-07-25 10:17:28.735 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling intialised at 86400 seconds - start in 86400 milliseconds.
2018-07-25 10:17:28.741 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 120: Encapsulating message, instance / endpoint 1
2018-07-25 10:17:28.740 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.zwave.handler.ZWaveThingHandler@f1748': Task already scheduled or cancelled
java.lang.IllegalStateException: Task already scheduled or cancelled
        at java.util.Timer.sched(Timer.java:401) [?:?]
        at java.util.Timer.schedule(Timer.java:193) [?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.startTransactionTimer(ZWaveTransactionManager.java:906) [174:org.openhab.binding.zwave:2.4.0.201807242215]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.addTransactionToQueue(ZWaveTransactionManager.java:335) [174:org.openhab.binding.zwave:2.4.0.201807242215]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.queueTransactionForSend(ZWaveTransactionManager.java:298) [174:org.openhab.binding.zwave:2.4.0.201807242215]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.enqueue(ZWaveController.java:493) [174:org.openhab.binding.zwave:2.4.0.201807242215]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendData(ZWaveController.java:864) [174:org.openhab.binding.zwave:2.4.0.201807242215]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.sendData(ZWaveControllerHandler.java:685) [174:org.openhab.binding.zwave:2.4.0.201807242215]
        at org.openhab.binding.zwave.handler.ZWaveThingHandler.handleCommand(ZWaveThingHandler.java:1091) [174:org.openhab.binding.zwave:2.4.0.201807242215]
        at sun.reflect.GeneratedMethodAccessor127.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [94:org.eclipse.smarthome.core:0.10.0.201807231443]
        at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [94:org.eclipse.smarthome.core:0.10.0.201807231443]
        at com.sun.proxy.$Proxy162.handleCommand(Unknown Source) [174:org.openhab.binding.zwave:2.4.0.201807242215]
        at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [101:org.eclipse.smarthome.core.thing:0.10.0.201807231443]
        at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [101:org.eclipse.smarthome.core.thing:0.10.0.201807231443]
        at sun.reflect.GeneratedMethodAccessor126.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [94:org.eclipse.smarthome.core:0.10.0.201807231443]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201807231443]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2018-07-25 10:17:28.759 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 120: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-07-25 10:17:28.778 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 120: SECURITY not supported

[Alexus1211 (Alex)]

@chris

it seems that your latest local changes haven’t yet been pushed to git, right?
as I mentioned before I use a binding that I build by myself, based on the latest commit from the dev branch from git. This message I can still see in my logs.

[chris (Chris Jackson)]

@Alexus1211

it seems that your latest local changes haven’t yet been pushed to git, right?

They are not merged into the development branch, that’s correct, but they are on git. As there are some changes going on at the moment, until these are consolidated and we get rid of the errors, I don’t want to merge this. I try to keep git updated though.

@Alexus1211

I use a binding that I build by myself

This is why I have asked that you use the binding I provide for the development version - that way we know where we are. It’s still unclear to me why you are simply building your own binding rather than using the binding provided?

@Alexus1211

This message I can still see in my logs.

As I said here and elsewhere, this message was changed a few days ago (maybe more). I also completely changed it yesterday to make it even clearer.

[vossivossi]

@chris

As there are some changes going on at the moment, until these are consolidated and we get rid of the errors

Unfortunately there are still quite a few. Just experienced another stopp of the Z-Wave binding (201807231832) with a Java exception. This time it is ‘Queue full’.
Here is the debug log (exception at 2018-07-25 20:55:39.233):

2018-07-25 20:55:38.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 171: Application Command Request (ALIVE:DONE)
2018-07-25 20:55:38.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 171: resetResendCount initComplete=true isDead=false
2018-07-25 20:55:38.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 171: Incoming command class COMMAND_CLASS_METER, endpoint 0
2018-07-25 20:55:38.193 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 171: SECURITY not supported
2018-07-25 20:55:38.193 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 171: Received COMMAND_CLASS_METER V3 METER_REPORT
2018-07-25 20:55:38.193 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 171: Meter: Type=Electric(1), Scale=W(2), Value=0.763
2018-07-25 20:55:38.194 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 171: Got an event from Z-Wave network: ZWaveMeterValueEvent
2018-07-25 20:55:38.194 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 171: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0.763
2018-07-25 20:55:38.194 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 171: Updating channel state zwave:device:ZWOG:node171:meter_watts to 0.763 [DecimalType]
2018-07-25 20:55:38.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 171: Commands processed 1.
2018-07-25 20:55:38.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 171: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2e473ad2.
2018-07-25 20:55:38.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 20:55:38.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 20:55:38.217 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 3F 06 31 05 01 22 01 1D C5 
2018-07-25 20:55:38.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 1D 
2018-07-25 20:55:38.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 1D 
2018-07-25 20:55:38.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 1D 
2018-07-25 20:55:38.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-25 20:55:38.221 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Application Command Request (ALIVE:DONE)
2018-07-25 20:55:38.221 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: resetResendCount initComplete=true isDead=false
2018-07-25 20:55:38.221 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2018-07-25 20:55:38.221 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: SECURITY not supported
2018-07-25 20:55:38.221 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 63: Received COMMAND_CLASS_SENSOR_MULTILEVEL V6 SENSOR_MULTILEVEL_REPORT
2018-07-25 20:55:38.221 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 63: Sensor Type = Temperature(1), Scale = 0
2018-07-25 20:55:38.221 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 63: Sensor Value = 28.5
2018-07-25 20:55:38.221 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2018-07-25 20:55:38.221 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 28.5
2018-07-25 20:55:38.221 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Updating channel state zwave:device:ZWOG:node63:sensor_temperature to 28.5 ? [QuantityType]
2018-07-25 20:55:38.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Commands processed 1.
2018-07-25 20:55:38.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@354af1b6.
2018-07-25 20:55:38.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.223 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.223 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 20:55:38.223 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 20:55:38.241 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 3F 06 31 05 01 22 01 1D C5 
2018-07-25 20:55:38.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 1D 
2018-07-25 20:55:38.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 1D 
2018-07-25 20:55:38.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 1D 
2018-07-25 20:55:38.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-25 20:55:38.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Application Command Request (ALIVE:DONE)
2018-07-25 20:55:38.244 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: resetResendCount initComplete=true isDead=false
2018-07-25 20:55:38.245 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2018-07-25 20:55:38.245 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: SECURITY not supported
2018-07-25 20:55:38.245 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 63: Received COMMAND_CLASS_SENSOR_MULTILEVEL V6 SENSOR_MULTILEVEL_REPORT
2018-07-25 20:55:38.245 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 63: Sensor Type = Temperature(1), Scale = 0
2018-07-25 20:55:38.245 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 63: Sensor Value = 28.5
2018-07-25 20:55:38.245 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2018-07-25 20:55:38.245 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 28.5
2018-07-25 20:55:38.245 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Updating channel state zwave:device:ZWOG:node63:sensor_temperature to 28.5 ? [QuantityType]
2018-07-25 20:55:38.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Commands processed 1.
2018-07-25 20:55:38.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@331680e0.
2018-07-25 20:55:38.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 20:55:38.247 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 20:55:38.264 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 3F 06 31 05 01 22 01 1D C5 
2018-07-25 20:55:38.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 1D 
2018-07-25 20:55:38.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 1D 
2018-07-25 20:55:38.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 06 31 05 01 22 01 1D 
2018-07-25 20:55:38.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-25 20:55:38.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Application Command Request (ALIVE:DONE)
2018-07-25 20:55:38.267 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: resetResendCount initComplete=true isDead=false
2018-07-25 20:55:38.268 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 0
2018-07-25 20:55:38.268 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: SECURITY not supported
2018-07-25 20:55:38.268 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 63: Received COMMAND_CLASS_SENSOR_MULTILEVEL V6 SENSOR_MULTILEVEL_REPORT
2018-07-25 20:55:38.268 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 63: Sensor Type = Temperature(1), Scale = 0
2018-07-25 20:55:38.268 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 63: Sensor Value = 28.5
2018-07-25 20:55:38.268 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2018-07-25 20:55:38.268 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SENSOR_MULTILEVEL, value = 28.5
2018-07-25 20:55:38.268 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Updating channel state zwave:device:ZWOG:node63:sensor_temperature to 28.5 ? [QuantityType]
2018-07-25 20:55:38.269 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Commands processed 1.
2018-07-25 20:55:38.269 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2208ecb6.
2018-07-25 20:55:38.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 20:55:38.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 20:55:38.305 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 3F 03 20 03 00 ED 
2018-07-25 20:55:38.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 03 20 03 00 
2018-07-25 20:55:38.308 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 03 20 03 00 
2018-07-25 20:55:38.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=63, callback=0, payload=00 3F 03 20 03 00 
2018-07-25 20:55:38.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-25 20:55:38.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Application Command Request (ALIVE:DONE)
2018-07-25 20:55:38.309 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: resetResendCount initComplete=true isDead=false
2018-07-25 20:55:38.309 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
2018-07-25 20:55:38.309 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 63: SECURITY not supported
2018-07-25 20:55:38.309 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 63: Received COMMAND_CLASS_BASIC V1 BASIC_REPORT
2018-07-25 20:55:38.309 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 63: Basic report, value = 0
2018-07-25 20:55:38.309 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-07-25 20:55:38.309 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 63: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_BASIC, value = 0
2018-07-25 20:55:38.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Commands processed 1.
2018-07-25 20:55:38.309 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 63: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@358ed38f.
2018-07-25 20:55:38.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:38.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 20:55:38.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 20:55:38.787 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 5B 0A 71 05 00 00 00 FF 07 03 00 00 35 
2018-07-25 20:55:38.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 124<>4 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-25 20:55:38.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=91, callback=0, payload=00 5B 0A 71 05 00 00 00 FF 07 03 00 00 
2018-07-25 20:55:38.949 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 40: TID 28835: Timeout at state ABORTED. 3 retries remaining.
2018-07-25 20:55:38.949 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 28835: Transaction is current transaction, so clearing!!!!!
2018-07-25 20:55:38.949 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 28835: Transaction CANCELLED
2018-07-25 20:55:38.949 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-25 20:55:38.949 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: notifyTransactionResponse TID:28835 CANCELLED
2018-07-25 20:55:38.950 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 20:55:38.950 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1B 03 43 02 01 25 EA 71 
2018-07-25 20:55:38.950 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 27: Sending REQUEST Message = 01 0A 00 13 1B 03 43 02 01 25 EA 71 
2018-07-25 20:55:38.951 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-25 20:55:38.951 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 28834: Transaction Start type SendData 
2018-07-25 20:55:38.952 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-25 20:55:38.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 125<>3 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 20:55:38.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 20:55:38.959 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-07-25 20:55:38.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 126<>2 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 20:55:38.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 20:55:39.100 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 EA 00 00 0F 0E 
2018-07-25 20:55:39.101 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 127<>1 : Message: class=SendData[19], type=Request[0], dest=0, callback=234, payload=EA 00 00 0F 
2018-07-25 20:55:39.101 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Request[0], dest=0, callback=234, payload=EA 00 00 0F 
2018-07-25 20:55:39.231 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 1B 06 43 03 01 22 01 27 AF 
2018-07-25 20:55:39.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 128<>0 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=27, callback=0, payload=00 1B 06 43 03 01 22 01 27 
2018-07-25 20:55:39.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=27, callback=0, payload=00 1B 06 43 03 01 22 01 27 
2018-07-25 20:55:39.233 [ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 
java.lang.IllegalStateException: Queue full
	at java.util.AbstractQueue.add(Unknown Source) [?:?]
	at java.util.concurrent.ArrayBlockingQueue.add(Unknown Source) [?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:395) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1053) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:634) [244:org.openhab.binding.zwave:2.4.0.201807231832]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:319) [244:org.openhab.binding.zwave:2.4.0.201807231832]
2018-07-25 20:55:39.234 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
2018-07-25 20:55:39.424 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 61 08 32 02 21 74 00 00 03 64 9E 
2018-07-25 20:55:39.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=97, callback=0, payload=00 61 08 32 02 21 74 00 00 03 64 
2018-07-25 20:55:39.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=97, callback=0, payload=00 61 08 32 02 21 74 00 00 03 64 
2018-07-25 20:55:39.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=97, callback=0, payload=00 61 08 32 02 21 74 00 00 03 64 
2018-07-25 20:55:39.427 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-25 20:55:39.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 97: Application Command Request (ALIVE:DONE)
2018-07-25 20:55:39.428 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 97: resetResendCount initComplete=true isDead=false
2018-07-25 20:55:39.428 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 97: Incoming command class COMMAND_CLASS_METER, endpoint 0
2018-07-25 20:55:39.428 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 97: SECURITY not supported
2018-07-25 20:55:39.428 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 97: Received COMMAND_CLASS_METER V3 METER_REPORT
2018-07-25 20:55:39.428 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 97: Meter: Type=Electric(1), Scale=W(2), Value=0.868
2018-07-25 20:55:39.428 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 97: Got an event from Z-Wave network: ZWaveMeterValueEvent
2018-07-25 20:55:39.428 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 97: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0.868
2018-07-25 20:55:39.428 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 97: Updating channel state zwave:device:ZWOG:node97:meter_watts to 0.868 [DecimalType]
2018-07-25 20:55:39.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 97: Commands processed 1.
2018-07-25 20:55:39.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 97: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@57ab53c9.
2018-07-25 20:55:39.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:39.429 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2018-07-25 20:55:39.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 20:55:39.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 20:55:39.537 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 61 08 32 02 21 74 00 00 03 64 9E 
2018-07-25 20:55:39.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=97, callback=0, payload=00 61 08 32 02 21 74 00 00 03 64 
2018-07-25 20:55:39.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationCommandHandler[4], type=Request[0], dest=97, callback=0, payload=00 61 08 32 02 21 74 00 00 03 64 
2018-07-25 20:55:39.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=97, callback=0, payload=00 61 08 32 02 21 74 00 00 03 64 
2018-07-25 20:55:39.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-25 20:55:39.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 97: Application Command Request (ALIVE:DONE)
2018-07-25 20:55:39.539 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 97: resetResendCount initComplete=true isDead=false
2018-07-25 20:55:39.539 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 97: Incoming command class COMMAND_CLASS_METER, endpoint 0
2018-07-25 20:55:39.539 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 97: SECURITY not supported
2018-07-25 20:55:39.539 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 97: Received COMMAND_CLASS_METER V3 METER_REPORT
2018-07-25 20:55:39.539 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 97: Meter: Type=Electric(1), Scale=W(2), Value=0.868
2018-07-25 20:55:39.539 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 97: Got an event from Z-Wave network: ZWaveMeterValueEvent
2018-07-25 20:55:39.539 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 97: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0.868
2018-07-25 20:55:39.539 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 97: Updating channel state zwave:device:ZWOG:node97:meter_watts to 0.868 [DecimalType]
2018-07-25 20:55:39.539 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 97: Commands processed 1.

[5iver (Scott Rushworth)]

@vossivossi

Z-Wave binding (201807231832)

The latest from the link in the first post is 2.4.0.201807242215.

[vossivossi]

@5iver

The latest from the link in the first post is 2.4.0.201807242215.

Sorry, but what does it help to change binding versions all 24h? I installed the version yesterday, 24th of July at 15:40 (so about just 30 hours ago). The recent dev versions have severe issues with stability and these only show up after >24 hours of continued operation. So I think the reporting of such severe errors is very useful. I am using the dev branch since 1,5 years now and the versions in the last 3 weeks have the poorest stability ever. It is nice to see battery powered devices to operate a bit smoother and some dead nodes to become green. BUT: at the moment the recent dev versions are not at all suitable for productive use. This was much better for 1,5 years so I would like to help to improve these critical stability issues.

@chris Could you please have a look at this? Thank you!

[mark_leonard_tuil (Mark)]

Hi, I thought my zwave troubles had been solved, however, they came back. All my zwave nodes have become very slow to respond including the powered ones. If I use the sitemap to turn a light on or off, it takes over a minute to respond. I put the binding into debug and got the following log. Unfortunately I had to cut the log short. (Node 18 is the light in question).

2018-07-25 23:43:07.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:07.688 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Polling...
2018-07-25 23:43:07.691 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Polling deferred until initialisation complete
2018-07-25 23:43:09.965 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:12.465 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:14.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:17.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:17.499 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 4: TID 56: Timeout at state WAIT_DATA. 3 retries remaining.
2018-07-25 23:43:17.502 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 56: Transaction is current transaction, so clearing!!!!!
2018-07-25 23:43:17.506 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 56: Transaction CANCELLED
2018-07-25 23:43:17.510 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-25 23:43:17.514 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:56 CANCELLED
2018-07-25 23:43:17.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 23:43:17.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 56: Transaction event listener: DONE: CANCELLED -> 
2018-07-25 23:43:17.521 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: -- To notify -- TIMEOUT_WAITING_FOR_DATA
2018-07-25 23:43:17.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 56 --
2018-07-25 23:43:17.528 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@141d837
2018-07-25 23:43:17.532 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: No data from device, but it was ACK'd. Possibly not supported? (Try 0)
2018-07-25 23:43:18.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@17e5507
2018-07-25 23:43:18.166 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Bump transaction 368 priority from Controller to Immediate
2018-07-25 23:43:18.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
2018-07-25 23:43:18.171 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 23:43:18.175 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 04 9F 
2018-07-25 23:43:18.179 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 04 9F 
2018-07-25 23:43:18.186 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-25 23:43:18.188 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:18.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:18.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:18.194 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 
2018-07-25 23:43:18.196 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-25 23:43:18.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-25 23:43:18.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 23:43:18.205 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 23:43:18.207 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-25 23:43:18.211 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 368: Transaction Start type RequestNodeInfo 
2018-07-25 23:43:18.213 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:18.217 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:18.219 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:18.222 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 368: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-07-25 23:43:18.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-25 23:43:18.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 368: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-07-25 23:43:18.230 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:18.232 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
2018-07-25 23:43:18.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 368: Advanced to WAIT_DATA
2018-07-25 23:43:18.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 368: Transaction not completed
2018-07-25 23:43:18.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 23:43:18.241 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 23:43:19.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:21.307 [INFO ] [.eclipse.smarthome.model.script.RULE] - --> astro init
2018-07-25 23:43:21.327 [INFO ] [.eclipse.smarthome.model.script.RULE] - --> Night_State ON
2018-07-25 23:43:22.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:24.965 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:25.083 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@19aaa9e
2018-07-25 23:43:25.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
2018-07-25 23:43:25.093 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 23:43:27.035 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 06 00 49 81 00 00 31 
2018-07-25 23:43:27.041 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2018-07-25 23:43:27.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2018-07-25 23:43:27.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2018-07-25 23:43:27.050 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 368: [WAIT_DATA] requiresResponse=true callback: 0
2018-07-25 23:43:27.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-25 23:43:27.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 368: [WAIT_DATA] requiresResponse=true callback: 0
2018-07-25 23:43:27.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 368: (Callback 0)
2018-07-25 23:43:27.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 368: callback 0
2018-07-25 23:43:27.063 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2018-07-25 23:43:27.065 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 4: Application update request. Node Info Request Failed.
2018-07-25 23:43:27.068 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 368: Transaction CANCELLED
2018-07-25 23:43:27.070 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-25 23:43:27.073 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: CANCEL while sending message. Requeueing - 2 attempts left!
2018-07-25 23:43:27.076 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 368: Transaction RESET with 2 retries remaining.
2018-07-25 23:43:27.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
2018-07-25 23:43:27.081 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 23:43:27.085 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 05 9E 
2018-07-25 23:43:27.088 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 05 9E 
2018-07-25 23:43:27.093 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-25 23:43:27.096 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:27.098 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:27.101 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 
2018-07-25 23:43:27.106 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-25 23:43:27.109 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 369: Transaction Start type RequestNodeInfo 
2018-07-25 23:43:27.111 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:27.112 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 368: Transaction not completed
2018-07-25 23:43:27.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:27.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:27.117 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 369: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-07-25 23:43:27.118 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-25 23:43:27.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:27.123 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 369: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-07-25 23:43:27.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-25 23:43:27.126 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 369: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-07-25 23:43:27.128 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:27.130 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
2018-07-25 23:43:27.132 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 369: Advanced to WAIT_DATA
2018-07-25 23:43:27.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 369: Transaction not completed
2018-07-25 23:43:27.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 23:43:27.137 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 23:43:27.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:29.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:32.343 [INFO ] [thome.model.script.*****MARKER******] - ****MARKER*****
2018-07-25 23:43:32.467 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:33.780 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@abc3df
2018-07-25 23:43:33.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Adding to device queue
2018-07-25 23:43:33.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 23:43:34.965 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:36.949 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Command received zwave:device:a93e88d5:node18:switch_dimmer --> 42
2018-07-25 23:43:36.967 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 18: Creating new message for command SWITCH_MULTILEVEL_SET
2018-07-25 23:43:36.983 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build null
2018-07-25 23:43:36.992 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Encapsulating message, endpoint 0
2018-07-25 23:43:37.019 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2018-07-25 23:43:37.022 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-07-25 23:43:37.027 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Adding to device queue
2018-07-25 23:43:37.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 23:43:37.039 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling intialised at 1800 seconds - start in 1500 milliseconds.
2018-07-25 23:43:37.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:38.539 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling...
2018-07-25 23:43:38.542 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling zwave:device:a93e88d5:node18:switch_dimmer
2018-07-25 23:43:38.545 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 18: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-07-25 23:43:38.547 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 18: Creating new message for command SWITCH_MULTILEVEL_GET
2018-07-25 23:43:38.550 [DEBUG] [ommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SWITCH_MULTILEVEL
2018-07-25 23:43:38.552 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Encapsulating message, endpoint 0
2018-07-25 23:43:38.555 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2018-07-25 23:43:38.558 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-07-25 23:43:38.560 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Polling skipped for zwave:device:a93e88d5:node18:switch_dimmer on COMMAND_CLASS_BASIC
2018-07-25 23:43:38.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Adding to device queue
2018-07-25 23:43:38.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 23:43:39.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:42.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:44.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:47.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:49.967 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:52.133 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 5: TID 369: Timeout at state WAIT_DATA. 3 retries remaining.
2018-07-25 23:43:52.141 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 369: Transaction is current transaction, so clearing!!!!!
2018-07-25 23:43:52.145 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 369: Transaction CANCELLED
2018-07-25 23:43:52.157 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-25 23:43:52.162 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:369 CANCELLED
2018-07-25 23:43:52.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 23:43:52.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 369: Transaction event listener: DONE: CANCELLED -> 
2018-07-25 23:43:52.173 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 60 04 9F 
2018-07-25 23:43:52.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: -- To notify -- TIMEOUT_WAITING_FOR_DATA
2018-07-25 23:43:52.181 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 60 04 9F 
2018-07-25 23:43:52.182 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 369 --
2018-07-25 23:43:52.188 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node Init response (7) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@171e983
2018-07-25 23:43:52.188 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-25 23:43:52.193 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: No data from device, but it was ACK'd. Possibly not supported? (Try 7)
2018-07-25 23:43:52.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:52.197 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-25 23:43:52.201 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:52.209 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:52.212 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-25 23:43:52.214 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 60 01 9B 
2018-07-25 23:43:52.215 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 368: Transaction Start type RequestNodeInfo 
2018-07-25 23:43:52.214 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-25 23:43:52.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 23:43:52.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:52.231 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:52.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 23:43:52.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:52.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 368: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-07-25 23:43:52.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-25 23:43:52.245 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 368: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-07-25 23:43:52.248 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeInfo[96], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:52.256 [DEBUG] [lmessage.RequestNodeInfoMessageClass] - Request node info successfully placed on stack.
2018-07-25 23:43:52.259 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 368: Advanced to WAIT_DATA
2018-07-25 23:43:52.261 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 368: Transaction not completed
2018-07-25 23:43:52.263 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 23:43:52.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 23:43:52.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:54.967 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:57.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2018-07-25 23:43:59.346 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 06 00 49 81 00 00 31 
2018-07-25 23:43:59.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2018-07-25 23:43:59.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2018-07-25 23:43:59.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2018-07-25 23:43:59.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 368: [WAIT_DATA] requiresResponse=true callback: 0
2018-07-25 23:43:59.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-25 23:43:59.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 368: [WAIT_DATA] requiresResponse=true callback: 0
2018-07-25 23:43:59.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 368: (Callback 0)
2018-07-25 23:43:59.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 368: callback 0
2018-07-25 23:43:59.377 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=0, callback=129, payload=81 00 00 
2018-07-25 23:43:59.380 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 4: Application update request. Node Info Request Failed.
2018-07-25 23:43:59.383 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 368: Transaction CANCELLED
2018-07-25 23:43:59.387 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-07-25 23:43:59.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: CANCEL while sending message. Requeueing - 1 attempts left!
2018-07-25 23:43:59.393 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 368: Transaction RESET with 1 retries remaining.
2018-07-25 23:43:59.396 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue
2018-07-25 23:43:59.399 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2018-07-25 23:43:59.404 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 12 02 26 02 25 AF 5B 
2018-07-25 23:43:59.408 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 18: Sending REQUEST Message = 01 09 00 13 12 02 26 02 25 AF 5B 
2018-07-25 23:43:59.415 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-25 23:43:59.417 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-25 23:43:59.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:59.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:59.421 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 372: Transaction Start type SendData 
2018-07-25 23:43:59.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 368: Transaction not completed
2018-07-25 23:43:59.432 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-07-25 23:43:59.432 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-25 23:43:59.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 372: [WAIT_RESPONSE] requiresResponse=true callback: 175
2018-07-25 23:43:59.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:59.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-25 23:43:59.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-25 23:43:59.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2018-07-25 23:43:59.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2018-07-25 23:43:59.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

[chris (Chris Jackson)]

@vossivossi

Sorry, but what does it help to change binding versions all 24h?

Ummm… I could of course only do a change once a week if you prefer, but as people are reporting some issues, then I try and update the binding to try and resolve them. Most of the time people are complaining it’s not updated often enough - not that it’s updated too often. Another reason is to update the database. If you don’t want to use the updated version, then you are not required to, but as this is a development binding, and we’re trying to resolve some issues, I’m updating it as needed.

Apologies if this is inconvenient though.

@vossivossi

Could you please have a look at this?

I am continually “looking” and as I find issues, I’m updating the binding. Please refer to the above points. I’m really not sure how you would like to see the updates handled?

[chris (Chris Jackson)]

There appears to be an issue with node 4 not responding. This is blocking the network and causing the 15 second delay on the command.

[JRB123 (Jeremy)]

Hi Chris,

I seem to be having the same issue with the recent updates. Working ok for many hours (could be 12, could be over 24), then an exception and everything after that is just “Aborting Transaction!”

I’ve uploaded the full log to your website, ticket kDj8cZWGd6N.

23-Jul-2018 12:58:15.095 [ERROR] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread. 
java.lang.IllegalStateException: Queue full
	at java.util.AbstractQueue.add(AbstractQueue.java:98) [?:?]
	at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:312) [?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:394) [190:org.openhab.binding.zwave:2.4.0.201807211340]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1053) [190:org.openhab.binding.zwave:2.4.0.201807211340]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:634) [190:org.openhab.binding.zwave:2.4.0.201807211340]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:319) [190:org.openhab.binding.zwave:2.4.0.201807211340]
23-Jul-2018 12:58:15.095 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Stopped ZWave thread: Receive
23-Jul-2018 12:58:17.063 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - NODE 14: TID 7984: Timeout at state WAIT_RESPONSE. 3 retries remaining.
23-Jul-2018 12:58:17.063 [DEBUG] [ocol.ZWaveTransactionManager$ZWaveTransactionTimer] - Aborting Transaction!
23-Jul-2018 12:58:17.063 [DEBUG] [b.binding.zwave.internal.protocol.ZWaveTransaction] - TID 7984: Transaction ABORTED

Many thanks,
Jeremy

[dan12345 (Dan)]

I have this too.

[chris (Chris Jackson)]

@dan12345

I have this too.

Sorry guys, I’ve not had the chance to look at this over the last day as I was not at home yesterday. I’ll take a look tonight - this is related to the hold-off timer.

Apologies for the hassle…

[dan12345 (Dan)]

when I last checked you were doing this out of goodwill in your spare time, so an apology is neither expected nor required!

[waitz_sebastian (Sebastian)]

Hey there,
I’m planning to buy a zwave door lock, so I guess I should migrate to this version of the binding, right?
Are there any plans to merge both z-wave bindings, or deprecate the old one and continue with this one?

Do I have to remove all things and re-add all the nodes via HABmin? I guess I dont need to have physical access to the nodes, since they are still connected to the Aeotec USB stick, right?

Thanks for your help!
Best Sebastian

[mhilbush (Mark)]

@waitz_sebastian

I’m planning to buy a zwave door lock, so I guess I should migrate to this version of the binding, right?

Correct. You need to install the version from the link in the first post of this thread. You also should confirm whether or not the door lock is in the database. If it’s not in the database, then you’ll need to do a little extra work to have it added. Odds are pretty high that it’ll be in the database.

@waitz_sebastian

Are there any plans to merge both z-wave bindings, or deprecate the old one and continue with this one?

Yes, @chris plans to replace the current master version with this version soon once a couple issues get sorted out.

@waitz_sebastian

Do I have to remove all things and re-add all the nodes via HABmin

Yes. You need to delete the node things (including the serial controller), then add them back. No need to exclude/include. A while back, I posted the steps I followed to migrate from master to development, in case you want to see what I did.

@waitz_sebastian

I guess I dont need to have physical access to the nodes

True, with one possible exception. If you have battery devices, you will need to wait for each of them to wake up before the initialization can complete. Having physical access can help speed up the initialization because you can wake them up manually.

[aradoorolesen (Anders Olesen)]

With the commit - Database update (#964), a new definition was added for the Fibaro smoke detector (FGSD002). The original defintion was changed to include:
versionMax" 3.1

My smoke detectors are version 3.3, and now when I try to add them from the inbox using PaperUI, I get an "Error: 404 - Not found, and the smoke detectors just remains in the inbox. Nothing in the log files! Even when logging zwave debug. Should I change log level on something else?
In the jsondb folder the DiscoveryResult file shows that it is using the new definition.

I assume there’s something wrong with the new definition file. I have tried deleting the cache and tmp folders.

New File: fibaro_fgsd002_3_2.xml
Original File: fibaro_fgsd002_00_000

On the device database homepage I can see that the new definition was approved on the 19th of July.

Approved on 2018-07-19 17:35:25, and last exported on 2018-07-20 23:16:28

[chris (Chris Jackson)]

@aradoorolesen

and the smoke detectors just remains in the inbox

I would suggest to delete it from the inbox and try a rediscovery to see if it improves things. I don’t think a problem in the database shouldn’t prevent a device being added as a thing.

[aradoorolesen (Anders Olesen)]

Done that many times. Same result.

[sihui]

@aradoorolesen

The original defintion was changed to include:
versionMax" 3.1

This was done because of this post:

Unknown Z-Wave+ devices in OH2 PaperUI

Hello, I have managed to add Zwave+ devices using PaperUI but they appear to be discovered as “unknown device”. From several topics, it looks like these devices are not included into the cd-jackson-zwave-device-list database. I have checked into the Zwave database for the following devices: –> Smoke detector from Fibaro FGSD-002: 010F:0C02:1003:3.3 https://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/129 –> Flood sensor from Fibaro FGFS-101: 010F:…

@ThomasL01

–> Smoke detector from Fibaro FGSD-002: 010F:0C02:1003:3.3

[aradoorolesen (Anders Olesen)]

I have been able to discover and add my smoke detectors up until the last developer version. With the latest version I devices are discovered correctly, but I cannot add them as things.

Z-Wave Node 008: FGSD002 Smoke Detector
FGSD002 Smoke Detector