MULTIPLE_IRP_COMPLETE_REQUESTS

Hello all.

I have strange situation. I pass an IRP down to stack returning STATUS_PENDING. Completion routine is set. Then I see that my completion routine is called once, it returns STATUS_SUCCESS and I get the following BSoD:

1: kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

MULTIPLE_IRP_COMPLETE_REQUESTS (44)
A driver has requested that an IRP be completed (IoCompleteRequest()), but
the packet has already been completed. This is a tough bug to find because
the easiest case, a driver actually attempted to complete its own packet
twice, is generally not what happened. Rather, two separate drivers each
believe that they own the packet, and each attempts to complete it. The
first actually works, and the second fails. Tracking down which drivers
in the system actually did this is difficult, generally because the trails
of the first driver have been covered by the second. However, the driver
stack for the current request can be found by examining the DeviceObject
fields in each of the stack locations.
Arguments:
Arg1: 86414720, Address of the IRP
Arg2: 00001bbe
Arg3: 00000000
Arg4: 00000000

Debugging Details:

*************************************************************************
*** ***
*** ***
*** Your debugger is not using the correct symbols ***
*** ***
*** In order for this command to work properly, your symbol path ***
*** must point to .pdb files that have full type information. ***
*** ***
*** Certain .pdb files (such as the public OS symbols) do not ***
*** contain the required information. Contact the group that ***
*** provided you with these symbols if you need this command to ***
*** work. ***
*** ***
*** Type referenced: kernel32!pNlsUserInfo ***
*** ***
*************************************************************************
*************************************************************************
*** ***
*** ***
*** Your debugger is not using the correct symbols ***
*** ***
*** In order for this command to work properly, your symbol path ***
*** must point to .pdb files that have full type information. ***
*** ***
*** Certain .pdb files (such as the public OS symbols) do not ***
*** contain the required information. Contact the group that ***
*** provided you with these symbols if you need this command to ***
*** work. ***
*** ***
*** Type referenced: kernel32!pNlsUserInfo ***
*** ***
*************************************************************************

IRP_ADDRESS: 86414720

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x44

PROCESS_NAME: ScannerClient.e

LAST_CONTROL_TRANSFER: from 804f8afd to 8052a5d8

STACK_TEXT:
ee7436c8 804f8afd 00000003 ee743a24 00000000 nt!RtlpBreakWithStatusInstruction
ee743714 804f96e8 00000003 864a53d0 86414720 nt!KiBugCheckDebugBreak+0x19
ee743af4 804f9c37 00000044 86414720 00001bbe nt!KeBugCheck2+0x574
ee743b14 804ef1e6 00000044 86414720 00001bbe nt!KeBugCheckEx+0x1b
ee743b3c 804f4a03 86414720 86414760 8667ca50 nt!IopFreeIrp+0x22
ee743b90 804febb5 86414760 ee743bdc ee743bd0 nt!IopCompleteRequest+0x1b7
ee743be0 80502b35 00000000 00000000 00000000 nt!KiDeliverApc+0xb3
ee743bf8 804fa737 00000103 864a542c 00000000 nt!KiSwapThread+0x89
ee743c24 8057c97a 00000000 00000000 ee743c40 nt!KeDelayExecutionThread+0x1c9
ee743c48 8057e709 014a542c 86414720 864147fc nt!IopCancelAlertedRequest+0x52
ee743c64 8057f4eb 864a5478 00000103 864a53d0 nt!IopSynchronousServiceTail+0xe1
ee743d00 8057804e 0000001c 00000000 00000000 nt!IopXxxControlFile+0x5c5
ee743d34 8054060c 0000001c 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
ee743d34 7c90eb94 0000001c 00000000 00000000 nt!KiFastCallEntry+0xfc
0012f9f0 7c90d8ef 7c801671 0000001c 00000000 ntdll!KiFastSystemCallRet
0012f9f4 7c801671 0000001c 00000000 00000000 ntdll!ZwDeviceIoControlFile+0xc
0012fa54 004305a6 0000001c 00222016 0012fb4c kernel32!DeviceIoControl+0xdd
0012ff6c 0042da47 00000001 00332fc0 00333030 ScannerClient!main+0x86 [d:\src\c\scannerclient\scannerclient.c @ 36]
0012ffb8 0042d91f 0012fff0 7c816d4f 7c910738 ScannerClient!__tmainCRTStartup+0x117 [f:\dd\vctools\crt_bld\self_x86\crt\src\crt0.c @ 266]
0012ffc0 7c816d4f 7c910738 ffffffff 7ffd5000 ScannerClient!mainCRTStartup+0xf [f:\dd\vctools\crt_bld\self_x86\crt\src\crt0.c @ 182]
0012fff0 00000000 0042bb72 00000000 78746341 kernel32!BaseProcessStart+0x23

