LED Light not turning off with ZWave control

[kdsnet3410 (Kevin S)]

The next test was done my liking a dimmer and turning the value to 100 then back to 0.

2019-11-07 17:21:02.629 [ome.event.ItemCommandEvent] - Item 'TestBench_Dimmer' received command ON

2019-11-07 17:21:02.660 [nt.ItemStatePredictedEvent] - TestBench_Dimmer predicted to become ON

2019-11-07 17:21:02.690 [vent.ItemStateChangedEvent] - TestBench_Dimmer changed from 0 to 100

==> /var/log/openhab2/openhab.log <==

2019-11-07 17:21:02.699 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Command received zwave:device:54aea7e5:node85:switch_dimmer --> ON [OnOffType]

2019-11-07 17:21:02.702 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 85: Creating new message for command SWITCH_MULTILEVEL_SET

2019-11-07 17:21:02.705 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL

2019-11-07 17:21:02.707 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2019-11-07 17:21:02.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Adding to device queue

2019-11-07 17:21:02.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Added 6846 to queue - size 3

2019-11-07 17:21:02.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:02.720 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 55 03 26 01 FF 25 E3 AE 

2019-11-07 17:21:02.724 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 85: Sending REQUEST Message = 01 0A 00 13 55 03 26 01 FF 25 E3 AE 

2019-11-07 17:21:02.727 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-11-07 17:21:02.730 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6846: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 227

2019-11-07 17:21:02.731 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-11-07 17:21:02.734 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling initialised at 86400 seconds - start in 1500 milliseconds.

2019-11-07 17:21:02.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:02.741 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:02.743 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6846: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 227

2019-11-07 17:21:02.747 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-11-07 17:21:02.749 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:02.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:21:02.755 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-11-07 17:21:02.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:02.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:02.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6846: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 227

2019-11-07 17:21:02.769 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E3 00 00 02 0A 

2019-11-07 17:21:02.772 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:02.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6846: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 227

2019-11-07 17:21:02.779 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:02.782 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: sentData successfully placed on stack.

2019-11-07 17:21:02.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=227, payload=E3 00 00 02 

2019-11-07 17:21:02.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6846: Advanced to WAIT_REQUEST

2019-11-07 17:21:02.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6846: Transaction not completed

2019-11-07 17:21:02.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=227, payload=E3 00 00 02 

2019-11-07 17:21:02.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6846: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 227

2019-11-07 17:21:02.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:02.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6846: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 227

2019-11-07 17:21:02.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 6846: (Callback 227)

2019-11-07 17:21:02.810 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-11-07 17:21:02.814 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 6846: callback 227

2019-11-07 17:21:02.817 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=227, payload=E3 00 00 02 

2019-11-07 17:21:02.820 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: SendData Request. CallBack ID = 227, Status = Transmission complete and ACK received(0)

2019-11-07 17:21:02.823 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:02.825 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6846: Transaction COMPLETED

2019-11-07 17:21:02.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Response processed after 97ms

2019-11-07 17:21:02.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6846: Transaction completed

2019-11-07 17:21:02.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: notifyTransactionResponse TID:6846 DONE

2019-11-07 17:21:02.840 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-11-07 17:21:02.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:02.845 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:02.856 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 55 03 20 03 63 E4 

2019-11-07 17:21:02.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 03 20 03 63 

2019-11-07 17:21:02.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 03 20 03 63 

2019-11-07 17:21:02.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-11-07 17:21:02.887 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Application Command Request (ALIVE:DONE)

2019-11-07 17:21:02.891 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:02.894 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Incoming command class COMMAND_CLASS_BASIC, endpoint 0

2019-11-07 17:21:02.896 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_BASIC

2019-11-07 17:21:02.914 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 85: Received COMMAND_CLASS_BASIC V1 BASIC_REPORT

2019-11-07 17:21:02.917 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 85: Basic report, value = 99

2019-11-07 17:21:02.920 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2019-11-07 17:21:02.923 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=99

2019-11-07 17:21:02.927 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Updating channel state zwave:device:54aea7e5:node85:switch_dimmer to 100 [PercentType]

2019-11-07 17:21:02.933 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Commands processed 1.

2019-11-07 17:21:02.938 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@12725c6.

2019-11-07 17:21:02.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:21:02.944 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:21:02.947 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:02.951 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:04.235 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling...

