DbgBreakPoint in WdfRequestCompleteWithInformation when cancelling IRP

We are developing a driver using KMDF 1.5 (WDK Rev6000). Now we meet a tricky DbgBreakPoint when calling the WdfRequestCompleteWithInformation to complete an IRP which is about to be cancelled.

This is our driver’s senario: our driver create a WDFRequest(IRP) for every incoming WDFRequest(IRP) and send those new created WDFRequests to another kernel driver. When the newly created wdfrequests have been completed, we also complete the corresponding framework built wdfrequest in the complete routine. In the cancel routine of the framework built wdfrequest, we don’t do anything except setting some flags in the wdfrequest context.

When we CTRL+C our test application to simulate IRP cancel, the debugger would report a DbgBreakPoint when the KMDF verifier is ON. Anyhow, if we omit this DbgBreakPoint by input g in the debugger, nothing seems wrong. We wonder if we did anything wrong in the driver to cause this DbgBreakPoint. Is there anyone could help us? Thanks!

-George

p.s. Here is what we got from debugger

Break instruction exception - code 80000003 (first chance)
nt!DbgBreakPoint:
80871654 cc int 3
0: kd> !analyze -v
Connected to Windows Server 2003 3790 x86 compatible target, ptr64 FALSE
Loading Kernel Symbols

Loading User Symbols

Loading unloaded module list

*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

Unknown bugcheck code (0)
Unknown bugcheck description
Arguments:
Arg1: 00000000
Arg2: 00000000
Arg3: 00000000
Arg4: 00000000

Debugging Details:

PROCESS_NAME: drsdemo.exe

FAULTING_IP:
nt!DbgBreakPoint+0
80871654 cc int 3

EXCEPTION_RECORD: ffffffff – (.exr 0xffffffffffffffff)
ExceptionAddress: 80871654 (nt!DbgBreakPoint)
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 3
Parameter[0]: 00000000
Parameter[1]: 81f31db0
Parameter[2]: 00000000

ERROR_CODE: (NTSTATUS) 0x80000003 - {EXCEPTION} Breakpoint A breakpoint has
been reached.

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x0

CURRENT_IRQL: 2

LAST_CONTROL_TRANSFER: from f70b236e to 80871654

