Optimize handling of occasional 401s

[oliverrahner]

Currently, the reaction to any 401 error received from the API leads an invalidation of the current session, which in turns leads to a login.

In my own tests, I have seen 401s occasionally appear and disappear again, without re-login or even refreshing tokens.

Question: should we remove that session invalidation completely?

[oliverrahner]

@stickpin this came to my mind because of #223

[stickpin]

It might be dangerous to cut the session invalidation completely.
If VW invalidates the token for whatever reason, we need to trigger the login flow somehow.
We neither use boolean or trigger re-login directly.

[stickpin]

@oliverrahner coming back to the token refresh topic.

There is a strange behavior of the VW servers with the token refresh.
Let me explain what's going on.

Every hour we have to refresh the token and now it's done using the refresh token function.
The problem is that VW servers will accept the token only once and then they will reject it.

Here is an example...
Refresh token request:

2023-12-09 20:15:21.944 DEBUG (MainThread) [volkswagencarnet.vw_connection] Tokens about to expire. Try to fetch new tokens.
2023-12-09 20:15:22.376 DEBUG (MainThread) [volkswagencarnet.vw_connection] Successfully refreshed tokens
2023-12-09 20:15:22.376 DEBUG (MainThread) [volkswagencarnet.vw_connection] Going to call vehicle updates
2023-12-09 20:15:22.377 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/selectivestatus?jobs=access,fuelStatus,vehicleLights,vehicleHealthInspection,measurements,charging,climatisation,automation"
2023-12-09 20:15:22.379 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v2/vehicles"
2023-12-09 20:15:22.379 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/parkingposition"
2023-12-09 20:15:22.380 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v1/trips/WVXXX/shortterm/last"
2023-12-09 20:15:23.022 DEBUG (MainThread) [volkswagencarnet.vw_connection] Request for "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/parkingposition" returned with status code [200], response: {'data': {'lon': 0.0, 'lat': 0.0, 'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 32, tzinfo=datetime.timezone.utc)}}
2023-12-09 20:15:23.096 DEBUG (MainThread) [volkswagencarnet.vw_connection] Request for "https://emea.bff.cariad.digital/vehicle/v1/trips/WVXXX/shortterm/last" returned with status code [200], response: {'data': {'id': '2142457450', 'tripEndTimestamp': datetime.datetime(2023, 12, 9, 17, 0, 24, tzinfo=datetime.timezone.utc), 'tripType': 'shortTerm', 'vehicleType': 'fuel', 'mileage_km': 4, 'startMileage_km': 33926, 'overallMileage_km': 33931, 'travelTime': 22, 'averageFuelConsumption': 15.5, 'averageSpeed_kmph': 13}}
2023-12-09 20:15:23.229 DEBUG (MainThread) [volkswagencarnet.vw_connection] Request for "https://emea.bff.cariad.digital/vehicle/v2/vehicles" returned with status code [200], response: {'data': [{'vin': 'WVXXX', 'userRole': 'PRIMARY_USER', 'userRoleStatus': 'ENABLED', 'enrollmentStatus': 'COMPLETED', 'brandCode': 'V', 'model': 'Touran', 'nickname': 'VW Touran', 'devicePlatform': 'MBB_ODP', 'fleetVehicle': False}]}
2023-12-09 20:15:23.372 DEBUG (MainThread) [volkswagencarnet.vw_connection] Request for "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/selectivestatus?jobs=access,fuelStatus,vehicleLights,vehicleHealthInspection,measurements,charging,climatisation,automation" returned with status code [207], response: {'access': {'accessStatus': {'value': {'overallStatus': 'safe', 'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'doors': [{'name': 'bonnet', 'status': ['closed']}, {'name': 'frontLeft', 'status': ['locked', 'closed']}, {'name': 'frontRight', 'status': ['locked', 'closed']}, {'name': 'rearLeft', 'status': ['locked', 'closed']}, {'name': 'rearRight', 'status': ['locked', 'closed']}, {'name': 'trunk', 'status': ['locked', 'closed']}], 'windows': [{'name': 'frontLeft', 'status': ['closed']}, {'name': 'frontRight', 'status': ['closed']}, {'name': 'rearLeft', 'status': ['closed']}, {'name': 'rearRight', 'status': ['closed']}, {'name': 'roofCover', 'status': ['unsupported']}, {'name': 'sunRoof', 'status': ['closed']}], 'doorLockStatus': 'locked'}}}, 'fuelStatus': {'rangeStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'carType': 'gasoline', 'primaryEngine': {'type': 'gasoline', 'currentSOC_pct': 73, 'remainingRange_km': 490, 'currentFuelLevel_pct': 73}, 'totalRange_km': 490}}}, 'vehicleLights': {'lightsStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'lights': [{'name': 'right', 'status': 'off'}, {'name': 'left', 'status': 'off'}]}}}, 'vehicleHealthInspection': {'maintenanceStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 32, tzinfo=datetime.timezone.utc), 'inspectionDue_days': 391, 'inspectionDue_km': 17200, 'mileage_km': 33931, 'oilServiceDue_days': 365, 'oilServiceDue_km': 16100}}}, 'measurements': {'rangeStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'gasolineRange': 490, 'totalRange_km': 490}}, 'odometerStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'odometer': 33931}}, 'fuelLevelStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'currentFuelLevel_pct': 73, 'primaryEngineType': 'gasoline', 'carType': 'gasoline'}}}}
2023-12-09 20:15:23.372 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service charging. (This is expected for several service/car combinations)
2023-12-09 20:15:23.372 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service climatisation. (This is expected for several service/car combinations)
2023-12-09 20:15:23.372 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service automation. (This is expected for several service/car combinations)
2023-12-09 20:15:23.372 DEBUG (MainThread) [volkswagencarnet.vw_connection] Getting API status updates

