Enphase Envoy - Timeouts reading large number of inverters

[neillt]

Home Assistant release with the issue: 0.103.5

Last working Home Assistant release (if known): N/A - Hasn't worked since at least .98 when I first started getting things running

Operating environment (Hass.io/Docker/Windows/etc.): hass.io running inside an Ubuntu VM on a large multi-Xeon vmWare server

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

Description of problem: I have an Enphase Envoy solar system, controlled by an "S" model controller. While summary production numbers are being produced, individual inverter statistics are stuck as "Unknown". My Home Assistant logs are filling up with two relevant errors:

2020-01-02 18:57:33 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.envoy_solar_controllerenvoy_inverter_121731044406 fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 281, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 459, in async_device_update
    await self.async_update()
  File "/usr/src/homeassistant/homeassistant/components/enphase_envoy/sensor.py", line 133, in async_update
    self._state = inverters[serial_number]
KeyError: 'ControllerEnvoy'

and

2020-01-02 18:53:01 WARNING (MainThread) [homeassistant.helpers.entity] Update of sensor.envoy_solar_controllerenvoy_inverter_121731037388 is taking over 10 seconds

I just picked an example of each type of error. I have 24 panels and microinverters so they all are generating the same 2 error types.

When I use another linux machine to manually run envoy_reader (the underpinning of this integration) downloaded from GitHub I receive the following output:

Enter the Envoy IP address or host name, or press enter to use 'envoy' as default: 
Enter the Username for Inverter data authentication, or press enter to use 'envoy' as default: 
Enter the Password for Inverter data authentication, or press enter to use the default password: 
Reading...
production:              3863
consumption:             3873
daily_production:        0
daily_consumption:       0
seven_days_production:   0
seven_days_consumption:  0
lifetime_production:     0
lifetime_consumption:    -3
inverters_production:   {'121731037388': [158, '2020-01-02 19:59:28'], '121731038085': [151, '2020-01-02 19:59:33'], '121731023211': [156, '2020-01-02 19:59:25'], '121731023758': [154, '2020-01-02 19:59:29'], '121731044407': [159, '2020-01-02 19:59:36'], '121731044406': [157, '2020-01-02 19:59:10'], '121731037503': [154, '2020-01-02 19:59:07'], '121731044863': [162, '2020-01-02 19:59:14'], '121731045676': [156, '2020-01-02 19:59:20'], '121731040860': [156, '2020-01-02 19:59:10'], '121731032959': [157, '2020-01-02 19:59:03'], '121731044153': [155, '2020-01-02 19:59:23'], '121731044143': [157, '2020-01-02 19:59:21'], '121731032724': [153, '2020-01-02 19:59:18'], '121731040984': [160, '2020-01-02 19:59:16'], '121731037408': [157, '2020-01-02 19:59:15'], '121731023280': [152, '2020-01-02 19:59:11'], '121731029397': [157, '2020-01-02 19:59:05'], '121731023151': [159, '2020-01-02 19:59:25'], '121731044656': [153, '2020-01-02 19:59:33'], '121731023488': [158, '2020-01-02 19:59:37'], '121731045122': [159, '2020-01-02 19:59:28'], '121731045846': [163, '2020-01-02 19:59:34'], '121731044648': [158, '2020-01-02 19:59:05']}

Clearly the inverters are returning data thru the local API. But for some reason the HA integration isn't properly ingesting the data.

Problem-relevant configuration.yaml entries:

# Solar System Interface
sensor:
  - platform: enphase_envoy
    ip_address: 192.168.71.65
    name: Envoy Solar Controller
    monitored_conditions:
      - production
      - inverters

Additional information: Willing to test out and help debug as needed. My Python skills are rudimentary so I am not sure where things are borked.

[exxamalte]

FYI - I've analysed the traffic between HA and the Envoy-S, and made some suggestions on how to improve the library. Someone is already working on this, and the fixes may help you with this issue. https://github.com/jesserizzo/envoy_reader/issues/12

[neillt]

In this case, doesn't the fact that the envoy_reader code is returning the correct values, but HA isn't ingesting them, point to a different problem?

[exxamalte]

You are right - yours may be different issue. My investigation was triggered by my own integration logging those "... is taking over 10 seconds" warning messages over and over, for production/consumption and inverters.

[stale[bot]]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[neillt]

This is still an issue.

[stale[bot]]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[neillt]

This issue still persists in 0.112. Exact same symptoms, the envoy_reader component is properly querying the inverters, but the data is not being ingested into HA correctly.

[gtdiehl]

@neillt Unfortunately the way the local API queries the inverter data and the way the HA queries the inverter data are slightly different. Running envoy_reader manually as you did, grabs all of the inverter data at once, and displays the output. When the HA sensor integration with envoy_reader invokes the inverter_production function, it does it for how many inverters you have in your system.

I did try and solve this with PR #32637 but my approach needed to be re-worked. I haven't had any time lately to revisit this issue.

[gtdiehl]

@neillt @exxamalte I have done some changes to the Envoy sensor and need others to try it out before I submit a PR. The sensor code is located at: Enphase HA sensor

