Correct usage of FLT_PREOP_PENDING and FltCompletePendedPreOperation()

Hi list,

I’m working on a minifilter driver and I’m having trouble trying to
pend IO from the filter pre-operation callback. Specifically, I get a
hang when calling FltCompletePendedPreOperation() to notify the filter
manager that the IO has been completed. Any advice on what I may be
doing wrong would be gratefully appreciated !

In brief, my application consists of a minifilter component which
forwards some IO requests to a userspace application. The filter
manager should pend whilst userspace is doing its work[1], so I think
I should be returning FLT_PREOP_PENDING from my filter’s preOp
callback.

The data flow for my app is as follows[2]:

  1. A a non-paging, IRP-based request arrives in the filter preOp callback.
  2. The filter generates an internal structure containing various bits
    of data that it copies from the preOp “callbackData” structure[3]. It
    also stashes a pointer to the callback data structure that it will use
    later to pass to FltCompletePendedPreOperation().
  3. The filter sends a message to a userspace application notifying it
    of the new request and its size.
  4. The request is placed on a linked list maintained within the
    filter driver. The preOp callback returns FLT_PREOP_PENDING.
  5. At some point, userspace asks for the data associated with the
    request via a filter message port.
  6. In the filter message port handler the filter looks up the request
    on the list and copies its data to userspace.
  7. Userspace does some magic processing before sending a message to
    the filter notifying it that the request has been completed.
  8. In the filter message port handler the filter looks up the request
    on its internal list and calls FltCompletePendedPreOperation(),
    passing the callbackData pointer that was stashed in step (2).
  9. The filter message port handler removes the internal request
    structure from the list and frees it.

Having read the MSDN docs associated with the
FltCompletePendedPreOperation() call as well as the cancelSafe
minifilter sample in the DDK it is not clear to me what I’m doing
wrong. The documentation hints that the expected usage model for
FltCompletePendedPreOperation() is with the deferred IO API
(FltQueueDeferredIoWorkItem() et al). However the cancelSafe sample
makes use of its own queuing mechanisms, which leads me to believe
that the use of FltQueueDeferredIoWorkItem() isn’t required. Indeed,
for my application FltQueueDeferredIoWorkItem() doesn’t sound
appropriate since I’d need to somehow synchronize between the deferred
IO item worker function and the filter port message handler[4].

Any suggestions ?

Thanks,
Tom

[1] The work the userspace app does may be fairly long-running, so I
assume that telling the filter manager to pend is the correct thing to
do.

[2] You may feel that this procedure is over-complex. We’ve designed
it this way to allow variable-length messages to be passed to
userspace. Inbetween steps (3) and (5) userspace might be allocating
a new buffer to fit the message generated in step (2).

[3] Or it may be generating data using other api calls with the
callback data as an argument. In either case the aim is to ensure I
have captured the data I want in a buffer I own at this point.

[4] … and I assume that the naive approach of simply blocking on a
message from userspace would cause unacceptable delays in the system
worker thread.

Tom Parkin
www.thhp.org.uk
The worst moment for the atheist is when he is really thankful and has
nobody to thank /Rossetti/

2009/9/21 Tom Parkin :
> The documentation hints that the expected usage model for
> FltCompletePendedPreOperation() is with the deferred IO API
> (FltQueueDeferredIoWorkItem() et al). ?However the cancelSafe sample
> makes use of its own queuing mechanisms …

Apologies, this is completely incorrect. As I should have noticed
earlier on, the cancelSafe sample makes use of
FltQueueGenericWorkItem().

So I guess I need to use a similar mechanism for deferring IO within my filter.

Tom

Tom Parkin
www.thhp.org.uk
The worst moment for the atheist is when he is really thankful and has
nobody to thank /Rossetti/

Hello Tom,

Queuing a work item is not necessarily a part of pending operations. You might want to queue a work item or not, depending on your design.

For example, you can do this:
Thread1 (T1)

  1. add operation to internal list
  2. Return FLT_PREOP_PENDING

