Two minifilters, MULTIPLE_IRP_COMPLETE_REQUESTS BSOD

NTFSD
1

Hello.

I have a problem on a system where two minifilters are running. One of them implements own oplock processing. Another minifilter does oplock request using FltPerformAsynchronousIo with specified PFLT_COMPLETED_ASYNC_IO_CALLBACK CallbackRoutine. When file is closed and PostCleanup invokes FltCheckOplock, BSOD MULTIPLE_IRP_COMPLETE_REQUESTS (44) happends.

Here are the main pieces of those minifilters code that illustrates a problem.
Both drivers are based on Passthrough sample. Some things in Passthrough2 are done just to simplify and show the problem. I know that one global oplock structure and detection of stream by file extension is not good, but that does not have effect on a problem.

/////////////////////////////////////////////////////////////
I. Minifilter that does request of the oplock (Passthrough, altitude 370400):

BOOLEAN IsMatchWithExt(PUNICODE_STRING pUs, PWCHAR wsFile)
{
UNICODE_STRING usFile;
RtlInitUnicodeString(&usFile, wsFile);

if (wsFile && pUs && pUs->Length && usFile.Length)
{
return 0 == RtlCompareUnicodeString(pUs, &usFile, TRUE);
}else
{
return FALSE;
}
}

BOOLEAN IsOurFile(IN OUT PFLT_CALLBACK_DATA Data)
{
PFLT_FILE_NAME_INFORMATION NameInfo = NULL;
NTSTATUS Status = FltGetFileNameInformation(Data, FLT_FILE_NAME_NORMALIZED|FLT_FILE_NAME_QUERY_DEFAULT, &NameInfo);
BOOLEAN bRet = FALSE;

if (NT_SUCCESS(Status))
{
Status = FltParseFileNameInformation( NameInfo );
if (NT_SUCCESS(Status))
{
if ( IsMatchWithExt(&NameInfo->Extension, L"123ABC789") )
{
bRet = TRUE;
}
}
}

if (NameInfo)
{
FltReleaseFileNameInformation(NameInfo);
}

return bRet;
}

FLT_PREOP_CALLBACK_STATUS
PtPreCreate(
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
OUT PVOID *CompletionContext
)
{
return FLT_PREOP_SUCCESS_WITH_CALLBACK;
}

VOID PtCompleteAsyncIoCallback(
PFLT_CALLBACK_DATA CallbackData,
PFLT_CONTEXT Context
)
{
PFLT_CALLBACK_DATA RetNewCallbackData = (PFLT_CALLBACK_DATA)Context;
DbgPrint("PtCompleteAsyncIoCallback:\n");

FltFreeCallbackData(RetNewCallbackData);
}

FLT_POSTOP_CALLBACK_STATUS
PtPostCreate(
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
IN PVOID CompletionContext,
IN FLT_POST_OPERATION_FLAGS Flags
)
{
UNREFERENCED_PARAMETER( FltObjects );
UNREFERENCED_PARAMETER( CompletionContext );

if (IsOurFile(Data))
{
PFLT_CALLBACK_DATA NewRequest = NULL;
NTSTATUS Status = FltAllocateCallbackData(FltObjects->Instance, FltObjects->FileObject, &NewRequest);
DbgPrint("PtPostCreate: FltAllocateCallbackData 0x%08X\n", Status );
if (NT_SUCCESS(Status))
{
NewRequest->Iopb->MajorFunction = IRP_MJ_FILE_SYSTEM_CONTROL;
NewRequest->Iopb->MinorFunction = IRP_MN_USER_FS_REQUEST;
NewRequest->Iopb->OperationFlags = 0;
NewRequest->Iopb->Parameters.FileSystemControl.Buffered.FsControlCode = FSCTL_REQUEST_FILTER_OPLOCK;
NewRequest->Iopb->Parameters.FileSystemControl.Buffered.InputBufferLength = 0;
NewRequest->Iopb->Parameters.FileSystemControl.Buffered.OutputBufferLength = 0;
NewRequest->Iopb->Parameters.FileSystemControl.Buffered.SystemBuffer = NULL;

Status = FltPerformAsynchronousIo(
NewRequest,
PtCompleteAsyncIoCallback,
NewRequest
);
DbgPrint("PtPostCreate: FltPerformAsynchronousIo 0x%08X\n", Status );
}
}

return FLT_POSTOP_FINISHED_PROCESSING;
}
/////////////////////////////////////////////////////////////

II. Minifilter which does oplocks handling (Passthrough2, altitude 270400):

BOOLEAN IsMatchWithExt(PUNICODE_STRING pUs, PWCHAR wsFile);
BOOLEAN IsOurFile(IN OUT PFLT_CALLBACK_DATA Data);

