Zwave traffic and rule problem

[Noddy (Norbert Meier)]

Hi,

I’ve a problem with my z-wave network or with a rule (see below).

The 2 switches of WS_BM_TERASSE_01 and the switch of WS_BM_TERASSE_01 are changing their states multpile times after the rule is tiggered.
The rule is triggered more than once although a button on the remote is only pressed once.

The attached log (DEBUG enabled for z-wave binding) shows a lot of traffic regarding these things.
The log is truncated.

Does someone have an idea what could cause these traffic and why the rule is triggered more than once?

Thanks
Norbert

z-wave node id		 	Device type					Thing name 
62				DEVOLO MT2653 Keyfob				RC_01_DEVOLO 
 9				FGWP102 Metered Wall Plug Switch		WP_BM_CARPORT_01
21				FGS223 Double Switch 2				WS_BM_TERASSE_01 

RC_01_DEVOLO Configured to send “central scene to gateway”

The log viewer shows some long runs for some messages and some rejected messages:

2018-08-22 20:21:14.418 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 3E 05 5B 03 F2 00 06 67 
2018-08-22 20:21:14.421 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:14.423 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0B 00 04 00 3E 05 5B 03 F2 00 06 67 
2018-08-22 20:21:14.425 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0B 00 04 00 3E 05 5B 03 F2 00 06 67 
2018-08-22 20:21:14.427 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 3E 05 5B 03 F2 00 06 
2018-08-22 20:21:14.429 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 62: Application Command Request (ALIVE:DONE)
2018-08-22 20:21:14.431 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 62: Starting initialisation from DONE
2018-08-22 20:21:14.432 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1fc41d9 already registered
2018-08-22 20:21:14.434 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 62: Incoming command class CENTRAL_SCENE
2018-08-22 20:21:14.436 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 62: Received CENTRAL_SCENE command V1
2018-08-22 20:21:14.437 [DEBUG] [dclass.ZWaveCentralSceneCommandClass] - NODE 62: Received scene 6 at key 0 [Single Press]
2018-08-22 20:21:14.440 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-08-22 20:21:14.441 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 62: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-08-22 20:21:14.443 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 62: Got a value event from Z-Wave network, endpoint = 0, command class = CENTRAL_SCENE, value = 6.0
2018-08-22 20:21:14.445 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 62: Updating channel state zwave:device:c1f45758:node62:scene_number to 6.0 [DecimalType]
2018-08-22 20:21:14.448 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 35: Transaction not completed: node address inconsistent.  lastSent=35, incoming=255
2018-08-22 20:21:14.471 [INFO ] [ipse.smarthome.model.script.r_RC_001] - rule r_RC_DEVOLO_01_Scene_Number_rcv_upd
                                                                         RC_DEVOLO_01_Scene_Number received command = "6.0"
