Reduce redundant logging during ChainedTokenCredential.get_token() (#19283)

Author: chlowell

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

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)

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

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

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

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)

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
 
 

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