search

briancmpbll / home_assistant_custom_envoy

173 stars 76 forks source link

Fetch of home.json times out, failing initialisation #123

Closed jsimonetti closed 11 months ago

jsimonetti commented 11 months ago

Hi, Using both 0.0.13 and main branch, I am having problems reading my Envoy system. The initialisation fails when fetching home.json. It appears that my system somehow blocks on that request.

I manually disabled the call to home.json and everything works again. I did this by commenting lines 159:162 from envoy_reader.py:

          #if self.has_grid_status:
          #    await self._update_endpoint(
          #        "endpoint_home_json_results", ENDPOINT_URL_HOME_JSON
          #    )

I am unsure why this is happening.

catsmanac commented 11 months ago

What type Envoy do you have @jsimonetti? Looks like for some reason it's expecting it has grid status.

Did this happen when you configured it for the first time and did it never start, or would it start and report issues in each collection run?

Can you enable debug on the envoy, let it run for a couple of minutes and disable it again, it will download the log file to your computer. Inspect it for any errors reported? Feel free to share, but remove the token information from it if you do so.

jsimonetti commented 11 months ago

I have an envoy-s-metered-eu.

I noticed this behaviour since yesterday evening, where it suddenly stopped responding. (I still have recorder entries up to then). Today I started debugging this, and noticed it is hanging on home.json.

See here the debug logging:

023-08-03 16:39:27.684 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Checking Token value:
2023-08-03 16:39:27.684 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Found empty token:
2023-08-03 16:39:31.818 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Commissioned Token valid for 364.9999905234851 days
2023-08-03 16:39:31.819 WARNING (MainThread) [custom_components.enphase_envoy.envoy_reader] Debug Info: setting Authorization header with token.
2023-08-03 16:39:31.820 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://10.10.3.30/auth/check_jwt: True: Header:{'Authorization': 'Bearer <TOKEN>'}
2023-08-03 16:39:32.356 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://10.10.3.30/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html><h2>Valid token.</h2>
2023-08-03 16:39:32.358 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Token is valid
2023-08-03 16:39:32.359 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://10.10.3.30/production.json?details=1: True: Header:{'Authorization': 'Bearer <TOKEN>'}
2023-08-03 16:39:36.726 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://10.10.3.30/production.json?details=1: <Response [200 OK]>: {"production":[{"type":"inverters","activeCount":15,"readingTime":1691073496,"wNow":1140,"whLifetime":593644},{"type":"eim","activeCount":1,"measurementType":"production","readingTime":1691073548,"wNow":1154.017,"whLifetime":7827146.87,"varhLeadLifetime":1.284,"varhLagLifetime":2583669.107,"vahLifetime":9722477.821,"rmsCurrent":5.015,"rmsVoltage":732.076,"reactPwr":255.554,"apprntPwr":1223.949,"pwrFactor":0.95,"whToday":13055.87,"whLastSevenDays":117277.87,"vahToday":15721.821,"varhLeadToday":1.284,"varhLagToday":4153.107,"lines":[{"wNow":462.929,"whLifetime":3117445.526,"varhLeadLifetime":0.509,"varhLagLifetime":1039597.975,"vahLifetime":3836923.549,"rmsCurrent":1.967,"rmsVoltage":245.613,"reactPwr":104.05,"apprntPwr":482.482,"pwrFactor":0.97,"whToday":5142.526,"whLastSevenDays":46736.526,"vahToday":6165.549,"varhLeadToday":0.509,"varhLagToday":1672.975},{"wNow":306.466,"whLifetime":2114511.901,"varhLeadLifetime":0.297,"varhLagLifetime":691175.402,"vahLifetime":2757522.498,"rmsCurrent":1.398,"rmsVoltage":243.122,"reactPwr":68.291,"apprntPwr":339.684,"pwrFactor":0.89,"whToday":3528.901,"whLastSevenDays":31513.901,"vahToday":4443.498,"varhLeadToday":0.297,"varhLagToday":1109.402},{"wNow":384.622,"whLifetime":2595189.443,"varhLeadLifetime":0.479,"varhLagLifetime":852895.729,"vahLifetime":3128031.774,"rmsCurrent":1.651,"rmsVoltage":243.341,"reactPwr":83.213,"apprntPwr":401.783,"pwrFactor":0.96,"whToday":4384.443,"whLastSevenDays":39027.443,"vahToday":5112.774,"varhLeadToday":0.479,"varhLagToday":1370.729}]}],"consumption":[{"type":"eim","activeCount":0,"measurementType":"total-consumption","readingTime":1691073548,"wNow":1154.017,"whLifetime":7827146.87,"varhLeadLifetime":-1.284,"varhLagLifetime":-2583669.107,"vahLifetime":0.0,"rmsCurrent":4.722,"rmsVoltage":732.691,"reactPwr":256.103,"apprntPwr":1154.23,"pwrFactor":1.0,"whToday":7827146.87,"whLastSevenDays":7827146.87,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0,"lines":[{"wNow":462.929,"whLifetime":3117445.526,"varhLeadLifetime":-0.509,"varhLagLifetime":-1039597.975,"vahLifetime":0.0,"rmsCurrent":1.967,"rmsVoltage":245.761,"reactPwr":104.05,"apprntPwr":483.322,"pwrFactor":0.96,"whToday":3117445.526,"whLastSevenDays":3117445.526,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0},{"wNow":306.466,"whLifetime":2114511.901,"varhLeadLifetime":-0.297,"varhLagLifetime":-691175.402,"vahLifetime":0.0,"rmsCurrent":1.105,"rmsVoltage":243.26,"reactPwr":68.84,"apprntPwr":268.705,"pwrFactor":1.0,"whToday":2114511.901,"whLastSevenDays":2114511.901,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0},{"wNow":384.622,"whLifetime":2595189.443,"varhLeadLifetime":-0.479,"varhLagLifetime":-852895.729,"vahLifetime":0.0,"rmsCurrent":1.651,"rmsVoltage":243.67,"reactPwr":83.213,"apprntPwr":402.203,"pwrFactor":0.96,"whToday":2595189.443,"whLastSevenDays":2595189.443,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0}]},{"type":"eim","activeCount":0,"measurementType":"net-consumption","readingTime":1691073548,"wNow":-0.0,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":-0.293,"rmsVoltage":732.691,"reactPwr":0.549,"apprntPwr":-71.273,"pwrFactor":0.0,"whToday":0,"whLastSevenDays":0,"vahToday":0,"varhLeadToday":0,"varhLagToday":0,"lines":[{"wNow":0.0,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.0,"rmsVoltage":245.761,"reactPwr":-0.0,"apprntPwr":0.0,"pwrFactor":0.0,"whToday":0,"whLastSevenDays":0,"vahToday":0,"varhLeadToday":0,"varhLagToday":0},{"wNow":-0.0,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":-0.293,"rmsVoltage":243.26,"reactPwr":0.549,"apprntPwr":-71.273,"pwrFactor":-1.0,"whToday":0,"whLastSevenDays":0,"vahToday":0,"varhLeadToday":0,"varhLagToday":0},{"wNow":0.0,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.0,"rmsVoltage":243.67,"reactPwr":0.0,"apprntPwr":0.0,"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"}]}
2023-08-03 16:39:36.727 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://10.10.3.30/ivp/ensemble/inventory: True: Header:{'Authorization': 'Bearer <TOKEN>'}
2023-08-03 16:39:36.954 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://10.10.3.30/ivp/ensemble/inventory: <Response [200 OK]>: []
2023-08-03 16:39:36.955 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://10.10.3.30/home.json: True: Header:{'Authorization': 'Bearer <TOKEN>'}
2023-08-03 16:39:55.878 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #2: https://10.10.3.30/home.json: True: Header:{'Authorization': 'Bearer <TOKEN>'}
2023-08-03 16:39:57.687 DEBUG (MainThread) [custom_components.enphase_envoy] Finished fetching envoy Envoy 122148009364 data in 30.003 seconds (success: False)

