Add request count and duration telemetry

build/dependencies.props

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

src/Microsoft.IdentityModel.Logging/IdentityModelTelemetry.cs

@@ -0,0 +1,49 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+using System.Diagnostics;
+using System.Diagnostics.Metrics;
+
+namespace Microsoft.IdentityModel.Logging
+{
+    internal class IdentityModelTelemetry
+    {
+        /// <summary>
+        /// Meter name for MicrosoftIdentityModel.
+        /// </summary>
+        public const string MeterName = "MicrosoftIdentityModel_Meter";
+        public const string ServiceName = "MicrosoftIdentityModel";
+
+        /// <summary>
+        /// The meter responsible for creating instruments.
+        /// </summary>
+        public static readonly Meter WilsonMeter = new(MeterName, "1.0.0");
+
+        internal const string TotalDurationHistogramName = "IdentityModelConfigurationRequestTotalDurationInMS";
+
+        /// <summary>
+        /// Counter to capture requests to configuration manager.
+        /// </summary>
+        internal const string WilsonConfigurationManagerCounterName = "WilsonConfigurationManagerCounter";
+        internal const string WilsonConfigurationManagerCounterDescription = "Counter capturing configuration manager operations.";
+        internal static readonly Counter<long> ConfigurationManagerCounter = WilsonMeter.CreateCounter<long>(WilsonConfigurationManagerCounterName, description: WilsonConfigurationManagerCounterDescription);
+
+        /// <summary>
+        /// Histogram to capture total duration of configuration manager operations in milliseconds.
+        /// </summary>
+        internal static readonly Histogram<long> TotalDurationHistogram = WilsonMeter.CreateHistogram<long>(
+            TotalDurationHistogramName,
+            unit: "ms",
+            description: "Performance of getting configuration calls total latency");
+
+        internal static void RecordTotalDurationHistogram(long requestDurationInMs, in TagList tagList)
+        {
+            TotalDurationHistogram.Record(requestDurationInMs, tagList);
+        }
+
+        internal static void IncrementConfigurationManagerCounter(in TagList tagList)
+        {
+            ConfigurationManagerCounter.Add(1, tagList);
+        }
+    }
+}

src/Microsoft.IdentityModel.Logging/IdentityModelTelemetryUtil.cs

@@ -6,6 +6,7 @@
 using System.Collections.Concurrent;
 using System.Reflection;
 using System.Net.Http;
+using System.Diagnostics;
 
 namespace Microsoft.IdentityModel.Logging
 {
@@ -23,6 +24,27 @@ public static class IdentityModelTelemetryUtil
             [versionTelemetry] = ClientVer
         };
 
+        // Static attribute tags
+        internal const string WilsonVersionTag = "WilsonVersion";
+        internal const string MetadataAddressTag = "MetadataAddress";
+        internal const string RefreshReasonTag = "RefreshReason";
+        internal const string OperationStatusTag = "OperationStatus";
+        internal const string ExceptionTypeTag = "ExceptionType";
+
+        // Validation result values
+        internal const string Success = "Success";
+        internal const string Failure = "Failure";
+
+        // Configuration manager refresh reasons
+        internal const string Requested = "Requested";
+        internal const string Scheduled = "Scheduled";
+        internal const string LKG = "LastKnownGood";
+
+        // Configuration manager exception types
+        internal const string ConfigurationInvalid = "ConfigurationInvalid";
+        internal const string ConfigurationRetrievalFailed = "ConfigurationRetrievalFailed";
+
+
         /// <summary>
         /// Get the string that represents the client SKU.
         /// </summary>
@@ -135,5 +157,40 @@ internal static bool UpdateDefaultTelemetryData(string key, string value)
             telemetryData[key] = value;
             return true;
         }
+
+        internal static void IncrementConfigurationManagerCounter(
+            string metadataAddress,
+            string refreshReason,
+            string operationStatus,
+            string exceptionType)
+        {
+            var tagList = new TagList()
+            {
+                { WilsonVersionTag, ClientVer },
+                { MetadataAddressTag, metadataAddress },
+                { RefreshReasonTag, refreshReason},
+                { OperationStatusTag, operationStatus },
+                { ExceptionTypeTag, exceptionType }
+            };
+        }
+
+        internal static void RecordTotalDuration(
+            long durationInMs,
+            string metadataAddress,
+            string refreshReason,
+            string operationStatus,
+            string exceptionType)
+        {
+            var tagList = new TagList()
+            {
+                { WilsonVersionTag, ClientVer },
+                { MetadataAddressTag, metadataAddress },
+                { RefreshReasonTag, refreshReason},
+                { OperationStatusTag, operationStatus },
+                { ExceptionTypeTag, exceptionType }
+            };
+
+            IdentityModelTelemetry.RecordTotalDurationHistogram(durationInMs, tagList);
+        }
     }
 }

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