STACK_TEXT:
f78a2c68 f70b236e f70ed118 81b01cd0 81b34458 nt!DbgBreakPoint
f78a2c98 f70b24d7 f70ed118 81b34458 00000000
Wdf01000!FxRequest::VerifierValidateCompletedRequest+0x9e
f78a2cc0 f70b4938 00000000 00000000 8607f0d0
Wdf01000!FxRequest::CompleteInternal+0x2c
f78a2cdc f70b495c 00000000 00000000 f78a2d08 Wdf01000!FxRequest::Complete+0xb3
f78a2cec f709dfd4 00000000 00000008 81eb22ec
Wdf01000!FxRequest::CompleteWithInformation+0x18
f78a2d08 f76eacdd 81b34458 7e4cbba0 00000000
Wdf01000!imp_WdfRequestCompleteWithInformation+0x7f
f78a2d20 f76ee826 7e4cbba0 00000000 00000008
HifnDrs!WdfRequestCompleteWithInformation+0x1d
[c:\winddk\6000\inc\wdf\kmdf\10\wdfrequest.h @ 848]
f78a2d78 f76eb45a 7e4cbba0 00000000 00000008 HifnDrs!DrsFinishRequest+0x356
f78a2da4 f70ba245 7cb7b368 7cb581d8 81eb22ec
HifnDrs!DrsReqCompleteRoutine+0x1ca
f78a2dcc f70915d3 834847cf 834a7e20 00000000
Wdf01000!FxRequestBase::CompleteSubmitted+0x89
f78a2de8 f709168d 01484c90 8600eed8 f78a2e14
Wdf01000!FxIoTarget::RequestCompletionRoutine+0x195
f78a2df8 8081d119 00000000 83484738 83484c90
Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
f78a2e14 8081de7d 00000000 83484738 8600eed8 nt!IopUnloadSafeCompletion+0x1d
f78a2e44 f70e76b4 81ec7f00 f78a2e7c f70b2994 nt!IopfCompleteRequest+0xcd
f78a2e50 f70b2994 00000000 f70ed118 81ec7f00
Wdf01000!FxIrp::CompleteRequest+0x13
f78a2e7c f70b4938 00000000 00000000 860f5300
Wdf01000!FxRequest::CompleteInternal+0x4e9
f78a2e98 f70b495c 00000000 00000000 f78a2ec4 Wdf01000!FxRequest::Complete+0xb3
f78a2ea8 f709dfd4 00000000 00000008 00000000
Wdf01000!FxRequest::CompleteWithInformation+0x18
f78a2ec4 f7107d5d 81ec7f00 7e1380f8 00000000
Wdf01000!imp_WdfRequestCompleteWithInformation+0x7f
f78a2edc f7107c87 7e1380f8 00000000 00000008
HifnDr!WdfRequestCompleteWithInformation+0x1d
[c:\winddk\6000\inc\wdf\kmdf\10\wdfrequest.h @ 848]
f78a2f3c f7103337 860376a8 f7055ef2 f7055ef7 HifnDr!DrRsltHandle+0x647
f78a2f70 f70d79ee 7cb560e0 79fc8b18 ffdffa40 HifnDr!DrEvtInterruptDpc+0x2b7
f78a2f8c f70d7a37 834a9f18 00000000 f78a2ff4
Wdf01000!FxInterrupt::DpcHandler+0x76
f78a2f9c 80831caa 834a9f64 834a9f18 834a9f18
Wdf01000!FxInterrupt::_InterruptDpcThunk+0x13
f78a2ff4 8088cfaf f62cd634 00000000 00000000 nt!KiRetireDpcList+0xca
f78a2ff8 f62cd634 00000000 00000000 00000000 nt!KiDispatchInterrupt+0x3f
WARNING: Frame IP not in any known module. Following frames may be wrong.
8088cfaf 00000000 0000000a bb837775 00000128 0xf62cd634

STACK_COMMAND: kb

FOLLOWUP_IP:
Wdf01000!FxRequest::VerifierValidateCompletedRequest+9e
f70b236e eb12 jmp
Wdf01000!FxRequest::VerifierValidateCompletedRequest+0xb2 (f70b2382)

SYMBOL_STACK_INDEX: 1

SYMBOL_NAME: Wdf01000!FxRequest::VerifierValidateCompletedRequest+9e

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: Wdf01000

IMAGE_NAME: Wdf01000.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4549b23a

FAILURE_BUCKET_ID: 0x0_Wdf01000!FxRequest::VerifierValidateCompletedRequest+9e

BUCKET_ID: 0x0_Wdf01000!FxRequest::VerifierValidateCompletedRequest+9e

Followup: MachineOwner

0: kd> !wdfrequest 0x7e4cbba0
!IRP 0x81b01c60
!WDFQUEUE 0x7cbc3498
State: Pending, Allocated by WDF for incoming IRP
System Buffer 0x8335c1e0, Length 0x20, !WDFMEMORY 0x7e4cbb39

Cancel or Completion Routine: HifnDrs!DrsEvtRequestCancel (f76eb4b0)

0: kd> !IRP 0x81b01c60 1
Irp is active with 1 stacks 1 is current (= 0x81b01cd0)
No Mdl: System buffer=8335c1e0: Thread 81f31b40: Irp stack trace.
Flags = 00000030
ThreadListEntry.Flink = 81b01c70
ThreadListEntry.Blink = 81b01c70
IoStatus.Status = 00000000
IoStatus.Information = 00000008
RequestorMode = 00000001
Cancel = 01
CancelIrql = 1
ApcEnvironment = 00
UserIosb = 0087fed8
UserEvent = 00000000
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = 81b01ca0
Tail.Overlay.Thread = 81f31b40
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 81ec7a08
Tail.Overlay.ListEntry.Blink = 81b3e5d8
Tail.Overlay.CurrentStackLocation = 81b01cd0
Tail.Overlay.OriginalFileObject = 83362028
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
cmd flg cl Device File Completion-Context

