Z-Wave Binding: No status update from Fibaro Roller Shutter 3 FGR223

HABuser · February 9, 2019, 12:05am

Hi there,
i tried the Fibaro Roller Shutter 3 FGR223 with openHAB 2.4 with Zwave binding snapshot 2.5 build from yesterday. I’d like to share my experience i got so far.
Inclusion, exclusion, calibration and controlling the blinds with blinds control items (instead of dimmers) works as expected. Thanks to everyone who makes this possible.
But there is one big problem with status updates and position feedback which makes this device nearly unusable in a home automation environment.
If the blind is moved by zwave command and reaches the target position, the controller receives no update about the new position. If the blind is moved by the hardware switches S1/S2, the controller doesn’t perceive the move. I can not be sure about the current position at any time.

I captured some debug lines while moving the blind from 0% to 78%


00:59:02.343 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'ZWaveNode012FGR223RollerShutter3Kueche_Dimmer' received command 78
00:59:02.356 [INFO ] [arthome.event.ItemStatePredictedEvent] - ZWaveNode012FGR223RollerShutter3Kueche_Dimmer predicted to become 78
00:59:02.370 [INFO ] [smarthome.event.ItemStateChangedEvent] - ZWaveNode012FGR223RollerShutter3Kueche_Dimmer changed from 34 to 78
00:59:02.370 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Command received zwave:device:ad3f9d85:node12:switch_dimmer --> 78 [PercentType]
00:59:02.386 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 12: Creating new message for command SWITCH_MULTILEVEL_SET
00:59:02.398 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
00:59:02.405 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
00:59:02.412 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
00:59:02.419 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Added 183 to queue - size 1
00:59:02.427 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
00:59:02.438 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0C 03 26 01 4E 25 9E 3B 
00:59:02.447 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 26 01 4E 25 9E 3B 
00:59:02.455 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
00:59:02.458 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
00:59:02.464 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
00:59:02.465 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
00:59:02.468 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
00:59:02.474 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
00:59:02.478 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
00:59:02.482 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
00:59:02.485 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 183: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 158
00:59:02.491 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
00:59:02.491 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling intialised at 86400 seconds - start in 1000 milliseconds.
00:59:02.512 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
00:59:02.518 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 9E 00 00 02 00 BE 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 D7 
00:59:02.523 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
00:59:02.526 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 183: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 158
00:59:02.531 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
00:59:02.535 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 183: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 158
00:59:02.540 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
00:59:02.545 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
00:59:02.550 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 183: Advanced to WAIT_REQUEST
00:59:02.553 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=158, payload=9E 00 00 02 00 BE 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
00:59:02.557 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: TID 183: Transaction not completed
00:59:02.563 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=158, payload=9E 00 00 02 00 BE 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
00:59:02.569 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 183: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 158
00:59:02.573 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
00:59:02.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 183: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 158
00:59:02.583 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 183: (Callback 158)
00:59:02.589 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
00:59:02.593 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 183: callback 158
00:59:02.598 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=158, payload=9E 00 00 02 00 BE 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
00:59:02.603 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 158, Status = Transmission complete and ACK received(0)
00:59:02.608 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
00:59:02.611 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 183: Transaction COMPLETED
00:59:02.618 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Response processed after 133ms
00:59:02.623 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: TID 183: Transaction completed
00:59:02.627 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:183 DONE
00:59:02.631 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
00:59:02.635 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
00:59:02.638 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
00:59:03.491 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling...
00:59:03.499 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling zwave:device:ad3f9d85:node12:switch_dimmer
00:59:03.507 [DEBUG] [verter.ZWaveMultiLevelSwitchConverter] - NODE 12: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
00:59:03.513 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 12: Creating new message for command SWITCH_MULTILEVEL_GET
00:59:03.522 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
00:59:03.528 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
00:59:03.535 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling zwave:device:ad3f9d85:node12:switch_dimmer1
00:59:03.542 [DEBUG] [verter.ZWaveMultiLevelSwitchConverter] - NODE 12: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1
00:59:03.549 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 12: Creating new message for command SWITCH_MULTILEVEL_GET
00:59:03.556 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: Encapsulating message, instance / endpoint 1
00:59:03.560 [DEBUG] [dclass.ZWaveMultiInstanceCommandClass] - NODE 12: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
00:59:03.563 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
00:59:03.568 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
00:59:03.571 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
00:59:03.575 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Added 184 to queue - size 1
00:59:03.579 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
00:59:03.585 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0C 02 26 02 25 9F 75 
00:59:03.589 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 09 00 13 0C 02 26 02 25 9F 75 
00:59:03.595 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
00:59:03.600 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
00:59:03.604 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
00:59:03.610 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
00:59:03.610 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
00:59:03.616 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
00:59:03.621 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
00:59:03.622 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
00:59:03.628 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 184: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 159
00:59:03.629 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
00:59:03.633 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
00:59:03.641 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Added 185 to queue - size 1
00:59:03.643 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 9F 00 00 02 00 BF 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 D7 
00:59:03.645 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
00:59:03.652 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
00:59:03.658 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
00:59:03.664 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 184: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 159
00:59:03.668 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
00:59:03.673 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 184: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 159
00:59:03.678 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
00:59:03.683 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=159, payload=9F 00 00 02 00 BF 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
00:59:03.683 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
00:59:03.691 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 184: Advanced to WAIT_REQUEST
00:59:03.691 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 0C 05 26 03 07 4E 0B BF 00 27 
00:59:03.696 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: TID 184: Transaction not completed
00:59:03.704 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=159, payload=9F 00 00 02 00 BF 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
00:59:03.711 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 184: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 159
00:59:03.716 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
00:59:03.720 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 184: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 159
00:59:03.725 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 184: (Callback 159)
00:59:03.730 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
00:59:03.733 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 05 26 03 07 4E 0B BF 00 
00:59:03.735 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 184: callback 159
00:59:03.743 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=159, payload=9F 00 00 02 00 BF 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
00:59:03.748 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 159, Status = Transmission complete and ACK received(0)
00:59:03.751 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
00:59:03.755 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 184: Advanced to WAIT_DATA
00:59:03.759 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: TID 184: Transaction not completed
00:59:03.763 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 05 26 03 07 4E 0B BF 00 
00:59:03.767 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
00:59:03.771 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:DONE)
00:59:03.776 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
00:59:03.779 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
00:59:03.783 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
00:59:03.788 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
00:59:03.792 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 12: Switch Multi Level report, value = 7
00:59:03.797 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
00:59:03.801 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 7
00:59:03.805 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating channel state zwave:device:ad3f9d85:node12:switch_dimmer to 7 [PercentType]
00:59:03.810 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1.
00:59:03.814 [INFO ] [smarthome.event.ItemStateChangedEvent] - ZWaveNode012FGR223RollerShutter3Kueche_Dimmer changed from 78 to 7
00:59:03.819 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1c5fb72.
00:59:03.826 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1c5fb72.
00:59:03.833 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:184 DONE
00:59:03.839 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
00:59:03.844 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
00:59:03.848 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
00:59:03.853 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
00:59:03.858 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
00:59:03.865 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 0C 06 60 0D 01 01 26 02 25 A0 27 
00:59:03.870 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0D 00 13 0C 06 60 0D 01 01 26 02 25 A0 27 
00:59:03.877 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
00:59:03.881 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
00:59:03.887 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
00:59:03.902 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
00:59:03.905 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 185: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 160
00:59:03.909 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
00:59:03.913 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 185: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 160
00:59:03.917 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
00:59:03.920 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
00:59:03.924 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
00:59:03.932 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
00:59:03.936 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
00:59:03.938 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 A0 00 00 02 00 BF 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 E8 
00:59:03.940 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 185: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 160
00:59:03.946 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
00:59:03.950 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 185: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 160
00:59:03.954 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
00:59:03.957 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
00:59:03.961 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 185: Advanced to WAIT_REQUEST
00:59:03.964 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: TID 185: Transaction not completed
00:59:03.968 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
00:59:03.974 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=160, payload=A0 00 00 02 00 BF 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
00:59:03.979 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
00:59:03.981 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 11 00 04 00 0C 09 60 0D 01 01 26 03 09 4E 0B BF 00 54 
00:59:03.985 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=160, payload=A0 00 00 02 00 BF 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
00:59:03.990 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 185: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 160
00:59:03.994 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
00:59:04.000 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 185: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 160
00:59:04.004 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 185: (Callback 160)
00:59:04.009 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
00:59:04.013 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 185: callback 160
00:59:04.017 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 09 60 0D 01 01 26 03 09 4E 0B BF 00 
00:59:04.019 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=160, payload=A0 00 00 02 00 BF 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
00:59:04.026 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 160, Status = Transmission complete and ACK received(0)
00:59:04.030 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
00:59:04.035 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 185: Advanced to WAIT_DATA
00:59:04.039 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: TID 185: Transaction not completed
00:59:04.045 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 09 60 0D 01 01 26 03 09 4E 0B BF 00 
00:59:04.050 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
00:59:04.055 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:DONE)
00:59:04.059 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
00:59:04.064 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
00:59:04.068 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1
00:59:04.072 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
00:59:04.077 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
00:59:04.081 [DEBUG] [ass.ZWaveMultiLevelSwitchCommandClass] - NODE 12: Switch Multi Level report, value = 9
00:59:04.086 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
00:59:04.091 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 9
00:59:04.096 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating channel state zwave:device:ad3f9d85:node12:switch_dimmer1 to 9 [PercentType]
00:59:04.102 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1.
00:59:04.106 [INFO ] [smarthome.event.ItemStateChangedEvent] - ZWaveNode012FGR223RollerShutter3Kueche_Dimmer1 changed from 32 to 9
00:59:04.113 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@f0b223.
00:59:04.121 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@f0b223.
00:59:04.126 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:185 DONE
00:59:04.132 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
00:59:04.137 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
00:59:04.141 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
00:59:04.145 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
00:59:04.149 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

