[Log Scrubbing] Clean up log messages in Wilson (#2339) (#2344)

[Log Scrubbing] Clean up log messages in Wilson (#2339)



* Update code to fix build breaks between dev and dev6x

src/Microsoft.IdentityModel.JsonWebTokens/JsonWebToken.cs

@@ -472,7 +472,10 @@ private void ReadToken(string encodedJson)
                 }
                 catch (Exception ex)
                 {
-                    throw LogHelper.LogExceptionMessage(new ArgumentException(LogHelper.FormatInvariant(LogMessages.IDX14102, encodedJson.Substring(0, Dot1)), ex));
+                    throw LogHelper.LogExceptionMessage(new ArgumentException(LogHelper.FormatInvariant(
+                        LogMessages.IDX14102,
+                        LogHelper.MarkAsUnsafeSecurityArtifact(encodedJson.Substring(0, Dot1), t => t.ToString())),
+                        ex));
                 }
 #if !NET45
                 finally
@@ -495,7 +498,10 @@ private void ReadToken(string encodedJson)
                 }
                 catch (Exception ex)
                 {
-                    throw LogHelper.LogExceptionMessage(new ArgumentException(LogHelper.FormatInvariant(LogMessages.IDX14101, encodedJson.Substring(Dot2, Dot2 - Dot1)), ex));
+                    throw LogHelper.LogExceptionMessage(new ArgumentException(LogHelper.FormatInvariant(
+                        LogMessages.IDX14101,
+                        LogHelper.MarkAsUnsafeSecurityArtifact(encodedJson.Substring(Dot1 + 1, Dot2 - Dot1 - 1), t => t.ToString())),
+                        ex));
                 }
 #if !NET45
                 finally
@@ -545,7 +551,10 @@ private void ReadToken(string encodedJson)
                 }
                 catch (Exception ex)
                 {
-                    throw LogHelper.LogExceptionMessage(new ArgumentException(LogHelper.FormatInvariant(LogMessages.IDX14102, encodedJson.Substring(0, Dot1)), ex));
+                    throw LogHelper.LogExceptionMessage(new ArgumentException(LogHelper.FormatInvariant(
+                        LogMessages.IDX14102,
+                        LogHelper.MarkAsUnsafeSecurityArtifact(encodedJson.Substring(0, Dot1), t => t.ToString())),
+                        ex));
                 }
 
                 // dir does not have any key bytes

src/Microsoft.IdentityModel.Logging/IdentityModelEventSource.cs

@@ -45,6 +45,11 @@ private IdentityModelEventSource()
         /// </summary>
         public static string HiddenPIIString { get; } = "[PII of type '{0}' is hidden. For more details, see https://aka.ms/IdentityModel/PII.]";
 
+        /// <summary>
+        /// String that is used in place of any arguments to log messages if the 'LogCompleteSecurityArtifact' flag is set to false.
+        /// </summary>
+        public static string HiddenSecurityArtifactString { get; } = "[Security Artifact of type '{0}' is hidden. For more details, see https://aka.ms/IdentityModel/SecurityArtifactLogging.]";
+
         /// <summary>
         /// Indicates whether or the log message header (contains library version, date/time, and PII debugging information) has been written.
         /// </summary>

src/Microsoft.IdentityModel.Logging/LogHelper.cs

@@ -44,6 +44,17 @@ internal static bool HeaderWritten
             set { _isHeaderWritten = value; }
         }
 
+#if !NET45
+        /// <summary>
+        /// Gets whether logging is enabled at the specified <see cref="EventLogLevel"/>."/>
+        /// </summary>
+        /// <param name="level">The log level</param>
+        /// <returns><see langword="true"/> if logging is enabled at the specified level; otherwise, <see langword="false"/>.</returns>
+        public static bool IsEnabled(EventLogLevel level) =>
+            Logger.IsEnabled(level) ||
+            IdentityModelEventSource.Logger.IsEnabled(EventLogLevelToEventLevel(level), EventKeywords.All);
+#endif
+
         /// <summary>
         /// Logs an exception using the event source logger and returns new <see cref="ArgumentNullException"/> exception.
         /// </summary>
@@ -345,6 +356,12 @@ public static void LogWarning(string message, params object[] args)
                     return (T)Activator.CreateInstance(typeof(T), argumentName, message);
         }
 
+        private static EventLogLevel EventLevelToEventLogLevel(EventLevel eventLevel) =>
+            (uint)(int)eventLevel <= 5 ? (EventLogLevel)eventLevel : EventLogLevel.Error;
+
+        private static EventLevel EventLogLevelToEventLevel(EventLogLevel eventLevel) =>
+            (uint)(int)eventLevel <= 5 ? (EventLevel)eventLevel : EventLevel.Error;
+
         /// <summary>
         /// Formats the string using InvariantCulture
         /// </summary>
