Strange hang while unloading a minifilter (by FLTMC command)

NTFSD
1

Hi guys,

Today I have seen this hang for the first time for my minifilter driver
running on Windows Vista x32 SP1. The following is a stack trace for a
system thread which performs final unload operations on behalf of Filter
Manager:

nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
nt!KiSwapThread+0x44f
nt!KeWaitForSingleObject+0x492
nt!ExfWaitForRundownProtectionRelease+0xe8
fltmgr!FltpObjectRundownWait+0x11 (FPO: [Non-Fpo])
fltmgr!FltUnregisterFilter+0xf6 (FPO: [Non-Fpo])
MyDriver!SnpUninitializeDriver+0x3c (FPO: [Non-Fpo])
MyDriver!SnpUnloadCallback+0xb7 (FPO: [Non-Fpo]) (CONV: stdcall)
fltmgr!FltpDoUnloadFilter+0xf3 (FPO: [Non-Fpo])
fltmgr!FltpUnloadFilterWorker+0x11 (FPO: [Non-Fpo])
fltmgr!FltpSyncOpWorker+0x2c (FPO: [Non-Fpo])
nt!ExpWorkerThread+0xfd
nt!PspSystemThreadStartup+0x9d
nt!KiThreadStartup+0x16

Then I checked FLT_FILTER object with !fltkd.filter command:

FLT_FILTER: 8635d008 “MyDriver” “365800”
FLT_OBJECT: 8635d008 [02000001] Filter DRAINING
RundownRef : 0x8312fad1
Could not read field “Count” of nt!_EX_RUNDOWN_WAIT_BLOCK from address:
8312fad0
PointerCount : 0x00000002
PrimaryLink : [86c7839c-849b35cc]
Frame : 849b3570 “Frame 0”
Flags : [00000002] FilteringInitiated
DriverObject : 86c78238
FilterLink : [86c7839c-849b35cc]
PreVolumeMount : 00000000 (null)
PostVolumeMount : 00000000 (null)
FilterUnload : 8b52d0b0
MyDriver!SnpUninitializeDriver+0x1d0
InstanceSetup : 8b52bce0 MyDriver!SnpInstanceSetupCallback
InstanceQueryTeardown : 8b52c390
MyDriver!SnpInstanceQueryTeardownCallback
InstanceTeardownStart : 8b52c460
MyDriver!SnpInstanceTeardownStartCallback
InstanceTeardownComplete : 8b52c530
MyDriver!SnpInstanceTeardownCompleteCallback
ActiveOpens : (8635d0dc) mCount=43
Communication Port List : (8635d108) mCount=0
Client Port List : (8635d134) mCount=0
VerifierExtension : 00000000
Operations : 8635d164
OldDriverUnload : 00000000 (null)
SupportedContexts : (8635d0a0)
VolumeContexts : (8635d0a0)
InstanceContexts : (8635d0a4)
ALLOCATE_CONTEXT_NODE: 86baaa08 “MyDriver” [03] AllocationRoutines
FileContexts : (8635d0a8)
StreamContexts : (8635d0ac)
StreamHandleContexts : (8635d0b0)
TransactionContext : (8635d0b4)
InstanceList : (8635d038)

First I was surprised by “Could not read field “Count” of
nt!_EX_RUNDOWN_WAIT_BLOCK…” string (simply _EX_RUNDOWN_WAIT_BLOCK is
not defined in PDB file, but I know what this structure is :-)).

Then I performed !fltkd.fltobj command (just in case) and what it displayed:

FLT_OBJECT: 8635d008 [02000001] Filter DRAINING
RundownRef : 0x8312fad1
Could not read field “Count” of nt!_EX_RUNDOWN_WAIT_BLOCK from address:
8312fad0
PointerCount : 0x00000002
PrimaryLink : [86c7839c-849b35cc]


At last I checked a memory location at 8312fad0 (where
_EX_RUNDOWN_WAIT_BLOCK should be) and figured out that Count field of
this structure is equal to ActiveOpens.mCount, i.e. to 43. What does
this value of ActiveOpens.mCount really mean? Is it a number of file
opens performed by FltCreateFile() or FltCreateFileEx() called inside my
driver or something else?

Of course additionally I will try to check my driver with Verifier
turned on, but I don’t know whether I will be able to reproduce this
hang (strange but formerly Verifier didn’t detect any lost handles or
references).

Any suggestions and explanations will be highly appreciated. Thanks a
lot beforehand.