The movement takes about 12 seconds but at the end comes no update with the 78% position.

HABuser · February 10, 2019, 9:12pm

In the meantime i activated the energy meter in the FGR223 to examine the behavior of this kind of status messages. While i’m not able to evaluate this, it shows that status messages are possible in general.
But the the status message for the reached position at the end of a movement is still absent.

2019-02-10 20:53:22.778 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Command received zwave:device:ad3f9d85:node12:blinds_control --> 50 [PercentType]
2019-02-10 20:53:22.780 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 12: Creating new message for command SWITCH_MULTILEVEL_SET
2019-02-10 20:53:22.782 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2019-02-10 20:53:22.784 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-02-10 20:53:22.786 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-02-10 20:53:22.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 174 to queue - size 1
2019-02-10 20:53:22.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-02-10 20:53:22.792 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0C 03 26 01 32 25 95 4C 
2019-02-10 20:53:22.795 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 26 01 32 25 95 4C 
2019-02-10 20:53:22.800 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-02-10 20:53:22.802 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-02-10 20:53:22.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-02-10 20:53:22.805 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-02-10 20:53:22.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-10 20:53:22.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-02-10 20:53:22.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 20:53:22.824 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-02-10 20:53:22.826 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 174: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 149
2019-02-10 20:53:22.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-10 20:53:22.828 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling intialised at 86400 seconds - start in 1500 milliseconds.
2019-02-10 20:53:22.854 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-10 20:53:22.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-10 20:53:22.858 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 174: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 149
2019-02-10 20:53:22.859 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 95 00 00 02 00 C6 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 A4 
2019-02-10 20:53:22.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-02-10 20:53:22.862 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 174: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 149
2019-02-10 20:53:22.865 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-10 20:53:22.867 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
2019-02-10 20:53:22.870 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 174: Advanced to WAIT_REQUEST
2019-02-10 20:53:22.872 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 174: Transaction not completed
2019-02-10 20:53:22.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 20:53:22.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-10 20:53:22.885 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=149, payload=95 00 00 02 00 C6 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2019-02-10 20:53:22.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=149, payload=95 00 00 02 00 C6 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2019-02-10 20:53:22.890 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 174: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 149
2019-02-10 20:53:22.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-02-10 20:53:22.894 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 174: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 149
2019-02-10 20:53:22.896 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 174: (Callback 149)
2019-02-10 20:53:22.898 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-02-10 20:53:22.900 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 174: callback 149
2019-02-10 20:53:22.902 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=149, payload=95 00 00 02 00 C6 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2019-02-10 20:53:22.904 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 149, Status = Transmission complete and ACK received(0)
2019-02-10 20:53:22.907 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-02-10 20:53:22.908 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 174: Transaction COMPLETED
2019-02-10 20:53:22.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Response processed after 84ms
2019-02-10 20:53:22.912 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 174: Transaction completed
2019-02-10 20:53:22.914 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:174 DONE
2019-02-10 20:53:22.916 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-02-10 20:53:22.919 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 20:53:22.920 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-02-10 20:53:24.329 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling...
2019-02-10 20:53:24.333 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Polling zwave:device:ad3f9d85:node12:blinds_control
2019-02-10 20:53:24.337 [DEBUG] [erter.ZWaveMultiLevelSwitchConverter] - NODE 12: Generating poll message for COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-02-10 20:53:24.340 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 12: Creating new message for command SWITCH_MULTILEVEL_GET
2019-02-10 20:53:24.344 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2019-02-10 20:53:24.347 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2019-02-10 20:53:24.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-02-10 20:53:24.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 175 to queue - size 1
2019-02-10 20:53:24.362 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-02-10 20:53:24.366 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 0C 02 26 02 25 96 7C 
2019-02-10 20:53:24.372 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 09 00 13 0C 02 26 02 25 96 7C 
2019-02-10 20:53:24.378 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-02-10 20:53:24.382 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-02-10 20:53:24.386 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-02-10 20:53:24.388 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-02-10 20:53:24.389 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-10 20:53:24.392 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-02-10 20:53:24.395 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 20:53:24.404 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-02-10 20:53:24.407 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 175: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 150
2019-02-10 20:53:24.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-10 20:53:24.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-10 20:53:24.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-10 20:53:24.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 175: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 150
2019-02-10 20:53:24.438 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 18 00 13 96 00 00 02 00 C6 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 A7 
2019-02-10 20:53:24.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-02-10 20:53:24.442 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 175: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 150
2019-02-10 20:53:24.444 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-02-10 20:53:24.446 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
2019-02-10 20:53:24.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 175: Advanced to WAIT_REQUEST
2019-02-10 20:53:24.450 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 175: Transaction not completed
2019-02-10 20:53:24.452 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 20:53:24.453 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-10 20:53:24.465 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=150, payload=96 00 00 02 00 C6 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2019-02-10 20:53:24.468 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 0C 05 26 03 0A 32 06 C6 00 22 
2019-02-10 20:53:24.468 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=150, payload=96 00 00 02 00 C6 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2019-02-10 20:53:24.470 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 175: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 150
2019-02-10 20:53:24.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-02-10 20:53:24.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 175: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 150
2019-02-10 20:53:24.476 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 175: (Callback 150)
2019-02-10 20:53:24.478 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-02-10 20:53:24.479 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 175: callback 150
2019-02-10 20:53:24.482 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=150, payload=96 00 00 02 00 C6 7F 7F 7F 7F 00 00 03 00 00 00 00 03 01 00 00 
2019-02-10 20:53:24.484 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 150, Status = Transmission complete and ACK received(0)
2019-02-10 20:53:24.486 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-02-10 20:53:24.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 175: Advanced to WAIT_DATA
2019-02-10 20:53:24.490 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 175: Transaction not completed
2019-02-10 20:53:24.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 20:53:24.494 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-02-10 20:53:24.494 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 05 26 03 0A 32 06 C6 00 
2019-02-10 20:53:24.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 05 26 03 0A 32 06 C6 00 
2019-02-10 20:53:24.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-10 20:53:24.501 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:DONE)
2019-02-10 20:53:24.503 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-02-10 20:53:24.505 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-02-10 20:53:24.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2019-02-10 20:53:24.509 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2019-02-10 20:53:24.511 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 12: Switch Multi Level report, value = 10
2019-02-10 20:53:24.513 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-02-10 20:53:24.515 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 10
2019-02-10 20:53:24.517 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating channel state zwave:device:ad3f9d85:node12:blinds_control to 10 [PercentType]
2019-02-10 20:53:24.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1.
2019-02-10 20:53:24.523 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@62e5.
2019-02-10 20:53:24.525 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@62e5.
2019-02-10 20:53:24.527 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:175 DONE
2019-02-10 20:53:24.530 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-02-10 20:53:24.532 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-02-10 20:53:24.533 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 20:53:24.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 20:53:24.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-02-10 20:53:25.707 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1A 00 04 00 0C 12 56 01 60 0D 01 01 32 02 21 32 06 14 00 00 00 00 12 08 C6 00 28 
2019-02-10 20:53:25.746 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 12 56 01 60 0D 01 01 32 02 21 32 06 14 00 00 00 00 12 08 C6 00 
2019-02-10 20:53:25.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 12 56 01 60 0D 01 01 32 02 21 32 06 14 00 00 00 00 12 08 C6 00 
2019-02-10 20:53:25.756 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-10 20:53:25.758 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:DONE)
2019-02-10 20:53:25.761 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-02-10 20:53:25.763 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_CRC_16_ENCAP
2019-02-10 20:53:25.766 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-02-10 20:53:25.769 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_METER, endpoint 1
2019-02-10 20:53:25.771 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_METER
2019-02-10 20:53:25.774 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_METER V3 METER_REPORT
2019-02-10 20:53:25.777 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Meter: Type=Electric(1), Scale=W(2), Value=155.6
2019-02-10 20:53:25.780 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveMeterValueEvent
2019-02-10 20:53:25.783 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_METER, value = 155.6
2019-02-10 20:53:25.786 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating channel state zwave:device:ad3f9d85:node12:meter_watts1 to 155.6 [DecimalType]
2019-02-10 20:53:25.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1.
2019-02-10 20:53:25.792 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@aefb3f.
2019-02-10 20:53:25.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 20:53:25.798 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 20:53:25.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 20:53:25.803 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-02-10 20:53:33.731 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1A 00 04 00 0C 12 56 01 60 0D 01 01 32 02 21 32 00 06 00 00 00 00 DF 30 C6 00 C9 
2019-02-10 20:53:33.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 12 56 01 60 0D 01 01 32 02 21 32 00 06 00 00 00 00 DF 30 C6 00 
2019-02-10 20:53:33.772 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 12 56 01 60 0D 01 01 32 02 21 32 00 06 00 00 00 00 DF 30 C6 00 
2019-02-10 20:53:33.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-02-10 20:53:33.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:DONE)
2019-02-10 20:53:33.782 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-02-10 20:53:33.785 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_CRC_16_ENCAP
2019-02-10 20:53:33.789 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-02-10 20:53:33.793 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_METER, endpoint 1
2019-02-10 20:53:33.796 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_METER
2019-02-10 20:53:33.799 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_METER V3 METER_REPORT
2019-02-10 20:53:33.802 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 12: Meter: Type=Electric(1), Scale=W(2), Value=0.6
2019-02-10 20:53:33.807 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveMeterValueEvent
2019-02-10 20:53:33.810 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint = 1, command class = COMMAND_CLASS_METER, value = 0.6
2019-02-10 20:53:33.815 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Updating channel state zwave:device:ad3f9d85:node12:meter_watts1 to 0.6 [DecimalType]
2019-02-10 20:53:33.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1.
2019-02-10 20:53:33.822 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5be47a.
2019-02-10 20:53:33.825 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 20:53:33.829 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-02-10 20:53:33.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-02-10 20:53:33.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

