Windows System Software -- Consulting, Training, Development -- Unique Expertise, Guaranteed Results
Before Posting...
Please check out the Community Guidelines in the Announcements and Administration Category.More Info on Driver Writing and Debugging
The free OSR Learning Library has more than 50 articles on a wide variety of topics about writing and debugging device drivers and Minifilters. From introductory level to advanced. All the articles have been recently reviewed and updated, and are written using the clear and definitive style you've come to expect from OSR over the years.
Check out The OSR Learning Library at: https://www.osr.com/osr-learning-library/
BSOD DRIVER_POWER_STATE_FAILURE (9f) when running WLK 1.5 CHAOS test
eric_verdonck
Member Posts: 2
in NTDEV
Hallo All,
When running the WLK 1.5 CHAOS ? Concurrent Hardware And OS Test on a Mobile broadband driver on Win7, we encounter a BSOD DRIVER_POWER_STATE_FAILURE (9f) probably caused by pnpfiltr.
Arg1 equals 4 indicating that some threads were hung in the kernel during power transition (hibernate, etc) while still holding the PnP lock, which is explained at http://social.msdn.microsoft.com/Forums/en-US/isvwindowserrors/thread/1f4a8876-df97-415e-b913-cc02e92fe289.
A very similar problem can be found on thread http://www.osronline.com/ShowThread.cfm?link=168190 entered by Skaramush
Doing some analysis we see that the surprise removal irp is still active is causing the BSOD 9F.
I would like to know how we can analysis in order to overcome the problem.
Thanks in advance for any hints,
Eric
!Analyze ?v
DRIVER_POWER_STATE_FAILURE (9f)
A driver is causing an inconsistent power state.
Arguments:
Arg1: 0000000000000004, The power transition timed out waiting to synchronize with the Pnp
subsystem.
Arg2: 0000000000000258, Timeout in seconds.
Arg3: fffffa8000ce3b60, The thread currently holding on to the Pnp lock.
Arg4: fffff80000b9c510
Debugging Details:
------------------
DRVPOWERSTATE_SUBCODE: 4
FAULTING_THREAD: fffffa8000ce3b60
DEFAULT_BUCKET_ID: VISTA_DRIVER_FAULT
BUGCHECK_STR: 0x9F
PROCESS_NAME: System
CURRENT_IRQL: 2
LAST_CONTROL_TRANSFER: from fffff80002ac5052 to fffff80002ac3dda
STACK_TEXT:
fffff880`031dd410 fffff800`02ac5052 : fffffa80`00ce3b60 fffffa80`00ce3b60 00000000`00000000 00000000`0000000c : nt!KiSwapContext+0x7a
fffff880`031dd550 fffff800`02ac71af : fffffa80`052451a0 fffffa80`05245000 fffff880`00000000 00000000`00000000 : nt!KiCommitThreadWait+0x1d2
fffff880`031dd5e0 fffff880`0151d6f2 : fffffa80`05245100 00000000`00000000 fffff980`04e4ce00 fffffa80`05245100 : nt!KeWaitForSingleObject+0x19f
fffff880`031dd680 fffff880`01578299 : 00000000`00000000 fffffa80`052451a0 fffff980`04e4ce50 00000000`00000017 : ndis!ndisPnPRemoveDeviceEx+0x112
fffff880`031dd6e0 fffff800`02f63c16 : fffff980`04e4ce50 fffff980`04e4ce50 fffffa80`05245050 00000000`00000000 : ndis! ?? ::LNCPHCLB::`string'+0x75c8
fffff880`031dd780 fffff880`0569f9bc : fffffa80`020606f0 fffff980`04e4ce50 fffffa80`01bec8f0 fffffa80`02824560 : nt!IovCallDriver+0x566
fffff880`031dd7e0 fffff880`056a62b9 : fffffa80`020606f0 fffff980`04e4ce50 fffffa80`00005a0c fffffa80`01bec8f0 : pnpfiltr+0x19bc
fffff880`031dd810 fffff880`056a55c8 : fffff980`04e4ce50 fffff880`0569e000 fffffa80`01bec8f0 fffffa80`01a95010 : pnpfiltr+0x82b9
fffff880`031dd840 fffff800`02f63c16 : fffff980`04e4ce50 00000000`00000002 fffffa80`01bec8f0 fffff880`031dd988 : pnpfiltr+0x75c8
fffff880`031dd870 fffff800`02d29419 : fffffa80`01bec8f0 00000000`c00000bb fffff880`031dd988 fffffa80`01a95010 : nt!IovCallDriver+0x566
fffff880`031dd8d0 fffff800`02ea7391 : fffffa80`03e649c0 00000000`00000000 fffffa80`03e4e790 00000000`00000000 : nt!IopSynchronousCall+0xc5
fffff880`031dd940 fffff800`02ea1e08 : 00000000`00000010 fffffa80`03e649c0 00000000`0000030a 00000000`00000308 : nt!IopRemoveDevice+0x101
fffff880`031dda00 fffff800`02ea6ed7 : fffffa80`03e4e790 00000000`00000000 00000000`00000003 00000000`00010246 : nt!PnpSurpriseRemoveLockedDeviceNode+0x128
fffff880`031dda40 fffff800`02ea6ff0 : 00000000`00000000 fffff8a0`02a1b000 fffff8a0`02a42ed0 00000000`4e706e50 : nt!PnpDeleteLockedDeviceNode+0x37
fffff880`031dda70 fffff800`02f36f6f : 00000000`00000002 00000000`00000000 fffffa80`03e4e790 fffff8a0`02a1b0c0 : nt!PnpDeleteLockedDeviceNodes+0xa0
fffff880`031ddae0 fffff800`02f37b2c : fffff880`031ddcb8 00000000`00000000 fffff8a0`02f4e700 fffffa80`00000000 : nt!PnpProcessQueryRemoveAndEject+0x6cf
fffff880`031ddc20 fffff800`02e22c48 : 00000000`00000000 fffffa80`03d97500 fffff8a0`02a1b0c0 00000000`00000001 : nt!PnpProcessTargetDeviceEvent+0x4c
fffff880`031ddc50 fffff800`02acb161 : fffff800`02d28fc0 fffff8a0`02a1b0c0 fffff800`02c615f8 00000000`00000000 : nt! ?? ::NNGAKEGL::`string'+0x5abab
fffff880`031ddcb0 fffff800`02d61166 : 66292062`261e5e23 fffffa80`00ce3b60 00000000`00000080 fffffa80`00cc6040 : nt!ExpWorkerThread+0x111
fffff880`031ddd40 fffff800`02a9c486 : fffff880`009e3180 fffffa80`00ce3b60 fffff880`009edf40 47996548`99654899 : nt!PspSystemThreadStartup+0x5a
fffff880`031ddd80 00000000`00000000 : fffff880`031de000 fffff880`031d8000 fffff880`031dcf90 00000000`00000000 : nt!KxStartSystemThread+0x16
STACK_COMMAND: .thread 0xfffffa8000ce3b60 ; kb
FOLLOWUP_IP:
pnpfiltr+19bc
fffff880`0569f9bc 8bd8 mov ebx,eax
SYMBOL_STACK_INDEX: 6
SYMBOL_NAME: pnpfiltr+19bc
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: pnpfiltr
IMAGE_NAME: pnpfiltr.sys
DEBUG_FLR_IMAGE_TIMESTAMP: 4b079fff
FAILURE_BUCKET_ID: X64_0x9F_VRF_pnpfiltr+19bc
BUCKET_ID: X64_0x9F_VRF_pnpfiltr+19bc
Followup: MachineOwner
---------
After receiving NdisDevicePnPEventSurpriseRemoved, the Mobile Broadband driver executes the PauseHandler and then HaltHandlerEx. HaltHandlerEx stops all threads, frees all memory completes or cancels all irps so that all references to the driver are removed.
The issue seems to be timing related because from time to time we pass the test when a debug driver is loaded. A release drivers seems to fail always.
When the test passes the UnloadHandler is called almost immediately after finishing the HaltHandlerEx.
We suspect that a pnp irp is hanging and prohibits the unloadhandler from being called.
!locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks..
Resource @ nt!IopDeviceTreeLock (0xfffff80002cc0500) Shared 1 owning threads
Threads: fffffa8000ce3b60-01<*>
KD: Scanning for held locks.
Resource @ nt!PiEngineLock (0xfffff80002cc0400) Exclusively owned
Contention Count = 54
NumberOfExclusiveWaiters = 1
Threads: fffffa8000ce3b60-01<*>
Threads Waiting On Exclusive Access:
fffffa8000ce2040
KD: Scanning for held locks..............................................................................................................................................................................................................................................................................................................
9708 total locks, 2 locks currently held
0: kd> !thread fffffa8000ce3b60
THREAD fffffa8000ce3b60 Cid 0004.0044 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable
fffff880031dd6b0 NotificationEvent
IRP List:
fffff98004e4ce50: (0006,01a8) Flags: 40000000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007e40
Owning Process fffffa8000cc6040 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 40644 Ticks: 38463 (0:00:10:00.026)
Context Switch Count 2948 NoStackSwap
UserTime 00:00:00.000
KernelTime 00:00:01.107
Win32 Start Address nt!ExpWorkerThread (0xfffff80002acb050)
Stack Init fffff880031dddb0 Current fffff880031dd3d0
Base fffff880031de000 Limit fffff880031d8000 Call 0
Priority 15 BasePriority 12 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr : Args to Child : Call Site
fffff880`031dd410 fffff800`02ac5052 : fffffa80`00ce3b60 fffffa80`00ce3b60 00000000`00000000 00000000`0000000c : nt!KiSwapContext+0x7a
fffff880`031dd550 fffff800`02ac71af : fffffa80`052451a0 fffffa80`05245000 fffff880`00000000 00000000`00000000 : nt!KiCommitThreadWait+0x1d2
fffff880`031dd5e0 fffff880`0151d6f2 : fffffa80`05245100 00000000`00000000 fffff980`04e4ce00 fffffa80`05245100 : nt!KeWaitForSingleObject+0x19f
fffff880`031dd680 fffff880`01578299 : 00000000`00000000 fffffa80`052451a0 fffff980`04e4ce50 00000000`00000017 : ndis!ndisPnPRemoveDeviceEx+0x112
fffff880`031dd6e0 fffff800`02f63c16 : fffff980`04e4ce50 fffff980`04e4ce50 fffffa80`05245050 00000000`00000000 : ndis! ?? ::LNCPHCLB::`string'+0x75c8
fffff880`031dd780 fffff880`0569f9bc : fffffa80`020606f0 fffff980`04e4ce50 fffffa80`01bec8f0 fffffa80`02824560 : nt!IovCallDriver+0x566
fffff880`031dd7e0 fffff880`056a62b9 : fffffa80`020606f0 fffff980`04e4ce50 fffffa80`00005a0c fffffa80`01bec8f0 : pnpfiltr+0x19bc
fffff880`031dd810 fffff880`056a55c8 : fffff980`04e4ce50 fffff880`0569e000 fffffa80`01bec8f0 fffffa80`01a95010 : pnpfiltr+0x82b9
fffff880`031dd840 fffff800`02f63c16 : fffff980`04e4ce50 00000000`00000002 fffffa80`01bec8f0 fffff880`031dd988 : pnpfiltr+0x75c8
fffff880`031dd870 fffff800`02d29419 : fffffa80`01bec8f0 00000000`c00000bb fffff880`031dd988 fffffa80`01a95010 : nt!IovCallDriver+0x566
fffff880`031dd8d0 fffff800`02ea7391 : fffffa80`03e649c0 00000000`00000000 fffffa80`03e4e790 00000000`00000000 : nt!IopSynchronousCall+0xc5
fffff880`031dd940 fffff800`02ea1e08 : 00000000`00000010 fffffa80`03e649c0 00000000`0000030a 00000000`00000308 : nt!IopRemoveDevice+0x101
fffff880`031dda00 fffff800`02ea6ed7 : fffffa80`03e4e790 00000000`00000000 00000000`00000003 00000000`00010246 : nt!PnpSurpriseRemoveLockedDeviceNode+0x128
fffff880`031dda40 fffff800`02ea6ff0 : 00000000`00000000 fffff8a0`02a1b000 fffff8a0`02a42ed0 00000000`4e706e50 : nt!PnpDeleteLockedDeviceNode+0x37
fffff880`031dda70 fffff800`02f36f6f : 00000000`00000002 00000000`00000000 fffffa80`03e4e790 fffff8a0`02a1b0c0 : nt!PnpDeleteLockedDeviceNodes+0xa0
fffff880`031ddae0 fffff800`02f37b2c : fffff880`031ddcb8 00000000`00000000 fffff8a0`02f4e700 fffffa80`00000000 : nt!PnpProcessQueryRemoveAndEject+0x6cf
fffff880`031ddc20 fffff800`02e22c48 : 00000000`00000000 fffffa80`03d97500 fffff8a0`02a1b0c0 00000000`00000001 : nt!PnpProcessTargetDeviceEvent+0x4c
fffff880`031ddc50 fffff800`02acb161 : fffff800`02d28fc0 fffff8a0`02a1b0c0 fffff800`02c615f8 00000000`00000000 : nt! ?? ::NNGAKEGL::`string'+0x5abab
fffff880`031ddcb0 fffff800`02d61166 : 66292062`261e5e23 fffffa80`00ce3b60 00000000`00000080 fffffa80`00cc6040 : nt!ExpWorkerThread+0x111
fffff880`031ddd40 fffff800`02a9c486 : fffff880`009e3180 fffffa80`00ce3b60 fffff880`009edf40 47996548`99654899 : nt!PspSystemThreadStartup+0x5a
fffff880`031ddd80 00000000`00000000 : fffff880`031de000 fffff880`031d8000 fffff880`031dcf90 00000000`00000000 : nt!KxStartSystemThread+0x16
0: kd> !irp fffff98004e4ce50 7
Irp is active with 3 stacks 3 is current (= 0xfffff98004e4cfb0)
No Mdl: No System Buffer: Thread fffffa8000ce3b60: Irp stack trace.
Flags = 40000000
ThreadListEntry.Flink = fffffa8000ce3f48
ThreadListEntry.Blink = fffffa8000ce3f48
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = fffff880031dd900
UserEvent = fffff880031dd910
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = fffff98004e4cec8
Tail.Overlay.Thread = fffffa8000ce3b60
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = fffff98004e4cfb0
Tail.Overlay.OriginalFileObject = 00000000
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
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
>[ 1b,17] 0 0 fffffa8005245050 00000000 00000000-00000000
\Driver\GTNDIS62
Args: 00000000 00000000 00000000 00000000
IO verifier information:
A problem occured reading memory
0: kd> !locks -v fffff80002cc0500
Resource @ nt!IopDeviceTreeLock (0xfffff80002cc0500) Shared 1 owning threads
Threads: fffffa8000ce3b60-01<*>
THREAD fffffa8000ce3b60 Cid 0004.0044 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable
fffff880031dd6b0 NotificationEvent
IRP List:
fffff98004e4ce50: (0006,01a8) Flags: 40000000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007e40
Owning Process fffffa8000cc6040 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 40644 Ticks: 38463 (0:00:10:00.026)
Context Switch Count 2948 NoStackSwap
UserTime 00:00:00.000
KernelTime 00:00:01.107
Win32 Start Address nt!ExpWorkerThread (0xfffff80002acb050)
Stack Init fffff880031dddb0 Current fffff880031dd3d0
Base fffff880031de000 Limit fffff880031d8000 Call 0
Priority 15 BasePriority 12 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffff880`031dd410 fffff800`02ac5052 nt!KiSwapContext+0x7a
fffff880`031dd550 fffff800`02ac71af nt!KiCommitThreadWait+0x1d2
fffff880`031dd5e0 fffff880`0151d6f2 nt!KeWaitForSingleObject+0x19f
fffff880`031dd680 fffff880`01578299 ndis!ndisPnPRemoveDeviceEx+0x112
fffff880`031dd6e0 fffff800`02f63c16 ndis! ?? ::LNCPHCLB::`string'+0x75c8
fffff880`031dd780 fffff880`0569f9bc nt!IovCallDriver+0x566
fffff880`031dd7e0 fffff880`056a62b9 pnpfiltr+0x19bc
fffff880`031dd810 fffff880`056a55c8 pnpfiltr+0x82b9
fffff880`031dd840 fffff800`02f63c16 pnpfiltr+0x75c8
fffff880`031dd870 fffff800`02d29419 nt!IovCallDriver+0x566
fffff880`031dd8d0 fffff800`02ea7391 nt!IopSynchronousCall+0xc5
fffff880`031dd940 fffff800`02ea1e08 nt!IopRemoveDevice+0x101
fffff880`031dda00 fffff800`02ea6ed7 nt!PnpSurpriseRemoveLockedDeviceNode+0x128
fffff880`031dda40 fffff800`02ea6ff0 nt!PnpDeleteLockedDeviceNode+0x37
fffff880`031dda70 fffff800`02f36f6f nt!PnpDeleteLockedDeviceNodes+0xa0
fffff880`031ddae0 fffff800`02f37b2c nt!PnpProcessQueryRemoveAndEject+0x6cf
fffff880`031ddc20 fffff800`02e22c48 nt!PnpProcessTargetDeviceEvent+0x4c
fffff880`031ddc50 fffff800`02acb161 nt! ?? ::NNGAKEGL::`string'+0x5abab
fffff880`031ddcb0 fffff800`02d61166 nt!ExpWorkerThread+0x111
fffff880`031ddd40 fffff800`02a9c486 nt!PspSystemThreadStartup+0x5a
fffff880`031ddd80 00000000`00000000 nt!KxStartSystemThread+0x16
1 total locks, 1 locks currently held
We see that a surpriseremoval irp which is in the stack of the Mobile Broadband driver (GTNDIS62.sys) is still active.
When running the WLK 1.5 CHAOS ? Concurrent Hardware And OS Test on a Mobile broadband driver on Win7, we encounter a BSOD DRIVER_POWER_STATE_FAILURE (9f) probably caused by pnpfiltr.
Arg1 equals 4 indicating that some threads were hung in the kernel during power transition (hibernate, etc) while still holding the PnP lock, which is explained at http://social.msdn.microsoft.com/Forums/en-US/isvwindowserrors/thread/1f4a8876-df97-415e-b913-cc02e92fe289.
A very similar problem can be found on thread http://www.osronline.com/ShowThread.cfm?link=168190 entered by Skaramush
Doing some analysis we see that the surprise removal irp is still active is causing the BSOD 9F.
I would like to know how we can analysis in order to overcome the problem.
Thanks in advance for any hints,
Eric
!Analyze ?v
DRIVER_POWER_STATE_FAILURE (9f)
A driver is causing an inconsistent power state.
Arguments:
Arg1: 0000000000000004, The power transition timed out waiting to synchronize with the Pnp
subsystem.
Arg2: 0000000000000258, Timeout in seconds.
Arg3: fffffa8000ce3b60, The thread currently holding on to the Pnp lock.
Arg4: fffff80000b9c510
Debugging Details:
------------------
DRVPOWERSTATE_SUBCODE: 4
FAULTING_THREAD: fffffa8000ce3b60
DEFAULT_BUCKET_ID: VISTA_DRIVER_FAULT
BUGCHECK_STR: 0x9F
PROCESS_NAME: System
CURRENT_IRQL: 2
LAST_CONTROL_TRANSFER: from fffff80002ac5052 to fffff80002ac3dda
STACK_TEXT:
fffff880`031dd410 fffff800`02ac5052 : fffffa80`00ce3b60 fffffa80`00ce3b60 00000000`00000000 00000000`0000000c : nt!KiSwapContext+0x7a
fffff880`031dd550 fffff800`02ac71af : fffffa80`052451a0 fffffa80`05245000 fffff880`00000000 00000000`00000000 : nt!KiCommitThreadWait+0x1d2
fffff880`031dd5e0 fffff880`0151d6f2 : fffffa80`05245100 00000000`00000000 fffff980`04e4ce00 fffffa80`05245100 : nt!KeWaitForSingleObject+0x19f
fffff880`031dd680 fffff880`01578299 : 00000000`00000000 fffffa80`052451a0 fffff980`04e4ce50 00000000`00000017 : ndis!ndisPnPRemoveDeviceEx+0x112
fffff880`031dd6e0 fffff800`02f63c16 : fffff980`04e4ce50 fffff980`04e4ce50 fffffa80`05245050 00000000`00000000 : ndis! ?? ::LNCPHCLB::`string'+0x75c8
fffff880`031dd780 fffff880`0569f9bc : fffffa80`020606f0 fffff980`04e4ce50 fffffa80`01bec8f0 fffffa80`02824560 : nt!IovCallDriver+0x566
fffff880`031dd7e0 fffff880`056a62b9 : fffffa80`020606f0 fffff980`04e4ce50 fffffa80`00005a0c fffffa80`01bec8f0 : pnpfiltr+0x19bc
fffff880`031dd810 fffff880`056a55c8 : fffff980`04e4ce50 fffff880`0569e000 fffffa80`01bec8f0 fffffa80`01a95010 : pnpfiltr+0x82b9
fffff880`031dd840 fffff800`02f63c16 : fffff980`04e4ce50 00000000`00000002 fffffa80`01bec8f0 fffff880`031dd988 : pnpfiltr+0x75c8
fffff880`031dd870 fffff800`02d29419 : fffffa80`01bec8f0 00000000`c00000bb fffff880`031dd988 fffffa80`01a95010 : nt!IovCallDriver+0x566
fffff880`031dd8d0 fffff800`02ea7391 : fffffa80`03e649c0 00000000`00000000 fffffa80`03e4e790 00000000`00000000 : nt!IopSynchronousCall+0xc5
fffff880`031dd940 fffff800`02ea1e08 : 00000000`00000010 fffffa80`03e649c0 00000000`0000030a 00000000`00000308 : nt!IopRemoveDevice+0x101
fffff880`031dda00 fffff800`02ea6ed7 : fffffa80`03e4e790 00000000`00000000 00000000`00000003 00000000`00010246 : nt!PnpSurpriseRemoveLockedDeviceNode+0x128
fffff880`031dda40 fffff800`02ea6ff0 : 00000000`00000000 fffff8a0`02a1b000 fffff8a0`02a42ed0 00000000`4e706e50 : nt!PnpDeleteLockedDeviceNode+0x37
fffff880`031dda70 fffff800`02f36f6f : 00000000`00000002 00000000`00000000 fffffa80`03e4e790 fffff8a0`02a1b0c0 : nt!PnpDeleteLockedDeviceNodes+0xa0
fffff880`031ddae0 fffff800`02f37b2c : fffff880`031ddcb8 00000000`00000000 fffff8a0`02f4e700 fffffa80`00000000 : nt!PnpProcessQueryRemoveAndEject+0x6cf
fffff880`031ddc20 fffff800`02e22c48 : 00000000`00000000 fffffa80`03d97500 fffff8a0`02a1b0c0 00000000`00000001 : nt!PnpProcessTargetDeviceEvent+0x4c
fffff880`031ddc50 fffff800`02acb161 : fffff800`02d28fc0 fffff8a0`02a1b0c0 fffff800`02c615f8 00000000`00000000 : nt! ?? ::NNGAKEGL::`string'+0x5abab
fffff880`031ddcb0 fffff800`02d61166 : 66292062`261e5e23 fffffa80`00ce3b60 00000000`00000080 fffffa80`00cc6040 : nt!ExpWorkerThread+0x111
fffff880`031ddd40 fffff800`02a9c486 : fffff880`009e3180 fffffa80`00ce3b60 fffff880`009edf40 47996548`99654899 : nt!PspSystemThreadStartup+0x5a
fffff880`031ddd80 00000000`00000000 : fffff880`031de000 fffff880`031d8000 fffff880`031dcf90 00000000`00000000 : nt!KxStartSystemThread+0x16
STACK_COMMAND: .thread 0xfffffa8000ce3b60 ; kb
FOLLOWUP_IP:
pnpfiltr+19bc
fffff880`0569f9bc 8bd8 mov ebx,eax
SYMBOL_STACK_INDEX: 6
SYMBOL_NAME: pnpfiltr+19bc
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: pnpfiltr
IMAGE_NAME: pnpfiltr.sys
DEBUG_FLR_IMAGE_TIMESTAMP: 4b079fff
FAILURE_BUCKET_ID: X64_0x9F_VRF_pnpfiltr+19bc
BUCKET_ID: X64_0x9F_VRF_pnpfiltr+19bc
Followup: MachineOwner
---------
After receiving NdisDevicePnPEventSurpriseRemoved, the Mobile Broadband driver executes the PauseHandler and then HaltHandlerEx. HaltHandlerEx stops all threads, frees all memory completes or cancels all irps so that all references to the driver are removed.
The issue seems to be timing related because from time to time we pass the test when a debug driver is loaded. A release drivers seems to fail always.
When the test passes the UnloadHandler is called almost immediately after finishing the HaltHandlerEx.
We suspect that a pnp irp is hanging and prohibits the unloadhandler from being called.
!locks
**** DUMP OF ALL RESOURCE OBJECTS ****
KD: Scanning for held locks..
Resource @ nt!IopDeviceTreeLock (0xfffff80002cc0500) Shared 1 owning threads
Threads: fffffa8000ce3b60-01<*>
KD: Scanning for held locks.
Resource @ nt!PiEngineLock (0xfffff80002cc0400) Exclusively owned
Contention Count = 54
NumberOfExclusiveWaiters = 1
Threads: fffffa8000ce3b60-01<*>
Threads Waiting On Exclusive Access:
fffffa8000ce2040
KD: Scanning for held locks..............................................................................................................................................................................................................................................................................................................
9708 total locks, 2 locks currently held
0: kd> !thread fffffa8000ce3b60
THREAD fffffa8000ce3b60 Cid 0004.0044 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable
fffff880031dd6b0 NotificationEvent
IRP List:
fffff98004e4ce50: (0006,01a8) Flags: 40000000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007e40
Owning Process fffffa8000cc6040 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 40644 Ticks: 38463 (0:00:10:00.026)
Context Switch Count 2948 NoStackSwap
UserTime 00:00:00.000
KernelTime 00:00:01.107
Win32 Start Address nt!ExpWorkerThread (0xfffff80002acb050)
Stack Init fffff880031dddb0 Current fffff880031dd3d0
Base fffff880031de000 Limit fffff880031d8000 Call 0
Priority 15 BasePriority 12 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr : Args to Child : Call Site
fffff880`031dd410 fffff800`02ac5052 : fffffa80`00ce3b60 fffffa80`00ce3b60 00000000`00000000 00000000`0000000c : nt!KiSwapContext+0x7a
fffff880`031dd550 fffff800`02ac71af : fffffa80`052451a0 fffffa80`05245000 fffff880`00000000 00000000`00000000 : nt!KiCommitThreadWait+0x1d2
fffff880`031dd5e0 fffff880`0151d6f2 : fffffa80`05245100 00000000`00000000 fffff980`04e4ce00 fffffa80`05245100 : nt!KeWaitForSingleObject+0x19f
fffff880`031dd680 fffff880`01578299 : 00000000`00000000 fffffa80`052451a0 fffff980`04e4ce50 00000000`00000017 : ndis!ndisPnPRemoveDeviceEx+0x112
fffff880`031dd6e0 fffff800`02f63c16 : fffff980`04e4ce50 fffff980`04e4ce50 fffffa80`05245050 00000000`00000000 : ndis! ?? ::LNCPHCLB::`string'+0x75c8
fffff880`031dd780 fffff880`0569f9bc : fffffa80`020606f0 fffff980`04e4ce50 fffffa80`01bec8f0 fffffa80`02824560 : nt!IovCallDriver+0x566
fffff880`031dd7e0 fffff880`056a62b9 : fffffa80`020606f0 fffff980`04e4ce50 fffffa80`00005a0c fffffa80`01bec8f0 : pnpfiltr+0x19bc
fffff880`031dd810 fffff880`056a55c8 : fffff980`04e4ce50 fffff880`0569e000 fffffa80`01bec8f0 fffffa80`01a95010 : pnpfiltr+0x82b9
fffff880`031dd840 fffff800`02f63c16 : fffff980`04e4ce50 00000000`00000002 fffffa80`01bec8f0 fffff880`031dd988 : pnpfiltr+0x75c8
fffff880`031dd870 fffff800`02d29419 : fffffa80`01bec8f0 00000000`c00000bb fffff880`031dd988 fffffa80`01a95010 : nt!IovCallDriver+0x566
fffff880`031dd8d0 fffff800`02ea7391 : fffffa80`03e649c0 00000000`00000000 fffffa80`03e4e790 00000000`00000000 : nt!IopSynchronousCall+0xc5
fffff880`031dd940 fffff800`02ea1e08 : 00000000`00000010 fffffa80`03e649c0 00000000`0000030a 00000000`00000308 : nt!IopRemoveDevice+0x101
fffff880`031dda00 fffff800`02ea6ed7 : fffffa80`03e4e790 00000000`00000000 00000000`00000003 00000000`00010246 : nt!PnpSurpriseRemoveLockedDeviceNode+0x128
fffff880`031dda40 fffff800`02ea6ff0 : 00000000`00000000 fffff8a0`02a1b000 fffff8a0`02a42ed0 00000000`4e706e50 : nt!PnpDeleteLockedDeviceNode+0x37
fffff880`031dda70 fffff800`02f36f6f : 00000000`00000002 00000000`00000000 fffffa80`03e4e790 fffff8a0`02a1b0c0 : nt!PnpDeleteLockedDeviceNodes+0xa0
fffff880`031ddae0 fffff800`02f37b2c : fffff880`031ddcb8 00000000`00000000 fffff8a0`02f4e700 fffffa80`00000000 : nt!PnpProcessQueryRemoveAndEject+0x6cf
fffff880`031ddc20 fffff800`02e22c48 : 00000000`00000000 fffffa80`03d97500 fffff8a0`02a1b0c0 00000000`00000001 : nt!PnpProcessTargetDeviceEvent+0x4c
fffff880`031ddc50 fffff800`02acb161 : fffff800`02d28fc0 fffff8a0`02a1b0c0 fffff800`02c615f8 00000000`00000000 : nt! ?? ::NNGAKEGL::`string'+0x5abab
fffff880`031ddcb0 fffff800`02d61166 : 66292062`261e5e23 fffffa80`00ce3b60 00000000`00000080 fffffa80`00cc6040 : nt!ExpWorkerThread+0x111
fffff880`031ddd40 fffff800`02a9c486 : fffff880`009e3180 fffffa80`00ce3b60 fffff880`009edf40 47996548`99654899 : nt!PspSystemThreadStartup+0x5a
fffff880`031ddd80 00000000`00000000 : fffff880`031de000 fffff880`031d8000 fffff880`031dcf90 00000000`00000000 : nt!KxStartSystemThread+0x16
0: kd> !irp fffff98004e4ce50 7
Irp is active with 3 stacks 3 is current (= 0xfffff98004e4cfb0)
No Mdl: No System Buffer: Thread fffffa8000ce3b60: Irp stack trace.
Flags = 40000000
ThreadListEntry.Flink = fffffa8000ce3f48
ThreadListEntry.Blink = fffffa8000ce3f48
IoStatus.Status = 00000000
IoStatus.Information = 00000000
RequestorMode = 00000000
Cancel = 00
CancelIrql = 0
ApcEnvironment = 00
UserIosb = fffff880031dd900
UserEvent = fffff880031dd910
Overlay.AsynchronousParameters.UserApcRoutine = 00000000
Overlay.AsynchronousParameters.UserApcContext = 00000000
Overlay.AllocationSize = 00000000 - 00000000
CancelRoutine = 00000000
UserBuffer = 00000000
&Tail.Overlay.DeviceQueueEntry = fffff98004e4cec8
Tail.Overlay.Thread = fffffa8000ce3b60
Tail.Overlay.AuxiliaryBuffer = 00000000
Tail.Overlay.ListEntry.Flink = 00000000
Tail.Overlay.ListEntry.Blink = 00000000
Tail.Overlay.CurrentStackLocation = fffff98004e4cfb0
Tail.Overlay.OriginalFileObject = 00000000
Tail.Apc = 00000000
Tail.CompletionKey = 00000000
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
>[ 1b,17] 0 0 fffffa8005245050 00000000 00000000-00000000
\Driver\GTNDIS62
Args: 00000000 00000000 00000000 00000000
IO verifier information:
A problem occured reading memory
0: kd> !locks -v fffff80002cc0500
Resource @ nt!IopDeviceTreeLock (0xfffff80002cc0500) Shared 1 owning threads
Threads: fffffa8000ce3b60-01<*>
THREAD fffffa8000ce3b60 Cid 0004.0044 Teb: 0000000000000000 Win32Thread: 0000000000000000 WAIT: (Executive) KernelMode Non-Alertable
fffff880031dd6b0 NotificationEvent
IRP List:
fffff98004e4ce50: (0006,01a8) Flags: 40000000 Mdl: 00000000
Not impersonating
DeviceMap fffff8a000007e40
Owning Process fffffa8000cc6040 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 40644 Ticks: 38463 (0:00:10:00.026)
Context Switch Count 2948 NoStackSwap
UserTime 00:00:00.000
KernelTime 00:00:01.107
Win32 Start Address nt!ExpWorkerThread (0xfffff80002acb050)
Stack Init fffff880031dddb0 Current fffff880031dd3d0
Base fffff880031de000 Limit fffff880031d8000 Call 0
Priority 15 BasePriority 12 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
Child-SP RetAddr Call Site
fffff880`031dd410 fffff800`02ac5052 nt!KiSwapContext+0x7a
fffff880`031dd550 fffff800`02ac71af nt!KiCommitThreadWait+0x1d2
fffff880`031dd5e0 fffff880`0151d6f2 nt!KeWaitForSingleObject+0x19f
fffff880`031dd680 fffff880`01578299 ndis!ndisPnPRemoveDeviceEx+0x112
fffff880`031dd6e0 fffff800`02f63c16 ndis! ?? ::LNCPHCLB::`string'+0x75c8
fffff880`031dd780 fffff880`0569f9bc nt!IovCallDriver+0x566
fffff880`031dd7e0 fffff880`056a62b9 pnpfiltr+0x19bc
fffff880`031dd810 fffff880`056a55c8 pnpfiltr+0x82b9
fffff880`031dd840 fffff800`02f63c16 pnpfiltr+0x75c8
fffff880`031dd870 fffff800`02d29419 nt!IovCallDriver+0x566
fffff880`031dd8d0 fffff800`02ea7391 nt!IopSynchronousCall+0xc5
fffff880`031dd940 fffff800`02ea1e08 nt!IopRemoveDevice+0x101
fffff880`031dda00 fffff800`02ea6ed7 nt!PnpSurpriseRemoveLockedDeviceNode+0x128
fffff880`031dda40 fffff800`02ea6ff0 nt!PnpDeleteLockedDeviceNode+0x37
fffff880`031dda70 fffff800`02f36f6f nt!PnpDeleteLockedDeviceNodes+0xa0
fffff880`031ddae0 fffff800`02f37b2c nt!PnpProcessQueryRemoveAndEject+0x6cf
fffff880`031ddc20 fffff800`02e22c48 nt!PnpProcessTargetDeviceEvent+0x4c
fffff880`031ddc50 fffff800`02acb161 nt! ?? ::NNGAKEGL::`string'+0x5abab
fffff880`031ddcb0 fffff800`02d61166 nt!ExpWorkerThread+0x111
fffff880`031ddd40 fffff800`02a9c486 nt!PspSystemThreadStartup+0x5a
fffff880`031ddd80 00000000`00000000 nt!KxStartSystemThread+0x16
1 total locks, 1 locks currently held
We see that a surpriseremoval irp which is in the stack of the Mobile Broadband driver (GTNDIS62.sys) is still active.
Howdy, Stranger!
| Upcoming OSR Seminars | ||
|---|---|---|
| OSR has suspended in-person seminars due to the Covid-19 outbreak. But, don't miss your training! Attend via the internet instead! | ||
| Kernel Debugging | 30 January 2023 | Live, Online |
| Developing Minifilters | 20 March 2023 | Live, Online |
| Internals & Software Drivers | 17 April 2023 | Live, Online |
| Writing WDF Drivers | 22 May 2023 | Live, Online |