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

Add-ons Bindings
,
3936

Here are several examples of a dimmer being set to a level, but the command polling comes back with the previous value of the light. This is with the command polling set to 15s. What makes this even odder, is that it does not happen for all devices of the same type, and it does not always happen for the same device. Adjusting the command polling interval did not have any affect. Other people have previously reported something similar.

Previous values reported by poll (filtered) 
2018-08-21 16:00:41.654 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Command received zwave:device:07cb40a2:node30:switch_dimmer --> 21
2018-08-21 16:00:41.654 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Creating new message for command SWITCH_MULTILEVEL_SET
2018-08-21 16:00:41.654 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2018-08-21 16:00:41.655 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-08-21 16:00:41.655 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
2018-08-21 16:00:41.657 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 30: Sending REQUEST Message = 01 0A 00 13 1E 03 26 01 15 25 85 69 
2018-08-21 16:00:41.662 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling intialised at 1800 seconds - start in 15000 milliseconds.
2018-08-21 16:00:41.668 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: sentData successfully placed on stack.
2018-08-21 16:00:41.668 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26788: Transaction not completed
2018-08-21 16:00:41.686 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: SendData Request. CallBack ID = 133, Status = Transmission complete and ACK received(0)
2018-08-21 16:00:41.686 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: resetResendCount initComplete=true isDead=false
2018-08-21 16:00:41.686 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Response processed after 25ms
2018-08-21 16:00:41.686 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26788: Transaction completed
2018-08-21 16:00:41.686 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: notifyTransactionResponse TID:26788 DONE
2018-08-21 16:00:41.687 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-08-21 16:00:56.662 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling...
2018-08-21 16:00:56.662 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling zwave:device:07cb40a2:node30:switch_dimmer
2018-08-21 16:00:56.662 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMultiLevelSwitchConverter] - NODE 30: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-08-21 16:00:56.662 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Creating new message for command SWITCH_MULTILEVEL_GET
2018-08-21 16:00:56.663 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2018-08-21 16:00:56.663 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-08-21 16:00:56.663 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling zwave:device:07cb40a2:node30:scene_number
2018-08-21 16:00:56.663 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling skipped for zwave:device:07cb40a2:node30:scene_number on COMMAND_CLASS_BASIC
2018-08-21 16:00:56.663 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
2018-08-21 16:00:56.663 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 30: Sending REQUEST Message = 01 09 00 13 1E 02 26 02 25 86 7E 
2018-08-21 16:00:56.674 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: sentData successfully placed on stack.
2018-08-21 16:00:56.674 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26792: Transaction not completed
2018-08-21 16:00:56.693 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: SendData Request. CallBack ID = 134, Status = Transmission complete and ACK received(0)
2018-08-21 16:00:56.693 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: resetResendCount initComplete=true isDead=false
2018-08-21 16:00:56.693 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26792: Transaction not completed
2018-08-21 16:00:56.701 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Application Command Request (ALIVE:DONE)
2018-08-21 16:00:56.701 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: resetResendCount initComplete=true isDead=false
2018-08-21 16:00:56.701 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-08-21 16:00:56.701 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2018-08-21 16:00:56.701 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass] - NODE 30: Received COMMAND_CLASS_SWITCH_MULTILEVEL V1 SWITCH_MULTILEVEL_REPORT
2018-08-21 16:00:56.701 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Switch Multi Level report, value = 0
2018-08-21 16:00:56.701 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-08-21 16:00:56.701 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 0
2018-08-21 16:00:56.701 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Updating channel state zwave:device:07cb40a2:node30:switch_dimmer to 0 [PercentType]
2018-08-21 16:00:56.702 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Commands processed 1.
2018-08-21 16:00:56.702 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5a9fc4aa.
2018-08-21 16:00:56.703 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5a9fc4aa.
2018-08-21 16:00:56.708 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: notifyTransactionResponse TID:26792 DONE
2018-08-21 16:00:56.710 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-08-21 16:01:46.029 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Command received zwave:device:07cb40a2:node30:switch_dimmer --> 58
2018-08-21 16:01:46.030 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Creating new message for command SWITCH_MULTILEVEL_SET
2018-08-21 16:01:46.031 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2018-08-21 16:01:46.031 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-08-21 16:01:46.032 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
2018-08-21 16:01:46.033 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 30: Sending REQUEST Message = 01 0A 00 13 1E 03 26 01 3A 25 88 4B 
2018-08-21 16:01:46.043 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling intialised at 1800 seconds - start in 15000 milliseconds.
2018-08-21 16:01:46.047 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: sentData successfully placed on stack.
2018-08-21 16:01:46.047 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26795: Transaction not completed
2018-08-21 16:01:46.060 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: SendData Request. CallBack ID = 136, Status = Transmission complete and ACK received(0)
2018-08-21 16:01:46.060 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: resetResendCount initComplete=true isDead=false
2018-08-21 16:01:46.060 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Response processed after 18ms
2018-08-21 16:01:46.060 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26795: Transaction completed
2018-08-21 16:01:46.060 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: notifyTransactionResponse TID:26795 DONE
2018-08-21 16:01:46.061 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-08-21 16:02:01.043 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling...
2018-08-21 16:02:01.043 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling zwave:device:07cb40a2:node30:switch_dimmer
2018-08-21 16:02:01.043 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMultiLevelSwitchConverter] - NODE 30: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-08-21 16:02:01.043 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Creating new message for command SWITCH_MULTILEVEL_GET
2018-08-21 16:02:01.043 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2018-08-21 16:02:01.043 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-08-21 16:02:01.043 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling zwave:device:07cb40a2:node30:scene_number
2018-08-21 16:02:01.043 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling skipped for zwave:device:07cb40a2:node30:scene_number on COMMAND_CLASS_BASIC
2018-08-21 16:02:01.043 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
2018-08-21 16:02:01.044 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 30: Sending REQUEST Message = 01 09 00 13 1E 02 26 02 25 89 71 
2018-08-21 16:02:01.059 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: sentData successfully placed on stack.
2018-08-21 16:02:01.059 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26796: Transaction not completed
2018-08-21 16:02:01.072 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: SendData Request. CallBack ID = 137, Status = Transmission complete and ACK received(0)
2018-08-21 16:02:01.072 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: resetResendCount initComplete=true isDead=false
2018-08-21 16:02:01.072 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26796: Transaction not completed
2018-08-21 16:02:01.080 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Application Command Request (ALIVE:DONE)
2018-08-21 16:02:01.080 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: resetResendCount initComplete=true isDead=false
2018-08-21 16:02:01.080 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-08-21 16:02:01.080 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2018-08-21 16:02:01.081 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass] - NODE 30: Received COMMAND_CLASS_SWITCH_MULTILEVEL V1 SWITCH_MULTILEVEL_REPORT
2018-08-21 16:02:01.081 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Switch Multi Level report, value = 21
2018-08-21 16:02:01.081 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-08-21 16:02:01.081 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 21
2018-08-21 16:02:01.081 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Updating channel state zwave:device:07cb40a2:node30:switch_dimmer to 21 [PercentType]
2018-08-21 16:02:01.086 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Commands processed 1.
2018-08-21 16:02:01.086 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@9446fef.
2018-08-21 16:02:01.087 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@9446fef.
2018-08-21 16:02:01.087 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: notifyTransactionResponse TID:26796 DONE
2018-08-21 16:02:01.088 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-08-21 16:02:21.533 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Command received zwave:device:07cb40a2:node30:switch_dimmer --> 0
2018-08-21 16:02:21.534 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Creating new message for command SWITCH_MULTILEVEL_SET
2018-08-21 16:02:21.534 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2018-08-21 16:02:21.534 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-08-21 16:02:21.535 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
2018-08-21 16:02:21.535 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 30: Sending REQUEST Message = 01 0A 00 13 1E 03 26 01 00 25 8A 73 
2018-08-21 16:02:21.540 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling intialised at 1800 seconds - start in 15000 milliseconds.
2018-08-21 16:02:21.553 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: sentData successfully placed on stack.
2018-08-21 16:02:21.553 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26797: Transaction not completed
2018-08-21 16:02:21.564 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: SendData Request. CallBack ID = 138, Status = Transmission complete and ACK received(0)
2018-08-21 16:02:21.564 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: resetResendCount initComplete=true isDead=false
2018-08-21 16:02:21.565 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Response processed after 25ms
2018-08-21 16:02:21.565 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26797: Transaction completed
2018-08-21 16:02:21.565 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: notifyTransactionResponse TID:26797 DONE
2018-08-21 16:02:21.565 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-08-21 16:02:36.540 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling...
2018-08-21 16:02:36.540 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling zwave:device:07cb40a2:node30:switch_dimmer
2018-08-21 16:02:36.540 [DEBUG] [org.openhab.binding.zwave.internal.converter.ZWaveMultiLevelSwitchConverter] - NODE 30: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-08-21 16:02:36.540 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Creating new message for command SWITCH_MULTILEVEL_GET
2018-08-21 16:02:36.540 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2018-08-21 16:02:36.540 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2018-08-21 16:02:36.540 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling zwave:device:07cb40a2:node30:scene_number
2018-08-21 16:02:36.540 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Polling skipped for zwave:device:07cb40a2:node30:scene_number on COMMAND_CLASS_BASIC
2018-08-21 16:02:36.541 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Adding to device queue
2018-08-21 16:02:36.541 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 30: Sending REQUEST Message = 01 09 00 13 1E 02 26 02 25 8B 73 
2018-08-21 16:02:36.552 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: sentData successfully placed on stack.
2018-08-21 16:02:36.552 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26798: Transaction not completed
2018-08-21 16:02:36.567 [DEBUG] [org.openhab.binding.zwave.internal.protocol.serialmessage.SendDataMessageClass] - NODE 30: SendData Request. CallBack ID = 139, Status = Transmission complete and ACK received(0)
2018-08-21 16:02:36.567 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: resetResendCount initComplete=true isDead=false
2018-08-21 16:02:36.567 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: TID 26798: Transaction not completed
2018-08-21 16:02:36.577 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Application Command Request (ALIVE:DONE)
2018-08-21 16:02:36.577 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: resetResendCount initComplete=true isDead=false
2018-08-21 16:02:36.577 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2018-08-21 16:02:36.577 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 30: SECURITY not supported
2018-08-21 16:02:36.577 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveCommandClass] - NODE 30: Received COMMAND_CLASS_SWITCH_MULTILEVEL V1 SWITCH_MULTILEVEL_REPORT
2018-08-21 16:02:36.577 [DEBUG] [org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveMultiLevelSwitchCommandClass] - NODE 30: Switch Multi Level report, value = 58
2018-08-21 16:02:36.577 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-08-21 16:02:36.577 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 58
2018-08-21 16:02:36.577 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Updating channel state zwave:device:07cb40a2:node30:switch_dimmer to 58 [PercentType]
2018-08-21 16:02:36.580 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Commands processed 1.
2018-08-21 16:02:36.580 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@19d53a18.
2018-08-21 16:02:36.580 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@19d53a18.
2018-08-21 16:02:36.580 [DEBUG] [org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager] - NODE 30: notifyTransactionResponse TID:26798 DONE
2018-08-21 16:02:36.581 [DEBUG] [org.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 30: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

EDIT: The binding seems to be doing everything right, and the device is just sending the wrong value. By popping the air gap (essentially power cycling the device) the dimmer began sending the correct values! In case anyone sees something similar, a power cycle may resolve it. Hopefully, this is not just a temporary fix. This was occurring with Leviton VRMX and DZMX1 dimmers.

3937

How did you get this device working? Mine shows “unknown” device.

Thanks

3938

Check the database if you have a different version which then may need to be added:

https://www.cd-jackson.com/index.php/zwave/zwave-device-database/zwave-device-list/devicesummary/664

3939

At binding startup, I can see these errors:

2018-08-22 12:02:28.020 [ERROR] [serialmessage.SetSucNodeMessageClass] - NODE 0: SetSucNodeID command failed.
2018-08-22 12:02:28.362 [ERROR] [serialmessage.SetSucNodeMessageClass] - NODE 0: SetSucNodeID command failed.
2018-08-22 12:02:28.654 [ERROR] [serialmessage.SetSucNodeMessageClass] - NODE 0: SetSucNodeID command failed.

Is it important ?

3940

Can you provide the log showing this please (just this command, and a little before it will be fine) and I’ll have a look…

3941

I got this error when the binding is stopped:

2018-08-22 11:57:54.589 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2018-08-22 11:57:54.606 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.dispose()' on 'org.openhab.binding.zwave.handler.ZWaveSerialHandler@1e3badc': null
java.lang.IllegalMonitorStateException: null
        at java.lang.Object.notify(Native Method) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.shutdown(ZWaveTransactionManager.java:207) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.shutdown(ZWaveController.java:118) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.dispose(ZWaveControllerHandler.java:247) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.handler.ZWaveSerialHandler.dispose(ZWaveSerialHandler.java:133) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at sun.reflect.GeneratedMethodAccessor116.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.201808211930]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
        at java.lang.Thread.run(Thread.java:745) [?:?]
