Thursday, January 19, 2012

Application Compatibility: Asynchronous Handles and Minifilters

Investigating application compatibility (AppCompat) issues with file system filters is the bread and butter of file system developers. There is simply an infinite number of ways in which filters can misbehave so I'm not going to even try to address them here. However, there are some that are worth discussing either because they are fairly common or because they are not the filter's fault but rather the system's.
The one such issue I'd like to talk about in this post is one that can be pretty hard to identify but not that hard to fix (or work around). My hope is that if developers are more aware of the problem they might have an easier time identifying it. The problem is that some applications (mostly user mode but it could happen for kernel drivers as well) occasionally open handles for asynchronous IO and then forget about this and perform IO on the handle as if it is synchronous (or maybe the developers aren't certain how to use a handle that was opened for asynchronous IO ). Anyway, what happens is that the application looks something like this:
 HANDLE hFile;

hFile = CreateFile(szFileName,
                      GENERIC_READ,
                      0,
                      NULL,
                      OPEN_EXISTING,
                      FILE_FLAG_NORMAL | FILE_FLAG_OVERLAPPED,
                      NULL);

...
// use the handle for some asynchronous IO
…
// perform some operation on the handle
If (GetFileInformationByHandle( hFile, ..)) {
 // do stuff with the information 
}
Please note that I'm using GetFileInformationByHandle() here just as an example, any function that works on a file handle could be used instead. Anyway, the problem in some cases is that the function might not be working as expected for asynchronous handles. For our example, GetFileInformationByHandle() is simply a thin wrapper over NtQueryInformationFile and it simply calls it and if the status it gets is NT_SUCCESS(status) then it thinks the IO was successful. However, if the handle has been opened for asynchronous IO it is possible that NtQueryInformationFile will return STATUS_PENDING, which is a success status (so NT_SUCCESS(STATUS_PENDING) == TRUE) and so the caller of GetFileInformationByHandle() might think the operation has completed successfully even though it hasn't. The result of this in our case is the fact that the application might be working an uninitialized buffer.
Of course, most such bugs will be caught during testing but (as always) there is a twist. There are some operations for which the file system never returns STATUS_PENDING and instead it just completes the operation in-line. In fact the file system is generally pretty conservative about returning STATUS_PENDING because doing it introduces additional overhead (there must be another thread that will be used to complete the request) and so the scenario where some operations are completed inline is rather common. This means that during testing the application will never get STATUS_PENDING and so the code that calls GetFileInformationByHandle() always works well and so the potential problem is never found. Driver Verifier has a mode in which it will return STATUS_PENDING for most IO but then not many application developers run with Driver Verifier enabled. I'm not sure whether Application Verifier offers something like this, but it's worth looking into.
This is where file system filters enter the picture. File system filters might return STATUS_PENDING in cases where the file system won't do that. In fact, there is one file system in particular that marks IRPs pending all the time: FltMgr. Filter Manager has simplified the IO model for minifilters quite a lot. Pretty much all the complexity of passing IRPs down and dealing with the completion routine is hidden from minifilters, but there is a cost. In FltMgr's model a filter can decide that it needs to pend a request during a postOp callback. In the NT model however this is not possible, the IRP must have been pended already in order for a completion callback to be able to return STATUS_MORE_PROCESSING_REQUIRED. Since FltMgr doesn't make the filter decide during the preOp whether it will pend the request during the postOp callback (in fact FltMgr allows a filter to not even have a preOp callback), it proactively marks the IRP pending, in case the minifilter will want to return FLT_POSTOP_MORE_PROCESSING_REQUIRED.
If the explanation above seems convoluted, the short version is this: FltMgr returns STATUS_PENDING a lot more than the file system. So this is where the problem shows up. Someone installs an innocent looking minifilter and suddenly some application starts failing in a strange way (if you're lucky; the unlucky case is the one where application starts slowly corrupting data…). The investigation shows that the presence of the filter clearly has something to do with the problem, but it's impossible to pin down what the filter is doing wrong. In some cases even disabling all filter functionality still somehow manages to reproduce the problem (and of course the reason is that the bug is in the application and the mere presence of the filter makes FltMgr return STATUS_PENDING and expose the bug).
So how can this be fixed ? In most cases there is a very simple fix, the filter must replace FLT_PREOP_SUCCESS_WITH_CALLBACK with FLT_PREOP_SYNCHRONIZE for the operation that exhibits the problem (for our example, IRP_MJ_QUERY_INFORMATION). This has the effect of making the operation synchronous at FltMgr's level and so NtQueryInformationFile() won't return STATUS_PENDING anymore. Of course, from a filter perspective the problem is identifying the operation that is causing the problem, but that can be done by replacing FLT_PREOP_SUCCESS_WITH_CALLBACK with FLT_PREOP_SYNCHRONIZE one at a time until the problem no longer occurs. Please note that it's possible that there is more than one operation that needs this so there may be more than one replacement necessary for the app to start working. In my experience it's easiest to start by replacing all the return statuses and then reverting them one at a time. Of course, this is a hack around the real fix (which is fixing the application) but since in most cases the filter developer doesn't have the luxury to tell the app developer to fix their problem this approach can be quite handy.
Now, this problem has largely been addressed by now in most apps since FltMgr has been around for a while and since Vista there are some minifilters running by default on the system and so application developers have mostly fixed their stuff, but it's possible that one still runs into this issue.
Finally I'd like to show you how this might look in practice. This thread shows how this problem might appear to a developer. Also, see KB article 939767 and KB article 2009604 and KB article 970878, all of which are examples of applications doing this sort of thing.

Update:

So I was a bit uncomfortable about not being able to remember if there are any specific Nt APIs that would leak STATUS_PENDING so I spent some time looking at some of the APIs. In most cases (including in the NtQueryInformationFile() function from my example) if the handle was opened for async IO and if the IO manager returns STATUS_PENDING the function will wait for the API to complete by waiting on a event. So the Nt APIs are well behaved, but applications might still try to perform reads and writes on a async handle treating it like a synchronous one. For example KB 970878 that I mentioned above states that the problem comes from using BackupRead() and BackupSeek() on an asynchronous handle (and the documentation for BackupWrite() states that it also requires a synchronous handle so it likely would exhibit the same behavior). KB article 939767 also explains how this could happen for a kernel driver (and in fact it's more likely to happen for a driver if they roll their own IRPs (or the minifilter equivalent of using the FLT_CALLBACKDATAs) instead of going through the Nt/Zw APIs since as we've seen those are careful about this sort of thing).

Another thing i've been meaning to say but I forgot until Jeho pointed it out (thanks Jeho!) was that the easiest way I found to check for this scenario is to use the Passthrough sample. It filters all APIs and it has completion routines for all of them, so FltMgr will be doing a lot of pending. Moreover, it's easy to just hand it with the source and everything to the app developer (where possible) and tell them how to reproduce the problem and since it's also coming from Microsoft it carries potentially more weight. However, when using this approach make sure to change the altitude of the sample because if the problem exists in a filter in the file system stack that is lower than the sample it won't reproduce the problem.

Thursday, January 12, 2012

Debugging Minifilters: using !fltkd.filter - Part III

In this post I finally get to look at context information about a filter and how to get to it. The !fltkd extension has split the information about contexts into information about which types of contexts the filter has registered and information about the contexts that the filter is using (they are either referenced by the filter or attached to an object). I'll try to follow the same scheme.
So first we'll look to see what information about the contexts we can get from the _FLT_FILTER structure:
0: kd> dt 94bb2da0 fltmgr!_FLT_FILTER
   +0x000 Base             : _FLT_OBJECT
   +0x014 Frame            : 0x94b58cc0 _FLTP_FRAME
   +0x018 Name             : _UNICODE_STRING "FileInfo"
   +0x020 DefaultAltitude  : _UNICODE_STRING "45000"
   +0x028 Flags            : 2 ( FLTFL_FILTERING_INITIATED )
   +0x02c DriverObject     : 0x9750f598 _DRIVER_OBJECT
   +0x030 InstanceList     : _FLT_RESOURCE_LIST_HEAD
   +0x074 VerifierExtension : 0x94bdcdd0 _FLT_VERIFIER_EXTENSION
   +0x078 VerifiedFiltersLink : _LIST_ENTRY [ 0x926904bc - 0xa0c92b38 ]
   +0x080 FilterUnload     : 0x926b8b6a     long  +ffffffff926b8b6a
   +0x084 InstanceSetup    : (null) 
   +0x088 InstanceQueryTeardown : (null) 
   +0x08c InstanceTeardownStart : (null) 
   +0x090 InstanceTeardownComplete : (null) 
   +0x094 SupportedContextsListHead : 0x94bbee70 _ALLOCATE_CONTEXT_HEADER
   +0x098 SupportedContexts : [6] (null) 
   +0x0b0 PreVolumeMount   : (null) 
   +0x0b4 PostVolumeMount  : (null) 
   +0x0b8 GenerateFileName : (null) 
   +0x0bc NormalizeNameComponent : (null) 
   +0x0c0 NormalizeNameComponentEx : (null) 
   +0x0c4 NormalizeContextCleanup : (null) 
   +0x0c8 KtmNotification  : (null) 
   +0x0cc Operations       : 0x94bb2efc _FLT_OPERATION_REGISTRATION
   +0x0d0 OldDriverUnload  : (null) 
   +0x0d4 ActiveOpens      : _FLT_MUTEX_LIST_HEAD
   +0x100 ConnectionList   : _FLT_MUTEX_LIST_HEAD
   +0x12c PortList         : _FLT_MUTEX_LIST_HEAD
   +0x158 PortLock         : _EX_PUSH_LOCK
0: kd> dp 94bb2da0+0x98 L6
94bb2e38  00000000 94bbee70 00000000 94bbef38
94bb2e48  00000000 00000000
As we can see there are two members that seem to be related to contexts, "SupportedContextsListHead" and "SupportedContexts". Interestingly enough SupportedContexts is an array of fixed size, embedded into the _FLT_FILTER structure. This is the same number of contexts that FltMgr supports in Win7. According to the documentation there seems to be a new context type coming in Win8 (FLT_SECTION_CONTEXT). Anyway, each entry in the array is of type _ALLOCATE_CONTEXT_HEADER, just like the "SupportedContextsListHead" variable. However, the _ALLOCATE_CONTEXT_HEADER doesn't start with a LIST_ENTRY (though it does contain one) so I'm not sure what SupportedContextsListHead actually does (since it's clearly not a list head). Anyway, let's ignore it for now and look at the entries in the array:
0: kd> dt 0x94bbee70 _ALLOCATE_CONTEXT_HEADER
fltmgr!_ALLOCATE_CONTEXT_HEADER
   +0x000 Filter           : 0x94bb2da0 _FLT_FILTER
   +0x004 ContextCleanupCallback : 0x926b7880     void  fileinfo!FIVolumeCleanup+0
   +0x008 Next             : (null) 
   +0x00c ContextType      : 2
   +0x00e Flags            : 0x1 ''
   +0x00f AllocationType   : 0x1 ''
0: kd> dt 94bbef38 _ALLOCATE_CONTEXT_HEADER
fltmgr!_ALLOCATE_CONTEXT_HEADER
   +0x000 Filter           : 0x94bb2da0 _FLT_FILTER
   +0x004 ContextCleanupCallback : 0x926b7cc4     void  fileinfo!FIStreamCleanup+0
   +0x008 Next             : (null) 
   +0x00c ContextType      : 8
   +0x00e Flags            : 0x1 ''
   +0x00f AllocationType   : 0x1 ''
The one odd bit here is the fact that the context type for the second entry in the array is 8, but we know there are only 6 context types.. Looking at the position of the entries in the array we can conclude that these are bit fields and they most likely map to the values in the FLT_CONTEXT_TYPE define. This also helps us identify the members of the array (first entry is for Volume contexts, the second for Instance contexts and so on). This is still a bit confusing since it would seems that the first entry is for an instance context but it's callback is named fileinfo!FIVolumeCleanup. Most likely what's happened is that FileInfo was using volume contexts and then they switched to using instance contexts (most likely for performance reasons) but didn't change the function name. A quick look at luafv shows it uses the same context type but the callback this time indicates it's an instance context:
0: kd> dt a0c72e70 _ALLOCATE_CONTEXT_HEADER
fltmgr!_ALLOCATE_CONTEXT_HEADER
   +0x000 Filter           : 0xa0c92ac0 _FLT_FILTER
   +0x004 ContextCleanupCallback : 0xa29b8a1f     void  luafv!LuafvInstanceCleanup+0
   +0x008 Next             : (null) 
   +0x00c ContextType      : 2
   +0x00e Flags            : 0x1 ''
   +0x00f AllocationType   : 0x1 ''
Another thing worth mentioning is that when allocating contexts of fixed size FltMgr uses a lookaside list. As such we expect that there is a lookaside list related to this context somewhere, and since the name of the structure is "_ALLOCATE_CONTEXT_HEADER" it's easy to guess that the data containing the lookaside list is right after the header. This is especially obvious considering that the memory that was allocated for one context is 0xc8 bytes, much larger than the 0x10 bytes that the _ALLOCATE_CONTEXT_HEADER takes:
0: kd> !pool 0x94bbee70 
Pool page 94bbee70 region is Special pool
*94bbe000 size:  190 data: 94bbee70 (NonPaged) *FMcr  <- we have 0x190 bytes
  Pooltag FMcr : Context registration structures, Binary : fltmgr.sys
0: kd> ? 0x94bbef38 - 0x94bbee70    
Evaluate expression: 200 = 000000c8 <- the second context starts at 0xc8 after the first
0: kd> ? 0xc8 * 2
Evaluate expression: 400 = 00000190 <- 0xc8 * 2 (for two contexts) is exactly 0x190 , the size of our block.. 
We could spend some time to try to reverse-engineer the meaning of the AllocationType and Flags members but it'd take too long.. So let's just see how we can get the contexts that are used by the filter. FltMgr keeps track of all the context it has allocated because it needs to be able to free all of them when the instance is detached, but they are stored inside the actual FLT_INSTANCE structure and while that's an interesting topic in itself, I'd rather not go into it in this post. However, information about all the contexts used by a filter is available when using Driver Verifier. As you might remember from the previous post, the _FLT_VERIFIER_EXTENSION structure has a tree of all the contexts. Unfortunately, the tree for the allocated objects is filled with other stuff as well so it's hard to find just the contexts (file name cache entries are also stored in the verifier tree and when a filter is using FltGetFileNameInformation() most of the verifier entries will be name cache entries (at least that has been my experience so far)).

Thursday, January 5, 2012

Debugging Minifilters: using !fltkd.filter - Part II

Happy New Year everyone! As I promised in my previous post I'll go over some of the flags !fltkd.filter has and show a couple more tricks about debugging filters. So let's start by listing the flags that are available for !fltkd.filter:
0: kd> !fltkd.filter
   filter [addr] [flags] [detail]            Dump FLT_FILTER
      where [flags] specify what information to dump:
         0x00000001 Basic filter information
         0x00000002 Filter's context registration information
         0x00000004 Filter's context usage information
         0x00000008 Filter's object usage/reference information
         0x00000010 Filter's Verifier information
         0x00000020 Filter's Port information
Let's go over each flag and discuss its output. When it comes to output please note that I have a different setup than last time (I've enabled driver verifier) and so the addresses will be different from the ones in my previous post.
  • 0x00000001 Basic filter information - this is actually the default flag so the output is the usual output that is displayed when !fltkd.filter is called for a filter.
  • 0x00000002 Filter's context registration information - this doesn't seem to show anything in addition to what the basic information shows. However, as I mentioned in my previous post, I get an error about how the PVOID type is not defined and as it happens I get that error right when displaying the field "SupportedContexts" and so possibly the extension would do something for contexts but it can't because of the error.
  • 0x00000004 Filter's context usage information - I'm not sure what this is supposed to show but it's only showing a list of the instances for the filter:
    0: kd> !fltkd.filter a0c92ac0 4
    
    FLT_FILTER: a0c92ac0 "luafv" "135000"
       InstanceList             : (a0c92af0)
          FLT_INSTANCE: a0cd0a50 "luafv" "135000"
    
  • 0x00000008 Filter's object usage/reference information - this requires verifier to be enabled and when verification is enabled for the filter it shows this (we'll get into more detail later):
    0: kd> !fltkd.filter a0c92ac0 0x8
    
    FLT_FILTER: a0c92ac0 "luafv" "135000"
       InstanceList             : (a0c92af0)
          FLT_INSTANCE: a0cd0a50 "luafv" "135000"
       Object usage/reference information: 
          References to FLT_CONTEXT                : 0 
          Allocations of FLT_CALLBACK_DATA         : 1 
          Allocations of FLT_DEFERRED_IO_WORKITEM  : 0 
          Allocations of FLT_GENERIC_WORKITEM      : 0 
          References to FLT_FILE_NAME_INFORMATION  : 0 
          Open files                               : 1 
          References to FLT_OBJECT                 : 0 
    
  • 0x00000010 Filter's Verifier information - this shows a long list of what seem to be operations but I think it's broken because they're all NULL.
  • 0x00000020 Filter's Port information - this appears to work but unfortunately I don't have a minifilter that uses communication ports handy so all I can see is this:
    0: kd> !fltkd.filter a0c92ac0 0x20
    
    FLT_FILTER: a0c92ac0 "luafv" "135000"
       InstanceList             : (a0c92af0)
          FLT_INSTANCE: a0cd0a50 "luafv" "135000"
       Client Port List         : Mutex (a0c92bec) List [a0c92c0c-a0c92c0c] mCount=0 
    
