Greenwave Powernode 6 measurements reported in wrong instance

[katiuskt]

Checklist:

• My problem is not within Home Assistant or the ZWave JS integration. Or: a Home Assistant developer has told me to come here.
• My problem is not within ZWaveJS2MQTT. Or: a ZWaveJS2MQTT developer has told me to come here.
• I have checked the troubleshooting section and my problem is not described there.
• I have read the changelog and my problem was not mentioned there.

Describe the bug
Measurements still not reported in their right sockets despite #2885
Please, take a look into the Additional Context for more details

Device information
Which device(s) is/are affected (manufacturer/model)? GreenWave Reality Inc. Multi-socket PowerNode (6-plug) NP240 / NP242
What is/are the node IDs? 2, 12

Did you change anything?

• Yes: (please describe)
• No

Did this use to work before?

• Don't know, this is a new device
• No, it never worked anywhere
• Yes, in: (specify application with versions)
• No, it never worked properly before

How are you using node-zwave-js

• zwavejs2mqtt (latest) docker image
• zwavejs2mqtt (dev) docker image
• zwavejs2mqtt Manual Docker build
  • node-zwave-js branch:
  • zwavejs2mqtt branch:
• ioBroker.zwave2 adapter
• HomeAssistant version XYZ
• Pkg
• Manual Docker build
  • node-zwave-js branch:
  • zwavejs2mqtt branch:
• node-red-contrib-zwave-js
  • Module version (double click node):
• Manually built (as described in the docs)
• Other:

To Reproduce

Steps to reproduce the behavior:

1. Go to 'Control Panel'
2. Click on Greenwave PowerStrip 6 Node
3. Scroll down to 'Meter' and click into 'Refresh'
4. [NODE-50-1-value-66049] Electric Consumed [W] and [NODE-50-1-value-65537] Electric Consumed [kWh] fields will be updated with not-socket1 information. [NODE-50-X-value-65537] (for X from 2 to 6) won't be updated with the kWh consumption of their respective sockets.

Additional context

I'm pretty sure this issue is related with the #2792 raised a few days ago (already fixed on v7.8.0)

After zwavejs (and zwavejs2mqtt) upgrade to be sure to we already have #2885 included, some things have been improved but some others don't.

Before upgrade:

1. kWh information for each instance of the device was pulled periodically (no issue with this)
2. kWh information of each socket was working OK. Every 1 hour (poll time of 3600s) each socket got updated its kWh information.
3. However, without the patch, the Watt information, didn't work. There is/was no need to refresh/automatic pull to get watt information automatically updated but the problem was the information was always reported on socket 1. This was fixed with feat: add compat flag to treat destination endpoint as source #2885 🎉

After upgrade:

