Deadlock in nt!CcAsyncReadWorker

DymOK93 · November 10, 2024, 11:07pm

Hi. I encountered what looks like a deadlock in the Cache Manager.

Let's start from afar. MyProcess.exe concurrently opens a file C:\x in two threads with RH oplock. First thread reads the file, second just closes it.
The file is also accessible via a network share \\share\x (via WebDAV redirector), and another process opens and reads it via the UNC path.

IRP_MJ_READ from MyProcess.exe's first thread is dispatched via ntfs!NtfsAsyncCachedReadRequest which acquires CB->PagingIoResource of C:\x shared and calls nt!CcAsyncCopyRead to post a request to the cache manager worker thread.

Cache Manager's thread with nt!CcAsyncReadWorker wakes up and does prefetch for \\share\x first:

nt!KiSwapContext+0x76
nt!KiSwapThread+0x17d
nt!KiCommitThreadWait+0x14f
nt!KeWaitForSingleObject+0x377
mrxdav!DavReadWriteFileEx+0x33a
mrxdav!MRxDAVReadContinuation+0x28f
mrxdav!UMRxAsyncEngOuterWrapper+0x193
mrxdav!MRxDAVRead+0x10e
rdbss!RxLowIoSubmit+0x33b
rdbss!RxCommonRead+0x5c5
rdbss!RxFsdCommonDispatch+0x55b
rdbss!RxFsdDispatch+0x86
mrxdav!MRxDAVFsdDispatch+0x6d1
mup!MupFsdIrpPassThrough+0xaa
FLTMGR!FltpDispatch+0xe2
nt!IoPageReadEx+0x2b0
nt!MiPfExecuteReadList+0xee
nt!MmPrefetchForCacheManager+0xe1
nt!CcAsyncReadPrefetch+0x135
nt!CcAsyncReadWorker+0x2ba
nt!PspSystemThreadStartup+0x41
nt!KiStartSystemThread+0x16

WebDav redirects the request to the local cache (C:\x), sending the nonpaged IRP_MJ_READ to NTFS. Because of this, NTFS worker thread hangs on exclusive acquisition of SCB.PagingIoResource:

nt!KiSwapContext+0x76
nt!KiSwapThread+0x17d
nt!KiCommitThreadWait+0x14f
nt!ExpWaitForResource+0x2a8
nt!ExAcquireResourceExclusiveLite+0x217
NTFS!NtfsCommonRead+0xb25
NTFS!NtfsFspDispatch+0x300
nt!ExpWorkerThread+0xe9
nt!PspSystemThreadStartup+0x41
nt!KiStartSystemThread+0x16

Things get even worse when the second thread of MyProcess.exe sends an IRP_MJ_CLEANUP from second thread that is processed with a shared VCB.Resource held: it's also trying to acquire SCB.PagingIoResource of C:\x.

After that, AnotherProcess1.exe tries to rename the file and hangs on the VCB.Resource exclusive acquition. Any further operations with the volume hang forever.

Deadlock graph:

Why doesn't the Cache Manager try to wake up another thread to handle the original IRP_MJ_READ?

rod_widdowson · November 11, 2024, 2:00pm

A few questions:

What's your role in this? Filter? FSD? Application
Where is the deadlock? In RDR or NTFS?
What does !locks say.
!stacks 2 nt!Cc might also be interesting.

Cachemanager provoked hangs are always challenging to debug, so prepare for a long haul

lucianpin · November 11, 2024, 2:11pm

Everything you add after that, to me look like only consequences, no need to focus on your second thread or another app if you say you already got the hang. The picture would be more useful if could show what exactly is the circular locking that would lead to dead lock. Or this is not known yet?

DymOK93 · November 11, 2024, 10:57pm

Thank you for the answers!
I've achieved some results in debugging, let me provide a more detailed description of initial circular locking.

My role is just an application - it opens local files for some scanning & hashing ("inventory") tasks.
Deadlock in NTFS
Output of some debugger commands (see the corresponding addresses in the picture):

> !locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks...... 
Resource @ 0xffff90844db38f90    Shared 1 owning threads
     Threads: ffff908449f299c3-01<*> *** Unknown owner, possibly FileSystem
KD: Scanning for held locks..
 
