hang on IRP_MJ_CLEANUP

NTFSD
1

Hi

I have a minifilter which handles some data. When handling the IRP_MJ_CLEANUP I need to close a file that was opened by the minifilter. I do this by calling FltClose.

My Problem is that if the FILE_OBJECT has the FO_FILE_MODIFIED bit set then the FltClose never returns. I get the same result on both cases when I call on the Pre or on the Post handling routine. Below the stack of the thread in this case FltClose was handled in the Post routine.

Stack was obtained on a Win2003 X64 OS.

IRP List:
fffffabf53bb0c60: (0006,03a0) Flags: 40000404 Mdl: 00000000
fffffabf52e8ce10: (0006,01f0) Flags: 40000404 Mdl: 00000000
Not impersonating
DeviceMap fffffa8000004b90
Owning Process fffffadff3f84040 Image: System
Wait Start TickCount 10338 Ticks: 240 (0:00:00:03.750)
Context Switch Count 14556 LargeStack
UserTime 00:00:02.0468
KernelTime 00:00:03.0125
Start Address 0x0000000078d59630
Win32 Start Address 0x0000000000771280
Stack Init fffffadfeacbfe00 Current fffffadfeacbe420
Base fffffadfeacc0000 Limit fffffadfeacb4000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
Child-SP RetAddr Call Site
fffffadfeacbe460 fffff8000103b403 nt!KiSwapContext+0x85
fffffadfeacbe5e0 fffff8000103c750 nt!KiSwapThread+0xc3
fffffadfeacbe620 fffff8000100b4a3 nt!KeWaitForSingleObject+0x525
fffffadfeacbe6b0 fffff8000105acad nt!ExpWaitForResource+0x1cb
fffffadfeacbe720 fffffadff1ae0a35 nt!ExAcquireResourceExclusiveLite+0x12a
fffffadfeacbe750 fffffadff1ae1351 Ntfs!NtfsCommonCleanup+0x260
fffffadfeacbeb50 fffff800013c82ab Ntfs!NtfsFsdCleanup+0x124
fffffadfeacbed50 fffffadff1ba7962 nt!IovCallDriver+0x20b
fffffadfeacbedd0 fffff800013c82ab fltMgr!FltpDispatch+0x1c2
fffffadfeacbee30 fffffadff1ba7962 nt!IovCallDriver+0x20b
fffffadfeacbeeb0 fffff800013c82ab fltMgr!FltpDispatch+0x1c2
fffffadfeacbef10 fffff800012c344e nt!IovCallDriver+0x20b
fffffadfeacbef90 fffff800012b3956 nt!IopCloseFile+0x342
fffffadfeacbf030 fffff800012b381e nt!ObpDecrementHandleCount+0x157
fffffadfeacbf090 fffff800012b3714 nt!ObpCloseHandleTableEntry+0x245
fffffadfeacbf130 fffff80001041422 nt!ObpCloseHandle+0xb0
fffffadfeacbf1b0 fffff80001041880 nt!KiSystemServiceCopyEnd+0x3 (TrapFrame @ fffffadfeacbf1b0) fffffadfeacbf348 fffffadfec510bcc nt!KiServiceLinkage fffffadfeacbf350 fffffadff1bd3629 myflt!MYFLT_PostCleanupOperation+0x30 fffffadfeacbf390 fffffadff1ba1fa6 fltMgr!FltvPostOperation+0x79 fffffadfeacbf3c0 fffffadff1ba67f7 fltMgr!FltpPerformPostCallbacks+0x286 fffffadfeacbf480 fffff800013c8a4c fltMgr!FltpPassThroughCompletion+0xe7 fffffadfeacbf4d0 fffff8000103c595 nt!IovpLocalCompletionRoutine+0xfc fffffadfeacbf520 fffff800013c88f8 nt!IopfCompleteRequest+0x117 fffffadfeacbf570 fffffadfee5a1e42 nt!IovCompleteRequest+0x1d8 fffffadfeacbf650 fffffadfee58fec7 Fastfat!FatCompleteRequest_Real+0xc2 fffffadfeacbf680 fffffadfee58f2c5 Fastfat!FatCommonCleanup+0xb67 fffffadfeacbf760 fffff800013c82ab Fastfat!FatFsdCleanup+0x75 fffffadfeacbf7a0 fffffadff1ba7962 nt!IovCallDriver+0x20b fffffadfeacbf820 fffff800013c82ab fltMgr!FltpDispatch+0x1c2 fffffadfeacbf880 fffffadff1ba759a nt!IovCallDriver+0x20b fffffadfeacbf900 fffffadff1ba791f fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x41a fffffadfeacbf970 fffff800013c82ab fltMgr!FltpDispatch+0x17f fffffadfeacbf9d0 fffff800012c344e nt!IovCallDriver+0x20b fffffadfeacbfa50 fffff800012b3956 nt!IopCloseFile+0x342 fffffadfeacbfaf0 fffff800012b381e nt!ObpDecrementHandleCount+0x157 fffffadfeacbfb50 fffff800012b3714 nt!ObpCloseHandleTableEntry+0x245 fffffadfeacbfbf0 fffff80001041422 nt!ObpCloseHandle+0xb0 fffffadfeacbfc70 0000000078ef135a nt!KiSystemServiceCopyEnd+0x3 (TrapFrame @ fffffadfeacbfc70)
000000000012e508 0000000000000000 0x78ef135a

