Blue screen. FltMgr device object in unexpected place.

Alexey_Barabash · January 20, 2012, 4:36pm

Hello.

I am investigating blue screen dump file and I am confused with things I saw.

Stack:

STACK_TEXT:
8078ad48 8b005700 badb0d00 00000001 00000000 nt!KiTrap0E+0x2cf
8078add8 8b1db71f 85fbf868 85d20e00 85f6d5d0 CLASSPNP!ClassIoComplete+0x142
8078adf4 82ab5913 85fbf868 85d20e00 85f6d5b8 disk!DiskFlushComplete+0x49
8078ae38 8adb7da3 8adc30a0 85c48910 8078ae60 nt!IopfCompleteRequest+0x128
8078ae48 8adb85b7 851c56c8 85d20e00 85f6d5d0 ataport!IdeCompleteScsiIrp+0x31
8078ae60 8adb54bd 85c48910 85c48910 851c70e0 ataport!IdeAlwaysSuccessCrbCompletion+0x21
8078ae7c 8adbb474 851c70e0 85c48910 85c48910 ataport!IdeTranslateCompletedRequest+0x161
8078aef4 8adbb677 851c70e0 85c48910 851c709c ataport!IdeProcessCompletedRequests+0x2a0
8078af48 82ab51b5 851c709c 851c7028 00000000 ataport!IdePortCompletionDpc+0xab
8078afa4 82ab5018 82b67d20 86fe0b88 00000000 nt!KiExecuteAllDpcs+0xf9
8078aff4 82ab47dc 880b5ab4 00000000 00000000 nt!KiRetireDpcList+0xd5
8078aff8 880b5ab4 00000000 00000000 00000000 nt!KiDispatchInterrupt+0x2c
WARNING: Frame IP not in any known module. Following frames may be wrong.
82ab47dc 00000000 0000001a 00d6850f bb830000 0x880b5ab4

STACK_COMMAND: kb

FOLLOWUP_IP:
CLASSPNP!ClassIoComplete+142
8b005700 c680a100000000 mov byte ptr [eax+0A1h],0

I found the line corresponding this instruction in function ClassIoComplete ( WINDDK\7600.16385.1\src\storage\class\classpnp\class.c)
fdoData->LoggedTURFailureSinceLastIO = FALSE;

eax=00000001

0A1h - is an offset of LoggedTURFailureSinceLastIO field, so fdoData wrong pointer:
0: kd> dt classpnp!_CLASS_PRIVATE_FDO_DATA
+0x000 SqmData : Uint4B
+0x004 TrackingFlags : Uint4B
…
+0x0a1 LoggedTURFailureSinceLastIO : UChar
…

The thing most confused me: device object arrived to ClassIoComplete belongs to FltMgr:

0: kd> !devobj 85fbf868
Device object (85fbf868) is for:
\FileSystem\FltMgr DriverObject 85b0fe40
Current Irp 00000000 RefCount 0 Type 00000008 Flags 00040000
DevExt 85fbf920 DevObjExt 85fbf950
ExtensionFlags (0x00000800)
Unknown flags 0x00000800
AttachedTo (Lower) 85fc6020 \FileSystem\Ntfs
Device queue is not busy.

ClassIoComplete expects another type of device (with FUNCTIONAL_DEVICE_EXTENSION extension):

PFUNCTIONAL_DEVICE_EXTENSION fdoExtension = Fdo->DeviceExtension;
PCLASS_PRIVATE_FDO_DATA fdoData = fdoExtension->PrivateFdoData;

And after this instructions device extension has been taken from DeviceExtension of FltMgr device and fdoData==0x00000001 in my case, which is invalid pointer.

Irp is available, but it also contains unexpected device of FltMgr in stack:

0: kd> !irp 85d20e00
Irp is active with 11 stacks 8 is current (= 0x85d20f6c)
No Mdl: No System Buffer: Thread 86fe0b88: Irp stack trace. Pending has been returned
cmd flg cl Device File Completion-Context
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000
[f, 0] 0 0 851c5610 00000000 8b1db6d6-85f6d5b8
\Driver\atapi disk!DiskFlushComplete
Args: 00000000 00000000 00000000 85c48910