@@ -0,0 +1,29 @@
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetry.MeterName = "MicrosoftIdentityModel_Meter" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetry.ServiceName = "MicrosoftIdentityModel" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetry.TotalDurationHistogramName = "IdentityModelConfigurationRequestTotalDurationInMS" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetry.WilsonConfigurationManagerCounterDescription = "Counter capturing configuration manager operations." -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetry.WilsonConfigurationManagerCounterName = "WilsonConfigurationManagerCounter" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.ConfigurationInvalid = "ConfigurationInvalid" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.ConfigurationRetrievalFailed = "ConfigurationRetrievalFailed" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.ExceptionTypeTag = "ExceptionType" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.Failure = "Failure" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.LKG = "LastKnownGood" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.MetadataAddressTag = "MetadataAddress" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.OperationStatusTag = "OperationStatus" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.RefreshReasonTag = "RefreshReason" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.Requested = "Requested" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.Scheduled = "Scheduled" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.Success = "Success" -> string
+const Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.WilsonVersionTag = "WilsonVersion" -> string
+Microsoft.IdentityModel.Logging.IdentityModelTelemetry
+Microsoft.IdentityModel.Logging.IdentityModelTelemetry.IdentityModelTelemetry() -> void
+Microsoft.IdentityModel.Logging.WatchUtility
+Microsoft.IdentityModel.Logging.WatchUtility.WatchUtility() -> void
+static Microsoft.IdentityModel.Logging.IdentityModelTelemetry.IncrementConfigurationManagerCounter(in System.Diagnostics.TagList tagList) -> void
+static Microsoft.IdentityModel.Logging.IdentityModelTelemetry.RecordTotalDurationHistogram(long requestDurationInMs, in System.Diagnostics.TagList tagList) -> void
+static Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.IncrementConfigurationManagerCounter(string metadataAddress, string refreshReason, string operationStatus, string exceptionType) -> void
+static Microsoft.IdentityModel.Logging.IdentityModelTelemetryUtil.RecordTotalDuration(long durationInMs, string metadataAddress, string refreshReason, string operationStatus, string exceptionType) -> void
+static readonly Microsoft.IdentityModel.Logging.IdentityModelTelemetry.ConfigurationManagerCounter -> System.Diagnostics.Metrics.Counter<long>
+static readonly Microsoft.IdentityModel.Logging.IdentityModelTelemetry.TotalDurationHistogram -> System.Diagnostics.Metrics.Histogram<long>
+static readonly Microsoft.IdentityModel.Logging.IdentityModelTelemetry.WilsonMeter -> System.Diagnostics.Metrics.Meter
+static readonly Microsoft.IdentityModel.Logging.WatchUtility.Watch -> System.Diagnostics.Stopwatch

src/Microsoft.IdentityModel.Logging/InternalsVisibleTo.cs

@@ -6,3 +6,4 @@
 [assembly: System.Runtime.CompilerServices.InternalsVisibleTo("Microsoft.IdentityModel.S2S.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100b5fc90e7027f67871e773a8fde8938c81dd402ba65b9201d60593e96c492651e889cc13f1415ebb53fac1131ae0bd333c5ee6021672d9718ea31a8aebd0da0072f25d87dba6fc90ffd598ed4da35e44c398c454307e8e33b8426143daec9f596836f97c8f74750e5975c64e2189f45def46b2a2b1247adc3652bf5c308055da9")]
 [assembly: System.Runtime.CompilerServices.InternalsVisibleTo("Microsoft.IdentityModel.S2S.Tokens.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100b5fc90e7027f67871e773a8fde8938c81dd402ba65b9201d60593e96c492651e889cc13f1415ebb53fac1131ae0bd333c5ee6021672d9718ea31a8aebd0da0072f25d87dba6fc90ffd598ed4da35e44c398c454307e8e33b8426143daec9f596836f97c8f74750e5975c64e2189f45def46b2a2b1247adc3652bf5c308055da9")]
 [assembly: System.Runtime.CompilerServices.InternalsVisibleTo("Microsoft.IdentityModel.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100b5fc90e7027f67871e773a8fde8938c81dd402ba65b9201d60593e96c492651e889cc13f1415ebb53fac1131ae0bd333c5ee6021672d9718ea31a8aebd0da0072f25d87dba6fc90ffd598ed4da35e44c398c454307e8e33b8426143daec9f596836f97c8f74750e5975c64e2189f45def46b2a2b1247adc3652bf5c308055da9")]
+[assembly: System.Runtime.CompilerServices.InternalsVisibleTo("Microsoft.IdentityModel.Protocols.OpenIdConnect.Tests, PublicKey=0024000004800000940000000602000000240000525341310004000001000100b5fc90e7027f67871e773a8fde8938c81dd402ba65b9201d60593e96c492651e889cc13f1415ebb53fac1131ae0bd333c5ee6021672d9718ea31a8aebd0da0072f25d87dba6fc90ffd598ed4da35e44c398c454307e8e33b8426143daec9f596836f97c8f74750e5975c64e2189f45def46b2a2b1247adc3652bf5c308055da9")]

