DRIVER_POWER_STATE_FAILURE (9f) issue with Minifilter driver

vvlsek

My driver crashes sporadically with the below bug check.

DRIVER_POWER_STATE_FAILURE (9f)
A driver has failed to complete a power IRP within a specific time.
Arguments:
Arg1: 0000000000000003, A device object has been blocking an IRP for too long a time
Arg2: ffffa702db867360, Physical Device Object of the stack
Arg3: fffffc8dc1aa7118, nt!TRIAGE_9F_POWER on Win7 and higher, otherwise the Functional Device Object of the stack
Arg4: ffffa702f89075a0, The blocked IRP

Initial understanding is that when there is power state change driver crashes. However when we put the machine to sleep, driver doesnt crash. we dont have repo step to reproduce it.
should we handle anything for power IRPs in minifilter driver?
can we call ExRegistercallback with \Callback\PowerState so that I can unload the driver when machine goes to sleep? Not sure whether it is correct approach.
I couldnt get much from the dump though. I could see my driver sending events to the usermode service during the crash.

My driver works in synchronous model. for every reg/file/process event it calls Fltsendmessage to send the event to user mode where we get the verdict and send it to driver for it to either block or allow.

Any pointers? Not sure where to start and look for this issue.
Thanks in advance

rod_widdowson

Not a clue, but I’d start by looking at the irp and then see whether you are in the loop (if filter manager is on the irp stack the cbd is usually the parameter at that stack location )

Scott_Noone_(OSR)

Power state transitions are handled by the System process so look for a thread stuck there:

!process 0 f System

There are also power related debugging commands:

!poaction
!powertriage

vvlsek

: kd> !poaction
PopAction: fffff8066c03c9e0
  State..........: 0 - Idle
  Updates........: 0 
  Action.........: None
  Lightest State.: Unspecified
  Flags..........: 10000003 QueryApps|UIAllowed
  Irp minor......: ??
  System State...: Unspecified
  Hiber Context..: 0000000000000000

Allocated power irps (PopIrpList - fffff8066c03d200)
  IRP: ffffb08f357a0c30 (wait-wake/S3), PDO: ffffb08f2d3292c0

Irp worker threads (PopIrpThreadList - fffff8066c03a1f0)
  THREAD: ffffb08f0f2a5040 (static)
  THREAD: ffffb08f0f294040 (static)
  THREAD: ffffb08f4395e040 (dynamic), IRP: ffffb08f2d81fb20, DEVICE: ffffb08f29f96030

Error resolving nt!_POP_CURRENT_BROADCAST...

Transition Thread Stack:
Entry 1:
  - Process: 0x0
  - Recorded Time: 0x0
  - Callback: 0x0
  - Context: 0x0

00000000: Unable to get thread contents


0: kd> !devobj 0xffffb08f2d3292c0
Device object (ffffb08f2d3292c0) is for:
 InfoMask field not found for _OBJECT_HEADER at ffffb08f2d329290
Unable to load image \SystemRoot\System32\DriverStore\FileRepository\intcoed.inf_amd64_dd6a7ef14d856351\IntcOED.sys, Win32 error 0n2
*** WARNING: Unable to verify timestamp for IntcOED.sys
 \Driver\IntcOED DriverObject ffffb08f2d332e30
Current Irp 00000000 RefCount 34 Type 0000001d Flags 00003044
SecurityDescriptor ffff810971cce0a0 DevExt ffffb08f2d96ee60 DevObjExt ffffb08f2d329438 DevNode ffffb08f2d7e9770 
ExtensionFlags (0x00000800)  DOE_DEFAULT_SD_PRESENT
Characteristics (0x00000180)  FILE_AUTOGENERATED_DEVICE_NAME, FILE_DEVICE_SECURE_OPEN
AttachedDevice (Upper) ffffb08f2dc1e050Unable to load image \SystemRoot\system32\drivers\RTKVHD64.sys, Win32 error 0n2
*** WARNING: Unable to verify timestamp for RTKVHD64.sys
 \Driver\IntcAzAudAddService
Device queue is not busy.
0: kd> !irp 0xffffb08f357a0c30
Irp is active with 8 stacks 6 is current (= 0xffffb08f357a0e68)
 No Mdl: No System Buffer: Thread 00000000:  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


  [IRP_MJ_POWER(16), IRP_MN_WAIT_WAKE(0)]


            0  1 ffffb08f2d3292c0 00000000 00000000-00000000    pending
           \Driver\IntcOED
            Args: 00000004 00000000 00000000 00000000
 [IRP_MJ_POWER(16), IRP_MN_WAIT_WAKE(0)]
            0 e0 ffffb08f2ccd4e00 00000000 fffff8066b7a6be0-ffffb08f4bfb28b0 Success Error Cancel 
           \Driver\ksthunk  nt!PopRequestCompletion
            Args: 00000004 00000000 00000000 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-ffffb08f4bfb28b0    

            Args: 00000000 00000000 00000000 00000000
