Add telemetry, logging, and fix overall logic

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

@@ -521,7 +521,8 @@ await ValidateJWEAsync(jsonWebToken, validationParameters, currentConfiguration)
                     {
                         _telemetryClient.IncrementConfigurationRefreshRequestCounter(
                             validationParameters.ConfigurationManager.MetadataAddress,
-                            TelemetryConstants.Protocols.Lkg);
+                            TelemetryConstants.Protocols.Lkg,
+                            TelemetryConstants.Protocols.IrrelevantConfigurationSource);
 
                         validationParameters.ConfigurationManager.RequestRefresh();
                         validationParameters.RefreshBeforeValidation = true;

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

@@ -231,8 +231,19 @@ private async Task<T> GetConfigurationNonBlockingAsync(CancellationToken cancel)
                     if (ConfigurationEventHandler != null)
                     {
                         var configurationRetrieved = await HandleBeforeRetrieveAsync(cancel).ConfigureAwait(false);
-                        if (configurationRetrieved)
-                            return _currentConfiguration; // TODO check if everything has been done
+
+                        // replicate the behavior of successful retrieval from endpoint
+                        if (configurationRetrieved != null && configurationRetrieved.Configuration != null)
+                        {
+                            TelemetryClient.IncrementConfigurationRefreshRequestCounter(
+                                MetadataAddress,
+                                TelemetryConstants.Protocols.FirstRefresh,
+                                TelemetryConstants.Protocols.HandlerAsConfigurationSource
+                                );
+
+                            UpdateConfiguration(configurationRetrieved.Configuration, configurationRetrieved.RetrievalTime);
+                            return _currentConfiguration;
+                        }
                     }
 
                     // Don't use the individual CT here, this is a shared operation that shouldn't be affected by an individual's cancellation.
@@ -259,7 +270,9 @@ private async Task<T> GetConfigurationNonBlockingAsync(CancellationToken cancel)
 
                     TelemetryClient.IncrementConfigurationRefreshRequestCounter(
                         MetadataAddress,
-                        TelemetryConstants.Protocols.FirstRefresh);
+                        TelemetryConstants.Protocols.FirstRefresh,
+                        TelemetryConstants.Protocols.EndpointAsConfigurationSource
+                        );
 
                     UpdateConfiguration(configuration, TimeProvider.GetUtcNow().UtcDateTime);
                 }
@@ -270,6 +283,7 @@ private async Task<T> GetConfigurationNonBlockingAsync(CancellationToken cancel)
                     TelemetryClient.IncrementConfigurationRefreshRequestCounter(
                         MetadataAddress,
                         TelemetryConstants.Protocols.FirstRefresh,
+                        TelemetryConstants.Protocols.EndpointAsConfigurationSource,
                         ex);
 
                     LogHelper.LogExceptionMessage(
@@ -292,7 +306,8 @@ private async Task<T> GetConfigurationNonBlockingAsync(CancellationToken cancel)
                 {
                     TelemetryClient.IncrementConfigurationRefreshRequestCounter(
                         MetadataAddress,
-                        TelemetryConstants.Protocols.Automatic);
+                        TelemetryConstants.Protocols.Automatic,
+                        TelemetryConstants.Protocols.IrrelevantConfigurationSource);
 
                     _ = Task.Run(UpdateCurrentConfiguration, CancellationToken.None);
                 }