So as we can see the flags don't really add much information to this extension. In particular two things seem to be missing, more details about the VerifierExtension and the contexts. So let's take a look at what we can find out without the extension. We'll start with VerifierExtension and we'll look at the symbols that FltMgr publishes:
0: kd> dt fltmgr!*VERIFIER*
          fltmgr!_FLT_VERIFIER_EXTENSION
          fltmgr!_FLT_VERIFIER_EXTENSION_FLAGS
          fltmgr!FLT_VERIFIER_OPERATIONS
          fltmgr!_FLT_VERIFIER_OBJECT
Clearly we need to see what's in fltmgr!_FLT_VERIFIER_EXTENSION and the address we need to look at is shown in !fltkd.filter under "VerifierExtension":
0: kd> !fltkd.filter a0c92ac0

FLT_FILTER: a0c92ac0 "luafv" "135000"
   FLT_OBJECT: a0c92ac0  [02000000] Filter
….
   Client Port List         : (a0c92bec)  mCount=0 
   VerifierExtension        : a0c3add0 
…
0: kd> dt fltmgr!_FLT_VERIFIER_EXTENSION a0c3add0
   +0x000 Flags            : 0 (No matching name)
   +0x004 FilterUnload     : (null) 
   +0x008 InstanceSetup    : 0xa29b562b     long  luafv!LuafvInstanceSetup+0
   +0x00c InstanceQueryTeardown : (null) 
   +0x010 InstanceTeardownStart : (null) 
   +0x014 InstanceTeardownComplete : (null) 
   +0x018 Operations       : [50] FLT_VERIFIER_OPERATIONS
   +0x1a8 Name             : 0xa0c30ff8  "luafv"
   +0x1b0 FltVerifierObjectsLookasideList : _NPAGED_LOOKASIDE_LIST
   +0x200 List             : _TREE_ROOT
   +0x204 Lock             : 0
   +0x208 Count            : [7] 0
   +0x224 FltVerifierObjectsAllocFailures : 0n0
   +0x228 FltVerifierObjectsUnlinkFailures : 0n0
