...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...
14be7173-5b9a-4bb5-b96b-ef31b97c3f9b-image.png
No who's to blame here I wonder...
54818173-f2b1-4fcf-b92f-bab694028551-image.png
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:
76d831c5-b904-4666-9745-b5133b42d06d-image.png
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] <-- ExitSo 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 PreviewTime 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):
f7c9d289-87c1-4a03-a9bf-8d42fd3c9b61-image.png
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 0x00000246D57A2D30The 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 0x246d578e0e0Only 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: 0xb000bControl 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: 0xb0233Oh, 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:
b3936f7a-6abe-4598-bfff-b1cabdbb8b0d-image.png
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:
e2300ed1-1729-4cde-b56c-2ecb5131ba84-image.png
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:
7cdb74ed-e015-4cc3-bc4d-432240b85132-image.png
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:
48cf9937-4f12-4b99-9462-39393bf11599-image.png
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 fixArmed with this knowledge there's 3 ways to deal with this issue.
Disable registry value by INFSince 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 supportedCould call it a day now, but there's more, especially to protect against adventurous users turning it back on again 😉
Handle the request with failurePreviously 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 properlyThere'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! 🎉