Improve logging for EventSource.WriteEvent parameter mismatch (dotnet/coreclr#25533)

* improve logging for EventSource.WriteEvent

* Fix IndexOutOfRangeException in SerializeEventArgs when incorrect arguments got passed

* simplify arg-check; remove nullable-todo

* switch from Debugger.Log to ReportOutOfBandMessage

* Remove unused flush-Paramater from ReportOutOfBandMessage

* fix parameter type nullable-check for reference-types

* fix parameter type nullable-check for nullable-types

Commit migrated from https://github.com/dotnet/coreclr/commit/4eb1526fde7a93a1cf0a3c2eca73fc8182845127

diff --git a/src/coreclr/src/System.Private.CoreLib/Resources/Strings.resx b/src/coreclr/src/System.Private.CoreLib/Resources/Strings.resx
index e8bc95242fb7385cf9a4cbf275674574e1dc5e04..f5563a2a0df046a7b1b49fc1d8a3b767e68bb507 100644 (file)
--- a/src/coreclr/src/System.Private.CoreLib/Resources/Strings.resx
+++ b/src/coreclr/src/System.Private.CoreLib/Resources/Strings.resx
@@ -2222,7 +2222,7 @@
     <value>Event {0} specifies an illegal or unsupported formatting message ("{1}").</value>
   </data>
   <data name="EventSource_VarArgsParameterMismatch" xml:space="preserve">
-    <value>The parameters to the Event method do not match the parameters to the WriteEvent method. This may cause the event to be displayed incorrectly.</value>
+    <value>Event {0} was called with a different type as defined (argument "{1}"). This may cause the event to be displayed incorrectly.</value>
   </data>
   <data name="Exception_EndOfInnerExceptionStack" xml:space="preserve">
     <value>--- End of inner exception stack trace ---</value>

diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/DiagnosticCounter.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/DiagnosticCounter.cs
index 9a01f20b04acb069e9be5ca012fbb81488973d43..577e9f193f8c111bf3ab2a96a164bbef97fb32f6 100644 (file)
--- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/DiagnosticCounter.cs
+++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/DiagnosticCounter.cs
@@ -123,7 +123,7 @@ namespace System.Diagnostics.Tracing
 
         internal void ReportOutOfBandMessage(string message)
         {
-            EventSource.ReportOutOfBandMessage(message, true);
+            EventSource.ReportOutOfBandMessage(message);
         }
 
         internal string GetMetadataString()

diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs
index a0d6a302a52af5df1b8e31acf085a1f809fe2b87..e21b304981489abce493195ae763cd9c173fa914 100644 (file)
--- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs
+++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs
@@ -1506,7 +1506,7 @@ namespace System.Diagnostics.Tracing
             catch (Exception e)
             {
                 m_constructionException ??= e;
-                ReportOutOfBandMessage("ERROR: Exception during construction of EventSource " + Name + ": " + e.Message, true);
+                ReportOutOfBandMessage("ERROR: Exception during construction of EventSource " + Name + ": " + e.Message);
             }
 
             // Once m_completelyInited is set, you can have concurrency, so all work is under the lock.
@@ -1898,7 +1898,7 @@ namespace System.Diagnostics.Tracing
                         }
                     }
 
-                    LogEventArgsMismatches(m_eventData[eventId].Parameters, args);
+                    LogEventArgsMismatches(eventId, args);
 
                     Guid* pActivityId = null;
                     Guid activityId = Guid.Empty;
@@ -2012,8 +2012,9 @@ namespace System.Diagnostics.Tracing
                                                         m_eventData[eventId].Parameters);
                 Interlocked.CompareExchange(ref m_eventData[eventId].TraceLoggingEventTypes, eventTypes, null);
             }
+            int paramCount = Math.Min(eventTypes.typeInfos.Length, args.Length); // parameter count mismatch get logged in LogEventArgsMismatches
             var eventData = new object?[eventTypes.typeInfos.Length];
-            for (int i = 0; i < eventTypes.typeInfos.Length; i++)
+            for (int i = 0; i < paramCount; i++)
             {
                 eventData[i] = eventTypes.typeInfos[i].GetData(args[i]);
             }
@@ -2024,40 +2025,38 @@ namespace System.Diagnostics.Tracing
         /// We expect that the arguments to the Event method and the arguments to WriteEvent match. This function
         /// checks that they in fact match and logs a warning to the debugger if they don't.
         /// </summary>
-        /// <param name="infos"></param>
+        /// <param name="eventId"></param>
         /// <param name="args"></param>
