Failed to refresh access token

[Prior99]

Even with the new implementation it will fail:

2024-09-22 06:28:09.792 INFO (MainThread) [myskoda.authorization] Refreshing IDK access token
2024-09-22 06:28:09.894 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token.
2024-09-22 06:28:09.917 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token.
2024-09-22 06:28:09.941 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token.
2024-09-22 06:28:09.966 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token.
2024-09-22 06:28:09.987 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token.
2024-09-22 06:28:10.009 ERROR (MainThread) [custom_components.myskoda.coordinator] Unexpected error fetching myskoda data
Traceback (most recent call last):
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 83, in perform_refresh
    raise InvalidStatusError(response.status)  # noqa: TRY301
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
myskoda.authorization.InvalidStatusError: Received invalid HTTP status code 400.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 83, in perform_refresh
    raise InvalidStatusError(response.status)  # noqa: TRY301
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
myskoda.authorization.InvalidStatusError: Received invalid HTTP status code 400.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 83, in perform_refresh
    raise InvalidStatusError(response.status)  # noqa: TRY301
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
myskoda.authorization.InvalidStatusError: Received invalid HTTP status code 400.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 83, in perform_refresh
    raise InvalidStatusError(response.status)  # noqa: TRY301
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
myskoda.authorization.InvalidStatusError: Received invalid HTTP status code 400.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 83, in perform_refresh
    raise InvalidStatusError(response.status)  # noqa: TRY301
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
myskoda.authorization.InvalidStatusError: Received invalid HTTP status code 400.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/prior/repositories/homeassistant-core/homeassistant/helpers/update_coordinator.py", line 354, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/prior/repositories/homeassistant-core/config/custom_components/myskoda/coordinator.py", line 82, in _async_update_data
    vehicle = await self.myskoda.get_vehicle(self.vin)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/prior/repositories/myskoda/myskoda/myskoda.py", line 180, in get_vehicle
    info = await self.get_info(vin)
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/prior/repositories/myskoda/myskoda/myskoda.py", line 136, in get_info
    return await self.rest_api.get_info(vin)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/prior/repositories/myskoda/myskoda/rest_api.py", line 47, in get_info
    headers=await self._headers(),
            ^^^^^^^^^^^^^^^^^^^^^
  File "/home/prior/repositories/myskoda/myskoda/rest_api.py", line 152, in _headers
    return {"authorization": f"Bearer {await self.idk_session.get_access_token(self.session)}"}
                                       ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 104, in get_access_token
    await self.perform_refresh(session)
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 92, in perform_refresh
    await self.perform_refresh(session, attempt=attempt + 1)
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 92, in perform_refresh
    await self.perform_refresh(session, attempt=attempt + 1)
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 92, in perform_refresh
    await self.perform_refresh(session, attempt=attempt + 1)
  [Previous line repeated 2 more times]
  File "/home/prior/repositories/myskoda/myskoda/authorization.py", line 83, in perform_refresh
    raise InvalidStatusError(response.status)  # noqa: TRY301
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
myskoda.authorization.InvalidStatusError: Received invalid HTTP status code 400.

Most likely, when this happens, we will have to login using username / password again.

[dvx76]

Damn. I'm really curious what error is returned though. Let's add some more info when we hit this.

[Prior99]

I prepared a little fix, I will let it run for today while I'm away

[Prior99]

