Thursday, May 17, 2012

More Fun with FileIDs: Boot Critical Files

As you might have guessed from my previous posts, I'm actively working on a file system filter that uses FileIDs to open files. As it happens this isn't something most developers do so I occasionally find myself in some dark corner of the file system that I had no idea existed. Today's post is about a debugging session where I ran into one of these corners.
This all started when I was testing my filter on Server 2008 R2. I have tested it extensively on Win7 AMD64 and since Srv08R2 is pretty much identical in terms of the kernel and file system code I didn't expect I'd run into any issues. However, to my surprise, the machine wouldn't boot, crashing with the following bugcheck (edited a couple of lines here and there to make the output smaller, and highlighted the important bits):
kd> !analyze -v
*******************************************************************************
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
*******************************************************************************

NTFS_FILE_SYSTEM (24)
    If you see NtfsExceptionFilter on the stack then the 2nd and 3rd
    parameters are the exception record and context record. Do a .cxr
    on the 3rd parameter and then kb to obtain a more informative stack
    trace.
Arguments:
Arg1: 00000000001904fb
Arg2: fffff880009903b8
Arg3: fffff8800098fc10
Arg4: fffff880017504cf

Debugging Details:
------------------

ExceptionAddress: fffff880017504cf (Ntfs! ?? ::NNGAKEGL::`string'+0x0000000000013040)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 0000000000000000
   Parameter[1]: 0000000000000070
Attempt to read from address 0000000000000070

CONTEXT:  fffff8800098fc10 -- (.cxr 0xfffff8800098fc10)
rax=fffff8a000aaa5e0 rbx=fffff8a000aaa940 rcx=0000000000000000
rdx=fffff88000990501 rsi=0000000000000000 rdi=0000000000000000
rip=fffff880017504cf rsp=fffff880009905f0 rbp=fffff88000990800
 r8=0000000000000000  r9=0000000000000000 r10=0000000000000000
r11=fffff880009905d0 r12=0000000000000000 r13=fffff8a000aaa501
r14=fffffa800e044500 r15=fffff8a000aaa760
iopl=0         nv up ei pl nz na pe nc
cs=0010  ss=0018  ds=002b  es=002b  fs=0053  gs=002b             efl=00010202
Ntfs! ?? ::NNGAKEGL::`string'+0x13040:
fffff880`017504cf 488b5770        mov     rdx,qword ptr [rdi+70h] ds:002b:00000000`00000070=????????????????
Resetting default scope

PROCESS_NAME:  lsass.exe

CURRENT_IRQL:  2

ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_PARAMETER1:  0000000000000000

EXCEPTION_PARAMETER2:  0000000000000070

READ_ADDRESS:  0000000000000070 

FOLLOWUP_IP: 
Ntfs! ?? ::NNGAKEGL::`string'+13040
fffff880`017504cf 488b5770        mov     rdx,qword ptr [rdi+70h]

FAULTING_IP: 
Ntfs! ?? ::NNGAKEGL::`string'+13040
fffff880`017504cf 488b5770        mov     rdx,qword ptr [rdi+70h]

BUGCHECK_STR:  0x24

DEFAULT_BUCKET_ID:  NULL_CLASS_PTR_DEREFERENCE

LAST_CONTROL_TRANSFER:  from fffff880016d8f46 to fffff880017504cf

STACK_TEXT:  
fffff880`009905f0 fffff880`016d8f46 : fffffa80`0e044500 00000000`00000000 00000000`00000000 00000000`00000001 : Ntfs! ?? ::NNGAKEGL::`string'+0x13040
fffff880`00990660 fffff880`016d96b4 : fffffa80`0e044500 fffffa80`0e6febb0 fffffa80`0d6d1420 00000000`00000000 : Ntfs!NtfsCommonFlushBuffers+0x3f2
fffff880`00990740 fffff880`00c02bcf : fffffa80`0e6fee78 fffffa80`0e6febb0 fffffa80`0e044500 fffff880`00990768 : Ntfs!NtfsFsdFlushBuffers+0x104
fffff880`009907b0 fffff880`00c016df : fffffa80`0d27d730 00000000`00000000 fffffa80`0d27d700 fffffa80`0e6febb0 : fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x24f
fffff880`00990840 fffff800`019e171b : 00000000`00000002 fffffa80`0d6cf640 00000000`00000000 fffffa80`0e6febb0 : fltmgr!FltpDispatch+0xcf
fffff880`009908a0 fffff800`01978871 : fffffa80`0e6febb0 fffffa80`0e54b6a0 fffffa80`0d6cf640 fffff800`0184be80 : nt!IopSynchronousServiceTail+0xfb
fffff880`00990910 fffff800`016d88d3 : fffffa80`0e54b6a0 fffff8a0`016edeb0 fffffa80`0d27d730 fffffa80`0d6cf640 : nt!NtFlushBuffersFile+0x171
fffff880`009909a0 fffff800`016d4e70 : fffff800`01979627 00000000`00000010 00000000`ffffffff 00000000`00000001 : nt!KiSystemServiceCopyEnd+0x13
fffff880`00990b38 fffff800`01979627 : 00000000`00000010 00000000`ffffffff 00000000`00000001 00000000`00000000 : nt!KiServiceLinkage
fffff880`00990b40 fffff800`019797a7 : 00000000`0000001e fffff880`00990bd0 00000000`00b1e801 fffff800`0000001f : nt!CmpFileFlush+0x3f
fffff880`00990b80 fffff800`016d88d3 : fffffa80`0e54b6a0 fffff8a0`016edeb0 fffff880`00990ca0 00000000`00c17120 : nt!NtFlushKey+0xfb
fffff880`00990c20 00000000`770a1f7a : 000007fe`fcbf3b76 00000000`00000000 00000000`00c17120 00000000`00c17120 : nt!KiSystemServiceCopyEnd+0x13
00000000`00b1eba8 000007fe`fcbf3b76 : 00000000`00000000 00000000`00c17120 00000000`00c17120 00000000`00000000 : ntdll!ZwFlushKey+0xa
00000000`00b1ebb0 000007fe`fe7323d5 : 00000000`00c17101 000007fe`00000000 00000000`00000001 00000000`00b1eea0 : SAMSRV!SamrCloseHandle+0xf6
00000000`00b1ec00 000007fe`fe7db68e : 00000000`00000002 00000000`00000001 000007fe`fcc80220 00000000`00c20c30 : RPCRT4!Invoke+0x65
00000000`00b1ec50 000007fe`fe71ac40 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000001 : RPCRT4!Ndr64StubWorker+0x61b
00000000`00b1f210 000007fe`fe7250f4 : 230100ef`00000001 00000000`ac896745 00002f00`e3236899 00000000`00000001 : RPCRT4!NdrServerCallAll+0x40
00000000`00b1f260 000007fe`fe724f56 : 00000000`00c20ad0 00000000`00000018 00000000`00b1f410 00000000`00c1b330 : RPCRT4!DispatchToStubInCNoAvrf+0x14
00000000`00b1f290 000007fe`fe71d879 : 00000000`00bda928 000007fe`fe72db94 00000000`00000001 00000000`00000001 : RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0x146
00000000`00b1f3b0 000007fe`fe71d6de : 00000000`00c20ad0 00000000`00c20ad0 00000000`00000003 00000000`00000000 : RPCRT4!OSF_SCALL::DispatchHelper+0x159
00000000`00b1f4d0 000007fe`fe71d4f9 : 00000000`00000014 00000000`00000000 00000000`00c1a2d0 00000000`00c20ad0 : RPCRT4!OSF_SCALL::ProcessReceivedPDU+0x18e
00000000`00b1f540 000007fe`fe71d023 : 00000000`00c20a18 00000000`00c20a70 00000000`00000000 00000000`00000000 : RPCRT4!OSF_SCONNECTION::ProcessReceiveComplete+0x3e9
00000000`00b1f5f0 000007fe`fe71d103 : 00000000`00bda850 00000000`00b1f9c0 00000000`00c20a18 00000000`00b1f8d8 : RPCRT4!CO_ConnectionThreadPoolCallback+0x123
00000000`00b1f6a0 000007fe`fd1c908f : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : RPCRT4!CO_NmpThreadPoolCallback+0x3f
00000000`00b1f6e0 00000000`7706098a : 00000000`00485840 00000000`00000000 00000000`77154da0 00000000`77070043 : KERNELBASE!BasepTpIoCallback+0x4b
00000000`00b1f720 00000000`7706feff : 00000000`00000002 00000000`00000000 00000000`00c20a70 00000000`00b1f9c0 : ntdll!TppIopExecuteCallback+0x1ff
00000000`00b1f7d0 00000000`76e4652d : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!TppWorkerThread+0x3f8
00000000`00b1fad0 00000000`7707c521 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
00000000`00b1fb00 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d
So as you can see, this was an access violation in NTFS, in some function that the debugger couldn't resolve properly (hence the weird Ntfs! ?? ::NNGAKEGL::`string'+0x13040 name). The stack shows how this happens when a registry key is flushed as a result of closing a handle, and the registry eventually ends up flushing the actual hive file which makes it to NTFS where it bugchecks.
The first thing to do is to try to figure out what the function is that NTFS actually bugchecks in:
kd> ub Ntfs!NtfsCommonFlushBuffers+0x3f2
Ntfs!NtfsCommonFlushBuffers+0x3c7:
fffff880`016d8f1b 488b4348        mov     rax,qword ptr [rbx+48h]
fffff880`016d8f1f 488b4818        mov     rcx,qword ptr [rax+18h]
fffff880`016d8f23 48898c24f8000000 mov     qword ptr [rsp+0F8h],rcx
fffff880`016d8f2b 8b051389fdff    mov     eax,dword ptr [Ntfs!NtfsDebugDiskFlush (fffff880`016b1844)]
fffff880`016d8f31 4c8b8424f8000000 mov     r8,qword ptr [rsp+0F8h]
fffff880`016d8f39 488b542468      mov     rdx,qword ptr [rsp+68h]
fffff880`016d8f3e 498bcc          mov     rcx,r12
fffff880`016d8f41 e84efaffff      call    Ntfs!NtfsFlushBootCritical (fffff880`016d8994)
So NtfsCommonFlushBuffers calls NtfsFlushBootCritical, which then jumps around a bit and, due to pretty aggressive optimizations, ends up in a location that the debugger doesn't have a name for, hence the "Ntfs! ?? ::NNGAKEGL::`string'+0x13040" name.
Anyway, next step in this case is to try to find the FILE_OBJECT and see if it's somehow damaged or something. I also generally like to find the IRP and, since I'm working on minifilter, I also like to get the FLT_CALLBACK_DATA structure. This isn't too bad in most cases but it's a pain on amd64 systems because the calling convention makes sure the IRP_CTRL (the parent structure for the FLT_CALLBACK_DATA) isn't passed as a parameter on the stack. Also, since FltMgr implements a callback model it means that while my filter was definitely involved in processing this IO, my callback functions (for which I have symbols and I could get local variables and such) have already returned and can't be found on this stack. So the easiest thing to do in this case is to try to find the IRP_CALL_CTRL structure (see these posts for more details on what that is and how to get it: Debugging Minifilters: Finding the FLT_CALLBACK_DATA - Part I and Debugging Minifilters: Finding the FLT_CALLBACK_DATA - Part II).
kd> dp fffff880`00990840
fffff880`00990840  fffffa80`0d27d730 00000000`00000000
fffff880`00990850  fffffa80`0d27d700 fffffa80`0e6febb0
fffff880`00990860  fffffa80`0d3875a0 fffffa80`0e6febb0
fffff880`00990870  fffffa80`0e8c7790 ffffffff`ffffffff
fffff880`00990880  00000000`00000000 fffffa80`00000204
fffff880`00990890  fffffa80`0e6febb0 fffff800`019e171b
fffff880`009908a0  00000000`00000002 fffffa80`0d6cf640
fffff880`009908b0  00000000`00000000 fffffa80`0e6febb0
kd> dt fffff880`00990840+0x20 fltmgr!_IRP_CALL_CTRL
   +0x000 Volume           : 0xfffffa80`0d3875a0 _FLT_VOLUME
   +0x008 Irp              : 0xfffffa80`0e6febb0 _IRP
   +0x010 IrpCtrl          : 0xfffffa80`0e8c7790 _IRP_CTRL
   +0x018 StartingCallbackNode : 0xffffffff`ffffffff _CALLBACK_NODE
   +0x020 OperationStatusCallbackListHead : _SINGLE_LIST_ENTRY
   +0x028 Flags            : 0x204 (No matching name)
kd> !fltkd.cbd 0xfffffa80`0e8c7790

IRP_CTRL: fffffa800e8c7790  FLUSH_BUFFERS (9) [00000001] Irp
Flags                    : [10000000] FixedAlloc
Irp                      : fffffa800e6febb0 
DeviceObject             : fffffa800d27d730 "\Device\HarddiskVolume1"
FileObject               : fffffa800d6d1420 
CompletionNodeStack      : fffffa800e8c78e0   Size=5  Next=1
SyncEvent                : (fffffa800e8c77a8)
InitiatingInstance       : 0000000000000000 
Icc                      : fffff88000990860 
PendingCallbackNode      : ffffffffffffffff 
PendingCallbackContext   : 0000000000000000 
PendingStatus            : 0x00000000 
CallbackData             : (fffffa800e8c7840)
 Flags                    : [00000001] Irp
 Thread                   : fffffa800e54b6a0 
 Iopb                     : fffffa800e8c7898 
 RequestorMode            : [00] KernelMode
 IoStatus.Status          : 0x00000000 
 IoStatus.Information     : 0000000000000000 
 TagData                  : 0000000000000000 
 FilterContext[0]         : 0000000000000000 
 FilterContext[1]         : 0000000000000000 
 FilterContext[2]         : 0000000000000000 
 FilterContext[3]         : 0000000000000000 

   Cmd     IrpFl   OpFl  CmpFl  Instance FileObjt Completion-Context  Node Adr
--------- -------- ----- -----  -------- -------- ------------------  --------
 [0,0]    00000000  00   0000   0000000000000000 0000000000000000 0000000000000000-0000000000000000   fffffa800e8c7ae0
     Args: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000
 [0,0]    00000000  00   0000   0000000000000000 0000000000000000 0000000000000000-0000000000000000   fffffa800e8c7a60
     Args: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000
 [0,0]    00000000  00   0000   0000000000000000 0000000000000000 0000000000000000-0000000000000000   fffffa800e8c79e0
     Args: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000
 [0,0]    00000000  00   0000   0000000000000000 0000000000000000 0000000000000000-0000000000000000   fffffa800e8c7960
     Args: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000
 [9,0]    00060004  00   0002   fffffa800d43d610 fffffa800d6cf640 fffff880014ecea0-0000000000000000   fffffa800e8c78e0
            ("ivm","IVM")  ivm!IvmFSPostOpDispatch 
     Args: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000
Working IOPB:
>[9,0]    00060004  00          fffffa800e73e010 fffffa800d6d1420                     fffffa800e8c7898
            ("luafv","luafv")  
     Args: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000
So now that I have the FLT_CALLBACK_DATA I need to get the FILE_OBJECT. Please note that the FILE_OBJECT changes between the parameters my filter gets and the ones FltMgr is using now (after my filter was called), which make sense since I replace the FILE_OBJECT in the callback. So let's see what that FILE_OBJECT looks like and what the file is:
kd> !fileobj fffffa800d6d1420

掃

Related File Object: 0xfffffa800d43d460

Device Object: 0xfffffa800d301cd0   \Driver\volmgr
Vpb: 0xfffffa800cee62f0
Event signalled
Access: Read Write 

Flags:  0x140008
 No Intermediate Buffering
 Handle Created
 Random Access

FsContext: 0xfffff8a000aaa6f0 FsContext2: 0xfffff8a000aaa940
CurrentByteOffset: 0
Cache Data:
  Section Object Pointers: fffffa800d6d3af8
  Shared Cache Map: 00000000


File object extension is at fffffa800d41b780:

As you have undoubtedly noticed, the file name is actually pretty strange (and in case you can read that character, one could possibly associate sweeping with flushing a file, but it's a bit of a stretch :)) . Whenever I see a filename that looks like one or a couple of characters that don't belong I suspect that that file was opened by ID (and in this case I actually know my filter does this so I was sort of expecting it anyway). A very important thing to check at this point is that the FILE_OBJECT is actually an NTFS FILE_OBJECT and I'm not somehow leaking FILE_OBJECTs from my filter into the file system. The easiest way to check is to look at the tags for the buffers in FsContext and FsContext2, since the owner of the FILE_OBJECT allocates those:
kd> !pool 0xfffff8a000aaa6f0 2
Pool page fffff8a000aaa6f0 region is Paged pool
*fffff8a000aaa5b0 size:  580 previous size:   80  (Allocated) *NtfF
  Pooltag NtfF : FCB_INDEX, Binary : ntfs.sys
kd> !pool 0xfffff8a000aaa940 2
Pool page fffff8a000aaa940 region is Paged pool
*fffff8a000aaa5b0 size:  580 previous size:   80  (Allocated) *NtfF
  Pooltag NtfF : FCB_INDEX, Binary : ntfs.sys
One final thing to check is that the actual file name is a file ID. This is pretty complicated to do since a fileID can look almost like anything. The easiest way to do this is to use a VM (so that it's easy to snap back to the same OS at an earlier point) and look at what the file system looks like without the filter installed and use fsutil.exe to resolve the FileID to a name:
kd> dt fffffa800d6d1420 nt!_FILE_OBJECT FileName.
   +0x058 FileName  :  "掃"
      +0x000 Length    : 8
      +0x002 MaximumLength : 0x38
      +0x008 Buffer    : 0xfffff8a0`00aed860  "掃"
kd> dp 0xfffff8a0`00aed860 L1
fffff8a0`00aed860  00010000`00006383
So anyway, this does look like a file ID and it actually was the fileID for the file "\Windows\System32\Config\SYSTEM", which is the system hive. This was pretty confusing because I was expecting I was doing something obviously wrong (like pass the wrong FILE_OBJECT down the stack) and yet I couldn't see anything broken here. So I decided to see what's actually going on in NTFS.
I spent some time looking at the disassembly for NtfsFlushBootCritical but like most NTFS code it's packed with structures I have no idea about. In these cases it's easier to walk through the code in the debugger to see what the structures look like (and the pool tags they use) to try to figure out what they might be. However, NtfsFlushBootCritical doesn't actually get called at all for (almost) any other file. So at this point I was pretty puzzled because it meant NTFS somehow knew that the system hive was a "boot critical" file, unlike any other file on the file system (since that function was never called again). I didn't know that NTFS did special things for files that are deemed boot critical (since NTFS is generally pretty uniform in how it does things, it's rare to see it do something special for a certain windows process) and I had no idea what those files were.
Anyway, as it turned out NtfsFlushBootCritical was called for the system hive even when my driver wasn't there so I could debug it in more detail. After walking through it a couple of times it became obvious that it was walking a list of SCBs, starting from the file I had. The SCB when my filter was present was NULL and then NTFS tried to access a member of the SCB, resulting in a NULL pointer dereference.
Now, I'd like to point out that NTFS keeps a pointer to the parent SCB for each SCB. So the SCB for the file "\Windows\System32\Config\SYSTEM" has a pointer to the SCB for the folder "\Windows\System32\Config", which in turn has a pointer to the SCB for its parent folder, "\Windows\System32" and so on. However this doesn't always happen for files that are opened by ID, because there is no path traversal necessary in order to open the file (NTFS can use the fileID as the index and immediately find the file) and it doesn't make much sense for NTFS to populate the SCB if it's not necessary.
So, obviously, the issue here is that when opening the file \Windows\System32\Config\SYSTEM by ID the pointer to the folder SCB wasn't initialized when NTFS expected it would be and so it ended up dereferencing a NULL pointer.
What puzzled me about this is that this never happened on Win7. So I debugged my code on that platform and guess what, in Win7 the link is actually initialized even when the file is opened by fileID. As it turns out, NTFS will not populate the pointer to the parent SCB if it doesn't have to, but if someone asks for the file name (a filter calling FltGetFileNameInformation() for example) then it will walk the list and build the path and then the SCB pointer will be initialized. This is exactly what happens on Win7 because there are other filters (FileInfo, Luafv) that query names, but on Srv08R2 they're not present (or at least not enabled) and so this doesn't happen.
Now the final bit of mystery was how did NTFS know that "\Windows\System32\Config\SYSTEM" should be handled in a special way. What was it that made it a boot critical file ? Well, as it turns out, there is an FSCTL, FSCTL_SET_BOOTLOADER_ACCESSED, which serves this purpose. When NTFS receives this for a FILE_OBJECT it sets an internal flag and then when an IRP_MJ_FLUSH_BUFFERS arrives on the same handle NTFS will flush not only that file but all the folders that make up the path to that file (which is all handled in NtfsFlushBootCritical).