2018-08-22 20:21:14.492 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Command received zwave:device:c1f45758:node21:switch_binary1 --> OFF
2018-08-22 20:21:14.495 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Creating new message for application command SWITCH_BINARY_SET
2018-08-22 20:21:14.507 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Encapsulating message, instance / endpoint 1
2018-08-22 20:21:14.509 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2018-08-22 20:21:14.511 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2018-08-22 20:21:14.511 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2018-08-22 20:21:14.513 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 15 07 60 0D 01 01 25 01 00 25 26 BA 
2018-08-22 20:21:14.516 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 21: Sending REQUEST Message = 01 0E 00 13 15 07 60 0D 01 01 25 01 00 25 26 BA 
2018-08-22 20:21:14.499 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Command received zwave:device:c1f45758:node9:switch_binary --> OFF
2018-08-22 20:21:14.520 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 9: Creating new message for application command SWITCH_BINARY_SET
2018-08-22 20:21:14.522 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Command received zwave:device:c1f45758:node21:switch_binary2 --> OFF
2018-08-22 20:21:14.527 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Creating new message for application command SWITCH_BINARY_SET
2018-08-22 20:21:14.527 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2018-08-22 20:21:14.529 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Encapsulating message, instance / endpoint 2
2018-08-22 20:21:14.533 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2018-08-22 20:21:14.536 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-08-22 20:21:14.539 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:14.541 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2018-08-22 20:21:14.535 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2018-08-22 20:21:14.543 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2018-08-22 20:21:14.545 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2018-08-22 20:21:14.547 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: Sent Data successfully placed on stack.
2018-08-22 20:21:14.754 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 26 00 00 17 DA 
2018-08-22 20:21:14.758 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:14.760 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 26 00 00 17 00 00 D4 
2018-08-22 20:21:14.762 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 26 00 00 17 00 00 D4 
2018-08-22 20:21:14.764 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=26 00 00 17 
2018-08-22 20:21:14.765 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: SendData Request. CallBack ID = 38, Status = Transmission complete and ACK received(0)
2018-08-22 20:21:14.767 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE
2018-08-22 20:21:14.774 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1b6081d already registered
2018-08-22 20:21:14.776 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=21, callback=38, payload=15 07 60 0D 01 01 25 01 00 
2018-08-22 20:21:14.784 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=26 00 00 17 
2018-08-22 20:21:14.794 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=38, expected=SendData, cancelled=false        transaction complete!
2018-08-22 20:21:14.795 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-08-22 20:21:14.797 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-08-22 20:21:14.809 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 21: Response processed after 291ms/4958ms.
2018-08-22 20:21:14.818 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2018-08-22 20:21:14.820 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 09 03 25 01 00 25 27 CA 
2018-08-22 20:21:14.822 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 9: Sending REQUEST Message = 01 0A 00 13 09 03 25 01 00 25 27 CA 
2018-08-22 20:21:14.833 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-08-22 20:21:14.837 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:14.840 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2018-08-22 20:21:14.844 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2018-08-22 20:21:14.848 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2018-08-22 20:21:14.851 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: Sent Data successfully placed on stack.
2018-08-22 20:21:14.912 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 15 07 60 0D 01 00 25 03 00 AE 
2018-08-22 20:21:14.915 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:14.917 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 04 00 15 07 60 0D 01 00 25 03 00 AE 
2018-08-22 20:21:14.918 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0D 00 04 00 15 07 60 0D 01 00 25 03 00 AE 
2018-08-22 20:21:14.920 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 15 07 60 0D 01 00 25 03 00 
2018-08-22 20:21:14.923 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)
2018-08-22 20:21:14.925 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE
2018-08-22 20:21:14.926 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1b6081d already registered
2018-08-22 20:21:14.928 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE
2018-08-22 20:21:14.929 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2
2018-08-22 20:21:14.931 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)
2018-08-22 20:21:14.932 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.
2018-08-22 20:21:14.934 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 21
2018-08-22 20:21:14.935 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 0
2018-08-22 20:21:14.937 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-08-22 20:21:14.939 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-08-22 20:21:14.940 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_BINARY, value = 0
2018-08-22 20:21:14.942 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary1 to OFF [OnOffType]
2018-08-22 20:21:14.950 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Transaction not completed: node address inconsistent.  lastSent=9, incoming=255
2018-08-22 20:21:18.633 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 27 00 01 7C B1 
2018-08-22 20:21:18.636 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:18.638 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 27 00 01 7C 00 00 BF 
2018-08-22 20:21:18.640 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 27 00 01 7C 00 00 BF 
2018-08-22 20:21:18.641 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=27 00 01 7C 
2018-08-22 20:21:18.643 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: SendData Request. CallBack ID = 39, Status = Transmission complete and ACK received(0)
2018-08-22 20:21:18.644 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Starting initialisation from DONE
2018-08-22 20:21:18.646 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@14fd291 already registered
2018-08-22 20:21:18.648 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=9, callback=39, payload=09 03 25 01 00 
2018-08-22 20:21:18.649 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=27 00 01 7C 
2018-08-22 20:21:18.651 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=39, expected=SendData, cancelled=false        transaction complete!
2018-08-22 20:21:18.653 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-08-22 20:21:18.654 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2018-08-22 20:21:18.656 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 9: Response processed after 3831ms/4958ms.
2018-08-22 20:21:18.658 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2018-08-22 20:21:18.660 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0E 00 13 15 07 60 0D 01 02 25 01 00 25 28 B7 
2018-08-22 20:21:18.662 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 21: Sending REQUEST Message = 01 0E 00 13 15 07 60 0D 01 02 25 01 00 25 28 B7 
2018-08-22 20:21:18.675 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2018-08-22 20:21:18.677 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:18.679 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 
2018-08-22 20:21:18.680 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 
2018-08-22 20:21:18.682 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 
2018-08-22 20:21:18.683 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: Sent Data successfully placed on stack.
2018-08-22 20:21:20.493 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0D 00 04 00 15 07 60 0D 01 00 25 03 00 AE 
2018-08-22 20:21:20.497 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:20.501 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 04 00 15 07 60 0D 01 00 25 03 00 AE 
2018-08-22 20:21:20.505 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0D 00 04 00 15 07 60 0D 01 00 25 03 00 AE 
2018-08-22 20:21:20.509 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 15 07 60 0D 01 00 25 03 00 
2018-08-22 20:21:20.512 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)
2018-08-22 20:21:20.515 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE
2018-08-22 20:21:20.518 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@1b6081d already registered
2018-08-22 20:21:20.521 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE
2018-08-22 20:21:20.524 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2
2018-08-22 20:21:20.527 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)
2018-08-22 20:21:20.529 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.
2018-08-22 20:21:20.532 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - Received Switch Binary Request for Node ID = 21
2018-08-22 20:21:20.535 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 0
2018-08-22 20:21:20.538 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-08-22 20:21:20.541 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-08-22 20:21:20.543 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_BINARY, value = 0
2018-08-22 20:21:20.548 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary1 to OFF [OnOffType]
2018-08-22 20:21:20.557 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Set, dest=21, callback=40, payload=15 07 60 0D 01 02 25 01 00 
2018-08-22 20:21:20.561 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 15 07 60 0D 01 00 25 03 00 
2018-08-22 20:21:20.566 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationCommandHandler, callback id=40, expected=SendData, cancelled=false      MISMATCH
2018-08-22 20:21:22.526 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 21 03 80 03 2D 7E 
2018-08-22 20:21:22.531 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:22.534 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 04 00 21 03 80 03 2D 7E 
2018-08-22 20:21:22.537 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 04 00 21 03 80 03 2D 7E 
2018-08-22 20:21:22.541 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 21 03 80 03 2D 
2018-08-22 20:21:22.546 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 21 06 43 03 01 42 08 98 43 
2018-08-22 20:21:22.553 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 33: Application Command Request (ALIVE:DONE)
2018-08-22 20:21:22.556 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 33: Starting initialisation from DONE
2018-08-22 20:21:22.559 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@10f65d8 already registered
2018-08-22 20:21:22.562 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 33: Incoming command class BATTERY
2018-08-22 20:21:22.566 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0A 00 04 00 21 04 46 08 00 7F E5 
2018-08-22 20:21:22.571 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 33: Received Battery Request
2018-08-22 20:21:22.573 [DEBUG] [ommandclass.ZWaveBatteryCommandClass] - NODE 33: Battery report value = 45
2018-08-22 20:21:22.576 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2018-08-22 20:21:22.579 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2018-08-22 20:21:22.582 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got a value event from Z-Wave network, endpoint = 0, command class = BATTERY, value = 45
2018-08-22 20:21:22.586 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Updating channel state zwave:device:c1f45758:node33:battery-level to 45 [DecimalType]
2018-08-22 20:21:22.591 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 21 06 31 05 01 42 09 85 2B 
2018-08-22 20:21:22.594 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255
2018-08-22 20:21:22.598 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=1
2018-08-22 20:21:22.603 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 04 00 21 06 43 03 01 42 08 98 43 
2018-08-22 20:21:22.615 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0C 00 04 00 21 06 43 03 01 42 08 98 43 
2018-08-22 20:21:22.622 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 21 06 43 03 01 42 08 98 
2018-08-22 20:21:22.616 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 00 04 00 21 02 84 07 53 
2018-08-22 20:21:22.627 [INFO ] [odel.script.batterydevices_bat_level] - r_BattDevs_Upd_LastUpdateItem : Updating all last update items
2018-08-22 20:21:22.628 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 33: Application Command Request (ALIVE:DONE)
2018-08-22 20:21:22.631 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 33: Starting initialisation from DONE
2018-08-22 20:21:22.634 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@10f65d8 already registered
2018-08-22 20:21:22.637 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 33: Incoming command class THERMOSTAT_SETPOINT
2018-08-22 20:21:22.639 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 33: Received Thermostat Setpoint Request
2018-08-22 20:21:22.642 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 33: Thermostat Setpoint report Scale = 0
2018-08-22 20:21:22.644 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 33: Thermostat Setpoint Value = 22
2018-08-22 20:21:22.647 [DEBUG] [.ZWaveThermostatSetpointCommandClass] - NODE 33: Thermostat Setpoint Report, Type Heating (1), value = 22
2018-08-22 20:21:22.649 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveThermostatSetpointValueEvent
2018-08-22 20:21:22.652 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got an event from Z-Wave network: ZWaveThermostatSetpointValueEvent
2018-08-22 20:21:22.654 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got a value event from Z-Wave network, endpoint = 0, command class = THERMOSTAT_SETPOINT, value = 22
2018-08-22 20:21:22.656 [DEBUG] [converter.ZWaveCommandClassConverter] - Converted temperature from 22C to 22C
2018-08-22 20:21:22.660 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Updating channel state zwave:device:c1f45758:node33:thermostat_setpoint_heating to 22 [DecimalType]
2018-08-22 20:21:22.665 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255
2018-08-22 20:21:22.667 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=2
2018-08-22 20:21:22.669 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 04 00 21 04 46 08 00 7F E5 
2018-08-22 20:21:22.672 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0A 00 04 00 21 04 46 08 00 7F E5 
2018-08-22 20:21:22.676 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 21 04 46 08 00 7F 
2018-08-22 20:21:22.678 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 33: Application Command Request (ALIVE:DONE)
2018-08-22 20:21:22.681 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 33: Starting initialisation from DONE
2018-08-22 20:21:22.684 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@10f65d8 already registered
2018-08-22 20:21:22.686 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 33: Incoming command class CLIMATE_CONTROL_SCHEDULE
2018-08-22 20:21:22.689 [DEBUG] [veClimateControlScheduleCommandClass] - NODE 33: Received CLIMATE_CONTROL_SCHEDULE command V1
2018-08-22 20:21:22.691 [INFO ] [veClimateControlScheduleCommandClass] - NODE 33 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2018-08-22 20:21:22.693 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255
2018-08-22 20:21:22.695 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=1
2018-08-22 20:21:22.697 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0C 00 04 00 21 06 31 05 01 42 09 85 2B 
2018-08-22 20:21:22.700 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 0C 00 04 00 21 06 31 05 01 42 09 85 2B 
2018-08-22 20:21:22.702 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 21 06 31 05 01 42 09 85 
2018-08-22 20:21:22.704 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 33: Application Command Request (ALIVE:DONE)
2018-08-22 20:21:22.706 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 33: Starting initialisation from DONE
2018-08-22 20:21:22.709 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@10f65d8 already registered
2018-08-22 20:21:22.712 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 33: Incoming command class SENSOR_MULTILEVEL
2018-08-22 20:21:22.714 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 33: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V6
2018-08-22 20:21:22.716 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 33: Sensor Multi Level REPORT received
2018-08-22 20:21:22.721 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 33: Sensor Type = Temperature(1), Scale = 0
2018-08-22 20:21:22.725 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 33: Sensor Value = 24.37
2018-08-22 20:21:22.728 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMultiLevelSensorValueEvent
2018-08-22 20:21:22.731 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2018-08-22 20:21:22.734 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 24.37
2018-08-22 20:21:22.738 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 33: Sensor is reporting scale 0, requiring conversion to 0. Value is now 24.37.
2018-08-22 20:21:22.741 [DEBUG] [converter.ZWaveCommandClassConverter] - Converted temperature from 24.37C to 24.37C
2018-08-22 20:21:22.744 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Updating channel state zwave:device:c1f45758:node33:sensor_temperature to 24.37 [DecimalType]
2018-08-22 20:21:22.749 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255
2018-08-22 20:21:22.754 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2018-08-22 20:21:22.757 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 08 00 04 00 21 02 84 07 53 
2018-08-22 20:21:22.759 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 08 00 04 00 21 02 84 07 53 
2018-08-22 20:21:22.762 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationCommandHandler[0x04], type=Request[0x00], priority=High, dest=255, callback=0, payload=00 21 02 84 07 
2018-08-22 20:21:22.764 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 33: Application Command Request (ALIVE:DONE)
2018-08-22 20:21:22.766 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 33: Starting initialisation from DONE
2018-08-22 20:21:22.769 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@10f65d8 already registered

