What is the cause of PAGE_FAULT_IN_NONPAGED_AREA (50) in clfs.sys

NTDEV
1

To be clear regarding drivers I am total newbie, and I am just learning how to write them.
I am writing some storage driver (virtual drive) and all BSOD stack-traces were point to my code, but this one doesn’t.
And so far I am unable to wrap my head around it. Couldn’t find anything that would help me resolve the real cause of the problem.
It always happens when I unmount the drive, and I am missing what else I need to do (or maybe I overdid something?).
I would appreciate some help debugging the cause of all this.

Here is the bugcheck Analysis
`
kd> !analyze -v

  •                                                                         *

  •                    Bugcheck Analysis                                    *

  •                                                                         *

PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by try-except.
Typically the address is just plain bad or it is pointing at freed memory.
Arguments:
Arg1: fffff8a0000cc000, memory referenced.
Arg2: 0000000000000000, value 0 = read operation, 1 = write operation.
Arg3: fffff88000d54e17, If non-zero, the instruction address which referenced the bad memory
address.
Arg4: 0000000000000000, (reserved)

Debugging Details:

Could not read faulting driver name

KEY_VALUES_STRING: 1

TIMELINE_ANALYSIS: 1

DUMP_CLASS: 1

DUMP_QUALIFIER: 400

BUILD_VERSION_STRING: 7601.17514.amd64fre.win7sp1_rtm.101119-1850

SYSTEM_MANUFACTURER: VMware, Inc.

VIRTUAL_MACHINE: VMware

SYSTEM_PRODUCT_NAME: VMware Virtual Platform

SYSTEM_VERSION: None

BIOS_VENDOR: Phoenix Technologies LTD

BIOS_VERSION: 6.00

BIOS_DATE: 07/31/2013

BASEBOARD_MANUFACTURER: Intel Corporation

BASEBOARD_PRODUCT: 440BX Desktop Reference Platform

BASEBOARD_VERSION: None

DUMP_TYPE: 2

BUGCHECK_P1: fffff8a0000cc000

BUGCHECK_P2: 0

BUGCHECK_P3: fffff88000d54e17

BUGCHECK_P4: 0

READ_ADDRESS: GetPointerFromAddress: unable to read from fffff80002d000e8
Unable to get MmSystemRangeStart
GetUlongPtrFromAddress: unable to read from fffff80002d00280
GetUlongPtrFromAddress: unable to read from fffff80002d00408
GetPointerFromAddress: unable to read from fffff80002d000a8
fffff8a0000cc000 Paged pool

FAULTING_IP:
CLFS!ClfsDecodeBlock+53
fffff880`00d54e17 0fb607 movzx eax,byte ptr [rdi]

MM_INTERNAL_CODE: 0

CPU_COUNT: 1

CPU_MHZ: b54

CPU_VENDOR: GenuineIntel

CPU_FAMILY: 6

CPU_MODEL: 3a

CPU_STEPPING: 9

CPU_MICROCODE: 6,3a,9,0 (F,M,S,R) SIG: 17’00000000 (cache) 17’00000000 (init)

CUSTOMER_CRASH_COUNT: 1

DEFAULT_BUCKET_ID: WIN7_DRIVER_FAULT

BUGCHECK_STR: 0x50

PROCESS_NAME: System

CURRENT_IRQL: 0

ANALYSIS_SESSION_HOST: W7X64DRV

ANALYSIS_SESSION_TIME: 12-28-2018 09:39:48.0306

ANALYSIS_VERSION: 10.0.17134.12 amd64fre

TRAP_FRAME: fffff8800492a970 – (.trap 0xfffff8800492a970)
NOTE: The trap frame does not contain all registers.
Some register values may be zeroed or incorrect.
rax=000000000082d67b rbx=0000000000000000 rcx=000000000000000b
rdx=0000000097500ff3 rsi=0000000000000000 rdi=0000000000000000
rip=fffff88000d54e17 rsp=fffff8800492ab00 rbp=fffff88000d6da40
r8=00000000005e6a00 r9=0000000000000010 r10=fffff8a0000b1000
r11=000000004a868051 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl nz ac po cy
CLFS!ClfsDecodeBlock+0x53:
fffff88000d54e17 0fb607 movzx eax,byte ptr [rdi] ds:0000000000000000=??
Resetting default scope

LAST_CONTROL_TRANSFER: from fffff80002a7b2ac to fffff80002acf640