[e, 0] 5 1 8343dc40 83362028 00000000-00000000 pending
\Driver\HifnDrs
Args: 00000000 00000020 0022e480 00000000


0: kd> !WDFQUEUE 0x7cbc3498

Dumping WDFQUEUE 0x7cbc3498

Parallel, Not power-managed, PowerOn, Can accept, Can dispatch,
ExecutionLevelDispatch, SynchronizationScopeNone
Number of driver owned requests: 4
!WDFREQUEST 0x7e5020e0 !IRP 0x81eb3440
!WDFREQUEST 0x7e138b80 !IRP 0x81b3e580
!WDFREQUEST 0x7e4cbba0 !IRP 0x81b01c60
!WDFREQUEST 0x7a801fb0 !IRP 0x81ec79b0
Number of waiting requests: 0

Number of driver owned cancelable requests: 3
!WDFREQUEST 0x7e5020e0 !IRP 0x81eb3440
!WDFREQUEST 0x7e138b80 !IRP 0x81b3e580
!WDFREQUEST 0x7a801fb0 !IRP 0x81ec79b0

Number of driver owned cancelled requests: 1
!WDFREQUEST 0x7e4cbba0 !IRP 0x81b01c60

EvtIoDeviceControl: (0xf76ea230) HifnDrs!DrsEvtIoDeviceControl

The output of “!wdfkd.wdflogdump -v HifnDrs” will tell you what is going wrong. What does the log say?

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@hotmail.com
Sent: Monday, November 19, 2007 8:36 PM
To: Windows System Software Devs Interest List
Subject: [ntdev] DbgBreakPoint in WdfRequestCompleteWithInformation when cancelling IRP

We are developing a driver using KMDF 1.5 (WDK Rev6000). Now we meet a tricky DbgBreakPoint when calling the WdfRequestCompleteWithInformation to complete an IRP which is about to be cancelled.

This is our driver’s senario: our driver create a WDFRequest(IRP) for every incoming WDFRequest(IRP) and send those new created WDFRequests to another kernel driver. When the newly created wdfrequests have been completed, we also complete the corresponding framework built wdfrequest in the complete routine. In the cancel routine of the framework built wdfrequest, we don’t do anything except setting some flags in the wdfrequest context.

When we CTRL+C our test application to simulate IRP cancel, the debugger would report a DbgBreakPoint when the KMDF verifier is ON. Anyhow, if we omit this DbgBreakPoint by input g in the debugger, nothing seems wrong. We wonder if we did anything wrong in the driver to cause this DbgBreakPoint. Is there anyone could help us? Thanks!

-George

p.s. Here is what we got from debugger

Break instruction exception - code 80000003 (first chance)
nt!DbgBreakPoint
80871654 cc int 3
0: kd> !analyze -v
Connected to Windows Server 2003 3790 x86 compatible target, ptr64 FALSE
Loading Kernel Symbols

Loading User Symbols

Loading unloaded module list

*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

Unknown bugcheck code (0)
Unknown bugcheck description
Arguments:
Arg1: 00000000
Arg2: 00000000
Arg3: 00000000
Arg4: 00000000

Debugging Details:

PROCESS_NAME: drsdemo.exe

FAULTING_IP:
nt!DbgBreakPoint+0
80871654 cc int 3

EXCEPTION_RECORD: ffffffff – (.exr 0xffffffffffffffff)
ExceptionAddress: 80871654 (nt!DbgBreakPoint)
ExceptionCode: 80000003 (Break instruction exception)
ExceptionFlags: 00000000
NumberParameters: 3
Parameter[0]: 00000000
Parameter[1]: 81f31db0
Parameter[2]: 00000000

ERROR_CODE: (NTSTATUS) 0x80000003 - {EXCEPTION} Breakpoint A breakpoint has
been reached.

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x0

CURRENT_IRQL: 2

LAST_CONTROL_TRANSFER: from f70b236e to 80871654

