Software Diagnostics Library

Today we introduce an icon for Hooked Functions (kernel space) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Today we introduce an icon for Hooked Functions (user space) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Today we introduce an icon for High Contention (processors) pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

This is a variant of High Contention pattern for processors where we have more threads at the same priority than the available processors. All these threads share the same notification event (or any other similar synchronization mechanism) and rush once it is signalled. If this happens often the system becomes sluggish or even appears frozen.

0: kd> !running

System Processors 3 (affinity mask)
  Idle Processors 0

Prcbs  Current   Next   
  0    ffdff120  89a92020            O...............
  1    f7737120  89275020            W...............

0: kd> !ready
Processor 0: Ready Threads at priority 8
    THREAD 894a1db0  Cid 1a98.25c0  Teb: 7ffde000 Win32Thread: bc19cea8 READY
    THREAD 897c4818  Cid 11d8.1c5c  Teb: 7ffa2000 Win32Thread: bc2c5ba8 READY
    THREAD 8911fd18  Cid 2730.03f4  Teb: 7ffd9000 Win32Thread: bc305830 READY
Processor 1: Ready Threads at priority 8
    THREAD 89d89db0  Cid 1b10.20ac  Teb: 7ffd7000 Win32Thread: bc16e680 READY
    THREAD 891f24a8  Cid 1e2c.20d0  Teb: 7ffda000 Win32Thread: bc1b9ea8 READY
    THREAD 89214db0  Cid 1e2c.24d4  Teb: 7ffd7000 Win32Thread: bc24ed48 READY
    THREAD 89a28020  Cid 1b10.21b4  Teb: 7ffa7000 Win32Thread: bc25b3b8 READY
    THREAD 891e03b0  Cid 1a98.05c4  Teb: 7ffdb000 Win32Thread: bc228bb0 READY
    THREAD 891b0020  Cid 1cd0.0144  Teb: 7ffde000 Win32Thread: bc205ea8 READY

All these threads have common stack trace (I show only a few threads here):

0: kd> !thread 89a92020 1f
THREAD 89a92020  Cid 11d8.27d8  Teb: 7ffd9000 Win32Thread: bc1e6860 RUNNING on processor 0
Not impersonating
DeviceMap                 e502b248
Owning Process            89e2a020       Image:         ProcessA.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      336581         Ticks: 0
Context Switch Count      61983                 LargeStack
UserTime                  00:00:00.156
KernelTime                00:00:00.281
Win32 Start Address ntdll!RtlpWorkerThread (0x7c839f2b)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init f3730000 Current f372f7e0 Base f3730000 Limit f372c000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
f3cc98e8 f6e21915 DriverA+0x1e4d
[...]
f3cc9ac0 f67f05dc nt!IofCallDriver+0x45
[...]
02e7ff44 7c83aa3b ntdll!RtlpWorkerCallout+0x71
02e7ff64 7c83aab2 ntdll!RtlpExecuteWorkerRequest+0x4f
02e7ff78 7c839f90 ntdll!RtlpApcCallout+0x11
02e7ffb8 77e6482f ntdll!RtlpWorkerThread+0x61
02e7ffec 00000000 kernel32!BaseThreadStart+0x34

0: kd> !thread 89275020 1f
THREAD 89275020  Cid 1cd0.2510  Teb: 7ffa9000 Win32Thread: bc343180 RUNNING on processor 1
Not impersonating
DeviceMap                 e1390978
Owning Process            89214708       Image:         ProcessB.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      336581         Ticks: 0
Context Switch Count      183429                 LargeStack
UserTime                  00:00:00.171
KernelTime                00:00:00.484
Win32 Start Address ntdll!RtlpWorkerThread (0x7c839f2b)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b9f6e000 Current b9f6d7e0 Base b9f6e000 Limit b9f6a000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
b9f6d87c f6e22d4b nt!KeWaitForSingleObject+0x497
b9f6d8e8 f6e21915 DriverA+0x1e4d
[...]
b9f6dac0 f67f05dc nt!IofCallDriver+0x45
[...]
0507ff44 7c83aa3b ntdll!RtlpWorkerCallout+0x71
0507ff64 7c83aab2 ntdll!RtlpExecuteWorkerRequest+0x4f
0507ff78 7c839f90 ntdll!RtlpApcCallout+0x11
0507ffb8 77e6482f ntdll!RtlpWorkerThread+0x61
0507ffec 00000000 kernel32!BaseThreadStart+0x34

