Add request count and duration telemetry (#3022)

* Add request count and duration telemetry

* Add request count and duration telemetry

* small fix

* Feedback, remodel timing and counters

* Use interface for logging, move constants to class

* some interface changes, rework tests

* fix naming

* address interface feedback

* Interface and namespace changes

* avoid friend assemblies

* add metadata

* doc comments for tags

* PR feedback

* Apply suggestions from code review

Co-authored-by: Keegan <[email protected]>

* change class name and add clarifying comments

* Change namespace, move package reference

---------

Co-authored-by: George Krechar <[email protected]>
Co-authored-by: jennyf19 <[email protected]>
Co-authored-by: Keegan <[email protected]>

Author: 4 people

build/dependencies.props

@@ -8,6 +8,7 @@
     <MicrosoftSourceLinkGitHubVersion>1.0.0</MicrosoftSourceLinkGitHubVersion>
     <NetStandardVersion>2.0.3</NetStandardVersion>
     <NewtonsoftVersion>13.0.3</NewtonsoftVersion>
+    <SystemDiagnosticSourceVersion>6.0.2</SystemDiagnosticSourceVersion>
     <SystemMemoryVersion>4.5.5</SystemMemoryVersion>
     <SystemSecurityCryptographyCngVersion>4.5.0</SystemSecurityCryptographyCngVersion>
     <SystemTextJson>8.0.5</SystemTextJson>

build/dependenciesTest.props

@@ -7,6 +7,7 @@
     <MicrosoftNETTestSdkVersion>17.11.1</MicrosoftNETTestSdkVersion>
     <NetStandardVersion>2.0.3</NetStandardVersion>
     <NewtonsoftVersion>13.0.3</NewtonsoftVersion>
+    <OpenTelemetryVersion>1.6.0</OpenTelemetryVersion>
     <SystemNetHttp>4.3.4</SystemNetHttp>
     <SystemSecurityClaimsVersion>4.3.0</SystemSecurityClaimsVersion>
     <SystemTextJson>8.0.5</SystemTextJson>

src/Microsoft.IdentityModel.JsonWebTokens/InternalAPI.Unshipped.txt

@@ -1,3 +1,4 @@
+Microsoft.IdentityModel.JsonWebTokens.JsonWebTokenHandler._telemetryClient -> Microsoft.IdentityModel.Telemetry.ITelemetryClient
 static Microsoft.IdentityModel.JsonWebTokens.JsonWebTokenHandler.CreateToken(string payload, Microsoft.IdentityModel.Tokens.SecurityTokenDescriptor tokenDescriptor) -> string
 static Microsoft.IdentityModel.JsonWebTokens.JsonWebTokenHandler.EncryptToken(byte[] innerTokenUtf8Bytes, Microsoft.IdentityModel.Tokens.EncryptingCredentials encryptingCredentials, string compressionAlgorithm, System.Collections.Generic.IDictionary<string, object> additionalHeaderClaims, string tokenType, bool includeKeyIdInHeader) -> string
 static Microsoft.IdentityModel.JsonWebTokens.JsonWebTokenHandler.EncryptToken(byte[] innerTokenUtf8Bytes, Microsoft.IdentityModel.Tokens.SecurityTokenDescriptor tokenDescriptor) -> string

src/Microsoft.IdentityModel.JsonWebTokens/JsonWebTokenHandler.ValidateToken.cs

@@ -10,13 +10,16 @@
 using Microsoft.IdentityModel.Abstractions;
 using Microsoft.IdentityModel.Logging;
 using Microsoft.IdentityModel.Tokens;
+using Microsoft.IdentityModel.Telemetry;
 using TokenLogMessages = Microsoft.IdentityModel.Tokens.LogMessages;
 
 namespace Microsoft.IdentityModel.JsonWebTokens
 {
     /// <remarks>This partial class contains methods and logic related to the validation of tokens.</remarks>
     public partial class JsonWebTokenHandler : TokenHandler
     {
+        internal Telemetry.ITelemetryClient _telemetryClient = new TelemetryClient();
+
         /// <summary>
         /// Returns a value that indicates if this handler can validate a <see cref="SecurityToken"/>.
         /// </summary>
@@ -511,6 +514,10 @@ await ValidateJWEAsync(jsonWebToken, validationParameters, currentConfiguration)
                     // where a new valid configuration was somehow published during validation time.
                     if (currentConfiguration != null)
                     {
+                        _telemetryClient.IncrementConfigurationRefreshRequestCounter(
+                            validationParameters.ConfigurationManager.MetadataAddress,
+                            TelemetryConstants.Protocols.Lkg);
+
                         validationParameters.ConfigurationManager.RequestRefresh();
                         validationParameters.RefreshBeforeValidation = true;
                         var lastConfig = currentConfiguration;

src/Microsoft.IdentityModel.Protocols/Configuration/ConfigurationManager.cs

@@ -9,6 +9,7 @@
 using Microsoft.IdentityModel.Logging;
 using Microsoft.IdentityModel.Protocols.Configuration;
 using Microsoft.IdentityModel.Tokens;
+using Microsoft.IdentityModel.Telemetry;
 
 namespace Microsoft.IdentityModel.Protocols
 {
@@ -45,6 +46,7 @@ public class ConfigurationManager<T> : BaseConfigurationManager, IConfigurationM
         private int _configurationRetrieverState = ConfigurationRetrieverIdle;
 
         private readonly TimeProvider _timeProvider = TimeProvider.System;
+        internal ITelemetryClient TelemetryClient = new TelemetryClient();
 
         // If a refresh is requested, then do the refresh as a blocking operation
         // not on a background thread. RequestRefresh signals that the app is explicitly
@@ -53,6 +55,7 @@ public class ConfigurationManager<T> : BaseConfigurationManager, IConfigurationM
         // refresh interval has passed.
         bool _refreshRequested;
 
+
         /// <summary>
         /// Instantiates a new <see cref="ConfigurationManager{T}"/> that manages automatic and controls refreshing on configuration data.
         /// </summary>
@@ -190,7 +193,7 @@ public virtual async Task<T> GetConfigurationAsync(CancellationToken cancel)
                 try
                 {
                     // Don't use the individual CT here, this is a shared operation that shouldn't be affected by an individual's cancellation.
-                    // The transport should have it's own timeouts, etc.
+                    // The transport should have its own timeouts, etc.
                     T configuration = await _configRetriever.GetConfigurationAsync(
                         MetadataAddress,
                         _docRetriever,
@@ -201,18 +204,29 @@ public virtual async Task<T> GetConfigurationAsync(CancellationToken cancel)
                         ConfigurationValidationResult result = _configValidator.Validate(configuration);
                         // in this case we have never had a valid configuration, so we will throw an exception if the validation fails
                         if (!result.Succeeded)
-                            throw LogHelper.LogExceptionMessage(
-                                new InvalidConfigurationException(
-                                    LogHelper.FormatInvariant(
-                                        LogMessages.IDX20810,
-                                        result.ErrorMessage)));
+                        {
+                            var ex = new InvalidConfigurationException(
+                                LogHelper.FormatInvariant(
+                                    LogMessages.IDX20810,
+                                    result.ErrorMessage));
+
+                            throw LogHelper.LogExceptionMessage(ex);
+                        }
                     }
 
+                    TelemetryClient.IncrementConfigurationRefreshRequestCounter(
+                        MetadataAddress,
+                        TelemetryConstants.Protocols.FirstRefresh);
+
                     UpdateConfiguration(configuration);
                 }
                 catch (Exception ex)
                 {
                     fetchMetadataFailure = ex;
+                    TelemetryClient.IncrementConfigurationRefreshRequestCounter(
+                        MetadataAddress,
+                        TelemetryConstants.Protocols.FirstRefresh,
+                        ex);
 
                     LogHelper.LogExceptionMessage(
                         new InvalidOperationException(
@@ -234,11 +248,22 @@ public virtual async Task<T> GetConfigurationAsync(CancellationToken cancel)
                 {
                     if (_refreshRequested)
                     {
+                        // Log as manual because RequestRefresh was called
+                        TelemetryClient.IncrementConfigurationRefreshRequestCounter(
+                            MetadataAddress,
+                            TelemetryConstants.Protocols.Manual);
+
                         UpdateCurrentConfiguration();
                         _refreshRequested = false;
                     }
                     else
+                    {
+                        TelemetryClient.IncrementConfigurationRefreshRequestCounter(
+                            MetadataAddress,
+                            TelemetryConstants.Protocols.Automatic);
+
                         _ = Task.Run(UpdateCurrentConfiguration, CancellationToken.None);
+                    }
                 }
             }
 
@@ -264,13 +289,20 @@ public virtual async Task<T> GetConfigurationAsync(CancellationToken cancel)
         private void UpdateCurrentConfiguration()
         {
 #pragma warning disable CA1031 // Do not catch general exception types
+            long startTimestamp = _timeProvider.GetTimestamp();
+
             try
             {
                 T configuration = _configRetriever.GetConfigurationAsync(
                     MetadataAddress,
                     _docRetriever,
                     CancellationToken.None).ConfigureAwait(false).GetAwaiter().GetResult();
 
+                var elapsedTime = _timeProvider.GetElapsedTime(startTimestamp);
+                TelemetryClient.LogConfigurationRetrievalDuration(
+                    MetadataAddress,
+                    elapsedTime);
+
                 if (_configValidator == null)
                 {
                     UpdateConfiguration(configuration);
@@ -291,6 +323,12 @@ private void UpdateCurrentConfiguration()
             }
             catch (Exception ex)
             {
+                var elapsedTime = _timeProvider.GetElapsedTime(startTimestamp);
+                TelemetryClient.LogConfigurationRetrievalDuration(
+                    MetadataAddress,
+                    elapsedTime,
+                    ex);
+
                 LogHelper.LogExceptionMessage(
                     new InvalidOperationException(
                         LogHelper.FormatInvariant(
@@ -336,7 +374,7 @@ ref Unsafe.As<DateTime, long>(ref _lastRequestRefresh),
         /// Obtains an updated version of Configuration.
         /// </summary>
         /// <param name="cancel">CancellationToken</param>
-        /// <returns>Configuration of type BaseConfiguration    .</returns>
+        /// <returns>Configuration of type BaseConfiguration.</returns>
         /// <remarks>If the time since the last call is less than <see cref="BaseConfigurationManager.AutomaticRefreshInterval"/> then <see cref="IConfigurationRetriever{T}.GetConfigurationAsync"/> is not called and the current Configuration is returned.</remarks>
         public override async Task<BaseConfiguration> GetBaseConfigurationAsync(CancellationToken cancel)
         {
@@ -353,6 +391,7 @@ public override async Task<BaseConfiguration> GetBaseConfigurationAsync(Cancella
         public override void RequestRefresh()
         {
             DateTime now = _timeProvider.GetUtcNow().UtcDateTime;
+
             if (now >= DateTimeUtil.Add(LastRequestRefresh, RefreshInterval) || _isFirstRefreshRequest)
             {
                 _isFirstRefreshRequest = false;

src/Microsoft.IdentityModel.Protocols/InternalAPI.Unshipped.txt

@@ -0,0 +1,2 @@
+Microsoft.IdentityModel.Protocols.ConfigurationManager<T>.TelemetryClient -> Microsoft.IdentityModel.Telemetry.ITelemetryClient
+Microsoft.IdentityModel.Protocols.ConfigurationManager<T>.TimeProvider -> System.TimeProvider

src/Microsoft.IdentityModel.Protocols/InternalsVisibleTo.cs

@@ -0,0 +1,4 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+[assembly: System.Runtime.CompilerServices.InternalsVisibleTo("Microsoft.IdentityModel.Protocols.OpenIdConnect.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100b5fc90e7027f67871e773a8fde8938c81dd402ba65b9201d60593e96c492651e889cc13f1415ebb53fac1131ae0bd333c5ee6021672d9718ea31a8aebd0da0072f25d87dba6fc90ffd598ed4da35e44c398c454307e8e33b8426143daec9f596836f97c8f74750e5975c64e2189f45def46b2a2b1247adc3652bf5c308055da9")]