[BUG] Initial configuration failed

itguy013 commented 5 months ago

Describe the bug Failed to initialize error. First time configuring this addon. The Enphase Envoy (DEV) was working perfectly. I wanted to switch to this integration because of the extra installer functions, but the initial configuration is not working. Debug logging shows that the integration is able to read some data.

Account type

[x] Installer
[ ] DIY / DHZ
[ ] Home Owner (This integration is not (fully) functional with a home owner account!)

Envoy

[x ] Metered with CTs installed
[ ] Metered without CTs
[ ] Standard
FW version: D7.6.175
Amount of micro inverters connected: 14

Home Assistant

Version: 2024.4.4

Additional context


Relevant snippet of Home Assistant error log. 
2024-04-30 16:54:34.586 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP POST https://xxx.xxx.xxx.xxx/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html><h2>Valid token.</h2>

2024-04-30 16:54:34.591 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] UPDATING ENDPOINT endpoint_production_json: https://{}/production.json?details=1
2024-04-30 16:54:34.591 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://xxx.xxx.xxx.xxx/production.json?details=1: Header:{} Cookies:<Cookies[<Cookie sessionId=for xxx.xxx.xxx.xxx />]>
2024-04-30 16:54:38.906 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://xxx.xxx.xxx.xxx/production.json?details=1: <Response [200 OK]>:  (and a lot of data)

vincentwolsink commented 5 months ago

Hi! Are there also any errors in the logs? Usually when this happens the previous integration was not fully removed. Please make sure that the custom_components/enphase_envoy dir is completely removed before installing this one.

itguy013 commented 5 months ago

Deleted the dir custom_components/enphase_envoy. Rebooted, tried to configure the integration but still failed to initialize.

024-05-01 10:39:36.289 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Checking Token value: 2024-05-01 10:39:36.289 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Found empty token: 2024-05-01 10:39:36.289 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetching envoy token 2024-05-01 10:39:36.295 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Local auth secret: 2024-05-01 10:39:36.295 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Doing authorize at entrez, with codeChallenge: 2024-05-01 10:39:36.940 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Checking JWT on envoy with params {'client_id': 'envoy-ui-1', 'code': '', 'code_verifier': '', 'grant_type': 'authorization_code', 'redirect_uri': 'https://xxx.xxx.xxx.xxx/auth/callback'} 2024-05-01 10:39:47.449 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Envoy Token 2024-05-01 10:39:47.449 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Token expires at: 2024-05-01 22:39:44 2024-05-01 10:39:47.452 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Token expires at: 2024-05-01 22:39:44 2024-05-01 10:39:47.452 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] TOKEN TYPE: installer 2024-05-01 10:39:47.452 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP POST Attempt: https://xxx.xxx.xxx.xxx/auth/check_jwt 2024-05-01 10:39:47.452 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP POST Data: None 2024-05-01 10:39:47.737 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP POST https://xxx.xxx.xxx.xxx/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html>

Valid token.

2024-05-01 10:39:47.738 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP POST Cookie: <Cookies[]> 2024-05-01 10:39:47.739 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] We got a session cookie (sessionId), empty the auth header 2024-05-01 10:39:47.739 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] Updating endpoints ['endpoint_production_json'] 2024-05-01 10:39:47.740 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] UPDATING ENDPOINT endpoint_production_json: https://{}/production.json?details=1 2024-05-01 10:39:47.740 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://xxx.xxx.xxx.xxx/production.json?details=1: Header:{} Cookies:<Cookies[]>

2024-05-01 10:39:54.271 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://xxx.xxx.xxx.xxx/production.json?details=1: <Response [200 OK]>: {"production":[{"type":"inverters","activeCount":14,"readingTime":1714552732,"wNow":2623,"whLifetime":503013},{"type":"eim","activeCount":1,"measurementType":"production","readingTime":1714552780,"wNow":2673.771,"whLifetime":14969957.303,"varhLeadLifetime":0.011,"varhLagLifetime":6249342.449,"vahLifetime":19540611.945,"rmsCurrent":11.224,"rmsVoltage":240.1,"reactPwr":248.343,"apprntPwr":2695.213,"pwrFactor":0.99,"whToday":4800.303,"whLastSevenDays":125572.303,"vahToday":6725.945,"varhLeadToday":0.011,"varhLagToday":2506.449,"lines":[{"wNow":2673.771,"whLifetime":14969957.303,"varhLeadLifetime":0.011,"varhLagLifetime":6249342.449,"vahLifetime":19540611.945,"rmsCurrent":11.224,"rmsVoltage":240.1,"reactPwr":248.343,"apprntPwr":2695.213,"pwrFactor":0.99,"whToday":4800.303,"whLastSevenDays":125572.303,"vahToday":6725.945,"varhLeadToday":0.011,"varhLagToday":2506.449}]}],"consumption":[{"type":"eim","activeCount":1,"measurementType":"total-consumption","readingTime":1714552780,"wNow":194.092,"whLifetime":12126093.537,"varhLeadLifetime":9517410.271,"varhLagLifetime":-6249198.632,"vahLifetime":26572894.436,"rmsCurrent":0.732,"rmsVoltage":240.123,"reactPwr":-85.642,"apprntPwr":175.709,"pwrFactor":1.0,"whToday":2302.537,"whLastSevenDays":23.537,"vahToday":7959.436,"varhLeadToday":3571.271,"varhLagToday":0.0,"lines":[{"wNow":194.092,"whLifetime":12126093.537,"varhLeadLifetime":9517410.271,"varhLagLifetime":-6249198.632,"vahLifetime":26572894.436,"rmsCurrent":0.732,"rmsVoltage":240.123,"reactPwr":-85.642,"apprntPwr":175.709,"pwrFactor":1.0,"whToday":2302.537,"whLastSevenDays":23.537,"vahToday":7959.436,"varhLeadToday":3571.271,"varhLagToday":0.0}]},{"type":"eim","activeCount":1,"measurementType":"net-consumption","readingTime":1714552780,"wNow":-2479.679,"whLifetime":-2843461.555,"varhLeadLifetime":9517410.282,"varhLagLifetime":143.818,"vahLifetime":26572894.436,"rmsCurrent":-10.492,"rmsVoltage":240.123,"reactPwr":-333.985,"apprntPwr":-2519.394,"pwrFactor":-1.0,"whToday":0,"whLastSevenDays":0,"vahToday":0,"varhLeadToday":0,"varhLagToday":0,"lines":[{"wNow":-2479.679,"whLifetime":-2843461.555,"varhLeadLifetime":9517410.282,"varhLagLifetime":143.818,"vahLifetime":26572894.436,"rmsCurrent":-10.492,"rmsVoltage":240.123,"reactPwr":-333.985,"apprntPwr":-2519.394,"pwrFactor":-1.0,"whToday":0,"whLastSevenDays":0,"vahToday":0,"varhLeadToday":0,"varhLagToday":0}]}],"storage":[{"type":"acb","activeCount":0,"readingTime":0,"wNow":0,"whNow":0,"state":"idle"}]} 2024-05-01 10:39:54.273 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] - FETCHING ENDPOINT endpoint_production_json TOOK 6.5335 seconds 2024-05-01 10:39:54.275 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_ensemble_power.devices: 2024-05-01 10:39:54.276 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_ensemble_power.devices: did not return anything! 2024-05-01 10:39:54.276 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_ensemble_inventory[0].devices 2024-05-01 10:39:54.276 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_ensemble_inventory[0].devices did not return anything! 2024-05-01 10:39:54.276 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_ensemble_power.devices: 2024-05-01 10:39:54.276 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_ensemble_power.devices: did not return anything! 2024-05-01 10:39:54.276 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_home_json.enpower.grid_status 2024-05-01 10:39:54.277 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_home_json.enpower.grid_status did not return anything! 2024-05-01 10:39:54.277 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_inventory.[?(@.type=='PCU')].devices[?(@.dev_type==1)] 2024-05-01 10:39:54.277 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_inventory.[?(@.type=='PCU')].devices[?(@.dev_type==1)] did not return anything! 2024-05-01 10:39:54.277 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_devstatus.pcu[?(@.devType==1)] 2024-05-01 10:39:54.277 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_devstatus.pcu[?(@.devType==1)] did not return anything! 2024-05-01 10:39:54.277 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_production_power.powerForcedOff 2024-05-01 10:39:54.277 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_production_power.powerForcedOff did not return anything! 2024-05-01 10:39:54.277 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_inventory.[?(@.type=='NSRB')].devices[?(@.dev_type==12)] 2024-05-01 10:39:54.278 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_inventory.[?(@.type=='NSRB')].devices[?(@.dev_type==12)] did not return anything! 2024-05-01 10:39:54.278 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_devstatus.pcu[?(@.devType==12)] 2024-05-01 10:39:54.278 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_devstatus.pcu[?(@.devType==12)] did not return anything! 2024-05-01 10:39:54.278 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_devstatus.nsrb 2024-05-01 10:39:54.278 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_devstatus.nsrb did not return anything! 2024-05-01 10:39:54.278 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Resolving jsonpath endpoint_inventory.[?(@.type=='NSRB')].devices[?(@.dev_type==12)] 2024-05-01 10:39:54.278 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] the configured path endpoint_inventory.[?(@.type=='NSRB')].devices[?(@.dev_type==12)] did not return anything! 2024-05-01 10:39:54.279 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] EnvoyData.get(relay_info) -> {} 2024-05-01 10:39:54.279 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] Updating endpoints {'endpoint_home_json', 'endpoint_ensemble_inventory', 'endpoint_ensemble_power', 'endpoint_inventory', 'endpoint_installer_agf', 'endpoint_production_report', 'endpoint_production_json', 'endpoint_info', 'endpoint_devstatus', 'endpoint_ensemble_secctrl', 'endpoint_production_power'} 2024-05-01 10:39:54.279 INFO (MainThread) [custom_components.enphase_envoy.envoy_reader] UPDATING ENDPOINT endpoint_home_json: https://{}/home.json 2024-05-01 10:39:54.279 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://xxx.xxx.xxx.xxx/home.json: Header:{} Cookies:<Cookies[]> 2024-05-01 10:40:15.107 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] TransportError: peer closed connection without sending complete message body (incomplete chunked read) 2024-05-01 10:40:15.109 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #2: https://xxx.xxx.xxx.xxx/home.json: Header:{} Cookies:<Cookies[]> 2024-05-01 10:40:26.975 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] TransportError: peer closed connection without sending complete message body (incomplete chunked read) 2024-05-01 10:40:26.975 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #3: https://xxx.xxx.xxx.xxx/home.json: Header:{} Cookies:<Cookies[]> 2024-05-01 10:40:36.293 DEBUG (MainThread) [custom_components.enphase_envoy] Finished fetching envoy Envoy 122103022093 data in 60.004 seconds (success: False)

vincentwolsink commented 5 months ago

Your Envoy does not respond in time to the request of home.json. You can try to power cycle your Envoy, usually this resolves the issue.

itguy013 commented 5 months ago

Still got the same error after rebooting the envoy:

2024-05-01 21:44:57.919 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] TransportError: peer closed connection without sending complete message body (incomplete chunked read).

Anything else I can try to let this work? This is after it tries to connect to home.json

vincentwolsink commented 5 months ago

Very strange. Does it work if you manually fetch home.json via your browser?

vincentwolsink / home_assistant_enphase_envoy_installer

[BUG] Initial configuration failed #127

Valid token.