Strings with embedded nulls cause issues with event payload decoding

[josalem]

Manifest driven EventSources mark all strings as win:UnicodeString in the manifest. This is interpreted by TraceEvent and other pieces of tracing infrastructure as "a null-terminated string". There is a separate type for "counted strings" that isn't used by EventSource.

C#, however, allows for embedded nulls in strings, and String.Length will give the full length of string including the embedded nulls.

EventSource uses String.Length when it is encoding strings, e.g.,

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

Lines 1089 to 1091 in c37257f

	descrs[1].DataPointer = (IntPtr)string2Bytes;
	descrs[1].Size = ((arg2.Length + 1) * 2);
	descrs[1].Reserved = 0;

This can lead to problems for the parser if there are things in the payload after the string. For example:

public class MySource : EventSource
{
    public static MySource Instance = new MySource();

    public void MyEvent(int foo, string bar, int baz) => WriteEvent(1, foo, bar, baz);
}

// ...

var myString = "aaa$bbb";
myString = myString.Replace('$', '\0');
MySource.Instance.MyEvent(10, myString, -10);

will result in the following at the reader end:

The event contains the full data:

<Event MSec=  "4096.7191" PID="24292" PName="EventSourceNullContent" TID="31320" EventName="MyEvent"
  TimeStamp="04/26/21 17:14:07.575276" ID="1" Version="0" Keywords="0x0000F00000000000" TimeStampQPC="9,698,287,562,667" QPCTime="0.100us"
  Level="Informational" ProviderName="MySource" ProviderGuid="a61ea624-4944-55fc-c2a8-37838829438d" ClassicProvider="False" ProcessorNumber="7"
  Opcode="0" Task="65533" Channel="0" PointerSize="8"
  CPU="7" EventIndex="70874" TemplateType="DynamicTraceEventData">
  <PrettyPrint>
    <Event MSec=  "4096.7191" PID="24292" PName="EventSourceNullContent" TID="31320" EventName="MyEvent" ProviderName="MySource" foo="10" bar="aaa" baz="6,422,626"/>
  </PrettyPrint>
  <Payload Length="24">
       0:   a  0  0  0 61  0 61  0 | 61  0  0  0 62  0 62  0   ....a.a. a...b.b.
      10:  62  0  0  0 f6 ff ff ff |                           b....... 
  </Payload>
</Event>

TraceEvent attempts to read a null terminated string, and then interprets the next 4 bytes as the baz parameter which is incorrect.

A potential solution would be to truncate input strings to the first null encountered. I imagine this is a very rare occurrence and the overhead of running String.IndexOf((char)0) should be minimal for the common use case. We could also push and out of band message that an event payload string was truncated.

CC @sywhang @noahfalk

[ghost]

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

Issue Details

---

Manifest driven EventSources mark all strings as win:UnicodeString in the manifest. This is interpreted by TraceEvent and other pieces of tracing infrastructure as "a null-terminated string". There is a separate type for "counted strings" that isn't used by EventSource.

C#, however, allows for embedded nulls in strings, and String.Length will give the full length of string including the embedded nulls.

EventSource uses String.Length when it is encoding strings, e.g.,

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

Lines 1089 to 1091 in c37257f

	descrs[1].DataPointer = (IntPtr)string2Bytes;
	descrs[1].Size = ((arg2.Length + 1) * 2);
	descrs[1].Reserved = 0;

This can lead to problems for the parser if there are things in the payload after the string. For example:

public class MySource : EventSource
{
    public static MySource Instance = new MySource();

    public void MyEvent(int foo, string bar, int baz) => WriteEvent(1, foo, bar, baz);
}

// ...

var myString = "aaa$bbb";
myString = myString.Replace('$', '\0');
MySource.Instance.MyEvent(10, myString, -10);

will result in the following at the reader end:

The event contains the full data:

<Event MSec=  "4096.7191" PID="24292" PName="EventSourceNullContent" TID="31320" EventName="MyEvent"
  TimeStamp="04/26/21 17:14:07.575276" ID="1" Version="0" Keywords="0x0000F00000000000" TimeStampQPC="9,698,287,562,667" QPCTime="0.100us"
  Level="Informational" ProviderName="MySource" ProviderGuid="a61ea624-4944-55fc-c2a8-37838829438d" ClassicProvider="False" ProcessorNumber="7"
  Opcode="0" Task="65533" Channel="0" PointerSize="8"
  CPU="7" EventIndex="70874" TemplateType="DynamicTraceEventData">
  <PrettyPrint>
    <Event MSec=  "4096.7191" PID="24292" PName="EventSourceNullContent" TID="31320" EventName="MyEvent" ProviderName="MySource" foo="10" bar="aaa" baz="6,422,626"/>
  </PrettyPrint>
  <Payload Length="24">
       0:   a  0  0  0 61  0 61  0 | 61  0  0  0 62  0 62  0   ....a.a. a...b.b.
      10:  62  0  0  0 f6 ff ff ff |                           b....... 
  </Payload>
</Event>

TraceEvent attempts to read a null terminated string, and then interprets the next 4 bytes as the baz parameter which is incorrect.