And in user mode you can have another thread (T2):

  1. get operation from list
  2. process operation (let’s say you decide whether to let the operation continue or fail it)
  3. call into the Filter via port or ioctl or whatever
  4. (now you’re in KM) -> call FltCompletePendedPreOperation with either FLT_PREOP_COMPLETE and Status = STATUS_ACCESS_DENIED (which means you failed it) or FLT_PREOP_SUCCESS_NO_CALLBACK (which means the operation is allowed to continue);

This kind of scenario (which is similar to your scenario as far as I can tell) requires no workitem.

Of course, there is a different scenario:
T1:

  1. queue a work item to do something (like perform IO)
  2. return FLT_PREOP_PENDING

And now T2 is the thread that is executing your work item:

  1. execute work
  2. call FltCompletePendedPreOperation (and again, you can either complete the operation here or send it below)

This kind of thing does require a work item.

The main thing about returning FLT_PREOP_PENDING is that there (usually) has to be another thread that at some point in time will either complete the operation or pass it below. In the first example, it was a user mode thread calling it, in the second case it was a worker thread the filter queued. There can be many other designs (for example another operation reaching your filter might trigger completion of the pended operation) but usually there is another thread.

So as far as I can tell your design appears correct. You need to provide some more details about the hang.

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

Hi Alex,

2009/9/21 Alexandru Carp :
>
> Queuing a work item is not necessarily a part of pending operations. You might want to queue a work item or not, depending on your design.
> …
> The main thing about returning FLT_PREOP_PENDING is that there (usually) has to be another thread that at some point in time will either complete the operation or pass it below.

Thanks for the clarification of this point. From further study of the
cancelSafe example I could see that the filter was using a work item
thread to complete IO operations, but wasn’t necessarily calling
FltQueueGenericWorkItem() for each IRP. This lead me to believe that
an IO operation’s presence on a deferred work queue was actually
orthogonal to safely returning FLT_PREOP_PENDING from the filter preOp
callback, but it is good to have this belief confirmed !

As you say, for my design I don’t need a separate thread to call
FltCompletePendedPreOperation() since the operation will be completed
within the context of the userspace thread which calls into the filter
via. the filter message port API.

>
> So as far as I can tell your design appears correct. You need to provide some more details about the hang.

I think part of my problem may be that the queue I am using internally
for the IO operations is not cancel-safe, so the first thing I plan to
do is to integrate my existing queue with the cancel-safe framework
provided by FltMgr.

If I still have issues at that point I’ll post back with further details.

Thanks again,
Tom

Tom Parkin
www.thhp.org.uk
The worst moment for the atheist is when he is really thankful and has
nobody to thank /Rossetti/

> 2009/9/21 Alexandru Carp :
>> So as far as I can tell your design appears correct. You need to provide some more details about the hang.
>
> I think part of my problem may be that the queue I am using internally
> for the IO operations is not cancel-safe, so the first thing I plan to
> do is to integrate my existing queue with the cancel-safe framework
> provided by FltMgr.
>
> If I still have issues at that point I’ll post back with further details.
>

And indeed I do have further issues.

I have integrated a cancel-safe queue, so the callback data structures
should be safely canceled by FltMgr. However, I still get a hang when
calling FltCompletePendedPreOperation().

I am calling this function from the context of the minifilter port
message handler on receipt of a message from user space. The code is
running at IRQL 0 (according to KeGetCurrentIrql()) which is within
the specification of IRQL <= APC_LEVEL mentioned in the MSDN comments
for FltCompletePendedPreOperation().

The outward symptoms of the hang are that
FltCompletePendedPreOperation() never returns, locking up the
userspace thread that called FilterSendMessage(). Otherwise the
system is running as normal e.g. responds to mouse interactions,
executes applications, etc. A resource monitor shows that the VM
running the driver isn’t using excessive CPU, so it doesn’t seem to be
spinning in a tight loop anywhere.

