Welcome to the beginning of another journey! Involving lots of driver stuff, USB, Bluetooth, HID and everything in between

Since March 2020 I've started working on DsHidMini, the true and final successor to the dated ScpToolkit to let the SIXAXIS/DualShock 3 shine in its past glory yet again, refreshed with Windows 10 compatibility and no trail of legacy code

So, why start a dev log now almost a year later? Well, nearing its "Beta"-Stage some quirks and obstacles have arisen I find worth documenting and ranting about. With DsHidMini I've gone a fairly new, "fresh" route. It's a user-mode driver utilizing UMDF v2 which means no more kernel restrictions like the good old signing mess and no more BSODs on driver crashes. It's also easier to debug (well, we'll get back to that later...) and quicker to develop, deploy and test. It's basically at its heart just a DLL with a few restrictions. Also to reduce the amount of dreadful duplicated code in a driver you end up with every time you need common patterns or practices I decided to give the shiny Microsoft DMF a go with it.

See you in the next post where I ramble about issues with WPP Software Tracing, missing or downright misleading documentation and a weird issue that only seems to arise on a certain machine of mine.

Stay tuned!

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:

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

Mining Cryptocurrency...

...is definitely not what happened here, but the results were equally wasteful on the poor i5 CPU

When deploying the driver on a new lab machine something rather unexpected happened: the CPU fans suddenly had a field day and spun up to rather uncomfortable levels noise-wise. I was almost a 100% certain that I've written a gamepad driver, not a fan controller driver so what was going on Oh...

No who's to blame here I wonder...

Looks like the host process our driver is running under (remember: UMDF means driver logic is just a DLL, loaded by a system process calling kernel APIs in proxy, if necessary). And looking at the DLL list Process Explorer provides one can quickly verify:

Analysis

First clue that something is not going so well is that now tracing spikes up to over a million captured events of DMF_RequestPassthru in only half a minute!

DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DmfContainerEvtDeviceIoControl] --> Entry
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_ModuleCollectionDeviceIoControl] --> Entry <DmfCollection=0xFFFFFE4AF44978C8 Request=0xFFFFFE4AF4471708
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_Generic_ModuleDeviceIoControl] --> Entry <DmfModule=0xFFFFFE4AF44975E8 [ScheduledTask]
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_Generic_ModuleDeviceIoControl] <-- Exit <DmfModule=0xFFFFFE4AF44975E8 [ScheduledTask] returnValue=0>
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_Generic_ModuleDeviceIoControl] --> Entry <DmfModule=0xFFFFFE4AF4496128 [DsHidMini]
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_Generic_ModuleDeviceIoControl] <-- Exit <DmfModule=0xFFFFFE4AF4496128 [DsHidMini] returnValue=0>
DmfUModules.Library	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_VirtualHidMini_ModuleDeviceIoControl] --> Entry
DmfUModules.Library	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_VirtualHidMini_ModuleDeviceIoControl] <-- Exit <returnValue=0>
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_Bridge_ModuleDeviceIoControl] --> Entry
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_Bridge_ModuleDeviceIoControl] <-- Exit <returnValue=0>
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DMF_ModuleCollectionDeviceIoControl] <-- Exit <DmfCollection=0xFFFFFE4AF44978C8 handled=0>
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_INFORMATION	 [DMF_RequestPassthru]Passthru Request: Request=FFFFFE4AF4471708
DmfUFramework	16980	4112	2021/01/24-12:17:21.522	TRACE_LEVEL_VERBOSE	 [DmfContainerEvtDeviceIoControl] <-- Exit

So apparently there's a lot of I/O (DeviceIoControl) coming from the upper driver (mshidumdf in this case) hammering our driver, and none of the DMF modules (who use their own default request queue as I haven't defined one) handle the request since it apparently uses an unknown control code. But which one? And why?

Poking under the hood with WinDbg Preview

Time to fire up the trusty (yet somewhat odd named) WinDbg Preview and poke the process. Again, being a user-mode driver allows us to not fiddle with kernel debugging but simply attach to the host process (make sure to use the right one by comparing the PID if there are multiple):

