Windows ETW: StartTrace failing with error 87 (ERROR_INVALID_PARAMETER)

https://stackoverflow.com/questions/9049971

03-12-2019
|

Question

i'm calling the Event Tracing for Windows StartTrace function:

StartTrace(sessionHandle, KERNEL_LOGGER_NAME, sessionProperties);

It is failing with error code 87 (ERROR_INVALID_PARAMETER). The MSDN gives some common causes for this error:

Properties is NULL.
SessionHandle is NULL.
The LogFileNameOffset member of Properties is not valid.
The LoggerNameOffset member of Properties is not valid.
The LogFileMode member of Properties specifies a combination of flags that is not valid.
The Wnode.Guid member is SystemTraceControlGuid, but the SessionName parameter is not KERNEL_LOGGER_NAME.

The code i'm calling is:

procedure StartKernelLogging;
var
    sessionProperties: PEVENT_TRACE_PROPERTIES;
    bufferSize: Int64;
    loggerName: AnsiString;
    logFilePath: AnsiString;
    th: TRACEHANDLE;
    hr: Cardinal;
begin
    {
        Allocate memory for the session properties. The memory must
        be large enough to include the log file name and session name,
        which get appended to the end of the session properties structure.
    }
    loggerName := KERNEL_LOGGER_NAME;
    logFilePath := 'C:\Users\Ian\foo.etl';

    bufferSize := sizeof(EVENT_TRACE_PROPERTIES)
            + Length(loggerName)+1
            + Length(logFilePath)+1;

    sessionProperties := AllocMem(bufferSize);

    ZeroMemory(sessionProperties, bufferSize);

    sessionProperties.Wnode.BufferSize := bufferSize;
    sessionProperties.Wnode.Flags := WNODE_FLAG_TRACED_GUID;
    sessionProperties.Wnode.ClientContext := 1; //QPC clock resolution
    sessionProperties.Wnode.Guid := SystemTraceControlGuid;
    sessionProperties.EnableFlags := EVENT_TRACE_FLAG_NETWORK_TCPIP;
    sessionProperties.LogFileMode := EVENT_TRACE_FILE_MODE_CIRCULAR;
    sessionProperties.MaximumFileSize := 5;  // 5 MB
    sessionProperties.LoggerNameOffset := sizeof(EVENT_TRACE_PROPERTIES);
    sessionProperties.LogFileNameOffset := sizeof(EVENT_TRACE_PROPERTIES) + Length(loggerName)+1;

    //Copy LoggerName to the offset address
    MoveMemory(Pointer(Cardinal(sessionProperties)+Cardinal(sessionProperties.LoggerNameOffset)), PAnsiChar(loggerName), Length(loggerName)+1);

    //Copy LogFilePath to the offset address
    MoveMemory(Pointer(Cardinal(sessionProperties)+Cardinal(sessionProperties.LogFileNameOffset)), PAnsiChar(logFilePath), Length(logFilePath)+1);

    th := 0;
    hr := EventTrace.StartTrace({var}th, PChar(loggerName), sessionProperties);
    if (hr <> ERROR_SUCCESS) then
    begin
        raise EWin32Error.Create(SysErrorMessage(hr));
    end;
end;

The language agnostic version of my call:

ADVAPI32.StartTraceA(
     TraceHandle: 0x18F56C
     InstanceName: 0x44E840
     Properties: 0x243BD8);

where TraceHandle points to a a 64-bit integer:

0018F56C: 00 00 00 00  00 00 00 00

and InstanceName is a pointer to a null-terminated ansi string:

0044E840: 4E 54 20 4B  65 72 6E 65  NT Kerne
0044E848: 6C 20 4C 6F  67 67 65 72  l Logger
0044E850: 00

and Properties is a pointer to an EVENT_TRACE_PROPERTIES structure, which i'll refrain from reproducing a complete hex dump

002A3BD8: 0000009A (154 bytes)

The important values are the two offsets:

properties.LoggerNameOffset = 116  (i.e. $243BB8 + 116 = $243C4C)
properties.LogFileNameOffset = 133 (i.e. $243BD8 + 133 = $243C5D)

which also contain the valid null-terminated ansi strings they are supposed to:

"NT Kernel Logger":

$243C4C  4B20544E 656E7265  NT Kerne
$243C54  6F4C206C 72656767  l Logger
$243C5C  xxxxxx00           .

"C:\Users\Ian\foo.etl":

$243C5C  5C3A43xx 72657355  .C:\User
$243C64  61495C73 6F665C6E  s\Ian\fo
$243C6C  74652E6F xxxx006C  o.etc.

Why are my parameters incorrect?

Bonus Reading

Update:

The session parameters:

9A 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00
AD 4A 81 9E 04 32 D2 11
9A 82 00 60 08 A8 69 39
01 00 00 00 00 00 02 00
00 00 00 00 00 00 00 00
00 00 00 00 05 00 00 00
02 00 00 00 00 00 00 00
00 00 01 00 00 00 00 00
00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00
00 00 00 00 00 00 00 00
00 00 00 00 85 00 00 00
74 00 00 00

Which breaks down to:

000| Wnode.BufferSize:          9A 00 00 00 (154)
004| Wnode.ProviderID:          00 00 00 00
008| Wnode.Version:             00 00 00 00
012| Wnode.Linkage:             00 00 00 00
016| Wnode.Timestamp:           00 00 00 00 00 00 00 00
024| Wnode.Guid:                AD 4A 81 9E 04 32 D2 11 9A 82 00 60 08 A8 69 39 (SystemTraceControlGuid)
040| Wnode.ClientContext:       01 00 00 00 (1)
044| Wnode.Flags:               00 00 02 00 (WNODE_FLAG_TRACED_GUID)
048| BufferSize:          00 00 00 00 
052| MinimumBuffers:      00 00 00 00
056| MaximumBuffers:      00 00 00 00 
060| MaximumFileSize:     05 00 00 00 (5 MB)
064| LogFileMode:         02 00 00 00 (EVENT_TRACE_FILE_MODE_CIRCULAR)
068| FlushTimer:          00 00 00 00
072| EnableFlags:         00 00 01 00 (EVENT_TRACE_FLAG_NETWORK_TCPIP)
076| AgeLimit:            00 00 00 00
080| NumberOfBuffers:     00 00 00 00 
084| FreeBuffers:         00 00 00 00
088| EventsLost:          00 00 00 00 
092| BuffersWritten:      00 00 00 00
096| LogBuffersLost:      00 00 00 00 
100| RealTimeBuffersLost: 00 00 00 00
104| LoggerThreadId:      00 00 00 00 
108| LogFileNameOffset:   85 00 00 00 (133)
112| LoggerNameOffset:    74 00 00 00 (116)
116| NT Kernel Logger\0
133| C:\Users\Ian\foo.etl\0
154|

If there's an alignment problem i won't be able to discover it alone.

The structure:

EVENT_TRACE_PROPERTIES = packed record
   Wnode : WNODE_HEADER;

   // data provided by caller
   BufferSize : Longword;              // buffer size for logging (kbytes)
   MinimumBuffers : Longword;          // minimum to preallocate
   MaximumBuffers : Longword;          // maximum buffers allowed
   MaximumFileSize : Longword;         // maximum logfile size (in MBytes)
   LogFileMode : Longword;             // sequential, circular
   FlushTimer : Longword;              // buffer flush timer, in seconds
   EnableFlags :Longword;              // trace enable flags
   AgeLimit : Longint;                // age decay time, in minutes

   // data returned to caller
   NumberOfBuffers : Longword;         // no of buffers in use
   FreeBuffers : Longword;             // no of buffers free
   EventsLost : Longword;              // event records lost
   BuffersWritten : Longword;          // no of buffers written to file
   LogBuffersLost : Longword;          // no of logfile write failures
   RealTimeBuffersLost : Longword;     // no of rt delivery failures
   LoggerThreadId : HANDLE;            // thread id of Logger
   LogFileNameOffset : Longword;        // Offset to LogFileName
   LoggerNameOffset : Longword;         // Offset to LoggerName
end;

along with:

WNODE_HEADER = packed record
   BufferSize : Longword;
   ProviderId : Longword;
   Version : Longword;
   Linkage : Longword;
   TimeStamp : Int64;
   Guid : TGUID;
   ClientContext : Longword;
   Flags : Longword;
end;

Solution

Oh i see what the comments from Luke's comments are saying.

It's not that the structure is misaligned is any way. The content after the structure must be 8-byte aligned. In other words:

000| Wnode.BufferSize:          9A 00 00 00 (154)
004| Wnode.ProviderID:          00 00 00 00
     ...snip...
108| LogFileNameOffset:   85 00 00 00 (133)
112| LoggerNameOffset:    74 00 00 00 (116)
116| 00 00 00 00 (4 bytes padding)
120| NT Kernel Logger\0
136| 00 00 00 00 00 00 00 (7 bytes padding)
144| C:\Users\Ian\foo.etl\0

Looks like data needs to be aligned on 8-byte boundries in Windows (7 (Professional (64-bit)))

To help the padding, i wrote a Pad function, which rounds a number up to the nearest multiple of 8:

function Pad(length: Cardinal): Cardinal;
var
    m: Integer;
const
    DataAlignment = 8; //align data on 8-byte boundaries
begin
    Result := length;

    m := length mod DataAlignment;
    if (m > 0) then
        Result := result + DataAlignment-m;
end;

Then i changed some of the code from the original question to use it.

calculate the total buffserSize required:

loggerName := KERNEL_LOGGER_NAME;
logFilePath := 'C:\Users\Ian\foo.etl';

bufferSize := sizeof(EVENT_TRACE_PROPERTIES)
        + Pad(Length(loggerName)+1)
        + Pad(Length(logFilePath)+1);

then i need to push my offsets on an 8-byte boundary:

sessionProperties.LoggerNameOffset := Pad(sizeof(EVENT_TRACE_PROPERTIES));
sessionProperties.LogFileNameOffset := Pad(sizeof(EVENT_TRACE_PROPERTIES)) + Pad(Length(loggerName)+1);

and as long as i copy the strings to the offsets declared in the structure i'm fine:

//Copy LoggerName to the offset address
MoveMemory(
      Pointer(Cardinal(sessionProperties)+sessionProperties.LoggerNameOffset),
      PAnsiChar(loggerName), Length(loggerName)+1);

//Copy LogFilePath to the offset address
MoveMemory(
      Pointer(Cardinal(sessionProperties)+sessionProperties.LogFileNameOffset),
      PAnsiChar(logFilePath), Length(logFilePath)+1);

And blingo-blango, it works.

Note: Any code is released into the public domain. No attribution required.

OTHER TIPS

Not an answer, but something interesting I found: If you replace the line:

hr := EventTrace.StartTrace({var}th, PChar(loggerName), sessionProperties);

with

hr := EventTrace.StartTrace({var}th, KERNEL_LOGGER_NAME, sessionProperties);

then the error code becomes ERROR_BAD_LENGTH (24). I think I'm using a different set of units for the trace APIs, and in my case, StartTrace wants a PWideChar, but loggerName is an AnsiString. Since I don't know your EventTrace unit looks like, it's hard to say if this is also the case for you or not though. And regardless, it does not make the StartTrace() call succeed.

Licensed under: CC-BY-SA with attribution

Not affiliated with StackOverflow