2018-08-22 11:57:54.633 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occurred while disposing handler of thing 'zwave:serial_zstick:controller': null
java.lang.IllegalMonitorStateException: null
        at java.lang.Object.notify(Native Method) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.shutdown(ZWaveTransactionManager.java:207) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.shutdown(ZWaveController.java:118) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.handler.ZWaveControllerHandler.dispose(ZWaveControllerHandler.java:247) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at org.openhab.binding.zwave.handler.ZWaveSerialHandler.dispose(ZWaveSerialHandler.java:133) [218:org.openhab.binding.zwave:2.4.0.201808200952]
        at sun.reflect.GeneratedMethodAccessor116.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.201808211930]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
        at java.lang.Thread.run(Thread.java:745) [?:?]
3942

I get the exact same since about a week back. Just haven’t got around to reporting it :blush:

To be more precise, the first time I got it was 2018-08-15. That day I upgraded the binding from an old (months back) version though, so this could have been introduced quite some time before that.

One thing I notice is that both me and @Lolodomo are on Z-sticks, don’t know if that’s relevant?

3943

I stood on a ladder last night for an hour excluding and reincluding an NGD00Z that had “lost” it’s secure inclusion. Hold offs were not always involved, but it’s looking like the failure was always the same:

2018-08-21 21:50:48.820 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer started...
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 250ms
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 129: Retry count exceeded. Discarding message: TID 1260: [CANCELLED] priority=Immediate, requiresResponse=true, callback: 29
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 129: TID 1260: Transaction completed
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 129: notifyTransactionResponse TID:1260 CANCELLED
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true.
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 1260: Transaction event listener: DONE: CANCELLED -> 
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 250ms
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 129: -- To notify -- TIMEOUT_WAITING_FOR_CONTROLLER
2018-08-21 21:50:48.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 1260 --
2018-08-21 21:50:48.821 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 129: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@20b4047e
2018-08-21 21:50:48.821 [DEBUG] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 129: timed out after 20455128398 / 20000000000
2018-08-21 21:50:48.821 [INFO ] [protocol.initialization.ZWaveNodeInitStageAdvancer] - NODE 129: SECURITY_INC State=FAILED, Reason=GET_SCHEME

