Standardize EventSource behavior in ETW for null values

[JJamesWWang]

fixes #12662

[ghost]

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
See info in area-owners.md if you want to be subscribed.

Issue Details

---

null

Author:	JJamesWWang
Assignees:	-
Labels:	area-System.Diagnostics.Tracing
Milestone:	-

[JJamesWWang]

This is the test failure based on the test case added.

      BasicEventSourceTests.TestsWriteEventToListener.Test_WriteEvent_ArgsBasicTypes [FAIL]
        Assert.Null() Failure
        Expected: (null)
        Actual:
        Stack Trace:
          C:\Users\JJame\Documents\OSSE\runtime\src\libraries\System.Diagnostics.Tracing\tests\BasicEventSourceTest\TestsWriteEventToListener.cs(208,0): at BasicEventSourceTests.TestsWriteEventToListener.Test_Wr 
  iteEvent_ArgsBasicTypes()
             at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
          C:\Users\JJame\Documents\OSSE\runtime\src\libraries\System.Private.CoreLib\src\System\Reflection\MethodInvoker.cs(64,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags 
   invokeAttr)

[JJamesWWang]

@AaronRobinsonMSFT re: #12662
This seems to be a valid failure to me; do you have any insight into what the error is?

[AaronRobinsonMSFT]

@AaronRobinsonMSFT re: #12662 This seems to be a valid failure to me; do you have any insight into what the error is?

This is saying that the value at index 0 isn't null. Which does seem odd for the current scenario, but it might be intentional converting a null to the string "(null)". Can you share what the value actually is?

[JJamesWWang]

Can you share what the value actually is?

I added this in:

Console.WriteLine("------------------------------------------");
Console.WriteLine((string)LoudListener.t_lastEvent.Payload[0]);
Console.WriteLine("------------------------------------------");

and the output is:

------------------------------------------
  
------------------------------------------

which leads me to believe it is the empty string.

Adding the following assert statement before the Assert.Null seems to prove it:

Assert.Equals("", (string)LoudListener.t_lastEvent.Payload[0]);

as it still fails on the Assert.Null

It seems that this is what is being called, and it looks consistent for the rest of the WriteEvent calls.

Is it intentional that null values become the empty string then?

[AaronRobinsonMSFT]

I added this in:

Console.WriteLine("------------------------------------------");
Console.WriteLine((string)LoudListener.t_lastEvent.Payload[0]);
Console.WriteLine("------------------------------------------");

A good rule of thumb is to put quotes around the string. Like so:

Console.WriteLine($"'{(string)LoudListener.t_lastEvent.Payload[0]}'");

Is it intentional that null values become the empty string then?

@noahfalk or @davmason Any thoughts here?

[davmason]

@noahfalk or @davmason Any thoughts here?

It looks like we special case null strings and make them empty strings here:

runtime/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs

Lines 908 to 927 in 570b373

	protected unsafe void WriteEvent(int eventId, string? arg1, string? arg2)
	{
	if (IsEnabled())
	{
	arg1 ??= "";
	arg2 ??= "";
	fixed (char* string1Bytes = arg1)
	fixed (char* string2Bytes = arg2)
	{
	EventSource.EventData* descrs = stackalloc EventSource.EventData[2];
	descrs[0].DataPointer = (IntPtr)string1Bytes;
	descrs[0].Size = ((arg1.Length + 1) * 2);
	descrs[0].Reserved = 0;
	descrs[1].DataPointer = (IntPtr)string2Bytes;
	descrs[1].Size = ((arg2.Length + 1) * 2);
	descrs[1].Reserved = 0;
	WriteEventCore(eventId, 2, descrs);
	}
	}
	}

I'm taking a deeper look now to see if this means #12662 was fixed but never closed or if it is talking about a different scenario

[davmason]

Ok, so this issue stills repros, but it's way more subtle than any of the previous discussion suggests.

The error happens specifically when an ETW or EventPipe session is enabled, and the WriteEvent(int eventId, params object?[] args) overload is used.

We have some specific overloads in EventSource for performance, but we fall back to this WriteEvent overload. We will translate the null string to an empty string in the overloads that explicitly take strings, and if using an EventListener we don't do any further processing and happily send a null event param.

If we are writing to an ETW/EventPipe session, however, we call in to EventProvider.WriteEvent and the code here sees that an argument is null and translates it to an error:

runtime/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventProvider.cs

Lines 981 to 985 in fdcbc7b

	else
	{
	s_returnCode = WriteEventErrorCode.NullInput;
	return false;
	}