FLT_PREOP_CALLBACK_STATUS
Pt2PreCreate(
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
OUT PVOID *CompletionContext
)
{
return FLT_PREOP_SUCCESS_WITH_CALLBACK;
}

FLT_POSTOP_CALLBACK_STATUS
Pt2PostCreate(
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
IN PVOID CompletionContext,
IN FLT_POST_OPERATION_FLAGS Flags
)
{
UNREFERENCED_PARAMETER( FltObjects );
UNREFERENCED_PARAMETER( CompletionContext );

if (IsOurFile(Data) &&
NULL == g_Oplock)
{
FltInitializeOplock(&g_Oplock);
}

return FLT_POSTOP_FINISHED_PROCESSING;
}

FLT_PREOP_CALLBACK_STATUS
Pt2PreCleanup(
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
OUT PVOID *CompletionContext
)
{
if (IsOurFile(Data))
{
*(PULONG)CompletionContext = 1;
return FLT_PREOP_SUCCESS_WITH_CALLBACK;

}

return FLT_PREOP_SUCCESS_NO_CALLBACK;
}

FLT_POSTOP_CALLBACK_STATUS
Pt2PostCleanup (
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
IN PVOID CompletionContext,
IN FLT_POST_OPERATION_FLAGS Flags
)
{
if ((ULONG)1 == (ULONG)CompletionContext)
{
FltCheckOplock(&g_Oplock, Data, NULL, NULL, NULL);

FltUninitializeOplock(&g_Oplock);
g_Oplock = NULL;
}

return FLT_POSTOP_FINISHED_PROCESSING;
}

FLT_PREOP_CALLBACK_STATUS
Pt2PreFileSystemControl(
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
OUT PVOID *CompletionContext
)
{
ULONG fsControlCode = Data->Iopb->Parameters.FileSystemControl.Common.FsControlCode;

if (FSCTL_REQUEST_FILTER_OPLOCK != fsControlCode)
{
return FLT_PREOP_SUCCESS_NO_CALLBACK;
}

if (IsOurFile(Data))
{
FLT_PREOP_CALLBACK_STATUS status = FltOplockFsctrl(
&g_Oplock, //__in POPLOCK Oplock,
Data, //__in PFLT_CALLBACK_DATA CallbackData,
1 //__in ULONG OpenCount
);
DbgPrint("Pt2PreFileSystemControl status=%d\n", status);
return status;
}

return FLT_PREOP_SUCCESS_NO_CALLBACK;
}

////////////////////////////////////////////////

The minifilter which requests oplock: "PassThrough", altitude "370400".
The minifilter which handles oplocks: "PassThrough2", altitude "270400".

Output of analyze command:
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: 816e2968, Address of the IRP
Arg2: 00000d64
Arg3: 00000000
Arg4: 00000000

Debugging Details:

TRIAGER: Could not open triage file : C:\WINDDK\8.0\Debuggers\x64\triage\modclass.ini, error 2

IRP_ADDRESS: 816e2968

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x44

PROCESS_NAME: FileTestOplocks

LAST_CONTROL_TRANSFER: from 804f7b9d to 80527bdc

