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:
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.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)
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).
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> 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
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> !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:
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> !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
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.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
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).
Posts
No comments:
Post a Comment