[rossko57]

Perhaps you could share the rule and a snippet of OH events log. Could be as simple as choosing the right rule trigger e.g. changed instead of updated

[Noddy (Norbert Meier)]

Sorry, I missed to add the rule

I could not use changed trigger, because the item state isn’t changed when pressing the same button twice. I want to toggle the switches ON/OFF by pressing the same button.

val String rulefilename = "r_RC_001"

rule r_RC_DEVOLO_01_Scene_Number_rcv_upd
  when Item RC_DEVOLO_01_Scene_Number received update
then
	logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd\n"+
                          "                                                                         "+
						  "RC_DEVOLO_01_Scene_Number received command = \"" + RC_DEVOLO_01_Scene_Number.state.toString + "\""
	       ) 
	
    // Button 1 ( top left ) 
	if ( RC_DEVOLO_01_Scene_Number.state == 1.0 )
	{
		// Terassenbeleuchtung: An/Aus
		if ( WS_BM_TERASSE_01_Switch1.state == OFF )
			WS_BM_TERASSE_01_Switch1.send(ON) 
		else
			WS_BM_TERASSE_01_Switch1.send(OFF) 
	}

    // Button 2 ( top right )
	if ( RC_DEVOLO_01_Scene_Number.state == 2.0 )
	{
		// Joska Glaskugel: An/Aus
		if ( WP_BM_CARPORT_01_Switch.state == OFF )
			WP_BM_CARPORT_01_Switch.send(ON) 
		else
			WP_BM_CARPORT_01_Switch.send(OFF) 
	}

    // Button 3 ( bottom left )
	if ( RC_DEVOLO_01_Scene_Number.state == 5.0 )
	{
		// Springbrunnen: An/Aus
		if ( WS_BM_TERASSE_01_Switch2.state == OFF )
			WS_BM_TERASSE_01_Switch2.send(ON) 
		else
			WS_BM_TERASSE_01_Switch2.send(OFF) 
	}

    // Button 4 ( bottom right )
	if ( RC_DEVOLO_01_Scene_Number.state == 6.0 )
	{
		// Terassenbeleuchtung: An/Aus prüfen
		if ( WS_BM_TERASSE_01_Switch1.state == OFF )
		{
			// Wenn aus, dann alles Einschalten
			WS_BM_TERASSE_01_Switch1.send(ON) // Terassenbeleuchtung
			WS_BM_TERASSE_01_Switch2.send(ON) // Springbrunnen
			WP_BM_CARPORT_01_Switch.send(ON)  // Joska Glaskugel
		}
		else
		{
			// Wenn aus, dann alles Einschalten
			WS_BM_TERASSE_01_Switch1.send(OFF) // Terassenbeleuchtung
			WS_BM_TERASSE_01_Switch2.send(OFF) // Springbrunnen
			WP_BM_CARPORT_01_Switch.send(OFF)  // Joska Glaskugel
		}
	}