sihui · February 11, 2019, 11:45am

Hi @chris, any chance to take a look at this?

The new Fibaro Rollershutter 3 (FGR223) does not report the percentage status when the blinds have been moved.
This may be a general problem with that device because other forums are reporting similar issues (FHEM, open-zwave)

We already discussed this in the German forum but to no avail …

Edit: he is using a recent 2.5 Zwave snapshot binding.

chris · March 3, 2019, 5:12pm

Sorry for the delay - I missed this while I was on holiday…

This looks like a new version of the command class. I will do an update to try and make this work better.

maisen20 · April 12, 2019, 12:13pm

Any news about that?

stedon81 · April 13, 2020, 8:17pm

Hi together,
wanted to warm up this topic, as this is still not resolved.
I have FGR-223 with Firmware 5.1 and have seen most of the issues that have been reported in the various places of this and other forums (FHEM, fibaro, …).

First, it seems that config updates are sometimes not properly sent to the FGR223. I found, that automatic calibration can be indeed triggered from PaperUI, it’s just that the value often is not properly written to the device - similar to other values.
I found that most often it works, if you use the option “reinitialize the device” within HABmin and immediately after change and save the config params. Then, the new values are mostly accepted by the module.

With that, only thing left on my side is this strange percentage reporting behavior that apparently occurs only on sending the “STOP” command. However, it seems that this is not a bug in the firmware. It seems to work for the Fibaro HC2 and all automation solutions (Openhab, FHEM, homeAssistant) that use open zwave have this problem.
They have filed this as bug 1705 but don’t seem to do anything about it.
A user called petergebruers claims that the devices are reporting the percentage value even too frequently, such that open zwave cannot catch up and just reads the first report (which makes the values appear to not change at all).
@chris: Do you think, you can look into this and confirm that this bug is not in the firmware but in open z-wave? Do you see a chance to convince the developers to fix that?

