search

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
71.55k stars 29.91k forks source link

Enphase Envoy integration KeyError #103871

Closed austinmroczek closed 8 months ago

austinmroczek commented 10 months ago

The problem

I'm getting a KeyError a few times per day with the Enphase Envoy integration. Seven errors over the last two days. Per the traceback below, it is not finding my serial number.

The Production Right Now and Production Lifetime sensors appear to be working properly, but the Production Today and Production Last Seven Days values are two days old - roughly the time of the first error.

What version of Home Assistant Core has the issue?

2023.11.2

What was the last working version of Home Assistant Core?

unknown, just installed

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

config_entry-enphase_envoy-59493540ff4b0613c1e0ae0424d2df37.json.txt

Example YAML snippet

n/a

Anything in the logs that might be useful for us?

Logger: homeassistant
Source: components/enphase_envoy/sensor.py:486
First occurred: November 10, 2023 at 10:18:16 PM (7 occurrences)
Last logged: 4:40:10 AM

Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 233, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 389, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 172, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 469, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 743, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 843, in _async_write_ha_state
    state, attr = self._async_generate_attributes()
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 784, in _async_generate_attributes
    state = self._stringify_state(available)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 749, in _stringify_state
    if (state := self.state) is None:
                 ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 501, in state
    value = self.native_value
            ^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/enphase_envoy/sensor.py", line 486, in native_value
    return self.entity_description.value_fn(inverters[self._serial_number])
                                            ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: '<<<my serial number>>>'



### Additional information

_No response_
home-assistant[bot] commented 10 months ago

Hey there @bdraco, @cgarwood, @dgomes, @joostlek, 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.

(message by CodeOwnersMention)

enphase_envoy documentation enphase_envoy source (message by IssueLinks)

catsmanac commented 10 months ago

@austinmroczek, so it is running, but reporting this key error voor inverters at various moments? What Envoy are you using, Metered (with or without configured CT, Standard) and which envoy firmware?

Can you share the diagnostic file here?

austinmroczek commented 10 months ago

Diagnostic attached config_entry-enphase_envoy-59493540ff4b0613c1e0ae0424d2df37.json-2.txt

I believe it is IQ7. The integration says "800-00647-r09" The gateway SKU is X-IQ-AM1-240-4 with firmware D7.3.130. I'm not sure about Metered with/without CT.

The integration is running. The "Production Right Now" and "Production Lifetime" sensors appear to be working properly and get updates every 5 minutes. However the "Production Today" and "Production Last Seven Days" values are now four+ days old - roughly the time of the first error.

catsmanac commented 10 months ago

