windowsdelphiwinapietw

Event Tracing for Windows: OpenTrace/ProcessTrace not returning any events - callback not being called

Short Version

I'm trying to use OpenTrace and ProcessTrace to read the events of a .etl file.

I know it's a valid .etl file, because i can open it in:

Long Version

Microsoft provides sample code on reading the events of a .etl file. The basic gist is:

  1. Initialize an EVENT_TRACE_LOGFILE structure with the filename we want to open, and the address of our callback function. The callback function is called once for every event in the file:

    var 
  filename: UnicodeString;
  trace: EVENT_TRACE_LOGFILEW;

filename := 'C:\test.etl';

//Initialize trace with filename and callback
ZeroMemory(@trace, sizeof(trace));
trace.LogFileName := PWideChar(filename);
trace.EventCallback := ProcessTraceEventCallback; //called once for each event in the file

  2. Call OpenTrace to open the specified .etl file, and get a TRACEHANDLE of the session:

    //Open the trace
var
  hTrace: TRACEHANDLE;

hTrace := OpenTraceW(trace);
if (hTrace = INVALID_PROCESSTRACE_HANDLE) then
  RaiseLastOSError;

  3. Call ProcessTrace to start reading events from the file. Our callback will be called once for each event in the file, and ProcessTrace will not return until all events have been read:

    var
   res: Cardinal;

res := ProcessTrace(@hTrace, 1, nil, nil);
if (res <> ERROR_SUCCESS) then
   RaiseLastOSError;

And that should be it, except the callback is never called:

procedure ProcessTraceEventCallback(pEvent: PEVENT_TRACE); stdcall;
begin
   //TODO: read the event information out of pEvent
   //pEvent.MofData ==> raw payload information
   //pEvent.MofLength ==> raw payload length (bytes)
   WriteLn('Got an event');
   Winapi.Windows.DebugBreak;
end;

None of the code returns an error.

My sample code, and the CRME below, all force the use of W Unicode version of the functions (just to eliminate that as a confusion). I'm sure there's something wrong with my header translations, record packing, alignment, or calling conventions - but i can't find anything.

Complete Reproducible Minimal Example

I know it doesn't seem minimal. But we need all the API functions and structures.

You will need your own C:\test.etl file. You can create one using Windows Performance Recorder, or search your PC for .etl files - Windows and Microsoft create a lot of them scattered everywhere.

program Project4;

{$APPTYPE CONSOLE}
{$ALIGN 8} //Windows ABI

{$R *.res}

uses
  System.SysUtils,
  Winapi.Windows;