I have done some probing with WinDbg (see the !process output below),
and this suggests that the application has hung attempting to obtain a
mutex of some sort in kernelspace. But I’m not really sure what I’m
looking at here.

Can you suggest what I should be investigating order to further debug this ?

Many thanks,
Tom

Here’s the WinDbg !process output for my userspace application, which
has called FltCompletePendedPreOperation() via. a minifilter port
message.

lkd> !process 820b3020 7
PROCESS 820b3020 SessionId: 0 Cid: 01c0 Peb: 7ffd4000 ParentCid: 03d8
DirBase: 02b182c0 ObjectTable: e1974590 HandleCount: 11.
Image: wepc-us.exe
VadRoot 8221b958 Vads 24 Clone 0 Private 46. Modified 40. Locked 0.
DeviceMap e16c46d0
Token e1088860
ElapsedTime 00:38:21.421
UserTime 00:00:00.031
KernelTime 00:00:00.046
QuotaPoolUsage[PagedPool] 12964
QuotaPoolUsage[NonPagedPool] 960
Working Set Sizes (now,min,max) (79, 50, 345) (316KB, 200KB, 1380KB)
PeakWorkingSetSize 197
VirtualSize 5 Mb
PeakVirtualSize 6 Mb
PageFaultCount 255
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 60

THREAD 82257588 Cid 01c0.01d0 Teb: 7ffdf000 Win32Thread:
00000000 WAIT: (UserRequest) UserMode Non-Alertable
8209d020 Thread
Not impersonating
DeviceMap e16c46d0
Owning Process 0 Image:
Attached Process 820b3020 Image: wepc-us.exe
Wait Start TickCount 179502 Ticks: 66809 (0:00:17:23.890)
Context Switch Count 19989
UserTime 00:00:00.015
KernelTime 00:00:00.046
Win32 Start Address wepc_us!mainCRTStartup (0x0105fc74)
Start Address kernel32!BaseProcessStartThunk (0x7c810705)
Stack Init f7a22000 Current f7a21960 Base f7a22000 Limit f7a1f000 Call 0
Priority 10 BasePriority 8 PriorityDecrement 2 DecrementCount 16
Kernel stack not resident.

THREAD 8209d020 Cid 01c0.0298 Teb: 7ffde000 Win32Thread: 00000000
WAIT: (Executive) KernelMode Non-Alertable
821c5838 SynchronizationEvent
8209d110 NotificationTimer
IRP List:
822607f8: (0006,0094) Flags: 00000000 Mdl: 00000000
Not impersonating
DeviceMap e16c46d0
Owning Process 0 Image:
Attached Process 820b3020 Image: wepc-us.exe
Wait Start TickCount 246281 Ticks: 166 (0:00:00:02.593)
Context Switch Count 947
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address wepc_us!dataPortWorker (0x0104b7f0)
Start Address kernel32!BaseThreadStartThunk (0x7c8106f9)
Stack Init f8b2f000 Current f8b2e85c Base f8b2f000 Limit f8b2c000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr Args to Child
f8b2e874 80503846 8209d090 8209d020 804fb078
nt!KiSwapContext+0x2f (FPO: [Uses EBP] [0,0,4])
f8b2e880 804fb078 00000000 821de548 8209d020
nt!KiSwapThread+0x8a (FPO: [0,0,0])
f8b2e8a8 80535d5c 00000000 00000000 00000000
nt!KeWaitForSingleObject+0x1c2 (FPO: [5,5,4])
f8b2e8e4 805361b4 00000000 821305a0 01dbe501
nt!ExpWaitForResource+0xd4 (FPO: [0,5,0])
f8b2e904 f80f3ff2 821de548 01dbe501 00000000
nt!ExAcquireResourceExclusiveLite+0x8e (FPO: [2,3,0])
WARNING: Frame IP not in any known module. Following frames may be wrong.
f8b2e9f4 805026a4 c0000225 00000000 f80f47e9 0xf80f3ff2
f8b2ed34 8054162c 000007e8 00000000 00000000
nt!KiContinuePreviousModeUser+0x74 (FPO: [4,182,4])
f8b2ed34 7c90e514 000007e8 00000000 00000000
nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ f8b2ed64)
002cfe94 7c90d28a 4ffe1752 000007e8 00000000
ntdll!KiFastSystemCallRet (FPO: [0,0,0])
002cfe98 4ffe1752 000007e8 00000000 00000000
ntdll!ZwDeviceIoControlFile+0xc (FPO: [10,0,0])
002cfefc 4ffe23c7 000007e8 0008801b 00272de8
FLTLIB!FilterpDeviceIoControl+0xcc (FPO: [Non-Fpo])
002cff24 0104bdb9 000007e8 00272de8 00000010
FLTLIB!FilterSendMessage+0x23 (FPO: [6,0,0])
002cff50 0104ba68 00272d68 00272de8 002cff8c
wepc_us!FilterCommSend+0x59 (FPO: [Non-Fpo]) (CONV: stdcall)
[y:\src\wepc\user\filtercommunication.c @ 102]
002cffb4 7c80b729 0006ff74 006e006c 000822c8
wepc_us!dataPortWorker+0x278 (FPO: [Non-Fpo]) (CONV: stdcall)
[y:\src\wepc\user\main.c @ 483]
002cffec 00000000 0104b7f0 0006ff74 00000000
kernel32!BaseThreadStart+0x37 (FPO: [Non-Fpo])


