[SOLVED] Z-Wave-Dimmer: no update when triggering with physical switch

Hello,
I am using a Fibaro Dimmer 2 to controll my main lights.

It is working perfect so far… there is only one problem: I don’t get an update if I use the physical switch connected to the device. It always stays in the most recent state known to openhab.

I am (now) using openHAB 2.5.0 Build #1502

Here are the Logs when triggering within openHAB:

2019-01-19 14:56:33.546 [ome.event.ItemCommandEvent] - Item 'LR_Light_Switch' received command ON

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

2019-01-19 14:56:33.552 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:d5d05bd6:node4:switch_dimmer1 --> ON [OnOffType]

2019-01-19 14:56:33.555 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 4: Creating new message for command SWITCH_MULTILEVEL_SET

2019-01-19 14:56:33.558 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Encapsulating message, instance / endpoint 1

2019-01-19 14:56:33.560 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 4: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1

2019-01-19 14:56:33.562 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL

2019-01-19 14:56:33.564 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured

2019-01-19 14:56:33.567 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue

2019-01-19 14:56:33.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added 44 to queue - size 1

2019-01-19 14:56:33.571 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-19 14:56:33.574 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 04 07 60 0D 01 01 26 01 FF 25 30 41 

2019-01-19 14:56:33.577 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 0E 00 13 04 07 60 0D 01 01 26 01 FF 25 30 41 

2019-01-19 14:56:33.580 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-01-19 14:56:33.582 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-01-19 14:56:33.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 44: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 48

2019-01-19 14:56:33.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:33.585 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling intialised at 86400 seconds - start in 1500 milliseconds.

2019-01-19 14:56:33.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:33.589 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 44: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 48

2019-01-19 14:56:33.589 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-01-19 14:56:33.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-01-19 14:56:33.591 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:33.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:33.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:33.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:33.597 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 44: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 48

2019-01-19 14:56:33.599 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:33.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 44: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 48

2019-01-19 14:56:33.602 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:33.605 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: sentData successfully placed on stack.

2019-01-19 14:56:33.606 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 30 00 00 02 D9 

2019-01-19 14:56:33.607 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 44: Advanced to WAIT_REQUEST

2019-01-19 14:56:33.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 44: Transaction not completed

2019-01-19 14:56:33.609 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=48, payload=30 00 00 02 

2019-01-19 14:56:33.610 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:33.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:33.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=48, payload=30 00 00 02 

2019-01-19 14:56:33.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 44: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 48

2019-01-19 14:56:33.618 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:33.620 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 44: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 48

2019-01-19 14:56:33.621 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 44: (Callback 48)

2019-01-19 14:56:33.623 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-01-19 14:56:33.625 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 44: callback 48

2019-01-19 14:56:33.627 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=48, payload=30 00 00 02 

2019-01-19 14:56:33.629 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 48, Status = Transmission complete and ACK received(0)

2019-01-19 14:56:33.631 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: resetResendCount initComplete=true isDead=false

2019-01-19 14:56:33.633 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 44: Transaction COMPLETED

2019-01-19 14:56:33.634 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Response processed after 52ms

2019-01-19 14:56:33.635 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 44: Transaction completed

2019-01-19 14:56:33.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:44 DONE

2019-01-19 14:56:33.637 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-01-19 14:56:33.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:33.642 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

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

2019-01-19 14:56:34.895 [vent.ItemStateChangedEvent] - Gateway_AmbientLight changed from 622 to 504

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

2019-01-19 14:56:35.085 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling...

2019-01-19 14:56:35.088 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling zwave:device:d5d05bd6:node4:switch_dimmer1

2019-01-19 14:56:35.090 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 4: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1

2019-01-19 14:56:35.091 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 4: Creating new message for command SWITCH_MULTILEVEL_GET

2019-01-19 14:56:35.093 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Encapsulating message, instance / endpoint 1