WBR,
Konstantin Manurin
Systems Programmer

2

Hello Konstantin,

ActiveOpens.mCount is the number of creates from FltCreateFileEx2 from your minifilter that filter manager didn’t see a cleanup for.

Regards,
Alex.
This posting is provided “AS IS” with no warranties, and confers no rights.

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Konstantin Manurin
Sent: Wednesday, August 20, 2008 6:22 AM
To: Windows File Systems Devs Interest List
Subject: [ntfsd] Strange hang while unloading a minifilter (by FLTMC command)

Hi guys,

Today I have seen this hang for the first time for my minifilter driver
running on Windows Vista x32 SP1. The following is a stack trace for a
system thread which performs final unload operations on behalf of Filter
Manager:

nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
nt!KiSwapThread+0x44f
nt!KeWaitForSingleObject+0x492
nt!ExfWaitForRundownProtectionRelease+0xe8
fltmgr!FltpObjectRundownWait+0x11 (FPO: [Non-Fpo])
fltmgr!FltUnregisterFilter+0xf6 (FPO: [Non-Fpo])
MyDriver!SnpUninitializeDriver+0x3c (FPO: [Non-Fpo])
MyDriver!SnpUnloadCallback+0xb7 (FPO: [Non-Fpo]) (CONV: stdcall)
fltmgr!FltpDoUnloadFilter+0xf3 (FPO: [Non-Fpo])
fltmgr!FltpUnloadFilterWorker+0x11 (FPO: [Non-Fpo])
fltmgr!FltpSyncOpWorker+0x2c (FPO: [Non-Fpo])
nt!ExpWorkerThread+0xfd
nt!PspSystemThreadStartup+0x9d
nt!KiThreadStartup+0x16

Then I checked FLT_FILTER object with !fltkd.filter command:

FLT_FILTER: 8635d008 “MyDriver” “365800”
FLT_OBJECT: 8635d008 [02000001] Filter DRAINING
RundownRef : 0x8312fad1
Could not read field “Count” of nt!_EX_RUNDOWN_WAIT_BLOCK from address:
8312fad0
PointerCount : 0x00000002
PrimaryLink : [86c7839c-849b35cc]
Frame : 849b3570 “Frame 0”
Flags : [00000002] FilteringInitiated
DriverObject : 86c78238
FilterLink : [86c7839c-849b35cc]
PreVolumeMount : 00000000 (null)
PostVolumeMount : 00000000 (null)
FilterUnload : 8b52d0b0
MyDriver!SnpUninitializeDriver+0x1d0
InstanceSetup : 8b52bce0 MyDriver!SnpInstanceSetupCallback
InstanceQueryTeardown : 8b52c390
MyDriver!SnpInstanceQueryTeardownCallback
InstanceTeardownStart : 8b52c460
MyDriver!SnpInstanceTeardownStartCallback
InstanceTeardownComplete : 8b52c530
MyDriver!SnpInstanceTeardownCompleteCallback
ActiveOpens : (8635d0dc) mCount=43
Communication Port List : (8635d108) mCount=0
Client Port List : (8635d134) mCount=0
VerifierExtension : 00000000
Operations : 8635d164
OldDriverUnload : 00000000 (null)
SupportedContexts : (8635d0a0)
VolumeContexts : (8635d0a0)
InstanceContexts : (8635d0a4)
ALLOCATE_CONTEXT_NODE: 86baaa08 “MyDriver” [03] AllocationRoutines
FileContexts : (8635d0a8)
StreamContexts : (8635d0ac)
StreamHandleContexts : (8635d0b0)
TransactionContext : (8635d0b4)
InstanceList : (8635d038)

First I was surprised by “Could not read field “Count” of
nt!_EX_RUNDOWN_WAIT_BLOCK…” string (simply _EX_RUNDOWN_WAIT_BLOCK is
not defined in PDB file, but I know what this structure is :-)).

Then I performed !fltkd.fltobj command (just in case) and what it displayed:

FLT_OBJECT: 8635d008 [02000001] Filter DRAINING
RundownRef : 0x8312fad1
Could not read field “Count” of nt!_EX_RUNDOWN_WAIT_BLOCK from address:
8312fad0
PointerCount : 0x00000002
PrimaryLink : [86c7839c-849b35cc]


At last I checked a memory location at 8312fad0 (where
_EX_RUNDOWN_WAIT_BLOCK should be) and figured out that Count field of
this structure is equal to ActiveOpens.mCount, i.e. to 43. What does
this value of ActiveOpens.mCount really mean? Is it a number of file
opens performed by FltCreateFile() or FltCreateFileEx() called inside my
driver or something else?