Tom Parkin
www.thhp.org.uk
The worst moment for the atheist is when he is really thankful and has
nobody to thank /Rossetti/

Hello Tom,

I don’t see filter manager on that stack. Maybe you don’t have symbols ?

Anyway, since the thread is waiting on a resource, I would start by calling !locks on that resource.

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

Hi Alex,

2009/9/28 Alexandru Carp :
> I don’t see filter manager on that stack. Maybe you don’t have symbols ?
>

Yes… I’m not sure why, but I needed to .reload to persuade WinDbg
to get the symbols. The traces are more sensible now :wink:

> Anyway, since the thread is waiting on a resource, I would start by calling !locks on that resource.
>

It looks like I’m deadlocking with RDBSS for a resource (I’m attached
to a network file system).

First, this is the resource I think I’m deadlocking on:

Resource @ 0x820b5018 Exclusively owned
Contention Count = 1
NumberOfExclusiveWaiters = 1
Threads: 8206d020-01<*>
Threads Waiting On Exclusive Access:
8208a538

The thread holding this resource is the rdbss worker thread:

lkd> !thread 8206d020 7
THREAD 8206d020 Cid 0004.00c0 Teb: 00000000 Win32Thread: 00000000
WAIT: (Executive) KernelMode Non-Alertable
f745dbb0 SynchronizationEvent
IRP List:
8206e620: (0006,0190) Flags: 00000404 Mdl: 00000000
Not impersonating
DeviceMap e10001f8
Owning Process 0 Image:
Attached Process 823c6a00 Image: System
Wait Start TickCount 8273 Ticks: 16323 (0:00:04:15.046)
Context Switch Count 220
UserTime 00:00:00.000
KernelTime 00:00:00.015
DBGHELP: rdbss - public symbols
c:\symcache\rdbss.pdb\B8FBFEC3A9EC42BCBAF08AC6F4CB01E12\rdbss.pdb
Start Address rdbss!RxWorkerThreadDispatcher (0xf813293d)
Stack Init f745e000 Current f745db3c Base f745e000 Limit f745b000 Call 0
Priority 14 BasePriority 8 PriorityDecrement 5 DecrementCount 16
ChildEBP RetAddr Args to Child
f745db54 80503846 8206d090 8206d020 804fb078 nt!KiSwapContext+0x2f
(FPO: [Uses EBP] [0,0,4])
f745db60 804fb078 8206e630 8206e620 820b8808 nt!KiSwapThread+0x8a (FPO: [0,0,0])
f745db88 80583b0e 00000000 00000000 00000000
nt!KeWaitForSingleObject+0x1c2 (FPO: [5,5,4])
f745dbd4 805bb472 000b8808 00000000 820b87f0 nt!IopDeleteFile+0x148
(FPO: [1,9,4])
f745dbf0 805266da 820b8808 00000000 00000000
nt!ObpRemoveObjectRoutine+0xe0 (FPO: [2,1,4])
f745dc08 8050a89a 00000000 8209d468 00000000
nt!ObfDereferenceObject+0x4c (FPO: [0,0,0])
f745dc30 8050b426 e10b31c8 8209d498 00000000 nt!MiSegmentDelete+0xec
(FPO: [1,5,4])
f745dc54 8050f8a5 8209d468 00000000 820b5000
nt!MiCheckControlArea+0x1c4 (FPO: [3,3,4])
f745dca0 804e5e6e 820b5000 01000000 e121c808 nt!MmPurgeSection+0x57d
(FPO: [4,11,0])
f745dccc f81355c3 820b500c 00000000 00000000
nt!CcPurgeCacheSection+0x100 (FPO: [4,2,4])
f745dcf4 f813a0ab e1260008 00000000 00000000
rdbss!RxPurgeFcbInSystemCache+0x6b (FPO: [5,2,0])
f745dd1c f8132591 e11cd930 f81321e0 822b1e68
rdbss!RxPurgeFobxFromCache+0x5f (FPO: [1,0,4])
f745dd4c f8132848 822b1b58 821df030 f8131fc0
rdbss!RxScavengerFinalizeEntries+0x119 (FPO: [1,6,4])
f745dd6c f81284b1 822b1b58 00000000 8206d020
rdbss!RxScavengerTimerRoutine+0x53 (FPO: [1,2,4])
f745dd9c f8132957 00131fc0 f8132240 f745dddc
rdbss!RxpWorkerThreadDispatcher+0x93 (FPO: [2,6,4])
f745ddac 805cff70 f8131fc0 00000000 00000000
rdbss!RxWorkerThreadDispatcher+0x1a (FPO: [1,0,0])
f745dddc 805460ee f813293d f8131fc0 00000000
nt!PspSystemThreadStartup+0x34 (FPO: [Non-Fpo])
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