[9, 0] 0 e1 85fbf868 85e48d18 8af21a08-00000009 Success Error Cancel pending
\FileSystem\FltMgr volmgr!VmpRefCountCompletionRoutine
Args: 00000000 00000000 00000000 00000000
[9, 0] 0 e0 85f72030 85e48d18 8b075fff-00000000 Success Error Cancel
\Driver\volmgr Ntfs!NtfsFlushCompletionRoutine
Args: 00000000 00000000 00000000 00000000
[9, 0] 0 e0 85fc6020 85e48d18 8b02d4de-85e298d0 Success Error Cancel
\FileSystem\Ntfs fltmgr!FltpSynchronizedOperationCompletion
Args: 00000000 00000000 00000000 00000000
[9, 0] 0 0 85fbf868 85e48d18 00000000-00000000
\FileSystem\FltMgr
Args: 00000000 00000000 00000000 00000000

This situation is not reproducible, but appeared just after my minifilter was started. So I am trying to find a reason of this.
Any ideas or tips why such situation could appear? What can be checked in dump to specify problem?

Thanks.

Best regards,
Alexey Barabash

Alex_Carp · January 23, 2012, 12:19pm

Could you please post the !devstack output for the device in question and for the file system stack where the device should be and the storage stack for that volume ?

BTW, I’ve never seen this before…

Thanks,
Alex.

Alexey_Barabash · January 24, 2012, 7:25am

Thanks for the advice. I have just rechecked all devices and did not found FltMgr device in stack at wrong position.

For device in question (which arrives into CLASSPNP!ClassIoComplete):

0: kd> !devstack 85fbf868
!DevObj !DrvObj !DevExt ObjectName

85fbf868 \FileSystem\FltMgr 85fbf920
85fc6020 \FileSystem\Ntfs 85fc60d8

File system stack
0: kd> !drvobj ntfs
Driver object (85b0f460) is for:
\FileSystem\Ntfs
Driver Extension List: (id , addr)

Device Object list:
8621e020 85fc6020 85ac8700

0: kd> !devstack 8621e020
!DevObj !DrvObj !DevExt ObjectName
86226670 \FileSystem\FltMgr 86226728

8621e020 \FileSystem\Ntfs 8621e0d8

0: kd> !devstack 85fc6020
!DevObj !DrvObj !DevExt ObjectName
85fbf868 \FileSystem\FltMgr 85fbf920

85fc6020 \FileSystem\Ntfs 85fc60d8

0: kd> !devstack 85ac8700
!DevObj !DrvObj !DevExt ObjectName
85b10020 \FileSystem\FltMgr 85b100d8

85ac8700 \FileSystem\Ntfs 00000000 Ntfs

Storage stack

0: kd> !drvobj disk
Driver object (85f6c6d0) is for:
\Driver\Disk
Driver Extension List: (id , addr)
(8b01963e 85f6de28)
Device Object list:
860cd030 85f6d150

0: kd> !devstack 860cd030
!DevObj !DrvObj !DevExt ObjectName
86079990 \Driver\partmgr 86079a48

860cd030 \Driver\Disk 860cd0e8 DR1
860cc6b0 \Driver\USBSTOR 860cc768 00000082
!DevNode 85e72008 :
DeviceInst is “USBSTOR\Disk&Ven_…”
ServiceName is “disk”

0: kd> !devstack 85f6d150
!DevObj !DrvObj !DevExt ObjectName
85f6e020 \Driver\partmgr 85f6e0d8

85f6d150 \Driver\Disk 85f6d208 DR0
85ac2270 \Driver\ACPI 85144e08
851c5610 \Driver\atapi 851c56c8 IdeDeviceP0T0L0-0
!DevNode 85a8e888 :
DeviceInst is “IDE\DiskWDC_WD3200AAKS…”
ServiceName is “disk”

0: kd> !drvobj volmgr
Driver object (85a967c0) is for:
\Driver\volmgr
Driver Extension List: (id , addr)

Device Object list:
85c7c6a8 85f722f0 85f72030 85a98030

0: kd> !devstack 85c7c6a8
!DevObj !DrvObj !DevExt ObjectName
85d4c020 \Driver\volsnap 85d4c0d8
85dd2c80 \Driver\fvevol 85dd2d38

85c7c6a8 \Driver\volmgr 85c7c760 HarddiskVolume3
!DevNode 85d52008 :
DeviceInst is “STORAGE\Volume_??USBSTOR#Disk&Ven…{53f56307-b6bf-11d0-94f2-00a0c91efb8b}”
ServiceName is “volsnap”

0: kd> !devstack 85f722f0
!DevObj !DrvObj !DevExt ObjectName
85f73020 \Driver\volsnap 85f730d8
85f70bd8 \Driver\rdyboost 85f70c90
85f704a8 \Driver\fvevol 85f70560

