FltClose hang

Horatiu_Guja · August 21, 2009, 9:25am

Hi

I have a sort or mirroring minifilter. When a file is opened I’m openning a mirror file using FltCreateFileEx (with FILE_NO_BUFFERING) somewhere else on disk.

Then for every intercepted paging io write I’m writing the data also to the mirror file and then return FLT_PREOP_SUCCESS_NO_CALLBACK.

When I intercept a cleanup on the opened file in the PreOp I’m calling FltClose on the mirror file … and here on Win7 X64 it hangs.

This is happening ONLY if the mirror files resides on an NTFS partition. On FAT partitions everthing is ok.

This is happening currently when I’m mirroring notepad files.

Analysing in the debugger I can see my mirror driver only on one stack. I searched also for ntfs references in the other threads but could not found any other reference to it.

!stacks

8c8.0008cc fffffa800092d960 ffffa75b Blocked nt!KiSwapContext+0x7a
nt!KiCommitThreadWait+0x1d2
nt!KeWaitForSingleObject+0x19f
nt!ExpWaitForResource+0xae
nt!ExAcquireResourceExclusiveLite+0x14f
Ntfs!NtfsCommonCleanup+0x2653
Ntfs!NtfsCommonCleanupCallout+0x19
nt!KeExpandKernelStackAndCalloutEx+0xda
Ntfs!NtfsCommonCleanupOnNewStack+0x42
Ntfs!NtfsFsdCleanup+0x144
fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x24f
fltmgr!FltpDispatch+0xcf
nt!IopCloseFile+0x11f
nt!ObpDecrementHandleCount+0xb4
nt!ObpCloseHandleTableEntry+0xb1
nt!ObpCloseHandle+0x94
nt!KiSystemServiceCopyEnd+0x13
nt!KiServiceLinkage
mirror!mirror_PreCleanupOperation+0x32c
fltmgr!FltpPerformPreCallbacks+0x2f7
fltmgr!FltpPassThrough+0x2d9
fltmgr!FltpDispatch+0xb7
nt!IopCloseFile+0x11f
nt!ObpDecrementHandleCount+0xb4
nt!ObpCloseHandleTableEntry+0xb1
nt!ObpCloseHandle+0x94
nt!KiSystemServiceCopyEnd+0x13
+0x7718ffaa

then running !locks I get

kd> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks…

Resource @ 0xfffffa80017e2880 Shared 1 owning threads
Threads: fffffa800092d960-01<*>
KD: Scanning for held locks…

Resource @ 0xfffffa80008cb020 Shared 2 owning threads
Threads: fffffa800080a3c0-01<*> fffffa80008466d0-01<*>
KD: Scanning for held locks…

Resource @ 0xfffffa8001c910f8 Shared 1 owning threads
Contention Count = 1
NumberOfExclusiveWaiters = 1
Threads: fffffa80006e2b60-01<*>
Threads Waiting On Exclusive Access:
fffffa800092d960

KD: Scanning for held locks…
5073 total locks, 3 locks currently held
kd> !locks -v 0xfffffa8001c910f8

Resource @ 0xfffffa8001c910f8 Shared 1 owning threads
Contention Count = 1
NumberOfExclusiveWaiters = 1
Threads: fffffa80006e2b60-01<*>

THREAD fffffa80006e2b60 Cid 0004.0020 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (WrQueue) UserMode Non-Alertable
fffff800028345a0 QueueObject
Not impersonating
DeviceMap fffff8a000006090
Owning Process fffffa80006d1ae0 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 22656 Ticks: 262 (0:00:00:04.093)
Context Switch Count 1821
UserTime 00:00:00.000
KernelTime 00:00:00.015
Win32 Start Address nt!ExpWorkerThread (0xfffff8000269e050)
Stack Init fffff88002f2adb0 Current fffff88002f2a9f0
Base fffff88002f2b000 Limit fffff88002f25000 Call 0
Priority 13 BasePriority 13 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffff88002f2aa30 fffff80002698052 nt!KiSwapContext+0x7a
fffff88002f2ab70 fffff8000269bac1 nt!KiCommitThreadWait+0x1d2
fffff88002f2ac00 fffff8000269e139 nt!KeRemoveQueueEx+0x301
fffff88002f2acb0 fffff80002934166 nt!ExpWorkerThread+0xe9
fffff88002f2ad40 fffff8000266f486 nt!PspSystemThreadStartup+0x5a
fffff88002f2ad80 0000000000000000 nt!KxStartSystemThread+0x16