type
    EVENT_TRACE_HEADER = packed record
        Size: Word;                         // Size of entire record
        FieldTypeFlags: Word;           // Reserved
        EventType: Byte;                    //Type of event. A provider can define their own event types or use the predefined event types (Info, Start,Stop, Suspend, Checkpoint, Resume, etc.)
        EventLevel: Byte;                   //Provider-defined value that defines the severity level used to generate the event. Verbose, Information, Warning, Error, Critical, etc
        EventVersion: Word;             //Which version of MOF class to use to decipher the event data. Specify zero if there is only one version of your event trace class.
        ThreadId: LongWord;                 //On output, identifies the thread that generated the event.
        ProcessId: LongWord;                //On output, identifies the process that generated the event.
        TimeStamp: Int64;                   //The time that the event occurred. On output, contains the time that the event occurred.
        Guid: TGUID;                        //Guid that identifies event. Event trace class GUID. You can use the class GUID to identify a category of events and the Class.Type member to identify an event within the category of events.
        ClientContext: LongWord;        //Reserved
        Flags: LongWord;              //
    end;
    PEVENT_TRACE_HEADER = ^EVENT_TRACE_HEADER;

  EVENT_TRACE = packed record
     Header: EVENT_TRACE_HEADER;    // Event trace header
     InstanceId: Cardinal;          // Instance identifier. Contains valid data when the provider calls the TraceEventInstance function to generate the event. Otherwise, the value is zero.
     ParentInstanceId: Cardinal;    // Instance identifier for a parent event. Contains valid data when the provider calls the TraceEventInstance function to generate the event. Otherwise, the value is zero.
     ParentGuid: TGUID;             // Class GUID of the parent event. Contains valid data when the provider calls the TraceEventInstance function to generate the event. Otherwise, the value is zero.
     MofData: Pointer;              // Pointer to the beginning of the event-specific data for this event.
     MofLength: Cardinal;           // Number of bytes to which MofData points.
     BufferContext: Cardinal;       // Provides information about the event such as the session identifier and processor number of the CPU on which the provider process ran.
  end;
  PEVENT_TRACE = ^EVENT_TRACE;

  TRACE_LOGFILE_HEADER = record
        BufferSize: LongWord;
        MajorVersion: Byte;
        MinorVersion: Byte;
        SubVersion: Byte;
        SubMinorVersion: Byte;

        ProviderVersion: LongWord;    // defaults to NT version
        NumberOfProcessors: LongWord; // Number of Processors
        EndTime: LARGE_INTEGER;       // Time when logger stops
        TimerResolution: LongWord;
        MaximumFileSize: LongWord;    // Maximum in Mbytes
        LogFileMode: LongWord;        // specify logfile mode
        BuffersWritten: LongWord;     // used to file start of Circular File
        StartBuffers: Cardinal;         // Reserved
        PointerSize: Cardinal;          // Size of a Pointer data type, in bytes.
        EventsLost: Cardinal;           // Number of events lost during the event tracing session. Events may be lost due to insufficient memory or a very high rate of incoming events.
        CpuSpeedInMHz: Cardinal;        // CPU speed, in megahertz.
        LoggerName: PWideChar;          // Do not use.
        LogFileName: PWideChar;         // Do not use
        TimeZone: TIME_ZONE_INFORMATION;    // A TIME_ZONE_INFORMATION structure that contains the time zone for the BootTime, EndTime and StartTime members.
        BootTime: Int64;                    // Time at which the system was started, in 100-nanosecond intervals since midnight, January 1, 1601. BootTime is supported only for traces written to the Global Logger session.
        PerfFreq: Int64;                    // Frequency of the high-resolution performance counter, if one exists.
        StartTime: Int64;                   // Time at which the event tracing session started, in 100-nanosecond intervals since midnight, January 1, 1601.
        ReservedFlags: Cardinal;
        BuffersLost: Cardinal;          // Total number of buffers lost during the event tracing session.
    end;
    PTRACE_LOGFILE_HEADER = ^TRACE_LOGFILE_HEADER;

    PEVENT_TRACE_LOGFILEW = ^EVENT_TRACE_LOGFILEW; //forward

    EVENT_TRACE_BUFFER_CALLBACKW = function (Logfile : PEVENT_TRACE_LOGFILEW) : Cardinal; stdcall;
    PEVENT_TRACE_BUFFER_CALLBACKW = EVENT_TRACE_BUFFER_CALLBACKW;

    //Legacy EventCallback callback
    EVENT_CALLBACK = procedure (pEvent: PEVENT_TRACE); stdcall;
    PEVENT_CALLBACK = EVENT_CALLBACK;

    //Newer EventCallback if ProcessTraceMode of PROCESS_TRACE_MODE_EVENT_RECORD is specified
//  EVENT_RECORD_CALLBACK = procedure (EventRecord: PEVENT_RECORD); stdcall;
//  PEVENT_RECORD_CALLBACK = EVENT_RECORD_CALLBACK;

    EVENT_TRACE_LOGFILEW = packed record
        LogFileName: PWideChar;                 // Logfile Name
        LoggerName: PWideChar;                  // LoggerName
        CurrentTime: Int64;                     // timestamp of last event
        BuffersRead: Cardinal;                  // buffers read to date
        ProcessTraceMode: Cardinal;
        CurrentEvent: EVENT_TRACE;              // Current Event from this stream. (84 bytes)
        LogfileHeader: TRACE_LOGFILE_HEADER;            // logfile header structure (272 bytes)
        BufferCallback: PEVENT_TRACE_BUFFER_CALLBACKW;  // callback before each buffer is read

        // following variables are filled for BufferCallback.
        BufferSize: Cardinal;       //On output, contains the size of each buffer, in bytes
        Filled: Cardinal;               //On output, contains the number of bytes in the buffer that contain valid information
        EventsLost: Cardinal;       //Not used

        // following needs to be propaged to each buffer
        EventCallback: PEVENT_CALLBACK; //or EventRecordCallback: PEvent_Record_Callback if flag is on
        IsKernelTrace: Cardinal;    // TRUE for kernel logfile
        Context: Pointer;          // reserved for internal use
    end;

    TRACEHANDLE  = UInt64;
    PTRACEHANDLE = ^TRACEHANDLE;