STACK_TEXT:
fffff8800492a808 fffff80002a7b2ac : 0000000000000050 fffff8a0000cc000 0000000000000000 fffff8800492a970 : nt!KeBugCheckEx
fffff8800492a810 fffff80002acd76e : 0000000000000000 fffff8a0000cc000 fffff8800492aa00 000000000000300d : nt! ?? ::FNODOBFM::string'+0x4621f fffff8800492a970 fffff88000d54e17 : 0000000000000001 fffffa800e9aa201 0000000000000002 0000000000000020 : nt!KiPageFault+0x16e fffff8800492ab00 fffff88000d75948 : fffff8a0000b1000 fffffa800ccc0b30 fffffa800e911010 fffff8a0000b1000 : CLFS!ClfsDecodeBlock+0x53 fffff8800492ab40 fffff88000d75642 : fffffa800e911010 fffffa800e911010 0000000000000001 fffff8a000001701 : CLFS!CClfsBaseFilePersisted::WriteMetadataBlock+0x288 fffff8800492abd0 fffff88000d59335 : fffffa800e911010 0000000000000001 0000000000000000 0000000000000000 : CLFS!CClfsBaseFilePersisted::FlushImage+0x3a fffff8800492ac10 fffff88000d862fd : 0000000000000000 0000000000000000 fffffa800ccc0b30 0000000000000000 : CLFS!CClfsLogFcbPhysical::FlushMetadata+0xe1 fffff8800492ac60 fffff88000d82d57 : fffffa800e96c630 fffff8a000001780 fffffa800d2e9300 0000000000000000 : CLFS!CClfsLogFcbVirtual::Cleanup+0x231 fffff8800492ad00 fffff88000d7fc52 : fffffa800e96c630 fffff8800492b110 fffffa800ccc0b30 0000000000000000 : CLFS!CClfsLogCcb::Cleanup+0x147 fffff8800492ad50 fffff88000d994be : fffffa800e9283e0 fffffa800e9283e0 0000000000000001 fffffa800e96ca00 : CLFS!CClfsRequest::Cleanup+0x5e fffff8800492ada0 fffff88000d71a09 : fffffa800e9283e0 0000000000000000 fffffa800d2e93c0 0000000000000000 : CLFS!ClfsDispatchIoRequest+0x32 fffff8800492adf0 fffff80002dd6f0f : fffffa800e9283e0 fffffa800ccc0b30 0000000000000000 fffffa800e96ca00 : CLFS!CClfsDriver::LogIoDispatch+0x21 fffff8800492ae20 fffff80002dc66b4 : 0000000000000000 fffffa800ccc0b30 fffff88000d6b110 fffff88000d5bb99 : nt!IopCloseFile+0x11f fffff8800492aeb0 fffff80002dc6471 : fffffa800ccc0b30 fffffa8000000001 fffff8a000001780 0000000000000002 : nt!ObpDecrementHandleCount+0xb4 fffff8800492af30 fffff80002dc6a34 : 0000000000000758 fffffa800ccc0b30 fffff8a000001780 0000000000000758 : nt!ObpCloseHandleTableEntry+0xb1 fffff8800492afc0 fffff80002ace8d3 : fffffa800e6ed060 fffff8800492b090 fffff88000d6b110 fffff88000d8c9d7 : nt!ObpCloseHandle+0x94 fffff8800492b010 fffff80002acae70 : fffff88000da0476 fffffffffffef800 0000000000000000 fffff8a002937520 : nt!KiSystemServiceCopyEnd+0x13 fffff8800492b1a8 fffff88000da0476 : fffffffffffef800 0000000000000000 fffff8a002937520 fffffa800e9ee320 : nt!KiServiceLinkage fffff8800492b1b0 fffff80002d58c42 : fffffa800e96cc40 fffffa800e96c510 fffffa800e9ee320 0000000000000000 : CLFS!ClfsCloseLogFileObject+0x7a fffff8800492b1f0 fffff80002d59a3b : 0000000000000000 fffffa800e9ee320 0000000000000000 fffffa800ccc0b30 : nt!TmpTmOffline+0xe6 fffff8800492b240 fffff80002dc66b4 : 0000000000000001 fffffa800e9ee320 fffffa800e96cc10 fffffa8000000000 : nt!TmpCloseTransactionManager+0x2b fffff8800492b280 fffff80002dc6471 : 0000000000000000 fffffa8000000000 fffff8a000001780 0000000000000000 : nt!ObpDecrementHandleCount+0xb4 fffff8800492b300 fffff80002dc6a34 : 0000000000000760 fffffa800e9ee320 fffff8a000001780 0000000000000760 : nt!ObpCloseHandleTableEntry+0xb1 fffff8800492b390 fffff80002ace8d3 : fffffa800e6ed060 fffff8800492b460 fffff8a0000a7000 0000000000000000 : nt!ObpCloseHandle+0x94 fffff8800492b3e0 fffff80002acae70 : fffff88001334585 fffff8800492b920 0000000000000000 fffff8a0000a7000 : nt!KiSystemServiceCopyEnd+0x13 fffff8800492b578 fffff88001334585 : fffff8800492b920 0000000000000000 fffff8a0000a7000 fffff8800492b600 : nt!KiServiceLinkage fffff8800492b580 fffff88001318418 : fffffa800e9aa2a0 fffff8a0000a7000 fffffa800f10e910 fffff880010d7000 : Ntfs!TxfShutdownRm+0x2e1 fffff8800492b660 fffff880013195f8 : fffffa800e9aa2a0 fffffa800f10d180 fffffa800f10d100 fffff88001123d00 : Ntfs!TxfShutdownVolume+0x10c fffff8800492b720 fffff880013073ee : fffffa800e9aa2a0 0000000000000000 0000000000000000 0000000000000000 : Ntfs!NtfsLockVolume+0x198 fffff8800492b800 0000000000000000 : 0000000000000000 0000000000000000 0000000000000000 00000000`00000000 : Ntfs!NtfsUserFsRequest+0x2de

