Debugging Minifilters: Finding the FLT_CALLBACK_DATA - Part II

In the post last week I've shown how to get to the FLT_CALLBACK_DATA when the original thread where the minifilter's callback was called is still available. This week I want to talk about pending. There are multiple scenarios to discuss, depending on who pends the IRP (the minifilter or a legacy filter or the file system) and where processing is with regards to the IRP (FltMgr still processing it or after it's been sent down).

When a minifilter is pending a request and processes it in a different thread, the original thread might not be available anymore so we can't rely on that to find the call to fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted. A real-world case where this might happen is when after installing such a minifilter the system freezes. By looking at the various threads one can see that some thread is blocked waiting for a request to complete but it's hard to tell if that IRP is stuck in the queue of some minifilter or which minifilter that might be. For this example I'll use an unmodified WDK sample, cancelSafe, which shows how a minifilter should implement pending of requests. This is what the threads involved in the process look like (using the same color scheme from the previous post for the IRP, FLT_VOLUME, IRP_CALL_CTRL and FLT_CALLBACK_DATA):

0: kd> !thread 981d68e0  
THREAD 981d68e0  Cid 0b00.0b04  Teb: 7ffdf000 Win32Thread: fe78aa90 WAIT: (Executive) UserMode Non-Alertable
    921c8f14  NotificationEvent
IRP List:
    bc57ce28: (0006,01d8) Flags: 40060900  Mdl: 00000000
    b83dae28: (0006,01d8) Flags: 40060000  Mdl: 00000000
Not impersonating
DeviceMap                 94529c98
Owning Process            b62124b8       Image:         Far.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      11251          Ticks: 763 (0:00:00:11.921)
Context Switch Count      59079             
UserTime                  00:00:00.140
KernelTime                00:00:04.984
Win32 Start Address 0x004ed48a
Stack Init b3989fd0 Current b3989b58 Base b398a000 Limit b3987000 Call 0
Priority 9 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
ChildEBP RetAddr  Args to Child              
b3989b70 828c0b25 981d68e0 8297ef08 8297bd20 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])
b3989ba8 828bf423 981d69a0 981d68e0 921c8f14 nt!KiSwapThread+0x266
b3989bd0 828b92cf 981d68e0 981d69a0 00000000 nt!KiCommitThreadWait+0x1df
b3989c48 82a8ffe6 921c8f14 00000000 00000101 nt!KeWaitForSingleObject+0x393
b3989c7c 82aa1f32 00000103 921c8eb8 00000001 nt!IopSynchronousServiceTail+0x270
b3989d08 8289544a 979133a8 bc57ce28 00000000 nt!NtReadFile+0x644
b3989d08 770564f4 979133a8 bc57ce28 00000000 nt!KiFastCallEntry+0x12a (FPO: [0,3] TrapFrame @ b3989d34)
WARNING: Frame IP not in any known module. Following frames may be wrong.
00129e68 00000000 00000000 00000000 00000000 0x770564f4