Resource @ 0xffff908454f69830    Shared 1 owning threads
    Contention Count = 3
    NumberOfSharedWaiters = 1
    NumberOfExclusiveWaiters = 2
     Threads: ffff90844b0fb113-01<*> *** Unknown owner, possibly FileSystem
              ffff9084588262c0-01<*> 
 
     Threads Waiting On Exclusive Access:
              ffff988943cf3040       ffff988945758800       
KD: Scanning for held locks.
 
Resource @ 0xffff9084510a61c0    Shared 1 owning threads
     Threads: ffff90845ada9803-01<*> *** Actual Thread 0xffff90845ada9800
 
Resource @ 0xffff9084510a6228    Shared 1 owning threads
     Threads: ffff908436df0043-01<*> *** Actual Thread 0xffff908436df0040
KD: Scanning for held locks.
 
Resource @ 0xffff908439ac47e0    Shared 1 owning threads
     Threads: ffff988935c50953-01<*> *** Unknown owner, possibly FileSystem
KD: Scanning for held locks.
 
Resource @ 0xffff9084528da100    Shared 1 owning threads
     Threads: ffff9889415a2973-01<*> *** Unknown owner, possibly FileSystem
232453 total locks, 6 locks currently held

0xffff90844db38f90 is SCB.PagingIoResource for local file. ffff90844b0fb113 is an "owner pointer" pointing to some NTFS structure:

> !pool 0xffff90844b0fb110 // clear 2 LSB
*ffff90844b0fb0e0 size:   60 previous size:   e0  (Allocated) *NtAR
        Pooltag NtAR : NTFS_ASYNC_CACHED_READ_CONTEXT, Binary : ntfs.sys
         
> dq ffff90844b0fb0e0 ffff90844b0fb0e0+60
...
ffff9084`4b0fb0f0  00000000`00000000 ffff9889`4b882928 --> IRP_CONTEXT* (see nt5src)
...        
> !pool ffff9889`4b882928
*ffff98894b882910 size:  250 previous size:  370  (Allocated) *Ntfi
        Pooltag Ntfi : IRP_CONTEXT, Binary : ntfs.sys
         
> dq ffff98894b882910+0n48
...
ffff9889`4b882970  ffff9889`3df59850 00000000`00000000  --> IRP* (see nt5src)
...        
 
> !irp ffff9889`3df59850 (Flags: 0x60900 -> IRP_READ_OPERATION | IRP_DEFER_IO_COMPLETION)
Irp is active with 9 stacks 9 is current (= 0xffff98893df59b60)
 Mdl=ffff988935ef9470: No System Buffer: Thread ffff988940a4d3c0:  Irp stack trace.  
     cmd  flg cl Device   File     Completion-Context
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
>[IRP_MJ_READ(3), N/A(0)]
            0  1 ffff90844169f030 ffff98894206aef0 00000000-00000000    pending
           \FileSystem\NTFS
            Args: 0000000a 00000000 00000000 00000000
             
THREAD ffff988940a4d3c0  Cid 8398.4a88  Teb: 00000051111d3000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable
    ffff9889468de490  NotificationEvent
IRP List:
    ffff98893df59850: (0006,03a0) Flags: 00060900  Mdl: ffff988935ef9470
    ffff9889995e1850: (0006,03a0) Flags: 00060870  Mdl: 00000000
Not impersonating
DeviceMap                 ffffc984f1c175e0
Owning Process            ffff9084528b6080       Image:         MyProcess.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      20273285       Ticks: 238003 (0:01:01:58.796)  // > 1h
Context Switch Count      4524           IdealProcessor: 61             
UserTime                  00:00:03.265
KernelTime                00:00:00.234
Win32 Start Address 0x00007ff705e609f0
Stack Init ffffa2015ff0b5d0 Current ffffa2015ff0b050
Base ffffa2015ff0c000 Limit ffffa2015ff05000 Call 0000000000000000
Priority 8  BasePriority 8  IoPriority 2  PagePriority 5
Kernel stack not resident.
Child-SP          RetAddr               : Args to Child                                                           : Call Site
ffffa201`5ff0b090 fffff802`7e8e768d     : 00000000`00000001 00000000`00000001 ffff9084`412077e0 ffff9889`3df59850 : nt!KiSwapContext+0x76
ffffa201`5ff0b1d0 fffff802`7e8e712f     : ffff9889`4206aef0 fffff802`7ed2b8ae ffff9889`4233a6c0 ffffb6a8`2b15f0db : nt!KiSwapThread+0x17d
ffffa201`5ff0b280 fffff802`7e8e8f07     : 00000000`00000000 fffff802`00000000 00000000`00000000 00000000`00000000 : nt!KiCommitThreadWait+0x14f
ffffa201`5ff0b320 fffff802`7ecee188     : ffff9889`468de490 00000000`00000006 00000000`00000000 00000053`00000000 : nt!KeWaitForSingleObject+0x377
ffffa201`5ff0b3d0 fffff802`7e97d103     : ffff9889`40a4d3c0 00000000`ffffffff 00000000`00000000 ffff9889`468de490 : nt!NtWaitForSingleObject+0xf8
ffffa201`5ff0b440 00007ffa`d0bf5ea4     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffa201`5ff0b440)
00000053`8e0fb758 00000000`00000000     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : 0x00007ffa`d0bf5ea4

