search

itchannel / fordpass-ha

Fordpass integration for Home Assistant
311 stars 56 forks source link

401 client error every so many minutes in logging #64

Closed degrashopper closed 3 years ago

degrashopper commented 3 years ago

Every so many minutes i get the following 3 error messages in the logging:

clearing the tokens dit not help.

Running version 1.12 and ha 2020.12.0

explosivo22 commented 3 years ago

I am getting the same thing since upgrading home assistant. I am running 1.12 and 2020.12.1. I didn't notice this until after an install of the 2020 version of home assistant.

itchannel commented 3 years ago

So I don't appear to be having the same issue on mine running the latest home assistant update.

Is this causing any of the fordpass entities to become unavaliable or is it just showing up in the log?

explosivo22 commented 3 years ago

Mine were all showing offline or unavailable. I tried clearing out fordpass and starting from scratch and now I have no entities.

explosivo22 commented 3 years ago

I am also getting the following in my log

Logger: homeassistant.config_entries
Source: config_entries.py:247
First occurred: 9:07:25 PM (31 occurrences)
Last logged: 9:22:03 PM

Config entry for fordpass not ready yet. Retrying in 10 seconds
Config entry for nest not ready yet. Retrying in 80 seconds
Config entry for fordpass not ready yet. Retrying in 20 seconds
Config entry for fordpass not ready yet. Retrying in 40 seconds
Config entry for fordpass not ready yet. Retrying in 80 seconds
degrashopper commented 3 years ago

After the error in de log all related entities go 'unavailable' for exactly 5 minutes. You can also see that in the history of the entities.

I am using the europe region setting.

itchannel commented 3 years ago

Does your HA install have enough system resources as you both say this happened with the latest version update to HA? I've seen config errors before in HA and it's usually caused by underpowered VM/Server.

The underlying code for the fordpass integration has only changed some minor functions so wouldn't be the cause of the errors you are now experiencing.

explosivo22 commented 3 years ago

SmartSelect_20201219-200051_Home Assistant This is what mine looks like right now

itchannel commented 3 years ago

Out of interest what HA install type are you using

Just trying to narrow down what might be causing it for some people.

explosivo22 commented 3 years ago

SmartSelect_20201219-201230_Home Assistant Should be hass.io on raspberry pi3.

itchannel commented 3 years ago

Your issue might be similar to #65 it seems the latest version of HA causes DNS resoloution issues. Or at least from my testing. Can you try changing your DNS server in /etc/resolv.conf to something like 1.1.1.1 or 8.8.8.8 and seeing if the problems go away.

explosivo22 commented 3 years ago

I am actually sending my whole network to 1.1.1.1 with 8.8.8.8 secondary. I will try changing it directly on the box though.

degrashopper commented 3 years ago

I am running hassio supervised on a ubuntu machine with more then enough resources left. I think it has something to do with a token that expires after 3600 seconds. between the last 2 unavailable sessions it was exactly an hour.

itchannel commented 3 years ago

@degrashopper Try manually deleted fordpass_token.txt in /tmp. Also what region are you in as the token expiring after an hour could potentially be you having the wrong application ID. As I can only collected what people give me so we may need to collect a different app id for you.

degrashopper commented 3 years ago

In the hassio tmp folder the fordpass_token.txt is not present. Or do you mean a different /tmp folder. Where is the /tmp folder located? I am in the europe region. Where can i see the application id i use?

degrashopper commented 3 years ago

I think I figured it out.

I checked the code and it tries to execute os.path.isfile("/tmp/fordpass_token.txt"). On a supervised system i don't think the application has the rights to do so. The file needs to stay within the persistent data file path so that the homeassistant container can reach it.

Now the integration can't read the file and tries to communicate with the api, and sends an empty value as token. It takes 300 seconds before a new attempt is executed. In the meantime all entities are unavailable.

degrashopper commented 3 years ago

Changing the /tmp/ path only made the file visible but did not fix the problem with the 401 error.

horfic commented 3 years ago

Hi, i also get during the https://usapi.cv.ford.com/api/vehicles/v4/VIN/status?lrdt=01-01-1970+00%3A00%3A00 call for region EU&UK a status 401 with $id = 1.

never got it working for my VIN, vin is correct as i can read vehicle capabilities and also vehicle details per rest.

does somebody got an idea?

itchannel commented 3 years ago

