G-Two / subarulink

A python package for interacting with Subaru STARLINK remote vehicle services.
Apache License 2.0
86 stars 13 forks source link

Handle API session expiring after 24 hours #15

Closed G-Two closed 3 years ago

G-Two commented 4 years ago

I get one of these every day with 0.3.3 and 0.3.4rc0. It is handled gracefully by HA, so seems to be a minor issue. Need to determine the type of exception and find out why the message isn't passing from subarulink to the subaru integration.


2020-07-29 02:03:35 ERROR (MainThread) [homeassistant.components.subaru] Error fetching subaru_data data: Error communicating with API: 
stboch commented 4 years ago

I have it too it sees to be a delay issue in Fetch Or some unknown timeout issue (I think) service: logging.set_level data: custom_componenets.subaru: debug (I use your app as a custom_component rather than having to merge my own HA code) subarulink: debug

I will let you know what it is freaking out on in a few hours...

stboch commented 4 years ago

Forgot to check the log before some more restarts today. Earlier though I was only getting timeouts because the fetch command took longer than 30 seconds to complete. Not sure if I am gonna catch the error before tomorrow's release will see.

G-Two commented 4 years ago

I found why the exception message wasn't being logged in the HA subaru __init__.py.

    async def async_update_data():
        """Fetch data from API endpoint."""
        try:
            async with async_timeout.timeout(30):
                data = await subaru_update(vehicle_info, controller)
            return data
        except SubaruException as err:
            raise UpdateFailed(f"Error communicating with API: {err}")

I think it might be the intermittent 403 error that occasionally happens. It looks like it resolves itself upon the next call to async_update_data()? A better behavior would probably be to catch the 403 and attempt the fetch again within the subarulink controller before raising the exception to HA. Though it would be best to get to the bottom of the root cause of the 403 and prevent it from happening in the first place.

stboch commented 4 years ago

would be good to raise these all as subaruexception errors if we're gonna use that for the err value. not sure where they all hide I don't think ever failure has been excepted yet.

G-Two commented 3 years ago

If the client maintains the session cookie by polling (via fetch) every 5 minutes or so, the session cookie never expires on the HTTP side, but any API requests that get forwarded on to backend servers stop working. This looks like it occurs after exactly 24 hours. I just need to have the connection object handle this specific 403 error and reauthenticate when it occurs.

5 2020-10-13 08:39:09 DEBUG (MainThread) [subarulink.connection] POST: https://mobileapi.prod.subarucs.com/g2v15/login.json
8 2020-10-13 08:39:11 DEBUG (MainThread) [subarulink.connection] Client authentication successful
...
61999 2020-10-14 08:38:37 DEBUG (MainThread) [homeassistant.components.subaru] Finished fetching subaru_data data in 1.056 seconds
62000 2020-10-14 08:43:37 DEBUG (MainThread) [subarulink.connection] GET: https://mobileapi.prod.subarucs.com/g2v15/validateSession.json
62001 2020-10-14 08:43:37 DEBUG (MainThread) [subarulink.connection] {'data': None, 'dataName': None, 'errorCode': None, 'success': True}
62002 2020-10-14 08:43:37 DEBUG (MainThread) [subarulink.connection] POST: https://mobileapi.prod.subarucs.com/g2v15/service/g2/vehicleStatus/execute.json
62003 2020-10-14 08:43:37 DEBUG (MainThread) [subarulink.controller] {'data': {'errorDescription': None,
62004           'errorLabel': '403-soa-unableToParseResponseBody'},
62005  'dataName': 'errorResponse',
62006  'errorCode': '403-soa-unableToParseResponseBody',
62007  'success': False}
62008 2020-10-14 08:43:37 ERROR (MainThread) [homeassistant.components.subaru] Error fetching subaru_data data:
62009 2020-10-14 08:43:37 DEBUG (MainThread) [homeassistant.components.subaru] Finished fetching subaru_data data in 0.513 seconds

There are probably other causes for the 403 error, but this one has been consistently bothering me in Home Assistant over the past month.

EDIT: It looks like the HTTP status code is normal, so handling this is up to controller. I'll expose a new connection.reset_session() function that can be used for controller to clear cookies when it encounters situations like this.