Add telemetry for cache refresh (#2383)

* Add telemetry for cache refresh * Update version in comment for last telemetry * Address comments * Fix logic to persist value if token refresh happens due to expired token * Add unit test for cache refresh values
AzureAD · Feb 4, 2021 · 2c988b2 · 2c988b2
1 parent 092604a
commit 2c988b2
Show file tree

Hide file tree

Showing 16 changed files with 275 additions and 59 deletions.
diff --git a/src/client/Microsoft.Identity.Client/Cache/CacheRefresh.cs b/src/client/Microsoft.Identity.Client/Cache/CacheRefresh.cs
@@ -0,0 +1,15 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.;
+
+namespace Microsoft.Identity.Client.Region
+{
+    // Enum to be used only for telemetry, to log reason for cache refresh and fetching AT from ests.
+    internal enum CacheRefresh
+    {
+        None = -1, // When no cache is used
+        NoCachedAT = 0, // When there is no AT is found in the cache
+        Expired = 1, // When the token refresh happens due to expired token in cache
+        RefreshIn = 2, // When the token refresh happens due to refresh in
+        ForceRefresh = 3 // When the token refresh happens due to force refresh
+    }
+}
diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs
@@ -3,13 +3,15 @@
 
 using System;
 using System.Collections.Generic;
+using System.Globalization;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Identity.Client.ApiConfig.Parameters;
 using Microsoft.Identity.Client.Cache.Items;
 using Microsoft.Identity.Client.Instance.Discovery;
 using Microsoft.Identity.Client.OAuth2;
+using Microsoft.Identity.Client.Region;
 using Microsoft.Identity.Client.TelemetryCore.Internal.Events;
 using Microsoft.Identity.Client.Utils;
 
@@ -39,6 +41,7 @@ protected override async Task<AuthenticationResult> ExecuteAsync(CancellationTok
 
             MsalAccessTokenCacheItem cachedAccessTokenItem = null;
             var logger = AuthenticationRequestParameters.RequestContext.Logger;
+            CacheRefresh cacheRefresh = CacheRefresh.None;
 
             if (!_clientParameters.ForceRefresh && 
                 string.IsNullOrEmpty(AuthenticationRequestParameters.Claims))
@@ -56,10 +59,28 @@ protected override async Task<AuthenticationResult> ExecuteAsync(CancellationTok
                         AuthenticationRequestParameters.RequestContext.CorrelationId,
                         TokenSource.Cache);
                 }
+                else if (cachedAccessTokenItem == null)
+                {
+                    cacheRefresh = CacheRefresh.NoCachedAT;
+                }
+                else
+                {
+                    cacheRefresh = CacheRefresh.RefreshIn;
+                }
             }
             else
             {
                 logger.Info("Skipped looking for an Access Token in the cache because ForceRefresh or Claims were set. ");
+
+                if (_clientParameters.ForceRefresh)
+                {
+                    cacheRefresh = CacheRefresh.ForceRefresh;
+                }
+            }
+
+            if (AuthenticationRequestParameters.RequestContext.ApiEvent.CacheRefresh == null)
+            {
+                AuthenticationRequestParameters.RequestContext.ApiEvent.CacheRefresh = (int)cacheRefresh;
             }
 
             // No AT in the cache or AT needs to be refreshed

diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs
@@ -9,6 +9,7 @@
 using Microsoft.Identity.Client.OAuth2;
 using Microsoft.Identity.Client.TelemetryCore.Internal.Events;
 using System.Linq;
+using Microsoft.Identity.Client.Region;
 
 namespace Microsoft.Identity.Client.Internal.Requests
 {
@@ -35,6 +36,7 @@ protected override async Task<AuthenticationResult> ExecuteAsync(CancellationTok
             }
 
             await ResolveAuthorityEndpointsAsync().ConfigureAwait(false);
+            CacheRefresh cacheRefresh = CacheRefresh.None;
 
             if (!_onBehalfOfParameters.ForceRefresh)
             {
@@ -59,6 +61,19 @@ protected override async Task<AuthenticationResult> ExecuteAsync(CancellationTok
                         AuthenticationRequestParameters.RequestContext.CorrelationId,
                         TokenSource.Cache);
                 }
+                else
+                {
+                    cacheRefresh = CacheRefresh.NoCachedAT;
+                }
+            }
+            else
+            {
+                cacheRefresh = CacheRefresh.ForceRefresh;
+            }
+
+            if (AuthenticationRequestParameters.RequestContext.ApiEvent.CacheRefresh == null)
+            {
+                AuthenticationRequestParameters.RequestContext.ApiEvent.CacheRefresh = (int)cacheRefresh;
             }
 
             var msalTokenResponse = await SendTokenRequestAsync(GetBodyParameters(), cancellationToken).ConfigureAwait(false);

diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs
@@ -11,6 +11,7 @@
 using Microsoft.Identity.Client.Cache.Items;
 using Microsoft.Identity.Client.Instance;
 using Microsoft.Identity.Client.OAuth2;
+using Microsoft.Identity.Client.Region;
 
 namespace Microsoft.Identity.Client.Internal.Requests.Silent
 {
@@ -39,6 +40,7 @@ public async Task<AuthenticationResult> ExecuteAsync(CancellationToken cancellat
         {
             var logger = AuthenticationRequestParameters.RequestContext.Logger;
             MsalAccessTokenCacheItem cachedAccessTokenItem = null;
+            CacheRefresh cacheRefresh = CacheRefresh.None;
 
             ThrowIfNoScopesOnB2C();
             ThrowIfCurrentBrokerAccount();
@@ -54,12 +56,26 @@ public async Task<AuthenticationResult> ExecuteAsync(CancellationToken cancellat
                     AuthenticationRequestParameters.RequestContext.ApiEvent.IsAccessTokenCacheHit = true;
                     return await CreateAuthenticationResultAsync(cachedAccessTokenItem).ConfigureAwait(false);
                 }
+                else if (cachedAccessTokenItem == null)
+                {
+                    cacheRefresh = CacheRefresh.NoCachedAT;
+                } 
+                else
+                {
+                    cacheRefresh = CacheRefresh.RefreshIn;
+                }
             }
             else
             {
+                cacheRefresh = CacheRefresh.ForceRefresh;
                 logger.Info("Skipped looking for an Access Token because ForceRefresh or Claims were set. ");
             }
 
+            if (AuthenticationRequestParameters.RequestContext.ApiEvent.CacheRefresh == null)
+            {
+                AuthenticationRequestParameters.RequestContext.ApiEvent.CacheRefresh = (int)cacheRefresh;
+            }
+
             // No AT or AT.RefreshOn > Now --> refresh the RT
             try
             {

diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/Http/HttpTelemetryManager.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/Http/HttpTelemetryManager.cs
@@ -48,7 +48,7 @@ public void RecordStoppedEvent(ApiEvent stoppedEvent)
 
         /// <summary>
         /// CSV expected format:
-        ///      2|silent_successful_count|failed_requests|errors|platform_fields
+        ///      3|silent_successful_count|failed_requests|errors|platform_fields
         ///      failed_request is: api_id_1,correlation_id_1,api_id_2,correlation_id_2|error_1,error_2
         ///      platform_fields: region_1,region_source_1,region_2,region_source_2
         /// </summary>
@@ -105,7 +105,7 @@ public string GetLastRequestHeader()
         }
 
         /// <summary>
-        /// Expected format: 2|api_id,force_refresh|platform_config
+        /// Expected format: 3|api_id,force_refresh,cache_refresh|platform_config
         /// platform_config: region,region_source,is_token_cache_serialized,user_provided_region,validate_use_region,fallback_to_global,is_legacy_cache_enabled
         /// </summary>
         public string GetCurrentRequestHeader(ApiEvent eventInProgress)
@@ -124,6 +124,7 @@ public string GetCurrentRequestHeader(ApiEvent eventInProgress)
             eventInProgress.TryGetValue(MsalTelemetryBlobEventNames.IsValidUserProvidedRegion, out string isValidUserProvidedRegion);
             eventInProgress.TryGetValue(MsalTelemetryBlobEventNames.IsLegacyCacheEnabledKey, out string isLegacyCacheEnabled);
             eventInProgress.TryGetValue(MsalTelemetryBlobEventNames.FallbackToGlobal, out string fallbackToGlobal);
+            eventInProgress.TryGetValue(MsalTelemetryBlobEventNames.CacheRefreshKey, out string cacheRefresh);
 
             // Since regional fields will only be logged in case it is opted.
             var platformConfig = new StringBuilder();
@@ -137,7 +138,7 @@ public string GetCurrentRequestHeader(ApiEvent eventInProgress)
             platformConfig.Append(ConvertFromStringToBitwise(isLegacyCacheEnabled));
 
             return $"{TelemetryConstants.HttpTelemetrySchemaVersion2}" +
-                $"|{apiId},{ConvertFromStringToBitwise(forceRefresh)}" +
+                $"|{apiId},{ConvertFromStringToBitwise(forceRefresh)},{cacheRefresh}" +
                 $"|{platformConfig}";
         }
 

diff --git a/...Microsoft.Identity.Client/TelemetryCore/Internal/Constants/MsalTelemetryBlobEventNames.cs b/...Microsoft.Identity.Client/TelemetryCore/Internal/Constants/MsalTelemetryBlobEventNames.cs
@@ -31,5 +31,6 @@ internal static class MsalTelemetryBlobEventNames
         public const string IsValidUserProvidedRegion = "msal.is_valid_user_provided_region";
         public const string FallbackToGlobal = "msal.fallback_to_global";
         public const string IsLegacyCacheEnabledKey = "msal.is_legacy_cache_enabled";
+        public const string CacheRefreshKey = "msal.cache_refresh";
     }
 }
diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/Internal/Events/ApiEvent.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/Internal/Events/ApiEvent.cs
@@ -7,6 +7,7 @@
 using Microsoft.Identity.Client.TelemetryCore.Internal.Constants;
 using Microsoft.Identity.Client.PlatformsCommon.Interfaces;
 using Microsoft.Identity.Client.Region;
+using Microsoft.Identity.Client.Cache;
 
 namespace Microsoft.Identity.Client.TelemetryCore.Internal.Events
 {
@@ -29,6 +30,7 @@ internal class ApiEvent : EventBase
         public const string IsValidUserProvidedRegionKey = EventNamePrefix + "is_valid_user_provided_region";
         public const string FallbackToGlobalKey = EventNamePrefix + "fallback_to_global";
         public const string IsLegacyCacheEnabledKey = EventNamePrefix + "is_legacy_cache_enabled";
+        public const string CacheRefreshKey = EventNamePrefix + "cache_refresh";
 
         public enum ApiIds
         {
@@ -230,5 +232,24 @@ public bool IsLegacyCacheEnabled
             get { return this[IsLegacyCacheEnabledKey] == true.ToString().ToLowerInvariant(); }
 #pragma warning restore CA1305 // Specify IFormatProvider
         }
+
+        public int? CacheRefresh
+        {
+            get
+            {
+                if (this.ContainsKey(CacheRefreshKey))
+                {
+                    int val = (int)Enum.Parse(typeof(CacheRefresh), this[CacheRefreshKey]);
+                    if (val != -1)
+                    {
+                        return val;
+                    }
+                }
+
+                return null;
+            }
+
+            set => this[CacheRefreshKey] = (value)?.ToString(CultureInfo.InvariantCulture);
+        }
     }
 }
diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/TelemetryConstants.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/TelemetryConstants.cs
@@ -11,7 +11,7 @@ internal static class TelemetryError
 
     internal static class TelemetryConstants
     {
-        public const string HttpTelemetrySchemaVersion2 = "2";
+        public const string HttpTelemetrySchemaVersion2 = "3";
         public const string HttpTelemetryPipe = "|";
         public const string XClientCurrentTelemetry = "x-client-current-telemetry";
         public const string XClientLastTelemetry = "x-client-last-telemetry";

diff --git a/src/client/Microsoft.Identity.Client/TokenCache.ITokenCacheInternal.cs b/src/client/Microsoft.Identity.Client/TokenCache.ITokenCacheInternal.cs
@@ -15,6 +15,7 @@
 using Microsoft.Identity.Client.Internal;
 using Microsoft.Identity.Client.Internal.Requests;
 using Microsoft.Identity.Client.OAuth2;
+using Microsoft.Identity.Client.Region;
 using Microsoft.Identity.Client.Utils;
 
 namespace Microsoft.Identity.Client
@@ -325,17 +326,28 @@ async Task<MsalAccessTokenCacheItem> ITokenCacheInternal.FindAccessTokenAsync(
             // perf: take a snapshot as calling Count(), Any() etc. on the IEnumerable evaluates it each time
             IReadOnlyList<MsalAccessTokenCacheItem> finalList = tokenCacheItems.ToList();
 
+            CacheRefresh cacheRefresh = CacheRefresh.None;
+
             // no match
             if (finalList.Count == 0)
             {
                 logger.Verbose("No tokens found for matching authority, client_id, user and scopes.");
+                cacheRefresh = CacheRefresh.NoCachedAT;
                 return null;
             }
 
             MsalAccessTokenCacheItem msalAccessTokenCacheItem = GetSingleResult(requestParams, finalList);
             msalAccessTokenCacheItem = FilterByKeyId(msalAccessTokenCacheItem, requestParams);
+            msalAccessTokenCacheItem = FilterByExpiry(msalAccessTokenCacheItem, requestParams);
+
+            if (msalAccessTokenCacheItem == null)
+            {
+                cacheRefresh = CacheRefresh.Expired;
+            }
+
+            requestParams.RequestContext.ApiEvent.CacheRefresh = (int) cacheRefresh;
 
-            return FilterByExpiry(msalAccessTokenCacheItem, requestParams);
+            return msalAccessTokenCacheItem; 
         }
 
         private static IEnumerable<MsalAccessTokenCacheItem> FilterByScopes(

diff --git a/tests/Microsoft.Identity.Test.Common/Core/Mocks/MockHttpAndServiceBundle.cs b/tests/Microsoft.Identity.Test.Common/Core/Mocks/MockHttpAndServiceBundle.cs
@@ -9,6 +9,7 @@
 using Microsoft.Identity.Client.Instance;
 using Microsoft.Identity.Client.Internal;
 using Microsoft.Identity.Client.Internal.Requests;
+using Microsoft.Identity.Client.TelemetryCore.Internal;
 using Microsoft.Identity.Client.TelemetryCore.Internal.Events;
 using Microsoft.Identity.Test.Unit;
 using Microsoft.VisualStudio.TestTools.UnitTesting;
@@ -62,7 +63,7 @@ public AuthenticationRequestParameters CreateAuthenticationRequestParameters(
                 ApiId = apiId
             };
 
-            return new AuthenticationRequestParameters(
+            AuthenticationRequestParameters authenticationRequestParameters = new AuthenticationRequestParameters(
                 ServiceBundle,
                 tokenCache,
                 commonParameters,
@@ -71,6 +72,13 @@ public AuthenticationRequestParameters CreateAuthenticationRequestParameters(
                 Account = account,
                 Authority = Authority.CreateAuthority(authority, validateAuthority)
             };
+
+            authenticationRequestParameters.RequestContext.ApiEvent = new ApiEvent(
+                authenticationRequestParameters.RequestContext.Logger,
+                ServiceBundle.PlatformProxy.CryptographyManager,
+                Guid.NewGuid().AsMatsCorrelationId());
+
+            return authenticationRequestParameters;
         }
     }
 }
diff --git a/...s/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/RegionalAuthIntegrationTests.cs b/...s/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/RegionalAuthIntegrationTests.cs
@@ -103,7 +103,7 @@ public async Task AcquireTokenToRegionalEndpointAsync()
             AuthenticationResult result = await GetAuthenticationResultAsync().ConfigureAwait(false); // regional endpoint
             AssertTokenSource_IsIdP(result);
             AssertValidHost(true, factory);
-            AssertTelemetry(factory, "2|1004,0|centralus,1,0,,,0,1");
+            AssertTelemetry(factory, "3|1004,0,0|centralus,1,0,,,0,1");
 
         }
 
@@ -125,12 +125,12 @@ public async Task AcquireTokenUserProvidedRegionSameAsRegionDetectedAsync()
             AuthenticationResult result = await GetAuthenticationResultAsync(userProvidedRegion: TestConstants.Region).ConfigureAwait(false); // regional endpoint
             AssertTokenSource_IsIdP(result);
             AssertValidHost(true, factory);
-            AssertTelemetry(factory, "2|1004,0|centralus,1,0,centralus,1,0,1");
+            AssertTelemetry(factory, "3|1004,0,0|centralus,1,0,centralus,1,0,1");
 
             result = await GetAuthenticationResultAsync(userProvidedRegion: TestConstants.Region, withForceRefresh: true).ConfigureAwait(false); // regional endpoint
             AssertTokenSource_IsIdP(result);
             AssertValidHost(true, factory, 1);
-            AssertTelemetry(factory, "2|1004,1|centralus,3,0,centralus,,0,1", 1);
+            AssertTelemetry(factory, "3|1004,1,3|centralus,3,0,centralus,,0,1", 1);
 
         }
 
@@ -152,12 +152,12 @@ public async Task AcquireTokenUserProvidedRegionDifferentFromRegionDetectedAsync
             AuthenticationResult result = await GetAuthenticationResultAsync(userProvidedRegion: "invalid").ConfigureAwait(false); // regional endpoint
             AssertTokenSource_IsIdP(result);
             AssertValidHost(true, factory);