0: kd> !irp bc57ce28
Irp is active with 10 stacks 10 is current (= 0xbc57cfdc)
 No Mdl: No System Buffer: Thread 981d68e0:  Irp stack trace.  
     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
 [  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
 [  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
 [  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
 [  0, 0]   0 10 00000000 00000000 00000000-00000000    

   Args: 00000000 00000000 00000000 00000000
>[  3, 0]   0  1 979133a8 921c8eb8 00000000-00000000    pending
        \FileSystem\FltMgr
   Args: 00001000 00000000 00000000 00000000

So we can see that the IRP is pending, and that it's pending somewhere inside FltMgr. This usually means that a minifilter pended it because FltMgr doesn't pend IRPs on its own. So let's look at what is in the IRP's DriverContext:

0: kd> dt bc57ce28 nt!_IRP -a Tail.Overlay.DriverContext
   +0x040 Tail                       : 
      +0x000 Overlay                    : 
         +0x000 DriverContext              : 
          [00] (null) 
          [01] 0xbb9a6e40 Void
          [02] (null) 
          [03] 0x98049ea8 Void
0: kd> !fltkd.cbd 0xbb9a6e40 

IRP_CTRL: bb9a6de0  READ (3) [00000001] Irp
Flags                    : [10000004] DontCopyParms FixedAlloc
Irp                      : bc57ce28 
DeviceObject             : 979133a8 "\Device\HarddiskVolume2"
FileObject               : 921c8eb8 
CompletionNodeStack      : bb9a6e98   Size=5  Next=0
SyncEvent                : (bb9a6df0)
InitiatingInstance       : 00000000 
Icc                      : b3989c0c 
PendingCallbackNode      : baacefb4 
PendingCallbackContext   : 00000000 
PendingStatus            : 0x00000000 
CallbackData             : (bb9a6e40)
 Flags                    : [00000001] Irp
 Thread                   : 981d68e0 
 Iopb                     : bb9a6e6c 
 RequestorMode            : [01] UserMode
 IoStatus.Status          : 0x00000000 
 IoStatus.Information     : 00000000 
 TagData                  : 00000000 
 FilterContext[0]         : b7c46fc4 
 FilterContext[1]         : b7c46fc4 
 FilterContext[2]         : 98049ea8 
 FilterContext[3]         : 00000000 

   Cmd     IrpFl   OpFl  CmpFl  Instance FileObjt Completion-Context  Node Adr
--------- -------- ----- -----  -------- -------- ------------------  --------
 [0,0]    00000000  00   0000   00000000 00000000 00000000-00000000   bb9a6fb8
     Args: 00000000 00000000 00000000 00000000 00000000 0000000000000000
 [0,0]    00000000  00   0000   00000000 00000000 00000000-00000000   bb9a6f70
     Args: 00000000 00000000 00000000 00000000 00000000 0000000000000000
 [0,0]    00000000  00   0000   00000000 00000000 00000000-00000000   bb9a6f28
     Args: 00000000 00000000 00000000 00000000 00000000 0000000000000000
 [0,0]    00000000  00   0000   00000000 00000000 00000000-00000000   bb9a6ee0
     Args: 00000000 00000000 00000000 00000000 00000000 0000000000000000
 [0,0]    00000000  00   0000   00000000 00000000 00000000-00000000   bb9a6e98
     Args: 00000000 00000000 00000000 00000000 00000000 0000000000000000
Working IOPB:
>[3,0]    40060900  00          baaceea0 921c8eb8                     bb9a6e6c
            ("CancelSafe","CancelSafe Instance")  
     Args: 00001000 00000000 00000000 00000000 0183e6d0 0000000000000000

So as you can see the Tail.Overlay.DriverContext[1] has a pointer to the IRP_CTRL structure associated with the IRP. As far as I can tell this is set both by the FltCbdqXxx routines as well as by FltSetCancelCompletion(). This means that minifilters can benefit from this even if they aren't using the FltCbdqXxx routines for whatever reason (though frankly they should use those routines pretty much every time they're delaying processing of a request). So this makes the process of finding an FLT_CALLBACK_DATA associated with an IRP that is pended by a minifilter a fairly straightforward thing.

Another question is what happens when the IRP reaches the file system or a different legacy filter after being pended by a minifilter. This is different from the case where the minifilter didn't pend the request (which we discussed last week) because this is a different stack from the original stack the IO was issued on, so there is no fltmgr!FltpDispatch to call fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted in this case. But nevertheless, as you may have guessed from the name, fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted will be called once all the preOp callbacks for the frame have been called anyway so we still can use the first parameter for it:

0: kd> kb
ChildEBP RetAddr  Args to Child              
94f13ba0 9267dbae b7deaee0 bc57ce28 069b05e3 Ntfs!NtfsCommonRead
94f13c10 82b816c3 97914020 bc57ce28 00000000 Ntfs!NtfsFsdRead+0x279
94f13c34 8288e473 00000000 bc57ce28 97914020 nt!IovCallDriver+0x258
94f13c48 9262620c 8288e3f1 00000000 baaceea0 nt!IofCallDriver+0x1b
94f13c6c 92629df7 94f13c84 979133a8 00000001 fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted+0x2aa
94f13c9c b08c0831 bb9a6e40 00000001 00000000 fltmgr!FltCompletePendedPreOperation+0x8b
94f13ccc 926453c8 bc5c4fc8 baaceea0 baaceea0 CancelSafe!PreReadWorkItemRoutine+0x131 [c:\temp6\cancelsafe\cancelsafe.c @ 1537]
94f13d00 828bff3b 00000000 00000000 82fae020 fltmgr!FltpProcessGenericWorkItem+0x38
94f13d50 82a606d3 00000001 ccd6e460 00000000 nt!ExpWorkerThread+0x10d
94f13d90 829120f9 828bfe2e 00000001 00000000 nt!PspSystemThreadStartup+0x9e
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x19
0: kd> dt 94f13c84 fltmgr!_IRP_CALL_CTRL
   +0x000 Volume           : 0x94de4ae0 _FLT_VOLUME
   +0x004 Irp              : 0xbc57ce28 _IRP
   +0x008 IrpCtrl          : 0xbb9a6de0 _IRP_CTRL
   +0x00c StartingCallbackNode : 0xbaacefb4 _CALLBACK_NODE
   +0x010 OperationStatusCallbackListHead : _SINGLE_LIST_ENTRY
   +0x014 Flags            : 1 ( ICCFL_SKIP_STARTING_NODE )

Finally, there is one more case to consider, the case of the IRP being pended after FltMgr called fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted, in either a legacy filter below the frame or in the file system. In this case there is no call to fltmgr!FltpLegacyProcessingAfterPreCallbacksCompleted on the stack and Tail.Overlay.DriverContext[1] has no reason to point to the FLT_CALLBACK_DATA. In this case the IRP_CTRL structure can be found as the context for the completion routine on the IRP:

0: kd> !irp 0xbc57ce28 
Irp is active with 10 stacks 9 is current (= 0xbc57cfb8)
 Mdl=b7dc2fd8: No System Buffer: Thread 981d68e0:  Irp stack trace.  
     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
 [  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
 [  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
 [  0, 0]   0  0 00000000 00000000 00000000-00000000    

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

   Args: 00000000 00000000 00000000 00000000
>[  3, 0]   0 e0 97914020 921c8eb8 92625aae-bb9a6de0 Success Error Cancel 
        \FileSystem\Ntfs fltmgr!FltpPassThroughCompletion
   Args: 00001000 00000000 00000000 00000000
 [  3, 0]   0  1 979133a8 921c8eb8 00000000-00000000    pending
        \FileSystem\FltMgr
   Args: 00001000 00000000 00000000 00000000

Finally there are a couple of things I'd like to mention:

• There is a FLT_CALLBACK_DATA structure per frame, so if there are multiple frames you need to find the right frame for your filter before looking for the right FLT_CALLBACK_DATA. The IRP_CALL_CTRL structure actually starts with a FLT_VOLUME pointer which is also unique per frame and so if you find the IRP_CALL_CTRL you can quickly check if it is the right one by checking whether !fltkd.volume shows your filter as belonging to that volume.
  
• Even when looking at the right FLT_CALLBACK_DATA you might not see any entry for your filter if you did not return FLT_PREOP_SUCCESS_WITH_CALLBACK or FLT_PREOP_SYNCHRONIZE from the preOp callback.
  
• The FLT_CALLBACK_DATA has a pointer to the IRP which is why I focused only on finding the FLT_CALLBACK_DATA given the IRP.
  
• I've been using the terms FLT_CALLBACK_DATA and IRP_CTRL interchangeably in this post, and i've even colored them with the same color. That's because from the perspective of this article we don't care about the differences between them and !fltkd.cbd can work with either one.