Now, we expect that there are a lot of callbacks pointers (in fact all the callbacks) because when verifier is enabled FltMgr replaces all the callbacks that minifilter can register with stubs so that it can control exactly how the filter's callback behaves. As such it needs a place to store the original function pointers for the filter and here they are, in the VerifierExtension. Incidentally, if you follow the steps outlined in my previous post on finding the callbacks for a minifilter you'll see that for a verified filter all the preOp callbacks are fltmgr!FltvPreOperation and all the postOp callbacks are fltmgr!FltvPostOperation… So know you know where the real callbacks are even for verified filters.
Once we're done with the callbacks there are few interesting things left:
  • Name - this is the name of the filter again but it's not a unicode string, it's an proper ASCII string complete with a NULL.
  • FltVerifierObjectsLookasideList - clearly a lookaside list of some kind, for some objects that are only allocated when verification is enabled.
  • List - this is probably the most interesting one.. When verification is enabled FltMgr tracks certain things (references to contexts, allocations of certain structures and so on) and they're all stored in this list (which is actually a tree, as we're about to see).
  • Lock - obviously some lock protecting the list.
  • Count - not as obvious but this seems to be where the counts for the "Filter's object usage/reference information" flag are coming from..
The rest of the fields don't seem to be interesting and I think they are meant for FltMgr internal tracking. Anyway, let's look at the List and Count in more detail:
0: kd> dt fltmgr!_FLT_VERIFIER_EXTENSION a0c3add0 List.
   +0x200 List  : 
      +0x000 Tree  : 0xcbc78fd8 _RTL_SPLAY_LINKS
0: kd> !tree 0xcbc78fd8 

TREE_ROOT: cbc78fd8 
TREE_NODE: a0ccefd8 (k1=974957b8, k2=00000000) [00010000] InTree
TREE_NODE: cbc78fd8 (k1=cbc62e40, k2=00000000) [00010000] InTree
0: kd> !pool a0ccefd8 2
Pool page a0ccefd8 region is Special pool
*a0cce000 size:   28 data: a0ccefd8 (NonPaged) *FMvj
  Pooltag FMvj : FLT_VERIFIER_OBJECT structure, Binary : fltmgr.sys
0: kd> !pool cbc78fd8 2
Pool page cbc78fd8 region is Special pool
*cbc78000 size:   28 data: cbc78fd8 (NonPaged) *FMvj
  Pooltag FMvj : FLT_VERIFIER_OBJECT structure, Binary : fltmgr.sys
So the tree is a tree of FLT_VERIFIER_OBJECT (which probably come from the FltVerifierObjectsLookasideList) and there are two things in the tree:
0: kd> !pool a0ccefd8 2
Pool page a0ccefd8 region is Special pool
*a0cce000 size:   28 data: a0ccefd8 (NonPaged) *FMvj
  Pooltag FMvj : FLT_VERIFIER_OBJECT structure, Binary : fltmgr.sys
0: kd> !pool cbc78fd8 2
Pool page cbc78fd8 region is Special pool
*cbc78000 size:   28 data: cbc78fd8 (NonPaged) *FMvj
  Pooltag FMvj : FLT_VERIFIER_OBJECT structure, Binary : fltmgr.sys
0: kd> dt a0ccefd8 fltmgr!_FLT_VERIFIER_OBJECT
   +0x000 TreeLink         : _TREE_NODE
   +0x01c Type             : 5
   +0x020 Object           : 0x974957b8 Void
   +0x024 RefCount         : 0n1
0: kd> !pool 0x974957b8 2
Pool page 974957b8 region is Nonpaged pool
*97495780 size:   b8 previous size:   30  (Allocated) *File (Protected)
  Pooltag File : File objects
0: kd> dt cbc78fd8 fltmgr!_FLT_VERIFIER_OBJECT
   +0x000 TreeLink         : _TREE_NODE
   +0x01c Type             : 1
   +0x020 Object           : 0xcbc62e40 Void
   +0x024 RefCount         : 0n1
0: kd> !pool 0xcbc62e40 2
Pool page cbc62e40 region is Special pool
*cbc62000 size:  220 data: cbc62de0 (NonPaged) *FMic
  Pooltag FMic : IRP_CTRL structure, Binary : fltmgr.sys
So as we can see the tree holds all structures tracked by FltMgr. It wasn't immediately obvious but when looking at the numbers returned with the "Filter's object usage/reference information" flag set it seems that the order in which those counts are displayed corresponds to the number that is the "Type" member of the fltmgr!_FLT_VERIFIER_OBJECT structure and that the count of each type are stored in the "Count" array in the of fltmgr!_FLT_VERIFIER_EXTENSION. So type 1 is IRP_CTRL and type 5 is FILE_OBJECT. Since I'm running on Win7 I have FileInfo running and it has more interesting stuff (like a lot of contexts and file names ):
0: kd> !fltkd.filter 94bb2da0 8

FLT_FILTER: 94bb2da0 "FileInfo" "45000"
   InstanceList             : (94bb2dd0)
      FLT_INSTANCE: 94a34dc8 "FileInfo" "45000"
      FLT_INSTANCE: 98952dc8 "FileInfo" "45000"
      FLT_INSTANCE: 99f00dc8 "FileInfo" "45000"
      FLT_INSTANCE: 9afdedc8 "FileInfo" "45000"
      FLT_INSTANCE: 9aeb0dc8 "FileInfo" "45000"
   Object usage/reference information: 
      References to FLT_CONTEXT                : 4229 
      Allocations of FLT_CALLBACK_DATA         : 0 
      Allocations of FLT_DEFERRED_IO_WORKITEM  : 0 
      Allocations of FLT_GENERIC_WORKITEM      : 0 
      References to FLT_FILE_NAME_INFORMATION  : 4224 
      Open files                               : 0 
      References to FLT_OBJECT                 : 0 
I was going to take a look at the context information that we can dig from the FLT_FILTER structure but I see this post has gotten quite long so I'll leave that for next time.

Thursday, December 15, 2011

Debugging Minifilters: Using !fltkd.filter