85f722f0 \Driver\volmgr 85f723a8 HarddiskVolume2
!DevNode 85f72c00 :
DeviceInst is “STORAGE\Volume{bdeef186-d092-11df-8469-806e6f6e6963}#0000004A72500000”
ServiceName is “volsnap”

0: kd> !devstack 85f72030
!DevObj !DrvObj !DevExt ObjectName
85f71020 \Driver\volsnap 85f710d8
85f72508 \Driver\rdyboost 85f725c0
85f70020 \Driver\fvevol 85f700d8

85f72030 \Driver\volmgr 85f720e8 HarddiskVolume1
!DevNode 85f6f7b8 :
DeviceInst is “STORAGE\Volume{bdeef186-d092-11df-8469-806e6f6e6963}#0000000000100000”
ServiceName is “volsnap”

0: kd> !devstack 85a98030
!DevObj !DrvObj !DevExt ObjectName

85a98030 \Driver\volmgr 85a980e8 VolMgrControl
851e5030 \Driver\PnpManager 851e50e8 00000058
!DevNode 851e5e78 :
DeviceInst is “Root\volmgr\0000”
ServiceName is “volmgr”

0: kd> !drvobj atapi
Driver object (85ab6200) is for:
\Driver\atapi
Driver Extension List: (id , addr)
(8adce006 85ab6bc8)
Device Object list:
85b0d338 851c5610 851c3028 851c7028

0: kd> !devstack 85b0d338
!DevObj !DrvObj !DevExt ObjectName
86254aa8 \Driver\cdrom 86229cc0 CdRom0
85ac6918 \Driver\ACPI 85144808

85b0d338 \Driver\atapi 85b0d3f0 IdeDeviceP1T0L0-1
!DevNode 851638a8 :
DeviceInst is “IDE\CdRomTSSTcorp_DVD±RW_TS…”
ServiceName is “cdrom”

0: kd> !devstack 851c5610
!DevObj !DrvObj !DevExt ObjectName
85f6e020 \Driver\partmgr 85f6e0d8
85f6d150 \Driver\Disk 85f6d208 DR0
85ac2270 \Driver\ACPI 85144e08

851c5610 \Driver\atapi 851c56c8 IdeDeviceP0T0L0-0
!DevNode 85a8e888 :
DeviceInst is “IDE\DiskWDC_WD3200AAKS…”
ServiceName is “disk”

0: kd> !devstack 851c3028
!DevObj !DrvObj !DevExt ObjectName

851c3028 \Driver\atapi 851c30e0 IdePort1
85a98bd8 \Driver\ACPI 85144a08
85ab59c8 \Driver\intelide 85ab5a80 PciIde0Channel1
!DevNode 85ab6008 :
DeviceInst is “PCIIDE\IDEChannel\4&99cfb8c&0&1”
ServiceName is “atapi”

0: kd> !devstack 851c7028
!DevObj !DrvObj !DevExt ObjectName

851c7028 \Driver\atapi 851c70e0 IdePort0
85a989a0 \Driver\ACPI 85144008
85ab5b90 \Driver\intelide 85ab5c48 PciIde0Channel0
!DevNode 85ab5810 :
DeviceInst is “PCIIDE\IDEChannel\4&99cfb8c&0&0”
ServiceName is “atapi”

0: kd> !drvobj atapi
Driver object (85ab6200) is for:
\Driver\atapi
Driver Extension List: (id , addr)
(8adce006 85ab6bc8)
Device Object list:
85b0d338 851c5610 851c3028 851c7028

0: kd> !devstack 851c5610
!DevObj !DrvObj !DevExt ObjectName
85f6e020 \Driver\partmgr 85f6e0d8
85f6d150 \Driver\Disk 85f6d208 DR0
85ac2270 \Driver\ACPI 85144e08

851c5610 \Driver\atapi 851c56c8 IdeDeviceP0T0L0-0
!DevNode 85a8e888 :
DeviceInst is “IDE\DiskWDC_WD3200AAKS…”
ServiceName is “disk”

Thanks.

Best regards,
Alexey Barabash

Alex_Carp · January 24, 2012, 12:03pm

Hi Alexey,

Sorry, i’ve been looking at the provided information but I can’t come up with any scenario that might explain this. Since this doesn’t look related to file systems, perhaps you should ask on NTDEV as well…

Thanks,
Alex.

Scott_Noone_OSR · January 24, 2012, 12:05pm

Does your driver pass Driver Verifier?

