home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
69.75k stars 28.91k forks source link

Enphase integration reporting erroneous data causing issues in the Energy panel #120091

Open MeanderingNL opened 2 weeks ago

MeanderingNL commented 2 weeks ago

The problem

Hi all,

I am using the Enphase integration to track my solarpanels and use that data in the Energy panel.

I have noticed unusual patterns on the Energy panel in Home Assistant, where incorrect values/graphics are shown:

Energy Usage

I am using the DAILY production total in this sample, but the LIFE-TIME production total also shows this problem.

Looking at the individual datasource it shows dropouts in the data, reporting a ZERO value in a datasource that is cummulative (for the DAY total or the LIFE-TIME production totals:

Production1

Zoomed in:

Production1 Zoom

The LIFE-TIME production total: shows the same dropouts:

Lifetime Production

I think the dropouts are created during communication problems HA <> Enphase Envoy and/or at times of boots/restarts. Is the integration reporting a ZERO instead of Not a Number (NaN) ???

Either way: The ZERO value is obviously incorrect in the samples shown, DAY totals resets to 0 at 00:00, but the LIFE-TIME total production is never reset)

I think the dropouts to 0 seem to be causing the erratic behaviour in the Energy panel as shown.

Would this issue be resolved if the Enphase integration if NaN is recorded as a GAP in the data?

What version of Home Assistant Core has the issue?

2024.6.3

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Core

Integration causing the issue

Enphase

Link to integration documentation on our website

https://www.home-assistant.io/integrations/enphase_envoy

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

Issue easily reproduced by unplugging the Enphase Envoy device

home-assistant[bot] commented 2 weeks ago

