Add logging to credentials #12319

chlowell · 2020-07-02T00:10:10Z

This adds logging to all credentials in alignment with the broad cross-language design implemented in Go and Java SDKs (closes #5548). I'm less than fully satisfied with the decorator approach I took here but it's the most expedient way I found to meet these requirements:

log success or failure of every get_token call
log all unhandled get_token exceptions at WARNING level, add tracebacks when the logger is enabled for DEBUG level
correlate log records to credentials
- i.e. include credential names, use loggers from credential modules

Basically I wanted context scoped logging. Getting a weak version of it here felt like hammering a square peg into a round hole but I'm not so familiar with logging and wouldn't be surprised to learn I missed a better way--alternative suggestions welcome 😸

example output

typical success and failure

[INFO] ClientSecretCredential.get_token succeeded

[WARNING] ClientSecretCredential.get_token failed: Azure Active Directory error '(invalid_client) AADSTS7000215: Invalid client secret is provided.
Trace ID: 95a0fb68-9a2e-4bcf-ad0f-001672c33400
Correlation ID: bc737463-0ee7-4d61-9f80-fd2f5cbaf7cc
Timestamp: 2020-07-01 22:50:44Z'

DefaultAzureCredential.get_token()

[WARNING] EnvironmentCredential.get_token failed: EnvironmentCredential authentication unavailable. Environment variables are not fully configured.
[INFO] DefaultAzureCredential - EnvironmentCredential is unavailable
[INFO] No response from the IMDS endpoint.
[WARNING] ManagedIdentityCredential.get_token failed: ManagedIdentityCredential authentication unavailable, no managed identity endpoint found.
[INFO] DefaultAzureCredential - ManagedIdentityCredential is unavailable
[INFO] SharedTokenCacheCredential.get_token succeeded
[INFO] DefaultAzureCredential acquired a token from SharedTokenCacheCredential

EnvironmentCredential()

nothing configured

[INFO] No environment configuration found.

partially configured

[WARNING] Incomplete environment configuration. Set variables: AZURE_CLIENT_ID, AZURE_CLIENT_SECRET

fully configured

[INFO] Environment is configured for ClientSecretCredential

ManagedIdentityCredential

[INFO] ManagedIdentityCredential will use IMDS
[INFO] No response from the IMDS endpoint.
[WARNING] ManagedIdentityCredential.get_token failed: ManagedIdentityCredential authentication unavailable, no managed identity endpoint found.

xiangyan99

Should we use span?

xiangyan99

Another question is does user always want to log the successful info?
Or we want to make it as opt-in mode?

chlowell · 2020-07-02T16:37:37Z

Should we use span?

What do you mean?

Another question is does user always want to log the successful info?
Or we want to make it as opt-in mode?

It's already opt in. Users control what's logged and how by configuring logging.

xiangyan99 · 2020-07-02T16:40:12Z

Should we use span?

What do you mean?

I meant e.g. https://github.com/Azure/azure-sdk-for-python/tree/master/sdk/core/azure-core-tracing-opencensus

Another question is does user always want to log the successful info?
Or we want to make it as opt-in mode?

It's already opt in. Users control what's logged and how by configuring logging.

I meant should we only log these information (including successful calls) only in debug mode?

chlowell · 2020-07-02T17:30:02Z

I meant e.g. https://github.com/Azure/azure-sdk-for-python/tree/master/sdk/core/azure-core-tracing-opencensus

When we first added tracing, we chose not to decorate credentials for it. Doing so would be work for a separate PR. This one's focused on the cross-language effort to improve what users get from their language's standard logging tools.

I meant should we only log these information (including successful calls) only in debug mode?

I think this is useful basic information not detailed enough to debug a complex scenario. Logging it at DEBUG level would hide it from users. It also wouldn't align with our Python guidelines, which want exceptions logged at WARNING level and normal operation at INFO level.

xiangyan99 · 2020-07-02T18:03:34Z

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

@@ -61,6 +66,11 @@ def __init__(self, client_id, **kwargs):
        self._prompt_callback = kwargs.pop("prompt_callback", None)
        super(DeviceCodeCredential, self).__init__(client_id=client_id, **kwargs)

+    @log_get_token(_LOGGER, "DeviceCodeCredential")


Does self.class.name work here? Then we don't need to have this in the sub-classes.

I wish it did. However, the decorator is applied during parsing of the class definition. There's no self and the class isn't yet defined (so this can't be just DeviceCodeCredential).

Then I doubt if decorator is the right way to go.

It will require us dup a lot of code for some complex hierarchy.

I'm interested in better ways to do this but I don't see duplication as one of the problems here. The decorator adds 2 lines of boilerplate (import the decorator, apply it to get_token) to every credential module. How could we get the same result with less duplication? What do you mean by "complex hierarchy"?

I meant if the hierarchy is very deep and wide like a tree, we would not be able to fully benefit from polymorphism.

And my another concern is like
class A()
class B(A)
class C(B)

My expected behavior: when I call A->get_token(), it can recognize the real class is C hence it calls C->get_token() and only logs C->get_token() is called.

In our case, C->get_token() ("C is called" is logged) will call into B->get_token() and call into A->get_token(), will we have "B is called" & "A is called" in our log?

First, let's agree not to build a deep and wide inheritance hierarchy 🤝

We're talking about an instance method. Calling C().get_token() only invokes A().get_token() if it calls super or C doesn't override get_token. But yes, if one decorated method calls another, each adds log entries. This isn't particular to the decorator though. Imagine the obvious alternative implementation: every get_token does its own logging. Then if C.get_token() calls A().get_token(), you still get logs from each. Nor is this necessarily a problem. One of our goals is to provide insight into what composite credentials like DefaultAzureCredential are doing. We want to see logs from both DefaultAzureCredential and the inner credentials it invokes.

I think we already have it?

UsernamePasswordCredential, InteractiveBrowserCredential, DeviceCodeCredential all inherit from InteractiveCredential which is a subclass of PublicClientCredential which is a sub class of MsalCredential.

Though now we are not quite hit by the problem because get_token in PublicClientCredential & MsalCredential are abstractmethod. We need to think about the cost of one day it happens.

Another question is let's say we want the logs of UsernamePasswordCredential, InteractiveBrowserCredential & DeviceCodeCredential to be a little bit different. How can we achieve it?

Another question is let's say we want the logs of UsernamePasswordCredential, InteractiveBrowserCredential & DeviceCodeCredential to be a little bit different. How can we achieve it?

The differences in their behavior are in their _request_token methods. We can log anything specific to an implementation in that method.

catalinaperalta · 2020-07-13T17:31:44Z

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

@@ -76,6 +81,21 @@ def __init__(self, **kwargs):
                **kwargs
            )

+        if self._credential:
+            _LOGGER.info("Environment is configured for %s", self._credential.__class__.__name__)


Just a question since I'm not familiar enough with how the credentials are set in python, do you log environment configurations for other credentials that are affected when there are environment variables present? For instance, in managed identity, if client ID is set, that affects the credential.

No, in this PR only EnvironmentCredential logs environment variables. Do we intend to log that a particular variable is set everywhere it's used?

I think we did settle on the fact that this is an important logging scenario, since env vars do impact the request for credentials when they are present. I would say that if possible we should only log them once per total log output. In Go, I have not quite reached that, I log them once per credential that is instantiated.

xiangyan99 · 2020-07-14T16:29:14Z

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

            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"',


Given this is chained credential, should this be a warning? Or just info?

The design guidelines stipulate exceptions be logged as warnings.

xiangyan99 · 2020-07-14T16:31:40Z

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

@@ -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)