STACK_TEXT:
f78a2c68 f70b236e f70ed118 81b01cd0 81b34458 nt!DbgBreakPoint
f78a2c98 f70b24d7 f70ed118 81b34458 00000000
Wdf01000!FxRequest::VerifierValidateCompletedRequest+0x9e
f78a2cc0 f70b4938 00000000 00000000 8607f0d0
Wdf01000!FxRequest::CompleteInternal+0x2c
f78a2cdc f70b495c 00000000 00000000 f78a2d08 Wdf01000!FxRequest::Complete+0xb3
f78a2cec f709dfd4 00000000 00000008 81eb22ec
Wdf01000!FxRequest::CompleteWithInformation+0x18
f78a2d08 f76eacdd 81b34458 7e4cbba0 00000000
Wdf01000!imp_WdfRequestCompleteWithInformation+0x7f
f78a2d20 f76ee826 7e4cbba0 00000000 00000008
HifnDrs!WdfRequestCompleteWithInformation+0x1d
[c:\winddk\6000\inc\wdf\kmdf\10\wdfrequest.h @ 848]
f78a2d78 f76eb45a 7e4cbba0 00000000 00000008 HifnDrs!DrsFinishRequest+0x356
f78a2da4 f70ba245 7cb7b368 7cb581d8 81eb22ec
HifnDrs!DrsReqCompleteRoutine+0x1ca
f78a2dcc f70915d3 834847cf 834a7e20 00000000
Wdf01000!FxRequestBase::CompleteSubmitted+0x89
f78a2de8 f709168d 01484c90 8600eed8 f78a2e14
Wdf01000!FxIoTarget::RequestCompletionRoutine+0x195
f78a2df8 8081d119 00000000 83484738 83484c90
Wdf01000!FxIoTarget::_RequestCompletionRoutine+0x35
f78a2e14 8081de7d 00000000 83484738 8600eed8 nt!IopUnloadSafeCompletion+0x1d
f78a2e44 f70e76b4 81ec7f00 f78a2e7c f70b2994 nt!IopfCompleteRequest+0xcd
f78a2e50 f70b2994 00000000 f70ed118 81ec7f00
Wdf01000!FxIrp::CompleteRequest+0x13
f78a2e7c f70b4938 00000000 00000000 860f5300
Wdf01000!FxRequest::CompleteInternal+0x4e9
f78a2e98 f70b495c 00000000 00000000 f78a2ec4 Wdf01000!FxRequest::Complete+0xb3
f78a2ea8 f709dfd4 00000000 00000008 00000000
Wdf01000!FxRequest::CompleteWithInformation+0x18
f78a2ec4 f7107d5d 81ec7f00 7e1380f8 00000000
Wdf01000!imp_WdfRequestCompleteWithInformation+0x7f
f78a2edc f7107c87 7e1380f8 00000000 00000008
HifnDr!WdfRequestCompleteWithInformation+0x1d
[c:\winddk\6000\inc\wdf\kmdf\10\wdfrequest.h @ 848]
f78a2f3c f7103337 860376a8 f7055ef2 f7055ef7 HifnDr!DrRsltHandle+0x647
f78a2f70 f70d79ee 7cb560e0 79fc8b18 ffdffa40 HifnDr!DrEvtInterruptDpc+0x2b7
f78a2f8c f70d7a37 834a9f18 00000000 f78a2ff4
Wdf01000!FxInterrupt::DpcHandler+0x76
f78a2f9c 80831caa 834a9f64 834a9f18 834a9f18
Wdf01000!FxInterrupt::_InterruptDpcThunk+0x13
f78a2ff4 8088cfaf f62cd634 00000000 00000000 nt!KiRetireDpcList+0xca
f78a2ff8 f62cd634 00000000 00000000 00000000 nt!KiDispatchInterrupt+0x3f
WARNING: Frame IP not in any known module. Following frames may be wrong.
8088cfaf 00000000 0000000a bb837775 00000128 0xf62cd634

STACK_COMMAND: kb

