WPP - Concatenate trace macro parameter with trace format string, in the preprocessor

NTDEV
1

hello.
i have the following macro, which i use to log function failures (both API and in-project functions):

#define WPP_LEVEL_FLAGS_FUNCTION_STATUS_LOGGER(lvl, flags, FUNCTION_NAME, STATUS)       WPP_LEVEL_LOGGER(flags)
#define WPP_LEVEL_FLAGS_FUNCTION_STATUS_ENABLED(lvl, flags, FUNCTION_NAME, STATUS)      (WPP_LEVEL_ENABLED(flags) && WPP_CONTROL(WPP_BIT_ ## flags).Level >= lvl)
 
// USEPREFIX (LogFuncFailNtStatus, "%!STDPREFIX!");
// FUNC LogFuncFailNtStatus{LEVEL=TRACE_LEVEL_ERROR, FLAGS=TRACE_GENERIC}(FUNCTION_NAME, STATUS);
// USESUFFIX (LogFuncFailNtStatus, "%s failed with %!STATUS!", FUNCTION_NAME, STATUS);

So i can do things like:

NTSTATUS status=ZwProtectVirtualMemory(...);
if(!NT_SUCCESS(status))
{
    LogFuncFailNtStatus("ZwProtectVirtualMemory", status);
    return status;
}

The macro works, the result is as expected.
My only problem is, that all the function names, that are passed as argument to the LogFuncFailNtStatus macro appear in the binary, taking up space, while i believe they could be compiled into the string literal from which the GUID is generated, so i can avoid clogging up the binary with a lot of strings.

I searched around the (rather vague) WPP documentation and also other examples and tutorials, but could not find any way to do that, since as it seems, the wpp pre-processor does not know to automatically concatenate string literals?
What i tried:
// USESUFFIX (LogFuncFailNtStatus, "" FUNCTION_NAME " failed with %!STATUS!", STATUS);
I was hoping, that i can concatenate constant string literals just like in C.

thank you

2

No, the WPP pre-processor is not integrated with the C pre-processor. There are many pre-processor tricks that can’t be used, because of the way and the point in the process that WPP gets involved.

However, the compiler is smart enough to pool literals, so if you have 20 calls to ZwProtectVirtualMemory, that string should only appear once.

3

WPP has a solution for this. The MSG string itself doesn’t appear in the binary. Nor does the prefix or suffix.

So in your example, here’s where the strings go:

  • Into the .PDB file: “%s failed with %!STATUS!”; “%!STDPREFIX!”
  • Into the .SYS file: “ZwProtectVirtualMemory”

Since the %s insert is a constant, you can orchestrate things so that the function name is the MSG, so it can be extracted into the PDB. In other words, you only need to use %s when the string is not known at compile-time. If the string is known at compile-time, just bake it into the trace message.

Try defining the trace like this:

// FUNC LogFuncFailNtStatus{LEVEL=TRACE_LEVEL_ERROR, FLAGS=TRACE_GENERIC}(MSG, STATUS);
// USESUFFIX (LogFuncFailNtStatus, ": failed with %!STATUS!", STATUS);

Then you can use it in the same way. Under the hood, the MSG will be “ZwProtectVirtualMemory”, and it’ll get a suffix of “: failed with %!STATUS!”. If you look into the TMF file, you should see “ZwProtectVirtualMemory” getting putting into the trace message itself. If you look into the TMH file, you should not see “ZwProtectVirtualMemory” getting emitted at runtime. You can even check by running strings.exe on the compiled .SYS file to verify that your trace messages aren’t shipping in any way. (Although keep in mind that if you link against a function named ZwProtectVirtualMemory, then you will have a string in your PE’s import table for that. So strings.exe will always find at least one copy of that string. Try adding more words to the trace message to make it distinctive.)

4

Thank you for your response.
For some reason, it still does not work as expected.

I defined the macro as follows:

#define WPP_LEVEL_FLAGS_LOGGER(lvl,flags) WPP_LEVEL_LOGGER(flags)
#define WPP_LEVEL_FLAGS_ENABLED(lvl,flags) (WPP_LEVEL_ENABLED(flags) && WPP_CONTROL(WPP_BIT_ ## flags).Level  >= lvl)

#define WPP_LEVEL_FLAGS_TIMESTAMP_LOGGER(lvl, flags, tmpstamp) WPP_LEVEL_LOGGER(flags)
#define WPP_LEVEL_FLAGS_TIMESTAMP_ENABLED(lvl, flags, tmpstamp) WPP_LEVEL_FLAGS_ENABLED(lvl, flags)

#define WPP_LEVEL_FLAGS_FUNCTION_NAME_STATUS_LOGGER(lvl, flags, FUNCTION_NAME, STATUS)       WPP_LEVEL_LOGGER(flags)
#define WPP_LEVEL_FLAGS_FUNCTION_NAME_STATUS_ENABLED(lvl, flags, FUNCTION_NAME, STATUS)      (WPP_LEVEL_ENABLED(flags) && WPP_CONTROL(WPP_BIT_ ## flags).Level >= lvl)

// FUNC LogFuncFail{LEVEL=TRACE_LEVEL_ERROR, FLAGS=TRACE_FLAG_CUSTOM}(FUNCTION_NAME, STATUS);
// USESUFFIX (LogFuncFail, " failed with %!STATUS!", STATUS);

In the generated tmf file, the function name appears correctly for these lines:

LogFuncFail("FailFunction", STATUS_UNSUCCESSFUL);
LogFuncFail("FailFunction", STATUS_SUCCESS);

The lines in the tmf file:

#typev sample_c10 63 "%0 failed with %10!s!" //   LEVEL=TRACE_LEVEL_ERROR FLAGS=TRACE_FLAG_CUSTOM FUNCTION_NAME='FailFunction' STATUS=STATUS_SUCCESS FUNC=TestFunc
{
STATUS, ItemNTSTATUS -- 10
}
#typev sample_c11 62 "%0 failed with %10!s!" //   LEVEL=TRACE_LEVEL_ERROR FLAGS=TRACE_FLAG_CUSTOM FUNCTION_NAME='FailFunction' STATUS=STATUS_UNSUCCESSFUL FUNC=TestFunc
{
STATUS, ItemNTSTATUS -- 10
}

While the WinDbg log output is the following:

"[0]0E80.09CC::[sample]:TestFunc::sample_c10" failed with 0xc0000001(STATUS_UNSUCCESSFUL)
"[0]0E80.09CC::[sample]:TestFunc::sample_c11" failed with STATUS_SUCCESS

By the way, this is my environment variable prefix format string (but i beleive the prefix format should not affect the actual message format?):
TRACE_FORMAT_PREFIX: "[%9!d!]%8!04X!.%3!04X!::[%1!s!]%!COMPNAME!:%!FUNC!::%2!s!"

5

A bit late, but found a solution:

// FUNC LogFuncFailNtStatus{LEVEL=TRACE_LEVEL_ERROR, FLAGS=TRACE_GENERIC}(STATUS, MSG, ...);
// USESUFFIX (LogFuncFailNtStatus, " failed with %!STATUS!", STATUS);

Just need to put the STATUS argument first and the MSG second
This uses a bit of “hack”, but works, the string is correctly concatenated and no longer appears in the binary.