I’m going to test secure inclusion with some other devices. Hopefully, this is just a hardware failure and not a regression in secure inclusion. On second thought…

3944

Hello!

I am having trouble including/excluding devices with an everspring zwave plus stick and while searching how to find the issue I saw weird logs trying to go to exclusion mode in habmin, binding log as debug:
(I am using version 2.4.0.201808191228 of the binding)

2018-08-22 16:30:15.063 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:512

2018-08-22 16:30:15.066 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received

2018-08-22 16:30:15.068 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_exclude to true

2018-08-22 16:30:15.069 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process already running - aborted

Is something stuck in my controller preventing it from excluding/including devices ?

Thanks for your help !

3945

It’s really hard to tell - you’ve only provide 6 milliseconds of logging and there’s nothing really wrong here in itself. It needs more context to understand what is happening, so please provide a minute or so of the log from prior to this.

3946

Did you also bring the controller up the ladder ?
I have just had to move mine really close to my door lock to get that securely included.
Routing, “network wide” inclusion they all don’t seem to work with secure inclusion.
Someone a couple of posts up posted this hint, and I can confirm.

3947

Maybe this is necessary for old locks that may use low power mode for inclusion, but this is definitely not the recommendation these days. Most devices should use high power inclusion (note that network wide inclusion is another issue again) and you should be able to include most devices up to 10 to 15 meters away (ie within standard, but direct range of the controller).