Out of curiosity, lets see what the In-Flight Recorder of the framework has to tell us:

!wdfkd.wdflogdump dshidmini.dll -f

206244174: FxPkgIo::Dispatch - WDFDEVICE 0xFFFFFDB92A887238 !devobj 0x00000246D579DB20 0x0000000e(IRP_MJ_DEVICE_CONTROL), IRP_MN 0, IRP 0x00000246D578C280
206244175: FxIoQueue::QueueRequest - Queuing WDFREQUEST 0xFFFFFDB92A873718 on WDFQUEUE 0xFFFFFDB92A84AE78
206244176: FxIoQueue::DispatchEvents - Thread 000000000000164C is processing WDFQUEUE 0xFFFFFDB92A84AE78
206244177: FxIoQueue::DispatchRequestToDriver - Calling driver EvtIoDeviceControl for WDFREQUEST 0xFFFFFDB92A873718
206244194: FxPkgIo::Dispatch - WDFDEVICE 0xFFFFFDB92A887238 !devobj 0x00000246D579DB20 0x0000000e(IRP_MJ_DEVICE_CONTROL), IRP_MN 0, IRP 0x00000246D578B880
206244195: FxIoQueue::QueueRequest - Queuing WDFREQUEST 0xFFFFFDB92A873E98 on WDFQUEUE 0xFFFFFDB92A84AE78
206244196: FxIoQueue::DispatchEvents - Thread 000000000000164C is processing WDFQUEUE 0xFFFFFDB92A84AE78
206244197: FxIoQueue::DispatchRequestToDriver - Calling driver EvtIoDeviceControl for WDFREQUEST 0xFFFFFDB92A873E98
206244212: FxPkgIo::Dispatch - WDFDEVICE 0xFFFFFDB92A887238 !devobj 0x00000246D579DB20 0x0000000e(IRP_MJ_DEVICE_CONTROL), IRP_MN 0, IRP 0x00000246D578CF00
206244213: FxIoQueue::QueueRequest - Queuing WDFREQUEST 0xFFFFFDB92A873998 on WDFQUEUE 0xFFFFFDB92A84AE78
206244214: FxIoQueue::DispatchEvents - Thread 000000000000164C is processing WDFQUEUE 0xFFFFFDB92A84AE78
206244215: FxIoQueue::DispatchRequestToDriver - Calling driver EvtIoDeviceControl for WDFREQUEST 0xFFFFFDB92A873998
206244230: FxPkgIo::Dispatch - WDFDEVICE 0xFFFFFDB92A887238 !devobj 0x00000246D579DB20 0x0000000e(IRP_MJ_DEVICE_CONTROL), IRP_MN 0, IRP 0x00000246D578D180
206244231: FxIoQueue::QueueRequest - Queuing WDFREQUEST 0xFFFFFDB92A874398 on WDFQUEUE 0xFFFFFDB92A84AE78
206244232: FxIoQueue::DispatchEvents - Thread 000000000000164C is processing WDFQUEUE 0xFFFFFDB92A84AE78
206244233: FxIoQueue::DispatchRequestToDriver - Calling driver EvtIoDeviceControl for WDFREQUEST 0xFFFFFDB92A874398
206244248: FxPkgIo::Dispatch - WDFDEVICE 0xFFFFFDB92A887238 !devobj 0x00000246D579DB20 0x0000000e(IRP_MJ_DEVICE_CONTROL), IRP_MN 0, IRP 0x00000246D57A2330
206244249: FxIoQueue::QueueRequest - Queuing WDFREQUEST 0xFFFFFDB92A85C9E8 on WDFQUEUE 0xFFFFFDB92A84AE78
206244250: FxIoQueue::DispatchEvents - Thread 00000000000028B4 is processing WDFQUEUE 0xFFFFFDB92A84AE78
206244251: FxIoQueue::DispatchRequestToDriver - Calling driver EvtIoDeviceControl for WDFREQUEST 0xFFFFFDB92A85C9E8
206244266: FxPkgIo::Dispatch - WDFDEVICE 0xFFFFFDB92A887238 !devobj 0x00000246D579DB20 0x0000000e(IRP_MJ_DEVICE_CONTROL), IRP_MN 0, IRP 0x00000246D57A2D30