2019-11-07 17:21:04.239 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling zwave:device:54aea7e5:node85:switch_dimmer

2019-11-07 17:21:04.242 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 85: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2019-11-07 17:21:04.245 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 85: Creating new message for command SWITCH_MULTILEVEL_GET

2019-11-07 17:21:04.248 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL

2019-11-07 17:21:04.251 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2019-11-07 17:21:04.254 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling skipped for zwave:device:54aea7e5:node85:switch_dimmer on COMMAND_CLASS_BASIC

2019-11-07 17:21:04.257 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling zwave:device:54aea7e5:node85:scene_number

2019-11-07 17:21:04.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Adding to device queue

2019-11-07 17:21:04.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Added 6847 to queue - size 3

2019-11-07 17:21:04.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:04.271 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 55 02 26 02 25 E4 57 

2019-11-07 17:21:04.275 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 85: Sending REQUEST Message = 01 09 00 13 55 02 26 02 25 E4 57 

2019-11-07 17:21:04.279 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-11-07 17:21:04.282 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-11-07 17:21:04.283 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6847: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 228

2019-11-07 17:21:04.286 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:04.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:04.292 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-11-07 17:21:04.292 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6847: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 228

2019-11-07 17:21:04.297 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-11-07 17:21:04.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:04.300 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:04.303 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:21:04.307 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:04.310 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E4 00 00 02 0D 

2019-11-07 17:21:04.311 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6847: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 228

2019-11-07 17:21:04.313 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:04.316 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6847: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 228

2019-11-07 17:21:04.319 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=228, payload=E4 00 00 02 

2019-11-07 17:21:04.321 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:04.323 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: sentData successfully placed on stack.

2019-11-07 17:21:04.326 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6847: Advanced to WAIT_REQUEST

2019-11-07 17:21:04.327 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 55 05 26 03 63 63 00 85 

2019-11-07 17:21:04.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6847: Transaction not completed

2019-11-07 17:21:04.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=228, payload=E4 00 00 02 

2019-11-07 17:21:04.334 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6847: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 228

2019-11-07 17:21:04.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:04.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 05 26 03 63 63 00 

2019-11-07 17:21:04.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6847: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 228

2019-11-07 17:21:04.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 6847: (Callback 228)

2019-11-07 17:21:04.345 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-11-07 17:21:04.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 6847: callback 228

2019-11-07 17:21:04.350 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=228, payload=E4 00 00 02 

2019-11-07 17:21:04.352 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: SendData Request. CallBack ID = 228, Status = Transmission complete and ACK received(0)

2019-11-07 17:21:04.355 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:04.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6847: Advanced to WAIT_DATA

2019-11-07 17:21:04.360 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6847: Transaction not completed

2019-11-07 17:21:04.363 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 05 26 03 63 63 00 

2019-11-07 17:21:04.365 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-11-07 17:21:04.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Application Command Request (ALIVE:DONE)

2019-11-07 17:21:04.370 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:04.373 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2019-11-07 17:21:04.375 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL

2019-11-07 17:21:04.377 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 85: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT

2019-11-07 17:21:04.380 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 85: Switch Multi Level report, value = 99

2019-11-07 17:21:04.382 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2019-11-07 17:21:04.385 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=99

2019-11-07 17:21:04.388 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Updating channel state zwave:device:54aea7e5:node85:switch_dimmer to 100 [PercentType]

2019-11-07 17:21:04.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Commands processed 1.

2019-11-07 17:21:04.398 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@637544.

2019-11-07 17:21:04.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@637544.

2019-11-07 17:21:04.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: notifyTransactionResponse TID:6847 DONE

2019-11-07 17:21:04.412 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-11-07 17:21:04.414 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2019-11-07 17:21:04.417 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:21:04.422 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:04.425 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:04.531 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 74: Polling...

2019-11-07 17:21:04.534 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 74: Polling zwave:device:54aea7e5:node74:switch_binary

2019-11-07 17:21:04.539 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 74: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 0

2019-11-07 17:21:04.542 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 74: Creating new message for application command SWITCH_BINARY_GET

2019-11-07 17:21:04.547 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 74: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY

2019-11-07 17:21:04.550 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 74: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured

2019-11-07 17:21:04.554 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 74: Polling skipped for zwave:device:54aea7e5:node74:switch_binary on COMMAND_CLASS_BASIC

2019-11-07 17:21:04.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 74: Adding to device queue

