This browser is no longer supported.
Upgrade to Microsoft Edge to take advantage of the latest features, security updates, and technical support.
![](data:image/svg+xml, %3Csvg xmlns='http://www.w3.org/2000/svg' height='64' class='font-weight-bold' style='font: 600 30.11764705882353px "SegoeUI", Arial' width='64'%3E%3Ccircle fill='hsl(240, 54%, 33%)' cx='32' cy='32' r='32' /%3E%3Ctext x='50%25' y='55%25' dominant-baseline='middle' text-anchor='middle' fill='%23FFF' %3EWD%3C/text%3E%3C/svg%3E)
We're seeing an intermittent pair of verifier bugchecks in a KMDF USB driver. The issue never happens on some systems, but happens regularly enough on some systems taht it warrants attention for us.
These are the bugchecks followed by the call stack:
WDF_VIOLATION (10d)
The Kernel-Mode Driver Framework was notified that Windows detected an error
in a framework-based driver...
Arguments:
Arg1: 0000000000000006, A fatal error was made in handling a WDF request. In this case,
Parameter 2 further specifies the type of fatal error that has
been made, as defined by the enumeration WDF_REQUEST_FATAL_ERROR.
Arg2: 0000000000000003, The driver attempted to send a framework request that has
already been sent to an I/O target.
Arg3: 00003f719a03bf18, The WDF request handle value.
Arg4: ffffc08e614c9de0, Reserved.
STACK_TEXT:
fffff807`120da148 fffff807`108b8920 : 00000000`0000010d 00000000`00000006 00000000`00000003 00003f71`9a03bf18 : nt!KeBugCheckEx
fffff807`120da150 fffff807`1087d5c1 : 00003f71`9a03bf18 00000000`00000000 00003f71`9a03bf18 fffff807`10863f7d : Wdf01000!FxVerifierBugCheckWorker+0x24 [minkernel\wdf\framework\shared\object\fxverifierbugcheck.cpp @ 68]
fffff807`120da190 fffff807`10861c4a : ffffc08e`65fc4000 ffffc08e`65fc40e0 00000000`00000000 ffffc08e`65fc40e0 : Wdf01000!FxIoTarget::SubmitLocked+0x1b631 [minkernel\wdf\framework\shared\targets\general\fxiotarget.cpp @ 1318]
fffff807`120da220 fffff807`1922cb34 : ffffc08e`614c9f00 ffffc08e`65fc40e0 ffffc08e`65d2ddf0 00000000`00000000 : Wdf01000!imp_WdfRequestSend+0x17a [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 2055]
fffff807`120da2a0 fffff807`192283a5 : fffff807`1922a1a0 ffffc08e`6215a820 ffffc08e`6215aa58 fffff807`192480a0 : FocusriteUsb!IsocUrb::Submit+0x74 [c:\Jenkins\jenkins2\workspace\HMP_Driver_Build_feature_wdf_iso\source\driver\usb\isocurb.cpp @ 280]
fffff807`120da2f0 fffff807`19229dde : ffffc08e`6215a820 00000000`00000009 ffffc08e`67b84f40 ffffc08e`67b84f40 : FocusriteUsb!UsbAudioStream::SubmitAudioUrb+0x45 [c:\Jenkins\jenkins2\workspace\HMP_Driver_Build_feature_wdf_iso\source\driver\usb\audstream.cpp @ 909]
fffff807`120da320 fffff807`10869248 : ffffc08e`65fbf2f0 00000000`00000001 fffff807`1922a1a0 ffffc08e`61721e10 : FocusriteUsb!UsbAudioStream::RequestCompletion+0x25e [c:\Jenkins\jenkins2\workspace\HMP_Driver_Build_feature_wdf_iso\source\driver\usb\audstream.cpp @ 671]
fffff807`120da380 fffff807`1086c854 : 00003f71`9a040d08 ffffc08e`65fbf2f0 ffffc08e`65fbf2f0 fffff807`0fdf8a48 : Wdf01000!FxRequestBase::CompleteSubmitted+0xe8 [minkernel\wdf\framework\shared\core\fxrequestbase.cpp @ 530]
fffff807`120da410 fffff807`0f76e976 : ffffc08e`66ea1980 ffffc08e`67df4a02 ffffc08e`67df4af0 fffff807`120da658 : Wdf01000!FxIoTarget::_RequestCompletionRoutine+0xe4 [minkernel\wdf\framework\shared\targets\general\fxiotarget.cpp @ 2448]
fffff807`120da480 fffff807`0fddd834 : fffff807`0f76e920 ffffc08e`67df4af0 fffff807`120da658 ffffc08e`67df4f68 : nt!IopUnloadSafeCompletion+0x56
fffff807`120da4b0 fffff807`0f69f07e : ffffc08e`67df4af0 00000000`0000000f 00000000`0000000f fffff807`120da599 : nt!IovpLocalCompletionRoutine+0x174
fffff807`120da510 fffff807`0fddd16f : ffffc08e`67df4af0 fffff807`120da600 00000000`00000002 ffffc08e`6ae07510 : nt!IopfCompleteRequest+0x11e
fffff807`120da600 fffff807`0f855d37 : 00000000`00000001 00000000`00000001 ffffc08e`60eb2a70 ffff7d7b`1c200000 : nt!IovCompleteRequest+0x1cf
fffff807`120da6f0 fffff807`1086811a : 00000000`00000000 ffffc08e`5abde780 ffffc08e`67df4af0 ffffc08e`6a4914e0 : nt!IofCompleteRequest+0x1b6e07
fffff807`120da720 fffff807`10865bbf : 00000000`00000002 fffff807`120da858 ffffc08e`67df4af0 00000000`00000000 : Wdf01000!FxRequest::CompleteInternal+0x23a [minkernel\wdf\framework\shared\core\fxrequest.cpp @ 869]
fffff807`120da7b0 fffff80c`1fb6265e : ffffc08e`60eb2c10 ffffc08e`60eb2a70 00000000`00000002 ffffc08e`6a48cda0 : Wdf01000!imp_WdfRequestComplete+0x8f [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 436]
fffff807`120da810 fffff80c`1fb620e6 : ffffc08e`6a48cda0 ffffc08e`6a48cda0 fffff807`00000120 fffff807`0f86f201 : USBXHCI!Isoch_Stage_CompleteTD+0x47e
fffff807`120da8d0 fffff80c`1fb61ef0 : fffff807`120daa00 fffff807`120daa00 00000000`00000000 fffff807`00000000 : USBXHCI!Isoch_ProcessTransferEventWithED1+0x1d6
fffff807`120da9b0 fffff80c`1fb66cc0 : 00000000`00000004 fffff807`120daa88 00000000`00000008 fffff807`120daa90 : USBXHCI!Isoch_EP_TransferEventHandler+0x10
fffff807`120da9e0 fffff80c`1fb667f5 : 00000000`00000780 00003f71`a501f300 ffff8d80`9b893fa0 ffffc08e`650c9d30 : USBXHCI!Endpoint_TransferEventHandler+0xb0
fffff807`120daa40 fffff80c`1fb664cc : ffffc08e`58b91f50 ffffc08e`58af5940 00003f71`a1a347c8 ffffc08e`58b91000 : USBXHCI!Interrupter_DeferredWorkProcessor+0x315
fffff807`120dab40 fffff807`108638f5 : 00000000`00000f44 00000000`00400a02 00000000`00000000 00000257`5878efdb : USBXHCI!Interrupter_WdfEvtInterruptDpc+0xc
fffff807`120dab70 fffff807`0f6b43ae : fffff807`0dfff240 fffff807`120dacb0 fffff807`120dae70 fffff807`00000002 : Wdf01000!FxInterrupt::_InterruptDpcThunk+0xa5 [minkernel\wdf\framework\shared\irphandlers\pnp\km\interruptobjectkm.cpp @ 404]
fffff807`120dabb0 fffff807`0f6b3694 : fffff807`0dffc180 00000000`00000000 00000000`00000008 00000000`00006a07 : nt!KiExecuteAllDpcs+0x30e
fffff807`120dad20 fffff807`0f818215 : 00000000`00000000 fffff807`0dffc180 ffff8d80`9c73d140 ffffd8c5`0cee8000 : nt!KiRetireDpcList+0x1f4
fffff807`120dafb0 fffff807`0f818000 : fffff807`0f80d2c0 fffff807`0f73fdfa ffffffff`ffffffff fffff807`0f736453 : nt!KxRetireDpcList+0x5
ffff8282`8bd10810 fffff807`0f8178b5 : ffffd8c5`0cee8000 fffff807`0f812d41 9c0c60f3`9049710a fffff807`0f73639c : nt!KiDispatchInterruptContinue
ffff8282`8bd10840 fffff807`0f812d41 : 9c0c60f3`9049710a fffff807`0f73639c 00000000`332e3880 fffff980`00989a90 : nt!KiDpcInterruptBypass+0x25
ffff8282`8bd10850 fffff807`0f9a5a3b : 00000000`00000001 fffff807`0f9a586d 00000000`00000000 00000000`00000000 : nt!KiInterruptDispatch+0xb1
ffff8282`8bd109e0 fffff807`0f9a534a : ffffd8c5`0cee7000 ffffc08e`65dd1420 ffffd8c5`0cee7000 00000000`ffffffff : nt!RtlpGenericRandomPatternWorker+0x15f
ffff8282`8bd10a20 fffff807`0f9790af : 00000000`00000000 ffffc08e`65dd1420 ffffd8c5`0cee7000 00000000`00032de3 : nt!RtlScrubMemory+0x112
ffff8282`8bd10a60 fffff807`0f978e46 : fffff807`1006aa40 ffffc08e`5803f740 00000000`00032de3 fffff807`1006aa40 : nt!MiScrubPage+0x14b
ffff8282`8bd10ab0 fffff807`0fcf2f38 : ffffc08e`00000000 fffff807`1006aa40 ffffc08e`65dd1420 00000000`00000300 : nt!MiScrubNode+0x18a
ffff8282`8bd10b40 fffff807`0f6d2505 : ffffc08e`67751040 ffffc08e`580c19c0 ffffc08e`580c19c0 00000000`00000000 : nt!MiScrubMemoryWorker+0x28
ffff8282`8bd10b70 fffff807`0f76f845 : ffffc08e`67751040 00000000`00000080 ffffc08e`580a3040 000f8067`b4bbbdff : nt!ExpWorkerThread+0x105
ffff8282`8bd10c10 fffff807`0f818828 : ffff8d80`9b480180 ffffc08e`67751040 fffff807`0f76f7f0 00000000`00000000 : nt!PspSystemThreadStartup+0x55
ffff8282`8bd10c60 00000000`00000000 : ffff8282`8bd11000 ffff8282`8bd0b000 00000000`00000000 00000000`00000000 : nt!KiStartSystemThread+0x28
AND
DRIVER_VERIFIER_IOMANAGER_VIOLATION (c9)
The IO manager has caught a misbehaving driver.
Arguments:
Arg1: 000000000000020b, The caller of IoFreeIrp is freeing an IRP that is still in use.
Arg2: fffff8035b897ace, The address in the driver's code where the error was detected.
Arg3: ffffe6827b112af0, IRP address.
Arg4: 0000000000000000
STACK_TEXT:
fffff803`5e2d9f48 fffff803`5bfd5e34 : 00000000`000000c9 00000000`0000020b fffff803`5b897ace ffffe682`7b112af0 : nt!KeBugCheckEx
fffff803`5e2d9f50 fffff803`5bfdd393 : 00000000`00000000 00000000`00000000 00000000`0000020b fffff803`5c3469b0 : nt!VerifierBugCheckIfAppropriate+0xe0
fffff803`5e2d9f90 fffff803`5bba3bbb : 00000000`0000020b 00000000`00000000 ffffe682`7b112af0 00000000`00000000 : nt!ViErrorFinishReport+0x117
fffff803`5e2d9ff0 fffff803`5bfd62cf : fffff803`5b897ace 00000000`00000002 00000000`00000000 fffff803`5ca6b7ee : nt!ViErrorReport1+0x63
fffff803`5e2da090 fffff803`5bfca23c : ffffe682`7956e70f ffffe682`7b112af0 ffffe682`6baf3000 ffffe682`7956e710 : nt!VfIoFreeIrp+0x83
fffff803`5e2da0d0 fffff803`5b897ace : ffffe682`78204c00 ffffe682`7956e710 ffffe682`7b112af0 ffffe682`79936af0 : nt!IovFreeIrpPrivate+0x6c
fffff803`5e2da110 fffff803`5ca87eab : fffff803`663b3d38 00000000`00000000 ffffe682`7bfd5000 ffffe682`6baf51a0 : nt!IoFreeIrp+0x1e
fffff803`5e2da140 fffff803`5cace16d : ffffe682`79580700 ffffe682`7956e710 ffffe682`79580700 fffff803`5ca6cdd7 : Wdf01000!FxRequestBase::ValidateTarget+0x1c70f [minkernel\wdf\framework\shared\core\fxrequestbase.cpp @ 375]
fffff803`5e2da190 fffff803`5cac85e7 : ffffe682`79580700 fffff803`5e2da260 0000197d`82163af8 00000000`00000000 : Wdf01000!FxFormatUrbRequest+0x2d [minkernel\wdf\framework\shared\targets\usb\usbutil.cpp @ 76]
fffff803`5e2da1e0 fffff803`6639c350 : ffffe682`7de9c568 ffffe682`7bae2858 00000000`00000000 ffffe682`6b0f9060 : Wdf01000!imp_WdfUsbTargetPipeFormatRequestForUrb+0x1a7 [minkernel\wdf\framework\shared\targets\usb\fxusbpipeapi.cpp @ 806]
fffff803`5e2da290 fffff803`6639838d : fffff803`6639a1a0 ffffe682`7bae2858 00000000`00000000 fffff803`663b80a0 : FocusriteUsb!IsocUrb::Recycle+0x1c0 [c:\Jenkins\jenkins2\workspace\HMP_Driver_Build_feature_wdf_iso\source\driver\usb\isocurb.cpp @ 204]
fffff803`5e2da2f0 fffff803`66399dde : ffffe682`7bae2820 00000000`00000009 ffffe682`74611570 ffffe682`74611570 : FocusriteUsb!UsbAudioStream::SubmitAudioUrb+0x2d [c:\Jenkins\jenkins2\workspace\HMP_Driver_Build_feature_wdf_iso\source\driver\usb\audstream.cpp @ 907]
fffff803`5e2da320 fffff803`5ca69248 : ffffe682`6b0f9060 00000000`00000001 fffff803`6639a1a0 ffffe682`7d780df0 : FocusriteUsb!UsbAudioStream::RequestCompletion+0x25e [c:\Jenkins\jenkins2\workspace\HMP_Driver_Build_feature_wdf_iso\source\driver\usb\audstream.cpp @ 671]
fffff803`5e2da380 fffff803`5ca6c854 : 0000197d`94f06f98 ffffe682`6b0f9060 ffffe682`6b0f9060 fffff803`5bfe5a48 : Wdf01000!FxRequestBase::CompleteSubmitted+0xe8 [minkernel\wdf\framework\shared\core\fxrequestbase.cpp @ 530]
fffff803`5e2da410 fffff803`5b95b976 : ffffe682`780b6de0 ffffe682`7bac8a02 ffffe682`7bac8af0 fffff803`5e2da658 : Wdf01000!FxIoTarget::_RequestCompletionRoutine+0xe4 [minkernel\wdf\framework\shared\targets\general\fxiotarget.cpp @ 2448]
fffff803`5e2da480 fffff803`5bfca834 : fffff803`5b95b920 ffffe682`7bac8af0 fffff803`5e2da658 ffffe682`7bac8f68 : nt!IopUnloadSafeCompletion+0x56
fffff803`5e2da4b0 fffff803`5b88c07e : ffffe682`7bac8af0 00000000`0000000f 00000000`0000000f fffff803`5e2da599 : nt!IovpLocalCompletionRoutine+0x174
fffff803`5e2da510 fffff803`5bfca16f : ffffe682`7bac8af0 fffff803`5e2da600 00000000`00000002 ffffe682`7bcef510 : nt!IopfCompleteRequest+0x11e
fffff803`5e2da600 fffff803`5ba42d37 : 00000000`00000001 00000000`00000001 ffffe682`7405d500 ffffc1f8`75200000 : nt!IovCompleteRequest+0x1cf
fffff803`5e2da6f0 fffff803`5ca6811a : 00000000`00000000 ffffe682`6dbf4de0 ffffe682`7bac8af0 ffffe682`7e13aa20 : nt!IofCompleteRequest+0x1b6e07
fffff803`5e2da720 fffff803`5ca65bbf : 00000000`00000002 fffff803`5e2da858 ffffe682`7bac8af0 00000000`00000000 : Wdf01000!FxRequest::CompleteInternal+0x23a [minkernel\wdf\framework\shared\core\fxrequest.cpp @ 869]
fffff803`5e2da7b0 fffff80c`f41f265e : ffffe682`7405d6a0 ffffe682`7405d500 00000000`00000002 ffffe682`7e34fe10 : Wdf01000!imp_WdfRequestComplete+0x8f [minkernel\wdf\framework\shared\core\fxrequestapi.cpp @ 436]
fffff803`5e2da810 fffff80c`f41f20e6 : ffffe682`7e34fe10 ffffe682`7e34fe10 fffff803`00000120 00000000`00000001 : USBXHCI!Isoch_Stage_CompleteTD+0x47e
fffff803`5e2da8d0 fffff80c`f41f1ef0 : fffff803`5e2daa00 fffff803`5e2daa00 00000000`00000000 fffff803`00000000 : USBXHCI!Isoch_ProcessTransferEventWithED1+0x1d6
fffff803`5e2da9b0 fffff80c`f41f6cc0 : 00000000`00000004 fffff803`5e2daa88 00000000`00000008 fffff803`5e2daa90 : USBXHCI!Isoch_EP_TransferEventHandler+0x10
fffff803`5e2da9e0 fffff80c`f41f67f5 : 00000000`00000780 0000197d`9200e300 ffffd201`c9a18010 ffffe682`6db57d10 : USBXHCI!Endpoint_TransferEventHandler+0xb0
fffff803`5e2daa40 fffff80c`f41f64cc : ffffe682`6bb8bc30 ffffe682`6baf6940 0000197d`8e9de7c8 ffffe682`6bb8b000 : USBXHCI!Interrupter_DeferredWorkProcessor+0x315
fffff803`5e2dab40 fffff803`5ca638f5 : 00000000`00000000 00000000`00000f45 00000000`000070a0 fffff803`5e2dae60 : USBXHCI!Interrupter_WdfEvtInterruptDpc+0xc
fffff803`5e2dab70 fffff803`5b8a13ae : fffff803`5a37b240 fffff803`5e2dacb0 fffff803`5e2dae70 fffff803`00000002 : Wdf01000!FxInterrupt::_InterruptDpcThunk+0xa5 [minkernel\wdf\framework\shared\irphandlers\pnp\km\interruptobjectkm.cpp @ 404]
fffff803`5e2dabb0 fffff803`5b8a0694 : fffff803`5a378180 00000000`00000000 00000000`00000000 00000000`000070a0 : nt!KiExecuteAllDpcs+0x30e
fffff803`5e2dad20 fffff803`5ba05215 : 00000000`00000000 fffff803`5a378180 ffffd201`c9b83a00 00000000`059aede4 : nt!KiRetireDpcList+0x1f4
fffff803`5e2dafb0 fffff803`5ba05000 : fffff803`5b9fa2c0 fffff803`5b92cdfa 00000000`00000000 ffffe682`7b57c660 : nt!KxRetireDpcList+0x5
ffffa08f`a16ebac0 fffff803`5ba048b5 : 00000000`059aede4 fffff803`5b9ffd41 00000000`059aed80 00000000`00000001 : nt!KiDispatchInterruptContinue
ffffa08f`a16ebaf0 fffff803`5b9ffd41 : 00000000`059aed80 00000000`00000001 ffffa08f`a16ebb18 ffffffff`f4143e00 : nt!KiDpcInterruptBypass+0x25
ffffa08f`a16ebb00 00000000`6fba06c1 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiInterruptDispatch+0xb1
00000000`059aecd8 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : 0x6fba06c1
The driver is using this code from (a function called from) its EvtRequestCompletion routine
NTSTATUS IsocUrb::Recycle(bool reuse)
{
NTSTATUS status = STATUS_SUCCESS;
ASSERT(_urb != NULL);
ASSERT(m_Buffer != NULL);
ASSERT(m_NumPackets > 0);
ASSERT(_pipe);
const USHORT urbLength = (USHORT)GET_ISO_URB_SIZE(m_NumPackets);
// zero header but not IsoPackets (for now)
RtlZeroMemory(_urb, sizeof(_urb->UrbIsochronousTransfer) - sizeof(_urb->UrbIsochronousTransfer.IsoPacket));
_urb->UrbHeader.Length = urbLength;
_urb->UrbHeader.Function = URB_FUNCTION_ISOCH_TRANSFER;
_urb->UrbHeader.Status = 0xFFFFFFFF;
_urb->UrbIsochronousTransfer.PipeHandle = WdfUsbTargetPipeWdmGetPipeHandle(_pipe);
_urb->UrbIsochronousTransfer.TransferFlags = (m_IsInput ? USBD_TRANSFER_DIRECTION_IN : 0);
_urb->UrbIsochronousTransfer.TransferBufferLength = m_TransferLength;
_urb->UrbIsochronousTransfer.TransferBuffer = m_Buffer;
//urb->UrbIsochronousTransfer.StartFrame = startFrame;
_urb->UrbIsochronousTransfer.NumberOfPackets = m_NumPackets;
for (ULONG i = 0; i < _urb->UrbIsochronousTransfer.NumberOfPackets; i++)
{
_urb->UrbIsochronousTransfer.IsoPacket[i].Status = 0xFFFFFFFF;
if (m_IsInput)
{
// This fixes compatibility with the Renesas USB 3.0 host controller driver (nusb3xhc.sys)
_urb->UrbIsochronousTransfer.IsoPacket[i].Length = 0;
}
}
if (reuse)
{
WDF_REQUEST_REUSE_PARAMS wdfrup;
WDF_REQUEST_REUSE_PARAMS_INIT(&wdfrup, WDF_REQUEST_REUSE_NO_FLAGS, STATUS_SUCCESS);
status = WdfRequestReuse(_wdfRequest, &wdfrup);
TraceAssert(NT_SUCCESS(status));
}
// m_Completions++;
status = WdfUsbTargetPipeFormatRequestForUrb(_pipe, _wdfRequest, _urbMemory, 0);
TraceAssert(NT_SUCCESS(status));
return status;
}
followed by this
NTSTATUS IsocUrb::Submit(ULONG startFrame)
{
NTSTATUS status = STATUS_SUCCESS;
if (!_urb || !_pipe || !_wdfRequest)
{
TraceError(" (!_urb || !_pipe || !_wdfRequest) - Error!");
return STATUS_INVALID_PARAMETER;
}
_urb->UrbIsochronousTransfer.StartFrame = startFrame;
if (startFrame == 0)
{
_urb->UrbIsochronousTransfer.TransferFlags |= USBD_START_ISO_TRANSFER_ASAP;
}
if (!WdfRequestSend(_wdfRequest, WdfUsbTargetPipeGetIoTarget(_pipe), WDF_NO_SEND_OPTIONS))
{
status = WdfRequestGetStatus(_wdfRequest);
TraceError("Isoc URB WDFREQUEST failed with error %!STATUS!", status);
}
TraceVerbose(TRACEFLG_USBURB,"URB[%c%d] REQ[%p] Submission: frame:%d status: %!STATUS!", m_IsInput ? 'I':'O', m_ID, (PVOID)_wdfRequest, startFrame, status);
return status;
}
Thanks!
OS is Windows 10 Pro 64 Bit 10.0.19041
Are you passing true IsocUrb::Submit to in all cases? Are you always reusing the WDFREQUEST that is being completed or possibly pulling the WDFREQUEST off a list in some (corner?) cases? Are you always send these requests to the same WDFIOTARGET (or WDFUSBPIPE) ? I ask because IIRC Wdf01000!FxRequestBase::ValidateTarget will only free the irp if it already has an IRP from a previous format call AND the current IRP does not have enough stack locations to be sent to the intended WDFIOTARGET. This would never happen if the same WDFIOTARGET is reused over and over again, but it would happen if the irp is currently in use and the current stack location does not reflect the true size of the irp.
Sent: 10 indicates the current number of requests that are sent on the target, it is not cumulative over the lifetime of the target. The IFR logs refer to the WDFREQUEST by its underlying object value, not the handle value (00007A707EC35DE8). I would suggest running
!wdfkd.wdfhandle 00007A707EC35DE8
and then searching on the underlying object value in the logs as well. I would also suggest turning on verbose enough logging to capture IO completion in the IFR as that is missing and probably an important state change that you need to track.
@Doron Holan
Any hints as to how to debug why this is happening twice? My Etls are not retrievable from a crash dump.
Hi Doron. I've added a bit more info and realized it's probably relevant that this is happening around the request cancellation processing, though I'm not doing anything special other than not attempting to resubmit the request if any part of it appears to be cancelled. Maybe that's not enough?
>> Are you passing true IsocUrb::Submit to in all cases?
yes, that's the only place the WDFREQUEST is touched.
*>> Are you always reusing the WDFREQUEST that is being completed or possibly pulling the WDFREQUEST off a list in some (corner?) cases? *
We're Only re-using using the current, completed request.
*>> Are you always send these requests to the same WDFIOTARGET (or WDFUSBPIPE) ?
yes, each set of WDFREQUESTS is associated with, and ONLY ever sent to, the same WDFUSBPIPE.
I had a question about this info (another dump of the same crash): Does the "Requests sent:10" mean total, forever, for this pipe? Just currently submitted?? I'm not clear on what exactly it means.
0: kd> !wdfrequest 00007a707ec35de8
Treating handle as a KMDF handle!
!irp 0xffff858f8b9aeb80
State: Allocated by driver, IRP allocated by WDF
!wdfiotarget 0x00007a7086291228
Completion Routine: FocusriteUsb!UsbAudioStream::EvtRequestCompletion (fffff800639ea1a0)
Completion Context: 0xffff858f7cd50820
0: kd> !wdfiotarget 0x00007a7086291228
Treating handle as a KMDF handle!
WDFIOTARGET 00007a7086291228
=========================
WDFDEVICE: 0x00007a70831f8da8
Target Device: !devobj 0xffff858f7ce07d20
Target PDO: !devobj 0xffff858f7ce09d40
Type: Instack target
State: WdfIoTargetStarted
Requests pending: 0
Requests sent: 10
WDFREQUEST 00007a707ec34f68 !irp 0xffff858f8b516b80
WDFREQUEST 00007a707ec35a48 !irp 0xffff858f89740b80
WDFREQUEST 00007a707ec36e38 !irp 0xffff858f8a2c8b80
WDFREQUEST 00007a707ec36a98 !irp 0xffff858f8b290b80
WDFREQUEST 00007a707ec342b8 !irp 0xffff858f8ae62b80
WDFREQUEST 00007a707ec368c8 !irp 0xffff858f8acbab80
WDFREQUEST 00007a707ec34d98 !irp 0xffff858f8b3dcb80
WDFREQUEST 00007a707ec34bc8 !irp 0xffff858f8b976b80
WDFREQUEST 00007a707ec34828 !irp 0xffff858f8b87eb80
WDFREQUEST 00007a707ec35de8 !irp 0xffff858f8b9aeb80
Requests sent with ignore-target-state: 0
!wdfrequest 00007a707ec35de8
Treating handle as a KMDF handle!
!irp 0xffff858f8b9aeb80
0: kd> !irp 0xffff858f8b9aeb80
Irp is active with 12 stacks 9 is current (= 0xffff858f8b9aee90)
No Mdl: No System Buffer: Thread 00000000: Irp stack trace. Pending has been returned
cmd flg cl Device File Completion-Context
[N/A(0), N/A(0)]
0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
[N/A(0), N/A(0)]
0 0 00000000 00000000 00000000-00000000
Args: 00000000 00000000 00000000 00000000
>[IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
0 1 ffff858f79e83c80 ffff858f817cc980 00000000-00000000 pending
\Driver\USBXHCI
Args: ffff858f817cc980 00000000 0x220003 00000000
[IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
0 e0 ffff858f79eefb90 ffff858f817cc980 00000000-00000000
\Driver\USBXHCI
Args: ffff858f817cc980 00000000 0x220003 00000000
[IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
0 e1 ffff858f79eefb90 ffff858f817cc980 00000000-00000000 pending
\Driver\USBXHCI
Args: ffff858f817cc980 00000000 0x220003 00000000
[IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
0 0 ffff858f7ce09d40 ffff858f817cc980 00000000-00000000
\Driver\USBHUB3
Args: ffff858f817cc980 00000000 0x220003 00000000
Irp Extension present at 0xffff858f8b9aefb0:
Inflight Trace recorder:
0: kd> !wdflogdump fumbumblee.sys
Trace searchpath is:
Trace format prefix is: %7!u!: %!FUNC! -
Trying to extract TMF information from - c:\myserversymbols\Wdf01000.pdb\BA0D580847BC0ABC20700F3C90FF0EFE1\Wdf01000.pdb
Gather log: Please wait, this may take a moment (reading 4024 bytes).
% read so far ... 10, 20, 30, 40, 50, 60, 70, 80, 90, 100
There are 94 log entries
--- start of log ---
2250: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2251: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2252: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2253: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2254: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2256: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2257: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2258: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2259: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2260: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2261: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2263: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2264: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2266: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2267: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2268: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2269: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2270: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2271: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2272: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2273: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2274: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2275: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2277: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2278: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2279: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2280: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2281: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2282: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2284: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2285: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2286: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707BC0E208
2287: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707BC0E208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2288: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2289: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2290: FxIoTarget::WaitForDisposeEvent - WDFIOTARGET 00007A707BC0E208, Waiting on Dispose event FFFFF90F5FDCB5A0
2291: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A708629CB38 state, sending WDFREQUEST FFFFF90F5FDCB820, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2293: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707B50C208
2294: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707B50C208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2295: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707B50C208
2296: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707B50C208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2297: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2298: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2299: FxIoTarget::WaitForDisposeEvent - WDFIOTARGET 00007A707B50C208, Waiting on Dispose event FFFFF90F5FDCB5A0
2300: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A708629CB38 state, sending WDFREQUEST FFFFF90F5FDCB820, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2302: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707F2B6208
2303: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707F2B6208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2304: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707F2B6208
2305: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707F2B6208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2306: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2307: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2309: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707F2B6208
2310: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707F2B6208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2311: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707F2B6208
2312: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707F2B6208 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2313: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2314: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2315: FxIoTarget::WaitForDisposeEvent - WDFIOTARGET 00007A707F2B6208, Waiting on Dispose event FFFFF90F5FDCB5A0
2316: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A708629CB38 state, sending WDFREQUEST FFFFF90F5FDCB820, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2318: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707E2A27E8
2319: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707E2A27E8 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2320: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A707E2A27E8
2321: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A707E2A27E8 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2322: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2323: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2324: FxIoTarget::WaitForDisposeEvent - WDFIOTARGET 00007A707E2A27E8, Waiting on Dispose event FFFFF90F5FDCB5A0
2325: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A708629CB38 state, sending WDFREQUEST FFFFF90F5FDCB820, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2327: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086287488
2328: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086287488 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2329: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086287488
2330: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086287488 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2331: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2332: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2334: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086287488
2335: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086287488 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
Unknown( 14): GUID=21fc475e-f23b-3eaa-217b-e8ced99c11a1 (No Format Information found).
2337: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086287488
2338: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086287488 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2339: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086291228
2340: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086291228 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2341: FxIoTarget::CancelSentIo - Cancelling pending I/O on WDFIOTARGET 00007A7086287488
2342: FxIoTarget::SubmitLocked - ignoring WDFIOTARGET 00007A7086287488 state, sending WDFREQUEST FFFFF90F5FDCB7E0, state WdfIoTargetStarted
2343: FxIoTarget::SubmitLocked - WDFREQUEST 00007A707EC35DE8 already sent to a target
---- end of log ----
Thanks, Doron, for your quick responses. Here are the relevant lines from a new crash with the VerboseOn=1.
1469781: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 00006E718A89E558
1469782: FxIoTarget::RemoveCompletedRequestLocked - WDFIOTARGET 00006E718F1682B8, WDFREQUEST 00006E718A89E558
1469783: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 00006E718A89E558 completed in completion routine
1469784: imp_WdfUsbTargetPipeFormatRequestForUrb - Pipe 00006E718F1682B8, Request 00006E718A89E558, Memory 00006E7189749B48
1469785: imp_WdfUsbTargetPipeFormatRequestForUrb - Pipe 00006E718F1682B8, Request 00006E718A89E558, Memory 00006E7189749B48, status STATUS_SUCCESS
1469786: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 00006E718AD3FD08
1469787: FxIoTarget::RemoveCompletedRequestLocked - WDFIOTARGET 00006E718F16A348, WDFREQUEST 00006E718AD3FD08
1469788: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 00006E718AD3FD08 completed in completion routine
1469789: imp_WdfUsbTargetPipeFormatRequestForUrb - Pipe 00006E718F16A348, Request 00006E718AD3FD08, Memory 00006E7189748648
1469790: imp_WdfUsbTargetPipeFormatRequestForUrb - Pipe 00006E718F16A348, Request 00006E718AD3FD08, Memory 00006E7189748648, status STATUS_SUCCESS
1469791: imp_WdfUsbTargetPipeFormatRequestForUrb - Pipe 00006E718F16A348, Request 00006E718AD3FD08, Memory 00006E7189748648
1469792: imp_WdfUsbTargetPipeFormatRequestForUrb - Pipe 00006E718F16A348, Request 00006E718AD3FD08, Memory 00006E7189748648, status STATUS_SUCCESS
1469793: FxIoTarget::SubmitLocked - WDFREQUEST 00006E718AD3FD08 already sent to a target
---- end of log ----
I'm not sure why I'm seeing doubled ...FormatRequestForUrb() calls?
The only reason I can think of is that you have a bug in your code that loops accidentally. As you see from previous entries in the logs, it is only called once where there is no DV error. I would suggest you supplement the IFR logs with your own logs to debug further