I was bitching a lot about the Hardware Lab Kit and debugging utilities in general in the past but to perfectly honest; the more I become familiar with them and overcome their quirks the more I appreciate the feedback they provide.
Like for example; I've tried to connect a DS3 while the profile driver is running under Driver Verifier (which in short means that a strong rule-set applies triggering bugs that might have gone under) on Windows 8.1 and it crashed with:
KMODE_EXCEPTION_NOT_HANDLED (1e) This is a very common bugcheck. Usually the exception address pinpoints the driver/function that caused the problem. Always note this address as well as the link date of the driver/image that contains this address. Arguments: Arg1: ffffffff80000003, The exception code that was not handled Arg2: fffff801f61cd3c0, The address that the exception occurred at Arg3: 0000000000000000, Parameter 0 of the exception Arg4: 7efefefefeff3252, Parameter 1 of the exception
Once in WinDbg with the symbols loaded we get a nice "stack trace":
STACK_TEXT: ... : nt!KeBugCheckEx ... : nt!KiFatalExceptionHandler+0x22 ... : nt!RtlpExecuteHandlerForException+0xd ... : nt!RtlDispatchException+0x1a5 ... : nt!KiDispatchException+0x18d ... : nt!KiExceptionDispatch+0xc2 ... : nt!KiBreakpointTrap+0x2dc ... : nt!DbgBreakPoint+0x1 ... : Wdf01000!FxIoTargetSendIoctl+0x282da ... : Wdf01000!imp_WdfIoTargetSendIoctlSynchronously+0x48 ... : BthPS3!L2CAP_PS3_HandleRemoteConnect+0x16a [e:\development\gogs\bthps3\bthps3\l2cap.c @ 49] ... : BthPS3!BthPS3_IndicationCallback+0x9c [e:\development\gogs\bthps3\bthps3\bluetooth.c @ 552] ... : bthport!L2CapInt_ProcessL2capConnectReq+0x40b ... : bthport!L2CapInt_ProcessSignallingPacket+0x45f ... : bthport!L2CapInt_ProcessReadBip+0x13a ... : bthport!HCI_ProcessAclReadBip+0x661 ... : bthport!HCI_ProcessAclRead+0x2a8 ... : bthport!HCI_ProcessMpBip+0x92 ... : bthport!BTHPORT_RecvMpBip+0x41 ... : BTHUSB!BthUsb_ReadTransferComplete+0x18d ... : BTHUSB!UsbWrapWorkRoutine+0x18d ... : BTHUSB!UsbWrapInterruptReadComplete+0x1d3 ... : nt!IovpLocalCompletionRoutine+0x174 ... : nt!IopfCompleteRequest+0x2ee ... : nt!IovCompleteRequest+0x1d7 ... : Wdf01000!FxRequest::CompleteInternal+0x23c ... : Wdf01000!imp_WdfRequestComplete+0x8c ... : BthPS3PSM!UrbFunctionBulkInTransferCompleted+0x107 [e:\development\gogs\bthps3\bthps3psm\filter.c @ 233] ... : Wdf01000!FxRequestBase::CompleteSubmitted+0x459 ... : Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x162 ... : nt!IopUnloadSafeCompletion+0x49 ... : nt!IovpLocalCompletionRoutine+0x174 ... : nt!IopfCompleteRequest+0x2ee ... : nt!IovCompleteRequest+0x1d7 ... : USBPORT!USBPORT_Core_iCompleteDoneTransfer+0xa02 ... : USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x21c ... : USBPORT!USBPORT_Core_UsbIocDpc_Worker+0x238 ... : USBPORT!USBPORT_Xdpc_Worker_IocDpc+0x1fe ... : nt!KiExecuteAllDpcs+0x1b0 ... : nt!KiRetireDpcList+0xd7 ... : nt!KiIdleLoop+0x5a
Alrighty, so line 49 in the function
l2cap.c of the driver
BthPS3 is triggering the fault. Let's see what's there:
Ah, an inline function! What does it contain that might bomb? I have a suspicion (mostly because it's hinted in the stack trace )...
Let's have a look at the docs of
WdfIoTargetSendIoctlSynchronously and check out the requirements section:
Hm, but our L2CAP callback is invoked at
PASSIVE_LEVEL, right? Let's throw in some tracing and have another run:
2019/03/10-10:46:19.023 TRACE_LEVEL_VERBOSE BthPS3_IndicationCallback Entry (Low (0x00)) 2019/03/10-10:46:19.023 TRACE_LEVEL_VERBOSE L2CAP_PS3_HandleRemoteConnect Entry (Low (0x00)) 2019/03/10-10:46:19.038 TRACE_LEVEL_VERBOSE BthPS3_IndicationCallback Entry (DPC (0x02)) 2019/03/10-10:46:19.038 TRACE_LEVEL_VERBOSE L2CAP_PS3_HandleRemoteConnect Entry (DPC (0x02))
Hey! The second call isn't at
DISPATCH_LEVEL! How dare you! Oh wait, the docs, check the docs:
IRQL Developers should code this function to operate at either IRQL = DISPATCH_LEVEL (if the callback function does not access paged memory), or IRQL = PASSIVE_LEVEL (if the callback function must access paged memory)
Ouch! How evil! So that can totally happen and
!wdfkd.wdflogdump gives clear insights:
1: kd> !wdfkd.wdflogdump BthPS3 ... 37: FxVerifierCheckIrqlLevel - Called at wrong IRQL; at level 2, should be at level 0 ---- end of log ----
Right, so this would've fallen under the radar if it didn't bomb in the lab. Thanks, WHQL Onward with the fixes!