-scott

–
Scott Noone
Consulting Associate and Chief System Problem Analyst
OSR Open Systems Resources, Inc.
http://www.osronline.com

wrote in message news:xxxxx@ntfsd…

Hi Alexey,

Sorry, i’ve been looking at the provided information but I can’t come up
with any scenario that might explain this. Since this doesn’t look related
to file systems, perhaps you should ask on NTDEV as well…

Thanks,
Alex.

Alexey_Barabash · January 25, 2012, 4:31am

Alex, thanks anyway.

Scott, yes driver pass the Driver Verifier.

Thanks.

Best regards,
Alexey Barabash

Scott_Noone_OSR · January 25, 2012, 10:02am

This crash has me fascinated, everything about the IRP seems normal except
for the FltMgr device object.

Does your filter do any special processing in IRP_MJ_FLUSH_BUFFERS?

-scott

–
Scott Noone
Consulting Associate and Chief System Problem Analyst
OSR Open Systems Resources, Inc.
http://www.osronline.com

wrote in message news:xxxxx@ntfsd…

Alex, thanks anyway.

Scott, yes driver pass the Driver Verifier.

Thanks.

Best regards,
Alexey Barabash

Alexey_Barabash · January 26, 2012, 7:29am

Hello.

Thank you for your interesting, Scott.

Yes. My driver does support of oplocks and it does check for oplock break in PreFlushBuffers by calling FltCheckOplock.

I have searched more in dump and found thread which make situation more clear:

0: kd> k
ChildEBP RetAddr
b44ef730 82abb65d nt!KiSwapContext+0x26
b44ef768 82aba4b7 nt!KiSwapThread+0x266
b44ef790 82ab40cf nt!KiCommitThreadWait+0x1df
b44ef808 82a6e089 nt!KeWaitForSingleObject+0x393
b44ef830 82ae815a nt!KiAcquireFastMutex+0x56
b44ef874 82ae7b2d nt!FsRtlCheckOplockEx+0x134
b44ef898 8b02e4e7 nt!FsRtlCheckOplock+0x53
b44ef8c4 8b02e615 fltmgr!FltpCommonOplockCheckBreak+0x99
b44ef8f4 b3979d8d fltmgr!FltCheckOplock+0x25
b44ef91c b3979e55 MyDriver!CheckOplockWithCallback_PreFlushBuffers+0x4b
b44ef94c b3979edf MyDriver!PreFlushBuffers+0xa9
b44ef964 8b041d9b MyDriver!PreFlushBuffersOplockComplete+0x1f
b44ef980 82b06867 fltmgr!FltpOplockWaitComplete+0x35
b44ef994 82a613d3 nt!FsRtlpRemoveAndCompleteWaitingIrp+0x45
b44ef9e0 82ae8198 nt!FsRtlpOplockCleanup+0x28e
b44efa2c 82ae7b2d nt!FsRtlCheckOplockEx+0x172
b44efa50 8b02e4e7 nt!FsRtlCheckOplock+0x53
b44efa7c 8b02e615 fltmgr!FltpCommonOplockCheckBreak+0x99
b44efaac b3973d0e fltmgr!FltCheckOplock+0x25
b44efadc 8b02a324 MyDriver!PostCleanUp+0xaa
b44efb44 8b02d512 fltmgr!FltpPerformPostCallbacks+0x24a
b44efb58 8b02db46 fltmgr!FltpProcessIoCompletion+0x10
b44efb68 8b02e29c fltmgr!FltpPassThroughCompletion+0x98
b44efb98 8b02e3cb fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x33a
b44efbd0 82a7458e fltmgr!FltpDispatch+0xc5
b44efbe8 82c6faa6 nt!IofCallDriver+0x63
b44efc28 82c60f47 nt!IopCloseFile+0x2f3
b44efc74 82c82394 nt!ObpDecrementHandleCount+0x139
b44efcbc 82c820d4 nt!ObpCloseHandleTableEntry+0x203
b44efcec 82c8246e nt!ObpCloseHandle+0x7f
b44efd08 90e32c5a nt!NtClose+0x4e
…

So, some time ago from a moment of a crash my driver received call of PreFlushBuffers. FltCheckOplock returned FLT_PREOP_PENDING ? this means ?An oplock break was initiated, which caused the Filter Manager to post the I/O operation to a work queue?. My PreFlushBuffers returned FLT_PREOP_PENDING also.