And here is my (not yet completed) IRP.
4. One of the CC workers is waiting for mrxdav (note the wait ticks in this and previously mentioned threads), the others are sleeping, and the above-mentioned IRP is in the CC queue:

> !stacks 2 nt!Cc
Proc.Thread  .Thread  Ticks   ThreadState Blocker
                            [fffff8027ebcc940 Idle]
                            [ffff9084368aa040 System]
   4.000288  ffff908436df1040 000000d Blocked    nt!KiSwapContext+0x76
                                        nt!KiSwapThread+0x17d
                                        nt!KiCommitThreadWait+0x14f
                                        nt!KeWaitForMultipleObjects+0x1fe
                                        nt!CcQueueLazyWriteScanThread+0x96
                                        nt!PspSystemThreadStartup+0x41
                                        nt!KiStartSystemThread+0x16
   4.00028c  ffff908436df0040 003a1b3 Blocked    nt!KiSwapContext+0x76
                                        nt!KiSwapThread+0x17d
                                        nt!KiCommitThreadWait+0x14f
                                        nt!KeWaitForSingleObject+0x377
                                        mrxdav!DavReadWriteFileEx+0x33a
                                        mrxdav!MRxDAVReadContinuation+0x28f
                                        mrxdav!UMRxAsyncEngOuterWrapper+0x193
                                        mrxdav!MRxDAVRead+0x10e
                                        rdbss!RxLowIoSubmit+0x33b
                                        rdbss!RxCommonRead+0x5c5
                                        rdbss!RxFsdCommonDispatch+0x55b
                                        rdbss!RxFsdDispatch+0x86
                                        mrxdav!MRxDAVFsdDispatch+0x6d1
                                        mup!MupFsdIrpPassThrough+0xaa
                                        FLTMGR!FltpDispatch+0xe2
                                        nt!IoPageReadEx+0x2b0
                                        nt!MiPfExecuteReadList+0xee
                                        nt!MmPrefetchForCacheManager+0xe1
                                        nt!CcAsyncReadPrefetch+0x135
                                        nt!CcAsyncReadWorker+0x2ba
                                        nt!PspSystemThreadStartup+0x41
                                        nt!KiStartSystemThread+0x16
   4.000290  ffff908436fe7040 138f98c Blocked    nt!KiSwapContext+0x76
                                        nt!KiSwapThread+0x17d
                                        nt!KiCommitThreadWait+0x14f
                                        nt!KeWaitForSingleObject+0x377
                                        nt!CcAsyncReadWorker+0x201
                                        nt!PspSystemThreadStartup+0x41
                                        nt!KiStartSystemThread+0x16
   4.000294  ffff908436fff040 138f98c Blocked    nt!KiSwapContext+0x76
                                        nt!KiSwapThread+0x17d
                                        nt!KiCommitThreadWait+0x14f
                                        nt!KeWaitForSingleObject+0x377
                                        nt!CcAsyncReadWorker+0x201
                                        nt!PspSystemThreadStartup+0x41
                                        nt!KiStartSystemThread+0x16
> !thread 0xffff908436df0040
THREAD ffff908436df0040  Cid 0004.028c  Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable
    ffffa2015cdc37e0  NotificationEvent
IRP List:
    ffff908458d93010: (0006,01f0) Flags: 00060403  Mdl: ffff9889327c7f50