function OpenTraceW(var Logfile : EVENT_TRACE_LOGFILEW): Cardinal; stdcall; external advapi32 name 'OpenTraceW';
function ProcessTrace(HandleArray: PTRACEHANDLE; HandleCount: Cardinal; StartTime: PFileTime; EndTime: PFileTime): Cardinal; stdcall; external advapi32 name 'ProcessTrace';
function CloseTrace(ATraceHandle: TRACEHANDLE): Cardinal; stdcall; external advapi32 name 'CloseTrace';

const
    INVALID_PROCESSTRACE_HANDLE: TRACEHANDLE = INVALID_HANDLE_VALUE; //i.e. TRACEHANDLE($00000000FFFFFFFF);

procedure ProcessTraceEventCallback(pEvent: PEVENT_TRACE); stdcall;
begin
{
    Our callback, called once for each event in the file
}
    WriteLn('Got an event');
    Winapi.Windows.DebugBreak;
end;

function BufferCallback(logFile: PEVENT_TRACE_LOGFILEW): LongWord; stdcall;
begin
    WriteLn('Finished processing a buffer-full of events. Buffercallback says '+IntToStr(logfile.EventsLost)+' events lost');

    Result := 1; // Return TRUE to continue processing more events. Otherwise FALSE
end;

procedure Main;
var
    trace: EVENT_TRACE_LOGFILEW;
    th: TRACEHANDLE;
    filename: UnicodeString;
    res: Cardinal;
begin
    filename := 'C:\test.etl';
    WriteLn('Filename: '+filename);

    {
      Example code of how to read from a .etl file:

      Using TdhFormatProperty to Consume Event Data
      https://learn.microsoft.com/en-us/windows/win32/etw/using-tdhformatproperty-to-consume-event-data
    }

    //Initialize EVENT_TRACE_LOGFILE with filename to open, and our callback function
    WriteLn('Initializing EVENT_TRACE_LOGFILE');
    ZeroMemory(@trace, sizeof(trace)); // 408 bytes
    trace.LogFileName := PWideChar(filename);
    trace.EventCallback := ProcessTraceEventCallback; //called once for each event in the file
//  trace.ProcessTraceMode := PROCESS_TRACE_MODE_EVENT_RECORD; //we wanted new style events through the "EventRecordCallback"
//  trace.BufferCallback := BufferCallback; //optional callback for inforamtion after processing a buffer-full of events

    WriteLn('Opening trace file "'+filename+'"');
    th := OpenTraceW(trace);
    if (th = INVALID_PROCESSTRACE_HANDLE) or (th = -1) then
    begin
        WriteLn('Error opening trace file: '+SysErrorMessage(GetLastError));
        Exit;
    end;
    WriteLn('Successfully opened trace session. TraceHandle: 0x'+IntToHex(th, 8));

    WriteLn('Processing trace file');
    res := ProcessTrace(@th, 1, nil, nil);
    if (res <> ERROR_SUCCESS) then // and (hr <> ERROR_CANCELLED) then
        RaiseLastOSError;
    WriteLn('Successfully processed trace file');

    WriteLn('Closing trace handle');
    CloseTrace(th);

    WriteLn('Finished processing '+filename);
end;

begin
  try
        Main;
        WriteLn('Execution complete. Press enter to close...');
        ReadLn;
  except
    on E: Exception do
        Writeln(E.ClassName, ': ', E.Message);
  end;
end.

And my output is:

Filename: C:\test.etl
Initializing EVENT_TRACE_LOGFILE
Opening trace file "C:\test.etl"
Successfully opened trace session. TraceHandle: 0x00000041
Processing trace file
Successfully processed trace file
Closing trace handle
Finished processing C:\test.etl
Execution complete. Press enter to close...

Can anyone see what i'm doing wrong?

Solution

  • The answer is exactly what I knew it would be.

    When that didn't work, i asked Stackoverflow.

    In the meantime, i spun up Visual Studio C++, and compared the sizeof of the original structures, and the Delphi translations.

    They didn't match.

    The problem was the packed records.

    Removing the record packing fixed it.