Of course additionally I will try to check my driver with Verifier
turned on, but I don’t know whether I will be able to reproduce this
hang (strange but formerly Verifier didn’t detect any lost handles or
references).

Any suggestions and explanations will be highly appreciated. Thanks a
lot beforehand.

WBR,
Konstantin Manurin
Systems Programmer

—
NTFSD is sponsored by OSR

For our schedule debugging and file system seminars
(including our new fs mini-filter seminar) visit:
http://www.osr.com/seminars

You are currently subscribed to ntfsd as: xxxxx@microsoft.com
To unsubscribe send a blank email to xxxxx@lists.osr.com

3

Good day Alexandru,

Thank you very much for this valuable information.

There’s one more question: is it critical in which order to call
FltClose() and ObDereferenceObject() for a handle and file object
returned by FltCreateFileEx()? The thing is that I first close a handle
and then dereference file object. But for my curiosity I checked
OBJECT_HEADER for a file object and saw that a HandleCount field is
equal to 0 and a PointerCount field is still equal to 1 right away after
FltClose()/ObDereferenceObject() calls. Is it normal for file object?
But how can such a file object be torn down later if its PointerCount is
not zero? Where did this extra reference come from?

Many thanks beforehand.

WBR,
Konstantin Manurin
Systems Programmer

Alexandru Carp wrote:

Hello Konstantin,

ActiveOpens.mCount is the number of creates from FltCreateFileEx2 from your minifilter that filter manager didn’t see a cleanup for.

Regards,
Alex.
This posting is provided “AS IS” with no warranties, and confers no rights.

-----Original Message-----
From: xxxxx@lists.osr.com [mailto:xxxxx@lists.osr.com] On Behalf Of Konstantin Manurin
Sent: Wednesday, August 20, 2008 6:22 AM
To: Windows File Systems Devs Interest List
Subject: [ntfsd] Strange hang while unloading a minifilter (by FLTMC command)

Hi guys,

Today I have seen this hang for the first time for my minifilter driver
running on Windows Vista x32 SP1. The following is a stack trace for a
system thread which performs final unload operations on behalf of Filter
Manager:

nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
nt!KiSwapThread+0x44f
nt!KeWaitForSingleObject+0x492
nt!ExfWaitForRundownProtectionRelease+0xe8
fltmgr!FltpObjectRundownWait+0x11 (FPO: [Non-Fpo])
fltmgr!FltUnregisterFilter+0xf6 (FPO: [Non-Fpo])
MyDriver!SnpUninitializeDriver+0x3c (FPO: [Non-Fpo])
MyDriver!SnpUnloadCallback+0xb7 (FPO: [Non-Fpo]) (CONV: stdcall)
fltmgr!FltpDoUnloadFilter+0xf3 (FPO: [Non-Fpo])
fltmgr!FltpUnloadFilterWorker+0x11 (FPO: [Non-Fpo])
fltmgr!FltpSyncOpWorker+0x2c (FPO: [Non-Fpo])
nt!ExpWorkerThread+0xfd
nt!PspSystemThreadStartup+0x9d
nt!KiThreadStartup+0x16

Then I checked FLT_FILTER object with !fltkd.filter command:

FLT_FILTER: 8635d008 “MyDriver” “365800”
FLT_OBJECT: 8635d008 [02000001] Filter DRAINING
RundownRef : 0x8312fad1
Could not read field “Count” of nt!_EX_RUNDOWN_WAIT_BLOCK from address:
8312fad0
PointerCount : 0x00000002
PrimaryLink : [86c7839c-849b35cc]
Frame : 849b3570 “Frame 0”
Flags : [00000002] FilteringInitiated
DriverObject : 86c78238
FilterLink : [86c7839c-849b35cc]
PreVolumeMount : 00000000 (null)
PostVolumeMount : 00000000 (null)
FilterUnload : 8b52d0b0
MyDriver!SnpUninitializeDriver+0x1d0
InstanceSetup : 8b52bce0 MyDriver!SnpInstanceSetupCallback
InstanceQueryTeardown : 8b52c390
MyDriver!SnpInstanceQueryTeardownCallback
InstanceTeardownStart : 8b52c460
MyDriver!SnpInstanceTeardownStartCallback
InstanceTeardownComplete : 8b52c530
MyDriver!SnpInstanceTeardownCompleteCallback
ActiveOpens : (8635d0dc) mCount=43
Communication Port List : (8635d108) mCount=0
Client Port List : (8635d134) mCount=0
VerifierExtension : 00000000
Operations : 8635d164
OldDriverUnload : 00000000 (null)
SupportedContexts : (8635d0a0)
VolumeContexts : (8635d0a0)
InstanceContexts : (8635d0a4)
ALLOCATE_CONTEXT_NODE: 86baaa08 “MyDriver” [03] AllocationRoutines
FileContexts : (8635d0a8)
StreamContexts : (8635d0ac)
StreamHandleContexts : (8635d0b0)
TransactionContext : (8635d0b4)
InstanceList : (8635d038)

