Runtime: MethodLoadVervose_V1 received with incorrect layout via EventPipe

Created on 6 Oct 2020  路  10Comments  路  Source: dotnet/runtime

When I'm using EventPipe to collect events from .NET 5 application built for x86 on Windows, sometimes at the beginning of the session I receive a bunch of MethodLoadVerbose_V1 events (id 143, version 1) with the invalid layout. Maybe this issue can be reproduced on other configurations too.

These events are based on MethodLoadUnloadVerbose_V1 template and should have following structure:

<data name="MethodID" inType="win:UInt64" outType="win:HexInt64" />
<data name="ModuleID" inType="win:UInt64" outType="win:HexInt64" />
<data name="MethodStartAddress" inType="win:UInt64" outType="win:HexInt64" />
<data name="MethodSize" inType="win:UInt32" outType="win:HexInt32" />
<data name="MethodToken" inType="win:UInt32" outType="win:HexInt32" />
<data name="MethodFlags" inType="win:UInt32" map="MethodFlagsMap" />
<data name="MethodNamespace" inType="win:UnicodeString" />
<data name="MethodName" inType="win:UnicodeString" />
<data name="MethodSignature" inType="win:UnicodeString" />
<data name="ClrInstanceID" inType="win:UInt16" />

but I receive events with only one string (MethodName actually). Examples of such events are

[2020-10-05 19:33:08.903096]: <debug> Memory dump:
  0000  cc 30 43 03 00 00 00 00 00 00 00 00 00 00 00 00  .0C.............
  0010  cc 30 43 03 00 00 00 00 34 00 00 00 00 00 00 00  .0C.....4.......
  0020  10 00 00 00 40 00 4e 00 65 00 77 00 4f 00 62 00  [email protected].
  0030  6a 00 65 00 63 00 74 00 00 00 0b 00              j.e.c.t.....
[2020-10-05 19:33:08.903096]: <debug> Memory dump:
  0000  00 31 43 03 00 00 00 00 00 00 00 00 00 00 00 00  .1C.............
  0010  00 31 43 03 00 00 00 00 54 00 00 00 00 00 00 00  .1C.....T.......
  0020  10 00 00 00 40 00 4e 00 65 00 77 00 4f 00 62 00  [email protected].
  0030  6a 00 65 00 63 00 74 00 41 00 6c 00 69 00 67 00  j.e.c.t.A.l.i.g.
  0040  6e 00 38 00 00 00 0b 00                          n.8.....
[2020-10-05 19:33:08.903096]: <debug> Memory dump:
  0000  54 31 43 03 00 00 00 00 00 00 00 00 00 00 00 00  T1C.............
  0010  54 31 43 03 00 00 00 00 74 00 00 00 00 00 00 00  T1C.....t.......
  0020  10 00 00 00 40 00 42 00 6f 00 78 00 00 00 0b 00  [email protected].....
[2020-10-05 19:33:08.903096]: <debug> Memory dump:
  0000  c8 31 43 03 00 00 00 00 00 00 00 00 00 00 00 00  .1C.............
  0010  c8 31 43 03 00 00 00 00 4c 00 00 00 00 00 00 00  .1C.....L.......
  0020  10 00 00 00 40 00 4e 00 65 00 77 00 41 00 72 00  [email protected].
  0030  72 00 61 00 79 00 31 00 4f 00 62 00 6a 00 65 00  r.a.y.1.O.b.j.e.
  0040  63 00 74 00 00 00 0b 00                          c.t.....

As far as I understand, these events are generated by ETW::MethodLog::SendHelperEvent from src/coreclr/src/vm/eventtrace.cpp:

VOID ETW::MethodLog::SendHelperEvent(ULONGLONG ullHelperStartAddress, ULONG ulHelperSize, LPCWSTR pHelperName)
{
    WRAPPER_NO_CONTRACT;
    if(pHelperName)
    {
         PCWSTR szDtraceOutput1=W("");
         ULONG methodFlags = ETW::MethodLog::MethodStructs::JitHelperMethod; // helper flag set
         FireEtwMethodLoadVerbose_V1(ullHelperStartAddress,
                                     0,
                                     ullHelperStartAddress,
                                     ulHelperSize,
                                     0,
                                     methodFlags,
                                     NULL,
                                     pHelperName,
                                     NULL,
                                     GetClrInstanceId());
    }
}

And the issue is caused by using NULLs here instead of empty strings. I don't found an implementation of FireEtwMethodLoadVerbose_V1 (is it generated?). If expected using of empty strings instead of NULLs in ETW::MethodLog::SendHelperEvent can cause issues in other subsystems, the issue can be fixed with additional checks in the FireEtwMethodLoadVerbose_V1.

As far as I understand, this issue relates to the issue #8008.

area-Tracing-coreclr
Source
picture valco1994

Most helpful comment

I just realized the code Sung and I were looking at isn't the code that would generate this event when it is fired over EventPipe. That is instead this code:

ULONG EventPipeWriteEventMethodLoadVerbose_V1(
    const unsigned __int64 MethodID,
    const unsigned __int64 ModuleID,
    const unsigned __int64 MethodStartAddress,
    const unsigned int MethodSize,
    const unsigned int MethodToken,
    const unsigned int MethodFlags,
    PCWSTR MethodNamespace,
    PCWSTR MethodName,
    PCWSTR MethodSignature,
    const unsigned short ClrInstanceID,
    LPCGUID ActivityId,
    LPCGUID RelatedActivityId)
{
    if (!EventPipeEventEnabledMethodLoadVerbose_V1())
        return ERROR_SUCCESS;

    char stackBuffer[230];
    char *buffer = stackBuffer;
    size_t offset = 0;
    size_t size = 230;
    bool fixedBuffer = true;

    bool success = true;
    success &= WriteToBuffer(MethodID, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(ModuleID, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodStartAddress, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodSize, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodToken, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodFlags, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodNamespace, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodName, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodSignature, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(ClrInstanceID, buffer, offset, size, fixedBuffer);

    if (!success)
    {
        if (!fixedBuffer)
            delete[] buffer;
        return ERROR_WRITE_FAULT;
    }

    EventPipe::WriteEvent(*EventPipeEventMethodLoadVerbose_V1, (BYTE *)buffer, (unsigned int)offset, ActivityId, RelatedActivityId);

    if (!fixedBuffer)
        delete[] buffer;

    return ERROR_SUCCESS;
}

Where calls to WriteToBuffer with a NULL string simply return true:

bool WriteToBuffer(PCWSTR str, char *&buffer, size_t& offset, size_t& size, bool &fixedBuffer)
{
    if(!str) return true;
    size_t byteCount = (wcslen(str) + 1) * sizeof(*str);

    if (offset + byteCount > size)
    {
        if (!ResizeBuffer(buffer, size, offset, size + byteCount, fixedBuffer))
            return false;
    }

    memcpy(buffer + offset, str, byteCount);
    offset += byteCount;
    return true;
}

Based on that, the event output we are seeing in EventPipe is "by design", but that doesn't match the manifest. I think this should have been happening in previous versions as well since I don't think this code has changed in a while. Let me go double check the git blame to be sure though.

picture josalem on 7 Oct 2020
👍2

All 10 comments

@sywhang @josalem

valco1994 picture valco1994 on 7 Oct 2020

Let me see if I can repro this locally.

I don't found an implementation of FireEtwMethodLoadVerbose_V1 (is it generated?).

Yes, the FireEt* methods are generated by a python script at build time. The generated files should be in one of the intermediate directories in the artifacts dir after a build. I don't recall specifically where off the top of my head.

josalem picture josalem on 7 Oct 2020

@valco1994 FireEtwMethodLoadVerbose_V1 is a generated macro definition. The manifest gets translated to code that looks like this:
image

As you can see we do null checks in there for any unicodestring formatted payloads and replace it with "NULL".

Is this trace file something you could share with us?

sywhang picture sywhang on 7 Oct 2020
👍1

Hm, it is very strange. I don't have a trace file, because I'm listening EventPipe in the live mode. But I can share the beginning of the log file which contains corresponding hex dumps. Not the one which I posted above, but with the same issue. 

[2020-10-06 14:50:51.357575]: <info> Opening connection to Windows named pipe "\\.\pipe\dotnet-diagnostic-6492"
[2020-10-06 14:50:51.392433]: <info> Windows named pipe opened successfully
[2020-10-06 14:50:51.392433]: <info> Starting EventPipe session (Diagnostics IPC)
[2020-10-06 14:50:51.392433]: <info> Sending message (size = 119)
[2020-10-06 14:50:51.392433]: <info> 119 bytes were written
[2020-10-06 14:50:51.393431]: <info> Receiving message
[2020-10-06 14:50:51.393431]: <info> Reading from Windows named pipe (20 requested)
[2020-10-06 14:50:51.400742]: <info> 20 bytes were read
[2020-10-06 14:50:51.400742]: <info> Reading from Windows named pipe (8 requested)
[2020-10-06 14:50:51.400742]: <info> 8 bytes were read
[2020-10-06 14:50:51.400742]: <info> EventPipe session started successfully, session_id=51569392
[2020-10-06 14:50:51.405982]: <debug> Memory dump:
  0000  4e 65 74 74 72 61 63 65 14 00 00 00 21 46 61 73  Nettrace....!Fas
  0010  74 53 65 72 69 61 6c 69 7a 61 74 69 6f 6e 2e 31  tSerialization.1
[2020-10-06 14:50:51.405982]: <info> Begin tag or NullReference tag expected
[2020-10-06 14:50:51.405982]: <debug> Memory dump:
  0000  05                                               .
[2020-10-06 14:50:51.405982]: <info> Processing TypeOfType
[2020-10-06 14:50:51.405982]: <debug> Memory dump:
  0000  05 01 04 00 00 00 04 00 00 00 05 00 00 00 54 72  ..............Tr
  0010  61 63 65 06                                      ace.
[2020-10-06 14:50:51.405982]: <info> Processing Trace object
[2020-10-06 14:50:51.405982]: <debug> Memory dump:
  0000  e4 07 0a 00 02 00 06 00 0b 00 32 00 33 00 88 01  ..........2.3...
  0010  78 00 ea be 24 01 00 00 80 96 98 00 00 00 00 00  x...$...........
  0020  04 00 00 00 5c 19 00 00 02 00 00 00 40 42 0f 00  ....\.......@B..
[2020-10-06 14:50:51.405982]: <info> Data size: 48 bytes
[2020-10-06 14:50:51.405982]: <info> 06.10.2020 11:50:51:392. SyncTimeQPC is 1257333457016, QPCFrequency is 10000000, Pointer size is 4, ProcessId is 6492, #processors=2, SamplingRate=1000000
[2020-10-06 14:50:51.407098]: <info> End tag expected
[2020-10-06 14:50:51.407098]: <debug> Memory dump:
  0000  06                                               .
[2020-10-06 14:50:51.407098]: <info> Begin tag or NullReference tag expected
[2020-10-06 14:50:51.407098]: <debug> Memory dump:
  0000  05                                               .
[2020-10-06 14:50:51.407098]: <info> Processing TypeOfType
[2020-10-06 14:50:51.407098]: <debug> Memory dump:
  0000  05 01 02 00 00 00 02 00 00 00 0d 00 00 00 4d 65  ..............Me
  0010  74 61 64 61 74 61 42 6c 6f 63 6b 06              tadataBlock.
[2020-10-06 14:50:51.407098]: <info> Processing MetadataBlock object
[2020-10-06 14:50:51.407098]: <info> Data size: 426 bytes
[2020-10-06 14:50:51.407098]: <debug> Memory dump:
  0000  aa 01 00 00                                      ....
[2020-10-06 14:50:51.407098]: <info> Skipping alignment << (4)
[2020-10-06 14:50:51.407098]: <debug> Memory dump:
  0000  00                                               .
[2020-10-06 14:50:51.407098]: <info> Processing BlockHeader
[2020-10-06 14:50:51.407098]: <debug> Memory dump:
  0000  14 00 01 00 8f 0c ea be 24 01 00 00 4f 1f ea be  ........$...O...
  0010  24 01 00 00                                      $...
[2020-10-06 14:50:51.407098]: <info> Processing EventBlobs
[2020-10-06 14:50:51.407098]: <info> EventBlobs headers are compressed
[2020-10-06 14:50:51.407098]: <debug> Memory dump:
  0000  c6 ff ff ff ff 0f 00 ff ff ff ff 0f e0 22 8f 99  ............."..
  0010  a8 f7 cb 24 5e 01 00 00 00 4d 00 69 00 63 00 72  ...$^....M.i.c.r
  0020  00 6f 00 73 00 6f 00 66 00 74 00 2d 00 57 00 69  .o.s.o.f.t.-.W.i
  0030  00 6e 00 64 00 6f 00 77 00 73 00 2d 00 44 00 6f  .n.d.o.w.s.-.D.o
  0040  00 74 00 4e 00 45 00 54 00 52 00 75 00 6e 00 74  .t.N.E.T.R.u.n.t
  0050  00 69 00 6d 00 65 00 00 00 55 00 00 00 00 00 00  .i.m.e...U......
  0060  08 01 00 00 00 00 00 00 00 00 00 04 00 00 00 00  ................
  0070  00 00 00 40 a8 0c 02 00 00 00 4d 00 69 00 63 00  [email protected].
  0080  72 00 6f 00 73 00 6f 00 66 00 74 00 2d 00 57 00  r.o.s.o.f.t.-.W.
  0090  69 00 6e 00 64 00 6f 00 77 00 73 00 2d 00 44 00  i.n.d.o.w.s.-.D.
  00a0  6f 00 74 00 4e 00 45 00 54 00 52 00 75 00 6e 00  o.t.N.E.T.R.u.n.
  00b0  74 00 69 00 6d 00 65 00 00 00 8f 00 00 00 00 00  t.i.m.e.........
  00c0  30 00 00 00 00 00 00 00 01 00 00 00 04 00 00 00  0...............
  00d0  00 00 00 00 40 a5 10 03 00 00 00 4d 00 69 00 63  [email protected]
  00e0  00 72 00 6f 00 73 00 6f 00 66 00 74 00 2d 00 57  .r.o.s.o.f.t.-.W
  00f0  00 69 00 6e 00 64 00 6f 00 77 00 73 00 2d 00 44  .i.n.d.o.w.s.-.D
  0100  00 6f 00 74 00 4e 00 45 00 54 00 52 00 75 00 6e  .o.t.N.E.T.R.u.n
  0110  00 74 00 69 00 6d 00 65 00 00 00 05 00 00 00 00  .t.i.m.e........
  0120  00 01 00 00 00 00 00 00 00 01 00 00 00 04 00 00  ................
  0130  00 00 00 00 00 40 f3 08 04 00 00 00 4d 00 69 00  [email protected].
  0140  63 00 72 00 6f 00 73 00 6f 00 66 00 74 00 2d 00  c.r.o.s.o.f.t.-.
  0150  57 00 69 00 6e 00 64 00 6f 00 77 00 73 00 2d 00  W.i.n.d.o.w.s.-.
  0160  44 00 6f 00 74 00 4e 00 45 00 54 00 52 00 75 00  D.o.t.N.E.T.R.u.
  0170  6e 00 74 00 69 00 6d 00 65 00 00 00 1e 00 00 00  n.t.i.m.e.......
  0180  00 00 02 00 00 00 00 00 00 00 00 00 00 00 04 00  ................
  0190  00 00 00 00 00 00                                ......
[2020-10-06 14:50:51.408101]: <debug> Memory dump:
  0000  01 00 00 00 4d 00 69 00 63 00 72 00 6f 00 73 00  ....M.i.c.r.o.s.
  0010  6f 00 66 00 74 00 2d 00 57 00 69 00 6e 00 64 00  o.f.t.-.W.i.n.d.
  0020  6f 00 77 00 73 00 2d 00 44 00 6f 00 74 00 4e 00  o.w.s.-.D.o.t.N.
  0030  45 00 54 00 52 00 75 00 6e 00 74 00 69 00 6d 00  E.T.R.u.n.t.i.m.
  0040  65 00 00 00 55 00 00 00 00 00 00 08 01 00 00 00  e...U...........
  0050  00 00 00 00 00 00 04 00 00 00 00 00 00 00        ..............
[2020-10-06 14:50:51.408101]: <debug> Memory dump:
  0000  02 00 00 00 4d 00 69 00 63 00 72 00 6f 00 73 00  ....M.i.c.r.o.s.
  0010  6f 00 66 00 74 00 2d 00 57 00 69 00 6e 00 64 00  o.f.t.-.W.i.n.d.
  0020  6f 00 77 00 73 00 2d 00 44 00 6f 00 74 00 4e 00  o.w.s.-.D.o.t.N.
  0030  45 00 54 00 52 00 75 00 6e 00 74 00 69 00 6d 00  E.T.R.u.n.t.i.m.
  0040  65 00 00 00 8f 00 00 00 00 00 30 00 00 00 00 00  e.........0.....
  0050  00 00 01 00 00 00 04 00 00 00 00 00 00 00        ..............
[2020-10-06 14:50:51.408101]: <debug> Memory dump:
  0000  03 00 00 00 4d 00 69 00 63 00 72 00 6f 00 73 00  ....M.i.c.r.o.s.
  0010  6f 00 66 00 74 00 2d 00 57 00 69 00 6e 00 64 00  o.f.t.-.W.i.n.d.
  0020  6f 00 77 00 73 00 2d 00 44 00 6f 00 74 00 4e 00  o.w.s.-.D.o.t.N.
  0030  45 00 54 00 52 00 75 00 6e 00 74 00 69 00 6d 00  E.T.R.u.n.t.i.m.
  0040  65 00 00 00 05 00 00 00 00 00 01 00 00 00 00 00  e...............
  0050  00 00 01 00 00 00 04 00 00 00 00 00 00 00        ..............
[2020-10-06 14:50:51.409112]: <debug> Memory dump:
  0000  04 00 00 00 4d 00 69 00 63 00 72 00 6f 00 73 00  ....M.i.c.r.o.s.
  0010  6f 00 66 00 74 00 2d 00 57 00 69 00 6e 00 64 00  o.f.t.-.W.i.n.d.
  0020  6f 00 77 00 73 00 2d 00 44 00 6f 00 74 00 4e 00  o.w.s.-.D.o.t.N.
  0030  45 00 54 00 52 00 75 00 6e 00 74 00 69 00 6d 00  E.T.R.u.n.t.i.m.
  0040  65 00 00 00 1e 00 00 00 00 00 02 00 00 00 00 00  e...............
  0050  00 00 00 00 00 00 04 00 00 00 00 00 00 00        ..............
[2020-10-06 14:50:51.409112]: <info> 
MetadataBlock header: Header size is 20, flags are 0x1, min timestamp is 1257333460111, max timestamp is 1257333464911
    Blob #0
        Blob header: metadata id is 0, sequence number is -1, thread id is 4448, capture thread id is 0, processor number is -1, stack id is 0, timestamp is -1091957329, activity id is 0000000000000000, related activity id is 0000000000000000, payload size is 94
        Metadata header: metadata id is 1, provider name is "Microsoft-Windows-DotNETRuntime", event id is 85, event name is "", keywords are 0x010800, version is 0, level is 4
        No payload
    Blob #1
        Blob header: metadata id is 0, sequence number is -1, thread id is 4448, capture thread id is 0, processor number is -1, stack id is 0, timestamp is -1091955753, activity id is 0000000000000000, related activity id is 0000000000000000, payload size is 94
        Metadata header: metadata id is 2, provider name is "Microsoft-Windows-DotNETRuntime", event id is 143, event name is "", keywords are 0x000030, version is 1, level is 4
        No payload
    Blob #2
        Blob header: metadata id is 0, sequence number is -1, thread id is 4448, capture thread id is 0, processor number is -1, stack id is 0, timestamp is -1091953668, activity id is 0000000000000000, related activity id is 0000000000000000, payload size is 94
        Metadata header: metadata id is 3, provider name is "Microsoft-Windows-DotNETRuntime", event id is 5, event name is "", keywords are 0x000001, version is 1, level is 4
        No payload
    Blob #3
        Blob header: metadata id is 0, sequence number is -1, thread id is 4448, capture thread id is 0, processor number is -1, stack id is 0, timestamp is -1091952529, activity id is 0000000000000000, related activity id is 0000000000000000, payload size is 94
        Metadata header: metadata id is 4, provider name is "Microsoft-Windows-DotNETRuntime", event id is 30, event name is "", keywords are 0x000002, version is 0, level is 4
        No payload
[2020-10-06 14:50:51.409112]: <info> End tag expected
[2020-10-06 14:50:51.410264]: <debug> Memory dump:
  0000  06                                               .
[2020-10-06 14:50:51.410392]: <info> Begin tag or NullReference tag expected
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  05                                               .
[2020-10-06 14:50:51.410392]: <info> Processing TypeOfType
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  05 01 02 00 00 00 02 00 00 00 0a 00 00 00 53 74  ..............St
  0010  61 63 6b 42 6c 6f 63 6b 06                       ackBlock.
[2020-10-06 14:50:51.410392]: <info> Processing StackBlock object
[2020-10-06 14:50:51.410392]: <info> Data size: 12 bytes
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  0c 00 00 00                                      ....
[2020-10-06 14:50:51.410392]: <info> Skipping alignment << (4)
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  00 00 00                                         ...
[2020-10-06 14:50:51.410392]: <info> Header: first_id = 1, count = 1
[2020-10-06 14:50:51.410392]: <info> Stack #1, stack size is 0
[2020-10-06 14:50:51.410392]: <info> []
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  01 00 00 00 01 00 00 00 00 00 00 00              ............
[2020-10-06 14:50:51.410392]: <info> End tag expected
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  06                                               .
[2020-10-06 14:50:51.410392]: <info> Begin tag or NullReference tag expected
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  05                                               .
[2020-10-06 14:50:51.410392]: <info> Processing TypeOfType
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  05 01 02 00 00 00 02 00 00 00 0a 00 00 00 45 76  ..............Ev
  0010  65 6e 74 42 6c 6f 63 6b 06                       entBlock.
[2020-10-06 14:50:51.410392]: <info> Processing EventBlock object
[2020-10-06 14:50:51.410392]: <info> Data size: 1094 bytes
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  46 04 00 00                                      F...
[2020-10-06 14:50:51.410392]: <info> Skipping alignment << (4)
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  00                                               .
[2020-10-06 14:50:51.410392]: <info> Processing BlockHeader
[2020-10-06 14:50:51.410392]: <debug> Memory dump:
  0000  14 00 01 00 8f 0c ea be 24 01 00 00 7d 28 ea be  ........$...}(..
  0010  24 01 00 00                                      $...
[2020-10-06 14:50:51.410392]: <info> Processing EventBlobs
[2020-10-06 14:50:51.410392]: <info> EventBlobs headers are compressed
[2020-10-06 14:50:51.411383]: <debug> Memory dump:
  0000  cf 01 00 b4 35 ff ff ff ff 0f b4 35 01 8f 99 a8  ....5......5....
  0010  f7 cb 24 1e d8 66 12 03 00 00 00 00 58 c3 17 03  ..$..f......X...
  0020  00 00 00 00 00 00 00 00 01 00 00 00 b4 1a 00 00  ................
  0030  0a 00 81 02 a8 0c 3c cc 30 06 03 00 00 00 00 00  ......<.0.......
  0040  00 00 00 00 00 00 00 cc 30 06 03 00 00 00 00 34  ........0......4
  0050  00 00 00 00 00 00 00 10 00 00 00 40 00 4e 00 65  [email protected]
  0060  00 77 00 4f 00 62 00 6a 00 65 00 63 00 74 00 00  .w.O.b.j.e.c.t..
  0070  00 0a 00 80 09 48 00 31 06 03 00 00 00 00 00 00  .....H.1........
  0080  00 00 00 00 00 00 00 31 06 03 00 00 00 00 54 00  .......1......T.
  0090  00 00 00 00 00 00 10 00 00 00 40 00 4e 00 65 00  [email protected].
  00a0  77 00 4f 00 62 00 6a 00 65 00 63 00 74 00 41 00  w.O.b.j.e.c.t.A.
  00b0  6c 00 69 00 67 00 6e 00 38 00 00 00 0a 00 80 07  l.i.g.n.8.......
  00c0  30 54 31 06 03 00 00 00 00 00 00 00 00 00 00 00  0T1.............
  00d0  00 54 31 06 03 00 00 00 00 74 00 00 00 00 00 00  .T1......t......
  00e0  00 10 00 00 00 40 00 42 00 6f 00 78 00 00 00 0a  [email protected]....
  00f0  00 80 06 48 c8 31 06 03 00 00 00 00 00 00 00 00  ...H.1..........
  0100  00 00 00 00 c8 31 06 03 00 00 00 00 4c 00 00 00  .....1......L...
  0110  00 00 00 00 10 00 00 00 40 00 4e 00 65 00 77 00  [email protected].
  0120  41 00 72 00 72 00 61 00 79 00 31 00 4f 00 62 00  A.r.r.a.y.1.O.b.
  0130  6a 00 65 00 63 00 74 00 00 00 0a 00 80 06 4e 14  j.e.c.t.......N.
  0140  32 06 03 00 00 00 00 00 00 00 00 00 00 00 00 14  2...............
  0150  32 06 03 00 00 00 00 5c 00 00 00 00 00 00 00 10  2......\........
  0160  00 00 00 40 00 4e 00 65 00 77 00 41 00 72 00 72  [email protected]
  0170  00 61 00 79 00 31 00 56 00 61 00 6c 00 75 00 65  .a.y.1.V.a.l.u.e
  0180  00 54 00 79 00 70 00 65 00 00 00 0a 00 80 06 54  .T.y.p.e.......T
  0190  70 32 06 03 00 00 00 00 00 00 00 00 00 00 00 00  p2..............
  01a0  70 32 06 03 00 00 00 00 78 00 00 00 00 00 00 00  p2......x.......
  01b0  10 00 00 00 40 00 4e 00 65 00 77 00 41 00 72 00  [email protected].
  01c0  72 00 61 00 79 00 31 00 4f 00 62 00 6a 00 65 00  r.a.y.1.O.b.j.e.
  01d0  63 00 74 00 41 00 6c 00 69 00 67 00 6e 00 38 00  c.t.A.l.i.g.n.8.
  01e0  00 00 0a 00 80 06 4a 3c 33 06 03 00 00 00 00 00  ......J<3.......
  01f0  00 00 00 00 00 00 00 3c 33 06 03 00 00 00 00 28  .......<3......(
  0200  00 00 00 00 00 00 00 10 00 00 00 40 00 53 00 74  [email protected]
  0210  00 61 00 74 00 69 00 63 00 42 00 61 00 73 00 65  .a.t.i.c.B.a.s.e
  0220  00 4f 00 62 00 6a 00 65 00 63 00 74 00 00 00 0a  .O.b.j.e.c.t....
  0230  00 80 06 50 64 33 06 03 00 00 00 00 00 00 00 00  ...Pd3..........
  0240  00 00 00 00 64 33 06 03 00 00 00 00 24 00 00 00  ....d3......$...
  0250  00 00 00 00 10 00 00 00 40 00 53 00 74 00 61 00  [email protected].
  0260  74 00 69 00 63 00 42 00 61 00 73 00 65 00 4e 00  t.i.c.B.a.s.e.N.
  0270  6f 00 6e 00 4f 00 62 00 6a 00 65 00 63 00 74 00  o.n.O.b.j.e.c.t.
  0280  00 00 0a 00 80 07 58 88 33 06 03 00 00 00 00 00  ......X.3.......
  0290  00 00 00 00 00 00 00 88 33 06 03 00 00 00 00 14  ........3.......
  02a0  00 00 00 00 00 00 00 10 00 00 00 40 00 53 00 74  [email protected]
  02b0  00 61 00 74 00 69 00 63 00 42 00 61 00 73 00 65  .a.t.i.c.B.a.s.e
  02c0  00 4f 00 62 00 6a 00 65 00 63 00 74 00 4e 00 6f  .O.b.j.e.c.t.N.o
  02d0  00 43 00 43 00 74 00 6f 00 72 00 00 00 0a 00 80  .C.C.t.o.r......
  02e0  06 5e 9c 33 06 03 00 00 00 00 00 00 00 00 00 00  .^.3............
  02f0  00 00 9c 33 06 03 00 00 00 00 10 00 00 00 00 00  ...3............
  0300  00 00 10 00 00 00 40 00 53 00 74 00 61 00 74 00  [email protected].
  0310  69 00 63 00 42 00 61 00 73 00 65 00 4e 00 6f 00  i.c.B.a.s.e.N.o.
  0320  6e 00 4f 00 62 00 6a 00 65 00 63 00 74 00 4e 00  n.O.b.j.e.c.t.N.
  0330  6f 00 43 00 43 00 74 00 6f 00 72 00 00 00 0a 00  o.C.C.t.o.r.....
  0340  81 03 ea 0f 16 00 10 e5 03 00 00 00 00 00 f0 ff  ................
  0350  00 00 00 00 00 00 00 00 00 0a 00 00 e9 01 00 10  ................
  0360  e5 04 00 00 00 00 00 f0 ff 00 00 00 00 00 01 00  ................
  0370  00 00 0a 00 00 80 01 00 10 e5 05 00 00 00 00 00  ................
  0380  f0 ff 00 00 00 00 00 03 00 00 00 0a 00 81 04 8a  ................
  0390  06 1a f8 10 05 03 00 00 00 00 00 00 00 00 00 00  ................
  03a0  00 00 58 c3 17 03 00 00 00 00 0a 00 00 0b f8 11  ..X.............
  03b0  05 03 00 00 00 00 02 00 00 00 00 00 00 00 58 c3  ..............X.
  03c0  17 03 00 00 00 00 0a 00 00 9d 06 f4 10 05 03 00  ................
  03d0  00 00 00 00 00 00 00 00 00 00 00 58 c3 17 03 00  ...........X....
  03e0  00 00 00 0a 00 00 09 f4 11 05 03 00 00 00 00 02  ................
  03f0  00 00 00 00 00 00 00 58 c3 17 03 00 00 00 00 0a  .......X........
  0400  00 c7 01 ee ff ff ff 0f e0 22 ff ff ff ff 0f e0  ........."......
  0410  22 fd 0b 1e 40 7b 1e 03 00 00 00 00 58 c3 17 03  "...@{......X...
  0420  00 00 00 00 00 00 00 00 02 00 00 00 60 11 00 00  ............`...
  0430  0a 00                                            ..
[2020-10-06 14:50:51.413641]: <debug> Memory dump:
  0000  d8 66 12 03 00 00 00 00 58 c3 17 03 00 00 00 00  .f......X.......
  0010  00 00 00 00 01 00 00 00 b4 1a 00 00 0a 00        ..............
[2020-10-06 14:50:51.413641]: <debug> Memory dump:
  0000  cc 30 06 03 00 00 00 00 00 00 00 00 00 00 00 00  .0..............
  0010  cc 30 06 03 00 00 00 00 34 00 00 00 00 00 00 00  .0......4.......
  0020  10 00 00 00 40 00 4e 00 65 00 77 00 4f 00 62 00  [email protected].
  0030  6a 00 65 00 63 00 74 00 00 00 0a 00              j.e.c.t.....
[2020-10-06 14:50:51.413641]: <debug> Memory dump:
  0000  00 31 06 03 00 00 00 00 00 00 00 00 00 00 00 00  .1..............
  0010  00 31 06 03 00 00 00 00 54 00 00 00 00 00 00 00  .1......T.......
  0020  10 00 00 00 40 00 4e 00 65 00 77 00 4f 00 62 00  [email protected].
  0030  6a 00 65 00 63 00 74 00 41 00 6c 00 69 00 67 00  j.e.c.t.A.l.i.g.
  0040  6e 00 38 00 00 00 0a 00                          n.8.....
[2020-10-06 14:50:51.413641]: <debug> Memory dump:
  0000  54 31 06 03 00 00 00 00 00 00 00 00 00 00 00 00  T1..............
  0010  54 31 06 03 00 00 00 00 74 00 00 00 00 00 00 00  T1......t.......
  0020  10 00 00 00 40 00 42 00 6f 00 78 00 00 00 0a 00  [email protected].....
[2020-10-06 14:50:51.413641]: <debug> Memory dump:
  0000  c8 31 06 03 00 00 00 00 00 00 00 00 00 00 00 00  .1..............
  0010  c8 31 06 03 00 00 00 00 4c 00 00 00 00 00 00 00  .1......L.......
  0020  10 00 00 00 40 00 4e 00 65 00 77 00 41 00 72 00  [email protected].
  0030  72 00 61 00 79 00 31 00 4f 00 62 00 6a 00 65 00  r.a.y.1.O.b.j.e.
  0040  63 00 74 00 00 00 0a 00                          c.t.....
[2020-10-06 14:50:51.414633]: <debug> Memory dump:
  0000  14 32 06 03 00 00 00 00 00 00 00 00 00 00 00 00  .2..............
  0010  14 32 06 03 00 00 00 00 5c 00 00 00 00 00 00 00  .2......\.......
  0020  10 00 00 00 40 00 4e 00 65 00 77 00 41 00 72 00  [email protected].
  0030  72 00 61 00 79 00 31 00 56 00 61 00 6c 00 75 00  r.a.y.1.V.a.l.u.
  0040  65 00 54 00 79 00 70 00 65 00 00 00 0a 00        e.T.y.p.e.....
[2020-10-06 14:50:51.414633]: <debug> Memory dump:
  0000  70 32 06 03 00 00 00 00 00 00 00 00 00 00 00 00  p2..............
  0010  70 32 06 03 00 00 00 00 78 00 00 00 00 00 00 00  p2......x.......
  0020  10 00 00 00 40 00 4e 00 65 00 77 00 41 00 72 00  [email protected].
  0030  72 00 61 00 79 00 31 00 4f 00 62 00 6a 00 65 00  r.a.y.1.O.b.j.e.
  0040  63 00 74 00 41 00 6c 00 69 00 67 00 6e 00 38 00  c.t.A.l.i.g.n.8.
  0050  00 00 0a 00                                      ....
[2020-10-06 14:50:51.414633]: <debug> Memory dump:
  0000  3c 33 06 03 00 00 00 00 00 00 00 00 00 00 00 00  <3..............
  0010  3c 33 06 03 00 00 00 00 28 00 00 00 00 00 00 00  <3......(.......
  0020  10 00 00 00 40 00 53 00 74 00 61 00 74 00 69 00  [email protected].
  0030  63 00 42 00 61 00 73 00 65 00 4f 00 62 00 6a 00  c.B.a.s.e.O.b.j.
  0040  65 00 63 00 74 00 00 00 0a 00                    e.c.t.....
[2020-10-06 14:50:51.414633]: <debug> Memory dump:
  0000  64 33 06 03 00 00 00 00 00 00 00 00 00 00 00 00  d3..............
  0010  64 33 06 03 00 00 00 00 24 00 00 00 00 00 00 00  d3......$.......
  0020  10 00 00 00 40 00 53 00 74 00 61 00 74 00 69 00  [email protected].
  0030  63 00 42 00 61 00 73 00 65 00 4e 00 6f 00 6e 00  c.B.a.s.e.N.o.n.
  0040  4f 00 62 00 6a 00 65 00 63 00 74 00 00 00 0a 00  O.b.j.e.c.t.....
[2020-10-06 14:50:51.414633]: <debug> Memory dump:
  0000  88 33 06 03 00 00 00 00 00 00 00 00 00 00 00 00  .3..............
  0010  88 33 06 03 00 00 00 00 14 00 00 00 00 00 00 00  .3..............
  0020  10 00 00 00 40 00 53 00 74 00 61 00 74 00 69 00  [email protected].
  0030  63 00 42 00 61 00 73 00 65 00 4f 00 62 00 6a 00  c.B.a.s.e.O.b.j.
  0040  65 00 63 00 74 00 4e 00 6f 00 43 00 43 00 74 00  e.c.t.N.o.C.C.t.
  0050  6f 00 72 00 00 00 0a 00                          o.r.....
[2020-10-06 14:50:51.415625]: <debug> Memory dump:
  0000  9c 33 06 03 00 00 00 00 00 00 00 00 00 00 00 00  .3..............
  0010  9c 33 06 03 00 00 00 00 10 00 00 00 00 00 00 00  .3..............
  0020  10 00 00 00 40 00 53 00 74 00 61 00 74 00 69 00  [email protected].
  0030  63 00 42 00 61 00 73 00 65 00 4e 00 6f 00 6e 00  c.B.a.s.e.N.o.n.
  0040  4f 00 62 00 6a 00 65 00 63 00 74 00 4e 00 6f 00  O.b.j.e.c.t.N.o.
  0050  43 00 43 00 74 00 6f 00 72 00 00 00 0a 00        C.C.t.o.r.....
[2020-10-06 14:50:51.415625]: <debug> Memory dump:
  0000  00 10 e5 03 00 00 00 00 00 f0 ff 00 00 00 00 00  ................
  0010  00 00 00 00 0a 00                                ......
[2020-10-06 14:50:51.415625]: <debug> Memory dump:
  0000  00 10 e5 04 00 00 00 00 00 f0 ff 00 00 00 00 00  ................
  0010  01 00 00 00 0a 00                                ......
[2020-10-06 14:50:51.415625]: <debug> Memory dump:
  0000  00 10 e5 05 00 00 00 00 00 f0 ff 00 00 00 00 00  ................
  0010  03 00 00 00 0a 00                                ......
[2020-10-06 14:50:51.415625]: <debug> Memory dump:
  0000  f8 10 05 03 00 00 00 00 00 00 00 00 00 00 00 00  ................
  0010  58 c3 17 03 00 00 00 00 0a 00                    X.........
[2020-10-06 14:50:51.415625]: <debug> Memory dump:
  0000  f8 11 05 03 00 00 00 00 02 00 00 00 00 00 00 00  ................
  0010  58 c3 17 03 00 00 00 00 0a 00                    X.........
[2020-10-06 14:50:51.415625]: <debug> Memory dump:
  0000  f4 10 05 03 00 00 00 00 00 00 00 00 00 00 00 00  ................
  0010  58 c3 17 03 00 00 00 00 0a 00                    X.........
[2020-10-06 14:50:51.415625]: <debug> Memory dump:
  0000  f4 11 05 03 00 00 00 00 02 00 00 00 00 00 00 00  ................
  0010  58 c3 17 03 00 00 00 00 0a 00                    X.........
[2020-10-06 14:50:51.415625]: <debug> Memory dump:
  0000  40 7b 1e 03 00 00 00 00 58 c3 17 03 00 00 00 00  @{......X.......
  0010  00 00 00 00 02 00 00 00 60 11 00 00 0a 00        ........`.....
[2020-10-06 14:50:51.415625]: <debug> provider is "Microsoft-Windows-DotNETRuntime", event id is 85, version is 0.
Event: AppDomainResourceManagement_ThreadCreated_85
    ManagedThreadID: 51537624
    AppDomainID: 51888984
    Flags: 0
    ManagedThreadIndex: 1
    OSThreadID: 6836
    ClrInstanceID: 10
No stack
[2020-10-06 14:50:51.415625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <error> Access to unparsed data
[2020-10-06 14:50:51.416625]: <debug> provider is "Microsoft-Windows-DotNETRuntime", event id is 5, version is 1.
Event: GC_GCCreateSegment_5
    Address: 65343488
    Size: 16773120
    Type: 0
    ClrInstanceID: 10
No stack
[2020-10-06 14:50:51.416625]: <debug> provider is "Microsoft-Windows-DotNETRuntime", event id is 5, version is 1.
Event: GC_GCCreateSegment_5
    Address: 82120704
    Size: 16773120
    Type: 1
    ClrInstanceID: 10
No stack
[2020-10-06 14:50:51.416625]: <debug> provider is "Microsoft-Windows-DotNETRuntime", event id is 5, version is 1.
Event: GC_GCCreateSegment_5
    Address: 98897920
    Size: 16773120
    Type: 3
    ClrInstanceID: 10
No stack
[2020-10-06 14:50:51.416625]: <debug> provider is "Microsoft-Windows-DotNETRuntime", event id is 30, version is 0.
Event: GC_SetGCHandle_30
    HandleID: 50663672
    ObjectID: 0
    Kind: 0
    Generation: 0
    AppDomainID: 51888984
    ClrInstanceID: 10
No stack
[2020-10-06 14:50:51.416625]: <debug> provider is "Microsoft-Windows-DotNETRuntime", event id is 30, version is 0.
Event: GC_SetGCHandle_30
    HandleID: 50663928
    ObjectID: 8589934592
    Kind: 2
    Generation: 0
    AppDomainID: 51888984
    ClrInstanceID: 10
No stack
[2020-10-06 14:50:51.416625]: <debug> provider is "Microsoft-Windows-DotNETRuntime", event id is 30, version is 0.
Event: GC_SetGCHandle_30
    HandleID: 50663668
    ObjectID: 0
    Kind: 0
    Generation: 0
    AppDomainID: 51888984
    ClrInstanceID: 10
No stack
[2020-10-06 14:50:51.416625]: <debug> provider is "Microsoft-Windows-DotNETRuntime", event id is 30, version is 0.
Event: GC_SetGCHandle_30
    HandleID: 50663924
    ObjectID: 8589934592
    Kind: 2
    Generation: 0
    AppDomainID: 51888984
    ClrInstanceID: 10
No stack
[2020-10-06 14:50:51.416625]: <debug> provider is "Microsoft-Windows-DotNETRuntime", event id is 85, version is 0.
Event: AppDomainResourceManagement_ThreadCreated_85
    ManagedThreadID: 52329280
    AppDomainID: 51888984
    Flags: 0
    ManagedThreadIndex: 2
    OSThreadID: 4448
    ClrInstanceID: 10
No stack
valco1994 picture valco1994 on 7 Oct 2020

@sywhang Is it possible that FireEtwMethodLoadVerbose_V1 generation was broken? I see this issue only on .NET 5 (RC 1), on previous versions all was working as expected.

valco1994 picture valco1994 on 7 Oct 2020

@valco1994 I wouldn't rule it out, but with the info we have so far it doesn't point to that being the culprit either, so we'd need more investigation with a repro. @josalem were you already looking at getting a repro of this issue? I'm happy to help as needed but if @josalem already has his hands on this, I will leave it to him to dig this further : )

sywhang picture sywhang on 7 Oct 2020

I think I've got a basic repro with a debug build of the runtime (Windows x86 Debug).

I added the following to the SampleProfiler meaning it should fire this event every millisecond:

            LPCWSTR helper = W("MyHelper");
            ETW::MethodLog::SendHelperEvent(0xDEADBEEF, 0x8, helper);

When I look at the trace in PerfView it sees that there are >3000 of the MethodLoad events (thetrace is ~3 seconds), but when I try to open them in the event viewer, the parser finds 0 events.

When I look at the trace in a hex editor, I see the following:
image
seemingly matching what @valco1994 saw. Let me run the target under a debugger and see if I can catch the behavior in action.

Edit 1:

I just double checked, and I'm seeing the same generated code that Sung posted above being generated for my build:

//
//Template from manifest : MethodLoadUnloadVerbose_V1
//
#ifndef McTemplateCoU0xxxqqqzzzh_def
#define McTemplateCoU0xxxqqqzzzh_def
ETW_INLINE
ULONG
McTemplateCoU0xxxqqqzzzh(
    _In_ PMCGEN_TRACE_CONTEXT Context,
    _In_ PCEVENT_DESCRIPTOR Descriptor,
    _In_ const unsigned __int64  _Arg0,
    _In_ const unsigned __int64  _Arg1,
    _In_ const unsigned __int64  _Arg2,
    _In_ const unsigned int  _Arg3,
    _In_ const unsigned int  _Arg4,
    _In_ const unsigned int  _Arg5,
    _In_opt_ PCWSTR  _Arg6,
    _In_opt_ PCWSTR  _Arg7,
    _In_opt_ PCWSTR  _Arg8,
    _In_ const unsigned short  _Arg9
    )
{
#define McTemplateCoU0xxxqqqzzzh_ARGCOUNT 10
    ULONG Error = 0;

    EVENT_DATA_DESCRIPTOR EventData[McTemplateCoU0xxxqqqzzzh_ARGCOUNT + 1];

    EventDataDescCreate(&EventData[1],&_Arg0, sizeof(const unsigned __int64)  );

    EventDataDescCreate(&EventData[2],&_Arg1, sizeof(const unsigned __int64)  );

    EventDataDescCreate(&EventData[3],&_Arg2, sizeof(const unsigned __int64)  );

    EventDataDescCreate(&EventData[4],&_Arg3, sizeof(const unsigned int)  );

    EventDataDescCreate(&EventData[5],&_Arg4, sizeof(const unsigned int)  );

    EventDataDescCreate(&EventData[6],&_Arg5, sizeof(const unsigned int)  );

    EventDataDescCreate(&EventData[7],
                        (_Arg6 != NULL) ? _Arg6 : L"NULL",
                        (_Arg6 != NULL) ? (ULONG)((wcslen(_Arg6) + 1) * sizeof(WCHAR)) : (ULONG)sizeof(L"NULL"));

    EventDataDescCreate(&EventData[8],
                        (_Arg7 != NULL) ? _Arg7 : L"NULL",
                        (_Arg7 != NULL) ? (ULONG)((wcslen(_Arg7) + 1) * sizeof(WCHAR)) : (ULONG)sizeof(L"NULL"));

    EventDataDescCreate(&EventData[9],
                        (_Arg8 != NULL) ? _Arg8 : L"NULL",
                        (_Arg8 != NULL) ? (ULONG)((wcslen(_Arg8) + 1) * sizeof(WCHAR)) : (ULONG)sizeof(L"NULL"));

    EventDataDescCreate(&EventData[10],&_Arg9, sizeof(const unsigned short)  );

    Error = McGenEventWrite(Context, Descriptor, NULL, McTemplateCoU0xxxqqqzzzh_ARGCOUNT + 1, EventData);

#ifdef MCGEN_CALLOUT
MCGEN_CALLOUT(Context->RegistrationHandle,
              Descriptor,
              McTemplateCoU0xxxqqqzzzh_ARGCOUNT,
              &EventData[1]);
#endif // MCGEN_CALLOUT

    return Error;
}
#endif // McTemplateCoU0xxxqqqzzzh_def
josalem picture josalem on 7 Oct 2020

I just realized the code Sung and I were looking at isn't the code that would generate this event when it is fired over EventPipe. That is instead this code:

ULONG EventPipeWriteEventMethodLoadVerbose_V1(
    const unsigned __int64 MethodID,
    const unsigned __int64 ModuleID,
    const unsigned __int64 MethodStartAddress,
    const unsigned int MethodSize,
    const unsigned int MethodToken,
    const unsigned int MethodFlags,
    PCWSTR MethodNamespace,
    PCWSTR MethodName,
    PCWSTR MethodSignature,
    const unsigned short ClrInstanceID,
    LPCGUID ActivityId,
    LPCGUID RelatedActivityId)
{
    if (!EventPipeEventEnabledMethodLoadVerbose_V1())
        return ERROR_SUCCESS;

    char stackBuffer[230];
    char *buffer = stackBuffer;
    size_t offset = 0;
    size_t size = 230;
    bool fixedBuffer = true;

    bool success = true;
    success &= WriteToBuffer(MethodID, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(ModuleID, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodStartAddress, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodSize, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodToken, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodFlags, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodNamespace, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodName, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(MethodSignature, buffer, offset, size, fixedBuffer);
    success &= WriteToBuffer(ClrInstanceID, buffer, offset, size, fixedBuffer);

    if (!success)
    {
        if (!fixedBuffer)
            delete[] buffer;
        return ERROR_WRITE_FAULT;
    }

    EventPipe::WriteEvent(*EventPipeEventMethodLoadVerbose_V1, (BYTE *)buffer, (unsigned int)offset, ActivityId, RelatedActivityId);

    if (!fixedBuffer)
        delete[] buffer;

    return ERROR_SUCCESS;
}

Where calls to WriteToBuffer with a NULL string simply return true:

bool WriteToBuffer(PCWSTR str, char *&buffer, size_t& offset, size_t& size, bool &fixedBuffer)
{
    if(!str) return true;
    size_t byteCount = (wcslen(str) + 1) * sizeof(*str);

    if (offset + byteCount > size)
    {
        if (!ResizeBuffer(buffer, size, offset, size + byteCount, fixedBuffer))
            return false;
    }

    memcpy(buffer + offset, str, byteCount);
    offset += byteCount;
    return true;
}

Based on that, the event output we are seeing in EventPipe is "by design", but that doesn't match the manifest. I think this should have been happening in previous versions as well since I don't think this code has changed in a while. Let me go double check the git blame to be sure though.

josalem picture josalem on 7 Oct 2020
👍2

Good catch @josalem. I forgot this was on EventPipe, not ETW. That does seem like an issue on EventPipe side that doesn't match the behavior of ETW. At the very least we should try to match the behavior on ETW so that the payloads don't differ based on the egression mechanism.

sywhang picture sywhang on 8 Oct 2020

At the very least we should try to match the behavior on ETW so that the payloads don't differ based on the egression mechanism.

Agreed. If the desired behavior is simply NULL string values become "NULL" strings, then the change should be simple enough inside WriteToBuffer without having to change the code gen scripts.

josalem picture josalem on 8 Oct 2020
Was this page helpful?
0 / 5 - 0 ratings

Related issues

btecu picture btecu  路  3Comments
aggieben picture aggieben  路  3Comments
sahithreddyk picture sahithreddyk  路  3Comments
noahfalk picture noahfalk  路  3Comments
omajid picture omajid  路  3Comments