0: kd> !thread 89d89db0 1f
THREAD 89d89db0  Cid 1b10.20ac  Teb: 7ffd7000 Win32Thread: bc16e680 READY
Not impersonating
DeviceMap                 e4e3a0b8
Owning Process            898cb020       Image:         ProcessC.exe
Attached Process          N/A            Image:         N/A
Wait Start TickCount      336581         Ticks: 0
Context Switch Count      159844                 LargeStack
UserTime                  00:00:00.234
KernelTime                00:00:00.484
Win32 Start Address ntdll!RtlpWorkerThread (0x7c839f2b)
Start Address kernel32!BaseThreadStartThunk (0x77e617ec)
Stack Init b9e1e000 Current b9e1d7e0 Base b9e1e000 Limit b9e1a000 Call 0
Priority 8 BasePriority 8 PriorityDecrement 0
ChildEBP RetAddr 
b9e1d7f8 80831292 nt!KiSwapContext+0x26
b9e1d818 80828c73 nt!KiExitDispatcher+0xf8
b9e1d830 80829c72 nt!KiAdjustQuantumThread+0x109
b9e1d87c f6e22d4b nt!KeWaitForSingleObject+0x536
b9e1d8e8 f6e21915 DriverA+0x1e4d
[...]
b9e1dac0 f67f05dc nt!IofCallDriver+0x45
[...]
014dff44 7c83aa3b ntdll!RtlpWorkerCallout+0x71
014dff64 7c83aab2 ntdll!RtlpExecuteWorkerRequest+0x4f
014dff78 7c839f90 ntdll!RtlpApcCallout+0x11
014dffb8 77e6482f ntdll!RtlpWorkerThread+0x61

They also share the same synchronization object:

0: kd> .thread 89275020
Implicit thread is now 89275020

0: kd> kv 1
ChildEBP RetAddr  Args to Child             
b9f6d87c f6e22d4b f6e25130 00000006 00000001 nt!KeWaitForSingleObject+0×497

0: kd> .thread 89d89db0
Implicit thread is now 89d89db0

0: kd> kv 4
ChildEBP RetAddr  Args to Child             
b9e1d7f8 80831292 f7737120 f7737b50 f7737a7c nt!KiSwapContext+0x26
b9e1d818 80828c73 00000000 89d89db0 89d89e58 nt!KiExitDispatcher+0xf8
b9e1d830 80829c72 f7737a7c 00000102 00000001 nt!KiAdjustQuantumThread+0x109
b9e1d87c f6e22d4b f6e25130 00000006 00000001 nt!KeWaitForSingleObject+0×536

0: kd> dt _DISPATCHER_HEADER f6e25130
ntdll!_DISPATCHER_HEADER
   +0×000 Type             : 0 ”
   +0×001 Absolute         : 0 ”
   +0×001 NpxIrql          : 0 ”
   +0×002 Size             : 0×4 ”
   +0×002 Hand             : 0×4 ”
   +0×003 Inserted         : 0 ”
   +0×003 DebugActive      : 0 ”
   +0×000 Lock             : 262144
   +0×004 SignalState      : 1
   +0×008 WaitListHead     : _LIST_ENTRY [ 0xf6e25138 - 0xf6e25138 ]

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Today we introduce an icon for Early Crash Dump pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Memory Dump Analysis Services (DumpAnalysis.com) organizes a free webinar

Date: 18th of August 2010
Time: 21:00 (BST) 16:00 (Eastern) 13:00 (Pacific)
Duration: 90 minutes

Topics include:

- User vs. kernel vs. physical (complete) memory space
- Challenges of complete memory dump analysis
- Common WinDbg commands
- Patterns
- Common mistakes
- Fiber bundles
- Hands-on exercise: a complete memory dump analysis
- A guide to DumpAnalysis.org case studies

Prerequisites: working knowledge of basic user process and kernel memory dump analysis or live debugging using WinDbg 

The webinar link will be posted before 18th of August on DumpAnalysis.com

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

It was reported that new remote sessions couldn’t be created. A complete memory dump stack trace collection log lists a special process that would not normally be present in a fully initialized session: userinit.exe. One of its threads is blocked waiting for an LPC response:

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: 

kd> !lpc message 0000acfd
Searching message acfd in threads …
    Server thread 89a80328 is working on message acfd                        
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> !thread 89a80328 1f
THREAD 89a80328  Cid 03c8.0644  Teb: 7ffd7000 Win32Thread: 00000000 WAIT: (WrLpcReply) UserMode Non-Alertable
    89a8051c  Semaphore Limit 0×1
Waiting 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 message 0000acfe
Searching message acfe in threads …
    Server thread 89b452e8 is working on message acfe
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 empty

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 89b452e8 1f
THREAD 89b452e8  Cid 03a8.0a28  Teb: 7ff94000 Win32Thread: 00000000 WAIT: (UserRequest) UserMode Non-Alertable
    89b466c0  SynchronizationEvent
IRP List:
    89b49008: (0006,01d8) Flags: 00000030  Mdl: 00000000