According to a thread in the Fibaro forum many users try to work around this issue by explicitly triggering a device poll within a rule, based on motor energy consumption. Unfortunately, this won’t work with openHAB, as the Z-Wave binding does not offer a manual polling trigger.
However, is there maybe a possibility to temporarily change the polling interval by rule?

Thanks,
stedon81

chris · April 13, 2020, 8:25pm

Sorry, but I have really no influence with OpenZWave so there’s really nothing I can do to help with OZW bugs.

chris · April 13, 2020, 9:27pm

I’ve just re-read this and noticed this comment - openHAB does not use OZW at all - it’s completely separate and there is no link.

stedon81 · April 14, 2020, 8:24am

Hi Chris,

thanks for your answer, I didn’t know and just believed what others wrote in other forums.
Then I’d like to ask you even more insistively to look into this issue - Fibaro and at least this user petergebruers claim that the device is continuously sending percentage reports while the roller is moving. Why don’t we see them in the Z-Wave binding?
And why do we see them only after a poll has been done (either by sending STOP command or reducing the polling interval)?

Regards,
Stefan D.

chris · April 14, 2020, 8:41am

What do you see in the ZWave log? Are these messages being received?

I don’t have this device, so its hard for me to comment. This thread is very old and I’ve not seen any recent logs.

HortusNanum · April 16, 2020, 11:16am

Hi Chris,

I have the same issue with my Fibaro Rollershutter 3. When I move the Rollershutters with OpenHAB (either by rule, PaperUI or App), I get the updated positon right after movement. When I move the shutters by switches, the position is updated the next time the device gets polled (polling period configured to 10min).

Today I enabled DEBUG log and logged this:

The Rollershutter (NODE 20) started at open position (0) and was moved by wall switch.

2020-04-16 11:39:16.162 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 14 0E 60 0D 01 01 32 02 21 32 00 00 00 00 00 00 BB 
2020-04-16 11:39:16.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 60 0D 01 01 32 02 21 32 00 00 00 00 00 00 
2020-04-16 11:39:16.167 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 60 0D 01 01 32 02 21 32 00 00 00 00 00 00 
2020-04-16 11:39:16.168 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:39:16.169 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Application Command Request (ALIVE:DONE)
2020-04-16 11:39:16.170 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:39:16.170 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2020-04-16 11:39:16.171 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Incoming command class COMMAND_CLASS_METER, endpoint 1
2020-04-16 11:39:16.172 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_METER
2020-04-16 11:39:16.172 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 20: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-04-16 11:39:16.173 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 20: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2020-04-16 11:39:16.174 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-04-16 11:39:16.175 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_METER, value=0E+1
2020-04-16 11:39:16.176 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Updating channel state zwave:device:57fa8ae6:node20:meter_watts1 to 0 [DecimalType]
2020-04-16 11:39:16.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Commands processed 1.
2020-04-16 11:39:16.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1b3b5b2.
2020-04-16 11:39:16.178 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:39:16.178 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:39:16.179 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:39:16.179 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-04-16 11:39:17.897 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling...
2020-04-16 11:39:17.898 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling deferred until initialisation complete
2020-04-16 11:39:47.297 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 14 0E 60 0D 01 01 32 02 21 32 02 BD 00 00 00 00 04 
2020-04-16 11:39:47.299 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 60 0D 01 01 32 02 21 32 02 BD 00 00 00 00 
2020-04-16 11:39:47.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 60 0D 01 01 32 02 21 32 02 BD 00 00 00 00 
2020-04-16 11:39:47.303 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:39:47.303 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Application Command Request (ALIVE:DONE)
2020-04-16 11:39:47.304 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:39:47.305 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2020-04-16 11:39:47.306 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Incoming command class COMMAND_CLASS_METER, endpoint 1
2020-04-16 11:39:47.306 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_METER
2020-04-16 11:39:47.307 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 20: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-04-16 11:39:47.308 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 20: Meter: Type=Electric(1), Scale=W(2), Value=70.1
2020-04-16 11:39:47.309 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-04-16 11:39:47.310 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_METER, value=70.1
2020-04-16 11:39:47.311 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Updating channel state zwave:device:57fa8ae6:node20:meter_watts1 to 70.1 [DecimalType]
2020-04-16 11:39:47.311 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Commands processed 1.
2020-04-16 11:39:47.312 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@321b44.
2020-04-16 11:39:47.313 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:39:47.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:39:47.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:39:47.315 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-04-16 11:39:47.898 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling...
2020-04-16 11:39:47.899 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling deferred until initialisation complete
2020-04-16 11:39:53.033 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0F 00 04 00 14 09 60 0D 01 01 26 03 3B 3B FE 5F 
2020-04-16 11:39:53.038 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 09 60 0D 01 01 26 03 3B 3B FE 
2020-04-16 11:39:53.041 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 09 60 0D 01 01 26 03 3B 3B FE 
2020-04-16 11:39:53.042 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:39:53.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Application Command Request (ALIVE:DONE)
2020-04-16 11:39:53.045 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:39:53.046 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2020-04-16 11:39:53.047 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 1
2020-04-16 11:39:53.048 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2020-04-16 11:39:53.049 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 20: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2020-04-16 11:39:53.050 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 20: Switch Multi Level report, value = 59
2020-04-16 11:39:53.053 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2020-04-16 11:39:53.055 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=59
2020-04-16 11:39:53.056 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Updating channel state zwave:device:57fa8ae6:node20:blinds_control1 to 59 [PercentType]
2020-04-16 11:39:53.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Commands processed 1.
2020-04-16 11:39:53.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@179b602.
2020-04-16 11:39:53.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:39:53.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:39:53.063 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:39:53.063 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-04-16 11:39:55.599 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 14 0E 60 0D 01 01 32 02 21 32 00 00 00 00 00 00 BB 
2020-04-16 11:39:55.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 60 0D 01 01 32 02 21 32 00 00 00 00 00 00 
2020-04-16 11:39:55.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 60 0D 01 01 32 02 21 32 00 00 00 00 00 00 
2020-04-16 11:39:55.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:39:55.603 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Application Command Request (ALIVE:DONE)
2020-04-16 11:39:55.605 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:39:55.606 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2020-04-16 11:39:55.609 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Incoming command class COMMAND_CLASS_METER, endpoint 1
2020-04-16 11:39:55.610 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_METER
2020-04-16 11:39:55.610 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 20: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-04-16 11:39:55.611 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 20: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2020-04-16 11:39:55.612 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-04-16 11:39:55.613 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_METER, value=0E+1
2020-04-16 11:39:55.613 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Updating channel state zwave:device:57fa8ae6:node20:meter_watts1 to 0 [DecimalType]
2020-04-16 11:39:55.614 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Commands processed 1.
2020-04-16 11:39:55.615 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1808c9b.
2020-04-16 11:39:55.615 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:39:55.616 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:39:55.617 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:39:55.617 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-04-16 11:40:17.897 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling...
2020-04-16 11:40:17.899 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling deferred until initialisation complete
2020-04-16 11:40:25.542 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 14 0E 60 0D 01 01 32 02 21 32 00 00 00 00 00 00 BB 
2020-04-16 11:40:25.543 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 60 0D 01 01 32 02 21 32 00 00 00 00 00 00 
2020-04-16 11:40:25.545 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 60 0D 01 01 32 02 21 32 00 00 00 00 00 00 
2020-04-16 11:40:25.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:40:25.547 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Application Command Request (ALIVE:DONE)
2020-04-16 11:40:25.548 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:40:25.549 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2020-04-16 11:40:25.550 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Incoming command class COMMAND_CLASS_METER, endpoint 1
2020-04-16 11:40:25.551 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_METER
2020-04-16 11:40:25.554 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 20: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-04-16 11:40:25.555 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 20: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2020-04-16 11:40:25.557 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-04-16 11:40:25.558 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_METER, value=0E+1
2020-04-16 11:40:25.559 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Updating channel state zwave:device:57fa8ae6:node20:meter_watts1 to 0 [DecimalType]
2020-04-16 11:40:25.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Commands processed 1.
2020-04-16 11:40:25.560 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@108bb3c.
2020-04-16 11:40:25.561 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:40:25.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:40:25.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:40:25.563 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-04-16 11:40:47.897 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling...
2020-04-16 11:40:47.898 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Polling deferred until initialisation complete
2020-04-16 11:40:55.030 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 04 0E 32 02 21 44 00 00 07 F8 01 2D 00 00 07 F8 9C 
2020-04-16 11:40:55.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=4, callback=0, payload=00 04 0E 32 02 21 44 00 00 07 F8 01 2D 00 00 07 F8 
2020-04-16 11:40:55.033 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=4, callback=0, payload=00 04 0E 32 02 21 44 00 00 07 F8 01 2D 00 00 07 F8 
2020-04-16 11:40:55.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:40:55.034 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Application Command Request (ALIVE:DONE)
2020-04-16 11:40:55.035 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: resetResendCount initComplete=true isDead=false
2020-04-16 11:40:55.036 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-04-16 11:40:55.036 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported
2020-04-16 11:40:55.037 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 4: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-04-16 11:40:55.038 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 4: Meter: Type=Electric(1), Scale=kWh(0), Value=20.4
2020-04-16 11:40:55.039 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-04-16 11:40:55.040 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=20.4
2020-04-16 11:40:55.041 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:57fa8ae6:node4:meter_kwh to 20.4 [DecimalType]
2020-04-16 11:40:55.042 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Commands processed 1.
2020-04-16 11:40:55.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@14676a2.
2020-04-16 11:40:55.043 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:40:55.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:40:55.045 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:40:55.045 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