Then file was closed. In PostCleanUp I call FltCheckOplock without break completion callbacks: FltCheckOplock(&streamContext->m_Oplock, Data, NULL, NULL, NULL).

Pended pre-operation (PreFlushBuffers) should be complete in PreFlushBuffersOplockComplete after call of PreFlushBuffers, which in turns calls FltCheckOplock, which should not wait, because oplock already should be broken because we are invoked from PreFlushBuffersOplockComplete. But the last FltCheckOplock waits for something and there is a crash in another thread, as it is described in my first message.

Here is code. If you have some suggestions I would appreciate if you let me know.

FLT_PREOP_CALLBACK_STATUS PreFlushBuffers(
__inout PFLT_CALLBACK_DATA Data,
__in PCFLT_RELATED_OBJECTS FltObjects,
__out PVOID *CompletionContext)
{
if (!FLT_IS_IRP_OPERATION(Data))
{
return FLT_PREOP_SUCCESS_NO_CALLBACK;
}

StreamContext* streamContext = NULL;
// Get stream context pointer
// …

FLT_PREOP_CALLBACK_STATUS status = FLT_PREOP_SUCCESS_NO_CALLBACK;
NTSTATUS ntStatus = STATUS_SUCCESS;

// Acquire stream’s ERESOURCE
// …

do
{
FLT_PREOP_CALLBACK_STATUS status = CheckOplockWithCallback_PreFlushBuffers(
&streamContext->m_Oplock,
Data,
FltObjects,
ntStatus);

if (!NT_SUCCESS(ntStatus))
{
break;
}

if (FLT_PREOP_SUCCESS_WITH_CALLBACK != status)
{
break;
}

status = FLT_PREOP_SUCCESS_NO_CALLBACK;

}while(FALSE);

// Release stream’s ERESOURCE
// …

if (!NT_SUCCESS(ntStatus))
{
return CompletePreop(Data, ntStatus);
}

return status;
}

FLT_PREOP_CALLBACK_STATUS CompletePreop(
__inout PFLT_CALLBACK_DATA Data,
__in NTSTATUS Status,
__in_opt ULONG_PTR Information)
{
Data->IoStatus.Status = Status;
Data->IoStatus.Information = Information;
return FLT_PREOP_COMPLETE;
}

FLT_PREOP_CALLBACK_STATUS CheckOplockWithCallback_PreFlushBuffers(
__in POPLOCK pOplock,
__in PFLT_CALLBACK_DATA Data,
__in PCFLT_RELATED_OBJECTS FltObjects,
__out NTSTATUS &ntStatus)
{
ntStatus = STATUS_SUCCESS;
PUCHAR pBuf = ExAllocatePool(NonPagedPool, FltObjects->Size);

if (NULL == pBuf)
{
ntStatus = STATUS_INSUFFICIENT_RESOURCES;
return FLT_PREOP_SUCCESS_NO_CALLBACK;
}

PFLT_RELATED_OBJECTS fltObjectsCopy = (PFLT_RELATED_OBJECTS)pBuf;
RtlCopyMemory(fltObjectsCopy, FltObjects, FltObjects->Size);

FLT_PREOP_CALLBACK_STATUS status = FltCheckOplock(
pOplock,
Data,
fltObjectsCopy,
PreFlushBuffersOplockComplete,
NULL);
if (FLT_PREOP_PENDING == status)
{
ExFreePool(fltObjectsCopy);
}

return status;
}

void PreFlushBuffersOplockComplete(
__in PFLT_CALLBACK_DATA Data,
__in PVOID Context)
{
FLT_PREOP_CALLBACK_STATUS status = FLT_PREOP_COMPLETE;
PVOID completionContext = NULL;
PFLT_RELATED_OBJECTS fltObjectsCopy = (PFLT_RELATED_OBJECTS)Context;

if (STATUS_SUCCESS == Data->IoStatus.Status)
{
status = PreFlushBuffers(Data, fltObjectsCopy, &completionContext);
}

if (FLT_PREOP_PENDING != status)
{
FltCompletePendedPreOperation(Data, status, completionContext);
}

ExFreePool(fltObjectsCopy);
}

Thanks.

Best regards,
Alexey Barabash

Scott_Noone_OSR · January 26, 2012, 1:59pm

>Pended pre-operation (PreFlushBuffers) should be complete in

PreFlushBuffersOplockComplete after call of PreFlushBuffers, which in turns
calls >FltCheckOplock, which should not wait, because oplock already should
be broken because we are invoked from PreFlushBuffersOplockComplete. But
>the last FltCheckOplock waits for something…