@@ -327,8 +342,11 @@ private void UpdateCurrentConfiguration()
                 if (ConfigurationEventHandler != null)
                 {
                     var configurationRetrieved = HandleBeforeRetrieveAsync().ConfigureAwait(false).GetAwaiter().GetResult();
-                    if (configurationRetrieved)
-                        return; // TODO check if everything has been done
+                    if (configurationRetrieved != null && configurationRetrieved.Configuration != null)
+                    {
+                        UpdateConfiguration(configurationRetrieved.Configuration, configurationRetrieved.RetrievalTime);
+                        return;
+                    }
                 }
 
                 T configuration = _configRetriever.GetConfigurationAsync(
@@ -339,6 +357,7 @@ private void UpdateCurrentConfiguration()
                 var elapsedTime = TimeProvider.GetElapsedTime(startTimestamp);
                 TelemetryClient.LogConfigurationRetrievalDuration(
                     MetadataAddress,
+                    TelemetryConstants.Protocols.EndpointAsConfigurationSource,
                     elapsedTime);
 
                 if (_configValidator == null)
@@ -365,6 +384,7 @@ private void UpdateCurrentConfiguration()
                 var elapsedTime = TimeProvider.GetElapsedTime(startTimestamp);
                 TelemetryClient.LogConfigurationRetrievalDuration(
                     MetadataAddress,
+                    TelemetryConstants.Protocols.EndpointAsConfigurationSource,
                     elapsedTime,
                     ex);
 
@@ -401,16 +421,10 @@ private void UpdateConfiguration(T configuration, DateTimeOffset retrievalTime)
                     }
                     catch (Exception ex)
                     {
-                        TelemetryClient.IncrementConfigurationRefreshRequestCounter(
-                            MetadataAddress,
-                            TelemetryConstants.Protocols.FirstRefresh, // todo is this true
-                            ex); // TODO new dimension
-
-                        // todo new logs
                         LogHelper.LogExceptionMessage(
                             new InvalidOperationException(
                                 LogHelper.FormatInvariant(
-                                    "IDX20817: Exception occurred while notifying configuration update handler. MetadataAddress: '{0}', Exception: '{1}'.",
+                                   LogMessages.IDX20812,
                                     LogHelper.MarkAsNonPII(MetadataAddress ?? "null"),
                                     ex),
                                 ex));
@@ -458,7 +472,8 @@ private void RequestRefreshBackgroundThread()
             {
                 TelemetryClient.IncrementConfigurationRefreshRequestCounter(
                     MetadataAddress,
-                    TelemetryConstants.Protocols.Manual);
+                    TelemetryConstants.Protocols.Manual,
+                    TelemetryConstants.Protocols.IrrelevantConfigurationSource);
 
                 _isFirstRefreshRequest = false;
                 if (Interlocked.CompareExchange(ref _configurationRetrieverState, ConfigurationRetrieverRunning, ConfigurationRetrieverIdle) == ConfigurationRetrieverIdle)
@@ -469,65 +484,62 @@ private void RequestRefreshBackgroundThread()
             }
         }
 
-        private async Task<bool> HandleBeforeRetrieveAsync(CancellationToken cancel = default)
+        private async Task<ConfigurationEventHandlerResult<T>> HandleBeforeRetrieveAsync(CancellationToken cancel = default)
         {
             long beforeHandlerTimestamp = TimeProvider.GetTimestamp();
+#pragma warning disable CA1031 // Do not catch general exception types
             try
             {
-                var cachedResult = await ConfigurationEventHandler.BeforeRetrieveAsync(MetadataAddress, cancel).ConfigureAwait(false);
-                if (cachedResult != null && cachedResult.Configuration != null)
+                var handlerResult = await ConfigurationEventHandler.BeforeRetrieveAsync(MetadataAddress, cancel).ConfigureAwait(false);
+                if (handlerResult != null && handlerResult.Configuration != null)
                 {
                     var handlerElapsedTime = TimeProvider.GetElapsedTime(beforeHandlerTimestamp);
                     TelemetryClient.LogConfigurationRetrievalDuration(
                         MetadataAddress,
-                        handlerElapsedTime);// TODO new dimension for source
+                        TelemetryConstants.Protocols.HandlerAsConfigurationSource,
+                        handlerElapsedTime);
 
                     // Validate configuration from handler
                     if (_configValidator != null)
                     {
-                        ConfigurationValidationResult result = _configValidator.Validate(cachedResult.Configuration);
+                        ConfigurationValidationResult result = _configValidator.Validate(handlerResult.Configuration);
                         if (!result.Succeeded)
                         {
                             // Just log the error and proceed to fetch from endpoint
                             LogHelper.LogExceptionMessage(
                                 new InvalidConfigurationException(
                                     LogHelper.FormatInvariant(
-                                        LogMessages.IDX20810, // TODO new log message
+                                        LogMessages.IDX20812,
                                         result.ErrorMessage)));
 
-                            return false;
+                            return ConfigurationEventHandlerResult<T>.NoResult;
                         }
                     }
 
-                    // No validator configured, use configuration
-                    TelemetryClient.IncrementConfigurationRefreshRequestCounter(
-                        MetadataAddress,
-                        TelemetryConstants.Protocols.FirstRefresh); // TODO new dimension for source
-
-                    UpdateConfiguration(cachedResult.Configuration, cachedResult.RetrievalTime);
-                    return true;
+                    // No validator configured, return configuration
+                    return handlerResult;
                 }
             }
             catch (Exception ex)
             {
                 var handlerErrorElapsedTime = TimeProvider.GetElapsedTime(beforeHandlerTimestamp);
                 TelemetryClient.LogConfigurationRetrievalDuration(
                     MetadataAddress,
+                    TelemetryConstants.Protocols.HandlerAsConfigurationSource,
                     handlerErrorElapsedTime,
-                    ex); // TODO new dimension for source
+                    ex);
 