I think the issue you guys are having is the region is different to the 3 I have so far. The only way to troubleshoot that would be to get you to proxy traffic between your local fordpass mobile app and the ford API. That way I can update the application ID for you.

A quick test is to open the fordapp and refresh the data, then try the fordpass integration and see if it works for an hour.

degrashopper commented 3 years ago

I use an android 10 device and catching https traffic with an added certifcate wont work. After android 7 the system ignores added certificates, so the requests stay unreadable.

The problem here is not the applicationID. The requests work but during the token renewal it goes wrong for some reason. Resulting in the application is unavailable for 300 seconds.

I have checked some request with postmen. The url's for requesting the first and second token works. The refresh url https://api.mps.ford.com/api/oauth2/v1/refresh did not work for me.

edit: the refresh url does work. used the wrong method.

horfic commented 3 years ago

the following works for me

Did the eur & uk client id ever work on the usapi.cv.ford.com server? I did find a new project from a ford employee https://github.com/kewashi/hpserver/ but that is using the new forconnect api https://developer.ford.com/fordconnect

I guess that the tokens we are getting are having the wrong scope

itchannel commented 3 years ago

the following works for me

* GET https://sso.ci.ford.com/oidc/endpoint/default/token

* PUT https://api.mps.ford.com/api/oauth2/v1/token

* PUT https://api.mps.ford.com/api/oauth2/v1/refresh

* GET https://api.mps.ford.com/api/users/vehicles