THREAD_SHA1_HASH_MOD_FUNC: 7d0edbd44806e28bde116c5debb37212f7a90710

THREAD_SHA1_HASH_MOD_FUNC_OFFSET: 58c88db71732daa38856123691e4b80fb91a30f1

THREAD_SHA1_HASH_MOD: a0d598732c44c6965712e3cfcfc078cb425401a6

FOLLOWUP_IP:
CLFS!ClfsDecodeBlock+53
fffff880`00d54e17 0fb607 movzx eax,byte ptr [rdi]

FAULT_INSTR_CODE: f07b60f

SYMBOL_STACK_INDEX: 3

SYMBOL_NAME: CLFS!ClfsDecodeBlock+53

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: CLFS

IMAGE_NAME: CLFS.SYS

DEBUG_FLR_IMAGE_TIMESTAMP: 4a5bc11d

IMAGE_VERSION: 6.1.7600.16385

STACK_COMMAND: .thread ; .cxr ; kb

FAILURE_BUCKET_ID: X64_0x50_CLFS!ClfsDecodeBlock+53

BUCKET_ID: X64_0x50_CLFS!ClfsDecodeBlock+53

PRIMARY_PROBLEM_CLASS: X64_0x50_CLFS!ClfsDecodeBlock+53

TARGET_TIME: 2018-12-28T08:30:27.000Z

OSBUILD: 7601

OSSERVICEPACK: 1000

SERVICEPACK_NUMBER: 0

OS_REVISION: 0

SUITE_MASK: 272

PRODUCT_TYPE: 1

OSPLATFORM_TYPE: x64

OSNAME: Windows 7

OSEDITION: Windows 7 WinNt (Service Pack 1) TerminalServer SingleUserTS

OS_LOCALE:

USER_LCID: 0

OSBUILD_TIMESTAMP: 2010-11-20 10:30:02

BUILDDATESTAMP_STR: 101119-1850

BUILDLAB_STR: win7sp1_rtm

BUILDOSVER_STR: 6.1.7601.17514.amd64fre.win7sp1_rtm.101119-1850

ANALYSIS_SESSION_ELAPSED_TIME: 6b4

ANALYSIS_SOURCE: KM

FAILURE_ID_HASH_STRING: km:x64_0x50_clfs!clfsdecodeblock+53

FAILURE_ID_HASH: {40eff690-da10-f4c9-2650-796690e5dda9}

Followup: MachineOwner

`

2

SoLaR wrote:

I am writing some storage driver (virtual drive) and all BSOD stack-traces were point to my code, but this one doesn’t.

And so far I am unable to wrap my head around it. Couldn’t find anything that would help me resolve the real cause of the problem.

