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!
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