2019-01-19 14:56:35.095 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 4: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1

2019-01-19 14:56:35.097 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL

2019-01-19 14:56:35.099 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured

2019-01-19 14:56:35.101 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Polling skipped for zwave:device:d5d05bd6:node4:switch_dimmer1 on COMMAND_CLASS_BASIC

2019-01-19 14:56:35.103 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Adding to device queue

2019-01-19 14:56:35.105 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Added 45 to queue - size 1

2019-01-19 14:56:35.107 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-19 14:56:35.110 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 04 06 60 0D 01 01 26 02 25 31 BE 

2019-01-19 14:56:35.115 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 0D 00 13 04 06 60 0D 01 01 26 02 25 31 BE 

2019-01-19 14:56:35.117 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-01-19 14:56:35.120 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-01-19 14:56:35.119 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 45: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 49

2019-01-19 14:56:35.122 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:35.124 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:35.125 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 45: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 49

2019-01-19 14:56:35.127 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-01-19 14:56:35.127 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-01-19 14:56:35.129 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:35.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:35.130 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:35.133 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:35.135 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 45: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 49

2019-01-19 14:56:35.136 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:35.138 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 45: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 49

2019-01-19 14:56:35.140 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:35.142 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: sentData successfully placed on stack.

2019-01-19 14:56:35.144 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 31 00 00 02 D8 

2019-01-19 14:56:35.144 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 45: Advanced to WAIT_REQUEST

2019-01-19 14:56:35.146 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 45: Transaction not completed

2019-01-19 14:56:35.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:35.148 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=49, payload=31 00 00 02 

2019-01-19 14:56:35.149 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:35.153 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=49, payload=31 00 00 02 

2019-01-19 14:56:35.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 45: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 49

2019-01-19 14:56:35.156 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:35.156 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 04 07 60 0D 01 01 26 03 63 DE 

2019-01-19 14:56:35.158 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 45: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 49

2019-01-19 14:56:35.160 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 45: (Callback 49)

2019-01-19 14:56:35.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=4, callback=0, payload=00 04 07 60 0D 01 01 26 03 63 

2019-01-19 14:56:35.162 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-01-19 14:56:35.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 45: callback 49

2019-01-19 14:56:35.166 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=49, payload=31 00 00 02 

2019-01-19 14:56:35.168 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 49, Status = Transmission complete and ACK received(0)

2019-01-19 14:56:35.170 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: resetResendCount initComplete=true isDead=false

2019-01-19 14:56:35.172 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 45: Advanced to WAIT_DATA

2019-01-19 14:56:35.173 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: TID 45: Transaction not completed

2019-01-19 14:56:35.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=4, callback=0, payload=00 04 07 60 0D 01 01 26 03 63 

2019-01-19 14:56:35.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-01-19 14:56:35.179 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Application Command Request (ALIVE:DONE)

2019-01-19 14:56:35.181 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: resetResendCount initComplete=true isDead=false

2019-01-19 14:56:35.183 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Decapsulating COMMAND_CLASS_MULTI_CHANNEL

2019-01-19 14:56:35.185 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1

2019-01-19 14:56:35.187 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL

2019-01-19 14:56:35.188 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 4: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT

2019-01-19 14:56:35.190 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 4: Switch Multi Level report, value = 99

2019-01-19 14:56:35.193 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2019-01-19 14:56:35.195 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 99

2019-01-19 14:56:35.197 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:d5d05bd6:node4:switch_dimmer1 to 100 [PercentType]

2019-01-19 14:56:35.201 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Commands processed 1.

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

2019-01-19 14:56:35.211 [vent.ItemStateChangedEvent] - LR_Light_Switch changed from OFF to ON

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

2019-01-19 14:56:35.211 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@4f6872.

2019-01-19 14:56:35.214 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@4f6872.

2019-01-19 14:56:35.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: notifyTransactionResponse TID:45 DONE

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

