Coupled processes, wait chains, message box, waiting thread time, paged out data, incorrect stack trace, hidden exception, unknown component and execution residue: pattern cooperation

Let’s look at one complete memory dump from a hanging system. It was reported that an application was hanging when trying to create a printer. In its process we can identify this blocked thread that was processing an LPC request and waiting for an LPC reply from a coupled process, a spooler service:

0: kd> !thread 88db89a8 1f
THREAD 88db89a8  Cid 0764.31b8  Teb: 7ffdc000 Win32Thread: bc2dc980 WAIT: (Unknown) UserMode Non-Alertable
    88db8b94  Semaphore Limit 0x1
Waiting for reply to LPC MessageId 0016346d:
Current LPC port e179d780
Not impersonating
DeviceMap                 e157b068
Owning Process            8a95f690       Image:         ApplicationA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      2750643        Ticks: 153453 (0:00:39:57.703)
Context Switch Count      2120                 LargeStack
UserTime                  00:00:00.031
KernelTime                00:00:00.078
Win32 Start Address 0×0015b4fd
LPC Server thread working on message Id 15b4fd
Start Address kernel32!BaseThreadStartThunk (0×77e617ec)
Stack Init b7848000 Current b7847c08 Base b7848000 Limit b7845000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr 
b7847c20 80833ec5 nt!KiSwapContext+0×26
b7847c4c 80829bc0 nt!KiSwapThread+0×2e5
b7847c94 80920f28 nt!KeWaitForSingleObject+0×346
b7847d50 8088ad3c nt!NtRequestWaitReplyPort+0×776
b7847d50 7c8285ec nt!KiFastCallEntry+0xfc (TrapFrame @ b7847d64)
00e6e150 7c82787b ntdll!KiFastSystemCallRet
00e6e154 77c80a6e ntdll!NtRequestWaitReplyPort+0xc
00e6e1a8 77c7fcf0 RPCRT4!LRPC_CCALL::SendReceive+0×230
00e6e1b4 77c80673 RPCRT4!I_RpcSendReceive+0×24
00e6e1c8 77ce315a RPCRT4!NdrSendReceive+0×2b
00e6e5b0 7307ca61 RPCRT4!NdrClientCall2+0×22e
00e6e5c8 73082e15 WINSPOOL!RpcAddPrinter+0×1c
00e6ea50 0040dd93 WINSPOOL!AddPrinterW+0×102
00e6ef40 0040f535 ApplicationA!CreatePrinter+0×8d9

[…]
00e6f8b4 77ce33e1 RPCRT4!Invoke+0×30
00e6fcb4 77ce35c4 RPCRT4!NdrStubCall2+0×299
00e6fcd0 77c7ff7a RPCRT4!NdrServerCall2+0×19
00e6fd04 77c8042d RPCRT4!DispatchToStubInCNoAvrf+0×38
00e6fd58 77c80353 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×11f
00e6fd7c 77c7e0d4 RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3
00e6fdbc 77c7e080 RPCRT4!RPC_INTERFACE::DispatchToStubWithObject+0xc0
00e6fdfc 77c812f0 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×41e
00e6fe20 77c88678 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×127
00e6ff84 77c88792 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430
00e6ff8c 77c8872d RPCRT4!RecvLotsaCallsWrapper+0xd
00e6ffac 77c7b110 RPCRT4!BaseCachedThreadRoutine+0×9d
00e6ffb8 77e64829 RPCRT4!ThreadStartRoutine+0×1b

We follow an LPC wait chain and see a thread blocked by a message box:

0: kd> !lpc message 0016346d
Searching message 16346d in threads …
    Server thread 891e9db0 is working on message 16346d                        
Client thread 88db89a8 waiting a reply from 16346d                         
Searching thread 88db89a8 in port rundown queues …

0: kd> !thread 891e9db0 1f
THREAD 891e9db0  Cid 045c.3b3c  Teb: 7ffa7000 Win32Thread: bc2d4ea8 WAIT: (Unknown) UserMode Non-Alertable
    88f5c850  SynchronizationEvent