Ever since I started this blog I had planned to go over all the fields that the !fltkd extension can show for the various FltMgr structures and talk about each of them. I'm going to start this with the !fltkd.filter command. Most commands take additional flags that control which information is shown. For this post I'll just focus on the default output without any flags and I'll cover the flags in a different post.

Before I begin I'd like to mention that the !fltkd command in general is heavily dependent on the public symbols for fltmgr.sys and so it doesn't work at all without the right symbols. Moreover, the extension itself and the symbols as well have some bugs and in some cases it can't display things correctly because some of the structures that it expects are not in the public symbols at all or at least they are not under the name the extension expects to find them. So you will occasionally see output from the debugger saying something along the lines of "Your debugger is not using the correct symbols … Type referenced: " followed by a type name. I've removed them from the output in the blog post and we'll work with what we have. Please note that if you want to follow along it's best to use a Win7 machine since the symbols were most complete in that release (though still not 100% fixed).

1: kd> !fltkd.filters

Filter List: 92cddd1c "Frame 0" 
   FLT_FILTER: 94144008 "luafv" "135000"
      FLT_INSTANCE: 94146008 "luafv" "135000"
   FLT_FILTER: 92cdda58 "FileInfo" "45000"
      FLT_INSTANCE: 930e7730 "FileInfo" "45000"
      FLT_INSTANCE: 93448dc8 "FileInfo" "45000"
      FLT_INSTANCE: 9357c340 "FileInfo" "45000"
      FLT_INSTANCE: 93584560 "FileInfo" "45000"
      FLT_INSTANCE: 9359a948 "FileInfo" "45000"
1: kd> !fltkd.filter 94144008 

FLT_FILTER: 94144008 "luafv" "135000"
   FLT_OBJECT: 94144008  [02000000] Filter
      RundownRef               : 0x00000008 (4)
      PointerCount             : 0x00000001 
      PrimaryLink              : [92cdda64-92cddd1c] 
   Frame                    : 92cddcc0 "Frame 0" 
   Flags                    : [00000006] FilteringInitiated NameProvider
   DriverObject             : 941427a8 
   FilterLink               : [92cdda64-92cddd1c] 
   PreVolumeMount           : 81f980cc  luafv!LuafvPreRedirect 
   PostVolumeMount          : 00000000  (null) 
   FilterUnload             : 00000000  (null) 
   InstanceSetup            : 81fa462b  luafv!LuafvInstanceSetup 
   InstanceQueryTeardown    : 00000000  (null) 
   InstanceTeardownStart    : 00000000  (null) 
   InstanceTeardownComplete : 00000000  (null) 
   ActiveOpens              : (941440dc)  mCount=1 
   Communication Port List  : (94144108)  mCount=0 
   Client Port List         : (94144134)  mCount=0 
   VerifierExtension        : 00000000 
   Operations               : 94144164 
   OldDriverUnload          : 00000000  (null) 
   SupportedContexts        : (941440a0)
      VolumeContexts           : (941440a0)
      InstanceContexts         : (941440a0)
      FileContexts             : (941440a0)
      StreamContexts           : (941440a0)
      StreamHandleContexts     : (941440a0)
      TransactionContext       : (941440a0)
   InstanceList             : (94144038)
      FLT_INSTANCE: 94146008 "luafv" "135000"