To fix this the right way we should audit all the overloads of WriteEvent, see where we do null->default values for any type (I think it's not just string) and then make WriteEventVarargs match that behavior.

[davmason]

Repro for the failing case, you can make a console app and add the Microsoft.Diagnostics.NETCore.Client nuget package

using System.Diagnostics.Tracing;
using System.Diagnostics;
using System;
using System.Threading.Tasks;
using System.Collections.Generic;
using Microsoft.Diagnostics.NETCore.Client;
using Microsoft.Diagnostics.Tracing;

[EventSource(Name = "Test.MyEventSource")]
class EventSourceTest : EventSource
{
    [Event(1)]
    public void TestEvent(string str, int i, float f, long l)
    {
        WriteEvent(1, str, i, f, l, nullStr);
    }
}

class Program
{
    static void Main(string[] args)
    {
        List<EventPipeProvider> providers = new List<EventPipeProvider>
        {
            new EventPipeProvider("Test.MyEventSource", EventLevel.Verbose)
        };

        int processId = Process.GetCurrentProcess().Id;
        DiagnosticsClient client = new DiagnosticsClient(processId);
        using (EventPipeSession session = client.StartEventPipeSession(providers, /* requestRunDown */ false))
        {
            using (var source = new EventSourceTest())
            {
                source.TestEvent(null, 1, 1, 1); ;

                var events = new EventPipeEventSource(session.EventStream);

                Task processTask = Task.Run(() =>
                {
                    events.Dynamic.All += (TraceEvent traceEvent) =>
                    {
                        Console.WriteLine($"Got event {traceEvent.EventName} with #args {traceEvent.PayloadNames.Length}");
                        foreach (string name in traceEvent.PayloadNames)
                        {
                            Console.WriteLine($"    {name}: \"{traceEvent.PayloadByName(name)}\"");
                        }
                    };
                    events.Process();
                });

                session.Stop();
                processTask.Wait();
            }
        }
    }
}

[JJamesWWang]

How do I simulate the EventPipe session in a test case? I believe the following set of assertions will fail if executed while an ETW or EventPipe session is enabled (as per the failing case repro), but I'm not quite sure how to create a test under the same circumstances.

log.EventWithFallbackArgs(null, 10, 11, 12);
Assert.Equal(56, LoudListener.t_lastEvent.EventId);
Assert.Equal(4, LoudListener.t_lastEvent.Payload.Count);
Assert.Equal("", (string)LoudListener.t_lastEvent.Payload[0]);
Assert.Equal(10, (int)LoudListener.t_lastEvent.Payload[1]);
Assert.Equal(11, (float)LoudListener.t_lastEvent.Payload[2]);
Assert.Equal(12, (long)LoudListener.t_lastEvent.Payload[3]);

[Event(56)]
public unsafe void EventWithFallbackArgs(string str, int i, float f, long l)
{
    this.WriteEvent(56, str, i, f, l);
}

[JJamesWWang]

The two objects that can be null when calling the specific overloads in EventSource are string types and byte[] arrays, but their behavior seems inconsistent when null is passed in. Strings have a payload of an empty string, while byte arrays have a payload of an empty byte array. WriteEventVarArgs has no way of knowing whether the null was a string or byte array, so isn't it impossible to standardize the behavior? In other words, don't we have to always write either an empty string or byte array?

[davmason]

@JJamesWWang thanks for sticking with this! Answers to your questions below.

How do I simulate the EventPipe session in a test case? I believe the following set of assertions will fail if executed while an ETW or EventPipe session is enabled (as per the failing case repro), but I'm not quite sure how to create a test under the same circumstances.

We have a test harness that automates it. See here for example:

runtime/src/tests/tracing/eventpipe/eventsvalidation/ExceptionThrown_V1.cs

Lines 14 to 23 in d3ab95d

	public static int Main(string[] args)
	{
	var providers = new List<EventPipeProvider>()
	{
	new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Verbose),
	//ExceptionKeyword (0x8000): 0b1000_0000_0000_0000
	new EventPipeProvider("Microsoft-Windows-DotNETRuntime", EventLevel.Warning, 0b1000_0000_0000_0000)
	};
	return IpcTraceTest.RunAndValidateEventCounts(_expectedEventCounts, _eventGeneratingAction, providers, 1024);

You give it a list of providers and then the expected event count, if it runs in to an exception it will fail the test.

If you want to add a test, the easiest way is to copy and paste the .cs and .csproj and change all the names as appropriate, and then add your event.

WriteEventVarArgs has no way of knowing whether the null was a string or byte array, so isn't it impossible to standardize the behavior? In other words, don't we have to always write either an empty string or byte array?

We keep information about the parameters in the event metadata. The metadata we already have available here has a .Parameters field:

runtime/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs

Line 1861 in d3ab95d

ref EventMetadata metadata = ref m_eventData[eventId];

You can determine what type it is by checking metadata.Parameters[i].ParameterType where i is the index of the null argument in the args array.

[JJamesWWang]

I've added a test (ETWNullEvent.cs) for the ETW simulation, but it doesn't appear to be throwing the expected exception and is also hanging forever once the code executes. I've reduced the test to its least complex form, but I can't figure out why the test isn't working as expected. Would someone be able to take a look at this?

Expected behavior:
log.EventNullString(null, 10, 11, 12); -> This should throw an exception because it invokes the fallback event handler inside of an EventPipeSession.

Actual behavior:
log.EventNullString(null, 10, 11, 12); is executed, does not throw an exception, and then the test hangs.

[davmason]

Hi @JJamesWWang,

My suspicion is that the test hanging is related to the failure, but I can't take a look since you deleted the repo you had created the pull request from.

I suspect that the test is failing, but that failure causes a hang.