RE: WdfRequestUnmarkCanc?elable results in BSOD (continued)

!wdfkd.wdflogdump riffaqq will tell you what is going wrong

d

Bent from my phone


From: xxxxx@gmail.commailto:xxxxx
Sent: ?4/?1/?2015 5:43 PM
To: Windows System Software Devs Interest Listmailto:xxxxx
Subject: [ntdev] WdfRequestUnmarkCanc?elable results in BSOD (continued)

I can’t seem to locate the original thread I started last month. So I’ll start a new one here.

I have an IOCTL based DMA driver that I wrote for interfacing with PCIe FPGAs. It’s for Win7 and built using the KMDF APIs. It works well and is reliable until I add support for IO cancellation. Once I add the WdfRequestMarkCancelableEx, WdfRequestUnmarkCancelable calls I get the BSOD .

The Minidump log when I have driver verifier turned on (as well as KMDF VerifyOn set to 1) is below.

CUSTOMER_CRASH_COUNT: 1

DEFAULT_BUCKET_ID: VERIFIER_ENABLED_VISTA_MINIDUMP

BUGCHECK_STR: 0x1E

PROCESS_NAME: svchost.exe

CURRENT_IRQL: 2

TAG_NOT_DEFINED_c000000f: FFFFF880032FFFB0

EXCEPTION_RECORD: fffff880032ff838 – (.exr 0xfffff880032ff838)
ExceptionAddress: fffff80002c7ccd0 (nt!DbgBreakPoint)
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 1
Parameter[0]: 0000000000000000

TRAP_FRAME: fffff880032ff8e0 – (.trap 0xfffff880032ff8e0)
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed or incorrect.
rax=fffff880032ffa78 rbx=0000000000000000 rcx=fffff98002aaafd0
rdx=fffff98002aaafd0 rsi=0000000000000000 rdi=0000000000000000
rip=fffff80002c7ccd1 rsp=fffff880032ffa78 rbp=fffff880032ffb02
r8=0000000000000000 r9=fffff88000ede610 r10=7efefefefefeff40
r11=8101010101010100 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl nz na pe nc
nt!DbgBreakPoint+0x1:
fffff80002c7ccd1 c3 ret<br>Resetting default scope<br><br>LAST_CONTROL_TRANSFER: from fffff80002c7c8be to fffff80002c84e90<br><br>STACK_TEXT:<br>fffff880032fe918 fffff80002c7c8be : fffffa80199bc580 fffff88000c0bf6b fffff880032ff090 fffff80002cb0a00 : nt!KeBugCheck<br>fffff880032fe920 fffff80002cb06cd : fffff80002e95398 fffff80002dce22c fffff80002c10000 fffff880032ff838 : nt!KiKernelCalloutExceptionHandler+0xe<br>fffff880032fe950 fffff80002caf4a5 : fffff80002dd62c4 fffff880032fe9c8 fffff880032ff838 fffff80002c10000 : nt!RtlpExecuteHandlerForException+0xd<br>fffff880032fe980 fffff80002cc0431 : fffff880032ff838 fffff880032ff090 fffff88000000000 00000000c0000010 : nt!RtlDispatchException+0x415<br>fffff880032ff060 fffff80002c84542 : fffff880032ff838 0000000000000000 fffff880032ff8e0 fffff98002aaae40 : nt!KiDispatchException+0x135<br>fffff880032ff700 fffff80002c82374 : 0000000000000000 fffff880032ff960 00000000c0000010 fffff98002aaae40 : nt!KiExceptionDispatch+0xc2<br>fffff880032ff8e0 fffff80002c7ccd1 : fffff88000efe0bd fffff98002aaafd0 fffff98002aaafd0 0000000000000000 : nt!KiBreakpointTrap+0xf4<br>fffff880032ffa78 fffff88000efe0bd : fffff98002aaafd0 fffff98002aaafd0 0000000000000000 fffff88000ede610 : nt!DbgBreakPoint+0x1<br>fffff880032ffa80 fffff88000eff691 : 0000000000000000 fffff98002aaae40 fffff98002aaae40 fffff9800c722e60 : Wdf01000!FxRequest::Vf_VerifyRequestIsCancelable+0x79<br>fffff880032ffad0 fffff88000e5dbcc : 0000000000000002 fffff9800c722e60 fffff880032ffb50 fffff88000000008 : Wdf01000!FxIoQueue::Vf_VerifyRequestCancelable+0x99<br>fffff880032ffb10 fffff88000e68685 : ffff9d59b1850b10 fffff9800c722e60 0000067ff38dd198 0000000000000022 : Wdf01000!FxIoQueue::RequestCancelable+0x3c<br>fffff880032ffb80 fffff880061a821b : fffff9800c722e60 0000067ffd4db1b8 fffff98002b24e40 fffffa801bf8049c : Wdf01000!imp_WdfRequestUnmarkCancelable+0x115<br>fffff880032ffbe0 fffff880061a6a22 : 0000067ff38dd198 fffffa801bf8049c fffff880061a9c70 fffffa801bf8030c : riffa!WdfRequestUnmarkCancelable+0x1b [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h @ 775]<br>fffff880032ffc10 fffff880061a7d6c : fffffa801bf802d0 fffff80000000000 fffff88000000000 fffffa801bf8030c : riffa!RiffaCompleteRequest+0xa2 [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1462]<br>fffff880032ffc70 fffff880061a5252 : fffffa801bf802d0 fffff88000000000 fffff88000000001 fffffa8000000000 : riffa!RiffaTransactionComplete+0x10c [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1907]<br>fffff880032ffcc0 fffff88000ed96d3 : 0000067ffd4db1b8 0000057fe407ffd8 000000004e54241d 000000004559db6a : riffa!RiffaEvtInterruptDpc+0x622 [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 878]<br>fffff880032ffed0 fffff80002c907ac : fffff880032d0180 fffff880032d0180 fffff98002b24ed8 0000000000000042 : Wdf01000!FxInterrupt::DpcHandler+0xc3<br>fffff880032fff00 fffff80002c87925 : 0000000000000000 fffffa8019cdb300 0000000000000000 fffff88000ed9840 : nt!KiRetireDpcList+0x1bc<br>fffff880032fffb0 fffff80002c8773c : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KxRetireDpcList+0x5<br>fffff880063657e0 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KiDispatchInterruptContinue<br><br>STACK_COMMAND: kb<br><br>FOLLOWUP_IP:<br>riffa!WdfRequestUnmarkCancelable+1b [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h @ 775]<br>fffff880061a821b 4883c428 add rsp,28h

FAULTING_SOURCE_LINE: c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h

FAULTING_SOURCE_FILE: c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h

FAULTING_SOURCE_LINE_NUMBER: 775

FAULTING_SOURCE_CODE:
771: WDFREQUEST Request
772: )
773: {
774: return ((PFN_WDFREQUESTUNMARKCANCELABLE) WdfFunctions[WdfRequestUnmarkCancelableTableIndex])(WdfDriverGlobals, Request);
> 775: }
776:
777: //
778: // WDF Function: WdfRequestIsCanceled
779: //
780: typedef

SYMBOL_STACK_INDEX: c

SYMBOL_NAME: riffa!WdfRequestUnmarkCancelable+1b

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: riffa

IMAGE_NAME: riffa.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 54e4c333

FAILURE_BUCKET_ID: X64_0x1E_VRF_riffa!WdfRequestUnmarkCancelable+1b

BUCKET_ID: X64_0x1E_VRF_riffa!WdfRequestUnmarkCancelable+1b

Followup: MachineOwner

---------------------------------
It seems to suggest that the call to WdfRequestUnmarkCancelable in my RiffaTransactionComplete function is to blame. OK. But my understanding is that I need to call WdfRequestUnmarkCancelable on every WDFREQUEST that I call WdfRequestMarkCancelable. According to the WdfRequestUnmarkCancelable MSDN page (https://msdn.microsoft.com/en-us/library/windows/hardware/ff550035(v=vs.85).aspx), this must be done everywhere except the EvtRequestCancel callback.

The general flow of things in my driver:

-> RiffaEvtIoDeviceControl()
// This is the entry point
-> RiffaIoctlSend()
// Save the WDFREQUEST in a field on the PDEVICE_EXTENSION object.
// Start a DMA transfer.
// Call WdfRequestMarkCancelableEx() with the WDFREQUEST and own EvtRequestCancel callback called RiffaEvtRequestCancel.

The driver waits for an interrupt to signal the end of the DMA transfer.

-> RiffaEvtInterruptDpc()
// Interrupt handler
-> RiffaTransactionComplete()
// Ends the DMA transfer, releases the DMA transaction object.
-> RiffaCompleteRequest()
// Gets WDFREQUEST off the PDEVICE_EXTENSION object. Checks if it’s null. If null the request was cancelled and this does nothing. If not null, sets the field on the PDEVICE_EXTENSION to null and calls WdfRequestUnmarkCancelable(), followed by WdfRequestCompleteWithInformation().

If ever invoked, the EvtRequestCancel callback, RiffaEvtRequestCancel, sets the WDFREQUEST field on the PDEVICE_EXTENSION to null and calls WdfRequestCompleteWithInformation().

It’s a pretty straightforward/simple driver modeled after the PLX9x5x driver example. I have yet been able to determine what’s causing this problem. The only thing I do know is that it only seems to happen when issuing a lot of back to back invocations. Stepping through invocations with a debugger seems to slow things down enough to prevent whatever’s going on.

I’ll post the relevant function bodies in a follow up post.

I’ll add a few extra detail and suspicions. The suspicions about possible causes stem from other somewhat related posts I’ve found. But as of yet, I’ve been unable to identify these ideas as the culprit.

1) The driver runs flawlessly without WdfRequestMarkCancelable & WdfRequestUnmarkCancelable. With low frequency and high frequency back to back invocations. But I need to be able to cancel the IO request. So I’m stuck using WdfRequestMarkCancelable & WdfRequestUnmarkCancelable.

2) Someone had a similar problem and discovered that the WDFREQUEST objects were being reused behind the scenes and that person’s driver was failing to call WdfRequestUnmarkCancelable on one of the code paths. His error was similar but was being raised when calling WdfRequestMarkCancelable on a WDFREQUEST that was presumably still marked cancelable. I don’t think this is what’s going on here, but knowing that the WDFREQUESTS are being used is useful.

3) In my initial post on this, someone vaguely suggested that the WDFREQUEST might be non-null on the PDEVICE_EXTENSION but that somehow the “underlying request” object" might have been completed. I don’t see how this could happen as both code paths that complete this WDFREQUEST mark it as null before doing so. This suggestion was a bit vague, so I don’t really know what would cause such a situation. If you do, please enlighten me.

Any ideas would be appreciated. Thanks.

Matt


NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer</mailto:xxxxx></mailto:xxxxx>

Thanks for the quick reply. That command didn’t seem to do anything
meaningful.

10: kd> !wdfkd.wdflogdump riffaqq
c0000005 Exception in wdfkd.wdflogdump debugger extension.
PC: 000000006b9f942b VA: 0000000000000000 R/W: 0 Parameter:
00000000`0001003f

I tried it with just the driver name “riffa”, but it resulted in the same:

10: kd> !wdfkd.wdflogdump riffa
c0000005 Exception in wdfkd.wdflogdump debugger extension.
PC: 000000006b9f942b VA: 0000000000000000 R/W: 0 Parameter:
00000000`0001003f

On Wed, Apr 1, 2015 at 5:56 PM, Doron Holan
wrote:

