diff --git a/cli/azd/docs/environment-variables.md b/cli/azd/docs/environment-variables.md index f85fcdc540f..9a237d3a4af 100644 --- a/cli/azd/docs/environment-variables.md +++ b/cli/azd/docs/environment-variables.md @@ -214,6 +214,7 @@ These variables are used by the Terraform provider integration to authenticate w | `AZD_DEBUG` | If true, enables debug mode. | | `AZD_DEBUG_LOG` | If true, enables debug-level logging. | | `AZD_DEBUG_TELEMETRY` | If true, enables debug-level telemetry output. | +| `AZD_DEBUG_MSAL_CACHE` | If true, logs MSAL cache metadata before and after login and around the first silent token acquisitions, including account identifiers and usernames, while hashing cache keys and token secrets. | | `AZD_DEBUG_LOGIN_FORCE_SUBSCRIPTION_REFRESH` | If true, forces a refresh of the subscription list on login. | | `AZD_DEBUG_SYNTHETIC_SUBSCRIPTION` | If set, provides a synthetic subscription for testing. | | `AZD_DEBUG_NO_ALPHA_WARNINGS` | If true, suppresses alpha feature warnings. | diff --git a/cli/azd/pkg/account/credentials.go b/cli/azd/pkg/account/credentials.go index 6baf2b5d5c5..e44f82f8e6f 100644 --- a/cli/azd/pkg/account/credentials.go +++ b/cli/azd/pkg/account/credentials.go @@ -8,6 +8,7 @@ import ( "errors" "fmt" "regexp" + "strings" "github.com/Azure/azure-sdk-for-go/sdk/azcore" "github.com/azure/azure-dev/cli/azd/internal" @@ -65,29 +66,49 @@ func (p *subscriptionCredentialProvider) CredentialForSubscription( if err != nil { // If this is an AADSTS refresh token error, enhance it with tenant-specific login guidance if aadRefreshTokenExpiredRegex.MatchString(err.Error()) { + message := fmt.Sprintf( + "Access to tenant '%s' requires re-authentication before azd can use this subscription.", + tenantId, + ) + // Check if the error already has a suggestion (ErrorWithSuggestion from auth layer) if errWithSuggestion, ok := errors.AsType[*internal.ErrorWithSuggestion](err); ok { - // Enhance the existing suggestion with tenant-specific guidance - enhancedSuggestion := fmt.Sprintf( - "%s To re-authenticate specifically to this tenant, run `azd auth login --tenant-id %s`.", - errWithSuggestion.Suggestion, - tenantId, - ) + if errWithSuggestion.Message != "" { + message = errWithSuggestion.Message + } + + suggestion := strings.TrimSpace(errWithSuggestion.Suggestion) + // If the auth layer's suggestion doesn't already include --tenant-id, + // append tenant-specific login guidance. + if !strings.Contains(suggestion, "--tenant-id") { + tenantHint := fmt.Sprintf( + "Run `azd auth login --tenant-id %s` to re-authenticate to this tenant.", + tenantId, + ) + if suggestion != "" { + suggestion = fmt.Sprintf("%s %s", suggestion, tenantHint) + } else { + suggestion = tenantHint + } + } + return nil, &internal.ErrorWithSuggestion{ Err: errWithSuggestion.Err, - Suggestion: enhancedSuggestion, + Message: message, + Suggestion: suggestion, + Links: errWithSuggestion.Links, } } // If it's not wrapped yet, create a new ErrorWithSuggestion + tenantSpecificSuggestion := fmt.Sprintf( + "Run `azd auth login --tenant-id %s` to re-authenticate to this tenant.", + tenantId, + ) return nil, &internal.ErrorWithSuggestion{ - Err: err, - Suggestion: fmt.Sprintf( - "Access to tenant '%s' has expired or requires re-authentication. "+ - "Run `azd auth login --tenant-id %s` to re-authenticate to this tenant.", - tenantId, - tenantId, - ), + Err: err, + Message: message, + Suggestion: tenantSpecificSuggestion, } } return nil, err diff --git a/cli/azd/pkg/account/credentials_test.go b/cli/azd/pkg/account/credentials_test.go index c99eefdedf3..a4d6c716c10 100644 --- a/cli/azd/pkg/account/credentials_test.go +++ b/cli/azd/pkg/account/credentials_test.go @@ -6,6 +6,8 @@ package account import ( "context" "errors" + "fmt" + "strings" "testing" "time" @@ -13,6 +15,7 @@ import ( "github.com/Azure/azure-sdk-for-go/sdk/azcore/policy" "github.com/azure/azure-dev/cli/azd/internal" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) func TestSubscriptionCredentialProvider(t *testing.T) { @@ -55,17 +58,17 @@ func TestSubscriptionCredentialProvider(t *testing.T) { ) t.Run("Success", func(t *testing.T) { - cred1, err := provider.CredentialForSubscription(context.Background(), sub1) + cred1, err := provider.CredentialForSubscription(t.Context(), sub1) assert.NoError(t, err) assert.Equal(t, tenantToCred[tenant1], cred1) - cred2, err := provider.CredentialForSubscription(context.Background(), sub2) + cred2, err := provider.CredentialForSubscription(t.Context(), sub2) assert.NoError(t, err) assert.Equal(t, tenantToCred[tenant2], cred2) }) t.Run("Failure", func(t *testing.T) { - _, err := provider.CredentialForSubscription(context.Background(), "11111111-1111-1111-1111-111111111111") + _, err := provider.CredentialForSubscription(t.Context(), "11111111-1111-1111-1111-111111111111") assert.Error(t, err) }) } @@ -90,7 +93,7 @@ func TestSubscriptionCredentialProvider_AADSTSErrors(t *testing.T) { }), ) - _, err := provider.CredentialForSubscription(context.Background(), subscriptionId) + _, err := provider.CredentialForSubscription(t.Context(), subscriptionId) assert.Error(t, err) // The error should be wrapped in an ErrorWithSuggestion @@ -100,6 +103,7 @@ func TestSubscriptionCredentialProvider_AADSTSErrors(t *testing.T) { // Check that the suggestion includes tenant-specific guidance assert.Contains(t, errWithSuggestion.Suggestion, tenantId) assert.Contains(t, errWithSuggestion.Suggestion, "azd auth login --tenant-id") + assert.Contains(t, errWithSuggestion.Message, tenantId) // The underlying error should contain AADSTS70043 assert.Contains(t, errWithSuggestion.Error(), "AADSTS70043") @@ -119,7 +123,7 @@ func TestSubscriptionCredentialProvider_AADSTSErrors(t *testing.T) { }), ) - _, err := provider.CredentialForSubscription(context.Background(), subscriptionId) + _, err := provider.CredentialForSubscription(t.Context(), subscriptionId) assert.Error(t, err) // The error should be wrapped in an ErrorWithSuggestion @@ -129,11 +133,68 @@ func TestSubscriptionCredentialProvider_AADSTSErrors(t *testing.T) { // Check that the suggestion includes tenant-specific guidance assert.Contains(t, errWithSuggestion.Suggestion, tenantId) assert.Contains(t, errWithSuggestion.Suggestion, "azd auth login --tenant-id") + assert.Contains(t, errWithSuggestion.Message, tenantId) // The underlying error should contain AADSTS700082 assert.Contains(t, errWithSuggestion.Error(), "AADSTS700082") }) + t.Run("AADSTS700082_WithExistingSuggestion_PreservesWrappedFields", func(t *testing.T) { + provider := NewSubscriptionCredentialProvider( + subscriptionResolverFunc(func(ctx context.Context, subId string) (*Subscription, error) { + return &Subscription{ + Id: subId, + TenantId: "resource-" + tenantId, + UserAccessTenantId: tenantId, + }, nil + }), + multiTenantCredentialProviderFunc(func(ctx context.Context, tid string) (azcore.TokenCredential, error) { + return nil, &internal.ErrorWithSuggestion{ + Err: errors.New("AADSTS700082: The refresh token has expired"), + Message: "Login expired for the current account.", + Suggestion: "Run `azd auth login` to acquire a new token.", + } + }), + ) + + _, err := provider.CredentialForSubscription(t.Context(), subscriptionId) + assert.Error(t, err) + + errWithSuggestion, ok := errors.AsType[*internal.ErrorWithSuggestion](err) + assert.True(t, ok, "error should be wrapped in ErrorWithSuggestion") + assert.Equal(t, "Login expired for the current account.", errWithSuggestion.Message) + assert.Contains(t, errWithSuggestion.Suggestion, "Run `azd auth login` to acquire a new token.") + assert.Contains(t, errWithSuggestion.Suggestion, tenantId) + }) + + t.Run("AADSTS700082_SuggestionAlreadyHasTenantID_NoRedundantAppend", func(t *testing.T) { + provider := NewSubscriptionCredentialProvider( + subscriptionResolverFunc(func(ctx context.Context, subId string) (*Subscription, error) { + return &Subscription{ + Id: subId, + TenantId: "resource-" + tenantId, + UserAccessTenantId: tenantId, + }, nil + }), + multiTenantCredentialProviderFunc(func(ctx context.Context, tid string) (azcore.TokenCredential, error) { + return nil, &internal.ErrorWithSuggestion{ + Err: errors.New("AADSTS700082: The refresh token has expired"), + Message: "Login expired for the current account.", + Suggestion: fmt.Sprintf( + "login expired, run `azd auth login --tenant-id %s` to acquire a new token.", tenantId), + } + }), + ) + + _, err := provider.CredentialForSubscription(t.Context(), subscriptionId) + assert.Error(t, err) + + errWithSuggestion, ok := errors.AsType[*internal.ErrorWithSuggestion](err) + require.True(t, ok) + // Should NOT duplicate the --tenant-id guidance + assert.Equal(t, 1, strings.Count(errWithSuggestion.Suggestion, "--tenant-id")) + }) + t.Run("TenantLookupFailure_EnhancedError", func(t *testing.T) { provider := NewSubscriptionCredentialProvider( subscriptionResolverFunc(func(ctx context.Context, subId string) (*Subscription, error) { @@ -144,7 +205,7 @@ func TestSubscriptionCredentialProvider_AADSTSErrors(t *testing.T) { }), ) - _, err := provider.CredentialForSubscription(context.Background(), subscriptionId) + _, err := provider.CredentialForSubscription(t.Context(), subscriptionId) assert.Error(t, err) assert.Contains(t, err.Error(), "AZURE_TENANT_ID") assert.Contains(t, err.Error(), "manually set the subscription ID") diff --git a/cli/azd/pkg/auth/additional_coverage_test.go b/cli/azd/pkg/auth/additional_coverage_test.go index 8f81b900dfe..a6a4153319b 100644 --- a/cli/azd/pkg/auth/additional_coverage_test.go +++ b/cli/azd/pkg/auth/additional_coverage_test.go @@ -30,7 +30,7 @@ func TestAzdCredential_GetToken_Success(t *testing.T) { account := public.Account{HomeAccountID: "h1"} cred := newAzdCredential( - pc, &account, cloud.AzurePublic(), "", + pc, &account, cloud.AzurePublic(), "", nil, ) tok, err := cred.GetToken(t.Context(), policy.TokenRequestOptions{ @@ -51,7 +51,7 @@ func TestAzdCredential_GetToken_WithTenantID(t *testing.T) { account := public.Account{HomeAccountID: "h1"} cred := newAzdCredential( - pc, &account, cloud.AzurePublic(), "default-t", + pc, &account, cloud.AzurePublic(), "default-t", nil, ) // Override with request-level tenant @@ -70,7 +70,7 @@ func TestAzdCredential_GetToken_GenericError(t *testing.T) { account := public.Account{HomeAccountID: "h1"} cred := newAzdCredential( - pc, &account, cloud.AzurePublic(), "", + pc, &account, cloud.AzurePublic(), "", nil, ) _, err := cred.GetToken(t.Context(), policy.TokenRequestOptions{ @@ -90,7 +90,7 @@ func TestAzdCredential_GetToken_AuthFailedNotReLogin(t *testing.T) { account := public.Account{HomeAccountID: "h1"} cred := newAzdCredential( - pc, &account, cloud.AzurePublic(), "", + pc, &account, cloud.AzurePublic(), "", nil, ) _, err := cred.GetToken(t.Context(), policy.TokenRequestOptions{ diff --git a/cli/azd/pkg/auth/azd_credential.go b/cli/azd/pkg/auth/azd_credential.go index 9bf8789f4cc..5a125fa0956 100644 --- a/cli/azd/pkg/auth/azd_credential.go +++ b/cli/azd/pkg/auth/azd_credential.go @@ -16,23 +16,29 @@ import ( ) type azdCredential struct { - client publicClient - account *public.Account - cloud *cloud.Cloud - tenantID string + client publicClient + account *public.Account + cloud *cloud.Cloud + tenantID string + cacheTracer *msalCacheTracer } // newAzdCredential creates a credential that acquires tokens via MSAL's public client. // tenantID, when non-empty, is forwarded to AcquireTokenSilent so MSAL issues tokens // for that specific tenant instead of defaulting to the account's home tenant. func newAzdCredential( - client publicClient, account *public.Account, cloud *cloud.Cloud, tenantID string, + client publicClient, + account *public.Account, + cloud *cloud.Cloud, + tenantID string, + cacheTracer *msalCacheTracer, ) *azdCredential { return &azdCredential{ - client: client, - account: account, - cloud: cloud, - tenantID: tenantID, + client: client, + account: account, + cloud: cloud, + tenantID: tenantID, + cacheTracer: cacheTracer, } } @@ -57,11 +63,19 @@ func (c *azdCredential) GetToken(ctx context.Context, options policy.TokenReques silentOpts = append(silentOpts, public.WithTenantID(tenantID)) } - res, err := c.client.AcquireTokenSilent(ctx, options.Scopes, silentOpts...) + phase := "after-first-acquire-token-silent" + failurePhase := "after-first-acquire-token-silent-failure" + if tenantID != "" { + phase = "after-first-tenant-acquire-token-silent" + failurePhase = "after-first-tenant-acquire-token-silent-failure" + } + res, err := c.client.AcquireTokenSilent(ctx, options.Scopes, silentOpts...) if err != nil { + c.cacheTracer.LogSnapshotOnce(failurePhase) + if authFailed, ok := errors.AsType[*AuthFailedError](err); ok { - if loginErr, ok := newReLoginRequiredError(authFailed.Parsed, options.Scopes, c.cloud); ok { + if loginErr, ok := newReLoginRequiredError(authFailed.Parsed, options.Scopes, c.cloud, tenantID); ok { log.Println(authFailed.httpErrorDetails()) if options.Claims != "" { @@ -79,6 +93,8 @@ func (c *azdCredential) GetToken(ctx context.Context, options policy.TokenReques return azcore.AccessToken{}, err } + c.cacheTracer.LogSnapshotOnce(phase) + return azcore.AccessToken{ Token: res.AccessToken, ExpiresOn: res.ExpiresOn.UTC(), diff --git a/cli/azd/pkg/auth/azd_credential_test.go b/cli/azd/pkg/auth/azd_credential_test.go index 339b087be78..4f29f4f0fcd 100644 --- a/cli/azd/pkg/auth/azd_credential_test.go +++ b/cli/azd/pkg/auth/azd_credential_test.go @@ -4,7 +4,11 @@ package auth import ( + "bytes" "context" + "errors" + "log" + "strings" "testing" "time" @@ -14,6 +18,26 @@ import ( "github.com/stretchr/testify/require" ) +type sequentialSilentClient struct { + mockPublicClient + results []struct { + result public.AuthResult + err error + } + calls int +} + +func (s *sequentialSilentClient) AcquireTokenSilent( + _ context.Context, + _ []string, + _ ...public.AcquireSilentOption, +) (public.AuthResult, error) { + step := s.results[s.calls] + s.calls++ + + return step.result, step.err +} + // spyPublicClient records the options passed to AcquireTokenSilent so tests can // verify that GetToken forwards TenantID correctly. type spyPublicClient struct { @@ -72,7 +96,7 @@ func TestAzdCredential_GetToken_ForwardsTenantID(t *testing.T) { t.Run(tt.name, func(t *testing.T) { spy := &spyPublicClient{} account := &public.Account{HomeAccountID: "test.id"} - cred := newAzdCredential(spy, account, cloud.AzurePublic(), tt.credTID) + cred := newAzdCredential(spy, account, cloud.AzurePublic(), tt.credTID, nil) _, err := cred.GetToken(t.Context(), policy.TokenRequestOptions{ Scopes: []string{"https://graph.microsoft.com/.default"}, @@ -101,3 +125,90 @@ func TestAzdCredential_GetToken_ForwardsTenantID(t *testing.T) { }) } } + +func TestAzdCredential_GetToken_LogsSuccessSnapshotAfterFailure(t *testing.T) { + t.Setenv(azdDebugMsalCacheEnv, "true") + + cacheJSON := []byte(`{ + "RefreshToken": { + "rt-key": { + "home_account_id": "home-1", + "environment": "login.microsoftonline.com", + "client_id": "client-1", + "family_id": "", + "secret": "super-secret-refresh-token" + } + }, + "AccessToken": { + "at-key": { + "home_account_id": "home-1", + "realm": "tenant-1", + "cached_at": 100, + "expires_on": 200 + } + }, + "Account": { + "acct-key": { + "home_account_id": "home-1", + "realm": "tenant-1", + "username": "user@example.com" + } + } + }`) + + cache := &memoryCache{ + cache: map[string][]byte{currentUserCacheKey: cacheJSON}, + } + tracer := newMsalCacheTracer(cache) + + var buf bytes.Buffer + originalWriter := log.Writer() + log.SetOutput(&buf) + t.Cleanup(func() { + log.SetOutput(originalWriter) + }) + + client := &sequentialSilentClient{ + results: []struct { + result public.AuthResult + err error + }{ + {err: errors.New("temporary failure")}, + { + result: public.AuthResult{ + AccessToken: "test-token", + ExpiresOn: time.Now().Add(time.Hour), + }, + }, + }, + } + + cred := newAzdCredential( + client, + &public.Account{HomeAccountID: "test.id"}, + cloud.AzurePublic(), + "", + tracer, + ) + + _, err := cred.GetToken(t.Context(), policy.TokenRequestOptions{ + Scopes: []string{"https://graph.microsoft.com/.default"}, + }) + require.Error(t, err) + + _, err = cred.GetToken(t.Context(), policy.TokenRequestOptions{ + Scopes: []string{"https://graph.microsoft.com/.default"}, + }) + require.NoError(t, err) + + output := buf.String() + require.NotEmpty(t, output) + require.Equal(t, 1, strings.Count( + output, + "msal-cache[after-first-acquire-token-silent-failure]: refresh_tokens=1 access_tokens=1 accounts=1", + )) + require.Equal(t, 1, strings.Count( + output, + "msal-cache[after-first-acquire-token-silent]: refresh_tokens=1 access_tokens=1 accounts=1", + )) +} diff --git a/cli/azd/pkg/auth/cache_debug.go b/cli/azd/pkg/auth/cache_debug.go new file mode 100644 index 00000000000..40889d7ac22 --- /dev/null +++ b/cli/azd/pkg/auth/cache_debug.go @@ -0,0 +1,187 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +package auth + +import ( + "crypto/sha256" + "encoding/hex" + "encoding/json" + "errors" + "fmt" + "log" + "maps" + "os" + "slices" + "strconv" + "sync" +) + +const azdDebugMsalCacheEnv = "AZD_DEBUG_MSAL_CACHE" + +type msalCacheTracer struct { + cache Cache + enabled bool + + mu sync.Mutex + logged map[string]bool +} + +type rawMsalCacheContract struct { + AccessToken map[string]rawMsalAccessToken `json:"AccessToken"` + RefreshToken map[string]rawMsalRefreshToken `json:"RefreshToken"` + Account map[string]rawMsalAccount `json:"Account"` +} + +type rawMsalAccessToken struct { + HomeAccountID string `json:"home_account_id"` + Realm string `json:"realm"` + CachedAt any `json:"cached_at"` + ExpiresOn any `json:"expires_on"` +} + +type rawMsalRefreshToken struct { + HomeAccountID string `json:"home_account_id"` + Environment string `json:"environment"` + ClientID string `json:"client_id"` + FamilyID string `json:"family_id"` + Secret string `json:"secret"` +} + +type rawMsalAccount struct { + HomeAccountID string `json:"home_account_id"` + Realm string `json:"realm"` + Username string `json:"username"` +} + +func newMsalCacheTracer(cache Cache) *msalCacheTracer { + return &msalCacheTracer{ + cache: cache, + enabled: isMsalCacheTraceEnabled(), + logged: map[string]bool{}, + } +} + +func isMsalCacheTraceEnabled() bool { + value := os.Getenv(azdDebugMsalCacheEnv) + if value == "" { + return false + } + + enabled, err := strconv.ParseBool(value) + return err == nil && enabled +} + +const msalCachePIIWarning = "msal-cache: WARNING: MSAL cache tracing enabled — " + + "output contains account identifiers (e.g. email, home account ID). Do not share without redaction." + +func (t *msalCacheTracer) logPIIWarningOnce() { + const key = "_pii_warning" + t.mu.Lock() + defer t.mu.Unlock() + + if t.logged[key] { + return + } + t.logged[key] = true + log.Println(msalCachePIIWarning) +} + +func (t *msalCacheTracer) LogSnapshot(phase string) { + if t == nil || !t.enabled || phase == "" || t.cache == nil { + return + } + + t.logPIIWarningOnce() + t.logSnapshot(phase) +} + +func (t *msalCacheTracer) LogSnapshotOnce(phase string) { + if t == nil || !t.enabled || phase == "" || t.cache == nil { + return + } + + t.logPIIWarningOnce() + + t.mu.Lock() + if t.logged[phase] { + t.mu.Unlock() + return + } + t.logged[phase] = true + t.mu.Unlock() + + t.logSnapshot(phase) +} + +func (t *msalCacheTracer) logSnapshot(phase string) { + val, err := t.cache.Read(currentUserCacheKey) + if errors.Is(err, errCacheKeyNotFound) || len(val) == 0 { + log.Printf("msal-cache[%s]: refresh_tokens=0 access_tokens=0 accounts=0", phase) + return + } + if err != nil { + log.Printf("msal-cache[%s]: failed reading cache: %v", phase, err) + return + } + + var contract rawMsalCacheContract + if err := json.Unmarshal(val, &contract); err != nil { + log.Printf("msal-cache[%s]: failed parsing cache: %v", phase, err) + return + } + + log.Printf( + "msal-cache[%s]: refresh_tokens=%d access_tokens=%d accounts=%d", + phase, + len(contract.RefreshToken), + len(contract.AccessToken), + len(contract.Account), + ) + + for _, key := range slices.Sorted(maps.Keys(contract.RefreshToken)) { + rt := contract.RefreshToken[key] + log.Printf( + "msal-cache[%s]: refresh_token key_sha256=%s home_account_id=%s "+ + "environment=%s client_id=%s family_id=%s secret_sha256=%s", + phase, + shortDigest(key), + rt.HomeAccountID, + rt.Environment, + rt.ClientID, + rt.FamilyID, + shortDigest(rt.Secret), + ) + } + + for _, key := range slices.Sorted(maps.Keys(contract.AccessToken)) { + at := contract.AccessToken[key] + log.Printf( + "msal-cache[%s]: access_token key_sha256=%s home_account_id=%s realm=%s cached_at=%s expires_on=%s", + phase, + shortDigest(key), + at.HomeAccountID, + at.Realm, + fmt.Sprint(at.CachedAt), + fmt.Sprint(at.ExpiresOn), + ) + } + + for _, key := range slices.Sorted(maps.Keys(contract.Account)) { + account := contract.Account[key] + log.Printf( + "msal-cache[%s]: account key_sha256=%s home_account_id=%s realm=%s username=%s", + phase, + shortDigest(key), + account.HomeAccountID, + account.Realm, + account.Username, + ) + } +} + +// shortDigest returns the first 8 hex characters of the SHA-256 digest of s. +func shortDigest(value string) string { + sum := sha256.Sum256([]byte(value)) + return hex.EncodeToString(sum[:4]) +} diff --git a/cli/azd/pkg/auth/cache_debug_test.go b/cli/azd/pkg/auth/cache_debug_test.go new file mode 100644 index 00000000000..0cfacfde4ad --- /dev/null +++ b/cli/azd/pkg/auth/cache_debug_test.go @@ -0,0 +1,71 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +package auth + +import ( + "bytes" + "log" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestMsalCacheTracer_LogSnapshotOnce_HashesTokenSecrets(t *testing.T) { + t.Setenv(azdDebugMsalCacheEnv, "true") + + cacheJSON := []byte(`{ + "RefreshToken": { + "rt-key": { + "home_account_id": "home-1", + "environment": "login.microsoftonline.com", + "client_id": "client-1", + "family_id": "", + "secret": "super-secret-refresh-token" + } + }, + "AccessToken": { + "at-key": { + "home_account_id": "home-1", + "realm": "tenant-1", + "cached_at": 100, + "expires_on": 200 + } + }, + "Account": { + "acct-key": { + "home_account_id": "home-1", + "realm": "tenant-1", + "username": "user@example.com" + } + } + }`) + + cache := &memoryCache{ + cache: map[string][]byte{currentUserCacheKey: cacheJSON}, + } + tracer := newMsalCacheTracer(cache) + + var buf bytes.Buffer + originalWriter := log.Writer() + log.SetOutput(&buf) + t.Cleanup(func() { + log.SetOutput(originalWriter) + }) + + tracer.LogSnapshotOnce("test-phase") + tracer.LogSnapshotOnce("test-phase") + + output := buf.String() + require.NotEmpty(t, output) + assert.Contains(t, output, "msal-cache[test-phase]: refresh_tokens=1 access_tokens=1 accounts=1") + assert.Contains(t, output, shortDigest("super-secret-refresh-token")) + assert.NotContains(t, output, "super-secret-refresh-token") + assert.Equal(t, 1, strings.Count(output, "msal-cache[test-phase]: refresh_tokens=1 access_tokens=1 accounts=1")) + + // PII warning banner should appear exactly once + assert.Contains(t, output, "WARNING: MSAL cache tracing enabled") + assert.Equal(t, 1, strings.Count(output, "WARNING: MSAL cache tracing enabled")) +} diff --git a/cli/azd/pkg/auth/cache_unix.go b/cli/azd/pkg/auth/cache_unix.go index ae6af502bdf..335c582177c 100644 --- a/cli/azd/pkg/auth/cache_unix.go +++ b/cli/azd/pkg/auth/cache_unix.go @@ -9,19 +9,23 @@ import ( "github.com/AzureAD/microsoft-authentication-library-for-go/apps/cache" ) +func newMsalCacheStore(root string) Cache { + return &memoryCache{ + cache: make(map[string][]byte), + inner: &fileCache{ + prefix: "cache", + root: root, + ext: "json", + }, + } +} + // newCache creates a cache implementation that satisfies [cache.ExportReplace] from the MSAL library. // // root must be created beforehand, and must point to a directory. func newCache(root string) cache.ExportReplace { return &msalCacheAdapter{ - cache: &memoryCache{ - cache: make(map[string][]byte), - inner: &fileCache{ - prefix: "cache", - root: root, - ext: "json", - }, - }, + cache: newMsalCacheStore(root), } } diff --git a/cli/azd/pkg/auth/cache_windows.go b/cli/azd/pkg/auth/cache_windows.go index 25d548df9d4..eebcfe0ccc3 100644 --- a/cli/azd/pkg/auth/cache_windows.go +++ b/cli/azd/pkg/auth/cache_windows.go @@ -31,21 +31,25 @@ type encryptionType string // for more information on these APIs. const cryptProtectDataEncryptionType encryptionType = "CryptProtectData" -func newCache(root string) cache.ExportReplace { - return &msalCacheAdapter{ - cache: &memoryCache{ - cache: make(map[string][]byte), - inner: &encryptedCache{ - inner: &fileCache{ - prefix: "cache", - root: root, - ext: "bin", - }, +func newMsalCacheStore(root string) Cache { + return &memoryCache{ + cache: make(map[string][]byte), + inner: &encryptedCache{ + inner: &fileCache{ + prefix: "cache", + root: root, + ext: "bin", }, }, } } +func newCache(root string) cache.ExportReplace { + return &msalCacheAdapter{ + cache: newMsalCacheStore(root), + } +} + func newCredentialCache(root string) Cache { return &memoryCache{ cache: make(map[string][]byte), diff --git a/cli/azd/pkg/auth/claims_test.go b/cli/azd/pkg/auth/claims_test.go index 305f84888e2..ce737b6a394 100644 --- a/cli/azd/pkg/auth/claims_test.go +++ b/cli/azd/pkg/auth/claims_test.go @@ -12,8 +12,10 @@ import ( "net/http" "net/url" "strings" + "sync" "testing" + "github.com/azure/azure-dev/cli/azd/internal" "github.com/azure/azure-dev/cli/azd/pkg/cloud" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -271,6 +273,36 @@ func TestMemoryCache_ReadAndSet(t *testing.T) { require.NoError(t, err) assert.Equal(t, []byte("inner-val"), val) }) + + t.Run("concurrent_read_and_set", func(t *testing.T) { + // Use an inner cache to exercise the full Set path (read old → inner.Set → map write). + inner := &memoryCache{cache: map[string][]byte{}} + mc := &memoryCache{cache: map[string][]byte{}, inner: inner} + + var wg sync.WaitGroup + for i := range 8 { + writerID := i + wg.Go(func() { + for j := range 200 { + value := fmt.Appendf(nil, "value-%d-%d", writerID, j) + _ = mc.Set("shared-key", value) + _, _ = mc.Read("shared-key") + } + }) + } + + wg.Wait() + + // Both the in-memory map and the inner cache must agree. + val, err := mc.Read("shared-key") + require.NoError(t, err) + assert.NotEmpty(t, val) + + innerVal, err := inner.Read("shared-key") + require.NoError(t, err) + assert.Equal(t, val, innerVal) + }) + } // ---------- fixedMarshaller ---------- @@ -405,7 +437,7 @@ func TestNewReLoginRequiredError(t *testing.T) { t.Run("nil_response_returns_false", func(t *testing.T) { t.Parallel() err, ok := newReLoginRequiredError( - nil, nil, cloud.AzurePublic()) + nil, nil, cloud.AzurePublic(), "") assert.Nil(t, err) assert.False(t, ok) }) @@ -417,7 +449,7 @@ func TestNewReLoginRequiredError(t *testing.T) { ErrorDescription: "something else", } err, ok := newReLoginRequiredError( - resp, nil, cloud.AzurePublic()) + resp, nil, cloud.AzurePublic(), "") assert.Nil(t, err) assert.False(t, ok) }) @@ -432,6 +464,7 @@ func TestNewReLoginRequiredError(t *testing.T) { resp, []string{"https://management.azure.com//.default"}, cloud.AzurePublic(), + "", ) assert.True(t, ok) require.Error(t, err) @@ -448,6 +481,7 @@ func TestNewReLoginRequiredError(t *testing.T) { resp, []string{"https://management.azure.com//.default"}, cloud.AzurePublic(), + "", ) assert.True(t, ok) require.Error(t, err) @@ -466,6 +500,7 @@ func TestNewReLoginRequiredError(t *testing.T) { "https://graph.microsoft.com//.default", }, cloud.AzurePublic(), + "", ) assert.True(t, ok) require.Error(t, err) @@ -480,9 +515,25 @@ func TestNewReLoginRequiredError(t *testing.T) { ErrorCodes: []int{70043}, } err, ok := newReLoginRequiredError( - resp, nil, cloud.AzurePublic()) + resp, nil, cloud.AzurePublic(), "") + assert.True(t, ok) + require.Error(t, err) + }) + + t.Run("error_code_700082_sets_login_expired", func(t *testing.T) { + t.Parallel() + resp := &AadErrorResponse{ + Error: "invalid_grant", + ErrorDescription: "AADSTS700082: expired", + ErrorCodes: []int{700082}, + } + err, ok := newReLoginRequiredError(resp, nil, cloud.AzurePublic(), "") assert.True(t, ok) require.Error(t, err) + + var errWithSuggestion *internal.ErrorWithSuggestion + require.True(t, errors.As(err, &errWithSuggestion)) + assert.Contains(t, errWithSuggestion.Suggestion, "login expired") }) t.Run("error_code_50005_adds_device_code_flag", func(t *testing.T) { @@ -493,10 +544,28 @@ func TestNewReLoginRequiredError(t *testing.T) { ErrorCodes: []int{50005}, } err, ok := newReLoginRequiredError( - resp, nil, cloud.AzurePublic()) + resp, nil, cloud.AzurePublic(), "") assert.True(t, ok) require.Error(t, err) }) + + t.Run("tenant_id_included_in_suggestion", func(t *testing.T) { + t.Parallel() + resp := &AadErrorResponse{ + Error: "invalid_grant", + ErrorDescription: "AADSTS70043: expired", + ErrorCodes: []int{70043}, + } + tenantID := "72f988bf-86f1-41af-91ab-2d7cd011db47" + err, ok := newReLoginRequiredError( + resp, nil, cloud.AzurePublic(), tenantID) + assert.True(t, ok) + require.Error(t, err) + + errWithSuggestion, ok := errors.AsType[*internal.ErrorWithSuggestion](err) + require.True(t, ok) + assert.Contains(t, errWithSuggestion.Suggestion, "--tenant-id "+tenantID) + }) } // ---------- helpers ---------- diff --git a/cli/azd/pkg/auth/errors.go b/cli/azd/pkg/auth/errors.go index e447c19e12d..8655982b1ec 100644 --- a/cli/azd/pkg/auth/errors.go +++ b/cli/azd/pkg/auth/errors.go @@ -43,6 +43,7 @@ func newReLoginRequiredError( response *AadErrorResponse, scopes []string, cloud *cloud.Cloud, + tenantID string, ) (error, bool) { if response == nil { return nil, false @@ -54,7 +55,7 @@ func newReLoginRequiredError( case "invalid_grant", "interaction_required": err := ReLoginRequiredError{} - err.init(response, scopes, cloud) + err.init(response, scopes, cloud, tenantID) // Note: Do not prefix with "Suggestion:" here — the UX renderer // (ErrorWithSuggestion.ToString) already adds that prefix when displaying. suggestion := fmt.Sprintf("%s, run `%s` to acquire a new token.", err.scenario, err.loginCmd) @@ -70,11 +71,20 @@ func newReLoginRequiredError( return nil, false } -func (e *ReLoginRequiredError) init(response *AadErrorResponse, scopes []string, cloud *cloud.Cloud) { +func (e *ReLoginRequiredError) init( + response *AadErrorResponse, + scopes []string, + cloud *cloud.Cloud, + tenantID string, +) { e.errText = response.ErrorDescription e.scenario = "reauthentication required" e.loginCmd = "azd auth login" + if tenantID != "" { + e.loginCmd += fmt.Sprintf(" --tenant-id %s", tenantID) + } + loginScopes := LoginScopesFull(cloud) for _, scope := range scopes { // filter out default login scopes @@ -83,8 +93,9 @@ func (e *ReLoginRequiredError) init(response *AadErrorResponse, scopes []string, } } - // The refresh token has expired or is invalid due to sign-in frequency checks by Conditional Access. - if slices.Contains(response.ErrorCodes, 70043) { + // The refresh token has expired, either due to inactivity (700082) or due to + // sign-in frequency checks enforced by Conditional Access (70043). + if slices.Contains(response.ErrorCodes, 70043) || slices.Contains(response.ErrorCodes, 700082) { e.scenario = "login expired" } diff --git a/cli/azd/pkg/auth/errors_test.go b/cli/azd/pkg/auth/errors_test.go index eb7ea015568..38beea34ef7 100644 --- a/cli/azd/pkg/auth/errors_test.go +++ b/cli/azd/pkg/auth/errors_test.go @@ -98,7 +98,7 @@ func TestReLoginRequired(t *testing.T) { } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - _, got := newReLoginRequiredError(tt.resp, LoginScopes(cloud.AzurePublic()), cloud.AzurePublic()) + _, got := newReLoginRequiredError(tt.resp, LoginScopes(cloud.AzurePublic()), cloud.AzurePublic(), "") require.Equal(t, tt.want, got) }) } @@ -129,7 +129,7 @@ func TestReLoginRequiredError(t *testing.T) { } for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { - err, _ := newReLoginRequiredError(tt.resp, LoginScopes(cloud.AzurePublic()), cloud.AzurePublic()) + err, _ := newReLoginRequiredError(tt.resp, LoginScopes(cloud.AzurePublic()), cloud.AzurePublic(), "") got := err.Error() require.Equal(t, tt.want, got) }) diff --git a/cli/azd/pkg/auth/final_coverage_test.go b/cli/azd/pkg/auth/final_coverage_test.go index c75f57b6ec9..7059bee48a7 100644 --- a/cli/azd/pkg/auth/final_coverage_test.go +++ b/cli/azd/pkg/auth/final_coverage_test.go @@ -204,7 +204,7 @@ func TestAzdCredentialGetToken_ClaimsReLoginPath(t *testing.T) { } acct := public.Account{HomeAccountID: "home-a"} - cred := newAzdCredential(client, &acct, c, "") + cred := newAzdCredential(client, &acct, c, "", nil) opts := tokenRequestOpts(c, "my-claims") _, err := cred.GetToken(t.Context(), opts) diff --git a/cli/azd/pkg/auth/manager.go b/cli/azd/pkg/auth/manager.go index 46c2345b974..73cfcc2de8b 100644 --- a/cli/azd/pkg/auth/manager.go +++ b/cli/azd/pkg/auth/manager.go @@ -90,6 +90,7 @@ type HttpClient interface { type Manager struct { publicClient publicClient publicClientOptions []public.Option + msalCacheTracer *msalCacheTracer cloud *cloud.Cloud configManager config.FileConfigManager userConfigManager config.UserConfigManager @@ -142,9 +143,10 @@ func NewManager( } msalClient := newUserAgentClient(httpClient, string(userAgent)) + msalCache := newMsalCacheStore(cacheRoot) options := []public.Option{ - public.WithCache(newCache(cacheRoot)), + public.WithCache(&msalCacheAdapter{cache: msalCache}), public.WithAuthority(authorityUrl), public.WithHTTPClient(msalClient), } @@ -157,6 +159,7 @@ func NewManager( return &Manager{ publicClient: &msalPublicClientAdapter{client: &publicClientApp}, publicClientOptions: options, + msalCacheTracer: newMsalCacheTracer(msalCache), cloud: cloud, configManager: configManager, userConfigManager: userConfigManager, @@ -325,7 +328,13 @@ func (m *Manager) CredentialForCurrentUser( for i, account := range accounts { if account.HomeAccountID == *currentUser.HomeAccountID { if options.TenantID == "" { - return newAzdCredential(m.publicClient, &accounts[i], m.cloud, "" /* tenantID */), nil + return newAzdCredential( + m.publicClient, + &accounts[i], + m.cloud, + "", /* tenantID */ + m.msalCacheTracer, + ), nil } else { newAuthority := m.cloud.Configuration.ActiveDirectoryAuthorityHost + options.TenantID @@ -343,7 +352,11 @@ func (m *Manager) CredentialForCurrentUser( return newAzdCredential( &msalPublicClientAdapter{client: &clientWithNewTenant}, - &accounts[i], m.cloud, options.TenantID), nil + &accounts[i], + m.cloud, + options.TenantID, + m.msalCacheTracer, + ), nil } } } @@ -696,6 +709,8 @@ func (m *Manager) LoginInteractive( scopes = m.LoginScopes() } + m.msalCacheTracer.LogSnapshot("before-login-interactive") + var claimsFile string if claims == "" { c, path, err := loadClaims() @@ -734,6 +749,8 @@ func (m *Manager) LoginInteractive( return nil, err } + m.msalCacheTracer.LogSnapshot("after-login-interactive") + if err := m.saveLoginForPublicClient(res); err != nil { return nil, err } @@ -742,7 +759,13 @@ func (m *Manager) LoginInteractive( _ = os.Remove(claimsFile) } - return newAzdCredential(m.publicClient, &res.Account, m.cloud, "" /* tenantID */), nil + return newAzdCredential( + m.publicClient, + &res.Account, + m.cloud, + "", /* tenantID */ + m.msalCacheTracer, + ), nil } // LoginWithBrokerAccount logs in an account provided by the system authentication broker via OneAuth. @@ -785,6 +808,8 @@ func (m *Manager) LoginWithDeviceCode( scopes = m.LoginScopes() } + m.msalCacheTracer.LogSnapshot("before-login-device-code") + var claimsFile string if claims == "" { c, path, err := loadClaims() @@ -844,6 +869,8 @@ func (m *Manager) LoginWithDeviceCode( } m.console.Message(ctx, "Device code authentication completed.") + m.msalCacheTracer.LogSnapshot("after-login-device-code") + if err := m.saveLoginForPublicClient(res); err != nil { return nil, err } @@ -852,7 +879,13 @@ func (m *Manager) LoginWithDeviceCode( _ = os.Remove(claimsFile) } - return newAzdCredential(m.publicClient, &res.Account, m.cloud, "" /* tenantID */), nil + return newAzdCredential( + m.publicClient, + &res.Account, + m.cloud, + "", /* tenantID */ + m.msalCacheTracer, + ), nil } diff --git a/cli/azd/pkg/auth/memory_cache.go b/cli/azd/pkg/auth/memory_cache.go index a20f7dcab57..a973db05d7c 100644 --- a/cli/azd/pkg/auth/memory_cache.go +++ b/cli/azd/pkg/auth/memory_cache.go @@ -5,6 +5,7 @@ package auth import ( "bytes" + "sync" ) type fixedMarshaller struct { @@ -23,14 +24,21 @@ func (f *fixedMarshaller) Unmarshal(cache []byte) error { // memoryCache is a simple memory cache that implements Cache. During export, if the cache contents has not changed, the // inner cache is not notified of a change. type memoryCache struct { + mu sync.RWMutex cache map[string][]byte inner Cache } func (c *memoryCache) Read(key string) ([]byte, error) { - if v, has := c.cache[key]; has { + c.mu.RLock() + v, has := c.cache[key] + c.mu.RUnlock() + + if has { return v, nil - } else if c.inner != nil { + } + + if c.inner != nil { return c.inner.Read(key) } @@ -38,9 +46,10 @@ func (c *memoryCache) Read(key string) ([]byte, error) { } func (c *memoryCache) Set(key string, value []byte) error { - old := c.cache[key] + c.mu.Lock() + defer c.mu.Unlock() - if bytes.Equal(old, value) { + if bytes.Equal(c.cache[key], value) { // no change, nothing more to do. return nil }