The IRP_MJ_DEVICE_CONTROL corresponds with the observations of the trace log from earlier, so lets take a closer look at the "contents" of the requests and see what they are:

!wdfkd.wdfumirps

Number of pending IRPS: 0xc
####  CWudfIrp          Current Type                                        UniqueId          KernelIrp         Device Stack
----  ----------------  --------------------------------------------------  ----------------  ----------------  ----------------
0000  0x246d5769a90     WdfRequestDeviceIoControl                           10                0xffffa98a2107b010  0x246d574a870    
0001  0x246d5769490     WdfRequestDeviceIoControl                           11                0xffffa98a20d4e8a0  0x246d574a870    
0002  0x246d57a5a40     WdfRequestDeviceIoControl                           0                 0x00000000        0x246d578ea90    
0003  0x246d57a6440     WdfRequestDeviceIoControl                           0                 0x00000000        0x246d578ea90    
0004  0x246d57a57c0     WdfRequestDeviceIoControl                           0                 0x00000000        0x246d578ea90    
0005  0x246d57a5f40     WdfRequestInternalIoctl                             0                 0x00000000        0x246d578e0e0    
0006  0x246d57a4dc0     WdfRequestInternalIoctl                             0                 0x00000000        0x246d578e0e0    
0007  0x246d57d5100     WdfRequestDeviceIoControl                           499c54            0xffffa98a260c4760  0x246d578ea90    
0008  0x246d57a89f0     WdfRequestDeviceIoControl                           499c55            0xffffa98a25e6b760  0x246d578ea90    
0009  0x246d57a7ff0     WdfRequestDeviceIoControl                           f7f73a            0xffffa98a224ab8a0  0x246d578e0e0    
0010  0x246d578c360     WdfRequestDeviceIoControl                           f7f73c            0xffffa98a25f12b60  0x246d578e0e0    
0011  0x246d578cd60     WdfRequestDeviceIoControl                           f7f771            0xffffa98a20b74bf0  0x246d578e0e0   

Only WdfRequestDeviceIoControl are of interest since a UMDF stack can't handle WdfRequestInternalIoctl, by ID alone there ain't much info to go by so just quickly poke at some and take random guesses:

!wdfumirp  0x00000246d57d5100  

UM IRP: 0x00000246d57d5100  UniqueId: 0x499c54  Kernel Irp: !irp  0xffffa98a260c4760
  Type: WdfRequestDeviceIoControl
  ClientProcessId: 0x0
  Device Stack: !wdfumdevstack  0x00000246d578ea90
  IoStatus
    hrStatus: 0x0
    Information: 0x0
  Driver/Framework created IRP: No
  Current Buffers:
    Input: 0x0000000000000000 / 0
    Output: 0x00000246d5767b60 / 0xc
  IsFrom32BitProcess: No
  EffectiveIoType: Buffered
  CancelFlagSet: No
  Cancel callback: 0x00007ffb86c79750 (WUDFx02000!FxIrpQueue::_WdmCancelRoutineInternal)
  Overlapped: 0x00000246d57d5228
  Total number of stack locations: 2
  CurrentStackLocation: StackLocation[ 1 ]
    StackLocation[ 0 ]
      UNINITIALIZED
  > StackLocation[ 1 ]
      FxDevice:   0x00000246d5741960
       dt  wudfx02000!FxFileObject 0x0000000000000000   !wdfumfile  0x0000000000000000
      Completion:
        Callback:   0x0000000000000000
        Context:    0x0000000000000000
      Parameters: (RequestType: WdfRequestDeviceIoControl)
        Input buffer length:  0x0
        Output buffer length: 0xc
        Control code:         0xb000b

Control code 0xb000blooks familiar and indeed, it's IOCTL_HID_READ_REPORT, the common request for a new input packet. This is expected to be seen and pending as a HID mini-driver issues those in a ping-pong fashion to poll for new information. I'd say we can rule this one out as "perfectly normal". Next:

!wdfumirp  0x00000246d578cd60  