could anyone give me a hint what could be the reason for that ?

thanks
horatiu

2

Both Fastfast and NTFS on the stack … you must be doing something
seriously wrong … Why does your MYFLT_PostCleanupOperation
call NTFS ?

L.

3

Hi

The minifilter does a sort of file mirroring.

As I said from an IRP_MJ_CLEANUP I have to close a file. The explanation why FAT and NTFS are on the stack is simple: the cleanup comes for a file that resides on a FAT partition and the file the minifilter has to close reside on a NTFS partition.

Meantime I get the same error when handling a SetInformation. Scenarios is similar to cleanup. If minifilter intercepts the SetInformation of a file it mirrors the call to another file. This is also hanging. Below the stack, and some analyze of the hang:

THREAD fffffadfff036040 Cid 06f0.0620 Teb: 000000007efdb000 Win32Thread: fffffa800294a010 WAIT: (Unknown) KernelMode Non-Alertable
fffffadff3e20970 Semaphore Limit 0x7fffffff
fffffadfff0360f8 NotificationTimer
IRP List:
fffffabf53086e10: (0006,01f0) Flags: 40000830 Mdl: 00000000
Not impersonating
DeviceMap fffffa8001e205c0
Owning Process fffffadfff025040 Image: uedit32.exe
Wait Start TickCount 10240 Ticks: 142 (0:00:00:02.218)
Context Switch Count 22882 LargeStack
UserTime 00:00:04.0000
KernelTime 00:00:04.0734
Start Address kernel32!BaseProcessStart (0x0000000078d59630)
Win32 Start Address 0x0000000000771280
Stack Init fffffadfeaf95e00 Current fffffadfeaf94b30
Base fffffadfeaf96000 Limit fffffadfeaf8a000 Call 0
Priority 14 BasePriority 8 PriorityDecrement 6
Child-SP RetAddr Call Site
fffffadfeaf94b70 fffff8000103b403 nt!KiSwapContext+0x85
fffffadfeaf94cf0 fffff8000103c750 nt!KiSwapThread+0xc3
fffffadfeaf94d30 fffff8000100b4a3 nt!KeWaitForSingleObject+0x525
fffffadfeaf94dc0 fffff80001025d71 nt!ExpWaitForResource+0x1cb
fffffadfeaf94e30 fffffadff1ad80f4 nt!ExAcquireResourceSharedLite+0x357
fffffadfeaf94e90 fffffadff1ad6b4b Ntfs!NtfsCommonQueryInformation+0x1b9
fffffadfeaf94f30 fffffadff1ad6db4 Ntfs!NtfsFsdDispatchSwitch+0x185
fffffadfeaf94fc0 fffff800013c82ab Ntfs!NtfsFsdDispatchWait+0x14
fffffadfeaf95170 fffffadff1ba7962 nt!IovCallDriver+0x20b
fffffadfeaf951f0 fffff800013c82ab fltMgr!FltpDispatch+0x1c2
fffffadfeaf95250 fffffadff1ba759a nt!IovCallDriver+0x20b
fffffadfeaf952d0 fffffadff1ba88d0 fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x41a
fffffadfeaf95340 fffffadff1bc68f6 fltMgr!FltPerformSynchronousIo+0x1b0
fffffadfeaf953b0 fffffadff2371204 fltMgr!FltQueryInformationFile+0x56
fffffadfeaf95400 fffffadff1bd3629 myflt!AKSDF_PostSetInformation+0xf0
fffffadfeaf954c0 fffffadff1ba1fa6 fltMgr!FltvPostOperation+0x79
fffffadfeaf954f0 fffffadff1ba67f7 fltMgr!FltpPerformPostCallbacks+0x286
fffffadfeaf955b0 fffff800013c8a4c fltMgr!FltpPassThroughCompletion+0xe7
fffffadfeaf95600 fffff8000103c595 nt!IovpLocalCompletionRoutine+0xfc
fffffadfeaf95650 fffff800013c88f8 nt!IopfCompleteRequest+0x117
fffffadfeaf956a0 fffffadfee5a3466 nt!IovCompleteRequest+0x1d8
fffffadfeaf95780 fffffadfee5a281b Fastfat!FatCommonSetInformation+0x546
fffffadfeaf95810 fffff800013c82ab Fastfat!FatFsdSetInformation+0x6b
fffffadfeaf95850 fffffadff1ba7962 nt!IovCallDriver+0x20b
fffffadfeaf958d0 fffff800013c82ab fltMgr!FltpDispatch+0x1c2
fffffadfeaf95930 fffffadff1ba759a nt!IovCallDriver+0x20b
fffffadfeaf959b0 fffffadff1ba791f fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x41a
fffffadfeaf95a20 fffff800013c82ab fltMgr!FltpDispatch+0x17f
fffffadfeaf95a80 fffff800012a72a2 nt!IovCallDriver+0x20b
fffffadfeaf95b00 fffff80001041422 nt!NtSetInformationFile+0x854
fffffadfeaf95c00 0000000078ef14da nt!KiSystemServiceCopyEnd+0x3 (TrapFrame @ fffffadfeaf95c70) 000000000012e438 000000000012dc30 ntdll!ZwSetInformationFile+0xa 000000000012e440 0000000000000000 0x12dc30 000000000012e448 0000000000000000 0x0 000000000012e450 0000000000000000 0x0 000000000012e458 0010016400040003 0x0 000000000012e460 000000000012e490 0x10016400040003
000000000012e468 00000000fedcba98 0x12e490
000000000012e470 4297a360b006a697 0xfedcba98
000000000012e478 67cc94f0baacfcb2 0x4297a360`b006a697

kd> !locks
The call to LoadLibrary(ext) failed, Win32 error 127
“The specified procedure could not be found.”
Please check your debugger configuration and/or network access.
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks…

Resource @ 0xfffffadff322d800 Shared 2 owning threads
Contention Count = 2
Threads: fffffadff3f75bd0-01<*> fffffadff3f75760-01<*>
KD: Scanning for held locks…

Resource @ 0xfffffadff3a66018 Shared 2 owning threads
Threads: fffffadff3a68bd0-01<*> fffffadff3a68760-01<*>
KD: Scanning for held locks…

Resource @ 0xfffffadfff495960 Shared 1 owning threads
Contention Count = 4
NumberOfSharedWaiters = 2
NumberOfExclusiveWaiters = 2
Threads: fffffadff3f641d0-01<*> fffffadff3f77760-01 fffffadfff036040-01
Threads Waiting On Exclusive Access:
fffffadff3f75bd0 fffffadff3f75760

KD: Scanning for held locks…
2817 total locks, 3 locks currently held

Stack of the thread who owns the object on which the thread containing the minifilter waits.

kd> !thread fffffadff3f641d0
The call to LoadLibrary(ext) failed, Win32 error 127
“The specified procedure could not be found.”
Please check your debugger configuration and/or network access.
THREAD fffffadff3f641d0 Cid 0004.0078 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Unknown) KernelMode Non-Alertable
fffff8000119e480 NotificationEvent
Not impersonating
DeviceMap fffffa8000004b90
Owning Process fffffadff3f84040 Image: System
Wait Start TickCount 7668 Ticks: 2714 (0:00:00:42.406)
Context Switch Count 2609
UserTime 00:00:00.0000
KernelTime 00:00:00.0015
Start Address nt!ExAcquireSharedWaitForExclusive (0xfffff80001029e10)
Stack Init fffffadff26dae00 Current fffffadff26daa10
Base fffffadff26db000 Limit fffffadff26d5000 Call 0
Priority 17 BasePriority 8 PriorityDecrement 0
Child-SP RetAddr : Args to Child : Call Site
fffffadff26daa50 fffff8000103b403 : 0000000000000100 fffff78000000008 0000000000000001 0000000000000000 : nt!KiSwapContext+0x85
fffffadff26dabd0 fffff8000103c750 : fffffadff3f64ee0 0000000000000000 0000000000000002 fffffadff3f641d0 : nt!KiSwapThread+0xc3
fffffadff26dac10 fffff80001029ee9 : fffffadf00000000 fffffadf00000012 0000000000000000 fffffadff3f64e00 : nt!KeWaitForSingleObject+0x525
fffffadff26daca0 fffff800012b226e : 0000000000000000 fffffadff3f641d0 fffffadff3f641d0 fffffadff3f65470 : nt!MiMappedPageWriter+0xdb
fffffadff26dad70 fffff80001044416 : fffff80001174180 fffffadff3f641d0 fffffadff3f65470 0000000000000000 : nt!PspSystemThreadStartup+0x3e
fffffadff26dadd0 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KxStartSystemThread+0x16

for shure something is wrong. My question is why is this happening and why is it wrong. There is nothing stated in the IFS kit documentation. I would understand if this would happen in a read/wwrite operation if the read/write I would generate would trigger a page fault in a pageing io read operation but this is not the case.

horatiu

4

Just a small add to my previous post just to avoid possible wrong assumptions.
As you cann see in the stack myflt is calling FltQueryInformationFile on a file residing on NTFS from a PostOp of SetInformationFile.
The efect is the same if this is done from PreOp or using in PostOp FltDoCompletionProcessingWhenSafe.

horatiu

5

I see the Mapped Page Writer thread, it seems that this thread is waiting
for the event which signals that dirty pages must be flushed, but this
thread holds the data stream’s resource shared. I think that
FastIoAcquireFileForModWrite called by MPW acquired this resource, then the
MPW sent asynchronous request, but FastIoReleaseFileForModWrite has not been
called, this means that MPW’s paging write request has not been completed(
i.e. it hangs ) or FastIoReleaseFileForModWrite has not been called( check
your filter ).

–
Slava Imameyev, xxxxx@hotmail.com

wrote in message news:xxxxx@ntfsd…
> Just a small add to my previous post just to avoid possible wrong
> assumptions.
> As you cann see in the stack myflt is calling FltQueryInformationFile on a
> file residing on NTFS from a PostOp of SetInformationFile.
> The efect is the same if this is done from PreOp or using in PostOp
> FltDoCompletionProcessingWhenSafe.
>
> horatiu
>