search

Hoffmann77 / home_assistant_enphase_gateway

A custom integration for Home Assistant to read data from your Enphase Gateway.
Apache License 2.0
0 stars 0 forks source link

Integration does not collect individual inverter data for Envoy-S non metered. #5

Closed catsmanac closed 1 year ago

catsmanac commented 1 year ago

For envoy-s non metered the integration only collects data from api/v1/production but not from api/v1/production/inverters.

Might be caused by the 401 at startup for production.json

home-assistant-v012-beta.log

Hoffmann77 commented 1 year ago

Yes this indeed originates from the initial 401 Error which causes a wrong classification of the gateway. Will have to improve error handling with a 401 response during model detection.

Regarding the initial 401 response, do you by any chance have a second integration running that uses token based authentication? Still investigating the reason of the initial 401 response.

catsmanac commented 1 year ago

No other token based integration active. What I note is that the use of 

ENDPOINT_URL_CHECK_JWT = "https://{}/auth/check_jwt"

to validate the token with the envoy has disappeared. Before you can access production.json you need to validate the token against auth/check_jwt on the envoy. The api/v1/production does not need token validation and it even seems when hitting it first validates the token too. But think you need to store the session cookie in either case.

catsmanac commented 1 year ago

The working one has this logic that is called right after obtaing token from enphase (or from file for that matter):

    async def _refresh_token_cookies(self):
        """
        Refresh the client's cookie with the token (if valid)
        :returns True if cookie refreshed, False if it couldn't be
        """
        # Create HTTP Header
        self._authorization_header = {"Authorization": "Bearer " + self._token}

        # Fetch the Enphase Token status from the local Envoy
        token_validation = await self._async_post(
            ENDPOINT_URL_CHECK_JWT.format(self.host)
        )

        if token_validation.status_code == 200:
            # set the cookies for future clients
            self._cookies = token_validation.cookies
            return True
catsmanac commented 1 year ago

Did some more testing and added _refresh_token_cookies to gateway_reader and call it from getData

        # Check if the Secure flag is set
        if self.use_token_auth:
            await self._enphase_token.prepare()
            await self._refresh_token_cookies()

_refresh_token_cookies is code from original

    async def _refresh_token_cookies(self):
        """
        Refresh the client's cookie with the token (if valid)
        :returns True if cookie refreshed, False if it couldn't be
        """
        # Create HTTP Header
        #self._authorization_header = {"Authorization": "Bearer " + self._enphase_token.token}

        # Fetch the Enphase Token status from the local Envoy
        token_validation = await self._async_post(
            ENDPOINT_URL_CHECK_JWT.format(self.host)
        )

        if token_validation.status_code == 200:
            # set the cookies for future clients
            self._cookies = token_validation.cookies
            return True

and had to uncomment the _async_post again and change it slighly

    async def _async_post(self, url, retries=2, data=None, raise_for_status=True, **kwargs):
        """Post using async.

        Parameters
        ----------
        url : str
            HTTP POST target url.
        retries : int, optional
            Number of retries to perform after the initial post request fails. 
            The default is 2.
        raise_for_status : bool, optional
            If True raise an exception for non 2xx responses.
            The default is True.
        **kwargs : dict, optional
            Extra arguments to httpx client.post().

        Returns
        -------
        r : http response
            HTTP POST response object.

        """
        client = httpx.AsyncClient(verify=False,  timeout=10.0)
        async with client:
            for attempt in range(1, 4):
                _LOGGER.debug(f"HTTP POST Attempt: #{attempt}: {url}")
                try:
                    r = await client.post(url,
                    headers=self._auth_header,
                    cookies=self._cookies,
                    data=data,
                    timeout=30.0,
                    **kwargs)
                    _LOGGER.debug(f"HTTP POST {url}: {r}: {r.text}")
                    _LOGGER.debug(f"HTTP POST Cookie: {r.cookies}")
                    if raise_for_status:
                        r.raise_for_status()
                except httpx.HTTPStatusError as err:
                    status_code = err.response.status_code
                    _LOGGER.debug(
                        f"Received status_code {status_code} from Envoy."
                    )
                    if status_code == 503:
                        raise RuntimeError(
                            "Envoy Service temporary unavailable (503)"
                        )
                    else:
                        raise
                except httpx.TransportError:
                    if attempt >= retries + 1:
                        raise
                    else:
                        await asyncio.sleep(attempt * 0.15)
                else:
                    return r

