Help debugging crash in KeWaitForSingleObject

Sorry for the length of this post, always hard to decide how much info is too-much vs. too-little…

I’ve recently had to revamp a FS mini-filter driver that redirects NTFS file I/O from one volume/drive (I’ll call the “primary” drive) to another volume/drive (I’ll call the “secondary” drive).

Originally we were just fixing up the path/filename and returning STATUS_REPARSE during IRP_MJ_CREATE to do the trick and save us alot of headache. This works nicely for the case when both primary and secondary are local drives (C:, D:, etc).

However in the case when the secondary drive is remote (i.e. \remoteserver\share.…), STATUS_REPARSE doesn’t work and we’ve had to move to a more complex shadow/proxy file object architecture, where now the mini-filter takes ownership of and manages some file objects that NTFS would normally handle. Any I/O to these shadow file objects the filter then redirects over to the “real” file of the same name on the remote server.

After much trial & error and pain & suffering we’ve managed to get things working well enough to do some stress testing. Now on one of our test servers we are consistently getting a BSOD that is proving a little tricky to dissect and determine exactly what the filter is doing wrong.

I’m almost certain it has to do with the filter not completely managing proxy/shadow file objects correctly and not doing something that the I/O subsystem is expecting us to do. But it’s hard to know exactly what since when the crash occurs our filter doesn’t show up in the call stack (although one of our proxy file objects does).

Although the call stacks vary from crash to crash, the cause of the crash is always at the same line of code in KeWaitForSingleObject (KeWaitForSingleObject + 17c to be exact, running Windows 2008 R2 x64), mov qword ptr [rax], r15. But rax is 0, thus the crash.

From what I can tell, it appears one of the filter proxy file objects is being passed to KeWaitForSingleObject, which is assuming that the fileObject->Lock Link fields are non-NULL, but in this case that’s not true so we ge the NULL memory reference and crash.

The MSDN Lib description of FILE_OBJECT fields doesn’t reveal much. Regarding Lock field it just says field is opaque and “used by the system”, but doesn’t really say exactly who is responsible for setting it up.

I’ve included stack trace and other useful info from the crash dump below. I also include a code snippet showing exactly what we do during IRP_MJ_CREATE when we take ownership of the shadow file object and how we are setting up the fields.

Any help/ideas are greatly appreciated. It’s really tough to find any information anywhere describing how to properly manage shadow/proxy file objects in a filter.

From the crash dump…

BugCheck A, {0, 2, 1, fffff8000168688c}

Probably caused by : srv.sys ( srv!QueryPathOrFileInformation+ca )

Followup: MachineOwner

kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

IRQL_NOT_LESS_OR_EQUAL (a)
An attempt was made to access a pageable (or completely invalid) address at an
interrupt request level (IRQL) that is too high. This is usually
caused by drivers using improper addresses.
If a kernel debugger is available get the stack backtrace.
Arguments:
Arg1: 0000000000000000, memory referenced
Arg2: 0000000000000002, IRQL
Arg3: 0000000000000001, bitfield :
bit 0 : value 0 = read operation, 1 = write operation
bit 3 : value 0 = not an execute operation, 1 = execute operation (only on chips which support this level of status)
Arg4: fffff8000168688c, address which referenced memory

Debugging Details:

WRITE_ADDRESS: 0000000000000000

CURRENT_IRQL: 2

FAULTING_IP:
nt!KeWaitForSingleObject+17c
fffff800`0168688c 4c8938 mov qword ptr [rax],r15

DEFAULT_BUCKET_ID: VISTA_DRIVER_FAULT

BUGCHECK_STR: 0xA

PROCESS_NAME: System

TRAP_FRAME: fffff88005167610 – (.trap 0xfffff88005167610)
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed or incorrect.
rax=0000000000000000 rbx=0000000000000000 rcx=fffffa8004ff6b98
rdx=0000000000000000 rsi=0000000000000000 rdi=0000000000000000
rip=fffff8000168688c rsp=fffff880051677a0 rbp=0000000000000000
r8=fffff78000000008 r9=fffff88005167800 r10=0000000000000000
r11=fffff800017f7e80 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl zr na po nc
nt!KeWaitForSingleObject+0x17c:
fffff800`0168688c 4c8938 mov qword ptr [rax],r15 ds:fbc0:0000=???
Resetting default scope