Hey there @bdraco, @cgarwood, @dgomes, @joostlek, @catsmanac, mind taking a look at this issue as it has been labeled with an integration (enphase_envoy) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `enphase_envoy` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign enphase_envoy` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)


enphase_envoy documentation enphase_envoy source (message by IssueLinks)

MeanderingNL commented 2 weeks ago

Additional zoom of the Life-Time Production of the Enphase Envoy:

Note also the other values in the dropouts (ie: not just zero's but also other incorrect values when communication resumes)

Lifetime Dropouts

catsmanac commented 2 weeks ago

Hi @MeanderingNL, the integration is passing data as received from the Envoy. If there's an error it will retry and timeout after like 45 sec. Typically there will be a gap and no datapoints, certainly over a HA reboot. I'll validate this for communication outages, but it should be gaps as well.

If a zero value is in the data the energy dashboard will indeed show it as a huge peak. Energy dashboard knows how to handle a reset to zero and slow build up after that for lifetime values. But if the previous value is then continuing again after the zero, it will be interpreted as production. So that is what you are observing.

can you provide some background information?

MeanderingNL commented 1 week ago

Hi,

First of all, thank you for your work and information above, appreciated :)

I have an older installation, based on an Envoy R, so no CT's :(

Envoy00

As limited as the logging is, I do see a single error in the Envoy's log:

Envoy01

I think I can reproduce the issue (Either by taking the power off the Envoy or by unplugging the Ethernet, will test that)

As for how often it happens is hard to say, as at this moment I was actively working on HA (Installing a couple of extra meters for water usage and district heating). I know I have seen similar errors in the past, where data didn't seem to make sense (Didn't report it tho)

I guess HA aggregates older data-points, so data/resolution gets lost smoothing out historic values? Below a couple of screenshots with more history, so it certainly isn't daily (And I reboot HA quite often)

EP Day history:

PV Production Day history

EP Lifetime history:

PV Production Lifetime history

The PV panels did have production at the time of the events (Unsure if the info below helps...)

https://github.com/home-assistant/core/assets/106403231/ac802b5e-50ba-4af4-9e76-6b3c8faede82

Enlighten01

Enlighten02

catsmanac commented 1 week ago

I have an older installation, based on an Envoy R, so no CT's :(

My Envoy S non-metered has no more info then your R, only newer firmware, but one could see that as newer issues versus older issues ;-).

I think I can reproduce the issue (Either by taking the power off the Envoy or by unplugging the Ethernet, will test that)

I've tested a communication outage and it leaves a gap, not zero's. The home assistant log file shows an error reported if such a thing occurs.

I guess HA aggregates older data-points, so data/resolution gets lost smoothing out historic values?

Yes, in standard setup it keeps all state details for 7 days, maintains a short-term history with 5 minute entries for ever and as well as a long-term history with hourly entries for ever. The 2 history tables contain like min, max, average and so for the period based on the type of data. Depending which period you request for display and the nature of the display it will source the data from a combination of these data store.

The PV panels did have production at the time of the events (Unsure if the info below helps...)

Nice way of showing it. Enlighten will probably not show the issue as this gets it's data in a different way as Home Assistant, its pushed by the Envoy. You would have to display home assistant history for a panel on that afternoon and see if there's a zero value too.

I have a suspicion that the data collected from the Envoy actually has a zero. No hard proof at this moment and I wouldn't mind to be proven wrong.

so it certainly isn't daily

If it is rare enough to correct manually you can do that in developers tools / statistics, set it to the previous or next value and the Energy dashboard will clean up. If you setup an event detecting it going to zero and create a notification with previous value and current time you have all the needed info when this happens. Yeah stopgap, but as said if rare it could help.

afbeelding

If it is too often for manual corrections, one can consider creating a calculated sensor using the lifetime as input and not pass zero values. But that would not have the history you build up already.

MeanderingNL commented 1 week ago

Hi Catsmanac,

Thank you for your answer.

Today I tried to reproduce the event manually (Unplugging the Envoy)

Looking at the Daily Production and Life-time Production, I also saw gaps, as shown below:

Production Today

Lifetime 1st view

The Energy Panel however DID still show the wrong data:

Energy Panel

So I went back the the Production Today and Life-time Production, zooming in on the data. Now the gaps do show as dropouts:

Production Today 'Show more'

Lifetime 'Show more'

Lifetime 'Show more' Zoom

As requested, I did have DEBUG LOGGING active, that I include below...

DEBUG-assistant_enphase_envoy_2024-06-22T12-40-26.674Z.log

Hope this helps...

catsmanac commented 1 week ago

You test reveals the problem, when the ENvoy comes back on line if first replies with 0 values for 2 or 3 minutes. Here's some exlanation to the debug log:

Last connection failure:

2024-06-22 13:56:12.555 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy XXXXXXXXX170 data in 12.823 seconds (success: False)

The Envoy comes back on line and reports its avaialble:

2024-06-22 13:56:13.580 DEBUG (MainThread) [homeassistant.components.enphase_envoy.config_flow] Zeroconf ip 4 processing x.y.z.26, current hosts: {'x.y.z.26'}

Next connection cycle, 1 minute later, results in 0 values reported by the Envoy:

2024-06-22 13:57:12.732 DEBUG (MainThread) [pyenphase.envoy] Requesting http://x.y.z.26/api/v1/production with timeout Timeout(connect=10.0, read=45.0, write=10.0, pool=10.0)
2024-06-22 13:57:12.746 DEBUG (MainThread) [pyenphase.envoy] Request reply from http://x.y.z.26/api/v1/production status 200: application/json b'{\n  "wattHoursToday": 0,\n  "wattHoursSevenDays": 0,\n  "wattHoursLifetime": 0,\n  "wattsNow": 0\n}\n'  
"wattHoursToday": 0,
"wattHoursSevenDays": 0,
"wattHoursLifetime": 0,
"wattsNow": 0

And no inverters are in the inverter report:

2024-06-22 13:57:12.746 DEBUG (MainThread) [pyenphase.envoy] Requesting http://x.y.z.26/api/v1/production/inverters with timeout Timeout(connect=10.0, read=45.0, write=10.0, pool=10.0)
2024-06-22 13:57:12.828 DEBUG (MainThread) [pyenphase.envoy] Request reply from http://x.y.z.26/api/v1/production/inverters status 200: application/json b'[\n\n]\n'
2024-06-22 13:57:12.829 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Envoy data: EnvoyData(encharge_inventory=None, encharge_power=None, encharge_aggregate=None, enpower=None, system_consumption=None, system_production=EnvoySystemProduction(watt_hours_lifetime=0, watt_hours_last_7_days=0, watt_hours_today=0, watts_now=0), system_consumption_phases=None, system_production_phases=None, ctmeter_production=None, ctmeter_consumption=None, ctmeter_storage=None, ctmeter_production_phases=None, ctmeter_consumption_phases=None, ctmeter_storage_phases=None, dry_contact_status={}, dry_contact_settings={}, inverters={}, tariff=None, raw={'/api/v1/production': {'wattHoursToday': 0, 'wattHoursSevenDays': 0, 'wattHoursLifetime': 0, 'wattsNow': 0}, '/api/v1/production/inverters': []})
2024-06-22 13:57:12.829 INFO (MainThread) [homeassistant.components.enphase_envoy.coordinator] Fetching Envoy XXXXXXXXX170 data recovered
2024-06-22 13:57:12.829 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy XXXXXXXXX170 data in 0.097 seconds (success: True)
2024-06-22 13:57:12.830 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY342 not in returned inverters array (size: 0)
2024-06-22 13:57:12.830 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY812 not in returned inverters array (size: 0)
2024-06-22 13:57:12.830 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY348 not in returned inverters array (size: 0)
2024-06-22 13:57:12.830 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY083 not in returned inverters array (size: 0)
2024-06-22 13:57:12.830 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY184 not in returned inverters array (size: 0)
2024-06-22 13:57:12.831 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY051 not in returned inverters array (size: 0)
2024-06-22 13:57:12.831 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY255 not in returned inverters array (size: 0)
2024-06-22 13:57:12.831 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY349 not in returned inverters array (size: 0)
2024-06-22 13:57:12.831 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY170 not in returned inverters array (size: 0)
2024-06-22 13:57:12.831 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY363 not in returned inverters array (size: 0)
2024-06-22 13:57:12.831 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY920 not in returned inverters array (size: 0)
2024-06-22 13:57:12.831 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY917 not in returned inverters array (size: 0)
2024-06-22 13:57:12.832 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY154 not in returned inverters array (size: 0)
2024-06-22 13:57:12.832 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY156 not in returned inverters array (size: 0)
2024-06-22 13:57:12.832 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Inverter YYYYYYYYY104 not in returned inverters array (size: 0)

One minute later next scan occurs with same results, 0 values and no inverters:

2024-06-22 13:58:12.731 DEBUG (MainThread) [pyenphase.envoy] Requesting http://x.y.z.26/api/v1/production with timeout Timeout(connect=10.0, read=45.0, write=10.0, pool=10.0)
2024-06-22 13:58:12.743 DEBUG (MainThread) [pyenphase.envoy] Request reply from http://x.y.z.26/api/v1/production status 200: application/json b'{\n  "wattHoursToday": 0,\n  "wattHoursSevenDays": 0,\n  "wattHoursLifetime": 0,\n  "wattsNow": 0\n}\n'
2024-06-22 13:58:12.744 DEBUG (MainThread) [pyenphase.envoy] Requesting http://x.y.z.26/api/v1/production/inverters with timeout Timeout(connect=10.0, read=45.0, write=10.0, pool=10.0)
2024-06-22 13:58:12.791 DEBUG (MainThread) [pyenphase.envoy] Request reply from http://x.y.z.26/api/v1/production/inverters status 200: application/json b'[\n\n]\n'
2024-06-22 13:58:12.792 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Envoy data: EnvoyData(encharge_inventory=None, encharge_power=None, encharge_aggregate=None, enpower=None, system_consumption=None, system_production=EnvoySystemProduction(watt_hours_lifetime=0, watt_hours_last_7_days=0, watt_hours_today=0, watts_now=0), system_consumption_phases=None, system_production_phases=None, ctmeter_production=None, ctmeter_consumption=None, ctmeter_storage=None, ctmeter_production_phases=None, ctmeter_consumption_phases=None, ctmeter_storage_phases=None, dry_contact_status={}, dry_contact_settings={}, inverters={}, tariff=None, raw={'/api/v1/production': {'wattHoursToday': 0, 'wattHoursSevenDays': 0, 'wattHoursLifetime': 0, 'wattsNow': 0}, '/api/v1/production/inverters': []})
2024-06-22 13:58:12.792 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy XXXXXXXXX170 data in 0.061 seconds (success: True)

Again 1 minute later another scan which finally brings in non-zero data:

2024-06-22 13:59:12.732 DEBUG (MainThread) [pyenphase.envoy] Requesting http://x.y.z.26/api/v1/production with timeout Timeout(connect=10.0, read=45.0, write=10.0, pool=10.0)
2024-06-22 13:59:12.743 DEBUG (MainThread) [pyenphase.envoy] Request reply from http://x.y.z.26/api/v1/production status 200: application/json b'{\n  "wattHoursToday": 10364,\n  "wattHoursSevenDays": 104393,\n  "wattHoursLifetime": 43681595,\n  "wattsNow": 1222\n}\n'
"wattHoursToday": 10364,
"wattHoursSevenDays": 104393,
"wattHoursLifetime": 43681595,
"wattsNow": 1222

and the inverters are included:

2024-06-22 13:59:12.743 DEBUG (MainThread) [pyenphase.envoy] Requesting http://x.y.z.26/api/v1/production/inverters with timeout Timeout(connect=10.0, read=45.0, write=10.0, pool=10.0)
2024-06-22 13:59:12.798 DEBUG (MainThread) [pyenphase.envoy] Request reply from http://x.y.z.26/api/v1/production/inverters status 200: application/json b'[\n  {\n    "serialNumber": "YYYYYYYYY342",\n    "lastReportDate": 1719057503,\n    "lastReportWatts": 82,\n    "maxReportWatts": 94\n  },\n  {\n    "serialNumber": "YYYYYYYYY812",\n    "lastReportDate": 1719057490,\n    "lastReportWatts": 78,\n    "maxReportWatts": 93\n  },\n  {\n    "serialNumber": "YYYYYYYYY348",\n    "lastReportDate": 1719057495,\n    "lastReportWatts": 79,\n    "maxReportWatts": 93\n  },\n  {\n    "serialNumber": "YYYYYYYYY083",\n    "lastReportDate": 1719057500,\n    "lastReportWatts": 83,\n    "maxReportWatts": 93\n  },\n  {\n    "serialNumber": "YYYYYYYYY184",\n    "lastReportDate": 1719057491,\n    "lastReportWatts": 80,\n    "maxReportWatts": 93\n  },\n  {\n    "serialNumber": "YYYYYYYYY051",\n    "lastReportDate": 1719057497,\n    "lastReportWatts": 83,\n    "maxReportWatts": 96\n  },\n  {\n    "serialNumber": "YYYYYYYYY255",\n    "lastReportDate": 1719057499,\n    "lastReportWatts": 81,\n    "maxReportWatts": 94\n  },\n  {\n    "serialNumber": "YYYYYYYYY349",\n    "lastReportDate": 1719057488,\n    "lastReportWatts": 79,\n    "maxReportWatts": 94\n  },\n  {\n    "serialNumber": "YYYYYYYYY170",\n    "lastReportDate": 1719057493,\n    "lastReportWatts": 81,\n    "maxReportWatts": 96\n  },\n  {\n    "serialNumber": "YYYYYYYYY363",\n    "lastReportDate": 1719057495,\n    "lastReportWatts": 84,\n    "maxReportWatts": 94\n  },\n  {\n    "serialNumber": "YYYYYYYYY920",\n    "lastReportDate": 1719057501,\n    "lastReportWatts": 84,\n    "maxReportWatts": 93\n  },\n  {\n    "serialNumber": "YYYYYYYYY917",\n    "lastReportDate": 1719057490,\n    "lastReportWatts": 79,\n    "maxReportWatts": 94\n  },\n  {\n    "serialNumber": "YYYYYYYYY154",\n    "lastReportDate": 1719057493,\n    "lastReportWatts": 79,\n    "maxReportWatts": 93\n  },\n  {\n    "serialNumber": "YYYYYYYYY156",\n    "lastReportDate": 1719057498,\n    "lastReportWatts": 83,\n    "maxReportWatts": 93\n  },\n  {\n    "serialNumber": "YYYYYYYYY104",\n    "lastReportDate": 1719057487,\n    "lastReportWatts": 87,\n    "maxReportWatts": 93\n  }\n]\n'

So what seems to happen is that the Envoy replies with 0 values and no inverters at startup before it restored its previous data and finalized connected with the inverters. While the Envoy is unavailable there will be a gap in HA, but then when the Envoy sends the zero's these are considered as send by the Envoy, which they are.

MeanderingNL commented 1 week ago

Hmmm...

Not really logical for it to start sending data already whilst is should wait for the inverters to report in :(

Explains the results indeed, note that this was caused by unplugging the power to the Envoy...

Will grab some debug data unplugging the ethernet cable for 5 minutes and then plugging it back in (Leaving the Envoy running)

Is your Envoy S doing something similar on a dirty shutdown/boot?

(edit) Guess reporting 0 when the inverters are offline is what happens at night as well (Where the 0 is correct at that time).

catsmanac commented 1 week ago

Is your Envoy S doing something similar on a dirty shutdown/boot?

No, it's returning an error 503 with a message telling "Resource busy, please retry after 30 seconds". And since it's an error no data is updated. So I have a gap, but not zero's.

2024-06-22 19:53:28.490 DEBUG (MainThread) [homeassistant.components.enphase_envoy.config_flow] Zeroconf ip 4 processing 192.168.3.112, current hosts: {'192.168.3.112'}
2024-06-22 19:53:42.978 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.3.112/api/v1/production with timeout Timeout(connect=10.0, read=45.0, write=10.0, pool=10.0)
2024-06-22 19:53:57.937 DEBUG (MainThread) [pyenphase.envoy] Request reply from https://192.168.3.112/api/v1/production status 503: application/json b'{\n  "status": 503,\n  "error": "",\n  "info": "Resource busy, please retry after 30 seconds",\n  "moreInfo": ""\n}\n'

Guess reporting 0 when the inverters are offline is what happens at night as well (Where the 0 is correct at that time)

Well that is true for the individual inverters, but the lifetime value should just keep its value.

MeanderingNL commented 1 week ago

That is certainly true indeed.

Possible to filter upon 0 and refuse that value?

Had a quick look at the subject lines of the other reported issues: Related???

catsmanac commented 1 week ago

Had a quick look at the subject lines of the other reported issues: Related???

Only to some extend. Most observations are like yours, sudden peak in Energy dashboard. But causes differ. In one case it was the smart grid meter that actually inserted the zero's, not the envoy. Another case is using the Envoy daily production value, which has shown to not be utmost reliable for Envoy-metered without connected CT. Hence the advise to use lifetime value for Energy dash.

Possible to filter upon 0 and refuse that value?

For now I would certainly look into an automation to report the zero's and investigate if the manual correction works.

MeanderingNL commented 1 week ago

Thank you for your efforts and input: very enlightening ;)

Could a quality eval not be as simple as 'if lifetime equals 0, reject all data' and not bothering with the inverters for the eval? A zero is always wrong for the lifetime production and it would also iron out the errors in the day production...

I will try and find out where HA stores the 7 days of values from the lifetime production total, if I can get that data cleaned up by deleting any values differing more than x% (as it seemes to report not just 0, but as can be seen in the last 'zoomed in' pictures also incorrect datapoints around 7000 and 15000, or do you think that is down to HA display routines?)

catsmanac commented 1 week ago

Enlighting it is :joy:

Could a quality eval not be as simple as 'if lifetime equals 0, reject all data' and not bothering with the inverters for the eval? A zero is always wrong for the lifetime production and it would also iron out the errors in the day production...

Generically yes, but there is a combination of FW and configuration where it is know to wrap to zero. So it needs a bit of care. Changes that it really hits zero versus having a small value again when HA polls are pretty low, but as Murphy says, if it can happen it will happen. I'm looking into it and need to fix it in pynphase. We leave this one open until that is completed.

I will try and find out where HA stores the 7 days of values from the lifetime production total

If I remember correctly I think the Energy dashboard reads from the history, not from the 7 day states table. And these are gone after 7 days and then it switches to history anyway. So correcting statistics, which is what history is named would be needed anyway. History data is written every 5 or 60 minutes, not at the end of the 7 days. Changing an older state value by updating the table will not update statistics.

differing more than x% (as it seemes to report not just 0, but as can be seen in the last 'zoomed in' pictures

That's drawing effect. The raw data in your debug log only shows zero or values before and after really close.