First I was surprised by “Could not read field “Count” of
nt!_EX_RUNDOWN_WAIT_BLOCK…” string (simply _EX_RUNDOWN_WAIT_BLOCK is
not defined in PDB file, but I know what this structure is :-)).

Then I performed !fltkd.fltobj command (just in case) and what it displayed:

FLT_OBJECT: 8635d008 [02000001] Filter DRAINING
RundownRef : 0x8312fad1
Could not read field “Count” of nt!_EX_RUNDOWN_WAIT_BLOCK from address:
8312fad0
PointerCount : 0x00000002
PrimaryLink : [86c7839c-849b35cc]

>
>
> At last I checked a memory location at 8312fad0 (where
> _EX_RUNDOWN_WAIT_BLOCK should be) and figured out that Count field of
> this structure is equal to ActiveOpens.mCount, i.e. to 43. What does
> this value of ActiveOpens.mCount really mean? Is it a number of file
> opens performed by FltCreateFile() or FltCreateFileEx() called inside my
> driver or something else?
>
> Of course additionally I will try to check my driver with Verifier
> turned on, but I don’t know whether I will be able to reproduce this
> hang (strange but formerly Verifier didn’t detect any lost handles or
> references).
>
>
> Any suggestions and explanations will be highly appreciated. Thanks a
> lot beforehand.
>
>
> WBR,
> Konstantin Manurin
> Systems Programmer
>
> —
> NTFSD is sponsored by OSR
>
> For our schedule debugging and file system seminars
> (including our new fs mini-filter seminar) visit:
> http://www.osr.com/seminars
>
> You are currently subscribed to ntfsd as: xxxxx@microsoft.com
> To unsubscribe send a blank email to xxxxx@lists.osr.com
>
>
>

4

If you use the file handle to perform I/O, the file object could be used
by the cache manager or memory manager (or both) as a “backing object”
for their own data structures. That would create the additional
reference. In that case, if you look with the debugger at
FileObject->SectionObjectPointers, you will see that one or more of
those three fields is non-NULL.

Tony
OSR

5

Tony,

Thanks for this info, I’m aware of this MM peculiarity (in my previous
virtual FS filter driver I even had to call MmForceSectionClose() in
order to get rid of all my private file objects which could possibly be
referenced by unused memory sections and it really worked (please
correct me if I’m wrong about this matter)).

But today I resumed a virtual machine with my minifilter and tried to
unload it. And oops, it hanged again. I checked ActiveOpens.mCount and
it was equal to 1094!!! Though my minifilter didn’t issue any of FltXxx
file calls (I added extensive debug statistics to my minifilter which
take into account almost whole FltXxx stuff throughout my minifilter
code, and all this counters are equal to zero, hence now I can draw a
conclusion that my minifilter didn’t use any of FltXxx calls to work
with files, such as FltCreateFileEx(), FltReadFile() and etc.)!!!

I’m really stuck. I don’t understand why my minifilter was referenced
and what OS component is responsible for such an odd behavior. And by
now I have realized that this problem is 100% reproducible when I
suspend and then resume a virtual machine with my minifilter turned on
and active. And the more the virtual machine is inactive (suspended),
the more “strange” references are collected (at least, I observed
exactly such a behavior, but perhaps it’s just a simple coincidence).

Any thoughts and ideas will be highly appreciated.

WBR,
Konstantin Manurin
Systems programmer

Tony Mason wrote:

If you use the file handle to perform I/O, the file object could be used
by the cache manager or memory manager (or both) as a “backing object”
for their own data structures. That would create the additional
reference. In that case, if you look with the debugger at
FileObject->SectionObjectPointers, you will see that one or more of
those three fields is non-NULL.

Tony
OSR