STACK_TEXT:
f05f91c8 804f7b9d 00000003 f05f9524 00000000 nt!RtlpBreakWithStatusInstruction
f05f9214 804f878a 00000003 00000000 816e2968 nt!KiBugCheckDebugBreak+0x19
f05f95f4 804f8cb5 00000044 816e2968 00000d64 nt!KeBugCheck2+0x574
f05f9614 804f08c1 00000044 816e2968 00000d64 nt!KeBugCheckEx+0x1b
f05f964c f9789785 f05f9680 f9789d9f 816e2968 nt!IopfCompleteRequest+0x2c5
f05f9654 f9789d9f 816e2968 00000000 816e2ab3 fltMgr!FltpCompleteRequest+0x2d
f05f9680 f978cd59 f05f9698 00000000 00000001 fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x10f
f05f96b0 f978a0f5 816bc444 00000004 00000000 fltMgr!FltCompletePendedPreOperation+0x8b
f05f96c4 804f069e 81ba5978 816e2968 816bc444 fltMgr!FltpFsRtlCompletionRoutine+0x27
f05f96f4 804eb8fb e10adfe0 816b8788 816b8788 nt!IopfCompleteRequest+0xa2
f05f9738 804ec13b e10adfe0 816b88f4 816b8788 nt!FsRtlOplockCleanup+0xc7
f05f9758 f978a18b f9ec8f8c 816b8788 00000000 nt!FsRtlCheckOplock+0x153
f05f9784 f9ec899f f9ec8f8c 816908cc 00000000 fltMgr!FltCheckOplock+0x87
f05f97a0 f9786ef3 816908cc f05f97c4 00000001 PassThrough2!Pt2PostCleanup+0x1f [d:\work\tickets\35774\passthrough2navoplock\passthrough2.c @ 1018]
f05f9808 f9789338 00690870 816b88d3 81690870 fltMgr!FltpPerformPostCallbacks+0x1c5
f05f981c f9789867 81690870 816b8788 f05f985c fltMgr!FltpProcessIoCompletion+0x10
f05f982c 804f069e 81ba5978 816b8788 81690870 fltMgr!FltpPassThroughCompletion+0x89
f05f985c f96e26bb e109e008 81b0d100 f05f9a7c nt!IopfCompleteRequest+0xa2
f05f986c f9707c9d f05f9a98 816b8788 00000000 Ntfs!NtfsCompleteRequest+0xac
f05f9a7c f9707d4d f05f9a98 816b8788 00000000 Ntfs!NtfsCommonCleanup+0x2604
f05f9bf4 804ee119 81b0d020 816b8788 816b8788 Ntfs!NtfsFsdCleanup+0xcf
f05f9c70 80578d3c 81956728 81bb8730 81956740 nt!IopfCallDriver+0x31
f05f9ca4 805b2154 81924230 81ba5978 0012019f nt!IopCloseFile+0x27c
f05f9cd4 805b1a81 81924230 00000001 81bb8730 nt!ObpDecrementHandleCount+0xd4
f05f9cfc 805b1b1f e19310f8 81956740 00000098 nt!ObpCloseHandleTableEntry+0x14d
f05f9d44 805b1c57 00000098 00000001 00000000 nt!ObpCloseHandle+0x87
f05f9d58 8053d638 00000098 0012f4cc 7c90e4f4 nt!NtClose+0x1d
f05f9d58 7c90e4f4 00000098 0012f4cc 7c90e4f4 nt!KiFastCallEntry+0xf8
0012f4bc 7c90cfdc 7c809c1b 00000098 0012f5bc ntdll!KiFastSystemCallRet
0012f4c0 7c809c1b 00000098 0012f5bc 0046c94e ntdll!NtClose+0xc
0012f4cc 0046c94e 00000098 0012f698 00453149 kernel32!CloseHandle+0x51
WARNING: Stack unwind information not available. Following frames may be wrong.
0012f5bc 0046beff 00010164 0012f794 00453149 FileTestOplocks+0x6c94e
0012f698 0046b774 00010164 00000000 00000419 FileTestOplocks+0x6beff
0012f794 7e418734 00010164 00000111 00000419 FileTestOplocks+0x6b774
0012f7c0 7e423ce4 00453149 00010164 00000111 USER32!InternalCallWinProc+0x28
0012f82c 7e423b30 00000000 00453149 00010164 USER32!UserCallDlgProcCheckWow+0x146
0012f874 7e42309b 00000000 00000111 00000419 USER32!DefDlgProcWorker+0xa8
0012f8a4 7e4292e3 007603b0 0075e220 00000419 USER32!SendMessageWorker+0x384
0012f8c4 773f7354 00010164 00000111 00000419 USER32!SendMessageW+0x7f
0012f8e4 773f7436 0019a2c0 00000000 000b0036 COMCTL32!Button_NotifyParent+0x3d
0012f900 773f973b 0019a2c0 00000001 0012f9f8 COMCTL32!Button_ReleaseCapture+0xd7
0012f990 7e418734 00010196 00000202 00000000 COMCTL32!Button_WndProc+0x887
0012f9bc 7e418816 773f8eb4 00010196 00000202 USER32!InternalCallWinProc+0x28
0012fa24 7e4189cd 00000000 773f8eb4 00010196 USER32!UserCallWinProcCheckWow+0x150
0012fa84 7e418a10 0012fca0 00000000 0012fab8 USER32!DispatchMessageWorker+0x306
0012fa94 7e4274ff 0012fca0 7ffd7000 0012fac8 USER32!DispatchMessageW+0xf
0012fab8 0045cf2d 0001015c 007618c8 0012fce4 USER32!IsDialogMessageW+0x572
0012fbbc 0045bb4b 0001015c 00010160 0012fca0 FileTestOplocks+0x5cf2d
0012fce4 00486e62 00000000 001564e0 80000001 FileTestOplocks+0x5bb4b
0012fef8 004a204f 00400000 00000000 000205f4 FileTestOplocks+0x86e62
0012ffb8 004a1d8d 0012fff0 7c817067 80000001 FileTestOplocks+0xa204f
0012ffc0 7c817067 80000001 001295bc 7ffd7000 FileTestOplocks+0xa1d8d
0012fff0 00000000 00454409 00000000 78746341 kernel32!BaseProcessStart+0x23