Looking at the data, it seems to be a Envoy metered without configured CT clamps. In the production segment of the report for type eim the activecount is 0. That's not the cause of the problem, but explains why "Production Today" and "Production Last Seven Days" are not reported. Envoy metered without CT clamps configured does not provide the numbers correctly.

    "data": {
      "/production.json": {
        "production": [
          {
            "type": "inverters",
            "activeCount": 20,
            "readingTime": 0,
            "wNow": 0,
            "whLifetime": 436743
          },
          {
            "type": "eim",
            "activeCount": 0,
            "measurementType": "production",
            "readingTime": 1700198466,

As for the error, that needs more investigation. I note a 0 timestamp in the inverters section of the above report as well as for 1 inverter, this may be the cause of the error

        {
          "serialNumber": "202212007684",
          "lastReportDate": 0,
          "devType": 1,
          "lastReportWatts": 0,
          "maxReportWatts": 0
        },

Also all inverters show same values for lastReportWatts and maxReportsWatt

         "lastReportWatts": 3,
          "maxReportWatts": 3

Has there been any sun on the panels? I would expect the maxReportWatts to be higher than the shown values. The one panel with 0 timestamp may not be working ok?

austinmroczek commented 10 months ago

config_entry-enphase_envoy-59493540ff4b0613c1e0ae0424d2df37.json-3.txt here's a diagnostic when it's actually daytime outside so the inverters are now reporting different numbers. Sorry about that.

I do have one dead/bad inverter that my solar company physically replaced, but they never removed from my account.

catsmanac commented 10 months ago

Thanks, that data looks as expected. The one inverter is indeed still reporting all 0. Tested if would cause an error, but HA accepts it and just shows the data with value 0 and last updated time as 53 years ago. As explained above, today and last 7 days values will not be useful for Envoy metered withoit configured CT. If you want those numbers use a HA utility meter based on lifetime value in with a daily and weekly frequency.

So you actually have 19 inverters and number 20 is old definition? The inverter values sum to the overall numbers so it seems not having an influence. If it would be an inverter with history then that is still accessible.

Is the error that you reported still happening? If so can you enable debug logging for the envoy and restart HA. Thne let it run until the error happens again and disable debug for the envoy again.

austinmroczek commented 10 months ago

The error was still happening as-of this morning. However, after turning on debug logging and restarting HA, the error has not returned (6+ hours later). I'll let it run a few days and check on it again.

austinmroczek commented 10 months ago

Happened again last night. Here are the last few minutes of logs leading up to it (pulled out everything from other integrations):

2023-11-18 23:29:13.468 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/production.json with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:29:14.598 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/production.json with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:29:17.175 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/production.json with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:29:19.129 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/production.json with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:29:22.056 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/production.json with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:29:24.617 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/production.json with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:29:26.264 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/production.json with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:30:26.542 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/production.json with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:31:16.552 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/api/v1/production/inverters with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:31:16.674 DEBUG (MainThread) [pyenphase.envoy] Requesting https://192.168.1.145/admin/lib/tariff with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
2023-11-18 23:31:21.895 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202207084671 data in 169.249 seconds (success: True)
2023-11-18 23:31:21.896 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 233, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 389, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 172, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 469, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 743, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 843, in _async_write_ha_state
    state, attr = self._async_generate_attributes()
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 784, in _async_generate_attributes
    state = self._stringify_state(available)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 749, in _stringify_state
    if (state := self.state) is None:
                 ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 501, in state
    value = self.native_value
            ^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/enphase_envoy/sensor.py", line 486, in native_value
    return self.entity_description.value_fn(inverters[self._serial_number])
                                            ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: '202211186226'
catsmanac commented 10 months ago

That log reveals some kind of delay or timeout-out going on, it took 3 minutes before it ended the fetch. In the first part the /production.json endpoint tried multiple times, looks like 8 times. 

Finished fetching Envoy 202207084671 data in 169.249 seconds (success: True)

I suspect that the error is generated by missing data it what came back. It tries to get the data for that inverter, but its not in the returned data.

Is this always happening in late evening? Reason I'm asking is some reports on Envoy's that always have a communication issue somewhere after 11 pm.

austinmroczek commented 10 months ago

Looking through my logs saved since I first reported this:

2023-11-12 20:39:50.698
2023-11-13 00:47:54.708
2023-11-13 02:50:10.454
2023-11-13 20:47:17.372
2023-11-13 22:47:33.978
2023-11-14 00:47:34.509 
2023-11-14 02:47:51.897
2023-11-14 23:20:30.752
2023-11-15 03:20:51.746
2023-11-15 22:33:46.449
2023-11-16 00:33:54.799
2023-11-16 04:34:14.236
2023-11-16 23:21:07.480
2023-11-17 05:23:03.713
2023-11-18 01:10:16.922
2023-11-18 05:30:10.973
2023-11-18 23:31:21.896

So seems to definitely be night time, but not the same time every night.

catsmanac commented 10 months ago

Interesting, common seems to be while not producing any power.

So al data is showing correctly in HA dashboard, but when this happens the log file is real messy?

The debug details are a bit scarce not showing the actual data involved. It will require some time (HA releases) to add more debug information and error handling to fully understand this situation.

The inverter that was reported failing is just the first inverter of the list. So almost as if an empty reply came back.

austinmroczek commented 10 months ago

Data is showing fine in the entity and history graphs in HA. The only thing I'm noticing is the error message in the logs.

Since this always seems to happen at night when production is zero, it wouldn't really be visible in the graphs.

It seems odd that the inverter(s) suddenly gives an empty reply. It must be some sort of error on the server end? If they always gave an empty reply when there was zero production the error would come much earlier in the evening (about 18:00 local at the moment)

catsmanac commented 10 months ago

Something is going on on the envoy when this happens, not sure what, but it seems to end with missing data.

If you check the debug log when all works fine you will see requests to the envoy every 1 minute ending with Finished fetching Envoy and how long it took to obtain the data.

[pyenphase.envoy] Requesting https://192.168.1.145/production.json with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
[pyenphase.envoy] Requesting https://192.168.1.145/api/v1/production/inverters with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
[pyenphase.envoy] Requesting https://192.168.1.145/admin/lib/tariff with timeout Timeout(connect=10.0, read=60.0, write=10.0, pool=10.0)
[homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202207084671 data in XX.XX seconds (success: True)

You may want to check what these times are on average.

In the log you shared however, we see repeated requests, 2-3 seconds apart for /production endpoint only. Then a 1 minute gap and then all 3 seem to make it. But HA times it as 1 data collection attempt that took close to 3 minutes. And then the error happens with missing data, where normally no error happens.

So one theory can be that the Envoy had an issue, did not accept any requests and the first accepted request did not return all the expected data.

catsmanac commented 10 months ago

To add more detail to the debug log you can add below lines to the configuration.yaml file in the /config folder and restart HA. It will add details about the communication between HA and the Envoy and maybe shed some light on what is going on during these errors. It will cause the log file to have quite a bit more entries.

logger:
  default: warning
  logs:
    homeassistant.components.enphase_envoy: debug
    httpcore: debug
    httpx: debug
austinmroczek commented 9 months ago

sorry just got time to add that logging detail. will send an update soon.

austinmroczek commented 9 months ago

Here is the last error I have from today, and all relevant log entries for the 60 seconds preceding:

2023-12-08 03:59:16.036 DEBUG (MainThread) [httpcore.connection] close.started
2023-12-08 03:59:16.037 DEBUG (MainThread) [httpcore.connection] close.complete
2023-12-08 03:59:16.037 DEBUG (MainThread) [httpcore.connection] connect_tcp.started host='192.168.1.145' port=443 local_address=None timeout=10.0 socket_options=None
2023-12-08 03:59:16.040 DEBUG (MainThread) [httpcore.connection] connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7fee2ffb9490>
2023-12-08 03:59:16.040 DEBUG (MainThread) [httpcore.connection] start_tls.started ssl_context=<ssl.SSLContext object at 0x7fee46cf8290> server_hostname='192.168.1.145' timeout=10.0
2023-12-08 03:59:16.168 DEBUG (MainThread) [httpcore.connection] start_tls.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7fee2ffb8390>
2023-12-08 03:59:16.168 DEBUG (MainThread) [httpcore.http11] send_request_headers.started request=<Request [b'GET']>
2023-12-08 03:59:16.170 DEBUG (MainThread) [httpcore.http11] send_request_headers.complete
2023-12-08 03:59:16.170 DEBUG (MainThread) [httpcore.http11] send_request_body.started request=<Request [b'GET']>
2023-12-08 03:59:16.170 DEBUG (MainThread) [httpcore.http11] send_request_body.complete
2023-12-08 03:59:16.170 DEBUG (MainThread) [httpcore.http11] receive_response_headers.started request=<Request [b'GET']>
2023-12-08 03:59:16.468 DEBUG (MainThread) [httpcore.http11] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Server', b'openresty/1.17.8.1'), (b'Date', b'Fri, 08 Dec 2023 11:59:16 GMT'), (b'Content-Type', b'application/json'), (b'Transfer-Encoding', b'chunked'), (b'Connection', b'keep-alive'), (b'Set-Cookie', b'sessionId=5Lh6jroW1JFxg9YjP8Kan3bJSHahGbYz; Secure; HttpOnly; path=/'), (b'Pragma', b'no-cache'), (b'Expires', b'1'), (b'Cache-Control', b'no-cache'), (b'Strict-Transport-Security', b'max-age=63072000; includeSubdomains'), (b'X-Frame-Options', b'DENY'), (b'X-Content-Type-Options', b'nosniff')])
2023-12-08 03:59:16.469 INFO (MainThread) [httpx] HTTP Request: GET https://192.168.1.145/production "HTTP/1.1 200 OK"
2023-12-08 03:59:16.470 DEBUG (MainThread) [httpcore.http11] receive_response_body.started request=<Request [b'GET']>
2023-12-08 03:59:16.474 DEBUG (MainThread) [httpcore.http11] receive_response_body.complete
2023-12-08 03:59:16.474 DEBUG (MainThread) [httpcore.http11] response_closed.started
2023-12-08 03:59:16.474 DEBUG (MainThread) [httpcore.http11] response_closed.complete
2023-12-08 03:59:16.477 DEBUG (MainThread) [httpcore.http11] send_request_headers.started request=<Request [b'GET']>
2023-12-08 03:59:16.478 DEBUG (MainThread) [httpcore.http11] send_request_headers.complete
2023-12-08 03:59:16.478 DEBUG (MainThread) [httpcore.http11] send_request_body.started request=<Request [b'GET']>
2023-12-08 03:59:16.478 DEBUG (MainThread) [httpcore.http11] send_request_body.complete
2023-12-08 03:59:16.478 DEBUG (MainThread) [httpcore.http11] receive_response_headers.started request=<Request [b'GET']>
2023-12-08 03:59:16.515 DEBUG (MainThread) [httpcore.http11] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Server', b'openresty/1.17.8.1'), (b'Date', b'Fri, 08 Dec 2023 11:59:16 GMT'), (b'Content-Type', b'application/json'), (b'Content-Length', b'2934'), (b'Connection', b'keep-alive'), (b'Set-Cookie', b'sessionId=5Lh6jroW1JFxg9YjP8Kan3bJSHahGbYz; Secure; HttpOnly; path=/'), (b'Strict-Transport-Security', b'max-age=63072000; includeSubdomains'), (b'X-Frame-Options', b'DENY'), (b'X-Content-Type-Options', b'nosniff')])
2023-12-08 03:59:16.515 INFO (MainThread) [httpx] HTTP Request: GET https://192.168.1.145/api/v1/production/inverters "HTTP/1.1 200 OK"
2023-12-08 03:59:16.516 DEBUG (MainThread) [httpcore.http11] receive_response_body.started request=<Request [b'GET']>
2023-12-08 03:59:16.516 DEBUG (MainThread) [httpcore.http11] receive_response_body.complete
2023-12-08 03:59:16.516 DEBUG (MainThread) [httpcore.http11] response_closed.started
2023-12-08 03:59:16.516 DEBUG (MainThread) [httpcore.http11] response_closed.complete
2023-12-08 03:59:16.520 DEBUG (MainThread) [httpcore.http11] send_request_headers.started request=<Request [b'GET']>
2023-12-08 03:59:16.521 DEBUG (MainThread) [httpcore.http11] send_request_headers.complete
2023-12-08 03:59:16.521 DEBUG (MainThread) [httpcore.http11] send_request_body.started request=<Request [b'GET']>
2023-12-08 03:59:16.521 DEBUG (MainThread) [httpcore.http11] send_request_body.complete
2023-12-08 03:59:16.521 DEBUG (MainThread) [httpcore.http11] receive_response_headers.started request=<Request [b'GET']>
2023-12-08 03:59:17.946 DEBUG (MainThread) [httpcore.http11] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Server', b'openresty/1.17.8.1'), (b'Date', b'Fri, 08 Dec 2023 11:59:17 GMT'), (b'Content-Type', b'application/json'), (b'Transfer-Encoding', b'chunked'), (b'Connection', b'keep-alive'), (b'Set-Cookie', b'sessionId=5Lh6jroW1JFxg9YjP8Kan3bJSHahGbYz; Secure; HttpOnly; path=/'), (b'Pragma', b'no-cache'), (b'Expires', b'1'), (b'Cache-Control', b'no-cache'), (b'Strict-Transport-Security', b'max-age=63072000; includeSubdomains'), (b'X-Frame-Options', b'DENY'), (b'X-Content-Type-Options', b'nosniff')])
2023-12-08 03:59:17.947 INFO (MainThread) [httpx] HTTP Request: GET https://192.168.1.145/admin/lib/tariff "HTTP/1.1 200 OK"
2023-12-08 03:59:17.947 DEBUG (MainThread) [httpcore.http11] receive_response_body.started request=<Request [b'GET']>
2023-12-08 03:59:18.339 DEBUG (MainThread) [httpcore.http11] receive_response_body.complete
2023-12-08 03:59:18.339 DEBUG (MainThread) [httpcore.http11] response_closed.started
2023-12-08 03:59:18.339 DEBUG (MainThread) [httpcore.http11] response_closed.complete
2023-12-08 03:59:18.340 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202207084671 data in 2.306 seconds (success: True)
2023-12-08 03:59:35.592 ERROR (SyncWorker_9) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 243, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 399, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 182, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 479, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 745, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 845, in _async_write_ha_state
    state, attr = self._async_generate_attributes()
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 786, in _async_generate_attributes
    state = self._stringify_state(available)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 751, in _stringify_state
    if (state := self.state) is None:
                 ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 501, in state
    value = self.native_value
            ^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/enphase_envoy/sensor.py", line 486, in native_value
    return self.entity_description.value_fn(inverters[self._serial_number])
                                            ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: '202211186226'
austinmroczek commented 9 months ago

The times for each request are usually in the 1-5 second range. Then I get one that is 100+ seconds and then the error. So maybe something wonky with my device. It's odd though that it only has errors when there is no sun. times2.txt

catsmanac commented 9 months ago

Looking at the log the inverters endpoint is accessible and returns status 200 Ok, but apparently no data in the message.

2023-12-08 03:59:16.477 DEBUG (MainThread) [httpcore.http11] send_request_headers.started request=<Request [b'GET']>
2023-12-08 03:59:16.478 DEBUG (MainThread) [httpcore.http11] send_request_headers.complete
2023-12-08 03:59:16.478 DEBUG (MainThread) [httpcore.http11] send_request_body.started request=<Request [b'GET']>
2023-12-08 03:59:16.478 DEBUG (MainThread) [httpcore.http11] send_request_body.complete
2023-12-08 03:59:16.478 DEBUG (MainThread) [httpcore.http11] receive_response_headers.started request=<Request [b'GET']>
2023-12-08 03:59:16.515 DEBUG (MainThread) [httpcore.http11] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Server', b'openresty/1.17.8.1'), (b'Date', b'Fri, 08 Dec 2023 11:59:16 GMT'), (b'Content-Type', b'application/json'), (b'Content-Length', b'2934'), (b'Connection', b'keep-alive'), (b'Set-Cookie', b'sessionId=5Lh6jroW1JFxg9YjP8Kan3bJSHahGbYz; Secure; HttpOnly; path=/'), (b'Strict-Transport-Security', b'max-age=63072000; includeSubdomains'), (b'X-Frame-Options', b'DENY'), (b'X-Content-Type-Options', b'nosniff')])
2023-12-08 03:59:16.515 INFO (MainThread) [httpx] HTTP Request: GET https://192.168.1.145/api/v1/production/inverters "HTTP/1.1 200 OK"
2023-12-08 03:59:16.516 DEBUG (MainThread) [httpcore.http11] receive_response_body.started request=<Request [b'GET']>
2023-12-08 03:59:16.516 DEBUG (MainThread) [httpcore.http11] receive_response_body.complete
2023-12-08 03:59:16.516 DEBUG (MainThread) [httpcore.http11] response_closed.started
2023-12-08 03:59:16.516 DEBUG (MainThread) [httpcore.http11] response_closed.complete

and HA reposrts all data is collected in 2 seconds.

2023-12-08 03:59:18.340 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202207084671 data in 2.306 seconds (success: True)

The expected inverted can't be found in the reply.

  File "/usr/src/homeassistant/homeassistant/components/enphase_envoy/sensor.py", line 486, in native_value
    return self.entity_description.value_fn(inverters[self._serial_number])
                                            ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: '202211186226'

The replay reports a content lenght of 2934: (b'Content-Length', b'2934'). You may want to check what a previous inverter reply content-length was.

austinmroczek commented 9 months ago

So almost every time there is an error:

2023-12-06 22:30:14.178
2023-12-07 00:30:24.462
2023-12-07 02:31:09.516
2023-12-07 06:34:00.761
2023-12-07 23:58:50.042
2023-12-08 01:59:58.267
2023-12-08 03:59:35.592
2023-12-08 05:59:28.904

There is a 5 byte response preceeding it by ~60 seconds:

2023-12-06 22:30:11.539 DEBUG (b'Content-Length', b'5'), 
2023-12-07 00:30:19.131 DEBUG (b'Content-Length', b'5'), 
2023-12-07 02:30:31.316 DEBUG (b'Content-Length', b'5'), 
2023-12-07 04:30:51.282 DEBUG (b'Content-Length', b'5'), 
2023-12-07 23:57:45.181 DEBUG (b'Content-Length', b'5'), 
2023-12-08 01:58:00.586 DEBUG (b'Content-Length', b'5'), 
2023-12-08 03:58:11.389 DEBUG (b'Content-Length', b'5'), 
2023-12-08 05:58:22.733 DEBUG (b'Content-Length', b'5'),

With the exception of the 4th error, which appears to have length 2934 for several minutes leading up to it. The 04:30:51 response of 5 bytes has no error associated with it.

catsmanac commented 9 months ago

Currently the code is only dumping the received raw data at HA startup. So there's no way to make the actual data visible right now. I've proposed a code change to write the raw data to to log each time when received when in debug mode.

The code change needs to go through the approval and testing process before showing up in one of the upcoming HA updates.

I still have the suspicion that the envoy is returning either no or malformed data, but we need to code change to defeat of confirm this suspicion.

I'm not sure about the b'5' messages, could be a continuation of a previous one or a brief status. Would need to see the full lines as well as the context around it.

austinmroczek commented 9 months ago

I'm a dev for another integration, so could easily run a custom integration or run code directly if desired.

catsmanac commented 9 months ago

It was added to 2023.12.2 milestone with a due date of 12/15 so that's end of the week.

If you want to test before that you can pull the PR and try it. But you would need to run your dev overnight I guess as the issue happens then.

catsmanac commented 9 months ago

The code was merged into dev this morning.

catsmanac commented 9 months ago

The other pattern in the timing of the issue seems a 2 hour cycle. The first day every 2 hour at the bottom of the hour. The second day, 2 hours apart around minute 57 in the hour.

With the new debug code you want to look for lines starting with

2023-12-13 18:09:04.593 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Envoy data: EnvoyData(encharge_inventory

These contain all the of the data used by the integration. In the line look for raw={ . In that json section find api/v1/production/inverters like below example.

    '/api/v1/production/inverters': [{
            'serialNumber': '10000000001',
            'lastReportDate': 1699000000,
            'devType': 1,
            'lastReportWatts': 123,
            'maxReportWatts': 141
        }, {
            'serialNumber': '10000000002',
            'lastReportDate': 1699000000,
            'devType': 1,
            'lastReportWatts': 185,
            'maxReportWatts': 142
        }
    ]

Example of the raw section from a sim attached. envoy.json.txt

austinmroczek commented 9 months ago

Here's a new log with HA 2023.12.3:

2023-12-17 00:29:29.561 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=1018171, watt_hours_last_7_days=0, watt_hours_today=0, watts_now=0), dry_contact_status={}, dry_contact_settings={}, inverters={}, tariff=EnvoyTariff(currency={'code': 'USD'}, logger='mylogger', date='1681527491', storage_settings=EnvoyStorageSettings(mode=<EnvoyStorageMode.SELF_CONSUMPTION: 'self-consumption'>, operation_mode_sub_type='', reserved_soc=0.0, very_low_soc=5, charge_from_grid=False, date='1681527491'), single_rate={'rate': 0.0, 'sell': 0.0}, seasons=[], seasons_sell=[]), raw={'/production': {'production': [{'type': 'inverters', 'activeCount': 20, 'readingTime': 0, 'wNow': 0, 'whLifetime': 1018171}, {'type': 'eim', 'activeCount': 0, 'measurementType': 'production', 'readingTime': 1702801764, 'wNow': 0.0, 'whLifetime': 0.0, 'varhLeadLifetime': 0.0, 'varhLagLifetime': 0.0, 'vahLifetime': 0.0, 'rmsCurrent': 3.384, 'rmsVoltage': 241.844, 'reactPwr': 402.336, 'apprntPwr': 409.467, 'pwrFactor': 0.0, 'whToday': 0.0, 'whLastSevenDays': 0.0, 'vahToday': 0.0, 'varhLeadToday': 0.0, 'varhLagToday': 0.0}], 'consumption': [{'type': 'eim', 'activeCount': 0, 'measurementType': 'total-consumption', 'readingTime': 1702801764, 'wNow': 0.0, 'whLifetime': 0.0, 'varhLeadLifetime': 0.0, 'varhLagLifetime': 0.0, 'vahLifetime': 0.0, 'rmsCurrent': 3.621, 'rmsVoltage': 241.87, 'reactPwr': -402.336, 'apprntPwr': 875.815, 'pwrFactor': 0.0, 'whToday': 0.0, 'whLastSevenDays': 0.0, 'vahToday': 0.0, 'varhLeadToday': 0.0, 'varhLagToday': 0.0}, {'type': 'eim', 'activeCount': 0, 'measurementType': 'net-consumption', 'readingTime': 1702801764, 'wNow': 0.0, 'whLifetime': 0.0, 'varhLeadLifetime': 0.0, 'varhLagLifetime': 0.0, 'vahLifetime': 0.0, 'rmsCurrent': 0.237, 'rmsVoltage': 241.896, 'reactPwr': 0.0, 'apprntPwr': 28.47, 'pwrFactor': 0.0, 'whToday': 0, 'whLastSevenDays': 0, 'vahToday': 0, 'varhLeadToday': 0, 'varhLagToday': 0}], 'storage': [{'type': 'acb', 'activeCount': 0, 'readingTime': 0, 'wNow': 0, 'whNow': 0, 'state': 'idle'}]}, '/api/v1/production/inverters': [], '/admin/lib/tariff': {'tariff': {'currency': {'code': 'USD'}, 'logger': 'mylogger', 'date': '1681527491', 'storage_settings': {'mode': 'self-consumption', 'operation_mode_sub_type': '', 'reserved_soc': 0.0, 'very_low_soc': 5, 'charge_from_grid': False, 'date': '1681527491'}, 'single_rate': {'rate': 0.0, 'sell': 0.0}, 'seasons': [], 'seasons_sell': []}, 'schedule': {'source': 'Tariff', 'date': '2023-07-05 16:31:10 UTC', 'version': '00.00.02', 'reserved_soc': 0.0, 'operation_mode_sub_type': '', 'very_low_soc': 5, 'charge_from_grid': False, 'battery_mode': 'self-consumption', 'schedule': {'Disable': [{'Sun': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Mon': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Tue': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Wed': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Thu': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Fri': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Sat': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}], 'tariff': [{'start': '1/1', 'end': '1/1', 'Sun': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Mon': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Tue': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Wed': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Thu': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Fri': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Sat': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}]}]}, 'override': False, 'override_backup_soc': 30.0, 'override_chg_dischg_rate': 0.0, 'override_tou_mode': 'StorageTouMode_DEFAULT_TOU_MODE'}}})
2023-12-17 00:29:29.562 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202207084671 data in 147.582 seconds (success: True)
2023-12-17 00:29:29.562 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 243, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 399, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 182, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 479, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 745, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 845, in _async_write_ha_state
    state, attr = self._async_generate_attributes()
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 786, in _async_generate_attributes
    state = self._stringify_state(available)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 751, in _stringify_state
    if (state := self.state) is None:
                 ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 501, in state
    value = self.native_value
            ^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/enphase_envoy/sensor.py", line 486, in native_value
    return self.entity_description.value_fn(inverters[self._serial_number])
                                            ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: '202211186226'

It's returning an empty array.

austinmroczek commented 9 months ago

...but I just noticed that one (of 4 current log entries) responds with an empty array but no error, then a seemingly valid response, then a KeyError.


2023-12-16 20:29:04.615 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=1018171, watt_hours_last_7_days=0, watt_hours_today=0, watts_now=0), dry_contact_status={}, dry_contact_settings={}, inverters={}, tariff=EnvoyTariff(currency={'code': 'USD'}, logger='mylogger', date='1681527491', storage_settings=EnvoyStorageSettings(mode=<EnvoyStorageMode.SELF_CONSUMPTION: 'self-consumption'>, operation_mode_sub_type='', reserved_soc=0.0, very_low_soc=5, charge_from_grid=False, date='1681527491'), single_rate={'rate': 0.0, 'sell': 0.0}, seasons=[], seasons_sell=[]), raw={'/production': {'production': [{'type': 'inverters', 'activeCount': 20, 'readingTime': 0, 'wNow': 0, 'whLifetime': 1018171}, {'type': 'eim', 'activeCount': 0, 'measurementType': 'production', 'readingTime': 1702787338, 'wNow': 0.0, 'whLifetime': 0.0, 'varhLeadLifetime': 0.0, 'varhLagLifetime': 0.0, 'vahLifetime': 0.0, 'rmsCurrent': 3.377, 'rmsVoltage': 242.239, 'reactPwr': 402.478, 'apprntPwr': 409.073, 'pwrFactor': 0.0, 'whToday': 0.0, 'whLastSevenDays': 0.0, 'vahToday': 0.0, 'varhLeadToday': 0.0, 'varhLagToday': 0.0}], 'consumption': [{'type': 'eim', 'activeCount': 0, 'measurementType': 'total-consumption', 'readingTime': 1702787338, 'wNow': 0.0, 'whLifetime': 0.0, 'varhLeadLifetime': 0.0, 'varhLagLifetime': 0.0, 'vahLifetime': 0.0, 'rmsCurrent': 3.607, 'rmsVoltage': 242.176, 'reactPwr': -402.478, 'apprntPwr': 873.435, 'pwrFactor': 0.0, 'whToday': 0.0, 'whLastSevenDays': 0.0, 'vahToday': 0.0, 'varhLeadToday': 0.0, 'varhLagToday': 0.0}, {'type': 'eim', 'activeCount': 0, 'measurementType': 'net-consumption', 'readingTime': 1702787338, 'wNow': 0.0, 'whLifetime': 0.0, 'varhLeadLifetime': 0.0, 'varhLagLifetime': 0.0, 'vahLifetime': 0.0, 'rmsCurrent': 0.23, 'rmsVoltage': 242.114, 'reactPwr': 0.0, 'apprntPwr': 28.076, 'pwrFactor': 0.0, 'whToday': 0, 'whLastSevenDays': 0, 'vahToday': 0, 'varhLeadToday': 0, 'varhLagToday': 0}], 'storage': [{'type': 'acb', 'activeCount': 0, 'readingTime': 0, 'wNow': 0, 'whNow': 0, 'state': 'idle'}]}, '/api/v1/production/inverters': [], '/admin/lib/tariff': {'tariff': {'currency': {'code': 'USD'}, 'logger': 'mylogger', 'date': '1681527491', 'storage_settings': {'mode': 'self-consumption', 'operation_mode_sub_type': '', 'reserved_soc': 0.0, 'very_low_soc': 5, 'charge_from_grid': False, 'date': '1681527491'}, 'single_rate': {'rate': 0.0, 'sell': 0.0}, 'seasons': [], 'seasons_sell': []}, 'schedule': {'source': 'Tariff', 'date': '2023-07-05 16:31:10 UTC', 'version': '00.00.02', 'reserved_soc': 0.0, 'operation_mode_sub_type': '', 'very_low_soc': 5, 'charge_from_grid': False, 'battery_mode': 'self-consumption', 'schedule': {'Disable': [{'Sun': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Mon': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Tue': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Wed': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Thu': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Fri': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Sat': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}], 'tariff': [{'start': '1/1', 'end': '1/1', 'Sun': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Mon': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Tue': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Wed': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Thu': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Fri': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Sat': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}]}]}, 'override': False, 'override_backup_soc': 30.0, 'override_chg_dischg_rate': 0.0, 'override_tou_mode': 'StorageTouMode_DEFAULT_TOU_MODE'}}})
2023-12-16 20:29:04.615 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202207084671 data in 165.636 seconds (success: True)
2023-12-16 20:30:03.981 DEBUG (MainThread) [httpcore.connection] close.started
2023-12-16 20:30:03.982 DEBUG (MainThread) [httpcore.connection] close.complete
2023-12-16 20:30:03.982 DEBUG (MainThread) [httpcore.connection] connect_tcp.started host='192.168.1.145' port=443 local_address=None timeout=10.0 socket_options=None
2023-12-16 20:30:03.984 DEBUG (MainThread) [httpcore.connection] connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7fac0c2a9f90>
2023-12-16 20:30:03.985 DEBUG (MainThread) [httpcore.connection] start_tls.started ssl_context=<ssl.SSLContext object at 0x7fac24362e70> server_hostname='192.168.1.145' timeout=10.0
2023-12-16 20:30:04.185 DEBUG (MainThread) [httpcore.connection] start_tls.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7fac0c2abe90>
2023-12-16 20:30:04.186 DEBUG (MainThread) [httpcore.http11] send_request_headers.started request=<Request [b'GET']>
2023-12-16 20:30:04.186 DEBUG (MainThread) [httpcore.http11] send_request_headers.complete
2023-12-16 20:30:04.187 DEBUG (MainThread) [httpcore.http11] send_request_body.started request=<Request [b'GET']>
2023-12-16 20:30:04.187 DEBUG (MainThread) [httpcore.http11] send_request_body.complete
2023-12-16 20:30:04.187 DEBUG (MainThread) [httpcore.http11] receive_response_headers.started request=<Request [b'GET']>
2023-12-16 20:30:04.701 DEBUG (MainThread) [httpcore.http11] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Server', b'openresty/1.17.8.1'), (b'Date', b'Sun, 17 Dec 2023 04:30:04 GMT'), (b'Content-Type', b'application/json'), (b'Transfer-Encoding', b'chunked'), (b'Connection', b'keep-alive'), (b'Set-Cookie', b'sessionId=Gj6tkQmrNVzLcZ4EhVnz57jQLBx4wumm; Secure; HttpOnly; path=/'), (b'Pragma', b'no-cache'), (b'Expires', b'1'), (b'Cache-Control', b'no-cache'), (b'Strict-Transport-Security', b'max-age=63072000; includeSubdomains'), (b'X-Frame-Options', b'DENY'), (b'X-Content-Type-Options', b'nosniff')])
2023-12-16 20:30:04.702 INFO (MainThread) [httpx] HTTP Request: GET https://192.168.1.145/production "HTTP/1.1 200 OK"
2023-12-16 20:30:04.702 DEBUG (MainThread) [httpcore.http11] receive_response_body.started request=<Request [b'GET']>
2023-12-16 20:30:04.708 DEBUG (MainThread) [httpcore.http11] receive_response_body.complete
2023-12-16 20:30:04.709 DEBUG (MainThread) [httpcore.http11] response_closed.started
2023-12-16 20:30:04.709 DEBUG (MainThread) [httpcore.http11] response_closed.complete
2023-12-16 20:30:04.711 DEBUG (MainThread) [httpcore.http11] send_request_headers.started request=<Request [b'GET']>
2023-12-16 20:30:04.712 DEBUG (MainThread) [httpcore.http11] send_request_headers.complete
2023-12-16 20:30:04.713 DEBUG (MainThread) [httpcore.http11] send_request_body.started request=<Request [b'GET']>
2023-12-16 20:30:04.713 DEBUG (MainThread) [httpcore.http11] send_request_body.complete
2023-12-16 20:30:04.713 DEBUG (MainThread) [httpcore.http11] receive_response_headers.started request=<Request [b'GET']>
2023-12-16 20:30:04.751 DEBUG (MainThread) [httpcore.http11] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Server', b'openresty/1.17.8.1'), (b'Date', b'Sun, 17 Dec 2023 04:30:04 GMT'), (b'Content-Type', b'application/json'), (b'Content-Length', b'2934'), (b'Connection', b'keep-alive'), (b'Set-Cookie', b'sessionId=Gj6tkQmrNVzLcZ4EhVnz57jQLBx4wumm; Secure; HttpOnly; path=/'), (b'Strict-Transport-Security', b'max-age=63072000; includeSubdomains'), (b'X-Frame-Options', b'DENY'), (b'X-Content-Type-Options', b'nosniff')])
2023-12-16 20:30:04.752 INFO (MainThread) [httpx] HTTP Request: GET https://192.168.1.145/api/v1/production/inverters "HTTP/1.1 200 OK"
2023-12-16 20:30:04.752 DEBUG (MainThread) [httpcore.http11] receive_response_body.started request=<Request [b'GET']>
2023-12-16 20:30:04.753 DEBUG (MainThread) [httpcore.http11] receive_response_body.complete
2023-12-16 20:30:04.753 DEBUG (MainThread) [httpcore.http11] response_closed.started
2023-12-16 20:30:04.753 DEBUG (MainThread) [httpcore.http11] response_closed.complete
2023-12-16 20:30:04.756 DEBUG (MainThread) [httpcore.http11] send_request_headers.started request=<Request [b'GET']>
2023-12-16 20:30:04.757 DEBUG (MainThread) [httpcore.http11] send_request_headers.complete
2023-12-16 20:30:04.757 DEBUG (MainThread) [httpcore.http11] send_request_body.started request=<Request [b'GET']>
2023-12-16 20:30:04.757 DEBUG (MainThread) [httpcore.http11] send_request_body.complete
2023-12-16 20:30:04.757 DEBUG (MainThread) [httpcore.http11] receive_response_headers.started request=<Request [b'GET']>
2023-12-16 20:30:05.273 DEBUG (MainThread) [httpcore.http11] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Server', b'openresty/1.17.8.1'), (b'Date', b'Sun, 17 Dec 2023 04:30:04 GMT'), (b'Content-Type', b'application/json'), (b'Transfer-Encoding', b'chunked'), (b'Connection', b'keep-alive'), (b'Set-Cookie', b'sessionId=Gj6tkQmrNVzLcZ4EhVnz57jQLBx4wumm; Secure; HttpOnly; path=/'), (b'Pragma', b'no-cache'), (b'Expires', b'1'), (b'Cache-Control', b'no-cache'), (b'Strict-Transport-Security', b'max-age=63072000; includeSubdomains'), (b'X-Frame-Options', b'DENY'), (b'X-Content-Type-Options', b'nosniff')])
2023-12-16 20:30:05.274 INFO (MainThread) [httpx] HTTP Request: GET https://192.168.1.145/admin/lib/tariff "HTTP/1.1 200 OK"
2023-12-16 20:30:05.274 DEBUG (MainThread) [httpcore.http11] receive_response_body.started request=<Request [b'GET']>
2023-12-16 20:30:05.487 DEBUG (MainThread) [httpcore.http11] receive_response_body.complete
2023-12-16 20:30:05.487 DEBUG (MainThread) [httpcore.http11] response_closed.started
2023-12-16 20:30:05.488 DEBUG (MainThread) [httpcore.http11] response_closed.complete
2023-12-16 20:30:05.489 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=1018171, watt_hours_last_7_days=0, watt_hours_today=0, watts_now=0), dry_contact_status={}, dry_contact_settings={}, inverters={'202211186226': EnvoyInverter(serial_number='202211186226', last_report_date=1702773674, last_report_watts=2, max_report_watts=2), '202211170473': EnvoyInverter(serial_number='202211170473', last_report_date=1702772982, last_report_watts=3, max_report_watts=3), '202211189869': EnvoyInverter(serial_number='202211189869', last_report_date=1702773613, last_report_watts=3, max_report_watts=3), '202211191862': EnvoyInverter(serial_number='202211191862', last_report_date=1702773962, last_report_watts=2, max_report_watts=2), '202211165752': EnvoyInverter(serial_number='202211165752', last_report_date=1702773707, last_report_watts=2, max_report_watts=2), '202211097237': EnvoyInverter(serial_number='202211097237', last_report_date=1702773708, last_report_watts=1, max_report_watts=1), '202212007684': EnvoyInverter(serial_number='202212007684', last_report_date=0, last_report_watts=0, max_report_watts=0), '202211165038': EnvoyInverter(serial_number='202211165038', last_report_date=1702773743, last_report_watts=2, max_report_watts=2), '202211172599': EnvoyInverter(serial_number='202211172599', last_report_date=1702773680, last_report_watts=2, max_report_watts=2), '202211192106': EnvoyInverter(serial_number='202211192106', last_report_date=1702773745, last_report_watts=2, max_report_watts=2), '202211134471': EnvoyInverter(serial_number='202211134471', last_report_date=1702772808, last_report_watts=3, max_report_watts=3), '202211164114': EnvoyInverter(serial_number='202211164114', last_report_date=1702773748, last_report_watts=1, max_report_watts=1), '202211168086': EnvoyInverter(serial_number='202211168086', last_report_date=1702772810, last_report_watts=2, max_report_watts=2), '202211185578': EnvoyInverter(serial_number='202211185578', last_report_date=1702773815, last_report_watts=2, max_report_watts=2), '202211097252': EnvoyInverter(serial_number='202211097252', last_report_date=1702773590, last_report_watts=2, max_report_watts=2), '202211063100': EnvoyInverter(serial_number='202211063100', last_report_date=1702773751, last_report_watts=2, max_report_watts=2), '202211191153': EnvoyInverter(serial_number='202211191153', last_report_date=1702772748, last_report_watts=4, max_report_watts=4), '202211050230': EnvoyInverter(serial_number='202211050230', last_report_date=1702773788, last_report_watts=1, max_report_watts=1), '202211168562': EnvoyInverter(serial_number='202211168562', last_report_date=1702773790, last_report_watts=1, max_report_watts=1), '202149002133': EnvoyInverter(serial_number='202149002133', last_report_date=1702772838, last_report_watts=3, max_report_watts=3)}, tariff=EnvoyTariff(currency={'code': 'USD'}, logger='mylogger', date='1681527491', storage_settings=EnvoyStorageSettings(mode=<EnvoyStorageMode.SELF_CONSUMPTION: 'self-consumption'>, operation_mode_sub_type='', reserved_soc=0.0, very_low_soc=5, charge_from_grid=False, date='1681527491'), single_rate={'rate': 0.0, 'sell': 0.0}, seasons=[], seasons_sell=[]), raw={'/production': {'production': [{'type': 'inverters', 'activeCount': 20, 'readingTime': 0, 'wNow': 0, 'whLifetime': 1018171}, {'type': 'eim', 'activeCount': 0, 'measurementType': 'production', 'readingTime': 1702787403, 'wNow': 0.0, 'whLifetime': 0.0, 'varhLeadLifetime': 0.0, 'varhLagLifetime': 0.0, 'vahLifetime': 0.0, 'rmsCurrent': 3.375, 'rmsVoltage': 242.013, 'reactPwr': 401.186, 'apprntPwr': 408.409, 'pwrFactor': 0.0, 'whToday': 0.0, 'whLastSevenDays': 0.0, 'vahToday': 0.0, 'varhLeadToday': 0.0, 'varhLagToday': 0.0}], 'consumption': [{'type': 'eim', 'activeCount': 0, 'measurementType': 'total-consumption', 'readingTime': 1702787403, 'wNow': 0.0, 'whLifetime': 0.0, 'varhLeadLifetime': 0.0, 'varhLagLifetime': 0.0, 'vahLifetime': 0.0, 'rmsCurrent': 3.612, 'rmsVoltage': 242.066, 'reactPwr': -401.186, 'apprntPwr': 874.431, 'pwrFactor': 0.0, 'whToday': 0.0, 'whLastSevenDays': 0.0, 'vahToday': 0.0, 'varhLeadToday': 0.0, 'varhLagToday': 0.0}, {'type': 'eim', 'activeCount': 0, 'measurementType': 'net-consumption', 'readingTime': 1702787403, 'wNow': 0.0, 'whLifetime': 0.0, 'varhLeadLifetime': 0.0, 'varhLagLifetime': 0.0, 'vahLifetime': 0.0, 'rmsCurrent': 0.237, 'rmsVoltage': 242.12, 'reactPwr': 0.0, 'apprntPwr': 28.49, 'pwrFactor': 0.0, 'whToday': 0, 'whLastSevenDays': 0, 'vahToday': 0, 'varhLeadToday': 0, 'varhLagToday': 0}], 'storage': [{'type': 'acb', 'activeCount': 0, 'readingTime': 0, 'wNow': 0, 'whNow': 0, 'state': 'idle'}]}, '/api/v1/production/inverters': [{'serialNumber': '202211186226', 'lastReportDate': 1702773674, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211170473', 'lastReportDate': 1702772982, 'devType': 1, 'lastReportWatts': 3, 'maxReportWatts': 3}, {'serialNumber': '202211189869', 'lastReportDate': 1702773613, 'devType': 1, 'lastReportWatts': 3, 'maxReportWatts': 3}, {'serialNumber': '202211191862', 'lastReportDate': 1702773962, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211165752', 'lastReportDate': 1702773707, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211097237', 'lastReportDate': 1702773708, 'devType': 1, 'lastReportWatts': 1, 'maxReportWatts': 1}, {'serialNumber': '202212007684', 'lastReportDate': 0, 'devType': 1, 'lastReportWatts': 0, 'maxReportWatts': 0}, {'serialNumber': '202211165038', 'lastReportDate': 1702773743, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211172599', 'lastReportDate': 1702773680, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211192106', 'lastReportDate': 1702773745, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211134471', 'lastReportDate': 1702772808, 'devType': 1, 'lastReportWatts': 3, 'maxReportWatts': 3}, {'serialNumber': '202211164114', 'lastReportDate': 1702773748, 'devType': 1, 'lastReportWatts': 1, 'maxReportWatts': 1}, {'serialNumber': '202211168086', 'lastReportDate': 1702772810, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211185578', 'lastReportDate': 1702773815, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211097252', 'lastReportDate': 1702773590, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211063100', 'lastReportDate': 1702773751, 'devType': 1, 'lastReportWatts': 2, 'maxReportWatts': 2}, {'serialNumber': '202211191153', 'lastReportDate': 1702772748, 'devType': 1, 'lastReportWatts': 4, 'maxReportWatts': 4}, {'serialNumber': '202211050230', 'lastReportDate': 1702773788, 'devType': 1, 'lastReportWatts': 1, 'maxReportWatts': 1}, {'serialNumber': '202211168562', 'lastReportDate': 1702773790, 'devType': 1, 'lastReportWatts': 1, 'maxReportWatts': 1}, {'serialNumber': '202149002133', 'lastReportDate': 1702772838, 'devType': 1, 'lastReportWatts': 3, 'maxReportWatts': 3}], '/admin/lib/tariff': {'tariff': {'currency': {'code': 'USD'}, 'logger': 'mylogger', 'date': '1681527491', 'storage_settings': {'mode': 'self-consumption', 'operation_mode_sub_type': '', 'reserved_soc': 0.0, 'very_low_soc': 5, 'charge_from_grid': False, 'date': '1681527491'}, 'single_rate': {'rate': 0.0, 'sell': 0.0}, 'seasons': [], 'seasons_sell': []}, 'schedule': {'source': 'Tariff', 'date': '2023-07-05 16:31:10 UTC', 'version': '00.00.02', 'reserved_soc': 0.0, 'operation_mode_sub_type': '', 'very_low_soc': 5, 'charge_from_grid': False, 'battery_mode': 'self-consumption', 'schedule': {'Disable': [{'Sun': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Mon': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Tue': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Wed': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Thu': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Fri': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}, {'Sat': [{'start': 0, 'duration': 1440, 'setting': 'ID'}]}], 'tariff': [{'start': '1/1', 'end': '1/1', 'Sun': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Mon': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Tue': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Wed': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Thu': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Fri': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}], 'Sat': [{'start': 0, 'duration': 1440, 'setting': 'ZN'}]}]}, 'override': False, 'override_backup_soc': 30.0, 'override_chg_dischg_rate': 0.0, 'override_tou_mode': 'StorageTouMode_DEFAULT_TOU_MODE'}}})
2023-12-16 20:30:05.489 DEBUG (MainThread) [homeassistant.components.enphase_envoy.coordinator] Finished fetching Envoy 202207084671 data in 1.510 seconds (success: True)
2023-12-16 20:30:10.103 ERROR (Recorder) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 243, in _handle_refresh_interval
    await self._async_refresh(log_failures=True, scheduled=True)
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 399, in _async_refresh
    self.async_update_listeners()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 182, in async_update_listeners
    update_callback()
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 479, in _handle_coordinator_update
    self.async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 745, in async_write_ha_state
    self._async_write_ha_state()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 845, in _async_write_ha_state
    state, attr = self._async_generate_attributes()
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 786, in _async_generate_attributes
    state = self._stringify_state(available)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 751, in _stringify_state
    if (state := self.state) is None:
                 ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/sensor/__init__.py", line 501, in state
    value = self.native_value
            ^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/enphase_envoy/sensor.py", line 486, in native_value
    return self.entity_description.value_fn(inverters[self._serial_number])
                                            ~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: '202211186226'
catsmanac commented 9 months ago

The empty array is definitely the cause of the error. Only option is to capture the error so log remains clean and other data that came back is collected. The inverters would show unknown for that collection cycle and debug log may show an entry reporting the empty array. Root cause is something going on in the Envoy apparently every ~4 hours.

As for the second log, I think it's the processing of the first reply with the empty array by HA core. Don't know how and when these run or get triggered to run, but its probably some delayed processing.

Can you share the log part of the collection before the failures so I can see what all is communicating in those long 165 second periods? Like 1 successful one and than all what happened in the long period. Its not only an empty array returned, but it takes for-ever as well.