That brought the individual inverter data into the log

2023-07-04 21:32:18.061 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] HTTP GET Attempt #1: https://192.168.3.112/api/v1/production/inverters: Header:{'Authorization': 'Bearer <token>'}
2023-07-04 21:32:18.295 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Fetched from https://192.168.3.112/api/v1/production/inverters: <Response [200 OK]>: [
  {
    "serialNumber": "122219085275",
    "lastReportDate": 1688498825,
    "devType": 1,
    "lastReportWatts": 1,
    "maxReportWatts": 309
  },
  {
    "serialNumber": "122219085086",
    "lastReportDate": 1688498827,
    "devType": 1,
    "lastReportWatts": 1,
    "maxReportWatts": 338
  },

There's still a lot of rough edges but it confirms the missing token validation with the envoy and storing the envoy session cookies. Above is just proof of concept, it probably needs better integration.

Hoffmann77 commented 1 year ago

Hey, thanks for the debugging work. Will definitely include the referesh_token_cookies logic back into the code with an upcoming update. I need to do some initial bug fixing for that update on the weekend first though.

Nevertheless I still don't really understand why authenticating using the authentication header isn't working in your case.

Would you be willing to add something like: _LOGGER.debug(f"Received error from Gateway: {err}") to line 283 of enphase_geteway.py? Maybe that way we can get some information why the 401 error is raised. Would need you to comment await self._refresh_token_cookies() for the time of the try.

Your help is much appreciated :)

catsmanac commented 1 year ago

Below the result of that test. Doesn't add any new information other then confirming the 401. The overall flow for these protected pages is that a post is done to the jwt page using the token and the cookie from that is used in subsequent get's.

2023-07-05 09:34:33.837 DEBUG (MainThread) [custom_components.enphase_gateway.enphase_token] New Enphase owner Token valid until: 2024-07-04 07:34:33+00:00
2023-07-05 09:34:33.838 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Setup Enphase gateway
2023-07-05 09:34:33.838 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] HTTP GET Attempt #1: https://192.168.3.112/production.json: Header:{'Authorization': 'Bearer <token<'}
2023-07-05 09:34:34.126 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Received status_code 401 from Gateway
2023-07-05 09:34:34.127 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Received error from Gateway: Client error '401 Unauthorized' for url 'https://192.168.3.112/production.json'
For more information check: https://httpstatuses.com/401

That also leads to a logic next step. If a 401 is ever received and the token is still valid, a new session registration to the jwt could be attempted first. Now code goes out to get new token on each 401 while post to jwt might do if time has not expired on token. Only when expiry is within next month or go go out and grab new token.

Hoffmann77 commented 1 year ago

That's a pity. Would you be willing to do one last test and add _LOGGER.debug(f"Response: {r}") to line 280 just below the GET request?

You are right. Refreshing the cookies first before getting a new token should be the default 401 resolution strategy. Will add this behavior back in.

catsmanac commented 1 year ago

Added the debug statement and got:

2023-07-05 14:33:46.006 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Setup Enphase gateway
2023-07-05 14:33:46.006 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Enpoint {}://{}/production.json
2023-07-05 14:33:46.007 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] HTTP GET Attempt #1: https://192.168.3.112/production.json: Header:{'Authorization': 'Bearer <token>'}
2023-07-05 14:33:46.237 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Response: <Response [401 Unauthorized]>
2023-07-05 14:33:46.237 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Received status_code 401 from Gateway
2023-07-05 14:33:46.237 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Received error from Gateway: Client error '401 Unauthorized' for url 'https://192.168.3.112/production.json'
For more information check: https://httpstatuses.com/401