It always happens when I unmount the drive, and I am missing what else I need to do (or maybe I overdid something?).

I would appreciate some help debugging the cause of all this.

The CLFS driver has dereferenced a null pointer while trying to close
out its transaction log.  I’m not a disk guy, but taking a wild stab,
I’d guess that you cleaned up part of your data structures before you
were really allowed to do so.    How is your cleanup distributed?  Do
you wait until “close”, or do you try to do part of it is “cleanup”?

3

hmm thought that FSCTL_LOCK_VOLUME would ensure there are no longer writes to drive since there are no longer locks to the drive?

You asked about CleanUp process so here it is
driver exe application:

    int vdUmount(char DriveLetter)
    {
        char    VolumeName[] = "\\\\.\\ :";
        char    DriveName[] = " :\\";
        HANDLE  Device;
        DWORD   BytesReturned;
    
        VolumeName[4] = DriveLetter;
        DriveName[0] = DriveLetter;
    
        Device = CreateFile(
            VolumeName,
            GENERIC_READ | GENERIC_WRITE,
            FILE_SHARE_READ | FILE_SHARE_WRITE,
            NULL,
            OPEN_EXISTING,
            FILE_FLAG_NO_BUFFERING,
            NULL
            );
    
        if (Device == INVALID_HANDLE_VALUE)
        {
            PrintLastError(&VolumeName[4]);
            return -1;
        }
    
        if (!DeviceIoControl(
            Device,
            FSCTL_LOCK_VOLUME,
            NULL,
            0,
            NULL,
            0,
            &BytesReturned,
            NULL
            ))
        {
            PrintLastError(&VolumeName[4]);
            CloseHandle(Device);
            return -1;
        }
    
        if (!DeviceIoControl(
            Device,
            IOCTL_VD_CLOSE_FILE,
            NULL,
            0,
            NULL,
            0,
            &BytesReturned,
            NULL
            ))
        {
            PrintLastError("VD:");
            CloseHandle(Device);
            return -1;
        }
    
        if (!DeviceIoControl(
            Device,
            FSCTL_DISMOUNT_VOLUME,
            NULL,
            0,
            NULL,
            0,
            &BytesReturned,
            NULL
            ))
        {
            PrintLastError(&VolumeName[4]);
            CloseHandle(Device);
            return -1;
        }
    
        if (!DeviceIoControl(
            Device,
            FSCTL_UNLOCK_VOLUME,
            NULL,
            0,
            NULL,
            0,
            &BytesReturned,
            NULL
            ))
        {
            PrintLastError(&VolumeName[4]);
            CloseHandle(Device);
            return -1;
        }
    
        CloseHandle(Device);
    
        if (!DefineDosDevice(
            DDD_REMOVE_DEFINITION,
            &VolumeName[4],
            NULL
            ))
        {
            PrintLastError(&VolumeName[4]);
            return -1;
        }
    
        SHChangeNotify(SHCNE_DRIVEREMOVED, SHCNF_PATH, DriveName, NULL);
    
        return 0;
    }

In sys driver in function vdMJDeviceControl() (DriverObject->MajorFunction[IRP_MJ_DEVICE_CONTROL] = vdMJDeviceControl;)
call to IOCTL_VD_CLOSE_FILE is enqueued for processing in vdThread():

case IOCTL_VD_CLOSE_FILE:				// returns STATUS_PENDING (ExInterlockedInsertTailList(Irp))
        {
            DbgPrint("VD([%x]DeviceControl): IOCTL_VD_CLOSE_FILE enter.\n",(void*)DeviceObject);

            IoMarkIrpPending(Irp);

            ExInterlockedInsertTailList(
                &device_extension->list_head,
                &Irp->Tail.Overlay.ListEntry,
                &device_extension->list_lock
                );

            KeSetEvent(
                &device_extension->request_event,
                (KPRIORITY) 0,
                FALSE
                );

            status = STATUS_PENDING;

            break;
        }

In sys driver function vdThread() simply called function vdCloseFile()

case IOCTL_VD_CLOSE_FILE:
            // call
            irp->IoStatus.Status = vdIOCloseFile(device_object, irp);
            break;