FOLLOWUP_IP:
Wdf01000!FxRequest::VerifierValidateCompletedRequest+9e
f70b236e eb12 jmp
Wdf01000!FxRequest::VerifierValidateCompletedRequest+0xb2 (f70b2382)

SYMBOL_STACK_INDEX: 1

SYMBOL_NAME: Wdf01000!FxRequest::VerifierValidateCompletedRequest+9e

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: Wdf01000

IMAGE_NAME: Wdf01000.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4549b23a

FAILURE_BUCKET_ID: 0x0_Wdf01000!FxRequest::VerifierValidateCompletedRequest+9e

BUCKET_ID: 0x0_Wdf01000!FxRequest::VerifierValidateCompletedRequest+9e

Followup: MachineOwner

0: kd> !wdfrequest 0x7e4cbba0
!IRP 0x81b01c60
!WDFQUEUE 0x7cbc3498
State: Pending, Allocated by WDF for incoming IRP
System Buffer 0x8335c1e0, Length 0x20, !WDFMEMORY 0x7e4cbb39

Cancel or Completion Routine: HifnDrs!DrsEvtRequestCancel (f76eb4b0)

0: kd> !IRP 0x81b01c60 1
Irp is active with 1 stacks 1 is current (= 0x81b01cd0)
No Mdl: System buffer=8335c1e0: Thread 81f31b40: Irp stack trace.
Flags = 00000030
ThreadListEntry.Flink = 81b01c70
ThreadListEntry.Blink = 81b01c70
IoStatus.Status = 00000000
IoStatus.Information = 00000008
RequestorMode = 00000001
Cancel = 01
CancelIrql = 1
ApcEnvironment = 00
UserIosb = 0087fed8
UserEvent = 00000000
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = 81b01ca0
Tail.Overlay.Thread = 81f31b40
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 81ec7a08
Tail.Overlay.ListEntry.Blink = 81b3e5d8
Tail.Overlay.CurrentStackLocation = 81b01cd0
Tail.Overlay.OriginalFileObject = 83362028
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
cmd flg cl Device File Completion-Context

[e, 0] 5 1 8343dc40 83362028 00000000-00000000 pending
\Driver\HifnDrs
Args: 00000000 00000020 0022e480 00000000


0: kd> !WDFQUEUE 0x7cbc3498

Dumping WDFQUEUE 0x7cbc3498

Parallel, Not power-managed, PowerOn, Can accept, Can dispatch,
ExecutionLevelDispatch, SynchronizationScopeNone
Number of driver owned requests: 4
!WDFREQUEST 0x7e5020e0 !IRP 0x81eb3440
!WDFREQUEST 0x7e138b80 !IRP 0x81b3e580
!WDFREQUEST 0x7e4cbba0 !IRP 0x81b01c60
!WDFREQUEST 0x7a801fb0 !IRP 0x81ec79b0
Number of waiting requests: 0

Number of driver owned cancelable requests: 3
!WDFREQUEST 0x7e5020e0 !IRP 0x81eb3440
!WDFREQUEST 0x7e138b80 !IRP 0x81b3e580
!WDFREQUEST 0x7a801fb0 !IRP 0x81ec79b0

Number of driver owned cancelled requests: 1
!WDFREQUEST 0x7e4cbba0 !IRP 0x81b01c60

EvtIoDeviceControl: (0xf76ea230) HifnDrs!DrsEvtIoDeviceControl


NTDEV is sponsored by OSR

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

Oops, Why can’t I see anything in wdflogdump? (I’ve set VerifierOn to 1 and TrackHandles to * in the registry, and also set the wdftmffile)

0: kd> !wdfkd.wdflogdump -v HifnDrs
Trace searchpath is:

Trace format prefix is: %7!u!: %!FUNC! -
TMF file used for formatting IFR log is: C:\WinDDK\6000\tools\tracing\i386\wdf01005.tmf

-George

Here is the wdflogdump. It is said that we shouldn’t complete the cancelled request until the EvtIoCancel is being called to avoid race condition of double completetion. But in our driver, we don’t complete the request in EvtIoCancel, so there’s no double completetion worry. ( We did this just like the usbsamp in KMDF sample). So is there any problem if we just leave this dbgBreakPoint there?