Debug run with the home.json commented out as mentioned above:

2023-08-03 16:42:39.055 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Checking Token value:
2023-08-03 16:42:39.055 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Found empty token:
2023-08-03 16:42:42.800 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Commissioned Token valid for 364.9999907389145 days
2023-08-03 16:42:42.800 WARNING (MainThread) [custom_components.enphase_envoy.envoy_reader] Debug Info: setting Authorization header with token.
2023-08-03 16:42:42.801 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://10.10.3.30/auth/check_jwt: True: Header:{'Authorization': 'Bearer <TOKEN>'}
2023-08-03 16:42:43.048 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://10.10.3.30/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html><h2>Valid token.</h2>
2023-08-03 16:42:43.049 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Token is valid
2023-08-03 16:42:43.049 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://10.10.3.30/production.json?details=1: True: Header:{'Authorization': 'Bearer <TOKEN>'}
2023-08-03 16:42:43.928 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://10.10.3.30/production.json?details=1: <Response [200 OK]>: {"production":[{"type":"inverters","activeCount":15,"readingTime":1691073673,"wNow":1215,"whLifetime":593757},{"type":"eim","activeCount":1,"measurementType":"production","readingTime":1691073735,"wNow":2104.146,"whLifetime":7827227.41,"varhLeadLifetime":1.284,"varhLagLifetime":2583682.419,"vahLifetime":9722560.242,"rmsCurrent":8.615,"rmsVoltage":735.901,"reactPwr":257.724,"apprntPwr":2127.797,"pwrFactor":0.99,"whToday":13136.41,"whLastSevenDays":117358.41,"vahToday":15804.242,"varhLeadToday":1.284,"varhLagToday":4166.419,"lines":[{"wNow":842.225,"whLifetime":3117477.753,"varhLeadLifetime":0.509,"varhLagLifetime":1039603.383,"vahLifetime":3836956.421,"rmsCurrent":3.418,"rmsVoltage":247.577,"reactPwr":106.421,"apprntPwr":851.056,"pwrFactor":0.99,"whToday":5174.753,"whLastSevenDays":46768.753,"vahToday":6198.421,"varhLeadToday":0.509,"varhLagToday":1678.383},{"wNow":561.57,"whLifetime":2114533.394,"varhLeadLifetime":0.297,"varhLagLifetime":691178.944,"vahLifetime":2757544.773,"rmsCurrent":2.323,"rmsVoltage":243.694,"reactPwr":67.896,"apprntPwr":569.255,"pwrFactor":0.99,"whToday":3550.394,"whLastSevenDays":31535.394,"vahToday":4465.773,"varhLeadToday":0.297,"varhLagToday":1112.944},{"wNow":700.352,"whLifetime":2595216.263,"varhLeadLifetime":0.479,"varhLagLifetime":852900.092,"vahLifetime":3128059.048,"rmsCurrent":2.874,"rmsVoltage":244.63,"reactPwr":83.406,"apprntPwr":707.485,"pwrFactor":0.98,"whToday":4411.263,"whLastSevenDays":39054.263,"vahToday":5140.048,"varhLeadToday":0.479,"varhLagToday":1375.092}]}],"consumption":[{"type":"eim","activeCount":0,"measurementType":"total-consumption","readingTime":1691073735,"wNow":2104.146,"whLifetime":7827227.41,"varhLeadLifetime":-1.284,"varhLagLifetime":-2583682.419,"vahLifetime":0.0,"rmsCurrent":8.324,"rmsVoltage":736.513,"reactPwr":258.685,"apprntPwr":2046.204,"pwrFactor":1.0,"whToday":7827227.41,"whLastSevenDays":7827227.41,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0,"lines":[{"wNow":842.225,"whLifetime":3117477.753,"varhLeadLifetime":-0.509,"varhLagLifetime":-1039603.383,"vahLifetime":0.0,"rmsCurrent":3.418,"rmsVoltage":247.686,"reactPwr":106.421,"apprntPwr":846.609,"pwrFactor":0.99,"whToday":3117477.753,"whLastSevenDays":3117477.753,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0},{"wNow":561.57,"whLifetime":2114533.394,"varhLeadLifetime":-0.297,"varhLagLifetime":-691178.944,"vahLifetime":0.0,"rmsCurrent":2.032,"rmsVoltage":243.888,"reactPwr":68.857,"apprntPwr":495.56,"pwrFactor":1.0,"whToday":2114533.394,"whLastSevenDays":2114533.394,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0},{"wNow":700.352,"whLifetime":2595216.263,"varhLeadLifetime":-0.479,"varhLagLifetime":-852900.092,"vahLifetime":0.0,"rmsCurrent":2.874,"rmsVoltage":244.939,"reactPwr":83.406,"apprntPwr":704.035,"pwrFactor":0.99,"whToday":2595216.263,"whLastSevenDays":2595216.263,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0}]},{"type":"eim","activeCount":0,"measurementType":"net-consumption","readingTime":1691073735,"wNow":-0.0,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":-0.291,"rmsVoltage":736.513,"reactPwr":0.961,"apprntPwr":-71.015,"pwrFactor":0.0,"whToday":0,"whLastSevenDays":0,"vahToday":0,"varhLeadToday":0,"varhLagToday":0,"lines":[{"wNow":0.0,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.0,"rmsVoltage":247.686,"reactPwr":-0.0,"apprntPwr":0.0,"pwrFactor":0.0,"whToday":0,"whLastSevenDays":0,"vahToday":0,"varhLeadToday":0,"varhLagToday":0},{"wNow":-0.0,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":-0.291,"rmsVoltage":243.888,"reactPwr":0.961,"apprntPwr":-71.015,"pwrFactor":-1.0,"whToday":0,"whLastSevenDays":0,"vahToday":0,"varhLeadToday":0,"varhLagToday":0},{"wNow":0.0,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.0,"rmsVoltage":244.939,"reactPwr":0.0,"apprntPwr":0.0,"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"}]}
2023-08-03 16:42:43.929 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://10.10.3.30/ivp/ensemble/inventory: True: Header:{'Authorization': 'Bearer <TOKEN>'}
2023-08-03 16:42:44.136 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://10.10.3.30/ivp/ensemble/inventory: <Response [200 OK]>: []
2023-08-03 16:42:44.137 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://10.10.3.30/api/v1/production/inverters: True: Header:{'Authorization': 'Bearer <TOKEN>'}
2023-08-03 16:42:44.362 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://10.10.3.30/api/v1/production/inverters: <Response [200 OK]>: [
2023-08-03 16:42:44.366 DEBUG (MainThread) [custom_components.enphase_envoy] Retrieved data from API: {'production': 2104, 'daily_production': 13136, 'seven_days_production': 117358, 'lifetime_production': 7827227, 'consumption': 2104, 'daily_consumption': 7827227, 'seven_days_consumption': 7827227, 'lifetime_consumption': 7827227, 'inverters_production': {'482149001757': [85, '2023-08-03 16:32:41'], '482149001655': [89, '2023-08-03 16:33:40'], '482149001558': [87, '2023-08-03 16:34:10'], '482219052636': [86, '2023-08-03 16:37:11'], '482219052511': [75, '2023-08-03 16:40:11'], '482219052517': [74, '2023-08-03 16:40:13'], '482149001399': [84, '2023-08-03 16:37:41'], '482219052516': [82, '2023-08-03 16:37:42'], '482219052535': [89, '2023-08-03 16:35:11'], '482149001787': [85, '2023-08-03 16:32:41'], '482219052305': [76, '2023-08-03 16:40:41'], '482219052536': [80, '2023-08-03 16:38:12'], '482219052115': [77, '2023-08-03 16:39:43'], '482149001626': [72, '2023-08-03 16:40:44'], '482219052496': [73, '2023-08-03 16:41:13']}, 'production_l1': 842, 'daily_production_l1': 5174, 'lifetime_production_l1': 3117477, 'production_l2': 561, 'daily_production_l2': 3550, 'lifetime_production_l2': 2114533, 'production_l3': 700, 'daily_production_l3': 4411, 'lifetime_production_l3': 2595216, 'consumption_l1': 842, 'daily_consumption_l1': 3117477, 'lifetime_consumption_l1': 3117477, 'consumption_l2': 561, 'daily_consumption_l2': 2114533, 'lifetime_consumption_l2': 2114533, 'consumption_l3': 700, 'daily_consumption_l3': 2595216, 'lifetime_consumption_l3': 2595216, 'grid_status': None}
2023-08-03 16:42:44.366 DEBUG (MainThread) [custom_components.enphase_envoy] Finished fetching envoy Envoy 122148009364 data in 5.311 seconds (success: True)
jsimonetti commented 11 months ago

