Hi @Chris, here is how far I got it with looking into the logfiles. I think I have a good hint on what is going on. The Power_meter updates in the logfiles are for the Qubino Flush 2 Relays are for endpoint=0 (which is the overall power), but not for endpoints=1 and endpoints=2, which are the individual switches. I do see in the logfiles lines like this:
2017-01-08 17:04:57.605 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Application Command Request (ALIVE:DONE)
2017-01-08 17:04:57.606 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from DONE
2017-01-08 17:04:57.606 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 2: Incoming command class METER
2017-01-08 17:04:57.606 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Received METER command V3
2017-01-08 17:04:57.606 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=W(2), Value=17.3
2017-01-08 17:04:57.606 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-01-08 17:04:57.606 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-01-08 17:04:57.606 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = METER, value = 17.3
2017-01-08 17:04:57.607 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:c1977c1d:node2:meter_watts to 17.3 [DecimalType]
2017-01-08 17:04:57.607 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_W
which is endpoint=0 and the command class is METER (!!). It looks to me the values are for the individual endpoints though ??? There are in fact tons of endpoint=0 messages for the nodes in the lofile like this, so the Qubino is reporting as it should, but it ends up wrongly.
One possible other issue I see is a mismatch comment E_KWh<> E_W in the logilfe during init phase (nodes get initialised). This looks like a bug to me, as the message gives scale=W.
Later on I found a different pattern for a Qubino Flush 2 Relays:
2017-01-08 17:15:00.426 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 57: Application Command Request (ALIVE:DONE)
2017-01-08 17:15:00.427 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 57: Starting initialisation from DONE
2017-01-08 17:15:00.427 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@63ef849a already registered
2017-01-08 17:15:00.427 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 57: Incoming command class METER
2017-01-08 17:15:00.427 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 57: Received METER command V3
2017-01-08 17:15:00.427 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 57: Meter: Type=Electric(1), Scale=W(2), Value=30.2
2017-01-08 17:15:00.427 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
and the nothing for this node anymore. I found this only once.
Then I tried turning on/off switches (from the Basic UI) to trigger power meter updates:
2017-01-08 17:48:40.888 [ItemCommandEvent ] - Item ‘Light_FF_DiningRoom_Rear’ received command ON
2017-01-08 17:48:40.907 [ItemStateChangedEvent ] - Light_FF_DiningRoom_Rear changed from OFF to ON
2017-01-08 17:48:41.913 [ItemCommandEvent ] - Item ‘Light_FF_LivingRoom_Sofa’ received command OFF
2017-01-08 17:48:41.930 [ItemStateChangedEvent ] - Light_FF_LivingRoom_Sofa changed from ON to OFF
2017-01-08 17:48:42.755 [ItemCommandEvent ] - Item ‘Light_SF_Mezzanine_Stairs’ received command ON
2017-01-08 17:48:42.788 [ItemStateChangedEvent ] - Light_SF_Mezzanine_Stairs changed from OFF to ON
2017-01-08 17:48:44.277 [ItemCommandEvent ] - Item ‘Light_FF_LivingRoom_Rear’ received command OFF
2017-01-08 17:48:44.282 [ItemStateChangedEvent ] - Light_FF_LivingRoom_Rear changed from ON to OFF
2017-01-08 17:48:44.851 [ItemCommandEvent ] - Item ‘Light_FF_Stairs’ received command ON
2017-01-08 17:48:44.857 [ItemStateChangedEvent ] - Light_FF_Stairs changed from OFF to ON
2017-01-08 17:48:45.591 [ItemCommandEvent ] - Item ‘Light_FF_GuestBedroom_Sofa’ received command ON
2017-01-08 17:48:45.626 [ItemStateChangedEvent ] - Light_FF_GuestBedroom_Sofa changed from OFF to ON
2017-01-08 17:48:46.845 [ItemCommandEvent ] - Item ‘Light_FF_GuestBedroom_Rear’ received command OFF
2017-01-08 17:48:46.848 [ItemStateChangedEvent ] - Light_FF_GuestBedroom_Rear changed from ON to OFF
This triggered 2 change events:
2017-01-08 17:49:16.371 [ItemStateChangedEvent ] - Light_FF_LivingRoom_Rear_Power changed from 9.6 to 0
2017-01-08 17:49:17.652 [ItemStateChangedEvent ] - Light_FF_LivingRoom_Sofa_Power changed from 18.4 to 0
I first did not understand this, but after some digging there was (by change) a POLL event in between:
2017-01-08 17:49:11.165 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Polling…
2017-01-08 17:49:11.165 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Polling zwave:device:c1977c1d:node57:switch_binary
2017-01-08 17:49:11.165 [DEBUG] [converter.ZWaveBinarySwitchConverter] - NODE 57: Generating poll message for SWITCH_BINARY, endpoint 0
2017-01-08 17:49:11.165 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 57: Creating new message for application command SWITCH_BINARY_GET
…
and this leads to
2017-01-08 17:49:16.358 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 57: Application Command Request (ALIVE:DONE)
2017-01-08 17:49:16.358 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 57: Starting initialisation from DONE
2017-01-08 17:49:16.358 [DEBUG] [ve.internal.protocol.ZWaveController] - Event Listener org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer@69978b4b already registered
2017-01-08 17:49:16.358 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 57: Incoming command class MULTI_INSTANCE
2017-01-08 17:49:16.358 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 57: Received MULTI_INSTANCE command V2
2017-01-08 17:49:16.358 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 57: Requested Command Class = METER (0x32)
2017-01-08 17:49:16.358 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 57: Endpoint = 1, calling handleApplicationCommandRequest.
2017-01-08 17:49:16.358 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 57: Received METER command V3
2017-01-08 17:49:16.358 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 57: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2017-01-08 17:49:16.358 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveMeterValueEvent
2017-01-08 17:49:16.358 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got an event from Z-Wave network: ZWaveMeterValueEvent
2017-01-08 17:49:16.358 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Got a value event from Z-Wave network, endpoint = 1, command class = METER, value = 0E+1
2017-01-08 17:49:16.358 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Updating channel state zwave:device:c1977c1d:node57:meter_watts1 to 0 [DecimalType]
2017-01-08 17:49:16.359 [DEBUG] [ternal.converter.ZWaveMeterConverter] - Not the right scale E_KWh <> E_W
similar for endpoint 2 afterwards. This is command is now class MULTI_INSTANCE, while the others are METER ??? It seems like this is the reason why the power_meter updates for endpoints 1 and 2 are ending up as channel updates for endpoint 0 ? Is this a mis-config of the Qubino, I don’t see where to configure this differently ? Or something else ?
Btw, there is a frequent ERROR message in the logfile, here an example for a Qubino Flush Shutter (!), the pattern is:
2017-01-08 17:05:52.394 [ERROR] [ocol.ZWaveController$ZWaveSendThread] - NODE 29: Timeout while sending message. Requeueing - 1 attempts left!
2017-01-08 17:05:52.394 [ERROR] [l.serialmessage.SendDataMessageClass] - NODE 29: Got an error while sending data. Resending message.
2017-01-08 17:05:52.394 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 117. Queue={}
2017-01-08 17:05:52.395 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 116
2017-01-08 17:05:52.395 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 1D 03 70 05 56 25 01 FF
2017-01-08 17:05:52.395 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 29: Sending REQUEST Message = 01 0A 00 13 1D 03 70 05 56 25 01 FF
2017-01-08 17:05:52.404 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-01-08 17:05:52.404 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-08 17:05:52.404 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-01-08 17:05:52.404 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-01-08 17:05:52.404 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-01-08 17:05:52.405 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 29: Sent Data successfully placed on stack.
2017-01-08 17:05:52.420 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 01 00 00 02 E8
2017-01-08 17:05:52.420 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-01-08 17:05:52.420 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 01 00 00 02 00 00 E6
2017-01-08 17:05:52.420 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 01 00 00 02 00 00 E6
2017-01-08 17:05:52.420 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 00 00 02
2017-01-08 17:05:52.420 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 29: SendData Request. CallBack ID = 1, Status = Transmission complete and ACK received(0)
2017-01-08 17:05:52.421 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=SendData[0x13], type=Request[0x00], priority=Config, dest=29, callback=
1, payload=1D 03 70 05 56
2017-01-08 17:05:52.421 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0
, payload=01 00 00 02
2017-01-08 17:05:52.421 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=SendData, callback id=1, expected=ApplicationCommandHandler, cancelled=false MIS
MATCH
It does not look to me this is related to the power meter issue, but I thought this might be interesting.