UM IRP: 0x00000246d578cd60  UniqueId: 0xf7f771  Kernel Irp: !irp  0xffffa98a20b74bf0
  Type: WdfRequestDeviceIoControl
  ClientProcessId: 0x0
  Device Stack: !wdfumdevstack  0x00000246d578e0e0
  IoStatus
    hrStatus: 0x0
    Information: 0x0
  Driver/Framework created IRP: No
  Current Buffers not set / not retrieved
  IsFrom32BitProcess: No
  EffectiveIoType: Buffered
  CancelFlagSet: No
  Cancel callback: (None)
  Overlapped: 0x00000246d578ce88
  Total number of stack locations: 2
  CurrentStackLocation: StackLocation[ 1 ]
    StackLocation[ 0 ]
      UNINITIALIZED
  > StackLocation[ 1 ]
      FxDevice:   0x00000246d5778dc0
       dt  wudfx02000!FxFileObject 0x0000000000000000   !wdfumfile  0x0000000000000000
      Completion:
        Callback:   0x0000000000000000
        Context:    0x0000000000000000
      Parameters: (RequestType: WdfRequestDeviceIoControl)
        Input buffer length:  0x0
        Output buffer length: 0x0
        Control code:         0xb0233

Oh, control code 0xb0233, who are you, haven't encountered you before! A quick web search reveals... nothing. OK, assuming it's a well known "official" code (which it should be since mshidumdf should only let HID-related requests through to us) we should find info about it in the SDK/WDK headers. But first, dissect it, being lazy I used the OSR tool for it:

Alrighty, function we're looking for is0x8C or 140 in decimal. The macro HID_CTL_CODE is used to define the HID IOCTLs so a quick grep should bring up the header files to look in:

And sure enough; hidclass.h has the answer:

#define IOCTL_HID_DEVICERESET_NOTIFICATION      HID_CTL_CODE(140)

Alright, now who are you and what is your deal inside my driver?! Excerpt:

The IOCTL_HID_DEVICERESET_NOTIFICATION request is sent by the HID client driver to HID class driver to wait for a device-initiated reset event. This request can also be sent by the HID Class driver to the HID Minidriver to wait for a device-initiated reset event.