Not impersonating
DeviceMap                 e1003170
Owning Process            0       Image:         <Unknown>
Attached Process          89a20858       Image:         svchost.exe
Wait Start TickCount      1845699        Ticks: 1284370 (0:05:34:28.281)
Context Switch Count      5            
UserTime                  00:00:00.000
KernelTime                00:00:00.000
Win32 Start Address 0×0000acfe
LPC Server thread working on message Id acfe
Start Address kernel32!BaseThreadStartThunk (0×7c8106f9)
Stack Init b88dd000 Current b88dcca0 Base b88dd000 Limit b88da000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0 DecrementCount 0
Kernel stack not resident.
ChildEBP RetAddr 
b88dccb8 804e1bf2 nt!KiSwapContext+0×2f
b88dccc4 804e1c3e nt!KiSwapThread+0×8a
b88dccec 8056dff6 nt!KeWaitForSingleObject+0×1c2
b88dcd50 804dd99f nt!NtWaitForSingleObject+0×9a
b88dcd50 7c90e514 nt!KiFastCallEntry+0xfc (TrapFrame @ b88dcd64)
036ef714 7c90df5a ntdll!KiFastSystemCallRet
036ef718 7c91b24b ntdll!ZwWaitForSingleObject+0xc
036ef7a0 7c901046 ntdll!RtlpWaitForCriticalSection+0×132
036ef7a8 6648a33b ntdll!RtlEnterCriticalSection+0×46
036ef7b0 6648c2ed ipnathlp!FwLock+0xa
036ef808 6648c705 ipnathlp!FwDynPortAdd+0×1d
036ef8c4 77e799f4 ipnathlp!FwOpenDynamicFwPort+0×125
036ef8e8 77ef421a RPCRT4!Invoke+0×30
036efcf4 77ef46ee RPCRT4!NdrStubCall2+0×297
036efd10 77e794bd RPCRT4!NdrServerCall2+0×19
036efd44 77e79422 RPCRT4!DispatchToStubInC+0×38
036efd98 77e7934e RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0×113
036efdbc 77e7be64 RPCRT4!RPC_INTERFACE::DispatchToStub+0×84
036efdf8 77e7bcc1 RPCRT4!LRPC_SCALL::DealWithRequestMessage+0×2db
036efe1c 77e7bc05 RPCRT4!LRPC_ADDRESS::DealWithLRPCRequest+0×16d
036eff80 77e76caf RPCRT4!LRPC_ADDRESS::ReceiveLotsaCalls+0×310
036eff88 77e76ad1 RPCRT4!RecvLotsaCallsWrapper+0xd
036effa8 77e76c97 RPCRT4!BaseCachedThreadRoutine+0×79
036effb4 7c80b729 RPCRT4!ThreadStartRoutine+0×1a
036effec 00000000 kernel32!BaseThreadStart+0×37

In order to get a critical section wait chain starting from the above thread we need to set the process context, use !cs WinDbg command, then walk thread stack trace parameters:

kd> .process /r /p 89a20858
Implicit process is now 89a20858

kd> !cs -l -o -s
-----------------------------------------
DebugInfo          = 0x7c97e500
Critical section   = 0x7c980600 (ntdll!FastPebLock+0x0)
LOCKED
LockCount          = 0x10
OwningThread       = 0x000004a8
RecursionCount     = 0x1
LockSemaphore      = 0xC20
SpinCount          = 0x00000000
OwningThread       = .thread 89cd9c10
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 0x000d7f08
Critical section   = 0x01e700d4 (+0x1E700D4)
LOCKED
LockCount          = 0x0
OwningThread       = 0x000001b8
RecursionCount     = 0x1
LockSemaphore      = 0x0
SpinCount          = 0x00000000
OwningThread       = .thread 89b3b348
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 0x000d96e0
Critical section   = 0x767e406c (w32time!g_state+0x24)
LOCKED
LockCount          = 0x3
OwningThread       = 0x00000f70
RecursionCount     = 0x2
LockSemaphore      = 0x7FC
SpinCount          = 0x00000000
OwningThread       = .thread 89a6a268
ntdll!RtlpStackTraceDataBase is NULL. Probably the stack traces are not enabled.
-----------------------------------------
DebugInfo          = 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> .thread 89b452e8
Implicit 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 6648a33b 664a3fe0 6648c2ed 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
OwningThread = .thread 898aa600
[…]

kd> .thread 898aa600
Implicit thread is now 898aa600

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
OwningThread = .thread 89cd9c10
[…]

kd> .thread 89cd9c10
Implicit 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 7731889e 0078894a 00000000 00000001 kernel32!SetCurrentDirectoryW+0×2b
00cffb84 7730ffbb 00788450 00788b38 00cffbe0 schedsvc!CSchedWorker::RunNTJob+0×221
00cffe34 7730c03a 01ea9108 8ed032d4 00787df8 schedsvc!CSchedWorker::RunJobs+0×304
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 90 0078894a
0078894a  “\\SERVER_B\Share_X$\Folder_Q”

