Tuesday, February 3, 2015

Oooops in Windows 10 filesystem filter

Windows 10 might be naughty to old style FSD filters or filters that registered to be called after Windows' WdFilter FS minifilter as the last one's create request postcallback sends a scan message (allegedly) to user mode that results in a delay in create IRP completion, in many cases this file object is used by an underlying FSD to initialize the cache, so this results in a situation when a file system filter driver observes an IO for the file object with IRP_MJ_CREATE request still lingering i.e. a scenario when not all completion routines and FS minifilter's postcallbacks have been called. For example the first IRP_MJ_CREATE completion is waiting in  WdFilter!MpScanFile and in the same time an application opens the file for writing and this create requests completes promptly, then the application issues a write request that results in first writing the data in the cache and then is followed by a synchronous cache flush with the file object for which IRP_MJ_CREATE is waiting in WdFilter!MpScanFile .

Below there are two call stacks for this scenario.

A create request issued by an FSD filter :

00 ffffd000`2060fd90 fffff804`0082020e nt!KiSwapContext+0x76
01 ffffd000`2060fed0 fffff804`0081f6ff nt!KiSwapThread+0x66e
02 ffffd000`2060ff90 fffff804`0081ee44 nt!KiCommitThreadWait+0x12f
03 ffffd000`20610010 fffff804`00c88ef1 nt!KeWaitForMultipleObjects+0x424
04 ffffd000`206100d0 fffff801`89a08d57 nt!FsRtlCancellableWaitForMultipleObjects+0x91
05 ffffd000`20610140 fffff801`8aa798fb FLTMGR!FltSendMessage+0x497
06 ffffd000`20610280 fffff801`8aa751f3 WdFilter!MpScanFile+0x5cb
07 ffffd000`20610400 fffff801`8aa747ea WdFilter!MpAmPostCreate+0x8a3
08 ffffd000`20610600 fffff801`89a03633 WdFilter!MpPostCreate+0x17a
09 ffffd000`206106b0 fffff801`89a03033 FLTMGR!FltpPerformPostCallbacks+0x2f3
0a ffffd000`20610780 fffff801`89a049f6 FLTMGR!FltpPassThroughCompletionWorker+0x73
0b ffffd000`206107c0 fffff801`89a314eb FLTMGR!FltpLegacyProcessingAfterPreCallbacksCompleted+0x1d6
0c ffffd000`20610830 fffff801`8d067232 FLTMGR!FltpCreate+0x33b
................................................................... Here was a pass through filter, removed because of NDA
15 ffffd000`206113c0 fffff804`00814ef2 nt!IovCallDriver+0x3d8
16 ffffd000`20611420 fffff804`00bfbf0e nt!IofCallDriver+0x72
17 ffffd000`20611460 fffff804`00c0313d nt!IopParseDevice+0x6ae
18 ffffd000`20611670 fffff804`00c0112c nt!ObpLookupObjectName+0x6ed
19 ffffd000`206117e0 fffff804`00be4029 nt!ObOpenObjectByName+0x1ec
1a ffffd000`20611910 fffff804`00be3ba0 nt!IopCreateFile+0x369
1b ffffd000`206119b0 fffff804`00d07b35 nt!IoCreateFileEx+0x100
1c ffffd000`20611a40 fffff801`8d07775a nt!IoCreateFileSpecifyDeviceObjectHint+0xe5
................................................................... Here was a pass through filter, removed because of NDA
1f ffffd000`20612780 fffff804`00ef0e6c VerifierExt!xdv_IRP_MJ_DEVICE_CONTROL_wrapper+0xff
20 ffffd000`206127e0 fffff804`00814ef2 nt!IovCallDriver+0x3d8
21 ffffd000`20612840 fffff804`00c0a587 nt!IofCallDriver+0x72
22 ffffd000`20612880 fffff804`00c90186 nt!IopXxxControlFile+0x8f7
23 ffffd000`20612a20 fffff804`00940f63 nt!NtDeviceIoControlFile+0x56
24 ffffd000`20612a90 00007ffe`803bda6a nt!KiSystemServiceCopyEnd+0x13

25 00000000`047bea08 00000000`00000000 ntdll!NtDeviceIoControlFile+0xa

A write request with a file object still in the IRP_MJ_CREATE completion phase, this file object is used to flush cache as this file object was used by FSD to back the mapped file segment object which is used in the file system cache implementation :

