Alright, here we go. I've got some juicy issues to report on and how I fixed them. First chapter on: tracing!
WPP verbose tracing not working
First of all let me give you a very brief summary of WPP Software Tracing; it's basically the preferred way to log/trace what's going on inside of a driver (and other software components but I digress), so naturally I use it in all my projects both during development and testing and also to be able to peek under the hood of production code in the wild not behaving as expected. WPP traces - when unobserved - simply live in a ring buffer of memory that overwrites itself by default when full, it's both fast and efficient in storage. So having WPP working as expected is somewhat crucial to my journey through both new products and during the research and development cycle. Sounds easy enough, right? Well... ugh... 😓
Within a driver there are certain events that happen quite frequently (many iterations per second), like reading from a USB device typically involves polling the device every few milliseconds. To not get drowned in logs that distract from "important" events, different levels are used to categorize them. You can tag errors, warning and informational messages as such. Errors typically represent an issue serious enough that the device/driver functionality might be seriously obstructed and might need a retry or can't be recovered from. Warnings might be events that are unexpected but don't introduce a serious issue in operation. Informational events typically appear infrequent and at device power up, reconfiguration or going to sleep. So far so good. And everything in between that can help visualize and understand the flow of the code can either be ignored (not instrumented by tracing) or, ideally, be traced as TRACE_LEVEL_VERBOSE.
The verbose level is considered off by default on production machines, so when reading a live trace or a stored trace log, every message tagged as verbose will simply not be there; they're not even captured in the background buffer to conserve resources unless the user/dev decides to include them. Makes sense, right? Why keep track of something that you never need 99.9% of the time where the driver is running as expected.
Now, due to another issue I'll address in a follow-up post I needed not only my own drivers verbose logs but also the verbose traces of the DMF components my driver heavily relies on. So lets look at the documentation on how to do that:
// Define the tracing flags.
//
// Tracing GUID - {1AE05C6D-9140-41DC-BFBD-C8C4391FD95F}
//
#define WPP_CONTROL_GUIDS \
WPP_DEFINE_CONTROL_GUID( \
DmfLibraryTraceGuid, (74DC7AB3,690B,480A,87A4,3627882A831C), \
WPP_DEFINE_BIT(DMF_TRACE) \
) \
WPP_DEFINE_CONTROL_GUID( \
DmfSampleDriverTraceGuid, {1AE05C6D,9140,41DC,BFBD,C8C4391FD95F} \
WPP_DEFINE_BIT(MYDRIVER_ALL_INFO) \
WPP_DEFINE_BIT(TRACE_DRIVER) \
WPP_DEFINE_BIT(TRACE_DEVICE) \
WPP_DEFINE_BIT(TRACE_QUEUE) \
WPP_DEFINE_BIT(TRACE_USP) \
)
// This comment block is scanned by the trace preprocessor to define our
// Trace function.
//
// USEPREFIX and USESUFFIX strip all trailing whitespace, so we need to surround
// FuncExit messages with brackets
//
// begin_wpp config
// FUNC Trace{FLAG=MYDRIVER_ALL_INFO}(LEVEL, MSG, \...);
// FUNC TraceEvents(LEVEL, FLAGS, MSG, \...);
// FUNC FuncEntry{LEVEL=TRACE_LEVEL_VERBOSE}(FLAGS);
// FUNC FuncEntryArguments{LEVEL=TRACE_LEVEL_VERBOSE}(FLAGS, MSG, \...);
// FUNC FuncExit{LEVEL=TRACE_LEVEL_VERBOSE}(FLAGS, MSG, \...);
// FUNC FuncExitVoid{LEVEL=TRACE_LEVEL_VERBOSE}(FLAGS);
// FUNC TraceError{LEVEL=TRACE_LEVEL_ERROR}(FLAGS, MSG, \...);
// FUNC TraceInformation{LEVEL=TRACE_LEVEL_INFORMATION}(FLAGS, MSG, \...);
// FUNC TraceVerbose{LEVEL=TRACE_LEVEL_VERBOSE}(FLAGS, MSG, \...);
// FUNC FuncExitNoReturn{LEVEL=TRACE_LEVEL_VERBOSE}(FLAGS);
// USEPREFIX(FuncEntry, "%!STDPREFIX! [%!FUNC!] --> Entry");
// USEPREFIX(FuncEntryArguments, "%!STDPREFIX! [%!FUNC!] --> Entry <");
// USEPREFIX(FuncExit, "%!STDPREFIX! [%!FUNC!] <-- Exit <");
// USESUFFIX(FuncExit, ">");
// USEPREFIX(FuncExitVoid, "%!STDPREFIX! [%!FUNC!] <-- Exit");
// USEPREFIX(TraceError, "%!STDPREFIX! [%!FUNC!] ERROR:");
// USEPREFIX(TraceEvents, "%!STDPREFIX! [%!FUNC!] ");
// USEPREFIX(TraceInformation, "%!STDPREFIX! [%!FUNC!] ");
// USEPREFIX(TraceVerbose, "%!STDPREFIX! [%!FUNC!] ");
// USEPREFIX(FuncExitNoReturn, "%!STDPREFIX! [%!FUNC!] <--");
// end_wpp
Don't worry if most of the content of that snippet looks weird, what's important to understand the issue is, that this recommendation basically "works" so I adopted it. Well, almost. The first WPP_DEFINE_CONTROL_GUID definition is to get all DMF components to talk. Fair enough, will include it. The second WPP_DEFINE_CONTROL_GUID is basically my own existing block for declaring a so called trace provider for my own code. Looks good, makes sense, compiles without errors and runs! Now DMF-specific events bubble up when observing the trace but TRACE_LEVEL_VERBOSE is still missing from both DMF and my driver... Alright, time to dig the docs some more!
Don't trust the documentation
Thankfully there's documentation available on how to turn on verbose logging for both KMDF and UMDF (the framework I use in this case).
Interpreting the article I'm supposed to put a DWORD registry value VerboseOn with content 1 in the key HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\WUDF\Services\dshidmini\Parameters\Wdfso I did exactly that (via INF file to avoid forgetting to setting it every time I update the driver 😉 ). Well, that changed absolutely nothing! 😒
Trust, but verify
Since a user-mode driver is loaded by a user-mode process (WUDFHost.exe) I can use common tools like Process Monitor to expose which registry regions are actually read upon driver load:
dfb896a0-5141-4353-9312-3b0dfd058554-image.png
Aha! HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\WUDF\Services\dshidmini\Parameters\VerboseOn you say? Well, don't mind if I set that instead! And sure enough, DMF verbose logs appear, yay! But what about my own verbose messages, they're still not showing up. Further digging required 🤔
Lies, damned lies, and statistics
So this is the block I had sporting in my Trace.h file, naïve as I was 😁
#define WPP_CONTROL_GUIDS \
WPP_DEFINE_CONTROL_GUID( \
DmfLibraryTraceGuid, ([redacted]), \
WPP_DEFINE_BIT(DMF_TRACE) \
) \
WPP_DEFINE_CONTROL_GUID( \
DsHidMiniTraceGuid, ([redacted]), \
WPP_DEFINE_BIT(MYDRIVER_ALL_INFO) \
WPP_DEFINE_BIT(TRACE_DRIVER) \
WPP_DEFINE_BIT(TRACE_DEVICE) \
WPP_DEFINE_BIT(TRACE_DSHID) \
WPP_DEFINE_BIT(TRACE_DSHIDMINIDRV) \
WPP_DEFINE_BIT(TRACE_POWER) \
WPP_DEFINE_BIT(TRACE_DSUSB) \
WPP_DEFINE_BIT(TRACE_DS3) \
WPP_DEFINE_BIT(TRACE_DSBTH) \
WPP_DEFINE_BIT(TRACE_CONFIG) \
) \
Well, deception I'm afraid. I've only briefly tested this for UMDF but to my observation verbose tracing doesn't work if more than one provider is defined 😠
So what I've ended up with is rather simple; only use one provider definition and declare the DMF_TRACE just along my own:
#define WPP_CONTROL_GUIDS \
WPP_DEFINE_CONTROL_GUID( \
DsHidMiniTraceGuid, ([redacted]), \
WPP_DEFINE_BIT(MYDRIVER_ALL_INFO) \
WPP_DEFINE_BIT(DMF_TRACE) \
WPP_DEFINE_BIT(TRACE_DRIVER) \
WPP_DEFINE_BIT(TRACE_DEVICE) \
WPP_DEFINE_BIT(TRACE_DSHID) \
WPP_DEFINE_BIT(TRACE_DSHIDMINIDRV) \
WPP_DEFINE_BIT(TRACE_POWER) \
WPP_DEFINE_BIT(TRACE_DSUSB) \
WPP_DEFINE_BIT(TRACE_DS3) \
WPP_DEFINE_BIT(TRACE_DSBTH) \
WPP_DEFINE_BIT(TRACE_CONFIG) \
) \
And that finally did the trick! 🎉
sys 10364 13400 2021/01/25-14:44:21.532 TRACE_LEVEL_VERBOSE [dshidminiEvtDeviceAdd] --> Entry
sys 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DsHidMini_BthConnectionContextInit] --> Entry
sys 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DsHidMini_BthConnectionContextInit] <-- Exit <status=STATUS_SUCCESS (0x00000000)>
sys 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_INFORMATION [dshidminiEvtDeviceAdd]!! DEVPKEY_Device_InstanceId: BTHPS3BUS\{53f88889-1aaf-4353-a047-556b69ec6da6}\9&12c5aacf&0&AC7A4D2819AC
sys 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_INFORMATION [dshidminiEvtDeviceAdd]!! DeviceAddress: AC7A4D2819AC
DmfUFramework 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DMF_ModulesCreate] --> Entry
sys 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DmfDeviceModulesAdd] --> Entry
sys 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DmfDeviceModulesAdd] <--
DmfUFramework 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DMF_ModuleCollectionCreate] --> Entry
DmfUModules.Library 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DMF_ScheduledTask_Create] --> Entry
DmfUFramework 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DMF_ModuleCreate] --> Entry
DmfUFramework 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DMF_SynchronizationCreate] --> Entry <DmfObject=0x000001EE316AB330 [ScheduledTask]
DmfUFramework 10364 13400 2021/01/25-14:44:21.533 TRACE_LEVEL_VERBOSE [DMF_SynchronizationCreate]DMF_MODULE_OPTIONS_PASSIVE
Now that we got the spam we wanted, onwards to the next issue with weirdly high CPU consumption 👀