* GET [https://api.mps.ford.com/api/users/vehicles/{vin}/detail/](https://api.mps.ford.com/api/users/vehicles/%7Bvin%7D/detail/)

* GET [https://api.mps.ford.com/api/capability/v1/vehicles/{vin}](https://api.mps.ford.com/api/capability/v1/vehicles/%7Bvin%7D)

* GET [https://usapi.cv.ford.com/api/vehicles/v2/{vin}/status](https://usapi.cv.ford.com/api/vehicles/v2/%7Bvin%7D/status) - results in a httpstatus 200 and app status 401

* GET [https://usapi.cv.ford.com/api/vehicles/v3/{vin}/status](https://usapi.cv.ford.com/api/vehicles/v3/%7Bvin%7D/status) - results in a httpstatus 200 and app status 401

* GET [https://usapi.cv.ford.com/api/vehicles/v4/{vin}/status](https://usapi.cv.ford.com/api/vehicles/v4/%7Bvin%7D/status) - results in a httpstatus 200 and app status 401

* GET [https://api.mps.ford.com/api/vehicles/v2/{vin}/status](https://api.mps.ford.com/api/vehicles/v2/%7Bvin%7D/status) - results in a httpstatus  404

* GET [https://api.mps.ford.com/api/vehicles/v3/{vin}/status](https://api.mps.ford.com/api/vehicles/v3/%7Bvin%7D/status) - results in a httpstatus 404

* GET [https://api.mps.ford.com/api/vehicles/v4/{vin}/status](https://api.mps.ford.com/api/vehicles/v4/%7Bvin%7D/status) - results in a httpstatus 404

* GET https://api.mps.ford.com/api/fordconnect/vehicles/v1- results in a httpstatus 401

Did the eur & uk client id ever work on the usapi.cv.ford.com server? I did find a new project from a ford employee https://github.com/kewashi/hpserver/ but that is using the new forconnect api https://developer.ford.com/fordconnect

I guess that the tokens we are getting are having the wrong scope

What country are you using the application in?

That error is usually application/client ID related the "Uk/Europe" one is an application ID provided by a user on here and may not be applicable to all European countries (However it does work for quite a lot of users). I only have the Australian version of the application to work from. The best way is to use a proxy like "Burp" to intercept the calls between the mobile application and the ford server and look at the application ID being used by your ford pass application. That way we can narrow down the issue as troubleshooting issues that rely on certain geo location apps is a pain to do without local access.

Did you try loading up the phone app to view your vehicle details and then trying the fordpass integration?

itchannel commented 3 years ago

I use an android 10 device and catching https traffic with an added certifcate wont work. After android 7 the system ignores added certificates, so the requests stay unreadable.

The problem here is not the applicationID. The requests work but during the token renewal it goes wrong for some reason. Resulting in the application is unavailable for 300 seconds.

I have checked some request with postmen. The url's for requesting the first and second token works. The refresh url https://api.mps.ford.com/api/oauth2/v1/refresh did not work for me.

edit: the refresh url does work. used the wrong method.

The application ID is normally the cause of the 300second issue, does reopening the fordpass application on your phone and refreshing bring the entities in HA back online again? As this issue seems very similar to #26

What country/appstore are you getting the application for I have a Android 10 device running Magisk and custom CA certs so can intercept if I can get hold of your version of the Android app.

itchannel commented 3 years ago

I've spent the morning dissasembling both android and IOS versions of the application and can confirm that the EU application ID is correct as well as the Australia/New Zealand one.

I don't quite understand why you are getting the error, have either of you tried the debug script so we have a full log of the traffic Debug Running that creates a log file of all calls to/from the server will give more verbose output.

horfic commented 3 years ago

Hi, 08:28:24,342 urllib3.connectionpool DEBUG Starting new HTTPS connection (1): usapi.cv.ford.com:443 08:28:25,303 urllib3.connectionpool DEBUG https://usapi.cv.ford.com:443 "GET /api/vehicles/v4/{REDACTED}/status?lrdt=01-01-1970+00%3A00%3A00 HTTP/1.1" 200 42 08:28:25,304 root DEBUG Vehicle Status 08:28:25,304 root DEBUG {'User-Agent': 'fordpass-ap/93 CFNetwork/1197 Darwin/20.0.0', 'Accept-Encoding': 'gzip, deflate, br', 'Accept': '*/*', 'Connection': 'keep-alive', 'Accept-Language': 'en-us', 'Application-Id': '5C80A6BB-CF0D-4A30-BDBF-FC804B5C1A98', 'Content-Type': 'application/json', 'auth-token': '{REDACTED}'} 08:28:25,304 root DEBUG None 08:28:25,304 root DEBUG 200 08:28:25,304 root DEBUG {"$id":"1","status":402,"version":"1.0.0"} 08:36:22,369 root DEBUG None 08:36:23,674 urllib3.connectionpool DEBUG Starting new HTTPS connection (1): usapi.cv.ford.com:443 08:36:24,671 urllib3.connectionpool DEBUG https://usapi.cv.ford.com:443 "GET /api/vehicles/v4/{REDACTED}/status?lrdt=01-01-1970+00%3A00%3A00 HTTP/1.1" 200 42 08:36:24,672 root DEBUG Vehicle Status 08:36:24,672 root DEBUG {'User-Agent': 'fordpass-ap/93 CFNetwork/1197 Darwin/20.0.0', 'Accept-Encoding': 'gzip, deflate, br', 'Accept': '*/*', 'Connection': 'keep-alive', 'Accept-Language': 'en-us', 'Application-Id': '1E8C7794-FF5F-49BC-9596-A1E0C86C5B19', 'Content-Type': 'application/json', 'auth-token': '{REDACTED}'} 08:36:24,672 root DEBUG None 08:36:24,672 root DEBUG 200 08:36:24,672 root DEBUG {"$id":"1","status":401,"version":"1.0.0"}

I have removed my VIN and the access token from the log, but as you can see i get the http status 200 with app status 401 for the "EU & UK" application id. For the US application id, i get http status 200 and app status 402.

token, token 2, refresh is all working, i can also get the list of vehicles, so the auth part is working

The android app used is this one https://play.google.com/store/apps/details?id=com.ford.fordpasseu and i'm based from austria.

degrashopper commented 3 years ago

I think i have the solution. The code is not handling 401 responses at the moment. And it should be able to.

Status defenition: When you call the vehicle status interface with an invalid token you will get a 401 response. To get past that you have to call the refresh defenition to get a valid token.

Refresh_token defenition: It can also happen that the refresh interface responses with a 401 response. In that case you have to go back to the auth defenition to start over.

the only thing is that im not a programmer and haven't figured out yet wat code i need to add to get this working.

horfic commented 3 years ago

that is not the solution for me, i get a 401 http status if the token is invalid. but i'm always testing with a brand new auth.

i get a status 200 but with json body

{ "$id": "1", "status": 401, "version": "1.0.0" }

degrashopper commented 3 years ago

@horfic do you use an automation to trigger the fordpass.refresh_status service? If so how many times a day is that service triggered? It could be that they block new requests when you trigger the status interface to much.

degrashopper commented 3 years ago

At the moment I added some code to the functions refresh_token and status in fordpass_new. So far I haven't had 401 errors anymore at http level. hopefully they stay away.

   def refreshToken(self, token):
       # Token is invalid so let's try refreshing it
       data = {"refresh_token": token["refresh_token"]}
       headers = {**apiHeaders, "Application-Id": self.region}

       r = requests.put(
           "https://api.mps.ford.com/api/oauth2/v1/refresh",
           data=json.dumps(data),
           headers=headers,
       )
       if r.status_code == 200:
           result = r.json()
           if self.saveToken:
               result["expiry_date"] = time.time() + result["expires_in"]
               self.writeToken(result)
           self.token = result["access_token"]
           self.refresh_token = result["refresh_token"]
           self.expiresAt = time.time() + result["expires_in"]
       if r.status_code == 401:
           self.auth()

   def status(self):
       # Get the status of the vehicle

       self.__acquireToken()

       params = {"lrdt": "01-01-1970 00:00:00"}

       headers = {
           **apiHeaders,
           "auth-token": self.token,
           "Application-Id": self.region,
       }

       r = requests.get(
           f"{baseUrl}/vehicles/v4/{self.vin}/status", params=params, headers=headers
       )
       if r.status_code == 200:
           result = r.json()
           if result["status"] == 402:
               r.raise_for_status()
           return result["vehiclestatus"]
       if r.status_code == 401:
           self.refreshToken(token)
           r = requests.get(
           f"{baseUrl}/vehicles/v4/{self.vin}/status", params=params, headers=headers
           )
           if r.status_code == 200:
               result = r.json()
           return result["vehiclestatus"]
       else:
           r.raise_for_status()
horfic commented 3 years ago

hi, the application itself is currently disabled, as its not working.

i only enabled it for the testing the requests 1) Works - https://sso.ci.ford.com/oidc/endpoint/default/token 2) Works - https://api.mps.ford.com/api/oauth2/v1/token 3) Works - https://api.mps.ford.com/api/oauth2/v1/refresh 4) NOPE - https://usapi.cv.ford.com/api/vehicles/v4/{vin}/status

itchannel commented 3 years ago

Id

Let me know how you get on, I've added the code changes to my dev copy to test. The only change I made was to change "token" to "self.token" otherwise it will result in an exception. If it works for a day I'll push it out in the next release.

degrashopper commented 3 years ago

After some tweaking the following code works for me. If i get a 401 response when calling the vehicle status interface. the token is refreshed.

To get this working from the original script I had to do the following things:

@itchannel please also change in the fordpass_new.py file all the current logging lines from logging.info("") to _LOGGER.debug("")

And add the following line to the file (between line 6 and 8) _LOGGER = logging.getLogger(__name__)

Now the lines will show up in homeassistant when you set the logger to debug.

Working status function:

   def status(self):
       # Get the status of the vehicle

       self.__acquireToken()

       params = {"lrdt": "01-01-1970 00:00:00"}

       headers = {
           **apiHeaders,
           "auth-token": self.token,
           "Application-Id": self.region,
       }

       r = requests.get(
           f"{baseUrl}/vehicles/v4/{self.vin}/status", params=params, headers=headers
       )
       if r.status_code == 200:
           result = r.json()
           if result["status"] == 402:
               r.raise_for_status()
           if result["status"] == 401:
               r.raise_for_status()
           return result["vehiclestatus"]
       if r.status_code == 401:
           _LOGGER.debug("401 with status request: start token refresh")
           data = dict()
           data["access_token"] = self.token
           data["refresh_token"] = self.refresh_token
           data["expiry_date"] = self.expiresAt
           self.refreshToken(data)
           _LOGGER.debug("401 with status request: refresh token success")
           self.__acquireToken()
           params = {"lrdt": "01-01-1970 00:00:00"}

           headers = {
               **apiHeaders,
               "auth-token": self.token,
               "Application-Id": self.region,
           }
           r = requests.get(
           f"{baseUrl}/vehicles/v4/{self.vin}/status", params=params, headers=headers
           )
           if r.status_code == 200:
               result = r.json()
               _LOGGER.debug("401 with status request: second attempt status request successful")
           return result["vehiclestatus"]
       else:
           r.raise_for_status()
           _LOGGER.debug(r.raise_for_status())

   def refreshToken(self, token):
       # Token is invalid so let's try refreshing it
       data = {"refresh_token": token["refresh_token"]}
       headers = {**apiHeaders, "Application-Id": self.region}

       r = requests.put(
           "https://api.mps.ford.com/api/oauth2/v1/refresh",
           data=json.dumps(data),
           headers=headers,
       )
       if r.status_code == 200:
           result = r.json()
           if self.saveToken:
               result["expiry_date"] = time.time() + result["expires_in"]
               self.writeToken(result)
           self.token = result["access_token"]
           self.refresh_token = result["refresh_token"]
           self.expiresAt = time.time() + result["expires_in"]
           _LOGGER.debug("Stage 2 token refresh successful")
       if r.status_code == 401:
           _LOGGER.debug("401 response stage 2: refresh stage 1 token")
           self.auth()
       else:
           r.raise_for_status()
           _LOGGER.debug(r.raise_for_status())
itchannel commented 3 years ago

@degrashopper cheers will add the code to mine and test the next day or so. But looks good so cheers 👍

itchannel commented 3 years ago

@degrashopper if you have 10minutes would you mind trying the new branch. I've implemented some of your changes and changed a few bits as some of your code was duplicating bits. If you need to change the token location you can edit the variable self.token_location in the py file however by default it now puts it with the integration files.

Development Branch

degrashopper commented 3 years ago

@itchannel i have added your code. After about 2 hours i got the error.

string indices must be integers

adding "self.token" will not work. I also tried this and then you get the above error.

Self.refreshToken(self.token)

Thats why i added data as a dict (like in the function "__acquireToken")

degrashopper commented 3 years ago

Also only changing Self.refreshToken(self.token) to Self.refreshToken(data) is not enough

itchannel commented 3 years ago

Ok cheers for testing.

itchannel commented 3 years ago

@degrashopper I was having a funny 5 yesterday and forgot the _acquiretoken required a dictionary. I've added in those extra lines in the dev branch so it should work for you now if you have 5 to check.

It's a pain as I can't trigger a 401 on mine to check :)

degrashopper commented 3 years ago

@itchannel I double checked it by running your code but t is not enough. After calling the refresh_token function you have to update the "self.token" value by calling the"acquireToken" function. After updating the self.token value you have to update the "headers" dict. After that you can execute the interface call.

So either you add the code below in the 401 handling part, or you need to re trigger the status function itself somehow so it can follow the 200 handling part of the code.

   if r.status_code == 401:
       data = dict()
       data["access_token"] = self.token
       data["refresh_token"] = self.refresh_token
       data["expiry_date"] = self.expiresAt
       self.refreshToken(data)
       _LOGGER.debug("401 with status request: refresh token success")
       self.__acquireToken()
       params = {"lrdt": "01-01-1970 00:00:00"}

       headers = {
           **apiHeaders,
           "auth-token": self.token,
           "Application-Id": self.region,
       }
       r = requests.get(
           f"{baseUrl}/vehicles/v4/{self.vin}/status",
           params=params,
           headers=headers,
       )
       if r.status_code == 200:
           result = r.json()
       return result["vehiclestatus"]
       r.raise_for_status()
   else:
       r.raise_for_status()

For me it is still strange that you never get a 401 response. When you call the vehicle status interface with an invalid token you will always get a 401 response. I think you can test it yourself if you increase the calculated expiry_date in the fordpass_token file by 400 seconds. With the 400 extra seconds the system will at least call the vehicle status interface once with an invalid token.

itchannel commented 3 years ago

@degrashopper out of interest have you tried it without the self.__acquireToken() as the refreshToken function should update the values of self.token. Trying to avoid running the token refresh twice.

This should be updating the value in refreshToken

            self.token = result["access_token"]
            self.refresh_token = result["refresh_token"]
            self.expiresAt = time.time() + result["expires_in"]

Either way I've added in both functions for now and it seems to be working well on mine. Can you check the latest update but it should work now

degrashopper commented 3 years ago

I commented the self.__acquireToken() line out in the above mentioned code. I will let you know if it works or not.

itchannel commented 3 years ago

I commented the self.__acquireToken() line out in the above mentioned code. I will let you know if it works or not.

Thanks.

itchannel commented 3 years ago

@degrashopper any luck?

itchannel commented 3 years ago

I've pushed the new version to release. I've left in the double check as it won't make a second call but may remove down the line if you confirm it still works 👍

degrashopper commented 3 years ago

The code is now almost running for 24h and haven't had an error yet, so it works