Fix for 3000 - improve logs for credential loading

Author: bgavrilMS

src/Microsoft.Identity.Web.Certificate/DefaultCredentialsLoader.cs

@@ -1,6 +1,7 @@
 // Copyright (c) Microsoft Corporation. All rights reserved.
 // Licensed under the MIT License.
 
+using System;
 using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Threading;
@@ -10,11 +11,34 @@
 
 namespace Microsoft.Identity.Web
 {
+
     /// <summary>
     /// Default credentials loader.
     /// </summary>
     public class DefaultCredentialsLoader : ICredentialsLoader
     {
+        /// <summary>
+        /// Logging infrastructure
+        /// </summary>
+        private static class Logger
+        {
+            public static void CredentialLoadingFailure(ILogger? logger, CredentialDescription cd, Exception? ex)
+            {
+                if (logger != null && logger.IsEnabled(LogLevel.Information))
+                {
+                    __CredentialLoadingFailure(logger, cd.Id, cd.CredentialType.ToString(), cd.Skip, ex);
+                }
+            }
+
+            private static readonly Action<ILogger, string, string, bool, Exception?> __CredentialLoadingFailure =
+                LoggerMessage.Define<string, string, bool>(
+                    LogLevel.Information,
+                    new EventId(
+                        7,
+                        nameof(CredentialLoadingFailure)),
+            "Failed to load credential {id} from source {sourceType}. Will it be skipped in the future ? {skip}.");
+        }
+
         ILogger<DefaultCredentialsLoader>? _logger;
         private readonly ConcurrentDictionary<string, SemaphoreSlim> _loadingSemaphores = new ConcurrentDictionary<string, SemaphoreSlim>();
 
@@ -32,7 +56,7 @@ public DefaultCredentialsLoader(ILogger<DefaultCredentialsLoader>? logger)
                 { CredentialSource.StoreWithThumbprint, new StoreWithThumbprintCertificateLoader() },
                 { CredentialSource.StoreWithDistinguishedName, new StoreWithDistinguishedNameCertificateLoader() },
                 { CredentialSource.Base64Encoded, new Base64EncodedCertificateLoader() },
-                { CredentialSource.SignedAssertionFromManagedIdentity, new SignedAssertionFromManagedIdentityCredentialLoader() },
+                { CredentialSource.SignedAssertionFromManagedIdentity, new SignedAssertionFromManagedIdentityCredentialLoader(_logger) },
                 { CredentialSource.SignedAssertionFilePath, new SignedAssertionFilePathCredentialsLoader(_logger) }
             };
         }
@@ -51,7 +75,8 @@ public DefaultCredentialsLoader() : this(null)
         public IDictionary<CredentialSource, ICredentialSourceLoader> CredentialSourceLoaders { get; }
 
         /// <inheritdoc/>
-        /// Load the credentials from the description, if needed.
+        /// Load the credentials from the description, if needed. 
+        /// Important: Ignores SKIP flag, propagates exceptions.
         public async Task LoadCredentialsIfNeededAsync(CredentialDescription credentialDescription, CredentialSourceLoaderParameters? parameters = null)
         {
             _ = Throws.IfNull(credentialDescription);
@@ -69,7 +94,17 @@ public async Task LoadCredentialsIfNeededAsync(CredentialDescription credentialD
                     if (credentialDescription.CachedValue == null)
                     {
                         if (CredentialSourceLoaders.TryGetValue(credentialDescription.SourceType, out ICredentialSourceLoader? loader))
-                            await loader.LoadIfNeededAsync(credentialDescription, parameters);
+                        {
+                            try
+                            {
+                                await loader.LoadIfNeededAsync(credentialDescription, parameters);
+                            }
+                            catch (Exception ex)
+                            {
+                                Logger.CredentialLoadingFailure(_logger, credentialDescription, ex);
+                                throw;
+                            }
+                        }
                     }
                 }
                 finally
@@ -81,11 +116,18 @@ public async Task LoadCredentialsIfNeededAsync(CredentialDescription credentialD
         }
 
         /// <inheritdoc/>
-        public async Task<CredentialDescription?> LoadFirstValidCredentialsAsync(IEnumerable<CredentialDescription> credentialDescriptions, CredentialSourceLoaderParameters? parameters = null)
+        /// Loads first valid credential which is not marked as Skipped. 
+        public async Task<CredentialDescription?> LoadFirstValidCredentialsAsync(
+            IEnumerable<CredentialDescription> credentialDescriptions, 
+            CredentialSourceLoaderParameters? parameters = null)
         {
             foreach (var credentialDescription in credentialDescriptions)
             {
                 await LoadCredentialsIfNeededAsync(credentialDescription, parameters);
+
+                // TODO:  Exceptions which occur in trying various credentials are logged and ignored.
+                // is this really intended behavior? This is different from WithClientCredentialsAsync
+
                 if (!credentialDescription.Skip)
                 {
                     return credentialDescription;
@@ -107,6 +149,5 @@ public void ResetCredentials(IEnumerable<CredentialDescription> credentialDescri
                 }
             }
         }
-
     }
 }

