Z-wave Binding and Fibaro RGBW Controller Bug

Add-ons Bindings
, ,
1

Hi all,
Today in the morning I found my LED lightning switched on , generating a bit of green light. I was wondering what happened, as my Rainbow Christmas control usually switches it off at 10pm.
Looking in Log files I saw strange behaviour:

My item file for Fibaro RGBW Controller looks as follows:

Dimmer  LED_Terasse_R    "Red [%d %%]"       <switch> (Terasse)  {zwave="21:2:command=switch_multilevel"}
Dimmer  LED_Terasse_G    "Green [%d %%]"       <switch> (Terasse)  {zwave="21:3:command=switch_multilevel"}
Dimmer  LED_Terasse_B    "Blue [%d %%]"         <switch> (Terasse)  {zwave="21:4:command=switch_multilevel"}
Dimmer  LED_Terasse_Bright    "Brightness [%d %%]"       {zwave="21"}

The rainbow controller is based on MQTT, so log for MQTT around 10pm was looking as follows:

12/15/16 21:59:12.913 /myhome/command/LED_Terasse_R/state 6
12/15/16 21:59:12.944 /myhome/in/LED_Terasse_R 6
12/15/16 21:59:12.957 /myhome/state/LED_Terasse_R 6
12/15/16 21:59:13.930 /myhome/command/LED_Terasse_G/state 2
12/15/16 21:59:13.958 /myhome/in/LED_Terasse_G 2
12/15/16 21:59:13.972 /myhome/state/LED_Terasse_G 2
12/15/16 21:59:17.109 /myhome/state/LED_Terasse_R 6
12/15/16 21:59:17.179 /myhome/state/LED_Terasse_G 2
12/15/16 21:59:17.258 /myhome/state/LED_Terasse_Bright 6
12/15/16 21:59:19.784 /myhome/state/LED_Terasse_Bright ON
...
12/15/16 22:00:00.360 /myhome/command/LED_Terasse_R/state 0
12/15/16 22:00:00.391 /myhome/in/LED_Terasse_R 0
12/15/16 22:00:00.406 /myhome/state/LED_Terasse_R 0
12/15/16 22:00:01.384 /myhome/command/LED_Terasse_G/state 0
12/15/16 22:00:01.396 /myhome/in/LED_Terasse_G 0
12/15/16 22:00:01.406 /myhome/state/LED_Terasse_G 0
12/15/16 22:00:03.535 /myhome/state/LED_Terasse_R 0
12/15/16 22:00:03.602 /myhome/state/LED_Terasse_Bright 2
12/15/16 22:00:05.687 /myhome/state/LED_Terasse_Bright ON

For clarification - on 21:59 controller last time updated state of RGB Lightning by setting Red color to 6 and Green color to 2. And on 22:00 it started to switch it off by first setting Red to 0 and one second later setting green to 0.
The strange thing happens on 22:00:03, where Openhab reports, that Brightness is still 2, but it should be zero as both colors are now zero. Obviously green color remained on, even Openhab did report that it switched off.
Below is output of z-wave log:

2016-12-15 22:00:00.362 [DEBUG] [veMultiLevelSwitchCommandClass:163 ]- NODE 21: Creating new message for command SWITCH_MULTILEVEL_SET
2016-12-15 22:00:00.364 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 21: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-12-15 22:00:00.365 [DEBUG] [.z.internal.protocol.ZWaveNode:671 ]- NODE 21: Encapsulating message, instance / endpoint 2
2016-12-15 22:00:00.367 [DEBUG] [ZWaveMultiInstanceCommandClass:560 ]- NODE 21: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2016-12-15 22:00:00.368 [DEBUG] [b.z.i.protocol.ZWaveController:938 ]- Callback ID = 13
2016-12-15 22:00:00.370 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 1
2016-12-15 22:00:00.370 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 0
2016-12-15 22:00:00.374 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0E 00 13 15 07 60 0D 01 02 26 01 00 25 0D 91 
2016-12-15 22:00:00.378 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 21: Sending REQUEST Message = 01 0E 00 13 15 07 60 0D 01 02 26 01 00 25 0D 91 
2016-12-15 22:00:00.383 [DEBUG] [.ZWaveBinarySwitchCommandClass:146 ]- NODE 29: Creating new message for application command SWITCH_BINARY_SET
2016-12-15 22:00:00.385 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 29: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-12-15 22:00:00.387 [DEBUG] [.z.internal.protocol.ZWaveNode:671 ]- NODE 29: Encapsulating message, instance / endpoint 1
2016-12-15 22:00:00.389 [DEBUG] [ZWaveMultiInstanceCommandClass:560 ]- NODE 29: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-12-15 22:00:00.390 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 04 01 13 01 E8 
2016-12-15 22:00:00.390 [DEBUG] [b.z.i.protocol.ZWaveController:938 ]- Callback ID = 14
2016-12-15 22:00:00.392 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 1
2016-12-15 22:00:00.393 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:00.399 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 13 01 E8 
2016-12-15 22:00:00.393 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=0
2016-12-15 22:00:00.401 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 04 01 13 01 E8 
2016-12-15 22:00:00.404 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2016-12-15 22:00:00.405 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 21: Sent Data successfully placed on stack.
2016-12-15 22:00:00.464 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 07 00 13 0D 00 00 08 EE 
2016-12-15 22:00:00.466 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-12-15 22:00:00.466 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:00.467 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 13 0D 00 00 08 00 00 E0 
2016-12-15 22:00:00.469 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 09 00 13 0D 00 00 08 00 00 E0 
2016-12-15 22:00:00.470 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 0D 00 00 08 
2016-12-15 22:00:00.470 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 21: SendData Request. CallBack ID = 13, Status = Transmission complete and ACK received(0)
2016-12-15 22:00:00.472 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 15 07 60 0D 01 02 26 01 00 
2016-12-15 22:00:00.473 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 0D 00 00 08 
2016-12-15 22:00:00.474 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SendData, expected=SendData, cancelled=false
2016-12-15 22:00:00.474 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-12-15 22:00:00.475 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-12-15 22:00:00.475 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-12-15 22:00:00.476 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 21: Response processed after 97ms/4885ms.
2016-12-15 22:00:00.477 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 0
2016-12-15 22:00:00.479 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0E 00 13 1D 07 60 0D 01 01 25 01 00 25 0E 9A 
2016-12-15 22:00:00.480 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 29: Sending REQUEST Message = 01 0E 00 13 1D 07 60 0D 01 01 25 01 00 25 0E 9A 
2016-12-15 22:00:00.493 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 04 01 13 01 E8 
2016-12-15 22:00:00.495 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-12-15 22:00:00.496 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:00.497 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 13 01 E8 
2016-12-15 22:00:00.498 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 04 01 13 01 E8 
2016-12-15 22:00:00.498 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2016-12-15 22:00:00.499 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 29: Sent Data successfully placed on stack.
2016-12-15 22:00:01.376 [DEBUG] [ZWaveMultiLevelSwitchConverter:182 ]- Multilevel Switch MultiLevelPercentCommandConverter
2016-12-15 22:00:01.377 [DEBUG] [veMultiLevelSwitchCommandClass:163 ]- NODE 21: Creating new message for command SWITCH_MULTILEVEL_SET
2016-12-15 22:00:01.379 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 21: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-12-15 22:00:01.380 [DEBUG] [.z.internal.protocol.ZWaveNode:671 ]- NODE 21: Encapsulating message, instance / endpoint 3
2016-12-15 22:00:01.381 [DEBUG] [ZWaveMultiInstanceCommandClass:560 ]- NODE 21: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 3
2016-12-15 22:00:01.382 [DEBUG] [b.z.i.protocol.ZWaveController:938 ]- Callback ID = 15
2016-12-15 22:00:01.384 [DEBUG] [b.z.i.protocol.ZWaveController:620 ]- Enqueueing message. Queue length = 1
2016-12-15 22:00:03.497 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 0D 00 04 00 15 07 60 0D 02 02 26 03 00 AC 
2016-12-15 22:00:03.501 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:03.503 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0D 00 04 00 15 07 60 0D 02 02 26 03 00 AC 
2016-12-15 22:00:03.505 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 0D 00 04 00 15 07 60 0D 02 02 26 03 00 AC 
2016-12-15 22:00:03.507 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 15 07 60 0D 02 02 26 03 00 
2016-12-15 22:00:03.508 [DEBUG] [ApplicationCommandMessageClass:38  ]- NODE 21: Application Command Request (ALIVE:DONE)
2016-12-15 22:00:03.509 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 21: Incoming command class MULTI_INSTANCE
2016-12-15 22:00:03.510 [DEBUG] [ZWaveMultiInstanceCommandClass:145 ]- NODE 21: Received Multi-instance/Multi-channel Request
2016-12-15 22:00:03.511 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=0
2016-12-15 22:00:03.513 [DEBUG] [ZWaveMultiInstanceCommandClass:452 ]- NODE 21: Requested Command Class = SWITCH_MULTILEVEL (0x26)
2016-12-15 22:00:03.514 [DEBUG] [ZWaveMultiInstanceCommandClass:472 ]- NODE 21: Endpoint = 2, calling handleApplicationCommandRequest.
2016-12-15 22:00:03.515 [DEBUG] [veMultiLevelSwitchCommandClass:94  ]- NODE 21: Received Switch Multi Level Request
2016-12-15 22:00:03.516 [DEBUG] [veMultiLevelSwitchCommandClass:114 ]- NODE 21: Switch Multi Level report, value = 0
2016-12-15 22:00:03.517 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveCommandClassValueEvent
2016-12-15 22:00:03.518 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-12-15 22:00:03.519 [DEBUG] [.z.internal.ZWaveActiveBinding:450 ]- NODE 21: Got a value event from Z-Wave network, endpoint = 2, command class = SWITCH_MULTILEVEL, value = 0
2016-12-15 22:00:03.520 [DEBUG] [ApplicationCommandMessageClass:85  ]- Transaction not completed: node address inconsistent.
2016-12-15 22:00:03.533 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 07 00 13 0E 01 01 31 D4 
2016-12-15 22:00:03.536 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-12-15 22:00:03.536 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:03.540 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 13 0E 01 01 31 00 00 DA 
2016-12-15 22:00:03.542 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 09 00 13 0E 01 01 31 00 00 DA 
2016-12-15 22:00:03.544 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 0E 01 01 31 
2016-12-15 22:00:03.545 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 29: SendData Request. CallBack ID = 14, Status = Transmission complete, no ACK received(1)
2016-12-15 22:00:03.546 [ERROR] [b.z.i.p.s.SendDataMessageClass:141 ]- NODE 29: Node is DEAD. Dropping message.
2016-12-15 22:00:03.547 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-12-15 22:00:03.548 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-12-15 22:00:03.549 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 29: Response processed after 3068ms/4885ms.
2016-12-15 22:00:03.550 [DEBUG] [WaveController$ZWaveSendThread:1211]- Took message from queue for sending. Queue length = 0
2016-12-15 22:00:03.553 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0E 00 13 15 07 60 0D 01 03 26 01 00 25 0F 92 
2016-12-15 22:00:03.554 [DEBUG] [WaveController$ZWaveSendThread:1268]- NODE 21: Sending REQUEST Message = 01 0E 00 13 15 07 60 0D 01 03 26 01 00 25 0F 92 
2016-12-15 22:00:03.564 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 04 01 13 01 E8 
2016-12-15 22:00:03.566 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-12-15 22:00:03.566 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:03.568 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 13 01 E8 
2016-12-15 22:00:03.569 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 04 01 13 01 E8 
2016-12-15 22:00:03.569 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2016-12-15 22:00:03.570 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 21: Sent Data successfully placed on stack.
2016-12-15 22:00:03.577 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 09 00 04 00 15 03 20 03 02 C5 
2016-12-15 22:00:03.579 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:03.579 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-12-15 22:00:03.581 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 04 00 15 03 20 03 02 C5 
2016-12-15 22:00:03.583 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 09 00 04 00 15 03 20 03 02 C5 
2016-12-15 22:00:03.584 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 15 03 20 03 02 
2016-12-15 22:00:03.585 [DEBUG] [ApplicationCommandMessageClass:38  ]- NODE 21: Application Command Request (ALIVE:DONE)
2016-12-15 22:00:03.586 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 21: Incoming command class BASIC
2016-12-15 22:00:03.587 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:74  ]- NODE 21: Received Basic Request
2016-12-15 22:00:03.588 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:107 ]- NODE 21: Basic report, value = 0x02
2016-12-15 22:00:03.588 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveCommandClassValueEvent
2016-12-15 22:00:03.589 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-12-15 22:00:03.589 [DEBUG] [.z.internal.ZWaveActiveBinding:450 ]- NODE 21: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 2
2016-12-15 22:00:03.704 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 07 00 13 0F 00 00 0E EA 
2016-12-15 22:00:03.706 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-12-15 22:00:03.706 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:03.708 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 13 0F 00 00 0E 00 00 E4 
2016-12-15 22:00:03.709 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 09 00 13 0F 00 00 0E 00 00 E4 
2016-12-15 22:00:03.710 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 0F 00 00 0E 
2016-12-15 22:00:03.711 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 21: SendData Request. CallBack ID = 15, Status = Transmission complete and ACK received(0)
2016-12-15 22:00:03.712 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 15 07 60 0D 01 03 26 01 00 
2016-12-15 22:00:03.713 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 0F 00 00 0E 
2016-12-15 22:00:03.714 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SendData, expected=SendData, cancelled=false
2016-12-15 22:00:03.714 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2016-12-15 22:00:03.715 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2016-12-15 22:00:03.715 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-12-15 22:00:03.716 [DEBUG] [WaveController$ZWaveSendThread:1327]- NODE 21: Response processed after 161ms/4885ms.
2016-12-15 22:00:03.838 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 0D 00 04 00 15 07 60 0D 01 01 26 03 02 AE 
2016-12-15 22:00:03.841 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-12-15 22:00:03.841 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:03.843 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0D 00 04 00 15 07 60 0D 01 01 26 03 02 AE 
2016-12-15 22:00:03.845 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 0D 00 04 00 15 07 60 0D 01 01 26 03 02 AE 
2016-12-15 22:00:03.846 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 15 07 60 0D 01 01 26 03 02 
2016-12-15 22:00:03.847 [DEBUG] [ApplicationCommandMessageClass:38  ]- NODE 21: Application Command Request (ALIVE:DONE)
2016-12-15 22:00:03.848 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 21: Incoming command class MULTI_INSTANCE
2016-12-15 22:00:03.849 [DEBUG] [ZWaveMultiInstanceCommandClass:145 ]- NODE 21: Received Multi-instance/Multi-channel Request
2016-12-15 22:00:03.850 [DEBUG] [ZWaveMultiInstanceCommandClass:452 ]- NODE 21: Requested Command Class = SWITCH_MULTILEVEL (0x26)
2016-12-15 22:00:03.851 [DEBUG] [ZWaveMultiInstanceCommandClass:472 ]- NODE 21: Endpoint = 1, calling handleApplicationCommandRequest.
2016-12-15 22:00:03.852 [DEBUG] [veMultiLevelSwitchCommandClass:94  ]- NODE 21: Received Switch Multi Level Request
2016-12-15 22:00:03.853 [DEBUG] [veMultiLevelSwitchCommandClass:114 ]- NODE 21: Switch Multi Level report, value = 2
2016-12-15 22:00:03.854 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveCommandClassValueEvent
2016-12-15 22:00:03.855 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-12-15 22:00:03.855 [DEBUG] [.z.internal.ZWaveActiveBinding:450 ]- NODE 21: Got a value event from Z-Wave network, endpoint = 1, command class = SWITCH_MULTILEVEL, value = 2
2016-12-15 22:00:03.856 [WARN ] [.z.internal.ZWaveActiveBinding:467 ]- NODE 21: No item bound for event, endpoint = 1, command class = SWITCH_MULTILEVEL, value = 2, ignoring.
2016-12-15 22:00:03.857 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 15 07 60 0D 01 03 26 01 00 
2016-12-15 22:00:03.859 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 15 07 60 0D 01 01 26 03 02 
2016-12-15 22:00:03.859 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=ApplicationCommandHandler, expected=SendData, cancelled=false
2016-12-15 22:00:05.659 [DEBUG] [eController$ZWaveReceiveThread:1481]- Receive Message = 01 0C 00 04 00 15 06 31 05 04 22 00 13 E5 
2016-12-15 22:00:05.662 [DEBUG] [eController$ZWaveReceiveThread:1405]- Receive queue ADD: Length=1
2016-12-15 22:00:05.662 [DEBUG] [b.z.i.protocol.ZWaveController:1163]- Receive queue TAKE: Length=0
2016-12-15 22:00:05.664 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 0C 00 04 00 15 06 31 05 04 22 00 13 E5 
2016-12-15 22:00:05.666 [DEBUG] [b.z.i.protocol.ZWaveController:1164]- Process Message = 01 0C 00 04 00 15 06 31 05 04 22 00 13 E5 
2016-12-15 22:00:05.667 [DEBUG] [b.z.i.protocol.ZWaveController:192 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 15 06 31 05 04 22 00 13 
2016-12-15 22:00:05.668 [DEBUG] [ApplicationCommandMessageClass:38  ]- NODE 21: Application Command Request (ALIVE:DONE)
2016-12-15 22:00:05.668 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 21: Incoming command class SENSOR_MULTILEVEL
2016-12-15 22:00:05.669 [DEBUG] [veMultiLevelSensorCommandClass:97  ]- NODE 21: Received Sensor Multi Level Request
2016-12-15 22:00:05.670 [DEBUG] [veMultiLevelSensorCommandClass:131 ]- NODE 21: Sensor Multi Level REPORT received
2016-12-15 22:00:05.670 [DEBUG] [veMultiLevelSensorCommandClass:141 ]- NODE 21: Sensor Type = Power(4), Scale = 0
2016-12-15 22:00:05.671 [DEBUG] [veMultiLevelSensorCommandClass:150 ]- NODE 21: Sensor Value = 1.9
2016-12-15 22:00:05.672 [DEBUG] [b.z.i.protocol.ZWaveController:635 ]- Notifying event listeners: ZWaveMultiLevelSensorValueEvent
2016-12-15 22:00:05.672 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2016-12-15 22:00:05.673 [DEBUG] [.z.internal.ZWaveActiveBinding:450 ]- NODE 21: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 1.9
2016-12-15 22:00:05.675 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 15 07 60 0D 01 03 26 01 00 
2016-12-15 22:00:05.676 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 15 06 31 05 04 22 00 13 
2016-12-15 22:00:05.677 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=ApplicationCommandHandler, expected=SendData, cancelled=false

According to z-wave log there is node 29 in between, which is dead at the moment. But my question is what leaded to ignoring Green command. Could it be, that previous command(setting red color to zero) was retransmitted after setting green command, and there was still old value for green?

2

I have no explanation, but my Fibaro RGBW was misbehaving with unexpected colours last night and this morning, but is now fine.

3

I don’t know, but looking at the log, the command to set green to 0 was sent and acked by the device, so it should have worked (ie transaction 15 below)…

Pasted image1342×596 144 KB

4

Chris, I have a question regarding two endpoints in same z-wave node: when controller wants to change value of endpoint 2, for example, should it still encode value of endpoints 1 and 3 in same message?
I have following scenario in my mind if this is the case: controller sends first message to set red color to zero. In this message green is still at 2. This message for some reasons is delayed. After a while controller sends second message with both colors set to zero. This message arrives to node normally. But after this first message is being retransmitted by somebody and finaly arrives at node. As it still has green color at 2 it is switched on back.

5

It’s not possible to encode more than one endpoint in a single message.

The proper way to solve this issue is to use the colour command class which allows many colours to be set in the same message to ensure consistency. However this is only supported in OH2.