STACK_COMMAND: kb

FOLLOWUP_IP:
nt!KiDeliverApc+b3
804febb5 8d55d8 lea edx,[ebp-28h]

SYMBOL_STACK_INDEX: 6

SYMBOL_NAME: nt!KiDeliverApc+b3

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: nt

IMAGE_NAME: ntkrpamp.exe

DEBUG_FLR_IMAGE_TIMESTAMP: 41107b0d

FAILURE_BUCKET_ID: 0x44_nt!KiDeliverApc+b3

BUCKET_ID: 0x44_nt!KiDeliverApc+b3

Followup: MachineOwner

Why the IRP is completed twice (I don’t call IoCompleteRequest by myself) and why I see it only once in my completion routine?


Thanking In Advance,
Mikae.

You need to fix your symbols.

.symfix

Mm
On Aug 20, 2011 12:22 PM, wrote:
> Hello all.
>
> I have strange situation. I pass an IRP down to stack returning
STATUS_PENDING. Completion routine is set. Then I see that my completion
routine is called once, it returns STATUS_SUCCESS and I get the following
BSoD:
>
> 1: kd> !analyze -v
>
***
> *
> * Bugcheck Analysis
> *
>

>
> MULTIPLE_IRP_COMPLETE_REQUESTS (44)
> A driver has requested that an IRP be completed (IoCompleteRequest()), but
> the packet has already been completed. This is a tough bug to find because
> the easiest case, a driver actually attempted to complete its own packet
> twice, is generally not what happened. Rather, two separate drivers each
> believe that they own the packet, and each attempts to complete it. The
> first actually works, and the second fails. Tracking down which drivers
> in the system actually did this is difficult, generally because the trails
> of the first driver have been covered by the second. However, the driver
> stack for the current request can be found by examining the DeviceObject
> fields in each of the stack locations.
> Arguments:
> Arg1: 86414720, Address of the IRP
> Arg2: 00001bbe
> Arg3: 00000000
> Arg4: 00000000
>
> Debugging Details:
> ------------------
>
>
>

>

>
Your debugger is not using the correct symbols
>

>
In order for this command to work properly, your symbol path
>
must point to .pdb files that have full type information.
>

>
Certain .pdb files (such as the public OS symbols) do not
>
contain the required information. Contact the group that
>
provided you with these symbols if you need this command to
>
work.
>

>
Type referenced: kernel32!pNlsUserInfo
>

>

>
>

>

>
Your debugger is not using the correct symbols
>

>
In order for this command to work properly, your symbol path
>
must point to .pdb files that have full type information.
>

>
Certain .pdb files (such as the public OS symbols) do not
>
contain the required information. Contact the group that
>
provided you with these symbols if you need this command to
>
work.
>

>
Type referenced: kernel32!pNlsUserInfo
>

>