OK, I think you have two problems.

First, the hang. If you look at your call stack, you’re recursively calling
FsRtlCheckOplockEx:

nt!KiSwapContext+0x26
nt!KiSwapThread+0x266
nt!KiCommitThreadWait+0x1df
nt!KeWaitForSingleObject+0x393
nt!KiAcquireFastMutex+0x56
nt!FsRtlCheckOplockEx+0x134 <…
fltmgr!FltCheckOplock+0x25
MyDriver!CheckOplockWithCallback_PreFlushBuffers+0x4b
MyDriver!PreFlushBuffers+0xa9
MyDriver!PreFlushBuffersOplockComplete+0x1f
b44ef994 82a613d3 nt!FsRtlpRemoveAndCompleteWaitingIrp+0x45
b44ef9e0 82ae8198 nt!FsRtlpOplockCleanup+0x28e
…
nt!FsRtlCheckOplockEx+0x172 <…
fltmgr!FltCheckOplock+0x25
MyDriver!PostCleanUp+0xaa

Note that the second, hanging call to FsRtlCheckOplockEx is waiting on a
fast mutex:

nt!KiAcquireFastMutex+0x56
nt!FsRtlCheckOplockEx+0x134

Which, by definition, is not recursively acquirable. So, I’d say that the
first call to FsRtlCheckOplockEx acquired a fast mutex protecting the oplock
and then when your callback fired you triggered another acquire to the same
mutex, thus causing the deadlock.

If I were you, I would try to dig out the fast mutex that the thread is
hanging on and make 100% sure that it is indeed the same lock acquired
earlier. If it is, then you probably just need to post the PreFlushBuffers
operation to a work item from within PreFlushBuffersOplockComplete instead
of calling it directly.

For the second issue, it’s hard to know if I’m right because you’ve only
posted a portion of your code. However, it looks like you have a scope
issue:

FLT_PREOP_CALLBACK_STATUS status = FLT_PREOP_SUCCESS_NO_CALLBACK;
…
do
{
FLT_PREOP_CALLBACK_STATUS status =
CheckOplockWithCallback_PreFlushBuffers(
&streamContext->m_Oplock,
Data,
FltObjects,
ntStatus);

…
}while(FALSE);

…
return status;
}

Doesn’t this always just return FLT_PREOP_SUCCESS_NO_CALLBACK? That would
certainly result in the type of crash you’re seeing because you’re not
pending the flush operation in the case of the oplock break.

-scott

–
Scott Noone
Consulting Associate and Chief System Problem Analyst
OSR Open Systems Resources, Inc.
http://www.osronline.com

wrote in message news:xxxxx@ntfsd…

Hello.

Thank you for your interesting, Scott.

Yes. My driver does support of oplocks and it does check for oplock break in
PreFlushBuffers by calling FltCheckOplock.

I have searched more in dump and found thread which make situation more
clear:

0: kd> k
ChildEBP RetAddr
b44ef730 82abb65d nt!KiSwapContext+0x26
b44ef768 82aba4b7 nt!KiSwapThread+0x266
b44ef790 82ab40cf nt!KiCommitThreadWait+0x1df
b44ef808 82a6e089 nt!KeWaitForSingleObject+0x393
b44ef830 82ae815a nt!KiAcquireFastMutex+0x56
b44ef874 82ae7b2d nt!FsRtlCheckOplockEx+0x134
b44ef898 8b02e4e7 nt!FsRtlCheckOplock+0x53
b44ef8c4 8b02e615 fltmgr!FltpCommonOplockCheckBreak+0x99
b44ef8f4 b3979d8d fltmgr!FltCheckOplock+0x25
b44ef91c b3979e55 MyDriver!CheckOplockWithCallback_PreFlushBuffers+0x4b
b44ef94c b3979edf MyDriver!PreFlushBuffers+0xa9
b44ef964 8b041d9b MyDriver!PreFlushBuffersOplockComplete+0x1f
b44ef980 82b06867 fltmgr!FltpOplockWaitComplete+0x35
b44ef994 82a613d3 nt!FsRtlpRemoveAndCompleteWaitingIrp+0x45
b44ef9e0 82ae8198 nt!FsRtlpOplockCleanup+0x28e
b44efa2c 82ae7b2d nt!FsRtlCheckOplockEx+0x172
b44efa50 8b02e4e7 nt!FsRtlCheckOplock+0x53
b44efa7c 8b02e615 fltmgr!FltpCommonOplockCheckBreak+0x99
b44efaac b3973d0e fltmgr!FltCheckOplock+0x25
b44efadc 8b02a324 MyDriver!PostCleanUp+0xaa
b44efb44 8b02d512 fltmgr!FltpPerformPostCallbacks+0x24a
b44efb58 8b02db46 fltmgr!FltpProcessIoCompletion+0x10
b44efb68 8b02e29c fltmgr!FltpPassThroughCompletion+0x98
b44efb98 8b02e3cb
fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x33a
b44efbd0 82a7458e fltmgr!FltpDispatch+0xc5
b44efbe8 82c6faa6 nt!IofCallDriver+0x63
b44efc28 82c60f47 nt!IopCloseFile+0x2f3
b44efc74 82c82394 nt!ObpDecrementHandleCount+0x139
b44efcbc 82c820d4 nt!ObpCloseHandleTableEntry+0x203
b44efcec 82c8246e nt!ObpCloseHandle+0x7f
b44efd08 90e32c5a nt!NtClose+0x4e
…

