Sufficiently complex data type passed to EventSource results in invalid event data

[jbhensley]

See comment here.

Branch with repro code at this location

EDIT: referenced comment copied below for convenience.

---

I did note another error condition during my testing that we should look at, but I'll open a separate issue for it. For this test:

tests.Add(new SubTest("WriteEvent/SelfDescribingOnly/UserData",
delegate ()
{
	logger.EventUserDataInt(new UserData() { x = 3, y = 8 }, 5);
},
delegate (Event evt)
{
	Assert.Equal(logger.Name, evt.ProviderName);
	Assert.Equal("EventUserDataInt", evt.EventName);

	var aClass = (IDictionary<string, object>)evt.PayloadValue(0, "aClass");
	Assert.Equal(3, (int)aClass["x"]);
	Assert.Equal(8, (int)aClass["y"]);
	Assert.Equal(5, evt.PayloadValue(1, "anInt"));
}));

Modifying UserData by adding four nullables like so:

[EventData]
public class UserData
{
	public int x { get; set; }
	public int y { get; set; }

	/*
	 *      These lines result in assert fail at 417:
	 *          Assert.Equal(5, evt.PayloadValue(1, "anInt"));
	 */

	public int? N1 { get; set; } = int.MaxValue;
	public int? N2 { get; set; } = int.MaxValue;
	public int? N3 { get; set; } = int.MaxValue;
	public int? N4 { get; set; } = int.MaxValue;
}

results in invalid data coming back. If I dump the event, this is what I see:

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
  Dump of Event
  Name EventUserDataInt
  Payload count: 2
  Payload:
  Name: aClass  Value: { x:3, y:8, N1:{ HasValue:True, Value:2147483647 }, N2:{ HasValue:True, Value:2147483647 }, N3:{ HasValue:True, Value:2147483647 } }
  Name: anInt   Value: -255
  !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

Note that the fourth nullable disappears out of the payload and we appear to stomp on the memory space of anInt, changing its value from 5 to -255. This results in an assert fail at Assert.Equal(5, evt.PayloadValue(1, "anInt"));.

The concerning thing here is this looks suspiciously like a buffer overflow.

[vancem]

@noahfalk FYI. does look like a serialization bug.

[jbhensley]

Following up on tip from @vancem. Changing the nullables to contain unique values for each byte:

public int? N1 { get; set; } = unchecked((int)0x98765432);
public int? N2 { get; set; } = unchecked((int)0x98765432);
public int? N3 { get; set; } = unchecked((int)0x98765432);
public int? N4 { get; set; } = unchecked((int)0x98765432);

Results in anInt returning 1985229313, which appears to be a clear stomp:

May not actually be an overrun, but obviously the value of the fourth nullable is affecting anInt somehow.

[vancem]

Yup. Definitely a bug. By the way, making the four values N1, N4 different (in every byte) in the test would make the test even better. e.g.

public int? N1 { get; set; } = unchecked((int)0x99897969);
public int? N2 { get; set; } = unchecked((int)0x98887868);
public int? N3 { get; set; } = unchecked((int)0x97877767);
public int? N4 { get; set; } = unchecked((int)0x96867666);

But that is a minor nit.

[jbhensley]

That gives us -2039060991, which is the final 3 bytes of N4 stomped over anInt as above, but more definitively.

[noahfalk]

@jorive - we should probably understand this issue before we back-port the Nullable change to 2.1. If the issue is Nullable-specific (and @jbhensley testing suggested that it might be) then dotnet/corefx#20350 may have fixed one issue but exposed a second one.

[vancem]

Test for this case added with https://github.com/dotnet/corefx/pull/32777/files

[jorive]

@jbhensley would you have a standalone-self-contained repro? I just tried before and after the change and I could not repro the stomp, but I could see the original bug fix working.

[jbhensley]

Just the branch referenced above. Note this particular set of tests have a IsProcessElevatedAndNotWindowsNanoServer condition, so you'll need to launch an elevated cmd to get them to run.

[jorive]

@jbhensley Thanks, I overlooked the fact that in this case the tests were using EtwListener.cs. Now, I can see what you are describing.
I'll look more into the issue.

[jorive]

I spent more time looking at this bug and it seems like a deserialization bug on TraceEvent. I opened the generated etl file with wpa and perfview.

• wpa display the data properly (no stomp or corruption)
• perfview display the following:

ThreadID="12,872" ProcessorNumber="7" aClass="{ x:3, y:8, N1:{ HasValue:True, Value:-1719043735 }, N2:{ HasValue:True, Value:-1735886744 }, N3:{ HasValue:True, Value:-1752729753 } }" anInt="-2,039,060,991"

which correspond to the following TraceEvent instance (under the debugger):

{<Event MSec=   "233.7354" PID="39884" PName=        "" TID="40144" EventName="EventUserDataInt1" ProviderName="EventSourceTestSelfDescribingOnly" aClass="{ x:3, y:8, N1:{ HasValue:True, Value:-1719043735 }, N2:{ HasValue:True, Value:-1735886744 }, N3:{ HasValue:True, Value:-1752729753 } }" anInt="-2,039,060,991"/>}

In the latter, you can see anInt="-2,039,060,991", and N4 data is missing.

Finally, these is the display from wpa:

Line #	ProviderName	Activity	EventName	Type	OpCode	aClass.N1.HasValue (Field 1)	aClass.N1.Value (Field 2)	aClass.N2.HasValue (Field 3)	aClass.N2.Value (Field 4)	aClass.N3.HasValue (Field 5)	aClass.N3.Value (Field 6)	aClass.N4.HasValue (Field 7)	aClass.N4.Value (Field 8)	aClass.x (Field 9)	aClass.y (Field 10)	anInt (Field 11)	StartTime (s)	EndTime (s)	Time (s)
1	EventSourceTestSelfDescribingOnly		EventUserDataInt1	Event	0	1	-1719043735	1	-1735886744	1	-1752729753	1	-1769572762	3	8	5	0.233735400	0.233735400	0.233735400

[vancem]

This was determined to be a bug in the Microsoft.Diagnostics.Tracing.TraceEvent NuGet package. It has been fixed in V2.0.32 now up on nuget.org (see https://github.com/Microsoft/perfview/releases/tag/T2.0.32). If you upgrade the tests to use this version of TraceEvent, it should fix the problem

[tommcdon]

Closing since this is not a CoreFX issue, and has been fixed in Microsoft.Diagnostics.Tracing.TraceEvent V2.0.32 and later