Here is a synthetic case study to show various wait chain patterns. The complete memory dump from a frozen system is inconsistent (Volume 1, page 269), saved by LiveKd. Stack trace collection shows many threads waiting for LPC (Volume 3, page 97) replies:
THREAD 87432520 Cid 0b10.0dd8 Teb: 7ff83000 Win32Thread: 00000000 WAIT:
(Unknown) UserMode Non-Alertable
8743270c Semaphore Limit 0x1
Waiting for reply to LPC MessageId 007ade85:
Current LPC port d676e560
Not impersonating
DeviceMap d6f05be8
Owning Process 87581c78 Image: ProcessA.exe
Attached Process N/A Image: N/A
Wait Start TickCount 4093415 Ticks: 659565 (0:02:51:45.703)
Context Switch Count 111255
UserTime 00:00:27.781
KernelTime 00:00:02.015
Win32 Start Address MSVCR71!_threadstartex (0×7c3494f6)
Start Address kernel32!BaseThreadStartThunk (0×77e617ec)
Stack Init b6439000 Current b6438c08 Base b6439000 Limit b6436000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr
b6438c10 00000000 0×0
Checking MessageId by using !lpc command gives us the following LPC server thread that is waiting for a mutant owned by thread 866d63e8 (this is equivalent to the thread 85b209d0 is waiting for thread (Volume 3, page 92) 866d63e8):
THREAD 85b209d0 Cid 1524.2770 Teb: 7ff78000 Win32Thread: 00000000 WAIT:
(Unknown) UserMode Non-Alertable
85e9ba00 Mutant - owning thread 866d63e8
Not impersonating
DeviceMap d64008d8
Owning Process 87200880 Image: ProcessB.exe
Attached Process N/A Image: N/A
Wait Start TickCount 4093415 Ticks: 659565 (0:02:51:45.703)
Context Switch Count 28
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address 0×007ade85
LPC Server thread working on message Id 7ade85
Start Address kernel32!BaseThreadStartThunk (0×77e617ec)
Stack Init b42e5000 Current b42e4c60 Base b42e5000 Limit b42e2000 Call 0
Priority 10 BasePriority 10 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr
b42e4c68 00000000 0xa000a02
Thread 866d63e8 is waiting for a process (page 43) 86b33b30:
THREAD 866d63e8 Cid 1524.3984 Teb: 7ff6e000 Win32Thread: 00000000 WAIT:
(Unknown) UserMode Non-Alertable
86b33b30 ProcessObject
866d6460 NotificationTimer
Not impersonating
DeviceMap d64008d8
Owning Process 87200880 Image: ProcessB.exe
Attached Process N/A Image: N/A
Wait Start TickCount 4755080
Context Switch Count 4767
UserTime 00:00:00.015
KernelTime 00:00:00.000
Win32 Start Address 0×007a5051
LPC Server thread working on message Id 7a5051
Start Address kernel32!BaseThreadStartThunk (0×77e617ec)
Stack Init ab459000 Current ab458c60 Base ab459000 Limit ab456000 Call 0
Priority 10 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr
ab458c78 8083d5b1 nt!KiSwapContext+0×26
ab458ca4 8083df9e nt!KiSwapThread+0×2e5
ab458cec 8092ae67 nt!KeWaitForSingleObject+0×346
ab458d50 80833bef nt!NtWaitForSingleObject+0×9a
ab458d50 7c82860c nt!KiFastCallEntry+0xfc (TrapFrame @ ab458d64)
0499fbec 7c827d29 ntdll!KiFastSystemCallRet
0499fbf0 76548721 ntdll!ZwWaitForSingleObject+0xc
0499fc0c 7654aa54 ProcessB!WaitForProcess+0×4a
[...]
0499ffec 00000000 kernel32!BaseThreadStart+0×34
We find the following thread in the process 86b33b30 where there is only one thread left when we expect many of them (Volume 1, page 362) in ProcessC:
THREAD 85a6fdb0 Cid 5c0c.26f4 Teb: 7ffdf000 Win32Thread: b9b778a0 WAIT:
(Unknown) KernelMode Non-Alertable
86686030 SynchronizationEvent
85a6fe28 NotificationTimer
Not impersonating
DeviceMap d6767248
Owning Process 86b33b30 Image: ProcessC.EXE
Attached Process N/A Image: N/A
Wait Start TickCount 4755681
Context Switch Count 77668 LargeStack
UserTime 00:00:00.437
KernelTime 00:00:04.421
*** ERROR: Module load completed but symbols could not be loaded for
ProcessC.EXE
Win32 Start Address 0×300010cc
Start Address kernel32!BaseProcessStartThunk (0×77e617f8)
Stack Init 9ad92000 Current 9ad91a40 Base 9ad92000 Limit 9ad8d000 Call 0
Priority 10 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr
9ad91a58 8083d5b1 nt!KiSwapContext+0×26
9ad91a84 8083df9e nt!KiSwapThread+0×2e5
9ad91acc 8081e05b nt!KeWaitForSingleObject+0×346
9ad91b08 8082e012 nt!ExpWaitForResource+0xd5
9ad91b28 b6a9c1ee nt!ExAcquireResourceExclusiveLite+0×8d9ad91b38 b6ab09d3 DriverA+0×21ee
[...]
9ad91c3c 80840153 DriverA+0×1ed6
9ad91c50 8092b51f nt!IofCallDriver+0×45
9ad91c64 8092b454 nt!IopSynchronousServiceTail+0×10b
9ad91d00 8092b574 nt!IopXxxControlFile+0×60f
9ad91d34 80833bef nt!NtDeviceIoControlFile+0×2a
9ad91d34 7c82860c nt!KiFastCallEntry+0xfc (TrapFrame @ 9ad91d64)
0012d4e0 00000000 ntdll!KiFastSystemCallRet
It is blocked by DriverA waiting for an executive resource (Volume 2, page 147). Fortunately, !locks command works for this inconsistent dump and we finally reach the thread 86ba5638:
0: kd> !locks
Resource @ 0x85610d30 Exclusively owned
Contention Count = 4
NumberOfExclusiveWaiters = 1
Threads: 86ba5638-01<*>
Threads Waiting On Exclusive Access:
85a6fdb0
This thread belongs to another instance of ProcessC.exe (different process 8690dd88):
0: kd> !thread 86ba5638 1f
THREAD 86ba5638 Cid 186c.1574 Teb: 7ffdf000 Win32Thread: b9a28a70 WAIT:
(Unknown) KernelMode Non-Alertable
8944e3d4 SynchronizationEvent
Not impersonating
DeviceMap d6767248
Owning Process 8690dd88 Image: ProcessC.EXE
Attached Process N/A Image: N/A
Wait Start TickCount 4074148 Ticks: 678832 (0:02:56:46.750)
Context Switch Count 95896 LargeStack
UserTime 00:00:00.593
KernelTime 00:00:05.343
*** ERROR: Module load completed but symbols could not be loaded for
ProcessC.EXE
Win32 Start Address 0×300010cc
Start Address kernel32!BaseProcessStartThunk (0×77e617f8)
Stack Init 99ef2000 Current 99ef19c0 Base 99ef2000 Limit 99eec000 Call 0
Priority 10 BasePriority 10 PriorityDecrement 0
ChildEBP RetAddr
99ef19d8 8083d5b1 nt!KiSwapContext+0×26
99ef1a04 8083df9e nt!KiSwapThread+0×2e5
99ef1a4c 80853f3f nt!KeWaitForSingleObject+0×346
99ef1a64 8081d45f nt!KiAcquireFastMutex+0×13
99ef1a70 b6a9c70d nt!ExAcquireFastMutex+0×20
WARNING: Stack unwind information not available. Following frames may be
wrong.
99ef1a7c b6aaf22a DriverA+0×270d
[...]
99ef1c3c 80840153 DriverA+0×1ed6
99ef1c50 8092b51f nt!IofCallDriver+0×45
99ef1c64 8092b454 nt!IopSynchronousServiceTail+0×10b
99ef1d00 8092b574 nt!IopXxxControlFile+0×60f
99ef1d34 80833bef nt!NtDeviceIoControlFile+0×2a
99ef1d34 7c82860c nt!KiFastCallEntry+0xfc (TrapFrame @ 99ef1d64)
0012db08 00000000 ntdll!KiFastSystemCallRet
We see this thread is also blocked by DriverA. We also check thread waiting times (Volume 1, page 343). All threads involved in wait chains have their Ticks value less than 86ba5638. This means that the thread 86ba5638 was blocked earlier. We contact DriverA vendor for any possible updates.
We recently got a crying request from a reader of this anthology to analyze the source of frequent bugchecks on a newly bought computer running Windows 7. We got 8 kernel minidumps with 5 different bugchecks. However, inspection of the output of the default analysis command revealed common Fault Context pattern (page 59) of high resource consumption flight simulator processes in 6 minidumps. Most fault IPs were showing signs of Wild Code pattern (Volume 2, page 219) and that most probably implicated Hardware Error (Volume 2, page 221) pattern (looks like WinDbg suggests that MISALIGNED_IP implicates hardware). Here is the listing of relevant output fragments with attempts to disassemble code around IP (Instruction Pointer) to see if the code makes any sense (italics underlined means the valid code that should have been instead of misaligned code highlighted in bold italics):
Windows 7 Kernel Version 7600 MP (4 procs) Free x86 compatibleDebug session time: Fri Jan 8 20:31:15.121 2010 (GMT+0) System Uptime: 0 days 2:54:44.9161: kd> !analyze -v DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1)PROCESS_NAME: FlightSimulatorA.exeCURRENT_IRQL: 2 TRAP_FRAME: 807e6ea4 -- (.trap 0xffffffff807e6ea4) ErrCode = 00000002 eax=872082a7 ebx=80028d5f ecx=b3348635 edx=87208638 esi=80280001 edi=000082a7 eip=8d613485 esp=807e6f18 ebp=6f248635 iopl=0 nv up ei ng nz na po nc cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010282 USBPORT!USBPORT_Xdpc_End+0xa6: 8d613485 897904 mov dword ptr [ecx+4],edi ds:0023:b3348639=???????? Resetting default scope STACK_TEXT: 807e6ea4 8d613485 badb0d00 87208638 82a7b334 nt!KiTrap0E+0x2cf 807e6f24 8d613d18 00000000 86358720 86358002 USBPORT!USBPORT_Xdpc_End+0xa6 807e6f48 82aa33b5 8635872c 86358002 00000000 USBPORT!USBPORT_Xdpc_Worker+0x173 807e6fa4 82aa3218 807c6120 87e7e950 00000000 nt!KiExecuteAllDpcs+0xf9 807e6ff4 82aa29dc 9f7e1ce4 00000000 00000000 nt!KiRetireDpcList+0xd5 807e6ff8 9f7e1ce4 00000000 00000000 00000000 nt!KiDispatchInterrupt+0x2c WARNING: Frame IP not in any known module. Following frames may be wrong. 82aa29dc 00000000 0000001a 00d6850f bb830000 0x9f7e1ce4Debug session time: Fri Jan 8 20:42:16.395 2010 (GMT+0) System Uptime: 0 days 0:10:22.815
2: kd> !analyze -v DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1) CURRENT_IRQL: 2 TRAP_FRAME: 8d91cbc4 -- (.trap 0xffffffff8d91cbc4) ErrCode = 00000002 eax=00000000 ebx=8d901a00 ecx=86570108 edx=86570108 esi=8d905884 edi=86573920 eip=911e5f5d esp=8d91cc38 ebp=8d91cc78 iopl=0 nv up ei pl nz na po nc cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010202Resetting default scopeHDAudBus!HdaController::NotificationDpc+0×14d: 911e5f5d ff ???2: kd> u HDAudBus!HdaController::NotificationDpc+14dIMAGE_NAME: hardware911e5f62 6a00 push 0 911e5f64 6a00 push 0 911e5f66 68ff000000 push 0FFh 911e5f6b 6a03 push 3 911e5f6d 6a04 push 4 2: kd> uf HDAudBus!HdaController::NotificationDpc [...] HDAudBus!HdaController::NotificationDpc+0x135: 911e5f45 8b45d8 mov eax,dword ptr [ebp-28h] 911e5f48 c6405400 mov byte ptr [eax+54h],0 911e5f4c 8b4dd8 mov ecx,dword ptr [ebp-28h] 911e5f4f 83c148 add ecx,48h 911e5f52 8a55e7 mov dl,byte ptr [ebp-19h] 911e5f55 ff1510a01e91 call dword ptr [HDAudBus!_imp_KfReleaseSpinLock (911ea010)]HDAudBus!HdaController::NotificationDpc+0×14d: 911e5f5d ff ??? 911e5f5e ff ??? 911e5f5f ff6a00 jmp fword ptr [edx]HDAudBus!HdaController::NotificationDpc+0x14b: 911e5f5b e909ffffff jmp HDAudBus!HdaController::NotificationDpc+0x59 (911e5e69)HDAudBus!HdaController::NotificationDpc+0x150: 911e5f60 6a00 push 0 911e5f62 6a00 push 0 911e5f64 6a00 push 0 911e5f66 68ff000000 push 0FFh 911e5f6b 6a03 push 3 911e5f6d 6a04 push 4 911e5f6f 6a08 push 8 911e5f71 6a02 push 2 911e5f73 e818180000 call HDAudBus!HDABusWmiLogETW (911e7790) 911e5f78 8b4df0 mov ecx,dword ptr [ebp-10h] 911e5f7b 64890d00000000 mov dword ptr fs:[0],ecx 911e5f82 59 pop ecx 911e5f83 5f pop edi 911e5f84 5e pop esi
911e5f85 5b pop ebx 911e5f86 8be5 mov esp,ebp 911e5f88 5d pop ebp 911e5f89 c21000 ret 10hDebug session time: Fri Jan 8 21:32:04.096 2010 (GMT+0) System Uptime: 0 days 0:49:10.5171: kd> !analyze -v KERNEL_MODE_EXCEPTION_NOT_HANDLED_M (1000008e) Arg1: c000001d, The exception code that was not handledTRAP_FRAME: a99e3644 -- (.trap 0xffffffffa99e3644) ErrCode = 00000000 eax=000000fe ebx=8556a2b0 ecx=754764cd edx=00000001 esi=858ad008 edi=858ad048 eip=82ada4c2 esp=a99e36b8 ebp=a99e3704 iopl=0 nv up ei ng nz na po nc cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010282EXCEPTION_CODE: (NTSTATUS) 0xc000001d - {EXCEPTION} Illegal Instruction An attempt was made to execute an illegal instruction.CURRENT_IRQL: 1nt!IopCompleteRequest+0×3ac: 82ada4c2 02cd add cl,chPROCESS_NAME: FlightSimulatorA.exe1: kd> uf nt!IopCompleteRequest+3acMISALIGNED_IP: nt!IopCompleteRequest+3ac 82ada4c2 02cd add cl,ch IMAGE_NAME: hardware82ada4c5 50 push eax 82ada4c6 ff75e0 push dword ptr [ebp-20h] 82ada4c9 57 push edi 82ada4ca e881830100 call nt!KeInitializeApc (82af2850) 82ada4cf 6a02 push 2 82ada4d1 6a00 push 0 82ada4d3 ff7628 push dword ptr [esi+28h] 82ada4d6 57 push edi 82ada4d7 e8d2830100 call nt!KeInsertQueueApc (82af28ae) 82ada4dc 33ff xor edi,edi 82ada4de eb5f jmp nt!IopCompleteRequest+0×429 (82ada53f)nt!IopCompleteRequest+0×3a9: 82ada4bf 82680002 sub byte ptr [eax],2 82ada4c3 cd82 int 82h1: kd> ub nt!IopCompleteRequest+3ac ^ Unable to find valid previous instruction for 'ub nt!IopCompleteRequest+3ac'
Debug session time: Sat Jan 9 07:45:24.155 2010 (GMT+0) System Uptime: 0 days 2:09:39.5760: kd> !analyze -v UNEXPECTED_KERNEL_MODE_TRAP (7f) Arg1: 0000000d, EXCEPTION_GP_FAULTPROCESS_NAME: FlightSimulatorA.exeCURRENT_IRQL: 6 STACK_TEXT: a24b3bd8 90f9e956 badb0d00 00000000 ddf1ba50 nt!KiSystemFatalException+0xf a24b3cc4 90f93f2b 00000001 00000004 00000004 HDAudBus!HDABusWmiLogETW+0x1c6 a24b3d08 82a817ad 864a6280 86541000 a24b3d34 HDAudBus!HdaController::Isr+0x2b a24b3d08 20c40d61 864a6280 86541000 a24b3d34 nt!KiInterruptDispatch+0x6d WARNING: Frame IP not in any known module. Following frames may be wrong. 1343f8ea 00000000 00000000 00000000 00000000 0x20c40d61Debug session time: Sat Jan 9 08:52:03.454 2010 (GMT+0) System Uptime: 0 days 1:05:54.2490: kd> !analyze -v IRQL_NOT_LESS_OR_EQUAL (a) CURRENT_IRQL: 2PROCESS_NAME: FlightSimulatorA.exeTRAP_FRAME: 8078adf0 -- (.trap 0xffffffff8078adf0) ErrCode = 00000002 eax=8632e2a6 ebx=00000000 ecx=880fb200 edx=00000118 esi=00000007 edi=8632e27c eip=82a0c967 esp=8078ae64 ebp=c1e2baa0 iopl=0 nv up ei ng nz na pe nc cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010286 hal!HalBuildScatterGatherList+0xf3: 82a0c967 8901 mov dword ptr [ecx],eax ds:0023:880fb200=???????? Resetting default scope STACK_TEXT: 8078adf0 82a0c967 badb0d00 00000118 82b5f466 nt!KiTrap0E+0x2cf 8078ae78 82a0cc16 880fb218 86379028 8632e260 hal!HalBuildScatterGatherList+0xf3 8078aea8 909b3e70 8651c6b0 86379028 8632e260 hal!HalGetScatterGatherList+0x26 8078aef4 909b3807 86379028 86379970 00000007 USBPORT!USBPORT_Core_iMapTransfer+0x21e 8078af24 909add18 86379028 86379970 86379002 USBPORT!USBPORT_Core_UsbMapDpc_Worker+0x1e3 8078af48 82aa73b5 8637997c 86379002 00000000 USBPORT!USBPORT_Xdpc_Worker+0x173 8078afa4 82aa7218 82b68d20 88139a98 00000000 nt!KiExecuteAllDpcs+0xf9 8078aff4 82aa69dc 9fd8cce4 00000000 00000000 nt!KiRetireDpcList+0xd5 8078aff8 9fd8cce4 00000000 00000000 00000000 nt!KiDispatchInterrupt+0x2c WARNING: Frame IP not in any known module. Following frames may be wrong. 82aa69dc 00000000 0000001a 00d6850f bb830000 0x9fd8cce4
Debug session time: Sat Jan 9 16:34:48.134 2010 (GMT+0) System Uptime: 0 days 1:53:05.9291: kd> !analyze -v DRIVER_IRQL_NOT_LESS_OR_EQUAL (d1) CURRENT_IRQL: 2 PROCESS_NAME: firefox.exe TRAP_FRAME: bb92449c -- (.trap 0xffffffffbb92449c) ErrCode = 00000000 eax=000005b4 ebx=0db19ba0 ecx=80000000 edx=00000001 esi=85fdff29 edi=bb924530 eip=8bc7e2c7 esp=bb924510 ebp=bb924638 iopl=0 nv up ei ng nz na po nc cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010282tcpip!TcpBeginTcbSend+0xa83: 8bc7e2c7 eb06 jmp tcpip!TcpBeginTcbSend+0xa8b (8bc7e2cf)Resetting default scope STACK_TEXT: bb92449c 8bc7e2c7 badb0d00 00000001 00000000 nt!KiTrap0E+0x2cf bb924638 8bc7d2bf 87b39c78 00000000 00000001 tcpip!TcpBeginTcbSend+0xa83 bb92479c 8bc814b5 87b39c78 00000000 00000001 tcpip!TcpTcbSend+0x426 bb9247bc 8bc7f349 87b39c78 87fa6c38 00000000 tcpip!TcpEnqueueTcbSendOlmNotifySendComplete+0x157 bb92481c 8bc81846 87b39c78 bb92491c 00000000 tcpip!TcpEnqueueTcbSend+0x3ca bb924838 82a95f8a bb9248c8 96d9c9d2 00000000 tcpip!TcpTlConnectionSendCalloutRoutine+0x17 bb9248a0 8bc80a0b 8bc8182f bb9248c8 00000000 nt!KeExpandKernelStackAndCalloutEx+0x132 bb9248d8 908b5d27 87b39c01 bb924900 85572e18 tcpip!TcpTlConnectionSend+0x73 bb92493c 908bb2e3 00d4f1e0 85572e18 85572eac tdx!TdxSendConnection+0x1d7 bb924958 82a424bc 86236b80 85572e18 862389c0 tdx!TdxTdiDispatchInternalDeviceControl+0x115 bb924970 908d65ca 86d0e0c8 00000000 86238990 nt!IofCallDriver+0x63 WARNING: Stack unwind information not available. Following frames may be wrong. bb9249c8 908d17f8 86238990 85572e18 85572ed0 aswTdi+0x55ca bb924a28 82a424bc 862388d8 85572e18 8623f0e8 aswTdi+0x7f8 bb924a40 90935310 8623f030 82a424bc 8623f030 nt!IofCallDriver+0x63 bb924a60 90900a0e 2b1c89ba bb924b20 00000001 aswRdr+0x310 bb924ab0 908ed542 00000000 908ed542 87a5c530 afd!AfdFastConnectionSend+0x2a6 bb924c28 82c608f7 87ec6701 00000001 02b5f8cc afd!AfdFastIoDeviceControl+0x53d bb924cd0 82c634ac 85a89c10 0000024c 00000000 nt!IopXxxControlFile+0x2d0 bb924d04 82a4942a 00000240 0000024c 00000000 nt!NtDeviceIoControlFile+0x2a bb924d04 774464f4 00000240 0000024c 00000000 nt!KiFastCallEntry+0x12a 02b5f920 00000000 00000000 00000000 00000000 0x774464f4 1: kd> u 8bc7e2cftcpip!TcpBeginTcbSend+0xa8b: 8bc7e2cf 83bd18ffffff00 cmp dword ptr [ebp-0E8h],08bc7e2d6 0f84d1000000 je tcpip!TcpBeginTcbSend+0xb68 (8bc7e3ad) 8bc7e2dc 8d85f8feffff lea eax,[ebp-108h] 8bc7e2e2 3bf8 cmp edi,eax 8bc7e2e4 0f85c3000000 jne tcpip!TcpBeginTcbSend+0xb68 (8bc7e3ad) 8bc7e2ea 83bd54ffffff00 cmp dword ptr [ebp-0ACh],0 8bc7e2f1 0f84b6000000 je tcpip!TcpBeginTcbSend+0xb68 (8bc7e3ad) 8bc7e2f7 f7433c00002000 test dword ptr [ebx+3Ch],200000h
Debug session time: Sat Jan 9 19:42:50.817 2010 (GMT+0) System Uptime: 0 days 3:07:23.6123: kd> !analyze -v BUGCODE_USB_DRIVER (fe) USB Driver bugcheck, first parameter is USB bugcheck code. Arguments: Arg1: 00000006, USBBUGCODE_BAD_SIGNATURE An Internal data structure (object) has been corrupted. Arg2: 864b20e0, Object address Arg3: 4f444648, Signature that was expected Arg4: 00000000 PROCESS_NAME: System CURRENT_IRQL: 2 STACK_TEXT: 8d952b8c 90fa1025 000000fe 00000006 864b20e0 nt!KeBugCheckEx+0x1e 8d952ba8 90fa6672 864b20e0 4f444668 4f444648 USBPORT!USBPORT_AssertSig+0x20 8d952bc8 90fa4553 864b2028 85c57d10 82a8b334 USBPORT!USBPORT_FlushAdapterDBs+0x1b 8d952c00 90fa5178 00000001 856e3ab8 87fb98c0 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x3cb 8d952c2c 90fa89af 864b2028 864b20f0 864b2a98 USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b 8d952c54 90fa2d18 864b2028 864b2a98 864b2002 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc 8d952c78 82ab33b5 864b2aa4 864b2002 00000000 USBPORT!USBPORT_Xdpc_Worker+0x173 8d952cd4 82ab3218 8d936120 8d93b800 00000000 nt!KiExecuteAllDpcs+0xf9 8d952d20 82ab3038 00000000 0000000e 00000000 nt!KiRetireDpcList+0xd5 8d952d24 00000000 0000000e 00000000 00000000 nt!KiIdleLoop+0x38Debug session time: Sun Jan 10 04:06:19.856 2010 (GMT+0) System Uptime: 0 days 0:23:05.6511: kd> !analyze -v PAGE_FAULT_IN_NONPAGED_AREA (50)PROCESS_NAME: FlightSimulatorB.exeCURRENT_IRQL: 0 TRAP_FRAME: a127fa30 -- (.trap 0xffffffffa127fa30) ErrCode = 00000000 eax=a127fec8 ebx=00000000 ecx=00000011 edx=86488ba0 esi=86488b78 edi=00000000 eip=8b83b87d esp=a127faa4 ebp=a127fab8 iopl=0 nv up ei ng nz na po nc cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010282Resetting default scopefltmgr!TreeFindNodeOrParent+0×9: 8b83b87d 0885c974498b or byte ptr mcupdate_GenuineIntel!_NULL_IMPORT_DESCRIPTOR <PERF> (mcupdate_GenuineIntel+0×764c9) (8b4974c9)[ebp],al ss:0010:2c716f81=??
STACK_TEXT: a127fa18 82a8d5f8 00000000 8b497414 00000000 nt!MmAccessFault+0x106 a127fa18 8b83b87d 00000000 8b497414 00000000 nt!KiTrap0E+0xdc a127fab8 8b834340 86488ba4 86e5e458 00000000 fltmgr!TreeFindNodeOrParent+0x9 a127faf8 8b83440a 86488b78 86e5e458 00000000 fltmgr!GetContextFromStreamList+0x50 a127fb14 8b86c6da 86e5e458 86488b78 a127fb40 fltmgr!FltGetStreamContext+0x34 a127fb44 8b866b35 87f30718 a127fb98 a127fba8 fileinfo!FIStreamGet+0x36 a127fbac 8b833aeb 87f30718 a127fbcc a127fbf8 fileinfo!FIPreReadWriteCallback+0xf1 a127fc18 8b83617b a127fc54 85cfd738 a127fcac fltmgr!FltpPerformPreCallbacks+0x34d a127fc30 8b848c37 0027fc54 8b848ad4 00000000 fltmgr!FltpPassThroughFastIo+0x3d a127fc74 82c96b32 85cfd738 a127fcb4 00001000 fltmgr!FltpFastIoRead+0x163 a127fd08 82a8a42a 86e484c0 00000000 00000000 nt!NtReadFile+0x2d5 a127fd08 775864f4 86e484c0 00000000 00000000 nt!KiFastCallEntry+0x12a WARNING: Frame IP not in any known module. Following frames may be wrong. 0202fc8c 00000000 00000000 00000000 00000000 0x775864f4MISALIGNED_IP: fltmgr!TreeFindNodeOrParent+9 8b83b87d 0885c974498b or byte ptr mcupdate_GenuineIntel!_NULL_IMPORT_DESCRIPTOR <PERF> (mcupdate_GenuineIntel+0x764c9) (8b4974c9)[ebp],al1: kd> u fltmgr!TreeFindNodeOrParentIMAGE_NAME: hardwarefltmgr!TreeFindNodeOrParent: 8b83b874 8bff mov edi,edi 8b83b876 55 push ebp 8b83b877 8bec mov ebp,esp 8b83b879 8b4508 mov eax,dword ptr [ebp+8] 8b83b87c 8b08 mov ecx,dword ptr [eax]8b83b87e 85c9 test ecx,ecx 8b83b880 7449 je fltmgr!TreeFindNodeOrParent+0×57 (8b83b8cb) 8b83b882 8b5510 mov edx,dword ptr [ebp+10h] 1: kd> ub 8b834340 fltmgr!GetContextFromStreamList+0x37: 8b834327 8bcb mov ecx,ebx 8b834329 ff15a4d0838b call dword ptr [fltmgr!_imp_ExfAcquirePushLockShared (8b83d0a4)] 8b83432f 33db xor ebx,ebx 8b834331 895dfc mov dword ptr [ebp-4],ebx 8b834334 ff7510 push dword ptr [ebp+10h] 8b834337 ff750c push dword ptr [ebp+0Ch] 8b83433a 57 push edi 8b83433b e896750000 call fltmgr!TreeLookup (8b83b8d6) 1: kd> uf 8b83b8d6 fltmgr!TreeLookup: 8b83b8d6 8bff mov edi,edi 8b83b8d8 55 push ebp 8b83b8d9 8bec mov ebp,esp 8b83b8db 8d4510 lea eax,[ebp+10h] 8b83b8de 50 push eax 8b83b8df ff7510 push dword ptr [ebp+10h] 8b83b8e2 ff750c push dword ptr [ebp+0Ch] 8b83b8e5 ff7508 push dword ptr [ebp+8] 8b83b8e8 e887ffffff call fltmgr!TreeFindNodeOrParent (8b83b874) 8b83b8ed 48 dec eax
8b83b8ee f7d8 neg eax 8b83b8f0 1bc0 sbb eax,eax 8b83b8f2 f7d0 not eax 8b83b8f4 234510 and eax,dword ptr [ebp+10h] 8b83b8f7 5d pop ebp 8b83b8f8 c20c00 ret 0Ch
A spooler service process was hanging and its user memory dump shows many threads blocked waiting for critical sections (Volume 1, page 490) including the main one (Volume 1, page 437):
0:000> kL ChildEBP RetAddr 0007fa94 7c827d29 ntdll!KiFastSystemCallRet0007fa98 7c83d266 ntdll!ZwWaitForSingleObject+0xc 0007fad4 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×1a3 0007faf4 7c82dadf ntdll!RtlEnterCriticalSection+0xa80007fb94 7c82dad1 ntdll!LdrpGetProcedureAddress+0×128 0007fbb0 77e63db9 ntdll!LdrGetProcedureAddress+0×18 0007fbd8 01002ea1 kernel32!GetProcAddress+0×44 0007fc38 01002dbc spoolsv!__delayLoadHelper2+0×1d9 0007fc64 7d1e41fc spoolsv!_tailMerge_SPOOLSS+0xd 0007fcd8 7d1e1ed9 ADVAPI32!ScDispatcherLoop+0×287 0007ff3c 01004019 ADVAPI32!StartServiceCtrlDispatcherW+0xe3 0007ff44 010047a2 spoolsv!main+0xb 0007ffc0 77e6f23b spoolsv!mainCRTStartup+0×12f 0007fff0 00000000 kernel32!BaseProcessStart+0×23 0:000> !analyze -v -hang DERIVED_WAIT_CHAIN: Dl Eid Cid WaitType -- --- ------- -------------------------- 0 3990.3e80 Critical Section- > 183990.3f28 Critical Section PRIMARY_PROBLEM_CLASS: APPLICATION_HANG_HeapCorruption FOLLOWUP_IP: msvcrt!calloc+118 77bbcdf3 8945e4 mov dword ptr [ebp-1Ch],eax 0:018> kL 100 ChildEBP RetAddr 03b589b4 7c827d19 ntdll!KiFastSystemCallRet 03b589b8 77e76792 ntdll!NtWaitForMultipleObjects+0xc 03b58cec 7c8604ae kernel32!UnhandledExceptionFilter+0x7c0 03b58cf4 7c8282f1 ntdll!RtlpPossibleDeadlock+0xa5
03b58d1c 7c828772 ntdll!_except_handler3+0x61
03b58d40 7c828743 ntdll!ExecuteHandler2+0x26
03b58de8 7c82865c ntdll!ExecuteHandler+0x24
03b590c8 7c860491 ntdll!RtlRaiseException+0×3d
03b5914c 7c84cf0c ntdll!RtlpPossibleDeadlock+0×8d
03b59180 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×226
03b591a0 7c82a284 ntdll!RtlEnterCriticalSection+0xa8
03b593c8 77bbcdf3 ntdll!RtlAllocateHeap+0×313
03b59408 77bbd45b msvcrt!calloc+0×118
03b59428 77bd3e55 msvcrt!_calloc_crt+0×19
03b59430 77bcfc38 msvcrt!_getbuf+0×12
03b59444 77bd1f26 msvcrt!_flsbuf+0×76
03b5946c 77bd40e6 msvcrt!_putwc_lk+0×99
03b5947c 77bd445b msvcrt!_ftbuf+0×4d
03b598f8 77bd253b msvcrt!_woutput+0×2ee
03b59940 7617785d msvcrt!fwprintf+0×33
03b59950 761778d3 localspl!InitiateErrorReport+0×28
03b59984 76176cfa localspl!CaptureAndLogException+0×24
03b5998c 3f01484b localspl!SplExceptionLoggingFilter+0×15
WARNING: Stack unwind information not available. Following frames may be
wrong.
03b599ac 02938a47 PrinterDriverA+0xb72b
03b59c34 7c8604ae PrinterDriverB+0xf2a7
03b59c3c 7c8282f1 ntdll!RtlpPossibleDeadlock+0xa5
03b59c64 7c828772 ntdll!_except_handler3+0×61
03b59c88 7c828743 ntdll!ExecuteHandler2+0×26
03b59d30 7c82865c ntdll!ExecuteHandler+0×24
03b5a010 7c860491 ntdll!RtlRaiseException+0×3d
03b5a094 7c84cf0c ntdll!RtlpPossibleDeadlock+0×8d
03b5a0c8 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×226
03b5a0e8 7c82a284 ntdll!RtlEnterCriticalSection+0xa8
03b5a310 77bbcdf3 ntdll!RtlAllocateHeap+0×313
03b5a350 77bbd45b msvcrt!calloc+0×118
03b5a370 77bd3e55 msvcrt!_calloc_crt+0×19
03b5a378 77bcfc38 msvcrt!_getbuf+0×12
03b5a38c 77bd1f26 msvcrt!_flsbuf+0×76
03b5a3b4 77bd40e6 msvcrt!_putwc_lk+0×99
03b5a3c4 77bd445b msvcrt!_ftbuf+0×4d
03b5a840 77bd253b msvcrt!_woutput+0×2ee
03b5a888 7617785d msvcrt!fwprintf+0×33
03b5a898 761778d3 localspl!InitiateErrorReport+0×28
03b5a8cc 76176cfa localspl!CaptureAndLogException+0×24
03b5a8d4 3f01484b localspl!SplExceptionLoggingFilter+0×15
03b5a8f4 02938a47 PrinterDriverA+0xb72b
03b5ab7c 7c8604ae PrinterDriverB+0xf2a7
03b5ab84 7c8282f1 ntdll!RtlpPossibleDeadlock+0xa5
03b5abac 7c828772 ntdll!_except_handler3+0×61
03b5abd0 7c828743 ntdll!ExecuteHandler2+0×26
03b5ac78 7c82865c ntdll!ExecuteHandler+0×24
03b5af58 7c860491 ntdll!RtlRaiseException+0×3d
03b5afdc 7c84cf0c ntdll!RtlpPossibleDeadlock+0×8d
03b5b010 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×226
03b5b030 7c82a284 ntdll!RtlEnterCriticalSection+0xa8
03b5b258 77bbcdf3 ntdll!RtlAllocateHeap+0×313
03b5b298 77bbd45b msvcrt!calloc+0×118 03b5b2b8 77bd3e55 msvcrt!_calloc_crt+0×19 03b5b2c0 77bcfc38 msvcrt!_getbuf+0×12 03b5b2d4 77bd1f26 msvcrt!_flsbuf+0×76 03b5b2fc 77bd40e6 msvcrt!_putwc_lk+0×99 03b5b30c 77bd445b msvcrt!_ftbuf+0×4d 03b5b788 77bd253b msvcrt!_woutput+0×2ee 03b5b7d0 7617785d msvcrt!fwprintf+0×33 03b5b7e0 761778d3 localspl!InitiateErrorReport+0×28 03b5b814 76176cfa localspl!CaptureAndLogException+0×24 03b5b81c 3f01484b localspl!SplExceptionLoggingFilter+0×15 03b5b83c 02938a47 PrinterDriverA+0xb72b 03b5bac4 7c8604ae PrinterDriverB+0xf2a7 03b5bacc 7c8282f1 ntdll!RtlpPossibleDeadlock+0xa5 03b5baf4 7c828772 ntdll!_except_handler3+0×61 03b5bb18 7c828743 ntdll!ExecuteHandler2+0×26 03b5bbc0 7c82865c ntdll!ExecuteHandler+0×24 03b5bea0 7c860491 ntdll!RtlRaiseException+0×3d 03b5bf24 7c84cf0c ntdll!RtlpPossibleDeadlock+0×8d 03b5bf58 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×226 03b5bf78 7c82a284 ntdll!RtlEnterCriticalSection+0xa8 03b5c1a0 77bbcdf3 ntdll!RtlAllocateHeap+0×313 03b5c1e0 77bbd45b msvcrt!calloc+0×118 03b5c200 77bd3e55 msvcrt!_calloc_crt+0×19 03b5c208 77bcfc38 msvcrt!_getbuf+0×12 03b5c21c 77bd1f26 msvcrt!_flsbuf+0×76 03b5c244 77bd40e6 msvcrt!_putwc_lk+0×99 03b5c254 77bd445b msvcrt!_ftbuf+0×4d 03b5c6d0 77bd253b msvcrt!_woutput+0×2ee 03b5c718 7617785d msvcrt!fwprintf+0×33 03b5c728 761778d3 localspl!InitiateErrorReport+0×28 03b5c75c 76176cfa localspl!CaptureAndLogException+0×24 03b5c764 3f01484b localspl!SplExceptionLoggingFilter+0×15 03b5c784 02938a47 PrinterDriverA+0xb72b 03b5ca0c 7c8604ae PrinterDriverB+0xf2a7 03b5ca14 7c8282f1 ntdll!RtlpPossibleDeadlock+0xa5 03b5ca3c 7c828772 ntdll!_except_handler3+0×61 03b5ca60 7c828743 ntdll!ExecuteHandler2+0×26 03b5cb08 7c82865c ntdll!ExecuteHandler+0×24 03b5cde8 7c860491 ntdll!RtlRaiseException+0×3d 03b5ce6c 7c84cf0c ntdll!RtlpPossibleDeadlock+0×8d 03b5cea0 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×226 03b5cec0 7c82a284 ntdll!RtlEnterCriticalSection+0xa8 03b5d0e8 77bbcdf3 ntdll!RtlAllocateHeap+0×313 03b5d128 77bbd45b msvcrt!calloc+0×118 03b5d148 77bd3e55 msvcrt!_calloc_crt+0×19 03b5d150 77bcfc38 msvcrt!_getbuf+0×12 03b5d164 77bd1f26 msvcrt!_flsbuf+0×76 03b5d18c 77bd40e6 msvcrt!_putwc_lk+0×99 03b5d19c 77bd445b msvcrt!_ftbuf+0×4d 03b5d618 77bd253b msvcrt!_woutput+0×2ee 03b5d660 7617785d msvcrt!fwprintf+0×33
03b5d670 761778d3 localspl!InitiateErrorReport+0×28
03b5d6a4 76176cfa localspl!CaptureAndLogException+0×24
03b5d6ac 3f01484b localspl!SplExceptionLoggingFilter+0×15
03b5d6cc 02938a47 PrinterDriverA+0xb72b
03b5d954 7c8604ae PrinterDriverB+0xf2a7
03b5d95c 7c8282f1 ntdll!RtlpPossibleDeadlock+0xa5
03b5d984 7c828772 ntdll!_except_handler3+0×61
03b5d9a8 7c828743 ntdll!ExecuteHandler2+0×26
03b5da50 7c82865c ntdll!ExecuteHandler+0×24
03b5dd30 7c860491 ntdll!RtlRaiseException+0×3d
03b5ddb4 7c84cf0c ntdll!RtlpPossibleDeadlock+0×8d
03b5dde8 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×226
03b5de08 7c82a284 ntdll!RtlEnterCriticalSection+0xa8
03b5e030 77bbcdf3 ntdll!RtlAllocateHeap+0×313
03b5e070 77bbd45b msvcrt!calloc+0×118
03b5e090 77bd3e55 msvcrt!_calloc_crt+0×19
03b5e098 77bcfc38 msvcrt!_getbuf+0×12
03b5e0ac 77bd1f26 msvcrt!_flsbuf+0×76
03b5e0d4 77bd40e6 msvcrt!_putwc_lk+0×99
03b5e0e4 77bd445b msvcrt!_ftbuf+0×4d
03b5e560 77bd253b msvcrt!_woutput+0×2ee
03b5e5a8 7617785d msvcrt!fwprintf+0×33
03b5e5b8 761778d3 localspl!InitiateErrorReport+0×28
03b5e5ec 76176cfa localspl!CaptureAndLogException+0×24
03b5e5f4 3f01484b localspl!SplExceptionLoggingFilter+0×15
03b5e614 02938a47 PrinterDriverA+0xb72b
03b5e89c 7c8604ae PrinterDriverB+0xf2a7
03b5e8a4 7c8282f1 ntdll!RtlpPossibleDeadlock+0xa5
03b5e8cc 7c828772 ntdll!_except_handler3+0×61
03b5e8f0 7c828743 ntdll!ExecuteHandler2+0×26
03b5e998 7c82865c ntdll!ExecuteHandler+0×24
03b5ec78 7c860491 ntdll!RtlRaiseException+0×3d
03b5ecfc 7c84cf0c ntdll!RtlpPossibleDeadlock+0×8d
03b5ed30 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×226
03b5ed50 7c82a284 ntdll!RtlEnterCriticalSection+0xa8
03b5ef78 77bbd08c ntdll!RtlAllocateHeap+0×313
03b5ef98 74ef12ca msvcrt!malloc+0×6c
03b5efac 74ef1241 resutils!_malloc_crt+0xf
03b5efb8 74ef132b resutils!_CRT_INIT+0×37
03b5efd8 7c81a352 resutils!_DllMainCRTStartup+0×42
03b5eff8 7c83348d ntdll!LdrpCallInitRoutine+0×14
03b5f100 7c834339 ntdll!LdrpRunInitializeRoutines+0×367
03b5f394 7c83408d ntdll!LdrpLoadDll+0×3cd
03b5f610 77e41bf7 ntdll!LdrLoadDll+0×198
03b5f678 77e5c70b kernel32!LoadLibraryExW+0×1b2
03b5f68c 7406621a kernel32!LoadLibraryW+0×11
03b5f6a8 740663c4 SPOOLSS!TClusterAPI::TClusterAPI+0×2d
03b5f758 74072c6b SPOOLSS!GetClusterIPAddresses+0×26
03b5f7bc 74072d8e SPOOLSS!TNameResolutionCache::IsNameCluster+0xdf
03b5f7d0 7403cf4d SPOOLSS!CacheIsNameCluster+0×1c
03b5f7e8 7403514e win32spl!IsNameTheLocalMachineOrAClusterSpooler+0xa1
03b5f818 74067306 win32spl!CacheOpenPrinter+0×4d
03b5f864 74066cf5 SPOOLSS!RouterOpenPrinterW+0×1bb
03b5f884 01004cf4 SPOOLSS!OpenPrinterW+0×19
03b5f8ac 01004c9e spoolsv!YOpenPrinter+0×5a 03b5f8d0 77c80193 spoolsv!RpcOpenPrinter+0×37 03b5f8f8 77ce33e1 RPCRT4!Invoke+0×30 03b5fcf8 77ce35c4 RPCRT4!NdrStubCall2+0×299 03b5fd14 77c7ff7a RPCRT4!NdrServerCall2+0×19 03b5fd48 77c8042d RPCRT4!DispatchToStubInCNoAvrf+0×38 03b5fd9c 77c80353 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×11f 03b5fdc0 77c811dc RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 03b5fdfc 77c812f0 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×42c 03b5fe20 77c88678 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×127 03b5ff84 77c88792 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430 03b5ff8c 77c8872d RPCRT4!RecvLotsaCallsWrapper+0xd 03b5ffac 77c7b110 RPCRT4!BaseCachedThreadRoutine+0×9d 03b5ffb8 77e6482f RPCRT4!ThreadStartRoutine+0×1b 03b5ffec 00000000 kernel32!BaseThreadStart+0×34
The default command also reports a heap corruption but the closer inspection reveals that it was a detected (Volume 2, page 318) deadlock (Volume 1, page 276):
0:018> kv 100 ChildEBP RetAddr Args to Child 03b589b4 7c827d19 77e76792 00000002 03b58b5c ntdll!KiFastSystemCallRet 03b589b8 77e76792 00000002 03b58b5c 00000001 ntdll!NtWaitForMultipleObjects+0xc 03b58cec 7c8604ae7c8282f1 03b58d1c kernel32!UnhandledExceptionFilter+0×7c0 03b58cf4 7c8282f1 03b58d1c 00000000 03b58d1c ntdll!RtlpPossibleDeadlock+0xa5 03b58d1c 7c828772 03b590e0 03b5913c 03b58df8 ntdll!_except_handler3+0×61 03b58d40 7c828743 03b590e0 03b5913c 03b58df8 ntdll!ExecuteHandler2+0×26 03b58de8 7c82865c 03b58000 03b58df8 00010007 ntdll!ExecuteHandler+0×24 03b590c8 7c860491 03b590e0 7c88a9e8 00030608 ntdll!RtlRaiseException+0×3d 03b5914c 7c84cf0c 00030608 00000001 0003060c ntdll!RtlpPossibleDeadlock+0×8d 03b59180 7c83d2b1 00000c4c 00000004 00030000 ntdll!RtlpWaitOnCriticalSection+0×226 03b591a0 7c82a28403b58d140003060800000000 00001000 ntdll!RtlEnterCriticalSection+0xa8 03b593c8 77bbcdf3 00030000 00000008 00001000 ntdll!RtlAllocateHeap+0×313 [...] 03b5e89c 7c8604ae 03b5e8c4 7c8282f1 03b5e8cc PrinterDriverA+0xf2a7 03b5e8a4 7c8282f1 03b5e8cc 00000000 03b5e8cc ntdll!RtlpPossibleDeadlock+0xa5 03b5e8cc 7c828772 03b5ec90 03b5ecec 03b5e9a8 ntdll!_except_handler3+0×61 03b5e8f0 7c828743 03b5ec90 03b5ecec 03b5e9a8 ntdll!ExecuteHandler2+0×26 03b5e998 7c82865c 03b58000 03b5e9a8 00010007 ntdll!ExecuteHandler+0×24 03b5ec78 7c8604917c88a9e8 00030608 ntdll!RtlRaiseException+0×3d 03b5ecfc 7c84cf0c 00030608 00000001 0003060c ntdll!RtlpPossibleDeadlock+0×8d 03b5ed30 7c83d2b1 00000c4c 00000004 00030000 ntdll!RtlpWaitOnCriticalSection+0×226 03b5ed50 7c82a28403b5ec900003060800000080 00000000 ntdll!RtlEnterCriticalSection+0xa8 03b5ef78 77bbd08c 00030000 00000000 00000080 ntdll!RtlAllocateHeap+0×313 03b5ef98 74ef12ca 00000080 00000000 00000000 msvcrt!malloc+0×6c 03b5efac 74ef1241 00000001 03b5efd8 74ef132b resutils!_malloc_crt+0xf 03b5efb8 74ef132b 74ef0000 00000001 00000000 resutils!_CRT_INIT+0×37 03b5efd8 7c81a352 74ef0000 00000001 00000000 resutils!_DllMainCRTStartup+0×42 03b5eff8 7c83348d 74ef12f4 74ef0000 00000001 ntdll!LdrpCallInitRoutine+0×14 03b5f100 7c834339 00000000 00000000 00000004 ntdll!LdrpRunInitializeRoutines+0×367 03b5f394 7c83408d 00000000 02785a60 03b5f65c ntdll!LdrpLoadDll+0×3cd 03b5f610 77e41bf7 02785a60 03b5f65c 03b5f63c ntdll!LdrLoadDll+0×198 03b5f678 77e5c70b 740654d4 00000000 00000000 kernel32!LoadLibraryExW+0×1b2 03b5f68c 7406621a 740654d4 000348b8 03b5f784 kernel32!LoadLibraryW+0×11 03b5f6a8 740663c4 000348b8 00000000 534c4354 SPOOLSS!TClusterAPI::TClusterAPI+0×2d
03b5f758 74072c6b 03b5f784 000e5874 00000610 SPOOLSS!GetClusterIPAddresses+0×26 03b5f7bc 74072d8e 00032920 000e5874 00000000 SPOOLSS!TNameResolutionCache::IsNameCluster+0xdf 03b5f7d0 7403cf4d 000e5874 000e5870 00000000 SPOOLSS!CacheIsNameCluster+0×1c 03b5f7e8 7403514e 000e5870 74075040 00c538f0 win32spl!IsNameTheLocalMachineOrAClusterSpooler+0xa1 03b5f818 74067306 000e5870 03b5f858 03b5f8a0 win32spl!CacheOpenPrinter+0×4d 03b5f864 74066cf5 000e5870 0273e500 03b5f8a0 SPOOLSS!RouterOpenPrinterW+0×1bb 03b5f884 01004cf4 000e5870 0273e500 03b5f8a0 SPOOLSS!OpenPrinterW+0×19 03b5f8ac 01004c9e 000e5870 0273e500 00000000 spoolsv!YOpenPrinter+0×5a 03b5f8d0 77c80193 000e5870 0273e500 00000000 spoolsv!RpcOpenPrinter+0×37 03b5f8f8 77ce33e1 01004c65 03b5fae0 00000005 RPCRT4!Invoke+0×30 03b5fcf8 77ce35c4 00000000 00000000 000f73d4 RPCRT4!NdrStubCall2+0×299 03b5fd14 77c7ff7a 000f73d4 000e4d30 000f73d4 RPCRT4!NdrServerCall2+0×19 03b5fd48 77c8042d 01002c47 000f73d4 03b5fdec RPCRT4!DispatchToStubInCNoAvrf+0×38 03b5fd9c 77c80353 00000001 00000000 0100d228 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×11f 03b5fdc0 77c811dc 000f73d4 00000000 0100d228 RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 03b5fdfc 77c812f0 000f21d8 000e7028 000e5828 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×42c 03b5fe20 77c88678 000e7060 03b5fe38 000f21d8 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×127 03b5ff84 77c88792 03b5ffac 77c8872d 000e7028 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430 03b5ff8c 77c8872d 000e7028 00000000 00000000 RPCRT4!RecvLotsaCallsWrapper+0xd 03b5ffac 77c7b110 000995b8 03b5ffec 77e6482f RPCRT4!BaseCachedThreadRoutine+0×9d 03b5ffb8 77e6482f 02753798 00000000 00000000 RPCRT4!ThreadStartRoutine+0×1b 03b5ffec 00000000 77c7b0f5 02753798 00000000 kernel32!BaseThreadStart+0×34 0:018> .exptr----- Exception record at 03b590e0: ExceptionAddress: 7c860491 (ntdll!RtlpPossibleDeadlock+0x0000008d) ExceptionCode: c0000194 ExceptionFlags: 00000000 NumberParameters: 1 Parameter[0]: 0003060803b58d14Critical section at 00030608 is owned by thread 00000000, causing this thread to raise an exception----- Context record at 03b58df8: eax=00000000 ebx=00000003 ecx=00030608 edx=03b590e0 esi=01000002 edi=7c88a9e8 eip=7c860491 esp=03b590d4 ebp=03b5914c iopl=0 nv up ei pl zr na pe nc cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246 ntdll!RtlpPossibleDeadlock+0x8d: 7c860491 eb24 jmp ntdll!RtlpPossibleDeadlock+0xa9 (7c8604b7) 0:018> .exrExceptionAddress: 7c860491 (ntdll!RtlpPossibleDeadlock+0×0000008d) ExceptionCode: c0000194 ExceptionFlags: 00000000 NumberParameters: 1 Parameter[0]: 0003060803b5ec90Critical section at 00030608 is owned by thread 00000000, causing this thread to raise an exception
Notice that the problem section doesn't have an owner. In order to find it we do search in memory:
0:018> s -d 0 L40000000003060800030578 00030608 00000000 00030688 010100000162fa04 00030608 00000002 0162fad0 0162fb1c 03b58b6c 00030608 00000704 00000082 03b589d4 03b58ea4 00030608 00000000 03b5914c 7c860491 03b5907c 00030608 00000003 000000e8 010000e8 03b590d8 00030608 00000003 c0000194 00000000 03b590f4 00030608 00000704 0000e7c8 03b58e84 03b59154 00030608 00000001 0003060c 00000000 03b591a8 00030608 00000000 00001000 00000000 03b59dec 00030608 00000000 03b5a094 7c860491 03b59fc4 00030608 00000003 000000e8 010000e8 03b5a020 00030608 00000003 c0000194 00000000 03b5a03c 00030608 00000704 0000e7c8 03b59dcc 03b5a09c 00030608 00000001 0003060c 00000000 03b5a0f0 00030608 00000000 00001000 00000000 03b5ad34 00030608 00000000 03b5afdc 7c860491 03b5af0c 00030608 00000003 000000e8 010000e8 03b5af68 00030608 00000003 c0000194 00000000 03b5af84 00030608 00000704 0000e7c8 03b5ad14 03b5afe4 00030608 00000001 0003060c 00000000 03b5b038 00030608 00000000 00001000 00000000 03b5bc7c 00030608 00000000 03b5bf24 7c860491 03b5be54 00030608 00000003 000000e8 010000e8 03b5beb0 00030608 00000003 c0000194 00000000 03b5becc 00030608 00000704 0000e7c8 03b5bc5c 03b5bf2c 00030608 00000001 0003060c 00000000 03b5bf80 00030608 00000000 00001000 00000000 03b5cbc4 00030608 00000000 03b5ce6c 7c860491 03b5cd9c 00030608 00000003 000000e8 010000e8 03b5cdf8 00030608 00000003 c0000194 00000000 03b5ce14 00030608 00000704 0000e7c8 03b5cba4 03b5ce74 00030608 00000001 0003060c 00000000 03b5cec8 00030608 00000000 00001000 00000000 03b5db0c 00030608 00000000 03b5ddb4 7c860491 03b5dce4 00030608 00000003 000000e8 010000e8 03b5dd40 00030608 00000003 c0000194 00000000 03b5dd5c 00030608 00000704 0000e7c8 03b5daec 03b5ddbc 00030608 00000001 0003060c 00000000 03b5de10 00030608 00000000 00001000 00000000 03b5ea54 00030608 00000000 03b5ecfc 7c860491 03b5ec2c 00030608 00000003 000000e8 010000e8 03b5ec88 00030608 00000003 c0000194 00000000 03b5eca4 00030608 7c82a11c 0000e7c8 03b5ea34 03b5ed04 00030608 00000001 0003060c 00000000 03b5ed58 00030608 00000080 00000000 7c829ff6
Addresses that start with 03b5 belong to the thread #18 we have seen already, the address 00030578 looks like belonging to the critical section list and the address 0162fa04 belongs to the thread #8 (we find it by looking at all thread stacks (Volume 1, page 409) and search for 0162 in ChildEBP fields):
0:018> ~*k [...] 8 Id: 3990.3d60 Suspend: 1 Teb: 7ffae000 Unfrozen ChildEBP RetAddr0162ff18 7c827d29 ntdll!KiFastSystemCallRet0162ff1c 77e61d1e ntdll!ZwWaitForSingleObject+0xc0162ff8c 77e61c8d kernel32!WaitForSingleObjectEx+0xac0162ffa0 72461375 kernel32!WaitForSingleObject+0×120162ffb8 77e6482f tcpmon!CDeviceStatus::StatusThread+0×2a0162ffec 00000000 kernel32!BaseThreadStart+0×34 [...]
Nothing interesting there until we look at the raw stack and its execution residue (Volume 2, page 239):
0:008> ~8s; !teb
eax=00000001 ebx=7246b050 ecx=0162fa78 edx=00000010 esi=0000041c
edi=00000000
eip=7c82860c esp=0162ff1c ebp=0162ff8c iopl=0 nv up ei ng nz ac pe
cy
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000
297
ntdll!KiFastSystemCallRet:
7c82860c c3 ret
TEB at 7ffae000
ExceptionList: 0162ff7c
StackBase: 01630000
StackLimit: 01628000
SubSystemTib: 00000000
FiberData: 00001e00
ArbitraryUserPointer: 00000000
Self: 7ffae000
EnvironmentPointer: 00000000
ClientId: 00003990 . 00003d60
RpcHandle: 00000000
Tls Storage: 00000000
PEB Address: 7ffde000
LastErrorValue: 0
LastStatusValue: c000000d
Count Owned Locks: 0
HardErrorMode: 0
0:008> dds01628000 0163000001628000 00000000 01628004 00000000 01628008 00000000 0162800c 00000000 01628010 00000000 01628014 00000000 01628018 00000000 [...] 0162f984 313231a0 0162f988 0000e7c8 0162f98c 0162f9c8 0162f990 7c80b429 ntdll!_vsnprintf+0×2f 0162f994 0162f9a8 0162f998 7c84cf68 ntdll!RtlpNotOwnerCriticalSection+0×118 0162f99c 0000e7c8 0162f9a0 0162f9dc 0162f9a4 7c80b429 ntdll!_vsnprintf+0×2f 0162f9a8 0162f9bc 0162f9ac 7c84cfb8 ntdll!RtlpNotOwnerCriticalSection+0×168 0162f9b0 0162fcc0 0162f9b4 00000000 0162f9b8 00000200 0162f9bc 7c808080 ntdll!DbgSetDebugFilterState+0xc 0162f9c0 00000000 0162f9c4 00000000 0162f9c8 7c808080 ntdll!DbgSetDebugFilterState+0xc 0162f9cc 00000001 0162f9d0 0162f9ec0162f9d8 00000001 0162f9dc0162f9d4 7c8081d9 ntdll!DebugPrint+0×1c0162fa780162f9e0 00000010 0162f9e4 ffffffff 0162f9e8 00000000 0162f9ec 0162fc94 0162f9f0 7c808194 ntdll!vDbgPrintExWithPrefixInternal+0×177 0162f9f4 0162fa60 0162f9f8 ffffffff 0162f9fc 7c812f85 ntdll!vDbgPrintExWithPrefixInternal+0×1d5 0162fa00 7c88a9e8 ntdll!RtlpTimeout0162fa08 00000002 0162fa0c 0162fad0 0162fa10 0162fb1c 0162fa14 7c828290 ntdll!_except_handler3 0162fa18 7c82d9b8 ntdll!'string'+0xc 0162fa1c ffffffff 0162fa20 7c82d9b5 ntdll!LdrpGetProcedureAddress+0xb3 0162fa24 7c82eaa3 ntdll!LdrpSnapThunk+0×31c 0162fa28 7c800000 ntdll!RtlDosPathSeperatorsString <PERF> (ntdll+0×0) [...]0162fa04 00030608
Here we find DebugPrint call in close proximity (Volume 2, page 300) to our critical section address and we dump its possible local data:
0:008> dc0162fa780162fa78 3a4c5452 2d655220 74696157 0a676e690162fa88 43203400 69746972 206c6163 74636553RTL: Re-Waiting.0162fa98 206e6f69 33303030 38303630 43202d20.4 Critical Sect0162faa8 65746e6f 6f69746e 756f436e 3d20746eion 00030608 - C0162fab8 0a38203d 00007000 000923a8 0162fad0ontentionCount =.p...#....b. 0162fac8 7c82b0ae 00000000 65440000 65646f63 ...|......Decode 0162fad8 6e696f50 00726574 0162fba4 00007078 Pointer...b.xp.. 0162fae8 000923a8 0162faf8 7c82b0ae 00000000 .#....b....|....= 8.
Nothing still points to that critical section owner and we try to find similar self-diagnostic messages in our original thread #18. We find one DebugPrint call in close proximity to deadlock detection and exception raising calls (after similar ~18s; !teb and dds commands):
03b58de0 03b60000 03b58de4 00000000 03b58de8 03b590c8 03b58dec 7c82865c ntdll!RtlRaiseException+0x3d 03b58df0 03b58000 03b58df4 03b58df8 03b58df8 00010007 03b58dfc 00000000 03b58e00 00000000 03b58e04 00000000 03b58e08 00000000 03b58e0c 00000000 03b58e10 33303030 03b58e14 38303630 03b58e18 00000000 03b58e1c 32323100 03b58e20 0000e7c8 03b58e24 03b58e60 03b58e28 7c80b429 ntdll!_vsnprintf+0x2f 03b58e2c 03b58e40 03b58e30 7c84cf68 ntdll!RtlpNotOwnerCriticalSection+0x118 03b58e34 03b59144 03b58e38 00000000 03b58e3c 00000200 03b58e40 7c808080 ntdll!DbgSetDebugFilterState+0xc 03b58e44 00000000 03b58e48 00000000 03b58e4c 7c808080 ntdll!DbgSetDebugFilterState+0xc 03b58e50 00000001 03b58e54 03b58e7003b58e5c 00000001 03b58e6003b58e58 7c8081d9 ntdll!DebugPrint+0×1c03b58efc
03b58e64 00000058 03b58e68 ffffffff 03b58e6c 00000000 03b58e70 03b59118 03b58e74 7c808194 ntdll!vDbgPrintExWithPrefixInternal+0×177 03b58e78 03b58ee4 03b58e7c ffffffff 03b58e80 7c812f85 ntdll!vDbgPrintExWithPrefixInternal+0×1d5 03b58e84 7c880000 ntdll!_raise_exc_ex+0xc5 03b58e88 0003003b 03b58e8c 00000023 03b58e90 00030023 03b58e94 7c88a9e8 ntdll!RtlpTimeout 03b58e98 01000002 spoolsv!_imp__SetServiceStatus <PERF> (spoolsv+0×2) 03b58e9c 00000003 03b58ea0 03b590e0 03b58ea4 00030608 03b58ea8 00000000 03b58eac 03b5914c 03b58eb0 7c860491 ntdll!RtlpPossibleDeadlock+0×8d 03b58eb4 0000001b 03b58eb8 00000246 03b58ebc 03b590d4 03b58ec0 00000023 03b58ec4 00000000 0:018> dc03b58efc03b58efc 3a4c5452 64695020 6469542e 39393320 RTL: Pid.Tid 399 03b58f0c 66332e30 202c3832 656e776f 69742072 0.3f28,03b58f1c 62332064 43203439 69746972 206c6163owner ti03b58f2c 74636553 206e6f69 33303030 38303630d 3b94 Critical03b58f3c 43202d20 65746e6f 6f69746e 756f436e - ContentionCou 03b58f4c 3d20746e 0a38203d 00165200 0277f0b0 nt == 8..R....w. 03b58f5c 000afa08 00020007 004cbe42 ffff0000 ........B.L..... 03b58f6c 004cbe41 00165230 00000072 0000000a A.L.0R..r.......Section 00030608
Now we see the owner TID 3b94! We immediately check its stack trace:
0:018> ~~[3b940:020> kL 100 ChildEBP RetAddr 036a792c 7c827d29 ntdll!KiFastSystemCallRet036a7930 7c83d266 ntdll!ZwWaitForSingleObject+0xc 036a796c 7c83d2b1 ntdll!RtlpWaitOnCriticalSection+0×1a3 036a798c 7c82d263 ntdll!RtlEnterCriticalSection+0xa8036a79c0 77e63cd8 ntdll!LdrLockLoaderLock+0xe4 036a7a20 0292703f kernel32!GetModuleFileNameW+0×77036a854c 6dfce91c COMPSTUI!CallpfnPSUI+0xdb 036a8564 6dfce5fc COMPSTUI!DeleteCPSUIPageProc+0×52 036a8580 6dfcff97 COMPSTUI!EnumCPSUIPages+0×40 036a87f0 6dfd00a2 COMPSTUI!InsertPSUIPage+0×27a 036a8848 7307c9ae COMPSTUI!CPSUICallBack+0xed 036a8870 6dfd059a WINSPOOL!DevicePropertySheets+0xd4 036a88d4 6dfcff1e COMPSTUI!CallpfnPSUI+0xdb 036a8b40 6dfd00a2 COMPSTUI!InsertPSUIPage+0×201 036a8b98 6dfd06a3 COMPSTUI!CPSUICallBack+0xed 036a8bcc 6dfd0799 COMPSTUI!DoCommonPropertySheetUI+0×74 036a8be4 730801c5 COMPSTUI!CommonPropertySheetUIW+0×17 036a8c2c 73080f5d WINSPOOL!CallCommonPropertySheetUI+0×43 036a9074 35145947 WINSPOOL!PrinterPropertiesNative+0×10c 036a90c4 3513a045 PrinterDriverA+0×159c7 036ae9ac 35131819 PrinterDriverA+0xa0c5 036aebdc 7111460e PrinterDriverA+0×1899 036aec04 7110faa3 UNIDRVUI!HComOEMPrinterEvent+0×33 036aec48 02927a79 UNIDRVUI!DrvPrinterEvent+0×27a 036aeea4 7308218c PrinterDriverA+0×20f9 036aeef0 761543c8 WINSPOOL!SpoolerPrinterEventNative+0×57 036aef0c 761560d2 localspl!SplDriverEvent+0×21 036aef30 761447f9 localspl!PrinterDriverEvent+0×46 036af3f8 76144b12 localspl!SplAddPrinter+0×5f3 036af424 74070193 localspl!LocalAddPrinterEx+0×2e 036af874 7407025c SPOOLSS!AddPrinterExW+0×151 036af890 0100792d SPOOLSS!AddPrinterW+0×17 036af8ac 01006762 spoolsv!YAddPrinter+0×75 036af8d0 77c80193 spoolsv!RpcAddPrinter+0×37 036af8f8 77ce33e1 RPCRT4!Invoke+0×30 036afcf8 77ce35c4 RPCRT4!NdrStubCall2+0×299 036afd14 77c7ff7a RPCRT4!NdrServerCall2+0×19 036afd48 77c8042d RPCRT4!DispatchToStubInCNoAvrf+0×38 036afd9c 77c80353 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×11f 036afdc0 77c811dc RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 036afdfc 77c812f0 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×42c 036afe20 77c88678 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×127 036aff84 77c88792 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430 036aff8c 77c8872d RPCRT4!RecvLotsaCallsWrapper+0xd 036affac 77c7b110 RPCRT4!BaseCachedThreadRoutine+0×9d 036affb8 77e6482f RPCRT4!ThreadStartRoutine+0×1b 036affec 00000000 kernel32!BaseThreadStart+0×34036a809c 02926f2c PrinterDriverA+0×1c1f 036a84e8 6dfd059a PrinterDriverA+0×1b0c
We see that it also has PrinterDriverA module on the stack trace and is waiting for a critical section that is owned by the thread #18 we have already seen:
0:020> kv ChildEBP RetAddr Args to Child 036a792c 7c827d29 7c83d266 000001b4 00000000 ntdll!KiFastSystemCallRet 036a7930 7c83d266 000001b4 00000000 7c88a9e8 ntdll!ZwWaitForSingleObject+0xc 036a796c 7c83d2b1 000001b4 00000004 00000001 ntdll!RtlpWaitOnCriticalSection+0x1a3 036a798c 7c82d26301000000 7c8897ec ntdll!RtlEnterCriticalSection+0xa8 036a79c0 77e63cd8 00000001 00000000 036a79fc ntdll!LdrLockLoaderLock+0xe4 036a7a20 0292703f 00000000 036a7a68 00000208 kernel32!GetModuleFileNameW+0×77 [...] 0:020> !cs -o7c8897a0-------------- Critical section = 0×7c8897a0 (ntdll!LdrpLoaderLock+0×0) DebugInfo = 0×7c8897c0 LOCKED LockCount = 0xB WaiterWoken = No OwningThread = 0×00003f28 RecursionCount = 0×2 LockSemaphore = 0×1B4 SpinCount = 0×000000007c8897a0OwningThread Stack = [...]OwningThread DbgId = ~18s
If we look again at the thread #18 we would see PrinterDriverA there too. So check its timestamp using lmv command and find out that its version is older than expected (Volume 2, page 299).
Note: !cs -l -o -s command is not helpful here and in fact it doesn't list #20 thread as a blocking thread so our inference about PrinterDriverA is speculative.
A print spooler service process was hanging and blocking print-related requests from other coupled processes (Volume 1, page 419). Default analysis of its dump doesn't show any problem (it shows the normal service main thread):
0:000> !analyze -v EXCEPTION_RECORD: ffffffff -- (.exr 0xffffffffffffffff) ExceptionAddress: 00000000 ExceptionCode: 80000003 (Break instruction exception) ExceptionFlags: 00000000 NumberParameters: 0 BUGCHECK_STR: APPLICATION_FAULT_STATUS_BREAKPOINT STACK_TEXT: 0006fbcc 7c82776b 77e418b2 00000064 00000000 ntdll!KiFastSystemCallRet 0006fbd0 77e418b2 00000064 00000000 00000000 ntdll!NtReadFile+0xc 0006fc38 77f65edb 00000064 0006fd04 0000021a kernel32!ReadFile+0x16c 0006fc64 77f65f82 00000064 0006fd04 0000021a advapi32!ScGetPipeInput+0x2a 0006fcd8 77f51ed9 00000064 0006fd04 0000021a advapi32!ScDispatcherLoop+0x51 0006ff3c 01004019 0100d5bc 010047a2 00000001 advapi32!StartServiceCtrlDispatcherW+0xe3 0006ff44 010047a2 00000001 00263fa0 00262be0 spoolsv!main+0xb 0006ffc0 77e6f23b 00000000 00000000 7ffd7000 spoolsv!mainCRTStartup+0x12f 0006fff0 00000000 0100468c 00000000 78746341 kernel32!BaseProcessStart+0x23 0:000> !analyze -v -hang EXCEPTION_RECORD: ffffffff -- (.exr 0xffffffffffffffff) ExceptionAddress: 00000000 ExceptionCode: 80000003 (Break instruction exception) ExceptionFlags: 00000000 NumberParameters: 0 BUGCHECK_STR: HANG STACK_TEXT: 0006fbcc 7c82776b 77e418b2 00000064 00000000 ntdll!KiFastSystemCallRet 0006fbd0 77e418b2 00000064 00000000 00000000 ntdll!NtReadFile+0xc 0006fc38 77f65edb 00000064 0006fd04 0000021a kernel32!ReadFile+0x16c 0006fc64 77f65f82 00000064 0006fd04 0000021a advapi32!ScGetPipeInput+0x2a 0006fcd8 77f51ed9 00000064 0006fd04 0000021a advapi32!ScDispatcherLoop+0x51 0006ff3c 01004019 0100d5bc 010047a2 00000001 advapi32!StartServiceCtrlDispatcherW+0xe3 0006ff44 010047a2 00000001 00263fa0 00262be0 spoolsv!main+0xb 0006ffc0 77e6f23b 00000000 00000000 7ffd7000 spoolsv!mainCRTStartup+0x12f 0006fff0 00000000 0100468c 00000000 78746341 kernel32!BaseProcessStart+0x23
Stack trace collection (Volume 1, page 409) shows several threads waiting for a critical section when allocating heap blocks or calling the loader functions, for example:
0:000> ~*k [...] 20 Id: 540.71d0 Suspend: 1 Teb: 7ffa2000 Unfrozen ChildEBP RetAddr 0597fa20 7c827d0b ntdll!KiFastSystemCallRet 0597fa24 7c83d236 ntdll!NtWaitForSingleObject+0xc0597fa60 7c83d281 ntdll!RtlpWaitOnCriticalSection+0×1a3 0597fa80 7c82a264 ntdll!RtlEnterCriticalSection+0xa8 0597fca8 77c7e5cf ntdll!RtlAllocateHeap+0×3130597fcbc 77c7e5a6 rpcrt4!AllocWrapper+0×1e 0597fcc8 77c82069 rpcrt4!operator new+0xd 0597fdf4 77c812a5 rpcrt4!LRPC_SCALL::LrpcMessageToRpcMessage+0xd0 0597fe20 77c88678 rpcrt4!LRPC_ADDRESS::DealWithLRPCRequest+0×66 0597ff84 77c88792 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430 0597ff8c 77c8872d rpcrt4!RecvLotsaCallsWrapper+0xd 0597ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0×9d 0597ffb8 77e64829 rpcrt4!ThreadStartRoutine+0×1b 0597ffec 00000000 kernel32!BaseThreadStart+0×34 21 Id: 540.5b3c Suspend: 1 Teb: 7ff9f000 Unfrozen ChildEBP RetAddr 090dfea0 7c827d0b ntdll!KiFastSystemCallRet 090dfea4 7c83d236 ntdll!NtWaitForSingleObject+0xc090dfee0 7c83d281 ntdll!RtlpWaitOnCriticalSection+0×1a3 090dff00 7c81909b ntdll!RtlEnterCriticalSection+0xa8090dffa8 77e4f920 ntdll!LdrShutdownThread+0×33 090dffb8 77e6482e kernel32!ExitThread+0×2f 090dffec 00000000 kernel32!BaseThreadStart+0×39 [...]
!cs command shows wait chains (Volume 1, page 490) and signs of critical section corruption (Volume 2, page 324). Here is the commented output:
0:000> !cs -l -o -s ----------------------------------------- DebugInfo = 0x7c8877c0Critical section = 0×7c8877a0 (ntdll!LdrpLoaderLock+0×0)LOCKEDLockCount = 0×5WaiterWoken = No OwningThread = 0×00005a20 RecursionCount = 0×1 LockSemaphore = 0×184
SpinCount = 0×00000000OwningThread DbgId = ~25sOwningThread Stack = ChildEBP RetAddr Args to Child 0568f42c 7c827d0b 7c83d236 00000da0 00000000 ntdll!KiFastSystemCallRet 0568f430 7c83d236 00000da0 00000000 00000000 ntdll!NtWaitForSingleObject+0xc 0568f46c 7c83d281 00000da0 00000004 00080000 ntdll!RtlpWaitOnCriticalSection+0×1a3 0568f48c 7c82a264 00080608 7c82e6b4 0000008e ntdll!RtlEnterCriticalSection+0xa8 0568f6b4 77e6427d 00080000 00000000 00000594 ntdll!RtlAllocateHeap+0×313 0568f718 77e643a2 77e643d0 00020abc 00000000 kernel32!BasepComputeProcessPath+0xc2 0568f758 77e65348 00000000 00000000 00000000 kernel32!BaseComputeProcessDllPath+0xe3 0568f79c 77e6528f 0568f7b8 00000000 4dc5822c kernel32!GetModuleHandleForUnicodeString+0×2b 0568fc14 77e65155 00000001 00000002 0568fc38 kernel32!BasepGetModuleHandleExW+0×17f 0568fc2c 4dc4d554 0568fc38 003a0043 0057005c kernel32!GetModuleHandleW+0×29 0568fe4c 4dc49a0a 4dc32328 00000001 0568fe80 MSCTFIME!GetSystemModuleHandleW+0×40 0568fe5c 4dc49bc3 4dc5822c 4dc32328 4dc32380 MSCTFIME!GetFn+0×2e 0568fe74 4dc49039 00000003 0568fea0 4dc49fbb MSCTFIME!TF_DllDetachInOther+0×2a 0568fe80 4dc49fbb 4dc30000 00000003 00000000 MSCTFIME!DllMain+0×1d 0568fea0 7c81a352 4dc30000 00000003 00000000 MSCTFIME!_DllMainCRTStartup+0×52 0568fec0 7c819178 4dc49f69 4dc30000 00000003 ntdll!LdrpCallInitRoutine+0×14 0568ff74 77e4f920 3533e0ec 00000000 0568ff98 ntdll!LdrShutdownThread+0xd2 0568ff84 77e52868 00000000 3533e0ec 77e5bf51 kernel32!ExitThread+0×2f 0568ff98 3530cd31 35100000 00000000 00000000 kernel32!FreeLibraryAndExitThread+0×40 WARNING: Stack unwind information not available. Following frames may be wrong. 0568ffb8 77e64829 00001430 00000000 00000000PrintDriverA!DllGetClassObject+0×1dcdb1 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
The thread #25 is blocked waiting for the critical section 00080608 but it also owns another critical section LdrpLoaderLock and blocks 5 other threads. The stack trace features PrintDriverA module.
----------------------------------------- DebugInfo = 0x7c887be0Critical section = 0×7c887740 (ntdll!FastPebLock+0×0)LOCKED LockCount = 0×0 WaiterWoken = No OwningThread = 0×00005a20 RecursionCount = 0×1 LockSemaphore = 0×868 SpinCount = 0×00000000 OwningThread DbgId = ~25s OwningThread Stack = ChildEBP RetAddr Args to Child 0568f42c 7c827d0b 7c83d236 00000da0 00000000 ntdll!KiFastSystemCallRet 0568f430 7c83d236 00000da0 00000000 00000000 ntdll!NtWaitForSingleObject+0xc 0568f46c 7c83d281 00000da0 00000004 00080000 ntdll!RtlpWaitOnCriticalSection+0×1a3 0568f48c 7c82a264000806087c82e6b4 0000008e ntdll!RtlEnterCriticalSection+0xa8 0568f6b4 77e6427d 00080000 00000000 00000594 ntdll!RtlAllocateHeap+0×313 0568f718 77e643a2 77e643d0 00020abc 00000000 kernel32!BasepComputeProcessPath+0xc2 0568f758 77e65348 00000000 00000000 00000000 kernel32!BaseComputeProcessDllPath+0xe3 0568f79c 77e6528f 0568f7b8 00000000 4dc5822c kernel32!GetModuleHandleForUnicodeString+0×2b 0568fc14 77e65155 00000001 00000002 0568fc38 kernel32!BasepGetModuleHandleExW+0×17f 0568fc2c 4dc4d554 0568fc38 003a0043 0057005c kernel32!GetModuleHandleW+0×29 0568fe4c 4dc49a0a 4dc32328 00000001 0568fe80 MSCTFIME!GetSystemModuleHandleW+0×40 0568fe5c 4dc49bc3 4dc5822c 4dc32328 4dc32380 MSCTFIME!GetFn+0×2e 0568fe74 4dc49039 00000003 0568fea0 4dc49fbb MSCTFIME!TF_DllDetachInOther+0×2a
0568fe80 4dc49fbb 4dc30000 00000003 00000000 MSCTFIME!DllMain+0×1d 0568fea0 7c81a352 4dc30000 00000003 00000000 MSCTFIME!_DllMainCRTStartup+0×52 0568fec0 7c819178 4dc49f69 4dc30000 00000003 ntdll!LdrpCallInitRoutine+0×14 0568ff74 77e4f920 3533e0ec 00000000 0568ff98 ntdll!LdrShutdownThread+0xd2 0568ff84 77e52868 00000000 3533e0ec 77e5bf51 kernel32!ExitThread+0×2f 0568ff98 3530cd31 35100000 00000000 00000000 kernel32!FreeLibraryAndExitThread+0×40 WARNING: Stack unwind information not available. Following frames may be wrong. 0568ffb8 77e64829 00001430 00000000 00000000 PrintDriverA!DllGetClassObject+0×1dcdb1 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
This is the same thread #25 but it also owns another critical section FastPebLock but this doesn't block additional threads.
----------------------------------------- DebugInfo = 0x7c887c80Critical section = 0×00080608 (+0×80608)LOCKEDLockCount = 0×4WaiterWoken = No OwningThread = 0×0000a8c4 RecursionCount = 0×1 LockSemaphore = 0xDA0 SpinCount = 0×00000fa0OwningThread DbgId = ~22sOwningThread Stack = ChildEBP RetAddr Args to Child 03456830 7739bf53 7739610a 00000000 00000000 ntdll!KiFastSystemCallRet 03456868 7738965e 186403ba 00000000 00000001 user32!NtUserWaitMessage+0xc034575f8 6dfd05cf 03456e5a 03457624 77bc6cd5 compstui!FilterException+0×174 03458584 6dfcff1e 02638dc8 00000000 03458c58 compstui!CallpfnPSUI+0×110 034587f0 6dfd00a2 02638b40 026393f8 00000000 compstui!InsertPSUIPage+0×201 03458848 7307c9ae 43440001 00000005 02118690 compstui!CPSUICallBack+0xed 03458870 6dfd059a 0345888c 03458c58 7307c8da winspool!DevicePropertySheets+0xd4 034588d4 6dfcff1e 026393f8 00000000 03458c58 compstui!CallpfnPSUI+0xdb 03458b40 6dfd00a2 02638b40 02638b40 00000000 compstui!InsertPSUIPage+0×201 03458b98 6dfd06a3 43440000 00000005 7307c8da compstui!CPSUICallBack+0xed 03458bcc 6dfd0799 00000000 7307c8da 03458c58 compstui!DoCommonPropertySheetUI+0×74 03458be4 730801c5 00000000 7307c8da 03458c58 compstui!CommonPropertySheetUIW+0×17 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.03456890 7739f762 77380000 05bdc880 00000000 user32!InternalDialogBox+0xd0 03456b50 7739f047 03456cac 00000000 ffffffff user32!SoftModalMessageBox+0×94b 03456ca0 7739eec9 03456cac 00000028 00000000 user32!MessageBoxWorker+0×2ba 03456cf8 773d7d0d 00000000 0ae7cc20 02639ea8 user32!MessageBoxTimeoutW+0×7a 03456d80 773c42c8 00000000 03456e14 03456df4 user32!MessageBoxTimeoutA+0×9c 03456da0 773c42a4 00000000 03456e14 03456df4 user32!MessageBoxExA+0×1b 03456dbc 6dfcf8c2 00000000 03456e14 03456df4 user32!MessageBoxA+0×45
The thread #22 is blocked waiting for the message box (Volume 2, page 177) but it also owns the critical section 00080608 we have seen above and the thread blocks 4 other threads.
Cannot read structure field value at 0x04ddbb64, error 0 Cannot determine if the critical section is locked or not. ----------------------------------------- Critical section = 0x04ddbb60 (+0x4DDBB60) DebugInfo = 0x01e10858 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ----------------------------------------- DebugInfo = 0x05b24d38 Critical section = 0x0589de08 (+0×49DE8) LOCKEDPrintDriverBLockCount = 0xC5D3FFF WaiterWoken = Yes OwningThread = 0×00008487 RecursionCount = 0×8DD5FF50 LockSemaphore = 0×50CE8B00 SpinCount = 0×878dd5ffWARNING: critical section DebugInfo = 0x0080878d doesn't point back to the DebugInfo found in the active critical sections list = 0x05b24d38. The critical section was probably reused without calling DeleteCriticalSection. ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ----------------------------------------- DebugInfo = 0x05b24c98 Critical section = 0x0589ddd8 (PrintDriverB+0x49DB8) LOCKED LockCount = 0x1D38F6EE WaiterWoken = Yes OwningThread = 0x1c2444db RecursionCount = 0xD3FF50CE LockSemaphore = 0x8D04EC83 SpinCount = 0x1cd9744f WARNING: critical section DebugInfo = 0x8dffff73 doesn't point back to the DebugInfo found in the active critical sections list = 0x05b24c98. The critical section was probably reused without calling DeleteCriticalSection. Cannot read structure field value at 0x8dffff75, error 0 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ----------------------------------------- DebugInfo = 0x05b24f40 Critical section = 0x0589de28 (PrintDriverB+0x49E08) LOCKED LockCount = 0x1D38F6EE WaiterWoken = Yes OwningThread = 0x1c2444db RecursionCount = 0xD3FF50CE LockSemaphore = 0x8D04EC83 SpinCount = 0x00008c8f WARNING: critical section DebugInfo = 0x8d242454 doesn't point back to the DebugInfo found in the active critical sections list = 0x05b24f40. The critical section was probably reused without calling DeleteCriticalSection.
Cannot read structure field value at 0x8d242456, error 0 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ----------------------------------------- DebugInfo = 0x05b24d10 Critical section = 0x0589de08 (PrintDriverB+0x49DE8) LOCKED LockCount = 0xC5D3FFF WaiterWoken = Yes OwningThread = 0x00008487 RecursionCount = 0x8DD5FF50 LockSemaphore = 0x50CE8B00 SpinCount = 0x878dd5ff WARNING: critical section DebugInfo = 0x0080878d doesn't point back to the DebugInfo found in the active critical sections list = 0x05b24d10. The critical section was probably reused without calling DeleteCriticalSection. ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ----------------------------------------- DebugInfo = 0x05b24ec8 Critical section = 0x0589de28 (PrintDriverB+0x49E08) LOCKED LockCount = 0x1D38F6EE WaiterWoken = Yes OwningThread = 0x1c2444db RecursionCount = 0xD3FF50CE LockSemaphore = 0x8D04EC83 SpinCount = 0x00008c8f WARNING: critical section DebugInfo = 0x8d242454 doesn't point back to the DebugInfo found in the active critical sections list = 0x05b24ec8. The critical section was probably reused without calling DeleteCriticalSection. Cannot read structure field value at 0x8d242456, error 0 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ----------------------------------------- DebugInfo = 0x05b24cc0 Critical section = 0x0589ddd8 (PrintDriverB+0x49DB8) LOCKED LockCount = 0x1D38F6EE WaiterWoken = Yes OwningThread = 0x1c2444db RecursionCount = 0xD3FF50CE LockSemaphore = 0x8D04EC83 SpinCount = 0x1cd9744f WARNING: critical section DebugInfo = 0x8dffff73 doesn't point back to the DebugInfo found in the active critical sections list = 0x05b24cc0. The critical section was probably reused without calling DeleteCriticalSection. Cannot read structure field value at 0x8dffff75, error 0 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
Here we see the recurrence of PrintDriverB module in the output that looks like corruption. Because the thread #22 heads the wait chain we look at its full stack trace:
0:000> ~22s; kL 100 eax=00465758 ebx=00000000 ecx=00467514 edx=00000001 esi=00467500 edi=00000000 eip=7c8285ec esp=03456834 ebp=03456868 iopl=0 nv up ei pl zr na pe nc cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246 ntdll!KiFastSystemCallRet: 7c8285ec c3 ret ChildEBP RetAddr 03456830 7739bf53 ntdll!KiFastSystemCallRet 03456868 7738965e user32!NtUserWaitMessage+0xc 03456890 7739f762 user32!InternalDialogBox+0xd0 03456b50 7739f047 user32!SoftModalMessageBox+0x94b 03456ca0 7739eec9 user32!MessageBoxWorker+0x2ba 03456cf8 773d7d0d user32!MessageBoxTimeoutW+0x7a 03456d80 773c42c8 user32!MessageBoxTimeoutA+0x9c 03456da0 773c42a4 user32!MessageBoxExA+0x1b03458584 6dfcff1e compstui!CallpfnPSUI+0×110 034587f0 6dfd00a2 compstui!InsertPSUIPage+0×201 03458848 7307c9ae compstui!CPSUICallBack+0xed 03458870 6dfd059a winspool!DevicePropertySheets+0xd4 034588d4 6dfcff1e compstui!CallpfnPSUI+0xdb 03458b40 6dfd00a2 compstui!InsertPSUIPage+0×201 03458b98 6dfd06a3 compstui!CPSUICallBack+0xed 03458bcc 6dfd0799 compstui!DoCommonPropertySheetUI+0×74 03458be4 730801c5 compstui!CommonPropertySheetUIW+0×17 03458c2c 73080f5d winspool!CallCommonPropertySheetUI+0×43 03459074 35145947 winspool!PrinterPropertiesNative+0×10c 034590c4 3513a04503456dbc 6dfcf8c2 user32!MessageBoxA+0×45 034575f8 6dfd05cf compstui!FilterException+0×174PrintDriverA!DllGetClassObject+0×159c7 0345e9ac 35131819 PrintDriverA!DllGetClassObject+0xa0c5 0345ebdc 32020661 PrintDriverA!DllGetClassObject+0×1899 0345ec04 3201b171 PS5UI!HComOEMPrinterEvent+0×33 0345ec48 02117a79 PS5UI!DrvPrinterEvent+0×239 0345eea4 7308218c PrintDriverA!DrvPrinterEvent+0xf9 0345eef0 761542cc winspool!SpoolerPrinterEventNative+0×57 0345ef0c 76155fd6 localspl!SplDriverEvent+0×21 0345ef30 76144799 localspl!PrinterDriverEvent+0×46 0345f3f8 76144ab2 localspl!SplAddPrinter+0×5f3 0345f424 74070193 localspl!LocalAddPrinterEx+0×2e 0345f874 7407025c spoolss!AddPrinterExW+0×151 0345f890 0100792d spoolss!AddPrinterW+0×17 0345f8ac 01006762 spoolsv!YAddPrinter+0×75 0345f8d0 77c80193 spoolsv!RpcAddPrinter+0×37 0345f8f8 77ce33e1 rpcrt4!Invoke+0×30 0345fcf8 77ce35c4 rpcrt4!NdrStubCall2+0×299 0345fd14 77c7ff7a rpcrt4!NdrServerCall2+0×19 0345fd48 77c8042d rpcrt4!DispatchToStubInCNoAvrf+0×38 0345fd9c 77c80353 rpcrt4!RPC_INTERFACE::DispatchToStubWorker+0×11f 0345fdc0 77c811dc rpcrt4!RPC_INTERFACE::DispatchToStub+0xa3 0345fdfc 77c812f0 rpcrt4!LRPC_SCALL::DealWithRequestMessage+0×42c 0345fe20 77c88678 rpcrt4!LRPC_ADDRESS::DealWithLRPCRequest+0×127 0345ff84 77c88792 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430 0345ff8c 77c8872d rpcrt4!RecvLotsaCallsWrapper+0xd 0345ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0×9d 0345ffb8 77e64829 rpcrt4!ThreadStartRoutine+0×1b 0345ffec 00000000 kernel32!BaseThreadStart+0×34
There is PrintDriverA module on the stack trace. Notice that we also have FilterException function on the stack trace. It raises the suspicion bar. We proceed to examining MessageBoxA parameters:
0:022> kv 100 ChildEBP RetAddr Args to Child 03456830 7739bf53 7739610a 00000000 00000000 ntdll!KiFastSystemCallRet 03456868 7738965e 186403ba 00000000 00000001 user32!NtUserWaitMessage+0xc 03456890 7739f762 77380000 05bdc880 00000000 user32!InternalDialogBox+0xd0 03456b50 7739f047 03456cac 00000000 ffffffff user32!SoftModalMessageBox+0x94b 03456ca0 7739eec9 03456cac 00000028 00000000 user32!MessageBoxWorker+0x2ba 03456cf8 773d7d0d 00000000 0ae7cc20 02639ea8 user32!MessageBoxTimeoutW+0x7a 03456d80 773c42c8 00000000 03456e14 03456df4 user32!MessageBoxTimeoutA+0x9c 03456da0 773c42a4 00000000 03456e14 03456df4 user32!MessageBoxExA+0x1b 03456dbc 6dfcf8c2 0000000003456e1403456df4 user32!MessageBoxA+0×45 034575f8 6dfd05cf 03456e5a 03457624 77bc6cd5 compstui!FilterException+0×174 [...] 0:022> da /c 9003456e1403456e14 "Function address 0×7c8100ca caused a protection fault. (exception code 0xc0000005). Some or all property page(s) may not be displayed."
There was an exception indeed diagnosed (Volume 2, page 318) by FilterException call. The exception is probably hidden (Volume 1, page 271) somewhere on the raw stack:
0:022> !teb
TEB at 7ffde000
ExceptionList: 03456d40
StackBase: 03460000
StackLimit: 03450000
SubSystemTib: 00000000
FiberData: 00001e00
ArbitraryUserPointer: 00000000
Self: 7ffde000
EnvironmentPointer: 00000000
ClientId: 00000540 . 0000a8c4
RpcHandle: 00000000
Tls Storage: 00000000
PEB Address: 7ffd7000
LastErrorValue: 0
LastStatusValue: c0000022
Count Owned Locks: 0
HardErrorMode: 0
0:022> dds 03450000 03460000 03450000 00000000 03450004 00000000 03450008 00000000 0345000c 00000000 [...]0345767c 03457710 03457680 03458574 03457684 0345772c 03457688 034576ec 0345768c 6dfd0a54 compstui!_except_handler3 03457690 00080000 03457694 03457710 03457698 0269b640 0345769c 026afc38 034576a0 00080000 034576a4 00080000 034576a8 026afc38 034576ac 026b2008 034576b0 034576cc 034576b4 7c82a771 ntdll!RtlpCoalesceFreeBlocks+0×383 034576b8 00000249 034576bc 026b2008 034576c0 00080000 034576c4 026afc38 034576c8 00080000 034576cc 00000000 034576d0 00080000 034576d4 034577b4 034576d8 7c82a90a ntdll!RtlFreeHeap+0×6b0 034576dc 00080608 034576e0 7c829f59 ntdll!RtlFreeHeap+0×70f 034576e4 03457870 034576e8 00000000 034576ec 00000001 034576f0 03460000 034576f4 006afc38 034576f8 03457c1403457674 03458574 03457678 7c8315c2 ntdll!RtlDispatchException+0×9103457700 03450000 03457704034576fc 7c82855e ntdll!KiUserExceptionDispatcher+0xe03457708 03457710 0345770c 0345772c 03457710 c0000005 03457714 00000000 03457718 00000000 0345771c 7c8100ca ntdll!RtlAllocateHeap+0×7b3 03457720 00000002 03457724 00000001 03457728 026c663c 0345772c 0001003f [...]0345772c
It finally looks like a heap corruption (Volume 1, page 257):
0:022> .cxr 0345772c eax=00000b28 ebx=00005e69 ecx=026c663c edx=0269b648 esi=0269b640 edi=00080000 eip=7c8100ca esp=034579f8 ebp=03457c14 iopl=0 nv up ei pl nz ac pe nc cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=000102160:022> kL 100 ChildEBP RetAddrntdll!RtlAllocateHeap+0×7b3: 7c8100ca 8901 mov dword ptr [ecx],eax ds:0023:026c663c=????????03457c44 77c1581a gdi32!EnumFontsInternalW+0×63 03457c68 32014246 gdi32!EnumFontFamiliesW+0×1c 03457ce4 32019ab4 PS5UI!BPackItemFontSubstTable+0×95 03457cf4 32014a0f PS5UI!BPackPrinterPropertyItems+0×19 03457d0c 32019e2b PS5UI!PPrepareDataForCommonUI+0×1af 0345813c 02118a57 PS5UI!DrvDevicePropertySheets+0×1dc WARNING: Stack unwind information not available. Following frames may be wrong. 03458520 6dfd059a03457c14 77c0b66f ntdll!RtlAllocateHeap+0×7b3PrintDriverA!DrvDevicePropertySheets+0×3c7 03458584 6dfcff1e compstui!CallpfnPSUI+0xdb 034587f0 6dfd00a2 compstui!InsertPSUIPage+0×201 03458848 7307c9ae compstui!CPSUICallBack+0xed 03458870 6dfd059a winspool!DevicePropertySheets+0xd4 034588d4 6dfcff1e compstui!CallpfnPSUI+0xdb 03458b40 6dfd00a2 compstui!InsertPSUIPage+0×201 03458b98 6dfd06a3 compstui!CPSUICallBack+0xed 03458bcc 6dfd0799 compstui!DoCommonPropertySheetUI+0×74 03458be4 730801c5 compstui!CommonPropertySheetUIW+0×17 03458c2c 73080f5d winspool!CallCommonPropertySheetUI+0×43 03459074 35145947 winspool!PrinterPropertiesNative+0×10c 034590c4 3513a045 PrintDriverA!DllGetClassObject+0×159c7 0345e9ac 35131819 PrintDriverA!DllGetClassObject+0xa0c5 0345ebdc 32020661 PrintDriverA!DllGetClassObject+0×1899 0345ec04 3201b171 PS5UI!HComOEMPrinterEvent+0×33 0345ec48 02117a79 PS5UI!DrvPrinterEvent+0×239 0345eea4 7308218c PrintDriverA!DrvPrinterEvent+0xf9 0345eef0 761542cc winspool!SpoolerPrinterEventNative+0×57 0345ef0c 76155fd6 localspl!SplDriverEvent+0×21 0345ef30 76144799 localspl!PrinterDriverEvent+0×46 0345f3f8 76144ab2 localspl!SplAddPrinter+0×5f3 0345f424 74070193 localspl!LocalAddPrinterEx+0×2e 0345f874 7407025c spoolss!AddPrinterExW+0×151 0345f890 0100792d spoolss!AddPrinterW+0×17 0345f8ac 01006762 spoolsv!YAddPrinter+0×75 0345f8d0 77c80193 spoolsv!RpcAddPrinter+0×37 0345f8f8 77ce33e1 rpcrt4!Invoke+0×30 0345fcf8 77ce35c4 rpcrt4!NdrStubCall2+0×299 0345fd14 77c7ff7a rpcrt4!NdrServerCall2+0×19
0345fd48 77c8042d rpcrt4!DispatchToStubInCNoAvrf+0×38 0345fd9c 77c80353 rpcrt4!RPC_INTERFACE::DispatchToStubWorker+0×11f 0345fdc0 77c811dc rpcrt4!RPC_INTERFACE::DispatchToStub+0xa3 0345fdfc 77c812f0 rpcrt4!LRPC_SCALL::DealWithRequestMessage+0×42c 0345fe20 77c88678 rpcrt4!LRPC_ADDRESS::DealWithLRPCRequest+0×127 0345ff84 77c88792 rpcrt4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430 0345ff8c 77c8872d rpcrt4!RecvLotsaCallsWrapper+0xd 0345ffac 77c7b110 rpcrt4!BaseCachedThreadRoutine+0×9d 0345ffb8 77e64829 rpcrt4!ThreadStartRoutine+0×1b 0345ffec 00000000 kernel32!BaseThreadStart+0×34
lmt command shows many loaded print drivers but we advise the fans of driver elimination to remove or upgrade PrintDriverB and PrintDriveA. We also advise to enable full page heap on the spooler service to find the direct offender.
A system had an abnormally high number of interrupt activity visible in various monitoring tools. A complete memory dump was collected. When we open it and look at an IRP list we find the statistically higher number of IRPs (Volume 1, page 459) belonging to Disk and DriverA device drivers:
0: kd> !irpfind Irp [Thread] irpStack: (Mj,Mn) DevObj [Driver] MDL Process [...] 8a3d3008 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [DriverDisk] 0×00000000 8a3d3340 [8acab888] irpStack: ( 3, 0) 8b4c6030 [ FileSystemNpfs] 8a3d4580 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [DriverDisk] 0×00000000 8a403e00 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [DriverDisk] 0×00000000 8a4047e0 [8b56cb10] irpStack: ( 4,34) 8b1b8030 [DriverDisk] 0×00000000 [...] 8aa6ab28 [00000000] irpStack: ( f, 0) 8b192030 [DriverDriverA] 0×00000000 8aa6ce28 [00000000] irpStack: ( f, 0) 8b192030 [DriverDriverA] 0×00000000 [...]
What we also notice is that the thread 8b56cb10 is also an active running thread, so we look at its raw stack to find any executon residue (Volume 2, page 239) providing hints to possible hardware activity (page 66).
0: kd> !stacks
Proc.Thread .Thread Ticks ThreadState Blocker
[8b57f7a8 System]
4.000070 8b579db0 ffffff42 Blocked +0x1
4.0000c0 8b5768d0 ffffff42 READY nt!KiAdjustQuantumThread+0x109
4.0000e4 8b56cb10 ffffff42 RUNNING +0xf6fb2044
[...]
0: kd> !thread 8b56cb10
THREAD 8b56cb10 Cid 0004.00e4 Teb: 00000000 Win32Thread: 00000000 RUNNING on
processor 0
Not impersonating
DeviceMap e10018b8
Owning Process 8b57f7a8 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 24437735
Context Switch Count 33644
UserTime 00:00:00.000
KernelTime 00:00:07.843
Start Address nt!MiMappedPageWriter (0x80847ffe)
Stack Init f70c4000 Current f70c3468 Base f70c4000 Limit f70c1000 Call 0
Priority 17 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr Args to Child
f70c3470 00000000 000000be e1912bc0 e1912bc4 0xf6fb2044
However, WinDbg reports another current thread running on the same processor so we obviously have an inconsistent dump (Volume 1, page 269) and should exercise caution:
0: kd> !thread THREADCid 0000.0000 Teb: 00000000 Win32Thread: 000000008089d8c0RUNNING on processor 0Not impersonating Owning Process 8089db40 Image: Idle Attached Process N/A Image: N/A Wait Start TickCount 24437476 Ticks: 69 (0:00:00:01.078) Context Switch Count 72194391 UserTime 00:00:00.000 KernelTime 4 Days 08:57:56.171 Stack Init 8089a8b0 Current 8089a5fcCall 0 Priority 0 BasePriority 0 PriorityDecrement 0 ChildEBP RetAddr Args to Child f3b30c5c 00000000 00000000 00000000 00000000Base 8089a8b0 Limit 808978b0LiveKdD+0×1c07 0: kd> !running [...] Prcbs Current Next 0 ffdff120................ 1 f772f1208089d8c0................ 0: kd> !thread f7732090 THREADf7732090f7732090Cid 0000.0000 Teb: 00000000 Win32Thread: 00000000RUNNING on processor 1Not impersonating Owning Process 8089db40 Image: Idle Attached Process N/A Image: N/A Wait Start TickCount 0 Ticks: 24437545 (4:10:03:56.640) Context Switch Count 75624870 UserTime 00:00:00.000 KernelTime 4 Days 08:56:05.125 Stack Init f78b3000 Current f78b2d4cCall 0 Priority 0 BasePriority 0 PriorityDecrement 0 ChildEBP RetAddr Args to Child f3b30c5c 00000000 00000000 00000000 00000000Base f78b3000 Limit f78b0000LiveKdD+0×1c07
Let's come back to the thread 8b56cb10. Its raw stack residue shows traces of SCSI activity:
0: kd> dps f70c1000 f70c4000
[...]
f70c2f38 8b20100c
f70c2f3c f70c2f9c
f70c2f40 f72922a5 DriverA!BuildScatterGather+0×9bf70c337c 00000000 f70c3380 00000246 f70c3384 808a6228 nt!KiProcessorBlock+0×8 f70c3388 00000002 f70c338c 00000011 f70c3390 00000246 f70c3394 f70c33a4 f70c3398 80a62a73 hal!HalRequestIpi+0×13 f70c339c 00000002 f70c33a0 000000e1 f70c33a4 f70c33dc f70c33a8 8082e4db nt!KiIpiSend+0×27 f70c33ac 00000002 f70c33b0 f772fa7c f70c33b4 8b56bdb0 f70c33b8 ffdff120 f70c33bc 00000000 f70c33c0 00000002 f70c33c4 00000001 f70c33c8 00000000 f70c33cc 00000002 f70c33d0 00000002 f70c33d4 f70c33e4 f70c33d8 80a61456 hal!KfLowerIrql+0×62 f70c33dc 00000001 f70c33e0 00000002 f70c33e4 f70c3494 f70c33e8 f70c3450 f70c33ec 8b56cb10 f70c33f0 8b089100 f70c33f4 8a5abe01 f70c33f8 f70c3450 f70c33fc 8b089100 f70c3400 8a5abe01 f70c3404 8b089101 f70c3408 f70c3418 f70c340c 80a61456 hal!KfLowerIrql+0×62 f70c3410 8a5abe98 f70c3414 8b089101 f70c3418 f70c3450 f70c341c f70c3434 f70c3420 80819c10 nt!FsFilterPerformCompletionCallbacks+0×2e f70c3424 f70c3450 f70c3428 00000000 f70c342c 00000000 f70c3430 00000000 f70c3434 f70c3584 f70c3438 f70c3584 f70c343c 80815040 nt!FsRtlReleaseFileForModWrite+0×190 f70c3440 f70c3450 f70c3444 8b56cdc4 f70c3448 00010000 f70c344c 8b56cd68
f70c3450 00000024 f70c3454 8b56cbfc f70c3458 8abe10f0 f70c345c 8a5b4830 f70c3460 8b089100 f70c3464 80a613f4 hal!KfLowerIrql f70c3468 00000001 f70c346c 00000246 f70c3470 f6fb2044 f70c3474 00000000 f70c3478 000000be f70c347c e1912bc0 f70c3480 e1912bc4 f70c3484 8a4b7db8 f70c3488 00000011 f70c348c f70c34a4 f70c3490 8081610e nt!FsRtlLookupBaseMcbEntry+0×16 f70c3494 80887b75 nt!KiFlushTargetSingleTb+0xd f70c3498 f70c34d0 f70c349c 8082e431 nt!KiIpiServiceRoutine+0×4d f70c34a0 f772f121 f70c34a4 00000000 f70c34a8 e2894000 f70c34ac 00000000 f70c34b0 80872322 nt!WRITE_REGISTER_ULONG+0xa f70c34b4 8b20100c f70c34b8 80a6157e hal!HalEndSystemInterrupt+0×6e f70c34bc 8b20100c f70c34c0 f70c34d0 f70c34c4 80a5e902 hal!HalpIpiHandler+0xd2 f70c34c8 80816209 nt!FsRtlLookupLargeMcbEntry+0×4d f70c34cc 000000e1 f70c34d0 f70c3564 f70c34d4 80872322 nt!WRITE_REGISTER_ULONG+0xa f70c34d8 badb0d00 f70c34dc f6fb2040 f70c34e0 8b20100c f70c34e4 8b038fb4 f70c34e8 0000f000 f70c34ec f70c3510 f70c34f0 8b377e10 f70c34f4 8b20100c f70c34f8 8b038fb4 f70c34fc 00000000 f70c3500 00000000 f70c3504 8b377e64 f70c3508 00000007 f70c350c f6fb2040 f70c3510 8b201100 f70c3514 0b377e10 f70c3518 00000005 f70c351c ffdff120 f70c3520 ffdffa40 f70c3524 8b4eca09
f70c3528 8b20100c f70c352c ffdffa40 f70c3530 8b4eca09 f70c3534 ffdffa09 f70c3538 f70c3548 f70c353c 80a61456 hal!KfLowerIrql+0×62 f70c3540 8b4ecab4 f70c3544 ffdffa09 f70c3548 f70c356c f70c354c80829f70 nt!KeInsertQueueDpc+0×1c4f70c3550 8b4ecaf8 f70c3554 8b038fb4 f70c3558 8b192001 f70c355c ffdffa48 f70c3560 ffdff120 f70c3564 00000000 f70c3568 01092855 f70c356c f70c3580 f70c3570f727221d SCSIPORT!SpRequestCompletionDpc+0×2df70c3574 014ecab4 f70c3578 8b4ecab8 f70c357c 8b4ecaf8 f70c3580 8b4ecbf8 f70c3584 00000102 f70c3588 8b4eca40 f70c358c 8b4ecaf8 f70c3590 8b4ecbf8 f70c3594 8b038f02 f70c3598 f70c35a8 f70c359c 8b4ecbf8 f70c35a0 8b038f02 f70c35a4 8b4ecb02 f70c35a8 f70c35b8 f70c35ac 80a61456 hal!KfLowerIrql+0×62 f70c35b0 8b038f02 f70c35b4 8b4ecb02 f70c35b8 f70c35d8 f70c35bc 80a5f44b hal!KfReleaseSpinLock+0xb f70c35c0f72737ae SCSIPORT!SpReceiveScatterGather+0×33bf70c35c4 8b56bb94 f70c35c8 00000000 f70c35cc 0cd8e000 f70c35d0 0000000f f70c35d4 0000000f f70c35d8 f70c3604 f70c35dc 80a60147 hal!HalBuildScatterGatherList+0×1c7 f70c35e0 8b4eca40 f70c35e4 8a5acd20 f70c35e8 8ab7aa98 f70c35ec 8ab7aa30 f70c35f0 8a5acd20 f70c35f4 8b4ecaf8 f70c35f8 8b038fb4
f70c35fc 00804001 f70c3600 00000000 f70c3604 f70c3650 f70c3608f72733a6 SCSIPORT!ScsiPortStartIo+0×36af70c360c 8ab7aa98 f70c3610 8b4eca40 f70c3614 8b56bb38 f70c3618 00000000 f70c361c 00010000 f70c3620f72736b4 SCSIPORT!SpReceiveScatterGatherf70c3624 8ab7aa30 f70c3628 00000000 f70c362c 8b4eca40 f70c3630 8a5acd20 f70c3634 00000002 f70c3638 8b4eca40 f70c363c f70c39e0 f70c3640 f70c3658 f70c3644 00000000 f70c3648 80a611ae hal!HalpDispatchSoftwareInterrupt+0×5e f70c364c 00000000 f70c3650 8a5acd00 f70c3654 00000202 f70c3658 f70c3674 f70c365c 80a613d9 hal!HalpCheckForSoftwareInterrupt+0×81 f70c3660 8b4ecb02 f70c3664 00000000 f70c3668 8b1920e8 f70c366c 8a5acd00 f70c3670 8b4ecb02 f70c3674 f70c3684 f70c3678 80a61456 hal!KfLowerIrql+0×62 f70c367c 8a5acd20 f70c3680 8b4ecb00 f70c3684 f70c36a8 f70c3688f7273638 SCSIPORT!ScsiPortFdoDispatch+0×279f70c368c 8b4ecaf8 f70c3690 8b41a228 f70c3694 8a5acd20 f70c3698 f70c36d0 f70c369c f70c36ac f70c36a0 8ab7aa30 f70c36a4 8b1920e8 f70c36a8 f70c36c4 f70c36acf7273146 SCSIPORT!SpDispatchRequest+0×68f70c36b0 8b4eca40 f70c36b4 005acdb4 f70c36b8 8b038fb4 f70c36bc 8b1920e8 f70c36c0 8a5acd20 f70c36c4 f70c36e0 f70c36c8f7272dc3 SCSIPORT!ScsiPortPdoScsi+0×129f70c36cc 8b1920e8 f70c36d0 8a5acd20
f70c36d4 8a581008
f70c36d8 8a5acd20
f70c36dc 8b192030
f70c36e0 f70c36f4
f70c36e4 f7272299 SCSIPORT!ScsiPortGlobalDispatch+0×1d
f70c36e8 8b192030
f70c36ec 8a5acd20
f70c36f0 8b5441c8
f70c36f4 f70c3708
f70c36f8 8081df85 nt!IofCallDriver+0×45
f70c36fc 8b192030
f70c3700 8a5acd20
f70c3704 8b038f08
f70c3708 f70c3718
f70c370c f725f607 CLASSPNP!SubmitTransferPacket+0xbb
f70c3710 8b038f08
f70c3714 00000000
f70c3718 f70c374c
f70c371c f725f2b2 CLASSPNP!ServiceTransferRequest+0×1e4
f70c3720 8b038f08
f70c3724 8b1b80e8
f70c3728 8a581150
f70c372c 8a581008
f70c3730 24052000
f70c3734 00000001
f70c3738 00000001
f70c373c 00011000
f70c3740 00010000
f70c3744 00000000
f70c3748 00000001
f70c374c f70c3770
f70c3750 f725f533 CLASSPNP!ClassReadWrite+0×159
f70c3754 00000103
f70c3758 00000000
f70c375c 8a581008
f70c3760 8b57e218
f70c3764 8b055790
f70c3768 8b192030
f70c376c 00010000
f70c3770 f70c3784
f70c3774 8081df85 nt!IofCallDriver+0×45
f70c3778 8b1b8030
f70c377c 00000103
f70c3780 8b51d1c8
f70c3784 f70c3794
f70c3788 f74c80cf PartMgr!PmReadWrite+0×95
f70c378c 8b467e00
f70c3790 8a581174
f70c3794 f70c37a8
f70c3798 8081df85 nt!IofCallDriver+0×45
f70c379c 8b0556d8
f70c37a0 8a581008
f70c37a4 8a581198
f70c37a8 f70c37c4 f70c37ac f7317053 ftdisk!FtDiskReadWrite+0×1a9 f70c37b0 8a5811b4 f70c37b4 8b5570c8 f70c37b8 8b201c40 f70c37bc 24032000 f70c37c0 8b467d48 f70c37c4 f70c37d8 f70c37c8 8081df85 nt!IofCallDriver+0×45 f70c37cc 8b467d48 f70c37d0 8a581008 f70c37d4 8a5811d8 f70c37d8 f70c37f8 f70c37dc f72c0537 volsnap!VolSnapWrite+0×46f f70c37e0 8a581008 f70c37e4 8b5851c8 f70c37e8 e25b3668 f70c37ec fd800000 f70c37f0 8b201c40 f70c37f4 00000002 f70c37f8 f70c380c f70c37fc 8081df85 nt!IofCallDriver+0×45 f70c3800 8b201b88 f70c3804 8a581008 [...]
There's past DPC insertion activity but no pending DPCs:
0: kd> ub 80829f70 nt!KeInsertQueueDpc+0x1a9: 80829f55 6a02 push 2 80829f57 5a pop edx 80829f58 e857450000 call nt!KiIpiSend (8082e4b4) 80829f5d eb08 jmp nt!KeInsertQueueDpc+0x1bb (80829f67) 80829f5f b102 mov cl,2 80829f61 ff1598108080 call dword ptr [nt!_imp_HalRequestSoftwareInterrupt (80801098)] 80829f67 8a4dfe mov cl,byte ptr [ebp-2] 80829f6a ff1508118080 call dword ptr [nt!_imp_KfLowerIrql (80801108)] 0: kd> !dpcs CPU Type KDPC Function dpcs: no pending DPCs found
We notice DriverA and also see it also attached to Disk driver device:
0: kd> !irp 8a3d3008
Irp is active with 11 stacks 7 is current (= 0x8a3d3150)
Mdl=8b56b6a0: No System Buffer: Thread 8b56cb10: 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
>[ 4,34] 0 e0 8b1b8030 00000000 f74c857e-8b0556d8 Success Error Cancel
DriverDisk PartMgr!PmIoCompletion
Args: 00010000 00000000 f457e000 00000002
[ 4, 0] 0 e1 8b0556d8 00000000 f7316558-8b467e00 Success Error Cancel pending
DriverPartMgr ftdisk!FtpRefCountCompletionRoutine
Args: 7274c6df 0002b74c f457e000 00000002
[ 4, 0] 0 e1 8b467d48 00000000 f72bf638-8b201c40 Success Error Cancel pending
DriverFtdisk volsnap!VspRefCountCompletionRoutine
Args: 7274c5f4 0002b74c f456e000 00000002
[ 4, 0] 0 e1 8b201b88 00000000 f71814e8-8b206238 Success Error Cancel pending
DriverVolSnap Ntfs!NtfsSingleAsyncCompletionRoutine
Args: 00010000 00000000 f456e000 00000002
[ 4, 0] 0 0 8b36b020 8a5b4830 00000000-00000000
FileSystemNtfs
Args: 00010000 00000000 08710000 00000000
0: kd> !devobj 8b1b8030
Device object (8b1b8030) is for:
DR0 DriverDisk DriverObject 8b57e218
Current Irp 00000000 RefCount 0 Type 00000007 Flags 00000050
Vpb 8b52f080 Dacl e13e397c DevExt 8b1b80e8 DevObjExt 8b1b8548 Dope 8b467828
ExtensionFlags (0000000000)
AttachedDevice (Upper) 8b0556d8 DriverPartMgr
AttachedTo (Lower) 8b192030 DriverDriverA
Device queue is not busy.
0: kd> !devstack 8b1b8030
!DevObj !DrvObj !DevExt ObjectName
8b0556d8 DriverPartMgr 8b055790
> 8b1b8030 DriverDisk 8b1b80e8 DR0
8b192030 DriverDriverA 8b1920e8 DriverA1Port1Path0Target0Lun0
!DevNode 8b56f5d0 :
DeviceInst is "SCSIDisk&Ven_A&Prod_Virtual_disk&Rev_1.04&1588251b&0&000"
ServiceName is "disk"
Additionally, we look at raw stack data of running threads 8089d8c0 and f7732090. We find the same hardware activity there and plus some network driver activity too. We also see "double fault" symbols:
[...] 8089a554 ffdffec0 8089a558 80a6157e hal!HalEndSystemInterrupt+0x6e 8089a55c ffdffec0 8089a5608089a570 nt!KiDoubleFaultStack+0×2cc08089a564 80a5e902 hal!HalpIpiHandler+0xd2 8089a568 00000002 8089a56c 000000e1 8089a5708089a600 nt!KiDoubleFaultStack+0×2d508089a574 f7549ca2 intelppm!AcpiC1Idle+0×12 8089a578 badb0d00 8089a57c 0002b74b 8089a580 00000000 8089a584 f7298da0 DriverA!DevScsiTimer 8089a588 00000000 8089a58c 00000000 8089a590 0005d373 8089a594 00000000 8089a598 8b4ecaf8 8089a59c 00000000 8089a5a0 8a4b1e20 8089a5a4 00000000 8089a5a88089a600 nt!KiDoubleFaultStack+0×2d508089a5ac 0002b74b 8089a5b0 ffdffee0 [...]
But they seem to be coincidental (Volume 1, page 390):
0: kd> ub 8089a570
^ Unable to find valid previous instruction for 'ub 8089a570'
0: kd> u 8089a570
nt!KiDoubleFaultStack+0x2cc0:
8089a570 00a68980a29c add byte ptr [esi-635D7F77h],ah
8089a576 54 push esp
8089a577 f7000ddbba4b test dword ptr [eax],4BBADB0Dh
8089a57d b702 mov bh,2
8089a57f 0000 add byte ptr [eax],al
8089a581 0000 add byte ptr [eax],al
8089a583 00a08d29f700 add byte ptr [eax+0F7298Dh],ah
8089a589 0000 add byte ptr [eax],al
0: kd> ub 8089a600
^ Unable to find valid previous instruction for 'ub
8089a600'
0: kd> u 8089a600 nt!KiDoubleFaultStack+0x2d50: 8089a600 0100 add dword ptr [eax],eax 8089a602 0000 add byte ptr [eax],al 8089a604 ebde jmp nt!KiDoubleFaultStack+0x2d34 (8089a5e4) 8089a606 888000000000 mov byte ptr [eax],al 8089a60c 0e push cs 8089a60d 0000 add byte ptr [eax],al 8089a60f 0000 add byte ptr [eax],al 8089a611 0000 add byte ptr [eax],al
We also find the system virtualized (Volume 4, page 131):
0: kd> !sysinfo machineid [...] SystemManufacturer = Virtualization Vendor A [...]
Looking at the DriverA timestamp we notice that it is much older than expected (Volume 2, page 299) and Google search points to similar cases (but not for virtualized systems) where it was recommended to update that driver.
A process was consuming CPU and its user memory dump was saved. The main thread (Volume 1, page 437) was a spiking thread (Volume 1, page 305) indeed:
0:000> !runaway f User Mode Time Thread Time 0:4b8 0 days0:00:16.0782:fec 0 days 0:00:00.000 1:630 0 days 0:00:00.000 Kernel Mode Time Thread Time 0:4b8 0 days0:00:44.2182:fec 0 days 0:00:00.000 1:630 0 days 0:00:00.000 Elapsed Time Thread Time 0:4b8 0 days 0:08:23.342 1:630 0 days 0:08:21.844 2:fec 0 days 0:02:46.425 0:000> kL ChildEBP RetAddr 0012fc80 7e43e1ad ntdll!KiFastSystemCallRet 0012fca8 74730844 user32!NtUserCallNextHookEx+0xc0012fcec 7e431923 DllA!ThreadKeyboardProc+0×770012fd20 7e42b317 user32!DispatchHookA+0×101 0012fd5c 7e430238 user32!CallHookWithSEH+0×21 0012fd80 7c90e473 user32!__fnHkINDWORD+0×24 0012fda4 7e4193e9 ntdll!KiUserCallbackDispatcher+0×13 0012fdd0 7e419402 user32!NtUserPeekMessage+0xc0012fdfc 747528ee user32!PeekMessageW+0xbc[...] 0012ffc0 7c817077 ApplicationA+0×10f1 0012fff0 00000000 kernel32!BaseProcessStart+0×23
We see the presence of a peek message loop (that can be the source of CPU consumption) but we also see a message hook function implemented in DllA. To see if there are any other hooks including patched API (Volume 1, page 469) we look at the raw stack:
0:000> !teb
TEB at 7ffde000
ExceptionList: 0012fcdc
StackBase: 00130000
StackLimit: 0011b000
SubSystemTib: 00000000
FiberData: 00001e00
ArbitraryUserPointer: 00000000
Self: 7ffde000
EnvironmentPointer: 00000000
ClientId: 0000050c . 000004b8
RpcHandle: 00000000
Tls Storage: 00000000
PEB Address: 7ffdf000
LastErrorValue: 0
LastStatusValue: c0000034
Count Owned Locks: 0
HardErrorMode: 0
0:000> dps 0011b000 00130000
[...]
0012e8f0 11201000 DllBHooks+0×10000012fba8 1120146b DllBHooks+0×146b
0012fbac 00000000
0012fbb0 00000003
0012fbb4 00000011
0012fbb8 001d0001
0012fbbc 00000003
0012fbc0 00020003
0012fbc4 001d0001
0012fbc8 0012fbfc
0012fbcc 7e431923 user32!DispatchHookA+0×101
0012fbd0 00000003
0012fbd4 00000011
0012fbd8 001d0001
0012fbdc 00020001
0012fbe0 7ffde000
0012fbe4 00000001
0012fbe8 7ffde000
0012fbec 00020001
0012fbf0 00000000
0012fbf4 00000003
0012fbf8 00000001
0012fbfc 0012fc38
0012fc00 7e42b317 user32!CallHookWithSEH+0×21
0012fc04 00020003
0012fc08 00000011
0012fc0c 00000000
0012fc10 7e42b326 user32!CallHookWithSEH+0×44
0012fc14 00020001
0012fc18 7ffde000
0012fc1c 00000001
0012fc20 0012fc14
0012fc24 00000001
0012fc28 0012fcdc
0012fc2c 7e44048f user32!_except_handler3
0012fc30 7e42b330 user32!'string'+0×6
0012fc34 ffffffff
0012fc38 7e42b326 user32!CallHookWithSEH+0×44
0012fc3c 7e430238 user32!__fnHkINDWORD+0×24
0012fc40 0012fc6c
0012fc44 001d0001
0012fc48 7e430248 user32!__fnHkINDWORD+0×34
0012fc4c 00000000
0012fc50 00000000
0012fc54 00000004
0012fc58 0012fc7c
0012fc5c 0012fca8
0012fc60 7c90e473 ntdll!KiUserCallbackDispatcher+0×13
0012fc64 0012fc6c
0012fc68 00000018
0012fc6c 00020003
0012fc70 00000011
0012fc74 112013c0 DllBHooks+0×13c0
0012fc78 7e4318d1 user32!DispatchHookA
0012fc7c 0012fcb8
0012fc80 7472467f DllA!GetThread+0×1d
0012fc84 7e43e1ad user32!NtUserCallNextHookEx+0xc
0012fc88 7e43e18a user32!CallNextHookEx+0×6f
0012fc8c 00000003
0012fc90 00000011
[...]
We find a few references to DllBHooks module and initially the address 11201000 (DllBHooks+0×1000) looks like coincidental symbolic information (Volume 1, page 390) and it is not a meaningful code indeed:
0:000> ub 11201000However, further module references look valid:
0:000> ub112013c0DllBHooks+0×13af: 112013af 68ff000000 push 0FFh 112013b4 ff152c202011 call dword ptr [DllBHooks!HookKeyboard+0xbac (1120202c)] 112013ba 5e pop esi 112013bb 90 nop 112013bc 90 nop 112013bd 90 nop 112013be 90 nop 112013bf 90 nop 0:000> u112013c0DllBHooks+0×13c0: 112013c0 55 push ebp 112013c1 8bec mov ebp,esp 112013c3 53 push ebx 112013c4 8b5d10 mov ebx,dword ptr [ebp+10h] 112013c7 56 push esi 112013c8 8b7508 mov esi,dword ptr [ebp+8] 112013cb 57 push edi 112013cc 8b7d0c mov edi,dword ptr [ebp+0Ch] 0:000> ub1120146bDllBHooks+0×1453: 11201453 ff1558202011 call dword ptr [DllBHooks!HookKeyboard+0xbd8 (11202058)] 11201459 8b0dd4302011 mov ecx,dword ptr [DllBHooks!HookKeyboard+0×1c54 (112030d4)] 1120145f 53 push ebx 11201460 57 push edi 11201461 56 push esi 11201462 8b11 mov edx,dword ptr [ecx] 11201464 52 push edx 11201465 ff155c202011 call dword ptr [DllBHooks!HookKeyboard+0xbdc (1120205c)] 0:000> u1120146bDllBHooks+0×146b: 1120146b 5f pop edi 1120146c 5e pop esi 1120146d 5b pop ebx 1120146e 5d pop ebp 1120146f c20c00 ret 0Ch 11201472 90 nop 11201473 90 nop 11201474 90 nop
Using lmv command we discover that DllA and DllBHooks modules belong to different vendors but share the same "keyboard" related functionality. So we don't have an instance of semantic split pattern (Volume 3, page 120) here and both module versions (Volume 2, page 299) need to be checked and also removed for testing purposes if necessary.
Continue scanning the raw stack we also find another hooking module that surfaces in !chkimg command as well:
[...] 0012a22c 00000000 0012a230 00205558 0012a234 0012a24c0012a238 00913ae6 DllCHook!DllUnregisterServer+0×1b060012a23c 00000020 0012a240 00000000 0012a244 00205558 0012a248 00205558 0012a24c 0012a25c0012a250 00913d73 DllCHook!DllUnregisterServer+0×1d930012a254 00205558 0012a258 00000038 [...] 0:000> ub00913ae6DllCHook!DllUnregisterServer+0×1af2: 00913ad2 7412 je DllCHook!DllUnregisterServer+0×1b06 (00913ae6) 00913ad4 85f6 test esi,esi 00913ad6 740e je DllCHook!DllUnregisterServer+0×1b06 (00913ae6) 00913ad8 a180e49800 mov eax,dword ptr [DllCHook+0×232d0 (0098e480)] 00913add 56 push esi 00913ade 6a00 push 0 00913ae0 50 push eax 00913ae1 e88a920000 call DllCHook!DllUnregisterServer+0xad90 (0091cd70) 0:000> ub00913d73DllCHook!DllUnregisterServer+0×1d7d: 00913d5d 8b4604 mov eax,dword ptr [esi+4] 00913d60 85c0 test eax,eax 00913d62 7409 je DllCHook!DllUnregisterServer+0×1d8d (00913d6d) 00913d64 50 push eax 00913d65 e826fdffff call DllCHook!DllUnregisterServer+0×1ab0 (00913a90) 00913d6a 83c404 add esp,4 00913d6d 56 push esi 00913d6e e81dfdffff call DllCHook!DllUnregisterServer+0×1ab0 (00913a90) 0:000> !chkimg -lo 50 -d !kernel32 -v Searching for module with expression: !kernel32 Will apply relocation fixups to file used for comparison Will ignore NOP/LOCK errors Will ignore patched instructions Image specific ignores will be applied Comparison image path: c:msskernel32.dll49C4F482f6000kernel32.dll No range specified Scanning section: .text Size: 537065 Range to scan: 7c801000-7c8841e9-7c801af9 5 bytes - kernel32!LoadLibraryExW [ 6a 34 68 f8 e0:e9 06 e5 58 03 ] [...]7c801af5
0:000> ukernel32!LoadLibraryExW: 7c801af5 e906e55803 jmp7c801af57fd900007c801afa 807ce8d509 cmp byte ptr [eax+ebp*8-2Bh],9 7c801aff 0000 add byte ptr [eax],al 7c801b01 33ff xor edi,edi 7c801b03 897dd8 mov dword ptr [ebp-28h],edi 7c801b06 897dd4 mov dword ptr [ebp-2Ch],edi 7c801b09 897de0 mov dword ptr [ebp-20h],edi 7c801b0c 897de4 mov dword ptr [ebp-1Ch],edi 0:000> u7fd900007fd90000 e93b5eb880 jmpDllCHook!DllUnregisterServer+0×3e60 (00915e40) 7fd90005 6a34 push 34h 7fd90007 68f8e0807c push offset kernel32!'string'+0xc 7fd9000c e9eb1aa7fc jmp kernel32!LoadLibraryExW+0×7 (7c801afc) 7fd90011 0000 add byte ptr [eax],al 7fd90013 0000 add byte ptr [eax],al 7fd90015 0000 add byte ptr [eax],al 7fd90017 0000 add byte ptr [eax],al 0:000> !chkimg -lo 50 -d !user32 -v Searching for module with expression: !user32 Will apply relocation fixups to file used for comparison Will ignore NOP/LOCK errors Will ignore patched instructions Image specific ignores will be applied Comparison image path: c:mssuser32.dll4802A11B91000user32.dll No range specified Scanning section: .text Size: 389763 Range to scan: 7e411000-7e470283-7e45a279 5 bytes - user32!ExitWindowsEx [ 8b ff 55 8b ec:e9 86 5d 87 01 ] [...] 0:000> u7e45a275user32!ExitWindowsEx: 7e45a275 e9865d8701 jmp7e45a2757fcd00007e45a27a 83ec18 sub esp,18h 7e45a27d 53 push ebx 7e45a27e 8b5d08 mov ebx,dword ptr [ebp+8] 7e45a281 56 push esi 7e45a282 8bf3 mov esi,ebx 7e45a284 81e60b580000 and esi,580Bh 7e45a28a f7de neg esi 0:000> u7fcd00007fcd0000 e9cba0c580 jmpDllCHook+0×65d0 (0092a0d0) 7fcd0005 8bff mov edi,edi 7fcd0007 55 push ebp 7fcd0008 8bec mov ebp,esp 7fcd000a e96ba278fe jmp user32!ExitWindowsEx+0×5 (7e45a27a) 7fcd000f 0000 add byte ptr [eax],al 7fcd0011 0000 add byte ptr [eax],al 7fcd0013 0000 add byte ptr [eax],al
0:000> !chkimg -lo 50 -d !advapi32 -v
Searching for module with expression: !advapi32
Will apply relocation fixups to file used for comparison
Will ignore NOP/LOCK errors
Will ignore patched instructions
Image specific ignores will be applied
Comparison image path: c:mssadvapi32.dll49901D489b000advapi32.dll
No range specified
Scanning section: .text
Size: 476617
Range to scan: 77dd1000-77e455c9
77e34ce5-77e34ce9 5 bytes - advapi32!InitiateSystemShutdownExW
[ 8b ff 55 8b ec:e9 16 b3 e8 07 ]
[...]
0:000> u 77e34ce57fcc0000
77e34cea 83ec14 sub esp,14h
77e34ced 53 push ebx
77e34cee 56 push esi
77e34cef 33db xor ebx,ebx
77e34cf1 57 push edi
77e34cf2 8b7d08 mov edi,dword ptr [ebp+8]
77e34cf5 43 inc ebx
0:000> u 7fcc0000
7fcc0000 e99ba1c680 jmp DllCHook+0×66a0 (0092a1a0)
7fcc0005 8bff mov edi,edi
7fcc0007 55 push ebp
7fcc0008 8bec mov ebp,esp
7fcc000a e9db4c17f8 jmp advapi32!InitiateSystemShutdownExW+0×5 (77e34cea)
7fcc000f 0000 add byte ptr [eax],al
7fcc0011 0000 add byte ptr [eax],al
7fcc0013 0000 add byte ptr [eax],al
However we know from other sources that DllCHook module doesn't have any relation to "keyboard".
We also find another module DllDHook on the raw stack but it looks like a pure coincidence (UNICODE-style addresses):
[...] 00129f10 016000ca00129f18 000100ca00129f14 00aa0004 DllDHook+0×3e41400129f20 00cf0001 [...]00129f1c 00aa00ca DllDHook+0×3e4da
0:000> ub 00aa0004 DllDHook+0×3e402: 00a9fff2 0000 add byte ptr [eax],al 00a9fff4 0000 add byte ptr [eax],al 00a9fff6 0000 add byte ptr [eax],al 00a9fff8 0000 add byte ptr [eax],al 00a9fffa 0000 add byte ptr [eax],al 00a9fffc a00f0000a0 mov al,byte ptr ds:[A000000Fh] 00aa0001 57 push edi 00aa0002 1b00 sbb eax,dword ptr [eax] 0:000> u 0000aaDllDHook+0×3e414: 00aa0004 ff ??? 00aa0005 ff ??? 00aa0006 ff ??? 00aa0007 ff00 inc dword ptr [eax] 00aa0009 0000 add byte ptr [eax],al 00aa000b 0000 add byte ptr [eax],al 00aa000d 0000 add byte ptr [eax],al 00aa000f 0000 add byte ptr [eax],al 0:000> ub 000400aaDllDHook+0×3e4ca: 00aa00ba 0000 add byte ptr [eax],al 00aa00bc 0000 add byte ptr [eax],al 00aa00be 0000 add byte ptr [eax],al 00aa00c0 0000 add byte ptr [eax],al 00aa00c2 0000 add byte ptr [eax],al 00aa00c4 0000 add byte ptr [eax],al 00aa00c6 0000 add byte ptr [eax],al 00aa00c8 0000 add byte ptr [eax],al 0:000> u 00ca00aaDllDHook+0×3e4da: 00aa00ca 0000 add byte ptr [eax],al 00aa00cc 0000 add byte ptr [eax],al 00aa00ce 0000 add byte ptr [eax],al 00aa00d0 0000 add byte ptr [eax],al 00aa00d2 0000 add byte ptr [eax],al 00aa00d4 0000 add byte ptr [eax],al 00aa00d6 0000 add byte ptr [eax],al 00aa00d8 0000 add byte ptr [eax],alca
On a server the new remote sessions couldn't be created. A complete memory dump stack trace collection (Volume 1, page 409) log lists a special process (Volume 2, page 164) that would not be normally present in a fully initialized session:
kd> !process 0 ff
**** NT ACTIVE PROCESS DUMP ****
[...]
PROCESS 89cf4870 SessionId: 0 Cid: 0fa4 Peb: 7ffde000 ParentCid:
0228
DirBase: 3c9e6000 ObjectTable: e1627410 HandleCount: 81.
Image: userinit.exe
VadRoot 89a80168 Vads 161 Clone 0 Private 517. Modified 4. Locked 0.
DeviceMap e1003170
Token e1575030
ElapsedTime 05:34:29.046
UserTime 00:00:00.046
KernelTime 00:00:00.234
QuotaPoolUsage[PagedPool] 42916
QuotaPoolUsage[NonPagedPool] 7176
Working Set Sizes (now,min,max) (1289, 50, 345) (5156KB, 200KB,
1380KB)
PeakWorkingSetSize 1291
VirtualSize 33 Mb
PeakVirtualSize 34 Mb
PageFaultCount 1411
MemoryPriority BACKGROUND
BasePriority 8
CommitCharge 866
[...]
THREAD 89d475a8 Cid 0fa4.0f48 Teb: 7ffda000 Win32Thread: 00000000 WAIT:
(WrLpcReply) UserMode Non-Alertable
89d4779c Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0000acfd:
Current LPC port e5501c28
Not impersonating
DeviceMap e1003170
Owning Process 0 Image: <Unknown>
Attached Process 89cf4870 Image: userinit.exe
Wait Start TickCount 1845699 Ticks: 1284370 (0:05:34:28.281)
Context Switch Count 149
UserTime 00:00:00.000
KernelTime 00:00:00.093
Win32 Start Address PAUTOENR!AEMainThreadProc (0×5e95a798)
Start Address kernel32!BaseThreadStartThunk (0×7c8106f9)
Stack Init b88a1000 Current b88a0c50 Base b88a1000 Limit b889e000 Call 0
Priority 7 BasePriority 7 PriorityDecrement 0 DecrementCount 0
Kernel stack not resident.
ChildEBP RetAddr
b88a0c68 804e1bf2 nt!KiSwapContext+0×2f
b88a0c74 804e1c3e nt!KiSwapThread+0×8a
b88a0c9c 8057d073 nt!KeWaitForSingleObject+0×1c2
b88a0d50 804dd99f nt!NtRequestWaitReplyPort+0×63d
b88a0d50 7c90e514 nt!KiFastCallEntry+0xfc (TrapFrame @ b88a0d64)
00a8f064 7c90daea ntdll!KiFastSystemCallRet
00a8f068 77e7cac1 ntdll!ZwRequestWaitReplyPort+0xc
00a8f0b4 77e7a33e RPCRT4!LRPC_CCALL::SendReceive+0×228
00a8f0c0 77e7a36f RPCRT4!I_RpcSendReceive+0×24
00a8f0d4 77ef4675 RPCRT4!NdrSendReceive+0×2b
00a8f4b0 76f235e7 RPCRT4!NdrClientCall2+0×222
00a8f4c4 76f2357b DNSAPI!R_ResolverQuery+0×1b
00a8f520 71a526c6 DNSAPI!DnsQuery_W+0×14f
00a8f554 71a5266f mswsock!HostentBlob_Query+0×29
00a8f580 71a51b0a mswsock!Rnr_DoDnsLookup+0×7d
00a8f9c8 71ab32b0 mswsock!NSPLookupServiceNext+0×533
00a8f9e0 71ab3290 WS2_32!NSPROVIDER::NSPLookupServiceNext+0×17
00a8f9fc 71ab325a WS2_32!NSPROVIDERSTATE::LookupServiceNext+0×1c
00a8fa28 71ab31f8 WS2_32!NSQUERY::LookupServiceNext+0xae
00a8fa48 76f775eb WS2_32!WSALookupServiceNextW+0×78
00a8faec 76f6a9d2 WLDAP32!GetHostByNameW+0xef
00a8fb38 76f6667b WLDAP32!OpenLdapServer+0×435
00a8fb58 76f6fb05 WLDAP32!LdapConnect+0×169
00a8fef8 76f704f3 WLDAP32!LdapBind+0×34
00a8ff20 5e95651a WLDAP32!ldap_bind_sW+0×2c
00a8ff68 5e95a887 PAUTOENR!AERobustLdapBind+0xc9
00a8ffb4 7c80b729 PAUTOENR!AEMainThreadProc+0xef
00a8ffec 00000000 kernel32!BaseThreadStart+0×37
[...]
We start following the LPC wait chain (Volume 3, page 97):
kd> !lpc message0000acfdSearching message acfd in threads ...Client thread 89d475a8 waiting a reply from acfd Searching thread 89d475a8 in port rundown queues ... Server communication port 0xe12fc438 Handles: 1 References: 1 The LpcDataInfoChainHead queue is empty Connected port: 0xe5501c28 Server connection port: 0xe1640798 Client communication port 0xe5501c28 Handles: 1 References: 2 The LpcDataInfoChainHead queue is empty Server connection port e1640798 Name: DNSResolver Handles: 1 References: 17 Server process : 899a0020 (svchost.exe) Queue semaphore : 89dabdf0 Semaphore state 0 (0x0) The message queue is empty The LpcDataInfoChainHead queue is empty Done. kd> !threadServer thread 89a80328 is working on message acfd1f THREAD 89a80328 Cid 03c8.0644 Teb: 7ffd7000 Win32Thread: 00000000 WAIT: (WrLpcReply) UserMode Non-Alertable 89a8051c Semaphore Limit 0×189a80328Waiting for reply to LPC MessageId 0000acfe:Current LPC port e10b6b00 Not impersonating DeviceMap e1b093c8 Owning Process 0 Image: <Unknown> Attached Process 899a0020 Image: svchost.exe Wait Start TickCount 1845699 Ticks: 1284370 (0:05:34:28.281) Context Switch Count 1208 UserTime 00:00:00.000 KernelTime 00:00:00.000 Win32 Start Address 0×0000acfd LPC Server thread working on message Id acfd Start Address kernel32!BaseThreadStartThunk (0×7c8106f9) Stack Init b7a33000 Current b7a32c50 Base b7a33000 Limit b7a30000 Call 0 Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0 Kernel stack not resident. ChildEBP RetAddr b7a32c68 804e1bf2 nt!KiSwapContext+0×2f b7a32c74 804e1c3e nt!KiSwapThread+0×8a b7a32c9c 8057d073 nt!KeWaitForSingleObject+0×1c2 b7a32d50 804dd99f nt!NtRequestWaitReplyPort+0×63d b7a32d50 7c90e514 nt!KiFastCallEntry+0xfc (TrapFrame @ b7a32d64)
00a9eb3c 7c90daea ntdll!KiFastSystemCallRet 00a9eb40 77e7cac1 ntdll!ZwRequestWaitReplyPort+0xc 00a9eb8c 77e7a33e RPCRT4!LRPC_CCALL::SendReceive+0×228 00a9eb98 77e7a36f RPCRT4!I_RpcSendReceive+0×24 00a9ebac 77ef4675 RPCRT4!NdrSendReceive+0×2b 00a9ef88 662e0c48 RPCRT4!NdrClientCall2+0×222 00a9ef9c 662dafa9 hnetcfg!FwOpenDynamicFwPort+0×1b 00a9f048 71a55025 hnetcfg!IcfOpenDynamicFwPort+0×6a 00a9f0e4 71a590f2 mswsock!WSPBind+0×332 00a9f200 71ab2fd7 mswsock!WSPSendTo+0×230 00a9f250 76f252c0 WS2_32!sendto+0×88 00a9f280 76f251ea DNSAPI!SendMessagePrivate+0×18d 00a9f2a0 76f2517c DNSAPI!SendUsingServerInfo+0×33 00a9f2c8 76f25436 DNSAPI!SendUdpToNextDnsServers+0×80 00a9f314 76f24dec DNSAPI!Dns_SendAndRecvUdp+0×121 00a9f34c 76f24d20 DNSAPI!Dns_SendAndRecv+0×7b 00a9f37c 76f24a7d DNSAPI!Query_SingleName+0×8b 00a9f3b0 7677373a DNSAPI!Query_Main+0×11a 00a9f3c8 7677303f dnsrslvr!ResolverQuery+0×48 00a9f8bc 77e799f4 dnsrslvr!R_ResolverQuery+0×111 00a9f8e4 77ef421a RPCRT4!Invoke+0×30 00a9fcf4 77ef46ee RPCRT4!NdrStubCall2+0×297 00a9fd10 77e794bd RPCRT4!NdrServerCall2+0×19 00a9fd44 77e79422 RPCRT4!DispatchToStubInC+0×38 00a9fd98 77e7934e RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×113 00a9fdbc 77e7be64 RPCRT4!RPC_INTERFACE::DispatchToStub+0×84 00a9fdf8 77e7bcc1 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×2db 00a9fe1c 77e7bc05 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×16d 00a9ff80 77e76caf RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×310 00a9ff88 77e76ad1 RPCRT4!RecvLotsaCallsWrapper+0xd 00a9ffa8 77e76c97 RPCRT4!BaseCachedThreadRoutine+0×79 00a9ffb4 7c80b729 RPCRT4!ThreadStartRoutine+0×1a 00a9ffec 00000000 kernel32!BaseThreadStart+0×37
We notice that an endpoint is blocked waiting for a critical section:
kd> !lpc message0000acfeSearching message acfe in threads ...Client thread 89a80328 waiting a reply from acfe Searching thread 89a80328 in port rundown queues ... Server communication port 0xe11152f8 Handles: 1 References: 1 The LpcDataInfoChainHead queue is empty Connected port: 0xe10b6b00 Server connection port: 0xe1633380 Client communication port 0xe10b6b00 Handles: 1 References: 4 The LpcDataInfoChainHead queue is emptyServer thread 89b452e8 is working on message acfe
Server connection port e1633380 Name: trkwks
Handles: 1 References: 19
Server process : 89a20858 (svchost.exe)
Queue semaphore : 89af47e8
Semaphore state 0 (0x0)
The message queue is empty
The LpcDataInfoChainHead queue is empty
Done.
kd> !thread 89b452e8Attached Process 89a20858 Image: svchost.exe036ef7a0 7c901046 ntdll!RtlpWaitForCriticalSection+0×132
036ef7a8 6648a33b ntdll!RtlEnterCriticalSection+0×46In order to get a critical section wait chain (Volume 1, page 490) starting from the above thread we need to set the process context, use !cs WinDbg command, then walk the thread stack trace parameters:
kd> .process /r /p 89a20858DebugInfo = 0x000e74f0 Critical section = 0x01e70cc8 (+0x1E70CC8) LOCKED LockCount = 0x2 OwningThread = 0x00000514 RecursionCount = 0x1 LockSemaphore = 0xBA8 SpinCount = 0x00000000 OwningThread = .thread 8996a338 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ----------------------------------------- DebugInfo = 0x00103d58 Critical section = 0x0272a8b4 (+0x272A8B4) LOCKED LockCount = 0x0 OwningThread = 0x00000d38 RecursionCount = 0x1 LockSemaphore = 0x0 SpinCount = 0x00000000 OwningThread = .thread 89912860 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ----------------------------------------- DebugInfo = 0x0010e8f0 Critical section = 0x664a3fe0 (ipnathlp!gFwMain+0x0) LOCKED LockCount = 0x6 OwningThread = 0x000009e8 RecursionCount = 0x1 LockSemaphore = 0xC48 SpinCount = 0x00000000 OwningThread = .thread 898aa600 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. ----------------------------------------- DebugInfo = 0x0010a7d8 Critical section = 0x00138cd0 (+0x138CD0) LOCKED LockCount = 0x0 OwningThread = 0x00000510 RecursionCount = 0x1 LockSemaphore = 0x0 SpinCount = 0x00000000 OwningThread = .thread 89a2eda8 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. -----------------------------------------
DebugInfo = 0x00109cb0 Critical section = 0x02750f18 (+0x2750F18) LOCKED LockCount = 0x0 OwningThread = 0x00000c84 RecursionCount = 0x1 LockSemaphore = 0x0 SpinCount = 0x00000000 OwningThread = .thread 898ba3d0 ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled. kd> .threadImplicit thread is now 89b452e8 kd> kv 0n10 ChildEBP RetAddr Args to Child b88dccb8 804e1bf2 89b45358 89b452e8 804e1c3e nt!KiSwapContext+0x2f b88dccc4 804e1c3e 00000000 00000000 00000000 nt!KiSwapThread+0x8a b88dccec 8056dff6 00000001 00000006 b88dcd01 nt!KeWaitForSingleObject+0x1c2 b88dcd50 804dd99f 00000c48 00000000 00000000 nt!NtWaitForSingleObject+0x9a b88dcd50 7c90e514 00000c48 00000000 00000000 nt!KiFastCallEntry+0xfc (TrapFrame @ b88dcd64) 036ef714 7c90df5a 7c91b24b 00000c48 00000000 ntdll!KiFastSystemCallRet 036ef718 7c91b24b 00000c48 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc 036ef7a0 7c901046 004a3fe0 6648a33b 664a3fe0 ntdll!RtlpWaitForCriticalSection+0x132 036ef7a8 6648a33b89b452e8664a3fe06648c2ed 00000000 ntdll!RtlEnterCriticalSection+0×46 036ef7b0 6648c2ed 00000000 00000000 00000001 ipnathlp!FwLock+0xa
The thread above is waiting for the critical section 664a3fe0 which has the owner thread 898aa600:
[...]Critical section = 0×664a3fe0 (ipnathlp!gFwMain+0×0)LOCKED LockCount = 0×6 OwningThread = 0×000009e8 RecursionCount = 0×1 LockSemaphore = 0xC48 SpinCount = 0×00000000[...] kd> .threadOwningThread = .thread 898aa600Implicit thread is now 898aa600898aa600
kd> kv 0n10
ChildEBP RetAddr Args to Child
b7b46cb8 804e1bf2 898aa670 898aa600 804e1c3e nt!KiSwapContext+0x2f
b7b46cc4 804e1c3e 00000000 00000000 00000000 nt!KiSwapThread+0x8a
b7b46cec 8056dff6 00000001 00000006 ffffff01 nt!KeWaitForSingleObject+0x1c
b7b46d50 804dd99f 00000c20 00000000 00000000 nt!NtWaitForSingleObject+0x9a
b7b46d50 7c90e514 00000c20 00000000 00000000 nt!KiFastCallEntry+0xfc (TrapFrame @
b7b46d64)
029ef324 7c90df5a 7c91b24b 00000c20 00000000 ntdll!KiFastSystemCallRet
029ef328 7c91b24b 00000c20 00000000 00000000 ntdll!ZwWaitForSingleObject+0xc
029ef3b0 7c901046 00980600 7c910435 7c980600 ntdll!RtlpWaitForCriticalSection+0x132
029ef3b8 7c910435 7c980600 00000000 00000000 ntdll!RtlEnterCriticalSection+0×46
029ef3f8 7c9145d1 00121abe 00121ab0 00000020 ntdll!RtlAcquirePebLock+0×28
The thread 898aa600 is waiting for the critical section 7c980600 which has the owner thread 89cd9c10:
[...]Critical section = 0×7c980600 (ntdll!FastPebLock+0×0)LOCKED LockCount = 0×10 OwningThread = 0×000004a8 RecursionCount = 0×1 LockSemaphore = 0xC20 SpinCount = 0×00000000[...] kd> .threadOwningThread = .thread 89cd9c10Implicit thread is now 89cd9c10 kd> kv 100 ChildEBP RetAddr Args to Child b881c8d4 804e1bf2 89cd9c80 89cd9c10 804e1c3e nt!KiSwapContext+0x2f b881c8e0 804e1c3e 00000000 89e35b08 89e35b34 nt!KiSwapThread+0x8a b881c908 f783092e 00000000 00000006 00000000 nt!KeWaitForSingleObject+0x1c2 b881c930 f7830a3b 89e35b08 00000000 f78356d8 Mup!PktPostSystemWork+0x3d b881c94c f7836712 b881c9b0 b881c9b0 b881c9b8 Mup!PktGetReferral+0xce b881c980 f783644f b881c9b0 b881c9b8 00000000 Mup!PktCreateDomainEntry+0x224 b881c9d0 f7836018 0000000b 00000000 b881c9f0 Mup!DfsFsctrlIsThisADfsPath+0x2bb b881ca14 f7835829 89a2e130 899ba350 b881caac Mup!CreateRedirectedFile+0x2cd b881ca70 804e13eb 89f46ee8 89a2e130 89a2e130 Mup!MupCreate+0x1cb b881ca80 805794b6 89f46ed0 89df3c44 b881cc18 nt!IopfCallDriver+0x31 b881cb60 8056d03b 89f46ee8 00000000 89df3ba0 nt!IopParseDevice+0xa12 b881cbd8 805701e7 00000000 b881cc18 00000042 nt!ObpLookupObjectName+0x53c b881cc2c 80579b12 00000000 00000000 00003801 nt!ObOpenObjectByName+0xea b881cca8 80579be1 00cff67c 00100020 00cff620 nt!IopCreateFile+0x407 b881cd04 80579d18 00cff67c 00100020 00cff620 nt!IoCreateFile+0x8e b881cd44 804dd99f 00cff67c 00100020 00cff620 nt!NtOpenFile+0x27 b881cd44 7c90e514 00cff67c 00100020 00cff620 nt!KiFastCallEntry+0xfc (TrapFrame @ b881cd64) 00cff5f0 7c90d5aa 7c91e8dd 00cff67c 00100020 ntdll!KiFastSystemCallRet 00cff5f4 7c91e8dd 00cff67c 00100020 00cff620 ntdll!ZwOpenFile+0xc 00cff69c 7c831e58 00cff6a8 00460044 0078894a ntdll!RtlSetCurrentDirectory_U+0x169 00cff6b0 7731889e89cd9c1000000000 000000010078894a+0×2b 00cffb84 7730ffbb 00788450 00788b38 00cffbe0 schedsvc!CSchedWorker::RunNTJob+0×221 00cffe34 7730c03a 01ea9108 8ed032d4 00787df8 schedsvc!CSchedWorker::RunJobs+0×304kernel32!SetCurrentDirectoryW
00cffe74 77310e4d 7c80a749 00000000 00000000 schedsvc!CSchedWorker::RunNextJobs+0×129 00cfff28 77310efc 7730b592 00000000 000ba4bc schedsvc!CSchedWorker::MainServiceLoop+0×6d9 00cfff2c 7730b592 00000000 000ba4bc 0009a2bc schedsvc!SchedMain+0xb 00cfff5c 7730b69f 00000001 000ba4b8 00cfffa0 schedsvc!SchedStart+0×266 00cfff6c 010011cc 00000001 000ba4b8 00000000 schedsvc!SchedServiceMain+0×33 00cfffa0 77df354b 00000001 000ba4b8 0007e898 svchost!ServiceStarter+0×9e 00cfffb4 7c80b729 000ba4b0 00000000 0007e898 ADVAPI32!ScSvcctrlThreadA+0×12 00cfffec 00000000 77df3539 000ba4b0 00000000 kernel32!BaseThreadStart+0×37 kd> du /c 900078894a "\0078894aSERVER_BShare_X$Folder_Q"
The thread above is blocked (Volume 2, page 184) trying to set the current directory residing on another server SERVER_B. Its waiting time (Volume 1, page 343) is almost 13 min 34 sec:
kd> !thread 89cd9c10 7
THREAD 89cd9c10 Cid 03a8.04a8 Teb: 7ffd5000 Win32Thread: e1cdc2c0 WAIT:
(UserRequest) KernelMode Non-Alertable
89e35b34 SynchronizationEvent
IRP List:
89a2e130: (0006,0094) Flags: 00000884 Mdl: 00000000
89a13008: (0006,01b4) Flags: 00000000 Mdl: 00000000
Impersonation token: e2deea00 (Level Impersonation)
DeviceMap e1cfe618
Owning Process 0 Image: <Unknown>
Attached Process 89a20858 Image: svchost.exe
Wait Start TickCount 4392 Ticks: 3125677 (0:13:33:58.703)
Context Switch Count 202 LargeStack
UserTime 00:00:00.031
KernelTime 00:00:00.015
Win32 Start Address ADVAPI32!ScSvcctrlThreadA (0×77df3539)
Start Address kernel32!BaseThreadStartThunk (0×7c8106f9)
Stack Init b881d000 Current b881c8bc Base b881d000 Limit b8819000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0 DecrementCount 0
ChildEBP RetAddr Args to Child
[...]
Looking at the previous !process 0 ff command output we also find the similar system thread running through the same drivers and having the same waiting time:
THREAD 8a04cb30 Cid 0004.0014 Teb: 00000000 Win32Thread: 00000000 WAIT:
(Executive) KernelMode Non-Alertable
89e344a8 SynchronizationEvent
IRP List:
89901348:Wait Start TickCount 4392 Ticks: 3125677 (0:13:33:58.703)It has an IRP having file object pointing the same server SERVER_B:
kd> !irpIrp is active with 1 stacks 1 is current (= 0×899013b8) No Mdl: No System Buffer: Thread 8a04cb30: Irp stack trace. cmd flg cl Device File Completion-Context >[ 0, 0] 0 0 89f46ee8 899ab170 00000000-00000000 FileSystemMup Args: f78b2930 03000020 00070080 00000000 kd> !fileobj 899ab17089901348SERVER_BIPC$ Device Object: 0x89f46ee8 FileSystemMup Vpb is NULL Flags: 0x2 Synchronous IO CurrentByteOffset: 0
So it looks like we have an instance of Coupled Machines pattern (page 81). We also notice that wait chain threads have various Windows socket modules on their thread stacks and we check if there is any IRP distribution anomaly (Volume 1, page 459) using !irpfind command. When counting IRPs we find the most of them are directed towards HTTP, Tcpip and AFD drivers:
In a complete memory dump we could see ALPC wait chains (Volume 3, page 97) leading to ServiceA.exe process with a queue of 372 messages. Additionally, we could also see ServiceB.exe process waiting for ServiceC.exe with the latter having a queue of 201 messages. Threads that were supposed to process some messages were missing (Volume 1, page 362). ServiceC process had a thread that was waiting for ServiceA.exe as well. But there was no any indication for a thread-2-thread deadlock. We could also see that threads waiting for ServiceA.exe sometimes had the greater waiting time (Volume 1, page 343) than threads waiting for ServiceC. Therefore, it could be the case that the problem initially started with ServiceA.exe. However, after more thorough analysis we could also see several terminating ApplicationD.exe processes with just one thread waiting in ModuleE with the waiting time exceeding the waiting time of the blocked threads waiting for ServiceA and ServiceC. Because of semantic process coupling (page 87) between ServiceA and ApplicationD we decided that ModuleE was responsible and its vendor was contacted for updates.
A complete memory dump was generated from a totally unresponsive frozen system. Looking at its virtual memory stats we see the shortage of nonpaged pool (insufficient pool memory pattern, Volume 1, page 441):
0: kd> !vm
*** Virtual Memory Usage ***
Physical Memory: 1047977 ( 4191908 Kb)
Page File: ??C:pagefile.sys
Current: 4195328 Kb Free Space: 4167696 Kb
Minimum: 4195328 Kb Maximum: 4195328 Kb
Page File: ??E:pagefile.sys
Current: 8372224 Kb Free Space: 8348916 Kb
Minimum: 8372224 Kb Maximum: 8388608 Kb
Available Pages: 855939 ( 3423756 Kb)
ResAvail Pages: 958559 ( 3834236 Kb)
Locked IO Pages: 100 ( 400 Kb)
Free System PTEs: 200627 ( 802508 Kb)
Free NP PTEs: 0 ( 0 Kb)
Free Special NP: 120925 ( 483700 Kb)
Modified Pages: 52 ( 208 Kb)
Modified PF Pages: 52 ( 208 Kb)
NonPagedPool Usage: 65199 ( 260796 Kb)
NonPagedPool Max: 65536 ( 262144 Kb)
********** Excessive NonPaged Pool Usage *****
PagedPool 0 Usage: 7731 ( 30924 Kb)
PagedPool 1 Usage: 6334 ( 25336 Kb)
PagedPool 2 Usage: 6316 ( 25264 Kb)
PagedPool 3 Usage: 6333 ( 25332 Kb)
PagedPool 4 Usage: 6318 ( 25272 Kb)
PagedPool Usage: 33032 ( 132128 Kb)
PagedPool Maximum: 66560 ( 266240 Kb)
********** 7041316 pool allocations have failed **********
Session Commit: 2860 ( 11440 Kb)
Shared Commit: 3904 ( 15616 Kb)
Special Pool: 255 ( 1020 Kb)
Shared Process: 9336 ( 37344 Kb)
PagedPool Commit: 33032 ( 132128 Kb)
Driver Commit: 2147 ( 8588 Kb)
Committed pages: 174724 ( 698896 Kb)
Commit limit: 4148057 ( 16592228 Kb)
Dumping sorted pool consumers we see the most used were DRV* pool tags:
0: kd> !poolused 3
Sorting by NonPaged Pool Consumed
Pool Used:
NonPaged
Tag Allocs Frees Diff Used
DRV2 21683882 21280457 403425 80685000 UNKNOWN pooltag 'DRV2'
DRV4 46621052 46217627 403425 54156728 UNKNOWN pooltag 'DRV4'
DRV5 37848660 37065132 783528 31341120 UNKNOWN pooltag 'DRV5'
MmCm 15754 14607 1147 24917536 Calls made to
MmAllocateContiguousMemory , Binary: nt!mm
DRV3 16189418 15785993 403425 19364400 UNKNOWN pooltag 'DRV3'
[...]
We also check CPU consumption and see two spiking threads (Volume 1, page 305):
0: kd> !running System Processors f (affinity mask) Idle Processors 9 Prcbs Current Next 1 f7727120................ 2 f772f12087c5ca48881ccae0................
We see the first thread spent much more kernel time and its stack trace involved DriverA module:
0: kd> !thread1f THREAD87c5ca48Cid 0ba0.0bc8 Teb: 7ffd7000 Win32Thread: 00000000 RUNNING on processor 1 Not impersonating DeviceMap e10028f0 Owning Process 87c3a978 Image: ApplicationB.exe Attached Process N/A Image: N/A Wait Start TickCount 4516745 Ticks: 2 (0:00:00:00.031) Context Switch Count 2234544 UserTime 00:00:58.50087c5ca48Win32 Start Address ApplicationB (0×402016bd) Start Address kernel32!BaseThreadStartThunk (0×77e617ec) Stack Init b8771000 Current b87708b4 Base b8771000 Limit b876e000 Call 0 Priority 13 BasePriority 8 PriorityDecrement 1 ChildEBP RetAddr b8770bd0 80892b6f nt!ExFreePoolWithTag+0xb7 b8770be0 80933bcd nt!ExFreePool+0xf b8770c0c 808bb471 nt!ObOpenObjectByName+0×163KernelTime 00:55:09.218
b8770cf8 b951f08e nt!NtOpenKey+0×1ad WARNING: Stack unwind information not available. Following frames may be wrong.b8770d50 7c82860c nt!KiFastCallEntry+0xfc (TrapFrame @ b8770d64) 00c0f0b4 7c827369 ntdll!KiFastSystemCallRet 00c0f0b8 7d206cb1 ntdll!ZwOpenKey+0xc 00c0f118 7d1fe187 ADVAPI32!LocalBaseRegOpenKey+0xd0 00c0f14c 40202284 ADVAPI32!RegOpenKeyExA+0×11c [...] 00c0ffb8 77e6482f ApplicationB+0×1891 00c0ffec 00000000 kernel32!BaseThreadStart+0×34 0: kd> !threadb8770d50 808897cc DriverA+0×1608e881ccae01f THREAD881ccae0Cid 05b8.05c4 Teb: 7ffde000 Win32Thread: 00000000 RUNNING on processor 2 Not impersonating DeviceMap e10028f0 Owning Process 881cf020 Image: ApplicationC.exe Attached Process N/A Image: N/A Wait Start TickCount 4516747 Ticks: 0 Context Switch Count 115916 UserTime 00:00:03.468KernelTime 00:00:53.156Win32 Start Address ADVAPI32!ScSvcctrlThreadA (0×7d1f5e70) Start Address kernel32!BaseThreadStartThunk (0×77e617ec) Stack Init b900d000 Current b900cc50 Base b900d000 Limit b900a000 Call 0 Priority 13 BasePriority 8 PriorityDecrement 0 ChildEBP RetAddr 005bf9c4 7d1eef7e ADVAPI32!LocalBaseRegEnumKey+0×2 005bfc24 010091c9 ADVAPI32!RegEnumKeyExA+0×12f WARNING: Stack unwind information not available. Following frames may be wrong. 005bfc74 0100a28c ApplicationC+0×91c9 [...] 005bffb8 77e6482f ApplicationC+0×8b13 005bffec 00000000 kernel32!BaseThreadStart+0×34
We check the pool entry it was freeing:
0: kd> .thread /r /pImplicit thread is now 87c5ca48 Implicit process is now 87c3a978 Loading User Symbols 0: kd> kv L1 ChildEBP RetAddr Args to Child b8770bd0 80892b6f87c5ca4800000000 b8770c0c nt!ExFreePoolWithTag+0xb78ab6b3c8
0: kd> !pool 8ab6b3c8 Pool page 8ab6b3c8 region is Nonpaged pool8ab6b0008ab6b0c8 size: 70 previous size: c8 (Allocated) MmCasize: c8 previous size: 0 (Allocated) DRV28ab6b1a8 size: 28 previous size: 30 (Allocated) NtFs8ab6b138 size: 10 previous size: 70 (Free) DRV2 8ab6b148 size: 30 previous size: 10 (Allocated) DRV3 8ab6b178 size: 30 previous size: 30 (Allocated) DRV38ab6b200 size: 18 previous size: 30 (Free) IrpC 8ab6b218 size: a8 previous size: 18 (Allocated) File (Protected) 8ab6b2c0 size: 100 previous size: a8 (Allocated) MmCi *8ab6b3c0 size: 38 previous size: 100 (Allocated) *ObCi Pooltag ObCi : captured information for ObCreateObject, Binary : nt!ob8ab6b1d0 size: 30 previous size: 28 (Allocated) DRV38ab6b448 size: 28 previous size: 8 (Allocated) NtFs 8ab6b470 size: 8 previous size: 28 (Free) Mdl8ab6b3f8 size: 48 previous size: 38 (Allocated) DRV2 8ab6b440 size: 8 previous size: 48 (Free) DRV48ab6b5a0 size: a8 previous size: c8 (Allocated) File (Protected)8ab6b478 size: 60 previous size: 8 (Allocated) DRV4 8ab6b4d8 size: c8 previous size: 60 (Allocated) DRV28ab6b7d8 size: 10 previous size: c8 (Free) File8ab6b648 size: c8 previous size: a8 (Allocated) DRV2 8ab6b710 size: c8 previous size: c8 (Allocated) DRV28ab6b8b0 size: 28 previous size: 30 (Allocated) NtFs8ab6b7e8 size: 98 previous size: 10 (Allocated) DRV4 8ab6b880 size: 30 previous size: 98 (Allocated) DRV38ab6b8d88ab6b930 size: a8 previous size: 30 (Allocated) File (Protected) 8ab6b9d8 size: 100 previous size: a8 (Allocated) MmCi 8ab6bad8 size: 10 previous size: 100 (Free) ObCi [...]size: 28 previous size: 28 (Allocated) DRV5 8ab6b900 size: 30 previous size: 28 (Allocated) DRV3
In the output above we see all clustering of DRV* pool tags and check their contents:
0: kd> dps8ab6b000 0a190000 [...] 8ab6b06c8ab6b0008ab6b070 87cb85c8 8ab6b074 002d0000 8ab6b078 8ab6b078 8ab6b07c 8ab6b078 0: kd> dpsb95349a0 DriverA+0×2b9a08ab6b8d8 0a050005 [...] 8ab6b8f88ab6b8d88ab6b8fc 00000074 [...]b95349a0 DriverA+0×2b9a0
It looks like all DRV* pool entries have symbolic references in the range of DriverA (data contents locality, Volume 2, page 300):
0: kd> lm m DriverA start end module name b9509000 b9537f00 DriverA (no symbols)
So the conclusion was to refer to DriverA vendor for any updates.
This case study centers on three user process dump files (two first chance exception and one second chance exception). To recall the difference between them please read first chance exceptions explained series[18]. When we get first and second chance exception dumps together we usually open a second chance exception dump first. However, in this case, the second chance exception dump has an incorrect stack trace (Volume 1, page 288):
(f54.b80): Access violation - code c0000005 (!!! second chance !!!)
eax=00000248 ebx=00000000 ecx=004054e8 edx=7c9032bc esi=00000000
edi=00000000
eip=7c7d24f0 esp=00030e4c ebp=000310a4 iopl=0 nv up ei pl nz ac po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00200212
kernel32!_SEH_prolog+0×1a:
7c7d24f0 53 push ebx
0:000> kL
ChildEBP RetAddr
000310a4 00000000 kernel32!_SEH_prolog+0x1a
The default analysis command detects stack overflow pattern (Volume 2, page 279):
0:000> !analyze -v [...] FAULTING_IP: ntdll!RtlDispatchException+8 7c92a978 56 push esi EXCEPTION_RECORD: ffffffff -- (.exr 0xffffffffffffffff) ExceptionAddress: 7c92a978 (ntdll!RtlDispatchException+0x00000008) ExceptionCode: c00000fd (Stack overflow) ExceptionFlags: 00000000 NumberParameters: 2 Parameter[0]: 00000001 Parameter[1]: 00032fc0 DEFAULT_BUCKET_ID: STACK_OVERFLOW
ERROR_CODE: (NTSTATUS) 0xc00000fd - A new guard page for the stack cannot
be created.Indeed, ESP is outside the stack region and that happened during unhandled exception processing:
0:000> r esp0:000> !teb TEB at 7ffdf000 ExceptionList: 000310c4 StackBase: 00130000esp=00030e4cSubSystemTib: 00000000 FiberData: 00001e00 ArbitraryUserPointer: 00000000 Self: 7ffdf000 EnvironmentPointer: 00000000 ClientId: 00000f54 . 00000b80 RpcHandle: 00000000 Tls Storage: 001537a8 PEB Address: 7ffdb000 LastErrorValue: 2 LastStatusValue: c000000f Count Owned Locks: 0 HardErrorMode: 0 0:000> dps esp l100 00030e4c ???????? 00030e50 ???????? [...] 00030ff8 ???????? 00030ffc ???????? 00031000 00000000 00031004 00000000 00031008 00000000 0003100c 00000000 00031010 00000000 00031014 00000000 00031018 00000000 0003101c 00000000 00031020 00000000 00031024 7c910323 ntdll!RtlpImageNtHeader+0x56 00031028 004054e8 Application+0x54e8 0003102c 00400000 Application 00031030 00400000 Application 00031034 00400100 Application+0x100 00031038 00031028StackLimit: 00031000
0003103c 7e390000 USER32!_imp__GetClipRgn <PERF> (USER32+0x0)
00031040 00031060
00031044 7c910385 ntdll!RtlImageDirectoryEntryToData+0x57
00031048 00400000 Application
0003104c 00000001
00031050 0000000e
00031054 00031084
00031058 7c910323 ntdll!RtlpImageNtHeader+0x56
0003105c 004054e8 Application+0x54e8
00031060 7c900000 ntdll!RtlDosPathSeperatorsString <PERF> (ntdll+0x0)
00031064 0012ff00
00031068 7c9000d0 ntdll!RtlDosPathSeperatorsString <PERF> (ntdll+0xd0)
0003106c 0003105c
00031070 0000000e
00031074 00114e88
00031078 7c90e920 ntdll!_except_handler3
0003107c 7c910328 ntdll!'string'+0x4
00031080 ffffffff
00031084 7c910323 ntdll!RtlpImageNtHeader+0x56
00031088 7c935f1c ntdll!RtlLookupFunctionTable+0xc5
0003108c 7c92ab3a ntdll!RtlLookupFunctionTable+0xf2
00031090 7c97e178 ntdll!LdrpLoaderLock
00031094 000310c4
00031098 7c809ad8 kernel32!_except_handler3
0003109c 7c833fd9 kernel32!UnhandledExceptionFilter+0xfBefore we try to reconstruct the stack trace we open the earlier (Volume 1, page 466) first-chance exception dump file:
0:000> .opendump 1stchance.dmp Loading Dump File [1stchance.dmp] User Dump File: Only application data is available Opened '1stchance.dmp'
||0:0:000> g
(f54.b80): Stack overflow - code c00000fd (first chance)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
eax=0003332c ebx=00033040 ecx=00033054 edx=7c90e514 esi=000333a8
edi=00000000
eip=7c92a978 esp=00032fc4 ebp=00033028 iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00200202
ntdll!RtlDispatchException+0×8:
7c92a978 56 push esi
Here we are able to get the stack trace from the saved nested exception (Volume 2, page 305):
||1:1:020> kL 1000 ChildEBP RetAddr 00033028 7c90e48a ntdll!RtlDispatchException+0x8 00033028 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00033390 7c90e48a ntdll!RtlDispatchException+0x133 00033390 7c95019e ntdll!KiUserExceptionDispatcher+0xe 000336f8 7c90e48a ntdll!RtlDispatchException+0x133 000336f8 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00033a60 7c90e48a ntdll!RtlDispatchException+0x133 00033a60 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00033dc8 7c90e48a ntdll!RtlDispatchException+0x133 00033dc8 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00034130 7c90e48a ntdll!RtlDispatchException+0x133 00034130 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00034498 7c90e48a ntdll!RtlDispatchException+0x133 00034498 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00034800 7c90e48a ntdll!RtlDispatchException+0x133 00034800 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00034b68 7c90e48a ntdll!RtlDispatchException+0x133 00034b68 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00034ed0 7c90e48a ntdll!RtlDispatchException+0x133 00034ed0 7c95019e ntdll!KiUserExceptionDispatcher+0xe [...] 001143f8 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00114760 7c90e48a ntdll!RtlDispatchException+0x133 00114760 7c95019e ntdll!KiUserExceptionDispatcher+0xe 00114ac8 7c90e48a ntdll!RtlDispatchException+0x133 00114ac8 7c7e2afb ntdll!KiUserExceptionDispatcher+0xe 00114e30 0057ad17 kernel32!RaiseException+0x53 WARNING: Stack unwind information not available. Following frames may be wrong. 00114e54 0098ff95 Application+0x17ad17 [...] 00121fd8 7e398734 Application+0x313be 00122004 7e398816 USER32!InternalCallWinProc+0x28 0012206c 7e3a8ea0 USER32!UserCallWinProcCheckWow+0x150
001220c0 7e3aacd1 USER32!DispatchClientMessage+0xa3 001220f0 7c90e473 USER32!__fnINSTRING+0x37 0012212c 7e3993e9 ntdll!KiUserCallbackDispatcher+0x13 00122158 7e3aa43b USER32!NtUserPeekMessage+0xc 00122184 004794d9 USER32!PeekMessageA+0xeb 00122234 00461667 Application+0x794d9 [...] 0012ffc0 7c7e7077 Application+0x60610b 0012fff0 00000000 kernel32!BaseProcessStart+0x23
This all points to a problem exception handler (page 126):
||1:1:020> !analyze -v
[...]
CONTEXT: 00114b10 -- (.cxr 0x114b10)
eax=00114de0 ebx=0eedfade ecx=00000000 edx=001537a8 esi=00114e88
edi=00000007
eip=7c7e2afb esp=00114ddc ebp=00114e30 iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00200202
kernel32!RaiseException+0x53:
7c7e2afb 5e pop esi
Resetting default scope
[...]
||1:1:020> .cxr 0x114b10
||1:1:020> kv 1
ChildEBP RetAddr Args to Child
00114e30 0057ad17 0eedfade 00000001Being curious we also open the second first chance exception dump and it points to the expected crash point (the same as seen in the second chance exception crash dump)
||1:1:020> .opendump 1stchance2.dmp Loading Dump File [1stchance2.dmp] User Dump File: Only application data is available Opened '1stchance2.dmp' ||1:1:020> g [...]
(f54.b80): Access violation - code c0000005 (first chance)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
eax=00000248 ebx=00000000 ecx=004054e8 edx=7c9032bc esi=00000000
edi=00000000
eip=7c7d24f0 esp=00030e4c ebp=000310a4 iopl=0 nv up ei pl nz ac po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00200212
kernel32!_SEH_prolog+0×1a:
7c7d24f0 53 push ebx
||2:2:040> kL
ChildEBP RetAddr
000310a4 00000000 kernel32!_SEH_prolog+0x1a
We find the similar past issue for a different process name but our main process module information includs the same vendor (page 128) name so it is easy to contact the corresponding vendor.
..................Content has been hidden....................
You can't read the all page of ebook, please click here login for view all page.