Not impersonating
DeviceMap                 ffffc984f1c175e0
Owning Process            ffff9084368aa040       Image:         System
Attached Process          N/A            Image:         N/A
Wait Start TickCount      20273285       Ticks: 238003 (0:01:01:58.796)  // > 1h
Context Switch Count      50347          IdealProcessor: 74             
UserTime                  00:00:00.000
KernelTime                00:00:01.031
Win32 Start Address nt!CcAsyncReadWorker (0xfffff8027e949010)
Stack Init ffffa2015cdc45d0 Current ffffa2015cdc3410
Base ffffa2015cdc5000 Limit ffffa2015cdbe000 Call 0000000000000000
Priority 8  BasePriority 8  IoPriority 2  PagePriority 5
Child-SP          RetAddr               : Args to Child                                                           : Call Site
ffffa201`5cdc3450 fffff802`7e8e768d     : 00000000`00000001 00000000`00000001 00000000`00000000 00000000`00000000 : nt!KiSwapContext+0x76
ffffa201`5cdc3590 fffff802`7e8e712f     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiSwapThread+0x17d
ffffa201`5cdc3640 fffff802`7e8e8f07     : 00000000`00000000 fffff804`42039000 ffff9889`35d3d470 00000000`00000000 : nt!KiCommitThreadWait+0x14f
ffffa201`5cdc36e0 fffff804`4204abf6     : ffffa201`5cdc37e0 ffff9084`00000000 00000000`00000000 fffff802`00000000 : nt!KeWaitForSingleObject+0x377
ffffa201`5cdc3790 fffff804`42049dcf     : 00000000`00000031 00000000`00000000 ffffa201`00000001 ffff9889`327c7f50 : mrxdav!DavReadWriteFileEx+0x33a
ffffa201`5cdc3840 fffff804`42055243     : ffff9889`3d88c8b0 ffff9889`41619010 ffff9889`41619000 fffff804`00000000 : mrxdav!MRxDAVReadContinuation+0x28f
ffffa201`5cdc3910 fffff804`42049aee     : ffff9889`41619010 00000000`00000000 ffff9889`3d88c8b0 fffff804`42748910 : mrxdav!UMRxAsyncEngOuterWrapper+0x193
ffffa201`5cdc3970 fffff804`427489ab     : ffff9889`41619010 ffff9889`41619010 00000000`c000000d ffffa201`5cdc3aa0 : mrxdav!MRxDAVRead+0x10e
ffffa201`5cdc39b0 fffff804`4274c6f5     : ffff9889`41619208 ffff9084`53ae6cd0 ffffc985`198dc010 ffffc985`198dc010 : rdbss!RxLowIoSubmit+0x33b
ffffa201`5cdc3a20 fffff804`42702acb     : ffff9889`41619010 ffff9084`47bd0040 ffff9889`41619010 ffff9084`58d93010 : rdbss!RxCommonRead+0x5c5
ffffa201`5cdc3b70 fffff804`4273f486     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : rdbss!RxFsdCommonDispatch+0x55b
ffffa201`5cdc3cf0 fffff804`42045751     : ffffc985`01c794c0 fffff804`418666a6 ffff9889`471744c8 fffff802`7e9ffec1 : rdbss!RxFsdDispatch+0x86
ffffa201`5cdc3d40 fffff804`4283eb3a     : ffff9084`47bd0040 ffff9084`58d93010 00000000`00000003 fffff802`7e8db100 : mrxdav!MRxDAVFsdDispatch+0x6d1
ffffa201`5cdc3e10 fffff804`40f42eb2     : ffff9084`36df06a8 fffff802`7e8a3572 00000000`00000000 00000000`00000000 : mup!MupFsdIrpPassThrough+0xaa
ffffa201`5cdc3e90 fffff802`7e8eff80     : ffff9084`58d93010 ffff9889`327c7ea0 00000000`00000000 ffff9084`58d93010 : FLTMGR!FltpDispatch+0xe2
ffffa201`5cdc3ef0 fffff802`7ecb3ffe     : ffff9889`327c7e50 00000000`00000001 ffff9889`327c7eb0 ffff9889`327c7e70 : nt!IoPageReadEx+0x2b0
ffffa201`5cdc3f60 fffff802`7ecb3e89     : ffff9889`409699a0 00000000`00000003 00000000`ffffffff 00000000`00000000 : nt!MiPfExecuteReadList+0xee
ffffa201`5cdc3fe0 fffff802`7e87176d     : ffff9084`4de6e790 00000000`00029000 ffff9889`409699a0 ffffa201`5cdc41d0 : nt!MmPrefetchForCacheManager+0xe1
ffffa201`5cdc4040 fffff802`7e9492ca     : ffff9084`00005146 ffff9084`00000000 00000000`00029277 00000000`00029000 : nt!CcAsyncReadPrefetch+0x135
ffffa201`5cdc40d0 fffff802`7e855fb5     : ffff9084`36df0040 ffff9084`36df0040 fffff802`7e949010 ffff9084`36be68e0 : nt!CcAsyncReadWorker+0x2ba
ffffa201`5cdc4550 fffff802`7e974296     : ffffa201`5b044180 ffff9084`36df0040 fffff802`7e855f74 ffffed51`e6109080 : nt!PspSystemThreadStartup+0x41
ffffa201`5cdc45a0 00000000`00000000     : ffffa201`5cdc5000 ffffa201`5cdbe000 00000000`00000000 00000000`00000000 : nt!KiStartSystemThread+0x16

