dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
15.27k stars 4.73k forks source link

EventAttribute Message not showing in ETW events #99274

Open jborean93 opened 8 months ago

jborean93 commented 8 months ago

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

ghost commented 8 months ago

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](https://learn.microsoft.com/en-us/dotnet/api/system.diagnostics.tracing.eventattribute.message?view=net-8.0) 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 ```csharp 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 ```xml net8.0-windows Exe ``` I compiled with `dotnet publish` and just ran the exe. In my testing I am using my custom PowerShell module [PSEtw](https://github.com/jborean93/PSEtw) by running the following in another admin PowerShell console when running the published exe from the above. ```powershell Trace-PSEtwEvent -Provider MyEventSource | % { $_ | ConvertTo-Json } ``` I've also reproduced the issue with [PerfView](https://github.com/microsoft/perfview) and [dotnet-trace](https://learn.microsoft.com/en-us/dotnet/core/diagnostics/dotnet-trace) and those are also missing the message data that I am expecting. ### Expected behavior ```json { "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 ```json { "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 commented 1 week ago

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 https://github.com/dotnet/runtime/blob/5ca9043932b908edfb5f4281b2a5cd461c40c708/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs#L1414-L1421

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 https://github.com/dotnet/runtime/blob/5ca9043932b908edfb5f4281b2a5cd461c40c708/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs#L2736-L2737

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 commented 1 week ago

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.