>
> IRP_ADDRESS: 86414720
>
> DEFAULT_BUCKET_ID: DRIVER_FAULT
>
> BUGCHECK_STR: 0x44
>
> PROCESS_NAME: ScannerClient.e
>
> LAST_CONTROL_TRANSFER: from 804f8afd to 8052a5d8
>
> STACK_TEXT:
> ee7436c8 804f8afd 00000003 ee743a24 00000000
nt!RtlpBreakWithStatusInstruction
> ee743714 804f96e8 00000003 864a53d0 86414720 nt!KiBugCheckDebugBreak+0x19
> ee743af4 804f9c37 00000044 86414720 00001bbe nt!KeBugCheck2+0x574
> ee743b14 804ef1e6 00000044 86414720 00001bbe nt!KeBugCheckEx+0x1b
> ee743b3c 804f4a03 86414720 86414760 8667ca50 nt!IopFreeIrp+0x22
> ee743b90 804febb5 86414760 ee743bdc ee743bd0 nt!IopCompleteRequest+0x1b7
> ee743be0 80502b35 00000000 00000000 00000000 nt!KiDeliverApc+0xb3
> ee743bf8 804fa737 00000103 864a542c 00000000 nt!KiSwapThread+0x89
> ee743c24 8057c97a 00000000 00000000 ee743c40
nt!KeDelayExecutionThread+0x1c9
> ee743c48 8057e709 014a542c 86414720 864147fc
nt!IopCancelAlertedRequest+0x52
> ee743c64 8057f4eb 864a5478 00000103 864a53d0
nt!IopSynchronousServiceTail+0xe1
> ee743d00 8057804e 0000001c 00000000 00000000 nt!IopXxxControlFile+0x5c5
> ee743d34 8054060c 0000001c 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
> ee743d34 7c90eb94 0000001c 00000000 00000000 nt!KiFastCallEntry+0xfc
> 0012f9f0 7c90d8ef 7c801671 0000001c 00000000 ntdll!KiFastSystemCallRet
> 0012f9f4 7c801671 0000001c 00000000 00000000
ntdll!ZwDeviceIoControlFile+0xc
> 0012fa54 004305a6 0000001c 00222016 0012fb4c kernel32!DeviceIoControl+0xdd
> 0012ff6c 0042da47 00000001 00332fc0 00333030 ScannerClient!main+0x86
[d:\src\c\scannerclient\scannerclient.c @ 36]
> 0012ffb8 0042d91f 0012fff0 7c816d4f 7c910738
ScannerClient!__tmainCRTStartup+0x117
[f:\dd\vctools\crt_bld\self_x86\crt\src\crt0.c @ 266]
> 0012ffc0 7c816d4f 7c910738 ffffffff 7ffd5000
ScannerClient!mainCRTStartup+0xf
[f:\dd\vctools\crt_bld\self_x86\crt\src\crt0.c @ 182]
> 0012fff0 00000000 0042bb72 00000000 78746341
kernel32!BaseProcessStart+0x23
>
>
> STACK_COMMAND: kb
>
> FOLLOWUP_IP:
> nt!KiDeliverApc+b3
> 804febb5 8d55d8 lea edx,[ebp-28h]
>
> SYMBOL_STACK_INDEX: 6
>
> SYMBOL_NAME: nt!KiDeliverApc+b3
>
> FOLLOWUP_NAME: MachineOwner
>
> MODULE_NAME: nt
>
> IMAGE_NAME: ntkrpamp.exe
>
> DEBUG_FLR_IMAGE_TIMESTAMP: 41107b0d
>
> FAILURE_BUCKET_ID: 0x44_nt!KiDeliverApc+b3
>
> BUCKET_ID: 0x44_nt!KiDeliverApc+b3
>
> Followup: MachineOwner
> ---------
>
>
> Why the IRP is completed twice (I don’t call IoCompleteRequest by myself)
and why I see it only once in my completion routine?
>
> –
> Thanking In Advance,
> Mikae.
>
> —
> 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

mm, I tried, but it didn’t help. Anyway, all symbols are visible in stack, I just try to figure out what goes wrong.

My bad - I reread your post, and you’re just missing the kernel32 stuff
that’s sometimes “normal.”

Mm
On Aug 20, 2011 1:11 PM, wrote:
> mm, I tried, but it didn’t help. Anyway, all symbols are visible in stack,
I just try to figure out what goes wrong.
>
> —
> 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

If it may help this is dump of the IRP that BSoDs OS just before passing it to IoFreeIrp in IopCompleteRequest:

ntdll!_IRP
+0x000 Type : 0
+0x002 Size : 0
+0x004 MdlAddress : (null)
+0x008 Flags : 0
+0x00c AssociatedIrp : __unnamed
+0x000 MasterIrp : 0x86701c00 _IRP
+0x000 Type : -24568
+0x002 Size : 0x8630
+0x004 MdlAddress : 0xcccccccc _MDL
+0x008 Flags : 0xcccccccc
+0x00c AssociatedIrp : __unnamed
+0x010 ThreadListEntry : _LIST_ENTRY [0xcccccccc - 0xcccccccc]
+0x018 IoStatus : _IO_STATUS_BLOCK
+0x020 RequestorMode : -52 ‘’
+0x021 PendingReturned : 0xcc ‘’
+0x022 StackCount : -52 ‘’
+0x023 CurrentLocation : -52 ‘’
+0x024 Cancel : 0xcc ‘’
+0x025 CancelIrql : 0xcc ‘’
+0x026 ApcEnvironment : -52 ‘’
+0x027 AllocationFlags : 0xcc ‘’
+0x028 UserIosb : 0xcccccccc _IO_STATUS_BLOCK
+0x02c UserEvent : 0xcccccccc _KEVENT
+0x030 Overlay : __unnamed
+0x038 CancelRoutine : 0xcccccccc void +ffffffffcccccccc
+0x03c UserBuffer : 0xcccccccc
+0x040 Tail : __unnamed
+0x000 IrpCount : -2039473152
+0x000 SystemBuffer : 0x86701c00
+0x010 ThreadListEntry : _LIST_ENTRY [0x8647d018 - 0x8647d018]
+0x000 Flink : 0x8647d018 _LIST_ENTRY [0x8647d018 - 0x8647d018]
+0x000 Flink : 0x8647d018 _LIST_ENTRY [0x8647d018 - 0x8647d018]
+0x004 Blink : 0x8647d018 _LIST_ENTRY [0x8647d018 - 0x8647d018]
+0x004 Blink : 0x8647d018 _LIST_ENTRY [0x8647d018 - 0x8647d018]
+0x000 Flink : 0x8647d018 _LIST_ENTRY [0x8647d018 - 0x8647d018]
+0x004 Blink : 0x8647d018 _LIST_ENTRY [0x8647d018 - 0x8647d018]
+0x018 IoStatus : _IO_STATUS_BLOCK
+0x000 Status : -1073741536
+0x000 Pointer : 0xc0000120
+0x004 Information : 0
+0x020 RequestorMode : 1 ‘’
+0x021 PendingReturned : 0x1 ‘’
+0x022 StackCount : 4 ‘’
+0x023 CurrentLocation : 6 ‘’
+0x024 Cancel : 0x1 ‘’
+0x025 CancelIrql : 0x1 ‘’
+0x026 ApcEnvironment : 0 ‘’
+0x027 AllocationFlags : 0xc ‘’
+0x028 UserIosb : 0x0012fa30 _IO_STATUS_BLOCK
+0x000 Status : 3342336
+0x000 Pointer : 0x00330000
+0x004 Information : 0xffffffff
+0x02c UserEvent : (null)
+0x030 Overlay : __unnamed
+0x000 AsynchronousParameters : __unnamed
+0x000 UserApcRoutine : (null)
+0x004 UserApcContext : (null)
+0x000 AllocationSize : _LARGE_INTEGER 0x0
+0x000 LowPart : 0
+0x004 HighPart : 0
+0x000 u : __unnamed
+0x000 QuadPart : 0
+0x038 CancelRoutine : (null)
+0x03c UserBuffer : (null)
+0x040 Tail : __unnamed
+0x000 Overlay : __unnamed
+0x000 DeviceQueueEntry : _KDEVICE_QUEUE_ENTRY
+0x000 DriverContext : [4] 0x00300012
+0x010 Thread : 0x86439054 _ETHREAD
+0x014 AuxiliaryBuffer : 0x804f484c “j,hH???”
+0x018 ListEntry : _LIST_ENTRY [0x8057f97c - 0x0]
+0x020 CurrentStackLocation : (null)
+0x020 PacketType : 0
+0x024 OriginalFileObject : 0x86628ea0 _FILE_OBJECT
+0x000 Apc : _KAPC
+0x000 Type : 18
+0x002 Size : 48
+0x004 Spare0 : 0
+0x008 Thread : 0x86439020 _KTHREAD
+0x00c ApcListEntry : _LIST_ENTRY [0x86439054 - 0x86439054]
+0x014 KernelRoutine : 0x804f484c void nt!IopCompleteRequest+0
+0x018 RundownRoutine : 0x8057f97c void nt!IopAbortRequest+0
+0x01c NormalRoutine : (null)
+0x020 NormalContext : (null)
+0x024 SystemArgument1 : 0x86628ea0
+0x028 SystemArgument2 : (null)
+0x02c ApcStateIndex : 0 ‘’
+0x02d ApcMode : 0 ‘’
+0x02e Inserted : 0 ‘’
+0x000 CompletionKey : 0x00300012

Solved: I accidentally set _IRP::Type to 0, so IopFreeIrp has decided that the IRP was already freed. Stupid typo, I’ve forgotten to set ‘&’ before InterlockedExchangePointer parameter, passing pointer to IRP to it instead of pointer to pointer.

>Then I see that my completion routine is called once, it returns STATUS_SUCCESS

If your completion routine returns STATUS_SUCCESS, then it must have this magic code:

if( Irp->PendingReturned )
IoMarkIrpPending(Irp);


Maxim S. Shatskih
Windows DDK MVP
xxxxx@storagecraft.com
http://www.storagecraft.com

> If your completion routine returns STATUS_SUCCESS, then it must have this magic code:

if( Irp->PendingReturned ) IoMarkIrpPending(Irp);

…unless he already called IoMarkIrpPending in his Dispatch routine before passing it down the stack
(if he does it this way he must unconditionally return STATUS_PENDING from it, regardless of the result that IoCallDriver() returns)…

Anton Bassov