EventAttribute Message not showing in ETW events

[jborean93]

Description

I'm honestly not sure if I'm just missing something simple but it seems like the EventAttribute.Message value is not being written in the underlying ETW event on Windows.

I was originally working with AOT and thought that could be the cause but when creating a reproducer to compare I found the non-AOT scenario was also missing this value.

Reproduction Steps

using System.Diagnostics.Tracing;

namespace EventTest;

[EventSource(Name = "MyEventSource")]
public sealed class MyEventSource : EventSource
{
    public static MyEventSource Log = new();

    private MyEventSource()
        : base(EventSourceSettings.EtwSelfDescribingEventFormat)
    { }

    [Event(1, Message = "foo {0}")]
    public void MyEvent(string msg)
        => WriteEvent(1, msg);
}

public static class Program
{
    public static void Main()
    {
        MyEventSource.Log.MyEvent("bar");
    }
}

With the csproj

<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <TargetFramework>net8.0-windows</TargetFramework>
    <OutputType>Exe</OutputType>
  </PropertyGroup>

</Project>

I compiled with dotnet publish and just ran the exe.

In my testing I am using my custom PowerShell module PSEtw by running the following in another admin PowerShell console when running the published exe from the above.

Trace-PSEtwEvent -Provider MyEventSource | % { $_ | ConvertTo-Json }

I've also reproduced the issue with PerfView and dotnet-trace and those are also missing the message data that I am expecting.

Expected behavior

{
  "ProviderId": "8983a2e6-c5d2-5a1f-691f-db243cb1f681",
  "ProviderName": "MyEventSource",
  "ProcessId": 13420,
  "ThreadId": 16120,
  "TimeStamp": "2024-03-05T15:04:48.5560144Z",
  "ActivityId": "00000000-0000-0000-0000-000000000000",
  "Id": 3,
  "Version": 0,
  "Channel": 11,
  "ChannelName": null,
  "Level": 4,
  "LevelName": null,
  "OpCode": 0,
  "OpCodeName": null,
  "Task": 0,
  "TaskName": "MyEvent",
  "Keyword": 263882790666240,
  "KeywordNames": [],
  "Tags": 0,
  "EventData": [],
  "Properties": [
    {
      "Name": "msg",
      "Value": "bar",
      "DisplayValue": "bar",
      "Tags": 0
    }
  ],
  "EventMessage": "foo bar"
}

I expect EventMessage to be the result of foo {0} (foo bar).

Actual behavior

{
  "ProviderId": "8983a2e6-c5d2-5a1f-691f-db243cb1f681",
  "ProviderName": "MyEventSource",
  "ProcessId": 13420,
  "ThreadId": 16120,
  "TimeStamp": "2024-03-05T15:04:48.5560144Z",
  "ActivityId": "00000000-0000-0000-0000-000000000000",
  "Id": 3,
  "Version": 0,
  "Channel": 11,
  "ChannelName": null,
  "Level": 4,
  "LevelName": null,
  "OpCode": 0,
  "OpCodeName": null,
  "Task": 0,
  "TaskName": "MyEvent",
  "Keyword": 263882790666240,
  "KeywordNames": [],
  "Tags": 0,
  "EventData": [],
  "Properties": [
    {
      "Name": "msg",
      "Value": "bar",
      "DisplayValue": "bar",
      "Tags": 0
    }
  ],
  "EventMessage": null
}

EventMessage is not set. I've also noticed Task is set to 0 not 1 as I would expect. This makes me even more suspicious I'm doing something wrong.

Regression?

I've gone back to net6.0 and it seems to have the same problem.

Known Workarounds

No response

Configuration

Running with .NET 8 on Windows Server 2022 x64.

Other information

No response

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

Issue Details

---

Description

I'm honestly not sure if I'm just missing something simple but it seems like the EventAttribute.Message value is not being written in the underlying ETW event on Windows.

I was originally working with AOT and thought that could be the cause but when creating a reproducer to compare I found the non-AOT scenario was also missing this value.

Reproduction Steps

using System.Diagnostics.Tracing;

namespace EventTest;

[EventSource(Name = "MyEventSource")]
public sealed class MyEventSource : EventSource
{
    public static MyEventSource Log = new();

    private MyEventSource()
        : base(EventSourceSettings.EtwSelfDescribingEventFormat)
    { }

    [Event(1, Message = "foo {0}")]
    public void MyEvent(string msg)
        => WriteEvent(1, msg);
}

public static class Program
{
    public static void Main()
    {
        MyEventSource.Log.MyEvent("bar");
    }
}

With the csproj

<Project Sdk="Microsoft.NET.Sdk">

  <PropertyGroup>
    <TargetFramework>net8.0-windows</TargetFramework>
    <OutputType>Exe</OutputType>
  </PropertyGroup>

</Project>

I compiled with dotnet publish and just ran the exe.

In my testing I am using my custom PowerShell module PSEtw by running the following in another admin PowerShell console when running the published exe from the above.

Trace-PSEtwEvent -Provider MyEventSource | % { $_ | ConvertTo-Json }

I've also reproduced the issue with PerfView and dotnet-trace and those are also missing the message data that I am expecting.

Expected behavior

{
  "ProviderId": "8983a2e6-c5d2-5a1f-691f-db243cb1f681",
  "ProviderName": "MyEventSource",
  "ProcessId": 13420,
  "ThreadId": 16120,
  "TimeStamp": "2024-03-05T15:04:48.5560144Z",
  "ActivityId": "00000000-0000-0000-0000-000000000000",
  "Id": 3,
  "Version": 0,
  "Channel": 11,
  "ChannelName": null,
  "Level": 4,
  "LevelName": null,
  "OpCode": 0,
  "OpCodeName": null,
  "Task": 0,
  "TaskName": "MyEvent",
  "Keyword": 263882790666240,
  "KeywordNames": [],
  "Tags": 0,
  "EventData": [],
  "Properties": [
    {
      "Name": "msg",
      "Value": "bar",
      "DisplayValue": "bar",
      "Tags": 0
    }
  ],
  "EventMessage": "foo bar"
}