Threads Waiting On Exclusive Access:
fffffa800092d960

1 total locks, 1 locks currently held

I presume the block is because the notepad thread is waiting on the PagingIoResource of the mirror file, but as can be seen the owning thread stack doesn’t display any wait on another resource which could presume a deadlock.

I’m handling every mirror redirection on the Pre operations

displaying the notepad thread and it’s IRP list result in the following:

kd> !thread fffffa800092d960
THREAD fffffa800092d960 Cid 08c8.08cc Teb: 000007fffffdc000 Win32Thread: fffff900c203d400 WAIT: (WrResource) KernelMode Non-Alertable
fffffa80023cd090 SynchronizationEvent
IRP List:
fffffa8000939c10: (0006,03e8) Flags: 00000404 Mdl: 00000000
fffffa8001c23c60: (0006,01f0) Flags: 00000404 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000006090
Owning Process fffffa800089d630 Image: notepad.exe
Attached Process fffffa80006d1ae0 Image: System
Wait Start TickCount 22693 Ticks: 225 (0:00:00:03.515)
Context Switch Count 1976 LargeStack
UserTime 00:00:01.031
KernelTime 00:00:00.640
Win32 Start Address 0x00000000ffe33570
Stack Init fffff880041badb0 Current fffff880041b9790
Base fffff880041bb000 Limit fffff880041ae000 Call 0
Priority 10 BasePriority 8 UnusualBoost 0 ForegroundBoost 2 IoPriority 2 PagePriority 5
Child-SP RetAddr : Args to Child : Call Site
fffff880041b97d0 fffff80002698052 : fffffa800092d960 fffffa800092d960 0000000000000000 fffff80000000000 : nt!KiSwapContext+0x7a
fffff880041b9910 fffff8000269a1af : 0000000000000000 0000000000000000 00000000000000a5 0000000000000000 : nt!KiCommitThreadWait+0x1d2
fffff880041b99a0 fffff80002659b1e : 0000000000000000 fffffa800000001b 0000000000000000 fffff80002809e00 : nt!KeWaitForSingleObject+0x19f
fffff880041b9a40 fffff800026991bc : fffffffffd9da600 fffffa80023cd090 fffffa8001c910f8 fffff80002c2b3c0 : nt!ExpWaitForResource+0xae
fffff880041b9ab0 fffff880012cbc86 : 0000000000000000 fffff8a000cca1e0 fffff880041ba360 0000000000000000 : nt!ExAcquireResourceExclusiveLite+0x14f
fffff880041b9b20 fffff88001238aa9 : 0000000000000000 fffff9600011714d fffff880041ba070 fffff880041a9000 : Ntfs!NtfsCommonCleanup+0x2653
fffff880041b9f30 fffff800026a064a : fffff880041ba070 0000000000000000 0000000000000000 0000000000000000 : Ntfs!NtfsCommonCleanupCallout+0x19
fffff880041b9f60 fffff88001238662 : fffff88001238a90 fffff880041ba070 fffff880041ba300 0000000000000000 : nt!KeExpandKernelStackAndCalloutEx+0xda
fffff880041ba040 fffff880012da244 : fffff880041ba110 fffff880041ba110 fffff880041ba110 00001fa002000702 : Ntfs!NtfsCommonCleanupOnNewStack+0x42
fffff880041ba0b0 fffff8800105323f : fffff880041ba110 fffffa8000939c10 fffffa8000939fb0 fffffa8000932430 : Ntfs!NtfsFsdCleanup+0x144
fffff880041ba320 fffff880010516df : fffffa80017ea360 0000000000000000 fffffa800105f200 fffffa8000939c10 : fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x24f
fffff880041ba3b0 fffff800029a468f : fffffa8000939c10 fffffa80006d1ae0 0000000000000000 fffffa8001ff5dc0 : fltmgr!FltpDispatch+0xcf
fffff880041ba410 fffff8000298a304 : 0000000000000001 fffffa800089d630 00000000000002c0 0000000000000000 : nt!IopCloseFile+0x11f
fffff880041ba4a0 fffff800029a4181 : fffffa800089d630 fffffa8000000001 fffff8a000001980 0000000000000000 : nt!ObpDecrementHandleCount+0xb4
fffff880041ba520 fffff800029a4094 : 000000000000068c fffffa800089d630 fffff8a000001980 000000000000068c : nt!ObpCloseHandleTableEntry+0xb1
fffff880041ba5b0 fffff80002690153 : fffffa800092d960 fffff880041ba680 fffffa80008fb730 fffffa800092d960 : nt!ObpCloseHandle+0x94
fffff880041ba600 fffff8000268c6f0 : fffff8800398522c 0000000000000000 fffffa80008fb730 0000000000000000 : nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffff880041ba600) fffff880041ba798 fffff8800398522c : 0000000000000000 fffffa80008fb730 0000000000000000 fffff80002809e80 : nt!KiServiceLinkage fffff880041ba7a0 fffff88001052027 : fffffa80008fb7e0 fffff880041ba8c8 fffff880041ba8a0 0000000000000000 : mirror!mirror_PreCleanupOperation+0x32c fffff880041ba850 fffff88001052be9 : fffff880041ba900 0000000000000012 0000000000000000 0000000000000000 : fltmgr!FltpPerformPreCallbacks+0x2f7 fffff880041ba950 fffff880010516c7 : fffffa8001c23c60 fffffa8002218370 fffffa800105f200 fffffa8001fef460 : fltmgr!FltpPassThrough+0x2d9 fffff880041ba9d0 fffff800029a468f : fffffa8001c23c60 fffffa800089d630 0000000000000000 fffffa8001fef460 : fltmgr!FltpDispatch+0xb7 fffff880041baa30 fffff8000298a304 : 0000000000000000 fffffa800089d630 000000000005018e 0000000000000000 : nt!IopCloseFile+0x11f fffff880041baac0 fffff800029a4181 : fffffa800089d630 fffffa8000000001 fffff8a000a5d0d0 0000000000000000 : nt!ObpDecrementHandleCount+0xb4 fffff880041bab40 fffff800029a4094 : 00000000000004bc fffffa800089d630 fffff8a000a5d0d0 00000000000004bc : nt!ObpCloseHandleTableEntry+0xb1 fffff880041babd0 fffff80002690153 : fffffa800092d960 fffff880041baca0 0000000000000000 0000000000008000 : nt!ObpCloseHandle+0x94 fffff880041bac20 000000007718ffaa : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffff880041bac20)
00000000000ff568 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 0000000000000000 : 0x7718ffaa

kd> !irp fffffa8000939c10
Irp is active with 11 stacks 10 is current (= 0xfffffa8000939f68)
No Mdl: No System Buffer: Thread fffffa800092d960: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[12, 0] 0 e0 fffffa80017e2030 fffffa8001ff5dc0 fffff88001055fe0-fffffa8000932430 Success Error Cancel
\FileSystem\Ntfs fltmgr!FltpPassThroughCompletion
Args: 00000000 00000000 00000000 00000000
[12, 0] 0 1 fffffa80017ea360 fffffa8001ff5dc0 00000000-00000000 pending
\FileSystem\FltMgr
Args: 00000000 00000000 00000000 00000000
kd> !irp fffffa8001c23c60
Irp is active with 3 stacks 3 is current (= 0xfffffa8001c23dc0)
No Mdl: No System Buffer: Thread fffffa800092d960: Irp stack trace.
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[12, 0] 0 1 fffffa8002218370 fffffa8001fef460 00000000-00000000 pending
\FileSystem\FltMgr
Args: 00000000 00000000 00000000 00000000

Did anyone experienced such a situation. Any idea how I could find what’s the reason for the hang would be welcome.

Thanks,
horatiu