I reported this problem here several times, reproduced it with simple WDF based driver and uploaded dumps for Doron. Today I encountered it again but now it is usbhub.sys driver what invokes D0 which never completes.
We’re testing ESDs against our USB fingerprint sensor which is hardwired in a notebook. Testing is really harsh; ESDs are used in series (it is customer’s idea, not mine) and the results are “funny” varying. Sometimes our device disappears from device manager and the only recovery (if I omit computer reset) is to disable and enable USB generic root hub device to which it is attached. There is an internal hub attached to UHCI HC to which is attached our device and internal SC reader. Disable/enable usually helps but in this situation device manager locked up which’d finally lead to system deadlock on suspend on hibernate which is on of worst things for notebook.
I made a manual crashdump and found my driver was surprise removed, forwarded SR IRP correctly down the stack but never received remove IRP. Device is in the following state:
1: kd> !devobj 81cb5030
Device object (81cb5030) is for:
000000f8 \Driver\TcUsb DriverObject 81c292c0
Current Irp 00000000 RefCount 0 Type 00000022 Flags 00002050
Dacl e15509b4 DevExt 81cb50e8 DevObjExt 81cb54a0
ExtensionFlags (0x00000008) DOE_REMOVE_PROCESSED
AttachedTo (Lower) 81d8fac0 \Driver\usbhub
Device queue is not busy.
In the device extension I have fields allowing to examine previous power transaction so I know it was never suspended and it is in D0 state. Also, there is no thread which would have my driver on the stack. So I examined active power IRPs:
1: kd> !poreqlist
All active Power Irps from PoRequestPowerIrp
PopReqestedPowerIrpList
FieldOffset = 00000004
Irp 8239b650 DevObj 823ceb60 \Driver\ACPI Ctx 00000005 * Wait Wake S4
Irp 8217c318 DevObj 81ee3030 \Driver\usbuhci Ctx 00000001 Wait Wake S0
Irp 81d0bcd8 DevObj 821c19f0 \Driver\usbhub Ctx 00000001 Wait Wake S0
Irp 81d76008 DevObj 81d6ebd8 \Driver\usbhub Ctx 00000001 Wait Wake S0
Irp 81d76cd8 DevObj 8214a030 \Driver\usbehci Ctx 00000001 Wait Wake S0
Irp 8217be70 DevObj 81d6e030 \Driver\usbuhci Ctx 00000001 Wait Wake S0
Irp 81d88628 DevObj 81d67030 \Driver\usbuhci Ctx 00000001 Wait Wake S0
Irp 81cec008 DevObj 8226ebc0 \Driver\usbhub Ctx 00000001 Wait Wake S0
Irp 81c92640 DevObj 81c34030 \Driver\usbhub Ctx 00000001 Wait Wake S0
Irp 82155628 DevObj 8226ebc0 \Driver\usbhub Ctx 00000003 Set Power D0 ShutdownType 0
Irp 81c8a9e8 DevObj 0000000000000000: Could not read device object or _DEVICE_OBJECT not found
Ctx 00000002 [blocked]
Irp 81d86628 DevObj 0000000000000000: Could not read device object or _DEVICE_OBJECT not found
Ctx 00000002 [blocked]
The last two are already completed IRPs issued by usbhub.sys driver, but before is suspicious D0 IRP:
1: kd> !irp 82155628
Irp is active with 7 stacks 4 is current (= 0x82155704)
No Mdl Thread 00000000: 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
[16, 2] 0 e1 8226ebc0 00000000 f865aad6-821b1200 Success Error Cancel pending
\Driver\usbhub usbhub!USBH_PowerIrpCompletion
Args: 00000003 00000001 00000001 00000000
[16, 2] 0 e1 821b1148 00000000 80525a9c-f86558ea Success Error Cancel pending
\Driver\usbhub nt!PopCompleteRequestIrp
Args: 00000003 00000001 00000001 00000000
[0, 0] 0 0 821b1148 00000000 00000000-00000000
\Driver\usbhub
Args: 8226ebc0 00000002 00000001 f88d8d5c
[0, 0] 0 0 00000000 00000000 00000000-00000000
Args: 81c8ab34 81c92768 82155628 00000000
Well, it seems as blocked one. Let’s examine threads. There are few blocked waiting for D0:
THREAD 823c6da8 Cid 0004.0028 Teb: 00000000 Win32Thread: 00000000 WAIT: (Suspended) KernelMode Non-Alertable
f88c8d5c NotificationEvent
Not impersonating
DeviceMap e1001948
Owning Process 823c87f8
Wait Start TickCount 108848 Elapsed Ticks: 128695
Context Switch Count 5799
UserTime 00:00:00.0000
KernelTime 00:00:00.0343
Start Address nt!ExpWorkerThread (0x80537668)
Stack Init f88c9000 Current f88c8ce8 Base f88c9000 Limit f88c6000 Call 0
Priority 12 BasePriority 12 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr Args to Child
f88c8d00 80502b17 823c6e18 823c6da8 804fad6c nt!KiSwapContext+0x2f (FPO: [EBP 0xf88c8d34] [0,0,4])
f88c8d0c 804fad6c 00000000 821b1200 804fabaa nt!KiSwapThread+0x6b (FPO: [0,0,0])
f88c8d34 f865a8fe 00000000 00000005 00000000 nt!KeWaitForSingleObject+0x1c2 (FPO: [Non-Fpo])
f88c8d6c f866113f 00000103 8056375c f88c8dac usbhub!USBH_HubSetD0+0x7a (FPO: [Non-Fpo])
f88c8d7c 80537757 81dafdc0 00000000 823c6da8 usbhub!USBH_IdleCancelPowerHubWorker+0x25 (FPO: [Non-Fpo])
f88c8dac 805ce794 81dafdc0 00000000 00000000 nt!ExpWorkerThread+0xef (FPO: [Non-Fpo])
f88c8ddc 805450ce 80537668 00000001 00000000 nt!PspSystemThreadStartup+0x34 (FPO: [Non-Fpo])
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16
THREAD 823c6b30 Cid 0004.002c Teb: 00000000 Win32Thread: 00000000 WAIT: (Suspended) KernelMode Non-Alertable
f88cc9c8 NotificationEvent
IRP List:
81c1c6d0: (0006,0190) Flags: 00000000 Mdl: 00000000
821c2a20: (0006,0094) Flags: 00000000 Mdl: 00000000
Not impersonating
DeviceMap e1001948
Owning Process 823c87f8
Wait Start TickCount 108848 Elapsed Ticks: 128695
Context Switch Count 41589
UserTime 00:00:00.0000
KernelTime 00:00:01.0328
Start Address nt!ExpWorkerThread (0x80537668)
Stack Init f88cd000 Current f88cc954 Base f88cd000 Limit f88ca000 Call 0
Priority 14 BasePriority 12 PriorityDecrement 2 DecrementCount 16
ChildEBP RetAddr Args to Child
f88cc96c 80502b17 823c6ba0 823c6b30 804fad6c nt!KiSwapContext+0x2f (FPO: [EBP 0xf88cc9a0] [0,0,4])
f88cc978 804fad6c 00000000 821b1200 804fabaa nt!KiSwapThread+0x6b (FPO: [0,0,0])
f88cc9a0 f865a8fe 00000000 00000005 00000000 nt!KeWaitForSingleObject+0x1c2 (FPO: [Non-Fpo])
f88cc9d8 f8656ebc 00000103 81c1c6d0 81c1c7d0 usbhub!USBH_HubSetD0+0x7a (FPO: [Non-Fpo])
f88cc9f4 f8657039 821b1200 81c1c6d0 00000007 usbhub!USBH_FdoPnP+0x60 (FPO: [Non-Fpo])
f88cca1c f86571ee 821b1200 81c1c6d0 f88cca68 usbhub!USBH_FdoDispatch+0x63 (FPO: [Non-Fpo])
f88cca2c 804eeeb1 821b1148 81c1c6d0 f88ccaac usbhub!USBH_HubDispatch+0x5e (FPO: [Non-Fpo])
f88cca3c 80591823 00000000 821bce78 821bcf58 nt!IopfCallDriver+0x31 (FPO: [0,0,0])
f88cca68 804f6b05 821b1148 f88cca88 821bcf58 nt!IopSynchronousCall+0xb7 (FPO: [Non-Fpo])
f88ccab0 8058db39 00000000 8226ebc0 00000001 nt!IopQueryDeviceRelations+0x45 (FPO: [Non-Fpo])
f88ccac8 80590f9b 821bce78 00000001 81c68a80 nt!PipEnumerateDevice+0x23 (FPO: [Non-Fpo])
f88ccd20 805913da 821bce78 00000001 00000000 nt!PipProcessDevNodeTree+0x21b (FPO: [Non-Fpo])
f88ccd54 804f669f 00000003 8055a5c0 8056375c nt!PiProcessReenumeration+0x60 (FPO: [Non-Fpo])
f88ccd7c 80537757 00000000 00000000 823c6b30 nt!PipDeviceActionWorker+0x14b (FPO: [Non-Fpo])
f88ccdac 805ce794 00000000 00000000 00000000 nt!ExpWorkerThread+0xef (FPO: [Non-Fpo])
f88ccddc 805450ce 80537668 00000001 00000000 nt!PspSystemThreadStartup+0x34 (FPO: [Non-Fpo])
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16
THREAD 823c63c8 Cid 0004.0038 Teb: 00000000 Win32Thread: 00000000 WAIT: (Suspended) KernelMode Non-Alertable
f88d8d5c NotificationEvent
Not impersonating
DeviceMap e1001948
Owning Process 823c87f8
Wait Start TickCount 108848 Elapsed Ticks: 128695
Context Switch Count 5714
UserTime 00:00:00.0000
KernelTime 00:00:01.0203
Start Address nt!ExpWorkerThread (0x80537668)
Stack Init f88d9000 Current f88d8ce8 Base f88d9000 Limit f88d6000 Call 0
Priority 12 BasePriority 12 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr Args to Child
f88d8d00 80502b17 823c6438 823c63c8 804fad6c nt!KiSwapContext+0x2f (FPO: [EBP 0xf88d8d34] [0,0,4])
f88d8d0c 804fad6c 00000000 821b1200 804fabaa nt!KiSwapThread+0x6b (FPO: [0,0,0])
f88d8d34 f865a8fe 00000000 00000005 00000000 nt!KeWaitForSingleObject+0x1c2 (FPO: [Non-Fpo])
f88d8d6c f8661765 00000103 8056375c f88d8dac usbhub!USBH_HubSetD0+0x7a (FPO: [Non-Fpo])
f88d8d7c 80537757 821b0318 00000000 823c63c8 usbhub!USBH_IdleCompletePowerHubWorker+0x25 (FPO: [Non-Fpo])
f88d8dac 805ce794 821b0318 00000000 00000000 nt!ExpWorkerThread+0xef (FPO: [Non-Fpo])
f88d8ddc 805450ce 80537668 00000001 00000000 nt!PspSystemThreadStartup+0x34 (FPO: [Non-Fpo])
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16
So what to do now? Would MS finally look at this problem and make a fix? Crashdump is of course available if anybody is interested.
Best regards,
Michal Vodicka
UPEK, Inc.
[xxxxx@upek.com, http://www.upek.com]