The thread above is blocked trying to set the current directory residing on another server SERVER_B. Its waiting time 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 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: (0006,0094) Flags: 00000884  Mdl: 00000000
Not impersonating
DeviceMap                 e1003170
Owning Process            0       Image:         <Unknown>
Attached Process          8a04d830       Image:         System
Wait Start TickCount      4392           Ticks: 3125677 (0:13:33:58.703)
Context Switch Count      1890            
UserTime                  00:00:00.000
KernelTime                00:00:00.109
Start Address nt!ExpWorkerThread (0×804e2311)
Stack Init f78b3000 Current f78b27c0 Base f78b3000 Limit f78b0000 Call 0
Priority 13 BasePriority 13 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr 
f78b27d8 804e1bf2 nt!KiSwapContext+0×2f
f78b27e4 804e1c3e nt!KiSwapThread+0×8a
f78b280c f7836328 nt!KeWaitForSingleObject+0×1c2
f78b282c f783622a Mup!MupiIssueQueryRequest+0×2f
f78b2854 f7836069 Mup!MupiResolvePrefix+0×11b
f78b2898 f7835829 Mup!CreateRedirectedFile+0×35d
f78b28f4 804e13eb Mup!MupCreate+0×1cb
f78b2904 805794b6 nt!IopfCallDriver+0×31
f78b29e4 8056d03b nt!IopParseDevice+0xa12
f78b2a5c 805701e7 nt!ObpLookupObjectName+0×53c
f78b2ab0 80579b12 nt!ObOpenObjectByName+0xea
f78b2b2c 80579be1 nt!IopCreateFile+0×407
f78b2b88 80573e2b nt!IoCreateFile+0×8e
f78b2bc8 804dd99f nt!NtCreateFile+0×30
f78b2bc8 804e3597 nt!KiFastCallEntry+0xfc (TrapFrame @ f78b2bfc)
f78b2c6c f78368ca nt!ZwCreateFile+0×11
f78b2cd4 f78306fa Mup!DfsCreateIpcConnection+0×9c
f78b2d60 f7830aae Mup!_PktGetReferral+0×11d
f78b2d7c 804e23d5 Mup!PktWorkInSystemContext+0×4c
f78b2dac 80576316 nt!ExpWorkerThread+0xef
f78b2ddc 804ec6f9 nt!PspSystemThreadStartup+0×34
00000000 00000000 nt!KiThreadStartup+0×16

It has an IRP having file object pointing the same server SERVER_B:

kd> !irp 89901348
Irp 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   
        \FileSystem\Mup
   Args: f78b2930 03000020 00070080 00000000
kd> !fileobj 899ab170

\SERVER_B\IPC$

Device Object: 0x89f46ee8   \FileSystem\Mup
Vpb is NULL

Flags:  0x2
 Synchronous IO

CurrentByteOffset: 0

So it looks like we have an instance of Coupled Machines pattern. 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 using !irpfind command. Counting IRPs we find the most of them are directed towards HTTP, Tcpip and AFD drivers:

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Today we introduce an icon for Local Buffer Overflow pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Sometimes we have threads that wait for a response from another machine (for example, via RPC) and for most of the time Coupled Processes pattern covers that if we assume that processes in that pattern are not restricted to same machine. However, sometimes we have threads that provide hints for dependency on an another machine through their data and that could also involve additional threads from different processes to accomplish the task. Here we have a need for another pattern that I call Coupled Machines. For example, the following thread on a computer SERVER_A is trying to set the current working directory that resides on a computer SERVER_B:

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
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 7731889e 0078894a 00000000 00000001 kernel32!SetCurrentDirectoryW+0×2b
00cffb84 7730ffbb 00788450 00788b38 00cffbe0 schedsvc!CSchedWorker::RunNTJob+0×221
00cffe34 7730c03a 01ea9108 8ed032d4 00787df8 schedsvc!CSchedWorker::RunJobs+0×304
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 90 0078894a
0078894a  “\\SERVER_B\Share_X$\Folder_Q”

The next post will discuss a pattern cooperation case study including this pattern in more detail.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

I knew it was my destiny!

kd> !analyze -vostokov

[...]

MANUALLY_INITIATED_CRASH (e2)
The user manually initiated this crash dump.
Arguments:
Arg1: 00000000
Arg2: 00000000
Arg3: 00000000
Arg4: 00000000

Debugging Details:
------------------

[...]

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

This is a specialization of Blocked Thread pattern where a thread is waiting for a hardware I/O response. For example, a frozen system initialization thread is waiting for a response from one of ACPI general register ports:

kd> kL 100
ChildEBP RetAddr 
f7a010bc f74c5a57 hal!READ_PORT_UCHAR+0×7
f7a010c8 f74c5ba4 ACPI!DefReadAcpiRegister+0xa1
f7a010d8 f74b4d78 ACPI!ACPIReadGpeStatusRegister+0×10
f7a010e4 f74b6334 ACPI!ACPIGpeIsEvent+0×14
f7a01100 8054157d ACPI!ACPIInterruptServiceRoutine+0×16
f7a01100 806d687d nt!KiInterruptDispatch+0×3d
f7a01194 804f9487 hal!HalEnableSystemInterrupt+0×79
f7a011d8 8056aac4 nt!KeConnectInterrupt+0×95
f7a011fc f74c987c nt!IoConnectInterrupt+0xf2
f7a0123c f74d13f0 ACPI!OSInterruptVector+0×76
f7a01250 f74b5781 ACPI!ACPIInitialize+0×154
f7a01284 f74cf824 ACPI!ACPIInitStartACPI+0×71
f7a012b0 f74b1e12 ACPI!ACPIRootIrpStartDevice+0xc0
f7a012e0 804ee129 ACPI!ACPIDispatchIrp+0×15a
f7a012f0 8058803b nt!IopfCallDriver+0×31
f7a0131c 805880b9 nt!IopSynchronousCall+0xb7
f7a01360 804f515c nt!IopStartDevice+0×4d
f7a0137c 80587769 nt!PipProcessStartPhase1+0×4e
f7a015d4 804f5823 nt!PipProcessDevNodeTree+0×1db
f7a01618 804f5ab3 nt!PipDeviceActionWorker+0xa3
f7a01630 8068afc6 nt!PipRequestDeviceAction+0×107
f7a01694 80687e48 nt!IopInitializeBootDrivers+0×376
f7a0183c 806862dd nt!IoInitSystem+0×712
f7a01dac 805c61e0 nt!Phase1Initialization+0×9b5
f7a01ddc 80541e02 nt!PspSystemThreadStartup+0×34
00000000 00000000 nt!KiThreadStartup+0×16

kd> r
eax=00000000 ebx=00000000 ecx=00000002 edx=0000100c esi=00000000 edi=867d8008
eip=806d664b esp=f7a010c0 ebp=f7a010c8 iopl=1         nv up ei pl zr na pe nc
cs=0008  ss=0010  ds=0023  es=0023  fs=0030  gs=0000             efl=00001246
hal!READ_PORT_UCHAR+0x7:
806d664b c20400          ret     4 

kd> ub eip
hal!KdRestore+0x9:
806d663f cc              int     3
806d6640 cc              int     3
806d6641 cc              int     3
806d6642 cc              int     3
806d6643 cc              int     3
hal!READ_PORT_UCHAR:
806d6644 33c0            xor     eax,eax
806d6646 8b542404        mov     edx,dword ptr [esp+4]
806d664a ec              in      al,dx

kd> version
[...]
System Uptime: 0 days 0:03:42.140
[...]

kd> !thread
THREAD 867c63e8  Cid 0004.0008  Teb: 00000000 Win32Thread: 00000000 RUNNING on processor 0
IRP List:
    867df008: (0006,0190) Flags: 00000000  Mdl: 00000000
Not impersonating
DeviceMap                 e1005460
Owning Process            0       Image:         <Unknown>
Attached Process          867c6660       Image:         System
Wait Start TickCount      39             Ticks: 1839 (0:00:00:18.416)
Context Switch Count      4            
UserTime                  00:00:00.000
KernelTime                00:00:00.911
Start Address nt!Phase1Initialization (0x80685928)
Stack Init f7a02000 Current f7a014a4 Base f7a02000 Limit f79ff000 Call 0
Priority 31 BasePriority 8 PriorityDecrement 0 DecrementCount 0
[...]

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Today we introduce an icon for IRP Distribution Anomaly pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Here we model Message Hooks pattern using MessageHistory tool. It uses window message hooking mechanism to intercept window messages. Download the tool and run either MessageHistory.exe or MessageHistory64.exe and push its Start button. Whenever any process becomes active after that either mhhooks.dll or mhhooks64.dll gets injected into the process virtual address space. Then we run WinDbg x86 or WinDbg x64, run notepad.exe and attach the debugger noninvasively to it:

*** wait with pending attach
Symbol search path is: srv*
Executable search path is:
WARNING: Process 2932 is not attached as a debuggee
         The process can be examined but debug events will not be received
(b74.f44): Wake debugger - code 80000007 (first chance)
USER32!NtUserGetMessage+0xa:
00000000`76f9c92a c3              ret

0:000> .symfix

0:000> .reload

0:000> k
Child-SP          RetAddr           Call Site
00000000`0028f908 00000000`76f9c95e USER32!NtUserGetMessage+0xa
00000000`0028f910 00000000`ff511064 USER32!GetMessageW+0x34
00000000`0028f940 00000000`ff51133c notepad!WinMain+0x182
00000000`0028f9c0 00000000`76e7f56d notepad!DisplayNonGenuineDlgWorker+0x2da
00000000`0028fa80 00000000`770b3281 kernel32!BaseThreadInitThunk+0xd
00000000`0028fab0 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

If we don’t select “Noninvasive” in “Attach to Process” dialog box we need to switch from the debugger injected thread to our main notepad application thread:

0:001> .symfix

0:001> .reload

0:001> k
Child-SP          RetAddr           Call Site
00000000`024bfe18 00000000`77178638 ntdll!DbgBreakPoint
00000000`024bfe20 00000000`76e7f56d ntdll!DbgUiRemoteBreakin+0x38
00000000`024bfe50 00000000`770b3281 kernel32!BaseThreadInitThunk+0xd
00000000`024bfe80 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

0:001> ~0s
USER32!NtUserGetMessage+0xa:
00000000`76f9c92a c3              ret