I'll just go over each field and discuss its meaning.
  • FLT_OBJECT: 94144008 [02000000] Filter - some of the main FltMgr objects (instance, volume and filter) begin with a standard structure that identifies the object type and contains some common synchronization primitives. You can see the structure by doing a "dt fltmgr!_FLT_OBJECT". The FLT_OBJECT is the first member of the structure and as such the address of the FLT_OBJECT is the same as the address of the bigger structure, which is the FLT_FILTER in our case.
  • RundownRef : 0x00000008 (4) - this is a rundown reference primitive that I've mentioned in my post here. The actual reference count is the value in parentheses. This value is incremented and decremented whenever someone calls FltObjectReference() and, respectively, FltObjectDereference(). This allows the filter to wait for other components to release their reference before tearing down (since the rundown reference will enter a special state that doesn't allow more references to be taken once the teardown process starts; this is different from a regular reference count where it's possible that the refcount never drops to 0)..
  • PointerCount : 0x00000001 - this is the actual reference count that controls when the memory is freed. There is no direct way filters can influence this (like FltReferenceObject), but I've seen communication ports increment this count.
  • PrimaryLink : [92cdda64-92cddd1c] - this is a link into a list of filters for the frame. Please remember that a filter is not aware of anything outside the frame and so the list of filters is a per-frame concept.
  • Frame : 92cddcc0 "Frame 0" - this is obviously a pointer to the frame the filter belongs to.
  • Flags : [00000006] FilteringInitiated NameProvider - obviously these are flags. Possible values include (as a general trick it's pretty easy to generate this list by changing the value of the flags in the structure and asking !fltkd.filter to display the filter again):
    • UnloadInProgress - the minifilter is unloading
    • FilteringInitiated - the minifilter has started filtering by calling FltStartFiltering().
    • NameProvider - the minifilter is a name provider. I think FltMgr sets this flag based on whether the minifilter registers the name provider callbacks.
  • DriverObject : 941427a8 - obviously the DRIVER_OBJECT for the filter.
  • FilterLink : [92cdda64-92cddd1c] - this is the same list as the PrimaryLink member of the FLT_OBJECT structure above.
  • PreVolumeMount : 81f980cc luafv!LuafvPreRedirect - this is actually the preOp callback for the IRP_MJ_MOUNT_VOLUME operation (that I've mentioned in my post How File System Filters Attach to Volumes - Part II). This looks like a strange place to have an operation callback but it makes sense because when this callback is called there is no instance associated with the volume (since the volume isn't mounted yet) and so the pointer couldn't have been called through the usual instance mechanism.
  • PostVolumeMount : 00000000 (null) - this is the postOp callback for the IRP_MJ_MOUNT_VOLUME operation.
  • FilterUnload : 00000000 (null) - this is the Unload callback (the FLT_REGISTRATION->FilterUnloadCallback member).
  • InstanceSetup : 81fa462b luafv!LuafvInstanceSetup - this is the FLT_REGISTRATION->InstanceSetupCallback member.
  • InstanceQueryTeardown : 00000000 (null) - this is the FLT_REGISTRATION->InstanceQueryTeardownCallback member.
  • InstanceTeardownStart : 00000000 (null) - this is the FLT_REGISTRATION->InstanceTeardownStartCallback member.
  • InstanceTeardownComplete : 00000000 (null) - this is the FLT_REGISTRATION->InstanceTeardownCompleteCallback member.
  • ActiveOpens : (941440dc) mCount=1 - the value in parentheses is a pointer to an internal FltMgr structure that is simply a doubly linked list protected by a mutex (you can see in the debugger by doing a dt fltmgr!_FLT_MUTEX_LIST_HEAD). For more information on this field please check out my post on Tracking a minifilter's ActiveOpens files.
  • Communication Port List : (94144108) mCount=0 - this is a list of opened communication ports for this filter (the same FLT_MUTEX_LIST_HEAD structure as mentioned above).
  • Client Port List : (94144134) mCount=0 - this is a list of connected communication ports.
  • VerifierExtension : 00000000 - this is the a structure that is used when DriverVerifier is enabled for this minifilter. I will go into more detail on this structure in a future post.
  • Operations : 94144164 - as mentioned in my post Debugging Minifilters: Finding the Callbacks this is actually a pointer to the _FLT_OPERATION_REGISTRATION structure that the filter used when it registered with FltMgr.
  • OldDriverUnload : 00000000 (null) - this is the routine that the driver registered as an unload routine. When a driver registers as a minifilter FltMgr needs to know when the driver is being unloaded (because it is possible to unload a minifilter like any other driver) and so FltMgr replaces the _DRIVER_OBJECT->DriverUnload member function with its own function so that it can detect that someone is trying to unload the driver and so that FltMgr can start the teardown process. Well, the original DriverUnload function is stored in the FLT_FILTER structure in this member.
  • SupportedContexts : (941440a0) - this is an array of information related to the context registration. I will discuss this in more depth in a future post.
  • InstanceList : (94144038) - this is a pointer to another FltMgr internal structure, the fltmgr!_FLT_RESOURCE_LIST_HEAD, which is a list protected by an ERESOURCE (as opposed to the fltmgr!_FLT_MUTEX_LIST_HEAD which was protected by a mutex). The entries in this list are the instances.

That's it for now. Next week I plan to discuss some of the !fltkd.filter flags and their output.

Thursday, December 8, 2011

Debugging Minifilters: Finding the Callbacks

When debugging interop issues I often need to be able to set breakpoints on a certain filter's dispatch function for a certain operation. In most cases the other filter is written by a 3rd party and I have no symbols for it at all and so it's not easy to look at function names and guess what the appropriate function to set the breakpoint on is. So in this post I would like to show how to find the appropriate routines for each operation for both legacy filters and minifilters. Because i'm using Microsoft filters for which symbols are available you can see all the function names, but of course the same principle applies even when you don't have symbols just that the names won't look so pretty.
When dealing with legacy filters the approach to get the callbacks is pretty well-known and it relies on looking at the fields in the DRIVER_OBJECT:
0: kd> !drvobj sr
Driver object (82332290) is for:
 \FileSystem\sr
Driver Extension List: (id , addr)

Device Object list:
8207d830  8213add0  8235e020  8238e248
8238e030  
0: kd> dt 82332290 nt!_DRIVER_OBJECT
   +0x000 Type             : 0n4
   +0x002 Size             : 0n168
   +0x004 DeviceObject     : 0x8207d830 _DEVICE_OBJECT
   +0x008 Flags            : 0x12
   +0x00c DriverStart      : 0xf8489000 Void
   +0x010 DriverSize       : 0x11f00
   +0x014 DriverSection    : 0x823eb998 Void
   +0x018 DriverExtension  : 0x82332338 _DRIVER_EXTENSION
   +0x01c DriverName       : _UNICODE_STRING "\FileSystem\sr"
   +0x024 HardwareDatabase : 0x8067d260 _UNICODE_STRING "\REGISTRY\MACHINE\HARDWARE\DESCRIPTION\SYSTEM"
   +0x028 FastIoDispatch   : 0xf848b4c0 _FAST_IO_DISPATCH
   +0x02c DriverInit       : 0xf8498fd4     long  sr!GsDriverEntry+0
   +0x030 DriverStartIo    : (null) 
   +0x034 DriverUnload     : (null) 
   +0x038 MajorFunction    : [28] 0xf848e726     long  sr!SrCreate+0
0: kd> dps 82332290+0x38 L0n28
823322c8  f848e726 sr!SrCreate
823322cc  f8489428 sr!SrPassThrough
823322d0  f8489428 sr!SrPassThrough
823322d4  f8489428 sr!SrPassThrough
823322d8  f8489320 sr!SrWrite
…
82332330  f8489428 sr!SrPassThrough
82332334  f848dd52 sr!SrPnp
Of course, legacy filters also have a couple of other sets of entrypoints, the FastIO routines and the FS_FILTER_CALLBACKS, which we might need to set breakpoints on:
0: kd> dt 0xf848b4c0 _FAST_IO_DISPATCH
nt!_FAST_IO_DISPATCH
   +0x000 SizeOfFastIoDispatch : 0x70
   +0x004 FastIoCheckIfPossible : 0xf8490914     unsigned char  sr!SrFastIoCheckIfPossible+0
   +0x008 FastIoRead       : 0xf8490962     unsigned char  sr!SrFastIoRead+0
   +0x00c FastIoWrite      : 0xf84909b0     unsigned char  sr!SrFastIoWrite+0
...
   +0x060 FastIoQueryOpen  : 0xf8490f30     unsigned char  sr!SrFastIoQueryOpen+0
   +0x064 ReleaseForModWrite : (null) 
   +0x068 AcquireForCcFlush : (null) 
   +0x06c ReleaseForCcFlush : (null) 

0: kd> dt 0x82332338 nt!_DRIVER_EXTENSION
   +0x000 DriverObject     : 0x82332290 _DRIVER_OBJECT
   +0x004 AddDevice        : (null) 
   +0x008 Count            : 0
   +0x00c ServiceKeyName   : _UNICODE_STRING "sr"
   +0x014 ClientDriverExtension : (null) 
   +0x018 FsFilterCallbacks : 0x8236d238 _FS_FILTER_CALLBACKS
0: kd> dt 0x8236d238 _FS_FILTER_CALLBACKS
nt!_FS_FILTER_CALLBACKS
   +0x000 SizeOfFsFilterCallbacks : 0x38
   +0x004 Reserved         : 0
   +0x008 PreAcquireForSectionSynchronization : 0xf8490c30     long  sr!SrPreAcquireForSectionSynchronization+0
   +0x00c PostAcquireForSectionSynchronization : (null) 
...
   +0x030 PreReleaseForModifiedPageWriter : (null) 
   +0x034 PostReleaseForModifiedPageWriter : (null) 
Things are similar for minifilters. There is a !fltkd command that tries to make things easier, but in my oppinion it could do a better job at helping out. For one, even though the callbacks are defined on a per-filter basis, the !fltkd.filter command that lists the contents of the filter structure doesn't actually show the registered callbacks, and instead one must use the the !fltkd.instance command on one of the instances of the filter , command that has a special flag that can be used to see the callbacks:
1: kd> !fltkd.filters

Filter List: 92cddd1c "Frame 0" 
   FLT_FILTER: 94144008 "luafv" "135000"
      FLT_INSTANCE: 94146008 "luafv" "135000"
   FLT_FILTER: 92cdda58 "FileInfo" "45000"
      FLT_INSTANCE: 930e7730 "FileInfo" "45000"
      FLT_INSTANCE: 93448dc8 "FileInfo" "45000"
      FLT_INSTANCE: 9357c340 "FileInfo" "45000"
      FLT_INSTANCE: 93584560 "FileInfo" "45000"
      FLT_INSTANCE: 9359a948 "FileInfo" "45000"
1: kd> !fltkd.filter 94144008 

FLT_FILTER: 94144008 "luafv" "135000"
   FLT_OBJECT: 94144008  [02000000] Filter
      RundownRef               : 0x00000008 (4)
      PointerCount             : 0x00000001 
      PrimaryLink              : [92cdda64-92cddd1c] 
   Frame                    : 92cddcc0 "Frame 0" 
   Flags                    : [00000006] FilteringInitiated NameProvider
   DriverObject             : 941427a8 
   FilterLink               : [92cdda64-92cddd1c] 
   PreVolumeMount           : 81f980cc  luafv!LuafvPreRedirect 
   PostVolumeMount          : 00000000  (null) 
   FilterUnload             : 00000000  (null) 
   InstanceSetup            : 81fa462b  luafv!LuafvInstanceSetup 
   InstanceQueryTeardown    : 00000000  (null) 
   InstanceTeardownStart    : 00000000  (null) 
   InstanceTeardownComplete : 00000000  (null) 
   ActiveOpens              : (941440dc)  mCount=1 
   Communication Port List  : (94144108)  mCount=0 
   Client Port List         : (94144134)  mCount=0 
   VerifierExtension        : 00000000 
   Operations               : 94144164 
   OldDriverUnload          : 00000000  (null) 
   SupportedContexts        : (941440a0)
      VolumeContexts           : (941440a0)
      InstanceContexts         : (941440a4)
         ALLOCATE_CONTEXT_NODE: 94144a20 "luafv" [01] LookasideList (size=608)
      FileContexts             : (941440a8)
      StreamContexts           : (941440ac)
      StreamHandleContexts     : (941440b0)
         ALLOCATE_CONTEXT_NODE: 94144ae8 "luafv" [01] LookasideList (size=20)
      TransactionContext       : (941440b4)
   InstanceList             : (94144038)
      FLT_INSTANCE: 94146008 "luafv" "135000"
1: kd> !fltkd.instance 94146008 4

FLT_INSTANCE: 94146008 "luafv" "135000"
   CallbackNodes            : (94146054)
       NORMALIZE_NAME_COMPONENT (-22)
         CALLBACK_NODE: 94146584  Inst:(94146008,"luafv","\Device\HarddiskVolume2") "luafv" "135000"
       GENERATE_FILE_NAME (-21)
         CALLBACK_NODE: 9414656c  Inst:(94146008,"luafv","\Device\HarddiskVolume2") "luafv" "135000"
       MDL_WRITE_COMPLETE (-18)
         CALLBACK_NODE: 9414611c  Inst:(94146008,"luafv","\Device\HarddiskVolume2") "luafv" "135000"
       PREPARE_MDL_WRITE (-17)
...
       ACQUIRE_FOR_SECTION_SYNC (-1)
         CALLBACK_NODE: 941462b4  Inst:(94146008,"luafv","\Device\HarddiskVolume2") "luafv" "135000"
       CREATE (0)
         CALLBACK_NODE: 941462cc  Inst:(94146008,"luafv","\Device\HarddiskVolume2") "luafv" "135000"
       CREATE_NAMED_PIPE (1)
         CALLBACK_NODE: 941462e4  Inst:(94146008,"luafv","\Device\HarddiskVolume2") "luafv" "135000"
...
       SET_QUOTA (26)
         CALLBACK_NODE: 9414653c  Inst:(94146008,"luafv","\Device\HarddiskVolume2") "luafv" "135000"
       PNP (27)
         CALLBACK_NODE: 94146554  Inst:(94146008,"luafv","\Device\HarddiskVolume2") "luafv" "135000"
However, the above mentioned debugger function returns pointers to a CALLBACK_NODE structure from which one can figure out what the actual function is. Please note that the structure contains unions and so a lot of the members actually point to the same function. It generally is pretty clear which member should be used depending on the function for which we got the CALLBACK_NODE. For this example I took the IRP_MJ_CREATE callback and the NORMALIZE_NAME_COMPONENT callback:
1: kd> dt 941462cc  fltmgr!_CALLBACK_NODE
   +0x000 CallbackLinks    : _LIST_ENTRY [ 0x93448edc - 0x9343757c ]
   +0x008 Instance         : 0x94146008 _FLT_INSTANCE
   +0x00c PreOperation     : 0x81f9f263     _FLT_PREOP_CALLBACK_STATUS  luafv!LuafvPreCreate+0
   +0x010 PostOperation    : 0x81fa24e8     _FLT_POSTOP_CALLBACK_STATUS  luafv!LuafvPostCreate+0
   +0x00c GenerateFileName : 0x81f9f263     long  luafv!LuafvPreCreate+0
   +0x00c NormalizeNameComponent : 0x81f9f263     long  luafv!LuafvPreCreate+0
   +0x00c NormalizeNameComponentEx : 0x81f9f263     long  luafv!LuafvPreCreate+0
   +0x010 NormalizeContextCleanup : 0x81fa24e8     void  luafv!LuafvPostCreate+0
   +0x014 Flags            : 0 (No matching name)
1: kd> dt 94146584  fltmgr!_CALLBACK_NODE
   +0x000 CallbackLinks    : _LIST_ENTRY [ 0x934374cc - 0x934374cc ]
   +0x008 Instance         : 0x94146008 _FLT_INSTANCE
   +0x00c PreOperation     : 0x81fa09b2     _FLT_PREOP_CALLBACK_STATUS  luafv!LuafvNormalizeNameComponentEx+0
   +0x010 PostOperation    : (null) 
   +0x00c GenerateFileName : 0x81fa09b2     long  luafv!LuafvNormalizeNameComponentEx+0
   +0x00c NormalizeNameComponent : 0x81fa09b2     long  luafv!LuafvNormalizeNameComponentEx+0
   +0x00c NormalizeNameComponentEx : 0x81fa09b2     long  luafv!LuafvNormalizeNameComponentEx+0
   +0x010 NormalizeContextCleanup : (null) 
   +0x014 Flags            : 4 ( CBNFL_USE_NAME_CALLBACK_EX )
Personally I found this approach somewhat cumbersome to use and so what I've done is to list the array of callback directly from the filter object. Please note that the array ends with a record for the IRP_MJ_OPERATION_END pseudo-operation (which is just an array terminator) which has the value of 0x80. This is actually the array of FLT_OPERATION_REGISTRATION structures that is passed to FltRegisterFilter() function in the FLT_REGISTRATION.OperationRegistration field. As such this array does not include the name generation callbacks.
: kd> dt -oca60 94144164 _FLT_OPERATION_REGISTRATION
fltmgr!_FLT_OPERATION_REGISTRATION
[0] @ 94144164 MajorFunction 0xec ''  Flags 0  PreOperation 0x81f980cc  _FLT_PREOP_CALLBACK_STATUS  luafv!LuafvPreRedirect+0  PostOperation (null)   Reserved1 (null)   
[1] @ 94144178 MajorFunction 0xed ''  Flags 0  PreOperation 0x81f980cc  _FLT_PREOP_CALLBACK_STATUS  luafv!LuafvPreRedirect+0  PostOperation (null)   Reserved1 (null)   
[2] @ 9414418c MajorFunction 0xee ''  Flags 0  PreOperation 0x81f98005  _FLT_PREOP_CALLBACK_STATUS  luafv!LuafvPreWrite+0  PostOperation (null)   Reserved1 (null)   
[3] @ 941441a0 MajorFunction 0xef ''  Flags 0  PreOperation 0x81f980cc  _FLT_PREOP_CALLBACK_STATUS  luafv!LuafvPreRedirect+0  PostOperation (null)   Reserved1 (null)   
…
[45] @ 941444e8 MajorFunction 0x19 ''  Flags 0  PreOperation 0x81f980cc  _FLT_PREOP_CALLBACK_STATUS  luafv!LuafvPreRedirect+0  PostOperation (null)   Reserved1 (null)   
[46] @ 941444fc MajorFunction 0x1a ''  Flags 0  PreOperation 0x81f980cc  _FLT_PREOP_CALLBACK_STATUS  luafv!LuafvPreRedirect+0  PostOperation (null)   Reserved1 (null)   
[47] @ 94144510 MajorFunction 0x1b ''  Flags 0  PreOperation 0x81fa3330  _FLT_PREOP_CALLBACK_STATUS  luafv!LuafvPrePnp+0  PostOperation (null)   Reserved1 (null)   
[48] @ 94144524 MajorFunction 0x80 ''  Flags 0  PreOperation (null)   PostOperation (null)   Reserved1 (null)   
...

Thursday, December 1, 2011

Name Normalization in Win8

It's interesting to note that one of the FltMgr features that a lot of minifilters use is the ability to have FltMgr generate normalized paths. This is not something trivial to implement and a lot of the code in FltMgr is dedicated to generating these names. It's also fairly expensive so FltMgr implements a name cache. However file systems don't implement any mechanism to get this information, even though looking at the Win7 WDK we can see some references that indicate that this has been in the works (search for FileNormalizedNameInformation; there are references to it both in wdm.h and ntddk.h):

typedef enum _FILE_INFORMATION_CLASS {
    FileDirectoryInformation         = 1,
    FileFullDirectoryInformation,   // 2
 ...
    FileNormalizedNameInformation,           // 48 <- this seems to be the information class one can use to request the name..
 ...
} FILE_INFORMATION_CLASS, *PFILE_INFORMATION_CLASS;

//
// This is also used for FileNormalizedNameInformation <- this indicates that the _FILE_NAME_INFORMATION structure can also be used for normalized names
//

typedef struct _FILE_NAME_INFORMATION {
    ULONG FileNameLength;
    WCHAR FileName[1];
} FILE_NAME_INFORMATION, *PFILE_NAME_INFORMATION;

Well, with the arrival of Win8 things are about to change and file systems and file system filters now have a way to query the file system directly for a normalized name. We can see some of the work that needs to happen by looking at the Win8 FastFat source, but the changes look pretty minimal. Also, there are no changes that I can see in the WDK headers from the Win7 WDK.

_Requires_lock_held_(_Global_critical_region_)    
NTSTATUS
FatCommonQueryInformation (
    IN PIRP_CONTEXT IrpContext,
    IN PIRP Irp
    )
{
...
            case FileNormalizedNameInformation:  <- FastFat will now support this request

                FatQueryNameInfo( IrpContext, Fcb, Ccb, TRUE, Buffer, &Length ); <- we can see a new boolean parameter for FatQueryNameInfo
                break;
}
...

VOID
FatQueryNameInfo (
...
    IN BOOLEAN Normalized,  <- new argument to tell FatQueryNameInfo whether it should return a normalized name or not
...
    )

/*++

Routine Description:

    This routine performs the query name information function for fat.

Arguments:

 ...
    Normalized - if true the caller wants a normalized name (w/out short names).
        This means we're servicing a FileNormalizedNameInformation query.

 ...

Return Value:

    None

--*/

{

 ...
    if (!Normalized &&
        (Fcb->LongName.Unicode.Name.Unicode.Buffer != NULL)) {

        if ((Ccb != NULL) &&
            FlagOn(Ccb->Flags, CCB_FLAG_OPENED_BY_SHORTNAME)) {

            TrimLength = Fcb->FinalNameLength;
        }
    }

 …
}

So now that we know that FastFat implements this, the next logical question is whether NTFS implements it as well and a small program I wrote confirms that it does and that it does indeed return a normalized path like one would expect.

The implications for file system developers are pretty clear, this is one more information class they need to implement and they can use FastFat as a sample of how that can be implemented. One thing I would add is that file systems might want to be extra careful about the performance of the implementation since it's likely that FltMgr's name generation and normalization code will use this information class and so it might be called pretty frequently.

Finally I'd like to talk about the implications about file system filter developers. There are a couple of scenarios that I think could be impacted by this.

  • Name providers must implement this information class. Actually all the filters that currently implement the FileNameInformation class should implement this new class as well (and if they do that they're most likely name providers.. I can't think of a case where a filter would need to implement that class and not be a name provider).
  • Filters that call FltGetFileNameInformation(..,FLT_FILE_NAME_NORMALIZED, ..) in preCreate might not see a significant performance improvement since in preCreate the file isn't opened and so FltMgr can't use this information class and while it might be able to use it for some parts of the path, a lot of the overhead is still there. So querying the normalized name in preCreate is likely to be just as bad as ever.
  • Filters that call FltGetFileNameInformation(..,FLT_FILE_NAME_NORMALIZED, ..) for open files might see some performance improvements since FltMgr should be able to leverage this information class a lot. Please note that I haven't verified that FltMgr actually does use this class, but it would make a lot of sense to use it.
  • Legacy filters would probably benefit the most from this new class but I don't expect that a lot of the legacy filters that are still around are in active development.

Thursday, November 24, 2011

Investigating an SR.sys Issue

This week I've looked at an interop issue with SR.sys and I want to share the results and the investigation. The filter I was looking at (MyFilter) is an SFO type filter which completes certain IRP_MJ_CREATEs for specific FILE_OBJECTs and then implements all the requests for them. As usual great care must be taken that none of the FILE_OBJECTs that MyFilter owns (SFOs) are ever seen below my filter (in other filters or in the file system) or those filters or the file system might think they own the FILE_OBJECTs and start walking their private structures (like the FCB or CCB) and get very confused about things and then either end with a bugcheck in the good case or data corruption in the bad case.
The problem I was investigating was exactly one of these, where somehow one of my FILE_OBJECTs ended up on the lower file system, NTFS. This is what the stack looked like:
f511ee9c f840cedc f511ef88 82035578 f511eed8 Ntfs!NtfsDecodeFileObject+0x37
f511ef10 f840b49c f511ef88 81fd5900 81cfb770 Ntfs!NtfsCommonQueryInformation+0x56
f511ef74 f840b4d5 f511ef88 81fd5900 00000001 Ntfs!NtfsFsdDispatchSwitch+0x12a
f511f098 804ef18f 81cfb770 81fd5900 81fd5900 Ntfs!NtfsFsdDispatchWait+0x1c
f511f0a8 f849852d 81d1fc10 f511f16e f511f15c nt!IopfCallDriver+0x31
f511f0d4 f849282c 81cfb770 82035578 f511f16e sr!SrQueryInformationFile+0x99
f511f100 f8492f33 00000034 82035578 f511f15c sr!SrpGetFileName+0x32
f511f270 f84936d1 81d1fc10 f511f2e0 f511f2d7 sr!SrpExpandPathOfFileName+0x19f
f511f290 f8493873 81d1fc10 823896a0 f511f2e0 sr!SrpGetFileNameFromFileObject+0xe7
f511f3f4 f848e8c2 81d1fc10 823896a0 00000000 sr!SrFileAlreadyExists+0x5f
f511f44c 804ef18f 81d1fc10 00000002 82130c98 sr!SrCreate+0x19c
f511f45c f84ab6c3 823896a0 82130ca8 823ca2e0 nt!IopfCallDriver+0x31
f511f48c 804ef18f 81e32020 82130c98 82130c98 fltMgr!FltpCreate+0x1d9
f511f49c 805831fa 81ccdb68 81fddfd4 f511f634 nt!IopfCallDriver+0x31
f511f57c 805bf444 81ccdb80 00000000 81fddf30 nt!IopParseDevice+0xa12
f511f5f4 805bb9d0 00000000 f511f634 00000640 nt!ObpLookupObjectName+0x53c
f511f648 80576033 00000000 00000000 36039c00 nt!ObOpenObjectByName+0xea
f511f6c4 80576a20 f511f848 00100002 f511f850 nt!IopCreateFile+0x407
f511f70c f84ad5b9 f511f848 00100002 f511f850 nt!IoCreateFileSpecifyDeviceObjectHint+0x52
f511f7b8 f84ada28 81d2d2d0 81d31008 f511f848 fltMgr!FltCreateFileEx+0x113
f511f7fc f500ea00 81d2d2d0 81d31008 f511f848 fltMgr!FltCreateFile+0x36
f511f868 f500ec87 81fc0994 81d31008 00000000 myfilter!MyCreateFile+0x100
Looking at the stack one thing looks really strange: FltMgr is calling into SR which is calling into NTFS. This indicates that SR is somehow loaded between FltMgr and NTFS. So I decided to see that the file system stack looks like:
1: kd> !fltkd.volumes

Volume List: 820210a0 "Frame 0" 
   FLT_VOLUME: 820ad668 "\Device\WebDavRedirector"
   FLT_VOLUME: 81d01168 "\Device\LanmanRedirector"
   FLT_VOLUME: 82005b48 "\Device\HGFS"
   FLT_VOLUME: 81ccbc18 "\Device\VhdDisk00000003"
      FLT_INSTANCE: 81d31008 "MyFilter Default Instance" "137000"
   FLT_VOLUME: 81d01c18 "\Device\VhdDisk00000002"
   FLT_VOLUME: 81cc8c18 "\Device\VhdDisk00000001"
   FLT_VOLUME: 8207fbd8 "\Device\HarddiskDmVolumes\PhysicalDmVolumes\BlockVolume1"
   FLT_VOLUME: 81e9a8a0 "\Device\HarddiskVolume2"
   FLT_VOLUME: 81d2e008 "\Device\HarddiskVolume1"
1: kd> !fltkd.volume 81ccbc18 

FLT_VOLUME: 81ccbc18 "\Device\VhdDisk00000003"
   FLT_OBJECT: 81ccbc18  [04000000] Volume
      RundownRef               : 0x00000004 (2)
      PointerCount             : 0x00000001 
      PrimaryLink              : [81d01c24-82005b54] 
   Frame                    : 82021000 "Frame 0" 
   Flags                    : [00000004] SetupNotifyCalled
   FileSystemType           : [00000002] FLT_FSTYPE_NTFS
   VolumeLink               : [81d01c24-82005b54] 
   DeviceObject             : 81e32020 
   DiskDeviceObject         : 81ccdb80 
   VolumeInNextFrame        : 00000000 
   Guid                     : "" 
   CDODeviceName            : "\Ntfs" 
   CDODriverName            : "\FileSystem\Ntfs" 
   Callbacks                : (81ccbca8)
   ContextLock              : (81ccbe38)
   VolumeContexts           : (81ccbe70)  Count=0
   StreamListCtrls          : (81ccbe74)  rCount=56 
   NameCacheCtrl            : (81ccbeb8)
   InstanceList             : (81ccbc64)
      FLT_INSTANCE: 81d31008 "MyFilter Default Instance" "137000"
1: kd> !devstack 81e32020 
  !DevObj   !DrvObj            !DevExt   ObjectName
> 81e32020  \FileSystem\FltMgr 81e320d8  
  81d1fb58  \FileSystem\sr     81d1fc10  
  81cfb770  \FileSystem\Ntfs   81cfb828 
So as you can see SR is indeed loaded between NTFS and FltMgr's frame0. As I mentioned in my post on how the file system stack is layered, in XP FltMgr doesn't create frame0 immediately and instead it waits for the first minifilter to register before it creates it. Since on my system there is no other minifilter FltMgr never created frame0 until I manually loaded my filter. However, since SR is a boot start driver by the time FltMgr initialized frame0 SR was already attached and FltMgr had no option but to attach on top of it.
Now, the FILE_OBJECT that NTFS chokes on is 82035578 and it is indeed an SFO. Looking on the stack we can see that it first appears when SR calls SrpGetFileName. There were two possibilities. Either I had leaked my SFO below my filter (either in this operation or at some point in the past) and SR got it and was using it or SR got their own FILE_OBJECT from my filter by issuing a request above my filter (most likely to the top of the stack). So I decided to see what the function that calls SrpGetFileName does (the function is rather long so I trimmed it a bit but it's still quite long so i tried to highlight things):
1: kd> uf sr!SrpExpandPathOfFileName
sr!SrpExpandPathOfFileName:
f8492d94 8bff            mov     edi,edi
f8492d96 55              push    ebp
…
f8492e3a 56              push    esi
f8492e3b 6800080000      push    800h
f8492e40 56              push    esi
f8492e41 56              push    esi
f8492e42 8385d4feffff02  add     dword ptr [ebp-12Ch],2
f8492e49 56              push    esi
f8492e4a 56              push    esi
f8492e4b 6821400000      push    4021h
f8492e50 6a01            push    1
f8492e52 6a03            push    3
f8492e54 6880000000      push    80h
f8492e59 56              push    esi
f8492e5a 8d85b0feffff    lea     eax,[ebp-150h]
f8492e60 50              push    eax
f8492e61 8d85b8feffff    lea     eax,[ebp-148h]
f8492e67 50              push    eax
f8492e68 6800001000      push    100000h
f8492e6d 8d85d8feffff    lea     eax,[ebp-128h]
f8492e73 50              push    eax
f8492e74 c785b8feffff18000000 mov dword ptr [ebp-148h],18h
f8492e7e 89b5bcfeffff    mov     dword ptr [ebp-144h],esi
f8492e84 c785c4feffff00020000 mov dword ptr [ebp-13Ch],200h
f8492e8e 899dc0feffff    mov     dword ptr [ebp-140h],ebx
f8492e94 89b5c8feffff    mov     dword ptr [ebp-138h],esi
f8492e9a 89b5ccfeffff    mov     dword ptr [ebp-134h],esi
f8492ea0 e8296bffff      call    sr!IoCreateFileSpecifyDeviceObjectHint (f84899ce)
f8492ea5 3bc6            cmp     eax,esi
f8492ea7 8985e8feffff    mov     dword ptr [ebp-118h],eax
f8492ead 7d08            jge     sr!SrpExpandPathOfFileName+0x123 (f8492eb7)

sr!SrpExpandPathOfFileName+0x11b:
f8492eaf c60701          mov     byte ptr [edi],1
f8492eb2 e9c0010000      jmp     sr!SrpExpandPathOfFileName+0x2e3 (f8493077)

sr!SrpExpandPathOfFileName+0x123:
f8492eb7 56              push    esi
f8492eb8 8d85dcfeffff    lea     eax,[ebp-124h]
f8492ebe 50              push    eax
f8492ebf a1389b48f8      mov     eax,dword ptr [sr!_imp__IoFileObjectType (f8489b38)]
f8492ec4 56              push    esi
f8492ec5 ff30            push    dword ptr [eax]
f8492ec7 56              push    esi
f8492ec8 ffb5d8feffff    push    dword ptr [ebp-128h]
f8492ece ff15349b48f8    call    dword ptr [sr!_imp__ObReferenceObjectByHandle (f8489b34)]
f8492ed4 3bc6            cmp     eax,esi
f8492ed6 8985e8feffff    mov     dword ptr [ebp-118h],eax
f8492edc 0f8c95010000    jl      sr!SrpExpandPathOfFileName+0x2e3 (f8493077)

sr!SrpExpandPathOfFileName+0x14e:
f8492ee2 8b85e0feffff    mov     eax,dword ptr [ebp-120h]
f8492ee8 ff7048          push    dword ptr [eax+48h]
f8492eeb ff15149c48f8    call    dword ptr [sr!_imp__IoGetAttachedDevice (f8489c14)]
f8492ef1 ffb5dcfeffff    push    dword ptr [ebp-124h]
f8492ef7 8bf8            mov     edi,eax
f8492ef9 ff15309b48f8    call    dword ptr [sr!_imp__IoGetRelatedDeviceObject (f8489b30)]
f8492eff 3bc7            cmp     eax,edi
f8492f01 7418            je      sr!SrpExpandPathOfFileName+0x187 (f8492f1b)

sr!SrpExpandPathOfFileName+0x16f:
f8492f03 8b85d0feffff    mov     eax,dword ptr [ebp-130h]
f8492f09 c785e8feffffd40000c0 mov dword ptr [ebp-118h],0C00000D4h
f8492f13 c60001          mov     byte ptr [eax],1
f8492f16 e95c010000      jmp     sr!SrpExpandPathOfFileName+0x2e3 (f8493077)

sr!SrpExpandPathOfFileName+0x187:
f8492f1b 8d85ecfeffff    lea     eax,[ebp-114h]
f8492f21 50              push    eax
f8492f22 ffb5dcfeffff    push    dword ptr [ebp-124h]
f8492f28 ffb5e0feffff    push    dword ptr [ebp-120h]
f8492f2e e8c7f8ffff      call    sr!SrpGetFileName (f84927fa)
…
So looking at the function we can see that SR is calling IoCreateFileSpecifyDeviceObjectHint and then gets the FILE_OBJECT associated with the handle it has (by calling ObReferenceObjectByHandle). From this call we can infer that the handle is stored in the local variable @ebp-128h and that the FILE_OBJECT is stored in the variable @ebp-124h. Then SR compares the device of the FILE_OBJECT with the device it is attached to and if they don't match it fails with status 0C00000D4h (STATUS_NOT_SAME_DEVICE; also please note that the status gets put into @ebp-118h). Then the function calls SrpGetFileName with the FILE_OBJECT it got from the call to IoCreateFileSpecifyDeviceObjectHint. Since all these are stored in local variables we can get the value of EBP for that function from the ChildEBP column (0xf511f270) and see which FILE_OBJECT they got:
1: kd> !error 0C00000D4h
Error code: (NTSTATUS) 0xc00000d4 (3221225684) - {Incorrect Volume}  The target file of a rename request is located on a different device than the source of the rename request.
1: kd> dp f511f270-0x128
f511f148  800005f4 82035578 81d1fc10 0000001e
f511f158  00000000 00fe0000 f511f16e 000000fe
f511f168  00000000 01000000 f511f0a8 f511f858
f511f178  f511f32c f83ea75b e113f858 ffffffff
f511f188  f83e5b5c e1cbada0 f511f858 81de4290
f511f198  00000000 00000000 f511f118 f511f1bc
f511f1a8  f511f32c f83ea75b f511f1c8 f511f2dc
f511f1b8  804e1ec4 f511f1fc f511f1d8 81cfb850
1: kd> !handle 800005f4 

PROCESS 81f43020  SessionId: 0  Cid: 0714    Peb: 7ffde000  ParentCid: 03ec
    DirBase: 02b40320  ObjectTable: e1518008  HandleCount:  32.
    Image: ifstest.exe

Kernel handle table at e1004000 with 345 entries in use

800005f4: Object: 82035578  GrantedAccess: 00100000 Entry: e1004be8
Object: 82035578  Type: (823aead0) File
    ObjectHeader: 82035560 (old version)
        HandleCount: 1  PointerCount: 2
        Directory Object: 00000000  Name: \opcreatg\ {VhdDisk00000003}
So as we can see SR actually got one my SFOs by sending a create to the top of the stack and then sent it directly to NTFS in a query. This was puzzling because SR is actually using IoCreateFileSpecifyDeviceObjectHint which is exactly what I expected it would use to target the IRP_MJ_CREATE appropriately. However, when looking at the call we can see that the DeviceObject member is passed in as "push esi" and it's hard to track exactly what a given register's value was at the time of the call without carefully analyzing the code. In this case however it seems we got lucky because a lot of other parameters are set up using the "push esi" instruction which means that either SR called IoCreateFileSpecifyDeviceObjectHint with a lot of the parameters set to the DEVICE_OBJECT or that it passed in NULL for the DEVICE_OBJECT. Looking at where ESI is initialized (which is not in the chunk of code I pasted here) we can see that indeed ESI is set to 0 and so now we know what is going on:
  1. SR calls IoCreateFileSpecifyDeviceObjectHint and sends a request to the top of the stack.
  2. SR takes the handle and resolves it to a FILE_OBJECT
  3. SR compares the DEVICE_OBJECT for the FILE_OBJECT it just got with the DEVICE_OBJECT it is attached to and if they are different it fails with STATUS_NOT_SAME_DEVICE.
  4. Finally SR uses the FILE_OBJECT in a call that is targeted below itself and thus my SFO reaches NTFS.
I'm not exactly sure why SR does this. It looks like the code was written so that it used IoCreateFileSpecifyDeviceObjectHint but then the DeviceObject was passed in as NULL which effectively changes it to IoCreateFile. But then the code itself checks whether the device for the FILE_OBJECT it gets is the same as the one it's attached on, which is something IoCreateFileSpecifyDeviceObjectHint would have done if used with a DeviceObject parameter. Anyway the problem is that SR sent requests to two different points on the stack, the IRP_MJ_CREATE to the top of the stack and then subsequent requests below itself on the stack and thus it runs into trouble when things change between the top of the stack and the altitude where SR is located. Had SR sent the IRP_MJ_CREATE below itself (which is the right behavior from a layering perspective) or the subsequent requests to the top of the stack (which is actually still wrong because it could lead to infinite loops and such) then it would have avoided this problem.