Skip to content

Commit 7f9d14e

Browse files
erich-wangisra-fel
erich-wang
and
isra-fel
authored
Add more logs in Az.Accounts before calling into Azure.Identity (Azure#14689)
* Add more logs before calling into Azure.Identity * Fix test error Co-authored-by: Yeming Liu <[email protected]>
1 parent 4822f6b commit 7f9d14e

14 files changed

+84
-17
lines changed

‎src/Accounts/Accounts/Account/ConnectAzureRmAccount.cs

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -417,6 +417,7 @@ public override void ExecuteCmdlet()
417417
}
418418

419419
profileClient.WarningLog = (message) => _tasks.Enqueue(new Task(() => this.WriteWarning(message)));
420+
profileClient.DebugLog = (message) => _tasks.Enqueue(new Task(() => this.WriteDebugWithTimestamp(message)));
420421
var task = new Task<AzureRmProfile>( () => profileClient.Login(
421422
azureAccount,
422423
_environment,

‎src/Accounts/Accounts/Models/RMProfileClient.cs

Lines changed: 21 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@ public class RMProfileClient
3636
private IProfileOperations _profile;
3737
private IAzureTokenCache _cache;
3838
public Action<string> WarningLog;
39+
public Action<string> DebugLog;
3940

4041
private IAzureContext DefaultContext
4142
{
@@ -242,9 +243,10 @@ public AzureRmProfile Login(
242243
token = null;
243244
}
244245
}
245-
catch
246+
catch(Exception e)
246247
{
247-
WriteWarningMessage(string.Format(ProfileMessages.UnableToAqcuireToken, tenant));
248+
WriteWarningMessage(string.Format(ProfileMessages.UnableToAqcuireToken, tenant, e.Message));
249+
WriteDebugMessage(string.Format(ProfileMessages.UnableToAqcuireToken, tenant, e.ToString()));
248250
}
249251

250252
if (token != null &&
@@ -498,12 +500,13 @@ public IEnumerable<IAzureSubscription> ListSubscriptions(string tenantIdOrDomain
498500
ListAllSubscriptionsForTenant(
499501
(tenant.GetId() == Guid.Empty) ? tenant.Directory : tenant.Id.ToString()));
500502
}
501-
catch (AadAuthenticationException)
503+
catch (AadAuthenticationException e)
502504
{
503505
WriteWarningMessage(string.Format(
504506
ProfileMessages.UnableToLogin,
505507
_profile.DefaultContext.Account,
506508
tenant));
509+
WriteDebugMessage(e.ToString());
507510
}
508511

509512
}
@@ -604,6 +607,7 @@ private bool TryGetTenantSubscription(IAccessToken accessToken,
604607
if (isTenantPresent || !string.Equals(ex.Body?.Code, "InvalidAuthenticationTokenTenant", StringComparison.OrdinalIgnoreCase))
605608
{
606609
WriteWarningMessage(ex.Message);
610+
WriteDebugMessage(ex.ToString());
607611
}
608612
}
609613

@@ -652,9 +656,10 @@ private List<AzureTenant> ListAccountTenants(
652656

653657
result = SubscriptionAndTenantClient?.ListAccountTenants(commonTenantToken, environment);
654658
}
655-
catch
659+
catch(Exception e)
656660
{
657-
WriteWarningMessage(string.Format(ProfileMessages.UnableToAqcuireToken, commonTenant));
661+
WriteWarningMessage(string.Format(ProfileMessages.UnableToAqcuireToken, commonTenant, e.Message));
662+
WriteDebugMessage(string.Format(ProfileMessages.UnableToAqcuireToken, commonTenant, e.ToString()));
658663
if (account.IsPropertySet(AzureAccount.Property.Tenants))
659664
{
660665
result =
@@ -698,9 +703,10 @@ private IEnumerable<AzureSubscription> ListAllSubscriptionsForTenant(
698703
{
699704
accessToken = AcquireAccessToken(account, environment, tenantId, password, promptBehavior, null);
700705
}
701-
catch
706+
catch(Exception e)
702707
{
703-
WriteWarningMessage(string.Format(ProfileMessages.UnableToAqcuireToken, tenantId));
708+
WriteWarningMessage(string.Format(ProfileMessages.UnableToAqcuireToken, tenantId, e.Message));
709+
WriteDebugMessage(string.Format(ProfileMessages.UnableToAqcuireToken, tenantId, e.ToString()));
704710
return new List<AzureSubscription>();
705711
}
706712

@@ -715,6 +721,14 @@ private void WriteWarningMessage(string message)
715721
}
716722
}
717723

724+
private void WriteDebugMessage(string message)
725+
{
726+
if(DebugLog != null)
727+
{
728+
DebugLog(message);
729+
}
730+
}
731+
718732
public ISubscriptionClientWrapper SubscriptionAndTenantClient = null;
719733
}
720734
}