Impersonation token:  e76f5030 (Level Impersonation)
DeviceMap                 e157b068
Owning Process            8ab10460       Image:         spoolsv.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      2414962        Ticks: 489134 (0:02:07:22.718)
Context Switch Count      6797                 LargeStack
UserTime                  00:00:00.359
KernelTime                00:00:01.437
Win32 Start Address 0×0016346d
LPC Server thread working on message Id 16346d
Start Address kernel32!BaseThreadStartThunk (0×77e617ec)
Stack Init b6aaa000 Current b6aa9c50 Base b6aaa000 Limit b6aa6000 Call 0
Priority 11 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.
ChildEBP RetAddr 
b6aa9c68 80833ec5 nt!KiSwapContext+0×26
b6aa9c94 80829bc0 nt!KiSwapThread+0×2e5
b6aa9cdc bf89aacc nt!KeWaitForSingleObject+0×346
b6aa9d38 bf89d952 win32k!xxxSleepThread+0×1be
b6aa9d4c bf89e310 win32k!xxxRealWaitMessageEx+0×12
b6aa9d5c 8088ad3c win32k!NtUserWaitMessage+0×14
b6aa9d5c 7c8285ec nt!KiFastCallEntry+0xfc (TrapFrame @ b6aa9d64)
021267bc 7739bf53 ntdll!KiFastSystemCallRet
021267f4 7738965e USER32!NtUserWaitMessage+0xc
0212681c 7739f762 USER32!InternalDialogBox+0xd0
02126adc 7739f047 USER32!SoftModalMessageBox+0×94b
02126c2c 7739eec9 USER32!MessageBoxWorker+0×2ba
02126c84 773d7d0d USER32!MessageBoxTimeoutW+0×7a
02126cb8 773c42c8 USER32!MessageBoxTimeoutA+0×9c
02126cd8 773c42a4 USER32!MessageBoxExA+0×1b
02126cf4 6dfcf8c2 USER32!MessageBoxA+0×45
WARNING: Frame IP not in any known module. Following frames may be wrong.
02126d98 530a2935 0×6dfcf8c2
02126d9c 20656d6f 0×530a2935
[…]

Looking at this thread waiting time we see the problem happened about 1 hour 20 minutes before our hanging application attempted to print. We want to see other threads in the spooler but most of them are paged out:

0: kd> !process 8ab10460 1f

[...]

THREAD 8a6aedb0  Cid 045c.1090  Teb: 7ffab000 Win32Thread: bc33bbe8 WAIT: (Unknown) UserMode Non-Alertable
    8abb2f40  SynchronizationEvent
    IRP List:
        8a0a2ed0: (0006,0094) Flags: 00000800  Mdl: 00000000
Impersonation token:  e7c94760 (Level Impersonation)
DeviceMap                 e9194e68
Owning Process            8ab10460       Image:         spoolsv.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      1897118        Ticks: 1006978 (0:04:22:14.031)
Context Switch Count      9711                 LargeStack
UserTime                  00:00:00.343
KernelTime                00:00:02.812
Win32 Start Address 0x00165a40
LPC Server thread working on message Id 165a40
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b7c28000 Current b7c27c60 Base b7c28000 Limit b7c24000 Call 0
Priority 13 BasePriority 8 PriorityDecrement 0
Kernel stack not resident.

[...] 

Coming back to our message box thread we inspect MessageBox parameters to see the message:

0: kd> .process /r /p 8ab10460
Implicit process is now 8ab10460
Loading User Symbols

0: kd> !thread 891e9db0
[...]
ChildEBP RetAddr  Args to Child             
[...]
02126cf4 6dfcf8c2 00000000 02126d4c 02126d2c USER32!MessageBoxA+0×45
[…]

0: kd> da /c 100 02126d4c
02126d4c  "Function address 0×77e63ce4 caused a protection fault. (exception code 0xc0000005).

0: kd> ln 0x77e63ce4
(77e63c87)   kernel32!GetModuleFileNameW+0×83   |  (77e63d7a)   kernel32!GetProcAddress

We see that the thread experienced an access violation in GetModuleFileName API call.

We also see that stack trace is incorrect and we try to reconstruct the point of exception by looking at thread raw stack and searching for any hidden exception

0: kd> .thread 891e9db0
Implicit thread is now 891e9db0

0: kd> !teb
TEB at 7ffa7000
    ExceptionList:        0212757c
    StackBase:            02130000
    StackLimit:           02123000

    SubSystemTib:         00000000
    FiberData:            00001e00
    ArbitraryUserPointer: 00000000
    Self:                 7ffa7000
    EnvironmentPointer:   00000000
    ClientId:             0000045c . 00003b3c
    RpcHandle:            00000000
    Tls Storage:          00000000
    PEB Address:          7ffde000
    LastErrorValue:       0
    LastStatusValue:      c0000034
    Count Owned Locks:    0
    HardErrorMode:        0