> !irp ffff908458d93010 (Flags: 0x60403 -> IRP_NOCACHE | IRP_PAGING_IO)
Irp is active with 4 stacks 4 is current (= 0xffff908458d931b8)
 Mdl=ffff9889327c7f50: No System Buffer: Thread ffff908436df0040:  Irp stack trace.  
     cmd  flg cl Device   File     Completion-Context
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    

			Args: 00000000 00000000 00000000 00000000
>[IRP_MJ_READ(3), N/A(0)]
            0  1 ffff908447bd0040 ffff908453ae6cd0 00000000-00000000    pending
	       \FileSystem\MRxDAV
			Args: 00004000 00000000 0002a000 00000000

WebDAV redirector has sent another IRP to NTFS, but NTFS can't process it

> !irp ffff9889`35d3d470 (Flags: 0x1 -> IRP_NOCACHE)
Irp is active with 9 stacks 8 is current (= 0xffff988935d3d738)
 Mdl=ffff908453f87f40: No System Buffer: Thread ffff908436df0040:  Irp stack trace.  
     cmd  flg cl Device   File     Completion-Context
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-00000000    
 
            Args: 00000000 00000000 00000000 00000000
>[IRP_MJ_READ(3), N/A(0)]
            0 e1 ffff90844169f030 ffff908455fdaef0 fffff80440f42c10-ffff9889366d55d0 Success Error Cancel pending
           \FileSystem\NTFS    FLTMGR!FltpPassThroughCompletion
            Args: 00004000 00000000 0002a000 00000000
 [IRP_MJ_READ(3), N/A(0)]
            0 e1 ffff90844121f590 ffff908455fdaef0 fffff80442033270-ffffa2015cdc37e0 Success Error Cancel pending
           \FileSystem\FltMgr    mrxdav!DavIrpCompletionRoutine
            Args: 00004000 00000000 0002a000 00000000
 
> !thread  ffff988943cf3040  // NTFS Async Worker
THREAD ffff988943cf3040  Cid 0004.4aac  Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (WrResource) KernelMode Non-Alertable
    ffff988940447250  SynchronizationEvent
Not impersonating
DeviceMap                 ffffc984f1c175e0
Owning Process            ffff9084368aa040       Image:         System
Attached Process          N/A            Image:         N/A
Wait Start TickCount      20511199       Ticks: 89 (0:00:00:01.390)
Context Switch Count      34896          IdealProcessor: 66             
UserTime                  00:00:00.000
KernelTime                00:00:00.796
Win32 Start Address nt!ExpWorkerThread (0xfffff8027e8a5170)
Stack Init ffffa2016c04f5d0 Current ffffa2016c04ed50
Base ffffa2016c050000 Limit ffffa2016c049000 Call 0000000000000000
Priority 13  BasePriority 13  IoPriority 2  PagePriority 5
Child-SP          RetAddr               : Args to Child                                                           : Call Site
ffffa201`6c04ed90 fffff802`7e8e768d     : 00000000`00000001 00000000`00000001 00000000`00000000 00000000`0000000d : nt!KiSwapContext+0x76
ffffa201`6c04eed0 fffff802`7e8e712f     : ffff9889`43cf3040 ffff9889`43cf3140 ffffa201`5b056580 00000000`00000000 : nt!KiSwapThread+0x17d
ffffa201`6c04ef80 fffff802`7e8e93e8     : ffff8281`00000000 ffff9084`54f69830 00000000`000000f4 ffff9889`43cf3040 : nt!KiCommitThreadWait+0x14f
ffffa201`6c04f020 fffff802`7e9182e7     : ffff9084`54f69830 ffff9889`40447250 ffff9084`00000300 ffff8281`00000000 : nt!ExpWaitForResource+0x2a8
ffffa201`6c04f0f0 fffff804`418672b5     : 00000000`00000000 ffffa201`6c04f380 ffff9084`4169f100 ffff9889`43cf3040 : nt!ExAcquireResourceExclusiveLite+0x217
ffffa201`6c04f170 fffff804`4187f690     : ffff9889`471744c8 ffff9889`35d3d470 ffff9889`47174401 00000000`11000000 : NTFS!NtfsCommonRead+0xb25
ffffa201`6c04f340 fffff802`7e8a5259     : ffffa201`5b056400 ffff9889`43cf3040 ffff9889`47174538 ffffa201`5b056580 : NTFS!NtfsFspDispatch+0x300
ffffa201`6c04f4c0 fffff802`7e855fb5     : ffff9889`43cf3040 00000000`00000080 ffff9084`368aa040 ffff9889`43cf3040 : nt!ExpWorkerThread+0xe9
ffffa201`6c04f550 fffff802`7e974296     : ffffa201`5b9cc180 ffff9889`43cf3040 fffff802`7e855f74 00000000`00000246 : nt!PspSystemThreadStartup+0x41
ffffa201`6c04f5a0 00000000`00000000     : ffffa201`6c050000 ffffa201`6c049000 00000000`00000000 00000000`00000000 : nt!KiStartSystemThread+0x16

I don't understand why my IRP in the CC queue hasn't been completed. It's unlikely that none of the workers have woken up in an hour. Maybe IRP was repeatedly inserted into the queue again?

DymOK93 · November 14, 2024, 12:52am

As I understood from the definition of CC_ASYNC_READ_CONTEXT in ntifs.h:

//
//  Async read request context
//

typedef struct _CC_ASYNC_READ_CONTEXT {

    ...

    //
    //  Virtual Disk Nesting Level
    //

    ULONG NestingLevel;

} CC_ASYNC_READ_CONTEXT, *PCC_ASYNC_READ_CONTEXT;

the Cache Manager creates an independent work queue and thread for each VHD Nesting Level (maximum - 2, i.e. "0, 1, 2"). In my case only "0" worker queue is used.

It turns out that the cyclic lock is a violation of mrxdav.sys.
It's received an IRP with flags IRP_NOCACHE | IRP_PAGING_IO from thread with FSRTL_ASYNC_CACHED_READ_TOP_LEVEL_IRP, but sent an IRP to the local NTFS without the IRP_PAGING_IO flag.

Possible confirmation: my OS is Windows Server 2016. In more modern versions of Windows 10 and Windows Server 2019, the implementation of mrxdav!DavReadWriteFileEx() has changed.
It was, according to IDA Pro disassembly:

Irp = IoAllocateIrp(...);
Irp->Flags |= IRP_NOCACHE;

TopLevelIrp = IoGetTopLevelIrp();
IoSetTopLevelIrp(NULL);
status = IoCallDriver(...);
IoSetTopLevelIrp(TopLevelIrp);

if (status == STATUS_PENDING) 
   keWaitForSingleObject(Event, ...);

It became:

Irp = IoAllocateIrp(...);
Flags = SomethingLikeOriginalIrpFlags & IRP_PAGING_IO;  // passed as the 10th parameter of the function
Irp->Flags |= Flags | IRP_NOCACHE;

TopLevelIrp = IoGetTopLevelIrp();
IoSetTopLevelIrp(NULL);
status = IoCallDriver(...);
IoSetTopLevelIrp(TopLevelIrp);

if (status == STATUS_PENDING) 
   keWaitForSingleObject(Event, ...);

system · December 14, 2024, 12:53am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.