‎src/Accounts/Accounts/Properties/Resources.Designer.cs

Lines changed: 1 addition & 1 deletion
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

‎src/Accounts/Accounts/Properties/Resources.resx

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -339,7 +339,7 @@
339339
<value>To create an access token credential, you must provide an access token account.</value>
340340
</data>
341341
<data name="UnableToAqcuireToken" xml:space="preserve">
342-
<value>Unable to acquire token for tenant '{0}'</value>
342+
<value>Unable to acquire token for tenant '{0}' with error '{1}'</value>
343343
</data>
344344
<data name="UnableToLogin" xml:space="preserve">
345345
<value>Could not authenticate user account '{0}' with tenant '{1}'. Subscriptions in this tenant will not be listed. Please login again using Connect-AzAccount to view the subscriptions in this tenant.</value>

‎src/Accounts/Authentication.Test/Mocks/MockMsalAccessTokenAcquirer.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,7 @@ class MockMsalAccessTokenAcquirer : MsalAccessTokenAcquirer
3232

3333
public TokenRequestContext TokenRequestContext { get; set; }
3434

35-
internal override async Task<IAccessToken> GetAccessTokenAsync(TokenCredential tokenCredential, TokenRequestContext requestContext, CancellationToken cancellationToken, string tenantId = null, string userId = null, string homeAccountId = "")
35+
internal override async Task<IAccessToken> GetAccessTokenAsync(string callerClassName, string parametersLog, TokenCredential tokenCredential, TokenRequestContext requestContext, CancellationToken cancellationToken, string tenantId = null, string userId = null, string homeAccountId = "")
3636
{
3737
TokenCredential = tokenCredential;
3838
TokenRequestContext = requestContext;

‎src/Accounts/Authenticators/AccessTokenAuthenticator.cs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -46,7 +46,7 @@ public override Task<IAccessToken> Authenticate(AuthenticationParameters paramet
4646
resourceId.EqualsInsensitively(environment.GetEndpoint(AzureEnvironment.Endpoint.AzureKeyVaultServiceEndpointResourceId)))
4747
&& account.IsPropertySet(AzureAccount.Property.KeyVaultAccessToken))
4848
{
49-
TracingAdapter.Information(string.Format("[AccessTokenAuthenticator] Creating KeyVault access token - Tenant: '{0}', ResourceId: '{1}', UserId: '{2}'", tenant, resourceId, account.Id));
49+
TracingAdapter.Information($"{DateTime.Now:T} - [AccessTokenAuthenticator] Creating KeyVault access token - Tenant: '{tenant}', ResourceId: '{resourceId}', UserId: '{account.Id}'");
5050
rawToken.AccessToken = account.GetProperty(AzureAccount.Property.KeyVaultAccessToken);
5151
}
5252
else if ((resourceId.EqualsInsensitively(environment.GraphEndpointResourceId) ||
@@ -55,7 +55,7 @@ public override Task<IAccessToken> Authenticate(AuthenticationParameters paramet
5555
resourceId.EqualsInsensitively(environment.GetEndpoint(AzureEnvironment.Endpoint.GraphEndpointResourceId)))
5656
&& account.IsPropertySet(AzureAccount.Property.GraphAccessToken))
5757
{
58-
TracingAdapter.Information(string.Format("[AccessTokenAuthenticator] Creating Graph access token - Tenant: '{0}', ResourceId: '{1}', UserId: '{2}'", tenant, resourceId, account.Id));
58+
TracingAdapter.Information($"{DateTime.Now:T} - [AccessTokenAuthenticator] Creating Graph access token - Tenant: '{tenant}', ResourceId: '{resourceId}', UserId: '{account.Id}'");
5959
rawToken.AccessToken = account.GetProperty(AzureAccount.Property.GraphAccessToken);
6060
}
6161
else if ((resourceId.EqualsInsensitively(environment.ActiveDirectoryServiceEndpointResourceId) ||
@@ -64,7 +64,7 @@ public override Task<IAccessToken> Authenticate(AuthenticationParameters paramet
6464
resourceId.EqualsInsensitively(environment.GetEndpoint(AzureEnvironment.Endpoint.ActiveDirectoryServiceEndpointResourceId)))
6565
&& account.IsPropertySet(AzureAccount.Property.AccessToken))
6666
{
67-
TracingAdapter.Information(string.Format("[AccessTokenAuthenticator] Creating access token - Tenant: '{0}', ResourceId: '{1}', UserId: '{2}'", tenant, resourceId, account.Id));
67+
TracingAdapter.Information($"{DateTime.Now:T} - [AccessTokenAuthenticator] Creating access token - Tenant: '{tenant}', ResourceId: '{resourceId}', UserId: '{account.Id}'");
6868
rawToken.AccessToken = account.GetAccessToken();
6969
}
7070
else

‎src/Accounts/Authenticators/DeviceCodeAuthenticator.cs

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,8 @@
1919
using Azure.Core;
2020
using Azure.Identity;
2121

22+
using Hyak.Common;
23+
2224
using Microsoft.Azure.Commands.Common.Authentication;
2325
using Microsoft.Azure.Commands.Common.Authentication.Abstractions;
2426
using Microsoft.Azure.Commands.ResourceManager.Common;
@@ -53,6 +55,7 @@ public override Task<IAccessToken> Authenticate(AuthenticationParameters paramet
5355
};
5456
var codeCredential = new DeviceCodeCredential(options);
5557

58+
TracingAdapter.Information($"{DateTime.Now:T} - [DeviceCodeAuthenticator] Calling DeviceCodeCredential.AuthenticateAsync - TenantId:'{options.TenantId}', Scopes:'{string.Join(",", scopes)}', AuthorityHost:'{options.AuthorityHost}'");
5659
var authTask = codeCredential.AuthenticateAsync(requestContext, cancellationToken);
5760
return MsalAccessToken.GetAccessTokenAsync(
5861
authTask,

‎src/Accounts/Authenticators/InteractiveUserAuthenticator.cs

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313
// ----------------------------------------------------------------------------------
1414

1515
using System;
16+
using System.Diagnostics;
1617
using System.Net;
1718
using System.Net.Sockets;
1819
using System.Threading;
@@ -21,6 +22,8 @@
2122
using Azure.Core;
2223
using Azure.Identity;
2324

25+
using Hyak.Common;
26+
2427
using Microsoft.Azure.Commands.Common.Authentication;
2528
using Microsoft.Azure.Commands.Common.Authentication.Abstractions;
2629

@@ -65,6 +68,8 @@ public override Task<IAccessToken> Authenticate(AuthenticationParameters paramet
6568
RedirectUri = GetReplyUrl(onPremise, interactiveParameters),
6669
};
6770
var browserCredential = new InteractiveBrowserCredential(options);
71+
72+
TracingAdapter.Information($"{DateTime.Now:T} - [InteractiveUserAuthenticator] Calling InteractiveBrowserCredential.AuthenticateAsync with TenantId:'{options.TenantId}', Scopes:'{string.Join(",", scopes)}', AuthorityHost:'{options.AuthorityHost}', RedirectUri:'{options.RedirectUri}'");
6873
var authTask = browserCredential.AuthenticateAsync(requestContext, cancellationToken);
6974

7075
return MsalAccessToken.GetAccessTokenAsync(

‎src/Accounts/Authenticators/ManagedServiceIdentityAuthenticator.cs

Lines changed: 12 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -12,13 +12,16 @@
1212
// limitations under the License.
1313
// ----------------------------------------------------------------------------------
1414

15+
using System;
1516
using System.Text.RegularExpressions;
1617
using System.Threading;
1718
using System.Threading.Tasks;
1819

1920
using Azure.Core;
2021
using Azure.Identity;
2122

23+
using Hyak.Common;
24+
2225
using Microsoft.Azure.Commands.Common.Authentication;
2326
using Microsoft.Azure.Commands.Common.Authentication.Abstractions;
2427
using Microsoft.Azure.PowerShell.Authenticators.Factories;
@@ -47,8 +50,15 @@ public override Task<IAccessToken> Authenticate(AuthenticationParameters paramet
4750

4851
var identityCredential = azureCredentialFactory.CreateManagedIdentityCredential(userAccountId);
4952
var msalAccessTokenAcquirer = msalAccessTokenAcquirerFactory.CreateMsalAccessTokenAcquirer();
50-
return msalAccessTokenAcquirer.GetAccessTokenAsync(identityCredential, requestContext, cancellationToken,
51-
msiParameters.TenantId, msiParameters.Account.Id);
53+
var parametersLog = $"- TenantId:'{msiParameters.TenantId}', Scopes:'{string.Join(",", scopes)}', UserId:'{userAccountId}'";
54+
return msalAccessTokenAcquirer.GetAccessTokenAsync(
55+
nameof(ManagedServiceIdentityAuthenticator),
56+
parametersLog,
57+
identityCredential,
58+
requestContext,
59+
cancellationToken,
60+
msiParameters.TenantId,
61+
msiParameters.Account.Id);
5262
}
5363

5464
public override bool CanAuthenticate(AuthenticationParameters parameters)

‎src/Accounts/Authenticators/MsalAccessToken.cs

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,8 @@
2121
using Azure.Core;
2222
using Azure.Identity;
2323

24+
using Hyak.Common;
25+
2426
using Microsoft.Azure.Commands.Common.Authentication;
2527

2628
namespace Microsoft.Azure.PowerShell.Authenticators
@@ -66,13 +68,16 @@ public void AuthorizeRequest(Action<string, string> authTokenSetter)
6668
}
6769

6870
internal static async Task<IAccessToken> GetAccessTokenAsync(
71+
string callerClassName,
72+
string parametersLog,
6973
TokenCredential tokenCredential,
7074
TokenRequestContext requestContext,
7175
CancellationToken cancellationToken,
7276
string tenantId = null,
7377
string userId = null,
7478
string homeAccountId = "")
7579
{
80+
TracingAdapter.Information($"{DateTime.Now:T} - [{callerClassName}] Calling {tokenCredential.GetType().Name}.GetTokenAsync {parametersLog}");
7681
var token = await tokenCredential.GetTokenAsync(requestContext, cancellationToken).ConfigureAwait(false);
7782
return new MsalAccessToken(tokenCredential, requestContext, token.Token, token.ExpiresOn, tenantId, userId, homeAccountId);
7883
}
@@ -86,6 +91,7 @@ internal static async Task<IAccessToken> GetAccessTokenAsync(
8691
{
8792
var record = await authTask.ConfigureAwait(false);
8893
cancellationToken.ThrowIfCancellationRequested();
94+
TracingAdapter.Information($"{DateTime.Now:T} - [MsalAccessToken] Calling {tokenCredential.GetType().Name}.GetTokenAsync - Scopes:'{string.Join(",", requestContext.Scopes)}'");
8995
var token = await tokenCredential.GetTokenAsync(requestContext, cancellationToken).ConfigureAwait(false);
9096

9197
return new MsalAccessToken(tokenCredential, requestContext, token.Token, token.ExpiresOn, record.TenantId, record.Username, record.HomeAccountId);

‎src/Accounts/Authenticators/MsalAccessTokenAcquirer.cs

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,26 +12,32 @@
1212
// limitations under the License.
1313
// ----------------------------------------------------------------------------------
1414

15+
using System;
1516
using System.Threading;
1617
using System.Threading.Tasks;
1718

1819
using Azure.Core;
1920
using Azure.Identity;
2021

22+
using Hyak.Common;
23+
2124
using Microsoft.Azure.Commands.Common.Authentication;
2225

2326
namespace Microsoft.Azure.PowerShell.Authenticators
2427
{
2528
public class MsalAccessTokenAcquirer
2629
{
2730
internal virtual async Task<IAccessToken> GetAccessTokenAsync(
31+
string callerClassName,
32+
string parametersLog,
2833
TokenCredential tokenCredential,
2934
TokenRequestContext requestContext,
3035
CancellationToken cancellationToken,
3136
string tenantId = null,
3237
string userId = null,
3338
string homeAccountId = "")
3439
{
40+
TracingAdapter.Information($"{DateTime.Now:T} - [{callerClassName}] Calling {tokenCredential.GetType().Name}.GetTokenAsync {parametersLog}");
3541
var token = await tokenCredential.GetTokenAsync(requestContext, cancellationToken).ConfigureAwait(false);
3642
return new MsalAccessToken(tokenCredential, requestContext, token.Token, token.ExpiresOn, tenantId, userId, homeAccountId);
3743
}
@@ -44,6 +50,7 @@ internal virtual async Task<IAccessToken> GetAccessTokenAsync(
4450
{
4551
var record = await authTask.ConfigureAwait(false);
4652
cancellationToken.ThrowIfCancellationRequested();
53+
TracingAdapter.Information($"{DateTime.Now:T} - [MsalAccessTokenAcquirer] Calling {tokenCredential.GetType().Name}.GetTokenAsync - Scopes:'{string.Join(",", requestContext.Scopes)}'");
4754
var token = await tokenCredential.GetTokenAsync(requestContext, cancellationToken).ConfigureAwait(false);
4855

4956
return new MsalAccessToken(tokenCredential, requestContext, token.Token, token.ExpiresOn, record.TenantId, record.Username, record.HomeAccountId);

‎src/Accounts/Authenticators/ServicePrincipalAuthenticator.cs

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,8 @@
2020
using Azure.Core;
2121
using Azure.Identity;
2222

23+
using Hyak.Common;
24+
2325
using Microsoft.Azure.Commands.Common.Authentication;
2426
using Microsoft.Azure.Commands.Common.Authentication.Abstractions;
2527
using Microsoft.Identity.Client;
@@ -55,7 +57,10 @@ public override Task<IAccessToken> Authenticate(AuthenticationParameters paramet
5557
//Service Principal with Certificate
5658
var certificate = AzureSession.Instance.DataStore.GetCertificate(spParameters.Thumbprint);
5759
ClientCertificateCredential certCredential = new ClientCertificateCredential(tenantId, spParameters.ApplicationId, certificate, options);
60+
var parametersLog = $"- Thumbprint:'{spParameters.Thumbprint}', ApplicationId:'{spParameters.ApplicationId}', TenantId:'{tenantId}', Scopes:'{string.Join(",", scopes)}', AuthorityHost:'{options.AuthorityHost}'";
5861
return MsalAccessToken.GetAccessTokenAsync(
62+
nameof(ServicePrincipalAuthenticator),
63+
parametersLog,
5964
certCredential,
6065
requestContext,
6166
cancellationToken,
@@ -66,7 +71,10 @@ public override Task<IAccessToken> Authenticate(AuthenticationParameters paramet
6671
{
6772
// service principal with secret
6873
var secretCredential = new ClientSecretCredential(tenantId, spParameters.ApplicationId, spParameters.Secret.ConvertToString(), options);
74+
var parametersLog = $"- ApplicationId:'{spParameters.ApplicationId}', TenantId:'{tenantId}', Scopes:'{string.Join(",", scopes)}', AuthorityHost:'{options.AuthorityHost}'";
6975
return MsalAccessToken.GetAccessTokenAsync(
76+
nameof(ServicePrincipalAuthenticator),
77+
parametersLog,
7078
secretCredential,
7179
requestContext,
7280
cancellationToken,

‎src/Accounts/Authenticators/SilentAuthenticator.cs

Lines changed: 12 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,8 @@
1919
using Azure.Core;
2020
using Azure.Identity;
2121

22+
using Hyak.Common;
23+
2224
using Microsoft.Azure.Commands.Common.Authentication;
2325
using Microsoft.Azure.Commands.Common.Authentication.Abstractions;
2426

@@ -48,8 +50,16 @@ public override Task<IAccessToken> Authenticate(AuthenticationParameters paramet
4850

4951
var cacheCredential = new SharedTokenCacheCredential(options);
5052
var requestContext = new TokenRequestContext(scopes);
51-
var tokenTask = cacheCredential.GetTokenAsync(requestContext);
52-
return MsalAccessToken.GetAccessTokenAsync(cacheCredential, requestContext, cancellationToken, silentParameters.TenantId, silentParameters.UserId, silentParameters.HomeAccountId);
53+
var parametersLog = $"- TenantId:'{options.TenantId}', Scopes:'{string.Join(",", scopes)}', AuthorityHost:'{options.AuthorityHost}', UserId:'{silentParameters.UserId}'";
54+
return MsalAccessToken.GetAccessTokenAsync(
55+
nameof(SilentAuthenticator),
56+
parametersLog,
57+
cacheCredential,
58+
requestContext,
59+
cancellationToken,
60+
silentParameters.TenantId,
61+
silentParameters.UserId,
62+
silentParameters.HomeAccountId);
5363
}
5464

5565
public override bool CanAuthenticate(AuthenticationParameters parameters)

0 commit comments

Comments
 (0)