src/Microsoft.Identity.Web.Certificate/LoggingEventId.cs

@@ -0,0 +1,33 @@
+// Copyright (c) Microsoft Corporation. All rights reserved.
+// Licensed under the MIT License.
+
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.Identity.Web
+{
+    /// <summary>
+    /// EventIds for Logging.
+    /// </summary>
+    internal static class LoggingEventId
+    {
+#pragma warning disable IDE1006 // Naming Styles
+        // SessionCacheProvider EventIds 200+
+        public static readonly EventId SessionCache = new EventId(200, "SessionCache");
+        public static readonly EventId SessionCacheKeyNotFound = new EventId(201, "SessionCacheKeyNotFound");
+
+        // TokenAcquisition EventIds 300+
+        public static readonly EventId TokenAcquisitionError = new EventId(300, "TokenAcquisitionError");
+        public static readonly EventId TokenAcquisitionMsalAuthenticationResultTime = new EventId(301, "TokenAcquisitionMsalAuthenticationResultTime");
+
+        // ConfidentialClientApplicationBuilderExtension EventIds 400+
+        public static readonly EventId NotUsingManagedIdentity = new EventId(400, "NotUsingManagedIdentity");
+        public static readonly EventId UsingManagedIdentity = new EventId(401, "UsingManagedIdentity");
+        public static readonly EventId UsingPodIdentityFile = new EventId(402, "UsingPodIdentityFile");
+        public static readonly EventId UsingCertThumbprint = new EventId(403, "UsingCertThumbprint");
+        public static readonly EventId UsingSignedAssertionFromVault = new EventId(404, "UsingSignedAssertionFromVault");
+        public static readonly EventId CredentialLoadAttempt = new EventId(405, "CredentialLoadAttempt");
+        public static readonly EventId CredentialLoadAttemptFailed = new EventId(406, "CredentialLoadAttemptFailed");
+
+#pragma warning restore IDE1006 // Naming Styles
+    }
+}

src/Microsoft.Identity.Web.Certificate/SignedAssertionFilePathCredentialsLoader.cs

@@ -36,13 +36,14 @@ public async Task LoadIfNeededAsync(CredentialDescription credentialDescription,
                 {
                     // Given that managed identity can be not available locally, we need to try to get a
                     // signed assertion, and if it fails, move to the next credentials
-                    _= await signedAssertion!.GetSignedAssertionAsync(null);
+                    _ = await signedAssertion!.GetSignedAssertionAsync(null);
                     credentialDescription.CachedValue = signedAssertion;
                 }
                 catch (Exception)
                 {
                     credentialDescription.Skip = true;
-                }
+                    throw;
+                }                
             }
         }
     }

src/Microsoft.Identity.Web.Certificate/SignedAssertionFromManagedIdentityCredentialLoader.cs

@@ -4,12 +4,21 @@
 using System.Threading;
 using System.Threading.Tasks;
 using Azure.Identity;
+using Microsoft.Extensions.Logging;
 using Microsoft.Identity.Abstractions;