and the thread waiting on exclusive access is my userspace thread.
The wepcFilter calls are my minifilter:

lkd> !thread 8208a538 7
THREAD 8208a538 Cid 04dc.05f8 Teb: 7ffde000 Win32Thread: 00000000
WAIT: (Executive) KernelMode Non-Alertable
8223f328 SynchronizationEvent
8208a628 NotificationTimer
IRP List:
82094cc0: (0006,0094) Flags: 00000000 Mdl: 00000000
Not impersonating
DeviceMap e1837bc8
Owning Process 0 Image:
Attached Process 822ea4b0 Image: wepc-us.exe
Wait Start TickCount 27085 Ticks: 45 (0:00:00:00.703)
Context Switch Count 646
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address windbg!WinSymbol::UpdateNames (0x0104b7e0)
Start Address kernel32!BaseThreadStartThunk (0x7c8106f9)
Stack Init f73ea000 Current f73e9864 Base f73ea000 Limit f73e7000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 16
DBGHELP: mrxsmb - public symbols
c:\symcache\mrxsmb.pdb\9ABEB1460B13404F800EA4FFFD6667932\mrxsmb.pdb
DBGHELP: fltMgr - public symbols
c:\symcache\fltMgr.pdb\30197425FFC04385B84C0354E5035D5C1\fltMgr.pdb
SYMSRV: c:\symcache\wepcFilter.pdb\F59465AEFFCE4C23BE09416CA827C4681\wepcFilter.pdb
not found
SYMSRV: http://msdl.microsoft.com/download/symbols/wepcFilter.pdb/F59465AEFFCE4C23BE09416CA827C4681/wepcFilter.pdb
not found
DBGHELP: wepcFilter - private symbols & lines
y:\src\wepc\filter\objchk_wxp_x86\i386\wepcFilter.pdb
ChildEBP RetAddr Args to Child
f73e987c 80503846 8208a5a8 8208a538 804fb078 nt!KiSwapContext+0x2f
(FPO: [Uses EBP] [0,0,4])
f73e9888 804fb078 00000000 820b5018 8208a538 nt!KiSwapThread+0x8a (FPO: [0,0,0])
f73e98b0 80535d5c 00000000 00000000 00000000
nt!KeWaitForSingleObject+0x1c2 (FPO: [5,5,4])
f73e98ec 805361b4 00000000 82087670 8206ed01
nt!ExpWaitForResource+0xd4 (FPO: [0,5,0])
f73e990c f8133ff2 820b5018 8206ed01 00000000
nt!ExAcquireResourceExclusiveLite+0x8e (FPO: [2,3,0])
f73e9950 f8134832 e1260008 82087670 00000001
rdbss!__RxAcquireFcb+0x1f9 (FPO: [Non-Fpo])
f73e99b4 f8128d51 82087670 820b8808 f81318a8 rdbss!RxCommonClose+0x84
(FPO: [Non-Fpo])
f73e9a4c f8132cc2 f81318a8 8206e602 8206e6b4
rdbss!RxFsdCommonDispatch+0x353 (FPO: [Non-Fpo])
f73e9a74 f80b4317 822b1b58 8206e602 00000000 rdbss!RxFsdDispatch+0xda
(FPO: [2,0,0])
f73e9a94 804ef19f 00000000 0106e620 8206e620
mrxsmb!MRxSmbFsdDispatch+0x134 (FPO: [2,1,4])
f73e9aa4 f84e1e9b 822a3e78 00000000 f739ebd0 nt!IopfCallDriver+0x31
(FPO: [0,0,0])
f73e9ac8 f84e4d59 f73e9ae0 82243020 00000001
fltMgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x20b (FPO:
[3,4,4])
f73e9af8 f73a0500 823d5ef4 00000001 00000000
fltMgr!FltCompletePendedPreOperation+0x8b (FPO: [3,6,4])
f73e9b1c f739edaf e1179ea0 00275100 00000082
wepcFilter!handleRequestCompletion+0x140 (FPO: [Non-Fpo]) (CONV:
stdcall) [y:\src\wepc\filter\wepcrequest.c @ 357]
f73e9b54 f84e329d f73bd5e4 00275100 00000010
wepcFilter!wepcDataMessageHandler+0x1df (FPO: [Non-Fpo]) (CONV:
stdcall) [y:\src\wepc\filter\wepcfilter.c @ 515]
f73e9b9c f84edef8 82272bd0 00275100 00000010
fltMgr!FltpFilterMessage+0x73 (FPO: [Non-Fpo])
f73e9bd0 f84e1a37 82272b00 82094c00 00275100
fltMgr!FltpMsgDeviceControl+0xa4 (FPO: [10,1,4])
f73e9c14 f84e1f7f 8234c678 82094cc0 82272bd0
fltMgr!FltpMsgDispatch+0x87 (FPO: [2,2,0])
f73e9c40 804ef19f 8234c678 82094cc0 806e6410 fltMgr!FltpDispatch+0x33
(FPO: [2,6,4])
f73e9c50 8057f982 82094d30 82272bd0 82094cc0 nt!IopfCallDriver+0x31
(FPO: [0,0,0])
f73e9c64 805807f7 8234c678 82094cc0 82272bd0
nt!IopSynchronousServiceTail+0x70 (FPO: [7,0,4])
f73e9d00 80579274 000007e8 00000000 00000000
nt!IopXxxControlFile+0x5c5 (FPO: [Non-Fpo])
f73e9d34 8054162c 000007e8 00000000 00000000
nt!NtDeviceIoControlFile+0x2a (FPO: [10,0,0])
f73e9d34 7c90e514 000007e8 00000000 00000000 nt!KiFastCallEntry+0xfc
(FPO: [0,0] TrapFrame @ f73e9d64)
002cfefc 00000000 00000000 00000000 00000000 ntdll!KiFastSystemCallRet
(FPO: [0,0,0])