STACK_COMMAND: kb

FOLLOWUP_IP:
PassThrough2!Pt2PostCleanup+1f [d:\work\tickets\35774\passthrough2navoplock\passthrough2.c @ 1018]
f9ec899f 688c8fecf9 push offset PassThrough2!g_Oplock (f9ec8f8c)

FAULTING_SOURCE_LINE: d:\work\tickets\35774\passthrough2navoplock\passthrough2.c

FAULTING_SOURCE_FILE: d:\work\tickets\35774\passthrough2navoplock\passthrough2.c

FAULTING_SOURCE_LINE_NUMBER: 1018

FAULTING_SOURCE_CODE:
1014: if ((ULONG)1 == (ULONG)CompletionContext)
1015: {
1016: FltCheckOplock(&g_Oplock, Data, NULL, NULL, NULL);
1017:

1018: FltUninitializeOplock(&g_Oplock);
1019: g_Oplock = NULL;
1020: }
1021:
1022: return FLT_POSTOP_FINISHED_PROCESSING;
1023: }

The sequence of execution during debug:

// On create file C:\Testfile.123ABC789

  1. PtPostCreate, FltAllocateCallbackData, FltPerformAsynchronousIo(FSCTL_REQUEST_FILTER_OPLOCK)
  2. Pt2PreFileSystemControl, FLT_PREOP_PENDING from FltOplockFsctrl

//On close file C:\Testfile.123ABC789
3) Pt2PostCleanup, call of FltCheckOplock
4) PtCompleteAsyncIoCallback, call of FltFreeCallbackData
?
BSOD 44

During debug breakpoint on fltMgr!FltpCompleteRequest was invoked twice for the Irp corresponding to the FSCTL_REQUEST_FILTER_OPLOCK. First time it succeed, on the second time it crashed system.

Both that drivers seems correct for me, but considering BSOD there is an error somewhere. Tested on WinXP and Win7. When just one of minifilters is running all works great. I can attach a full sample sources ready for compilation, if required.

Could you please point me to the problems in specified sources?

Best regards,
Alexey Barabash

2

Have you tried looking at the IRP log?

http://msdn.microsoft.com/en-us/library/windows/hardware/ff547329(v=vs.85).aspx

You really want to see where the IRP was already completed (or freed).

Tony
OSR

3

Hello and Merry Christmas!

Thanks for the reply. I've launched the verifier with options from that
article and it gave me a different bug-check code. Unfortunately, I was not
able to review output of dc2wmiparser.exe because system crashed before it
wrote anything.

Also I rewrote sample drivers to get rid of any oplock handling - but the
problem is still there. Now Passthrough on altitude 370400 performs
FltPerformAsynchronousIo(IRP_MJ_DIRECTORY_CONTROL, IRP_MN_QUERY_DIRECTORY).
Passthrough2 on altitude 270400 completes Pt2PreDirectoryControl request
with STATUS_ACCESS_DENIED. Now I also get MULTIPLE_IRP_COMPLETE_REQUESTS
(44) BSOD without enabled verifier. And within enabled verifier I get
another DRIVER_PAGE_FAULT_IN_FREED_SPECIAL_POOL (d5) crash code from
fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted.

Few words about new minifilters. Passthrough2 is very simple. It has just
one significant callback which denies listing of directory content for
specified dir. I am sure it is correct.
Passthrough is also simple. It calls FltAllocateCallbackData,
FltPerformAsynchronousIo(IRP_MJ_DIRECTORY_CONTROL, IRP_MN_QUERY_DIRECTORY)
and then does FltFreeCallbackData in async io callback.

The only thing I suspect can cause a problem - it is this call of
FltFreeCallbackData in async io callback. When I tried to disable the call
of FltFreeCallbackData in completion, I didn't receive a BSOD. From other
side, documentation on FltAllocateCallbackData says "When the callback data
structure allocated by FltAllocateCallbackData is no longer needed, the
caller is responsible for freeing it by calling FltFreeCallbackData."