And finally in sys driver function vdCloseFile I’ve cleaned up all resources:

  NTSTATUS
  vdIOCloseFile (
      IN PDEVICE_OBJECT   DeviceObject,
      IN PIRP             Irp
      )
  {
    PDEVICE_EXTENSION device_extension;

    PAGED_CODE();

    ASSERT(DeviceObject != NULL);
    ASSERT(Irp != NULL);

    DbgPrint("VD([%x]CloseFile): enter.\n",(void*)DeviceObject);

    device_extension = (PDEVICE_EXTENSION) DeviceObject->DeviceExtension;

    // SA: I'am done with object reference (this got to be it????)
    DbgPrint("VD([%x]CloseFile): ObDereferenceObject(device_extension->file_object_device);\n",(void*)DeviceObject);
    ObDereferenceObject(device_extension->file_object_device);

	DbgPrint("VD([%x]CloseFile): ExFreePool(device_extension->drive_header); //SA\n",(void*)DeviceObject);
	ExFreePool(device_extension->drive_header);

    DbgPrint("VD([%x]CloseFile): ExFreePool(device_extension->file_name.Buffer);\n",(void*)DeviceObject);
    ExFreePool(device_extension->file_name.Buffer);

    DbgPrint("VD([%x]CloseFile): ZwClose(device_extension->file_handle);\n",(void*)DeviceObject);
    ZwClose(device_extension->file_handle);
	device_extension->file_handle = NULL;

    DbgPrint("VD([%x]CloseFile): media_in_device = FALSE.\n",(void*)DeviceObject);
    device_extension->media_in_device = FALSE;

    Irp->IoStatus.Status = STATUS_SUCCESS;
    Irp->IoStatus.Information = 0;

    return STATUS_SUCCESS;
    }

The only thing I see that sticks out is following line:

ObDereferenceObject(device_extension->file_object_device);

I’ve intended to try properly handle power management I/O control and flush buffers prior to releasing, but not quite finished that part.

4

The trap frame is misleading, this is actually an invalid kernel pointer dereference (see Arg1) in CLFS!ClfsDecodeBlock. Makes me wonder if you’ve returned the wrong data.

Can you provide the crash dump?

5

Sure I can, here is more recent (have plenty of them :/)
but I would like to know how I can do test the same thing in the future.

6

The minidump restricts how far I can get on this, but here’s what I can tell…

CLFS is in a loop walking the buffer pointed to by the first argument (RCX) one byte at a time and eventually goes off a cliff. Here’s the loop:

CLFS!ClfsDecodeBlock+0x50:
fffff880`00d13e14 mov     rdi,rcx

CLFS!ClfsDecodeBlock+0x53:
fffff880`00d13e17 movzx   eax,byte ptr [rdi]
fffff880`00d13e1a movzx   ecx,dl
fffff880`00d13e1d lea     rbp,[CLFS!CCrc32::m_rgCrcTable (fffff880`00d2ca40)]
fffff880`00d13e24 xor     rcx,rax
fffff880`00d13e27 mov     eax,edx
fffff880`00d13e29 inc     rdi
fffff880`00d13e2c mov     edx,dword ptr [rbp+rcx*4]
fffff880`00d13e30 shr     eax,8
fffff880`00d13e33 xor     edx,eax
fffff880`00d13e35 add     r8d,0FFFFFFFFh
fffff880`00d13e39 jne     CLFS!ClfsDecodeBlock+0x53 (fffff880`00d13e17)  Branch

Note that we won’t leave until R8D goes to zero.

However, at the time of the crash R8D is still 0x5eda00. Given that we’ve already gone off the end of the buffer, I’d say that you have a bad count value here somehow.

Tracking back a bit further, the R8D value comes from ((*(PUSHORT)(RCX+4)) << 9) and on this system started off as 0x601a00. Taking a working system and putting a breakpoint at the top of ClfsDecodeBlock I can see that this value seems to match up with the size of the overall allocation:

kd> !pool @rcx 2
Pool page fffff8a00d204000 region is Paged pool
*fffff8a00d204000 : large page allocation, tag is Clfs, size is 0x7a10 bytes
		Pooltag Clfs : CLFS General buffer, or owner page lookaside list, Binary : clfs.sys

kd> ?wo(@rcx+4) << 9
Evaluate expression: 31232 = 00000000`00007a00

Soooo based on the surrounding disassembly I’d say the code is trying to calculate the checksum of a chunk of the log. Presumably the length of the chunk is encoded in the header on the buffer and the CLFS walk of the buffer is unbounded. I’d want to dump out the buffer pointed to by RCX in your dump and see what it looks like, but I can’t do that with a minidump.

It seems possible to me that you’re returning the wrong data for this buffer and thus causing a crash in CLFS. That’s just my initial guess though and would need to look more at the buffer to have a chance of further ideas.

7

Thanks for this elaborate,
could try to produce full dump but not sure will it lead somewhere useful.
Think I am failing something else here (knowledge on upper layers).

…or maybe not properly filled counter value somewhere when I am returning no media device when drive is unmounted.
which is unfortunately almost everywhere :S, I only allow custom IO control code to pass trough so I could mount drive again,
otherwise I have everywhere following code:

    Irp->IoStatus.Status = STATUS_NO_MEDIA_IN_DEVICE;
    Irp->IoStatus.Information = 0;
    IoCompleteRequest(Irp, IO_NO_INCREMENT);        
    return STATUS_NO_MEDIA_IN_DEVICE;

discovered also if I keep my vd driver running, on system shutdown same PAGE_FAULT_IN_NONPAGED_AREA fault will occur.

the only I have working open source project that implements virtual drive is imdisk that returns STATUS_DEVICE_REMOVED when pending terminate:

if ((io_stack->MajorFunction == IRP_MJ_CREATE) &&
    KeReadStateEvent(&device_extension->terminate_thread))
{
    KdPrint(("ImDisk: Attempt to open device %i when shut down.\n",
        device_extension->device_number));
    status = STATUS_DEVICE_REMOVED;
    Irp->IoStatus.Status = status;
    Irp->IoStatus.Information = 0;
    IoCompleteRequest(Irp, IO_NO_INCREMENT);
    return status;
}

I will try later today recode to STATUS_DEVICE_REMOVED instead of STATUS_NO_MEDIA_IN_DEVICE (not sure will it help at all).
Will try also to examine again my unmount procedure, need to read a lot of more docs…

But in case if it doesn’t help: by knowing that ntfs has all fs transactions log to transactions log file, guess that CLFS.sys is responsible for upkeep of this transactions log files on volumes. So my best guess here is that CLFS.sys is upper driver somewhere in device tree (tried to see where it sits but DeviceTree doesn’t show nothing useful, I am guessing it has to be something like this DISK > PARTMGR > VOLUME > NTFS > CLFS order ?). And that is trying to IO/Read/Write to my device after I have “unmounted” drive. I though by checking Create/Close reference count I can keep track who else needs access to drive, and prevent unmount in such case (me so green), but it seams that CLFS opens each time transaction log file to write to it.
So in lames terms I need to instruct upper drivers to FLUSH BUFFERS/STOP/WAIT upper layers complete before I unmount drive.
Is there any documentation on subject for storage drivers how to do this, what would be necessary steps here?

8

could try to produce full dump but not sure will it lead somewhere useful.

I think looking at the buffer would be useful as it would help categorize the corruption of the buffer. But, hey, it’s your bug :slight_smile:

I will try later today recode to STATUS_DEVICE_REMOVED instead of STATUS_NO_MEDIA_IN_DEVICE (not sure will it help at all).

Device removed is a better error in this case but I don’t think that has anything to do with the crash.

So my best guess here is that CLFS.sys is upper driver somewhere in device tree

No, it’s just a export driver (DLL) that NTFS calls.

And that is trying to IO/Read/Write to my device after I have “unmounted” drive

No, that’s not correct. Just look at the call stack:

03 CLFS!ClfsDecodeBlock
04 CLFS!CClfsBaseFilePersisted::WriteMetadataBlock
05 CLFS!CClfsBaseFilePersisted::FlushImage
06 CLFS!CClfsLogFcbPhysical::FlushMetadata
07 CLFS!CClfsLogFcbVirtual::Cleanup
08 CLFS!CClfsLogCcb::Cleanup
09 CLFS!CClfsRequest::Cleanup
0a CLFS!ClfsDispatchIoRequest
0b CLFS!CClfsDriver::LogIoDispatch
0c nt!IopCloseFile
0d nt!ObpDecrementHandleCount
0e nt!ObpCloseHandleTableEntry
0f nt!ObpCloseHandle
10 nt!KiSystemServiceCopyEnd
11 nt!KiServiceLinkage
12 CLFS!ClfsCloseLogFileObject
13 nt!TmpTmOffline
14 nt!TmpCloseTransactionManager
15 nt!ObpDecrementHandleCount
16 nt!ObpCloseHandleTableEntry
17 nt!ObpCloseHandle
18 nt!KiSystemServiceCopyEnd
19 nt!KiServiceLinkage
1a Ntfs!TxfShutdownRm
1b Ntfs!TxfShutdownVolume
1c Ntfs!NtfsLockVolume
1d Ntfs!NtfsUserFsRequest

When you lock the volume NTFS shuts down the transaction manager for the volume. This in turn causes CLFS to flush out the log files that it is maintaining. It’s during this flush operation that CLFS trips over the bad block.

So, like I said, seems to ME that you’re returning the wrong data someplace.

9

Yes you are right BSOD occurs immediately on FSCTL_LOCK_VOLUME.
Which made me go through entire source code for IO CTRL codes step by step.
And discovered mistake I made:
I was originally using driver_extension->file_size to calculate everything and it was working fine.
later added offset from start of file (extended file for that size) and thought I have replaced everywhere for that offset (me green).
Forgot to accommodate for already existing file on disk where instead using original value sent by driver application I was using ZwQueryFileInformation (FILE_STANDARD_INFORMATION) which returned entire file size. And all the time I was using already existing raw disk file for mount.

The following code fixed BSOD:

// at this point file is created and EOF-ed, so we need to trunk our offset
device_extension->file_size.QuadPart = file_standard.EndOfFile.QuadPart - DISK_DATA_OFFSET;

DISK_DATA_OFFSET - size of VD header from start of file, after which actual raw disk data begins.

added logging to driver app so I could step trough each call write+flush to log (on VM shared drive) and _getch() :

BSOD log:

190103-043600.230 |  634 |   | int vdUmount(char DriveLetter:H)
190103-043600.230 |  634 |   | CreateFile(VolumeName:\\.\H:)
190103-043611.571 |  634 |   | DeviceIoControl(Device:64, FSCTL_LOCK_VOLUME)

After fixing log:

190103-053916.765 |  508 |   | int vdUmount(char DriveLetter:H)
190103-053916.765 |  508 |   | CreateFile(VolumeName:\\.\H:)
190103-053926.546 |  508 |   | DeviceIoControl(Device:64, FSCTL_LOCK_VOLUME)
190103-053940.212 |  508 |   | DeviceIoControl(Device:64, IOCTL_VD_CLOSE_FILE)
190103-053948.917 |  508 |   | DeviceIoControl(Device:64, FSCTL_DISMOUNT_VOLUME)
190103-053950.446 |  508 |   | DeviceIoControl(Device:64, FSCTL_UNLOCK_VOLUME)
190103-053951.709 |  508 |   | CloseHandle(Device:64)
190103-053952.926 |  508 |   | DefineDosDevice(DDD_REMOVE_DEFINITION, VolumeName:\\.\H:)
190103-053954.049 |  508 |   | SHChangeNotify(SHCNE_DRIVEREMOVED, SHCNF_PATH, DriveName:H:\, NULL);

Could try to trace which was exact Control Code which made this BSOD using incorrect data, but maybe some other time.
I was almost to give up on this driver and start new one…
so thanks a lot for helping me out and going into right direction :wink:

10

SoLaR wrote:

Yes you are right BSOD occurs immediately on FSCTL_LOCK_VOLUME.
Which made me go through entire source code for IO CTRL codes step by step.
And discovered mistake I made:
…
I was almost to give up on this driver and start new one…
so thanks a lot for helping me out and going into right direction

And thank YOU very much for posting your successful solution.  In so
many cases, threads like this fade away with no resolution, and that
doesn’t help the next person who has a similar problem.

11

Yes I know.
I was reading a lot of threads here, and in most cases there was no “end summary” on the subject.
And those most times got frustrated cause I’ve read entire threads on subject and there was no closure/conclusion.

Just a few thoughts:

  1. maybe this forum should implement some kind of system for marking threads as [SOLVED/COMPLETE,UNSOLVED/INCOMPLETE] or similar.
  2. marking single post in thread as answer as solution would be also very helpful.

This is only most active community on windows drivers (except few Russian communities) and some threads here are pure “Gold” that can’t be found anywhere on net. But also there is a lot of nonsense, and it is hard to sort one from the other very quickly without loosing minutes/hours reading them. Some system for sorting one from the other would certainly help.

best regards.