Closed wptracy closed 2 months 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!
(message by CodeOwnersMention)
enphase_envoy documentation enphase_envoy source (message by IssueLinks)
Hi @wptracy, have you checked what Envoy response times are when using the standard 60 sec interval? Enable debug on the HA enphase_envoy integration, let it run for some time. Check log file for lines with finished fetching Envoy
Finished fetching Envoy 123456789012 data in 1.234 seconds (success: True)
That will provide you with some background on how long all responses take. You can also see time it takes to get individual data endpoints from the Envoy in this way.
2024-05-29 11:33:37.283 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.10/production.json?details=1 with timeout Timeout(connect=10.0, read=45.0, write=10.0, pool=10.0)
2024-05-29 11:33:37.771 DEBUG (MainThread) [pyenphase.envoy] Request reply from https://192.168.1.10/production.json?details=1 status 200:
Then do same with custom interval of 30 sec first or 10 sec again and see how this goes. The debug log will provide more details on what is going on.
I couldn't include the debug log because maximum comment size is 65536 characters. so I grep'ed "Finished"instead.
The debug log below has 3 different captures (time 03:47, time 15:43, and time 07:42): The 1st two captures had a trigger time set for 10 seconds over a 1 minute period of time. Maximum Finish time of 3.779 seconds The last capture had a trigger time of 60 seconds over a 6 minute period of time. Maximum Finish time of 4.275 seconds
I grep'ed the debug file for "envoy" to get just the envoy logs:
Enphase Envoy fetches production.json?details=1, production/inverters, and admin/lib/tariff Then the inverter readings roll in.
The longest it took to fetch the data was 4.275 seconds.
So it should be able to fetch all the data in 10 seconds.
DEBUG LOG:
wptracy@Rpi5-1-logitechmediaserver:~/Downloads $ grep Finished 'comment back to Arie Catsman.txt'
2024-06-17 03:47:27.793 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.657 seconds (success: True)
2024-06-17 03:47:41.002 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 3.205 seconds (success: True)
2024-06-17 03:47:53.528 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 2.518 seconds (success: True)
2024-06-17 03:48:06.459 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 2.924 seconds (success: True)
2024-06-17 03:48:17.716 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.252 seconds (success: True)
2024-06-17 03:48:29.517 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.794 seconds (success: True)
2024-06-17 15:43:56.294 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 2.733 seconds (success: True)
2024-06-17 15:44:10.084 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 3.779 seconds (success: True)
2024-06-17 15:44:23.517 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 3.426 seconds (success: True)
2024-06-17 15:44:34.702 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.175 seconds (success: True)
2024-06-17 15:44:46.734 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 2.024 seconds (success: True)
2024-06-18 07:42:00.671 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.567 seconds (success: True)
2024-06-18 07:43:01.869 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 2.764 seconds (success: True)
2024-06-18 07:44:03.379 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 4.275 seconds (success: True)
2024-06-18 07:45:00.937 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.835 seconds (success: True)
2024-06-18 07:46:01.060 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.958 seconds (success: True)
2024-06-18 07:47:02.995 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 3.893 seconds (success: True)
wptracy@Rpi5-1-logitechmediaserver:~/Downloads $
I couldn't include the debug log because maximum comment size is 65536 characters.
You can upload the file by dragging it onto below the comment box.
The examples you shared shows a completion ~every 12-14 sec for the 10 sec cycle and every 60-63 sec in the 60 sec cycle.
Next step would be to check the debug to see what values for current_power_production are in the log file. If the value doesn't change between 2 readings HA history is probably not storing it.
I'm not a unix or perl shell scripter. It would take me forever to parse and add up all the inverter readings.
Are you expert in scripting??
The problem was happening between 10:35 and 1:45 AM. I had debug turned on and am uploading the debug file. In one of the screenshots, There is a big difference between what enphase produced (2,880 Watts) and what was fed back to the grid (-5472 Watts).
The "last_report_watts=" do change, but not by much, I don't know if they add up to the total reported by Enphase Envoy App.
I'm including some screenshots of the problem and also a readable file format of https://10.0.0.105/api/v1/production/inverters
[
{
"serialNumber": "202331145751",
"lastReportDate": 1718728822,
"devType": 1,
"lastReportWatts": 213,
"maxReportWatts": 329
},
{
"serialNumber": "202331145858",
"lastReportDate": 1718728823,
"devType": 1,
"lastReportWatts": 214,
"maxReportWatts": 329
},
{
"serialNumber": "202331146991",
"lastReportDate": 1718728852,
"devType": 1,
"lastReportWatts": 226,
"maxReportWatts": 329
},
{
"serialNumber": "202331149166",
"lastReportDate": 1718728762,
"devType": 1,
"lastReportWatts": 183,
"maxReportWatts": 329
},
{
"serialNumber": "202331151170",
"lastReportDate": 1718728853,
"devType": 1,
"lastReportWatts": 229,
"maxReportWatts": 329
},
{
"serialNumber": "202331153017",
"lastReportDate": 1718728763,
"devType": 1,
"lastReportWatts": 183,
"maxReportWatts": 329
},
{
"serialNumber": "202331153959",
"lastReportDate": 1718728854,
"devType": 1,
"lastReportWatts": 230,
"maxReportWatts": 329
},
{
"serialNumber": "202331154288",
"lastReportDate": 1718728942,
"devType": 1,
"lastReportWatts": 203,
"maxReportWatts": 329
},
{
"serialNumber": "202331154526",
"lastReportDate": 1718728792,
"devType": 1,
"lastReportWatts": 197,
"maxReportWatts": 329
},
{
"serialNumber": "202331155409",
"lastReportDate": 1718728763,
"devType": 1,
"lastReportWatts": 185,
"maxReportWatts": 330
},
{
"serialNumber": "202331156456",
"lastReportDate": 1718728793,
"devType": 1,
"lastReportWatts": 199,
"maxReportWatts": 329
},
{
"serialNumber": "202331157995",
"lastReportDate": 1718728793,
"devType": 1,
"lastReportWatts": 201,
"maxReportWatts": 329
},
{
"serialNumber": "202331158076",
"lastReportDate": 1718728855,
"devType": 1,
"lastReportWatts": 162,
"maxReportWatts": 329
},
{
"serialNumber": "202331158772",
"lastReportDate": 1718728855,
"devType": 1,
"lastReportWatts": 233,
"maxReportWatts": 329
},
{
"serialNumber": "202331159864",
"lastReportDate": 1718728823,
"devType": 1,
"lastReportWatts": 214,
"maxReportWatts": 329
},
{
"serialNumber": "202331159881",
"lastReportDate": 1718728824,
"devType": 1,
"lastReportWatts": 217,
"maxReportWatts": 329
},
{
"serialNumber": "202331159895",
"lastReportDate": 1718728856,
"devType": 1,
"lastReportWatts": 232,
"maxReportWatts": 329
},
{
"serialNumber": "202213129654",
"lastReportDate": 1718728972,
"devType": 1,
"lastReportWatts": 213,
"maxReportWatts": 329
},
{
"serialNumber": "202224144296",
"lastReportDate": 1718728882,
"devType": 1,
"lastReportWatts": 179,
"maxReportWatts": 329
},
{
"serialNumber": "202224158329",
"lastReportDate": 1718728912,
"devType": 1,
"lastReportWatts": 186,
"maxReportWatts": 329
},
{
"serialNumber": "202224161713",
"lastReportDate": 1718728943,
"devType": 1,
"lastReportWatts": 207,
"maxReportWatts": 329
}
]
If you can upload the debug file as file then I'll have a look at the raw data with a script I'm working on for something different already.
Looking at the data in 1035to1045.txt you can see that the trigger fires 10 seconds after a data request completes.
2024-06-18 10:30:10.650 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.945 seconds
2024-06-18 10:30:20.654 DEBUG (MainThread) [pyenphase.envoy] Requesting https://10.0.0.105/production.json?details=1 with timeout Timeout(connect=10.0, re
2024-06-18 10:30:22.100 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.446 seconds
2024-06-18 10:30:32.114 DEBUG (MainThread) [pyenphase.envoy] Requesting https://10.0.0.105/production.json?details=1 with timeout Timeout(connect=10.0, re
2024-06-18 10:30:35.169 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 3.056 seconds
2024-06-18 10:30:45.179 DEBUG (MainThread) [pyenphase.envoy] Requesting https://10.0.0.105/production.json?details=1 with timeout Timeout(connect=10.0, re
2024-06-18 10:30:47.427 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 2.248 seconds
2024-06-18 10:30:57.435 DEBUG (MainThread) [pyenphase.envoy] Requesting https://10.0.0.105/production.json?details=1 with timeout Timeout(connect=10.0, re
2024-06-18 10:30:58.634 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.200 seconds
2024-06-18 10:31:08.645 DEBUG (MainThread) [pyenphase.envoy] Requesting https://10.0.0.105/production.json?details=1 with timeout Timeout(connect=10.0, re
Then at 10:34 there's triggers for collection during 2 minutes 20 sec.
2024-06-18 10:34:12.244 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202321168106 data in 1.568 seconds (success: True)
2024-06-18 10:36:31.264 DEBUG (MainThread) [pyenphase.envoy] Requesting https://10.0.0.105/production.json?details=1 with timeout Timeout(connect=10.0, read=45.0, write=10.0, pool=10.0)
After which the 10 sec after each collection end trigger resumes. Envoy replies in 3-4 sec each time when data collection occurs, but trigger does not seem to occur. From Envoy side I can't see why. To detect issues around the triggers you can opt to enable full debug on HA by adding
homeassistant:
debug: true
to your configuration.yaml and restart HA. That will grow the log file, so depending on how frequently the issue occurs it might become quite large.
What type Envoy do you have, metered without current transformers or Standard (not metered) one?
Still looking into the other data details. Power values will always be time dependent, In above case the solar was frozen for 2 minutes. Have to validate it, but I think the Envoy, without Current Transformers is only updating it's data from the inverters 1/minute.
To detect issues around the triggers you can opt to enable full debug on HA by adding
homeassistant: debug: true
I can't get this debug mode this to work. It says Property debug is not allowed in homeassistant:
homeassistant: debug: true Property debug is not allowed.
Strange, got directions to look here for this and I think you are running 2024.6.x which is newer as the 2024.5.x required.
Alternative to try would be:
logger:
default: debug
logger: default: debug
This enables debug logging everywhere, but the logs don't show up in logs.
I combined the data in the debug log into and overview for Power/Watts reported from various sources. File is attached below. The top row is the header row:
header | description |
---|---|
scan end | the time when the log reported Finished fetching Envoy xxx data in yyy seconds which is the end of the data collection cycle from the envoy |
duration | The time it took to collect the data as reported in the log line |
interval | Seconds between the collection end and the previous end. Should reflect how often the trigger fires. |
sum inv W prod | The sum of the Power reported by the individual inverters. |
inv W | The reported total inverter Power in the inverter segment of the /production endpoint |
prod W | The reported produced Power in the production segment of the /production endpoint |
inverter time | The time in the day when the individual inverter report was received |
inverter time span | Each inverter in the individual inverter report reports a 'last reported to envoy' time. The time span is the oldest and the most recent time of these times. |
pr.inv time | The reading time of the inverter section of the /production endpoint |
prod time | The reading time of the production section of the /production endpoint |
Last 3 time columns have my local timezone time, that's caused by the data processing.
inv W
column instead of the prod W
column. Comparing the inv W
column to the sum inv W prod
show that these are really close.This does not explain anything about the 2 minute gap, aside from the fact that for some reason data collection did not trigger as there are no data collections in the log in that period.
If shows however that your trigger frequency is faster as the Envoy updates from the inverters. That is not an issue on it's own, but explains why you won't see data every 10 seconds in HA history as these are only recorded when values change. And it will cause these out-of-sync values with the grid meters.
Still need to look at the energy side of this.
This enables debug logging everywhere, but the logs don't show up in logs.
Nothing in the home-assistant.log
file in the config folder?
If shows however that your trigger frequency is faster as the Envoy updates from the inverters.
I increased the trigger to 15 seconds.
I'm experiencing the same problem, I'm sending more power to the grid than I produce.
I enabled debug again and grep'ed the log for envoy.
I'm uploading both logs, the all_logs and the grep'ed logs so we can maybe correlate some other event with the start of the long interval of no collection.
That script you made is very impressive. I like the report it generates. Thanks!! And thanks for your help on this.
I included screenshots of the energy meters for the same time period. File names have the timestamps.
grep_debug_log_for_envoy.txt
all_debug_logs_home-assistant_enphase_envoy_2024-06-19T19-11-58.498Z.log
This enables debug logging everywhere, but the logs don't show up in logs.
Nothing in the
home-assistant.log
file in the config folder?
When I enable and disable debug on the enphase envoy integration it takes a snapshot of /root/config/home-assistant.log and downloads it to my windows directory from firefox.
I don't see any difference in debug level when I make the log debug entry in configuration.yaml
I don't see any difference in debug level when I make the log debug entry in configuration.yaml
The difference is that when using the configuration.yaml method, debug is enabled for all modules in Home Assistant. We are looking for something outside enphase that happens when the triggers you configured fail to start the data collection and cause the 2 minute gap. Something that maybe prevents the triggers from firing or anything else. These triggers are not part of the Envoy code but rather HA functionality.
I'm experiencing the same problem, I'm sending more power to the grid than I produce.
The fundamental issue is that the envoy reports Power/Watts collected only every 20-30 sec from the inverters and the smart electric meter
is reporting every 5 seconds. So these will very often differ as these are not in sync. Only if these are taken really close together it will be close. No matter how you set the trigger, this will remain with this configuration.
Below is my Envoy showing the same, the purple line being the grid export on various occasions more then the green envoy production line. Data not taken at exact same time at both measurement points is causing this, especially when variations in power usage or production occur.
To have a sensor that shows what is going on in the course of the day, outside of the energy dashboard, you can configure a daily utility meter
helper using Envoy <serial> Lifetime Energy production
, one for the 'smart electric meter production' and the 'smart electric meter consumption'. You will see these growing during the day and reset to zero at midnight. This provides a more accurate view on what is going on, but is not a momentary view of what happens at that exact moment, but rather how energy evoved over the day.
I have this saved in configuration.yaml and I restarted, but now it's not enabeloing debug on all modules.
logger: default: debug
Only if these are taken really close together it will be close. No matter how you set the trigger, this will remain with this configuration.
So if I set the automation to trigger every 15 seconds, and Smart Electric Meter Production and Consumption to poll every 15 seconds this should work?
I'll do the polling every 15 seconds and see if that works.
So if I set the automation to trigger every 15 seconds, and Smart Electric Meter Production and Consumption to poll every 15 seconds this should work?
Doubt it as there's delay between the Envoy and it's inverters, but trying will learn it.
how do you do the helper for "Envoy
Go to Setting / Devices & Services / Helpers. Use create helper
and select utility meter
from the list. input sensor
would be the sensor.envoy_<sn>_lifetime_energy_production
. Select Daily
for meter reset cycle
.
I have this saved in configuration.yaml and I restarted, but now it's not enabeloing debug on all modules.
Not sure if it always shows on the dashboard. See Settings / System / Logs and use button there to download or to view the log file.
Go to Setting / Devices & Services / Helpers.
I created the helper, now how do I display it like yours.
That's a history-graph card
- type: history-graph
entities:
- entity: sensor.envoy_no_dagproductie
- entity: sensor.envoy_zw_dagproductie
- entity: sensor.electriciteit_balans
hours_to_show: 36
I use 2, top one for energy and bottom one for power.
The top one has the daily energy utility meters. The bottom power one has power production from envoy and production and consumption from my smart meter.
I created the power consumption and production. I think I have to wait and see what it looks like in 36 hours.
How did you create the sensors for Envoy NO and ZW Daily Production and Electricity Balance? What is NO and ZW
Ah, NO and ZW is Dutch for NE (North-East) and SW (South West). I have half of my panels facing North-East and half of them South-West.
I have a Riemann Integrator
helper on each panel, this helper integrates the power into lifetime energy for each panel. And on each panel's lifetime energy I have a daily utility meter so I know daily energy produced per panel.
NO Daily production is then the sum of the daily utility meters NE facing and ZW Daily Production the sum for the SW facing panels.
Electricity balance is the sum of 2 daily utility meters, one on my smart meter lifetime grid energy import and one on my smart meter lifetime grid energy export. So it shows my daily balance for import vs export. As the smart meter is the one also read (and owned) by the electricity company it what really counts.
Thanks @catsmanac
Yesterday I configured the automation to poll Envoy every 15 minutes and the configuration.yaml smart.electric.meter.power/consumption/production to poll every 15 minutes. I synchronized them with a restart and yesterday the meter readings looked believable. I'm watching it again today.
My Utility Meter helper and history-graph card isn't looking like your. Either I have the wrong sensors assigned or I'm doing something else wrong.
- type: history-graph
entities:
- entity: sensor.power_consumption
- entity: sensor.power_production
- entity: sensor.envoy_production_kw
hours_to_show: 36
For the other issue I opened a ticket on, I'm waiting to see if I get a consumption or production spike when envoy lifetime reaches roughly 1.2MWh.
Your history card is nicely revealing what is going on, consumption from midnight going up, then it starts flattening a bit when solar gets going. And next you will see power_production going up when solar exceeds house demand.
I have an addinitional calculation on grid production and consumption, in your case something like:
- name: "Electricity Balance"
unique_id: Electricity_balance_kWh
unit_of_measurement: "kWh"
icon: mdi:solar-panel
state: >
{{(states('sensor.power_production') | float(0)
- states('sensor.power_consumption') | float(0)) | round(3) }}
availability: >
{{ has_value('sensor.power_production') and
has_value('sensor.power_consumption') }}
I'm still seeing the behavior of reporting more power back to the grid than I produce, but It's not nearly as bad as it was before I matched and synchronized the polling interval time (15 minutes) for Grid Power and Envoy Power..
So I should close this ticket.
@catsmanac , thanks for you help in analyzing and fixing this.
It looks like Envoy was overwhelmed with all the polling and couldn't keep up with 5 second polling of 21 panels.
Smart Electric Meter Power and Envoy Current power production still get out of sync, but not like it was before when I saw double the power back to the grid than Envoy produced.
The problem
Enphase Envoy custom polling interval set for 10seconds and triggers every 10seconds but "action update entity" doesn't execute ever 10seconds.
Here is my custom polling automation:
Enphase Envoy custom polling interval is set for 10seconds and triggers every 10seconds but action "update entity" doesn't execute ever 10seconds
For example, in the 60 minute log capture below, from 2024-06-16T18:00:44.798Z to 2024-06-16T18:04:13.329Z The automation should poll 6 times a minute but during this 4 minute interval it only captures data every two minutes.
The affect it has on the GUI is, I send more power to the grid than I produce from Envoy.
My Smart meter sensor.smart_electric_meter_power is updated every 5 seconds with:
The "grep -Eo '[0-9]+" can read a negative number which means I'm sending power to the grid.
So when production results lag the grid consumption/production results by two minutes, I often see that I send more energy to the grid than I produce from envoy.
Here is a 60 minute log capture with time stamps of sensor.envoy_202321168106_current_power_production
What version of Home Assistant Core has the issue?
core-2024.6.3
What was the last working version of Home Assistant Core?
No response
What type of installation are you running?
Home Assistant OS
Integration causing the issue
Enphase Envoy
Link to integration documentation on our website
https://www.home-assistant.io/integrations/enphase_envoy/
Diagnostics information
No response
Example YAML snippet
Anything in the logs that might be useful for us?
No response
Additional information
No response