src/Microsoft.IdentityModel.Logging/Microsoft.IdentityModel.Logging.csproj

@@ -32,6 +32,10 @@
     </None>
   </ItemGroup>
 
+  <ItemGroup Condition="'$(TargetFrameworkIdentifier)' == '.NETFramework' or '$(TargetFramework)' == 'netstandard2.0' ">
+    <PackageReference Include="System.Diagnostics.DiagnosticSource" Version="$(SystemDiagnosticSourceVersion)" />
+  </ItemGroup>
+
   <ItemGroup>
     <ProjectReference Include="..\Microsoft.IdentityModel.Abstractions\Microsoft.IdentityModel.Abstractions.csproj" />
   </ItemGroup>

src/Microsoft.IdentityModel.Logging/WatchUtility.cs

@@ -0,0 +1,15 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+using System.Diagnostics;
+
+namespace Microsoft.IdentityModel.Logging
+{
+    /// <summary>
+    /// A utility class to measure time.
+    /// </summary>
+    internal class WatchUtility
+    {
+        internal static readonly Stopwatch Watch = Stopwatch.StartNew();
+    }
+}

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

@@ -147,8 +147,14 @@ public async Task<T> GetConfigurationAsync()
         /// <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 virtual async Task<T> GetConfigurationAsync(CancellationToken cancel)
         {
+            var methodStartTicks = WatchUtility.Watch.Elapsed.Ticks;
+
             if (_currentConfiguration != null && _syncAfter > DateTimeOffset.UtcNow)
+            {
+                TrackGetConfiguration(
+                    methodStartTicks, IdentityModelTelemetryUtil.LKG, IdentityModelTelemetryUtil.Success, string.Empty);
                 return _currentConfiguration;
+            }
 
             Exception fetchMetadataFailure = null;
 
@@ -164,6 +170,8 @@ public virtual async Task<T> GetConfigurationAsync(CancellationToken cancel)
                 await _configurationNullLock.WaitAsync(cancel).ConfigureAwait(false);
                 if (_currentConfiguration != null)
                 {
+                    TrackGetConfiguration(
+                        methodStartTicks, IdentityModelTelemetryUtil.LKG, IdentityModelTelemetryUtil.Success, string.Empty);
                     _configurationNullLock.Release();
                     return _currentConfiguration;
                 }
@@ -183,11 +191,15 @@ 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)
+                        {
+                            TrackGetConfiguration(
+                                methodStartTicks, IdentityModelTelemetryUtil.Requested, IdentityModelTelemetryUtil.Failure, IdentityModelTelemetryUtil.ConfigurationInvalid);
                             throw LogHelper.LogExceptionMessage(
                                 new InvalidConfigurationException(
                                     LogHelper.FormatInvariant(
                                         LogMessages.IDX20810,
                                         result.ErrorMessage)));
+                        }
                     }
 
                     UpdateConfiguration(configuration);
@@ -220,8 +232,14 @@ public virtual async Task<T> GetConfigurationAsync(CancellationToken cancel)
 
             // If metadata exists return it.
             if (_currentConfiguration != null)
+            {
+                TrackGetConfiguration(
+                    methodStartTicks, IdentityModelTelemetryUtil.Requested, IdentityModelTelemetryUtil.Success, string.Empty);
                 return _currentConfiguration;
+            }
 
+            TrackGetConfiguration(
+                methodStartTicks, IdentityModelTelemetryUtil.Requested, IdentityModelTelemetryUtil.Failure, IdentityModelTelemetryUtil.ConfigurationRetrievalFailed);
             throw LogHelper.LogExceptionMessage(
                 new InvalidOperationException(
                     LogHelper.FormatInvariant(
@@ -293,7 +311,7 @@ private void UpdateConfiguration(T configuration)
         /// 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)
         {
@@ -322,6 +340,19 @@ public override void RequestRefresh()
             }
         }
 
+        internal void TrackGetConfiguration(long methodStartTicks, string refreshReason, string operationStatus, string exceptionType)
+        {
+            IdentityModelTelemetryUtil.IncrementConfigurationManagerCounter(
+                    MetadataAddress, refreshReason, operationStatus, exceptionType);
+
+            IdentityModelTelemetryUtil.RecordTotalDuration(
+                (WatchUtility.Watch.Elapsed.Ticks - methodStartTicks) / TimeSpan.TicksPerMillisecond,
+                MetadataAddress,
+                refreshReason,
+                operationStatus,
+                exceptionType);
+        }
+
         /// <summary>
         /// 12 hours is the default time interval that afterwards, <see cref="GetBaseConfigurationAsync(CancellationToken)"/> will obtain new configuration.
         /// </summary>

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

@@ -0,0 +1 @@
+Microsoft.IdentityModel.Protocols.ConfigurationManager<T>.TrackGetConfiguration(long methodStartTicks, string refreshReason, string operationStatus, string exceptionType) -> void