Just to be clear, my tokens are based on a Enphase Home owner account, not an installer account. And I'm using an Envoy-S standard (not metered)

catsmanac commented 1 year ago

Did some more testing and using a get (not post) to the jwt page and saving the returned session cookie (if returned) let me access the production.json. In _update_endpoint, determine if it's the jwt page and if cookie came back store it. 

    async def _update_endpoint(self, key, url):
        """Fetch the given endpoint and update the endpoint_results dict."""
        formatted_url = url.format(self._protocol, self.host)
        response = await self._async_get(
            formatted_url, follow_redirects=False
        )
        if url == ENDPOINT_URL_CHECK_JWT:
            _LOGGER.debug("Maybe Refresh cookies")
            if response.status_code == 200 and response.cookies:
                # set the cookies for future clients
                _LOGGER.debug("Refresh cookies")
                self._cookies = response.cookies
        self.endpoint_results[key] = response

It required to change the gateway_detection_endpoints and gateway_endpoints lists for the envoy_model_s to have as first the jwt.

GATEWAY_DETECTION_ENDPOINTS = {
    "ENVOY_MODEL_S": {
        "envoy_jwt": ENDPOINT_URL_CHECK_JWT,
        "production_json": ENDPOINT_URL_PRODUCTION_JSON,
    },

and

    'ENVOY_MODEL_S_STANDARD': {
        "envoy_jwt": ENDPOINT_URL_CHECK_JWT,
        "production_json": ENDPOINT_URL_PRODUCTION_JSON,
        "production_v1": ENDPOINT_URL_PRODUCTION_V1,
        "ensemble_json": ENDPOINT_URL_ENSEMBLE_INVENTORY,
        "home_json": ENDPOINT_URL_HOME_JSON,
    },

To get all data flowing for Envoy Standard the production function needs to be changed to use the production_v1 and not the production_json data. For Standard Envoy-S production.json does not contain actual production data

        elif self.gateway_type == "ENVOY_MODEL_S_STANDARD":
#            raw_json = self.endpoint_results["production_json"].json()
#            production = raw_json["production"][0]["wNow"]
            raw_json = self.endpoint_results["production_v1"].json()
            production = raw_json["wattsNow"]

After these changes (just proof of concept, may be a better place to do this) the log reflects validation the token and storing the session cookie (see debug entries maybe refresh cookies and refresh cookies:

Setup Enphase gateway
Enpoint {}://{}/auth/check_jwt
HTTP GET Attempt #1: https://192.168.3.112/auth/check_jwt: Header:{'Authorization': 'Bearer eyJraWQiOiI3ZDEw
Response: <Response [200 OK]>
Fetched from https://192.168.3.112/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html><h2>Valid token.</h2>

Maybe Refresh cookies
Refresh cookies
Enpoint {}://{}/production.json
HTTP GET Attempt #1: https://192.168.3.112/production.json: Header:{'Authorization': 'Bearer eyJraWQiOiI3ZDE
Response: <Response [200 OK]>
Fetched from https://192.168.3.112/production.json: <Response [200 OK]>: {"production":[{"type":"inverters",
Enpoint {}://{}/auth/check_jwt
HTTP GET Attempt #1: https://192.168.3.112/auth/check_jwt: Header:{'Authorization': 'Bearer eyJraWQiOiI3ZDEw
Response: <Response [200 OK]>
Fetched from https://192.168.3.112/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html><h2>Valid token.</h2>

Maybe Refresh cookies
Enpoint {}://{}/production.json
HTTP GET Attempt #1: https://192.168.3.112/production.json: Header:{'Authorization': 'Bearer eyJraWQiOiI3ZDE
Response: <Response [200 OK]>
Fetched from https://192.168.3.112/production.json: <Response [200 OK]>: {"production":[{"type":"inverters",
Enpoint {}://{}/api/v1/production
HTTP GET Attempt #1: https://192.168.3.112/api/v1/production: Header:{'Authorization': 'Bearer eyJraWQiOiI3Z
Response: <Response [200 OK]>
Fetched from https://192.168.3.112/api/v1/production: <Response [200 OK]>: {

When my test PC went into hibernation and I woke it again couple of hours later, the above mechanism picked-up the new sessionid automatically.

2023-07-05 15:38:38.542 DEBUG (MainThread) [custom_components.enphase_gateway] Finished fetching envoy Envoy 122302045041 data in 8.132 seconds (success: True)
2023-07-05 19:51:57.049 DEBUG (MainThread) [custom_components.enphase_gateway.enphase_token] Checking Enphase token: <token>
2023-07-05 19:51:57.052 DEBUG (MainThread) [custom_components.enphase_gateway.enphase_token] Token is populated: <token>
2023-07-05 19:51:57.053 DEBUG (MainThread) [custom_components.enphase_gateway.enphase_token] Token expires at: 2024-07-04 12:57:06+00:00 UTC
2023-07-05 19:51:57.053 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Enpoint {}://{}/auth/check_jwt
2023-07-05 19:51:57.056 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] HTTP GET Attempt #1: https://192.168.3.112/auth/check_jwt: Header:{'Authorization': 'Bearer <token>'}
2023-07-05 19:51:57.731 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Response: <Response [200 OK]>
2023-07-05 19:51:57.733 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Fetched from https://192.168.3.112/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html><h2>Valid token.</h2>

2023-07-05 19:51:57.738 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Maybe Refresh cookies
2023-07-05 19:51:57.739 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] HTTP GET {}://{}/auth/check_jwt: <Response [200 OK]>: <!DOCTYPE html><h2>Valid token.</h2>