2019-11-07 17:21:04.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 74: Added 6848 to queue - size 3

2019-11-07 17:21:04.565 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:04.571 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 4A 02 25 02 25 E5 4A 

2019-11-07 17:21:04.575 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 74: Sending REQUEST Message = 01 09 00 13 4A 02 25 02 25 E5 4A 

2019-11-07 17:21:04.579 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-11-07 17:21:04.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6848: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 229

2019-11-07 17:21:04.583 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-11-07 17:21:04.588 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:04.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:04.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6848: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 229

2019-11-07 17:21:04.597 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-11-07 17:21:04.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-11-07 17:21:04.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:04.605 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:04.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:21:04.613 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:04.617 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6848: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 229

2019-11-07 17:21:04.620 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:04.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6848: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 229

2019-11-07 17:21:04.628 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:04.632 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E5 00 00 05 0B 

2019-11-07 17:21:04.632 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 74: sentData successfully placed on stack.

2019-11-07 17:21:04.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6848: Advanced to WAIT_REQUEST

2019-11-07 17:21:04.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=229, payload=E5 00 00 05 

2019-11-07 17:21:04.642 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 74: TID 6848: Transaction not completed

2019-11-07 17:21:04.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=229, payload=E5 00 00 05 

2019-11-07 17:21:04.649 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6848: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 229

2019-11-07 17:21:04.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:04.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6848: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 229

2019-11-07 17:21:04.659 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 6848: (Callback 229)

2019-11-07 17:21:04.662 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-11-07 17:21:04.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 6848: callback 229

2019-11-07 17:21:04.669 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=229, payload=E5 00 00 05 

2019-11-07 17:21:04.673 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 74: SendData Request. CallBack ID = 229, Status = Transmission complete and ACK received(0)

2019-11-07 17:21:04.676 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 74: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:04.680 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6848: Advanced to WAIT_DATA

2019-11-07 17:21:04.683 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 74: TID 6848: Transaction not completed

2019-11-07 17:21:04.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:04.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:21:04.708 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 4A 03 25 03 00 9D 

2019-11-07 17:21:04.713 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=74, callback=0, payload=00 4A 03 25 03 00 

2019-11-07 17:21:04.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=74, callback=0, payload=00 4A 03 25 03 00 

2019-11-07 17:21:04.720 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-11-07 17:21:04.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 74: Application Command Request (ALIVE:DONE)

2019-11-07 17:21:04.726 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 74: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:04.729 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 75: Polling...

2019-11-07 17:21:04.729 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 74: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0

2019-11-07 17:21:04.731 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 75: Polling zwave:device:54aea7e5:node75:switch_binary

2019-11-07 17:21:04.731 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 74: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY

2019-11-07 17:21:04.735 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 75: Generating poll message for COMMAND_CLASS_SWITCH_BINARY, endpoint 0

2019-11-07 17:21:04.735 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 74: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT

2019-11-07 17:21:04.738 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 74: Switch Binary report, value = 0

2019-11-07 17:21:04.739 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 75: Creating new message for application command SWITCH_BINARY_GET

2019-11-07 17:21:04.742 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 74: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2019-11-07 17:21:04.742 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 75: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY

2019-11-07 17:21:04.745 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 74: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_BINARY, value=0

2019-11-07 17:21:04.745 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 75: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured

2019-11-07 17:21:04.749 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 74: Updating channel state zwave:device:54aea7e5:node74:switch_binary to OFF [OnOffType]

2019-11-07 17:21:04.749 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 75: Polling skipped for zwave:device:54aea7e5:node75:switch_binary on COMMAND_CLASS_BASIC

2019-11-07 17:21:04.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: Adding to device queue

2019-11-07 17:21:04.757 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 74: Commands processed 1.

2019-11-07 17:21:04.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: Added 6849 to queue - size 3

2019-11-07 17:21:04.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 74: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1928314.

2019-11-07 17:21:04.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:21:04.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 74: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1928314.

2019-11-07 17:21:04.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 74: notifyTransactionResponse TID:6848 DONE

2019-11-07 17:21:04.774 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 74: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-11-07 17:21:04.778 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2019-11-07 17:21:04.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:21:04.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:04.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:04.794 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 4B 02 25 02 25 E6 48 

2019-11-07 17:21:04.799 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 75: Sending REQUEST Message = 01 09 00 13 4B 02 25 02 25 E6 48 