First request after token refresh with the new token:

2023-12-09 20:20:22.944 DEBUG (MainThread) [volkswagencarnet.vw_connection] Going to call vehicle updates
2023-12-09 20:20:22.946 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/selectivestatus?jobs=access,fuelStatus,vehicleLights,vehicleHealthInspection,measurements,charging,climatisation,automation"
2023-12-09 20:20:22.947 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v2/vehicles"
2023-12-09 20:20:22.947 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/parkingposition"
2023-12-09 20:20:22.948 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v1/trips/WVXXX/shortterm/last"
2023-12-09 20:20:23.517 DEBUG (MainThread) [volkswagencarnet.vw_connection] Request for "https://emea.bff.cariad.digital/vehicle/v1/trips/WVXXX/shortterm/last" returned with status code [200], response: {'data': {'id': '2142457450', 'tripEndTimestamp': datetime.datetime(2023, 12, 9, 17, 0, 24, tzinfo=datetime.timezone.utc), 'tripType': 'shortTerm', 'vehicleType': 'fuel', 'mileage_km': 4, 'startMileage_km': 33926, 'overallMileage_km': 33931, 'travelTime': 22, 'averageFuelConsumption': 15.5, 'averageSpeed_kmph': 13}}
2023-12-09 20:20:23.660 DEBUG (MainThread) [volkswagencarnet.vw_connection] Request for "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/parkingposition" returned with status code [200], response: {'data': {'lon': 0.0, 'lat': 0.0, 'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 32, tzinfo=datetime.timezone.utc)}}
2023-12-09 20:20:23.704 DEBUG (MainThread) [volkswagencarnet.vw_connection] Request for "https://emea.bff.cariad.digital/vehicle/v2/vehicles" returned with status code [200], response: {'data': [{'vin': 'WVXXX', 'userRole': 'PRIMARY_USER', 'userRoleStatus': 'ENABLED', 'enrollmentStatus': 'COMPLETED', 'brandCode': 'V', 'model': 'Touran', 'nickname': 'VW Touran', 'devicePlatform': 'MBB_ODP', 'fleetVehicle': False}]}
2023-12-09 20:20:23.905 DEBUG (MainThread) [volkswagencarnet.vw_connection] Request for "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/selectivestatus?jobs=access,fuelStatus,vehicleLights,vehicleHealthInspection,measurements,charging,climatisation,automation" returned with status code [207], response: {'access': {'accessStatus': {'value': {'overallStatus': 'safe', 'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'doors': [{'name': 'bonnet', 'status': ['closed']}, {'name': 'frontLeft', 'status': ['locked', 'closed']}, {'name': 'frontRight', 'status': ['locked', 'closed']}, {'name': 'rearLeft', 'status': ['locked', 'closed']}, {'name': 'rearRight', 'status': ['locked', 'closed']}, {'name': 'trunk', 'status': ['locked', 'closed']}], 'windows': [{'name': 'frontLeft', 'status': ['closed']}, {'name': 'frontRight', 'status': ['closed']}, {'name': 'rearLeft', 'status': ['closed']}, {'name': 'rearRight', 'status': ['closed']}, {'name': 'roofCover', 'status': ['unsupported']}, {'name': 'sunRoof', 'status': ['closed']}], 'doorLockStatus': 'locked'}}}, 'fuelStatus': {'rangeStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'carType': 'gasoline', 'primaryEngine': {'type': 'gasoline', 'currentSOC_pct': 73, 'remainingRange_km': 490, 'currentFuelLevel_pct': 73}, 'totalRange_km': 490}}}, 'vehicleLights': {'lightsStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'lights': [{'name': 'right', 'status': 'off'}, {'name': 'left', 'status': 'off'}]}}}, 'vehicleHealthInspection': {'maintenanceStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 32, tzinfo=datetime.timezone.utc), 'inspectionDue_days': 391, 'inspectionDue_km': 17200, 'mileage_km': 33931, 'oilServiceDue_days': 365, 'oilServiceDue_km': 16100}}}, 'measurements': {'rangeStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'gasolineRange': 490, 'totalRange_km': 490}}, 'odometerStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'odometer': 33931}}, 'fuelLevelStatus': {'value': {'carCapturedTimestamp': datetime.datetime(2023, 12, 9, 17, 1, 34, tzinfo=datetime.timezone.utc), 'currentFuelLevel_pct': 73, 'primaryEngineType': 'gasoline', 'carType': 'gasoline'}}}}
2023-12-09 20:20:23.905 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service charging. (This is expected for several service/car combinations)
2023-12-09 20:20:23.905 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service climatisation. (This is expected for several service/car combinations)
2023-12-09 20:20:23.905 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service automation. (This is expected for several service/car combinations)
2023-12-09 20:20:23.905 DEBUG (MainThread) [volkswagencarnet.vw_connection] Getting API status updates