2019-01-19 14:56:35.221 [GroupItemStateChangedEvent] - gMainLighting changed from OFF to ON through LR_Light_Switch

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

2019-01-19 14:56:35.226 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

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

2019-01-19 14:56:35.228 [vent.ItemStateChangedEvent] - LR_Dimmer_Brightness changed from 0 to 100

2019-01-19 14:56:35.235 [GroupItemStateChangedEvent] - gLighting changed from OFF to ON through gMainLighting

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

2019-01-19 14:56:35.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1

2019-01-19 14:56:35.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0

2019-01-19 14:56:35.241 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:35.242 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-19 14:56:48.677 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: ZWaveCommandClassTransactionPayload - send to node

2019-01-19 14:56:48.680 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: SECURITY not supported

2019-01-19 14:56:48.682 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Command Class COMMAND_CLASS_NO_OPERATION is NOT required to be secured

2019-01-19 14:56:48.684 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@d53c73

2019-01-19 14:56:48.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue

2019-01-19 14:56:48.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 46 to queue - size 1

2019-01-19 14:56:48.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-19 14:56:48.696 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 03 01 00 25 32 F1 

2019-01-19 14:56:48.699 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 08 00 13 03 01 00 25 32 F1 

2019-01-19 14:56:48.702 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-01-19 14:56:48.705 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-01-19 14:56:48.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:48.708 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:48.708 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 50

2019-01-19 14:56:48.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-01-19 14:56:48.711 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-01-19 14:56:48.712 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:48.714 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:48.714 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-01-19 14:56:48.717 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:48.720 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:48.723 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 50

2019-01-19 14:56:48.725 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:48.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 50

2019-01-19 14:56:48.730 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:48.733 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.

2019-01-19 14:56:48.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 46: Advanced to WAIT_REQUEST

2019-01-19 14:56:48.738 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 46: Transaction not completed

2019-01-19 14:56:48.740 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:48.743 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:48.846 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 32 01 00 0E D6 

2019-01-19 14:56:48.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=50, payload=32 01 00 0E 

2019-01-19 14:56:48.850 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=50, payload=32 01 00 0E 

2019-01-19 14:56:48.851 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 46: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 50

2019-01-19 14:56:48.852 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:48.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 46: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 50

2019-01-19 14:56:48.855 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 46: (Callback 50)

2019-01-19 14:56:48.857 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-01-19 14:56:48.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 46: callback 50

2019-01-19 14:56:48.859 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=50, payload=32 01 00 0E 

2019-01-19 14:56:48.860 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 50, Status = Transmission complete, no ACK received(1)

2019-01-19 14:56:48.862 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 46: Transaction CANCELLED

2019-01-19 14:56:48.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: CANCEL while sending message. Requeueing - 2 attempts left!

2019-01-19 14:56:48.864 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 46: Transaction RESET with 2 retries remaining.

2019-01-19 14:56:48.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue

2019-01-19 14:56:48.867 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 46 to queue - size 1

2019-01-19 14:56:48.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-19 14:56:48.870 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 03 01 00 25 33 F0 

2019-01-19 14:56:48.871 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 08 00 13 03 01 00 25 33 F0 

2019-01-19 14:56:48.873 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-01-19 14:56:48.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 51

2019-01-19 14:56:48.875 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-01-19 14:56:48.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 46: Transaction not completed

2019-01-19 14:56:48.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:48.877 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:48.879 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:48.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:48.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 51

2019-01-19 14:56:48.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-01-19 14:56:48.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:48.884 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-01-19 14:56:48.885 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:48.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:48.889 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:48.890 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 51

2019-01-19 14:56:48.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:48.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 51

2019-01-19 14:56:48.894 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:48.896 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.

2019-01-19 14:56:48.897 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 46: Advanced to WAIT_REQUEST

2019-01-19 14:56:48.898 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 46: Transaction not completed

