search

briancmpbll / home_assistant_custom_envoy

173 stars 76 forks source link

Failing setup (since yesterday) #127

Closed RolandGoud closed 10 months ago

RolandGoud commented 11 months ago

Since yesterday the set up fails every time. I think I updated HA yesterday(?)

Home Assistant 2023.8.1 Supervisor 2023.08.1 Operating System 10.4

catsmanac commented 11 months ago

You had this custom integration running, updated HA to new version and it wouldn't start anymore?

Anything in the log file /config/home-assistant.log?

What type of Envoy?

KRGT-NL commented 11 months ago

Same - removed - re-added - but getting this error in the Debug.

Home Assistant 2023.8.1 Supervisor 2023.08.1 Operating System 10.4 Frontend-versie: 20230802.0 - latest

2023-08-09 12:51:21.967 WARNING (MainThread) [custom_components.enphase_envoy_custom.envoy_reader] Debug Info: setting Authorization header with token.
2023-08-09 12:52:17.406 WARNING (MainThread) [custom_components.enphase_envoy_custom.envoy_reader] Debug Info: setting Authorization header with token.
2023-08-09 12:52:43.754 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Envoy 12345678900' for enphase_envoy integration not ready yet; Retrying in background
2023-08-09 12:52:43.757 ERROR (MainThread) [homeassistant.helpers.integration_platform] Unexpected error importing enphase_envoy/diagnostics.py
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/integration_platform.py", line 50, in _async_process_single_integration_platform_component
    platform = integration.get_platform(platform_name)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/loader.py", line 833, in get_platform
    cache[full_name] = self._import_platform(platform_name)
                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/loader.py", line 850, in _import_platform
    return importlib.import_module(f"{self.pkg_path}.{platform_name}")
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/importlib/__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<frozen importlib._bootstrap>", line 1204, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1176, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1140, in _find_and_load_unlocked
ModuleNotFoundError: No module named 'custom_components.enphase_envoy_custom.diagnostics'
catsmanac commented 11 months ago

Rename folder 'config/custom_components/enphase_envoy_custom' to 'config/custom_components/enphase_envoy' and restart HA. Did you use HACS to install?

KRGT-NL commented 11 months ago

@catsmanac Yes, sorry - had used HACS - but now installed manual - have renamed the folder -

Below the logs, looks OK to me, removed the key - but the Add-on gives: "No devices or entities" and initialisation failed, will try again later"

2023-08-09 15:52:20.440 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://192.168.2.35/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html><h2>Valid token.</h2>

