DsHidMini Devlogs
-
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 secondWPP_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 butTRACE_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 valueVerboseOn
with content1
in the keyHKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\WUDF\Services\dshidmini\Parameters\Wdf
so 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 requiredLies, 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 handleWdfRequestInternalIoctl
, 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
0xb000b
looks familiar and indeed, it'sIOCTL_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 sincemshidumdf
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 is
0x8C
or140
in decimal. The macroHID_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