From a8b93d42c8083097bfa452d313504e92d1ebc414 Mon Sep 17 00:00:00 2001 From: Peter <34331512+pmaytak@users.noreply.github.com> Date: Mon, 16 Oct 2023 12:15:40 -0700 Subject: [PATCH] Print refresh token cache keys to logs (#4375) * Print RTs to cache. * Add tests. --- .../Cache/Items/MsalRefreshTokenCacheItem.cs | 11 ++ .../TokenCache.ITokenCacheInternal.cs | 25 ++-- .../CacheTests/TokenCacheTests.cs | 108 +++++++++++------- 3 files changed, 91 insertions(+), 53 deletions(-) diff --git a/src/client/Microsoft.Identity.Client/Cache/Items/MsalRefreshTokenCacheItem.cs b/src/client/Microsoft.Identity.Client/Cache/Items/MsalRefreshTokenCacheItem.cs index a9ba569039..28bc937234 100644 --- a/src/client/Microsoft.Identity.Client/Cache/Items/MsalRefreshTokenCacheItem.cs +++ b/src/client/Microsoft.Identity.Client/Cache/Items/MsalRefreshTokenCacheItem.cs @@ -81,6 +81,17 @@ internal void InitCacheKey() iOSCacheKeyLazy = new Lazy(() => InitiOSKey()); } + internal string ToLogString(bool piiEnabled = false) + { + return MsalCacheKeys.GetCredentialKey( + piiEnabled ? HomeAccountId : HomeAccountId?.GetHashCode().ToString(), + Environment, + StorageJsonValues.CredentialTypeRefreshToken, + ClientId, + tenantId: null, + scopes: null); + } + #region iOS private IiOSKey InitiOSKey() { diff --git a/src/client/Microsoft.Identity.Client/TokenCache.ITokenCacheInternal.cs b/src/client/Microsoft.Identity.Client/TokenCache.ITokenCacheInternal.cs index 1b527cfda9..0f72fd4aa5 100644 --- a/src/client/Microsoft.Identity.Client/TokenCache.ITokenCacheInternal.cs +++ b/src/client/Microsoft.Identity.Client/TokenCache.ITokenCacheInternal.cs @@ -266,7 +266,7 @@ async Task> IToke await tokenCacheInternal.OnAfterAccessAsync(args).ConfigureAwait(false); requestParams.RequestContext.ApiEvent.DurationInCacheInMs += sw.ElapsedMilliseconds; - DumpCacheToLogs(requestParams); + LogCacheContents(requestParams); } #pragma warning disable CS0618 // Type or member is obsolete @@ -294,27 +294,34 @@ private bool ShouldCacheAccessToken(MsalAccessTokenCacheItem msalAccessTokenCach //This method pulls all of the access and refresh tokens from the cache and can therefore be very impactful on performance. //This will run on a background thread to mitigate this. - private void DumpCacheToLogs(AuthenticationRequestParameters requestParameters) + private void LogCacheContents(AuthenticationRequestParameters requestParameters) { if (requestParameters.RequestContext.Logger.IsLoggingEnabled(LogLevel.Verbose)) { var accessTokenCacheItems = Accessor.GetAllAccessTokens(); var refreshTokenCacheItems = Accessor.GetAllRefreshTokens(); - var accessTokenCacheItemsSubset = accessTokenCacheItems.Take(10).Select(item => item).ToList(); + var accessTokenCacheItemsSubset = accessTokenCacheItems.Take(10).ToList(); + var refreshTokenCacheItemsSubset = refreshTokenCacheItems.Take(10).ToList(); - StringBuilder tokenCacheKeyDump = new StringBuilder(); + StringBuilder tokenCacheKeyLog = new StringBuilder(); - tokenCacheKeyDump.AppendLine($"Total number of access tokens in cache: {accessTokenCacheItems.Count}"); - tokenCacheKeyDump.AppendLine($"Total number of refresh tokens in cache: {refreshTokenCacheItems.Count}"); + tokenCacheKeyLog.AppendLine($"Total number of access tokens in the cache: {accessTokenCacheItems.Count}"); + tokenCacheKeyLog.AppendLine($"Total number of refresh tokens in the cache: {refreshTokenCacheItems.Count}"); - tokenCacheKeyDump.AppendLine($"Token cache dump of the first {accessTokenCacheItemsSubset.Count} cache keys."); + tokenCacheKeyLog.AppendLine($"First {accessTokenCacheItemsSubset.Count} access token cache keys:"); foreach (var cacheItem in accessTokenCacheItemsSubset) { - tokenCacheKeyDump.AppendLine($"AT Cache Key: {cacheItem.ToLogString(requestParameters.RequestContext.Logger.PiiLoggingEnabled)}"); + tokenCacheKeyLog.AppendLine($"AT Cache Key: {cacheItem.ToLogString(requestParameters.RequestContext.Logger.PiiLoggingEnabled)}"); } - requestParameters.RequestContext.Logger.Verbose(() => tokenCacheKeyDump.ToString()); + tokenCacheKeyLog.AppendLine($"First {refreshTokenCacheItemsSubset.Count} refresh token cache keys:"); + foreach (var cacheItem in refreshTokenCacheItemsSubset) + { + tokenCacheKeyLog.AppendLine($"RT Cache Key: {cacheItem.ToLogString(requestParameters.RequestContext.Logger.PiiLoggingEnabled)}"); + } + + requestParameters.RequestContext.Logger.Verbose(() => tokenCacheKeyLog.ToString()); } } diff --git a/tests/Microsoft.Identity.Test.Unit/CacheTests/TokenCacheTests.cs b/tests/Microsoft.Identity.Test.Unit/CacheTests/TokenCacheTests.cs index 34f02223bf..cbea48486a 100644 --- a/tests/Microsoft.Identity.Test.Unit/CacheTests/TokenCacheTests.cs +++ b/tests/Microsoft.Identity.Test.Unit/CacheTests/TokenCacheTests.cs @@ -4,7 +4,6 @@ using System; using System.Collections.Generic; using System.Linq; -using System.Text; using System.Threading.Tasks; using Castle.Core.Internal; using Microsoft.Identity.Client; @@ -25,7 +24,6 @@ using Microsoft.Identity.Test.Common.Core.Mocks; using Microsoft.VisualStudio.TestTools.UnitTesting; using NSubstitute; -using NSubstitute.Extensions; namespace Microsoft.Identity.Test.Unit.CacheTests { @@ -497,7 +495,7 @@ public void ExpiryNoTokens() var userAccessorExpiration = TokenCache.CalculateSuggestedCacheExpiry(userTokenCache.Accessor, logger); // Assert - Assert.IsNull(appAccessorExpiration ); + Assert.IsNull(appAccessorExpiration); Assert.IsNull(userAccessorExpiration); Assert.IsFalse(appTokenCache.Accessor.HasAccessOrRefreshTokens()); Assert.IsFalse(userTokenCache.Accessor.HasAccessOrRefreshTokens()); @@ -1371,7 +1369,7 @@ public void TestIsFociMember_EnvAlias() "1")); // Act - bool? result = cache.IsFociMemberAsync(requestParams, "1").Result; //requst params uses ProductionPrefEnvAlias + bool? result = cache.IsFociMemberAsync(requestParams, "1").Result; //request params uses ProductionPrefEnvAlias // Assert Assert.AreEqual(true, result.Value); @@ -1380,58 +1378,80 @@ public void TestIsFociMember_EnvAlias() [TestMethod] [TestCategory(TestCategories.TokenCacheTests)] - public async Task ValidateTokenCacheIsDumpedToLogsTestAsync() + public async Task ValidateTokenCacheContentsAreLogged_TestAsync() { - using (MockHttpAndServiceBundle harness = CreateTestHarness()) - { - //Arrange - harness.HttpManager.AddInstanceDiscoveryMockHandler(); + using MockHttpAndServiceBundle harness = CreateTestHarness(); - string dump = string.Empty; - LogCallback callback = (LogLevel level, string message, bool containsPii) => + //Arrange + harness.HttpManager.AddInstanceDiscoveryMockHandler(); + + string logs = string.Empty; + LogCallback logCallback = (LogLevel level, string message, bool containsPii) => + { + if (level == LogLevel.Verbose) { - if (level == LogLevel.Verbose) - { - dump += $"MSAL Test: {message}\n"; - } - }; + logs += message; + } + }; - var serviceBundle = TestCommon.CreateServiceBundleWithCustomHttpManager(harness.HttpManager, logCallback: callback); - ITokenCacheInternal cache = new TokenCache(serviceBundle, false); - cache.SetAfterAccess((args) => { return; }); + var serviceBundle = TestCommon.CreateServiceBundleWithCustomHttpManager(harness.HttpManager, logCallback: logCallback); + ITokenCacheInternal cache = new TokenCache(serviceBundle, false); + cache.SetAfterAccess((args) => { return; }); - var ex = TokenCacheHelper.PopulateCacheWithAccessTokens(cache.Accessor, 19); + TokenCacheHelper.PopulateCacheWithAccessTokens(cache.Accessor, 11); - var requestParams = TestCommon.CreateAuthenticationRequestParameters( - serviceBundle, - scopes: new HashSet()); - requestParams.Account = TestConstants.s_user; - requestParams.RequestContext.ApiEvent = new ApiEvent(Guid.NewGuid()); + var requestParams = TestCommon.CreateAuthenticationRequestParameters( + serviceBundle, + scopes: new HashSet()); + requestParams.Account = TestConstants.s_user; + requestParams.RequestContext.ApiEvent = new ApiEvent(Guid.NewGuid()); - var response = TokenCacheHelper.CreateMsalTokenResponse(true); + var response = TokenCacheHelper.CreateMsalTokenResponse(true); - //Act - await cache.SaveTokenResponseAsync(requestParams, response).ConfigureAwait(false); + //Act + await cache.SaveTokenResponseAsync(requestParams, response).ConfigureAwait(false); - //Assert - Assert.IsTrue(dump != string.Empty); - Assert.IsTrue(dump.Contains("Total number of access tokens in cache: 20")); - Assert.IsTrue(dump.Contains("Total number of refresh tokens in cache: 20")); - Assert.IsTrue(dump.Contains("Token cache dump of the first 10 cache keys")); - - var accessTokens = cache.Accessor.GetAllAccessTokens().ToList(); - foreach (MsalAccessTokenCacheItem item in accessTokens) - { - Assert.IsTrue(dump.Contains(item.ToLogString())); - if (accessTokens.IndexOf(item) >= 9) - { - break; - } - } + //Assert + Assert.IsTrue(logs != string.Empty); + Assert.IsTrue(logs.Contains("Total number of access tokens in the cache: 12")); + Assert.IsTrue(logs.Contains("Total number of refresh tokens in the cache: 12")); + Assert.IsTrue(logs.Contains("First 10 access token cache keys:")); + Assert.IsTrue(logs.Contains("First 10 refresh token cache keys:")); + + var accessTokens = cache.Accessor.GetAllAccessTokens().ToList(); + var refreshTokens = cache.Accessor.GetAllRefreshTokens().ToList(); + for (int i = 0; i < 10; i++) + { + Assert.IsTrue(logs.Contains(accessTokens[i].ToLogString())); + Assert.IsTrue(logs.Contains(refreshTokens[i].ToLogString())); } } - + [DataTestMethod] + [DataRow(true)] + [DataRow(false)] + public void AccessTokenCacheItem_ToLogString_UsesPiiFlag_Test(bool enablePii) + { + var accessTokenCacheItem = TokenCacheHelper.CreateAccessTokenItem(); + + var log = accessTokenCacheItem.ToLogString(enablePii); + + Assert.AreEqual(enablePii, log.Contains(accessTokenCacheItem.HomeAccountId)); + Assert.AreNotEqual(enablePii, log.Contains(accessTokenCacheItem.HomeAccountId.GetHashCode().ToString())); + } + + [DataTestMethod] + [DataRow(true)] + [DataRow(false)] + public void RefreshTokenCacheItem_ToLogString_UsesPiiFlag_Test(bool enablePii) + { + var refreshTokenCacheItem = TokenCacheHelper.CreateRefreshTokenItem(); + + var log = refreshTokenCacheItem.ToLogString(enablePii); + + Assert.AreEqual(enablePii, log.Contains(refreshTokenCacheItem.HomeAccountId)); + Assert.AreNotEqual(enablePii, log.Contains(refreshTokenCacheItem.HomeAccountId.GetHashCode().ToString())); + } private void ValidateIsFociMember( ITokenCacheInternal cache,