This call must succeed, right?

Then maybe we can just do

_LOGGER.info( "%s acquired a token from %s", self.__class__.__name__, self._successful_credential.__class__.__name__ ) return self._successful_credential.get_token(*scopes, **kwargs)

?

This call could fail. Maybe the credential requests a new token and something goes wrong.

xiangyan99

Do we want to add timestamps into the logs?

chlowell · 2020-07-14T16:40:11Z

Do we want to add timestamps into the logs?

No, logging timestamps logs and applications decide how to display them.

joshfree · 2020-07-20T17:43:06Z

@chlowell can you please get this merged ahead of the Wednesday out-of-band Identity preview?

…into ta_opinion_mining_sample * 'master' of https://github.com/Azure/azure-sdk-for-python: (124 commits) [formrecognizer] Add type to FormField (Azure#12561) Add example summary for azure-identity readme.md (Azure#12509) Add logging to credentials (Azure#12319) Sdk automation/track2 azure mgmt keyvault (Azure#12638) Remove unnecessary coroutine declaration (Azure#12602) [Cosmos] Fix type comment (Azure#12598) replace aka link (Azure#12597) [ServiceBus] Message/ReceivedMessage Properties alignment with other languages (Azure#12451) Find list of installed packages using pkg_resources (Azure#12591) token refresh offset (Azure#12136) updates (Azure#12595) User authentication samples (Azure#11343) Remove unnecessary base class (Azure#12374) Sequence -> Iterable for scopes (Azure#12579) Disable apistubgen step until issue is fixed (Azure#12594) fix pylint issue (Azure#12578) fix name in example (Azure#12572) Update tests.md (Azure#12574) Add stress tests for max batch size/prefetch, and for unsettled message receipt. Add capability to not auto-complete and adjust max_batch_size into the base stress tester. (Azure#12344) [formrecognizer] Capitalize enum values (Azure#12540) ...

jiasli · 2020-12-23T03:49:26Z

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

+            expected_variables = set(EnvironmentVariables.CERT_VARS + EnvironmentVariables.CLIENT_SECRET_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))


This sentence feels semantically ambiguous to me, it can mean either:

[imperative mood] Please set variables

[past participle] Variables that are already set

@dbradish-microsoft