0: kd> dds 02123000 02130000
02123000  00000000
02123004  00000000
02123008  00000000
0212300c  00000000
[...]
021275a8  02127648
021275ac  0212aa0c
021275b0  7c8315c2 ntdll!RtlDispatchException+0×91
021275b4  02127648
021275b8  0212aa0c
021275bc  02127664

021275c0  02127624
021275c4  6dfd0a54
021275c8  063b0000
021275cc  02127648
021275d0  7c8877ec ntdll!PebLdr+0xc
021275d4  77e61a60 kernel32!_except_handler3
021275d8  77e69cf8 kernel32!`string’+0xc
021275dc  ffffffff
021275e0  00080000
021275e4  00089878
021275e8  77b92e40 VERSION!`string’
021275ec  00000000
021275f0  00000000
021275f4  00017608
021275f8  02127540
021275fc  77b92e40 VERSION!`string’
02127600  02127648
02127604  7c828270 ntdll!_except_handler3
02127608  7c829f60 ntdll!CheckHeapFillPattern+0×64
0212760c  ffffffff
02127610  7c829f59 ntdll!RtlFreeHeap+0×70f
02127614  77e62444 kernel32!LocalFree+0×27
02127618  00080000
0212761c  00000000
02127620  77e62457 kernel32!LocalFree+0×108
02127624  5dff1510
02127628  02130000
0212762c  00000000
02127630  0212797c
02127634  7c82855e ntdll!KiUserExceptionDispatcher+0xe
02127638  02123000
0212763c  02127664

02127640  02127648
02127644  02127664
02127648  c0000005
0212764c  00000000
02127650  00000000
02127654  77e63ce4 kernel32!GetModuleFileNameW+0×83
02127658  00000002
0212765c  00000000
02127660  00000018
02127664  0001003f
02127668  00000000
0212766c  00000000
02127670  00000000
[…]

0: kd> .cxr 02127664
eax=00000000 ebx=00000000 ecx=7c82d279 edx=7c8877a0 esi=7c8877ec edi=063b0000
eip=77e63ce4 esp=02127930 ebp=0212797c iopl=0  nv up ei ng nz ac pe cy
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000  efl=00010297
kernel32!GetModuleFileNameW+0x83:
001b:77e63ce4 3b7818          cmp     edi,dword ptr [eax+18h] ds:0023:00000018=????????

0: kd> kv
  *** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr  Args to Child             
0212797c 77390f3d 063b0000 021279d0 00000104 kernel32!GetModuleFileNameW+0x83
02127990 77390f13 063b0000 021279d0 00000104 USER32!WowGetModuleFileName+0x14
02127bdc 7738bcbd 063b0000 00000097 00000003 USER32!LoadIcoCur+0x76
02127bfc 06425db5 063b0000 00000097 02127d28 USER32!LoadIconW+0×1b
WARNING: Frame IP not in any known module. Following frames may be wrong.
02127c38 7c82cefe 00000704 00001f10 02127c58 0×6425db5
02127c4c 7c82ceb0 00001f10 00002614 00000704 ntdll!ARRAY_FITS+0×29
02127c8c c0150008 00000000 03923f68 0000001d ntdll!RtlpLocateActivationContextSection+0×1da
02127d20 7c82e0ef 00000000 00000000 00071f10 0xc0150008

What we see is the fact that the thread tried to load an icon from 063b0000 module not listed in lmv command output list perhaps because it was not fully loaded yet. We see that the thread also holds a loader critical section:

0: kd> !cs -l -o -s
-----------------------------------------
DebugInfo          = 0x7c8877c0
Critical section   = 0×7c8877a0 (ntdll!LdrpLoaderLock+0×0)
LOCKED
LockCount          = 0xC
WaiterWoken        = No
OwningThread       = 0×00003b3c
RecursionCount     = 0×1
LockSemaphore      = 0×108
SpinCount          = 0×00000000
OwningThread       = .thread 891e9db0
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.

However we can inspect the unknown module PE headers left in memory:

 0: kd> !dh 063b0000

File Type: DLL
FILE HEADER VALUES
     14C machine (i386)
       4 number of sections
42B9172C time date stamp Wed Jun 22 08:45:48 2005

       0 file pointer to symbol table
       0 number of symbols
      E0 size of optional header
    210E characteristics
            Executable
            Line numbers stripped
            Symbols stripped
            32 bit word machine
            DLL

[...]

Debug Directories(1)
 Type       Size     Address  Pointer
 cv           16       10198     f598 Format: NB10, 42b9172c, 1, c:\printerdriver123UI.pdb

[...]

We see that the module name is printerdriver123UI. So we should recommend to check the printer driver package containing this component. lmv command lists many printer drivers with the similar name prefix and we look at thread execution residue to get better stack trace and find the corresponding printer. We know that the application called AddPrinter API and therefore we try to find the corresponding call on the raw stack that we examined for hidden exceptions before:

[...]
0212ef2c  01f20390
0212ef30  0212f3f8
0212ef34  76144799 localspl!SplAddPrinter+0×5f3
0212ef38  01efb730
0212ef3c  00000003
[…]
0212f3f8  0212f424
0212f3fc  76144ab2 localspl!LocalAddPrinterEx+0×2e
0212f400  00000000
[…]
0212f424  0212f874
0212f428  7407018b SPOOLSS!AddPrinterExW+0×151
0212f42c  00000000
[…]
0212f874  0212f890
0212f878  74070254 SPOOLSS!AddPrinterW+0×17
0212f87c  00000000
[…]

0: kd> kv L=0212ef30
ChildEBP RetAddr  Args to Child             
0212ef30 76144799 01efb730 00000003 00000000 kernel32!GetModuleFileNameW+0x83
0212f3f8 76144ab2 00000000 00000002 011116e0 localspl!SplAddPrinter+0x5f3
0212f424 7407018b 00000000 00000002 011116e0 localspl!LocalAddPrinterEx+0x2e
0212f874 74070254 00000000 00000002 011116e0 SPOOLSS!AddPrinterExW+0x151
0212f890 0100792d 00000000 00000002 011116e0 SPOOLSS!AddPrinterW+0×17
0212f8ac 01006762 00000000 0118f968 00159180 spoolsv!YAddPrinter+0×75
0212f8d0 77c80193 00000000 0118f968 00159180 spoolsv!RpcAddPrinter+0×37
0212f8f8 77ce33e1 0100672b 0212fae0 00000005 RPCRT4!Invoke+0×30
0212fcf8 77ce35c4 00000000 00000000 000cefbc RPCRT4!NdrStubCall2+0×299
0212fd14 77c7ff7a 000cefbc 000bbd20 000cefbc RPCRT4!NdrServerCall2+0×19
0212fd48 77c8042d 01002c47 000cefbc 0212fdec RPCRT4!DispatchToStubInCNoAvrf+0×38
0212fd9c 77c80353 00000005 00000000 0100d228 RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×11f
0212fdc0 77c811dc 000cefbc 00000000 0100d228 RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3
0212fdfc 77c812f0 000c9e80 000a7af0 0014ce70 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×42c
0212fe20 77c88678 000a7b28 0212fe38 000c9e80 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×127
0212ff84 77c88792 0212ffac 77c8872d 000a7af0 RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×430
0212ff8c 77c8872d 000a7af0 00000000 00000000 RPCRT4!RecvLotsaCallsWrapper+0xd
0212ffac 77c7b110 000885d8 0212ffec 77e64829 RPCRT4!BaseCachedThreadRoutine+0×9d
0212ffb8 77e64829 000a3750 00000000 00000000 RPCRT4!ThreadStartRoutine+0×1b
0212ffec 00000000 77c7b0f5 000a3750 00000000 kernel32!BaseThreadStart+0×34

 
Examination of the server-side AddPrinter arguments reveals the printer name:

0: kd> dpu 011116e0 l5
011116e0  00000000
011116e4  00158f48
011116e8  00000000
011116ec  00158fe4
011116f0  00159040 "PRINTER NAME ABCDEF

- Dmitry Vostokov @ DumpAnalysis.org -

2 Responses to “Coupled processes, wait chains, message box, waiting thread time, paged out data, incorrect stack trace, hidden exception, unknown component and execution residue: pattern cooperation”

  1. Adrian Says:

    Thank for the article, in contains really good tips.

  2. Dmitry Vostokov Says:

    Good domain name idea :-) Adding it to my blogroll

Leave a Reply

You must be logged in to post a comment.