FYI I have firmware version D7.6.175, should that make any difference.

catsmanac commented 11 months ago

Are the meters actually connected?

catsmanac commented 11 months ago

What happens if you open http://envoy.local/home.json in your browser?

I'm getting a listing of data pretty quick and am on D7.6.175 too

jsimonetti commented 11 months ago

I get an error page retrieving home.json:

# curl -kv https://10.10.3.30/home.json
*   Trying 10.10.3.30:443...
* Connected to 10.10.3.30 (10.10.3.30) port 443 (#0)
* ALPN: offers h2,http/1.1
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
* ALPN: server did not agree on a protocol. Uses default.
* Server certificate:
*  subject: CN=envoy-122148009364
*  start date: Jul  7 05:39:51 2023 GMT
*  expire date: Jul  6 05:39:51 2024 GMT
*  issuer: CN=envoy-122148009364
*  SSL certificate verify result: self-signed certificate (18), continuing anyway.
* using HTTP/1.x
> GET /home.json HTTP/1.1
> Host: 10.10.3.30
> User-Agent: curl/8.1.1
> Accept: */*
>
< HTTP/1.1 301 Moved Permanently
< Server: openresty/1.17.8.1
< Date: Thu, 03 Aug 2023 15:24:03 GMT
< Content-Type: application/json
< Transfer-Encoding: chunked
< Connection: keep-alive
< Pragma: no-cache
< Expires: 1
< Cache-Control: no-cache
< Location: /error
< Strict-Transport-Security: max-age=63072000; includeSubdomains
< X-Frame-Options: DENY
< X-Content-Type-Options: nosniff
<
* TLSv1.2 (IN), TLS alert, close notify (256):
* transfer closed with outstanding read data remaining
* Closing connection 0
* TLSv1.2 (OUT), TLS alert, close notify (256):
curl: (18) transfer closed with outstanding read data remaining

I have the production meters/clamps connected, the usage meters/clamps are not connected.

jsimonetti commented 11 months ago

This is the error page btw:

image
jsimonetti commented 11 months ago

Ok, i am not sure what was happening, but after powercycling the envoy, home.json works as expected. So it looks like this is not a problem with this integration.

catsmanac commented 11 months ago

Good to hear you solved it.

jsimonetti commented 11 months ago

Thank you for the time and effort!