As suggested by #12319 (comment).

As suggested by Azure#12319 (comment).

chlowell added Client This issue points to a problem in the data-plane of the library. Azure.Identity labels Jul 2, 2020

chlowell requested review from sadasant, jianghaolu, catalinaperalta and xiangyan99 July 2, 2020 00:10

chlowell requested a review from schaabs as a code owner July 2, 2020 00:10

xiangyan99 reviewed Jul 2, 2020

View reviewed changes

chlowell requested a review from xiangyan99 July 2, 2020 22:20

chlowell marked this pull request as draft July 3, 2020 02:40

chlowell marked this pull request as ready for review July 10, 2020 17:38

catalinaperalta reviewed Jul 13, 2020

View reviewed changes

xiangyan99 reviewed Jul 14, 2020

View reviewed changes

chlowell added 7 commits July 17, 2020 15:32

ChainedTokenCredential

d26328c

log managed identity type

0290c6e

EnvironmentCredential

c72c411

decorator logs get_token success/failure

0fe67d7

move logging into InteractiveCredential.get_token

4ff5632

move wrap_exceptions into decorators module

b1ea850

msal_credentials uses its local logger

3f4bf1a

chlowell force-pushed the logging branch from 157e711 to 3f4bf1a Compare July 17, 2020 22:43

xiangyan99 previously approved these changes Jul 18, 2020

View reviewed changes

joshfree added the blocking-release Blocks release label Jul 20, 2020

joshfree added this to the [2020] August milestone Jul 20, 2020

decorators use a local logger instance

9625cb3

chlowell dismissed xiangyan99’s stale review via 9625cb3 July 20, 2020 17:59

chlowell requested a review from xiangyan99 July 20, 2020 17:59

xiangyan99 previously approved these changes Jul 20, 2020

View reviewed changes

remove unused properties from test classes

9d9c771

chlowell dismissed xiangyan99’s stale review via 9d9c771 July 20, 2020 23:36

chlowell requested a review from xiangyan99 July 20, 2020 23:54

xiangyan99 approved these changes Jul 21, 2020

View reviewed changes

chlowell merged commit 86f4124 into Azure:master Jul 21, 2020

chlowell deleted the logging branch July 21, 2020 15:16

jiasli reviewed Dec 23, 2020

View reviewed changes

chlowell mentioned this pull request Jan 4, 2021

Clearer message for incomplete environment configuration #15974

Merged

ghost pushed a commit that referenced this pull request Jan 4, 2021

Clearer message for incomplete environment configuration (#15974)

4c62441

As suggested by #12319 (comment).

rakshith91 pushed a commit to rakshith91/azure-sdk-for-python that referenced this pull request Jan 8, 2021

Clearer message for incomplete environment configuration (Azure#15974)

393e3c3

As suggested by Azure#12319 (comment).

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add logging to credentials #12319

Add logging to credentials #12319

chlowell commented Jul 2, 2020

xiangyan99 left a comment

xiangyan99 left a comment

chlowell commented Jul 2, 2020

xiangyan99 commented Jul 2, 2020

chlowell commented Jul 2, 2020

xiangyan99 Jul 2, 2020

chlowell Jul 2, 2020

xiangyan99 Jul 2, 2020 •

edited

Loading

chlowell Jul 2, 2020

xiangyan99 Jul 2, 2020 •

edited

Loading

chlowell Jul 2, 2020

xiangyan99 Jul 3, 2020

chlowell Jul 6, 2020

catalinaperalta Jul 13, 2020

chlowell Jul 13, 2020

catalinaperalta Jul 13, 2020

xiangyan99 Jul 14, 2020

chlowell Jul 14, 2020

xiangyan99 Jul 14, 2020

chlowell Jul 14, 2020

xiangyan99 left a comment

chlowell commented Jul 14, 2020

joshfree commented Jul 20, 2020

jiasli Dec 23, 2020 •

edited

Loading

jiasli Dec 23, 2020

chlowell Jan 4, 2021

Add logging to credentials #12319

Add logging to credentials #12319

Conversation

chlowell commented Jul 2, 2020

example output

typical success and failure

DefaultAzureCredential.get_token()

EnvironmentCredential()

nothing configured

partially configured

fully configured

ManagedIdentityCredential

xiangyan99 left a comment

Choose a reason for hiding this comment

xiangyan99 left a comment

Choose a reason for hiding this comment

chlowell commented Jul 2, 2020

xiangyan99 commented Jul 2, 2020

chlowell commented Jul 2, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

xiangyan99 Jul 2, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

xiangyan99 Jul 2, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

xiangyan99 left a comment

Choose a reason for hiding this comment

chlowell commented Jul 14, 2020

joshfree commented Jul 20, 2020

jiasli Dec 23, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

xiangyan99 Jul 2, 2020 •

edited

Loading

xiangyan99 Jul 2, 2020 •

edited

Loading

jiasli Dec 23, 2020 •

edited

Loading