end

[5iver (Scott Rushworth)]

@Noddy

The rule is triggered more than once although a button on the remote is only pressed once.

The log shows only the one entry for the rule, so it is only being triggered once. Commands are sent to the devices, the devices receive the commands and turn off, the devices send a notification that they have turned off, and then the binding updates the item states based on the info received from the devices. In new versions of the binding, you’ll also see a poll of each channel to check the state of a device after a command is sent, since some devices do not send this information automatically. Hopefully this answers your question… everything looks to be working normally.

[rlkoshak (Rich Koshak)]

@5iver

In new versions of the binding, you’ll also see a poll of each channel to check the state of a device after a command is sent, since some devices do not send this information automatically.

I have not followed the development version of the binding and had no idea this was implemented. This is exciting. It solves a particularly annoying problem I have with my setup. At this point I’ll wait until Chris finishes merging and upgrade to the snapshot for that feature.

[5iver (Scott Rushworth)]

@rlkoshak

upgrade to the snapshot for that feature.

It is also configurable (100-15000ms).

[Noddy (Norbert Meier)]

I used snapshot 2.4 08/18/2018 of openhab (openhabian).

@Scott: Thanks for your comments. I need to truncate the log, because it’s too long for a post.
Lamps are connected to the switches and the result is that the lamps are turned on and off and on and off for minutes. The lamps become flash lights instead of being switched once.