The PaperUI still showed the 0 as position. To poll an update of the item, I pressed the “stop” button in PaperUI:

==> /var/log/openhab2/events.log <==
2020-04-16 11:40:56.001 [ome.event.ItemCommandEvent] - Item 'AZ_Rollladen_Schalter' received command STOP
==> /var/log/openhab2/openhab.log <==
2020-04-16 11:40:56.008 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Command received zwave:device:57fa8ae6:node20:blinds_control --> STOP [StopMoveType]
2020-04-16 11:40:56.009 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 20: Creating new message for command SWITCH_MULTILEVEL_STOP_LEVEL_CHANGE
2020-04-16 11:40:56.010 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2020-04-16 11:40:56.010 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2020-04-16 11:40:56.012 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 20: Creating new message for command SWITCH_MULTILEVEL_GET
2020-04-16 11:40:56.016 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2020-04-16 11:40:56.017 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Command Class COMMAND_CLASS_SWITCH_MULTILEVEL is NOT required to be secured
2020-04-16 11:40:56.018 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 04 0E 32 02 21 54 00 00 00 00 01 2D 00 00 00 00 8C 
2020-04-16 11:40:56.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Adding to device queue
2020-04-16 11:40:56.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Added 2925 to queue - size 1
2020-04-16 11:40:56.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-04-16 11:40:56.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=4, callback=0, payload=00 04 0E 32 02 21 54 00 00 00 00 01 2D 00 00 00 00 
2020-04-16 11:40:56.022 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 14 02 26 05 25 61 94 
2020-04-16 11:40:56.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=4, callback=0, payload=00 04 0E 32 02 21 54 00 00 00 00 01 2D 00 00 00 00 
2020-04-16 11:40:56.024 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:40:56.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Application Command Request (ALIVE:DONE)
2020-04-16 11:40:56.025 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: resetResendCount initComplete=true isDead=false
2020-04-16 11:40:56.027 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-04-16 11:40:56.028 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: SECURITY not supported
2020-04-16 11:40:56.027 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 20: Sending REQUEST Message = 01 09 00 13 14 02 26 05 25 61 94 
2020-04-16 11:40:56.029 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-04-16 11:40:56.030 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 4: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-04-16 11:40:56.032 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 4: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2020-04-16 11:40:56.032 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2925: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 97
2020-04-16 11:40:56.034 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-04-16 11:40:56.035 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-04-16 11:40:56.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-16 11:40:56.035 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=0E+1
2020-04-16 11:40:56.037 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Adding to device queue
2020-04-16 11:40:56.037 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Updating channel state zwave:device:57fa8ae6:node4:meter_watts to 0 [DecimalType]
2020-04-16 11:40:56.040 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2020-04-16 11:40:56.041 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:40:56.040 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Commands processed 1.
2020-04-16 11:40:56.042 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Added 2926 to queue - size 1
2020-04-16 11:40:56.044 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 4: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1bb132e.
2020-04-16 11:40:56.045 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:40:56.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2020-04-16 11:40:56.048 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2020-04-16 11:40:56.051 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-16 11:40:56.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2925: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 97
2020-04-16 11:40:56.054 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-04-16 11:40:56.056 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:40:56.057 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2925: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 97
2020-04-16 11:40:56.058 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-16 11:40:56.059 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2925: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 97
2020-04-16 11:40:56.060 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:40:56.061 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: sentData successfully placed on stack.
2020-04-16 11:40:56.062 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2925: Advanced to WAIT_REQUEST
2020-04-16 11:40:56.063 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 2925: Transaction not completed
2020-04-16 11:40:56.073 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:40:56.076 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:40:56.188 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 61 00 00 0F 85 
2020-04-16 11:40:56.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=97, payload=61 00 00 0F 
2020-04-16 11:40:56.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=97, payload=61 00 00 0F 
2020-04-16 11:40:56.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2925: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 97
2020-04-16 11:40:56.195 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-16 11:40:56.196 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2925: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 97
2020-04-16 11:40:56.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 2925: (Callback 97)
2020-04-16 11:40:56.197 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-04-16 11:40:56.197 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 2925: callback 97
2020-04-16 11:40:56.198 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=97, payload=61 00 00 0F 
2020-04-16 11:40:56.199 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: SendData Request. CallBack ID = 97, Status = Transmission complete and ACK received(0)
2020-04-16 11:40:56.201 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:40:56.202 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2925: Transaction COMPLETED
2020-04-16 11:40:56.204 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Response processed after 172ms
2020-04-16 11:40:56.205 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 2925: Transaction completed
2020-04-16 11:40:56.205 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: notifyTransactionResponse TID:2925 DONE
2020-04-16 11:40:56.206 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-04-16 11:40:56.209 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:40:56.209 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-04-16 11:40:56.210 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 14 02 26 02 25 62 90 
2020-04-16 11:40:56.211 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 20: Sending REQUEST Message = 01 09 00 13 14 02 26 02 25 62 90 
2020-04-16 11:40:56.211 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-04-16 11:40:56.212 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2926: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 98
2020-04-16 11:40:56.215 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-04-16 11:40:56.216 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-16 11:40:56.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-16 11:40:56.219 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2926: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 98
2020-04-16 11:40:56.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-04-16 11:40:56.221 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:40:56.222 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2020-04-16 11:40:56.224 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:40:56.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:40:56.226 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:40:56.227 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2926: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 98
2020-04-16 11:40:56.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-16 11:40:56.229 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2926: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 98
2020-04-16 11:40:56.231 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:40:56.232 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: sentData successfully placed on stack.
2020-04-16 11:40:56.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2926: Advanced to WAIT_REQUEST
2020-04-16 11:40:56.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 2926: Transaction not completed
2020-04-16 11:40:56.235 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:40:56.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:40:56.264 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 62 00 00 04 8D 
2020-04-16 11:40:56.264 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=98, payload=62 00 00 04 
2020-04-16 11:40:56.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=98, payload=62 00 00 04 
2020-04-16 11:40:56.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2926: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 98
2020-04-16 11:40:56.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-16 11:40:56.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2926: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 98
2020-04-16 11:40:56.265 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 2926: (Callback 98)
2020-04-16 11:40:56.266 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-04-16 11:40:56.266 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 2926: callback 98
2020-04-16 11:40:56.266 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=98, payload=62 00 00 04 
2020-04-16 11:40:56.266 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: SendData Request. CallBack ID = 98, Status = Transmission complete and ACK received(0)
2020-04-16 11:40:56.267 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:40:56.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2926: Advanced to WAIT_DATA
2020-04-16 11:40:56.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 2926: Transaction not completed
2020-04-16 11:40:56.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:40:56.267 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:40:56.338 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 14 05 26 03 3B 3B FE 3A 
2020-04-16 11:40:56.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 05 26 03 3B 3B FE 
2020-04-16 11:40:56.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 05 26 03 3B 3B FE 
2020-04-16 11:40:56.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:40:56.340 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Application Command Request (ALIVE:DONE)
2020-04-16 11:40:56.340 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:40:56.340 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2020-04-16 11:40:56.340 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_SWITCH_MULTILEVEL
2020-04-16 11:40:56.341 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 20: Received COMMAND_CLASS_SWITCH_MULTILEVEL V3 SWITCH_MULTILEVEL_REPORT
2020-04-16 11:40:56.341 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 20: Switch Multi Level report, value = 59
2020-04-16 11:40:56.341 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2020-04-16 11:40:56.342 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_SWITCH_MULTILEVEL, value=59
2020-04-16 11:40:56.342 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Updating channel state zwave:device:57fa8ae6:node20:blinds_control to 41 [PercentType]
2020-04-16 11:40:56.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Commands processed 1.
==> /var/log/openhab2/events.log <==
2020-04-16 11:40:56.343 [vent.ItemStateChangedEvent] - AZ_Rollladen_Schalter changed from 0 to 41
==> /var/log/openhab2/openhab.log <==
2020-04-16 11:40:56.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3aaf56.
2020-04-16 11:40:56.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@3aaf56.
2020-04-16 11:40:56.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: notifyTransactionResponse TID:2926 DONE
2020-04-16 11:40:56.344 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-04-16 11:40:56.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2020-04-16 11:40:56.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:40:56.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:40:56.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
==> /var/log/openhab2/events.log <==
2020-04-16 11:40:56.345 [GroupItemStateChangedEvent] - gBlinds changed from 0 to UNDEF through AZ_Rollladen_Schalter
2020-04-16 11:40:56.345 [GroupItemStateChangedEvent] - gBlindsHabitableRoom changed from 0 to UNDEF through AZ_Rollladen_Schalter