OK, so this request is meant to be kept pending and answered once a device reset has happened, common for USB devices. That explains, why it gets spammed over and over again; if this type of request is completed immediately upon arrival by DMF (since there's nobody left to ask to handle it instead) the upper driver assumes, the event has happened and will issue another request to wait if said event happens again, and again and again and ag... you get the idea Question remains; why is this suddenly an issue and hasn't appeared at a sooner stage in development? Another little hint from the documentation:

A HID minidriver can enable this feature by adding a registry value in the INF file. The DeviceResetNotificationEnabled under the device's hardware key must be set to 1 to enable the feature.

Soooooo... this has to be explicitly enabled to happen? That's odd, lets look at the appropriate location in the registry:

Hey hey, look at that, where did you come from, I didn't set ya Ah, but the default Windows stock HID drivers did when I first plugged the DS3 into this fresh machine! Searching the input.inf confirms the suspicion:

So mixing the remains of these default settings with a driver that in fact doesn't handle/supports this request leads to unexpected consequences (no pun intended).

The fix

Armed with this knowledge there's 3 ways to deal with this issue.

Disable registry value by INF

Since the troublesome request won't be issued if the value is disabled, overwriting it in the INF is the first secure step, since most systems in the wild will probably have the registry "poisoned" by the stock driver being in place by default:

[dshidmini.USB_AddReg]
HKR,,"LowerFilters",0x00010008,"WUDFRd" ; FLG_ADDREG_TYPE_MULTI_SZ | FLG_ADDREG_APPEND
HKR,,"DeviceResetNotificationEnabled",0x00010001,0 ; enabled by default, not supported

Could call it a day now, but there's more, especially to protect against adventurous users turning it back on again

Handle the request with failure

Previously I had no need to define a default queue for my driver since the Virtual HID Mini Module handles all I/O coming from above explicitly. But as we observed, the module doesn't handle IOCTL_HID_DEVICERESET_NOTIFICATION so we need to do that instead:

WDF_IO_QUEUE_CONFIG_INIT_DEFAULT_QUEUE(&queueConfig, WdfIoQueueDispatchParallel);
queueConfig.PowerManaged = WdfTrue;
queueConfig.EvtIoDeviceControl = DSHM_EvtWdfIoQueueIoDeviceControl;
DMF_DmfDeviceInitHookQueueConfig(dmfDeviceInit, &queueConfig);

ntStatus = WdfIoQueueCreate(
	device, 
	&queueConfig, 
	WDF_NO_OBJECT_ATTRIBUTES, 
	&queue
);

The callback:

void DSHM_EvtWdfIoQueueIoDeviceControl(
	WDFQUEUE Queue,
	WDFREQUEST Request,
	size_t OutputBufferLength,
	size_t InputBufferLength,
	ULONG IoControlCode
)
{
	NTSTATUS status = STATUS_NOT_IMPLEMENTED;

	UNREFERENCED_PARAMETER(Queue);
	UNREFERENCED_PARAMETER(OutputBufferLength);
	UNREFERENCED_PARAMETER(InputBufferLength);

	FuncEntry(TRACE_DEVICE);

	switch (IoControlCode)
	{
	case IOCTL_HID_DEVICERESET_NOTIFICATION:
		TraceVerbose(
			TRACE_DEVICE,
			"IOCTL_HID_DEVICERESET_NOTIFICATION not supported"
		);
		status = STATUS_NOT_SUPPORTED;
		break;
	default:
		TraceVerbose(TRACE_DEVICE, "Unhandled I/O control code 0x%X", IoControlCode);
		break;
	}

	FuncExitNoReturn(TRACE_DEVICE);

	WdfRequestComplete(Request, status);
}

Good, now even if it comes along again, failure is reported and the upper driver will not issue it again (this has been confirmed by testing). Yay!

DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DmfContainerEvtDeviceIoControl] --> Entry
DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_ModuleCollectionDeviceIoControl] --> Entry <DmfCollection=0xFFFFFE50E9098998 Request=0xFFFFFE50E90827C8
DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_Generic_ModuleDeviceIoControl] --> Entry <DmfModule=0xFFFFFE50E9098708 [ScheduledTask]
DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_Generic_ModuleDeviceIoControl] <-- Exit <DmfModule=0xFFFFFE50E9098708 [ScheduledTask] returnValue=0>
DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_Generic_ModuleDeviceIoControl] --> Entry <DmfModule=0xFFFFFE50E9095DE8 [DsHidMini]
DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_Generic_ModuleDeviceIoControl] <-- Exit <DmfModule=0xFFFFFE50E9095DE8 [DsHidMini] returnValue=0>
DmfUModules.Library	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_VirtualHidMini_ModuleDeviceIoControl] --> Entry
DmfUModules.Library	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_INFORMATION	 [DMF_VirtualHidMini_ModuleDeviceIoControl]IoControlCode = 0xB0233
DmfUModules.Library	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_VirtualHidMini_ModuleDeviceIoControl] <-- Exit <returnValue=0>
DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_Bridge_ModuleDeviceIoControl] --> Entry
sys	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DSHM_EvtWdfIoQueueIoDeviceControl] --> Entry
sys	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DSHM_EvtWdfIoQueueIoDeviceControl]IOCTL_HID_DEVICERESET_NOTIFICATION not supported
sys	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DSHM_EvtWdfIoQueueIoDeviceControl] <--
DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_Bridge_ModuleDeviceIoControl] <-- Exit <returnValue=1>
DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DMF_ModuleCollectionDeviceIoControl] <-- Exit <DmfCollection=0xFFFFFE50E9098998 handled=1>
DmfUFramework	14828	13944	2021/01/25-14:29:56.657	TRACE_LEVEL_VERBOSE	 [DmfContainerEvtDeviceIoControl] <-- Exit

Handle the request properly

There's another option I skipped on for now: actually keep the request pending and complete it if e.g. a pipe failure requiring a device reset has happened. I haven't encountered this case in many iterations of testing now so I'll put it on the back seat for now (only to come back later and bite me another day I'm sure )