I expect EventMessage to be the result of foo {0} (foo bar).

Actual behavior

{
  "ProviderId": "8983a2e6-c5d2-5a1f-691f-db243cb1f681",
  "ProviderName": "MyEventSource",
  "ProcessId": 13420,
  "ThreadId": 16120,
  "TimeStamp": "2024-03-05T15:04:48.5560144Z",
  "ActivityId": "00000000-0000-0000-0000-000000000000",
  "Id": 3,
  "Version": 0,
  "Channel": 11,
  "ChannelName": null,
  "Level": 4,
  "LevelName": null,
  "OpCode": 0,
  "OpCodeName": null,
  "Task": 0,
  "TaskName": "MyEvent",
  "Keyword": 263882790666240,
  "KeywordNames": [],
  "Tags": 0,
  "EventData": [],
  "Properties": [
    {
      "Name": "msg",
      "Value": "bar",
      "DisplayValue": "bar",
      "Tags": 0
    }
  ],
  "EventMessage": null
}

EventMessage is not set.

Regression?

I've gone back to net6.0 and

Known Workarounds

No response

Configuration

Running with .NET 8 on Windows Server 2022 x64.

Other information

No response

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

[mdh1418]

Hi @jborean93! I think you're right in that using EventSource with EventSourceSettings.EtwSelfDescribingEventFormat will not transmit the Message metadata when writing events. metadata.Message is not passed through

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

Lines 1414 to 1421 in 5ca9043

	EventSourceOptions opt = new EventSourceOptions
	{
	Keywords = (EventKeywords)metadata.Descriptor.Keywords,
	Level = (EventLevel)metadata.Descriptor.Level,
	Opcode = (EventOpcode)metadata.Descriptor.Opcode
	};
	WriteMultiMerge(metadata.Name, ref opt, metadata.TraceLoggingEventTypes, pActivityId, relatedActivityId, data);

However, I'm thinking that is by design, as it seems to me like self-describing events should transmit payloads that are self-sufficient.

On the other hand, using EventSource with EventSourceSettings.EtwManifestEventFormat will read the EventAttribute metadata when it creates a manifest and sends the manifest

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

Lines 2736 to 2737 in 5ca9043

	if (!SelfDescribingEvents)
	SendManifest(m_rawManifest);

I tried out your repro using the EtwManifestEventFormat setting instead, and was able to collect via PerfView and see the FormattedMessage "foo bar".

Would using EtwManifestEventFormat work for you, or do you need to use EtwSelfDescribingEventFormat for your scenario?

[jborean93]

Would using EtwManifestEventFormat work for you, or do you need to use EtwSelfDescribingEventFormat for your scenario?

It's been a while but at the time I had trouble using the manifest'd event source in newer versions of .NET. IIRC the underlying nuget package that actually was able to generate the manifest only worked up till net6.0 or something around that. Because of this I went with the self describing one which is a lot simpler to setup and use. I would have thought if one worked in one then it should work in the other which is why I opened this issue.

[mdh1418]

I'm not sure what nuget package you're using, but I believe in more recent versions of .NET Framework and .NET Core, using System.Diagnostics.Tracing namespace directly to leverage EventSource is recommended. If you're hitting any issues when trying to use the Manifest based format, we can open up separate issues and investigate them.

I don't know the exact design decision as to why the EventAttribute message format isn't passed along for EtwSelfDescribingEventFormat, but I'm thinking it's deliberate. My first guess is that it is expensive as the same format data would be sent per event, compared to the EtwManifestEventFormat sending the format data once in a manifest event.

Looking at some of the documentation, the EventAttribute example uses the default EventSource constructor which uses the EtwManifestEventFormat (compared to your custom EventSource that uses the EtwSelfDescribingEventFormat), so I believe the EventAttribute docs should be updated to note the behavior with EtwSelfDescribingEventFormat

[jborean93]

At the time I was testing out an ETW consumer and wanted to test out both a self describing and manifest driven event source. I came across two different ways to produce these events in .NET

• Microsoft.Diagnostics.Tracing.EventRegister
• System.Diagnostics.Tracing.EventSource

The Microsoft.* seemed to be the older option and was able to generate a manifest and the resource dll at build time but didn't support newer .NET versions. From what I understand this package should not be used anymore which makes sense.

The System.* one was able to do self describing events but was unable to generate the manifest and resource dll to use with wevutil registration. Is this even a use case that's supported anymore, if not what is the purpose of the manifest file if I can't register it in Windows? Being able to register it on the system provides a few advantages like being able to see it in the provider browser and view things like the registered events, levels, etc.

I tried out your repro using the EtwManifestEventFormat setting instead, and was able to collect via PerfView and see the FormattedMessage "foo bar".

How did you register the manifest with PerfView? It seems like based on microsoft/perfview#558 I need to use a separate tool to generate the dll to then register with wevutil? If so it would be good to see some documentation around that process, especially if things like this is expected and we need to use the manifest event type. There's a good chance I just don't fully understand or have misinterpreted how things work with EventSource and ETW. The whole ETW API is quite complicated and super confusing to me.

If this is as expected then it's fine to close this issue, I probably won't use this anyway as it's somewhat too confusing for me. I just would have expected that this attribute would fail if being used for this scenario rather than just silently ignored or actually work.