Debugging Stop 0x44 - MULTIPLE_IRP_COMPLETE_REQUESTS

x BlueRobot

x BlueRobot

Administrator
Staff member
Joined
May 7, 2013
Posts
10,400
Rich (BB code): 
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: ffffd00a304432c0, Address of the IRP
Arg2: 0000000000001232
Arg3: 0000000000000000
Arg4: 0000000000000000

Rich (BB code): 
1: kd> knL
 # Child-SP          RetAddr               Call Site
00 ffffcc89`9a82f1a8 fffff804`5f007ddd     nt!KeBugCheckEx
01 ffffcc89`9a82f1b0 fffff804`5ee668d7     nt!IopfCompleteRequest+0x1a14ed << The same IRP request is completed twice!
02 ffffcc89`9a82f2c0 fffff804`608084ad     nt!IofCompleteRequest+0x17
03 (Inline Function) --------`--------     Wdf01000!FxIrp::CompleteRequest+0x13 << A wrapper function used by WDF to call IoCompleteRequest
04 ffffcc89`9a82f2f0 fffff804`60807f7b     Wdf01000!FxRequest::CompleteInternal+0x22d
05 (Inline Function) --------`--------     Wdf01000!FxRequest::Complete+0x31
06 ffffcc89`9a82f380 fffff804`7942b524     Wdf01000!imp_WdfRequestComplete+0x8b
07 ffffcc89`9a82f3e0 fffff804`7942b6dd     USBXHCI!Control_Transfer_Complete+0x1d8
08 ffffcc89`9a82f460 fffff804`7942afc1     USBXHCI!Control_Transfer_CompleteCancelable+0x161
09 ffffcc89`9a82f4b0 fffff804`7942a2b0     USBXHCI!Control_ProcessTransferEventWithED1+0x48d
0a ffffcc89`9a82f540 fffff804`794298d3     USBXHCI!Control_EP_TransferEventHandler+0x10
0b ffffcc89`9a82f570 fffff804`7941ba4f     USBXHCI!TR_TransferEventHandler+0x17
0c ffffcc89`9a82f5a0 fffff804`7943c2f2     USBXHCI!Endpoint_TransferEventHandler+0x167
0d ffffcc89`9a82f620 fffff804`7941ea3c     USBXHCI!UsbDevice_TransferEventHandler+0xa6
0e ffffcc89`9a82f680 fffff804`7941f55c     USBXHCI!Interrupter_DeferredWorkProcessor+0x578
0f ffffcc89`9a82f780 fffff804`608026ad     USBXHCI!Interrupter_WdfEvtInterruptDpc+0xc
10 (Inline Function) --------`--------     Wdf01000!FxInterrupt::DpcHandler+0x70
11 ffffcc89`9a82f7b0 fffff804`5eec296a     Wdf01000!FxInterrupt::_InterruptDpcThunk+0x9d
12 ffffcc89`9a82f7f0 fffff804`5eec1fbf     nt!KiExecuteAllDpcs+0x30a
13 ffffcc89`9a82f930 fffff804`5efc764e     nt!KiRetireDpcList+0x1ef
14 ffffcc89`9a82fb60 00000000`00000000     nt!KiIdleLoop+0x7e

Rich (BB code): 
1: kd> !irp ffffd00a304432c0
IRP signature does not match, probably not an IRP.  Use any flag to force.

This appears to be a very common issue with Stop 0x44 bugchecks, I've read suggestions that the Type and Size fields are overrun or the IRP is freed to a lookaside list which does appear to be what is happening in this particular bugcheck.

Rich (BB code): 
1: kd> !irp ffffd00a304432c0 1
Irp is active with 15 stacks 12 is current (= 0xffffd00a304436a8)
 No Mdl: No System Buffer: Thread 00000000:  Irp stack trace.
Flags = 00000000
ThreadListEntry.Flink = ffffd00a304432e0
ThreadListEntry.Blink = ffffd00a304432e0
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 01
UserIosb = 00000000
UserEvent = 00000000
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = ffffd00a30443338
Tail.Overlay.Thread = 00000000
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = ffffd00a30443368
Tail.Overlay.ListEntry.Blink = ffffd00a30443368
Tail.Overlay.CurrentStackLocation = ffffd00a304436a8
Tail.Overlay.OriginalFileObject = 00000000
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
     cmd  flg cl Device   File     Completion-Context
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000

            Args: 00000000 00000000 00000000 00000000
>[IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
            0  1 ffffd00a269e0570 00000000 00000000-00000000    pending
           \Driver\USBXHCI
            Args: ffffcc899a82e628 00000000 0x220003 ffffd00a26707500
 [IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
            0 e0 ffffd00a0d789de0 00000000 00000000-00000000    
           \Driver\USBXHCI
            Args: ffffcc899a82e628 00000000 0x220003 ffffd00a26707500
 [IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
            0 e1 ffffd00a0d789de0 00000000 00000000-00000000    pending
           \Driver\USBXHCI
            Args: ffffcc899a82e628 00000000 0x220003 ffffd00a26707500
 [IRP_MJ_INTERNAL_DEVICE_CONTROL(f), N/A(0)]
            0 e0 ffffd00a2769e2f0 00000000 00000000-00000000
           \Driver\USBHUB3
            Args: ffffcc899a82e628 00000000 0x220003 ffffd00a26707500

Notice the duplicate stack locations within the IRP? This causes the same completion routine to be called twice which leads to the bugcheck.

As a result of misunderstanding the location of completion routines in the I/O stack, a very common mistake occurs when passing an IRP from your driver to an underlying driver. This mistake, illustrated in Figure 3, is to simply copy the current I/O stack location to the next driver’s I/O stack location. The problem is that copying the contents of the current stack location to the next stack location also copies the I/O completion routine along with it. This works fine, as long as there is no completion routine in the current stack location. If a completion routine was supplied, it will now appear in two different I/O stack locations, with the obvious result of it being called twice. This is generally not good, and results in an eventual blue screen or other unstable system behavior. Of course, the caller’s code could be written to handle this case and everything will still work fine. But few driver writers anticipate that their completion routines will be called incorrectly!
Click to expand...

Rich (BB code): 
1: kd> dt _IO_STACK_LOCATION ffffd00a`304436f0+0x48
win32k!_IO_STACK_LOCATION
   +0x000 MajorFunction    : 0xf ''
   +0x001 MinorFunction    : 0 ''
   +0x002 Flags            : 0 ''
   +0x003 Control          : 0xe1 ''
   +0x008 Parameters       : _IO_STACK_LOCATION::<unnamed-type-Parameters>
   +0x028 DeviceObject     : 0xffffd00a`0d789de0 _DEVICE_OBJECT
   +0x030 FileObject       : (null)
   +0x038 CompletionRoutine : 0xfffff804`5ef34020     long  nt!IopUnloadSafeCompletion+0
   +0x040 Context          : 0xffffd00a`328f8f70 Void

This is documented by ReactOS and is very similar to the actual implementation as shown here:

Rich (BB code): 
nt!IopUnloadSafeCompletion+0x33:
fffff804`5ef34053 498b18          mov     rbx,qword ptr [r8]
fffff804`5ef34056 ba496f4370      mov     edx,70436F49h
fffff804`5ef3405b 488bcb          mov     rcx,rbx
fffff804`5ef3405e e84d96edff      call    nt!ObfReferenceObjectWithTag (fffff804`5ee0d6b0) (1)
fffff804`5ef34063 488b4610        mov     rax,qword ptr [rsi+10h]
fffff804`5ef34067 488bd5          mov     rdx,rbp
fffff804`5ef3406a 4c8b4608        mov     r8,qword ptr [rsi+8]
fffff804`5ef3406e 498bce          mov     rcx,r14
fffff804`5ef34071 e87a850900      call    nt!guard_dispatch_icall (fffff804`5efcc5f0) (2)
fffff804`5ef34076 33d2            xor     edx,edx
fffff804`5ef34078 488bce          mov     rcx,rsi
fffff804`5ef3407b 8bf8            mov     edi,eax
fffff804`5ef3407d e81ea02300      call    nt!ExFreePool (fffff804`5f16e0a0) (3)
fffff804`5ef34082 ba496f4370      mov     edx,70436F49h
fffff804`5ef34087 488bcb          mov     rcx,rbx
fffff804`5ef3408a e891baf0ff      call    nt!ObfDereferenceObjectWithTag (fffff804`5ee3fb20) (4)

We open a handle to the device object through a pointer stored on the context object which is stored in the Context field (1). The completion routine is then called (2) and the pool allocation for the context object is then freed (3), afterwards we close the handle to our context object and decrement the reference count. The nt!guard_dispatch_icall function is wrapper function which is used by Control Flow Guard (CFG) to ensure that we are jumping to an appropriate address and some address which is outside of our intended control flow i.e. the address is within the address space of a module loaded by our process.

ReactOS: ntoskrnl/io/iomgr/iocomp.c File Reference

The Context member of the I/O stack location is cast to _IO_UNLOAD_SAFE_COMPLETION_CONTEXT which has the following structure:

Rich (BB code): 
 //
 // I/O Completion Context for IoSetIoCompletionRoutineEx
 //
 typedef struct _IO_UNLOAD_SAFE_COMPLETION_CONTEXT
 {
     PDEVICE_OBJECT DeviceObject;
     PVOID Context;
     PIO_COMPLETION_ROUTINE CompletionRoutine;
 } IO_UNLOAD_SAFE_COMPLETION_CONTEXT, *PIO_UNLOAD_SAFE_COMPLETION_CONTEXT;

Unfortunately, there isn't too much you can do here apart from run Driver Verifier with the usual settings and then check the I/O verifier logs with !verifier 0x100 <IRP Address> to see where the IRP has been and who has completed what. You will need a complete kernel memory dump in order to extract this information.

Curiosities:

Rich (BB code): 
1: kd> !load pde; !dpx
=========================================================================================
 PDE v11.3 - Copyright 2017 Andrew Richards
=========================================================================================
Start memory scan  : 0xffffcc899a82f1a8 ($csp)
End memory scan    : 0xffffcc899a830000 (Kernel Stack Base)

               rdi : 0xffffd00a2667ea00 :  dt Wdf01000!FxIoQueue
               r11 : 0xffffcc899a82f2b8 : 0xfffff8045ee668d7 : nt!IofCompleteRequest+0x17
0xffffcc899a82f1d8 : 0xfffff804609510d8 : ACPI!ACPIDispatchIrp+0xc8
0xffffcc899a82f1e0 : 0xffffd00a0b2423f0 : 0xfffff804609cf358 : ACPI!gAcpiTriageInfo
0xffffcc899a82f218 : 0xfffff8045ee38ba6 : nt!RtlpHpLfhSlotAllocate+0x126
0xffffcc899a82f248 : 0xfffff80477f7d8f8 : UsbHub3!WPP_e683e3a97dd23da98d402d95dd0016a2_Traceguids
0xffffcc899a82f258 : 0xfffff8045ee37159 : nt!IofCallDriver+0x59
0xffffcc899a82f2a8 : 0xffffd00a2d037020 :  dt Wdf01000!FxRequestFromLookaside
0xffffcc899a82f2b8 : 0xfffff8045ee668d7 : nt!IofCompleteRequest+0x17
0xffffcc899a82f2e0 : 0xffffd00a2667ea00 :  dt Wdf01000!FxIoQueue
0xffffcc899a82f2e8 : 0xfffff804608084ad : Wdf01000!FxRequest::CompleteInternal+0x22d
0xffffcc899a82f2f8 : 0xffffd00a2d037020 :  dt Wdf01000!FxRequestFromLookaside
0xffffcc899a82f330 : 0xffffd00a2763b0b0 :  !da ""00 SLT02 DCI01""
0xffffcc899a82f338 : 0xfffff8047942d4d9 : USBXHCI!WPP_RECORDER_SF_DDqdDD+0x135
[...]

In case you've examined the thread stack using !dpx and noticed a few strings, those are WDF log Ids as shown below:

Rich (BB code): 
1: kd> !wdflogdump USBXHCI -d
Log dump command                           Log ID                   Size
================                           ======                   ====
 !wdflogdump   USBXHCI -a 0xFFFFD00A2CEE74E0  00 SLT08 DCI05           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2CEE9010  00 SLT03 DCI11           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2CEE89B0  00 SLT03 DCI10           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2A184010  00 SLT09 DCI03           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A27D966E0  00 SLT07 DCI05           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2A19C9B0  00 SLT07 DCI04           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2A19C4E0  00 SLT07 DCI03           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A27D9A9B0  00 SLT08 DCI15           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A27D9B010  00 SLT09 DCI01           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A27D9E010  00 SLT08 DCI01           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A266C1860  00 SLT07 DCI01           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A278B3010  00 SLT06 DCI03           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A278B39B0  00 SLT05 DCI03           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A278BC9F0  00 SLT06 DCI01           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2611A010  00 SLT05 DCI01           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2785D610  00 SLT04 DCI03           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2782F9F0  00 SLT04 DCI01           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A26A11B20  00 SLT03 DCI09           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2773AAF0  00 SLT03 DCI31           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2773BAB0  00 SLT03 DCI01           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A267214E0  00 SLT02 DCI07           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A268444E0  00 SLT02 DCI05           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A26721010  00 SLT02 DCI03           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A267654E0  00 SLT01 DCI07           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A27630470  00 SLT01 DCI05           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A27630940  00 SLT01 DCI03           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2763B0B0  00 SLT02 DCI01           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A2763BA50  00 SLT01 DCI01           1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A263178A0  00 CMD                   1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A263148A0  00 INT00                 1024
 !wdflogdump   USBXHCI -a 0xFFFFD00A26BB4050  00 8086 a36d             1024

You can then dump the log using the suggested command:

Rich (BB code): 
1: kd> !wdflogdump  USBXHCI -a 0xFFFFD00A2763B0B0 
Trace searchpath is:

Trace format prefix is: %7!u!: %!FUNC! -
Trying to extract TMF information from - C:\ProgramData\dbg\sym\usbxhci.pdb\682ED4C113AF6BDD8D0D92FBCEA54A861\usbxhci.pdb
--- start of log ---
1622018018: Control_WdfEvtIoDefault - 2.1.0: WdfRequest 0x00002FF5CDE20AF8 Bytes 1 transferData 0xFFFFD00A321DF6A0
1622018019: Control_Transfer_MapIntoRing - 2.1.0: Programmed WdfRequest 0x00002FF5CDE20AF8 transferData 0xFFFFD00A321DF6A0
1622018026: Control_ProcessTransferEventWithED1 - 2.1.0: TransferEventTrb 0xFFFFCC899A82F6F8 0x1 Length 1 EventData 1 Pointer 0xffffd00a321df6a0
1622018027: Control_ProcessTransferEventWithED1 - 2.1.0: WdfRequest 0x00002FF5CDE20AF8 transferData 0xFFFFD00A321DF6A0
1622018031: Control_ProcessTransferEventWithED1 - 2.1.0: TransferEventTrb 0xFFFFCC899A82F6F8 0x1 Length 0 EventData 1 Pointer 0xffffd00a321df6a4
1622018032: Control_ProcessTransferEventWithED1 - 2.1.0: WdfRequest 0x00002FF5CDE20AF8 transferData 0xFFFFD00A321DF6A0
1622018033: Control_Transfer_Complete - 2.1.0: WdfRequest 0x00002FF5CDE20AF8 completed with STATUS_SUCCESS BytesTransferred 1 BytesTotal 1
1622018404: Control_WdfEvtIoDefault - 2.1.0: WdfRequest 0x00002FF5D2FC8FD8 Bytes 1 transferData 0xFFFFD00A2D0371C0
1622018405: Control_Transfer_MapIntoRing - 2.1.0: Programmed WdfRequest 0x00002FF5D2FC8FD8 transferData 0xFFFFD00A2D0371C0
1622018419: Control_ProcessTransferEventWithED1 - 2.1.0: TransferEventTrb 0xFFFFCC899A82F6F8 0x1 Length 1 EventData 1 Pointer 0xffffd00a2d0371c0
1622018420: Control_ProcessTransferEventWithED1 - 2.1.0: WdfRequest 0x00002FF5D2FC8FD8 transferData 0xFFFFD00A2D0371C0
1622018423: Control_ProcessTransferEventWithED1 - 2.1.0: TransferEventTrb 0xFFFFCC899A82F6F8 0x1 Length 0 EventData 1 Pointer 0xffffd00a2d0371c4
1622018424: Control_ProcessTransferEventWithED1 - 2.1.0: WdfRequest 0x00002FF5D2FC8FD8 transferData 0xFFFFD00A2D0371C0
1622018425: Control_Transfer_Complete - 2.1.0: WdfRequest 0x00002FF5D2FC8FD8 completed with STATUS_SUCCESS BytesTransferred 1 BytesTotal 1
---- end of log ----

The requests are handles to a WdfRequest object so you can use !wdfrequest with it or dump the associated object type using !wdfhandle.

Rich (BB code): 
1: kd> !wdfhandle 00002FF5D2FC8FD8
Treating handle as a KMDF handle!

Dumping WDFHANDLE 0x00002ff5d2fc8fd8
=============================
Handle type is WDFREQUEST
Refcount: 1
Contexts:
    context:  dt 0xffffd00a2d0371c0 USBXHCI!REQUEST_DATA (size is 0x300 bytes)
    <no associated attribute callbacks>
Owning device: !wdfdevice 0x00002ff5d943ff98

!wdfobject 0xffffd00a2d037020


References:

Multiple IRP completions
The NT Insider:Secrets of the Universe Revealed! - How NT Handles I/O Completion
The State of Exploit Development: Part 1 | CrowdStrike
How Control Flow Integrity is implemented in Windows 10 · lucasg.github.io
 
Last edited:
You must log in or register to reply here.

Has Sysnative Forums helped you? Please consider donating to help us support the site!

Back
Top