The post is getting too long for the Forum, so I’ll continue in next post …

HortusNanum · April 16, 2020, 11:16am

Then I opened the shutter again using the wall switch. The PaperUI showed still the 41% position and so and waited for the regular poll period to update the tem position to 0 (~15minutes later):

 2020-04-16 11:57:00.882 [vent.ItemStateChangedEvent] - AZ_Rollladen_Schalter changed from 41 to 0
==> /var/log/openhab2/openhab.log <==
2020-04-16 11:57:00.882 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-04-16 11:57:00.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2938: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 112
==> /var/log/openhab2/events.log <==
2020-04-16 11:57:00.883 [GroupItemStateChangedEvent] - gBlindsHabitableRoom changed from UNDEF to 0 through AZ_Rollladen_Schalter
2020-04-16 11:57:00.883 [GroupItemStateChangedEvent] - gBlinds changed from UNDEF to 0 through AZ_Rollladen_Schalter
==> /var/log/openhab2/openhab.log <==
2020-04-16 11:57:00.885 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-04-16 11:57:00.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-16 11:57:00.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-16 11:57:00.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2938: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 112
2020-04-16 11:57:00.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-04-16 11:57:00.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:57:00.886 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:57:00.892 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2020-04-16 11:57:00.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:57:00.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:57:00.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2938: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 112
2020-04-16 11:57:00.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-16 11:57:00.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2938: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 112
2020-04-16 11:57:00.893 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:57:00.893 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: sentData successfully placed on stack.
2020-04-16 11:57:00.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2938: Advanced to WAIT_REQUEST
2020-04-16 11:57:00.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 2938: Transaction not completed
2020-04-16 11:57:00.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:57:00.893 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:57:00.996 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 70 00 00 0B 90 
2020-04-16 11:57:00.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=112, payload=70 00 00 0B 
2020-04-16 11:57:00.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=112, payload=70 00 00 0B 
2020-04-16 11:57:00.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2938: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 112
2020-04-16 11:57:00.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-16 11:57:00.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2938: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 112
2020-04-16 11:57:00.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 2938: (Callback 112)
2020-04-16 11:57:00.997 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-04-16 11:57:00.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 2938: callback 112
2020-04-16 11:57:00.997 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=112, payload=70 00 00 0B 
2020-04-16 11:57:00.998 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: SendData Request. CallBack ID = 112, Status = Transmission complete and ACK received(0)
2020-04-16 11:57:00.998 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:57:00.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2938: Advanced to WAIT_DATA
2020-04-16 11:57:00.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 2938: Transaction not completed
2020-04-16 11:57:00.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:57:00.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:57:01.235 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 14 0E 32 02 21 44 00 00 00 12 00 00 00 00 00 00 B2 
2020-04-16 11:57:01.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 32 02 21 44 00 00 00 12 00 00 00 00 00 00 
2020-04-16 11:57:01.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0E 32 02 21 44 00 00 00 12 00 00 00 00 00 00 
2020-04-16 11:57:01.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:57:01.236 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Application Command Request (ALIVE:DONE)
2020-04-16 11:57:01.237 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:57:01.237 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-04-16 11:57:01.237 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_METER
2020-04-16 11:57:01.237 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 20: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-04-16 11:57:01.237 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 20: Meter: Type=Electric(1), Scale=kWh(0), Value=0.18
2020-04-16 11:57:01.238 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-04-16 11:57:01.238 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=0.18
2020-04-16 11:57:01.238 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Updating channel state zwave:device:57fa8ae6:node20:meter_kwh to 0.18 [DecimalType]
2020-04-16 11:57:01.238 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Commands processed 1.
2020-04-16 11:57:01.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@d814eb.
2020-04-16 11:57:01.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@d814eb.
2020-04-16 11:57:01.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: notifyTransactionResponse TID:2938 DONE
2020-04-16 11:57:01.239 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-04-16 11:57:01.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2020-04-16 11:57:01.239 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:57:01.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:57:01.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-04-16 11:57:01.240 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 14 03 32 01 10 25 71 86 
2020-04-16 11:57:01.240 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 20: Sending REQUEST Message = 01 0A 00 13 14 03 32 01 10 25 71 86 
2020-04-16 11:57:01.240 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-04-16 11:57:01.241 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2939: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 113
2020-04-16 11:57:01.244 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-04-16 11:57:01.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-16 11:57:01.244 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-04-16 11:57:01.245 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2939: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 113
2020-04-16 11:57:01.245 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-04-16 11:57:01.245 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:57:01.245 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:57:01.251 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2020-04-16 11:57:01.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:57:01.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:57:01.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2939: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 113
2020-04-16 11:57:01.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-16 11:57:01.251 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2939: [WAIT_RESPONSE] priority=Get, requiresResponse=true, callback: 113
2020-04-16 11:57:01.252 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2020-04-16 11:57:01.252 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: sentData successfully placed on stack.
2020-04-16 11:57:01.252 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2939: Advanced to WAIT_REQUEST
2020-04-16 11:57:01.252 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 2939: Transaction not completed
2020-04-16 11:57:01.252 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:57:01.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:57:01.346 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 71 00 00 0A 90 
2020-04-16 11:57:01.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=113, payload=71 00 00 0A 
2020-04-16 11:57:01.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=113, payload=71 00 00 0A 
2020-04-16 11:57:01.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2939: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 113
2020-04-16 11:57:01.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-04-16 11:57:01.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2939: [WAIT_REQUEST] priority=Get, requiresResponse=true, callback: 113
2020-04-16 11:57:01.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 2939: (Callback 113)
2020-04-16 11:57:01.347 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2020-04-16 11:57:01.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 2939: callback 113
2020-04-16 11:57:01.347 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=113, payload=71 00 00 0A 
2020-04-16 11:57:01.347 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 20: SendData Request. CallBack ID = 113, Status = Transmission complete and ACK received(0)
2020-04-16 11:57:01.348 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:57:01.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 2939: Advanced to WAIT_DATA
2020-04-16 11:57:01.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: TID 2939: Transaction not completed
2020-04-16 11:57:01.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:57:01.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-04-16 11:57:01.575 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 14 0A 32 02 21 32 00 00 00 00 00 00 D6 
2020-04-16 11:57:01.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0A 32 02 21 32 00 00 00 00 00 00 
2020-04-16 11:57:01.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=20, callback=0, payload=00 14 0A 32 02 21 32 00 00 00 00 00 00 
2020-04-16 11:57:01.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-04-16 11:57:01.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Application Command Request (ALIVE:DONE)
2020-04-16 11:57:01.577 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: resetResendCount initComplete=true isDead=false
2020-04-16 11:57:01.577 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: Incoming command class COMMAND_CLASS_METER, endpoint 0
2020-04-16 11:57:01.577 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 20: SECURITY NOT required on COMMAND_CLASS_METER
2020-04-16 11:57:01.577 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 20: Received COMMAND_CLASS_METER V3 METER_REPORT
2020-04-16 11:57:01.577 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 20: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2020-04-16 11:57:01.577 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveMeterValueEvent
2020-04-16 11:57:01.578 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_METER, value=0E+1
2020-04-16 11:57:01.578 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Updating channel state zwave:device:57fa8ae6:node20:meter_watts to 0 [DecimalType]
2020-04-16 11:57:01.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Commands processed 1.
2020-04-16 11:57:01.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@19c2a04.
2020-04-16 11:57:01.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@19c2a04.
2020-04-16 11:57:01.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 20: notifyTransactionResponse TID:2939 DONE
2020-04-16 11:57:01.579 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-04-16 11:57:01.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2020-04-16 11:57:01.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2020-04-16 11:57:01.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-04-16 11:57:01.580 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