There we have it, another mystery solved!

Exposing Battery Status

A rather long-running issue I wanted to solve for good was the whole deal of the controller battery status/charge level. It's a fairly big deal to the user to know, if the battery is fully charged or close to dying when on wireless and in a wild smash session (no pun intended)

This simple functionality is rather annoying to implement, due to the lack of a standardised "battery API" on Windows. The major challenge for a device driver in the end is: how to properly refine and represent the data of the device to the system and in the end to a user (application).

The battery status of the PS3 peripherals is sent with every input report update as an uint_8 with these possible values:

typedef enum _DS_BATTERY_STATUS
{
    DsBatteryStatusNone = 0x00,
    DsBatteryStatusDying = 0x01,
    DsBatteryStatusLow = 0x02,
    DsBatteryStatusMedium = 0x03,
    DsBatteryStatusHigh = 0x04,
    DsBatteryStatusFull = 0x05,
    DsBatteryStatusCharging = 0xEE,
    DsBatteryStatusCharged = 0xEF
	
} DS_BATTERY_STATUS, *PDS_BATTERY_STATUS;

I could theoretically expose the battery level as either another HID input report or a dedicated feature report but this is unfortunately not possible in compliance with the sixaxis.sys emulation I built in. Thanks to Sony choosing not to include report IDs in their official drivers HID Report Descriptor it is not possible to add new features without breaking compatibility. Nice move yet again. So I've settled for a different, lesser known route. Behold the introduction of the Unified Device Property Model!

I can add custom properties with different types of data (strings or in this case a single byte value) with a simple definition like so:

// {52FAC1DA-5A52-40F5-A123-367F760F8BC2}
DEFINE_DEVPROPKEY(DEVPKEY_DsHidMini_BatteryStatus,
	0x52fac1da, 0x5a52, 0x40f5, 0xa1, 0x23, 0x36, 0x7f, 0x76, 0xf, 0x8b, 0xc2, 2); // DEVPROP_TYPE_BYTE

Later in the code the WdfDeviceAssignProperty API can be used to set/update the property with a value:

battery = (DS_BATTERY_STATUS)((PUCHAR)rdrBuffer)[30];

//
// Update battery status property
// 
if (battery != pDevCtx->BatteryStatus)
{
	WDF_DEVICE_PROPERTY_DATA propertyData;

	WDF_DEVICE_PROPERTY_DATA_INIT(&propertyData, &DEVPKEY_DsHidMini_BatteryStatus);
	propertyData.Flags |= PLUGPLAY_PROPERTY_PERSISTENT;
	propertyData.Lcid = LOCALE_NEUTRAL;

	(void)WdfDeviceAssignProperty(
		(WDFDEVICE)Context,
		&propertyData,
		DEVPROP_TYPE_BYTE,
		sizeof(BYTE),
		&battery
	);
}

This makes it visible to the system in Device Manager, WMI, PowerShell and the SetupAPI:

Neat! Now I'd love to have a proper human readable display/key name for it but unfortunately - surprise surprise - this isn't documented anywhere Maybe some more digging in Windows' internals...

Cheers!

UsER-MODe dRiVeRs CaN't CraSh THe SYsteM

WE LIKE THE STOP

DEBUGGER GO BRRRR

2: kd> !analyze -v
*******************************************************************************
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
*******************************************************************************

DRIVER_POWER_STATE_FAILURE (9f)
A driver has failed to complete a power IRP within a specific time.
Arguments:
Arg1: 0000000000000003, A device object has been blocking an Irp for too long a time
Arg2: ffffb68f733afa80, Physical Device Object of the stack
Arg3: fffff500a4e37850, nt!TRIAGE_9F_POWER on Win7 and higher, otherwise the Functional Device Object of the stack
Arg4: ffffb68f73cc0750, The blocked IRP

New day, new challenge