2019-11-07 17:21:04.803 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-11-07 17:21:04.805 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-11-07 17:21:04.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:04.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6849: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 230

2019-11-07 17:21:04.813 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-11-07 17:21:04.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:04.816 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6849: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 230

2019-11-07 17:21:04.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:04.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-11-07 17:21:04.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:04.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6849: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 230

2019-11-07 17:21:04.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:04.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6849: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 230

2019-11-07 17:21:04.840 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:04.844 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 75: sentData successfully placed on stack.

2019-11-07 17:21:04.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6849: Advanced to WAIT_REQUEST

2019-11-07 17:21:04.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: TID 6849: Transaction not completed

2019-11-07 17:21:04.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:04.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:21:04.893 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E6 00 00 08 05 

2019-11-07 17:21:04.898 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 08 

2019-11-07 17:21:04.902 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 08 

2019-11-07 17:21:04.906 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6849: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 230

2019-11-07 17:21:04.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:04.913 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6849: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 230

2019-11-07 17:21:04.917 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 6849: (Callback 230)

2019-11-07 17:21:04.921 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-11-07 17:21:04.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 6849: callback 230

2019-11-07 17:21:04.945 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 08 

2019-11-07 17:21:04.948 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 75: SendData Request. CallBack ID = 230, Status = Transmission complete and ACK received(0)

2019-11-07 17:21:04.952 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 75: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:04.955 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6849: Advanced to WAIT_DATA

2019-11-07 17:21:04.958 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: TID 6849: Transaction not completed

2019-11-07 17:21:04.961 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:04.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:21:04.973 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 4B 03 25 03 00 9C 

2019-11-07 17:21:04.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=75, callback=0, payload=00 4B 03 25 03 00 

2019-11-07 17:21:04.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=75, callback=0, payload=00 4B 03 25 03 00 

2019-11-07 17:21:04.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-11-07 17:21:04.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: Application Command Request (ALIVE:DONE)

2019-11-07 17:21:04.995 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 75: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:04.998 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 75: Incoming command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0

2019-11-07 17:21:05.003 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 75: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY

2019-11-07 17:21:05.006 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 75: Received COMMAND_CLASS_SWITCH_BINARY V1 SWITCH_BINARY_REPORT

2019-11-07 17:21:05.010 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 75: Switch Binary report, value = 0

2019-11-07 17:21:05.016 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 75: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2019-11-07 17:21:05.021 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 75: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_BINARY, value=0

2019-11-07 17:21:05.029 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 75: Updating channel state zwave:device:54aea7e5:node75:switch_binary to OFF [OnOffType]

2019-11-07 17:21:05.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: Commands processed 1.

2019-11-07 17:21:05.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1398f3d.

2019-11-07 17:21:05.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1398f3d.

2019-11-07 17:21:05.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 75: notifyTransactionResponse TID:6849 DONE

2019-11-07 17:21:05.052 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 75: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-11-07 17:21:05.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2019-11-07 17:21:05.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:21:05.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:05.065 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

==> /var/log/openhab2/events.log <==

2019-11-07 17:21:08.674 [ome.event.ItemCommandEvent] - Item 'TestBench_Dimmer' received command OFF

2019-11-07 17:21:08.718 [nt.ItemStatePredictedEvent] - TestBench_Dimmer predicted to become OFF

2019-11-07 17:21:08.736 [vent.ItemStateChangedEvent] - TestBench_Dimmer changed from 100 to 0

==> /var/log/openhab2/openhab.log <==

2019-11-07 17:21:08.743 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Command received zwave:device:54aea7e5:node85:switch_dimmer --> OFF [OnOffType]

2019-11-07 17:21:08.746 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 85: Creating new message for command SWITCH_MULTILEVEL_SET

2019-11-07 17:21:08.748 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL

2019-11-07 17:21:08.751 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2019-11-07 17:21:08.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Adding to device queue

2019-11-07 17:21:08.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Added 6850 to queue - size 3

2019-11-07 17:21:08.762 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:08.768 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 55 03 26 01 00 25 E7 55 

2019-11-07 17:21:08.774 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 85: Sending REQUEST Message = 01 0A 00 13 55 03 26 01 00 25 E7 55 

2019-11-07 17:21:08.778 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-11-07 17:21:08.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6850: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 231

2019-11-07 17:21:08.783 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