2023-07-05 19:51:57.740 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] HTTP GET Cookie: <Cookies[<Cookie sessionId=j2bQ9er0w4iWEqygNW0JoSyI85gC9Ndq for 192.168.3.112 />]>
2023-07-05 19:51:57.740 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Refresh cookies
2023-07-05 19:51:57.742 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Enpoint {}://{}/production.json
2023-07-05 19:51:57.743 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] HTTP GET Attempt #1: https://192.168.3.112/production.json: Header:{'Authorization': 'Bearer <token>'}
2023-07-05 19:51:58.197 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Response: <Response [200 OK]>
2023-07-05 19:51:58.197 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Fetched from https://192.168.3.112/production.json: <Response [200 OK]>: {"production":[{"type":"inverters","activeCount":24,"readingTime":1688579402,"wNow":553,"whLifetime":133965}],"storage":[{"type":"acb","activeCount":0,"readingTime":0,"wNow":0,"whNow":0,"state":"idle"}]}
2023-07-05 19:51:58.200 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] Enpoint {}://{}/api/v1/production
2023-07-05 19:51:58.201 DEBUG (MainThread) [custom_components.enphase_gateway.gateway_reader.gateway_reader] HTTP GET Attempt #1: https://192.168.3.112/api/v1/production: Header:{'Authorization': 'Bearer <tiken>'}

Long story for: I need this for the Envoy-S standard. And it seems different for yours

Hoffmann77 commented 1 year ago

Thanks for the update. Unfortunately it doesn't provide any new information why bare token authentication fails.

Implied that the token is valid authentication using just the token in the header should work. But in some cases it doesn't seem to work. Found a similar case on the Enphase Forum.

Using the session cookie from the jwt page seems to be the workaround for this. Will re implement the use of cookies.

catsmanac commented 1 year ago

You may want to have a look at this one as he has many of the issues solved you are looking at too