1. kWh information is still needed to be pulled periodically (no issue with this) 👍
2. Doing that, it only updates kWh values at instance 1 of the node (although that socket doesn't have any device powered). The other sockets kWh information aren't updated. 👎
3. You don't need any automatic pull/refresh to get the Watt information (same behavior as before). Now, the improvement: watt information now is reported on its right socket. Hurrah! 👍
   However, if you force a meter refresh (manually or by an automatic polling) because, as I said, you need it in order to get updated the kWh information, things mess up: 👎
   a. Watt information is shown in socket 1. Not its real socket 1 consumption because there is no device on it
   b. kWh information is shown in socket 1. Not its real socket 1 consumption because there is no device on it
   c. kWh information of the other sockets aren't updated

Without refreshing/polling we have this (which is OK): [12-50-3-value-66049] Electric Consumed [W] value changes automatically (8.9W, 9.9W,... whatever) and no mess at socket 1:

However, if I try to refresh (at 13:15 UTC), [12-50-1-value-65537] Electric Consumed [kWh] is updated:

and also [12-50-1-value-66049] Electric Consumed [W] is also updated:

Eventually they go back to 0kWh/0W at socket 1 but kWh of socket 3 (where I have a powered device) wasn't updated at all:

Taking a look at log I think the root cause for points 3.a and 3.b might be information is reported at "Endpoint 0" (? socket only have 6 sockets). According log there is no map for Endpoint 0 so value is assigned to "Endpoint 1" no matter what.
For instance, for the above 0.4893kWh into the second snapshot:

2021-06-28T13:16:09.459Z SERIAL « 0x011a0004000c12600d0300320221840000131d00090000131c7e0072          (28 bytes)
2021-06-28T13:16:09.460Z CNTRLR   [Node 012] [~] [Meter] value[65537]: 0 => 0.4893                  [Endpoint 0]
2021-06-28T13:16:09.460Z SERIAL » [ACK]                                                                   (0x06)
2021-06-28T13:16:09.460Z DRIVER « [Node 012] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      0
                                    │ destination: 0
                                    └─[MeterCCReport]
                                        type:        Electric
                                        scale:       kWh
                                        rate type:   Consumed
                                        value:       0.4893
                                        time delta:  9 seconds
                                        prev. value: 0.4892
2021-06-28T13:16:09.461Z CNTRLR   [Node 012] Mapping unsolicited report from root device to first supporting end
                                  point #1
2021-06-28T13:16:09.461Z CNTRLR   [Node 012] [~] [Meter] value[65537]: 0 => 0.4893                  [Endpoint 1]
2021-06-28T13:16:10.753Z SERIAL « 0x011a0004000c12600d0103320221340000005e0009000000897e0015          (28 bytes)

Same seems to happen with those 9.4W assigned to socket 1 too:

2021-06-28T13:16:19.539Z SERIAL « 0x011a0004000c12600d0300320221340000005e0009000000897e0014          (28 bytes)
2021-06-28T13:16:19.540Z CNTRLR   [Node 012] [~] [Meter] value[66049]: 0 => 9.4                     [Endpoint 0]
2021-06-28T13:16:19.540Z SERIAL » [ACK]                                                                   (0x06)
2021-06-28T13:16:19.540Z DRIVER « [Node 012] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      0
                                    │ destination: 0
                                    └─[MeterCCReport]
                                        type:        Electric
                                        scale:       W
                                        rate type:   Consumed
                                        value:       9.4
                                        time delta:  9 seconds
                                        prev. value: 13.7
2021-06-28T13:16:19.540Z CNTRLR   [Node 012] Mapping unsolicited report from root device to first supporting end
                                  point #1
2021-06-28T13:16:19.541Z CNTRLR   [Node 012] [~] [Meter] value[66049]: 0 => 9.4                     [Endpoint 1]
2021-06-28T13:16:19.753Z SERIAL « 0x011a0004000c12600d0103320221340000007d00090000005e7e00e1          (28 bytes)

Still guessing, I think root cause for 3.c (kWh information for other sockets aren't updated) could be related somehow. It sounds like information is asked for socket X but it is answered to endpoint 0 which turns out to be mapped to endpoint 1 and not its real endpoint X. Does it makes any sense?

2021-06-28T13:16:09.311Z CNTRLR » [Node 012] querying meter value (type = Electric, scale = kWh)... [Endpoint 3]
2021-06-28T13:16:09.313Z SERIAL » 0x010e00130c07600d00033201002555c4                                  (16 bytes)
2021-06-28T13:16:09.313Z DRIVER » [Node 012] [REQ] [SendData]
                                  │ transmit options: 0x25
                                  │ callback id:      85
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      0
                                    │ destination: 3
                                    └─[MeterCCGet]
                                        scale: kWh
2021-06-28T13:16:09.316Z SERIAL « [ACK]                                                                   (0x06)
2021-06-28T13:16:09.324Z SERIAL « 0x0104011301e8                                                       (6 bytes)
2021-06-28T13:16:09.324Z SERIAL » [ACK]                                                                   (0x06)
2021-06-28T13:16:09.325Z DRIVER « [RES] [SendData]
                                    was sent: true
2021-06-28T13:16:09.386Z SERIAL « 0x0118001355000007027e7f7f7f7f0000030408000003010000d7              (26 bytes)
2021-06-28T13:16:09.387Z SERIAL » [ACK]                                                                   (0x06)
2021-06-28T13:16:09.387Z DRIVER « [REQ] [SendData]
                                    callback id:     85
                                    transmit status: OK
2021-06-28T13:16:09.459Z SERIAL « 0x011a0004000c12600d0300320221840000131d00090000131c7e0072          (28 bytes)
2021-06-28T13:16:09.460Z CNTRLR   [Node 012] [~] [Meter] value[65537]: 0 => 0.4893                  [Endpoint 0]
2021-06-28T13:16:09.460Z SERIAL » [ACK]                                                                   (0x06)
2021-06-28T13:16:09.460Z DRIVER « [Node 012] [REQ] [ApplicationCommand]
                                  └─[MultiChannelCCCommandEncapsulation]
                                    │ source:      0
                                    │ destination: 0
                                    └─[MeterCCReport]
                                        type:        Electric
                                        scale:       kWh
                                        rate type:   Consumed
                                        value:       0.4893
                                        time delta:  9 seconds
                                        prev. value: 0.4892
2021-06-28T13:16:09.461Z CNTRLR   [Node 012] Mapping unsolicited report from root device to first supporting end
                                  point #1
2021-06-28T13:16:09.461Z CNTRLR   [Node 012] [~] [Meter] value[65537]: 0 => 0.4893                  [Endpoint 1]
2021-06-28T13:16:10.753Z SERIAL « 0x011a0004000c12600d0103320221340000005e0009000000897e0015          (28 bytes)

Logfile:
zwavejs_2021-06-28.log

[AlCalzone]

Endpoint 0 is the "root" endpoint, meaning the device itself and not one of the outlets. Some devices use that to report the combined consumption. Can you confirm that, e.g. by adding two similar devices in two outlets and then look at the value if it is roughly double?

Looks like the device is also swapping the source/destination endpoint in the queries it receives. We can test if adding that behavior to the flag is enough to make it work.

[katiuskt]

Sure. I have another node (ID 2) with the same powerstrip and more devices powered on it. As I thought it would be easier to see the issue on NODE 12 I reported it but on this NODE 2 it happens the same.

Starting scenario (please, forget the ugly 'unknown' entity. I don't know why it appeared back in time). Powered devices are on sockets 2, 4 and 6:

Please find attached log when I hit Refresh option:
zwavejs_2021-06-28_node2.log

I wasn't able to take snapshots to each status change but values changed on socket 1 with this sequence (each one in its proper field according the unit of measurement): 0.5289kWh -> 22,7W -> 0.4503kWh -> 0W -> 0.1842kWh -> 11.8W -> 0kWh -> (...) -> 0.287kWh -> 1.2W
It doesn't seem to be the sum of the values. My guess (based on the attached devices): those 22,7W belongs to socket 2, those 11.8W belongs to socket 4 and those 1.2W to the device in socket 6.

To me it seems like hitting the "refresh" button it starts some kind of loop and it reports (on socket 1) the W/kWh information of each socket until it reaches the sixth one and its information remains on socket 1 (unless you click on [2-50-1-reset] to clean it up)

Please, notice during the whole process, Watt information of each socket (2-50-X-value-65537) was being updated on their respective fields with no issue.

[AlCalzone]

Because the device responds with source 0, destination 0 when we query the individual endpoints, the response isn't detected as the response to our request. It then gets treated like an unsolicited message and gets mapped to the first supporting endpoint (which is something I'm looking to change).

I'll update the compat flag to also set a different source endpoint when querying the device, hoping it will respond with its endpoint values then. If that doesn't work, I'll need one of those things to test hands-on. Debugging such a severely misbehaving device via issues and screenshots is wasting time I could better invest elsewhere.

[AlCalzone]

PR is up at #2919 for testing.