I hope this helps for debugging the issue.
In my humble opinion it could maybe help if the ZWave Binding would frequently poll the device status when other values (e.g. motor power) change.

If you need get hands on a Rollershutter3 device to solve the issue, I would volunteer to sponsor one. Do you have a public Amazon wishlist where you could put it on? Then I’ll order it for you.

Cheers, Roland

chris · April 16, 2020, 2:24pm

What channel are you using? Is it the “Blinds Control” or “Blinds Control 1”?

HortusNanum · April 16, 2020, 2:50pm

It’s “blinds_control”. This is the item definition:

Rollershutter   AZ_Rollladen_Schalter           "Rollladen [%.0f]"      <blinds>    (gArbeitszimmer,gBlinds,gBlindsHabitableRoom)               {channel="zwave:device:57fa8ae6:node20:blinds_control"}

chris · April 16, 2020, 2:53pm

Try using blinds_control1 instead - that is the channel that is receiving the reports as far as I can tell. If that works ok, then we should remove the blinds_control channel from the database.

CHTHSCH · April 16, 2020, 2:55pm

Dear all,

I am using the FIBARO Roller Shutter since about a year. I think at the end it is no much of a problem.

Example to ensure, that the status is correctly updated:

rule "Status Refresh Jalousie SR"
when
  Item LIV_Jalousie_SR_Leistung1 changed