@@ -372,7 +389,17 @@ private static object SanitizeSecurityArtifact(object arg)
 
             if (IdentityModelEventSource.LogCompleteSecurityArtifact && arg is ISafeLogSecurityArtifact)
                 return (arg as ISafeLogSecurityArtifact).UnsafeToString();
+            else if (arg is ISafeLogSecurityArtifact)
+            {
+                // We may later add a further flag which would log a best effort scrubbing of an artifact. E.g. JsonWebToken tries to remove the signature
+                // in the current implementation. Another flag may be added in the future to allow this middle path but for now, LogCompleteSecurityArtifact
+                // must be logged to emit any token part (other than specific claim values).
+                return string.Format(CultureInfo.InvariantCulture, IdentityModelEventSource.HiddenSecurityArtifactString, arg?.GetType().ToString() ?? "Null");
+            }
 
+            // If it's not a ISafeLogSecurityArtifact then just return the object which will be converted to string.
+            // It's possible a raw string will contain a security artifact and be exposed here but the alternative is to scrub all objects
+            // which defeats the purpose of the ShowPII flag.
             return arg;
         }
 
@@ -412,11 +439,48 @@ public static object MarkAsNonPII(object arg)
         /// <param name="arg">A log message argument to be marked as SecurityArtifact.</param>
         /// <param name="callback">A callback function to log the security artifact safely.</param>
         /// <returns>An argument marked as SecurityArtifact.</returns>
+        /// <remarks>
+        /// Since even the payload may sometimes contain security artifacts, naïve disarm algorithms such as removing signatures
+        /// will not work. For now the <paramref name="callback"/> will only be leveraged if
+        /// <see cref="IdentityModelEventSource.LogCompleteSecurityArtifact"/> is set and no unsafe callback is provided. Future changes
+        /// may introduce a support for best effort disarm logging.
+        /// </remarks>
         public static object MarkAsSecurityArtifact(object arg, Func<object, string> callback)
         {
             return new SecurityArtifact(arg, callback);
         }
 
+        /// <summary>
+        /// Marks a log message argument (<paramref name="arg"/>) as SecurityArtifact.
+        /// </summary>
+        /// <param name="arg">A log message argument to be marked as SecurityArtifact.</param>
+        /// <param name="callback">A callback function to log the security artifact safely.</param>
+        /// <param name="callbackUnsafe">A callback function to log the security artifact without scrubbing.</param>
+        /// <returns>An argument marked as SecurityArtifact.</returns>
+        /// <exception cref="ArgumentNullException">if <paramref name="callback"/> is null.</exception>
+        /// <exception cref="ArgumentNullException">if <paramref name="callbackUnsafe"/> is null.</exception>
+        /// <remarks>
+        /// Since even the payload may sometimes contain security artifacts, naïve disarm algorithms such as removing signatures
+        /// will not work. For now the <paramref name="callback"/> is currently unused. Future changes
+        /// may introduce a support for best effort disarm logging which will leverage <paramref name="callback"/>.
+        /// </remarks>
+        public static object MarkAsSecurityArtifact(object arg, Func<object, string> callback, Func<object, string> callbackUnsafe)
+        {
+            return new SecurityArtifact(arg, callback, callbackUnsafe);
+        }
+
+        /// <summary>
+        /// Marks a log message argument (<paramref name="arg"/>) as SecurityArtifact.
+        /// </summary>
+        /// <param name="arg">A log message argument to be marked as SecurityArtifact.</param>
+        /// <param name="callbackUnsafe">A callback function to log the security artifact without scrubbing.</param>
+        /// <returns>An argument marked as SecurityArtifact.</returns>
+        /// <exception cref="ArgumentNullException">if <paramref name="callbackUnsafe"/> is null.</exception>
+        public static object MarkAsUnsafeSecurityArtifact(object arg, Func<object, string> callbackUnsafe)
+        {
+            return new SecurityArtifact(arg, SecurityArtifact.UnknownSafeTokenCallback, callbackUnsafe);
+        }
+
         /// <summary>
         /// Creates a <see cref="LogEntry"/> by using the provided event level, exception argument, string argument and arguments list.
         /// </summary>

src/Microsoft.IdentityModel.Logging/SecurityArtifact.cs

@@ -14,44 +14,92 @@ namespace Microsoft.IdentityModel.Logging
     /// </remarks>
     internal struct SecurityArtifact : ISafeLogSecurityArtifact
     {
+        private const string _scrubbedArtifact = "#ScrubbedArtifact#";
+
         /// <summary>
         /// Argument wrapped with a <see cref="SecurityArtifact"/> structure is considered as SecurityArtifact in the message logging process.
         /// </summary>
         private object Argument { get; set; }
 
         /// <summary>
-        /// The ToString callback delegate that return a disarmed SecurityArtifact.
+        /// The ToString callback delegate that returns a disarmed SecurityArtifact.
         /// </summary>
-        private Func<object, string> _callback;
+        private readonly Func<object, string> _disarmCallback;
+
+        /// <summary>
+        /// The ToString callback delegate that returns an unscrubbed SecurityArtifact.
+        /// </summary>
+        private readonly Func<object, string> _callbackUnsafe;
 
         /// <summary>
         /// Creates an instance of <see cref="SecurityArtifact"/> that wraps the <paramref name="argument"/>.
         /// </summary>
         /// <param name="argument">An argument that is considered as SecurityArtifact.</param>
-        /// <param name="toStringCallback">A ToString callback.</param>
-        /// <exception cref="ArgumentNullException">if <paramref name="argument"/> is null.</exception>
+        /// <param name="toStringCallback">A callback used to disarm the token.</param>
+        /// <remarks>
+        /// Since even the payload may sometimes contain security artifacts, naïve disarm algorithms (such as removing signatures
+        /// in the case of JWTs) will not work. For now the <paramref name="toStringCallback"/> will only be leveraged if
+        /// <see cref="IdentityModelEventSource.LogCompleteSecurityArtifact"/> is set and no unsafe callback is provided. Future changes
+        /// may introduce a support for best effort disarm logging.
+        /// </remarks>
         public SecurityArtifact(object argument, Func<object, string> toStringCallback)
         {
             Argument = argument;
-            _callback = toStringCallback;
+            _disarmCallback = toStringCallback;
+            _callbackUnsafe = null;
+        }
+
+        /// <summary>
+        /// Creates an instance of <see cref="SecurityArtifact"/> that wraps the <paramref name="argument"/>.
+        /// </summary>
+        /// <param name="argument">An argument that is considered as SecurityArtifact.</param>
+        /// <param name="toStringCallback">A ToString callback.</param>
+        /// <param name="toStringCallbackUnsafe">A ToString callback which will return the unscrubbed artifact.</param>
+        /// <remarks>
+        /// Since even the payload may sometimes contain security artifacts, naïve disarm algorithms (such as removing signatures
+        /// in the case of JWTs) will not work. For now the <paramref name="toStringCallback"/> is currently unused. Future changes
+        /// may introduce a support for best effort disarm logging which will leverage <paramref name="toStringCallback"/>.
+        /// </remarks>
+        public SecurityArtifact(object argument, Func<object, string> toStringCallback, Func<object, string> toStringCallbackUnsafe)
+        {
+            Argument = argument;
+            _disarmCallback = toStringCallback;
+            _callbackUnsafe = toStringCallbackUnsafe;
+        }
+
+        /// <summary>
+        /// A dummy callback which can be leveraged to return a standard scrubbed token in the case where expected token is unknown.
+        /// </summary>
+        /// <param name="_">Ignored token.</param>
+        /// <returns>The standard scrubbed token string.</returns>
+        public static string UnknownSafeTokenCallback(object _)
+        {
+            return _scrubbedArtifact;
         }
 
         /// <summary>
         /// Returns a string that represents the <see cref="Argument"/>.
         /// </summary>
-        /// <returns><c>Null</c> if the <see cref="Argument"/> is <see langword="null"/>, otherwise calls <see cref="System.ValueType.ToString()"/> method of the <see cref="Argument"/>.</returns>
+        /// <returns><c>Null</c> if the <see cref="Argument"/> is <see langword="null"/>, otherwise calls the provided safe callback on <see cref="Argument"/>.</returns>
         public override string ToString()
         {
-            if (_callback != null && Argument != null)
-                return _callback(Argument);
-
-            return Argument?.ToString() ?? "null";
+            // Defense in depth, ideally callers will set a callback which actually provides information but, since not initially required in a publicly facing API we
+            // don't explicitly check and so it's possible we can instrument without a callback in which case we'll return a generic _scrubbedArtifact string.
+            if (_disarmCallback == null)
+                return _scrubbedArtifact;
+            if (Argument == null)
+                return "null";
+            else
+                return _disarmCallback(Argument);
         }
 
         // <inheritdoc/>
         public string UnsafeToString()
         {
-            return Argument?.ToString() ?? "null";
+            if (_callbackUnsafe == null || Argument == null)
+                return ToString();
+            else
+                return _callbackUnsafe(Argument);
         }
     }
 }

src/Microsoft.IdentityModel.Protocols.SignedHttpRequest/SignedHttpRequestHandler.cs

@@ -660,7 +660,11 @@ internal virtual async Task<SecurityKey> ValidateSignatureAsync(JsonWebToken sig
                 throw LogHelper.LogExceptionMessage(new SignedHttpRequestInvalidSignatureException(LogHelper.FormatInvariant(LogMessages.IDX23009, ex.ToString()), ex));
             }
 
-            throw LogHelper.LogExceptionMessage(new SignedHttpRequestInvalidSignatureException(LogHelper.FormatInvariant(LogMessages.IDX23034, signedHttpRequest.EncodedToken)));
+            throw LogHelper.LogExceptionMessage(
+                new SignedHttpRequestInvalidSignatureException(
+                    LogHelper.FormatInvariant(
+                        LogMessages.IDX23034,
+                        LogHelper.MarkAsUnsafeSecurityArtifact(signedHttpRequest.EncodedToken, t => t.ToString()))));
         }
 
         /// <summary>

src/Microsoft.IdentityModel.Tokens.Saml/Microsoft.IdentityModel.Tokens.Saml.csproj

@@ -27,4 +27,8 @@
     <ProjectReference Include="..\Microsoft.IdentityModel.Xml\Microsoft.IdentityModel.Xml.csproj" />
   </ItemGroup>
 
+  <ItemGroup>
+    <ProjectReference Include="..\Microsoft.IdentityModel.Abstractions\Microsoft.IdentityModel.Abstractions.csproj" />
+  </ItemGroup>
+
 </Project>

src/Microsoft.IdentityModel.Tokens.Saml/Saml/SamlSecurityTokenHandler.cs

@@ -1213,7 +1213,12 @@ private ClaimsPrincipal ValidateToken(SamlSecurityToken samlToken, string token,
                 identities.ElementAt(0).BootstrapContext = samlToken.Assertion.CanonicalString;
             }
 
-            LogHelper.LogInformation(TokenLogMessages.IDX10241, token);
+#if !NET45
+            if (LogHelper.IsEnabled(Abstractions.EventLogLevel.Informational))
+#endif
+                LogHelper.LogInformation(
+                    TokenLogMessages.IDX10241,
+                    LogHelper.MarkAsUnsafeSecurityArtifact(token, t => t.ToString()));
 
             return new ClaimsPrincipal(identities);
         }

src/Microsoft.IdentityModel.Tokens.Saml/Saml2/Saml2SecurityTokenHandler.cs

@@ -270,7 +270,12 @@ private ClaimsPrincipal ValidateToken(Saml2SecurityToken samlToken, string token
             if (validationParameters.SaveSigninToken)
                 identity.BootstrapContext = samlToken.Assertion.CanonicalString;
 
-            LogHelper.LogInformation(TokenLogMessages.IDX10241, token);
+#if !NET45
+            if (LogHelper.IsEnabled(Abstractions.EventLogLevel.Informational))
+#endif
+                LogHelper.LogInformation(
+                    TokenLogMessages.IDX10241,
+                    LogHelper.MarkAsUnsafeSecurityArtifact(token, t => t.ToString()));
 
             return new ClaimsPrincipal(identity);
         }

src/Microsoft.IdentityModel.Tokens/Validators.cs

@@ -68,7 +68,11 @@ public static void ValidateAudience(IEnumerable<string> audiences, SecurityToken
             if (validationParameters.AudienceValidator != null)
             {
                 if (!validationParameters.AudienceValidator(audiences, securityToken, validationParameters))
-                    throw LogHelper.LogExceptionMessage(new SecurityTokenInvalidAudienceException(LogHelper.FormatInvariant(LogMessages.IDX10231, securityToken))
+                    throw LogHelper.LogExceptionMessage(
+                        new SecurityTokenInvalidAudienceException(
+                            LogHelper.FormatInvariant(
+                                LogMessages.IDX10231,
+                                LogHelper.MarkAsUnsafeSecurityArtifact(securityToken, t => t.ToString())))
                     {
                         InvalidAudience = Utility.SerializeAsSingleCommaDelimitedString(audiences)
                     });
@@ -477,7 +481,10 @@ public static void ValidateTokenReplay(DateTime? expirationTime, string security
             if (validationParameters.TokenReplayValidator != null)
             {
                 if (!validationParameters.TokenReplayValidator(expirationTime, securityToken, validationParameters))
-                    throw LogHelper.LogExceptionMessage(new SecurityTokenReplayDetectedException(LogHelper.FormatInvariant(LogMessages.IDX10228, securityToken)));
+                    throw LogHelper.LogExceptionMessage(new SecurityTokenReplayDetectedException(
+                        LogHelper.FormatInvariant(
+                            LogMessages.IDX10228,
+                            LogHelper.MarkAsUnsafeSecurityArtifact(securityToken, t => t.ToString()))));
                 return;
             }