A second request with the new token (unauthorized):

2023-12-09 20:25:23.943 DEBUG (MainThread) [volkswagencarnet.vw_connection] Going to call vehicle updates
2023-12-09 20:25:23.944 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/selectivestatus?jobs=access,fuelStatus,vehicleLights,vehicleHealthInspection,measurements,charging,climatisation,automation"
2023-12-09 20:25:23.945 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v2/vehicles"
2023-12-09 20:25:23.945 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/parkingposition"
2023-12-09 20:25:23.946 DEBUG (MainThread) [volkswagencarnet.vw_connection] HTTP GET "https://emea.bff.cariad.digital/vehicle/v1/trips/WVXXX/shortterm/last"
2023-12-09 20:25:24.048 WARNING (MainThread) [volkswagencarnet.vw_connection] Received "unauthorized" error while fetching data: 401, message='Unauthorized', url=URL('https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/parkingposition')
2023-12-09 20:25:24.048 WARNING (MainThread) [volkswagencarnet.vw_connection] Could not fetch parkingposition, HTTP status code: 401
2023-12-09 20:25:24.052 WARNING (MainThread) [volkswagencarnet.vw_connection] Received "unauthorized" error while fetching data: 401, message='Unauthorized', url=URL('https://emea.bff.cariad.digital/vehicle/v1/vehicles/WVXXX/selectivestatus?jobs=access,fuelStatus,vehicleLights,vehicleHealthInspection,measurements,charging,climatisation,automation')
2023-12-09 20:25:24.052 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service access. (This is expected for several service/car combinations)
2023-12-09 20:25:24.052 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service fuelStatus. (This is expected for several service/car combinations)
2023-12-09 20:25:24.052 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service vehicleLights. (This is expected for several service/car combinations)
2023-12-09 20:25:24.052 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service vehicleHealthInspection. (This is expected for several service/car combinations)
2023-12-09 20:25:24.052 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service measurements. (This is expected for several service/car combinations)
2023-12-09 20:25:24.052 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service charging. (This is expected for several service/car combinations)
2023-12-09 20:25:24.052 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service climatisation. (This is expected for several service/car combinations)
2023-12-09 20:25:24.052 DEBUG (MainThread) [volkswagencarnet.vw_connection] Did not receive return data for requested service automation. (This is expected for several service/car combinations)
2023-12-09 20:25:24.061 WARNING (MainThread) [volkswagencarnet.vw_connection] Received "unauthorized" error while fetching data: 401, message='Unauthorized', url=URL('https://emea.bff.cariad.digital/vehicle/v2/vehicles')
2023-12-09 20:25:24.061 WARNING (MainThread) [volkswagencarnet.vw_connection] Could not fetch vehicle data, error: 'NoneType' object is not iterable
2023-12-09 20:25:24.066 WARNING (MainThread) [volkswagencarnet.vw_connection] Received "unauthorized" error while fetching data: 401, message='Unauthorized', url=URL('https://emea.bff.cariad.digital/vehicle/v1/trips/WVXXX/shortterm/last')
2023-12-09 20:25:24.066 WARNING (MainThread) [volkswagencarnet.vw_connection] Could not fetch last trip data, server response: {'status_code': 401}
2023-12-09 20:25:24.066 DEBUG (MainThread) [volkswagencarnet.vw_connection] Getting API status updates

