Stack trace collection, special process, LPC and critical section wait chains, blocked thread, coupled machines, thread waiting time and IRP distribution anomaly: pattern cooperation

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 -

One Response to “Stack trace collection, special process, LPC and critical section wait chains, blocked thread, coupled machines, thread waiting time and IRP distribution anomaly: pattern cooperation”

  1. Marc Sherman Says:

    Excellent article, thank you.

Leave a Reply