Add logging to credentials

sdk/identity/azure-identity/azure/identity/_credentials/authorization_code.py

@@ -6,6 +6,7 @@
 
 from azure.core.exceptions import ClientAuthenticationError
 from .._internal.aad_client import AadClient
+from .._internal.decorators import log_get_token
 
 if TYPE_CHECKING:
     # pylint:disable=unused-import,ungrouped-imports
@@ -38,6 +39,7 @@ def __init__(self, tenant_id, client_id, authorization_code, redirect_uri, **kwa
         self._client = kwargs.pop("client", None) or AadClient(tenant_id, client_id, **kwargs)
         self._redirect_uri = redirect_uri
 
+    @log_get_token("AuthorizationCodeCredential")
     def get_token(self, *scopes, **kwargs):
         # type: (*str, **Any) -> AccessToken
         """Request an access token for `scopes`.

sdk/identity/azure-identity/azure/identity/_credentials/azure_cli.py

@@ -17,11 +17,13 @@
 
 from .. import CredentialUnavailableError
 from .._internal import _scopes_to_resource
+from .._internal.decorators import log_get_token
 
 if TYPE_CHECKING:
     # pylint:disable=ungrouped-imports
     from typing import Any
 
+
 CLI_NOT_FOUND = "Azure CLI not found on path"
 COMMAND_LINE = "az account get-access-token --output json --resource {}"
 NOT_LOGGED_IN = "Please run 'az login' to set up an account"
@@ -33,6 +35,7 @@ class AzureCliCredential(object):
     This requires previously logging in to Azure via "az login", and will use the CLI's currently logged in identity.
     """
 
+    @log_get_token("AzureCliCredential")
     def get_token(self, *scopes, **kwargs):  # pylint:disable=no-self-use,unused-argument
         # type: (*str, **Any) -> AccessToken
         """Request an access token for `scopes`.

sdk/identity/azure-identity/azure/identity/_credentials/certificate.py

@@ -5,6 +5,7 @@
 from typing import TYPE_CHECKING
 
 from .._internal import AadClient, CertificateCredentialBase
+from .._internal.decorators import log_get_token
 
 if TYPE_CHECKING:
     from azure.core.credentials import AccessToken
@@ -30,6 +31,7 @@ class CertificateCredential(CertificateCredentialBase):
           is unavailable. Default to False. Has no effect when `enable_persistent_cache` is False.
     """
 
+    @log_get_token("CertificateCredential")
     def get_token(self, *scopes, **kwargs):  # pylint:disable=unused-argument
         # type: (*str, **Any) -> AccessToken
         """Request an access token for `scopes`.

sdk/identity/azure-identity/azure/identity/_credentials/chained.py

@@ -2,6 +2,8 @@
 # Copyright (c) Microsoft Corporation.
 # Licensed under the MIT License.
 # ------------------------------------
+import logging
+
 from azure.core.exceptions import ClientAuthenticationError
 
 from .. import CredentialUnavailableError
@@ -16,6 +18,8 @@
     from typing import Any, Optional
     from azure.core.credentials import AccessToken, TokenCredential
 
+_LOGGER = logging.getLogger(__name__)
+
 
 def _get_error_message(history):
     attempts = []
@@ -61,16 +65,26 @@ def get_token(self, *scopes, **kwargs):  # pylint:disable=unused-argument
         for credential in self.credentials:
             try:
                 token = credential.get_token(*scopes, **kwargs)
+                _LOGGER.info("%s acquired a token from %s", self.__class__.__name__, credential.__class__.__name__)
                 self._successful_credential = credential
                 return token
             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(
+                    '%s.get_token failed: %s raised unexpected error "%s"',
+                    self.__class__.__name__,
+                    credential.__class__.__name__,
+                    ex,
+                    exc_info=_LOGGER.isEnabledFor(logging.DEBUG),
+                )
                 break
 
         attempts = _get_error_message(history)
         message = self.__class__.__name__ + " failed to retrieve a token from the included credentials." + attempts
+        _LOGGER.warning(message)
         raise ClientAuthenticationError(message=message)

sdk/identity/azure-identity/azure/identity/_credentials/client_secret.py

@@ -3,6 +3,7 @@
 # Licensed under the MIT License.
 # ------------------------------------
 from .._internal import AadClient, ClientSecretCredentialBase
+from .._internal.decorators import log_get_token
 
 try:
     from typing import TYPE_CHECKING
@@ -31,6 +32,7 @@ class ClientSecretCredential(ClientSecretCredentialBase):
           is unavailable. Default to False. Has no effect when `enable_persistent_cache` is False.
     """
 
+    @log_get_token("ClientSecretCredential")
     def get_token(self, *scopes, **kwargs):
         # type: (*str, **Any) -> AccessToken
         """Request an access token for `scopes`.

sdk/identity/azure-identity/azure/identity/_credentials/default.py

@@ -102,7 +102,6 @@ def __init__(self, **kwargs):
                 )
                 credentials.append(shared_cache)
             except Exception as ex:  # pylint:disable=broad-except
-                # transitive dependency pywin32 doesn't support 3.8 (https://github.com/mhammond/pywin32/issues/1431)
                 _LOGGER.info("Shared token cache is unavailable: '%s'", ex)
         if not exclude_visual_studio_code_credential:
             credentials.append(VSCodeCredential())
@@ -124,6 +123,10 @@ def get_token(self, *scopes, **kwargs):
           `message` attribute listing each authentication attempt and its error message.
         """
         if self._successful_credential:
-            return self._successful_credential.get_token(*scopes, **kwargs)
+            token = self._successful_credential.get_token(*scopes, **kwargs)
+            _LOGGER.info(
+                "%s acquired a token from %s", self.__class__.__name__, self._successful_credential.__class__.__name__
+            )
+            return token
 
         return super(DefaultAzureCredential, self).get_token(*scopes, **kwargs)

sdk/identity/azure-identity/azure/identity/_credentials/environment.py

@@ -2,10 +2,13 @@
 # Copyright (c) Microsoft Corporation.
 # Licensed under the MIT License.
 # ------------------------------------
+import logging
 import os
 
+
 from .. import CredentialUnavailableError
 from .._constants import EnvironmentVariables
+from .._internal.decorators import log_get_token
 from .certificate import CertificateCredential
 from .client_secret import ClientSecretCredential
 from .user_password import UsernamePasswordCredential
@@ -22,6 +25,8 @@
 
     EnvironmentCredentialTypes = Union["CertificateCredential", "ClientSecretCredential", "UsernamePasswordCredential"]
 
+_LOGGER = logging.getLogger(__name__)
+
 
 class EnvironmentCredential(object):
     """A credential configured by environment variables.
@@ -76,6 +81,21 @@ def __init__(self, **kwargs):
                 **kwargs
             )
 
+        if self._credential:
+            _LOGGER.info("Environment is configured for %s", self._credential.__class__.__name__)
+        else:
+            expected_variables = set(
+                EnvironmentVariables.CERT_VARS
+                + EnvironmentVariables.CLIENT_SECRET_VARS
+                + EnvironmentVariables.USERNAME_PASSWORD_VARS
+            )
+            set_variables = [v for v in expected_variables if v in os.environ]
+            if set_variables:
+                _LOGGER.warning("Incomplete environment configuration. Set variables: %s", ", ".join(set_variables))
+            else:
+                _LOGGER.info("No environment configuration found.")
+
+    @log_get_token("EnvironmentCredential")
     def get_token(self, *scopes, **kwargs):  # pylint:disable=unused-argument
         # type: (*str, **Any) -> AccessToken
         """Request an access token for `scopes`.

sdk/identity/azure-identity/azure/identity/_credentials/managed_identity.py

@@ -2,6 +2,7 @@
 # Copyright (c) Microsoft Corporation.
 # Licensed under the MIT License.
 # ------------------------------------
+import logging
 import os
 
 import six
@@ -21,6 +22,7 @@
 from .. import CredentialUnavailableError
 from .._authn_client import AuthnClient
 from .._constants import Endpoints, EnvironmentVariables
+from .._internal.decorators import log_get_token
 from .._internal.user_agent import USER_AGENT
 
 try:
@@ -32,6 +34,8 @@
     # pylint:disable=unused-import
     from typing import Any, Optional, Type
 
+_LOGGER = logging.getLogger(__name__)
+
 
 class ManagedIdentityCredential(object):
     """Authenticates with an Azure managed identity in any hosting environment which supports managed identities.
@@ -50,10 +54,13 @@ def __init__(self, **kwargs):
         # type: (**Any) -> None
         self._credential = None
         if os.environ.get(EnvironmentVariables.MSI_ENDPOINT):
+            _LOGGER.info("%s will use MSI", self.__class__.__name__)
             self._credential = MsiCredential(**kwargs)
         else:
+            _LOGGER.info("%s will use IMDS", self.__class__.__name__)
             self._credential = ImdsCredential(**kwargs)
 
+    @log_get_token("ManagedIdentityCredential")
     def get_token(self, *scopes, **kwargs):
         # type: (*str, **Any) -> AccessToken
         """Request an access token for `scopes`.
@@ -160,6 +167,7 @@ def get_token(self, *scopes, **kwargs):  # pylint:disable=unused-argument
             except Exception:  # pylint:disable=broad-except
                 # if anything else was raised, assume the endpoint is unavailable
                 self._endpoint_available = False
+                _LOGGER.info("No response from the IMDS endpoint.")
 
         if not self._endpoint_available:
             message = "ManagedIdentityCredential authentication unavailable, no managed identity endpoint found."

sdk/identity/azure-identity/azure/identity/_credentials/shared_cache.py

@@ -5,6 +5,7 @@
 from .. import CredentialUnavailableError
 from .._constants import AZURE_CLI_CLIENT_ID
 from .._internal import AadClient
+from .._internal.decorators import log_get_token
 from .._internal.shared_token_cache import NO_TOKEN, SharedTokenCacheBase
 
 try:
@@ -36,6 +37,7 @@ class SharedTokenCacheCredential(SharedTokenCacheBase):
         is unavailable. Defaults to False.
     """
 
+    @log_get_token("SharedTokenCacheCredential")
     def get_token(self, *scopes, **kwargs):  # pylint:disable=unused-argument
         # type (*str, **Any) -> AccessToken
         """Get an access token for `scopes` from the shared cache.

sdk/identity/azure-identity/azure/identity/_credentials/vscode_credential.py

@@ -4,9 +4,11 @@
 # ------------------------------------
 import sys
 from typing import TYPE_CHECKING
+
 from .._exceptions import CredentialUnavailableError
 from .._constants import AZURE_VSCODE_CLIENT_ID
 from .._internal.aad_client import AadClient
+from .._internal.decorators import log_get_token
 
 if sys.platform.startswith("win"):
     from .._internal.win_vscode_adapter import get_credentials
@@ -29,6 +31,7 @@ def __init__(self, **kwargs):
         self._client = kwargs.pop("_client", None) or AadClient("organizations", AZURE_VSCODE_CLIENT_ID, **kwargs)
         self._refresh_token = None
 
+    @log_get_token("VSCodeCredential")
     def get_token(self, *scopes, **kwargs):
         # type: (*str, **Any) -> AccessToken
         """Request an access token for `scopes`.

sdk/identity/azure-identity/azure/identity/_internal/__init__.py

@@ -36,7 +36,7 @@ def get_default_authority():
 from .aadclient_certificate import AadClientCertificate
 from .certificate_credential_base import CertificateCredentialBase
 from .client_secret_credential_base import ClientSecretCredentialBase
-from .exception_wrapper import wrap_exceptions
+from .decorators import wrap_exceptions
 from .msal_credentials import InteractiveCredential
 
 

sdk/identity/azure-identity/azure/identity/_internal/decorators.py

@@ -0,0 +1,52 @@
+# ------------------------------------
+# Copyright (c) Microsoft Corporation.
+# Licensed under the MIT License.
+# ------------------------------------
+import functools
+import logging
+
+from six import raise_from
+from azure.core.exceptions import ClientAuthenticationError
+
+_LOGGER = logging.getLogger(__name__)
+
+
+def log_get_token(class_name):
+    """Adds logging around get_token calls.
+
+    :param str class_name: required for the sake of Python 2.7, which lacks an easy way to get the credential's class
+        name from the decorated function
+    """
+
+    def decorator(fn):
+        qualified_name = class_name + ".get_token"
+
+        @functools.wraps(fn)
+        def wrapper(*args, **kwargs):
+            try:
+                token = fn(*args, **kwargs)
+                _LOGGER.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))
+                raise
+
+        return wrapper
+
+    return decorator
+
+
+def wrap_exceptions(fn):
+    """Prevents leaking exceptions defined outside azure-core by raising ClientAuthenticationError from them."""
+
+    @functools.wraps(fn)
+    def wrapper(*args, **kwargs):
+        try:
+            return fn(*args, **kwargs)
+        except ClientAuthenticationError:
+            raise
+        except Exception as ex:  # pylint:disable=broad-except
+            auth_error = ClientAuthenticationError(message="Authentication failed: {}".format(ex))
+            raise_from(auth_error, ex)
+
+    return wrapper