Today I’ve updated to the actual openhabian snapshot “openHAB 2.4.0~20180823114345-1 (Build #1339)”.
It seems that the rule is now not triggered more than once but sometimes - NOT EACH TIME A BUTTON ON THE REMOTE IS PRESSED - the lights are suddenly flash lights. A lot of log entries regarding the two switch things are displayed. After a few minutes this behaviour stops suddenly like it starts

I can send the whole part of the log, if it is possible to upload or attach such a big file.

Thanks
Norbert

[5iver (Scott Rushworth)]

I remember someone reporting something similar. Are you using an in-wall dimmer device? IIRC, the issue was with wiring in the switch paddles. I’ll see if I can find the post… found it…

Qubino Flush 2 Relais misbehaves once every x times

UPDATE 2: The Qubino is often not working when put in the wall, but works perfectly when it’s hanging out from the wall. I think the built quality is too poor and stresses coming from stiff wires cause malfunction. I always put most of the wires into the wall, then the Qubino, and than the be-stable switch. I found out by lots of trial and error that it’s better to first put in the qubino, with the flat back against the back of the hole in the wall, Then put the wires in between the Qubino and …

[Noddy (Norbert Meier)]

Thanks for the information.

I’ll try to place the Fibaro Double-Reley-Switch outside the garage for testing.
I’ll come bach after testing.

[Noddy (Norbert Meier)]

I’ve placed the Fibaro Double Relay switch as mentioned outside the garage, so that only one wall of the house is between it and the next z-wave node. Unfortunatelly that’s not the solution.

I changed the rule and added also some rules for logging, when then the switch items changed.
A group is now used for switching all items on and off by button 4 of the Devolo remote.

Group:Switch G_Terasse_All_PowerOutlets <lamp>

Switch	WP_BM_CARPORT_01_Switch		"Terassenbeleuchtung Joska-Glaskugel" 		<light>		(G_Terasse_All_PowerOutlets)	{ channel="zwave:device:c1f45758:node9:switch_binary" }
Switch 	WS_BM_TERASSE_01_Switch1	"Terassenbeleuchtung"				<light>		(G_Terasse_All_PowerOutlets)	{channel="zwave:device:c1f45758:node21:switch_binary1"}
Switch	WS_BM_TERASSE_01_Switch2	"Springbrunnen Pumpe"				<pump>		(G_Terasse_All_PowerOutlets)	{channel="zwave:device:c1f45758:node21:switch_binary2"}

rule r_WS_BM_TERASSE_01_Switch1_chg
	when Item WS_BM_TERASSE_01_Switch1 changed
then
	logInfo(rulefilename, "rule r_WS_BM_TERASSE_01_Switch1_chg: WS_BM_TERASSE_01_Switch1.state = " + WS_BM_TERASSE_01_Switch1.state.toString)
end
					
rule r_WS_BM_TERASSE_01_Switch2_chg
	when Item WS_BM_TERASSE_01_Switch2 changed
then
	logInfo(rulefilename, "rule r_WS_BM_TERASSE_01_Switch2_chg: WS_BM_TERASSE_01_Switch2.state = " + WS_BM_TERASSE_01_Switch2.state.toString)
end					

rule r_WP_BM_CARPORT_01_Switch_chg
	when Item WP_BM_CARPORT_01_Switch changed
then
	logInfo(rulefilename, "rule r_WP_BM_CARPORT_01_Switch_chg: WP_BM_CARPORT_01_Switch.state = " + WP_BM_CARPORT_01_Switch.state.toString)
end					


rule r_RC_DEVOLO_01_Scene_Number_rcv_upd
  when Item RC_DEVOLO_01_Scene_Number received update
then
    var String s1
	if ( RC_DEVOLO_01_Scene_Number.state.toString.length > 0) {
	 s1 = RC_DEVOLO_01_Scene_Number.state.toString.substring(0,1)
	} else {
		s1 = ""
	}
    // logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd :: s1 = \"" + s1 + "\"")

    var String s2
	if ( RC_DEVOLO_01_Scene_Number.state.toString.length > 2) {
		s2 = RC_DEVOLO_01_Scene_Number.state.toString.substring(2,3)
	} else {
		s2 = ""
	}
    // logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd :: s2 = \"" + s2 + "\"")

	var String sButton
	var String sClick 
	var String sRelease

	if ( (s1 == "1") || (s1 == "5") ) {
		sButton = "top left"
	} else if ( (s1 == "2") || (s1 == "6") ) {
		sButton = "top right"
	} else if ( (s1 == "3") || (s1 == "7") ) {
		sButton = "bottom left"
	} else if ( (s1 == "4") || (s1 == "8") ) {
		sButton = "bottom left"
	} 

	if ( s1 < "5") {
		sClick = "Single click "
	} else {
		sClick = "Double click "
	}

	if ( s2 == "0") {
		sRelease = ""
	} else if ( s2 == "1") {
		sRelease = " (on Release)"
	} else if ( s2 == "2") {
		sRelease = " (on Press)"
	} else {
		sRelease = " (on unknown event)"
	} 



	logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd :: "+
						  "RC_DEVOLO_01_Scene_Number received command = \"" + RC_DEVOLO_01_Scene_Number.state.toString + "\" // " + sClick + sButton + sRelease
	       ) 
	
    // Button 1 ( top left ) 
	if ( ( RC_DEVOLO_01_Scene_Number.state == 1.0 ) /*Single click*/ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 1.1 ) /*Release button after single click holding down (dim end) */ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 5.0 ) /* Double click */ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 5.1 ) /*Release button after double click holding down (dim end) */ 
	   )
	{
		// logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: in if state == 1")
		if ( (!lock_button1.isLocked) && (!lock_button4.isLocked) )
		{
			// logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock_button4.isLocked = false  ::"+
			                    //   "                        before lock1.lock")
			lock_button1.lock
			// logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: after lock1.lock")
			try {
				// Terassenbeleuchtung: An/Aus
				if ( WS_BM_TERASSE_01_Switch1.state == OFF ) {
					logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: WS_BM_TERASSE_01_Switch1.send(ON)")
					WS_BM_TERASSE_01_Switch1.send(ON) 
				} else {
					logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: WS_BM_TERASSE_01_Switch1.send(OFF)")
					WS_BM_TERASSE_01_Switch1.send(OFF) 
				}
				Thread.sleep(1000)           
			} finally  {
				lock_button1.unlock
				logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock1.unlock")
			}
		}
		else
		{
			logWarn(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock_button 1 or 4 isLocked !!! => Do nothing")
		}
	}

    // Button 2 ( top right )
	if ( ( RC_DEVOLO_01_Scene_Number.state == 2.0 ) /*Single click*/ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 2.1 ) /*Release button after single click holding down (dim end) */ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 6.0 ) /* Double click */ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 6.1 ) /*Release button after double click holding down (dim end) */
	   )
	{
		if ( (!lock_button2.isLocked) && (!lock_button4.isLocked) )
		{
			// logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock_button4.isLocked = false :: "+
			                    //   "                        before lock2.lock")
			lock_button2.lock
			logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: after lock2.lock")
			try {
				// Joska Glaskugel: An/Aus
				if ( WP_BM_CARPORT_01_Switch.state == OFF ) {
					logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: WP_BM_CARPORT_01_Switch.send(ON)")
					WP_BM_CARPORT_01_Switch.send(ON) 
				} else {
					logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: WP_BM_CARPORT_01_Switch.send(OFF)")
					WP_BM_CARPORT_01_Switch.send(OFF) 
				}
				Thread.sleep(1000)           
			} finally  {
				lock_button2.unlock
				logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock1.unlock")
			}
		}
		else
		{
			logWarn(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock_button 2 or 4 isLocked !!! => Do nothing")
		}
	}

    // Button 3 ( bottom left )
	if ( ( RC_DEVOLO_01_Scene_Number.state == 3.0 ) /*Single click*/ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 3.1 ) /*Release button after single click holding down (dim end) */ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 7.0 ) /* Double click */ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 7.1 ) /*Release button after double click holding down (dim end) */ 
	   )
	{
		if ( (!lock_button3.isLocked) && (!lock_button4.isLocked) )
		{
			// logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock_button4.isLocked = false :: "+
			//                       "                        before lock3.lock")
			lock_button3.lock
			logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: after lock3.lock")
			try {
				// Springbrunnen: An/Aus
				if ( WS_BM_TERASSE_01_Switch2.state == OFF ) {
					logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: WS_BM_TERASSE_01_Switch2.send(OFF)")
					WS_BM_TERASSE_01_Switch2.send(ON) 
				} else {
					logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: WS_BM_TERASSE_01_Switch2.send(OFF)")
					WS_BM_TERASSE_01_Switch2.send(OFF) 
				}
				Thread.sleep(1000)           
			} finally  {
				lock_button3.unlock
				logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock1.unlock")
			}
		}
		else
		{
			logWarn(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock_button 3 or 4 isLocked !!! => Do nothing")
		}
	}

    // Button 4 ( bottom right )
	if ( ( RC_DEVOLO_01_Scene_Number.state == 4.0 ) /*Single click*/ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 4.1 ) /*Release button after single click holding down (dim end) */ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 8.0 ) /* Double click */ ||
	     ( RC_DEVOLO_01_Scene_Number.state == 8.1 ) /*Release button after double click holding down (dim end) */ 
	   )

	{
		if ( (!lock_button1.isLocked) && (!lock_button2.isLocked) && (!lock_button3.isLocked) && (!lock_button4.isLocked) )
		{
			// logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock_button 1 2 and 3.isLocked = false :: "+
			//                       "                        before lock4.lock")
			lock_button4.lock
			logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: after lock4.lock")
			try 
			{
				// Terassenbeleuchtung: An/Aus prüfen
				if ( WS_BM_TERASSE_01_Switch1.state == OFF )
				{
					// Wenn aus, dann alles Einschalten
					logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: G_Terasse_All_PowerOutlets.send(ON)")
					G_Terasse_All_PowerOutlets.send(ON)
				}
				else
				{
					// Wenn aus, dann alles Einschalten
					logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: G_Terasse_All_PowerOutlets.send(OFF)")
					G_Terasse_All_PowerOutlets.send(OFF) 
				}
				Thread.sleep(500)           
			} finally  {
				lock_button4.unlock
				logInfo(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock4.unlock")
			}
		}
		else
		{
			logWarn(rulefilename, "rule r_RC_DEVOLO_01_Scene_Number_rcv_upd: lock_button 1 2 3 oder 4 isLocked !!! => Do nothing")
		}
	}

end

I observed the following:
Sometimes it works well. A few seconds later using the Devolo remote again the system reacts very slow. It took in this case a few seconds between pressing the button and that the z-wave switch changed it status (light on/off).
Using the button 4 (switching all on/off): Switch 2 of node 21 needs a very long time to change it state, if the slow behaviour ocours.
I added also a reentrance lock to the rule, but that seems not to be the problem. The unlock is done in the rule before the zwave channel chaged its state.

I don’t added the log because it’s very long.

What can I try further to get this solved?

Here is the current network view of HABmin:

All three nodes (9, 21 and 62) do not have a direct link to the controller (Node 1).

[Noddy (Norbert Meier)]

I did more testing. I created a simple sitemap to find out if the Devolo remote or my rule is the problem.
Both aren’t the problem, because using the sitemap is also creating problems.

sitemap TERASSE_01 label="Terasse"
{
	Frame label="" {	

		Switch	item=WS_BM_TERASSE_01_Switch1 			
		Switch	item=WS_BM_TERASSE_01_Switch2
		Switch	item=WP_BM_CARPORT_01_Switch
		Switch	item=G_Terasse_All_PowerOutlets
	}
}

Using the switches that are link to simple item switches works, but at the end there a some
" Transaction not completed: node address inconsistent" messages (see log below).
The time between changing the state in the UI and the real change of the power outlet is ok.

2018-08-29 22:08:22.188 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Command received zwave:device:c1f45758:node21:switch_binary1 --> ON

2018-08-29 22:08:22.204 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Creating new message for application command SWITCH_BINARY_SET

2018-08-29 22:08:22.252 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Encapsulating message, instance / endpoint 1

2018-08-29 22:08:22.256 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1

2018-08-29 22:08:22.276 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 21: Sending REQUEST Message = 01 0E 00 13 15 07 60 0D 01 01 25 01 FF 25 1A 79 

2018-08-29 22:08:22.324 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: Sent Data successfully placed on stack.

2018-08-29 22:08:22.519 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: SendData Request. CallBack ID = 26, Status = Transmission complete and ACK received(0)

2018-08-29 22:08:22.521 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:08:22.538 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2018-08-29 22:08:22.540 [DEBUG] [curityCommandClassWithInitialization] - NODE 21: updating lastSentMessageTimestamp

2018-08-29 22:08:22.543 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 21: Response processed after 255ms/4963ms.

2018-08-29 22:08:22.666 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:08:22.668 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:08:22.672 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:08:22.674 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:08:22.676 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)

2018-08-29 22:08:22.677 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:08:22.681 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 255

2018-08-29 22:08:22.685 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:08:22.686 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_BINARY, value = 255

2018-08-29 22:08:22.689 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary1 to ON [OnOffType]

2018-08-29 22:08:25.197 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:08:25.200 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:08:25.211 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:08:25.213 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:08:25.215 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = METER (0x32)

2018-08-29 22:08:25.218 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:08:25.220 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Received METER command V3

2018-08-29 22:08:25.222 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Meter: Type=Electric(1), Scale=W(2), Value=23.1

2018-08-29 22:08:25.226 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveMeterValueEvent

2018-08-29 22:08:25.229 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = METER, value = 23.1

2018-08-29 22:08:25.233 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:meter_watts1 to 23.1 [DecimalType]

2018-08-29 22:08:30.125 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:09:03.795 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:09:03.875 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:09:03.920 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:09:03.991 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:09:04.063 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

But using the group that include only the three items cause most of the time a huge delay until all power outlet have changed their state (see log below):

2018-08-29 22:19:17.323 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Command received zwave:device:c1f45758:node9:switch_binary --> ON

2018-08-29 22:19:17.325 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 9: Creating new message for application command SWITCH_BINARY_SET

2018-08-29 22:19:17.331 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 9: Sending REQUEST Message = 01 0A 00 13 09 03 25 01 FF 25 8F 9D 

2018-08-29 22:19:17.334 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Command received zwave:device:c1f45758:node21:switch_binary1 --> ON

2018-08-29 22:19:17.336 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Creating new message for application command SWITCH_BINARY_SET

2018-08-29 22:19:17.347 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Encapsulating message, instance / endpoint 1

2018-08-29 22:19:17.349 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1

2018-08-29 22:19:17.364 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: Sent Data successfully placed on stack.

2018-08-29 22:19:17.354 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Command received zwave:device:c1f45758:node21:switch_binary2 --> ON