The only minifilter where I saw a FltAllocateCallbackData
/FltPerformAsynchronousIo/FltFreeCallbackData is "NameChanger File System
Minifilter Driver"
(http://code.msdn.microsoft.com/windowshardware/NameChanger-File-System-728e
1b2a#content). FltFreeCallbackData is invoked from the async io completion
callback there. And if I put another minifilter below, which completes
request from NameChanger's FltPerformAsynchronousIo
(IRP_MJ_DIRECTORY_CONTROL, IRP_MN_NOTIFY_CHANGE_DIRECTORY), I get the same
BSOD.

My questions now are:

  1. Is it legal to call FltFreeCallbackData from FltPerformAsynchronousIo's
    async io completion callback?
  2. Should the minifilter which attempts to complete pre-operation detect
    that request if from another minifilter (for example by
    FLTFL_CALLBACK_DATA_GENERATED_IO flag) and do some additional actions before
    returning FLT_PREOP_COMPLETE?

Below is the code of most simple minifilters that causes a
MULTIPLE_IRP_COMPLETE_REQUESTS/DRIVER_PAGE_FAULT_IN_FREED_SPECIAL_POOL BSOD
and output of analyze command.

Best regards,
Alexey Barabash

/////////////////////////////////////////////////////////////
I. Minifilter that does FltPerformAsynchronousIo (Passthrough, altitude
370400):

NTSTATUS
DriverEntry (
IN PDRIVER_OBJECT DriverObject,
IN PUNICODE_STRING RegistryPath
)
{
...
g_FileInformationLength = 65536;
g_FileInformationBuffer = ExAllocatePoolWithTag(NonPagedPool,
g_FileInformationLength, '4PtT');
if (NULL == g_FileInformationBuffer)
{
return STATUS_INSUFFICIENT_RESOURCES;
}
...
}

VOID PtCompleteAsyncIoCallback(
PFLT_CALLBACK_DATA CallbackData,
PFLT_CONTEXT Context
)
{
PFLT_CALLBACK_DATA RetNewCallbackData = (PFLT_CALLBACK_DATA)Context;
DbgPrint("PtCompleteAsyncIoCallback:\n");

FltFreeCallbackData(RetNewCallbackData);
}

FLT_POSTOP_CALLBACK_STATUS
PtPostCreate(
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
IN PVOID CompletionContext,
IN FLT_POST_OPERATION_FLAGS Flags
)
{
BOOLEAN IsDirectory = FALSE;
NTSTATUS Status = STATUS_UNSUCCESSFUL;

UNREFERENCED_PARAMETER( FltObjects );
UNREFERENCED_PARAMETER( CompletionContext );

ASSERT(IRP_MJ_CREATE == Data->Iopb->MajorFunction);

Status = FltIsDirectory(FltObjects->FileObject, FltObjects->Instance,
&IsDirectory);
if (FALSE == NT_SUCCESS(Status))
{
return FLT_POSTOP_FINISHED_PROCESSING;
}

if (IsOurFile(Data) && IsDirectory)
{
PFLT_CALLBACK_DATA NewRequest = NULL;
NTSTATUS Status = FltAllocateCallbackData(FltObjects->Instance,
FltObjects->FileObject, &NewRequest);
DbgPrint("PtPostCreate: FltAllocateCallbackData 0x%08X\n",
Status );
if (NT_SUCCESS(Status))
{
NewRequest->Iopb->MajorFunction =
IRP_MJ_DIRECTORY_CONTROL;
NewRequest->Iopb->MinorFunction = IRP_MN_QUERY_DIRECTORY;
NewRequest->Iopb->OperationFlags = SL_RESTART_SCAN;

NewRequest->Iopb->Parameters.DirectoryControl.QueryDirectory.Length =
g_FileInformationLength;

NewRequest->Iopb->Parameters.DirectoryControl.QueryDirectory.FileName =
NULL;

NewRequest->Iopb->Parameters.DirectoryControl.QueryDirectory.FileInformation
Class = FileIdFullDirectoryInformation;

NewRequest->Iopb->Parameters.DirectoryControl.QueryDirectory.FileIndex = 0;

NewRequest->Iopb->Parameters.DirectoryControl.QueryDirectory.DirectoryBuffer
= g_FileInformationBuffer;

NewRequest->Iopb->Parameters.DirectoryControl.QueryDirectory.MdlAddress =
NULL;

Status = FltPerformAsynchronousIo(
NewRequest,
PtCompleteAsyncIoCallback,
NewRequest
);
DbgPrint("PtPostCreate: FltPerformAsynchronousIo
0x%08X\n", Status );
}
}

return FLT_POSTOP_FINISHED_PROCESSING;
}

/////////////////////////////////////////////////////////////
II. Minifilter which completes IRP_MJ_DIRECTORY_CONTROL (Passthrough2,
altitude 270400):

FLT_PREOP_CALLBACK_STATUS
Pt2PreDirectoryControl (
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
OUT PVOID *CompletionContext
)
{
ASSERT(IRP_MJ_DIRECTORY_CONTROL == Data->Iopb->MajorFunction);

if (IRP_MN_QUERY_DIRECTORY == Data->Iopb->MinorFunction &&
IsOurFile(Data))
{
Data->IoStatus.Status = STATUS_ACCESS_DENIED;
Data->IoStatus.Information = 0;
DbgPrint("Pt2PreDirectoryControl complete with
STATUS_ACCESS_DENIED\n");
return FLT_PREOP_COMPLETE;
}

return FLT_PREOP_SUCCESS_NO_CALLBACK;
}

//////////////////////////////////////////////////////////
Analyze output:

DRIVER_PAGE_FAULT_IN_FREED_SPECIAL_POOL (d5)
Memory was referenced after it was freed.
This cannot be protected by try-except.
When possible, the guilty driver's name (Unicode string) is printed on
the bugcheck screen and saved in KiBugCheckDriver.
Arguments:
Arg1: 81c76fdf, memory referenced
Arg2: 00000001, value 0 = read operation, 1 = write operation
Arg3: badedd94, if non-zero, the address which referenced memory.
Arg4: 00000000, (reserved)

Debugging Details:

WRITE_ADDRESS: 81c76fdf Special pool
FAULTING_IP:
fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+104
badedd94 806003fe and byte ptr [eax+3],0FEh

MM_INTERNAL_CODE: 0
IMAGE_NAME: PassThrough.sys
DEBUG_FLR_IMAGE_TIMESTAMP: 50d85c4b
FAULTING_MODULE: badea000 fltMgr
DEFAULT_BUCKET_ID: DRIVER_FAULT
BUGCHECK_STR: 0xD5

TRAP_FRAME: f074e808 -- (.trap 0xfffffffff074e808)
ErrCode = 00000002
eax=81c76fdc ebx=00000103 ecx=815c8b00 edx=00000002 esi=81c76e70
edi=c0000022
eip=badedd94 esp=f074e87c ebp=f074e898 iopl=0 nv up ei pl zr na pe
nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000
efl=00010246
fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x104:
badedd94 806003fe and byte ptr [eax+3],0FEh
ds:0023:81c76fdf=??
Resetting default scope

LAST_CONTROL_TRANSFER: from 804f7b9d to 80527bdc

STACK_TEXT:
f074e344 804f7b9d 00000003 81c76fdf 00000000
nt!RtlpBreakWithStatusInstruction
f074e390 804f878a 00000003 00000000 c040e3b0 nt!KiBugCheckDebugBreak+0x19
f074e770 804f8cb5 00000050 81c76fdf 00000001 nt!KeBugCheck2+0x574
f074e790 8051cc4f 00000050 81c76fdf 00000001 nt!KeBugCheckEx+0x1b
f074e7f0 8054051c 00000001 81c76fdf 00000000 nt!MmAccessFault+0x8e7
f074e7f0 badedd94 00000001 81c76fdf 00000000 nt!KiTrap0E+0xcc
f074e898 badeeac9 f074e8b8 c0000022 00000000
fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x104
f074e8d0 bae046ed 816f39cc f9d6b950 816f39cc
fltMgr!FltPerformAsynchronousIo+0xcf
f074e8e8 f9d6bbc0 816f39cc f9d6b950 816f39cc
fltMgr!FltvPerformAsynchronousIo+0x3b
f074e90c bae041eb 81580e84 f074e954 00000000 PassThrough!PtPostCreate+0x150
[d:\work\passthrough\passthrough.c @ 1019]
f074e930 badeaef3 81580e84 0174e954 00000000 fltMgr!FltvPostOperation+0x4d
f074e998 baded338 00580e28 00000000 81580e28
fltMgr!FltpPerformPostCallbacks+0x1c5
f074e9ac baded867 81580e28 8257ee70 f074e9ec
fltMgr!FltpProcessIoCompletion+0x10
f074e9bc badedef9 819b7a48 8257ee70 81580e28
fltMgr!FltpPassThroughCompletion+0x89
f074e9ec badfa754 f074ea0c 00000000 00000000
fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x269
f074ea28 804ee119 819b7a48 8257ee70 806d22e8 fltMgr!FltpCreate+0x26a
f074ea38 8064d628 8257ee80 8257ee70 81584c00 nt!IopfCallDriver+0x31
...

STACK_COMMAND: kb

FOLLOWUP_IP:
PassThrough!PtPostCreate+150 [d:\work\passthrough\passthrough.c @ 1019]
f9d6bbc0 8945f0 mov dword ptr [ebp-10h],eax

FAULTING_SOURCE_LINE_NUMBER: 1019

FAULTING_SOURCE_CODE:
1015: Status = FltPerformAsynchronousIo(
1016: NewRequest,
1017: PtCompleteAsyncIoCallback,
1018: NewRequest

1019: );
1020: DbgPrint("PtPostCreate: FltPerformAsynchronousIo
0x%08X\n", Status );
1021: }
1022: }
1023:
1024: return FLT_POSTOP_FINISHED_PROCESSING;

SYMBOL_STACK_INDEX: 9
SYMBOL_NAME: PassThrough!PtPostCreate+150
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: PassThrough
FAILURE_BUCKET_ID: 0xD5_VRF_PassThrough!PtPostCreate+150
BUCKET_ID: 0xD5_VRF_PassThrough!PtPostCreate+150

4

Found answer on my 1st question. FltPerformAsynchronousIo,
http://msdn.microsoft.com/en-us/library/windows/hardware/ff543420(v=vs.85).a
spx : “Because the callback routine that CallbackRoutine points to is always
called by the Filter Manager, even when FltPerformAsynchronousIo fails, the
minifilter driver can perform the freeing or reusing operations directly in
the callback routine.”. Yes, it is legal.

Another thing: if I will set STATUS_ACCESS_DENIED in post operation
callback, I will not get a BSOD. This seems too weird.

FLT_PREOP_CALLBACK_STATUS
Pt2PreDirectoryControl (
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
OUT PVOID *CompletionContext
)
{
ASSERT(IRP_MJ_DIRECTORY_CONTROL == Data->Iopb->MajorFunction);

if (IRP_MN_QUERY_DIRECTORY == Data->Iopb->MinorFunction &&
IsOurFile(Data))
{
*(PULONG)CompletionContext = 1;
DbgPrint(“Pt2PreDirectoryControl
FLT_PREOP_SUCCESS_WITH_CALLBACK Data=0x%p\n”, Data);
return FLT_PREOP_SUCCESS_WITH_CALLBACK;
}

return FLT_PREOP_SUCCESS_NO_CALLBACK;
}

FLT_POSTOP_CALLBACK_STATUS
Pt2PostDirectoryControl(
IN OUT PFLT_CALLBACK_DATA Data,
IN PCFLT_RELATED_OBJECTS FltObjects,
IN PVOID CompletionContext,
IN FLT_POST_OPERATION_FLAGS Flags
)
{
if ((PVOID)1 == CompletionContext)
{
Data->IoStatus.Status = STATUS_ACCESS_DENIED;
Data->IoStatus.Information = 0;
DbgPrint(“Pt2PostDirectoryControl complete with
STATUS_ACCESS_DENIED Data=0x%p\n”, Data);
}

return FLT_POSTOP_FINISHED_PROCESSING;
}

Best regards,
Alexey Barabash

5

So have you used the verifier pool tracking function to find out where the IRP was completed (and thus deleted) in the first place?

The special pool fault confirms this really is a duplicate completion (since completion deletes the IRP). Using the pool tracking function on the IRP address, you should be able to see the call stack where it was freed the time before.

I suspect the problem is that you are telling filter manager you are done with this operation, when you aren’t done:

Status = FltPerformAsynchronousIo(
NewRequest,
PtCompleteAsyncIoCallback,
NewRequest
);
DbgPrint(“PtPostCreate: FltPerformAsynchronousIo 0x%08X\n”, Status );
}
}