So, some time ago from a moment of a crash my driver received call of
PreFlushBuffers. FltCheckOplock returned FLT_PREOP_PENDING ? this means ?An
oplock break was initiated, which caused the Filter Manager to post the I/O
operation to a work queue?. My PreFlushBuffers returned FLT_PREOP_PENDING
also.

Then file was closed. In PostCleanUp I call FltCheckOplock without break
completion callbacks: FltCheckOplock(&streamContext->m_Oplock, Data, NULL,
NULL, NULL).

Pended pre-operation (PreFlushBuffers) should be complete in
PreFlushBuffersOplockComplete after call of PreFlushBuffers, which in turns
calls FltCheckOplock, which should not wait, because oplock already should
be broken because we are invoked from PreFlushBuffersOplockComplete. But the
last FltCheckOplock waits for something and there is a crash in another
thread, as it is described in my first message.

Here is code. If you have some suggestions I would appreciate if you let me
know.

FLT_PREOP_CALLBACK_STATUS PreFlushBuffers(
inout PFLT_CALLBACK_DATA Data,
in PCFLT_RELATED_OBJECTS FltObjects,
__out PVOID CompletionContext)
{
if (!FLT_IS_IRP_OPERATION(Data))
{
return FLT_PREOP_SUCCESS_NO_CALLBACK;
}

StreamContext streamContext = NULL;
// Get stream context pointer
// …

FLT_PREOP_CALLBACK_STATUS status = FLT_PREOP_SUCCESS_NO_CALLBACK;
NTSTATUS ntStatus = STATUS_SUCCESS;

// Acquire stream’s ERESOURCE
// …

do
{
FLT_PREOP_CALLBACK_STATUS status =
CheckOplockWithCallback_PreFlushBuffers(
&streamContext->m_Oplock,
Data,
FltObjects,
ntStatus);

if (!NT_SUCCESS(ntStatus))
{
break;
}

if (FLT_PREOP_SUCCESS_WITH_CALLBACK != status)
{
break;
}

status = FLT_PREOP_SUCCESS_NO_CALLBACK;

}while(FALSE);

// Release stream’s ERESOURCE
// …

if (!NT_SUCCESS(ntStatus))
{
return CompletePreop(Data, ntStatus);
}

return status;
}

FLT_PREOP_CALLBACK_STATUS CompletePreop(
__inout PFLT_CALLBACK_DATA Data,
in NTSTATUS Status,
in_opt ULONG_PTR Information)
{
Data->IoStatus.Status = Status;
Data->IoStatus.Information = Information;
return FLT_PREOP_COMPLETE;
}

FLT_PREOP_CALLBACK_STATUS CheckOplockWithCallback_PreFlushBuffers(
in POPLOCK pOplock,
in PFLT_CALLBACK_DATA Data,
in PCFLT_RELATED_OBJECTS FltObjects,
out NTSTATUS &ntStatus)
{
ntStatus = STATUS_SUCCESS;
PUCHAR pBuf = ExAllocatePool(NonPagedPool, FltObjects->Size);

if (NULL == pBuf)
{
ntStatus = STATUS_INSUFFICIENT_RESOURCES;
return FLT_PREOP_SUCCESS_NO_CALLBACK;
}

PFLT_RELATED_OBJECTS fltObjectsCopy = (PFLT_RELATED_OBJECTS)pBuf;
RtlCopyMemory(fltObjectsCopy, FltObjects, FltObjects->Size);

FLT_PREOP_CALLBACK_STATUS status = FltCheckOplock(
pOplock,
Data,
fltObjectsCopy,
PreFlushBuffersOplockComplete,
NULL);
if (FLT_PREOP_PENDING == status)
{
ExFreePool(fltObjectsCopy);
}

return status;
}