Basically, this:

    async def perform_refresh(self, session: ClientSession, username: str, password: str) -> None:
        """Refresh the authorization token.

        This will consume the `refresh_token` and exchange it for a new set of tokens.
        """
        json_data = {"token": self.refresh_token}

        async def perform_request() -> bool:
            meta = jwt.decode(
                self.access_token, options={"verify_signature": False}
            )
            expiry = datetime.fromtimestamp(cast(float, meta.get("exp")), tz=UTC)
            if datetime.now(tz=UTC) + timedelta(minutes=10) < expiry:
                return True
            async with session.post(
                f"{BASE_URL_SKODA}/api/v1/authentication/refresh-token?tokenType=CONNECT",
                json=json_data,
            ) as response:
                try:
                    if not response.ok:
                        raise InvalidStatusError(response.status)  # noqa: TRY301
                    data = json.loads(await response.text())
                    self.access_token = data.get("accessToken")
                    self.refresh_token = data.get("refreshToken")
                    self.id_token = data.get("idToken")
                except Exception:
                    return False
                else:
                    return True

        async with refresh_token_lock:
            attempts = 0
            while not await perform_request():
                if attempts >= MAX_RETRIES:
                    _LOGGER.error(
                        "Refreshing token failed after %d attempts.", MAX_RETRIES
                    )
                    _LOGGER.info("Trying to recover by logging in again...")
                    try:
                        tokens = await idk_authorize(session, username, password)
                    except Exception:
                        _LOGGER.exception("Failed to login.")
                    else:
                        self.access_token = tokens.access_token
                        self.refresh_token = tokens.refresh_token
                        self.id_token = tokens.id_token
                        _LOGGER.info("Successfully recovered by logging in.")
                _LOGGER.warning("Retrying failed request to refresh token. Retrying...")
                attempts = attempts + 1

Let's see.

[dvx76]

Ah lol I just pushed #14 and have that running locally today as well. We'll see :)

[dvx76]

2024-09-22 12:36:49.544 DEBUG (MainThread) [myskoda.myskoda] Trace: POST https://mysmob.api.connect.skoda-auto.cz/api/v1/authenticati - response: 400 (808 bytes) Validation failed for argument at index 1 in method: public reactor.core.publisher.Mono<org.springframework.http.ResponseEntity<cz.skodaauto.bff.v1.models.AuthenticationDto>> cz.skodaauto.bff.myskoda.mobile.feature.authentication.controller.AuthenticationController.refreshToken(java.lang.String,reactor.core.publisher.Mono<cz.skodaauto.bff.v1.models.RefreshTokenDto>,org.springframework.web.server.ServerWebExchange), with 1 error(s): [Field error in object 'refreshTokenDtoMono' on field 'token': rejected value [null]; codes [NotNull.refreshTokenDtoMono.token,NotNull.token,NotNull.java.lang.String,NotNull]; arguments [org.springframework.context.support.DefaultMessageSourceResolvable: codes [refreshTokenDtoMono.token,token]; arguments []; default message [token]]; default message [must not be null]]

We're sending null for the refresh token?!

[dvx76]

Looks like it. 🙃

2024-09-22 18:40:24.389 INFO (MainThread) [myskoda.authorization] Sending refresh json_data: {'token': None}

[Prior99]

1167   │ 2024-09-22 13:57:56.950 INFO (MainThread) [myskoda.authorization] Refreshing IDK access token
1168   │ 2024-09-22 13:57:56.980 INFO (MainThread) [myskoda.authorization] Refreshing IDK access token
1169   │ 2024-09-22 13:57:57.046 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token. Retrying...
1170   │ 2024-09-22 13:57:57.072 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token. Retrying...
1171   │ 2024-09-22 13:57:57.095 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token. Retrying...
1172   │ 2024-09-22 13:57:57.121 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token. Retrying...
1173   │ 2024-09-22 13:57:57.147 WARNING (MainThread) [myskoda.authorization] Retrying failed request to refresh token. Retrying...
1174   │ 2024-09-22 13:57:57.174 ERROR (MainThread) [myskoda.authorization] Refreshing token failed after 5 attempts.
1175   │ 2024-09-22 13:57:57.174 INFO (MainThread) [myskoda.authorization] Trying to recover by logging in again...
1176   │ 2024-09-22 13:57:58.389 INFO (MainThread) [myskoda.authorization] Successfully recovered by logging in.

It always seem to re-login, refresh token seem to fail

[Prior99]

@dvx76 that explains it :laughing: