reduce use of TRACE_VERBOSE in SslStream (dotnet#37917)

* reduce use of TRACE_VERBOSE * add NetEventSource.Verbose Co-authored-by: Tomas Weinfurt <[email protected]>
waiyiptam · Jun 16, 2020 · fb39507 · fb39507
1 parent 5182718
commit fb39507
Show file tree

Hide file tree

Showing 3 changed files with 34 additions and 41 deletions.
diff --git a/src/libraries/Common/src/Interop/Windows/SspiCli/SecuritySafeHandles.cs b/src/libraries/Common/src/Interop/Windows/SspiCli/SecuritySafeHandles.cs
@@ -225,9 +225,7 @@ public static unsafe int AcquireDefaultCredential(
                             ref outCredential._handle,
                             out timeStamp);
 
-#if TRACE_VERBOSE
-            if (NetEventSource.IsEnabled) NetEventSource.Info(null, $"{nameof(Interop.SspiCli.AcquireCredentialsHandleW)} returns 0x{errorCode:x}, handle = {outCredential}");
-#endif
+            if (NetEventSource.IsEnabled) NetEventSource.Verbose(null, $"{nameof(Interop.SspiCli.AcquireCredentialsHandleW)} returns 0x{errorCode:x}, handle = {outCredential}");
 
             if (errorCode != 0)
             {
@@ -307,9 +305,7 @@ public static unsafe int AcquireCredentialsHandle(
                 authdata.paCred = copiedPtr;
             }
 
-#if TRACE_VERBOSE
-            if (NetEventSource.IsEnabled) NetEventSource.Info(null, $"{nameof(Interop.SspiCli.AcquireCredentialsHandleW)} returns 0x{errorCode:x}, handle = {outCredential}");
-#endif
+            if (NetEventSource.IsEnabled) NetEventSource.Verbose(null, $"{nameof(Interop.SspiCli.AcquireCredentialsHandleW)} returns 0x{errorCode:x}, handle = {outCredential}");
 
             if (errorCode != 0)
             {
@@ -401,13 +397,7 @@ internal static unsafe int InitializeSecurityContext(
             ref SecurityBuffer outSecBuffer,
             ref Interop.SspiCli.ContextFlags outFlags)
         {
-#if TRACE_VERBOSE
-            if (NetEventSource.IsEnabled)
-            {
-                NetEventSource.Enter(null, $"credential:{inCredentials}, crefContext:{refContext}, targetName:{targetName}, inFlags:{inFlags}, endianness:{endianness}");
-                NetEventSource.Info(null, $"inSecBuffers.Length = {inSecBuffers.Length}");
-            }
-#endif
+            if (NetEventSource.IsEnabled) NetEventSource.Enter(null, $"credential:{inCredentials}, crefContext:{refContext}, targetName:{targetName}, inFlags:{inFlags}, endianness:{endianness}");
 
             if (inCredentials == null)
             {
@@ -639,13 +629,7 @@ internal static unsafe int AcceptSecurityContext(
             ref SecurityBuffer outSecBuffer,
             ref Interop.SspiCli.ContextFlags outFlags)
         {
-#if TRACE_VERBOSE
-            if (NetEventSource.IsEnabled)
-            {
-                NetEventSource.Enter(null, $"credential={inCredentials}, refContext={refContext}, inFlags={inFlags}");
-                NetEventSource.Info(null, $"inSecBuffers.Length = {inSecBuffers.Length}");
-            }
-#endif
+            if (NetEventSource.IsEnabled) NetEventSource.Enter(null, $"credential={inCredentials}, refContext={refContext}, inFlags={inFlags}");
 
             if (inCredentials == null)
             {
@@ -900,9 +884,6 @@ internal static unsafe int CompleteAuthToken(
                     inSecBuffer.unmanagedToken != null ? inSecBuffer.unmanagedToken.DangerousGetHandle() :
                     inSecBuffer.token == null || inSecBuffer.token.Length == 0 ? IntPtr.Zero :
                     (IntPtr)(pinnedToken + inSecBuffer.offset);
-#if TRACE_VERBOSE
-                if (NetEventSource.IsEnabled) NetEventSource.Info(null, $"SecBuffer: cbBuffer:{inSecBuffer.size} BufferType: {inSecBuffer.type}");
-#endif
 
                 Interop.SspiCli.CredHandle contextHandle = refContext != null ? refContext._handle : default;
                 if (refContext == null || refContext.IsInvalid)
@@ -964,9 +945,6 @@ internal static unsafe int ApplyControlToken(
                     inSecBuffer.unmanagedToken != null ? inSecBuffer.unmanagedToken.DangerousGetHandle() :
                     inSecBuffer.token == null || inSecBuffer.token.Length == 0 ? IntPtr.Zero :
                     (IntPtr)(pinnedInSecBufferToken + inSecBuffer.offset);
-#if TRACE_VERBOSE
-                if (NetEventSource.IsEnabled) NetEventSource.Info(null, $"SecBuffer: cbBuffer:{inSecBuffer.size} BufferType:{inSecBuffer.type}");
-#endif
 
                 Interop.SspiCli.CredHandle contextHandle = refContext != null ? refContext._handle : default;
 

diff --git a/src/libraries/Common/src/System/Net/Logging/NetEventSource.Common.cs b/src/libraries/Common/src/System/Net/Logging/NetEventSource.Common.cs
@@ -299,6 +299,36 @@ private void CriticalFailure(string thisOrContextObject, string? memberName, str
             WriteEvent(CriticalFailureEventId, thisOrContextObject, memberName ?? MissingMember, message);
         #endregion
 
+        #region Verbose
+        /// <summary>Logs an info message at verbose mode.</summary>
+        /// <param name="thisOrContextObject">`this`, or another object that serves to provide context for the operation.</param>
+        /// <param name="formattableString">The message to be logged.</param>
+        /// <param name="memberName">The calling member.</param>
+        [NonEvent]
+        public static void Verbose(object? thisOrContextObject, FormattableString formattableString, [CallerMemberName] string? memberName = null)
+        {
+            DebugValidateArg(thisOrContextObject);
+            DebugValidateArg(formattableString);
+            if (IsEnabled) Log.ErrorMessage(IdOf(thisOrContextObject), memberName, Format(formattableString));
+        }
+
+        /// <summary>Logs an info at verbose mode.</summary>
+        /// <param name="thisOrContextObject">`this`, or another object that serves to provide context for the operation.</param>
+        /// <param name="message">The message to be logged.</param>
+        /// <param name="memberName">The calling member.</param>
+        [NonEvent]
+        public static void Verbose(object? thisOrContextObject, object message, [CallerMemberName] string? memberName = null)
+        {
+            DebugValidateArg(thisOrContextObject);
+            DebugValidateArg(message);
+            if (IsEnabled) Log.VerboseMessage(IdOf(thisOrContextObject), memberName, Format(message).ToString());
+        }
+
+        [Event(ErrorEventId, Level = EventLevel.Verbose, Keywords = Keywords.Default)]
+        private void VerboseMessage(string thisOrContextObject, string? memberName, string? message) =>
+            WriteEvent(ErrorEventId, thisOrContextObject, memberName ?? MissingMember, message);
+        #endregion
+
         #region DumpBuffer
         /// <summary>Logs the contents of a buffer.</summary>
         /// <param name="thisOrContextObject">`this`, or another object that serves to provide context for the operation.</param>

diff --git a/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs b/src/libraries/System.Net.Security/src/System/Net/Security/SslStream.Implementation.cs
@@ -1093,13 +1093,6 @@ private Framing DetectFraming(ReadOnlySpan<byte> bytes)
                     return Framing.Invalid;
                 }
 
-#if TRACE_VERBOSE
-                if (bytes[1] != 3 && NetEventSource.IsEnabled)
-                {
-                    if (NetEventSource.IsEnabled) NetEventSource.Info(this, $"WARNING: SslState::DetectFraming() SSL protocol is > 3, trying SSL3 framing in retail = {bytes[1]:x}");
-                }
-#endif
-
                 version = (bytes[1] << 8) | bytes[2];
                 if (version < 0x300 || version >= 0x500)
                 {
@@ -1112,14 +1105,6 @@ private Framing DetectFraming(ReadOnlySpan<byte> bytes)
                 return Framing.SinceSSL3;
             }
 
-#if TRACE_VERBOSE
-            if ((bytes[0] & 0x80) == 0 && NetEventSource.IsEnabled)
-            {
-                // We have a three-byte header format
-                if (NetEventSource.IsEnabled) NetEventSource.Info(this, $"WARNING: SslState::DetectFraming() SSL v <=2 HELLO has no high bit set for 3 bytes header, we are broken, received byte = {bytes[0]:x}");
-            }
-#endif
-
             if (bytes.Length < 3)
             {
                 return Framing.Invalid;