0:000> k
Child-SP          RetAddr           Call Site
00000000`000af9e8 00000000`76f9c95e USER32!NtUserGetMessage+0xa
00000000`000af9f0 00000000`ff511064 USER32!GetMessageW+0x34
00000000`000afa20 00000000`ff51133c notepad!WinMain+0x182
00000000`000afaa0 00000000`76e7f56d notepad!DisplayNonGenuineDlgWorker+0x2da
00000000`000afb60 00000000`770b3281 kernel32!BaseThreadInitThunk+0xd
00000000`000afb90 00000000`00000000 ntdll!RtlUserThreadStart+0x1d

We then inspect the raw stack data to see any execution residue and find a few related function calls:

0:000> !teb
TEB at 000007fffffdd000
    ExceptionList:        0000000000000000
    StackBase:            0000000000290000
    StackLimit:           000000000027f000
    SubSystemTib:         0000000000000000
    FiberData:            0000000000001e00
    ArbitraryUserPointer: 0000000000000000
    Self:                 000007fffffdd000
    EnvironmentPointer:   0000000000000000
    ClientId:             0000000000000b74 . 0000000000000f44
    RpcHandle:            0000000000000000
    Tls Storage:          000007fffffdd058
    PEB Address:          000007fffffdf000
    LastErrorValue:       0
    LastStatusValue:      c0000034
    Count Owned Locks:    0
    HardErrorMode:        0