2018-08-29 22:19:17.381 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Creating new message for application command SWITCH_BINARY_SET

2018-08-29 22:19:17.392 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Encapsulating message, instance / endpoint 2

2018-08-29 22:19:17.397 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2

2018-08-29 22:19:17.480 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 9: SendData Request. CallBack ID = 143, Status = Transmission complete and ACK received(0)

2018-08-29 22:19:17.482 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Starting initialisation from DONE

2018-08-29 22:19:17.492 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2018-08-29 22:19:17.493 [DEBUG] [curityCommandClassWithInitialization] - NODE 9: updating lastSentMessageTimestamp

2018-08-29 22:19:17.495 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 9: Response processed after 158ms/4963ms.

2018-08-29 22:19:17.500 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 21: Sending REQUEST Message = 01 0E 00 13 15 07 60 0D 01 01 25 01 FF 25 90 F3 

2018-08-29 22:19:17.520 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: Sent Data successfully placed on stack.

2018-08-29 22:19:17.953 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:17.954 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Starting initialisation from DONE

2018-08-29 22:19:17.957 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Incoming command class SWITCH_BINARY

2018-08-29 22:19:17.961 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 9: Switch Binary report, value = 255

2018-08-29 22:19:17.964 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:19:17.965 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_BINARY, value = 255

2018-08-29 22:19:17.967 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Updating channel state zwave:device:c1f45758:node9:switch_binary to ON [OnOffType]

2018-08-29 22:19:17.970 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:19:21.912 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: SendData Request. CallBack ID = 144, Status = Transmission complete and ACK received(0)

2018-08-29 22:19:21.915 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:21.929 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2018-08-29 22:19:21.931 [DEBUG] [curityCommandClassWithInitialization] - NODE 21: updating lastSentMessageTimestamp

2018-08-29 22:19:21.933 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 21: Response processed after 4432ms/4963ms.

2018-08-29 22:19:21.940 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 21: Sending REQUEST Message = 01 0E 00 13 15 07 60 0D 01 02 25 01 FF 25 91 F1 

2018-08-29 22:19:21.969 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: Sent Data successfully placed on stack.

2018-08-29 22:19:26.801 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 21: SendData Request. CallBack ID = 145, Status = Transmission complete and ACK received(0)

2018-08-29 22:19:26.803 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:26.820 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2018-08-29 22:19:26.822 [DEBUG] [curityCommandClassWithInitialization] - NODE 21: updating lastSentMessageTimestamp

2018-08-29 22:19:26.825 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 21: Response processed after 4882ms/4963ms.

2018-08-29 22:19:26.897 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:26.899 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:26.904 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:26.906 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:26.909 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)

2018-08-29 22:19:26.911 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:19:26.915 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 255

2018-08-29 22:19:26.920 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:19:26.922 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_BINARY, value = 255

2018-08-29 22:19:26.925 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary1 to ON [OnOffType]

2018-08-29 22:19:26.994 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:26.996 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:27.002 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:27.005 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:27.007 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = METER (0x32)

2018-08-29 22:19:27.010 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:19:27.013 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Received METER command V3

2018-08-29 22:19:27.015 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Meter: Type=Electric(1), Scale=W(2), Value=23.5

2018-08-29 22:19:27.020 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveMeterValueEvent

2018-08-29 22:19:27.023 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = METER, value = 23.5

2018-08-29 22:19:27.028 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:meter_watts1 to 23.5 [DecimalType]

2018-08-29 22:19:27.159 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:27.161 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:27.167 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:27.169 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:27.172 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)

2018-08-29 22:19:27.174 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:19:27.179 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 255

2018-08-29 22:19:27.184 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:19:27.187 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_BINARY, value = 255

2018-08-29 22:19:27.190 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary1 to ON [OnOffType]

2018-08-29 22:19:27.226 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:27.228 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:27.232 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:27.233 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:27.235 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)

2018-08-29 22:19:27.237 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:19:27.240 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 255

2018-08-29 22:19:27.244 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:19:27.245 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_BINARY, value = 255

2018-08-29 22:19:27.247 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary1 to ON [OnOffType]

2018-08-29 22:19:27.901 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:27.903 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 9: Starting initialisation from DONE

2018-08-29 22:19:27.909 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 9: Incoming command class SENSOR_MULTILEVEL

2018-08-29 22:19:27.912 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V5

2018-08-29 22:19:27.915 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Multi Level REPORT received

2018-08-29 22:19:27.918 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Type = Power(4), Scale = 0

2018-08-29 22:19:27.921 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 9: Sensor Value = 3.5

2018-08-29 22:19:27.927 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent

2018-08-29 22:19:27.930 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 3.5

2018-08-29 22:19:27.934 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Updating channel state zwave:device:c1f45758:node9:sensor_power to 3.5 [DecimalType]

2018-08-29 22:19:27.943 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:19:28.152 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:28.154 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:28.158 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:28.159 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:28.161 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)

2018-08-29 22:19:28.163 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:19:28.166 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 255

2018-08-29 22:19:28.170 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:19:28.172 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_BINARY, value = 255

2018-08-29 22:19:28.174 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary1 to ON [OnOffType]

2018-08-29 22:19:28.538 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:28.540 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:28.545 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:28.549 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:28.551 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)

2018-08-29 22:19:28.553 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:19:28.556 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 255

2018-08-29 22:19:28.560 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:19:28.561 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_BINARY, value = 255

2018-08-29 22:19:28.563 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary1 to ON [OnOffType]

2018-08-29 22:19:28.698 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:28.701 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:28.706 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:28.710 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:28.714 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)

2018-08-29 22:19:28.718 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 2, calling handleApplicationCommandRequest.

2018-08-29 22:19:28.726 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 255

2018-08-29 22:19:28.734 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:19:28.739 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 2, command class = SWITCH_BINARY, value = 255

2018-08-29 22:19:28.743 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary2 to ON [OnOffType]

2018-08-29 22:19:28.854 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:28.855 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:28.875 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:28.876 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:28.877 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)

2018-08-29 22:19:28.878 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:19:28.881 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 255

