diff --git a/sdk/identity/azure-identity/CHANGELOG.md b/sdk/identity/azure-identity/CHANGELOG.md index 5c0f944d3b57..009aa5376d42 100644 --- a/sdk/identity/azure-identity/CHANGELOG.md +++ b/sdk/identity/azure-identity/CHANGELOG.md @@ -18,6 +18,7 @@ ### Other Changes - Bumped minimum dependency on `msal` to `>=1.31.0`. +- Added debug logging of access token cache hits in several credentials to improve troubleshooting of token cache behavior. ([#44963](https://github.com/Azure/azure-sdk-for-python/pull/44963)) - Replace instances of `azure.core.pipeline.transport.HttpRequest` with `azure.core.rest.HttpRequest`. ([#44993](https://github.com/Azure/azure-sdk-for-python/pull/44993)) ## 1.26.0b1 (2025-11-07) diff --git a/sdk/identity/azure-identity/azure/identity/_internal/aad_client_base.py b/sdk/identity/azure-identity/azure/identity/_internal/aad_client_base.py index e359cc50af8a..43ee3ce62945 100644 --- a/sdk/identity/azure-identity/azure/identity/_internal/aad_client_base.py +++ b/sdk/identity/azure-identity/azure/identity/_internal/aad_client_base.py @@ -5,6 +5,7 @@ import abc import base64 import json +import logging import time from uuid import uuid4 from typing import TYPE_CHECKING, List, Any, Iterable, Optional, Union, Dict, cast @@ -32,6 +33,8 @@ JWT_BEARER_ASSERTION = "urn:ietf:params:oauth:client-assertion-type:jwt-bearer" +_LOGGER = logging.getLogger(__name__) + class AadClientBase(abc.ABC): _POST = ["POST"] @@ -45,7 +48,7 @@ def __init__( cae_cache: Optional[TokenCache] = None, *, additionally_allowed_tenants: Optional[List[str]] = None, - **kwargs: Any + **kwargs: Any, ) -> None: self._authority = normalize_authority(authority) if authority else get_default_authority() @@ -91,14 +94,25 @@ def get_cached_access_token(self, scopes: Iterable[str], **kwargs: Any) -> Optio ) cache = self._get_cache(**kwargs) + now = int(time.time()) for token in cache.search( TokenCache.CredentialType.ACCESS_TOKEN, target=list(scopes), query={"client_id": self._client_id, "realm": tenant}, ): expires_on = int(token["expires_on"]) - if expires_on > int(time.time()): + if expires_on > now: refresh_on = int(token["refresh_on"]) if "refresh_on" in token else None + expires_in = expires_on - now + refresh_on_msg = f", refresh in {refresh_on - now}s" if refresh_on else "" + _LOGGER.debug( + "Access token found in cache for scopes %s (tenant: %s, expires in %ss%s, cache ID: %s)", + list(scopes), + tenant, + expires_in, + refresh_on_msg, + id(cache), + ) return AccessTokenInfo( token["secret"], expires_on, token_type=token.get("token_type", "Bearer"), refresh_on=refresh_on ) @@ -301,7 +315,7 @@ def _get_on_behalf_of_request( scopes: Iterable[str], client_credential: Union[str, AadClientCertificate, Dict[str, Any]], user_assertion: str, - **kwargs: Any + **kwargs: Any, ) -> HttpRequest: data = { "assertion": user_assertion, @@ -356,7 +370,7 @@ def _get_refresh_token_on_behalf_of_request( scopes: Iterable[str], client_credential: Union[str, AadClientCertificate, Dict[str, Any]], refresh_token: str, - **kwargs: Any + **kwargs: Any, ) -> HttpRequest: data = { "grant_type": "refresh_token", diff --git a/sdk/identity/azure-identity/azure/identity/_internal/managed_identity_client.py b/sdk/identity/azure-identity/azure/identity/_internal/managed_identity_client.py index d305ffe33abc..80cc8452e0d6 100644 --- a/sdk/identity/azure-identity/azure/identity/_internal/managed_identity_client.py +++ b/sdk/identity/azure-identity/azure/identity/_internal/managed_identity_client.py @@ -3,6 +3,7 @@ # Licensed under the MIT License. # ------------------------------------ import abc +import logging import time from typing import Any, Callable, Dict, Optional @@ -17,6 +18,8 @@ from .._internal import _scopes_to_resource from .._internal.pipeline import build_pipeline +_LOGGER = logging.getLogger(__name__) + class ManagedIdentityClientBase(abc.ABC): def __init__( @@ -24,7 +27,7 @@ def __init__( request_factory: Callable[[str, dict], HttpRequest], client_id: Optional[str] = None, identity_config: Optional[Dict] = None, - **kwargs: Any + **kwargs: Any, ) -> None: self._custom_cache = False self._cache = kwargs.pop("_cache", None) @@ -101,6 +104,15 @@ def get_cached_token(self, *scopes: str, **kwargs: Any) -> Optional[AccessTokenI expires_on = int(token["expires_on"]) refresh_on = int(token["refresh_on"]) if "refresh_on" in token else None if expires_on > now and (not refresh_on or refresh_on > now): + expires_in = expires_on - int(now) + refresh_on_msg = f", refresh in {refresh_on - int(now)}s" if refresh_on else "" + _LOGGER.debug( + "Access token found in cache for resource %s (expires in %ss%s, cache ID: %s)", + resource, + expires_in, + refresh_on_msg, + id(self._cache), + ) return AccessTokenInfo( token["secret"], expires_on, token_type=token.get("token_type", "Bearer"), refresh_on=refresh_on )