!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>fffff880
032fe918 fffff80002c7c8be : fffffa80
199bc580 fffff88000c0bf6b fffff880
032ff090 fffff80002cb0a00 : nt!KeBugCheck<br>fffff880
032fe920 fffff80002cb06cd : fffff800
02e95398 fffff80002dce22c fffff800
02c10000 fffff880032ff838 : nt!KiKernelCalloutExceptionHandler+0xe<br>fffff880
032fe950 fffff80002caf4a5 : fffff800
02dd62c4 fffff880032fe9c8 fffff880
032ff838 fffff80002c10000 : nt!RtlpExecuteHandlerForException+0xd<br>fffff880
032fe980 fffff80002cc0431 : fffff880
032ff838 fffff880032ff090 fffff880
00000000 00000000c0000010 : nt!RtlDispatchException+0x415<br>fffff880
032ff060 fffff80002c84542 : fffff880
032ff838 0000000000000000 fffff880
032ff8e0 fffff98002aaae40 : nt!KiDispatchException+0x135<br>fffff880
032ff700 fffff80002c82374 : 00000000
00000000 fffff880032ff960 00000000
c0000010 fffff98002aaae40 : nt!KiExceptionDispatch+0xc2<br>fffff880
032ff8e0 fffff80002c7ccd1 : fffff880
00efe0bd fffff98002aaafd0 fffff980
02aaafd0 0000000000000000 : nt!KiBreakpointTrap+0xf4<br>fffff880
032ffa78 fffff88000efe0bd : fffff980
02aaafd0 fffff98002aaafd0 00000000
00000000 fffff88000ede610 : nt!DbgBreakPoint+0x1<br>fffff880
032ffa80 fffff88000eff691 : 00000000
00000000 fffff98002aaae40 fffff980
02aaae40 fffff9800c722e60 : Wdf01000!FxRequest::Vf_VerifyRequestIsCancelable+0x79<br>fffff880
032ffad0 fffff88000e5dbcc : 00000000
00000002 fffff9800c722e60 fffff880
032ffb50 fffff88000000008 : Wdf01000!FxIoQueue::Vf_VerifyRequestCancelable+0x99<br>fffff880
032ffb10 fffff88000e68685 : ffff9d59
b1850b10 fffff9800c722e60 0000067f
f38dd198 0000000000000022 : Wdf01000!FxIoQueue::RequestCancelable+0x3c<br>fffff880
032ffb80 fffff880061a821b : fffff980
0c722e60 0000067ffd4db1b8 fffff980
02b24e40 fffffa801bf8049c : Wdf01000!imp_WdfRequestUnmarkCancelable+0x115<br>fffff880
032ffbe0 fffff880061a6a22 : 0000067f
f38dd198 fffffa801bf8049c fffff880
061a9c70 fffffa801bf8030c : riffa!WdfRequestUnmarkCancelable+0x1b [c:\winddk\7600.16385.1\inc\wdf\kmdf\1.9\wdfrequest.h @ 775]<br>fffff880
032ffc10 fffff880061a7d6c : fffffa80
1bf802d0 fffff80000000000 fffff880
00000000 fffffa801bf8030c : riffa!RiffaCompleteRequest+0xa2 [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1462]<br>fffff880
032ffc70 fffff880061a5252 : fffffa80
1bf802d0 fffff88000000000 fffff880
00000001 fffffa8000000000 : riffa!RiffaTransactionComplete+0x10c [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 1907]<br>fffff880
032ffcc0 fffff88000ed96d3 : 0000067f
fd4db1b8 0000057fe407ffd8 00000000
4e54241d 000000004559db6a : riffa!RiffaEvtInterruptDpc+0x622 [c:\winddk\7600.16385.1\src\general\riffa\driver\windows\sys\riffa.c @ 878]<br>fffff880
032ffed0 fffff80002c907ac : fffff880
032d0180 fffff880032d0180 fffff980
02b24ed8 0000000000000042 : Wdf01000!FxInterrupt::DpcHandler+0xc3<br>fffff880
032fff00 fffff80002c87925 : 00000000
00000000 fffffa8019cdb300 00000000
00000000 fffff88000ed9840 : nt!KiRetireDpcList+0x1bc<br>fffff880
032fffb0 fffff80002c8773c : 00000000
00000000 0000000000000000 00000000
00000000 0000000000000000 : nt!KxRetireDpcList+0x5<br>fffff880
063657e0 0000000000000000 : 00000000
00000000 0000000000000000 00000000
00000000 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>fffff880
061a821b 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>