15 ffffd000`227c6280 fffff804`00814ef2 nt!IovCallDriver+0x3d8
16 ffffd000`227c62e0 fffff804`008bbfec nt!IofCallDriver+0x72
17 ffffd000`227c6320 fffff804`008bbe76 nt!IoSynchronousPageWriteEx+0x140
18 ffffd000`227c6360 fffff804`0084ca5a nt!MiIssueSynchronousFlush+0x6a
19 ffffd000`227c63d0 fffff804`0084ef08 nt!MiFlushSectionInternal+0x96a
1a ffffd000`227c65f0 fffff804`0084fadc nt!MmFlushSection+0x108
1b ffffd000`227c66c0 fffff804`00833982 nt!CcFlushCachePriv+0x57c
1c ffffd000`227c67c0 fffff804`0087bebe nt!CcMapAndCopyInToCache+0x622
1d ffffd000`227c68b0 fffff801`8d300f32 nt!CcCopyWriteEx+0x1de
1e ffffd000`227c6950 fffff801`8d2c772d fastfat!FatCommonWrite+0x194a
1f ffffd000`227c6b90 fffff804`00ef0e6c fastfat!FatFsdWrite+0xed
20 ffffd000`227c6bd0 fffff804`00814ef2 nt!IovCallDriver+0x3d8
21 ffffd000`227c6c30 fffff801`89a04974 nt!IofCallDriver+0x72
22 ffffd000`227c6c70 fffff801`89a02972 FLTMGR!FltpLegacyProcessingAfterPreCallbacksCompleted+0x154
23 ffffd000`227c6ce0 fffff801`8d067232 FLTMGR!FltpDispatch+0xb2
................................................................... Here was a pass through filter, removed because of NDA
2c ffffd000`227c7820 fffff804`00814ef2 nt!IovCallDriver+0x3d8
2d ffffd000`227c7880 fffff804`00c70d62 nt!IofCallDriver+0x72
2e ffffd000`227c78c0 fffff804`00c71f37 nt!IopSynchronousServiceTail+0x162
2f ffffd000`227c7990 fffff804`00940f63 nt!NtWriteFile+0x687
30 ffffd000`227c7a90 00007ffe`803bda7a nt!KiSystemServiceCopyEnd+0x13
31 00000000`076fc8a8 00007ffe`7d7617cc ntdll!NtWriteFile+0xa
32 00000000`076fc8b0 00007ffe`7d762657 KERNELBASE!WriteFile+0x10c
33 00000000`076fc930 00007ffe`7d760524 KERNELBASE!BaseCopyStream+0x953
34 00000000`076fda90 00007ffe`7d7cfd09 KERNELBASE!BasepCopyFileExW+0x774
35 00000000`076fe070 00007ffe`7e45bb74 KERNELBASE!CopyFile2+0xf9
36 00000000`076fe180 00007ffe`7e45555b SHELL32!CFSTransfer::_PerformCopyFileWithRetry+0xd0
37 00000000`076fe230 00007ffe`7e1c6cbd SHELL32!CFSTransfer::CopyItem+0x23b
38 00000000`076fe2a0 00007ffe`7e1b9c16 SHELL32!CCopyOperation::_CreateDestinationOrCopyItemWithRetry+0xc1
39 00000000`076fe360 00007ffe`7dededf0 SHELL32!CCopyOperation::Do+0x126
3a 00000000`076fe660 00007ffe`7dedeaaf SHELL32!CCopyWorkItem::_DoOperation+0x50
3b 00000000`076fe6d0 00007ffe`7dede3b8 SHELL32!CCopyWorkItem::_SetupAndPerformOp+0x273
3c 00000000`076fea10 00007ffe`7dede70e SHELL32!CCopyWorkItem::ProcessWorkItem+0x194
3d 00000000`076fecd0 00007ffe`7dede479 SHELL32!CCopyWorkItem::_ProcessChildren+0xf6
3e 00000000`076fed50 00007ffe`7dee0f7e SHELL32!CCopyWorkItem::ProcessWorkItem+0x255
3f 00000000`076ff010 00007ffe`7dee2dbd SHELL32!CRecursiveFolderOperation::Do+0x1ce
40 00000000`076ff0c0 00007ffe`7dee27cf SHELL32!CFileOperation::_EnumRootDo+0x2c9
41 00000000`076ff170 00007ffe`7dee1c3f SHELL32!CFileOperation::PrepareAndDoOperations+0x1c7
42 00000000`076ff250 00007ffe`7e46c339 SHELL32!CFileOperation::PerformOperations+0xcf
43 00000000`076ff2b0 00007ffe`7e46a79b SHELL32!CFSDropTargetHelper::_MoveCopyHIDA+0x271
44 00000000`076ff370 00007ffe`7e46d10e SHELL32!CFSDropTargetHelper::_Drop+0x333
45 00000000`076ff650 00007ffe`7d65a737 SHELL32!CFSDropTargetHelper::s_DoDropThreadProc+0x3e
46 00000000`076ff680 00007ffe`7fde5f72 SHCORE!GetDpiForMonitor+0x157
47 00000000`076ff770 00007ffe`80389b54 KERNEL32!BaseThreadInitThunk+0x22
48 00000000`076ff7a0 00000000`00000000 ntdll!RtlUserThreadStart+0x34