then
  if (LIV_Jalousie_SR_Leistung1.state == 0) LIV_Jalousie_SR_Schalter1.sendCommand("REFRESH")
end

This can be used for the two relevant “switches” that control the position of the blinds and the lamellas.

I am controlling the blinds with scenes. Example:

rule "Szenen Jalousien Bibliothek"
when
  Item LIB_Jalousie_Szene received command
then
  var Timer tLamellen   = null
  var Timer tRefresh    = null
  switch(receivedCommand.toString) {
// Jalousien schliessen
    case "1": {
      LIB_Jalousie_Lamellen.sendCommand(100)
      LIB_Jalousie.sendCommand(100)
      if ( tRefresh !== null ) {
        tRefresh.cancel
        tRefresh = null
      }
      tRefresh = createTimer(now.plusMinutes(1)) [
        LIB_Jalousie_Lamellen.sendCommand("REFRESH")
        LIB_Jalousie.sendCommand("REFRESH")
      ]
    }
// Jalousien öffnen
    case "2": {
      LIB_Jalousie_Lamellen.sendCommand(0)
      LIB_Jalousie.sendCommand(0)
      if ( tRefresh !== null ) {
        tRefresh.cancel
        tRefresh = null
      }
      tRefresh = createTimer(now.plusMinutes(1)) [
        LIB_Jalousie.sendCommand("REFRESH")
        LIB_Jalousie_Lamellen.sendCommand("REFRESH")
      ]
    }
// Jalousien Sonnenschutz
    case "3": {
      LIB_Jalousie.sendCommand(75)
      if ( tLamellen !== null ) {
        tLamellen.cancel
        tLamellen = null
      }
      tLamellen = createTimer(now.plusMinutes(1)) [ LIB_Jalousie_Lamellen.sendCommand(60) ]
      if ( tRefresh !== null ) {
        tRefresh.cancel
        tRefresh = null
      }
      tRefresh = createTimer(now.plusMinutes(1)) [
        LIB_Jalousie_Lamellen.sendCommand("REFRESH")
        LIB_Jalousie.sendCommand("REFRESH")
      ]
    }
// Jalousien lüften
    case "4": {
      LIB_Jalousie_Lamellen.sendCommand(60)
      if ( tRefresh !== null ) {
        tRefresh.cancel
        tRefresh = null
      }
      tRefresh = createTimer(now.plusMinutes(1)) [ LIB_Jalousie_Lamellen.sendCommand("REFRESH") ]
    }
    default: {
      logInfo("Szenen.rules", "Das Programm sollte nie hier her kommen.\nSzene Jalousie Bibliothek")
    }
  }
end

These scenes are called depending on the time of the day, by selections in the sitemap, by the weather forecast, etc.
Example:

rule "Sonnenschutz Kernzeiten"
when
  Item Azimut changed
then
  var Helligkeit      = ((Sensor1_Illuminance.state as Number).floatValue)
  var int Sonnenstand = (Azimut.state as Number).intValue
  var Winkel          = (Sonnenhoehe.state as Number).floatValue
  if ( Winkel >= 3 && Sonnenstand >= 60 && Sonnenstand <= 155 ) {
    if ( LIV_Sonnenschutz_O.state != ON ) LIV_Sonnenschutz_O.postUpdate(ON)
  } else {
    LIV_Sonnenschutz_O.postUpdate(OFF)
  }
  if ( Winkel >= 3 && Sonnenstand >= 80 && Sonnenstand <= 195 ) {
    if ( LIB_Sonnenschutz.state   != ON ) LIB_Sonnenschutz.postUpdate(ON)
  } else {
    LIB_Sonnenschutz.postUpdate(OFF)
  }
  if ( Winkel >= 3 && Sonnenstand >= 80 && Sonnenstand <= 245 ) {
    if ( LIV_Sonnenschutz_S.state != ON ) LIV_Sonnenschutz_S.postUpdate(ON)
  } else {
    LIV_Sonnenschutz_S.postUpdate(OFF)
  }
  if ( Winkel >= 3 && Sonnenstand >= 80 && Sonnenstand <= 245 ) {
    if ( BED_Sonnenschutz.state   != ON ) BED_Sonnenschutz.postUpdate(ON)
  } else {
    BED_Sonnenschutz.postUpdate(OFF)
  }
  if ( Winkel >= 3 && Sonnenstand >= 260 && Sonnenstand <= 305 ) {
    if ( KUC_Sonnenschutz.state   != ON ) KUC_Sonnenschutz.postUpdate(ON)
  } else {
    KUC_Sonnenschutz.postUpdate(OFF)
  }
end

I hardly use the wall switches anymore. If someone is interested I can post all the rule files.

HortusNanum · April 16, 2020, 3:11pm

Hi Chris,

I quickly changed the item definition to

Rollershutter   KUE_Rollladen_Schalter          "Rollladen [%.0f]"      <blinds>    (gKueche,gBlinds,gBlindsSouth,gBlindsHabitableRoom)         {channel="zwave:device:57fa8ae6:node19:blinds_control"}

and it works like a charm! I always wondered why there are two sets of channels. So it might make sense to remove the channels without the “1”. But this would probably be a breaking change to everybody using these channels.
What is the channel blinds_control2 for?

Many thanks for your help!

Best regards,
Roland

chris · April 16, 2020, 3:26pm

You do not say what software you are using? OH2.4, 2.5? I suspect that it will be different depending on what version you have due to the way endpoints and associations are managed.

chris · April 16, 2020, 3:30pm

Yes, but new users of OH2.5 will find, as you did, that it doesn’t work with the blinds_control channel due to the way that multi channel associations are now used. So, it’s either a breaking change, or just broken

I’m not sure to be honest - I don’t have this device. It will be linked with association group 3, but it’s not clear from the manual exactly how it’s used.

CHTHSCH · April 16, 2020, 6:12pm

I have been using 2.5 - now production release and prior to that I used the snapshots. The RS3 did not work with 2.4