137657: FxIoQueue::DispatchRequestToDriver - WDFREQUEST 0x7DCCDCD0 dispatched to driver
137658: FxIoQueue::DispatchEvents - No requests on WDFQUEUE 0x7CB951E8
137659: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 7CBC4DF0
137660: FxIoQueue::CancelForDriver - WDFREQUEST 0x7DCCDCD0 was cancelled in driver for WDFQUEUE 0x7CB951E8
137661: FxIoTarget::RemoveCompletedRequestLocked - WDFIOTARGET 7DE61240, WDFREQUEST 7CBC4DF0
137662: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 7CBC4DF0 completed in completion routine
137663: imp_WdfRequestUnmarkCancelable - Enter: WDFREQUEST 0x7DCCDCD0
137664: imp_WdfRequestCompleteWithInformation - Completing WDFREQUEST 0x7DCCDCD0, STATUS_SUCCESS
137665: FxRequest::Complete - Completing WDFREQUEST 0x7DCCDCD0 for IRP 0x8280E9D0 with Information 0x8, STATUS_SUCCESS
137666: FxRequest::VerifierValidateCompletedRequest - Completing Cancelable WDFREQUEST 7DCCDCD0. This results in a race condition in the device driver that can cause double completions. Call WdfRequestUnmarkCancelable before WdfRequestComplete. If WdfRequestUnmarkCancelable returns STATUS_CANCELLED, do not complete the request until the EvtIoCancel handler is called. The straightforward way to ensure this is to complete a canceled request from the EvIoCancel callback.
---- end of log ----

Sorry, no -v, just

!wdfkd.wdflogdump HifnDrs

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@hotmail.com
Sent: Monday, November 19, 2007 9:13 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] DbgBreakPoint in WdfRequestCompleteWithInformation when cancelling IRP

Oops, Why can’t I see anything in wdflogdump? (I’ve set VerifierOn to 1 and TrackHandles to * in the registry, and also set the wdftmffile)

0: kd> !wdfkd.wdflogdump -v HifnDrs
Trace searchpath is:

Trace format prefix is: %7!u!: %!FUNC! -
TMF file used for formatting IFR log is: C:\WinDDK\6000\tools\tracing\i386\wdf01005.tmf

-George


NTDEV is sponsored by OSR

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

Here is the wdflogdump. It is said that we should not “complete the request until the EvtIoCancel handler is called if WdfRequestUnmarkCancelable returns STATUS_CANCELLED to avoid a race condition that can cause double completions”. But our driver don’t complete the request in EvtIoCancel so there is no worry about the double completions. (we did this just like the usbsamp driver in KMDF samples). Is there any problem in this situation? Can we just ignore this DbgBreakPoint()?

-George

137657: FxIoQueue::DispatchRequestToDriver - WDFREQUEST 0x7DCCDCD0 dispatched to driver
137658: FxIoQueue::DispatchEvents - No requests on WDFQUEUE 0x7CB951E8
137659: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 7CBC4DF0
137660: FxIoQueue::CancelForDriver - WDFREQUEST 0x7DCCDCD0 was cancelled in driver for WDFQUEUE 0x7CB951E8
137661: FxIoTarget::RemoveCompletedRequestLocked - WDFIOTARGET 7DE61240, WDFREQUEST 7CBC4DF0
137662: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 7CBC4DF0 completed in completion routine
137663: imp_WdfRequestUnmarkCancelable - Enter: WDFREQUEST 0x7DCCDCD0
137664: imp_WdfRequestCompleteWithInformation - Completing WDFREQUEST 0x7DCCDCD0, STATUS_SUCCESS
137665: FxRequest::Complete - Completing WDFREQUEST 0x7DCCDCD0 for IRP 0x8280E9D0 with Information 0x8, STATUS_SUCCESS
137666: FxRequest::VerifierValidateCompletedRequest - Completing Cancelable WDFREQUEST 7DCCDCD0. This results in a race condition in the device driver that can cause double completions. Call WdfRequestUnmarkCancelable before WdfRequestComplete. If WdfRequestUnmarkCancelable returns STATUS_CANCELLED, do not complete the request until the EvtIoCancel handler is called. The straightforward way to ensure this is to complete a canceled request from the EvIoCancel callback.
---- end of log ----