'''

[kdsnet3410 (Kevin S)]

2019-11-07 17:21:08.789 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:08.794 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:08.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6850: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 231

2019-11-07 17:21:08.798 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-11-07 17:21:08.802 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-11-07 17:21:08.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:08.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:21:08.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:08.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:08.819 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E7 00 00 02 0E 

2019-11-07 17:21:08.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6850: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 231

2019-11-07 17:21:08.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:08.830 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 02 

2019-11-07 17:21:08.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6850: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 231

2019-11-07 17:21:08.838 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:08.844 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: sentData successfully placed on stack.

2019-11-07 17:21:08.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6850: Advanced to WAIT_REQUEST

2019-11-07 17:21:08.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6850: Transaction not completed

2019-11-07 17:21:08.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 02 

2019-11-07 17:21:08.859 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6850: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 231

2019-11-07 17:21:08.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:08.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6850: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 231

2019-11-07 17:21:08.869 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 55 03 20 03 00 87 

2019-11-07 17:21:08.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 6850: (Callback 231)

2019-11-07 17:21:08.876 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-11-07 17:21:08.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 03 20 03 00 

2019-11-07 17:21:08.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 6850: callback 231

2019-11-07 17:21:08.883 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 02 

2019-11-07 17:21:08.887 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: SendData Request. CallBack ID = 231, Status = Transmission complete and ACK received(0)

2019-11-07 17:21:08.890 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:08.893 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6850: Transaction COMPLETED

2019-11-07 17:21:08.896 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Response processed after 115ms

2019-11-07 17:21:08.899 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6850: Transaction completed

2019-11-07 17:21:08.903 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: notifyTransactionResponse TID:6850 DONE

2019-11-07 17:21:08.907 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-11-07 17:21:08.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 03 20 03 00 

2019-11-07 17:21:08.913 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-11-07 17:21:08.917 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Application Command Request (ALIVE:DONE)

2019-11-07 17:21:08.922 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:08.925 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Incoming command class COMMAND_CLASS_BASIC, endpoint 0

2019-11-07 17:21:08.927 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_BASIC

2019-11-07 17:21:08.931 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 85: Received COMMAND_CLASS_BASIC V1 BASIC_REPORT

2019-11-07 17:21:08.935 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 85: Basic report, value = 0

2019-11-07 17:21:08.938 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2019-11-07 17:21:08.942 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0

2019-11-07 17:21:08.947 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Updating channel state zwave:device:54aea7e5:node85:switch_dimmer to 0 [PercentType]

2019-11-07 17:21:08.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Commands processed 1.

2019-11-07 17:21:08.957 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1968649.

2019-11-07 17:21:08.959 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:21:08.962 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:21:08.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:08.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:10.288 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling...

2019-11-07 17:21:10.291 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling zwave:device:54aea7e5:node85:switch_dimmer

2019-11-07 17:21:10.293 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 85: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2019-11-07 17:21:10.296 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 85: Creating new message for command SWITCH_MULTILEVEL_GET

2019-11-07 17:21:10.299 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL

2019-11-07 17:21:10.302 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2019-11-07 17:21:10.304 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling skipped for zwave:device:54aea7e5:node85:switch_dimmer on COMMAND_CLASS_BASIC

2019-11-07 17:21:10.307 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling zwave:device:54aea7e5:node85:scene_number

2019-11-07 17:21:10.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Adding to device queue

2019-11-07 17:21:10.313 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Added 6851 to queue - size 3

2019-11-07 17:21:10.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:21:10.320 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 55 02 26 02 25 E8 5B 

2019-11-07 17:21:10.324 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 85: Sending REQUEST Message = 01 09 00 13 55 02 26 02 25 E8 5B 

2019-11-07 17:21:10.327 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-11-07 17:21:10.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6851: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 232

2019-11-07 17:21:10.330 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-11-07 17:21:10.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:10.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:21:10.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6851: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 232

2019-11-07 17:21:10.341 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-11-07 17:21:10.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-11-07 17:21:10.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:10.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:10.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:21:10.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:10.353 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E8 00 00 02 01 

2019-11-07 17:21:10.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6851: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 232

2019-11-07 17:21:10.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:10.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=232, payload=E8 00 00 02 

2019-11-07 17:21:10.359 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6851: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 232

2019-11-07 17:21:10.362 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:21:10.365 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: sentData successfully placed on stack.

2019-11-07 17:21:10.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6851: Advanced to WAIT_REQUEST

2019-11-07 17:21:10.369 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 55 05 26 03 00 00 00 85 

2019-11-07 17:21:10.371 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6851: Transaction not completed

2019-11-07 17:21:10.373 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=232, payload=E8 00 00 02 

2019-11-07 17:21:10.376 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6851: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 232

2019-11-07 17:21:10.376 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 05 26 03 00 00 00 

2019-11-07 17:21:10.379 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:21:10.381 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6851: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 232

2019-11-07 17:21:10.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 6851: (Callback 232)

2019-11-07 17:21:10.388 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-11-07 17:21:10.390 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 6851: callback 232

2019-11-07 17:21:10.392 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=232, payload=E8 00 00 02 

2019-11-07 17:21:10.395 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: SendData Request. CallBack ID = 232, Status = Transmission complete and ACK received(0)

2019-11-07 17:21:10.398 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:10.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6851: Advanced to WAIT_DATA

2019-11-07 17:21:10.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6851: Transaction not completed

2019-11-07 17:21:10.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 05 26 03 00 00 00 

2019-11-07 17:21:10.407 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-11-07 17:21:10.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Application Command Request (ALIVE:DONE)

2019-11-07 17:21:10.413 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:21:10.415 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0

2019-11-07 17:21:10.417 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL

2019-11-07 17:21:10.420 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 85: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT

2019-11-07 17:21:10.422 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 85: Switch Multi Level report, value = 0

2019-11-07 17:21:10.424 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2019-11-07 17:21:10.427 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=0

2019-11-07 17:21:10.430 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Updating channel state zwave:device:54aea7e5:node85:switch_dimmer to 0 [PercentType]

2019-11-07 17:21:10.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Commands processed 1.

2019-11-07 17:21:10.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@861b2a.

2019-11-07 17:21:10.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@861b2a.

2019-11-07 17:21:10.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: notifyTransactionResponse TID:6851 DONE

2019-11-07 17:21:10.446 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-11-07 17:21:10.449 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2019-11-07 17:21:10.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:21:10.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:21:10.456 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

The final test was done by linking a binary switch and turning the device ON then OFF

2019-11-07 17:35:07.143 [ome.event.ItemCommandEvent] - Item 'TestBench_Switch' received command ON

2019-11-07 17:35:07.222 [nt.ItemStatePredictedEvent] - TestBench_Switch predicted to become ON

2019-11-07 17:35:07.257 [vent.ItemStateChangedEvent] - TestBench_Switch changed from OFF to ON

==> /var/log/openhab2/openhab.log <==

2019-11-07 17:35:07.265 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Command received zwave:device:54aea7e5:node85:switch_dimmer --> ON [OnOffType]

2019-11-07 17:35:07.271 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 85: Creating new message for command SWITCH_MULTILEVEL_SET

2019-11-07 17:35:07.275 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL

2019-11-07 17:35:07.280 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2019-11-07 17:35:07.285 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Adding to device queue

2019-11-07 17:35:07.289 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Added 6862 to queue - size 3

2019-11-07 17:35:07.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:35:07.296 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 55 03 26 01 FF 25 F3 BE 

2019-11-07 17:35:07.300 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 85: Sending REQUEST Message = 01 0A 00 13 55 03 26 01 FF 25 F3 BE 

2019-11-07 17:35:07.304 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-11-07 17:35:07.307 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-11-07 17:35:07.307 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6862: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 243

2019-11-07 17:35:07.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:35:07.310 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling initialised at 86400 seconds - start in 1500 milliseconds.

2019-11-07 17:35:07.313 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:35:07.316 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6862: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 243

2019-11-07 17:35:07.316 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-11-07 17:35:07.322 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:35:07.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-11-07 17:35:07.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:35:07.336 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 F3 00 00 02 1A 

2019-11-07 17:35:07.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6862: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 243

2019-11-07 17:35:07.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=243, payload=F3 00 00 02 

2019-11-07 17:35:07.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:35:07.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6862: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 243

2019-11-07 17:35:07.364 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:35:07.369 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: sentData successfully placed on stack.

2019-11-07 17:35:07.371 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6862: Advanced to WAIT_REQUEST

2019-11-07 17:35:07.374 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6862: Transaction not completed

2019-11-07 17:35:07.377 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=243, payload=F3 00 00 02 

2019-11-07 17:35:07.380 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6862: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 243

2019-11-07 17:35:07.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:35:07.385 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6862: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 243

2019-11-07 17:35:07.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 6862: (Callback 243)
2019-11-07 17:35:07.391 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-11-07 17:35:07.393 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 6862: callback 243

2019-11-07 17:35:07.397 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=243, payload=F3 00 00 02 

2019-11-07 17:35:07.400 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: SendData Request. CallBack ID = 243, Status = Transmission complete and ACK received(0)

2019-11-07 17:35:07.402 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:35:07.401 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 55 03 20 03 63 E4 

2019-11-07 17:35:07.405 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6862: Transaction COMPLETED

2019-11-07 17:35:07.409 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Response processed after 102ms

2019-11-07 17:35:07.412 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6862: Transaction completed

2019-11-07 17:35:07.414 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: notifyTransactionResponse TID:6862 DONE

2019-11-07 17:35:07.418 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-11-07 17:35:07.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 03 20 03 63 

2019-11-07 17:35:07.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:35:07.424 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:35:07.428 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 03 20 03 63 

2019-11-07 17:35:07.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-11-07 17:35:07.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Application Command Request (ALIVE:DONE)

2019-11-07 17:35:07.437 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:35:07.440 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Incoming command class COMMAND_CLASS_BASIC, endpoint 0

2019-11-07 17:35:07.442 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_BASIC

2019-11-07 17:35:07.445 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 85: Received COMMAND_CLASS_BASIC V1 BASIC_REPORT

2019-11-07 17:35:07.448 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 85: Basic report, value = 99

2019-11-07 17:35:07.451 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2019-11-07 17:35:07.453 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=99

2019-11-07 17:35:07.457 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Updating channel state zwave:device:54aea7e5:node85:switch_dimmer to 100 [PercentType]

2019-11-07 17:35:07.462 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Commands processed 1.

2019-11-07 17:35:07.465 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@cb72db.

2019-11-07 17:35:07.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:35:07.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:35:07.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:35:07.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:35:08.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@31c8e6

2019-11-07 17:35:08.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 13424 to queue - size 1

2019-11-07 17:35:08.322 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:35:08.326 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 2A 90 

2019-11-07 17:35:08.331 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 04 00 41 2A 90 

2019-11-07 17:35:08.335 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 13424: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0

2019-11-07 17:35:08.810 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling...

2019-11-07 17:35:09.074 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1e73091

2019-11-07 17:35:09.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 13425 to queue - size 1

2019-11-07 17:35:09.081 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:35:10.338 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 13424: Timeout at state WAIT_RESPONSE. 3 retries remaining.

2019-11-07 17:35:10.340 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 13424: Transaction is current transaction, so clearing!!!!!

2019-11-07 17:35:10.343 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13424: Transaction CANCELLED

2019-11-07 17:35:10.345 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:13424 CANCELLED

2019-11-07 17:35:10.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:35:10.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 13424: Transaction event listener: DONE: CANCELLED -> 

2019-11-07 17:35:10.352 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 07 BD 

2019-11-07 17:35:10.353 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 42: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@16ccdd2

2019-11-07 17:35:10.355 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Port closed sending REQUEST Message = 01 04 00 41 07 BD 

2019-11-07 17:35:10.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 13425: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0

==> /var/log/openhab2/events.log <==

2019-11-07 17:35:12.113 [ome.event.ItemCommandEvent] - Item 'TestBench_Switch' received command OFF

2019-11-07 17:35:12.146 [nt.ItemStatePredictedEvent] - TestBench_Switch predicted to become OFF

2019-11-07 17:35:12.169 [vent.ItemStateChangedEvent] - TestBench_Switch changed from ON to OFF

==> /var/log/openhab2/openhab.log <==

2019-11-07 17:35:12.183 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Command received zwave:device:54aea7e5:node85:switch_dimmer --> OFF [OnOffType]

2019-11-07 17:35:12.187 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 85: Creating new message for command SWITCH_MULTILEVEL_SET

2019-11-07 17:35:12.191 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL

2019-11-07 17:35:12.194 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured

2019-11-07 17:35:12.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Adding to device queue

2019-11-07 17:35:12.200 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Added 6863 to queue - size 3

2019-11-07 17:35:12.203 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:35:12.208 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 55 03 26 01 00 25 F4 46 

2019-11-07 17:35:12.212 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 85: Sending REQUEST Message = 01 0A 00 13 55 03 26 01 00 25 F4 46 

2019-11-07 17:35:12.216 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-11-07 17:35:12.219 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 6863: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 244

2019-11-07 17:35:12.221 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-11-07 17:35:12.223 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling initialised at 86400 seconds - start in 1500 milliseconds.

2019-11-07 17:35:12.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:35:12.232 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-11-07 17:35:12.235 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6863: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 244

2019-11-07 17:35:12.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-11-07 17:35:12.239 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-11-07 17:35:12.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:35:12.246 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:35:12.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:35:12.255 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 F4 00 00 02 1D 

2019-11-07 17:35:12.260 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:35:12.262 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6863: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 244

2019-11-07 17:35:12.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:35:12.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6863: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 244

2019-11-07 17:35:12.270 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-11-07 17:35:12.270 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=244, payload=F4 00 00 02 

2019-11-07 17:35:12.273 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: sentData successfully placed on stack.

2019-11-07 17:35:12.276 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 6863: Advanced to WAIT_REQUEST

2019-11-07 17:35:12.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6863: Transaction not completed

2019-11-07 17:35:12.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:35:12.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-11-07 17:35:12.289 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=244, payload=F4 00 00 02 

2019-11-07 17:35:12.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 6863: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 244

2019-11-07 17:35:12.294 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-11-07 17:35:12.296 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 6863: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 244

2019-11-07 17:35:12.299 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 6863: (Callback 244)

2019-11-07 17:35:12.301 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-11-07 17:35:12.307 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 55 03 20 03 00 87 

2019-11-07 17:35:12.312 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 6863: callback 244

2019-11-07 17:35:12.315 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=244, payload=F4 00 00 02 

2019-11-07 17:35:12.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 03 20 03 00 

2019-11-07 17:35:12.317 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 85: SendData Request. CallBack ID = 244, Status = Transmission complete and ACK received(0)

2019-11-07 17:35:12.320 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:35:12.322 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 6863: Transaction COMPLETED

2019-11-07 17:35:12.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Response processed after 105ms

2019-11-07 17:35:12.327 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: TID 6863: Transaction completed

2019-11-07 17:35:12.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: notifyTransactionResponse TID:6863 DONE

2019-11-07 17:35:12.332 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-11-07 17:35:12.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=85, callback=0, payload=00 55 03 20 03 00 

2019-11-07 17:35:12.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-11-07 17:35:12.340 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Application Command Request (ALIVE:DONE)

2019-11-07 17:35:12.343 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: resetResendCount initComplete=true isDead=false

2019-11-07 17:35:12.345 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: Incoming command class COMMAND_CLASS_BASIC, endpoint 0

2019-11-07 17:35:12.348 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 85: SECURITY NOT required on COMMAND_CLASS_BASIC

2019-11-07 17:35:12.350 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 85: Received COMMAND_CLASS_BASIC V1 BASIC_REPORT

2019-11-07 17:35:12.352 [DEBUG] [.commandclass.ZWaveBasicCommandClass] - NODE 85: Basic report, value = 0

2019-11-07 17:35:12.355 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2019-11-07 17:35:12.357 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0

2019-11-07 17:35:12.361 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 13425: Timeout at state WAIT_RESPONSE. 3 retries remaining.

2019-11-07 17:35:12.363 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 13425: Transaction is current transaction, so clearing!!!!!

2019-11-07 17:35:12.362 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Updating channel state zwave:device:54aea7e5:node85:switch_dimmer to 0 [PercentType]

2019-11-07 17:35:12.365 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 13425: Transaction CANCELLED

2019-11-07 17:35:12.368 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Commands processed 1.

2019-11-07 17:35:12.367 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:13425 CANCELLED

2019-11-07 17:35:12.370 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 85: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@35a19d.

2019-11-07 17:35:12.372 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:35:12.375 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-11-07 17:35:12.377 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-11-07 17:35:12.380 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:35:12.381 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-11-07 17:35:12.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 13425: Transaction event listener: DONE: CANCELLED -> 

2019-11-07 17:35:12.392 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 7: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1fbff8b

2019-11-07 17:35:13.723 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Polling...

I also measured the current draw through the device. When the device is turned off by pressing the switch the current draw is ~70 mA. When the device is turned off through openHAB the current draw is 80 mA. That would explain why a single LED can remain slightly illuminated. If I change the in incandescent lamp there is still the 10 mA of excess draw, its just not visible on the light.