Skip to content

Commit

Permalink
Add more logging to GetAccounts by id (#4929)
Browse files Browse the repository at this point in the history 
Add more verbose logging to cache op
  • Loading branch information
@bgavrilMS
bgavrilMS authored Dec 2, 2024
1 parent 5dacb5f commit 7cadf60
Show file tree
Hide file tree
Showing 3 changed files with 86 additions and 30 deletions.
13 changes: 11 additions & 2 deletions src/client/Microsoft.Identity.Client/ClientApplicationBase.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -38,8 +38,8 @@ public abstract partial class ClientApplicationBase : ApplicationBase, IClientAp

internal ClientApplicationBase(ApplicationConfiguration config) : base(config)
{
UserTokenCacheInternal =
config.UserTokenCacheInternalForTest ??
UserTokenCacheInternal =
config.UserTokenCacheInternalForTest ??
new TokenCache(
ServiceBundle,
false,
Expand Down Expand Up @@ -171,6 +171,15 @@ private async Task<IEnumerable<IAccount>> GetAccountsInternalAsync(ApiIds apiId,
{
Guid correlationId = Guid.NewGuid();
RequestContext requestContext = CreateRequestContext(correlationId, cancellationToken);

if (requestContext.Logger.IsLoggingEnabled(LogLevel.Info))
{
requestContext.Logger.Info($"==== GetAccounts started - {apiId} ====");
requestContext.Logger.InfoPii(
$"Account id filter: {homeAccountIdFilter}",
$"Account id filter: {!string.IsNullOrEmpty(homeAccountIdFilter)}");
}

requestContext.ApiEvent = new ApiEvent(correlationId);
requestContext.ApiEvent.ApiId = apiId;

Expand Down
51 changes: 46 additions & 5 deletions ...osoft.Identity.Client/PlatformsCommon/Shared/InMemoryPartitionedUserTokenCacheAccessor.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -223,17 +223,36 @@ public virtual List<MsalAccessTokenCacheItem> GetAllAccessTokens(string partitio
/// It should only support external token caching, in the hope that the external token cache is partitioned.
public virtual List<MsalRefreshTokenCacheItem> GetAllRefreshTokens(string partitionKey = null, ILoggerAdapter requestlogger = null)
{
List<MsalRefreshTokenCacheItem> result;
var logger = requestlogger ?? _logger;
logger.Always($"[Internal cache] Total number of cache partitions found while getting refresh tokens: {RefreshTokenCacheDictionary.Count}");
logger.AlwaysPii(
$"[Internal cache] Total number of cache partitions found while getting refresh tokens: {RefreshTokenCacheDictionary.Count}. PartitionKey {partitionKey}",
$"[Internal cache] Total number of cache partitions found while getting refresh tokens: {RefreshTokenCacheDictionary.Count}. PartitionKey {!string.IsNullOrEmpty(partitionKey)}");

if (string.IsNullOrEmpty(partitionKey))
{
return RefreshTokenCacheDictionary.SelectMany(dict => dict.Value).Select(kv => kv.Value).ToList();
result = RefreshTokenCacheDictionary.SelectMany(dict => dict.Value).Select(kv => kv.Value).ToList();
logger.Verbose(() => $"[Internal cache] GetAllRefreshTokens (no partition) found {result.Count} refresh tokens:");

}
else
{
RefreshTokenCacheDictionary.TryGetValue(partitionKey, out ConcurrentDictionary<string, MsalRefreshTokenCacheItem> partition);
return partition?.Select(kv => kv.Value)?.ToList() ?? CollectionHelpers.GetEmptyList<MsalRefreshTokenCacheItem>();

result = partition?.Select(kv => kv.Value)?.ToList() ?? CollectionHelpers.GetEmptyList<MsalRefreshTokenCacheItem>();
if (logger.IsLoggingEnabled(LogLevel.Verbose))
{
logger.Verbose(() => $"[Internal cache] GetAllRefreshTokens (with partition - exists? {partition != null})) found {result.Count} refresh tokens:");
if (RefreshTokenCacheDictionary.Count == 1 && result.Count == 0)
{
logger.VerbosePii(
() => $"[Internal cache] 0 RTs and 1 partition. Partition in cache is {RefreshTokenCacheDictionary.Keys.First()}",
() => "[Internal cache] 0 RTs and 1 partition] 0 RTs and 1 partition.");
}
}
}

return result;
}

/// WARNING: if partitionKey is null, this API is slow as it loads all tokens, not just from 1 partition.
Expand All @@ -255,15 +274,37 @@ public virtual List<MsalIdTokenCacheItem> GetAllIdTokens(string partitionKey = n
/// It should only support external token caching, in the hope that the external token cache is partitioned.
public virtual List<MsalAccountCacheItem> GetAllAccounts(string partitionKey = null, ILoggerAdapter requestlogger = null)
{
var logger = requestlogger ?? _logger;
List<MsalAccountCacheItem> result;

logger.AlwaysPii(
$"[Internal cache] Total number of cache partitions found while getting accounts: {AccountCacheDictionary.Count}. PartitionKey {partitionKey}",
$"[Internal cache] Total number of cache partitions found while getting accounts: {AccountCacheDictionary.Count}. PartitionKey {!string.IsNullOrEmpty(partitionKey)}");

if (string.IsNullOrEmpty(partitionKey))
{
return AccountCacheDictionary.SelectMany(dict => dict.Value).Select(kv => kv.Value).ToList();
result = AccountCacheDictionary.SelectMany(dict => dict.Value).Select(kv => kv.Value).ToList();
logger.Verbose(() => $"[Internal cache] GetAllAccounts (no partition) found {result.Count} accounts.");
}
else
{
AccountCacheDictionary.TryGetValue(partitionKey, out ConcurrentDictionary<string, MsalAccountCacheItem> partition);
return partition?.Select(kv => kv.Value)?.ToList() ?? CollectionHelpers.GetEmptyList<MsalAccountCacheItem>();
result = partition?.Select(kv => kv.Value)?.ToList() ?? CollectionHelpers.GetEmptyList<MsalAccountCacheItem>();

if (logger.IsLoggingEnabled(LogLevel.Verbose))
{
logger.Verbose(() => $"[Internal cache] GetAllAccounts (with partition - exists? {partition != null}) found {result.Count} accounts.");
if (AccountCacheDictionary.Count == 1 && result.Count == 0)
{
// get dictionary first key
logger.VerbosePii(
() => $"[Internal cache] 0 RTs and 1 partition. Partition in cache is {AccountCacheDictionary.Keys.First()}",
() => "[Internal cache] 0 RTs and 1 partition] 0 RTs and 1 partition.");
}
}
}

return result;
}

public virtual List<MsalAppMetadataCacheItem> GetAllAppMetadata()
Expand Down
52 changes: 29 additions & 23 deletions src/client/Microsoft.Identity.Client/TokenCache.ITokenCacheInternal.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -90,7 +90,7 @@ async Task<Tuple<MsalAccessTokenCacheItem, MsalIdTokenCacheItem, Account>> IToke
"client_credentials flow should not receive a refresh token");

Debug.Assert(
(requestParams.ApiId != ApiEvent.ApiIds.AcquireTokenForSystemAssignedManagedIdentity ||
(requestParams.ApiId != ApiEvent.ApiIds.AcquireTokenForSystemAssignedManagedIdentity ||
requestParams.ApiId != ApiEvent.ApiIds.AcquireTokenForUserAssignedManagedIdentity),
"Managed identity flow should not receive a refresh token");

Expand Down Expand Up @@ -152,7 +152,7 @@ async Task<Tuple<MsalAccessTokenCacheItem, MsalIdTokenCacheItem, Account>> IToke
}
}


account = new Account(
homeAccountId,
username,
Expand Down Expand Up @@ -195,7 +195,7 @@ async Task<Tuple<MsalAccessTokenCacheItem, MsalIdTokenCacheItem, Account>> IToke
identityLogger: requestParams.RequestContext.Logger.IdentityLogger,
piiLoggingEnabled: requestParams.RequestContext.Logger.PiiLoggingEnabled);

var measuredResultDuration = await StopwatchService.MeasureCodeBlockAsync( async () =>
var measuredResultDuration = await StopwatchService.MeasureCodeBlockAsync(async () =>
{
await tokenCacheInternal.OnBeforeAccessAsync(args).ConfigureAwait(false);
await tokenCacheInternal.OnBeforeWriteAsync(args).ConfigureAwait(false);
Expand Down Expand Up @@ -930,18 +930,21 @@ async Task<IEnumerable<IAccount>> ITokenCacheInternal.GetAccountsAsync(Authentic
// this will either be the home account ID or null, it can never be OBO assertion or tenant ID
string partitionKey = CacheKeyFactory.GetKeyFromRequest(requestParameters);

logger.VerbosePii(() => $"[GetAccounts] PartitionKey: {partitionKey}. request.HomeAccountId {requestParameters.HomeAccountId}", () => "");

var refreshTokenCacheItems = Accessor.GetAllRefreshTokens(partitionKey);
var accountCacheItems = Accessor.GetAllAccounts(partitionKey);

if (filterByClientId)
{
FilterTokensByClientId(refreshTokenCacheItems);
refreshTokenCacheItems.FilterWithLogging(item =>
string.Equals(item.ClientId, ClientId, StringComparison.OrdinalIgnoreCase),
logger,
"[GetAccounts] Filtering RTs by clientID",
true);
}

if (logger.IsLoggingEnabled(LogLevel.Verbose))
{
logger.Verbose(() => $"[GetAccounts] Found {refreshTokenCacheItems.Count} RTs and {accountCacheItems.Count} accounts in MSAL cache. ");
}
logger.Verbose(() => $"[GetAccounts] Found {refreshTokenCacheItems.Count} RTs and {accountCacheItems.Count} accounts in MSAL cache before env filtering.");

// Multi-cloud support - must filter by environment.
ISet<string> allEnvironmentsInCache = new HashSet<string>(
Expand Down Expand Up @@ -969,15 +972,21 @@ async Task<IEnumerable<IAccount>> ITokenCacheInternal.GetAccountsAsync(Authentic
// since the authority in request is different from the authority used to get the token
if (!requestParameters.AppConfig.MultiCloudSupportEnabled)
{
refreshTokenCacheItems.RemoveAll(rt => !instanceMetadata.Aliases.ContainsOrdinalIgnoreCase(rt.Environment));
accountCacheItems.RemoveAll(acc => !instanceMetadata.Aliases.ContainsOrdinalIgnoreCase(acc.Environment));
}
refreshTokenCacheItems.FilterWithLogging(
rt => instanceMetadata.Aliases.ContainsOrdinalIgnoreCase(rt.Environment),
logger,
"[GetAccounts] Filtering RTs by environment",
true);

if (logger.IsLoggingEnabled(LogLevel.Verbose))
{
logger.Verbose(() => $"[GetAccounts] Found {refreshTokenCacheItems.Count} RTs and {accountCacheItems.Count} accounts in MSAL cache after environment filtering. ");
accountCacheItems.FilterWithLogging(
a => instanceMetadata.Aliases.ContainsOrdinalIgnoreCase(a.Environment),
logger,
"[GetAccounts] Filtering accounts by environment",
true);
}

logger.Verbose(() => $"[GetAccounts] Found {refreshTokenCacheItems.Count} RTs and {accountCacheItems.Count} accounts in MSAL cache after environment filtering. ");

IDictionary<string, Account> clientInfoToAccountMap = new Dictionary<string, Account>();
foreach (MsalRefreshTokenCacheItem rtItem in refreshTokenCacheItems)
{
Expand Down Expand Up @@ -1047,14 +1056,11 @@ async Task<IEnumerable<IAccount>> ITokenCacheInternal.GetAccountsAsync(Authentic

if (!string.IsNullOrEmpty(requestParameters.HomeAccountId))
{
accounts = accounts.Where(acc => acc.HomeAccountId.Identifier.Equals(
requestParameters.HomeAccountId,
StringComparison.OrdinalIgnoreCase)).ToList();

if (logger.IsLoggingEnabled(LogLevel.Verbose))
{
logger.Verbose(() => $"Filtered by home account id. Remaining accounts {accounts.Count} ");
}
accounts.FilterWithLogging(
acc => acc.HomeAccountId.Identifier.Equals(requestParameters.HomeAccountId, StringComparison.OrdinalIgnoreCase),
logger,
"[GetAccounts] Filtering by accountID",
true);
}

return accounts;
Expand Down Expand Up @@ -1287,7 +1293,7 @@ async Task ITokenCacheInternal.RemoveAccountAsync(IAccount account, Authenticati
}

RemoveAccountInternal(account, requestParameters.RequestContext);

if (IsLegacyAdalCacheEnabled(requestParameters))
{
CacheFallbackOperations.RemoveAdalUser(
Expand Down

1 comment on commit 7cadf60

@github-actions
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Performance Alert ⚠️

Possible performance regression was detected for benchmark 'TokenCacheTestsWithCache'.
Benchmark result of this commit is worse than the previous benchmark result exceeding threshold 1.30.

Benchmark suite Current: 7cadf60 Previous: f29be92 Ratio
Microsoft.Identity.Test.Performance.TokenCacheTests.GetAccountAsync_TestAsync(CacheSize: (10000, 10)) 53957.2444132487 ns (± 384.39983166681753) 20760.811285400392 ns (± 189.90814695750393) 2.60
Microsoft.Identity.Test.Performance.TokenCacheTests.RemoveAccountAsync_TestAsync(CacheSize: (10000, 10)) 204460.96 ns (± 23228.327734510254) 151692.28 ns (± 15988.021808690139) 1.35

This comment was automatically generated by workflow using github-action-benchmark.

Please sign in to comment.