Using this information I did a quick search of the NTFSD list archives
and came up with this post which looks somewhat similar to my problem:

http://www.osronline.com/showThread.cfm?link=154874

I’m not entirely sure about this, but it looks at least similar…

Investigating further with my own minifilter I’ve observed the following:

1. If I attach to local filesystems only I don’t deadlock.

2. If I pass FLT_PREOP_COMPLETE to FltCompletePendedPreOperation()
and mark the callback data as cancelled (rather than passing
FLT_PREOP_SUCCESS_NO_CALLBACK as I was previously), I don’t deadlock.
I presume this is because the IRP doesn’t ever make it down to RDBSS.

3. The deadlock seems to be somewhat timing dependent; I either
hang on the first IRP I process, or after some (small) number of IRPs
depending on the amount of debug the filter outputs.

Is there anything special I should do for network filesystem IRPs in
order to pend / complete ?

Thanks,
Tom

2009/9/28 Alexandru Carp :
> Hello Tom,
>
> I don’t see filter manager on that stack. Maybe you don’t have symbols ?
>
> Anyway, since the thread is waiting on a resource, I would start by calling !locks on that resource.
>
> Regards,
> Alex.
> This posting is provided “AS IS” with no warranties, and confers no rights.

Tom Parkin
www.thhp.org.uk
The worst moment for the atheist is when he is really thankful and has
nobody to thank /Rossetti/