LAST_CONTROL_TRANSFER: from fffff8000167cb69 to fffff8000167d600

STACK_TEXT:
fffff880051674c8 fffff8000167cb69 : 000000000000000a 0000000000000000 0000000000000002 0000000000000001 : nt!KeBugCheckEx
fffff880051674d0 fffff8000167b7e0 : 0000000000000001 0000000000000000 fffff88005167410 fffffa8004db1c60 : nt!KiBugCheckDispatch+0x69
fffff88005167610 fffff8000168688c : fffffa8000000000 fffffa80018bcd80 fffffa80051a4201 fffff88005167a20 : nt!KiPageFault+0x260
fffff880051677a0 fffff800018e04d8 : 0000000000000f00 0000000000000000 fffff88005167a00 0000000000000000 : nt!KeWaitForSingleObject+0x17c
fffff88005167840 fffff80001961fc9 : fffffa8004ff6b10 0000000000000016 fffff8a00d463118 0000000000000016 : nt!IopAcquireFileObjectLock+0x84
fffff88005167880 fffff88003a4c18a : ffffffff80000b2c fffff88005167a00 fffff8a00d463118 0000000000000ffe : nt!NtQueryInformationFile+0x894
fffff880051679c0 fffff88003a4c05d : fffffa800279d730 0000000000000000 fffffa8005573820 fffff8a00d463010 : srv!QueryPathOrFileInformation+0xca
fffff88005167a80 fffff88003a4c2f5 : 0000000000000016 fffff8a00d463114 fffffa8002798220 0000000000000004 : srv!SrvSmbQueryFileInformation+0x15d
fffff88005167af0 fffff88003a4a7a4 : fffffa8002798220 0000000000000000 00000000fffffffc 0000000000000004 : srv!ExecuteTransaction+0xc5
fffff88005167b30 fffff88003a02698 : fffff88003a1d100 fffffa800279d701 fffff8a00d463118 0000000000000000 : srv!SrvSmbTransaction+0x664
fffff88005167c30 fffff88003a025b3 : fffffa800279d730 0000000000000006 0000000000000006 fffffa800279d730 : srv!SrvProcessSmb+0xb8
fffff88005167cb0 fffff88003a47763 : fffffa8002784b80 0000000000000005 fffffa800279d730 fffffa800279d740 : srv!SrvRestartReceive+0xa3
fffff88005167cf0 fffff80001922a86 : fffffa800279d730 fffffa8002557b60 0000000000000080 fffffa800183c450 : srv!WorkerThread+0xed
fffff88005167d40 fffff8000165bb06 : fffff800017f7e80 fffffa8002557b60 fffffa8004d4e680 fffff880016746c0 : nt!PspSystemThreadStartup+0x5a
fffff88005167d80 0000000000000000 : fffff88005168000 fffff88005162000 fffff880051679f0 0000000000000000 : nt!KxStartSystemThread+0x16

STACK_COMMAND: kb

