From 53e202d585ce8a8abcf3cc05d98c606792c6c21d Mon Sep 17 00:00:00 2001 From: Neha Bhargava <61847233+neha-bhargava@users.noreply.github.com> Date: Mon, 22 Jan 2024 16:34:07 -0800 Subject: [PATCH 1/7] For proactive refresh log error to otel and change token source to IDP --- .../AuthenticationResultMetadata.cs | 2 +- .../Requests/ClientCredentialRequest.cs | 3 +- .../Requests/ManagedIdentityAuthRequest.cs | 4 +- .../Internal/Requests/OnBehalfOfRequest.cs | 3 +- .../Internal/Requests/RequestBase.cs | 10 +- .../Requests/Silent/CacheSilentStrategy.cs | 3 +- .../Internal/Requests/SilentRequestHelper.cs | 21 ++- .../OpenTelemetry/OtelInstrumentation.cs | 23 ++- .../OpenTelemetry/IOtelInstrumentation.cs | 2 +- .../OpenTelemetry/NullOtelInstrumentation.cs | 2 +- .../TelemetryCore/TelemetryConstants.cs | 1 + .../OTelInstrumentationTests.cs | 162 ++++++++++++++++-- 12 files changed, 197 insertions(+), 39 deletions(-) diff --git a/src/client/Microsoft.Identity.Client/AuthenticationResultMetadata.cs b/src/client/Microsoft.Identity.Client/AuthenticationResultMetadata.cs index 666ecfad21..e5dc5f094c 100644 --- a/src/client/Microsoft.Identity.Client/AuthenticationResultMetadata.cs +++ b/src/client/Microsoft.Identity.Client/AuthenticationResultMetadata.cs @@ -24,7 +24,7 @@ public AuthenticationResultMetadata(TokenSource tokenSource) /// /// The source of the token in the result. /// - public TokenSource TokenSource { get; } + public TokenSource TokenSource { get; internal set; } /// /// The token endpoint used to contact the Identity Provider (e.g. Azure Active Directory). diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs index 49345f0056..f18be0b1e6 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs @@ -71,6 +71,7 @@ protected override async Task ExecuteAsync(CancellationTok if (proactivelyRefresh) { AuthenticationRequestParameters.RequestContext.ApiEvent.CacheInfo = CacheRefreshReason.ProactivelyRefreshed; + authResult.AuthenticationResultMetadata.TokenSource = TokenSource.IdentityProvider; SilentRequestHelper.ProcessFetchInBackground( cachedAccessTokenItem, @@ -79,7 +80,7 @@ protected override async Task ExecuteAsync(CancellationTok // Use a linked token source, in case the original cancellation token source is disposed before this background task completes. using var tokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); return GetAccessTokenAsync(tokenSource.Token, logger); - }, logger); + }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId.ToString()); } } catch (MsalServiceException e) diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/ManagedIdentityAuthRequest.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/ManagedIdentityAuthRequest.cs index 6f3ddf0ff2..99c1fb6a28 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/ManagedIdentityAuthRequest.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/ManagedIdentityAuthRequest.cs @@ -61,6 +61,7 @@ protected override async Task ExecuteAsync(CancellationTok logger.Info("[ManagedIdentityRequest] Initiating a proactive refresh."); AuthenticationRequestParameters.RequestContext.ApiEvent.CacheInfo = CacheRefreshReason.ProactivelyRefreshed; + authResult.AuthenticationResultMetadata.TokenSource = TokenSource.IdentityProvider; SilentRequestHelper.ProcessFetchInBackground( cachedAccessTokenItem, @@ -69,7 +70,7 @@ protected override async Task ExecuteAsync(CancellationTok // Use a linked token source, in case the original cancellation token source is disposed before this background task completes. using var tokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); return GetAccessTokenAsync(tokenSource.Token, logger); - }, logger); + }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId.ToString()); } } catch (MsalServiceException e) @@ -99,7 +100,6 @@ private async Task GetAccessTokenAsync( AuthenticationResult authResult; MsalAccessTokenCacheItem cachedAccessTokenItem = null; - // Requests to a managed identity endpoint must be throttled; // otherwise, the endpoint will throw a HTTP 429. logger.Verbose(() => "[ManagedIdentityRequest] Entering managed identity request semaphore."); diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs index ca1aa7c3bf..83773542a5 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs @@ -120,6 +120,7 @@ protected override async Task ExecuteAsync(CancellationTok if (shouldRefresh) { AuthenticationRequestParameters.RequestContext.ApiEvent.CacheInfo = CacheRefreshReason.ProactivelyRefreshed; + authResult.AuthenticationResultMetadata.TokenSource = TokenSource.IdentityProvider; SilentRequestHelper.ProcessFetchInBackground( cachedAccessToken, @@ -128,7 +129,7 @@ protected override async Task ExecuteAsync(CancellationTok // Use a linked token source, in case the original cancellation token source is disposed before this background task completes. using var tokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); return RefreshRtOrFetchNewAccessTokenAsync(tokenSource.Token); - }, logger); + }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId.ToString()); } } diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs index 44f0e74f63..1b73e2198e 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs @@ -106,7 +106,7 @@ public async Task RunAsync(CancellationToken cancellationT AuthenticationRequestParameters.RequestContext.Logger.ErrorPii(ex); LogMsalErrorTelemetryToClient(ex, telemetryEventDetails, telemetryClients); - LogMsalFailedTelemetryToOtel(ex, ex.ErrorCode); + LogMsalFailedTelemetryToOtel(ex.ErrorCode, apiEvent.ApiId.ToString()); throw; } catch (Exception ex) @@ -115,7 +115,7 @@ public async Task RunAsync(CancellationToken cancellationT AuthenticationRequestParameters.RequestContext.Logger.ErrorPii(ex); LogMsalErrorTelemetryToClient(ex, telemetryEventDetails, telemetryClients); - LogMsalFailedTelemetryToOtel(ex, ex.GetType().Name); + LogMsalFailedTelemetryToOtel(ex.GetType().Name, apiEvent.ApiId.ToString()); throw; } finally @@ -137,12 +137,14 @@ private void LogMsalSuccessTelemetryToOtel(AuthenticationResult authenticationRe AuthenticationRequestParameters.RequestContext.Logger); } - private void LogMsalFailedTelemetryToOtel(Exception exception, string errorCodeToLog) + private void LogMsalFailedTelemetryToOtel(string errorCodeToLog, string apiId) { // Log metrics ServiceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( ServiceBundle.PlatformProxy.GetProductName(), - errorCodeToLog); + errorCodeToLog, + apiId, + false); } private void LogMsalErrorTelemetryToClient(Exception ex, MsalTelemetryEventDetails telemetryEventDetails, ITelemetryClient[] telemetryClients) diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs index 4846bba076..8e10f2343a 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs @@ -90,6 +90,7 @@ public async Task ExecuteAsync(CancellationToken cancellat if (shouldRefresh) { AuthenticationRequestParameters.RequestContext.ApiEvent.CacheInfo = CacheRefreshReason.ProactivelyRefreshed; + authResult.AuthenticationResultMetadata.TokenSource = TokenSource.IdentityProvider; SilentRequestHelper.ProcessFetchInBackground( cachedAccessTokenItem, @@ -98,7 +99,7 @@ public async Task ExecuteAsync(CancellationToken cancellat // Use a linked token source, in case the original cancellation token source is disposed before this background task completes. using var tokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); return RefreshRtOrFailAsync(tokenSource.Token); - }, logger); + }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId.ToString()); } } diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs index 9886c0e7bf..9626585a1c 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs @@ -82,10 +82,14 @@ internal static bool NeedsRefresh(MsalAccessTokenCacheItem oldAccessToken, out D internal static void ProcessFetchInBackground( MsalAccessTokenCacheItem oldAccessToken, Func> fetchAction, - ILoggerAdapter logger) + ILoggerAdapter logger, + IServiceBundle serviceBundle, + string apiId) { _ = Task.Run(async () => { + string error = null; + try { await fetchAction().ConfigureAwait(false); @@ -101,14 +105,29 @@ internal static void ProcessFetchInBackground( { logger.ErrorPiiWithPrefix(ex, logMsg); } + + error = ex.ErrorCode; } catch (OperationCanceledException ex) { logger.WarningPiiWithPrefix(ex, ProactiveRefreshCancellationError); + error = ex.GetType().Name; } catch (Exception ex) { logger.ErrorPiiWithPrefix(ex, ProactiveRefreshGeneralError); + error = ex.GetType().Name; + } + finally + { + if (!string.IsNullOrEmpty(error)) + { + serviceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( + serviceBundle.PlatformProxy.GetProductName(), + error, + apiId, + true); + } } }); } diff --git a/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs index a0986b2d41..3e9897d06d 100644 --- a/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs @@ -95,13 +95,20 @@ void IOtelInstrumentation.LogSuccessMetrics( AuthenticationResultMetadata authResultMetadata, ILoggerAdapter logger) { + var tokenSource = authResultMetadata.TokenSource; + + //if (authResultMetadata.CacheRefreshReason == CacheRefreshReason.ProactivelyRefreshed) + //{ + // tokenSource = TokenSource.IdentityProvider; + //} + if (s_successCounter.Value.Enabled) { s_successCounter.Value.Add(1, new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), new(TelemetryConstants.Platform, platform), new(TelemetryConstants.ApiId, apiId), - new(TelemetryConstants.TokenSource, authResultMetadata.TokenSource), + new(TelemetryConstants.TokenSource, tokenSource), new(TelemetryConstants.CacheRefreshReason, authResultMetadata.CacheRefreshReason), new(TelemetryConstants.CacheLevel, cacheLevel)); logger.Info("[OpenTelemetry] Completed incrementing to isSuccessful counter."); @@ -113,7 +120,7 @@ void IOtelInstrumentation.LogSuccessMetrics( new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), new(TelemetryConstants.Platform, platform), new(TelemetryConstants.ApiId, apiId), - new(TelemetryConstants.TokenSource, authResultMetadata.TokenSource), + new(TelemetryConstants.TokenSource, tokenSource), new(TelemetryConstants.CacheLevel, cacheLevel)); } @@ -127,7 +134,7 @@ void IOtelInstrumentation.LogSuccessMetrics( } // Only log duration in HTTP when token is fetched from IDP - if (s_durationInHttp.Value.Enabled && authResultMetadata.TokenSource.Equals(TokenSource.IdentityProvider)) + if (s_durationInHttp.Value.Enabled && tokenSource.Equals(TokenSource.IdentityProvider)) { s_durationInHttp.Value.Record(authResultMetadata.DurationInHttpInMs, new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), @@ -136,26 +143,28 @@ void IOtelInstrumentation.LogSuccessMetrics( } // Only log duration in microseconds when the cache level is L1. - if (s_durationInL1CacheInUs.Value.Enabled && authResultMetadata.TokenSource.Equals(TokenSource.Cache) + if (s_durationInL1CacheInUs.Value.Enabled && tokenSource.Equals(TokenSource.Cache) && authResultMetadata.CacheLevel.Equals(CacheLevel.L1Cache)) { s_durationInL1CacheInUs.Value.Record(totalDurationInUs, new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), new(TelemetryConstants.Platform, platform), new(TelemetryConstants.ApiId, apiId), - new(TelemetryConstants.TokenSource, authResultMetadata.TokenSource), + new(TelemetryConstants.TokenSource, tokenSource), new(TelemetryConstants.CacheLevel, cacheLevel)); } } - void IOtelInstrumentation.LogFailedMetrics(string platform, string errorCode) + void IOtelInstrumentation.LogFailedMetrics(string platform, string errorCode, string apiId, bool isProactiveTokenRefresh) { if (s_failureCounter.Value.Enabled) { s_failureCounter.Value.Add(1, new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), new(TelemetryConstants.Platform, platform), - new(TelemetryConstants.ErrorCode, errorCode)); + new(TelemetryConstants.ErrorCode, errorCode), + new(TelemetryConstants.ApiId, apiId), + new(TelemetryConstants.IsProactiveRefresh, isProactiveTokenRefresh)); } } } diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs index 82b880b3ea..ff9844ef1e 100644 --- a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs @@ -16,6 +16,6 @@ internal void LogSuccessMetrics( long totalDurationInUs, AuthenticationResultMetadata authResultMetadata, ILoggerAdapter logger); - internal void LogFailedMetrics(string platform, string errorCode); + internal void LogFailedMetrics(string platform, string errorCode, string apiId, bool isProactiveTokenRefresh); } } diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs index f274dd0750..b5513509b6 100644 --- a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs @@ -23,7 +23,7 @@ public void LogSuccessMetrics( // No op } - public void LogFailedMetrics(string platform, string errorCode) + public void LogFailedMetrics(string platform, string errorCode, string apiId, bool isProactiveTokenRefresh) { // No op } diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/TelemetryConstants.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/TelemetryConstants.cs index 6163d5b5da..d92fe073f0 100644 --- a/src/client/Microsoft.Identity.Client/TelemetryCore/TelemetryConstants.cs +++ b/src/client/Microsoft.Identity.Client/TelemetryCore/TelemetryConstants.cs @@ -44,6 +44,7 @@ internal static class TelemetryConstants public const string ClientId = "ClientId"; public const string Platform = "Platform"; public const string ApiId = "ApiId"; + public const string IsProactiveRefresh = "IsProactiveRefresh"; #endregion } diff --git a/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs b/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs index cbe3a1b6a9..b90f18b9cb 100644 --- a/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs +++ b/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs @@ -10,6 +10,7 @@ using Microsoft.Identity.Client; using Microsoft.Identity.Client.Platforms.Features.OpenTelemetry; using Microsoft.Identity.Client.TelemetryCore; +using Microsoft.Identity.Test.Common; using Microsoft.Identity.Test.Common.Core.Helpers; using Microsoft.Identity.Test.Common.Core.Mocks; using Microsoft.VisualStudio.TestTools.UnitTesting; @@ -60,7 +61,101 @@ public async Task AcquireTokenOTelTestAsync() await AcquireTokenMsalClientExceptionAsync().ConfigureAwait(false); s_meterProvider.ForceFlush(); - VerifyMetrics(5, _exportedMetrics); + VerifyMetrics(5, _exportedMetrics, 2, 2); + } + } + + [TestMethod] + [Description("AT in cache, needs refresh. AAD responds well to Refresh.")] + public async Task ProactiveTokenRefresh_ValidResponse_Async() + { + // Arrange + using (_harness = base.CreateTestHarness()) + { + Trace.WriteLine("1. Setup an app"); + CreateApplication(); + TokenCacheHelper.PopulateCache(_cca.AppTokenCacheInternal.Accessor, addSecondAt: false); + + Trace.WriteLine("2. Configure AT so that it shows it needs to be refreshed"); + var refreshOn = TestCommon.UpdateATWithRefreshOn(_cca.AppTokenCacheInternal.Accessor).RefreshOn; + + TokenCacheAccessRecorder cacheAccess = _cca.AppTokenCache.RecordAccess(); + + Trace.WriteLine("3. Configure AAD to respond with valid token to the refresh RT flow"); + _harness.HttpManager.AddAllMocks(TokenResponseType.Valid_ClientCredentials); + + // Act + Trace.WriteLine("4. ATS - should perform an RT refresh"); + AuthenticationResult result = await _cca.AcquireTokenForClient(TestConstants.s_scope) + .ExecuteAsync() + .ConfigureAwait(false); + + // Assert + TestCommon.YieldTillSatisfied(() => _harness.HttpManager.QueueSize == 0); + Assert.IsNotNull(result); + Assert.AreEqual(0, _harness.HttpManager.QueueSize, + "MSAL should have refreshed the token because the original AT was marked for refresh"); + cacheAccess.WaitTo_AssertAcessCounts(1, 1); + Assert.IsTrue(result.AuthenticationResultMetadata.CacheRefreshReason == CacheRefreshReason.ProactivelyRefreshed); + Assert.IsTrue(result.AuthenticationResultMetadata.RefreshOn == refreshOn); + + result = await _cca.AcquireTokenForClient(TestConstants.s_scope) + .ExecuteAsync() + .ConfigureAwait(false); + + Assert.IsTrue(result.AuthenticationResultMetadata.CacheRefreshReason == CacheRefreshReason.NotApplicable); + + s_meterProvider.ForceFlush(); + VerifyMetrics(3, _exportedMetrics, 2, 0); + } + } + + [TestMethod] + [Description("AT in cache, needs refresh. AAD is unavailable when refreshing.")] + public async Task ProactiveTokenRefresh_AadUnavailableResponse_Async() + { + // Arrange + using (_harness = base.CreateTestHarness()) + { + Trace.WriteLine("1. Setup an app "); + CreateApplication(); + TokenCacheHelper.PopulateCache(_cca.AppTokenCacheInternal.Accessor, addSecondAt: false); + + Trace.WriteLine("2. Configure AT so that it shows it needs to be refreshed"); + + TestCommon.UpdateATWithRefreshOn(_cca.AppTokenCacheInternal.Accessor); + + TokenCacheAccessRecorder cacheAccess = _cca.AppTokenCache.RecordAccess(); + + Trace.WriteLine("3. Configure AAD to respond with an error"); + _harness.HttpManager.AddAllMocks(TokenResponseType.Invalid_AADUnavailable503); + _harness.HttpManager.AddTokenResponse(TokenResponseType.Invalid_AADUnavailable503); + + // Act + AuthenticationResult result = await _cca.AcquireTokenForClient(TestConstants.s_scope) + .ExecuteAsync() + .ConfigureAwait(false); + + // Assert + Assert.IsNotNull(result, "ClientCredentials should still succeeds even though AAD is unavailable"); + TestCommon.YieldTillSatisfied(() => _harness.HttpManager.QueueSize == 0); + Assert.AreEqual(0, _harness.HttpManager.QueueSize); + cacheAccess.WaitTo_AssertAcessCounts(1, 0); // the refresh failed, no new data is written to the cache + + // Now let AAD respond with tokens + _harness.HttpManager.AddTokenResponse(TokenResponseType.Valid_ClientCredentials); + + result = await _cca.AcquireTokenForClient(TestConstants.s_scope) + .ExecuteAsync() + .ConfigureAwait(false); + Assert.IsNotNull(result); + + cacheAccess.WaitTo_AssertAcessCounts(2, 1); // new tokens written to cache + + Thread.Sleep(1000); + + s_meterProvider.ForceFlush(); + VerifyMetrics(4, _exportedMetrics, 2, 1); } } @@ -74,16 +169,15 @@ private async Task AcquireTokenSuccessAsync() .ExecuteAsync(CancellationToken.None).ConfigureAwait(false); Assert.IsNotNull(result); - // Acquire token silently - var account = (await _cca.GetAccountsAsync().ConfigureAwait(false)).Single(); - result = await _cca.AcquireTokenSilent(TestConstants.s_scope, account) - .ExecuteAsync().ConfigureAwait(false); + // Acquire token from the cache + //var account = (await _cca.GetAccountsAsync().ConfigureAwait(false)).Single(); + result = await _cca.AcquireTokenForClient(TestConstants.s_scope) + .ExecuteAsync(CancellationToken.None).ConfigureAwait(false); Assert.IsNotNull(result); } private async Task AcquireTokenMsalServiceExceptionAsync() { - _harness.HttpManager.AddTokenResponse(TokenResponseType.InvalidClient); //Test for MsalServiceException @@ -116,16 +210,15 @@ private void CreateApplication() .WithClientSecret(TestConstants.ClientSecret) .WithHttpManager(_harness.HttpManager) .BuildConcrete(); - TokenCacheHelper.PopulateCache(_cca.UserTokenCacheInternal.Accessor); } - private void VerifyMetrics(int expectedMetricCount, List exportedMetrics) + private void VerifyMetrics(int expectedMetricCount, List exportedMetrics, + long expectedSuccessfulRequests, long expectedFailedRequests) { Assert.AreEqual(expectedMetricCount, exportedMetrics.Count); foreach (Metric exportedItem in exportedMetrics) { - int expectedTagCount = 0; List expectedTags = new List(); Assert.AreEqual(OtelInstrumentation.MeterName, exportedItem.MeterName); @@ -135,7 +228,6 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics case "MsalSuccess": Assert.AreEqual(MetricType.LongSum, exportedItem.MetricType); - expectedTagCount = 6; expectedTags.Add(TelemetryConstants.MsalVersion); expectedTags.Add(TelemetryConstants.Platform); expectedTags.Add(TelemetryConstants.ApiId); @@ -143,59 +235,94 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics expectedTags.Add(TelemetryConstants.CacheRefreshReason); expectedTags.Add(TelemetryConstants.CacheLevel); + long totalSuccessfulRequests = 0; + foreach (var metricPoint in exportedItem.GetMetricPoints()) + { + totalSuccessfulRequests += metricPoint.GetSumLong(); + AssertTags(metricPoint.Tags, 6, expectedTags); + } + + Assert.AreEqual(expectedSuccessfulRequests, totalSuccessfulRequests); + break; case "MsalFailure": Assert.AreEqual(MetricType.LongSum, exportedItem.MetricType); - expectedTagCount = 3; expectedTags.Add(TelemetryConstants.MsalVersion); expectedTags.Add(TelemetryConstants.Platform); expectedTags.Add(TelemetryConstants.ErrorCode); + expectedTags.Add(TelemetryConstants.ApiId); + expectedTags.Add(TelemetryConstants.IsProactiveRefresh); + + long totalFailedRequests = 0; + foreach (var metricPoint in exportedItem.GetMetricPoints()) + { + totalFailedRequests += metricPoint.GetSumLong(); + AssertTags(metricPoint.Tags, 5, expectedTags); + } + + Assert.AreEqual(expectedFailedRequests, totalFailedRequests); break; case "MsalTotalDuration.1A": Assert.AreEqual(MetricType.Histogram, exportedItem.MetricType); - expectedTagCount = 5; expectedTags.Add(TelemetryConstants.MsalVersion); expectedTags.Add(TelemetryConstants.Platform); expectedTags.Add(TelemetryConstants.ApiId); expectedTags.Add(TelemetryConstants.TokenSource); expectedTags.Add(TelemetryConstants.CacheLevel); + foreach (var metricPoint in exportedItem.GetMetricPoints()) + { + AssertTags(metricPoint.Tags, 5, expectedTags); + } + break; case "MsalDurationInL1CacheInUs.1B": Assert.AreEqual(MetricType.Histogram, exportedItem.MetricType); - expectedTagCount = 5; expectedTags.Add(TelemetryConstants.MsalVersion); expectedTags.Add(TelemetryConstants.Platform); expectedTags.Add(TelemetryConstants.ApiId); expectedTags.Add(TelemetryConstants.TokenSource); expectedTags.Add(TelemetryConstants.CacheLevel); + foreach (var metricPoint in exportedItem.GetMetricPoints()) + { + AssertTags(metricPoint.Tags, 5, expectedTags); + } + break; case "MsalDurationInL2Cache.1A": Assert.AreEqual(MetricType.Histogram, exportedItem.MetricType); - expectedTagCount = 3; expectedTags.Add(TelemetryConstants.MsalVersion); expectedTags.Add(TelemetryConstants.Platform); expectedTags.Add(TelemetryConstants.ApiId); + foreach (var metricPoint in exportedItem.GetMetricPoints()) + { + AssertTags(metricPoint.Tags, 3, expectedTags); + } + break; case "MsalDurationInHttp.1A": Assert.AreEqual(MetricType.Histogram, exportedItem.MetricType); - expectedTagCount = 3; expectedTags.Add(TelemetryConstants.MsalVersion); expectedTags.Add(TelemetryConstants.Platform); expectedTags.Add(TelemetryConstants.ApiId); + foreach (var metricPoint in exportedItem.GetMetricPoints()) + { + AssertTags(metricPoint.Tags, 3, expectedTags); + } + break; default: @@ -203,10 +330,7 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics break; } - foreach (var metricPoint in exportedItem.GetMetricPoints()) - { - AssertTags(metricPoint.Tags, expectedTagCount, expectedTags); - } + } } From 00cc21ed8958402fbccb52db1659aedcf3854145 Mon Sep 17 00:00:00 2001 From: Neha Bhargava <61847233+neha-bhargava@users.noreply.github.com> Date: Wed, 24 Jan 2024 09:46:50 -0800 Subject: [PATCH 2/7] Address comments --- .../Requests/ClientCredentialRequest.cs | 3 +- .../Requests/ManagedIdentityAuthRequest.cs | 3 +- .../Internal/Requests/OnBehalfOfRequest.cs | 3 +- .../Internal/Requests/RequestBase.cs | 12 ++++---- .../Requests/Silent/CacheSilentStrategy.cs | 3 +- .../Internal/Requests/SilentRequestHelper.cs | 28 +++++++++---------- .../OpenTelemetry/OtelInstrumentation.cs | 21 +++++++------- .../OpenTelemetry/IOtelInstrumentation.cs | 8 ++++-- .../OpenTelemetry/NullOtelInstrumentation.cs | 8 ++++-- 9 files changed, 45 insertions(+), 44 deletions(-) diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs index f18be0b1e6..e297c2c9c5 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/ClientCredentialRequest.cs @@ -71,7 +71,6 @@ protected override async Task ExecuteAsync(CancellationTok if (proactivelyRefresh) { AuthenticationRequestParameters.RequestContext.ApiEvent.CacheInfo = CacheRefreshReason.ProactivelyRefreshed; - authResult.AuthenticationResultMetadata.TokenSource = TokenSource.IdentityProvider; SilentRequestHelper.ProcessFetchInBackground( cachedAccessTokenItem, @@ -80,7 +79,7 @@ protected override async Task ExecuteAsync(CancellationTok // Use a linked token source, in case the original cancellation token source is disposed before this background task completes. using var tokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); return GetAccessTokenAsync(tokenSource.Token, logger); - }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId.ToString()); + }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId); } } catch (MsalServiceException e) diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/ManagedIdentityAuthRequest.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/ManagedIdentityAuthRequest.cs index 99c1fb6a28..b0f3c57b21 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/ManagedIdentityAuthRequest.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/ManagedIdentityAuthRequest.cs @@ -61,7 +61,6 @@ protected override async Task ExecuteAsync(CancellationTok logger.Info("[ManagedIdentityRequest] Initiating a proactive refresh."); AuthenticationRequestParameters.RequestContext.ApiEvent.CacheInfo = CacheRefreshReason.ProactivelyRefreshed; - authResult.AuthenticationResultMetadata.TokenSource = TokenSource.IdentityProvider; SilentRequestHelper.ProcessFetchInBackground( cachedAccessTokenItem, @@ -70,7 +69,7 @@ protected override async Task ExecuteAsync(CancellationTok // Use a linked token source, in case the original cancellation token source is disposed before this background task completes. using var tokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); return GetAccessTokenAsync(tokenSource.Token, logger); - }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId.ToString()); + }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId); } } catch (MsalServiceException e) diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs index 83773542a5..f3f297a1f4 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/OnBehalfOfRequest.cs @@ -120,7 +120,6 @@ protected override async Task ExecuteAsync(CancellationTok if (shouldRefresh) { AuthenticationRequestParameters.RequestContext.ApiEvent.CacheInfo = CacheRefreshReason.ProactivelyRefreshed; - authResult.AuthenticationResultMetadata.TokenSource = TokenSource.IdentityProvider; SilentRequestHelper.ProcessFetchInBackground( cachedAccessToken, @@ -129,7 +128,7 @@ protected override async Task ExecuteAsync(CancellationTok // Use a linked token source, in case the original cancellation token source is disposed before this background task completes. using var tokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); return RefreshRtOrFetchNewAccessTokenAsync(tokenSource.Token); - }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId.ToString()); + }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId); } } diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs index 1b73e2198e..55314fc41e 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs @@ -96,7 +96,7 @@ public async Task RunAsync(CancellationToken cancellationT UpdateTelemetry(sw, apiEvent, authenticationResult); LogMetricsFromAuthResult(authenticationResult, AuthenticationRequestParameters.RequestContext.Logger); LogSuccessfulTelemetryToClient(authenticationResult, telemetryEventDetails, telemetryClients); - LogMsalSuccessTelemetryToOtel(authenticationResult, apiEvent.ApiId.ToString(), sw.ElapsedTicks / (TimeSpan.TicksPerMillisecond / 1000)); + LogMsalSuccessTelemetryToOtel(authenticationResult, apiEvent.ApiId, sw.ElapsedTicks / (TimeSpan.TicksPerMillisecond / 1000)); return authenticationResult; } @@ -106,7 +106,7 @@ public async Task RunAsync(CancellationToken cancellationT AuthenticationRequestParameters.RequestContext.Logger.ErrorPii(ex); LogMsalErrorTelemetryToClient(ex, telemetryEventDetails, telemetryClients); - LogMsalFailedTelemetryToOtel(ex.ErrorCode, apiEvent.ApiId.ToString()); + LogMsalFailedTelemetryToOtel(ex.ErrorCode, apiEvent.ApiId); throw; } catch (Exception ex) @@ -115,7 +115,7 @@ public async Task RunAsync(CancellationToken cancellationT AuthenticationRequestParameters.RequestContext.Logger.ErrorPii(ex); LogMsalErrorTelemetryToClient(ex, telemetryEventDetails, telemetryClients); - LogMsalFailedTelemetryToOtel(ex.GetType().Name, apiEvent.ApiId.ToString()); + LogMsalFailedTelemetryToOtel(ex.GetType().Name, apiEvent.ApiId); throw; } finally @@ -125,19 +125,19 @@ public async Task RunAsync(CancellationToken cancellationT } } - private void LogMsalSuccessTelemetryToOtel(AuthenticationResult authenticationResult, string apiId, long durationInUs) + private void LogMsalSuccessTelemetryToOtel(AuthenticationResult authenticationResult, ApiEvent.ApiIds apiId, long durationInUs) { // Log metrics ServiceBundle.PlatformProxy.OtelInstrumentation.LogSuccessMetrics( ServiceBundle.PlatformProxy.GetProductName(), apiId, - GetCacheLevel(authenticationResult).ToString(), + GetCacheLevel(authenticationResult), durationInUs, authenticationResult.AuthenticationResultMetadata, AuthenticationRequestParameters.RequestContext.Logger); } - private void LogMsalFailedTelemetryToOtel(string errorCodeToLog, string apiId) + private void LogMsalFailedTelemetryToOtel(string errorCodeToLog, ApiEvent.ApiIds apiId) { // Log metrics ServiceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs index 8e10f2343a..22d402e7cf 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/Silent/CacheSilentStrategy.cs @@ -90,7 +90,6 @@ public async Task ExecuteAsync(CancellationToken cancellat if (shouldRefresh) { AuthenticationRequestParameters.RequestContext.ApiEvent.CacheInfo = CacheRefreshReason.ProactivelyRefreshed; - authResult.AuthenticationResultMetadata.TokenSource = TokenSource.IdentityProvider; SilentRequestHelper.ProcessFetchInBackground( cachedAccessTokenItem, @@ -99,7 +98,7 @@ public async Task ExecuteAsync(CancellationToken cancellat // Use a linked token source, in case the original cancellation token source is disposed before this background task completes. using var tokenSource = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken); return RefreshRtOrFailAsync(tokenSource.Token); - }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId.ToString()); + }, logger, ServiceBundle, AuthenticationRequestParameters.RequestContext.ApiEvent.ApiId); } } diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs index 9626585a1c..14389bd3db 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs @@ -9,6 +9,7 @@ using Microsoft.Identity.Client.Core; using Microsoft.Identity.Client.Internal.Requests; using Microsoft.Identity.Client.OAuth2; +using Microsoft.Identity.Client.TelemetryCore.Internal.Events; #if iOS using Microsoft.Identity.Client.Platforms.iOS; #endif @@ -84,12 +85,10 @@ internal static void ProcessFetchInBackground( Func> fetchAction, ILoggerAdapter logger, IServiceBundle serviceBundle, - string apiId) + ApiEvent.ApiIds apiId) { _ = Task.Run(async () => { - string error = null; - try { await fetchAction().ConfigureAwait(false); @@ -106,28 +105,29 @@ internal static void ProcessFetchInBackground( logger.ErrorPiiWithPrefix(ex, logMsg); } - error = ex.ErrorCode; + serviceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( + serviceBundle.PlatformProxy.GetProductName(), + ex.ErrorCode, + apiId, + true); } catch (OperationCanceledException ex) { logger.WarningPiiWithPrefix(ex, ProactiveRefreshCancellationError); - error = ex.GetType().Name; + serviceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( + serviceBundle.PlatformProxy.GetProductName(), + ex.GetType().Name, + apiId, + true); } catch (Exception ex) { logger.ErrorPiiWithPrefix(ex, ProactiveRefreshGeneralError); - error = ex.GetType().Name; - } - finally - { - if (!string.IsNullOrEmpty(error)) - { - serviceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( + serviceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( serviceBundle.PlatformProxy.GetProductName(), - error, + ex.GetType().Name, apiId, true); - } } }); } diff --git a/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs index 3e9897d06d..32598a70a5 100644 --- a/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs @@ -9,6 +9,7 @@ using Microsoft.Identity.Client.TelemetryCore.OpenTelemetry; using System.Diagnostics.Metrics; using Microsoft.Identity.Client.Internal; +using Microsoft.Identity.Client.TelemetryCore.Internal.Events; namespace Microsoft.Identity.Client.Platforms.Features.OpenTelemetry { @@ -89,18 +90,18 @@ public OtelInstrumentation() // Aggregates the successful requests based on token source and cache refresh reason. void IOtelInstrumentation.LogSuccessMetrics( string platform, - string apiId, - string cacheLevel, + ApiEvent.ApiIds apiId, + CacheLevel cacheLevel, long totalDurationInUs, AuthenticationResultMetadata authResultMetadata, ILoggerAdapter logger) { var tokenSource = authResultMetadata.TokenSource; - //if (authResultMetadata.CacheRefreshReason == CacheRefreshReason.ProactivelyRefreshed) - //{ - // tokenSource = TokenSource.IdentityProvider; - //} + if (authResultMetadata.CacheRefreshReason == CacheRefreshReason.ProactivelyRefreshed) + { + tokenSource = TokenSource.IdentityProvider; + } if (s_successCounter.Value.Enabled) { @@ -125,7 +126,7 @@ void IOtelInstrumentation.LogSuccessMetrics( } // Only log cache duration if L2 cache was used. - if (s_durationInL2Cache.Value.Enabled && cacheLevel.Equals(CacheLevel.L2Cache)) + if (s_durationInL2Cache.Value.Enabled && cacheLevel == CacheLevel.L2Cache) { s_durationInL2Cache.Value.Record(authResultMetadata.DurationInCacheInMs, new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), @@ -134,7 +135,7 @@ void IOtelInstrumentation.LogSuccessMetrics( } // Only log duration in HTTP when token is fetched from IDP - if (s_durationInHttp.Value.Enabled && tokenSource.Equals(TokenSource.IdentityProvider)) + if (s_durationInHttp.Value.Enabled && tokenSource == TokenSource.IdentityProvider) { s_durationInHttp.Value.Record(authResultMetadata.DurationInHttpInMs, new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), @@ -143,7 +144,7 @@ void IOtelInstrumentation.LogSuccessMetrics( } // Only log duration in microseconds when the cache level is L1. - if (s_durationInL1CacheInUs.Value.Enabled && tokenSource.Equals(TokenSource.Cache) + if (s_durationInL1CacheInUs.Value.Enabled && tokenSource == TokenSource.Cache && authResultMetadata.CacheLevel.Equals(CacheLevel.L1Cache)) { s_durationInL1CacheInUs.Value.Record(totalDurationInUs, @@ -155,7 +156,7 @@ void IOtelInstrumentation.LogSuccessMetrics( } } - void IOtelInstrumentation.LogFailedMetrics(string platform, string errorCode, string apiId, bool isProactiveTokenRefresh) + void IOtelInstrumentation.LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, bool isProactiveTokenRefresh) { if (s_failureCounter.Value.Enabled) { diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs index ff9844ef1e..972f954d6d 100644 --- a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs @@ -3,7 +3,9 @@ using System; using System.Collections.Generic; +using Microsoft.Identity.Client.Cache; using Microsoft.Identity.Client.Core; +using Microsoft.Identity.Client.TelemetryCore.Internal.Events; namespace Microsoft.Identity.Client.TelemetryCore.OpenTelemetry { @@ -11,11 +13,11 @@ internal interface IOtelInstrumentation { internal void LogSuccessMetrics( string platform, - string apiId, - string cacheLevel, + ApiEvent.ApiIds apiId, + CacheLevel cacheLevel, long totalDurationInUs, AuthenticationResultMetadata authResultMetadata, ILoggerAdapter logger); - internal void LogFailedMetrics(string platform, string errorCode, string apiId, bool isProactiveTokenRefresh); + internal void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, bool isProactiveTokenRefresh); } } diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs index b5513509b6..efecc3339b 100644 --- a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs @@ -6,7 +6,9 @@ using System.Linq; using System.Text; using System.Threading.Tasks; +using Microsoft.Identity.Client.Cache; using Microsoft.Identity.Client.Core; +using Microsoft.Identity.Client.TelemetryCore.Internal.Events; namespace Microsoft.Identity.Client.TelemetryCore.OpenTelemetry { @@ -14,8 +16,8 @@ internal class NullOtelInstrumentation : IOtelInstrumentation { public void LogSuccessMetrics( string platform, - string apiId, - string cacheLevel, + ApiEvent.ApiIds apiId, + CacheLevel cacheLevel, long totalDurationInUs, AuthenticationResultMetadata authResultMetadata, ILoggerAdapter logger) @@ -23,7 +25,7 @@ public void LogSuccessMetrics( // No op } - public void LogFailedMetrics(string platform, string errorCode, string apiId, bool isProactiveTokenRefresh) + public void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, bool isProactiveTokenRefresh) { // No op } From 7c19bfc4260f2b965a5fadd073c2e0bb3e17eb57 Mon Sep 17 00:00:00 2001 From: Neha Bhargava <61847233+neha-bhargava@users.noreply.github.com> Date: Tue, 13 Feb 2024 14:27:42 -0800 Subject: [PATCH 3/7] Update as discussed in doc --- .../Internal/Requests/RequestBase.cs | 8 +- .../Internal/Requests/SilentRequestHelper.cs | 15 +- .../OpenTelemetry/OtelInstrumentation.cs | 69 +++++---- .../OpenTelemetry/IOtelInstrumentation.cs | 10 +- .../OpenTelemetry/NullOtelInstrumentation.cs | 7 +- ...t.Identity.Test.Integration.NetCore.csproj | 2 + .../HeadlessTests/ProactiveRefreshTests.cs | 105 ++++++++++++++ ...oft.Identity.Test.Integration.NetFx.csproj | 2 + ...entity.Test.Integration.NetStandard.csproj | 3 + .../OTelInstrumentationTests.cs | 132 +++++++++++++++--- 10 files changed, 297 insertions(+), 56 deletions(-) create mode 100644 tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs index 7edb5b1186..3d669d890a 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs @@ -106,7 +106,7 @@ public async Task RunAsync(CancellationToken cancellationT AuthenticationRequestParameters.RequestContext.Logger.ErrorPii(ex); LogMsalErrorTelemetryToClient(ex, telemetryEventDetails, telemetryClients); - LogMsalFailedTelemetryToOtel(ex.ErrorCode, apiEvent.ApiId); + LogMsalFailedTelemetryToOtel(ex.ErrorCode, apiEvent.ApiId, apiEvent.CacheInfo); throw; } catch (Exception ex) @@ -115,7 +115,7 @@ public async Task RunAsync(CancellationToken cancellationT AuthenticationRequestParameters.RequestContext.Logger.ErrorPii(ex); LogMsalErrorTelemetryToClient(ex, telemetryEventDetails, telemetryClients); - LogMsalFailedTelemetryToOtel(ex.GetType().Name, apiEvent.ApiId); + LogMsalFailedTelemetryToOtel(ex.GetType().Name, apiEvent.ApiId, apiEvent.CacheInfo); throw; } finally @@ -137,14 +137,14 @@ private void LogMsalSuccessTelemetryToOtel(AuthenticationResult authenticationRe AuthenticationRequestParameters.RequestContext.Logger); } - private void LogMsalFailedTelemetryToOtel(string errorCodeToLog, ApiEvent.ApiIds apiId) + private void LogMsalFailedTelemetryToOtel(string errorCodeToLog, ApiEvent.ApiIds apiId, CacheRefreshReason cacheRefreshReason) { // Log metrics ServiceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( ServiceBundle.PlatformProxy.GetProductName(), errorCodeToLog, apiId, - false); + cacheRefreshReason); } private static void LogMsalErrorTelemetryToClient(Exception ex, MsalTelemetryEventDetails telemetryEventDetails, ITelemetryClient[] telemetryClients) diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs index 14389bd3db..23a8d20c94 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs @@ -91,7 +91,14 @@ internal static void ProcessFetchInBackground( { try { - await fetchAction().ConfigureAwait(false); + var authResult = await fetchAction().ConfigureAwait(false); + serviceBundle.PlatformProxy.OtelInstrumentation.IncrementToSuccessCounter( + serviceBundle.PlatformProxy.GetProductName(), + apiId, + TokenSource.IdentityProvider, + CacheRefreshReason.ProactivelyRefreshed, + Cache.CacheLevel.None, + logger); } catch (MsalServiceException ex) { @@ -109,7 +116,7 @@ internal static void ProcessFetchInBackground( serviceBundle.PlatformProxy.GetProductName(), ex.ErrorCode, apiId, - true); + CacheRefreshReason.ProactivelyRefreshed); } catch (OperationCanceledException ex) { @@ -118,7 +125,7 @@ internal static void ProcessFetchInBackground( serviceBundle.PlatformProxy.GetProductName(), ex.GetType().Name, apiId, - true); + CacheRefreshReason.ProactivelyRefreshed); } catch (Exception ex) { @@ -127,7 +134,7 @@ internal static void ProcessFetchInBackground( serviceBundle.PlatformProxy.GetProductName(), ex.GetType().Name, apiId, - true); + CacheRefreshReason.ProactivelyRefreshed); } }); } diff --git a/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs index 32598a70a5..e3482ffa78 100644 --- a/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs @@ -10,6 +10,7 @@ using System.Diagnostics.Metrics; using Microsoft.Identity.Client.Internal; using Microsoft.Identity.Client.TelemetryCore.Internal.Events; +using static Microsoft.Identity.Client.Platforms.Features.DesktopOs.Kerberos.NativeMethods; namespace Microsoft.Identity.Client.Platforms.Features.OpenTelemetry { @@ -88,7 +89,7 @@ public OtelInstrumentation() } // Aggregates the successful requests based on token source and cache refresh reason. - void IOtelInstrumentation.LogSuccessMetrics( + public void LogSuccessMetrics( string platform, ApiEvent.ApiIds apiId, CacheLevel cacheLevel, @@ -96,24 +97,13 @@ void IOtelInstrumentation.LogSuccessMetrics( AuthenticationResultMetadata authResultMetadata, ILoggerAdapter logger) { - var tokenSource = authResultMetadata.TokenSource; - - if (authResultMetadata.CacheRefreshReason == CacheRefreshReason.ProactivelyRefreshed) - { - tokenSource = TokenSource.IdentityProvider; - } - - if (s_successCounter.Value.Enabled) - { - s_successCounter.Value.Add(1, - new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), - new(TelemetryConstants.Platform, platform), - new(TelemetryConstants.ApiId, apiId), - new(TelemetryConstants.TokenSource, tokenSource), - new(TelemetryConstants.CacheRefreshReason, authResultMetadata.CacheRefreshReason), - new(TelemetryConstants.CacheLevel, cacheLevel)); - logger.Info("[OpenTelemetry] Completed incrementing to isSuccessful counter."); - } + IncrementToSuccessCounter( + platform, + apiId, + authResultMetadata.TokenSource, + authResultMetadata.CacheRefreshReason, + cacheLevel, + logger); if (s_durationTotal.Value.Enabled) { @@ -121,8 +111,9 @@ void IOtelInstrumentation.LogSuccessMetrics( new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), new(TelemetryConstants.Platform, platform), new(TelemetryConstants.ApiId, apiId), - new(TelemetryConstants.TokenSource, tokenSource), - new(TelemetryConstants.CacheLevel, cacheLevel)); + new(TelemetryConstants.TokenSource, authResultMetadata.TokenSource), + new(TelemetryConstants.CacheLevel, cacheLevel), + new(TelemetryConstants.CacheRefreshReason, authResultMetadata.CacheRefreshReason)); } // Only log cache duration if L2 cache was used. @@ -131,11 +122,12 @@ void IOtelInstrumentation.LogSuccessMetrics( s_durationInL2Cache.Value.Record(authResultMetadata.DurationInCacheInMs, new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), new(TelemetryConstants.Platform, platform), - new(TelemetryConstants.ApiId, apiId)); + new(TelemetryConstants.ApiId, apiId), + new(TelemetryConstants.CacheRefreshReason, authResultMetadata.CacheRefreshReason)); } // Only log duration in HTTP when token is fetched from IDP - if (s_durationInHttp.Value.Enabled && tokenSource == TokenSource.IdentityProvider) + if (s_durationInHttp.Value.Enabled && authResultMetadata.TokenSource == TokenSource.IdentityProvider) { s_durationInHttp.Value.Record(authResultMetadata.DurationInHttpInMs, new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), @@ -144,19 +136,40 @@ void IOtelInstrumentation.LogSuccessMetrics( } // Only log duration in microseconds when the cache level is L1. - if (s_durationInL1CacheInUs.Value.Enabled && tokenSource == TokenSource.Cache + if (s_durationInL1CacheInUs.Value.Enabled && authResultMetadata.TokenSource == TokenSource.Cache && authResultMetadata.CacheLevel.Equals(CacheLevel.L1Cache)) { s_durationInL1CacheInUs.Value.Record(totalDurationInUs, new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), new(TelemetryConstants.Platform, platform), new(TelemetryConstants.ApiId, apiId), - new(TelemetryConstants.TokenSource, tokenSource), - new(TelemetryConstants.CacheLevel, cacheLevel)); + new(TelemetryConstants.TokenSource, authResultMetadata.TokenSource), + new(TelemetryConstants.CacheLevel, authResultMetadata.CacheLevel), + new(TelemetryConstants.CacheRefreshReason, authResultMetadata.CacheRefreshReason)); + } + } + + public void IncrementToSuccessCounter(string platform, + ApiEvent.ApiIds apiId, + TokenSource tokenSource, + CacheRefreshReason cacheRefreshReason, + CacheLevel cacheLevel, + ILoggerAdapter logger) + { + if (s_successCounter.Value.Enabled) + { + s_successCounter.Value.Add(1, + new(TelemetryConstants.MsalVersion, MsalIdHelper.GetMsalVersion()), + new(TelemetryConstants.Platform, platform), + new(TelemetryConstants.ApiId, apiId), + new(TelemetryConstants.TokenSource, tokenSource), + new(TelemetryConstants.CacheRefreshReason, cacheRefreshReason), + new(TelemetryConstants.CacheLevel, cacheLevel)); + logger.Info("[OpenTelemetry] Completed incrementing to success counter."); } } - void IOtelInstrumentation.LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, bool isProactiveTokenRefresh) + public void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, CacheRefreshReason cacheRefreshReason) { if (s_failureCounter.Value.Enabled) { @@ -165,7 +178,7 @@ void IOtelInstrumentation.LogFailedMetrics(string platform, string errorCode, Ap new(TelemetryConstants.Platform, platform), new(TelemetryConstants.ErrorCode, errorCode), new(TelemetryConstants.ApiId, apiId), - new(TelemetryConstants.IsProactiveRefresh, isProactiveTokenRefresh)); + new(TelemetryConstants.CacheRefreshReason, cacheRefreshReason)); } } } diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs index 972f954d6d..e73b34c554 100644 --- a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs @@ -18,6 +18,14 @@ internal void LogSuccessMetrics( long totalDurationInUs, AuthenticationResultMetadata authResultMetadata, ILoggerAdapter logger); - internal void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, bool isProactiveTokenRefresh); + + internal void IncrementToSuccessCounter(string platform, + ApiEvent.ApiIds apiId, + TokenSource tokenSource, + CacheRefreshReason cacheRefreshReason, + CacheLevel cacheLevel, + ILoggerAdapter logger); + + internal void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, CacheRefreshReason cacheRefreshReason); } } diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs index efecc3339b..2716a7113c 100644 --- a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs @@ -25,7 +25,12 @@ public void LogSuccessMetrics( // No op } - public void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, bool isProactiveTokenRefresh) + public void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, CacheRefreshReason cacheRefreshReason) + { + // No op + } + + void IOtelInstrumentation.IncrementToSuccessCounter(string platform, ApiEvent.ApiIds apiId, TokenSource tokenSource, CacheRefreshReason cacheRefreshReason, CacheLevel cacheLevel, ILoggerAdapter logger) { // No op } diff --git a/tests/Microsoft.Identity.Test.Integration.netcore/Microsoft.Identity.Test.Integration.NetCore.csproj b/tests/Microsoft.Identity.Test.Integration.netcore/Microsoft.Identity.Test.Integration.NetCore.csproj index fbfc01f242..c39c88db07 100644 --- a/tests/Microsoft.Identity.Test.Integration.netcore/Microsoft.Identity.Test.Integration.NetCore.csproj +++ b/tests/Microsoft.Identity.Test.Integration.netcore/Microsoft.Identity.Test.Integration.NetCore.csproj @@ -24,6 +24,8 @@ + + diff --git a/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs b/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs index b90f18b9cb..6bc6848c78 100644 --- a/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs +++ b/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs @@ -8,6 +8,8 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Identity.Client; +using Microsoft.Identity.Client.AppConfig; +using Microsoft.Identity.Client.ManagedIdentity; using Microsoft.Identity.Client.Platforms.Features.OpenTelemetry; using Microsoft.Identity.Client.TelemetryCore; using Microsoft.Identity.Test.Common; @@ -67,14 +69,22 @@ public async Task AcquireTokenOTelTestAsync() [TestMethod] [Description("AT in cache, needs refresh. AAD responds well to Refresh.")] - public async Task ProactiveTokenRefresh_ValidResponse_Async() + public async Task ProactiveTokenRefresh_ValidResponse_ClientCredential_Async() { // Arrange using (_harness = base.CreateTestHarness()) { Trace.WriteLine("1. Setup an app"); CreateApplication(); - TokenCacheHelper.PopulateCache(_cca.AppTokenCacheInternal.Accessor, addSecondAt: false); + + _harness.HttpManager.AddAllMocks(TokenResponseType.Valid_ClientCredentials); + AuthenticationResult result = await _cca.AcquireTokenForClient(TestConstants.s_scope) + .ExecuteAsync() + .ConfigureAwait(false); + // Assert + Assert.IsNotNull(result); + + //TokenCacheHelper.PopulateCache(_cca.AppTokenCacheInternal.Accessor, addSecondAt: false); Trace.WriteLine("2. Configure AT so that it shows it needs to be refreshed"); var refreshOn = TestCommon.UpdateATWithRefreshOn(_cca.AppTokenCacheInternal.Accessor).RefreshOn; @@ -82,14 +92,16 @@ public async Task ProactiveTokenRefresh_ValidResponse_Async() TokenCacheAccessRecorder cacheAccess = _cca.AppTokenCache.RecordAccess(); Trace.WriteLine("3. Configure AAD to respond with valid token to the refresh RT flow"); - _harness.HttpManager.AddAllMocks(TokenResponseType.Valid_ClientCredentials); + _harness.HttpManager.AddTokenResponse(TokenResponseType.Valid_ClientCredentials); // Act Trace.WriteLine("4. ATS - should perform an RT refresh"); - AuthenticationResult result = await _cca.AcquireTokenForClient(TestConstants.s_scope) + result = await _cca.AcquireTokenForClient(TestConstants.s_scope) .ExecuteAsync() .ConfigureAwait(false); + Trace.WriteLine(result.AuthenticationResultMetadata.DurationTotalInMs); + // Assert TestCommon.YieldTillSatisfied(() => _harness.HttpManager.QueueSize == 0); Assert.IsNotNull(result); @@ -99,14 +111,91 @@ public async Task ProactiveTokenRefresh_ValidResponse_Async() Assert.IsTrue(result.AuthenticationResultMetadata.CacheRefreshReason == CacheRefreshReason.ProactivelyRefreshed); Assert.IsTrue(result.AuthenticationResultMetadata.RefreshOn == refreshOn); + Trace.WriteLine("5. ATS - should not perform an RT refresh, as the token is still valid"); result = await _cca.AcquireTokenForClient(TestConstants.s_scope) .ExecuteAsync() .ConfigureAwait(false); + Trace.WriteLine(result.AuthenticationResultMetadata.DurationTotalInMs); + Assert.IsTrue(result.AuthenticationResultMetadata.CacheRefreshReason == CacheRefreshReason.NotApplicable); s_meterProvider.ForceFlush(); - VerifyMetrics(3, _exportedMetrics, 2, 0); + VerifyMetrics(3, _exportedMetrics, 4, 0); + } + } + + [TestMethod] + [Description("AT in cache, needs refresh. AAD responds well to Refresh.")] + public async Task ProactiveTokenRefresh_ValidResponse_MSI_Async() + { + string appServiceEndpoint = "http://127.0.0.1:41564/msi/token"; + string resource = "https://management.azure.com/"; + + using (new EnvVariableContext()) + using (var httpManager = new MockHttpManager(isManagedIdentity: true)) + { + ManagedIdentityTestUtil.SetEnvironmentVariables(ManagedIdentitySource.AppService, appServiceEndpoint); + + Trace.WriteLine("1. Setup an app with a token cache with one AT"); + + var miBuilder = ManagedIdentityApplicationBuilder.Create(ManagedIdentityId.SystemAssigned) + .WithHttpManager(httpManager); + + // Disabling shared cache options to avoid cross test pollution. + miBuilder.Config.AccessorOptions = null; + + var mi = miBuilder.BuildConcrete(); + + httpManager.AddManagedIdentityMockHandler( + appServiceEndpoint, + resource, + MockHelpers.GetMsiSuccessfulResponse(), + ManagedIdentitySource.AppService); + + AuthenticationResult result = await mi.AcquireTokenForManagedIdentity(resource) + .ExecuteAsync() + .ConfigureAwait(false); + + Trace.WriteLine("2. Configure AT so that it shows it needs to be refreshed"); + var refreshOn = TestCommon.UpdateATWithRefreshOn(mi.AppTokenCacheInternal.Accessor).RefreshOn; + TokenCacheAccessRecorder cacheAccess = mi.AppTokenCacheInternal.RecordAccess(); + + Trace.WriteLine("3. Configure MSI to respond with a valid token"); + httpManager.AddManagedIdentityMockHandler( + appServiceEndpoint, + resource, + MockHelpers.GetMsiSuccessfulResponse(), + ManagedIdentitySource.AppService); + + // Act + Trace.WriteLine("4. ATM - should perform an RT refresh"); + result = await mi.AcquireTokenForManagedIdentity(resource) + .ExecuteAsync() + .ConfigureAwait(false); + + // Assert + TestCommon.YieldTillSatisfied(() => httpManager.QueueSize == 0); + + Assert.IsNotNull(result); + + Assert.AreEqual(0, httpManager.QueueSize, + "MSAL should have refreshed the token because the original AT was marked for refresh"); + + cacheAccess.WaitTo_AssertAcessCounts(1, 1); + + Assert.AreEqual(CacheRefreshReason.ProactivelyRefreshed, result.AuthenticationResultMetadata.CacheRefreshReason); + + Assert.AreEqual(refreshOn, result.AuthenticationResultMetadata.RefreshOn); + + result = await mi.AcquireTokenForManagedIdentity(resource) + .ExecuteAsync() + .ConfigureAwait(false); + + Assert.AreEqual(CacheRefreshReason.NotApplicable, result.AuthenticationResultMetadata.CacheRefreshReason); + + s_meterProvider.ForceFlush(); + VerifyMetrics(3, _exportedMetrics, 4, 0); } } @@ -122,7 +211,6 @@ public async Task ProactiveTokenRefresh_AadUnavailableResponse_Async() TokenCacheHelper.PopulateCache(_cca.AppTokenCacheInternal.Accessor, addSecondAt: false); Trace.WriteLine("2. Configure AT so that it shows it needs to be refreshed"); - TestCommon.UpdateATWithRefreshOn(_cca.AppTokenCacheInternal.Accessor); TokenCacheAccessRecorder cacheAccess = _cca.AppTokenCache.RecordAccess(); @@ -155,7 +243,7 @@ public async Task ProactiveTokenRefresh_AadUnavailableResponse_Async() Thread.Sleep(1000); s_meterProvider.ForceFlush(); - VerifyMetrics(4, _exportedMetrics, 2, 1); + VerifyMetrics(3, _exportedMetrics, 3, 1); } } @@ -170,7 +258,6 @@ private async Task AcquireTokenSuccessAsync() Assert.IsNotNull(result); // Acquire token from the cache - //var account = (await _cca.GetAccountsAsync().ConfigureAwait(false)).Single(); result = await _cca.AcquireTokenForClient(TestConstants.s_scope) .ExecuteAsync(CancellationToken.None).ConfigureAwait(false); Assert.IsNotNull(result); @@ -215,7 +302,7 @@ private void CreateApplication() private void VerifyMetrics(int expectedMetricCount, List exportedMetrics, long expectedSuccessfulRequests, long expectedFailedRequests) { - Assert.AreEqual(expectedMetricCount, exportedMetrics.Count); + Assert.AreEqual(expectedMetricCount, exportedMetrics.Count, "Count of metrics recorded is not as expected."); foreach (Metric exportedItem in exportedMetrics) { @@ -226,6 +313,7 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics switch (exportedItem.Name) { case "MsalSuccess": + Trace.WriteLine("Verify the metrics captured for MsalSuccess counter."); Assert.AreEqual(MetricType.LongSum, exportedItem.MetricType); expectedTags.Add(TelemetryConstants.MsalVersion); @@ -239,26 +327,27 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics foreach (var metricPoint in exportedItem.GetMetricPoints()) { totalSuccessfulRequests += metricPoint.GetSumLong(); - AssertTags(metricPoint.Tags, 6, expectedTags); + AssertTags(metricPoint.Tags, expectedTags); } Assert.AreEqual(expectedSuccessfulRequests, totalSuccessfulRequests); break; case "MsalFailure": + Trace.WriteLine("Verify the metrics captured for MsalFailure counter."); Assert.AreEqual(MetricType.LongSum, exportedItem.MetricType); expectedTags.Add(TelemetryConstants.MsalVersion); expectedTags.Add(TelemetryConstants.Platform); expectedTags.Add(TelemetryConstants.ErrorCode); expectedTags.Add(TelemetryConstants.ApiId); - expectedTags.Add(TelemetryConstants.IsProactiveRefresh); + expectedTags.Add(TelemetryConstants.CacheRefreshReason); long totalFailedRequests = 0; foreach (var metricPoint in exportedItem.GetMetricPoints()) { totalFailedRequests += metricPoint.GetSumLong(); - AssertTags(metricPoint.Tags, 5, expectedTags); + AssertTags(metricPoint.Tags, expectedTags); } Assert.AreEqual(expectedFailedRequests, totalFailedRequests); @@ -266,6 +355,7 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics break; case "MsalTotalDuration.1A": + Trace.WriteLine("Verify the metrics captured for MsalTotalDuration.1A histogram."); Assert.AreEqual(MetricType.Histogram, exportedItem.MetricType); expectedTags.Add(TelemetryConstants.MsalVersion); @@ -273,15 +363,17 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics expectedTags.Add(TelemetryConstants.ApiId); expectedTags.Add(TelemetryConstants.TokenSource); expectedTags.Add(TelemetryConstants.CacheLevel); + expectedTags.Add(TelemetryConstants.CacheRefreshReason); foreach (var metricPoint in exportedItem.GetMetricPoints()) { - AssertTags(metricPoint.Tags, 5, expectedTags); + AssertTags(metricPoint.Tags, expectedTags); } break; case "MsalDurationInL1CacheInUs.1B": + Trace.WriteLine("Verify the metrics captured for MsalDurationInL1CacheInUs.1B histogram."); Assert.AreEqual(MetricType.Histogram, exportedItem.MetricType); expectedTags.Add(TelemetryConstants.MsalVersion); @@ -289,29 +381,33 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics expectedTags.Add(TelemetryConstants.ApiId); expectedTags.Add(TelemetryConstants.TokenSource); expectedTags.Add(TelemetryConstants.CacheLevel); + expectedTags.Add(TelemetryConstants.CacheRefreshReason); foreach (var metricPoint in exportedItem.GetMetricPoints()) { - AssertTags(metricPoint.Tags, 5, expectedTags); + AssertTags(metricPoint.Tags, expectedTags); } break; case "MsalDurationInL2Cache.1A": + Trace.WriteLine("Verify the metrics captured for MsalDurationInL2Cache.1A histogram."); Assert.AreEqual(MetricType.Histogram, exportedItem.MetricType); expectedTags.Add(TelemetryConstants.MsalVersion); expectedTags.Add(TelemetryConstants.Platform); expectedTags.Add(TelemetryConstants.ApiId); + expectedTags.Add(TelemetryConstants.CacheRefreshReason); foreach (var metricPoint in exportedItem.GetMetricPoints()) { - AssertTags(metricPoint.Tags, 3, expectedTags); + AssertTags(metricPoint.Tags, expectedTags); } break; case "MsalDurationInHttp.1A": + Trace.WriteLine("Verify the metrics captured for MsalDurationInHttp.1A histogram."); Assert.AreEqual(MetricType.Histogram, exportedItem.MetricType); expectedTags.Add(TelemetryConstants.MsalVersion); @@ -320,7 +416,7 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics foreach (var metricPoint in exportedItem.GetMetricPoints()) { - AssertTags(metricPoint.Tags, 3, expectedTags); + AssertTags(metricPoint.Tags, expectedTags); } break; @@ -334,9 +430,9 @@ private void VerifyMetrics(int expectedMetricCount, List exportedMetrics } } - private void AssertTags(ReadOnlyTagCollection tags, int expectedTagCount, List expectedTags) + private void AssertTags(ReadOnlyTagCollection tags, List expectedTags) { - Assert.AreEqual(expectedTagCount, tags.Count); + Assert.AreEqual(expectedTags.Count, tags.Count); IDictionary tagDictionary = new Dictionary(); foreach (var tag in tags) From e71c5f9d82fe1630079ade980a96b51cc7169011 Mon Sep 17 00:00:00 2001 From: Neha Bhargava <61847233+neha-bhargava@users.noreply.github.com> Date: Thu, 15 Feb 2024 10:51:13 -0800 Subject: [PATCH 4/7] Add tests for OBO to validate telemetry --- .../AuthenticationResultMetadata.cs | 2 +- .../OTelInstrumentationTests.cs | 88 ++++++++++++++++--- 2 files changed, 76 insertions(+), 14 deletions(-) diff --git a/src/client/Microsoft.Identity.Client/AuthenticationResultMetadata.cs b/src/client/Microsoft.Identity.Client/AuthenticationResultMetadata.cs index e5dc5f094c..666ecfad21 100644 --- a/src/client/Microsoft.Identity.Client/AuthenticationResultMetadata.cs +++ b/src/client/Microsoft.Identity.Client/AuthenticationResultMetadata.cs @@ -24,7 +24,7 @@ public AuthenticationResultMetadata(TokenSource tokenSource) /// /// The source of the token in the result. /// - public TokenSource TokenSource { get; internal set; } + public TokenSource TokenSource { get; } /// /// The token endpoint used to contact the Identity Provider (e.g. Azure Active Directory). diff --git a/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs b/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs index 6bc6848c78..541db40b30 100644 --- a/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs +++ b/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs @@ -5,11 +5,13 @@ using System.Collections.Generic; using System.Diagnostics; using System.Linq; +using System.Net.Http; using System.Threading; using System.Threading.Tasks; using Microsoft.Identity.Client; using Microsoft.Identity.Client.AppConfig; using Microsoft.Identity.Client.ManagedIdentity; +using Microsoft.Identity.Client.OAuth2; using Microsoft.Identity.Client.Platforms.Features.OpenTelemetry; using Microsoft.Identity.Client.TelemetryCore; using Microsoft.Identity.Test.Common; @@ -84,13 +86,9 @@ public async Task ProactiveTokenRefresh_ValidResponse_ClientCredential_Async() // Assert Assert.IsNotNull(result); - //TokenCacheHelper.PopulateCache(_cca.AppTokenCacheInternal.Accessor, addSecondAt: false); - Trace.WriteLine("2. Configure AT so that it shows it needs to be refreshed"); var refreshOn = TestCommon.UpdateATWithRefreshOn(_cca.AppTokenCacheInternal.Accessor).RefreshOn; - TokenCacheAccessRecorder cacheAccess = _cca.AppTokenCache.RecordAccess(); - Trace.WriteLine("3. Configure AAD to respond with valid token to the refresh RT flow"); _harness.HttpManager.AddTokenResponse(TokenResponseType.Valid_ClientCredentials); @@ -107,7 +105,6 @@ public async Task ProactiveTokenRefresh_ValidResponse_ClientCredential_Async() Assert.IsNotNull(result); Assert.AreEqual(0, _harness.HttpManager.QueueSize, "MSAL should have refreshed the token because the original AT was marked for refresh"); - cacheAccess.WaitTo_AssertAcessCounts(1, 1); Assert.IsTrue(result.AuthenticationResultMetadata.CacheRefreshReason == CacheRefreshReason.ProactivelyRefreshed); Assert.IsTrue(result.AuthenticationResultMetadata.RefreshOn == refreshOn); @@ -121,12 +118,12 @@ public async Task ProactiveTokenRefresh_ValidResponse_ClientCredential_Async() Assert.IsTrue(result.AuthenticationResultMetadata.CacheRefreshReason == CacheRefreshReason.NotApplicable); s_meterProvider.ForceFlush(); - VerifyMetrics(3, _exportedMetrics, 4, 0); + VerifyMetrics(4, _exportedMetrics, 4, 0); } } [TestMethod] - [Description("AT in cache, needs refresh. AAD responds well to Refresh.")] + [Description("Setup AT in cache, needs refresh. MSI responds well to Refresh.")] public async Task ProactiveTokenRefresh_ValidResponse_MSI_Async() { string appServiceEndpoint = "http://127.0.0.1:41564/msi/token"; @@ -159,7 +156,6 @@ public async Task ProactiveTokenRefresh_ValidResponse_MSI_Async() Trace.WriteLine("2. Configure AT so that it shows it needs to be refreshed"); var refreshOn = TestCommon.UpdateATWithRefreshOn(mi.AppTokenCacheInternal.Accessor).RefreshOn; - TokenCacheAccessRecorder cacheAccess = mi.AppTokenCacheInternal.RecordAccess(); Trace.WriteLine("3. Configure MSI to respond with a valid token"); httpManager.AddManagedIdentityMockHandler( @@ -182,20 +178,86 @@ public async Task ProactiveTokenRefresh_ValidResponse_MSI_Async() Assert.AreEqual(0, httpManager.QueueSize, "MSAL should have refreshed the token because the original AT was marked for refresh"); - cacheAccess.WaitTo_AssertAcessCounts(1, 1); - + Assert.AreEqual(TokenSource.Cache, result.AuthenticationResultMetadata.TokenSource); Assert.AreEqual(CacheRefreshReason.ProactivelyRefreshed, result.AuthenticationResultMetadata.CacheRefreshReason); - Assert.AreEqual(refreshOn, result.AuthenticationResultMetadata.RefreshOn); result = await mi.AcquireTokenForManagedIdentity(resource) .ExecuteAsync() .ConfigureAwait(false); - + + Assert.AreEqual(TokenSource.Cache, result.AuthenticationResultMetadata.TokenSource); + Assert.AreEqual(CacheRefreshReason.NotApplicable, result.AuthenticationResultMetadata.CacheRefreshReason); + + s_meterProvider.ForceFlush(); + VerifyMetrics(4, _exportedMetrics, 4, 0); + } + } + + private MockHttpMessageHandler AddMockHandlerAadSuccess( + MockHttpManager httpManager) + { + var handler = new MockHttpMessageHandler + { + ExpectedUrl = TestConstants.AuthorityCommonTenant + "oauth2/v2.0/token", + ExpectedMethod = HttpMethod.Post, + ResponseMessage = MockHelpers.CreateSuccessTokenResponseMessage() + }; + + httpManager.AddMockHandler(handler); + + return handler; + } + + [TestMethod] + [Description("AT in cache, needs refresh. AAD responds well to Refresh.")] + public async Task ProactiveTokenRefresh_ValidResponse_OBO_Async() + { + using (var httpManager = new MockHttpManager()) + { + httpManager.AddInstanceDiscoveryMockHandler(); + + AddMockHandlerAadSuccess(httpManager); + + Trace.WriteLine("1. Setup an app with a token cache with one AT"); + var cca = ConfidentialClientApplicationBuilder + .Create(TestConstants.ClientId) + .WithClientSecret(TestConstants.ClientSecret) + .WithAuthority(TestConstants.AuthorityCommonTenant) + .WithHttpManager(httpManager) + .BuildConcrete(); + + string oboCacheKey = "obo-cache-key"; + var result = await cca.InitiateLongRunningProcessInWebApi(TestConstants.s_scope, TestConstants.DefaultAccessToken, ref oboCacheKey) + .ExecuteAsync().ConfigureAwait(false); + + Assert.AreEqual(TestConstants.ATSecret, result.AccessToken); + Assert.AreEqual(TokenSource.IdentityProvider, result.AuthenticationResultMetadata.TokenSource); + + Trace.WriteLine("2. Configure AT so that it shows it needs to be refreshed"); + TestCommon.UpdateATWithRefreshOn(cca.UserTokenCacheInternal.Accessor); + + AddMockHandlerAadSuccess(httpManager); + + Trace.WriteLine("3. Configure AAD to respond with a valid token"); + result = await cca.AcquireTokenInLongRunningProcess(TestConstants.s_scope, oboCacheKey).ExecuteAsync().ConfigureAwait(false); + + Assert.AreEqual(TestConstants.ATSecret, result.AccessToken); + Assert.AreEqual(TokenSource.Cache, result.AuthenticationResultMetadata.TokenSource); + Assert.AreEqual(CacheRefreshReason.ProactivelyRefreshed, result.AuthenticationResultMetadata.CacheRefreshReason); + + // Add delay to let the proactive refresh happen + Thread.Sleep(1000); + + Trace.WriteLine("4. Fetch token from cache"); + result = await cca.AcquireTokenInLongRunningProcess(TestConstants.s_scope, oboCacheKey).ExecuteAsync().ConfigureAwait(false); + + Assert.AreEqual(TestConstants.ATSecret, result.AccessToken); + Assert.AreEqual(TokenSource.Cache, result.AuthenticationResultMetadata.TokenSource); Assert.AreEqual(CacheRefreshReason.NotApplicable, result.AuthenticationResultMetadata.CacheRefreshReason); s_meterProvider.ForceFlush(); - VerifyMetrics(3, _exportedMetrics, 4, 0); + VerifyMetrics(4, _exportedMetrics, 4, 0); } } From 29f41873b91648da6d8768fef1b77e83753dc932 Mon Sep 17 00:00:00 2001 From: Neha Bhargava <61847233+neha-bhargava@users.noreply.github.com> Date: Fri, 16 Feb 2024 15:35:10 -0800 Subject: [PATCH 5/7] Address comments --- .../Internal/Requests/RequestBase.cs | 12 ++++++------ .../Internal/Requests/SilentRequestHelper.cs | 8 ++++---- .../OpenTelemetry/OtelInstrumentation.cs | 11 +++++++---- .../OpenTelemetry/IOtelInstrumentation.cs | 7 +++++-- .../OpenTelemetry/NullOtelInstrumentation.cs | 12 ++++++++++-- .../HeadlessTests/ProactiveRefreshTests.cs | 1 - .../OTelInstrumentationTests.cs | 19 ++----------------- 7 files changed, 34 insertions(+), 36 deletions(-) diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs index 3d669d890a..58a738fa20 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs @@ -96,7 +96,7 @@ public async Task RunAsync(CancellationToken cancellationT UpdateTelemetry(sw, apiEvent, authenticationResult); LogMetricsFromAuthResult(authenticationResult, AuthenticationRequestParameters.RequestContext.Logger); LogSuccessfulTelemetryToClient(authenticationResult, telemetryEventDetails, telemetryClients); - LogMsalSuccessTelemetryToOtel(authenticationResult, apiEvent.ApiId, sw.ElapsedTicks / (TimeSpan.TicksPerMillisecond / 1000)); + LogSuccessTelemetryToOtel(authenticationResult, apiEvent.ApiId, sw.ElapsedTicks / (TimeSpan.TicksPerMillisecond / 1000)); return authenticationResult; } @@ -106,7 +106,7 @@ public async Task RunAsync(CancellationToken cancellationT AuthenticationRequestParameters.RequestContext.Logger.ErrorPii(ex); LogMsalErrorTelemetryToClient(ex, telemetryEventDetails, telemetryClients); - LogMsalFailedTelemetryToOtel(ex.ErrorCode, apiEvent.ApiId, apiEvent.CacheInfo); + LogFailureTelemetryToOtel(ex.ErrorCode, apiEvent.ApiId, apiEvent.CacheInfo); throw; } catch (Exception ex) @@ -115,7 +115,7 @@ public async Task RunAsync(CancellationToken cancellationT AuthenticationRequestParameters.RequestContext.Logger.ErrorPii(ex); LogMsalErrorTelemetryToClient(ex, telemetryEventDetails, telemetryClients); - LogMsalFailedTelemetryToOtel(ex.GetType().Name, apiEvent.ApiId, apiEvent.CacheInfo); + LogFailureTelemetryToOtel(ex.GetType().Name, apiEvent.ApiId, apiEvent.CacheInfo); throw; } finally @@ -125,7 +125,7 @@ public async Task RunAsync(CancellationToken cancellationT } } - private void LogMsalSuccessTelemetryToOtel(AuthenticationResult authenticationResult, ApiEvent.ApiIds apiId, long durationInUs) + private void LogSuccessTelemetryToOtel(AuthenticationResult authenticationResult, ApiEvent.ApiIds apiId, long durationInUs) { // Log metrics ServiceBundle.PlatformProxy.OtelInstrumentation.LogSuccessMetrics( @@ -137,10 +137,10 @@ private void LogMsalSuccessTelemetryToOtel(AuthenticationResult authenticationRe AuthenticationRequestParameters.RequestContext.Logger); } - private void LogMsalFailedTelemetryToOtel(string errorCodeToLog, ApiEvent.ApiIds apiId, CacheRefreshReason cacheRefreshReason) + private void LogFailureTelemetryToOtel(string errorCodeToLog, ApiEvent.ApiIds apiId, CacheRefreshReason cacheRefreshReason) { // Log metrics - ServiceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( + ServiceBundle.PlatformProxy.OtelInstrumentation.LogFailureMetrics( ServiceBundle.PlatformProxy.GetProductName(), errorCodeToLog, apiId, diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs index 23a8d20c94..1dfd1ee1ab 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/SilentRequestHelper.cs @@ -92,7 +92,7 @@ internal static void ProcessFetchInBackground( try { var authResult = await fetchAction().ConfigureAwait(false); - serviceBundle.PlatformProxy.OtelInstrumentation.IncrementToSuccessCounter( + serviceBundle.PlatformProxy.OtelInstrumentation.IncrementSuccessCounter( serviceBundle.PlatformProxy.GetProductName(), apiId, TokenSource.IdentityProvider, @@ -112,7 +112,7 @@ internal static void ProcessFetchInBackground( logger.ErrorPiiWithPrefix(ex, logMsg); } - serviceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( + serviceBundle.PlatformProxy.OtelInstrumentation.LogFailureMetrics( serviceBundle.PlatformProxy.GetProductName(), ex.ErrorCode, apiId, @@ -121,7 +121,7 @@ internal static void ProcessFetchInBackground( catch (OperationCanceledException ex) { logger.WarningPiiWithPrefix(ex, ProactiveRefreshCancellationError); - serviceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( + serviceBundle.PlatformProxy.OtelInstrumentation.LogFailureMetrics( serviceBundle.PlatformProxy.GetProductName(), ex.GetType().Name, apiId, @@ -130,7 +130,7 @@ internal static void ProcessFetchInBackground( catch (Exception ex) { logger.ErrorPiiWithPrefix(ex, ProactiveRefreshGeneralError); - serviceBundle.PlatformProxy.OtelInstrumentation.LogFailedMetrics( + serviceBundle.PlatformProxy.OtelInstrumentation.LogFailureMetrics( serviceBundle.PlatformProxy.GetProductName(), ex.GetType().Name, apiId, diff --git a/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs index e3482ffa78..c01614de26 100644 --- a/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/Platforms/Features/OpenTelemetry/OtelInstrumentation.cs @@ -97,7 +97,7 @@ public void LogSuccessMetrics( AuthenticationResultMetadata authResultMetadata, ILoggerAdapter logger) { - IncrementToSuccessCounter( + IncrementSuccessCounter( platform, apiId, authResultMetadata.TokenSource, @@ -149,7 +149,7 @@ public void LogSuccessMetrics( } } - public void IncrementToSuccessCounter(string platform, + public void IncrementSuccessCounter(string platform, ApiEvent.ApiIds apiId, TokenSource tokenSource, CacheRefreshReason cacheRefreshReason, @@ -165,11 +165,14 @@ public void IncrementToSuccessCounter(string platform, new(TelemetryConstants.TokenSource, tokenSource), new(TelemetryConstants.CacheRefreshReason, cacheRefreshReason), new(TelemetryConstants.CacheLevel, cacheLevel)); - logger.Info("[OpenTelemetry] Completed incrementing to success counter."); + logger.Verbose(() => "[OpenTelemetry] Completed incrementing to success counter."); } } - public void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, CacheRefreshReason cacheRefreshReason) + public void LogFailureMetrics(string platform, + string errorCode, + ApiEvent.ApiIds apiId, + CacheRefreshReason cacheRefreshReason) { if (s_failureCounter.Value.Enabled) { diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs index e73b34c554..45e2491001 100644 --- a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/IOtelInstrumentation.cs @@ -19,13 +19,16 @@ internal void LogSuccessMetrics( AuthenticationResultMetadata authResultMetadata, ILoggerAdapter logger); - internal void IncrementToSuccessCounter(string platform, + internal void IncrementSuccessCounter(string platform, ApiEvent.ApiIds apiId, TokenSource tokenSource, CacheRefreshReason cacheRefreshReason, CacheLevel cacheLevel, ILoggerAdapter logger); - internal void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, CacheRefreshReason cacheRefreshReason); + internal void LogFailureMetrics(string platform, + string errorCode, + ApiEvent.ApiIds apiId, + CacheRefreshReason cacheRefreshReason); } } diff --git a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs index 2716a7113c..f51e276f5c 100644 --- a/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs +++ b/src/client/Microsoft.Identity.Client/TelemetryCore/OpenTelemetry/NullOtelInstrumentation.cs @@ -25,12 +25,20 @@ public void LogSuccessMetrics( // No op } - public void LogFailedMetrics(string platform, string errorCode, ApiEvent.ApiIds apiId, CacheRefreshReason cacheRefreshReason) + public void LogFailureMetrics(string platform, + string errorCode, + ApiEvent.ApiIds apiId, + CacheRefreshReason cacheRefreshReason) { // No op } - void IOtelInstrumentation.IncrementToSuccessCounter(string platform, ApiEvent.ApiIds apiId, TokenSource tokenSource, CacheRefreshReason cacheRefreshReason, CacheLevel cacheLevel, ILoggerAdapter logger) + void IOtelInstrumentation.IncrementSuccessCounter(string platform, + ApiEvent.ApiIds apiId, + TokenSource tokenSource, + CacheRefreshReason cacheRefreshReason, + CacheLevel cacheLevel, + ILoggerAdapter logger) { // No op } diff --git a/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs b/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs index 90d3479cc7..a6fe9a163a 100644 --- a/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs +++ b/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs @@ -40,7 +40,6 @@ public async Task TestProactiveTokenWithTelemetry() ConfidentialClientApplication confidentialApp = ConfidentialClientApplicationBuilder .Create(settings.ClientId) .WithAuthority(settings.Authority, true) - .WithTestLogging() .WithCertificate(settings.GetCertificate()) .BuildConcrete(); diff --git a/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs b/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs index 541db40b30..2d5fda857d 100644 --- a/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs +++ b/tests/Microsoft.Identity.Test.Unit/TelemetryTests/OTelInstrumentationTests.cs @@ -194,21 +194,6 @@ public async Task ProactiveTokenRefresh_ValidResponse_MSI_Async() } } - private MockHttpMessageHandler AddMockHandlerAadSuccess( - MockHttpManager httpManager) - { - var handler = new MockHttpMessageHandler - { - ExpectedUrl = TestConstants.AuthorityCommonTenant + "oauth2/v2.0/token", - ExpectedMethod = HttpMethod.Post, - ResponseMessage = MockHelpers.CreateSuccessTokenResponseMessage() - }; - - httpManager.AddMockHandler(handler); - - return handler; - } - [TestMethod] [Description("AT in cache, needs refresh. AAD responds well to Refresh.")] public async Task ProactiveTokenRefresh_ValidResponse_OBO_Async() @@ -217,7 +202,7 @@ public async Task ProactiveTokenRefresh_ValidResponse_OBO_Async() { httpManager.AddInstanceDiscoveryMockHandler(); - AddMockHandlerAadSuccess(httpManager); + httpManager.AddSuccessTokenResponseMockHandlerForPost(); Trace.WriteLine("1. Setup an app with a token cache with one AT"); var cca = ConfidentialClientApplicationBuilder @@ -237,7 +222,7 @@ public async Task ProactiveTokenRefresh_ValidResponse_OBO_Async() Trace.WriteLine("2. Configure AT so that it shows it needs to be refreshed"); TestCommon.UpdateATWithRefreshOn(cca.UserTokenCacheInternal.Accessor); - AddMockHandlerAadSuccess(httpManager); + httpManager.AddSuccessTokenResponseMockHandlerForPost(); Trace.WriteLine("3. Configure AAD to respond with a valid token"); result = await cca.AcquireTokenInLongRunningProcess(TestConstants.s_scope, oboCacheKey).ExecuteAsync().ConfigureAwait(false); From 4b9ec028b29a02386ac0a41f46e9561d62cb05ec Mon Sep 17 00:00:00 2001 From: Neha Bhargava <61847233+neha-bhargava@users.noreply.github.com> Date: Fri, 16 Feb 2024 15:39:31 -0800 Subject: [PATCH 6/7] Update tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs Co-authored-by: Peter <34331512+pmaytak@users.noreply.github.com> --- .../HeadlessTests/ProactiveRefreshTests.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs b/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs index a6fe9a163a..8d41a27f9b 100644 --- a/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs +++ b/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs @@ -22,7 +22,7 @@ namespace Microsoft.Identity.Test.Integration.HeadlessTests public class ProactiveRefreshTests { [TestMethod] - public async Task TestProactiveTokenWithTelemetry() + public async Task ProactiveRefreshTriggers_WithTelemetry_Test() { Trace.WriteLine("Add exporter to test the metrics for proactive token refresh"); List exportedMetrics = new(); From 774d08abac92c03b57c99572e09cac078b8abf20 Mon Sep 17 00:00:00 2001 From: Neha Bhargava <61847233+neha-bhargava@users.noreply.github.com> Date: Tue, 20 Feb 2024 14:09:52 -0800 Subject: [PATCH 7/7] Address comments --- .../Internal/Requests/RequestBase.cs | 2 +- .../HeadlessTests/ProactiveRefreshTests.cs | 23 +++++++++++++------ 2 files changed, 17 insertions(+), 8 deletions(-) diff --git a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs index f71706930a..e1a053d280 100644 --- a/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs +++ b/src/client/Microsoft.Identity.Client/Internal/Requests/RequestBase.cs @@ -106,7 +106,7 @@ public async Task RunAsync(CancellationToken cancellationT UpdateTelemetry(measureDurationResult.Milliseconds + measureTelemetryDurationResult.Milliseconds, apiEvent, authenticationResult); LogMetricsFromAuthResult(authenticationResult, AuthenticationRequestParameters.RequestContext.Logger); LogSuccessfulTelemetryToClient(authenticationResult, telemetryEventDetails, telemetryClients); - LogSuccessTelemetryToOtel(authenticationResult, apiEvent.ApiId, sw.ElapsedTicks / (TimeSpan.TicksPerMillisecond / 1000)); + LogSuccessTelemetryToOtel(authenticationResult, apiEvent.ApiId, measureDurationResult.Ticks / (TimeSpan.TicksPerMillisecond / 1000)); return authenticationResult; } diff --git a/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs b/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs index 8d41a27f9b..dba09b5ba2 100644 --- a/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs +++ b/tests/Microsoft.Identity.Test.Integration.netfx/HeadlessTests/ProactiveRefreshTests.cs @@ -51,7 +51,7 @@ public async Task ProactiveRefreshTriggers_WithTelemetry_Test() Assert.IsNotNull(authResult); Assert.IsNotNull(authResult.AccessToken); - Assert.IsTrue(authResult.AuthenticationResultMetadata.DurationTotalInMs > 50); + Assert.AreEqual(TokenSource.IdentityProvider, authResult.AuthenticationResultMetadata.TokenSource); Trace.WriteLine("Acquire a token from cache."); authResult = await confidentialApp @@ -80,25 +80,34 @@ public async Task ProactiveRefreshTriggers_WithTelemetry_Test() Assert.AreEqual(CacheRefreshReason.ProactivelyRefreshed, authResult.AuthenticationResultMetadata.CacheRefreshReason); Assert.IsTrue(authResult.AuthenticationResultMetadata.DurationTotalInMs < 50); - Thread.Sleep(5000); // Wait for the background process to complete - meterProvider.ForceFlush(); + + TestCommon.YieldTillSatisfied(()=>ValidateSuccessMetrics(meterProvider, exportedMetrics) == 4); // Wait for the background process to complete + + exportedMetrics.Clear(); + meterProvider.Dispose(); + } + + private long ValidateSuccessMetrics(MeterProvider meterProvider, List exportedMetrics) + { Assert.AreEqual(4, exportedMetrics.Count); foreach (var metric in exportedMetrics) { if (metric.Name == "MsalSuccess") { - var successfulRequests = 0; + long successfulRequests = 0; + foreach (var metricPoint in metric.GetMetricPoints()) { - successfulRequests += (int)metricPoint.GetSumLong(); + successfulRequests += metricPoint.GetSumLong(); } - Trace.WriteLine("Assert that there are 4 successful requests logged including 1 for background refresh."); - Assert.AreEqual(4, successfulRequests); + return successfulRequests; } } + + return 0; } } }