[bug] NAS-WR01ZE: kWh meter value displayed as negative number

[andre-richter]

Version

Checklist:

• I am not using HomeAssistant. Or: a 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 problem was not mentioned there.

Build/Run method

• Docker
• PKG
• Snap package
• Manually built (git clone - yarn install - yarn run build )

zwavejs2mqtt version: 4.3.1
zwave-js version: 7.5.1

Describe the bug

The kWh meter of the NAS-WR01ZE (https://devices.zwave-js.io/?jumpTo=0x0258:0x0200:0x1027:2.32) smart plug is reported/displayed as a negative number.

After resetting the accumulated meter values, sane positive values are reported for sometime, but at some point it flips to negative.

zwavejs2mqtt.log:

2021-05-24 20:46:26.806 DEBUG SOCKET: Event ZWAVE_API emitted to FHb1fJMDSyU3lbGJAAAB
2021-05-24 20:46:26.808 INFO ZWAVE: Calling api refreshCCValues with args: [ 42, 50, [length]: 2 ]
2021-05-24 20:46:26.971 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.13 => -21474836.13
2021-05-24 20:46:27.120 INFO ZWAVE: Node 42: value updated: 50-0-value-66049 27.85 => 27.49
2021-05-24 20:46:27.266 INFO ZWAVE: Node 42: value updated: 50-0-value-66561 234.62 => 234.93
2021-05-24 20:46:27.410 INFO ZWAVE: Node 42: value updated: 50-0-value-66817 0.25 => 0.25

zwavejs.log:

2021-05-24T20:46:26.811Z CNTRLR » [Node 042] querying meter value (type = Electric, scale = kWh, rate type = Con
                                  sumed)...
2021-05-24T20:46:26.975Z CNTRLR » [Node 042] querying meter value (type = Electric, scale = W, rate type = Consu
                                  med)...
2021-05-24T20:46:27.123Z CNTRLR » [Node 042] querying meter value (type = Electric, scale = V, rate type = Consu
                                  med)...
2021-05-24T20:46:27.268Z CNTRLR » [Node 042] querying meter value (type = Electric, scale = A, rate type = Consu
                                  med)...

The negative value also gets picked up by Home Assistant.

To Reproduce

Let the device report for some time.

Expected behavior

A sane number being reported.

Additional context

I am unsure if this is a SW issue or a quirk with the device itself, since it looks like bit 31 is being flipped.
The screenshot below was made not too long after a reset of the accumulated values. If I take the negative number and flip bit 31 from 1 to 0, we get 35, which would be 0.35 kWh I presume, and that would make sense given that a reset was done earlier.

This is happening on multiple of the same devices I own, not only a single one.

[andre-richter]

Update:

Caught in the act on another node:

2021-05-24 21:14:30.202 INFO ZWAVE: Node 41: value updated: 50-0-value-65537 0.27 => 0.29
2021-05-24 21:19:30.187 INFO ZWAVE: Node 41: value updated: 50-0-value-65537 0.29 => 0.33
2021-05-24 21:24:30.172 INFO ZWAVE: Node 41: value updated: 50-0-value-65537 0.33 => 0.37
2021-05-24 21:29:30.156 INFO ZWAVE: Node 41: value updated: 50-0-value-65537 0.37 => 0.39
2021-05-24 21:34:30.142 INFO ZWAVE: Node 41: value updated: 50-0-value-65537 0.39 => -21474836.05

[rickk88]

Also see https://community.home-assistant.io/t/energy-consumption-for-neo-coolcam-plug/219844/5?u=rickkramer

[andre-richter]

Thanks @rickk88!

From what I could see yesterday, it might really just be bit 31 randomly toggling between 1 and 0. Anyone agrees?

@robertsLando would zwave_js be open to implement masking this bit out as a quirk for this particular device?

[robertsLando]

I think this should be handled on zjs side.
CC
@AlCalzone @blhoward2

[AlCalzone]

@andre-richter any chance you could catch this in a zwave-js log with loglevel debug? I wonder if it is only that bit.

[andre-richter]

@AlCalzone, are you particularly interested in the event of flipping from sane to negative value or something else?
I could set up that experiment later, and increase the reporting interval to report every minute or so.

In the meantime, another experiment completed, giving more insight. I have one of those devices connected to a consumer that constantly drains ~27 W. I had set the reporting interval to 10 minutes before resetting:

2021-05-25 08:38:43.108 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 0 => 0
2021-05-25 08:48:43.034 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 0 => 0
2021-05-25 08:58:42.973 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 0 => 0
2021-05-25 09:08:42.914 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 0 => -21474836.46
2021-05-25 09:18:42.857 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.46 => -21474836.46
2021-05-25 09:28:42.795 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.46 => -21474836.44
2021-05-25 09:38:43.739 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.44 => -21474836.44
2021-05-25 09:48:43.679 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.44 => -21474836.42
2021-05-25 09:58:43.618 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.42 => -21474836.42
2021-05-25 10:08:43.557 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.42 => -21474836.4
2021-05-25 10:18:43.503 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.4 => -21474836.4
2021-05-25 10:28:43.444 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.4 => -21474836.4
2021-05-25 10:38:43.388 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.4 => 0.1
2021-05-25 10:48:43.329 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 0.1 => 0.1
2021-05-25 10:58:43.271 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 0.1 => -21474836.36

Exactly after 2 hours, it incidentally switched back to a sane value.
We would expect to see 2 h * 27 W = 54 Wh, or 0.05 kWh respectively. The reported value is double, which seems in line with what was reported here: https://community.home-assistant.io/t/energy-consumption-for-neo-coolcam-plug/219844/8.

Taking the last timestamp, which is after 140 minutes, we would expect 140 minutes * 27 W = 63 Wh, aka 0.06 kWh

The reported value is -21474836.36.
Naively converting this (not sure if this is valid, aka what the actual number representation used in the zwave value is):

-21474836.36 * 100 = -2147483636
-2147483636 & 0x7fff_ffff = 12
12 / 100 = 0.12 kWh

Which would again be double the expected value.

[AlCalzone]

I'm interested in the raw commands that get sent - best case some correct ones and some flipped ones. Make sure to set the loglevel of the zwave-js logger to debug, so we can see this.

Naively converting this (not sure if this is valid, aka what the actual number representation used in the zwave value is):

Seems correct, in Z-Wave floats are just encoded as integers plus precision (# of decimal places).

Based on the history of values I think this device has some big problems with encoding values that aren't divisible by 0.1.

        0.00 => 0.00 ✔
-21474836.46 => 0.02
-21474836.44 => 0.04
-21474836.42 => 0.06
-21474836.40 => 0.08
        0.10 => 0.10 ✔
-21474836.36 => 0.12

Which would again be double the expected value.

Not much we can do about that if the device reports this.

[andre-richter]

Based on the history of values I think this device has some big problems with encoding values that aren't divisible by 0.1.

        0.00 => 0.00 ✔
-21474836.46 => 0.02
-21474836.44 => 0.04
-21474836.42 => 0.06
-21474836.40 => 0.08
        0.10 => 0.10 ✔
-21474836.36 => 0.12

Some more from this run:

2021-05-25 11:08:43.212 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.36 => -21474836.36
2021-05-25 11:18:43.157 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.36 => -21474836.34
2021-05-25 11:28:43.095 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.34 => -21474836.34
2021-05-25 11:38:43.037 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 -21474836.34 => 0.16
2021-05-25 11:48:42.981 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 0.16 => 0.16
2021-05-25 11:58:42.924 INFO ZWAVE: Node 42: value updated: 50-0-value-65537 0.16 => 0.18

Which would again be double the expected value.

Not much we can do about that if the device reports this.

So some correcting math on the value on retrieval is not feasible? I can hack it into my home-assistant installation, but before I go there, I'm trying to understand to what extend zwave_js is the correct place to correct such awful quirks.

Trying to set up your experiment now.

[AlCalzone]

I'm trying to understand to what extend zwave_js is the correct place to correct such awful quirks.

Generally we do not try to fix application level device quirks in the driver for two reasons:

1. While these values seem obviously wrong, it is impossible to tell automatically whether the value was reported like this on purpose or not
2. It is not our job to clean up the manufacturers' mess. Sure, we work around some things to make the devices usable at all, but fiddling around with the reported values doesn't belong in this project.

Other projects (like SmartThings) have done these things by writing device-specific integrations, which in the end just leads to the manufacturers saying "but it works in XYZ 🤷🏻‍♂️" when in reality they are just too lazy to fix their shit. The stuff above would have been caught by QA if they bothered to test it. Maybe having a majority of their users complain because their stuff does not work with a standards-compliant software will change that mentality.

Some manufacturers do care - I've already seen a case where we had a beta firmware version to test just hours after a bug report.

[andre-richter]

I don't know what is different this time. Currently having a run from 0 to 0.14 kWh for almost 3 hours without any negative value. Will update once there is a repro.

[andre-richter]

@AlCalzone logs at: https://send.tresorit.com/a#wHJq_Ng_rc3XDLPmKNw6XQ