[Identity] Improving DefaultAzureCredential diagnosability (#16844)

This PR aims to improve the diagnosability of the `DefaultAzureCredential` (and the `ChainedTokenCredential`) by aggregating all the errors that might have occurred on the credential chain during `GetToken` calls into a single message provided via logs and errors if the chain is finally unable to retrieve a token. Note: On #15923 it was mentioned to link to the troubleshooting guide on these aggregated errors, but it really makes the most sense on the underlying errors. I have made a separate issue to track that effort https://github.com/Azure/azure-sdk-for-go/issues/16843 Fixed #15923
2022-01-28 21:09:41 -05:00 · 2022-01-28 21:09:41 -05:00 · 5a344195de
--- a/sdk/azidentity/CHANGELOG.md
+++ b/sdk/azidentity/CHANGELOG.md
@ -10,6 +10,9 @@

 ### Other Changes

+* Improved the diagnosability of the `DefaultAzureCredential` by logging failures by credentials when at least one credential succeeded at initialization.
+* Improved the diagnosability of the `DefaultAzureCredential` and `ChainedTokenCredential` aggregating all the errors that might have occurred on the credential chain during `GetToken` calls into a single message provided via logs and errors if the chain is finally unable to retrieve a token.
+
 ## 0.13.0 (2022-01-11)

 ### Breaking Changes
--- a/sdk/azidentity/chained_token_credential.go
+++ b/sdk/azidentity/chained_token_credential.go
@ -7,9 +7,11 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"strings"

 	"github.com/Azure/azure-sdk-for-go/sdk/azcore"
 	"github.com/Azure/azure-sdk-for-go/sdk/azcore/policy"
+	"github.com/Azure/azure-sdk-for-go/sdk/internal/log"
 )

 // ChainedTokenCredentialOptions contains optional parameters for ChainedTokenCredential.
@ -28,6 +30,7 @@ type ChainedTokenCredential struct {
 	sources              []azcore.TokenCredential
 	successfulCredential azcore.TokenCredential
 	retrySources         bool
+	name                 string
 }

 // NewChainedTokenCredential creates a ChainedTokenCredential.
@ -47,7 +50,7 @@ func NewChainedTokenCredential(sources []azcore.TokenCredential, options *Chaine
 	if options == nil {
 		options = &ChainedTokenCredentialOptions{}
 	}
-	return &ChainedTokenCredential{sources: cp, retrySources: options.RetrySources}, nil
+	return &ChainedTokenCredential{sources: cp, name: "ChainedTokenCredential", retrySources: options.RetrySources}, nil
 }

 // GetToken calls GetToken on the chained credentials in turn, stopping when one returns a token. This method is called automatically by Azure SDK clients.
@ -66,32 +69,36 @@ func (c *ChainedTokenCredential) GetToken(ctx context.Context, opts policy.Token
 		} else if err != nil {
 			var authFailed AuthenticationFailedError
 			if errors.As(err, &authFailed) {
-				err = fmt.Errorf("Authentication failed:\n%s\n%s"+createChainedErrorMessage(errList), err)
+				err = fmt.Errorf("%s: %s\n\t%s", c.name, createChainedErrorMessage(errList), err)
 				authErr := newAuthenticationFailedError(err, authFailed.RawResponse)
 				return nil, authErr
 			}
 			return nil, err
 		} else {
-			logGetTokenSuccess(c, opts)
+			log.Writef(EventAuthentication, "Azure Identity => %s authenticated with %s", c.name, extractCredentialName(cred))
 			c.successfulCredential = cred
 			return token, nil
 		}
 	}

 	// if we reach this point it means that all of the credentials in the chain returned CredentialUnavailableError
-	credErr := newCredentialUnavailableError("Chained Token Credential", createChainedErrorMessage(errList))
-	// skip adding the stack trace here as it was already logged by other calls to GetToken()
-	addGetTokenFailureLogs("Chained Token Credential", credErr, false)
+	credErr := newCredentialUnavailableError(c.name, createChainedErrorMessage(errList))
+
+	log.Writef(EventAuthentication, "Azure Identity => ERROR in GetToken() call for %s", credErr.Error())
+
 	return nil, credErr
 }

 func createChainedErrorMessage(errList []credentialUnavailableError) string {
-	msg := ""
+	msg := "failed to acquire a token.\nAttempted credentials:\n"
 	for _, err := range errList {
-		msg += err.Error()
+		msg += fmt.Sprintf("\t%s\n", err.Error())
 	}
+	return msg[0 : len(msg)-1]
+}

-	return msg
+func extractCredentialName(credential azcore.TokenCredential) string {
+	return strings.TrimPrefix(fmt.Sprintf("%T", credential), "*azidentity.")
 }

 var _ azcore.TokenCredential = (*ChainedTokenCredential)(nil)