return FLT_POSTOP_FINISHED_PROCESSING; }

But you aren’t done - you’re still processing the operation. Have you considered returning
FLT_POSTOP_MORE_PROCESSING_REQUIRED and then in your asynchronous I/O routine invoking FltCompletePendedPostOperation?

Tony
OSR

6

Hello.

Thanks, Tony. Your advises helped very much.

Returning of FLT_POSTOP_MORE_PROCESSING_REQUIRED with next call
FltCompletePendedPostOperation solved the problem.

In the example I put earlier I assumed that I can mark original request as
completed, because I thought new request is independent from the first.

A more careful debugging showed that different Data structures has the same
Irp (!fltkd.cbd <pflt_callback_data>).

In PtPostCreate (before call FltPerformAsynchronousIo)

PtPostCreate: Data=0x9D570E40
|Irp : 9d354e48

PtPostCreate: FltAllocateCallbackData 0x00000000 NewRequest=0x9D5A4E40
|Irp : 00000000

In Pt2PreDirectoryControl

Pt2PreDirectoryControl complete with STATUS_ACCESS_DENIED Data=0x9D5A4E40
|Irp : 9d54ee48

In PtCompleteAsyncIoCallback

PtCompleteAsyncIoCallback: CallbackData=0x9D5A4E40 |Irp : 9d54ee48