> !wdfkd.wdflogdump riffaqq will tell you what is going wrong
>
> d
>
> Bent from my phone
> ------------------------------
> From: xxxxx@gmail.com
> Sent: ‎4/‎1/‎2015 5:43 PM
> To: Windows System Software Devs Interest List
> Subject: [ntdev] WdfRequestUnmarkCanc?elable results in BSOD (continued)
>
> I can’t seem to locate the original thread I started last month. So
> I’ll start a new one here.
>
> I have an IOCTL based DMA driver that I wrote for interfacing with PCIe
> FPGAs. It’s for Win7 and built using the KMDF APIs. It works well and is
> reliable until I add support for IO cancellation. Once I add the
> WdfRequestMarkCancelableEx, WdfRequestUnmarkCancelable calls I get the BSOD
> .
>
> The Minidump log when I have driver verifier turned on (as well as KMDF
> VerifyOn set to 1) is below.
>
> CUSTOMER_CRASH_COUNT: 1
>
> DEFAULT_BUCKET_ID: VERIFIER_ENABLED_VISTA_MINIDUMP
>
> BUGCHECK_STR: 0x1E
>
> PROCESS_NAME: svchost.exe
>
> CURRENT_IRQL: 2
>
> TAG_NOT_DEFINED_c000000f: FFFFF880032FFFB0
>
> EXCEPTION_RECORD: fffff880032ff838 – (.exr 0xfffff880032ff838)
> ExceptionAddress: fffff80002c7ccd0 (nt!DbgBreakPoint)
> ExceptionCode: 80000003 (Break instruction exception)
> ExceptionFlags: 00000000
> NumberParameters: 1
> Parameter[0]: 0000000000000000
>
> TRAP_FRAME: fffff880032ff8e0 – (.trap 0xfffff880032ff8e0)
> NOTE: The trap frame does not contain all registers.
> Some register values may be zeroed or incorrect.
> rax=fffff880032ffa78 rbx=0000000000000000 rcx=fffff98002aaafd0
> rdx=fffff98002aaafd0 rsi=0000000000000000 rdi=0000000000000000
> rip=fffff80002c7ccd1 rsp=fffff880032ffa78 rbp=fffff880032ffb02
> r8=0000000000000000 r9=fffff88000ede610 r10=7efefefefefeff40
> r11=8101010101010100 r12=0000000000000000 r13=0000000000000000
> r14=0000000000000000 r15=0000000000000000
> iopl=0 nv up ei pl nz na pe nc
> nt!DbgBreakPoint+0x1:
> fffff80002c7ccd1 c3 ret<br>&gt; Resetting default scope<br>&gt;<br>&gt; LAST_CONTROL_TRANSFER: from fffff80002c7c8be to fffff80002c84e90<br>&gt;<br>&gt; STACK_TEXT:<br>&gt; fffff880032fe918 fffff80002c7c8be : fffffa80199bc580 fffff88000c0bf6b<br>&gt; fffff880032ff090 fffff80002cb0a00 : nt!KeBugCheck<br>&gt; fffff880032fe920 fffff80002cb06cd : fffff80002e95398 fffff80002dce22c<br>&gt; fffff80002c10000 fffff880032ff838 : nt!KiKernelCalloutExceptionHandler+0xe<br>&gt; fffff880032fe950 fffff80002caf4a5 : fffff80002dd62c4 fffff880032fe9c8<br>&gt; fffff880032ff838 fffff80002c10000 : nt!RtlpExecuteHandlerForException+0xd<br>&gt; fffff880032fe980 fffff80002cc0431 : fffff880032ff838 fffff880032ff090<br>&gt; fffff88000000000 00000000c0000010 : nt!RtlDispatchException+0x415<br>&gt; fffff880032ff060 fffff80002c84542 : fffff880032ff838 0000000000000000<br>&gt; fffff880032ff8e0 fffff98002aaae40 : nt!KiDispatchException+0x135<br>&gt; fffff880032ff700 fffff80002c82374 : 0000000000000000 fffff880032ff960<br>&gt; 00000000c0000010 fffff98002aaae40 : nt!KiExceptionDispatch+0xc2<br>&gt; fffff880032ff8e0 fffff80002c7ccd1 : fffff88000efe0bd fffff98002aaafd0<br>&gt; fffff98002aaafd0 0000000000000000 : nt!KiBreakpointTrap+0xf4<br>&gt; fffff880032ffa78 fffff88000efe0bd : fffff98002aaafd0 fffff98002aaafd0<br>&gt; 0000000000000000 fffff88000ede610 : nt!DbgBreakPoint+0x1<br>&gt; fffff880032ffa80 fffff88000eff691 : 0000000000000000 fffff98002aaae40<br>&gt; fffff98002aaae40 fffff9800c722e60 :<br>&gt; Wdf01000!FxRequest::Vf_VerifyRequestIsCancelable+0x79<br>&gt; fffff880032ffad0 fffff88000e5dbcc : 0000000000000002 fffff9800c722e60<br>&gt; fffff880032ffb50 fffff88000000008 :<br>&gt; Wdf01000!FxIoQueue::Vf_VerifyRequestCancelable+0x99<br>&gt; fffff880032ffb10 fffff88000e68685 : ffff9d59b1850b10 fffff9800c722e60<br>&gt; 0000067ff38dd198 0000000000000022 :<br>&gt; Wdf01000!FxIoQueue::RequestCancelable+0x3c<br>&gt; fffff880032ffb80 fffff880061a821b : fffff9800c722e60 0000067ffd4db1b8<br>&gt; fffff98002b24e40 fffffa801bf8049c :<br>&gt; Wdf01000!imp_WdfRequestUnmarkCancelable+0x115<br>&gt; fffff880032ffbe0 fffff880061a6a22 : 0000067ff38dd198 fffffa801bf8049c<br>&gt; fffff880061a9c70 fffffa801bf8030c : riffa!WdfRequestUnmarkCancelable+0x1b<br>&gt; [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h @ 775]<br>&gt; fffff880032ffc10 fffff880061a7d6c : fffffa801bf802d0 fffff80000000000<br>&gt; fffff88000000000 fffffa801bf8030c : riffa!RiffaCompleteRequest+0xa2<br>&gt; [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1462]<br>&gt; fffff880032ffc70 fffff880061a5252 : fffffa801bf802d0 fffff88000000000<br>&gt; fffff88000000001 fffffa8000000000 : riffa!RiffaTransactionComplete+0x10c<br>&gt; [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1907]<br>&gt; fffff880032ffcc0 fffff88000ed96d3 : 0000067ffd4db1b8 0000057fe407ffd8<br>&gt; 000000004e54241d 000000004559db6a : riffa!RiffaEvtInterruptDpc+0x622<br>&gt; [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 878]<br>&gt; fffff880032ffed0 fffff80002c907ac : fffff880032d0180 fffff880032d0180<br>&gt; fffff98002b24ed8 0000000000000042 : Wdf01000!FxInterrupt::DpcHandler+0xc3<br>&gt; fffff880032fff00 fffff80002c87925 : 0000000000000000 fffffa8019cdb300<br>&gt; 0000000000000000 fffff88000ed9840 : nt!KiRetireDpcList+0x1bc<br>&gt; fffff880032fffb0 fffff80002c8773c : 0000000000000000 0000000000000000<br>&gt; 0000000000000000 0000000000000000 : nt!KxRetireDpcList+0x5<br>&gt; fffff880063657e0 0000000000000000 : 0000000000000000 0000000000000000<br>&gt; 0000000000000000 0000000000000000 : nt!KiDispatchInterruptContinue<br>&gt;<br>&gt;<br>&gt; STACK_COMMAND: kb<br>&gt;<br>&gt; FOLLOWUP_IP:<br>&gt; riffa!WdfRequestUnmarkCancelable+1b<br>&gt; [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h @ 775]<br>&gt; fffff880061a821b 4883c428 add rsp,28h
>
> FAULTING_SOURCE_LINE: c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h
>
> FAULTING_SOURCE_FILE: c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h
>
> FAULTING_SOURCE_LINE_NUMBER: 775
>
> FAULTING_SOURCE_CODE:
> 771: WDFREQUEST Request
> 772: )
> 773: {
> 774: return ((PFN_WDFREQUESTUNMARKCANCELABLE)
> WdfFunctions[WdfRequestUnmarkCancelableTableIndex])(WdfDriverGlobals,
> Request);
> > 775: }
> 776:
> 777: //
> 778: // WDF Function: WdfRequestIsCanceled
> 779: //
> 780: typedef
>
>
> SYMBOL_STACK_INDEX: c
>
> SYMBOL_NAME: riffa!WdfRequestUnmarkCancelable+1b
>
> FOLLOWUP_NAME: MachineOwner
>
> MODULE_NAME: riffa
>
> IMAGE_NAME: riffa.sys
>
> DEBUG_FLR_IMAGE_TIMESTAMP: 54e4c333
>
> FAILURE_BUCKET_ID: X64_0x1E_VRF_riffa!WdfRequestUnmarkCancelable+1b
>
> BUCKET_ID: X64_0x1E_VRF_riffa!WdfRequestUnmarkCancelable+1b
>
> Followup: MachineOwner
>
> ---------------------------------
> It seems to suggest that the call to WdfRequestUnmarkCancelable in my
> RiffaTransactionComplete function is to blame. OK. But my understanding is
> that I need to call WdfRequestUnmarkCancelable on every WDFREQUEST that I
> call WdfRequestMarkCancelable. According to the WdfRequestUnmarkCancelable
> MSDN page (
> https://msdn.microsoft.com/en-us/library/windows/hardware/ff550035(v=vs.85).aspx),
> this must be done everywhere except the EvtRequestCancel callback.
>
> The general flow of things in my driver:
>
> -> RiffaEvtIoDeviceControl()
> // This is the entry point
> -> RiffaIoctlSend()
> // Save the WDFREQUEST in a field on the PDEVICE_EXTENSION object.
> // Start a DMA transfer.
> // Call WdfRequestMarkCancelableEx() with the WDFREQUEST and own
> EvtRequestCancel callback called RiffaEvtRequestCancel.
>
> The driver waits for an interrupt to signal the end of the DMA transfer.
>
> -> RiffaEvtInterruptDpc()
> // Interrupt handler
> -> RiffaTransactionComplete()
> // Ends the DMA transfer, releases the DMA transaction object.
> -> RiffaCompleteRequest()
> // Gets WDFREQUEST off the PDEVICE_EXTENSION object. Checks if it’s
> null. If null the request was cancelled and this does nothing. If not null,
> sets the field on the PDEVICE_EXTENSION to null and calls
> WdfRequestUnmarkCancelable(), followed by
> WdfRequestCompleteWithInformation().
>
> If ever invoked, the EvtRequestCancel callback, RiffaEvtRequestCancel,
> sets the WDFREQUEST field on the PDEVICE_EXTENSION to null and calls
> WdfRequestCompleteWithInformation().
>
> It’s a pretty straightforward/simple driver modeled after the PLX9x5x
> driver example. I have yet been able to determine what’s causing this
> problem. The only thing I do know is that it only seems to happen when
> issuing a lot of back to back invocations. Stepping through invocations
> with a debugger seems to slow things down enough to prevent whatever’s
> going on.
>
> I’ll post the relevant function bodies in a follow up post.
>
> I’ll add a few extra detail and suspicions. The suspicions about possible
> causes stem from other somewhat related posts I’ve found. But as of yet,
> I’ve been unable to identify these ideas as the culprit.
>
> 1) The driver runs flawlessly without WdfRequestMarkCancelable &
> WdfRequestUnmarkCancelable. With low frequency and high frequency back to
> back invocations. But I need to be able to cancel the IO request. So I’m
> stuck using WdfRequestMarkCancelable & WdfRequestUnmarkCancelable.
>
> 2) Someone had a similar problem and discovered that the WDFREQUEST
> objects were being reused behind the scenes and that person’s driver was
> failing to call WdfRequestUnmarkCancelable on one of the code paths. His
> error was similar but was being raised when calling
> WdfRequestMarkCancelable on a WDFREQUEST that was presumably still marked
> cancelable. I don’t think this is what’s going on here, but knowing that
> the WDFREQUESTS are being used is useful.
>
> 3) In my initial post on this, someone vaguely suggested that the
> WDFREQUEST might be non-null on the PDEVICE_EXTENSION but that somehow the
> “underlying request” object" might have been completed. I don’t see how
> this could happen as both code paths that complete this WDFREQUEST mark it
> as null before doing so. This suggestion was a bit vague, so I don’t really
> know what would cause such a situation. If you do, please enlighten me.
>
> Any ideas would be appreciated. Thanks.
>
> Matt
>
>
> —
> NTDEV is sponsored by OSR
>
> Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev
>
> OSR is HIRING!! See http://www.osr.com/careers
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
> —
> NTDEV is sponsored by OSR
>
> Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev
>
> OSR is HIRING!! See http://www.osr.com/careers
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>

What os are you running the debugger on? What version of the debugger are you running? Iirc there is a wdfkd.dll in the kit, you want to use that version.

d

Bent from my phone


From: Matt Jacobsenmailto:xxxxx
Sent: ?4/?1/?2015 8:01 PM
To: Windows System Software Devs Interest Listmailto:xxxxx
Subject: Re: [ntdev] WdfRequestUnmarkCanc?elable results in BSOD (continued)

Thanks for the quick reply. That command didn’t seem to do anything meaningful.

10: kd> !wdfkd.wdflogdump riffaqq
c0000005 Exception in wdfkd.wdflogdump debugger extension.
PC: 000000006b9f942b VA: 0000000000000000 R/W: 0 Parameter: 000000000001003f<br><br>I tried it with just the driver name "riffa", but it resulted in the same:<br><br>10: kd&gt; !wdfkd.wdflogdump riffa<br>c0000005 Exception in wdfkd.wdflogdump debugger extension.<br> PC: 000000006b9f942b VA: 0000000000000000 R/W: 0 Parameter: 000000000001003f

On Wed, Apr 1, 2015 at 5:56 PM, Doron Holan > wrote:
!wdfkd.wdflogdump riffaqq will tell you what is going wrong

d