As I say though, some devices may not respect this - I think in the past the recommendation from ZWA was to use low power inclusion for locks, but it’s not the case now.

3948

@chris Is there anyway to force a wakeup from a battery device (except for opening the device/push its button).
I just installed the snapshot build from the 18th august. All my battery devices were rediscovered, but unknown… I suspect this is due to they´re not wake.

A shot side matter on the upgrade…
When I removed the 2.3.0 Z-wave binding via PaperUI, I suddenly got tons of Zigbee errors… is there a connection somewhere??

3949

No - if a device is asleep, then it can only wake up by itself. Either by pressing the button, or through the regular timer.

Probably - you need to wait for them to wake up, or manually wake them up.

No - there’s no link at all (other than the serial driver of course, but that’s not related to the binding).

3950

When i restart openhab the following IllegalMonitorStateException is shown. I’m not sure when this exception first occured and what the cause is, using 2018-08-20 binding version.

2018-08-22 22:08:15.130 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2018-08-22 22:08:15.189 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-08-22 22:08:54.374 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2018-08-22 22:15:45.388 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2018-08-22 22:15:57.508 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Stopped ZWave serial handler
2018-08-22 22:15:57.520 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.dispose()' on 'org.openhab.binding.zwave.handler.ZWaveSerialHandler@3759ed': null
java.lang.IllegalMonitorStateException: null
	at java.lang.Object.notify(Native Method) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.shutdown(ZWaveTransactionManager.java:207) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.shutdown(ZWaveController.java:118) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.dispose(ZWaveControllerHandler.java:247) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler.dispose(ZWaveSerialHandler.java:133) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at sun.reflect.GeneratedMethodAccessor141.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.201808211930]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
	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-08-22 22:15:57.541 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occurred while disposing handler of thing 'zwave:serial_zstick:512': null