FOLLOWUP_IP:
srv!QueryPathOrFileInformation+ca
fffff880`03a4c18a 65488b0c2588010000 mov rcx,qword ptr gs:[188h]

SYMBOL_STACK_INDEX: 6

SYMBOL_NAME: srv!QueryPathOrFileInformation+ca

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: srv

IMAGE_NAME: srv.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4b1e0f37

FAILURE_BUCKET_ID: X64_0xA_srv!QueryPathOrFileInformation+ca

BUCKET_ID: X64_0xA_srv!QueryPathOrFileInformation+ca

Followup: MachineOwner

kd> !fileobj fffffa8004ff6b10

udir\mill\0009.DIR\1808.FIL

Related File Object: 0xfffffa80027b7050

Device Object: 0xfffffa8001bdb750 \Driver\volmgr
Vpb: 0xfffffa8001bdb690
Access: Read SharedRead SharedWrite SharedDelete

Flags: 0x10c0002
Synchronous IO
Handle Created
Fast IO Read
Remote Origin

File Object is currently busy and has 1 waiters.

FsContext: 0xfffff8a00d475ae0 FsContext2: 0xfffff8a00ca9deb8
CurrentByteOffset: 0
Cache Data:
Section Object Pointers: fffffa8004ca15d8
Shared Cache Map: fffffa8004c4a270 File Offset: 0 in VACB number 0
Vacb: fffffa80018df3f0
Your data is at: fffff98023c80000

kd> dd fffffa8004ff6b10
fffffa8004ff6b10 00d80005 00000000 01bdb750 fffffa80 fffffa8004ff6b20 01bdb690 fffffa80 0d475ae0 fffff8a0
fffffa8004ff6b30 0ca9deb8 fffff8a0 04ca15d8 fffffa80 fffffa8004ff6b40 00000000 00000000 00000000 00000000
fffffa8004ff6b50 027b7050 fffffa80 00010000 01010100 fffffa8004ff6b60 010c0002 00000000 00380036 00000000
fffffa8004ff6b70 064be6f0 fffff8a0 00000000 00000000 fffffa8004ff6b80 00000001 00000001 00000000 00000000
kd> d
fffffa8004ff6b90 00000080 00000000 00000000 00000000 fffffa8004ff6ba0 00000000 00000000 00060000 00000000
fffffa8004ff6bb0 04ff6bb0 fffffa80 04ff6bb0 fffffa80 fffffa8004ff6bc0 00000000 00000000 00000000 00000000
fffffa8004ff6bd0 04ff6bd0 fffffa80 04ff6bd0 fffffa80 fffffa8004ff6be0 00000000 00000000 00000000 00000000
fffffa8004ff6bf0 02130013 e56c6946 00000000 00000000 fffffa8004ff6c00 00000000 00000000 00000000 fffff880

In our code at IRP_MJ_CREATE time in our PostCreate handler we do the following in the case when local NTFS driver returns
(Data->IoStatus.Status == STATUS_OBJECT_NAME_NOT_FOUND || Data->IoStatus.Status == STATUS_OBJECT_PATH_NOT_FOUND)

1). Build file/pathname over to remote server and do FltCreateFile and then ObReferenceObjectByHandle to get actual file handle/object for the remote file (using MUP & CIFS client/redirector).

  1. Take ownership and initialize the local NTFS shadow/proxy file object as shown below. Note that for the most part we are “borrowing” fields from the remote file object to try and make life easier for us. We then hold a reference on the remote file object until we are completely finished with the shadow/proxy file object. Code snippet showing how we are initializing shadow file object:

if (Data->Iopb->TargetFileObject->Vpb == NULL &&
Data->Iopb->TargetFileObject->RelatedFileObject != NULL)
{
Data->Iopb->TargetFileObject->Vpb = Data->Iopb->TargetFileObject->RelatedFileObject->Vpb;
}

Data->Iopb->TargetFileObject->FsContext = remoteFileObject->FsContext;
Data->Iopb->TargetFileObject->FsContext2 = remoteFileObject->FsContext2;
Data->Iopb->TargetFileObject->SectionObjectPointer =
remoteFileObject->SectionObjectPointer;
Data->Iopb->TargetFileObject->LockOperation =
remoteFileObject->LockOperation;
Data->Iopb->TargetFileObject->DeletePending =
remoteFileObject->DeletePending;
Data->Iopb->TargetFileObject->ReadAccess =
remoteFileObject->ReadAccess;
Data->Iopb->TargetFileObject->WriteAccess =
remoteFileObject->WriteAccess;
Data->Iopb->TargetFileObject->DeleteAccess =
remoteFileObject->DeleteAccess;
Data->Iopb->TargetFileObject->SharedRead =
remoteFileObject->SharedRead;
Data->Iopb->TargetFileObject->SharedWrite =
remoteFileObject->SharedWrite;
Data->Iopb->TargetFileObject->SharedDelete =
remoteFileObject->SharedDelete;
Data->Iopb->TargetFileObject->Flags = FileObject->Flags;
Data->Iopb->TargetFileObject->CurrentByteOffset =
remoteFileObject->CurrentByteOffset;

We then change the IoStatus from failed to SUCCESS and complete the I/O.

  1. Then we intercept ALL I/O to the shadow file object and make proxy Flt/Zw calls to the remote server using the file handle/object obtained during Create time. We massage the returned data if necessary and pass it back to the original caller and complete the I/O. We have to make sure that NTFS will NEVER see one of these proxy file objects or it will croak.

  2. At Close time we tear down the relationship between the local proxy file object and the remote file object and finally do a deferred close on the remote file.

NOTE: There is also other stuff we’re doing related to managing the proxy file object that I haven’t show here as I don’t think it’s relevant to the problem and this post is already WAY too long. I’ll add more later if anyone thinks it would be helpful.

THanks for your help and diligence in reading this far!!

Do I understand it correctly that the BSOD is on the server side, so it is not on machine on which you are twiddling with FILE_OBJECTS? It is really weird in this case.

The created handle/FILE_OBJECT is by default “synchronous” if not specified by FLAG to be asynchronous, so all NtXXX like operations are synchronized by means of waiting on FILE_OBJECT. It is very common scenario. Your file object has synchronous IO flag set. The FILEObject.Lock event cannot be NULL as it is KEVENT structure itself. FILE_OBJECTs are allocated from non-paged pool, so it cannot be paged out. The question is if irql is raised to dispatch level by KeWaitForSingleObject(), or is has been raised before entry into NtQueryInformationFile() API.
It looks like buffer overrun or unbalanced referencing/dereferencing of FILE_OBJECT.

Bronislav Gabrhelik

can you show the content of file object by command?

dt nt!_FILE_OBJECT address /b

Thanks for your help Bronislav.

Actually the BSOD IS on the same machine where my filter is running and fiddling with FILE_OBJECTS.

Here is the content of the fileobj (BTW thanks for the heads up on this debug command do get the detailed file obj decode, much better than !fileobj)

kd> dt nt!_FILE_OBJECT fffffa8004ff6b10 /b
+0x000 Type : 0n5
+0x002 Size : 0n216
+0x008 DeviceObject : 0xfffffa8001bdb750 +0x010 Vpb : 0xfffffa8001bdb690
+0x018 FsContext : 0xfffff8a00d475ae0 +0x020 FsContext2 : 0xfffff8a00ca9deb8
+0x028 SectionObjectPointer : 0xfffffa8004ca15d8 +0x030 PrivateCacheMap : (null) +0x038 FinalStatus : 0n0 +0x040 RelatedFileObject : 0xfffffa80027b7050
+0x048 LockOperation : 0 ‘’
+0x049 DeletePending : 0 ‘’
+0x04a ReadAccess : 0x1 ‘’
+0x04b WriteAccess : 0 ‘’
+0x04c DeleteAccess : 0 ‘’
+0x04d SharedRead : 0x1 ‘’
+0x04e SharedWrite : 0x1 ‘’
+0x04f SharedDelete : 0x1 ‘’
+0x050 Flags : 0x10c0002
+0x058 FileName : _UNICODE_STRING “udir\mill\0009.DIR\1808.FIL”
+0x000 Length : 0x36
+0x002 MaximumLength : 0x38
+0x008 Buffer : 0xfffff8a0064be6f0 "udir\mill\0009.DIR\1808.FIL" +0x068 CurrentByteOffset : _LARGE_INTEGER 0x0 +0x000 LowPart : 0 +0x004 HighPart : 0n0 +0x000 u : <unnamed-tag><br> +0x000 LowPart : 0<br> +0x004 HighPart : 0n0<br> +0x000 QuadPart : 0n0<br> +0x070 Waiters : 1<br> +0x074 Busy : 1<br> +0x078 LastLock : (null) <br> +0x080 Lock : _KEVENT<br> +0x000 Header : _DISPATCHER_HEADER<br> +0x000 Type : 0x80 ''<br> +0x001 TimerControlFlags : 0 ''<br> +0x001 Absolute : 0y0<br> +0x001 Coalescable : 0y0<br> +0x001 KeepShifting : 0y0<br> +0x001 EncodedTolerableDelay : 0y00000 (0)<br> +0x001 Abandoned : 0 ''<br> +0x001 Signalling : 0 ''<br> +0x002 ThreadControlFlags : 0 ''<br> +0x002 CpuThrottled : 0y0<br> +0x002 CycleProfiling : 0y0<br> +0x002 CounterProfiling : 0y0<br> +0x002 Reserved : 0y00000 (0)<br> +0x002 Hand : 0 ''<br> +0x002 Size : 0 ''<br> +0x003 TimerMiscFlags : 0 ''<br> +0x003 Index : 0y000000 (0)<br> +0x003 Inserted : 0y0<br> +0x003 Expired : 0y0<br> +0x003 DebugActive : 0 ''<br> +0x003 ActiveDR7 : 0y0<br> +0x003 Instrumented : 0y0<br> +0x003 Reserved2 : 0y0000<br> +0x003 UmsScheduled : 0y0<br> +0x003 UmsPrimary : 0y0<br> +0x003 DpcActive : 0 ''<br> +0x000 Lock : 0n128<br> +0x004 SignalState : 0n0<br> +0x008 WaitListHead : _LIST_ENTRY [0x0000000000000000 - 0x0]
+0x000 Flink : (null)
+0x008 Blink : (null)
+0x098 Event : _KEVENT
+0x000 Header : _DISPATCHER_HEADER
+0x000 Type : 0 ‘’
+0x001 TimerControlFlags : 0 ‘’
+0x001 Absolute : 0y0
+0x001 Coalescable : 0y0
+0x001 KeepShifting : 0y0
+0x001 EncodedTolerableDelay : 0y00000 (0)
+0x001 Abandoned : 0 ‘’
+0x001 Signalling : 0 ‘’
+0x002 ThreadControlFlags : 0x6 ‘’
+0x002 CpuThrottled : 0y0
+0x002 CycleProfiling : 0y1
+0x002 CounterProfiling : 0y1
+0x002 Reserved : 0y00000 (0)
+0x002 Hand : 0x6 ‘’
+0x002 Size : 0x6 ‘’
+0x003 TimerMiscFlags : 0 ‘’
+0x003 Index : 0y000000 (0)
+0x003 Inserted : 0y0
+0x003 Expired : 0y0
+0x003 DebugActive : 0 ‘’
+0x003 ActiveDR7 : 0y0
+0x003 Instrumented : 0y0
+0x003 Reserved2 : 0y0000
+0x003 UmsScheduled : 0y0
+0x003 UmsPrimary : 0y0
+0x003 DpcActive : 0 ‘’
+0x000 Lock : 0n393216
+0x004 SignalState : 0n0
+0x008 WaitListHead : _LIST_ENTRY [0xfffffa8004ff6bb0 - 0xfffffa8004ff6bb0]
+0x000 Flink : 0xfffffa8004ff6bb0 <br> +0x008 Blink : 0xfffffa8004ff6bb0
+0x0b0 CompletionContext : (null)
+0x0b8 IrpListLock : 0
+0x0c0 IrpList : _LIST_ENTRY [0xfffffa8004ff6bd0 - 0xfffffa8004ff6bd0]
+0x000 Flink : 0xfffffa8004ff6bd0 <br> +0x008 Blink : 0xfffffa8004ff6bd0
+0x0d0 FileObjectExtension : (null)

Is it possible that you allocate some synchronization object (like an event
or something) somewhere else in your code from paged pool ? Again, not
related to this code path, just anywhere in the code…

Thanks,
Alex.

Alex - I don’t think so but I’ll look over the code and see if that could be the case.

Also to clarify regarding the file object being dumped in the earlier post - this IS one of the file objects for which the filter is taking ownership and using as a shadow/proxy file object for the real file object that exists on the remote secondary server (where no filter is running). So the file in the file object (“1808.FIL”) doesn’t exists on the server where the filter is running and the BSOD occured. The actual file is on the remote secondary server.

Thanks.

I am quite confused. AFAIK srv.sys is part of CIFS server. The srv.sys shouldn’t be involved on the machine where you are redirecting , but on secondary machine. On primary machine should be involved CIFS client (mrxsmb.sys). That was reason I mentioned buffer overrun. The only scenario I can see is that the CIFS server on primary machine sends request to NTFS which you are filtering, so some third machine is involved as a CIFS client.

You know this is really big hack and I don’t think that this approach can work reliably. I think the problem causes following assignment
Data->Iopb->TargetFileObject->Flags = FileObject->Flags;
In other words remote file object was created for synchronous operations, but the primary file object not, here you have overwritten flags, so IO subsystem thinks that it should synchronize, but KEVENT is not initialized.

Furthermore you are leaving VCB and device object fields, so you don’t lose control over the file object, but this object has stolen CC related structures, so it is in quite inconsistent state. I believe you filter FastIOs, but there are also cache callbacks, which you might not redirect, w/o implementing the whole layered FSD, which is even more tough task than FSD itself.

Bronislav Gabrhelik

Thank alot for your suggestions Bronislav.

I realize I neglected to include some information that might clear some of the confusion. There is another client machine (or multiple clients for that matter) involved when this crash occurs. In fact the filter driver is mostly concerned with only I/O that originated from remote clients (i.e. impersonated users), rather than local I/O to the primary device.

So in other words we are mainly watching for I/O originating from remote clients that have a mapped a drive to a CIFS share on the Primary server. Then we are presenting an altered view of the file/dir structure that not only includes files on the Primary local device where the share is defined, but also shows files from the remote secondary server as if they were on the Primary. So as far as the client is concerned, they don’t know that some of the files they are seeing when they do a “DIR” are actually on a different server.

But so when the client wants to access those remote files, that is when the filter has to step in and act as a proxy, taking over the “shadow” file objects that represent those files on the remote secondary and redirecting any I/O to those files over to the remote secondary.

I believe we very will may end up with full-blown layered FSD before this is all said and done. Currently we force NON-Fast IOs to simplify things. In our shadow file objects we are borrowing some of the fields from the remote file object (FsContexts, SOP, etc) so I’m not entirely sure if we’ll need to do additional work related to the cache. I’m pretty sure we’ll need to be a name provider to prevent our shadow objects from getting down to NTFS. I’ll be the first to admit I’m no expert in this area and I’m flying-by-the-seat-of-my-pants so to speak.

I do realize this is a big hack fraught with peril, but near as I can tell from the research we’ve done and feedback from experts, we don’t have alot of other options since STATUS_REPARSE won’t work correctly in the case of redirecting I/O that came from a remote client over to a remote server. There are also the authentication/security issues to overcome since we are essentially allowing the user to “share a share”, something that Windows won’t normally allow you to do.

If you are aware of safer, less hackish architecture to accomplish this I would certainly love to hear the details.

Many thanks again for your kind assistance.

I cannot see any “easy” solution, but maybe I am wrong. The OSR DMK might safe you several man-years I think, but it is probably something you woudn’t like to hear.

Bronislav Gabrhelik

Bronislav - Thanks for the helpful suggestions and confirmation of the difficulty of what we’re trying to do. I love to pass along comments/warnings from outside expert sources to my management (such as “man-years”, “big hack…”, “probably won’t work…”, “harder than FSD itself”, etc), and watch their reactions, very entertaining :slight_smile:

They must go positively apoplectic when they’re equated to the “pointy
haired boss”.

Gary G. Little
H (952) 223-1349
C (952) 454-4629
xxxxx@comcast.net

-----Original Message-----
From: xxxxx@lists.osr.com
[mailto:xxxxx@lists.osr.com] On Behalf Of xxxxx@yahoo.com
Sent: Tuesday, June 29, 2010 12:15 PM
To: Windows File Systems Devs Interest List
Subject: RE:[ntfsd] Help debugging crash in KeWaitForSingleObject

Bronislav - Thanks for the helpful suggestions and confirmation of the
difficulty of what we’re trying to do. I love to pass along
comments/warnings from outside expert sources to my management (such as
“man-years”, “big hack…”, “probably won’t work…”, “harder than FSD
itself”, etc), and watch their reactions, very entertaining :slight_smile:


NTFSD is sponsored by OSR

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

To unsubscribe, visit the List Server section of OSR Online at
http://www.osronline.com/page.cfm?name=ListServer

How do you handle “QueryInformationFile” in your filter driver? We had a “similar” bsod before. It turns out it was because we didn’t handle some directoryinformation request “timely”.

Hope it helps,

Jiajun Lu

Just wanted to mention that we haven’t been able to reproduce this problem since I followed Bronislov’s earlier suggestion to initialize the shadow fileobject->Flags differently.

Thanks for the help!