void PreFlushBuffersOplockComplete(
in PFLT_CALLBACK_DATA Data,
in PVOID Context)
{
FLT_PREOP_CALLBACK_STATUS status = FLT_PREOP_COMPLETE;
PVOID completionContext = NULL;
PFLT_RELATED_OBJECTS fltObjectsCopy = (PFLT_RELATED_OBJECTS)Context;

if (STATUS_SUCCESS == Data->IoStatus.Status)
{
status = PreFlushBuffers(Data, fltObjectsCopy, &completionContext);
}

if (FLT_PREOP_PENDING != status)
{
FltCompletePendedPreOperation(Data, status, completionContext);
}

ExFreePool(fltObjectsCopy);
}

Thanks.

Best regards,
Alexey Barabash

Christian_Allred · January 26, 2012, 2:25pm

Even if the mutex in the thread in this case isn’t the same one in each call to FsRtlCheckOplockEx you should never allow the possibility of calling into the oplock package twice on the same stack. You will inevitably deadlock.

Christian [MSFT]
This posting is provided “AS IS” with no warranties, and confers no rights.

Alexey_Barabash · January 26, 2012, 3:45pm

Hello.

As you said, it is a deadlock indeed. Here is part of stack with raw arguments:

b44ef8f4 b3979d8d 8636b6a0 85e29930 876a8960 fltmgr!FltCheckOplock+0x25 <b44ef91c b3979e55 8636b6a0 85e29930 87123130 MyDriver!CheckOplockWithCallback_PreFlushBuffers+0x4b
b44ef94c b3979edf 85e29930 87123130 b44ef970 MyDriver!PreFlushBuffers+0xa9
b44ef964 8b041d9b 85e29930 87123130 85d20e00 MyDriver!PreFlushBuffersOplockComplete+0x1f
b44ef980 82b06867 ceebd5f8 85d20e00 cefe8464 fltmgr!FltpOplockWaitComplete+0x35
b44ef994 82a613d3 9ba1b410 cefe8448 871c3008 nt!FsRtlpRemoveAndCompleteWaitingIrp+0x45
b44ef9e0 82ae8198 cefe8448 871c31e0 9ba1b7dc nt!FsRtlpOplockCleanup+0x28e
b44efa2c 82ae7b2d 0136b6a0 871c3008 00000000 nt!FsRtlCheckOplockEx+0x172
b44efa50 8b02e4e7 8636b6a0 871c3008 00000000 nt!FsRtlCheckOplock+0x53
b44efa7c 8b02e615 8636b6a0 85d20c00 00000000 fltmgr!FltpCommonOplockCheckBreak+0x99
b44efaac b3973d0e 8636b6a0 85d20c00 00000000 fltmgr!FltCheckOplock+0x25 <b44efadc 8b02a324 85d20c00 8636b6a4 00000000 MyDriver!PostCleanUp+0xaa

Oplock is the same, 0x8636b6a0.
And more, if I have extracted fast mutext from oplock, I will see:
0: kd> dd 8636b6a0 L1
8636b6a0 cefe8448

Offset of fast mutex pointer in oplock structure is 0x38 - from FsRtlUninitializeOplock code.
0: kd> dd cefe8448+38 L1
cefe8480 85d1b508

0: kd> dt nt!_FAST_MUTEX 85d1b508
+0x000 Count : 0n4
+0x004 Owner : 0x85ce5030 _KTHREAD
+0x008 Contention : 1
+0x00c Event : _KEVENT
+0x01c OldIrql : 1
Owner is this thread already (85ce5030).

The second issue is scope problem indeed. Yes, my PreFlushBuffers always returned FLT_PREOP_SUCCESS_NO_CALLBACK. I looked thousands times on this code, but didn?t noticed that. Thank you very much for pointed me to this problem, Scott! You are completelly right about the reason of the crash.

So, each oplock break complete callback should not call original pre-op directly, because it can be oplock break caused by own post-cleanup? Correct?

Today I tried to reproduce the situation when oplock break was in progress and FltCheckOplock returned FLT_PREOP_PENDING. But didn?t see it at all, in any of operations. Is there any tool or scenario which uses oplocks intensively to verify my changes?

Thanks.

Best regards,
Alexey Barabash