0: kd> !drvobj \Driver\ksthunk
Driver object \Driver\ksthunk not found
0: kd> !drvobj \Driver\IntcOED
Driver object \Driver\IntcOED not found
0: kd> !irp ffffb08f2d81fb20
Irp is active with 6 stacks 5 is current (= 0xffffb08f2d81fd10)
 No Mdl: No System Buffer: Thread 00000000:  Irp stack trace.  Pending has been returned
     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_POWER(16), IRP_MN_WAIT_WAKE(0)]
            0  0 ffffb08f0fd4a360 00000000 fffff8067773fe90-fffff08355940298    
           \Driver\pci  dxgkrnl!DpiFdoPowerCompletionRoutine
            Args: 00000000 00000000 00000000 00000000


  [IRP_MJ_POWER(16), IRP_MN_SET_POWER(2)]


            0 e1 ffffb08f29f96030 00000000 fffff8066b7a6be0-ffffb08f2fa8d730 Success Error Cancel pending
          Unable to load image \SystemRoot\System32\DriverStore\FileRepository\iigd_dch.inf_amd64_9b41cef4891594fc\igdkmdn64.sys, Win32 error 0n2
*** WARNING: Unable to verify timestamp for igdkmdn64.sys
 \Driver\igfxn  nt!PopRequestCompletion
            Args: 00000000 00000001 00000001 00000000
 [N/A(0), N/A(0)]
            0  0 00000000 00000000 00000000-ffffb08f2fa8d730    

            Args: 00000000 00000000 00000000 00000000
0: kd> kb
  *** Stack trace for last set context - .thread/.cxr resets it
 # RetAddr               : Args to Child                                                           : Call Site
00 fffff806`6b637825     : 00000000`00000002 00000000`00000000 ffffb08f`0f2bc250 fffff806`6bb2a468 : nt!KiSwapContext+0x76
01 fffff806`6b638c47     : ffffb08f`0f55c000 fffff806`6b64f9a8 fffff806`6b400000 00000000`00000000 : nt!KiSwapThread+0xb05
02 fffff806`6b6ac5df     : ffff0000`00000000 ffff8109`00000001 fffff806`00000000 00000000`00000000 : nt!KiCommitThreadWait+0x137
03 fffff806`6bb2ea11     : 00000036`b4abbe37 00000000`00989680 00000000`00000000 fffff806`6b639445 : nt!KeWaitForMultipleObjects+0x2df
04 fffff806`69e817a5     : 00000000`00000000 ffffb08f`46be1370 ffffb08f`3205aae0 ffffb08f`32486070 : nt!FsRtlCancellableWaitForMultipleObjects+0x91
05 fffff806`71a12fdc     : ffffb08f`323c9aa0 fffff083`5593e988 ffffb08f`4b749a00 00000000`0000008d : FLTMGR!FltSendMessage+0x1b5
06 00000000`00000000     : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : mydriver!ProcessEventEx+0x1b4 

I could see my driver sending messgae to usermode and waiting for the reply. For some reason it did not receive a reply from application.
Is there a way to capture the running application/services from the dump?

I wanted to know whether my application is running or for some reason it got terminated and the driver is waiting/getting blocked for a reply from the application.

Is there a way/command to know this from dump?

Scott_Noone_(OSR)

You can look at your user mode service with:

!process 0 1f name.exe

That will show you the user mode stacks if it's a full memory dump and they're paged in. If it's a kernel summary dump you won't see anything in user mode, though it should show you your process if it's running.

vvlsek

Mine is just a 4MB dump..not complete memory dump. The above command did not display any data..so not sure whether my application was running at that moment or not..
so I tried the following..
Manually killed the application from task manager and put the machine to sleep mode. I could see the crash where stack trace is exactly matching.
My hypothesis is that this crash happens when application crashed/terminated and driver is waiting for the update from application and machine goes to sleep mode.
when I further debugged I figured out that unload callback routine is not called when application is terminated or crashed. it gets called only when the application is stopped.
I was also thinking if we could handle ExRegistercallback with \Callback\PowerState as machine crashes when application is there and machine going to sleep mode.
Any idea how to handle this?

Scott_Noone_(OSR)

What unload callback are you expecting to happen? You should get a DisconnectNotifyCallback callback (passed to FltCreateCommunicationPort) but the app crashing definitely won't unload your driver.

vvlsek

Thanks Scott. I am checking what callback will be called when application is getting killed or goes to suspend state so that I can handle the scenarios in driver