You are completing the request with the cancelation routine still set. Either you set the cancelation routine yourself and did not clear it, or the request is parked in a manual queue and you did not dequeue it.

From your original email

0: kd> !wdfrequest 0x7e4cbba0
!IRP 0x81b01c60
!WDFQUEUE 0x7cbc3498
State: Pending, Allocated by WDF for incoming IRP
System Buffer 0x8335c1e0, Length 0x20, !WDFMEMORY 0x7e4cbb39

Cancel or Completion Routine: HifnDrs!DrsEvtRequestCancel (f76eb4b0) <– your cancel routine

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@hotmail.com
Sent: Monday, November 19, 2007 9:55 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] DbgBreakPoint in WdfRequestCompleteWithInformation when cancelling IRP

Here is the wdflogdump. It is said that we should not “complete the request until the EvtIoCancel handler is called if WdfRequestUnmarkCancelable returns STATUS_CANCELLED to avoid a race condition that can cause double completions”. But our driver don’t complete the request in EvtIoCancel so there is no worry about the double completions. (we did this just like the usbsamp driver in KMDF samples). Is there any problem in this situation? Can we just ignore this DbgBreakPoint()?

-George

137657: FxIoQueue::DispatchRequestToDriver - WDFREQUEST 0x7DCCDCD0 dispatched to driver
137658: FxIoQueue::DispatchEvents - No requests on WDFQUEUE 0x7CB951E8
137659: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 7CBC4DF0
137660: FxIoQueue::CancelForDriver - WDFREQUEST 0x7DCCDCD0 was cancelled in driver for WDFQUEUE 0x7CB951E8
137661: FxIoTarget::RemoveCompletedRequestLocked - WDFIOTARGET 7DE61240, WDFREQUEST 7CBC4DF0
137662: FxIoTarget::RequestCompletionRoutine - WDFREQUEST 7CBC4DF0 completed in completion routine
137663: imp_WdfRequestUnmarkCancelable - Enter: WDFREQUEST 0x7DCCDCD0
137664: imp_WdfRequestCompleteWithInformation - Completing WDFREQUEST 0x7DCCDCD0, STATUS_SUCCESS
137665: FxRequest::Complete - Completing WDFREQUEST 0x7DCCDCD0 for IRP 0x8280E9D0 with Information 0x8, STATUS_SUCCESS
137666: FxRequest::VerifierValidateCompletedRequest - Completing Cancelable WDFREQUEST 7DCCDCD0. This results in a race condition in the device driver that can cause double completions. Call WdfRequestUnmarkCancelable before WdfRequestComplete. If WdfRequestUnmarkCancelable returns STATUS_CANCELLED, do not complete the request until the EvtIoCancel handler is called. The straightforward way to ensure this is to complete a canceled request from the EvIoCancel callback.
---- end of log ----


NTDEV is sponsored by OSR

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

We have WdfRequestUnmarkCancelable() the request before we complete it, and the request is not in any manual queue at the time of complete. Anyway, the WdfRequestUnmarkCancelable() do returns STATUS_CANCELLED, but we ignore that return value and complete the request. Does it matters?

-George

You have to honor what the docs say about the return value, otherwise this type of problem can occur.

d

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@hotmail.com
Sent: Monday, November 19, 2007 10:25 PM
To: Windows System Software Devs Interest List
Subject: RE:[ntdev] DbgBreakPoint in WdfRequestCompleteWithInformation when cancelling IRP

We have WdfRequestUnmarkCancelable() the request before we complete it, and the request is not in any manual queue at the time of complete. Anyway, the WdfRequestUnmarkCancelable() do returns STATUS_CANCELLED, but we ignore that return value and complete the request. Does it matters?

-George


NTDEV is sponsored by OSR

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