Hi Tom,

I have followed up with the owner of RDBSS and his reply was this:

“Did this filter pend the close issued by thread 8206d020? Or did it post the close to another thread? If so, this would be a deadlock, because RDR is holding the FCB resource while issuing the purge and it expects the close to come down on the same thread.”

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

Hi Alex

2009/9/29 Alexandru Carp :
> I have followed up with the owner of RDBSS and his reply was this:
>
> “Did this filter pend the close issued by thread 8206d020? ?Or did it post the close to another thread? If so, this would be a deadlock, because RDR is holding the FCB resource while issuing the purge and it expects the close to come down on the same thread.”
>

Thank you for this.

I’m not sure I understand the question “Did this filter pend the close
issued by thread 8206d020?” – it seems to me that 8206d020 is the
RDBSS worker thread. So this may mean:

1) I haven’t understood RDBSS’ design very well, and RDBSS might
issue close requests directly itself. I had thought that RDBSS sits
below FltMgr in the stack.
2) I’ve misread the stack traces and 8206d020 isn’t an RDBSS thread.
3) I’ve got the wrong end of the stick all together …

In any case, I’m missing something, so I’ll just present the scenario
as I see it and hope you’ll be able to glean something sensible from
it.

-> A userspace thread (A) issues an IRP_MJ_CLOSE [1]
-> The IRP arrives at my minifilter PreOp callback
-> My minifilter sends a message to userspace and returns
FLT_PREOP_PENDING to FltMgr
-> My userspace application thread (B) calls into the minifilter
via. FilterSendMessage()
-> Within the minifilter code, thread B calls
FltCompletePendedPreOperation() with the status
FLT_PREOP_SUCCESS_NO_CALLBACK
-> FltCompletePendedPreOperation() never returns

So the IRP_MJ_CLOSE operation that is pended by thread A is completed
by thread B. I think this is probably the scenario that the RDBSS
owner outlined.

One final data point for you – since posting my mail yesterday I
experimented with an alternative minifilter design which, rather than
returning FLT_PREOP_PENDING to FltMgr from the PreOp callback actually
blocks on a notification event which is signaled when my userspace
thread has done its work. This design appears to avoid the hang I
have seen with the FLT_PREOP_PENDING approach – although I haven’t
tested it very thoroughly yet.