A potential solution would be to truncate input strings to the first null encountered. I imagine this is a very rare occurrence and the overhead of running String.IndexOf((char)0) should be minimal for the common use case. We could also push and out of band message that an event payload string was truncated.

CC @sywhang @noahfalk

Author:	josalem
Assignees:	-
Labels:	area-System.Diagnostics.Tracing
Milestone:	6.0.0

[sywhang]

we should also probably document this behavior in EventSource docs?

[KalleOlaviNiemitalo]

Another possible fix would be to replace null characters with U+2400 SYMBOL FOR NULL (␀), but then that would need a memory allocation.

[KalleOlaviNiemitalo]

For the self-describing format, DataCollector.AddNullTerminatedString already truncates the string at the first null character:

runtime/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/DataCollector.cs

Lines 155 to 162 in d1fed28

	// Calculate the size of the string including the trailing NULL char.
	// Don't use value.Length here because string allows for embedded NULL characters.
	int nullCharIndex = value.IndexOf((char)0);
	if (nullCharIndex < 0)
	{
	nullCharIndex = value.Length;
	}
	int size = (nullCharIndex + 1) * 2;

This came from dotnet/coreclr#16672; it used counted strings before that.

[Robo210]

@brianrob @idigdoug For context / awareness.

[brianrob]

As an FYI, this is a long-standing known issue for EventSource. We've done nothing in the past to solve it, and have just allowed it to live on "by design". If we were so inclined to fix it, we could switch to counted strings, though we'd need to add support to EventPipe for this, and then investigate how to address LTTng, and EventListener deserialization for both EventSource produced events and native events that are plumbed up to EventListener implementations.

[josalem]

Due to how long this behavior has existed, I think it may be beneficial to just document it.

Are there known, common use cases where a null would be present in the middle of a C# string? I can't think of any off the top of my head, but they might exist.

[jecollet]

Are there known, common use cases where a null would be present in the middle of a C# string? I can't think of any off the top of my head, but they might exist.

We just hit this issue in .NET Framework because we were tracing some HTTP request bodies using ETW. In our case, one of our APIs was being sent a binary payload that contained multiple '\0' characters. This completely messed up our tracing due to the issue you described, and it was quite a journey to understand what was going on.

Due to how long this behavior has existed, I think it may be beneficial to just document it.

I think the problem with this resolution is that there are many cases where event data does not originate from the event emitter (like the case above). So even if you document it, consumers are likely to hit this unless they are explicitly sanitizing all of their event data for null terminators.

I'm not sure how complicated the internals are here, but your earlier suggestions of truncation and/or some kind of warning being logged sound appropriate.

[josalem]

one of our APIs was being sent a binary payload that contained multiple '\0' characters

Out of curiosity, were you logging this payload as a string or was one of the in-box providers logging a binary payload as a string? I don't believe this should be affecting arbitrary binary data that is logged. Only strings.

I'm not sure how complicated the internals are here

It's not so much that it's complicated, but that it would be a breaking change for some providers (this only affects manifest-based providers; self-described providers are unaffected since they truncate to the first null). Similarly, we would be introducing a O(N) or O(logN) (I don't know if IndexOf is linear or doing a binary search) cost to every event with a string.

As I said, self-describing providers already truncate to the first null. I'm not opposed to making the change, but I haven't done the due diligence that comes with making a breaking change.

@brianrob it sounds like there was a history to making this change. Any context you can share on why we haven't made this change in the past? I would be on board with truncating to the first null and optionally logging an out-of-band message that a string was truncated. With the caveat that I don't want to introduce allocations or O(N) work for every string put through EventPipe (strings can get very long for some providers). Doing counted strings has the plus of adding less potential overhead, but also requires a lot more plumbing work to implement.

[jecollet]

Out of curiosity, were you logging this payload as a string or was one of the in-box providers logging a binary payload as a string? I don't believe this should be affecting arbitrary binary data that is logged. Only strings.

This is a binary payload that was converted to a string as part of the logging process. I should have specified that.

It's not so much that it's complicated, but that it would be a breaking change for some providers

By breaking change, are you referring to the change in behavior regarding null terminators, or some other consequence of the proposed change?

[josalem]

By breaking change, are you referring to the change in behavior regarding null terminators, or some other consequence of the proposed change?

The behavior change. Currently, the data is all there, but the reader doesn't know how to parse it correctly. In theory, so long as the string is only variably sized payload parameter, the parser could be changed to get all the data. If we change the behavior, that could have unintended consequences for readers or any writers that have made changes to get around this limitation.

Making the change is a matter of doing due diligence and getting enough signal that the change is worth making.

[brianrob]

This is one of those things that has been around for a long time, and there hasn't been much will to address it - mostly because there was a strong belief that strings are null-terminated. The amount of change involved here also isn't small, because if you switch all strings to be counted strings by default, then this is a breaking change to the serialization format, but it won't be obvious. There's also likely to be a bug tail because there are a handful of places where we serialize and de-serialize. My recommendation here is to just log a byte[], which will be of type win:Binary in ETW and will be treated as having a payload and size.

If you really do want to change this, it might be good to consider building it as an opt-in, which would allow you to not break any existing implementations, but folks could decorate the parameter as a counted string in the EventSource.