Bent from my phone
________________________________
From: xxxxx@gmail.commailto:xxxxx
Sent: ?4/?1/?2015 5:43 PM
To: Windows System Software Devs Interest Listmailto:xxxxx
Subject: [ntdev] WdfRequestUnmarkCanc?elable results in BSOD (continued)

I can’t seem to locate the original thread I started last month. So I’ll start a new one here.

I have an IOCTL based DMA driver that I wrote for interfacing with PCIe FPGAs. It’s for Win7 and built using the KMDF APIs. It works well and is reliable until I add support for IO cancellation. Once I add the WdfRequestMarkCancelableEx, WdfRequestUnmarkCancelable calls I get the BSOD .

The Minidump log when I have driver verifier turned on (as well as KMDF VerifyOn set to 1) is below.

CUSTOMER_CRASH_COUNT: 1

DEFAULT_BUCKET_ID: VERIFIER_ENABLED_VISTA_MINIDUMP

BUGCHECK_STR: 0x1E

PROCESS_NAME: svchost.exe

CURRENT_IRQL: 2

TAG_NOT_DEFINED_c000000f: FFFFF880032FFFB0

EXCEPTION_RECORD: fffff880032ff838 – (.exr 0xfffff880032ff838)
ExceptionAddress: fffff80002c7ccd0 (nt!DbgBreakPoint)
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 1
Parameter[0]: 0000000000000000

TRAP_FRAME: fffff880032ff8e0 – (.trap 0xfffff880032ff8e0)
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed or incorrect.
rax=fffff880032ffa78 rbx=0000000000000000 rcx=fffff98002aaafd0
rdx=fffff98002aaafd0 rsi=0000000000000000 rdi=0000000000000000
rip=fffff80002c7ccd1 rsp=fffff880032ffa78 rbp=fffff880032ffb02
r8=0000000000000000 r9=fffff88000ede610 r10=7efefefefefeff40
r11=8101010101010100 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl nz na pe nc
nt!DbgBreakPoint+0x1:
fffff80002c7ccd1 c3 ret<br>Resetting default scope<br><br>LAST_CONTROL_TRANSFER: from fffff80002c7c8be to fffff80002c84e90<br><br>STACK_TEXT:<br>fffff880032fe918 fffff80002c7c8be : fffffa80199bc580 fffff88000c0bf6b fffff880032ff090 fffff80002cb0a00 : nt!KeBugCheck<br>fffff880032fe920 fffff80002cb06cd : fffff80002e95398 fffff80002dce22c fffff80002c10000 fffff880032ff838 : nt!KiKernelCalloutExceptionHandler+0xe<br>fffff880032fe950 fffff80002caf4a5 : fffff80002dd62c4 fffff880032fe9c8 fffff880032ff838 fffff80002c10000 : nt!RtlpExecuteHandlerForException+0xd<br>fffff880032fe980 fffff80002cc0431 : fffff880032ff838 fffff880032ff090 fffff88000000000 00000000c0000010 : nt!RtlDispatchException+0x415<br>fffff880032ff060 fffff80002c84542 : fffff880032ff838 0000000000000000 fffff880032ff8e0 fffff98002aaae40 : nt!KiDispatchException+0x135<br>fffff880032ff700 fffff80002c82374 : 0000000000000000 fffff880032ff960 00000000c0000010 fffff98002aaae40 : nt!KiExceptionDispatch+0xc2<br>fffff880032ff8e0 fffff80002c7ccd1 : fffff88000efe0bd fffff98002aaafd0 fffff98002aaafd0 0000000000000000 : nt!KiBreakpointTrap+0xf4<br>fffff880032ffa78 fffff88000efe0bd : fffff98002aaafd0 fffff98002aaafd0 0000000000000000 fffff88000ede610 : nt!DbgBreakPoint+0x1<br>fffff880032ffa80 fffff88000eff691 : 0000000000000000 fffff98002aaae40 fffff98002aaae40 fffff9800c722e60 : Wdf01000!FxRequest::Vf_VerifyRequestIsCancelable+0x79<br>fffff880032ffad0 fffff88000e5dbcc : 0000000000000002 fffff9800c722e60 fffff880032ffb50 fffff88000000008 : Wdf01000!FxIoQueue::Vf_VerifyRequestCancelable+0x99<br>fffff880032ffb10 fffff88000e68685 : ffff9d59b1850b10 fffff9800c722e60 0000067ff38dd198 0000000000000022 : Wdf01000!FxIoQueue::RequestCancelable+0x3c<br>fffff880032ffb80 fffff880061a821b : fffff9800c722e60 0000067ffd4db1b8 fffff98002b24e40 fffffa801bf8049c : Wdf01000!imp_WdfRequestUnmarkCancelable+0x115<br>fffff880032ffbe0 fffff880061a6a22 : 0000067ff38dd198 fffffa801bf8049c fffff880061a9c70 fffffa801bf8030c : riffa!WdfRequestUnmarkCancelable+0x1b [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h @ 775]<br>fffff880032ffc10 fffff880061a7d6c : fffffa801bf802d0 fffff80000000000 fffff88000000000 fffffa801bf8030c : riffa!RiffaCompleteRequest+0xa2 [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1462]<br>fffff880032ffc70 fffff880061a5252 : fffffa801bf802d0 fffff88000000000 fffff88000000001 fffffa8000000000 : riffa!RiffaTransactionComplete+0x10c [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1907]<br>fffff880032ffcc0 fffff88000ed96d3 : 0000067ffd4db1b8 0000057fe407ffd8 000000004e54241d 000000004559db6a : riffa!RiffaEvtInterruptDpc+0x622 [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 878]<br>fffff880032ffed0 fffff80002c907ac : fffff880032d0180 fffff880032d0180 fffff98002b24ed8 0000000000000042 : Wdf01000!FxInterrupt::DpcHandler+0xc3<br>fffff880032fff00 fffff80002c87925 : 0000000000000000 fffffa8019cdb300 0000000000000000 fffff88000ed9840 : nt!KiRetireDpcList+0x1bc<br>fffff880032fffb0 fffff80002c8773c : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KxRetireDpcList+0x5<br>fffff880063657e0 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KiDispatchInterruptContinue<br><br>STACK_COMMAND: kb<br><br>FOLLOWUP_IP:<br>riffa!WdfRequestUnmarkCancelable+1b [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h @ 775]<br>fffff880061a821b 4883c428 add rsp,28h

FAULTING_SOURCE_LINE: c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h

FAULTING_SOURCE_FILE: c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h

FAULTING_SOURCE_LINE_NUMBER: 775

FAULTING_SOURCE_CODE:
771: WDFREQUEST Request
772: )
773: {
774: return ((PFN_WDFREQUESTUNMARKCANCELABLE) WdfFunctions[WdfRequestUnmarkCancelableTableIndex])(WdfDriverGlobals, Request);
> 775: }
776:
777: //
778: // WDF Function: WdfRequestIsCanceled
779: //
780: typedef

SYMBOL_STACK_INDEX: c

SYMBOL_NAME: riffa!WdfRequestUnmarkCancelable+1b

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: riffa

IMAGE_NAME: riffa.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 54e4c333

FAILURE_BUCKET_ID: X64_0x1E_VRF_riffa!WdfRequestUnmarkCancelable+1b

BUCKET_ID: X64_0x1E_VRF_riffa!WdfRequestUnmarkCancelable+1b

Followup: MachineOwner

---------------------------------
It seems to suggest that the call to WdfRequestUnmarkCancelable in my RiffaTransactionComplete function is to blame. OK. But my understanding is that I need to call WdfRequestUnmarkCancelable on every WDFREQUEST that I call WdfRequestMarkCancelable. According to the WdfRequestUnmarkCancelable MSDN page (https://msdn.microsoft.com/en-us/library/windows/hardware/ff550035(v=vs.85).aspx), this must be done everywhere except the EvtRequestCancel callback.

The general flow of things in my driver:

-> RiffaEvtIoDeviceControl()
// This is the entry point
-> RiffaIoctlSend()
// Save the WDFREQUEST in a field on the PDEVICE_EXTENSION object.
// Start a DMA transfer.
// Call WdfRequestMarkCancelableEx() with the WDFREQUEST and own EvtRequestCancel callback called RiffaEvtRequestCancel.

The driver waits for an interrupt to signal the end of the DMA transfer.

-> RiffaEvtInterruptDpc()
// Interrupt handler
-> RiffaTransactionComplete()
// Ends the DMA transfer, releases the DMA transaction object.
-> RiffaCompleteRequest()
// Gets WDFREQUEST off the PDEVICE_EXTENSION object. Checks if it’s null. If null the request was cancelled and this does nothing. If not null, sets the field on the PDEVICE_EXTENSION to null and calls WdfRequestUnmarkCancelable(), followed by WdfRequestCompleteWithInformation().

If ever invoked, the EvtRequestCancel callback, RiffaEvtRequestCancel, sets the WDFREQUEST field on the PDEVICE_EXTENSION to null and calls WdfRequestCompleteWithInformation().

It’s a pretty straightforward/simple driver modeled after the PLX9x5x driver example. I have yet been able to determine what’s causing this problem. The only thing I do know is that it only seems to happen when issuing a lot of back to back invocations. Stepping through invocations with a debugger seems to slow things down enough to prevent whatever’s going on.

I’ll post the relevant function bodies in a follow up post.

I’ll add a few extra detail and suspicions. The suspicions about possible causes stem from other somewhat related posts I’ve found. But as of yet, I’ve been unable to identify these ideas as the culprit.

1) The driver runs flawlessly without WdfRequestMarkCancelable & WdfRequestUnmarkCancelable. With low frequency and high frequency back to back invocations. But I need to be able to cancel the IO request. So I’m stuck using WdfRequestMarkCancelable & WdfRequestUnmarkCancelable.

2) Someone had a similar problem and discovered that the WDFREQUEST objects were being reused behind the scenes and that person’s driver was failing to call WdfRequestUnmarkCancelable on one of the code paths. His error was similar but was being raised when calling WdfRequestMarkCancelable on a WDFREQUEST that was presumably still marked cancelable. I don’t think this is what’s going on here, but knowing that the WDFREQUESTS are being used is useful.

3) In my initial post on this, someone vaguely suggested that the WDFREQUEST might be non-null on the PDEVICE_EXTENSION but that somehow the “underlying request” object" might have been completed. I don’t see how this could happen as both code paths that complete this WDFREQUEST mark it as null before doing so. This suggestion was a bit vague, so I don’t really know what would cause such a situation. If you do, please enlighten me.

Any ideas would be appreciated. Thanks.

Matt


NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer


NTDEV is sponsored by OSR

Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev

OSR is HIRING!! See http://www.osr.com/careers

For our schedule of WDF, WDM, debugging and other seminars visit:
http://www.osr.com/seminars

To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer

— NTDEV is sponsored by OSR Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev OSR is HIRING!! See http://www.osr.com/careers For our schedule of WDF, WDM, debugging and other seminars visit: http://www.osr.com/seminars To unsubscribe, visit the List Server section of OSR Online at http://www.osronline.com/page.cfm?name=ListServer</mailto:xxxxx></mailto:xxxxx></mailto:xxxxx></mailto:xxxxx>

The debugger is running on Win 7 Professional 32 bit. The version of the
debugger is 6.2.9200.16384 x86. It’s the debugger that came with the WDK
7600.16385.1. Is there a dll that I need to load into the debugger to get
the symbols or something? I am running the debugger on a minidump of the
crash from a Win 7 64 bit machine that had verifier turned on and KMDF
VerifierOn set to 1 (if that helps).

Thanks,
Matt

On Wed, Apr 1, 2015 at 8:16 PM, Doron Holan
wrote:

> What os are you running the debugger on? What version of the debugger
> are you running? Iirc there is a wdfkd.dll in the kit, you want to use that
> version.
>
> d
>
> Bent from my phone
> ------------------------------
> From: Matt Jacobsen
> Sent: ‎4/‎1/‎2015 8:01 PM
> To: Windows System Software Devs Interest List
> Subject: Re: [ntdev] WdfRequestUnmarkCanc?elable results in BSOD
> (continued)
>
> Thanks for the quick reply. That command didn’t seem to do anything
> meaningful.
>
> 10: kd> !wdfkd.wdflogdump riffaqq
> c0000005 Exception in wdfkd.wdflogdump debugger extension.
> PC: 000000006b9f942b VA: 0000000000000000 R/W: 0 Parameter:
> 000000000001003f<br>&gt;<br>&gt; I tried it with just the driver name "riffa", but it resulted in the<br>&gt; same:<br>&gt;<br>&gt; 10: kd&gt; !wdfkd.wdflogdump riffa<br>&gt; c0000005 Exception in wdfkd.wdflogdump debugger extension.<br>&gt; PC: 000000006b9f942b VA: 0000000000000000 R/W: 0 Parameter:<br>&gt; 000000000001003f
>
>
> On Wed, Apr 1, 2015 at 5:56 PM, Doron Holan
> wrote:
>
>> !wdfkd.wdflogdump riffaqq will tell you what is going wrong
>>
>> d
>>
>> Bent from my phone
>> ------------------------------
>> From: xxxxx@gmail.com
>> Sent: ‎4/‎1/‎2015 5:43 PM
>> To: Windows System Software Devs Interest List
>> Subject: [ntdev] WdfRequestUnmarkCanc?elable results in BSOD (continued)
>>
>> I can’t seem to locate the original thread I started last month. So
>> I’ll start a new one here.
>>
>> I have an IOCTL based DMA driver that I wrote for interfacing with PCIe
>> FPGAs. It’s for Win7 and built using the KMDF APIs. It works well and is
>> reliable until I add support for IO cancellation. Once I add the
>> WdfRequestMarkCancelableEx, WdfRequestUnmarkCancelable calls I get the BSOD
>> .
>>
>> The Minidump log when I have driver verifier turned on (as well as KMDF
>> VerifyOn set to 1) is below.
>>
>> CUSTOMER_CRASH_COUNT: 1
>>
>> DEFAULT_BUCKET_ID: VERIFIER_ENABLED_VISTA_MINIDUMP
>>
>> BUGCHECK_STR: 0x1E
>>
>> PROCESS_NAME: svchost.exe
>>
>> CURRENT_IRQL: 2
>>
>> TAG_NOT_DEFINED_c000000f: FFFFF880032FFFB0
>>
>> EXCEPTION_RECORD: fffff880032ff838 – (.exr 0xfffff880032ff838)
>> ExceptionAddress: fffff80002c7ccd0 (nt!DbgBreakPoint)
>> ExceptionCode: 80000003 (Break instruction exception)
>> ExceptionFlags: 00000000
>> NumberParameters: 1
>> Parameter[0]: 0000000000000000
>>
>> TRAP_FRAME: fffff880032ff8e0 – (.trap 0xfffff880032ff8e0)
>> NOTE: The trap frame does not contain all registers.
>> Some register values may be zeroed or incorrect.
>> rax=fffff880032ffa78 rbx=0000000000000000 rcx=fffff98002aaafd0
>> rdx=fffff98002aaafd0 rsi=0000000000000000 rdi=0000000000000000
>> rip=fffff80002c7ccd1 rsp=fffff880032ffa78 rbp=fffff880032ffb02
>> r8=0000000000000000 r9=fffff88000ede610 r10=7efefefefefeff40
>> r11=8101010101010100 r12=0000000000000000 r13=0000000000000000
>> r14=0000000000000000 r15=0000000000000000
>> iopl=0 nv up ei pl nz na pe nc
>> nt!DbgBreakPoint+0x1:
>> fffff80002c7ccd1 c3 ret<br>&gt;&gt; Resetting default scope<br>&gt;&gt;<br>&gt;&gt; LAST_CONTROL_TRANSFER: from fffff80002c7c8be to fffff80002c84e90<br>&gt;&gt;<br>&gt;&gt; STACK_TEXT:<br>&gt;&gt; fffff880032fe918 fffff80002c7c8be : fffffa80199bc580 fffff88000c0bf6b<br>&gt;&gt; fffff880032ff090 fffff80002cb0a00 : nt!KeBugCheck<br>&gt;&gt; fffff880032fe920 fffff80002cb06cd : fffff80002e95398 fffff80002dce22c<br>&gt;&gt; fffff80002c10000 fffff880032ff838 : nt!KiKernelCalloutExceptionHandler+0xe<br>&gt;&gt; fffff880032fe950 fffff80002caf4a5 : fffff80002dd62c4 fffff880032fe9c8<br>&gt;&gt; fffff880032ff838 fffff80002c10000 : nt!RtlpExecuteHandlerForException+0xd<br>&gt;&gt; fffff880032fe980 fffff80002cc0431 : fffff880032ff838 fffff880032ff090<br>&gt;&gt; fffff88000000000 00000000c0000010 : nt!RtlDispatchException+0x415<br>&gt;&gt; fffff880032ff060 fffff80002c84542 : fffff880032ff838 0000000000000000<br>&gt;&gt; fffff880032ff8e0 fffff98002aaae40 : nt!KiDispatchException+0x135<br>&gt;&gt; fffff880032ff700 fffff80002c82374 : 0000000000000000 fffff880032ff960<br>&gt;&gt; 00000000c0000010 fffff98002aaae40 : nt!KiExceptionDispatch+0xc2<br>&gt;&gt; fffff880032ff8e0 fffff80002c7ccd1 : fffff88000efe0bd fffff98002aaafd0<br>&gt;&gt; fffff98002aaafd0 0000000000000000 : nt!KiBreakpointTrap+0xf4<br>&gt;&gt; fffff880032ffa78 fffff88000efe0bd : fffff98002aaafd0 fffff98002aaafd0<br>&gt;&gt; 0000000000000000 fffff88000ede610 : nt!DbgBreakPoint+0x1<br>&gt;&gt; fffff880032ffa80 fffff88000eff691 : 0000000000000000 fffff98002aaae40<br>&gt;&gt; fffff98002aaae40 fffff9800c722e60 :<br>&gt;&gt; Wdf01000!FxRequest::Vf_VerifyRequestIsCancelable+0x79<br>&gt;&gt; fffff880032ffad0 fffff88000e5dbcc : 0000000000000002 fffff9800c722e60<br>&gt;&gt; fffff880032ffb50 fffff88000000008 :<br>&gt;&gt; Wdf01000!FxIoQueue::Vf_VerifyRequestCancelable+0x99<br>&gt;&gt; fffff880032ffb10 fffff88000e68685 : ffff9d59b1850b10 fffff9800c722e60<br>&gt;&gt; 0000067ff38dd198 0000000000000022 :<br>&gt;&gt; Wdf01000!FxIoQueue::RequestCancelable+0x3c<br>&gt;&gt; fffff880032ffb80 fffff880061a821b : fffff9800c722e60 0000067ffd4db1b8<br>&gt;&gt; fffff98002b24e40 fffffa801bf8049c :<br>&gt;&gt; Wdf01000!imp_WdfRequestUnmarkCancelable+0x115<br>&gt;&gt; fffff880032ffbe0 fffff880061a6a22 : 0000067ff38dd198 fffffa801bf8049c<br>&gt;&gt; fffff880061a9c70 fffffa801bf8030c : riffa!WdfRequestUnmarkCancelable+0x1b<br>&gt;&gt; [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h @ 775]<br>&gt;&gt; fffff880032ffc10 fffff880061a7d6c : fffffa801bf802d0 fffff80000000000<br>&gt;&gt; fffff88000000000 fffffa801bf8030c : riffa!RiffaCompleteRequest+0xa2<br>&gt;&gt; [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1462]<br>&gt;&gt; fffff880032ffc70 fffff880061a5252 : fffffa801bf802d0 fffff88000000000<br>&gt;&gt; fffff88000000001 fffffa8000000000 : riffa!RiffaTransactionComplete+0x10c<br>&gt;&gt; [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1907]<br>&gt;&gt; fffff880032ffcc0 fffff88000ed96d3 : 0000067ffd4db1b8 0000057fe407ffd8<br>&gt;&gt; 000000004e54241d 000000004559db6a : riffa!RiffaEvtInterruptDpc+0x622<br>&gt;&gt; [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 878]<br>&gt;&gt; fffff880032ffed0 fffff80002c907ac : fffff880032d0180 fffff880032d0180<br>&gt;&gt; fffff98002b24ed8 0000000000000042 : Wdf01000!FxInterrupt::DpcHandler+0xc3<br>&gt;&gt; fffff880032fff00 fffff80002c87925 : 0000000000000000 fffffa8019cdb300<br>&gt;&gt; 0000000000000000 fffff88000ed9840 : nt!KiRetireDpcList+0x1bc<br>&gt;&gt; fffff880032fffb0 fffff80002c8773c : 0000000000000000 0000000000000000<br>&gt;&gt; 0000000000000000 0000000000000000 : nt!KxRetireDpcList+0x5<br>&gt;&gt; fffff880063657e0 0000000000000000 : 0000000000000000 0000000000000000<br>&gt;&gt; 0000000000000000 0000000000000000 : nt!KiDispatchInterruptContinue<br>&gt;&gt;<br>&gt;&gt;<br>&gt;&gt; STACK_COMMAND: kb<br>&gt;&gt;<br>&gt;&gt; FOLLOWUP_IP:<br>&gt;&gt; riffa!WdfRequestUnmarkCancelable+1b<br>&gt;&gt; [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h @ 775]<br>&gt;&gt; fffff880061a821b 4883c428 add rsp,28h
>>
>> FAULTING_SOURCE_LINE:
>> c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h
>>
>> FAULTING_SOURCE_FILE:
>> c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h
>>
>> FAULTING_SOURCE_LINE_NUMBER: 775
>>
>> FAULTING_SOURCE_CODE:
>> 771: WDFREQUEST Request
>> 772: )
>> 773: {
>> 774: return ((PFN_WDFREQUESTUNMARKCANCELABLE)
>> WdfFunctions[WdfRequestUnmarkCancelableTableIndex])(WdfDriverGlobals,
>> Request);
>> > 775: }
>> 776:
>> 777: //
>> 778: // WDF Function: WdfRequestIsCanceled
>> 779: //
>> 780: typedef
>>
>>
>> SYMBOL_STACK_INDEX: c
>>
>> SYMBOL_NAME: riffa!WdfRequestUnmarkCancelable+1b
>>
>> FOLLOWUP_NAME: MachineOwner
>>
>> MODULE_NAME: riffa
>>
>> IMAGE_NAME: riffa.sys
>>
>> DEBUG_FLR_IMAGE_TIMESTAMP: 54e4c333
>>
>> FAILURE_BUCKET_ID: X64_0x1E_VRF_riffa!WdfRequestUnmarkCancelable+1b
>>
>> BUCKET_ID: X64_0x1E_VRF_riffa!WdfRequestUnmarkCancelable+1b
>>
>> Followup: MachineOwner
>>
>> ---------------------------------
>> It seems to suggest that the call to WdfRequestUnmarkCancelable in my
>> RiffaTransactionComplete function is to blame. OK. But my understanding is
>> that I need to call WdfRequestUnmarkCancelable on every WDFREQUEST that I
>> call WdfRequestMarkCancelable. According to the WdfRequestUnmarkCancelable
>> MSDN page (
>> https://msdn.microsoft.com/en-us/library/windows/hardware/ff550035(v=vs.85).aspx),
>> this must be done everywhere except the EvtRequestCancel callback.
>>
>> The general flow of things in my driver:
>>
>> -> RiffaEvtIoDeviceControl()
>> // This is the entry point
>> -> RiffaIoctlSend()
>> // Save the WDFREQUEST in a field on the PDEVICE_EXTENSION object.
>> // Start a DMA transfer.
>> // Call WdfRequestMarkCancelableEx() with the WDFREQUEST and own
>> EvtRequestCancel callback called RiffaEvtRequestCancel.
>>
>> The driver waits for an interrupt to signal the end of the DMA transfer.
>>
>> -> RiffaEvtInterruptDpc()
>> // Interrupt handler
>> -> RiffaTransactionComplete()
>> // Ends the DMA transfer, releases the DMA transaction object.
>> -> RiffaCompleteRequest()
>> // Gets WDFREQUEST off the PDEVICE_EXTENSION object. Checks if it’s
>> null. If null the request was cancelled and this does nothing. If not null,
>> sets the field on the PDEVICE_EXTENSION to null and calls
>> WdfRequestUnmarkCancelable(), followed by
>> WdfRequestCompleteWithInformation().
>>
>> If ever invoked, the EvtRequestCancel callback, RiffaEvtRequestCancel,
>> sets the WDFREQUEST field on the PDEVICE_EXTENSION to null and calls
>> WdfRequestCompleteWithInformation().
>>
>> It’s a pretty straightforward/simple driver modeled after the PLX9x5x
>> driver example. I have yet been able to determine what’s causing this
>> problem. The only thing I do know is that it only seems to happen when
>> issuing a lot of back to back invocations. Stepping through invocations
>> with a debugger seems to slow things down enough to prevent whatever’s
>> going on.
>>
>> I’ll post the relevant function bodies in a follow up post.
>>
>> I’ll add a few extra detail and suspicions. The suspicions about possible
>> causes stem from other somewhat related posts I’ve found. But as of yet,
>> I’ve been unable to identify these ideas as the culprit.
>>
>> 1) The driver runs flawlessly without WdfRequestMarkCancelable &
>> WdfRequestUnmarkCancelable. With low frequency and high frequency back to
>> back invocations. But I need to be able to cancel the IO request. So I’m
>> stuck using WdfRequestMarkCancelable & WdfRequestUnmarkCancelable.
>>
>> 2) Someone had a similar problem and discovered that the WDFREQUEST
>> objects were being reused behind the scenes and that person’s driver was
>> failing to call WdfRequestUnmarkCancelable on one of the code paths. His
>> error was similar but was being raised when calling
>> WdfRequestMarkCancelable on a WDFREQUEST that was presumably still marked
>> cancelable. I don’t think this is what’s going on here, but knowing that
>> the WDFREQUESTS are being used is useful.
>>
>> 3) In my initial post on this, someone vaguely suggested that the
>> WDFREQUEST might be non-null on the PDEVICE_EXTENSION but that somehow the
>> “underlying request” object" might have been completed. I don’t see how
>> this could happen as both code paths that complete this WDFREQUEST mark it
>> as null before doing so. This suggestion was a bit vague, so I don’t really
>> know what would cause such a situation. If you do, please enlighten me.
>>
>> Any ideas would be appreciated. Thanks.
>>
>> Matt
>>
>>
>> —
>> NTDEV is sponsored by OSR
>>
>> Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev
>>
>> OSR is HIRING!! See http://www.osr.com/careers
>>
>> For our schedule of WDF, WDM, debugging and other seminars visit:
>> http://www.osr.com/seminars
>>
>> To unsubscribe, visit the List Server section of OSR Online at
>> http://www.osronline.com/page.cfm?name=ListServer
>>
>> —
>> NTDEV is sponsored by OSR
>>
>> Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev
>>
>> OSR is HIRING!! See http://www.osr.com/careers
>>
>> For our schedule of WDF, WDM, debugging and other seminars visit:
>> http://www.osr.com/seminars
>>
>> To unsubscribe, visit the List Server section of OSR Online at
>> http://www.osronline.com/page.cfm?name=ListServer
>>
>
> — NTDEV is sponsored by OSR Visit the list at:
> http://www.osronline.com/showlists.cfm?list=ntdev OSR is HIRING!! See
> http://www.osr.com/careers For our schedule of WDF, WDM, debugging and
> other seminars visit: http://www.osr.com/seminars To unsubscribe, visit
> the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>
> —
> NTDEV is sponsored by OSR
>
> Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev
>
> OSR is HIRING!! See http://www.osr.com/careers
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>