The file object

5: kd> dt nt!_FILE_OBJECT ffffe0015b432800
   +0x000 Type             : 0n5
   +0x002 Size             : 0n216
   +0x008 DeviceObject     : 0xffffe001`5b027c00 _DEVICE_OBJECT
   +0x010 Vpb              : 0xffffe001`62c9c290 _VPB
   +0x018 FsContext        : 0xffffc001`cba39da0 Void
   +0x020 FsContext2       : 0xffffc001`cc292340 Void
   +0x028 SectionObjectPointer : 0xffffe001`59d656f0 _SECTION_OBJECT_POINTERS
   +0x030 PrivateCacheMap  : (null) 
   +0x038 FinalStatus      : 0n0
   +0x040 RelatedFileObject : (null) 
   +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            : 0x42
   +0x058 FileName         : _UNICODE_STRING "\TestPicture\bootmgr"
   +0x068 CurrentByteOffset : _LARGE_INTEGER 0x0
   +0x070 Waiters          : 0
   +0x074 Busy             : 0
   +0x078 LastLock         : (null) 
   +0x080 Lock             : _KEVENT
   +0x098 Event            : _KEVENT
   +0x0b0 CompletionContext : (null) 
   +0x0b8 IrpListLock      : 0
   +0x0c0 IrpList          : _LIST_ENTRY [ 0xffffe001`5b4328c0 - 0xffffe001`5b4328c0 ]

   +0x0d0 FileObjectExtension : 0xffffcf81`75df8fb0 Void

The create IRP

5: kd> !irp 0xffffcf81`75fb8a20 1
Irp is active with 17 stacks 17 is current (= 0xffffcf8175fb8f70)
 No Mdl: No System Buffer: Thread ffffe0015941d080:  Irp stack trace.  
Flags = 40000884
ThreadListEntry.Flink = ffffcf8176c30ec0
ThreadListEntry.Blink = ffffe0015941d6e0
IoStatus.Status = 00000000
IoStatus.Information = 00000001
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = ffffd00020611560
UserEvent = 00000000
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000   
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = ffffcf8175fb8a98
Tail.Overlay.Thread = ffffe0015941d080
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = ffffcf8175fb8f70
Tail.Overlay.OriginalFileObject = ffffe0015b432800
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
     cmd  flg cl Device   File     Completion-Context

...................................
Args: 00000000 00000000 00000000 00000000
 [  0, 0]   0 10 ffffe00159976970 00000000 fffff80189a09220-ffffe001595856b0    
      \FileSystem\fastfat FLTMGR!FltpSynchronizedOperationCompletion
Args: 00000000 00000000 00000000 00000000
>[  0, 0]   0 e0 ffffe001599b8060 ffffe0015b432800 fffff8018d0498b0-ffffcf81765d0f80 Success Error Cancel 
      \FileSystem\FltMgr DeviceLockDriver0!DlFoHashCreateRequestHookCompletion

Args: ffffd000206115f0 01000120 00070080 00000000

The write IRP with the FILE_OBJECT at ffffe0015b432800 that has its IRP_MJ_CREATE  Irp waiting in a minifilter postcreate callback

5: kd> !irp 0xffffcf81`76a62a20 0x1
Irp is active with 17 stacks 17 is current (= 0xffffcf8176a62f70)
 Mdl=ffffe0016312e280: No System Buffer: Thread ffffe00163211080:  Irp stack trace.  
Flags = 40060043
ThreadListEntry.Flink = ffffcf8176562a40
ThreadListEntry.Blink = ffffe001632116e0
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = ffffd000227c6850
UserEvent = ffffd000227c6390
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000   
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = ffffcf8176a62a98
Tail.Overlay.Thread = ffffe00163211080
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = ffffcf8176a62f70
Tail.Overlay.OriginalFileObject = ffffe0015b432800
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
     cmd  flg cl Device   File     Completion-Context

..........................

>[  4, 0]   4  0 ffffe001599b8060 ffffe0015b432800 00000000-00000000    
      \FileSystem\FltMgr
Args: 00020000 00000000 00000000 00000000