[neillt]

Here is what I see using the code you posted. I am on 0.113.1.

Using the config I have been using for a while (querying just production), HA restarts just fine with the caveat of a "Setup of sensor platorm enphase_envoy is taking over 10 seconds". But it eventually reads current production summation numbers via sensor.envoy_solar_controllerenvoy_current_energy_production just fine.

When I add "inverters" as a monitored condition, I get a slew of errors. A typical set:

2020-07-26 17:36:45 ERROR (MainThread) [homeassistant.helpers.entity] Update for sensor.envoy_solar_controllerenvoy_inverter_121731045846 fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 272, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 463, in async_device_update
    await self.async_update()  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/enphase_envoy/sensor.py", line 239, in async_update
    self._state = self.coordinator.data.get("inverters_production").get(
TypeError: 'NoneType' object is not subscriptable

It appears to be iterating through all of my microinverters and producing similar results.

If there is anything I can do to troubleshoot, just shout.

[neillt]

Interestingly, if I turn on debug logging, I do eventually see this:

2020-07-26 17:50:23 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Retrieved data from API: {'production': 2593, 'consumption': 2593, 'daily_production': 0, 'daily_consumption': 0, 'seven_days_production': 0, 'seven_days_consumption': 0, 'lifetime_production': 0, 'lifetime_consumption': -3, 'inverters_production': {'121731037388': [134, '2020-07-26 17:49:32'], '121731038085': [128, '2020-07-26 17:49:37'], '121731023211': [123, '2020-07-26 17:49:28'], '121731023758': [133, '2020-07-26 17:49:35'], '121731044407': [122, '2020-07-26 17:49:41'], '121731044406': [134, '2020-07-26 17:49:51'], '121731037503': [120, '2020-07-26 17:49:50'], '121731044863': [136, '2020-07-26 17:49:56'], '121731045676': [136, '2020-07-26 17:50:02'], '121731040860': [134, '2020-07-26 17:49:51'], '121731032959': [121, '2020-07-26 17:49:45'], '121731044153': [126, '2020-07-26 17:50:05'], '121731044143': [85, '2020-07-26 17:50:04'], '121731032724': [15, '2020-07-26 17:50:00'], '121731040984': [124, '2020-07-26 17:49:59'], '121731037408': [122, '2020-07-26 17:49:57'], '121731023280': [8, '2020-07-26 17:49:55'], '121731029397': [135, '2020-07-26 17:49:47'], '121731023151': [123, '2020-07-26 17:49:31'], '121731044656': [133, '2020-07-26 17:49:36'], '121731023488': [123, '2020-07-26 17:49:42'], '121731045122': [124, '2020-07-26 17:49:32'], '121731045846': [131, '2020-07-26 17:49:41'], '121731044648': [123, '2020-07-26 17:49:46']}} 2020-07-26 17:50:23 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Returning API data. 2020-07-26 17:50:23 DEBUG (MainThread) [homeassistant.components.enphase_envoy.sensor] Finished fetching sensor data in 4.784 seconds

So at least the data is getting pulled from the controller, it's just not pushing into hass for some reason.

The entities are being created for each inverter, but state is "Unknown" and last_reported is null.

[gtdiehl]

@neillt Thanks for the help. What kind of Envoy do you have?

[gtdiehl]

@neillt You maybe running into a timeout issue? I have pushed a changed to the Envoy API (PR #35). I was seeing the Timeout issue with HA 0.112.x but with 0.113.1 I'm not seeing it anymore. Probably due to the speed optimization changes!

Still a bit at a loss. Rather than changing anything on your end, can you e-mail me the HA log file with DEBUG enabled for the envoy sensor with inverters added as a monitored_conditions? Just need the log from when the server starts to about 2 minutes after to have HA poll the envoy a few time. Thanks!

[neillt]

For the timeouts... I have a large Hass install, and even though it's running on a beefy ESXi host it still bogs down when first starting up. The timeout messages appear for many of the integrations.

I have an Envoy Model S.

Collecting logs now.

[gtdiehl]

@neillt Were you able to e-mail the logs over? My e-mail is in my github profile.

Looking at your debug post from a few days ago, I'm still at a loss as to why it would return None (or Unknown). Which firmware is your Envoy-S running? I could try and get access to a similar unit.

[neillt]

I had sent them, but I can certainly re-send! I'll do it tonight (West Coast USA Time).

As far as my inverter, here is all the data:

Envoy

Serial Number
1(redacted)10
Part Number
800-00555-r03
Software Version
D5.0.49 (77afa8)
Software Build Date
19 Mar, 2020 1:44 AM
Wi-Fi IP Address
192.168.71.65
Wi-Fi Mac Address
50:F1:(redacted)
Ethernet IP Address
169.254.120.1
Ethernet Mac Address
00:1D:(redacted)
Database Size
18 MB (4% full)
Current Timezone
US/Pacific

Although since it seems like the data is being provided by the Python reader, it's some kind of strange issue with figuring out where to stuff it in Hass?

[gtdiehl]

@neillt I didn't receive the second e-mail either. I guess if it's not too long you can post the log here?