What I’ve gleaned from the above is that: completing a pended
IRP_MJ_CLOSE request destined to hit RDBSS from a different thread
than that which issued the request isn’t safe. Would that be a fair
statement ?

Thanks again for your help with this,
Tom

[1] Based on some investigation this morning I appear always to hang
on an IRP_MJ_CLOSE request as the RDBSS owner suggests. The fact that
the minifilter might handle some small number of IRPs prior to
hanging, as observed previously, seems to be dependent upon how
quickly I start processing data following a build / install cycle. If
I happen to catch a IRP_MJ_CLOSE at the end of the build / install
activity I hang right away. Otherwise, I need to prompt some further
filesystem activity e.g. by opening explorer to cause the hang –
typically in this case I see a few requests e.g.
IRP_MJ_QUERY_INFORMATION complete successfully before hanging on
IRP_MJ_CLOSE.

Tom Parkin
www.thhp.org.uk
The worst moment for the atheist is when he is really thankful and has
nobody to thank /Rossetti/

So 8206d020 is an RDBSS worker thread. On that thread RDBSS is pretty much cleaning up the cache entry for that file. It has the FCB resource and it calls nt!CcPurgeCacheSection, which will purge the section and deletes the control area. This in turn leads to dereferencing the FileObject which, if this was the last reference, ends up calling IopDeleteFile. IopDeleteFile creates and IRP_MJ_CLOSE and sends it to the top of the stack. Your minifilter sees that IRP_MJ_CLOSE and pends it. If STATUS_PENDING is return then IopDeleteFile waits for an event to be signaled.

On your user mode thread you call FltCompletePendedPreOperation for the IRP_MJ_CLOSE which will eventually get to RDBSS which tries to get the FCB resource that the other thread already has acquired… Deadlock.

Some things I’d like to comment on:

  1. " A userspace thread (A) issues an IRP_MJ_CLOSE [1]" -> not exactly the case. IRP_MJ_CLOSE if issued when the last reference to the FILE_OBJECT is released. A user mode thread doesn’t directly issue IRP_MJ_CLOSE, it might happen that on calling CloseHandle it releases the final reference, but it does not directly trigger it. If the file is memory mapped then there will be a reference on the FILE_OBJECT from MM and only when that final reference goes away you will see the IRP_MJ_CLOSE.

  2. " I had thought that RDBSS sits below FltMgr in the stack." Yes it does, but it doesn’t matter, RDBSS can trigger operations that will be seen in the IO stack above itself (all filesystems and even filters can do this). Like dereferencing a FILE_OBJECT, which might cause an IRP_MJ_CLOSE.

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

Hi Alex,

2009/9/30 Alexandru Carp :
> So 8206d020 is an RDBSS worker thread. On that thread RDBSS is pretty much cleaning up the cache entry for that file. It has the FCB resource and it calls nt!CcPurgeCacheSection, which will purge the section and deletes the control area. This in turn leads to dereferencing the FileObject which, if this was the last reference, ends up calling IopDeleteFile. IopDeleteFile creates and IRP_MJ_CLOSE and sends it to the top of the stack. Your minifilter sees that IRP_MJ_CLOSE and pends it. If STATUS_PENDING is return then IopDeleteFile waits for an event to be signaled.
>
> On your user mode thread you call FltCompletePendedPreOperation for the IRP_MJ_CLOSE which will eventually get to RDBSS which tries to get the FCB resource that the other thread already has acquired… Deadlock.
>

Okay, that makes sense. I hadn’t fully understood the way that RDBSS
and the cache manager were interacting with the filesystem – thanks
for explaining it !

I suppose with your points in mind I should either avoid pending
IRP_MJ_CLOSE requests, or avoid pending any requests by means of the
blocking mechanism I outlined previously. In either case, I see where
I’m going wrong now.

Thanks again,
Tom

Tom Parkin
www.thhp.org.uk
The worst moment for the atheist is when he is really thankful and has
nobody to thank /Rossetti/