-            AssertTelemetry(factory, "2|1004,0|centralus,1,0,invalid,0,0,1");
+            AssertTelemetry(factory, "3|1004,0,0|centralus,1,0,invalid,0,0,1");
 
             result = await GetAuthenticationResultAsync(userProvidedRegion: TestConstants.Region, withForceRefresh: true).ConfigureAwait(false); // regional endpoint
             AssertTokenSource_IsIdP(result);
             AssertValidHost(true, factory, 1);
-            AssertTelemetry(factory, "2|1004,1|centralus,3,0,centralus,,0,1", 1);
+            AssertTelemetry(factory, "3|1004,1,3|centralus,3,0,centralus,,0,1", 1);
 
         }
 

diff --git a/...crosoft.Identity.Test.Integration.netfx/HeadlessTests/UsernamePasswordIntegrationTests.cs b/...crosoft.Identity.Test.Integration.netfx/HeadlessTests/UsernamePasswordIntegrationTests.cs
@@ -29,11 +29,11 @@ public class UsernamePasswordIntegrationTests
 
         // HTTP Telemetry Constants
         private static Guid CorrelationId = new Guid("ad8c894a-557f-48c0-b045-c129590c344e");
-        private const string XClientCurrentTelemetryROPC = "2|1003,0|,,0,,,,1";
-        private const string XClientCurrentTelemetryROPCFailure = "2|1003,0|,,0,,,,1";
-        private const string XClientLastTelemetryROPC = "2|0|||";
+        private const string XClientCurrentTelemetryROPC = "3|1003,0,|,,0,,,,1";
+        private const string XClientCurrentTelemetryROPCFailure = "3|1003,0,|,,0,,,,1";
+        private const string XClientLastTelemetryROPC = "3|0|||";
         private const string XClientLastTelemetryROPCFailure =
-            "2|0|1003,ad8c894a-557f-48c0-b045-c129590c344e|invalid_grant|,";
+            "3|0|1003,ad8c894a-557f-48c0-b045-c129590c344e|invalid_grant|,";
         private const string ApiIdAndCorrelationIdSection =
             "1003,ad8c894a-557f-48c0-b045-c129590c344e";
         private const string InvalidGrantError = "invalid_grant";

diff --git a/tests/Microsoft.Identity.Test.Integration.netfx/Infrastructure/HttpTelemetryRecorder.cs b/tests/Microsoft.Identity.Test.Integration.netfx/Infrastructure/HttpTelemetryRecorder.cs
@@ -25,7 +25,7 @@ public void SplitCurrentCsv(string telemetryCsv)
             string[] splitCsv = telemetryCsv.Split('|');
             string[] splitApiIdAndForceRefresh = splitCsv[1].Split(',');
             ApiId.Add(splitApiIdAndForceRefresh[0]);
-            string forceRefresh = splitApiIdAndForceRefresh[splitApiIdAndForceRefresh.Length - 1];
+            string forceRefresh = splitApiIdAndForceRefresh[splitApiIdAndForceRefresh.Length - 2];
             ForceRefresh = forceRefresh;
         }
 

diff --git a/tests/Microsoft.Identity.Test.Unit/CacheTests/TokenCacheTests.cs b/tests/Microsoft.Identity.Test.Unit/CacheTests/TokenCacheTests.cs
@@ -15,6 +15,7 @@
 using Microsoft.Identity.Client.Internal.Requests;
 using Microsoft.Identity.Client.OAuth2;
 using Microsoft.Identity.Client.PlatformsCommon.Interfaces;
+using Microsoft.Identity.Client.TelemetryCore.Internal;
 using Microsoft.Identity.Client.TelemetryCore.Internal.Events;
 using Microsoft.Identity.Client.Utils;
 using Microsoft.Identity.Test.Common;
@@ -1108,6 +1109,10 @@ public void FindAccessToken_ScopeCaseInsensitive()
                 serviceBundle, 
                 scopes: new HashSet<string>());
             requestParams.Account = TestConstants.s_user;
+            requestParams.RequestContext.ApiEvent = new ApiEvent(
+                serviceBundle.DefaultLogger,
+                serviceBundle.PlatformProxy.CryptographyManager,
+                Guid.NewGuid().AsMatsCorrelationId());
 
             string scopeInCache = TestConstants.s_scope.FirstOrDefault();