And as the result, full relogin:

2023-12-09 20:30:23.944 DEBUG (MainThread) [volkswagencarnet.vw_connection] Requesting openid config
2023-12-09 20:30:24.046 DEBUG (MainThread) [volkswagencarnet.vw_connection] Get authorization page from "https://identity.vwgroup.io/oidc/v1/authorize"
2023-12-09 20:30:24.046 DEBUG (MainThread) [volkswagencarnet.vw_connection] Request headers: "{'Connection': 'keep-alive', 'Accept': 'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9', 'Accept-Encoding': 'gzip, deflate', 'Content-Type': 'application/x-www-form-urlencoded'}"
2023-12-09 20:30:24.149 DEBUG (MainThread) [volkswagencarnet.vw_connection] Got redirect to "https://identity.vwgroup.io/signin-service/v1/signin/a24fba63-34b3-4d43-b181-942111e6bda8@apps_vw-dilab_com?relayState=removed"
2023-12-09 20:30:24.247 DEBUG (MainThread) [volkswagencarnet.vw_connection] Got authorization endpoint
2023-12-09 20:30:24.428 DEBUG (MainThread) [volkswagencarnet.vw_connection] Authenticating with email and password.
2023-12-09 20:30:24.429 DEBUG (MainThread) [volkswagencarnet.vw_connection] Using login action url: "https://identity.vwgroup.io/signin-service/v1/a24fba63-34b3-4d43-b181-942111e6bda8@apps_vw-dilab_com/login/authenticate"
2023-12-09 20:30:24.670 DEBUG (MainThread) [volkswagencarnet.vw_connection] Parsing login response.
2023-12-09 20:30:24.670 DEBUG (MainThread) [volkswagencarnet.vw_connection] Following redirect to "https://identity.vwgroup.io/oidc/v1/oauth/sso?clientId=a24fba63-34b3-4d43-b181-942111e6bda8@apps_vw-dilab_com&relayState=removed&userId=removed&HMAC=3removed"
2023-12-09 20:30:24.750 DEBUG (MainThread) [volkswagencarnet.vw_connection] Following redirect to "https://identity.vwgroup.io/signin-service/v1/consent/users/removed/a24fba63-34b3-4d43-b181-942111e6bda8@apps_vw-dilab_com?scopes=openid%20profile%20badge%20cars%20dealers%20vin&relayState=removed&callback=https://identity.vwgroup.io/oidc/v1/oauth/client/callback&hmac=6f87871731514d82ec9be22ea5234ef31b405201046a8578daf383d56b03326a"
2023-12-09 20:30:24.839 DEBUG (MainThread) [volkswagencarnet.vw_connection] Following redirect to "https://identity.vwgroup.io/oidc/v1/oauth/client/callback/success?user_id=removed&client_id=a24fba63-34b3-4d43-b181-942111e6bda8@apps_vw-dilab_com&scopes=openid%20profile%20badge%20cars%20dealers%20vin&consentedScopes=openid%20profile%20badge%20cars%20dealers%20vin&relayState=removed&hmac=removed"
2023-12-09 20:30:24.909 DEBUG (MainThread) [volkswagencarnet.vw_connection] Login successful, received authorization code.
2023-12-09 20:30:24.909 DEBUG (MainThread) [volkswagencarnet.vw_connection] Trying to fetch user identity tokens.
2023-12-09 20:30:25.046 DEBUG (MainThread) [volkswagencarnet.vw_connection] Got token token_type
2023-12-09 20:30:25.046 DEBUG (MainThread) [volkswagencarnet.vw_connection] Got token expires_in
2023-12-09 20:30:25.046 DEBUG (MainThread) [volkswagencarnet.vw_connection] Got token id_token
2023-12-09 20:30:25.046 DEBUG (MainThread) [volkswagencarnet.vw_connection] Got token access_token
2023-12-09 20:30:25.046 DEBUG (MainThread) [volkswagencarnet.vw_connection] Got token refresh_token
2023-12-09 20:30:25.082 DEBUG (MainThread) [volkswagencarnet.vw_connection] User identity token verified OK.
2023-12-09 20:30:25.083 DEBUG (MainThread) [volkswagencarnet.vw_connection] Going to call vehicle updates

It's a persistent issue and easy to reproduce. Only need to wait one hour. :)
Seems like there is one more step required for the refreshed token to work.
With API status sensors it's visible as well:

Btw... one more interesting thing... the refreshed token and the token after an unauthorized error is the same token.

[stickpin]

The issue is fixed by this PR: #229

[oliverrahner]

I guess we can close this for now