2018-08-29 22:19:28.883 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:19:28.885 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_BINARY, value = 255

2018-08-29 22:19:28.886 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary1 to ON [OnOffType]

2018-08-29 22:19:29.027 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:29.029 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:29.031 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:29.033 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:29.034 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = METER (0x32)

2018-08-29 22:19:29.036 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 2, calling handleApplicationCommandRequest.

2018-08-29 22:19:29.037 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Received METER command V3

2018-08-29 22:19:29.039 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Meter: Type=Electric(1), Scale=W(2), Value=27.1

2018-08-29 22:19:29.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveMeterValueEvent

2018-08-29 22:19:29.044 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 2, command class = METER, value = 27.1

2018-08-29 22:19:29.047 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:meter_watts2 to 27.1 [DecimalType]

2018-08-29 22:19:29.195 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:29.196 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:29.199 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:29.201 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:29.202 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = METER (0x32)

2018-08-29 22:19:29.203 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.

2018-08-29 22:19:29.204 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Received METER command V3

2018-08-29 22:19:29.206 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Meter: Type=Electric(1), Scale=W(2), Value=23.5

2018-08-29 22:19:29.208 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveMeterValueEvent

2018-08-29 22:19:29.210 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = METER, value = 23.5

2018-08-29 22:19:29.212 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:meter_watts1 to 23.5 [DecimalType]

2018-08-29 22:19:29.353 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:29.354 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:29.357 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:29.358 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:29.359 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = SWITCH_BINARY (0x25)

2018-08-29 22:19:29.361 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 2, calling handleApplicationCommandRequest.

2018-08-29 22:19:29.363 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 21: Switch Binary report, value = 255

2018-08-29 22:19:29.365 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent

2018-08-29 22:19:29.367 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 2, command class = SWITCH_BINARY, value = 255

2018-08-29 22:19:29.368 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:switch_binary2 to ON [OnOffType]

2018-08-29 22:19:30.098 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:19:31.140 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Application Command Request (ALIVE:DONE)

2018-08-29 22:19:31.141 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 21: Starting initialisation from DONE

2018-08-29 22:19:31.144 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Incoming command class MULTI_INSTANCE

2018-08-29 22:19:31.145 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Received MULTI_INSTANCE command V2

2018-08-29 22:19:31.146 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Requested Command Class = METER (0x32)

2018-08-29 22:19:31.147 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 21: Endpoint = 2, calling handleApplicationCommandRequest.

2018-08-29 22:19:31.149 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Received METER command V3

2018-08-29 22:19:31.150 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 21: Meter: Type=Electric(1), Scale=W(2), Value=27.1

2018-08-29 22:19:31.153 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveMeterValueEvent

2018-08-29 22:19:31.154 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 2, command class = METER, value = 27.1

2018-08-29 22:19:31.157 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Updating channel state zwave:device:c1f45758:node21:meter_watts2 to 27.1 [DecimalType]

2018-08-29 22:19:44.344 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:19:44.421 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

2018-08-29 22:19:44.485 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 21: Transaction not completed: node address inconsistent.  lastSent=21, incoming=255

The “Transaction not completed node address inconsistent” is here also logged

I tried to heal and reinitialize the two nodes 9 & 21 more than once, but it doesn’t help.

What could be the problem and how can I solve it?

[vossivossi]

@5iver

It is also configurable (100-15000ms).

Is is possible to configure a default value for this? So far I only can find it for each single device and need to tweak it several times.

[5iver (Scott Rushworth)]

@vossivossi

Is is possible to configure a default value for this? So far I only can find it for each single device and need to tweak it several times.

No, it looks like there is no global setting for this. You might want to request it to be added as a feature.

@Noddy

The “Transaction not completed node address inconsistent” is here also logged

This is a normal message and does not suggest any issue.

You’re using the snapshot version of the binding. You might want to try the development version, but it is soon to be merged. But my gut is saying that this is more of a rule issue, since the binding is responding well to using the sitemap. I would definitely remove the ReentrantLocks. It also looks like the rule will take the same action when the button is pressed and released, and potentially twice more from command polling, and since you are triggering on received update, the rule will fire once for the state change and again for the timestamp change. That’s 8 triggers per press/release. If this is correct, you should see it in the log. You could also be running out of threads. The locks and sleeps will only exacerbate this. Are the lights still flashing, or was that remedied by only sending the command if it was different that the current state of the switch?

[Noddy (Norbert Meier)]

@5iver:
Using the sitemap is causing issues, if I press the same button several times.
The problem is than the same as pressing the button for the group.
Log messages for the thing (node 9 or node 21) are recognized over 10 to 20 seconds.
I’ll try to create a log showing that. I’ll upload that to a Google or one drive due to its size.
I don’t understand what is causing these behaviour. Is there a problem with my radio layer in that area that is causing these kind of problems?

I found your nice thread regarding updating zwave things

Rule for deleting and rediscovering Things

OH2 does not currently have a mechanism for updating Thing types. When a binding update includes new or modified Channel definitions, the Thing needs to be manually deleted and recreated in order to use the new/modified Channel. For most bindings, it is not too cumbersome to do this manually. But when you are using the Zwave binding with ~120 devices, this can be a real headache. Here is an example of how I have automated the deletion, rediscovery, and reconfiguration of my Zwave Things. I run t…

and the following two:

ZWave binding migration to development version

Important message first - upcoming changes to the ZWave binding will require that existing things are deleted, and re-added so that the binding picks up the latest thing definitions. You don’t need to exclude and re-include the devices from the network, and in most cases the devices should look the same to the user so channels should be the same (the database is the same for all versions). For some time now, most features and fixes in the ZWave binding have been added to a development branch o…

GitHub - openhab/org.openhab.binding.zwave: openHAB binding for Z-Wave

I’ll update to the zwave binding to the deveolpment branch and report afterwards.

[Noddy (Norbert Meier)]

I checked the actual log that was just created and I found some strange entries.

That’s the behaviour that I tried to discribe. Sometimes the time between changing the switch on the sitemap and the real change of the zwave switch power outlet is longer than a second.