From a65e8535376de8864b0c7b89f27b3da9d7e47182 Mon Sep 17 00:00:00 2001 From: Charles Lowell Date: Tue, 20 Jul 2021 09:57:52 -0700 Subject: [PATCH] Reduce redundant logging during ChainedTokenCredential.get_token() (#19283) --- sdk/identity/azure-identity/CHANGELOG.md | 4 ++++ .../azure/identity/_credentials/chained.py | 8 +++++--- .../azure/identity/_internal/__init__.py | 17 +++++++++++++++++ .../azure/identity/_internal/decorators.py | 15 +++++++++++++-- .../azure/identity/_internal/get_token_mixin.py | 15 ++++++++++++--- .../azure/identity/aio/_credentials/chained.py | 8 +++++--- .../azure/identity/aio/_internal/decorators.py | 15 +++++++++++++-- .../identity/aio/_internal/get_token_mixin.py | 15 ++++++++++++--- 8 files changed, 81 insertions(+), 16 deletions(-) diff --git a/sdk/identity/azure-identity/CHANGELOG.md b/sdk/identity/azure-identity/CHANGELOG.md index 347fc411901e3..40296e83a8bb1 100644 --- a/sdk/identity/azure-identity/CHANGELOG.md +++ b/sdk/identity/azure-identity/CHANGELOG.md @@ -9,6 +9,10 @@ ### Bugs Fixed ### Other Changes +- Reduced redundant `ChainedTokenCredential` and `DefaultAzureCredential` + logging. On Python 3.7+, credentials invoked by these classes now log debug + rather than info messages. + ([#18972](https://github.com/Azure/azure-sdk-for-python/issues/18972)) ## 1.7.0b2 (2021-07-08) ### Features Added diff --git a/sdk/identity/azure-identity/azure/identity/_credentials/chained.py b/sdk/identity/azure-identity/azure/identity/_credentials/chained.py index 2b79420246d65..239adf55d988c 100644 --- a/sdk/identity/azure-identity/azure/identity/_credentials/chained.py +++ b/sdk/identity/azure-identity/azure/identity/_credentials/chained.py @@ -7,6 +7,7 @@ from azure.core.exceptions import ClientAuthenticationError from .. import CredentialUnavailableError +from .._internal import within_credential_chain try: from typing import TYPE_CHECKING @@ -61,6 +62,7 @@ def get_token(self, *scopes, **kwargs): # pylint:disable=unused-argument :param str scopes: desired scopes for the access token. This method requires at least one scope. :raises ~azure.core.exceptions.ClientAuthenticationError: no credential in the chain provided a token """ + within_credential_chain.set(True) history = [] for credential in self.credentials: try: @@ -71,19 +73,19 @@ def get_token(self, *scopes, **kwargs): # pylint:disable=unused-argument except CredentialUnavailableError as ex: # credential didn't attempt authentication because it lacks required data or state -> continue history.append((credential, ex.message)) - _LOGGER.info("%s - %s is unavailable", self.__class__.__name__, credential.__class__.__name__) except Exception as ex: # pylint: disable=broad-except # credential failed to authenticate, or something unexpectedly raised -> break history.append((credential, str(ex))) - _LOGGER.warning( + _LOGGER.debug( '%s.get_token failed: %s raised unexpected error "%s"', self.__class__.__name__, credential.__class__.__name__, ex, - exc_info=_LOGGER.isEnabledFor(logging.DEBUG), + exc_info=True, ) break + within_credential_chain.set(False) attempts = _get_error_message(history) message = self.__class__.__name__ + " failed to retrieve a token from the included credentials." + attempts _LOGGER.warning(message) diff --git a/sdk/identity/azure-identity/azure/identity/_internal/__init__.py b/sdk/identity/azure-identity/azure/identity/_internal/__init__.py index 93e032cbb8298..a1799b0679a84 100644 --- a/sdk/identity/azure-identity/azure/identity/_internal/__init__.py +++ b/sdk/identity/azure-identity/azure/identity/_internal/__init__.py @@ -14,6 +14,23 @@ if TYPE_CHECKING: from typing import Any, Optional +try: + from contextvars import ContextVar + + within_credential_chain = ContextVar("within_credential_chain", default=False) +except ImportError: + # No ContextVar on Python < 3.7. Credentials will behave as if they're never in a chain i.e. they will log fully. + + class AlwaysFalse: + # pylint:disable=no-self-use + def get(self): + return False + + def set(self, _): + pass + + within_credential_chain = AlwaysFalse() # type: ignore + def normalize_authority(authority): # type: (str) -> str diff --git a/sdk/identity/azure-identity/azure/identity/_internal/decorators.py b/sdk/identity/azure-identity/azure/identity/_internal/decorators.py index 6c00f74bff67c..9fff6e95b6376 100644 --- a/sdk/identity/azure-identity/azure/identity/_internal/decorators.py +++ b/sdk/identity/azure-identity/azure/identity/_internal/decorators.py @@ -8,6 +8,9 @@ from six import raise_from from azure.core.exceptions import ClientAuthenticationError +from . import within_credential_chain + + _LOGGER = logging.getLogger(__name__) @@ -25,10 +28,18 @@ def decorator(fn): def wrapper(*args, **kwargs): try: token = fn(*args, **kwargs) - _LOGGER.info("%s succeeded", qualified_name) + _LOGGER.log( + logging.DEBUG if within_credential_chain.get() else logging.INFO, "%s succeeded", qualified_name + ) return token except Exception as ex: - _LOGGER.warning("%s failed: %s", qualified_name, ex, exc_info=_LOGGER.isEnabledFor(logging.DEBUG)) + _LOGGER.log( + logging.DEBUG if within_credential_chain.get() else logging.WARNING, + "%s failed: %s", + qualified_name, + ex, + exc_info=_LOGGER.isEnabledFor(logging.DEBUG), + ) raise return wrapper diff --git a/sdk/identity/azure-identity/azure/identity/_internal/get_token_mixin.py b/sdk/identity/azure-identity/azure/identity/_internal/get_token_mixin.py index d605e92e765e9..d8b683e984bd1 100644 --- a/sdk/identity/azure-identity/azure/identity/_internal/get_token_mixin.py +++ b/sdk/identity/azure-identity/azure/identity/_internal/get_token_mixin.py @@ -7,6 +7,7 @@ import time from typing import TYPE_CHECKING +from . import within_credential_chain from .._constants import DEFAULT_REFRESH_OFFSET, DEFAULT_TOKEN_REFRESH_RETRY_DELAY try: @@ -80,11 +81,19 @@ def get_token(self, *scopes, **kwargs): token = self._request_token(*scopes, **kwargs) except Exception: # pylint:disable=broad-except pass - _LOGGER.info("%s.get_token succeeded", self.__class__.__name__) + _LOGGER.log( + logging.DEBUG if within_credential_chain.get() else logging.INFO, + "%s.get_token succeeded", + self.__class__.__name__, + ) return token except Exception as ex: - _LOGGER.warning( - "%s.get_token failed: %s", self.__class__.__name__, ex, exc_info=_LOGGER.isEnabledFor(logging.DEBUG) + _LOGGER.log( + logging.DEBUG if within_credential_chain.get() else logging.WARNING, + "%s.get_token failed: %s", + self.__class__.__name__, + ex, + exc_info=_LOGGER.isEnabledFor(logging.DEBUG), ) raise diff --git a/sdk/identity/azure-identity/azure/identity/aio/_credentials/chained.py b/sdk/identity/azure-identity/azure/identity/aio/_credentials/chained.py index 07c46e2741f7b..c0e86ebc33977 100644 --- a/sdk/identity/azure-identity/azure/identity/aio/_credentials/chained.py +++ b/sdk/identity/azure-identity/azure/identity/aio/_credentials/chained.py @@ -10,6 +10,7 @@ from .._internal import AsyncContextManager from ... import CredentialUnavailableError from ..._credentials.chained import _get_error_message +from ..._internal import within_credential_chain if TYPE_CHECKING: from typing import Any, Optional @@ -52,6 +53,7 @@ async def get_token(self, *scopes: str, **kwargs: "Any") -> "AccessToken": :param str scopes: desired scopes for the access token. This method requires at least one scope. :raises ~azure.core.exceptions.ClientAuthenticationError: no credential in the chain provided a token """ + within_credential_chain.set(True) history = [] for credential in self.credentials: try: @@ -62,19 +64,19 @@ async def get_token(self, *scopes: str, **kwargs: "Any") -> "AccessToken": except CredentialUnavailableError as ex: # credential didn't attempt authentication because it lacks required data or state -> continue history.append((credential, ex.message)) - _LOGGER.info("%s - %s is unavailable", self.__class__.__name__, credential.__class__.__name__) except Exception as ex: # pylint: disable=broad-except # credential failed to authenticate, or something unexpectedly raised -> break history.append((credential, str(ex))) - _LOGGER.warning( + _LOGGER.debug( '%s.get_token failed: %s raised unexpected error "%s"', self.__class__.__name__, credential.__class__.__name__, ex, - exc_info=_LOGGER.isEnabledFor(logging.DEBUG), + exc_info=True, ) break + within_credential_chain.set(False) attempts = _get_error_message(history) message = self.__class__.__name__ + " failed to retrieve a token from the included credentials." + attempts raise ClientAuthenticationError(message=message) diff --git a/sdk/identity/azure-identity/azure/identity/aio/_internal/decorators.py b/sdk/identity/azure-identity/azure/identity/aio/_internal/decorators.py index 10bbd33269d2b..aadddcf0457db 100644 --- a/sdk/identity/azure-identity/azure/identity/aio/_internal/decorators.py +++ b/sdk/identity/azure-identity/azure/identity/aio/_internal/decorators.py @@ -7,6 +7,8 @@ from azure.core.exceptions import ClientAuthenticationError +from ..._internal import within_credential_chain + _LOGGER = logging.getLogger(__name__) @@ -15,11 +17,20 @@ def log_get_token_async(fn): async def wrapper(*args, **kwargs): try: token = await fn(*args, **kwargs) - _LOGGER.info("%s succeeded", fn.__qualname__) + _LOGGER.log( + logging.DEBUG if within_credential_chain.get() else logging.INFO, "%s succeeded", fn.__qualname__ + ) return token except Exception as ex: - _LOGGER.warning("%s failed: %s", fn.__qualname__, ex, exc_info=_LOGGER.isEnabledFor(logging.DEBUG)) + _LOGGER.log( + logging.DEBUG if within_credential_chain.get() else logging.WARNING, + "%s failed: %s", + fn.__qualname__, + ex, + exc_info=_LOGGER.isEnabledFor(logging.DEBUG), + ) raise + return wrapper diff --git a/sdk/identity/azure-identity/azure/identity/aio/_internal/get_token_mixin.py b/sdk/identity/azure-identity/azure/identity/aio/_internal/get_token_mixin.py index 5da662f4e2b4a..17b8d225b55dd 100644 --- a/sdk/identity/azure-identity/azure/identity/aio/_internal/get_token_mixin.py +++ b/sdk/identity/azure-identity/azure/identity/aio/_internal/get_token_mixin.py @@ -8,6 +8,7 @@ from typing import TYPE_CHECKING from ..._constants import DEFAULT_REFRESH_OFFSET, DEFAULT_TOKEN_REFRESH_RETRY_DELAY +from ..._internal import within_credential_chain if TYPE_CHECKING: # pylint:disable=ungrouped-imports,unused-import @@ -70,11 +71,19 @@ async def get_token(self, *scopes: str, **kwargs: "Any") -> "AccessToken": token = await self._request_token(*scopes, **kwargs) except Exception: # pylint:disable=broad-except pass - _LOGGER.info("%s.get_token succeeded", self.__class__.__name__) + _LOGGER.log( + logging.DEBUG if within_credential_chain.get() else logging.INFO, + "%s.get_token succeeded", + self.__class__.__name__, + ) return token except Exception as ex: - _LOGGER.warning( - "%s.get_token failed: %s", self.__class__.__name__, ex, exc_info=_LOGGER.isEnabledFor(logging.DEBUG) + _LOGGER.log( + logging.DEBUG if within_credential_chain.get() else logging.WARNING, + "%s.get_token failed: %s", + self.__class__.__name__, + ex, + exc_info=_LOGGER.isEnabledFor(logging.DEBUG), ) raise