2023-08-09 15:52:22.876 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://192.168.2.35/production.json?details=1: <Response [200 OK]>: {"production":[{"type":"inverters","activeCount":15,"readingTime":1691589085,"wNow":3696,"whLifetime":956339},{"type":"eim","activeCount":0,"measurementType":"production","readingTime":1691589099,"wNow":1.371,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.324,"rmsVoltage":247.442,"reactPwr":0.0,"apprntPwr":25.257,"pwrFactor":0.0,"whToday":0.0,"whLastSevenDays":0.0,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0,"lines":[{"wNow":1.304,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.102,"rmsVoltage":238.716,"reactPwr":0.0,"apprntPwr":24.269,"pwrFactor":0.0,"whToday":0.0,"whLastSevenDays":0.0,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0},{"wNow":0.0,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":-0.0,"rmsVoltage":4.302,"reactPwr":-0.0,"apprntPwr":-0.0,"pwrFactor":0.0,"whToday":0.0,"whLastSevenDays":0.0,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0},{"wNow":0.066,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.223,"rmsVoltage":4.424,"reactPwr":-0.0,"apprntPwr":0.988,"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":1691589099,"wNow":0.832,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.064,"rmsVoltage":251.13,"reactPwr":0.0,"apprntPwr":24.034,"pwrFactor":0.0,"whToday":0.0,"whLastSevenDays":0.0,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0,"lines":[{"wNow":1.304,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.102,"rmsVoltage":238.691,"reactPwr":0.0,"apprntPwr":24.263,"pwrFactor":0.05,"whToday":0.0,"whLastSevenDays":0.0,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0},{"wNow":-0.539,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":-0.26,"rmsVoltage":6.21,"reactPwr":-0.0,"apprntPwr":-1.615,"pwrFactor":-1.0,"whToday":0.0,"whLastSevenDays":0.0,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0},{"wNow":0.066,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":0.223,"rmsVoltage":6.229,"reactPwr":-0.0,"apprntPwr":1.386,"pwrFactor":0.05,"whToday":0.0,"whLastSevenDays":0.0,"vahToday":0.0,"varhLeadToday":0.0,"varhLagToday":0.0}]},{"type":"eim","activeCount":0,"measurementType":"net-consumption","readingTime":1691589099,"wNow":-0.539,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":-0.26,"rmsVoltage":251.13,"reactPwr":0.0,"apprntPwr":-1.615,"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":238.691,"reactPwr":0.0,"apprntPwr":0.0,"pwrFactor":0.0,"whToday":0,"whLastSevenDays":0,"vahToday":0,"varhLeadToday":0,"varhLagToday":0},{"wNow":-0.539,"whLifetime":0.0,"varhLeadLifetime":0.0,"varhLagLifetime":0.0,"vahLifetime":0.0,"rmsCurrent":-0.26,"rmsVoltage":6.21,"reactPwr":0.0,"apprntPwr":-1.615,"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":6.229,"reactPwr":0.0,"apprntPwr":0.0,"pwrFactor":0.39,"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-09 15:52:22.877 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://192.168.2.35/ivp/ensemble/inventory: True: Header:{'Authorization': 'Bearer 
2023-08-09 15:52:23.087 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://192.168.2.35/ivp/ensemble/inventory: <Response [200 OK]>: []
2023-08-09 15:52:23.087 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://192.168.2.35/home.json: True: Header:{'Authorization': 'Bearer 
2023-08-09 15:52:35.173 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #2: https://192.168.2.35/home.json: True: Header:{'Authorization': 'Bearer '}
RolandGoud commented 11 months ago

my custom components folder was already named enphase_envoy' i used HACS

2023-08-09 16:46:50.216 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Checking Token value: 2023-08-09 16:46:50.217 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Found empty token: 2023-08-09 16:46:54.866 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Commissioned Token valid for 364.99998997383096 days 2023-08-09 16:46:54.866 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://192.168..x.xxx/auth/check_jwt: Header:{'Authorization': 'Bearer xxxxxx'} 2023-08-09 16:46:55.092 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://192.168..x.xxx/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html><h2>Valid token.</h2> 2023-08-09 16:46:55.097 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Token is valid 2023-08-09 16:46:55.098 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://192.168..x.xxx/production.json?details=1: Header:{'Authorization': 'Bearer xxxxxx'} 2023-08-09 16:46:55.660 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://192.168.x.xxx/production.json?details=1: <Response [200 OK]>: {"production":[{"type":"inverters","activeCount":10,"readingTime":1691592469,"wNow":784,"whLifetime":880790}],"storage":[{"type":"acb","activeCount":0,"readingTime":0,"wNow":0,"whNow":0,"state":"idle"}]} 2023-08-09 16:46:55.664 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://192.168..x.xxx/ivp/ensemble/inventory: Header:{'Authorization': 'Bearer xxxxxx'} 2023-08-09 16:46:55.894 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] Fetched from https://192.168.x.xxx/ivp/ensemble/inventory: <Response [200 OK]>: [] 2023-08-09 16:46:55.896 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #1: https://192.168.x.xxx/home.json: Header:{'Authorization': 'Bearer xxxxxx'} 2023-08-09 16:47:12.421 DEBUG (MainThread) [custom_components.enphase_envoy.envoy_reader] HTTP GET Attempt #2: https://192.168.x.xxx/home.json: Header:{'Authorization': 'Bearer xxxxx'} 2023-08-09 16:47:20.219 DEBUG (MainThread) [custom_components.enphase_envoy] Finished fetching envoy Envoy 122149071928 data in 30.003 seconds (success: False) 2023-08-09 16:47:20.220 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Envoy 122149071xxx' for enphase_envoy integration not ready yet; Retrying in background

catsmanac commented 11 months ago

Just fired up one of my dev systems running that same version you are using with @briancmpbll 's 0.0.13 version working with my ENVOY-S Standard with firmware D7.6.175 and all working fine here.

Both your logfiles show same problem, failing on home.json. There's some reports that on some systems this page is slow.

What ENVOY types are you using, ENVOY-s Standard or metered, and if metered are Current Messuremnts coils installed and configured or not? And which firmware version is the Envoy running?

Can you: Enable debug on the envoy, reload Envoy or restart HA, let it run for couple of minutes and disable debug again. In the downloaded file clean the token (whole or partially) and share the file as file so we can see what's going on in detail.

KRGT-NL commented 11 months ago

Not all the time right now to generate the debug - but some information already:

I run the ENVOY Metered on firmware D7.6.175 (f79c8d) but without the coils and Metering is disabled.

I feel like the same - that the page is to slow - and it drops the request. Let me shut down - and start the Envoy again.

/edit After een reboot of the ENVOY - it works again for a couple of minutes and then stops... and works again...

I think it's the firmware who is buggy from Enphase... if the CPU is not keeping up.

RolandGoud commented 11 months ago

@catsmanac: no cclue what you mean with standard or metered...Gateway is on D7.6.175

I rebooted the gateway....it seems to work now. (but lets see how long it lasts)

catsmanac commented 11 months ago

Currently time-out for requests is 30 seconds. If you know where to find the config folder of home assistant then you can try changing that value. navigate to /config/custom_components/enphase_envoy.

In that folder edit envoy_reader.py

Look for a line 'async def _async_fetch_with_retry(self, url, **kwargs):'

Couple of line below it you find 

            try:
                async with self.async_client as client:
                    resp = await client.get(
                        url, headers=self._authorization_header, timeout=30, **kwargs
                    )

There change the timeout=30 to timeout=60, save the file and restart HA. Maybe it brings relief.

If you rather have me doing such a thing let me know, but it will come with a recipe to load a test version of this integration (add another HCAS library, download the test version and try that one).

Can you also check if you have a grid-status entity in your HA? That is sourced from home file, but if you don't have it it should not load home.

catsmanac commented 11 months ago

no cclue what you mean with standard or metered...Gateway is on D7.6.175

@RolandGoud , the Gateway comes in a standard version and a metered version. Packaged in the same box, but the metered one has connection points where current transformers (CT) can be connected to measure power through the power lines.

These CT are typically used to measure power consumption by the house and production by the solar panels. Such measurements are more accurate and faster then the numbers from the inverters on the solar panels. Especially when installing batteries these are used to control battery charge and discharge. The Standard version does not have that possibility.

Both run same firmware version, the firmware detects the mode and behaves differently based on that.

RolandGoud commented 11 months ago

rebooting the gateway seemed to have fixed it for me!

catsmanac commented 11 months ago

V0.0.15 is published that has option in the configure menu to change timing. You can increase the 'Timeout for getting single Envoy data page' setting. Default is 30 sec. If needed also increase the 'Overall timeout on getting all Envoy data' which is 55 sec default.

When you update your changes to the code will be overwritten, so you can use the configure menu to change it again.

To find what time is needed, increase the both numbers, enable debug on the envoy and reload it or restart HA. Let it run for couple of minutes and disable debug again. In the log file is downloaded look for line like:

Finished fetching envoy Envoy 122302045041 data in 9.433 seconds (success: True)

This time as an indication for the overall timeout.

For the individual page timeouts look for time used on the home page as taht is typically the slowest one:

HTTP GET Attempt #1 of 2: https://192.168.3.112/home.json: use token: True: Header: <Token hidden>  Timeout: 30 Holdoff: 0
Fetched (1 of 2) in 3.0 sec from https://192.168.3.112/home.json: <Response [200 OK]>: {"software_build_epoch":1687430621,"timezone":"