-        private void LogEventArgsMismatches(ParameterInfo[] infos, object?[] args)
+        private void LogEventArgsMismatches(int eventId, object?[] args)
         {
-#if (!ES_BUILD_PCL && !ES_BUILD_PN)
-            // It would be nice to have this on PCL builds, but it would be pointless since there isn't support for
-            // writing to the debugger log on PCL.
-            bool typesMatch = args.Length == infos.Length;
+            Debug.Assert(m_eventData != null);
+            ParameterInfo[] infos = m_eventData[eventId].Parameters;
+
+            if (args.Length != infos.Length)
+            {
+                ReportOutOfBandMessage(SR.Format(SR.EventSource_EventParametersMismatch, eventId, args.Length, infos.Length));
+                return;
+            }
 
             int i = 0;
-            while (typesMatch && i < args.Length)
+            while (i < args.Length)
             {
                 Type pType = infos[i].ParameterType;
-
-                Type? argType = args[i]?.GetType();
+                object? arg = args[i];
 
                 // Checking to see if the Parameter types (from the Event method) match the supplied argument types.
                 // Fail if one of two things hold : either the argument type is not equal or assignable to the parameter type, or the
                 // argument is null and the parameter type is a non-Nullable<T> value type.
-                if ((args[i] != null && !pType.IsAssignableFrom(argType))
-                    || (args[i] == null && !((pType.IsGenericType && pType.GetGenericTypeDefinition() == typeof(Nullable<>)) || !pType.IsValueType)))
+                if ((arg != null && !pType.IsAssignableFrom(arg.GetType()))
+                    || (arg == null && (pType.IsValueType && !(pType.IsGenericType && pType.GetGenericTypeDefinition() == typeof(Nullable<>))))
+                    )
                 {
-                    typesMatch = false;
-                    break;
+                    ReportOutOfBandMessage(SR.Format(SR.EventSource_VarArgsParameterMismatch, eventId, infos[i].Name));
+                    return;
                 }
 
                 ++i;
             }
-
-            if (!typesMatch)
-            {
-                System.Diagnostics.Debugger.Log(0, null, SR.EventSource_VarArgsParameterMismatch + "\r\n");
-            }
-#endif //!ES_BUILD_PCL
         }
 
         private unsafe void WriteToAllListeners(int eventId, Guid* activityID, Guid* childActivityID, int eventDataCount, EventSource.EventData* data)
@@ -2083,7 +2082,7 @@ namespace System.Diagnostics.Tracing
             }
             if (eventDataCount != modifiedParamCount)
             {
-                ReportOutOfBandMessage(SR.Format(SR.EventSource_EventParametersMismatch, eventId, eventDataCount, paramCount), true);
+                ReportOutOfBandMessage(SR.Format(SR.EventSource_EventParametersMismatch, eventId, eventDataCount, paramCount));
                 paramCount = Math.Min(paramCount, eventDataCount);
             }
 
@@ -2139,7 +2138,7 @@ namespace System.Diagnostics.Tracing
                         catch (Exception e)
                         {
                             ReportOutOfBandMessage("ERROR: Exception during EventSource.OnEventWritten: "
-                                 + e.Message, false);
+                                 + e.Message);
                             lastThrownException = e;
                         }
                     }
@@ -2319,29 +2318,29 @@ namespace System.Diagnostics.Tracing
                 switch (EventProvider.GetLastWriteEventError())
                 {
                     case EventProvider.WriteEventErrorCode.EventTooBig:
-                        ReportOutOfBandMessage(errorPrefix + ": " + SR.EventSource_EventTooBig, true);
+                        ReportOutOfBandMessage(errorPrefix + ": " + SR.EventSource_EventTooBig);
                         if (ThrowOnEventWriteErrors) throw new EventSourceException(SR.EventSource_EventTooBig, innerEx);
                         break;
                     case EventProvider.WriteEventErrorCode.NoFreeBuffers:
-                        ReportOutOfBandMessage(errorPrefix + ": " + SR.EventSource_NoFreeBuffers, true);
+                        ReportOutOfBandMessage(errorPrefix + ": " + SR.EventSource_NoFreeBuffers);
                         if (ThrowOnEventWriteErrors) throw new EventSourceException(SR.EventSource_NoFreeBuffers, innerEx);
                         break;
                     case EventProvider.WriteEventErrorCode.NullInput:
-                        ReportOutOfBandMessage(errorPrefix + ": " + SR.EventSource_NullInput, true);
+                        ReportOutOfBandMessage(errorPrefix + ": " + SR.EventSource_NullInput);
                         if (ThrowOnEventWriteErrors) throw new EventSourceException(SR.EventSource_NullInput, innerEx);
                         break;
                     case EventProvider.WriteEventErrorCode.TooManyArgs:
-                        ReportOutOfBandMessage(errorPrefix + ": " + SR.EventSource_TooManyArgs, true);
+                        ReportOutOfBandMessage(errorPrefix + ": " + SR.EventSource_TooManyArgs);
                         if (ThrowOnEventWriteErrors) throw new EventSourceException(SR.EventSource_TooManyArgs, innerEx);
                         break;
                     default:
                         if (innerEx != null)
                         {
                             innerEx = innerEx.GetBaseException();
-                            ReportOutOfBandMessage(errorPrefix + ": " + innerEx.GetType() + ":" + innerEx.Message, true);
+                            ReportOutOfBandMessage(errorPrefix + ": " + innerEx.GetType() + ":" + innerEx.Message);
                         }
                         else
-                            ReportOutOfBandMessage(errorPrefix, true);
+                            ReportOutOfBandMessage(errorPrefix);
                         if (ThrowOnEventWriteErrors) throw new EventSourceException(innerEx);
                         break;
                 }
@@ -2811,7 +2810,7 @@ namespace System.Diagnostics.Tracing
             {
                 // When the ETW session is created after the EventSource has registered with the ETW system
                 // we can send any error messages here.
-                ReportOutOfBandMessage("ERROR: Exception in Command Processing for EventSource " + Name + ": " + e.Message, true);
+                ReportOutOfBandMessage("ERROR: Exception in Command Processing for EventSource " + Name + ": " + e.Message);
                 // We never throw when doing a command.
             }
         }
@@ -3804,9 +3803,8 @@ namespace System.Diagnostics.Tracing
         /// <summary>
         /// Sends an error message to the debugger (outputDebugString), as well as the EventListeners
         /// It will do this even if the EventSource is not enabled.
-        /// TODO remove flush parameter it is not used.
         /// </summary>
-        internal void ReportOutOfBandMessage(string msg, bool flush)
+        internal void ReportOutOfBandMessage(string msg)
         {
             try
             {