BSOD

kd> !analyze -v

…

DRIVER_PAGE_FAULT_IN_FREED_SPECIAL_POOL (d5)

Arg1: 9d54efdb, memory referenced

Arg2: 00000001, value 0 = read operation, 1 = write operation

Arg3: 83248aad, if non-zero, the address which referenced memory.

…

94d2c828 83248aad 00000001 9d54efdb 00000000 nt!KiTrap0E+0xdc

94d2c8d0 832498a9 94d2c8f0 c0000022 00000000
fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x157

94d2c908 83268af7 9d5a4e40 9677c960 9d5a4e40
fltmgr!FltPerformAsynchronousIo+0xcd

94d2c920 9677cc53 9d5a4e40 9677c960 9d5a4e40
fltmgr!FltvPerformAsynchronousIo+0x51

94d2c944 83268473 9d570e40 94d2c998 00000000 PassThrough!PtPostCreate+0x163
[d:\work\passthrough\passthrough.c @ 1020]

94d2c974 832450f3 9d570e40 00d2c998 00000000 fltmgr!FltvPostOperation+0x71

94d2c9d8 83248090 00570de0 00000000 9d570de0
fltmgr!FltpPerformPostCallbacks+0x1f1

94d2c9ec 832485c6 9d570de0 9d354e48 94d2ca2c
fltmgr!FltpProcessIoCompletion+0x10