0:000> dps 000000000027f000 0000000000290000
[...]
00000000`0028e388  00000000`008bd8e0
00000000`0028e390  00000000`00000000
00000000`0028e398  00000000`00000001
00000000`0028e3a0  00000000`00000282
00000000`0028e3a8  00000000`76f966b2 USER32!SendMessageToUI+0x6a
00000000`0028e3b0  00000000`001406b0
00000000`0028e3b8  00000000`004000f8
00000000`0028e3c0  00000000`00000001
00000000`0028e3c8  00000001`800014b8 mhhooks64!CallWndProc+0×2d8
00000000`0028e3d0  00000000`00000000
00000000`0028e3d8  00000000`002f0664
00000000`0028e3e0  00000000`00000001
00000000`0028e3e8  00000000`76f96a72 USER32!ImeNotifyHandler+0xb4
00000000`0028e3f0  00000000`00000000
00000000`0028e3f8  00000000`004000f8
00000000`0028e400  00000000`00000001
00000000`0028e408  000007fe`ff1213b4 IMM32!CtfImmDispatchDefImeMessage+0×60
00000000`0028e410  00000000`00000000
00000000`0028e418  00000000`002f0664
00000000`0028e420  00000000`00000000
00000000`0028e428  00000000`002f0664
00000000`0028e430  00000000`008bd8e0
00000000`0028e438  00000000`76f96a06 USER32!ImeWndProcWorker+0×3af
00000000`0028e440  00000000`00000282
00000000`0028e448  00000000`00000000
00000000`0028e450  00000000`00000001
00000000`0028e458  00000000`004000f8
00000000`0028e460  00000000`00000000
00000000`0028e468  00000000`00000001
00000000`0028e470  00000000`00000000
00000000`0028e478  00000000`00000000
00000000`0028e480  00000000`00000000
00000000`0028e488  00000000`76f9a078 USER32!_fnDWORD+0×44
00000000`0028e490  00000000`00000000
[…]
00000000`0028f770  00000000`001406b0
00000000`0028f778  000007ff`fffdd000
00000000`0028f780  00000000`0028f8c8
00000000`0028f788  00000000`008bd8e0
00000000`0028f790  00000000`00000018
00000000`0028f798  00000000`76f885a0 USER32!DispatchHookW+0×2c
00000000`0028f7a0  000022b2`00000000
00000000`0028f7a8  00000000`00000001
00000000`0028f7b0  000007fe`ff2d2560 MSCTF!IMCLock::`vftable’
00000000`0028f7b8  00000000`00407c50
00000000`0028f7c0  00000000`000c0e51
00000000`0028f7c8  00000000`00000000
00000000`0028f7d0  00000000`00000000
00000000`0028f7d8  00000000`00000113
00000000`0028f7e0  00000000`00000113
00000000`0028f7e8  00000000`00000001
00000000`0028f7f0  00000000`00000000
00000000`0028f7f8  00000000`76f9c3df USER32!UserCallWinProcCheckWow+0×1cb
00000000`0028f800  00000000`ff510000 notepad!CFileDialogEvents_QueryInterface <PERF> (notepad+0×0)
00000000`0028f808  00000000`00000000
00000000`0028f810  00000000`00000000
00000000`0028f818  00000000`00000000
00000000`0028f820  00000000`00000000
00000000`0028f828  00000000`00000038
00000000`0028f830  00000000`00000000
00000000`0028f838  00000000`00000000
00000000`0028f840  00000000`00000000
00000000`0028f848  00000000`770cfdf5 ntdll!KiUserCallbackDispatcherContinue
00000000`0028f850  00000000`00000048
00000000`0028f858  00000000`00000001
00000000`0028f860  00000000`00000000
[…]

We also see a 3rd-party module in proximity having “hook” in its module name: mhhooks64. We disassemble its address to see yet another message hooking evidence:

0:000> .asm no_code_bytes
Assembly options: no_code_bytes

0:000> ub 00000001`800014b8
mhhooks64!CallWndProc+0×2ae:
00000001`8000148e imul    rcx,rcx,30h
00000001`80001492 lea     rdx,[mhhooks64!sendMessages (00000001`80021030)]
00000001`80001499 mov     dword ptr [rdx+rcx+28h],eax
00000001`8000149d mov     r9,qword ptr [rsp+50h]
00000001`800014a2 mov     r8,qword ptr [rsp+48h]
00000001`800014a7 mov     edx,dword ptr [rsp+40h]
00000001`800014ab mov     rcx,qword ptr [mhhooks64!hCallWndHook (00000001`80021028)]
00000001`800014b2 call    qword ptr [mhhooks64!_imp_CallNextHookEx (00000001`80017280)]

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Our future sponsor has been registered in Ireland and has its own independent website and logo: DumpAnalysis.com

More information will be available later this month.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Being a software engineer, the author penetrated a software technical support department of a major software company rising to a management position. There he started collecting various management bits and tips promising everyone to write a management book. After moving back to engineering he became a director of several software research, education, publishing and software behavior analysis consultancy institutions including a museum. This book is an anthology of selected and edited blog posts from his Management Bits and Tips blog.

What this book has to do with the crash dump analysis then? Considering metaphorically an organization as a software machine, teams as processes and individuals as threads the author had applied his unique knowledge of software crashes and hangs to organizational project failures.

• Title: Management Bits: An Anthology from Reductionist Manager
• Author: Dmitry Vostokov
• Publisher: OpenTask (September 2010)
• Language: English
• Product Dimensions: 19.8 x 12.9
• Paperback: 100 pages
• ISBN-13: 978-1906717131

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Today we introduce an icon for Historical Information pattern:

B/W

Color

The icon motivated the following debugging slang: BCE 

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

Today we introduce an icon for Busy System pattern:

B/W

Color

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

The process was reported consuming CPU and its user memory dump was saved. The main thread was a spiking thread indeed:

0:000> !runaway f
 User Mode Time
  Thread       Time
   0:4b8       0 days 0:00:16.078
   2:fec       0 days 0:00:00.000
   1:630       0 days 0:00:00.000
 Kernel Mode Time
  Thread       Time
   0:4b8       0 days 0:00:44.218
   2: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+0xc
0012fcec 7e431923 DllA!ThreadKeyboardProc+0×77
0012fd20 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+0xc
0012fdfc 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 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×1000
[…]
0012fb9c  00000003
0012fba0  001d0001
0012fba4  0012fbc8
0012fba8  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 11201000 (DllBHooks+0×1000) looks like coincidental  symbolic information and it is not a meaningful code indeed: 

0:000> ub 11201000
DllBHooks+0xff0:
11200ff0 0000            add     byte ptr [eax],al
11200ff2 0000            add     byte ptr [eax],al
11200ff4 0000            add     byte ptr [eax],al
11200ff6 0000            add     byte ptr [eax],al
11200ff8 0000            add     byte ptr [eax],al
11200ffa 0000            add     byte ptr [eax],al
11200ffc 0000            add     byte ptr [eax],al
11200ffe 0000            add     byte ptr [eax],al

However further module references look valid:

0:000> ub 112013c0
DllBHooks+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> u 112013c0
DllBHooks+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> ub 1120146b
DllBHooks+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> u 1120146b
DllBHooks+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 here and both module versions 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  0012a24c
0012a238  00913ae6 DllCHook!DllUnregisterServer+0×1b06
0012a23c  00000020
0012a240  00000000
0012a244  00205558
0012a248  00205558
0012a24c  0012a25c
0012a250  00913d73 DllCHook!DllUnregisterServer+0×1d93
0012a254  00205558
0012a258  00000038
[…]

0:000> ub 00913ae6
DllCHook!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> ub 00913d73
DllCHook!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:\mss\kernel32.dll\49C4F482f6000\kernel32.dll
No range specified

Scanning section:    .text
Size: 537065
Range to scan: 7c801000-7c8841e9
    7c801af5-7c801af9  5 bytes - kernel32!LoadLibraryExW
 [ 6a 34 68 f8 e0:e9 06 e5 58 03 ]
[…]

0:000> u 7c801af5
kernel32!LoadLibraryExW:
7c801af5 e906e55803 jmp 7fd90000
7c801afa 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> u 7fd90000
7fd90000 e93b5eb880 jmp DllCHook!DllUnregisterServer+0×3e60 (00915e40)
7fd90005 6a34 push 34h
7fd90007 68f8e0807c push offset kernel32!`string’+0xc (7c80e0f8)
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:\mss\user32.dll\4802A11B91000\user32.dll
No range specified

Scanning section:    .text
Size: 389763
Range to scan: 7e411000-7e470283
    7e45a275-7e45a279  5 bytes - user32!ExitWindowsEx
 [ 8b ff 55 8b ec:e9 86 5d 87 01 ]
[…]

0:000> u 7e45a275
user32!ExitWindowsEx:
7e45a275 e9865d8701 jmp 7fcd0000
7e45a27a 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> u 7fcd0000
7fcd0000 e9cba0c580 jmp DllCHook+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:\mss\advapi32.dll\49901D489b000\advapi32.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 77e34ce5
advapi32!InitiateSystemShutdownExW:
77e34ce5 e916b3e807      jmp     7fcc0000
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  016000ca
00129f14  00aa0004 DllDHook+0×3e414
00129f18  000100ca
00129f1c  00aa00ca DllDHook+0×3e4da
00129f20  00cf0001
[…]

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 00aa0004
DllDHook+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 00aa00ca
DllDHook+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 00aa00ca
DllDHook+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],al

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

The rules of the previously announced competition have been changed. You can now also nominate someone by sending a debugging story link. Please send your story or a nomination using this page: http://www.dumpanalysis.org/contact or dmitry dot vostokov at dumpanalysis dot org (if a story is with pictures).

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -

In addition to hooking functions via code patching there is another function pre- and post-processing done via windows message hooking mechanism that I call Message Hooks pattern to differentiate it from Hooked Functions pattern. In some cases message hooking become sources of aberrant software behaviour including spikes, hangs and crashes. We can identify such residue looking at the problem thread 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
[...]
0012fc78  7e4318d1 user32!DispatchHookA
0012fc7c  0012fcb8
0012fc80  7472467f
0012fc84  7e43e1ad user32!NtUserCallNextHookEx+0xc
0012fc88  7e43e18a user32!CallNextHookEx+0×6f
0012fc8c  00000003
0012fc90  00000011
0012fc94  001d0001
0012fc98  00000001
0012fc9c  00000003
0012fca0  00000000
0012fca4  001d0001
0012fca8  0012fcec
0012fcac  74730844DllA!ThreadKeyboardProc+0×77
0012fcb0  001e04f7
0012fcb4  00000003
0012fcb8  00000011
0012fcbc  001d0001
0012fcc0  00000003
0012fcc4  00020003
0012fcc8  001d0001
0012fccc  00000000
0012fcd0  001e04f7
0012fcd4  0012fcc0
0012fcd8  00000000
0012fcdc  0012fd4c
0012fce0  7475f1a6
0012fce4  74730850
0012fce8  ffffffff
0012fcec  0012fd20
0012fcf0  7e431923 user32!DispatchHookA+0×101
0012fcf4  00000003
0012fcf8  00000011
0012fcfc  001d0001
0012fd00  00000000
0012fd04  0012fe94
0012fd08  00000102
0012fd0c  7ffde000
0012fd10  00000000
0012fd14  00000001
0012fd18  00000003
0012fd1c  7e42b326 user32!CallHookWithSEH+0×44
0012fd20  0012fd5c
0012fd24  7e42b317 user32!CallHookWithSEH+0×21
0012fd28  00020003
0012fd2c  00000011
0012fd30  001d0001
0012fd34  747307c3
0012fd38  00000000
0012fd3c  0012fe94
0012fd40  00000102
[…]

0:000> ub 74730844
DllA!ThreadKeyboardProc+0×5e:
7473082b jne     DllA!ThreadKeyboardProc+0×77 (74730844)
7473082d cmp     dword ptr [ebp-1Ch],esi
74730830 je      DllA!ThreadKeyboardProc+0×77 (74730844)
74730832 push    dword ptr [ebp+10h]
74730835 push    dword ptr [ebp+0Ch]
74730838 push    dword ptr [ebp+8]
7473083b push    dword ptr [ebp-1Ch]
7473083e call    dword ptr [DllA!_imp__CallNextHookEx (74721248)]

Sometimes we can even reconstruct stack trace fragments that show message hooking call stack. When threads are spiking or blocked in a message hook procedure we can see a hooking module too:

0:000> kL
ChildEBP RetAddr 
0012fc80 7e43e1ad ntdll!KiFastSystemCallRet
0012fca8 74730844 user32!NtUserCallNextHookEx+0xc
0012fcec 7e431923 DllA!ThreadKeyboardProc+0×77
0012fd20 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+0xc
0012fdfc 747528ee user32!PeekMessageW+0xbc
[…]
0012fff0 00000000 kernel32!BaseProcessStart+0×23

The next 2 posts will feature a case study and a modeling example.

- Dmitry Vostokov @ DumpAnalysis.org + TraceAnalysis.org -