On Apr 1, 2015, at 5:44 PM, xxxxx@gmail.com wrote:

I have an IOCTL based DMA driver that I wrote for interfacing with PCIe FPGAs. It’s for Win7 and built using the KMDF APIs. It works well and is reliable until I add support for IO cancellation. Once I add the WdfRequestMarkCancelableEx, WdfRequestUnmarkCancelable calls I get the BSOD .

It seems to suggest that the call to WdfRequestUnmarkCancelable in my RiffaTransactionComplete function is to blame. OK. But my understanding is that I need to call WdfRequestUnmarkCancelable on every WDFREQUEST that I call WdfRequestMarkCancelable. According to the WdfRequestUnmarkCancelable MSDN page (https://msdn.microsoft.com/en-us/library/windows/hardware/ff550035(v=vs.85).aspx), this must be done everywhere except the EvtRequestCancel callback.

Well, you need call it for every request that was marked. The implication from the stack dump is that you tried to Unmark a request that was not current marked as cancelable. Now, I can’t tell whether the request had been marked and then unmarked, or never marked at all.

The general flow of things in my driver:

-> RiffaEvtIoDeviceControl()
// This is the entry point
-> RiffaIoctlSend()
// Save the WDFREQUEST in a field on the PDEVICE_EXTENSION object.
// Start a DMA transfer.
// Call WdfRequestMarkCancelableEx() with the WDFREQUEST and own EvtRequestCancel callback called RiffaEvtRequestCancel.

Why don’t you just use a manual queue? That way, you don’t have to deal with the cancelable status at all.

Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

On Apr 1, 2015, at 5:57 PM, xxxxx@gmail.com wrote:

// Complete the send request
InterlockedExchange(&DevExt->Chnl[Chnl].InUse, 0);
RiffaCompleteRequest(DevExt, Chnl, Status);

You’re doing those in the wrong order. As soon as you set InUse to 0, your original ioctl handler is free to overwrite that channel’s request with a different one. If it happens to do so before you get into the completion routine, it will complete the wrong request. You should complete it, and then release InUse.

Again, wouldn’t this all be easier if you had a manual I/O queue for each channel? Put all of your data in a context structure for the request. Every time a DMA completes, you can pop the next one, instead of just rejecting requests when one is already in progress.

Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

Tim, thanks for pointing this out. I removed the InUse entirely and just
make sure there’s no code after the WdfRequestComplete calls. Yes, there’s
no protection for multiple threads trying to enter simultaneously, but I
can deal with that later after this bug is resolved.

I’m not sure I fully understand how to use a manual queue. Any example I
could look at? Your description sounds a lot like what I’m already doing.
I’m saving the WDFREQUEST in the PDEVICE_EXTENSION upon entering the
driver. Then when I receive the “DMA done” interrupt I retrieve the
WDFREQUEST from the PDEVICE_EXTENSION and complete it.

Lastly, after reorganizing the driver to perform the WdfRequestComplete as
the absolute last operation from every code path, I’m encountering a
slightly different error. From the minidump:

CUSTOMER_CRASH_COUNT: 1
DEFAULT_BUCKET_ID: VERIFIER_ENABLED_VISTA_MINIDUMP
BUGCHECK_STR: 0x1E
PROCESS_NAME: Project1.exe
CURRENT_IRQL: 2
TAG_NOT_DEFINED_c000000f: FFFFF880032FFFB0
EXCEPTION_RECORD: fffff880032ff8b8 – (.exr 0xfffff880032ff8b8)
ExceptionAddress: fffff80002c79cd0 (nt!DbgBreakPoint)
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 1
Parameter[0]: 0000000000000000
TRAP_FRAME: fffff880032ff960 – (.trap 0xfffff880032ff960)
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed or incorrect.
rax=fffff880032ffaf8 rbx=0000000000000000 rcx=fffff98002decfd0
rdx=fffff98002decfd0 rsi=0000000000000000 rdi=0000000000000000
rip=fffff80002c79cd1 rsp=fffff880032ffaf8 rbp=fffff880032ffb02
r8=0000000000000000 r9=fffff88000f97610 r10=7efefefefefeff40
r11=8101010101010100 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl nz na pe nc
nt!DbgBreakPoint+0x1:
fffff80002c79cd1 c3 ret Resetting default scope LAST_CONTROL_TRANSFER: from fffff80002c798be to fffff80002c81e90 STACK_TEXT: fffff880032fe998 fffff80002c798be : 000000000000003c fffff88000fd2c74 fffff880032ff110 fffff80002cada00 : nt!KeBugCheck fffff880032fe9a0 fffff80002cad6cd : fffff80002e92398 fffff80002dcb22c fffff80002c0d000 fffff880032ff8b8 : nt!KiKernelCalloutExceptionHandler+0xe fffff880032fe9d0 fffff80002cac4a5 : fffff80002dd32c4 fffff880032fea48 fffff880032ff8b8 fffff80002c0d000 : nt!RtlpExecuteHandlerForException+0xd fffff880032fea00 fffff80002cbd431 : fffff880032ff8b8 fffff880032ff110 fffff88000000000 00000000c0000010 : nt!RtlDispatchException+0x415 fffff880032ff0e0 fffff80002c81542 : fffff880032ff8b8 0000000000000000 fffff880032ff960 fffff98002dece40 : nt!KiDispatchException+0x135 fffff880032ff780 fffff80002c7f374 : fffffa8020591470 fffff8000311eb31 0000000000000000 fffff880032ffb00 : nt!KiExceptionDispatch+0xc2 fffff880032ff960 fffff80002c79cd1 : fffff88000fb70bd fffff98002decfd0 fffff98002decfd0 0000000000000000 : nt!KiBreakpointTrap+0xf4 fffff880032ffaf8 fffff88000fb70bd : fffff98002decfd0 fffff98002decfd0 0000000000000000 fffff88000f97610 : nt!DbgBreakPoint+0x1 fffff880032ffb00 fffff88000fb8691 : 0000000000000000 fffff98002dece40 fffff98002dece40 fffff98009d90e60 : Wdf01000!FxRequest::Vf_VerifyRequestIsCancelable+0x79 fffff880032ffb50 fffff88000f16bcc : 0000000000000002 fffff98009d90e60 fffff880032ffbd0 fffff88000000008 : Wdf01000!FxIoQueue::Vf_VerifyRequestCancelable+0x99 fffff880032ffb90 fffff88000f21685 : fffffa801c04d2d0 fffff98009d90e60 0000067ff626f198 fffff80002cbd7e8 : Wdf01000!FxIoQueue::RequestCancelable+0x3c fffff880032ffc00 fffff880061ba552 : fffff98009d90e60 0000000000000000 0000000000000000 0000067ff626f198 : Wdf01000!imp_WdfRequestUnmarkCancelable+0x115 fffff880032ffc60 fffff88000000001 : 0000000000000000 0000000000000034 fffff880032ffded fffff880061b988b : riffa!RiffaIoctlSend+0x142 [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1006] fffff880032ffce0 0000000000000000 : 0000000000000034 fffff880032ffded fffff880061b988b 0000000000000000 : 0xfffff88000000001

STACK_COMMAND: kb
FOLLOWUP_IP:
riffa!RiffaIoctlSend+142
[c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1006]
fffff880`061ba552 ?? ???
FAULTING_SOURCE_LINE:
c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c
FAULTING_SOURCE_FILE:
c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c
FAULTING_SOURCE_LINE_NUMBER: 1006
FAULTING_SOURCE_CODE:
1002: return;
1003: }
1004:
1005: // Set the channel number in the request context for
RiffaEvtRequestCancel.

1006: reqExt = RiffaGetRequestContext(Request);
1007: reqExt->Chnl = io->Chnl;
1008:
1009: // Start a send transaction.
1010: if (length) {
1011: // Start a DMA transaction for sending.

SYMBOL_STACK_INDEX: c
SYMBOL_NAME: riffa!RiffaIoctlSend+142
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: riffa
IMAGE_NAME: riffa.sys
DEBUG_FLR_IMAGE_TIMESTAMP: 551f2b56
FAILURE_BUCKET_ID: X64_0x1E_VRF_riffa!RiffaIoctlSend+142
BUCKET_ID: X64_0x1E_VRF_riffa!RiffaIoctlSend+142
Followup: MachineOwner

This would suggest that the PREQUEST_EXTENSION struct I’m using to pass
information to the EvtRequestCancel callback is somehow calling
WdfRequestUnmarkCancelable. Clearly this is going to fail because this is
the entry point into the driver, I haven’t marked the WDFREQUEST
cancellable yet. In fact, I might complete the request before I do so (if
there’s an input validation problem). I don’t know why on earth this call
to get the PREQUEST_EXTENSION would decide to call
WdfRequestUnmarkCancelable on my behalf. There’s no code in this function
that calls WdfRequestUnmarkCancelable . This is complete madness.

Any insights would be appreciated.

Thanks,
Matt

On Wed, Apr 1, 2015 at 11:04 PM, Tim Roberts wrote:

> On Apr 1, 2015, at 5:57 PM, xxxxx@gmail.com wrote:
> >
> > // Complete the send request
> > InterlockedExchange(&DevExt->Chnl[Chnl].InUse, 0);
> > RiffaCompleteRequest(DevExt, Chnl, Status);
>
> You’re doing those in the wrong order. As soon as you set InUse to 0,
> your original ioctl handler is free to overwrite that channel’s request
> with a different one. If it happens to do so before you get into the
> completion routine, it will complete the wrong request. You should
> complete it, and then release InUse.
>
> Again, wouldn’t this all be easier if you had a manual I/O queue for each
> channel? Put all of your data in a context structure for the request.
> Every time a DMA completes, you can pop the next one, instead of just
> rejecting requests when one is already in progress.
> —
> Tim Roberts, xxxxx@probo.com
> Providenza & Boekelheide, Inc.
>
>
> —
> NTDEV is sponsored by OSR
>
> Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev
>
> OSR is HIRING!! See http://www.osr.com/careers
>
> For our schedule of WDF, WDM, debugging and other seminars visit:
> http://www.osr.com/seminars
>
> To unsubscribe, visit the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>

Any ideas on this? According to the stack trace from the minidump the
failing instruction sequence is:

riffa!RiffaIoctlSend –> Wdf01000!imp_WdfRequestUnmarkCancelable

But this is impossible. There is no instruction in RiffaIoctlSend that
would jump to WdfRequestUnmarkCancelable. Moreover the line in source it
says is the problem is a call to get the PREQUEST_EXTENSION. That’s clearly
not causing this. The only thing I can imagine is that the driver code is
corrupt because this stack trace is clearly garbage. To test this, I moved
some lines of code around without changing any behavior, recompiled the
driver, and tested again. The same error and stack trace are encountered,
but this time it says the offending line of code is an if statement
checking if the value of an INT32 is 0 or not. Absolute rubbish!

Is this typical of Windows driver development? I’ve never seen this in
other OS development. Do I need to disable and re-enable the driver
verifier every time I upgrade the driver code? Is there a special dance
that needs to be done? Or sacrificial offering to the Windows driver god?

Thanks,
Matt

On Fri, Apr 3, 2015 at 5:44 PM, Matt Jacobsen
wrote:

> Tim, thanks for pointing this out. I removed the InUse entirely and just
> make sure there’s no code after the WdfRequestComplete calls. Yes, there’s
> no protection for multiple threads trying to enter simultaneously, but I
> can deal with that later after this bug is resolved.
>
> I’m not sure I fully understand how to use a manual queue. Any example I
> could look at? Your description sounds a lot like what I’m already doing.
> I’m saving the WDFREQUEST in the PDEVICE_EXTENSION upon entering the
> driver. Then when I receive the “DMA done” interrupt I retrieve the
> WDFREQUEST from the PDEVICE_EXTENSION and complete it.
>
> Lastly, after reorganizing the driver to perform the WdfRequestComplete as
> the absolute last operation from every code path, I’m encountering a
> slightly different error. From the minidump:
>
> CUSTOMER_CRASH_COUNT: 1
> DEFAULT_BUCKET_ID: VERIFIER_ENABLED_VISTA_MINIDUMP
> BUGCHECK_STR: 0x1E
> PROCESS_NAME: Project1.exe
> CURRENT_IRQL: 2
> TAG_NOT_DEFINED_c000000f: FFFFF880032FFFB0
> EXCEPTION_RECORD: fffff880032ff8b8 – (.exr 0xfffff880032ff8b8)
> ExceptionAddress: fffff80002c79cd0 (nt!DbgBreakPoint)
> ExceptionCode: 80000003 (Break instruction exception)
> ExceptionFlags: 00000000
> NumberParameters: 1
> Parameter[0]: 0000000000000000
> TRAP_FRAME: fffff880032ff960 – (.trap 0xfffff880032ff960)
> NOTE: The trap frame does not contain all registers.
> Some register values may be zeroed or incorrect.
> rax=fffff880032ffaf8 rbx=0000000000000000 rcx=fffff98002decfd0
> rdx=fffff98002decfd0 rsi=0000000000000000 rdi=0000000000000000
> rip=fffff80002c79cd1 rsp=fffff880032ffaf8 rbp=fffff880032ffb02
> r8=0000000000000000 r9=fffff88000f97610 r10=7efefefefefeff40
> r11=8101010101010100 r12=0000000000000000 r13=0000000000000000
> r14=0000000000000000 r15=0000000000000000
> iopl=0 nv up ei pl nz na pe nc
> nt!DbgBreakPoint+0x1:
> fffff80002c79cd1 c3 ret<br>&gt; Resetting default scope<br>&gt; LAST_CONTROL_TRANSFER: from fffff80002c798be to fffff80002c81e90<br>&gt; STACK_TEXT:<br>&gt; fffff880032fe998 fffff80002c798be : 000000000000003c fffff88000fd2c74<br>&gt; fffff880032ff110 fffff80002cada00 : nt!KeBugCheck<br>&gt; fffff880032fe9a0 fffff80002cad6cd : fffff80002e92398 fffff80002dcb22c<br>&gt; fffff80002c0d000 fffff880032ff8b8 : nt!KiKernelCalloutExceptionHandler+0xe<br>&gt; fffff880032fe9d0 fffff80002cac4a5 : fffff80002dd32c4 fffff880032fea48<br>&gt; fffff880032ff8b8 fffff80002c0d000 : nt!RtlpExecuteHandlerForException+0xd<br>&gt; fffff880032fea00 fffff80002cbd431 : fffff880032ff8b8 fffff880032ff110<br>&gt; fffff88000000000 00000000c0000010 : nt!RtlDispatchException+0x415<br>&gt; fffff880032ff0e0 fffff80002c81542 : fffff880032ff8b8 0000000000000000<br>&gt; fffff880032ff960 fffff98002dece40 : nt!KiDispatchException+0x135<br>&gt; fffff880032ff780 fffff80002c7f374 : fffffa8020591470 fffff8000311eb31<br>&gt; 0000000000000000 fffff880032ffb00 : nt!KiExceptionDispatch+0xc2<br>&gt; fffff880032ff960 fffff80002c79cd1 : fffff88000fb70bd fffff98002decfd0<br>&gt; fffff98002decfd0 0000000000000000 : nt!KiBreakpointTrap+0xf4<br>&gt; fffff880032ffaf8 fffff88000fb70bd : fffff98002decfd0 fffff98002decfd0<br>&gt; 0000000000000000 fffff88000f97610 : nt!DbgBreakPoint+0x1<br>&gt; fffff880032ffb00 fffff88000fb8691 : 0000000000000000 fffff98002dece40<br>&gt; fffff98002dece40 fffff98009d90e60 :<br>&gt; Wdf01000!FxRequest::Vf_VerifyRequestIsCancelable+0x79<br>&gt; fffff880032ffb50 fffff88000f16bcc : 0000000000000002 fffff98009d90e60<br>&gt; fffff880032ffbd0 fffff88000000008 :<br>&gt; Wdf01000!FxIoQueue::Vf_VerifyRequestCancelable+0x99<br>&gt; fffff880032ffb90 fffff88000f21685 : fffffa801c04d2d0 fffff98009d90e60<br>&gt; 0000067ff626f198 fffff80002cbd7e8 :<br>&gt; Wdf01000!FxIoQueue::RequestCancelable+0x3c<br>&gt; fffff880032ffc00 fffff880061ba552 : fffff98009d90e60 0000000000000000<br>&gt; 0000000000000000 0000067ff626f198 :<br>&gt; Wdf01000!imp_WdfRequestUnmarkCancelable+0x115<br>&gt; fffff880032ffc60 fffff88000000001 : 0000000000000000 0000000000000034<br>&gt; fffff880032ffded fffff880061b988b : riffa!RiffaIoctlSend+0x142<br>&gt; [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1006]<br>&gt; fffff880032ffce0 0000000000000000 : 0000000000000034 fffff880032ffded<br>&gt; fffff880061b988b 0000000000000000 : 0xfffff88000000001
>
> STACK_COMMAND: kb
> FOLLOWUP_IP:
> riffa!RiffaIoctlSend+142
> [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1006]
> fffff880`061ba552 ?? ???
> FAULTING_SOURCE_LINE:
> c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c
> FAULTING_SOURCE_FILE:
> c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c
> FAULTING_SOURCE_LINE_NUMBER: 1006
> FAULTING_SOURCE_CODE:
> 1002: return;
> 1003: }
> 1004:
> 1005: // Set the channel number in the request context for
> RiffaEvtRequestCancel.
> > 1006: reqExt = RiffaGetRequestContext(Request);
> 1007: reqExt->Chnl = io->Chnl;
> 1008:
> 1009: // Start a send transaction.
> 1010: if (length) {
> 1011: // Start a DMA transaction for sending.
>
> SYMBOL_STACK_INDEX: c
> SYMBOL_NAME: riffa!RiffaIoctlSend+142
> FOLLOWUP_NAME: MachineOwner
> MODULE_NAME: riffa
> IMAGE_NAME: riffa.sys
> DEBUG_FLR_IMAGE_TIMESTAMP: 551f2b56
> FAILURE_BUCKET_ID: X64_0x1E_VRF_riffa!RiffaIoctlSend+142
> BUCKET_ID: X64_0x1E_VRF_riffa!RiffaIoctlSend+142
> Followup: MachineOwner
> ---------
>
> This would suggest that the PREQUEST_EXTENSION struct I’m using to pass
> information to the EvtRequestCancel callback is somehow calling
> WdfRequestUnmarkCancelable. Clearly this is going to fail because this is
> the entry point into the driver, I haven’t marked the WDFREQUEST
> cancellable yet. In fact, I might complete the request before I do so (if
> there’s an input validation problem). I don’t know why on earth this call
> to get the PREQUEST_EXTENSION would decide to call
> WdfRequestUnmarkCancelable on my behalf. There’s no code in this function
> that calls WdfRequestUnmarkCancelable . This is complete madness.
>
> Any insights would be appreciated.
>
> Thanks,
> Matt
>
>
> On Wed, Apr 1, 2015 at 11:04 PM, Tim Roberts wrote:
>
>> On Apr 1, 2015, at 5:57 PM, xxxxx@gmail.com wrote:
>> >
>> > // Complete the send request
>> > InterlockedExchange(&DevExt->Chnl[Chnl].InUse, 0);
>> > RiffaCompleteRequest(DevExt, Chnl, Status);
>>
>> You’re doing those in the wrong order. As soon as you set InUse to 0,
>> your original ioctl handler is free to overwrite that channel’s request
>> with a different one. If it happens to do so before you get into the
>> completion routine, it will complete the wrong request. You should
>> complete it, and then release InUse.
>>
>> Again, wouldn’t this all be easier if you had a manual I/O queue for each
>> channel? Put all of your data in a context structure for the request.
>> Every time a DMA completes, you can pop the next one, instead of just
>> rejecting requests when one is already in progress.
>> —
>> Tim Roberts, xxxxx@probo.com
>> Providenza & Boekelheide, Inc.
>>
>>
>> —
>> NTDEV is sponsored by OSR
>>
>> Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev
>>
>> OSR is HIRING!! See http://www.osr.com/careers
>>
>> For our schedule of WDF, WDM, debugging and other seminars visit:
>> http://www.osr.com/seminars
>>
>> To unsubscribe, visit the List Server section of OSR Online at
>> http://www.osronline.com/page.cfm?name=ListServer
>>
>
>

https://github.com/Microsoft/Windows-driver-frameworks

The source code for KMDF. That might be a better way to get an answer.

Mark Roddy

On Mon, Apr 6, 2015 at 11:15 AM, Matt Jacobsen
wrote:

> Any ideas on this? According to the stack trace from the minidump the
> failing instruction sequence is:
>
> riffa!RiffaIoctlSend –> Wdf01000!imp_WdfRequestUnmarkCancelable
>
> But this is impossible. There is no instruction in RiffaIoctlSend
> that would jump to WdfRequestUnmarkCancelable. Moreover the line in
> source it says is the problem is a call to get the PREQUEST_EXTENSION.
> That’s clearly not causing this. The only thing I can imagine is that the
> driver code is corrupt because this stack trace is clearly garbage. To test
> this, I moved some lines of code around without changing any behavior,
> recompiled the driver, and tested again. The same error and stack trace are
> encountered, but this time it says the offending line of code is an if
> statement checking if the value of an INT32 is 0 or not. Absolute rubbish!
>
> Is this typical of Windows driver development? I’ve never seen this in
> other OS development. Do I need to disable and re-enable the driver
> verifier every time I upgrade the driver code? Is there a special dance
> that needs to be done? Or sacrificial offering to the Windows driver god?
>
> Thanks,
> Matt
>
>
> On Fri, Apr 3, 2015 at 5:44 PM, Matt Jacobsen
> wrote:
>
>> Tim, thanks for pointing this out. I removed the InUse entirely and just
>> make sure there’s no code after the WdfRequestComplete calls. Yes, there’s
>> no protection for multiple threads trying to enter simultaneously, but I
>> can deal with that later after this bug is resolved.
>>
>> I’m not sure I fully understand how to use a manual queue. Any example I
>> could look at? Your description sounds a lot like what I’m already doing.
>> I’m saving the WDFREQUEST in the PDEVICE_EXTENSION upon entering the
>> driver. Then when I receive the “DMA done” interrupt I retrieve the
>> WDFREQUEST from the PDEVICE_EXTENSION and complete it.
>>
>> Lastly, after reorganizing the driver to perform the WdfRequestComplete
>> as the absolute last operation from every code path, I’m encountering a
>> slightly different error. From the minidump:
>>
>> CUSTOMER_CRASH_COUNT: 1
>> DEFAULT_BUCKET_ID: VERIFIER_ENABLED_VISTA_MINIDUMP
>> BUGCHECK_STR: 0x1E
>> PROCESS_NAME: Project1.exe
>> CURRENT_IRQL: 2
>> TAG_NOT_DEFINED_c000000f: FFFFF880032FFFB0
>> EXCEPTION_RECORD: fffff880032ff8b8 – (.exr 0xfffff880032ff8b8)
>> ExceptionAddress: fffff80002c79cd0 (nt!DbgBreakPoint)
>> ExceptionCode: 80000003 (Break instruction exception)
>> ExceptionFlags: 00000000
>> NumberParameters: 1
>> Parameter[0]: 0000000000000000
>> TRAP_FRAME: fffff880032ff960 – (.trap 0xfffff880032ff960)
>> NOTE: The trap frame does not contain all registers.
>> Some register values may be zeroed or incorrect.
>> rax=fffff880032ffaf8 rbx=0000000000000000 rcx=fffff98002decfd0
>> rdx=fffff98002decfd0 rsi=0000000000000000 rdi=0000000000000000
>> rip=fffff80002c79cd1 rsp=fffff880032ffaf8 rbp=fffff880032ffb02
>> r8=0000000000000000 r9=fffff88000f97610 r10=7efefefefefeff40
>> r11=8101010101010100 r12=0000000000000000 r13=0000000000000000
>> r14=0000000000000000 r15=0000000000000000
>> iopl=0 nv up ei pl nz na pe nc
>> nt!DbgBreakPoint+0x1:
>> fffff80002c79cd1 c3 ret<br>&gt;&gt; Resetting default scope<br>&gt;&gt; LAST_CONTROL_TRANSFER: from fffff80002c798be to fffff80002c81e90<br>&gt;&gt; STACK_TEXT:<br>&gt;&gt; fffff880032fe998 fffff80002c798be : 000000000000003c fffff88000fd2c74<br>&gt;&gt; fffff880032ff110 fffff80002cada00 : nt!KeBugCheck<br>&gt;&gt; fffff880032fe9a0 fffff80002cad6cd : fffff80002e92398 fffff80002dcb22c<br>&gt;&gt; fffff80002c0d000 fffff880032ff8b8 : nt!KiKernelCalloutExceptionHandler+0xe<br>&gt;&gt; fffff880032fe9d0 fffff80002cac4a5 : fffff80002dd32c4 fffff880032fea48<br>&gt;&gt; fffff880032ff8b8 fffff80002c0d000 : nt!RtlpExecuteHandlerForException+0xd<br>&gt;&gt; fffff880032fea00 fffff80002cbd431 : fffff880032ff8b8 fffff880032ff110<br>&gt;&gt; fffff88000000000 00000000c0000010 : nt!RtlDispatchException+0x415<br>&gt;&gt; fffff880032ff0e0 fffff80002c81542 : fffff880032ff8b8 0000000000000000<br>&gt;&gt; fffff880032ff960 fffff98002dece40 : nt!KiDispatchException+0x135<br>&gt;&gt; fffff880032ff780 fffff80002c7f374 : fffffa8020591470 fffff8000311eb31<br>&gt;&gt; 0000000000000000 fffff880032ffb00 : nt!KiExceptionDispatch+0xc2<br>&gt;&gt; fffff880032ff960 fffff80002c79cd1 : fffff88000fb70bd fffff98002decfd0<br>&gt;&gt; fffff98002decfd0 0000000000000000 : nt!KiBreakpointTrap+0xf4<br>&gt;&gt; fffff880032ffaf8 fffff88000fb70bd : fffff98002decfd0 fffff98002decfd0<br>&gt;&gt; 0000000000000000 fffff88000f97610 : nt!DbgBreakPoint+0x1<br>&gt;&gt; fffff880032ffb00 fffff88000fb8691 : 0000000000000000 fffff98002dece40<br>&gt;&gt; fffff98002dece40 fffff98009d90e60 :<br>&gt;&gt; Wdf01000!FxRequest::Vf_VerifyRequestIsCancelable+0x79<br>&gt;&gt; fffff880032ffb50 fffff88000f16bcc : 0000000000000002 fffff98009d90e60<br>&gt;&gt; fffff880032ffbd0 fffff88000000008 :<br>&gt;&gt; Wdf01000!FxIoQueue::Vf_VerifyRequestCancelable+0x99<br>&gt;&gt; fffff880032ffb90 fffff88000f21685 : fffffa801c04d2d0 fffff98009d90e60<br>&gt;&gt; 0000067ff626f198 fffff80002cbd7e8 :<br>&gt;&gt; Wdf01000!FxIoQueue::RequestCancelable+0x3c<br>&gt;&gt; fffff880032ffc00 fffff880061ba552 : fffff98009d90e60 0000000000000000<br>&gt;&gt; 0000000000000000 0000067ff626f198 :<br>&gt;&gt; Wdf01000!imp_WdfRequestUnmarkCancelable+0x115<br>&gt;&gt; fffff880032ffc60 fffff88000000001 : 0000000000000000 0000000000000034<br>&gt;&gt; fffff880032ffded fffff880061b988b : riffa!RiffaIoctlSend+0x142<br>&gt;&gt; [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1006]<br>&gt;&gt; fffff880032ffce0 0000000000000000 : 0000000000000034 fffff880032ffded<br>&gt;&gt; fffff880061b988b 0000000000000000 : 0xfffff88000000001
>>
>> STACK_COMMAND: kb
>> FOLLOWUP_IP:
>> riffa!RiffaIoctlSend+142
>> [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1006]
>> fffff880`061ba552 ?? ???
>> FAULTING_SOURCE_LINE:
>> c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c
>> FAULTING_SOURCE_FILE:
>> c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c
>> FAULTING_SOURCE_LINE_NUMBER: 1006
>> FAULTING_SOURCE_CODE:
>> 1002: return;
>> 1003: }
>> 1004:
>> 1005: // Set the channel number in the request context for
>> RiffaEvtRequestCancel.
>> > 1006: reqExt = RiffaGetRequestContext(Request);
>> 1007: reqExt->Chnl = io->Chnl;
>> 1008:
>> 1009: // Start a send transaction.
>> 1010: if (length) {
>> 1011: // Start a DMA transaction for sending.
>>
>> SYMBOL_STACK_INDEX: c
>> SYMBOL_NAME: riffa!RiffaIoctlSend+142
>> FOLLOWUP_NAME: MachineOwner
>> MODULE_NAME: riffa
>> IMAGE_NAME: riffa.sys
>> DEBUG_FLR_IMAGE_TIMESTAMP: 551f2b56
>> FAILURE_BUCKET_ID: X64_0x1E_VRF_riffa!RiffaIoctlSend+142
>> BUCKET_ID: X64_0x1E_VRF_riffa!RiffaIoctlSend+142
>> Followup: MachineOwner
>> ---------
>>
>> This would suggest that the PREQUEST_EXTENSION struct I’m using to pass
>> information to the EvtRequestCancel callback is somehow calling
>> WdfRequestUnmarkCancelable. Clearly this is going to fail because this is
>> the entry point into the driver, I haven’t marked the WDFREQUEST
>> cancellable yet. In fact, I might complete the request before I do so (if
>> there’s an input validation problem). I don’t know why on earth this call
>> to get the PREQUEST_EXTENSION would decide to call
>> WdfRequestUnmarkCancelable on my behalf. There’s no code in this function
>> that calls WdfRequestUnmarkCancelable . This is complete madness.
>>
>> Any insights would be appreciated.
>>
>> Thanks,
>> Matt
>>
>>
>> On Wed, Apr 1, 2015 at 11:04 PM, Tim Roberts wrote:
>>
>>> On Apr 1, 2015, at 5:57 PM, xxxxx@gmail.com wrote:
>>> >
>>> > // Complete the send request
>>> > InterlockedExchange(&DevExt->Chnl[Chnl].InUse, 0);
>>> > RiffaCompleteRequest(DevExt, Chnl, Status);
>>>
>>> You’re doing those in the wrong order. As soon as you set InUse to 0,
>>> your original ioctl handler is free to overwrite that channel’s request
>>> with a different one. If it happens to do so before you get into the
>>> completion routine, it will complete the wrong request. You should
>>> complete it, and then release InUse.
>>>
>>> Again, wouldn’t this all be easier if you had a manual I/O queue for
>>> each channel? Put all of your data in a context structure for the
>>> request. Every time a DMA completes, you can pop the next one, instead of
>>> just rejecting requests when one is already in progress.
>>> —
>>> Tim Roberts, xxxxx@probo.com
>>> Providenza & Boekelheide, Inc.
>>>
>>>
>>> —
>>> NTDEV is sponsored by OSR
>>>
>>> Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev
>>>
>>> OSR is HIRING!! See http://www.osr.com/careers
>>>
>>> For our schedule of WDF, WDM, debugging and other seminars visit:
>>> http://www.osr.com/seminars
>>>
>>> To unsubscribe, visit the List Server section of OSR Online at
>>> http://www.osronline.com/page.cfm?name=ListServer
>>>
>>
>>
> — NTDEV is sponsored by OSR Visit the list at:
> http://www.osronline.com/showlists.cfm?list=ntdev OSR is HIRING!! See
> http://www.osr.com/careers For our schedule of WDF, WDM, debugging and
> other seminars visit: http://www.osr.com/seminars To unsubscribe, visit
> the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>

Matt Jacobsen wrote:

Tim, thanks for pointing this out. I removed the InUse entirely and
just make sure there’s no code after the WdfRequestComplete calls.
Yes, there’s no protection for multiple threads trying to enter
simultaneously, but I can deal with that later after this bug is resolved.

You are assuming this not what’s happening right now. Can you be sure
of that?

I’m not sure I fully understand how to use a manual queue. Any example
I could look at? Your description sounds a lot like what I’m already
doing. I’m saving the WDFREQUEST in the PDEVICE_EXTENSION upon
entering the driver. Then when I receive the “DMA done” interrupt I
retrieve the WDFREQUEST from the PDEVICE_EXTENSION and complete it.

It’s basically a wrapped implementation of the cancel-safe queues
(IoCsqXxx) that were introduced in Windows XP. Instead of saving the
request in a single cell that you have to monitor, you call
WdfRequestForwardToIoQueue. When you have data to complete, you call
WdfQueueRetrieveNextRequest. The framework will automatically handle
cancellation. If you call WdfQueueRetrieveNextRequest and there’s
nothing there, then your request must have been canceled. You can
register a callback if a request is canceled while on the queue.

In general, I always try to minimize the time that I own a request. I
want to hand it back to a queue so the framework does the management.

Lastly, after reorganizing the driver to perform the
WdfRequestComplete as the absolute last operation from every code
path, I’m encountering a slightly different error. From the minidump:

This is showing a KMDF Verifier assertion failure. The !wdflogdump
output should show you what the assertion was, but my guess is trying to
unmark a request that has already been unmarked, or was never marked to
begin with. You should be able to get the WDFREQUEST handle from the
dump and explore its information.

STACK_COMMAND: kb
FOLLOWUP_IP:
riffa!RiffaIoctlSend+142
[c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @
1006]
fffff880`061ba552 ?? ???
FAULTING_SOURCE_LINE:
c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c
FAULTING_SOURCE_FILE:
c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c

It’s not a good practice to put your driver sources in the DDK tree.
What happens when you move to the next WDK, or if you have to reinstall?

FAULTING_SOURCE_LINE_NUMBER: 1006
FAULTING_SOURCE_CODE:
1002: return;
1003: }
1004:
1005: // Set the channel number in the request context for
RiffaEvtRequestCancel.
> 1006: reqExt = RiffaGetRequestContext(Request);
1007: reqExt->Chnl = io->Chnl;
1008:
1009: // Start a send transaction.
1010: if (length) {
1011: // Start a DMA transaction for sending.

This would suggest that the PREQUEST_EXTENSION struct I’m using to
pass information to the EvtRequestCancel callback is somehow calling
WdfRequestUnmarkCancelable. Clearly this is going to fail because this
is the entry point into the driver, I haven’t marked the WDFREQUEST
cancellable yet. In fact, I might complete the request before I do so
(if there’s an input validation problem). I don’t know why on earth
this call to get the PREQUEST_EXTENSION would decide to call
WdfRequestUnmarkCancelable on my behalf. There’s no code in this
function that calls WdfRequestUnmarkCancelable . This is complete madness.

Is this a debug build or a release build? Compiler optimizations can
really do a number on the debugger’s ability to pinpoint locations. Are
you sure the symbols you have match the binary used in the dump?


Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

Matt Jacobsen wrote:

Is this typical of Windows driver development? I’ve never seen this in
other OS development. Do I need to disable and re-enable the driver
verifier every time I upgrade the driver code? Is there a special
dance that needs to be done? Or sacrificial offering to the Windows
driver god?

Debugging is not a precise art. If you have edited your source code,
for example, the debugger can’t know that. It sees “line 936” in the
debugger tables, so it shows you line 936, even if you have added 12
lines of code since that build. Also, as I said, in the release build
with optimizations on, things move around a lot. The debugger tries to
keep up, but the information can be imprecise.

You are simply doing post-mortem analysis at this point, right? You
might need to hook up a live kernel debugger and grab some breakpoints,
to make sure things are happening in the order you expect.


Tim Roberts, xxxxx@probo.com
Providenza & Boekelheide, Inc.

As I think I responded earlier, if you have cancelable requests on your
hardware that require your driver to perform operations with your hardware
to effect the cancelation then you have to handle the race condition
between hardware completion and request cancelation, and the only way I
have found to do that is to have a request extension that contains two
state variables:

struct FDO_REQUEST_CONTEXT
{
LONG CancelSet;
LONG RequestCompleted;
}

that your code maintains, and you have to use WdfObjectDereference
and WdfObjectReference appropriately to keep the request context valid
until both CancelSet and RequestCompleted are zero.

Your “put on hardware” routine has to add a reference to the request before
it commits the request to hardware, and remove that reference on its
completion handling. If you don’t do this correctly you cannot examine the
request context safely.

Your hardware completion handling has to inspect RequestCompleted and
CancelSet, ignoring the request if the RequestCompleted flag is set other
than to remove its reference on the request,
calling WdfRequestUnmarkCancelable if CancelSet is true and
RequestCompleted is false, and handling the error return
from WdfRequestUnmarkCancelable correctly by not processing the request
other than to again call WdfObjectDereference.

Your cancel routine can safely assume that it has exclusive access to the
request, as the hardware completion side is testing the return value from
WdfRequestUnmarkCancelable, and the CancelSet flag is not cleared by your
cancel routine until it is completing the request.

Mark Roddy

On Mon, Apr 6, 2015 at 11:15 AM, Matt Jacobsen
wrote:

> Any ideas on this? According to the stack trace from the minidump the
> failing instruction sequence is:
>
> riffa!RiffaIoctlSend –> Wdf01000!imp_WdfRequestUnmarkCancelable
>
> But this is impossible. There is no instruction in RiffaIoctlSend
> that would jump to WdfRequestUnmarkCancelable. Moreover the line in
> source it says is the problem is a call to get the PREQUEST_EXTENSION.
> That’s clearly not causing this. The only thing I can imagine is that the
> driver code is corrupt because this stack trace is clearly garbage. To test
> this, I moved some lines of code around without changing any behavior,
> recompiled the driver, and tested again. The same error and stack trace are
> encountered, but this time it says the offending line of code is an if
> statement checking if the value of an INT32 is 0 or not. Absolute rubbish!
>
> Is this typical of Windows driver development? I’ve never seen this in
> other OS development. Do I need to disable and re-enable the driver
> verifier every time I upgrade the driver code? Is there a special dance
> that needs to be done? Or sacrificial offering to the Windows driver god?
>
> Thanks,
> Matt
>
>
> On Fri, Apr 3, 2015 at 5:44 PM, Matt Jacobsen
> wrote:
>
>> Tim, thanks for pointing this out. I removed the InUse entirely and just
>> make sure there’s no code after the WdfRequestComplete calls. Yes, there’s
>> no protection for multiple threads trying to enter simultaneously, but I
>> can deal with that later after this bug is resolved.
>>
>> I’m not sure I fully understand how to use a manual queue. Any example I
>> could look at? Your description sounds a lot like what I’m already doing.
>> I’m saving the WDFREQUEST in the PDEVICE_EXTENSION upon entering the
>> driver. Then when I receive the “DMA done” interrupt I retrieve the
>> WDFREQUEST from the PDEVICE_EXTENSION and complete it.
>>
>> Lastly, after reorganizing the driver to perform the WdfRequestComplete
>> as the absolute last operation from every code path, I’m encountering a
>> slightly different error. From the minidump:
>>
>> CUSTOMER_CRASH_COUNT: 1
>> DEFAULT_BUCKET_ID: VERIFIER_ENABLED_VISTA_MINIDUMP
>> BUGCHECK_STR: 0x1E
>> PROCESS_NAME: Project1.exe
>> CURRENT_IRQL: 2
>> TAG_NOT_DEFINED_c000000f: FFFFF880032FFFB0
>> EXCEPTION_RECORD: fffff880032ff8b8 – (.exr 0xfffff880032ff8b8)
>> ExceptionAddress: fffff80002c79cd0 (nt!DbgBreakPoint)
>> ExceptionCode: 80000003 (Break instruction exception)
>> ExceptionFlags: 00000000
>> NumberParameters: 1
>> Parameter[0]: 0000000000000000
>> TRAP_FRAME: fffff880032ff960 – (.trap 0xfffff880032ff960)
>> NOTE: The trap frame does not contain all registers.
>> Some register values may be zeroed or incorrect.
>> rax=fffff880032ffaf8 rbx=0000000000000000 rcx=fffff98002decfd0
>> rdx=fffff98002decfd0 rsi=0000000000000000 rdi=0000000000000000
>> rip=fffff80002c79cd1 rsp=fffff880032ffaf8 rbp=fffff880032ffb02
>> r8=0000000000000000 r9=fffff88000f97610 r10=7efefefefefeff40
>> r11=8101010101010100 r12=0000000000000000 r13=0000000000000000
>> r14=0000000000000000 r15=0000000000000000
>> iopl=0 nv up ei pl nz na pe nc
>> nt!DbgBreakPoint+0x1:
>> fffff80002c79cd1 c3 ret<br>&gt;&gt; Resetting default scope<br>&gt;&gt; LAST_CONTROL_TRANSFER: from fffff80002c798be to fffff80002c81e90<br>&gt;&gt; STACK_TEXT:<br>&gt;&gt; fffff880032fe998 fffff80002c798be : 000000000000003c fffff88000fd2c74<br>&gt;&gt; fffff880032ff110 fffff80002cada00 : nt!KeBugCheck<br>&gt;&gt; fffff880032fe9a0 fffff80002cad6cd : fffff80002e92398 fffff80002dcb22c<br>&gt;&gt; fffff80002c0d000 fffff880032ff8b8 : nt!KiKernelCalloutExceptionHandler+0xe<br>&gt;&gt; fffff880032fe9d0 fffff80002cac4a5 : fffff80002dd32c4 fffff880032fea48<br>&gt;&gt; fffff880032ff8b8 fffff80002c0d000 : nt!RtlpExecuteHandlerForException+0xd<br>&gt;&gt; fffff880032fea00 fffff80002cbd431 : fffff880032ff8b8 fffff880032ff110<br>&gt;&gt; fffff88000000000 00000000c0000010 : nt!RtlDispatchException+0x415<br>&gt;&gt; fffff880032ff0e0 fffff80002c81542 : fffff880032ff8b8 0000000000000000<br>&gt;&gt; fffff880032ff960 fffff98002dece40 : nt!KiDispatchException+0x135<br>&gt;&gt; fffff880032ff780 fffff80002c7f374 : fffffa8020591470 fffff8000311eb31<br>&gt;&gt; 0000000000000000 fffff880032ffb00 : nt!KiExceptionDispatch+0xc2<br>&gt;&gt; fffff880032ff960 fffff80002c79cd1 : fffff88000fb70bd fffff98002decfd0<br>&gt;&gt; fffff98002decfd0 0000000000000000 : nt!KiBreakpointTrap+0xf4<br>&gt;&gt; fffff880032ffaf8 fffff88000fb70bd : fffff98002decfd0 fffff98002decfd0<br>&gt;&gt; 0000000000000000 fffff88000f97610 : nt!DbgBreakPoint+0x1<br>&gt;&gt; fffff880032ffb00 fffff88000fb8691 : 0000000000000000 fffff98002dece40<br>&gt;&gt; fffff98002dece40 fffff98009d90e60 :<br>&gt;&gt; Wdf01000!FxRequest::Vf_VerifyRequestIsCancelable+0x79<br>&gt;&gt; fffff880032ffb50 fffff88000f16bcc : 0000000000000002 fffff98009d90e60<br>&gt;&gt; fffff880032ffbd0 fffff88000000008 :<br>&gt;&gt; Wdf01000!FxIoQueue::Vf_VerifyRequestCancelable+0x99<br>&gt;&gt; fffff880032ffb90 fffff88000f21685 : fffffa801c04d2d0 fffff98009d90e60<br>&gt;&gt; 0000067ff626f198 fffff80002cbd7e8 :<br>&gt;&gt; Wdf01000!FxIoQueue::RequestCancelable+0x3c<br>&gt;&gt; fffff880032ffc00 fffff880061ba552 : fffff98009d90e60 0000000000000000<br>&gt;&gt; 0000000000000000 0000067ff626f198 :<br>&gt;&gt; Wdf01000!imp_WdfRequestUnmarkCancelable+0x115<br>&gt;&gt; fffff880032ffc60 fffff88000000001 : 0000000000000000 0000000000000034<br>&gt;&gt; fffff880032ffded fffff880061b988b : riffa!RiffaIoctlSend+0x142<br>&gt;&gt; [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1006]<br>&gt;&gt; fffff880032ffce0 0000000000000000 : 0000000000000034 fffff880032ffded<br>&gt;&gt; fffff880061b988b 0000000000000000 : 0xfffff88000000001
>>
>> STACK_COMMAND: kb
>> FOLLOWUP_IP:
>> riffa!RiffaIoctlSend+142
>> [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1006]
>> fffff880`061ba552 ?? ???
>> FAULTING_SOURCE_LINE:
>> c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c
>> FAULTING_SOURCE_FILE:
>> c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c
>> FAULTING_SOURCE_LINE_NUMBER: 1006
>> FAULTING_SOURCE_CODE:
>> 1002: return;
>> 1003: }
>> 1004:
>> 1005: // Set the channel number in the request context for
>> RiffaEvtRequestCancel.
>> > 1006: reqExt = RiffaGetRequestContext(Request);
>> 1007: reqExt->Chnl = io->Chnl;
>> 1008:
>> 1009: // Start a send transaction.
>> 1010: if (length) {
>> 1011: // Start a DMA transaction for sending.
>>
>> SYMBOL_STACK_INDEX: c
>> SYMBOL_NAME: riffa!RiffaIoctlSend+142
>> FOLLOWUP_NAME: MachineOwner
>> MODULE_NAME: riffa
>> IMAGE_NAME: riffa.sys
>> DEBUG_FLR_IMAGE_TIMESTAMP: 551f2b56
>> FAILURE_BUCKET_ID: X64_0x1E_VRF_riffa!RiffaIoctlSend+142
>> BUCKET_ID: X64_0x1E_VRF_riffa!RiffaIoctlSend+142
>> Followup: MachineOwner
>> ---------
>>
>> This would suggest that the PREQUEST_EXTENSION struct I’m using to pass
>> information to the EvtRequestCancel callback is somehow calling
>> WdfRequestUnmarkCancelable. Clearly this is going to fail because this is
>> the entry point into the driver, I haven’t marked the WDFREQUEST
>> cancellable yet. In fact, I might complete the request before I do so (if
>> there’s an input validation problem). I don’t know why on earth this call
>> to get the PREQUEST_EXTENSION would decide to call
>> WdfRequestUnmarkCancelable on my behalf. There’s no code in this function
>> that calls WdfRequestUnmarkCancelable . This is complete madness.
>>
>> Any insights would be appreciated.
>>
>> Thanks,
>> Matt
>>
>>
>> On Wed, Apr 1, 2015 at 11:04 PM, Tim Roberts wrote:
>>
>>> On Apr 1, 2015, at 5:57 PM, xxxxx@gmail.com wrote:
>>> >
>>> > // Complete the send request
>>> > InterlockedExchange(&DevExt->Chnl[Chnl].InUse, 0);
>>> > RiffaCompleteRequest(DevExt, Chnl, Status);
>>>
>>> You’re doing those in the wrong order. As soon as you set InUse to 0,
>>> your original ioctl handler is free to overwrite that channel’s request
>>> with a different one. If it happens to do so before you get into the
>>> completion routine, it will complete the wrong request. You should
>>> complete it, and then release InUse.
>>>
>>> Again, wouldn’t this all be easier if you had a manual I/O queue for
>>> each channel? Put all of your data in a context structure for the
>>> request. Every time a DMA completes, you can pop the next one, instead of
>>> just rejecting requests when one is already in progress.
>>> —
>>> Tim Roberts, xxxxx@probo.com
>>> Providenza & Boekelheide, Inc.
>>>
>>>
>>> —
>>> NTDEV is sponsored by OSR
>>>
>>> Visit the list at: http://www.osronline.com/showlists.cfm?list=ntdev
>>>
>>> OSR is HIRING!! See http://www.osr.com/careers
>>>
>>> For our schedule of WDF, WDM, debugging and other seminars visit:
>>> http://www.osr.com/seminars
>>>
>>> To unsubscribe, visit the List Server section of OSR Online at
>>> http://www.osronline.com/page.cfm?name=ListServer
>>>
>>
>>
> — NTDEV is sponsored by OSR Visit the list at:
> http://www.osronline.com/showlists.cfm?list=ntdev OSR is HIRING!! See
> http://www.osr.com/careers For our schedule of WDF, WDM, debugging and
> other seminars visit: http://www.osr.com/seminars To unsubscribe, visit
> the List Server section of OSR Online at
> http://www.osronline.com/page.cfm?name=ListServer
>