-                // Log but don't fail - proceed to fetch from endpoint
-                // TODO check error
                 LogHelper.LogExceptionMessage(
                     new InvalidOperationException(
                         LogHelper.FormatInvariant(
-                            "Failed to retrieve configuration from event handler. MetadataAddress: '{0}', Exception: '{1}'.",
+                            LogMessages.IDX20811,
                             LogHelper.MarkAsNonPII(MetadataAddress ?? "null"),
                             ex),
                         ex));
             }
+#pragma warning restore CA1031 // Do not catch general exception types
 
-            return false;
+            return ConfigurationEventHandlerResult<T>.NoResult;
         }
 
         /// <summary>

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

@@ -38,8 +38,19 @@ private async Task<T> GetConfigurationWithBlockingAsync(CancellationToken cancel
                         if (ConfigurationEventHandler != null)
                         {
                             var configurationRetrieved = await HandleBeforeRetrieveAsync(cancel).ConfigureAwait(false);
-                            if (configurationRetrieved)
+
+                            // replicate the behavior of successful retrieval from endpoint
+                            if (configurationRetrieved != null && configurationRetrieved.Configuration != null)
+                            {
+                                TelemetryForUpdateBlocking(TelemetryConstants.Protocols.HandlerAsConfigurationSource);
+
+                                if (_refreshRequested)
+                                    _refreshRequested = false;
+
+                                UpdateConfiguration(configurationRetrieved.Configuration, configurationRetrieved.RetrievalTime);
+
                                 return _currentConfiguration;
+                            }
                         }
 
                         // Don't use the individual CT here, this is a shared operation that shouldn't be affected by an individual's cancellation.
@@ -49,6 +60,7 @@ private async Task<T> GetConfigurationWithBlockingAsync(CancellationToken cancel
                         var elapsedTime = TimeProvider.GetElapsedTime(startTimestamp);
                         TelemetryClient.LogConfigurationRetrievalDuration(
                             MetadataAddress,
+                            TelemetryConstants.Protocols.EndpointAsConfigurationSource,
                             elapsedTime);
 
                         if (_configValidator != null)
@@ -60,7 +72,7 @@ private async Task<T> GetConfigurationWithBlockingAsync(CancellationToken cancel
 
                         _lastRequestRefresh = TimeProvider.GetUtcNow().UtcDateTime;
 
-                        TelemetryForUpdateBlocking();
+                        TelemetryForUpdateBlocking(TelemetryConstants.Protocols.EndpointAsConfigurationSource);
 
                         if (_refreshRequested)
                             _refreshRequested = false;
@@ -90,6 +102,7 @@ private async Task<T> GetConfigurationWithBlockingAsync(CancellationToken cancel
                             TelemetryClient.IncrementConfigurationRefreshRequestCounter(
                                 MetadataAddress,
                                 TelemetryConstants.Protocols.FirstRefresh,
+                                TelemetryConstants.Protocols.EndpointAsConfigurationSource,
                                 ex);
 
                             throw LogHelper.LogExceptionMessage(
@@ -106,6 +119,7 @@ private async Task<T> GetConfigurationWithBlockingAsync(CancellationToken cancel
 
                             TelemetryClient.LogConfigurationRetrievalDuration(
                                 MetadataAddress,
+                                TelemetryConstants.Protocols.EndpointAsConfigurationSource,
                                 elapsedTime,
                                 ex);
 
@@ -147,7 +161,7 @@ private void RequestRefreshBlocking()
             }
         }
 
-        private void TelemetryForUpdateBlocking()
+        private void TelemetryForUpdateBlocking(string configurationSource)
         {
             string updateMode;
 
@@ -160,6 +174,7 @@ private void TelemetryForUpdateBlocking()
             {
                 TelemetryClient.IncrementConfigurationRefreshRequestCounter(
                     MetadataAddress,
+                    configurationSource,
                     updateMode);
             }
 #pragma warning disable CA1031 // Do not catch general exception types

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

@@ -0,0 +1,2 @@
+const Microsoft.IdentityModel.Protocols.LogMessages.IDX20811 = "IDX20811: Failed to retrieve configuration from event handler. MetadataAddress: '{0}', Exception: '{1}'." -> string
+const Microsoft.IdentityModel.Protocols.LogMessages.IDX20812 = "IDX20812: Failed to validate configuration retrieved via event handler. Exception: '{0}'." -> string

src/Microsoft.IdentityModel.Protocols/LogMessages.cs

@@ -29,6 +29,8 @@ internal static class LogMessages
         internal const string IDX20808 = "IDX20808: Network error occurred. Status code: '{0}'. \nResponse content: '{1}'. \nAttempting to retrieve document again from: '{2}'.";
         internal const string IDX20809 = "IDX20809: Unable to retrieve document from: '{0}'. Status code: '{1}'. \nResponse content: '{2}'.";
         internal const string IDX20810 = "IDX20810: Configuration validation failed, see inner exception for more details. Exception: '{0}'.";
+        internal const string IDX20811 = "IDX20811: Failed to retrieve configuration from event handler. MetadataAddress: '{0}', Exception: '{1}'.";
+        internal const string IDX20812 = "IDX20812: Failed to validate configuration retrieved via event handler. Exception: '{0}'.";
 
 #pragma warning restore 1591
     }

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

@@ -1,3 +1,17 @@
+const Microsoft.IdentityModel.Telemetry.TelemetryConstants.ConfigurationSourceTag = "ConfigurationSource" -> string
+const Microsoft.IdentityModel.Telemetry.TelemetryConstants.Protocols.EndpointAsConfigurationSource = "MetadataEndpoint" -> string
+const Microsoft.IdentityModel.Telemetry.TelemetryConstants.Protocols.HandlerAsConfigurationSource = "Handler" -> string
+const Microsoft.IdentityModel.Telemetry.TelemetryConstants.Protocols.IrrelevantConfigurationSource = "IrrelevantForScenario" -> string
 const Microsoft.IdentityModel.Tokens.AppContextSwitches.UseCapitalizedXMLTypeAttrSwitch = "Switch.Microsoft.IdentityModel.UseCapitalizedXMLTypeAttr" -> string
 const Microsoft.IdentityModel.Tokens.LogMessages.IDX10278 = "IDX10278: Unable to retrieve configuration from authority: '{0}'. \nProceeding with token decryption in case the relevant properties have been set manually on the TokenValidationParameters. Exception caught: \n {1}. See https://aka.ms/validate-using-configuration-manager for additional information." -> string
+Microsoft.IdentityModel.Telemetry.ITelemetryClient.IncrementConfigurationRefreshRequestCounter(string metadataAddress, string operationStatus, string configurationSource) -> void
+Microsoft.IdentityModel.Telemetry.ITelemetryClient.IncrementConfigurationRefreshRequestCounter(string metadataAddress, string operationStatus, string configurationSource, System.Exception exception) -> void
+Microsoft.IdentityModel.Telemetry.ITelemetryClient.LogBackgroundConfigurationRefreshFailure(string metadataAddress, string configurationSource, System.Exception exception) -> void
+Microsoft.IdentityModel.Telemetry.ITelemetryClient.LogConfigurationRetrievalDuration(string metadataAddress, string configurationSource, System.TimeSpan operationDuration) -> void
+Microsoft.IdentityModel.Telemetry.ITelemetryClient.LogConfigurationRetrievalDuration(string metadataAddress, string configurationSource, System.TimeSpan operationDuration, System.Exception exception) -> void
+Microsoft.IdentityModel.Telemetry.TelemetryClient.IncrementConfigurationRefreshRequestCounter(string metadataAddress, string operationStatus, string configurationSource) -> void
+Microsoft.IdentityModel.Telemetry.TelemetryClient.IncrementConfigurationRefreshRequestCounter(string metadataAddress, string operationStatus, string configurationSource, System.Exception exception) -> void
+Microsoft.IdentityModel.Telemetry.TelemetryClient.LogBackgroundConfigurationRefreshFailure(string metadataAddress, string configurationSource, System.Exception exception) -> void
+Microsoft.IdentityModel.Telemetry.TelemetryClient.LogConfigurationRetrievalDuration(string metadataAddress, string configurationSource, System.TimeSpan operationDuration) -> void
+Microsoft.IdentityModel.Telemetry.TelemetryClient.LogConfigurationRetrievalDuration(string metadataAddress, string configurationSource, System.TimeSpan operationDuration, System.Exception exception) -> void
 static Microsoft.IdentityModel.Tokens.AppContextSwitches.UseCapitalizedXMLTypeAttr.get -> bool