Audit all info and verbose logs and use lambdas to generate strings (#…

…3919) * Audit all info and verbose logs and use lambdas to generate strings * fix * fix * fix * Apply suggestions from code review Co-authored-by: Peter M <[email protected]> Co-authored-by: Gladwin Johnson <[email protected]> * fix * fix --------- Co-authored-by: Peter M <[email protected]> Co-authored-by: Gladwin Johnson <[email protected]>
AzureAD · Feb 9, 2023 · a07da18 · a07da18
1 parent 7929bff
commit a07da18
Show file tree

Hide file tree

Showing 76 changed files with 536 additions and 448 deletions.
diff --git a/src/client/Microsoft.Identity.Client.Broker/RuntimeBroker.cs b/src/client/Microsoft.Identity.Client.Broker/RuntimeBroker.cs
@@ -146,7 +146,7 @@ public async Task<MsalTokenResponse> AcquireTokenInteractiveAsync(
 
             var cancellationToken = authenticationRequestParameters.RequestContext.UserCancellationToken;
 
-            _logger?.Verbose("[WamBroker] Using Windows account picker.");
+            _logger?.Verbose(() => "[WamBroker] Using Windows account picker.");
 
             if (authenticationRequestParameters?.Account?.HomeAccountId?.ObjectId != null)
             {
@@ -215,7 +215,7 @@ public async Task<MsalTokenResponse> SignInInteractivelyAsync(
             {
                 //Login Hint
                 string loginHint = authenticationRequestParameters.LoginHint ?? authenticationRequestParameters?.Account?.Username;
-                _logger?.Verbose("[WamBroker] AcquireTokenInteractive - login hint provided? " + !string.IsNullOrEmpty(loginHint));
+                _logger?.Verbose(() => "[WamBroker] AcquireTokenInteractive - login hint provided? " + !string.IsNullOrEmpty(loginHint));
 
                 using (var result = await s_lazyCore.Value.SignInInteractivelyAsync(
                     _parentHandle,
@@ -242,7 +242,7 @@ public async Task<MsalTokenResponse> AcquireTokenInteractiveDefaultUserAsync(
             MsalTokenResponse msalTokenResponse = null;
             var cancellationToken = authenticationRequestParameters.RequestContext.UserCancellationToken;
 
-            _logger?.Verbose("[WamBroker] Signing in with the default user account.");
+            _logger?.Verbose(() => "[WamBroker] Signing in with the default user account.");
 
             using (var authParams = WamAdapters.GetCommonAuthParameters(
                 authenticationRequestParameters, 
@@ -283,7 +283,7 @@ public async Task<MsalTokenResponse> AcquireTokenSilentAsync(
             var cancellationToken = authenticationRequestParameters.RequestContext.UserCancellationToken;
             MsalTokenResponse msalTokenResponse = null;
 
-            _logger?.Verbose("[WamBroker] Acquiring token silently.");
+            _logger?.Verbose(() => "[WamBroker] Acquiring token silently.");
 
             using (var authParams = WamAdapters.GetCommonAuthParameters(
                 authenticationRequestParameters, 
@@ -331,7 +331,7 @@ public async Task<MsalTokenResponse> AcquireTokenSilentDefaultUserAsync(
             var cancellationToken = authenticationRequestParameters.RequestContext.UserCancellationToken;
             MsalTokenResponse msalTokenResponse = null;
 
-            _logger?.Verbose("[WamBroker] Acquiring token silently for default account.");
+            _logger?.Verbose(() => "[WamBroker] Acquiring token silently for default account.");
 
             using (var authParams = WamAdapters.GetCommonAuthParameters(
                 authenticationRequestParameters, 
@@ -361,7 +361,7 @@ public async Task<MsalTokenResponse> AcquireTokenByUsernamePasswordAsync(
             var cancellationToken = authenticationRequestParameters.RequestContext.UserCancellationToken;
             MsalTokenResponse msalTokenResponse = null;
 
-            _logger?.Verbose("[WamBroker] Acquiring token with Username Password flow.");
+            _logger?.Verbose(() => "[WamBroker] Acquiring token with Username Password flow.");
 
             using (AuthParameters authParams = WamAdapters.GetCommonAuthParameters(
                 authenticationRequestParameters, 
@@ -391,7 +391,7 @@ public async Task RemoveAccountAsync(ApplicationConfiguration appConfig, IAccoun
 
             if (account == null)
             {
-                _logger?.Verbose("[WamBroker] No valid account was passed to RemoveAccountAsync. ");
+                _logger?.Verbose(() => "[WamBroker] No valid account was passed to RemoveAccountAsync. ");
                 throw new MsalClientException("wam_remove_account_failed", "No valid account was passed.");
             }
 
@@ -400,11 +400,11 @@ public async Task RemoveAccountAsync(ApplicationConfiguration appConfig, IAccoun
             //if OperatingSystemAccount is passed then we use the user signed -in on the machine
             if (PublicClientApplication.IsOperatingSystemAccount(account))
             {
-                _logger?.Verbose("[WamBroker] Default Operating System Account cannot be removed. ");
+                _logger?.Verbose(() => "[WamBroker] Default Operating System Account cannot be removed. ");
                 throw new MsalClientException("wam_remove_account_failed", "Default Operating System account cannot be removed.");
             }
 
-            _logger?.Info($"Removing WAM Account. Correlation ID : {correlationId} ");
+            _logger?.Info(() => $"Removing WAM Account. Correlation ID : {correlationId} ");
 
             {
                 using (var readAccountResult = await s_lazyCore.Value.ReadAccountByIdAsync(
@@ -414,7 +414,7 @@ public async Task RemoveAccountAsync(ApplicationConfiguration appConfig, IAccoun
                 {
                     if (readAccountResult.IsSuccess)
                     {
-                        _logger?.Verbose("[WamBroker] WAM Account exist and can be removed.");
+                        _logger?.Verbose(() => "[WamBroker] WAM Account exists and can be removed.");
 
                     }
                     else
@@ -431,7 +431,7 @@ public async Task RemoveAccountAsync(ApplicationConfiguration appConfig, IAccoun
                     {
                         if (result.IsSuccess)
                         {
-                            _logger?.Verbose("[WamBroker] Account signed out successfully. ");
+                            _logger?.Verbose(() => "[WamBroker] Account signed out successfully. ");
                         }
                         else
                         {
@@ -470,7 +470,7 @@ public async Task<IReadOnlyList<IAccount>> GetAccountsAsync(
                 {
                     List<NativeInterop.Account> wamAccounts = discoverAccountsResult.Accounts;
 
-                    _logger.Info($"[WamBroker] Broker returned {wamAccounts.Count} account(s).");
+                    _logger.Info(() => $"[WamBroker] Broker returned {wamAccounts.Count} account(s).");
 
                     if (wamAccounts.Count == 0)
                     {
@@ -487,11 +487,11 @@ public async Task<IReadOnlyList<IAccount>> GetAccountsAsync(
                                 environmentList,
                                 requestContext).ConfigureAwait(false);
 
-                        _logger.Verbose($"[WamBroker] Filtering WAM accounts based on Environment.");
+                        _logger.Verbose(() => $"[WamBroker] Filtering WAM accounts based on Environment.");
 
                         wamAccounts.RemoveAll(acc => !instanceMetadata.Aliases.ContainsOrdinalIgnoreCase(acc.Environment));
 
-                        _logger.Verbose($"[WamBroker] {wamAccounts.Count} account(s) returned after filtering.");
+                        _logger.Verbose(() => $"[WamBroker] {wamAccounts.Count} account(s) returned after filtering.");
                     }
 
                     List<IAccount> msalAccounts = new List<IAccount>();
@@ -504,7 +504,7 @@ public async Task<IReadOnlyList<IAccount>> GetAccountsAsync(
                         }
                     }
 
-                    _logger.Verbose($"[WamBroker] Converted {msalAccounts.Count} WAM account(s) to MSAL Account(s).");
+                    _logger.Verbose(() => $"[WamBroker] Converted {msalAccounts.Count} WAM account(s) to MSAL Account(s).");
 
                     return msalAccounts;
                 }
@@ -549,12 +549,12 @@ public bool IsBrokerInstalledAndInvokable(AuthorityType authorityType)
 
             if (s_lazyCore.Value == null)
             {
-                _logger?.Info("[WAM Broker] MsalRuntime initialization failed. See https://aka.ms/msal-net-wam#wam-limitations");
+                _logger?.Info(() => "[WAM Broker] MsalRuntime initialization failed. See https://aka.ms/msal-net-wam#wam-limitations");
                 _logger?.InfoPii(s_initException);
                 return false;
             }
 
-            _logger?.Verbose($"[WAM Broker] MsalRuntime initialization successful.");
+            _logger?.Verbose(() => "[WAM Broker] MsalRuntime initialization successful.");
             return true;
         }
 

diff --git a/src/client/Microsoft.Identity.Client.Broker/WamAdapters.cs b/src/client/Microsoft.Identity.Client.Broker/WamAdapters.cs
@@ -73,7 +73,7 @@ private static void ThrowExceptionFromWamError(
             string errorMessage;
 
             logger.Info("[WamBroker] Processing WAM exception");
-            logger.Verbose($"[WamBroker] TelemetryData: {authResult.TelemetryData}");
+            logger.Verbose(()=>$"[WamBroker] TelemetryData: {authResult.TelemetryData}");
 
             switch ((ResponseStatus)authResult.Error.Status)
             {
@@ -127,7 +127,7 @@ private static void ThrowExceptionFromWamError(
 
                 default:
                     errorMessage = $"Unknown {authResult.Error} (error code {errorCode}) (internal error code {internalErrorCode})";
-                    logger.Verbose($"[WamBroker] {MsalError.UnknownBrokerError} {errorMessage}");
+                    logger.Verbose(()=>$"[WamBroker] {MsalError.UnknownBrokerError} {errorMessage}");
                     throw new MsalServiceException(MsalError.UnknownBrokerError, errorMessage);
             }
         }
@@ -143,7 +143,7 @@ public static NativeInterop.AuthParameters GetCommonAuthParameters(
             WindowsBrokerOptions brokerOptions,
             ILoggerAdapter logger)
         {
-            logger.Verbose("[WamBroker] Validating Common Auth Parameters.");
+            logger.Verbose(() => "[WamBroker] Validating Common Auth Parameters.");
 
             var authParams = new NativeInterop.AuthParameters
                 (authenticationRequestParameters.AppConfig.ClientId,
@@ -153,12 +153,12 @@ public static NativeInterop.AuthParameters GetCommonAuthParameters(
             if (!ScopeHelper.HasNonMsalScopes(authenticationRequestParameters.Scope))
             {
                 authParams.RequestedScopes = ScopeHelper.GetMsalRuntimeScopes();
-                logger.Verbose("[WamBroker] No scopes were passed in the request. Adding default scopes.");
+                logger.Verbose(() => "[WamBroker] No scopes were passed in the request. Adding default scopes.");
             }
             else
             {
                 authParams.RequestedScopes = string.Join(" ", authenticationRequestParameters.Scope);
-                logger.Verbose("[WamBroker] Scopes were passed in the request.");
+                logger.Verbose(() => "[WamBroker] Scopes were passed in the request.");
             }
 
             //WAM redirect URi does not need to be configured by the user
@@ -202,7 +202,7 @@ public static NativeInterop.AuthParameters GetCommonAuthParameters(
 
             AddPopParams(authenticationRequestParameters, authParams);
 
-            logger.Verbose("[WamBroker] Acquired Common Auth Parameters.");
+            logger.Verbose(()=>"[WamBroker] Acquired Common Auth Parameters.");
 
             return authParams;
         }
@@ -241,16 +241,12 @@ private static void SetMSALIdentityProvider(
 
                     if (tenantObjectId.Equals(Constants.MsaTenantId, StringComparison.OrdinalIgnoreCase))
                     {
-                        logger.Verbose($"[WamBroker] MSALRuntime Identity provider set to " +
-                            $"{ IdentityProviderTypeMSA }.");
-
+                        logger.Verbose(() => $"[WamBroker] MSALRuntime Identity provider set to MSA.");
                         authParams.Properties[MsalIdentityProvider] = IdentityProviderTypeMSA;
                     }
                     else
                     {
-                        logger.Verbose($"[WamBroker] MSALRuntime Identity provider set to " +
-                            $"{ IdentityProviderTypeAAD }.");
-
+                        logger.Verbose(() => "[WamBroker] MSALRuntime Identity provider set to AAD");
                         authParams.Properties[MsalIdentityProvider] = IdentityProviderTypeAAD;
                     }
                 }
@@ -267,7 +263,7 @@ public static MsalTokenResponse HandleResponse(
             if (TokenReceivedFromWam(authResult, logger))
             {
                 msalTokenResponse = ParseRuntimeResponse(authResult, authenticationRequestParameters, logger);
-                logger.Verbose("[WamBroker] Successfully retrieved token.");
+                logger.Verbose(()=>"[WamBroker] Successfully retrieved token.");
             }
             else
             {
@@ -434,28 +430,32 @@ private static void ToLogMessage(
             NativeInterop.Account wamAccount,
             ILoggerAdapter logger)
         {
-            // Create PII enabled string builder
-            var builder = new StringBuilder(
-                Environment.NewLine + "=== [WamBroker] Converting WAM Account to MSAL Account ===" +
-                Environment.NewLine);
+            if (logger.IsLoggingEnabled(LogLevel.Info))
+            {
+                // Create PII enabled string builder
+                var builder = new StringBuilder(
+                    Environment.NewLine + "=== [WamBroker] Converting WAM Account to MSAL Account ===" +
+                    Environment.NewLine);
 
-            builder.AppendLine($"wamAccount.AccountId: {wamAccount.AccountId}.");
-            builder.AppendLine($"wamAccount.HomeAccountid: {wamAccount.HomeAccountid}.");
-            builder.AppendLine($"wamAccount.UserName: {wamAccount.UserName}.");
+                builder.AppendLine($"wamAccount.AccountId: {wamAccount.AccountId}.");
+                builder.AppendLine($"wamAccount.HomeAccountid: {wamAccount.HomeAccountid}.");
+                builder.AppendLine($"wamAccount.UserName: {wamAccount.UserName}.");
 
-            string messageWithPii = builder.ToString();
+                string messageWithPii = builder.ToString();
 
-            // Create non PII enabled string builder
-            builder = new StringBuilder(
-                Environment.NewLine + "=== [WamBroker] Converting WAM Account to MSAL Account ===" + 
-                Environment.NewLine);
+                // Create non PII enabled string builder
+                builder = new StringBuilder(
+                    Environment.NewLine + "=== [WamBroker] Converting WAM Account to MSAL Account ===" +
+                    Environment.NewLine);
 
-            builder.AppendLine($"wamAccount.AccountId: {string.IsNullOrEmpty(wamAccount.AccountId)}.");
-            builder.AppendLine($"wamAccount.HomeAccountid: {string.IsNullOrEmpty(wamAccount.HomeAccountid)}");
-            builder.AppendLine($"wamAccount.Environment: {wamAccount.Environment}.");
-            builder.AppendLine($"wamAccount.UserName: {string.IsNullOrEmpty(wamAccount.UserName)}.");
+                builder.AppendLine($"wamAccount.AccountId: {string.IsNullOrEmpty(wamAccount.AccountId)}.");
+                builder.AppendLine($"wamAccount.HomeAccountid: {string.IsNullOrEmpty(wamAccount.HomeAccountid)}");
+                builder.AppendLine($"wamAccount.Environment: {wamAccount.Environment}.");
+                builder.AppendLine($"wamAccount.UserName: {string.IsNullOrEmpty(wamAccount.UserName)}.");
 
-            logger.InfoPii(messageWithPii, builder.ToString());
+                logger.InfoPii(messageWithPii, builder.ToString());
+            }
+
             logger.Error($"[WamBroker] WAM Account properties are missing. Cannot convert to MSAL Accounts.");
         }
     }

diff --git a/src/client/Microsoft.Identity.Client/ApiConfig/EmbeddedWebViewOptions.cs b/src/client/Microsoft.Identity.Client/ApiConfig/EmbeddedWebViewOptions.cs
@@ -51,7 +51,7 @@ internal void LogParameters(ILoggerAdapter logger)
         {
             logger.Info("WebView2Options configured");
 
-            logger.Info($"Title: {Title}");
+            logger.Info(() => $"Title: {Title}");
         }
 
         internal static void ValidatePlatformAvailability()

diff --git a/src/client/Microsoft.Identity.Client/ApiConfig/Executors/AbstractExecutor.cs b/src/client/Microsoft.Identity.Client/ApiConfig/Executors/AbstractExecutor.cs
@@ -24,7 +24,7 @@ protected RequestContext CreateRequestContextAndLogVersionInfo(Guid correlationI
             var requestContext = new RequestContext(ServiceBundle, correlationId, userCancellationToken);
 
             requestContext.Logger.Info(
-                string.Format(
+                () => string.Format(
                     CultureInfo.InvariantCulture,
                     "MSAL {0} with assembly version '{1}'. CorrelationId({2})",
                     ServiceBundle.PlatformProxy.GetProductName(),

diff --git a/src/client/Microsoft.Identity.Client/ApiConfig/Executors/ClientApplicationBaseExecutor.cs b/src/client/Microsoft.Identity.Client/ApiConfig/Executors/ClientApplicationBaseExecutor.cs
@@ -62,7 +62,7 @@ public async Task<AuthenticationResult> ExecuteAsync(
                 requestContext,
                 _clientApplicationBase.UserTokenCacheInternal).ConfigureAwait(false);
 
-            requestContext.Logger.Info(LogMessages.UsingXScopesForRefreshTokenRequest(commonParameters.Scopes.Count()));
+            requestContext.Logger.Info(() => LogMessages.UsingXScopesForRefreshTokenRequest(commonParameters.Scopes.Count()));
 
             requestParameters.SendX5C = refreshTokenParameters.SendX5C ?? false;
 

diff --git a/src/client/Microsoft.Identity.Client/ApiConfig/Parameters/AcquireTokenForClientParameters.cs b/src/client/Microsoft.Identity.Client/ApiConfig/Parameters/AcquireTokenForClientParameters.cs
@@ -15,11 +15,14 @@ internal class AcquireTokenForClientParameters : AbstractAcquireTokenConfidentia
         /// <inheritdoc />
         public void LogParameters(ILoggerAdapter logger)
         {
-            var builder = new StringBuilder();
-            builder.AppendLine("=== AcquireTokenForClientParameters ===");
-            builder.AppendLine("SendX5C: " + SendX5C);
-            builder.AppendLine("ForceRefresh: " + ForceRefresh);
-            logger.Info(builder.ToString());
+            if (logger.IsLoggingEnabled(LogLevel.Info))
+            {
+                var builder = new StringBuilder();
+                builder.AppendLine("=== AcquireTokenForClientParameters ===");
+                builder.AppendLine("SendX5C: " + SendX5C);
+                builder.AppendLine("ForceRefresh: " + ForceRefresh);
+                logger.Info(builder.ToString());
+            }
         }
     }
 }
diff --git a/...lient/Microsoft.Identity.Client/ApiConfig/Parameters/AcquireTokenInteractiveParameters.cs b/...lient/Microsoft.Identity.Client/ApiConfig/Parameters/AcquireTokenInteractiveParameters.cs
@@ -30,16 +30,19 @@ internal class AcquireTokenInteractiveParameters : IAcquireTokenParameters
 
         public void LogParameters(ILoggerAdapter logger)
         {
-            var builder = new StringBuilder();
-            builder.AppendLine("=== InteractiveParameters Data ===");
-            builder.AppendLine("LoginHint provided: " + !string.IsNullOrEmpty(LoginHint));
-            builder.AppendLine("User provided: " + (Account != null));
-            builder.AppendLine("UseEmbeddedWebView: " + UseEmbeddedWebView);
-            builder.AppendLine("ExtraScopesToConsent: " + string.Join(";", ExtraScopesToConsent ?? CollectionHelpers.GetEmptyReadOnlyList<string>()));
-            builder.AppendLine("Prompt: " + Prompt.PromptValue);
-            builder.AppendLine("HasCustomWebUi: " + (CustomWebUi != null));
-            UiParent.SystemWebViewOptions?.LogParameters(logger);
-            logger.Info(builder.ToString());
+            if (logger.IsLoggingEnabled(LogLevel.Info))
+            {
+                var builder = new StringBuilder();
+                builder.AppendLine("=== InteractiveParameters Data ===");
+                builder.AppendLine("LoginHint provided: " + !string.IsNullOrEmpty(LoginHint));
+                builder.AppendLine("User provided: " + (Account != null));
+                builder.AppendLine("UseEmbeddedWebView: " + UseEmbeddedWebView);
+                builder.AppendLine("ExtraScopesToConsent: " + string.Join(";", ExtraScopesToConsent ?? CollectionHelpers.GetEmptyReadOnlyList<string>()));
+                builder.AppendLine("Prompt: " + Prompt.PromptValue);
+                builder.AppendLine("HasCustomWebUi: " + (CustomWebUi != null));
+                UiParent.SystemWebViewOptions?.LogParameters(logger);
+                logger.Info(builder.ToString());
+            }
         }
     }
 }