2: kd> !irp ffffb68f73cc0750
...
>[IRP_MJ_POWER(16), IRP_MN_SET_POWER(2)]
            0 e1 ffffb68f733afa80 00000000 00000000-00000000    pending
	       \Driver\BthPS3
			Args: 00041100 00000001 00000001 00000002
 [IRP_MJ_POWER(16), IRP_MN_SET_POWER(2)]
            0  1 ffffb68f72ce6a50 00000000 00000000-00000000    pending
	       \Driver\WudfRd
			Args: 00041100 00000001 00000001 00000002
 [IRP_MJ_POWER(16), IRP_MN_SET_POWER(2)]
            0 e0 ffffb68f7417d060 00000000 fffff8032f994f90-ffffb68f7417d1b0 Success Error Cancel 
	       \Driver\mshidumdf	HIDCLASS!HidpFdoPowerCompletion
			Args: 00041100 00000001 00000001 00000002
 [IRP_MJ_POWER(16), IRP_MN_SET_POWER(2)]
            0 e1 ffffb68f7417d060 00000000 fffff80329365e10-ffffb68f6ec401e8 Success Error Cancel pending
	       \Driver\mshidumdf	nt!PopRequestCompletion
			Args: 00041100 00000001 00000001 00000002
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-ffffb68f6ec401e8    

			Args: 00000000 00000000 00000000 00000000

Convenient, two pieces of software written by me who could be the culprits!

2: kd> !devobj ffffb68f72ce6a50
Device object (ffffb68f72ce6a50) is for:
  \Driver\WudfRd DriverObject ffffb68f7135da90
Current Irp 00000000 RefCount 0 Type 0000002a Flags 0000304c
SecurityDescriptor ffff8005098abca0 DevExt ffffb68f72ce6ba0 DevObjExt ffffb68f72ce6bc8 
ExtensionFlags (0x00000800)  DOE_DEFAULT_SD_PRESENT
Characteristics (0x00000180)  FILE_AUTOGENERATED_DEVICE_NAME, FILE_DEVICE_SECURE_OPEN
AttachedDevice (Upper) ffffb68f7417d060 \Driver\mshidumdf
AttachedTo (Lower) ffffb68f733afa80 \Driver\BthPS3
Device queue is not busy.

OK, can't shift the blame, meh. What did I do now... Lets investigate EvtDeviceD0Exit:

NTSTATUS DsHidMini_EvtDeviceD0Exit(
	_In_ WDFDEVICE              Device,
	_In_ WDF_POWER_DEVICE_STATE TargetState
)
{
	PDEVICE_CONTEXT pDevCtx;

	UNREFERENCED_PARAMETER(TargetState);

	FuncEntry(TRACE_POWER);

	pDevCtx = DeviceGetContext(Device);

	if (pDevCtx->ConnectionType == DsDeviceConnectionTypeUsb)
	{
		WdfIoTargetStop(WdfUsbTargetPipeGetIoTarget(
			pDevCtx->Connection.Usb.InterruptInPipe),
			WdfIoTargetCancelSentIo
		);
	}

	if (pDevCtx->ConnectionType == DsDeviceConnectionTypeBth)
	{
		WdfTimerStop(pDevCtx->Connection.Bth.Timers.HidOutputReport, TRUE);
		WdfTimerStop(pDevCtx->Connection.Bth.Timers.HidControlConsume, TRUE);

		WdfIoTargetStop(pDevCtx->Connection.Bth.BthIoTarget, WdfIoTargetCancelSentIo);
	}

	FuncExitNoReturn(TRACE_POWER);

	return STATUS_SUCCESS;
}

Lets take a closer look to how WdfTimerStop is called...

Wait

[in] KMDF A Boolean value that, if TRUE, specifies that the framework does not return until all queued calls to the driver's deferred procedure calls (DPCs), including the driver's EvtTimerFunc callback functions, have executed.

UMDF A Boolean value that, if TRUE, specifies that the framework does not return until all queued calls to the timer's EvtTimerFunc callback function have executed.

Oh, brilliant idea to block endlessly in the power-down callback Why endlessly you ask, if I don't do any heavy lifting the timer callback should end within a few milliseconds, right? Well... I start the timer in the callback again, to that it runs periodically And apparently that is enough to cause a timing issue (no pun intended) that will keep the stop call from completing. Oh well, set it to FALSE, fixed