java.lang.IllegalMonitorStateException: null
	at java.lang.Object.notify(Native Method) ~[?:?]
	at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.shutdown(ZWaveTransactionManager.java:207) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.internal.protocol.ZWaveController.shutdown(ZWaveController.java:118) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.handler.ZWaveControllerHandler.dispose(ZWaveControllerHandler.java:247) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at org.openhab.binding.zwave.handler.ZWaveSerialHandler.dispose(ZWaveSerialHandler.java:133) [180:org.openhab.binding.zwave:2.4.0.201808200952]
	at sun.reflect.GeneratedMethodAccessor141.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.201808211930]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [94:org.eclipse.smarthome.core:0.10.0.201808211930]
	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-08-22 22:15:59.522 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2018-08-22 22:16:03.148 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2018-08-22 22:16:03.186 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2018-08-22 22:16:03.218 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
3951

Hmm. After updating to the snapshot binding, I have a problem with a Vision PIR (model ZP3102).
I can not get it to report Alarm. Binary works fine though…

In the settings under wakeup configuration, I can not choose Controller (or OpenHab). I can however choose Node 1 (or any other number). Is Node 1 equal to OpenHab?
Under associate I can choose Controller, which I believe is correct, right?

3952

Node 1 in a standard setup should be the zwave controller.

3953

I am a bit confused here.
For the ZP3102 Vision Motion and temperatur sensor. I´m not able to choose OpenHab.
EDIT - Correction, I can choose Controller or Node under Association. I can not choose OpenHab.

See screenshot:

zwave%20VisionPIR1
zwave VisionPIR1.png1915×1088 82.9 KB

3954

It appears to be added, but it is incomplete. I added comments to the device, but I am unable to edit it. It is identical to DZ6HD just the wattage is different. Is there any way to force the device to use the same profile?

3955

I can not get the Alarm channel to trigger for both my zwave sensors. They worked fine with binding 2.3.0. After updating to latest snapshot, Alarm channel no longer trigger. Binary channel works fine though.
This applies to Vision PIR ZP3102 as well as Neo Coolcam (the one without temperature sensor).