94d2c9fc 83248c37 86ae5108 9d354e48 9d570de0
fltmgr!FltpPassThroughCompletion+0x94

94d2ca2c 8325b643 94d2ca4c 00000000 00000000
fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x2e1

94d2ca78 81b226be 86ae5108 85dd2ba8 8ad7acfc fltmgr!FltpCreate+0x2a1

94d2ca9c 8188492d 9d354fd8 8a3f1e6c 86ae5108 nt!IovCallDriver+0x23f

94d2cab0 81a7f0d5 931be4fc 862f0acc 85ff3bf0 nt!IofCallDriver+0x1b

…

A verifier pool tracking for a faulted memory, 2 last: .

kd> !verifier 80 9d54efdb 2

Log of recent kernel pool Allocate and Free operations:

There are up to 0x10000 entries in the log.

Parsing 0x00010000 log entries, searching for address 0x9d54efdb.

======================================================================

Pool block 9d54ee48, Size 000001b8, Thread 8ad7aad0

8192d0b7 nt!ExFreePoolWithTag+0xb2

81b293c5 nt!VfIrpFree+0x15

81b295cb nt!VerifierIoFreeIrp+0x11d

81b221c1 nt!IovFreeIrpPrivate+0x4c

832443ea fltmgr!FltpFreeIrpCtrl+0x48

832446dc fltmgr!FltFreeCallbackData+0x1a

832689ef fltmgr!FltvFreeCallbackData+0x33

9677c98a PassThrough!PtCompleteAsyncIoCallback+0x2a

832480f3 fltmgr!FltpProcessIoCompletion+0x73

832485c6 fltmgr!FltpPassThroughCompletion+0x94

83248a24 fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0xce

832498a9 fltmgr!FltPerformAsynchronousIo+0xcd

83268af7 fltmgr!FltvPerformAsynchronousIo+0x51

======================================================================

Pool block 9d54ede0, Size 00000220, Thread 88f616a8

8192d0b7 nt!ExFreePoolWithTag+0xb2

832444ce fltmgr!FltpFreeIrpCtrl+0x12c

8324851b fltmgr!FltpSynchronizeIoCleanup+0x3b

83248c84 fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x32e

8325b643 fltmgr!FltpCreate+0x2a1

81b226be nt!IovCallDriver+0x23f

8188492d nt!IofCallDriver+0x1b

81a7f0d5 nt!IopParseDevice+0xf61

81a6d521 nt!ObpLookupObjectName+0x5a8

81a7aaa2 nt!ObOpenObjectByName+0x13c

81a801dc nt!IopCreateFile+0x63b

81a84ffa nt!IoCreateFileEx+0x9d

8325d7dc fltmgr!FltCreateFileEx2+0xae

Parsed entry 000003cd/00010000…

Parsed 000003cd entries out of 00010000.

…

So, first time the Irp was freed in PtCompleteAsyncIoCallback ->
FltFreeCallbackData - according to verifier pool tracking.

The next attempt to access that was done inside PtPostCreate ->
FltPerformAsynchronousIo (according to call stack).

My next questions are:

Why FltAllocateCallbackData/FltPerformAsynchronousIo uses the same Irp as
PFLT_CALLBACK_DATA of the original operation does? I suppose this is done to
save Irp creation.

Is there still an opportunity to force FltPerformAsynchronousIo to create a
new IRP?

Best regards,

Alexey Barabash</pflt_callback_data>