2019-01-19 14:56:48.899 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:48.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:49.017 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 33 01 00 0E D7 

2019-01-19 14:56:49.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=51, payload=33 01 00 0E 

2019-01-19 14:56:49.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=51, payload=33 01 00 0E 

2019-01-19 14:56:49.022 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 46: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 51

2019-01-19 14:56:49.023 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:49.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 46: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 51

2019-01-19 14:56:49.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 46: (Callback 51)

2019-01-19 14:56:49.027 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-01-19 14:56:49.028 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 46: callback 51

2019-01-19 14:56:49.030 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=51, payload=33 01 00 0E 

2019-01-19 14:56:49.031 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 51, Status = Transmission complete, no ACK received(1)

2019-01-19 14:56:49.032 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 46: Transaction CANCELLED

2019-01-19 14:56:49.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: CANCEL while sending message. Requeueing - 1 attempts left!

2019-01-19 14:56:49.035 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 46: Transaction RESET with 1 retries remaining.

2019-01-19 14:56:49.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Adding to device queue

2019-01-19 14:56:49.037 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Added 46 to queue - size 1

2019-01-19 14:56:49.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-19 14:56:49.040 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 13 03 01 00 25 34 F7 

2019-01-19 14:56:49.042 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 3: Sending REQUEST Message = 01 08 00 13 03 01 00 25 34 F7 

2019-01-19 14:56:49.043 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-01-19 14:56:49.045 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-01-19 14:56:49.046 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:49.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 52

2019-01-19 14:56:49.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 46: Transaction not completed

2019-01-19 14:56:49.050 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-19 14:56:49.051 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 52

2019-01-19 14:56:49.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-01-19 14:56:49.053 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:49.055 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 

2019-01-19 14:56:49.055 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:49.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:49.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:49.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 52

2019-01-19 14:56:49.060 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:49.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 46: [WAIT_RESPONSE] priority=Poll, requiresResponse=true, callback: 52

2019-01-19 14:56:49.063 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 

2019-01-19 14:56:49.064 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: sentData successfully placed on stack.

2019-01-19 14:56:49.065 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 46: Advanced to WAIT_REQUEST

2019-01-19 14:56:49.067 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 46: Transaction not completed

2019-01-19 14:56:49.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:49.069 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-19 14:56:49.172 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 34 01 00 0D D3 

2019-01-19 14:56:49.174 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=1, callback=52, payload=34 01 00 0D 

2019-01-19 14:56:49.175 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=1, callback=52, payload=34 01 00 0D 

2019-01-19 14:56:49.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 46: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 52

2019-01-19 14:56:49.178 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-19 14:56:49.179 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 46: [WAIT_REQUEST] priority=Poll, requiresResponse=true, callback: 52

2019-01-19 14:56:49.180 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 46: (Callback 52)

2019-01-19 14:56:49.182 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-01-19 14:56:49.183 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 46: callback 52

2019-01-19 14:56:49.184 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=1, callback=52, payload=34 01 00 0D 

2019-01-19 14:56:49.186 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 3: SendData Request. CallBack ID = 52, Status = Transmission complete, no ACK received(1)

2019-01-19 14:56:49.187 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 46: Transaction CANCELLED

2019-01-19 14:56:49.188 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Retry count exceeded. Discarding message: TID 46: [CANCELLED] priority=Poll, requiresResponse=true, callback: 52

2019-01-19 14:56:49.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 46: Transaction completed

2019-01-19 14:56:49.191 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:46 CANCELLED

2019-01-19 14:56:49.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-19 14:56:49.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 46: Transaction event listener: DONE: CANCELLED -> 

2019-01-19 14:56:49.194 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-19 14:56:49.198 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1255036

Anyone got an idea what I am doing wrong?

Thanks in advance
Joe

Although this should have been already set by the binding, set your Lifeline association group to your controller.

1 Like

Ok, that was easy.
Thank you very much!

1 Like