--- a/sdk/azidentity/chained_token_credential_test.go
+++ b/sdk/azidentity/chained_token_credential_test.go
@ -29,7 +29,7 @@ func TestChainedTokenCredential_InstantiateSuccess(t *testing.T) {
 	}
 	cred, err := NewChainedTokenCredential([]azcore.TokenCredential{secCred, envCred}, nil)
 	if err != nil {
-		t.Fatalf("unexpected error: %v", err)
+		t.Fatal(err)
 	}
 	if cred != nil {
 		if len(cred.sources) != 2 {
@ -74,7 +74,7 @@ func TestChainedTokenCredential_GetTokenSuccess(t *testing.T) {
 	}
 	cred, err := NewChainedTokenCredential([]azcore.TokenCredential{secCred, envCred}, nil)
 	if err != nil {
-		t.Fatalf("unexpected error: %v", err)
+		t.Fatal(err)
 	}
 	tk, err := cred.GetToken(context.Background(), policy.TokenRequestOptions{Scopes: []string{liveTestScope}})
 	if err != nil {
@ -98,7 +98,7 @@ func TestChainedTokenCredential_GetTokenFail(t *testing.T) {
 	}
 	cred, err := NewChainedTokenCredential([]azcore.TokenCredential{secCred}, nil)
 	if err != nil {
-		t.Fatalf("unexpected error: %v", err)
+		t.Fatal(err)
 	}
 	_, err = cred.GetToken(context.Background(), policy.TokenRequestOptions{Scopes: []string{liveTestScope}})
 	if err == nil {
@ -113,6 +113,95 @@ func TestChainedTokenCredential_GetTokenFail(t *testing.T) {
 	}
 }

+func TestChainedTokenCredential_MultipleCredentialsGetTokenUnavailable(t *testing.T) {
+	credential1 := &TestCredential{responses: []testCredentialResponse{
+		{err: newCredentialUnavailableError("unavailableCredential1", "Unavailable expected error")},
+	}}
+	credential2 := &TestCredential{responses: []testCredentialResponse{
+		{err: newCredentialUnavailableError("unavailableCredential2", "Unavailable expected error")},
+	}}
+	credential3 := &TestCredential{responses: []testCredentialResponse{
+		{err: newCredentialUnavailableError("unavailableCredential3", "Unavailable expected error")},
+	}}
+	cred, err := NewChainedTokenCredential([]azcore.TokenCredential{credential1, credential2, credential3}, nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+	_, err = cred.GetToken(context.Background(), policy.TokenRequestOptions{Scopes: []string{liveTestScope}})
+	if err == nil {
+		t.Fatalf("Expected an error but did not receive one")
+	}
+	var authErr credentialUnavailableError
+	if !errors.As(err, &authErr) {
+		t.Fatalf("Expected CredentialUnavailableError, received %T", err)
+	}
+	expectedError := `ChainedTokenCredential: failed to acquire a token.
+Attempted credentials:
+	unavailableCredential1: Unavailable expected error
+	unavailableCredential2: Unavailable expected error
+	unavailableCredential3: Unavailable expected error`
+	if err.Error() != expectedError {
+		t.Fatalf("Did not create an appropriate error message.\n\nReceived:\n%s\n\nExpected:\n%s", err.Error(), expectedError)
+	}
+}
+
+func TestChainedTokenCredential_MultipleCredentialsGetTokenAuthenticationFailed(t *testing.T) {
+	credential1 := &TestCredential{responses: []testCredentialResponse{
+		{err: newCredentialUnavailableError("unavailableCredential1", "Unavailable expected error")},
+	}}
+	credential2 := &TestCredential{responses: []testCredentialResponse{
+		{err: newCredentialUnavailableError("unavailableCredential2", "Unavailable expected error")},
+	}}
+	credential3 := &TestCredential{responses: []testCredentialResponse{
+		{err: newAuthenticationFailedError(newCredentialUnavailableError("authenticationFailedCredential3", "Authentication failed expected error"), nil)},
+	}}
+	cred, err := NewChainedTokenCredential([]azcore.TokenCredential{credential1, credential2, credential3}, nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+	_, err = cred.GetToken(context.Background(), policy.TokenRequestOptions{Scopes: []string{liveTestScope}})
+	if err == nil {
+		t.Fatalf("Expected an error but did not receive one")
+	}
+	var authErr AuthenticationFailedError
+	if !errors.As(err, &authErr) {
+		t.Fatalf("Expected AuthenticationFailedError, received %T", err)
+	}
+	expectedError := `ChainedTokenCredential: failed to acquire a token.
+Attempted credentials:
+	unavailableCredential1: Unavailable expected error
+	unavailableCredential2: Unavailable expected error
+	authenticationFailedCredential3: Authentication failed expected error`
+	if err.Error() != expectedError {
+		t.Fatalf("Did not create an appropriate error message.\n\nReceived:\n%s\n\nExpected:\n%s", err.Error(), expectedError)
+	}
+}
+
+func TestChainedTokenCredential_MultipleCredentialsGetTokenCustomName(t *testing.T) {
+	credential1 := &TestCredential{responses: []testCredentialResponse{
+		{err: newCredentialUnavailableError("unavailableCredential1", "Unavailable expected error")},
+	}}
+	cred, err := NewChainedTokenCredential([]azcore.TokenCredential{credential1}, nil)
+	if err != nil {
+		t.Fatal(err)
+	}
+	cred.name = "CustomNameCredential"
+	_, err = cred.GetToken(context.Background(), policy.TokenRequestOptions{Scopes: []string{liveTestScope}})
+	if err == nil {
+		t.Fatalf("Expected an error but did not receive one")
+	}
+	var authErr credentialUnavailableError
+	if !errors.As(err, &authErr) {
+		t.Fatalf("Expected credentialUnavailableError, received %T", err)
+	}
+	expectedError := `CustomNameCredential: failed to acquire a token.
+Attempted credentials:
+	unavailableCredential1: Unavailable expected error`
+	if err.Error() != expectedError {
+		t.Fatalf("Did not create an appropriate error message.\n\nReceived:\n%s\n\nExpected:\n%s", err.Error(), expectedError)
+	}
+}
+
 // TestCredential response
 type testCredentialResponse struct {
 	token *azcore.AccessToken
@ -156,7 +245,7 @@ func TestChainedTokenCredential_RepeatedGetTokenWithSuccessfulCredential(t *test

 	cred, err := NewChainedTokenCredential([]azcore.TokenCredential{failedCredential, successfulCredential}, nil)
 	if err != nil {
-		t.Fatalf("unexpected error: %v", err)
+		t.Fatal(err)
 	}

 	getTokenOptions := policy.TokenRequestOptions{Scopes: []string{liveTestScope}}
@ -191,7 +280,7 @@ func TestChainedTokenCredential_RepeatedGetTokenWithSuccessfulCredentialWithRetr

 	cred, err := NewChainedTokenCredential([]azcore.TokenCredential{failedCredential, successfulCredential}, &ChainedTokenCredentialOptions{RetrySources: true})
 	if err != nil {
-		t.Fatalf("unexpected error: %v", err)
+		t.Fatal(err)
 	}

 	getTokenOptions := policy.TokenRequestOptions{Scopes: []string{liveTestScope}}
--- a/sdk/azidentity/default_azure_credential.go
+++ b/sdk/azidentity/default_azure_credential.go
@ -6,10 +6,13 @@ package azidentity
 import (
 	"context"
 	"errors"
+	"fmt"
+	"strings"
 	"time"

 	"github.com/Azure/azure-sdk-for-go/sdk/azcore"
 	"github.com/Azure/azure-sdk-for-go/sdk/azcore/policy"
+	"github.com/Azure/azure-sdk-for-go/sdk/internal/log"
 )

 // DefaultAzureCredentialOptions contains optional parameters for DefaultAzureCredential.
@ -39,7 +42,7 @@ type DefaultAzureCredential struct {
 // NewDefaultAzureCredential creates a DefaultAzureCredential.
 func NewDefaultAzureCredential(options *DefaultAzureCredentialOptions) (*DefaultAzureCredential, error) {
 	var creds []azcore.TokenCredential
-	errMsg := ""
+	var errorMessages []string

 	if options == nil {
 		options = &DefaultAzureCredentialOptions{}
@ -51,7 +54,7 @@ func NewDefaultAzureCredential(options *DefaultAzureCredentialOptions) (*Default
 	if err == nil {
 		creds = append(creds, envCred)
 	} else {
-		errMsg += err.Error()
+		errorMessages = append(errorMessages, fmt.Sprintf("EnvironmentCredential: %s", err.Error()))
 	}

 	msiCred, err := NewManagedIdentityCredential(&ManagedIdentityCredentialOptions{ClientOptions: options.ClientOptions})
@ -59,25 +62,26 @@ func NewDefaultAzureCredential(options *DefaultAzureCredentialOptions) (*Default
 		creds = append(creds, msiCred)
 		msiCred.client.imdsTimeout = time.Second
 	} else {
-		errMsg += err.Error()
+		errorMessages = append(errorMessages, fmt.Sprintf("ManagedIdentityCredential: %s", err.Error()))
 	}

 	cliCred, err := NewAzureCLICredential(&AzureCLICredentialOptions{TenantID: options.TenantID})
 	if err == nil {
 		creds = append(creds, cliCred)
 	} else {
-		errMsg += err.Error()
+		errorMessages = append(errorMessages, fmt.Sprintf("AzureCLICredential: %s", err.Error()))
 	}

-	if len(creds) == 0 {
-		err := errors.New(errMsg)
-		logCredentialError("Default Azure Credential", err)
+	err = defaultAzureCredentialConstructorErrorHandler(len(creds), errorMessages)
+	if err != nil {
 		return nil, err
 	}
+
 	chain, err := NewChainedTokenCredential(creds, nil)
 	if err != nil {
 		return nil, err
 	}
+	chain.name = "DefaultAzureCredential"
 	return &DefaultAzureCredential{chain: chain}, nil
 }

@ -87,3 +91,19 @@ func NewDefaultAzureCredential(options *DefaultAzureCredentialOptions) (*Default
 func (c *DefaultAzureCredential) GetToken(ctx context.Context, opts policy.TokenRequestOptions) (token *azcore.AccessToken, err error) {
 	return c.chain.GetToken(ctx, opts)
 }
+
+func defaultAzureCredentialConstructorErrorHandler(numberOfSuccessfulCredentials int, errorMessages []string) (err error) {
+	errorMessage := strings.Join(errorMessages, "\n\t")
+
+	if numberOfSuccessfulCredentials == 0 {
+		err := errors.New(errorMessage)
+		log.Writef(EventAuthentication, "Azure Identity => Failed to initialize the Default Azure Credential:\n\t%s", err.Error())
+		return err
+	}
+
+	if len(errorMessages) != 0 {
+		log.Writef(EventAuthentication, "Azure Identity => Failed to initialize some credentials on the Default Azure Credential:\n\t%s", errorMessage)
+	}
+
+	return nil
+}
--- a/sdk/azidentity/default_azure_credential_test.go
+++ b/sdk/azidentity/default_azure_credential_test.go
@ -5,9 +5,11 @@ package azidentity

 import (
 	"context"
+	"os"
 	"testing"

 	"github.com/Azure/azure-sdk-for-go/sdk/azcore/policy"
+	"github.com/Azure/azure-sdk-for-go/sdk/internal/log"
 )

 func TestDefaultAzureCredential_GetTokenSuccess(t *testing.T) {
@ -24,3 +26,64 @@ func TestDefaultAzureCredential_GetTokenSuccess(t *testing.T) {
 		t.Fatalf("GetToken error: %v", err)
 	}
 }
+
+func TestDefaultAzureCredential_defaultAzureCredentialConstructorErrorHandlerNoSuccessfulCredential(t *testing.T) {
+	err := os.Setenv("AZURE_SDK_GO_LOGGING", "all")
+	if err != nil {
+		t.Fatal("Unexpected error", err.Error())
+	}
+
+	logMessages := []string{}
+	log.SetListener(func(event log.Event, message string) {
+		logMessages = append(logMessages, message)
+	})
+
+	errorMessages := []string{
+		"<credential-name>: <error-message>",
+		"<credential-name>: <error-message>",
+	}
+	err = defaultAzureCredentialConstructorErrorHandler(0, errorMessages)
+	if err == nil {
+		t.Fatalf("Expected an error, but received none.")
+	}
+	expectedError := `<credential-name>: <error-message>
+	<credential-name>: <error-message>`
+	if err.Error() != expectedError {
+		t.Fatalf("Did not create an appropriate error message.\n\nReceived:\n%s\n\nExpected:\n%s", err.Error(), expectedError)
+	}
+
+	expectedLogs := `Azure Identity => Failed to initialize the Default Azure Credential:
+	<credential-name>: <error-message>
+	<credential-name>: <error-message>`
+	if logMessages[0] != expectedLogs {
+		t.Fatalf("Did not receive the expected logs.\n\nReceived:\n%s\n\nExpected:\n%s", logMessages[0], expectedLogs)
+	}
+}
+
+func TestDefaultAzureCredential_defaultAzureCredentialConstructorErrorHandlerOneSuccessfulCredential(t *testing.T) {
+	err := os.Setenv("AZURE_SDK_GO_LOGGING", "all")
+	if err != nil {
+		t.Fatal("Unexpected error", err.Error())
+	}
+
+	logMessages := []string{}
+	log.SetListener(func(event log.Event, message string) {
+		logMessages = append(logMessages, message)
+	})
+
+	errorMessages := []string{
+		"<credential-name>: <error-message>",
+		"<credential-name>: <error-message>",
+	}
+	err = defaultAzureCredentialConstructorErrorHandler(1, errorMessages)
+	if err != nil {
+		t.Fatal("Unexpected error", err.Error())
+	}
+
+	expectedLogs := `Azure Identity => Failed to initialize some credentials on the Default Azure Credential:
+	<credential-name>: <error-message>
+	<credential-name>: <error-message>`
+	if logMessages[0] != expectedLogs {
+		t.Fatalf("Did not receive the expected logs.\n\nReceived:\n%s\n\nExpected:\n%s", logMessages[0], expectedLogs)
+	}
+}