+using Microsoft.Identity.Client;
 
 namespace Microsoft.Identity.Web
 {
     internal class SignedAssertionFromManagedIdentityCredentialLoader : ICredentialSourceLoader
     {
+        private ILogger<DefaultCredentialsLoader>? _logger;
+
+        public SignedAssertionFromManagedIdentityCredentialLoader(ILogger<DefaultCredentialsLoader>? logger)
+        {
+            _logger = logger;
+        }
+
         public CredentialSource CredentialSource => CredentialSource.SignedAssertionFromManagedIdentity;
 
         public async Task LoadIfNeededAsync(CredentialDescription credentialDescription, CredentialSourceLoaderParameters? credentialSourceLoaderParameters)
@@ -19,16 +28,19 @@ public async Task LoadIfNeededAsync(CredentialDescription credentialDescription,
                 ManagedIdentityClientAssertion? managedIdentityClientAssertion = credentialDescription.CachedValue as ManagedIdentityClientAssertion;
                 if (credentialDescription.CachedValue == null)
                 {
-                    managedIdentityClientAssertion = new ManagedIdentityClientAssertion(credentialDescription.ManagedIdentityClientId, credentialDescription.TokenExchangeUrl);
+                    managedIdentityClientAssertion = new ManagedIdentityClientAssertion(
+                        credentialDescription.ManagedIdentityClientId, 
+                        credentialDescription.TokenExchangeUrl,
+                        _logger);
                 }
                 try
                 {
                     // Given that managed identity can be not available locally, we need to try to get a
                     // signed assertion, and if it fails, move to the next credentials
-                    _= await managedIdentityClientAssertion!.GetSignedAssertionAsync(null);
+                    _ = await managedIdentityClientAssertion!.GetSignedAssertionAsync(null);
                     credentialDescription.CachedValue = managedIdentityClientAssertion;
                 }
-                catch (AuthenticationFailedException)
+                catch (MsalServiceException)
                 {
                     credentialDescription.Skip = true;
                     throw;

src/Microsoft.Identity.Web.Certificateless/AzureIdentityForKubernetesClientAssertion.Logger.cs

@@ -8,28 +8,28 @@ namespace Microsoft.Identity.Web
 {
     public partial class AzureIdentityForKubernetesClientAssertion
     {
-    /*       
-    // High performance logger messages (before generation).
-    #pragma warning disable SYSLIB1009 // Logging methods must be static
-            [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "SignedAssertionFileDiskPath not provided. Falling back to the content of the AZURE_FEDERATED_TOKEN_FILE environment variable. ")]
-            partial void SignedAssertionFileDiskPathNotProvided(ILogger logger);
+        /*       
+        // High performance logger messages (before generation).
+        #pragma warning disable SYSLIB1009 // Logging methods must be static
+                [LoggerMessage(EventId = 1, Level = LogLevel.Information, Message = "SignedAssertionFileDiskPath not provided. Falling back to the content of the AZURE_FEDERATED_TOKEN_FILE environment variable. ")]
+                partial void SignedAssertionFileDiskPathNotProvided(ILogger logger);
 
-            [LoggerMessage(EventId = 2, Level = LogLevel.Information, Message = "The `{environmentVariableName}` environment variable not provided. ")]
-            partial void SignedAssertionEnvironmentVariableNotProvided(ILogger logger, string environmentVariableName);
+                [LoggerMessage(EventId = 2, Level = LogLevel.Information, Message = "The `{environmentVariableName}` environment variable not provided. ")]
+                partial void SignedAssertionEnvironmentVariableNotProvided(ILogger logger, string environmentVariableName);
 
-            [LoggerMessage(EventId = 3, Level = LogLevel.Error, Message = "The environment variable AZURE_FEDERATED_TOKEN_FILE or AZURE_ACCESS_TOKEN_FILE or the 'SignedAssertionFileDiskPath' must be set to the path of the file containing the signed assertion. ")]
-            partial void NoSignedAssertionParameterProvided(ILogger logger);
+                [LoggerMessage(EventId = 3, Level = LogLevel.Error, Message = "The environment variable AZURE_FEDERATED_TOKEN_FILE or AZURE_ACCESS_TOKEN_FILE or the 'SignedAssertionFileDiskPath' must be set to the path of the file containing the signed assertion. ")]
+                partial void NoSignedAssertionParameterProvided(ILogger logger);
 
-            [LoggerMessage(EventId = 4, Level = LogLevel.Error, Message = "The file `{filePath}` containing the signed assertion was not found. ")]
-            partial void FileAssertionPathNotFound(ILogger logger, string filePath);
+                [LoggerMessage(EventId = 4, Level = LogLevel.Error, Message = "The file `{filePath}` containing the signed assertion was not found. ")]
+                partial void FileAssertionPathNotFound(ILogger logger, string filePath);
 
-            [LoggerMessage(EventId = 5, Level = LogLevel.Information, Message = "Successfully read the signed assertion for `{filePath}`. Expires at {expiry}. ")]
-            partial void SuccessFullyReadSignedAssertion(ILogger logger, string filePath, DateTime expiry);
+                [LoggerMessage(EventId = 5, Level = LogLevel.Information, Message = "Successfully read the signed assertion for `{filePath}`. Expires at {expiry}. ")]
+                partial void SuccessFullyReadSignedAssertion(ILogger logger, string filePath, DateTime expiry);
 
-            [LoggerMessage(EventId = 6, Level = LogLevel.Error, Message = "The file `{filePath} does not contain a valid signed assertion. {message}. ")]
-            partial void FileDoesNotContainValidAssertion(ILogger logger, string filePath, string message);
-    #pragma warning restore SYSLIB1009 // Logging methods must be static
-    */
+                [LoggerMessage(EventId = 6, Level = LogLevel.Error, Message = "The file `{filePath} does not contain a valid signed assertion. {message}. ")]
+                partial void FileDoesNotContainValidAssertion(ILogger logger, string filePath, string message);
+        #pragma warning restore SYSLIB1009 // Logging methods must be static
+        */
 
         /// <summary>
         /// Performant logging messages.
@@ -84,6 +84,7 @@ public static void FileDoesNotContainValidAssertion(ILogger? logger, string file
                 }
             }
 
+
             private static readonly Action<ILogger, Exception?> __SignedAssertionFileDiskPathNotProvidedCallback =
                 LoggerMessage.Define(LogLevel.Information, new EventId(1, nameof(SignedAssertionFileDiskPathNotProvided)), "SignedAssertionFileDiskPath not provided. Falling back to the content of the AZURE_FEDERATED_TOKEN_FILE environment variable. ");
             private static readonly Action<ILogger, string, Exception?> __SignedAssertionEnvironmentVariableNotProvidedCallback =
@@ -100,6 +101,7 @@ public static void FileDoesNotContainValidAssertion(ILogger? logger, string file
 
             private static readonly Action<ILogger, string, string, Exception?> __FileDoesNotContainValidAssertionCallback =
                 LoggerMessage.Define<string, string>(LogLevel.Error, new EventId(6, nameof(FileDoesNotContainValidAssertion)), "The file `{filePath} does not contain a valid signed assertion. {message}. ");
+
         }
     }
 }