Debugging a Hang at “Applying Computer Settings”

Debugging a Hang at “Applying Computer Settings”

  • Comments 2

Hi Everyone - My name is Aman. I'm an Escalation Engineer on the Microsoft GES (Global Escalation Services) team. We recently came across a critical situation where-in the following issues were reported by the customer:

 

1.       DC login hangs at “applying computer settings” regardless of RDP or local console.

2.       Connecting to the server using computer management console fails with "RPC Server is too busy to complete the operation"

3.       Server responds to ping in the problem state but cannot be accessed through ports 445/139.

4.       Reboot will fix the issue for a couple of days but the problem will return again.

 

The case had already been troubleshot many times in the past without any results. So, to get to the root cause, it was escalated to GES and we took a full memory dump. In this blog I want to show you how to navigate between processes via LPC messages to drill down to root cause.

 

Disclaimer – Not every hang at “Applying Computer Settings” requires a debug. Standard troubleshooting typically resolves this type of thing. 

 

Now let's have a look at the Complete Memory Dump (note: a Kernel dump is not enough). Since the console session hangs at "applying computer settings", the target starting point of my debug will be the process called winlogon. Winlogon.exe is the executable responsible for initiating the logon process for users. If the console session is hung at "applying computer settings", winlogon has to have an explanation as to why it's unable to process the user logon successfully.

 

So, let’s get the address of the winlogon process:

 

kd> ! process 0 0 winlogon.exe

PROCESS 85c63830  SessionId: 0  Cid: 01a4    Peb: 7ffdf000  ParentCid: 0158

    DirBase: 39f6a000  ObjectTable: e13d7928  HandleCount: 535.

    Image: winlogon.exe

 

PROCESS 84f02020  SessionId: 1  Cid: 0344    Peb: 7ffdf000  ParentCid: 0158

    DirBase: 2d675000  ObjectTable: e35abc78  HandleCount: 313.

    Image: winlogon.exe

 

 

So, why we have two winlogon processes executing? Simple, the customer tried to log into the domain controller via RDP and local console. Both methods resulted in the hang, hence creating two winlogon sessions. Let’s check the first one and see what's happening in there. I picked up only questionable threads for the sake of this session.

 

 

kd> .process /p /r 85c63830

Implicit process is now 85c63830

Loading User Symbols

................................................................

.........

kd> !process 85c63830 7

PROCESS 85c63830  SessionId: 0  Cid: 01a4    Peb: 7ffdf000  ParentCid: 0158

    DirBase: 39f6a000  ObjectTable: e13d7928  HandleCount: 535.

    Image: winlogon.exe

    VadRoot 85c599c8 Vads 157 Clone 0 Private 1266. Modified 1081. Locked 0.

    DeviceMap e1001150

    Token                             e1743a38

    ElapsedTime                       15:50:33.974

    UserTime                          00:00:00.187

    KernelTime                        00:00:02.125

    QuotaPoolUsage[PagedPool]         53444

    QuotaPoolUsage[NonPagedPool]      63864

    Working Set Sizes (now,min,max)  (1161, 50, 345) (4644KB, 200KB, 1380KB)

    PeakWorkingSetSize                2834

    VirtualSize                       49 Mb

    PeakVirtualSize                   52 Mb

    PageFaultCount                    10861

    MemoryPriority                    BACKGROUND

    BasePriority                      13

    CommitCharge                      1979

 

 

 

        THREAD 847318d0  Cid 01a4.58e4  Teb: 7ffdd000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

            84731abc  Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 00213bd7:

        Current LPC port e125d4e0

        Not impersonating

        DeviceMap                 e1001150

        Owning Process            85c63830       Image:         winlogon.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3650157        Ticks: 525 (0:00:00:08.203)

        Context Switch Count      2            

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

        Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init f5c98000 Current f5c97c20 Base f5c98000 Limit f5c95000 Call 0

        Priority 14 BasePriority 13 PriorityDecrement 0

        ChildEBP RetAddr  Args to Child             

        f5c97c38 808202b6 847318d0 84731978 00000000 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

        f5c97c50 8081fb6e 84731abc 84731a90 847318d0 nt!KiSwapThread+0x83 (FPO: [0,2,0])

        f5c97c94 80915355 84731abc 00000011 f5c97d01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

        f5c97d50 8082350b 0000080c 00087ba0 00087ba0 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

        f5c97d50 7c8285ec 0000080c 00087ba0 00087ba0 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ f5c97d64)

        0075fab0 7c82787b 77c80a6e 0000080c 00087ba0 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

        0075fab4 77c80a6e 0000080c 00087ba0 00087ba0 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

        0075fb00 77c7fcf0 0075fb3c 0075fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

        0075fb0c 77c80673 0075fb3c 75822c38 0075ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

        0075fb20 77ce315a 0075fb68 00087c18 001125a8 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

        0075ff08 75822b74 75822c38 75822b8a 0075ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

        0075ff20 75822b4f 00b81460 0075ff3c 0075ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

        0075ff30 75824e7a 0075ff3c 00100000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

        0075ff60 0103917b 0075ff78 00000000 00000000 WlNotify!SensStopScreenSaverEvent+0x58 (FPO: [1,9,0])

        0075ffb8 77e64829 001125a8 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

        0075ffec 00000000 010390b7 001125a8 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

We found somewhere around 15 threads in the process above. Only the above thread looked suspicious since it has issued a LPC call and hasn't received a reply yet. Before we investigate further, let’s check the other winlogon process and find out about the threads in there as well....just in case if there is a commonality or not amongst both the processes...

 

Note the long tick counts in these threads!

 

 

kd> .process /p /r 84f02020

Implicit process is now 84f02020

Loading User Symbols

................................................................

................

kd> !process 84f02020 7

PROCESS 84f02020  SessionId: 1  Cid: 0344    Peb: 7ffdf000  ParentCid: 0158

    DirBase: 2d675000  ObjectTable: e35abc78  HandleCount: 313.

    Image: winlogon.exe

    VadRoot 85e86dd0 Vads 184 Clone 0 Private 656. Modified 722. Locked 0.

    DeviceMap e1001150

    Token                             e3a09030

    ElapsedTime                       04:51:33.657

    UserTime                          00:00:00.140

    KernelTime                        00:00:00.796

    QuotaPoolUsage[PagedPool]         49464

    QuotaPoolUsage[NonPagedPool]      10080

    Working Set Sizes (now,min,max)  (1099, 50, 345) (4396KB, 200KB, 1380KB)

    PeakWorkingSetSize                2193

    VirtualSize                       48 Mb

    PeakVirtualSize                   50 Mb

    PageFaultCount                    4312

    MemoryPriority                    BACKGROUND

    BasePriority                      13

    CommitCharge                      1329

 

        THREAD 847a93f0  Cid 0344.4ab0  Teb: 7ffd7000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

            847a95dc  Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 0020b318:

        Current LPC port e3761290

        Impersonation token:  e3a92250 (Level Impersonation)

        DeviceMap                 e1bca430

        Owning Process            84f02020       Image:         winlogon.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3500419        Ticks: 150263 (0:00:39:07.859)

        Context Switch Count      1            

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

        Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init b9d00000 Current b9cffc20 Base b9d00000 Limit b9cfd000 Call 0

        Priority 13 BasePriority 13 PriorityDecrement 0

        Kernel stack not resident.

        ChildEBP RetAddr  Args to Child             

        b9cffc38 808202b6 847a93f0 847a9498 00000310 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

        b9cffc50 8081fb6e 847a95dc 847a95b0 847a93f0 nt!KiSwapThread+0x83 (FPO: [0,2,0])

        b9cffc94 80915355 847a95dc 00000011 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

        b9cffd50 8082350b 00000364 000b9760 000b9760 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

        b9cffd50 7c8285ec 00000364 000b9760 000b9760 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9cffd64)

        0087fab0 7c82787b 77c80a6e 00000364 000b9760 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

        0087fab4 77c80a6e 00000364 000b9760 000b9760 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

        0087fb00 77c7fcf0 0087fb3c 0087fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

        0087fb0c 77c80673 0087fb3c 75822c38 0087ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

        0087fb20 77ce315a 0087fb68 000b9820 000a8bd8 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

        0087ff08 75822b74 75822c38 75822b8a 0087ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

        0087ff20 75822b4f 000c1e30 0087ff3c 0087ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

        0087ff30 75824e19 0087ff3c 00080000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

        0087ff60 0103917b 0087ff78 00000000 00000000 WlNotify!SensStartScreenSaverEvent+0x58 (FPO: [1,9,0])

        0087ffb8 77e64829 000a8bd8 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

        0087ffec 00000000 010390b7 000a8bd8 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

        THREAD 847ad8d0  Cid 0344.4c7c  Teb: 7ffac000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

            847adabc  Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 0020bf59:

        Current LPC port e3761290

        Impersonation token:  e39b1358 (Level Impersonation)

        DeviceMap                 e1bca430

        Owning Process            84f02020       Image:         winlogon.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3513766        Ticks: 136916 (0:00:35:39.312)

        Context Switch Count      1            

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

        Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init b9dc0000 Current b9dbfc20 Base b9dc0000 Limit b9dbd000 Call 0

        Priority 13 BasePriority 13 PriorityDecrement 0

        Kernel stack not resident.

        ChildEBP RetAddr  Args to Child             

        b9dbfc38 808202b6 847ad8d0 847ad978 00000341 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

        b9dbfc50 8081fb6e 847adabc 847ada90 847ad8d0 nt!KiSwapThread+0x83 (FPO: [0,2,0])

        b9dbfc94 80915355 847adabc 00000011 b9dbfd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

        b9dbfd50 8082350b 00000364 000ba340 000ba340 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

        b9dbfd50 7c8285ec 00000364 000ba340 000ba340 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9dbfd64)

        00b7fab0 7c82787b 77c80a6e 00000364 000ba340 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

        00b7fab4 77c80a6e 00000364 000ba340 000ba340 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

        00b7fb00 77c7fcf0 00b7fb3c 00b7fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

        00b7fb0c 77c80673 00b7fb3c 75822c38 00b7ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

        00b7fb20 77ce315a 00b7fb68 000ba400 000a8b80 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

        00b7ff08 75822b74 75822c38 75822b8a 00b7ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

        00b7ff20 75822b4f 000c1e30 00b7ff3c 00b7ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

        00b7ff30 75824e7a 00b7ff3c 00100000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

        00b7ff60 0103917b 00b7ff78 00000000 00000000 WlNotify!SensStopScreenSaverEvent+0x58 (FPO: [1,9,0])

        00b7ffb8 77e64829 000a8b80 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

        00b7ffec 00000000 010390b7 000a8b80 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

        THREAD 84989b40  Cid 0344.4c88  Teb: 7ffaa000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

            84989d2c  Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 0020bf60:

        Current LPC port e3761290

        Impersonation token:  e3a48030 (Level Impersonation)

        DeviceMap                 e1bca430

        Owning Process            84f02020       Image:         winlogon.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3513766        Ticks: 136916 (0:00:35:39.312)

        Context Switch Count      1            

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

        Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init b9c44000 Current b9c43c20 Base b9c44000 Limit b9c41000 Call 0

        Priority 13 BasePriority 13 PriorityDecrement 0

        Kernel stack not resident.

        ChildEBP RetAddr  Args to Child             

        b9c43c38 808202b6 84989b40 84989be8 00000741 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

        b9c43c50 8081fb6e 84989d2c 84989d00 84989b40 nt!KiSwapThread+0x83 (FPO: [0,2,0])

        b9c43c94 80915355 84989d2c 00000011 b9c43d01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

        b9c43d50 8082350b 00000364 000c18a8 000c18a8 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

        b9c43d50 7c8285ec 00000364 000c18a8 000c18a8 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9c43d64)

        00dffab0 7c82787b 77c80a6e 00000364 000c18a8 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

        00dffab4 77c80a6e 00000364 000c18a8 000c18a8 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

        00dffb00 77c7fcf0 00dffb3c 00dffb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

        00dffb0c 77c80673 00dffb3c 75822c38 00dfff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

        00dffb20 77ce315a 00dffb68 000c1968 000bcd80 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

        00dfff08 75822b74 75822c38 75822b8a 00dfff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

        00dfff20 75822b4f 000c1e30 00dfff3c 00dfff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

        00dfff30 75824d57 00dfff3c 00020000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

        00dfff60 0103917b 00dfff78 00000000 00000000 WlNotify!SensLockEvent+0x58 (FPO: [1,9,0])

        00dfffb8 77e64829 000bcd80 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

        00dfffec 00000000 010390b7 000bcd80 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

        THREAD 847d7b18  Cid 0344.4c9c  Teb: 7ffa6000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

            847d7d04  Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 0020bfb4:

        Current LPC port e3761290

        Impersonation token:  e423a358 (Level Impersonation)

        DeviceMap                 e1bca430

        Owning Process            84f02020       Image:         winlogon.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3514154        Ticks: 136528 (0:00:35:33.250)

        Context Switch Count      1            

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

        Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init b9c00000 Current b9bffc20 Base b9c00000 Limit b9bfd000 Call 0

        Priority 13 BasePriority 13 PriorityDecrement 0

        Kernel stack not resident.

        ChildEBP RetAddr  Args to Child             

        b9bffc38 808202b6 847d7b18 847d7bc0 00002601 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

        b9bffc50 8081fb6e 847d7d04 847d7cd8 847d7b18 nt!KiSwapThread+0x83 (FPO: [0,2,0])

        b9bffc94 80915355 847d7d04 00000011 b9bffd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

        b9bffd50 8082350b 00000364 000ab970 000ab970 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

        b9bffd50 7c8285ec 00000364 000ab970 000ab970 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9bffd64)

        00fcfab0 7c82787b 77c80a6e 00000364 000ab970 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

        00fcfab4 77c80a6e 00000364 000ab970 000ab970 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

        00fcfb00 77c7fcf0 00fcfb3c 00fcfb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

        00fcfb0c 77c80673 00fcfb3c 75822c38 00fcff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

        00fcfb20 77ce315a 00fcfb68 000aba30 000bd858 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

        00fcff08 75822b74 75822c38 75822b8a 00fcff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

        00fcff20 75822b4f 000c1e30 00fcff3c 00fcff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

        00fcff30 75824db8 00fcff3c 00040000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

        00fcff60 0103917b 00fcff78 00000000 00000000 WlNotify!SensUnlockEvent+0x58 (FPO: [1,9,0])

        00fcffb8 77e64829 000bd858 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

        00fcffec 00000000 010390b7 000bd858 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

        THREAD 8478e8d0  Cid 0344.53d0  Teb: 7ffab000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

            8478eabc  Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 0020f7bb:

        Current LPC port e3761290

        Impersonation token:  e3811358 (Level Impersonation)

        DeviceMap                 e1bca430

        Owning Process            84f02020       Image:         winlogon.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3572296        Ticks: 78386 (0:00:20:24.781)

        Context Switch Count      1            

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

        Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init b94bc000 Current b94bbc20 Base b94bc000 Limit b94b9000 Call 0

        Priority 13 BasePriority 13 PriorityDecrement 0

        Kernel stack not resident.

        ChildEBP RetAddr  Args to Child             

        b94bbc38 808202b6 8478e8d0 8478e978 00000310 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

        b94bbc50 8081fb6e 8478eabc 8478ea90 8478e8d0 nt!KiSwapThread+0x83 (FPO: [0,2,0])

        b94bbc94 80915355 8478eabc 00000011 b94bbd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

        b94bbd50 8082350b 00000364 000880a8 000880a8 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

        b94bbd50 7c8285ec 00000364 000880a8 000880a8 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b94bbd64)

        00dbfab0 7c82787b 77c80a6e 00000364 000880a8 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

        00dbfab4 77c80a6e 00000364 000880a8 000880a8 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

        00dbfb00 77c7fcf0 00dbfb3c 00dbfb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

        00dbfb0c 77c80673 00dbfb3c 75822c38 00dbff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

        00dbfb20 77ce315a 00dbfb68 00088168 0008bd80 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

        00dbff08 75822b74 75822c38 75822b8a 00dbff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

        00dbff20 75822b4f 000c1e30 00dbff3c 00dbff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

        00dbff30 75824e19 00dbff3c 00080000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

        00dbff60 0103917b 00dbff78 00000000 00000000 WlNotify!SensStartScreenSaverEvent+0x58 (FPO: [1,9,0])

        00dbffb8 77e64829 0008bd80 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

        00dbffec 00000000 010390b7 0008bd80 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

        THREAD 846e6660  Cid 0344.56a8  Teb: 7ffa7000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

            846e684c  Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 0021117f:

        Current LPC port e3761290

        Impersonation token:  e37a5358 (Level Impersonation)

        DeviceMap                 e1bca430

        Owning Process            84f02020       Image:         winlogon.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3602966        Ticks: 47716 (0:00:12:25.562)

        Context Switch Count      1            

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

        Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init b9500000 Current b94ffc20 Base b9500000 Limit b94fd000 Call 0

        Priority 13 BasePriority 13 PriorityDecrement 0

        Kernel stack not resident.

        ChildEBP RetAddr  Args to Child             

        b94ffc38 808202b6 846e6660 846e6708 00000241 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

        b94ffc50 8081fb6e 846e684c 846e6820 846e6660 nt!KiSwapThread+0x83 (FPO: [0,2,0])

        b94ffc94 80915355 846e684c 00000011 b94ffd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

        b94ffd50 8082350b 00000364 0008ba78 0008ba78 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

        b94ffd50 7c8285ec 00000364 0008ba78 0008ba78 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b94ffd64)

        00f8fab0 7c82787b 77c80a6e 00000364 0008ba78 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

        00f8fab4 77c80a6e 00000364 0008ba78 0008ba78 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

        00f8fb00 77c7fcf0 00f8fb3c 00f8fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

        00f8fb0c 77c80673 00f8fb3c 75822c38 00f8ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

        00f8fb20 77ce315a 00f8fb68 0008bb38 0009bbf0 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

        00f8ff08 75822b74 75822c38 75822b8a 00f8ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

        00f8ff20 75822b4f 000c1e30 00f8ff3c 00f8ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

        00f8ff30 75824e7a 00f8ff3c 00100000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

        00f8ff60 0103917b 00f8ff78 00000000 00000000 WlNotify!SensStopScreenSaverEvent+0x58 (FPO: [1,9,0])

        00f8ffb8 77e64829 0009bbf0 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

        00f8ffec 00000000 010390b7 0009bbf0 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

        THREAD 8470d428  Cid 0344.56b4  Teb: 7ffa4000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

            8470d614  Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 00211186:

        Current LPC port e3761290

        Impersonation token:  e4167358 (Level Impersonation)

        DeviceMap                 e1bca430

        Owning Process            84f02020       Image:         winlogon.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3602966        Ticks: 47716 (0:00:12:25.562)

        Context Switch Count      1            

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

        Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init b9378000 Current b9377c20 Base b9378000 Limit b9375000 Call 0

        Priority 13 BasePriority 13 PriorityDecrement 0

        Kernel stack not resident.

        ChildEBP RetAddr  Args to Child             

        b9377c38 808202b6 8470d428 8470d4d0 00002241 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

        b9377c50 8081fb6e 8470d614 8470d5e8 8470d428 nt!KiSwapThread+0x83 (FPO: [0,2,0])

        b9377c94 80915355 8470d614 00000011 b9377d01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

        b9377d50 8082350b 00000364 0013b340 0013b340 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

        b9377d50 7c8285ec 00000364 0013b340 0013b340 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9377d64)

        016dfab0 7c82787b 77c80a6e 00000364 0013b340 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

        016dfab4 77c80a6e 00000364 0013b340 0013b340 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

        016dfb00 77c7fcf0 016dfb3c 016dfb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

        016dfb0c 77c80673 016dfb3c 75822c38 016dff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

        016dfb20 77ce315a 016dfb68 0013b400 0007f808 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

        016dff08 75822b74 75822c38 75822b8a 016dff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

        016dff20 75822b4f 000c1e30 016dff3c 016dff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

        016dff30 75824d57 016dff3c 00020000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

        016dff60 0103917b 016dff78 00000000 00000000 WlNotify!SensLockEvent+0x58 (FPO: [1,9,0])

        016dffb8 77e64829 0007f808 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

        016dffec 00000000 010390b7 0007f808 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

        THREAD 846c4b40  Cid 0344.56d0  Teb: 7ffa2000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

            846c4d2c  Semaphore Limit 0x1

        Waiting for reply to LPC MessageId 00211223:

        Current LPC port e3761290

        Impersonation token:  e3826358 (Level Impersonation)

        DeviceMap                 e1bca430

        Owning Process            84f02020       Image:         winlogon.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      3603490        Ticks: 47192 (0:00:12:17.375)

        Context Switch Count      1            

        UserTime                  00:00:00.000

        KernelTime                00:00:00.000

        Win32 Start Address winlogon!WlpExecuteNotify (0x010390b7)

        Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

        Stack Init b9310000 Current b930fc20 Base b9310000 Limit b930d000 Call 0

        Priority 13 BasePriority 13 PriorityDecrement 0

        Kernel stack not resident.

        ChildEBP RetAddr  Args to Child             

        b930fc38 808202b6 846c4b40 846c4be8 00002301 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

        b930fc50 8081fb6e 846c4d2c 846c4d00 846c4b40 nt!KiSwapThread+0x83 (FPO: [0,2,0])

        b930fc94 80915355 846c4d2c 00000011 b930fd01 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

        b930fd50 8082350b 00000364 0013c440 0013c440 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

        b930fd50 7c8285ec 00000364 0013c440 0013c440 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b930fd64)

        0175fab0 7c82787b 77c80a6e 00000364 0013c440 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

        0175fab4 77c80a6e 00000364 0013c440 0013c440 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

        0175fb00 77c7fcf0 0175fb3c 0175fb20 77c80673 RPCRT4!LRPC_CCALL::SendReceive+0x230 (FPO: [1,11,0])

        0175fb0c 77c80673 0175fb3c 75822c38 0175ff28 RPCRT4!I_RpcSendReceive+0x24 (FPO: [1,0,0])

        0175fb20 77ce315a 0175fb68 0013c500 00098ef8 RPCRT4!NdrSendReceive+0x2b (FPO: [2,0,0])

        0175ff08 75822b74 75822c38 75822b8a 0175ff28 RPCRT4!NdrClientCall2+0x22e (FPO: [SEH])

        0175ff20 75822b4f 000c1e30 0175ff3c 0175ff60 WlNotify!SensApip_RPC_SensNotifyWinlogonEvent+0x1c (FPO: [2,1,0])

        0175ff30 75824db8 0175ff3c 00040000 00000024 WlNotify!SensNotifyWinlogonEvent+0x1c (FPO: [1,0,0])

        0175ff60 0103917b 0175ff78 00000000 00000000 WlNotify!SensUnlockEvent+0x58 (FPO: [1,9,0])

        0175ffb8 77e64829 00098ef8 00000000 00000000 winlogon!WlpExecuteNotify+0xc4 (FPO: [SEH])

        0175ffec 00000000 010390b7 00098ef8 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

Wow!....look at that...around 8 threads, and all waiting for replies to the LPC calls issued. So, both the winlogon processes are stuck waiting for a reply for the LPC calls they made.

 

The next part is to find out what's happening at the server part of these LPC calls since winlogon is stuck until the processing of the LPC calls are finished.

 

To find the server part of the LPC call, we pick the message ID from each thread. Look for (Waiting for reply to LPC MessageId "message_id":) in the threads above. Let's start with the first winlogon process to find out the server end of the LPC call it had in there. If you remember, we did find one thread in the first winlogon process waiting for a reply to the LPC call and message id of that LPC call was 00213bd7.

 

kd> !lpc message 00213bd7

Searching message 213bd7 in threads ...

Client thread 847318d0 waiting a reply from 213bd7                         

Searching thread 847318d0 in port rundown queues ...

 

Server communication port 0xe365aa90

    Handles: 1   References: 1

    The LpcDataInfoChainHead queue is empty

        Connected port: 0xe125d4e0      Server connection port: 0xe1c37920

 

Client communication port 0xe125d4e0

    Handles: 1   References: 2

    The LpcDataInfoChainHead queue is empty

 

Server connection port e1c37920  Name: senssvc

    Handles: 1   References: 17

    Server process  : 85e021e0 (svchost.exe)

    Queue semaphore : 850fa890

    Semaphore state 16 (0x10)

        Messages in queue:

        0000 e3791a88 - Busy  Id=001fbe4f  From: 0f4c.335c  Context=80060002  [e1c37930 . e1281378]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 00000028 00000005 00010050 00d0fdac

        0000 e1281378 - Busy  Id=001fbe56  From: 0f4c.336c  Context=80060002  [e3791a88 . e15c5350]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 00490065 0074006e 006c0065 00500000

        0000 e15c5350 - Busy  Id=00200326  From: 0f4c.3840  Context=80060002  [e1281378 . e14ba008]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 0008c080 00000000 0049004d 00440048

        0000 e14ba008 - Busy  Id=0020032a  From: 0f4c.3848  Context=80060002  [e15c5350 . e1120290]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 00000000 00000000 0000000c 00000000

        0000 e1120290 - Busy  Id=002049b3  From: 0f4c.3b08  Context=80060002  [e14ba008 . e40a48c8]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 00600040 00600050 00900050 00600050

        0000 e40a48c8 - Busy  Id=00204e8d  From: 0f4c.09c8  Context=80060002  [e1120290 . e1ab41d0]

                   Length=00200008  Type=00000005 (LPC_PORT_CLOSED)

                   Data: fd48cde3 01c9700a

        0000 e1ab41d0 - Busy  Id=0020b318  From: 0344.4ab0  Context=80050001  [e40a48c8 . e1b35378]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 00000028 00000005 00010050 00d0fdac

        0000 e1b35378 - Busy  Id=0020bf59  From: 0344.4c7c  Context=80050001  [e1ab41d0 . e1bdc918]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 00000000 00000000 00000000 00000000

        0000 e1bdc918 - Busy  Id=0020bf60  From: 0344.4c88  Context=80050001  [e1b35378 . e1657ca0]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 0037002d 00350032 00340033 00350035

        0000 e1657ca0 - Busy  Id=0020bfb4  From: 0344.4c9c  Context=80050001  [e1bdc918 . e3a463e8]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 4ed07378 cf0ee4b3 5faeb176 0000000c

        0000 e3a463e8 - Busy  Id=0020f7bb  From: 0344.53d0  Context=80050001  [e1657ca0 . e1bcab08]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 00000000 00000000 00000000 00000000

        0000 e1bcab08 - Busy  Id=0021117f  From: 0344.56a8  Context=80050001  [e3a463e8 . e4190008]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 00000000 813a8198 00001601 00027011

        0000 e4190008 - Busy  Id=00211186  From: 0344.56b4  Context=80050001  [e1bcab08 . e40afca8]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 002e0070 0061006d 00720072 006f0069

        0000 e40afca8 - Busy  Id=00211223  From: 0344.56d0  Context=80050001  [e4190008 . e37de340]

                   Length=00c000a8  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 4bdd485c 5d18bba4 d4bb211b 0000000c

        0000 e37de340 - Busy  Id=00213bd7  From: 01a4.58e4  Context=80030000  [e40afca8 . e1c37930]

                   Length=00780060  Type=00000001 (LPC_REQUEST)

                   Data: 00000001 00000241 00000000 811fc308 00001601 000152cb

    The message queue contains 15 messages

    The LpcDataInfoChainHead queue is empty

 

Done!                                            

 

Interesting, along with the message id, 00213bd7 , in the queue, we also found all other message ID's seen in the second winlogon process.

Take a look at the messages in queue and you will see all of them in there.

 

So, now the question arises as to what is this process doing and why its unable to process these LPC call's successfully.

 

Let's switch context to the Server process  :  85e021e0 (svchost.exe)

 

kd> .process /p /r 85e021e0

Implicit process is now 85e021e0 

Loading User Symbols

................................................................

...........................................

 

When I dumped the threads in this process, the thread count turned out to be an alarming 4900 which is extremely bizarre. Around 1325 of those threads were waiting to acquire a common critical section. This became a very solid point of interest and almost all of them (around 4870) were in a wait state pending a single common SynchronizationEvent i.e. 85d1eeb0.

 

These threads wait for the message to come through via the LPC port to the server process. That also explains why the server service (user mode component: srvsvc.dll) is unable to process any remote requests.

 

Few of those threads, waiting on the common critical section, looked like this: (Don’t get bothered by the “Kernel stack not resident” as we know memory gets swapped to disk)

 

kd> !thread 84832af8

THREAD 84832af8  Cid 03d8.4760  Teb: 7ef49000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

    85d1eeb0  SynchronizationEvent

Not impersonating

DeviceMap                 e1001150

Owning Process            85e021e0       Image:         svchost.exe

Attached Process          N/A            Image:         N/A

Wait Start TickCount      3474348        Ticks: 176334 (0:00:45:55.218)

Context Switch Count      1            

UserTime                  00:00:00.000

KernelTime                00:00:00.000

Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

Stack Init b9fd4000 Current b9fd3c78 Base b9fd4000 Limit b9fd1000 Call 0

Priority 8 BasePriority 8 PriorityDecrement 0

Kernel stack not resident.

ChildEBP RetAddr  Args to Child             

b9fd3c90 808202b6 84832af8 84832ba0 00000000 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

b9fd3ca8 8081fb6e 00000000 00000000 00000000 nt!KiSwapThread+0x83 (FPO: [0,2,0])

b9fd3cec 8090e64e 85d1eeb0 00000006 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

b9fd3d50 8082350b 00000314 00000000 00000000 nt!NtWaitForSingleObject+0x9a (FPO: [SEH])

b9fd3d50 7c8285ec 00000314 00000000 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9fd3d64)

3d6bfbc8 7c827d0b 7c83d236 00000314 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

3d6bfbcc 7c83d236 00000314 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])

3d6bfc08 7c83d281 00000314 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x1a3 (FPO: [2,7,4])

3d6bfc28 7c82ee3b 7c8877a0 00000000 7ffd8000 ntdll!RtlEnterCriticalSection+0xa8 (FPO: [1,1,0])

3d6bfcb8 7c82ec9f 3d6bfd28 3d6bfd28 00000000 ntdll!LdrpInitializeThread+0x68 (FPO: [SEH])

3d6bfd14 7c8284c5 3d6bfd28 7c800000 00000000 ntdll!_LdrpInitialize+0x16f (FPO: [SEH])

00000000 00000000 00000000 00000000 00000000 ntdll!KiUserApcDispatcher+0x25

 

kd> !thread 847d8b40

THREAD 847d8b40  Cid 03d8.4be0  Teb: 7ed63000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

    85d1eeb0  SynchronizationEvent

Not impersonating

DeviceMap                 e1001150

Owning Process            85e021e0       Image:         svchost.exe

Attached Process          N/A            Image:         N/A

Wait Start TickCount      3549550        Ticks: 101132 (0:00:26:20.187)

Context Switch Count      1            

UserTime                  00:00:00.000

KernelTime                00:00:00.000

Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

Stack Init b98a4000 Current b98a3c78 Base b98a4000 Limit b98a1000 Call 0

Priority 8 BasePriority 8 PriorityDecrement 0

Kernel stack not resident.

ChildEBP RetAddr  Args to Child             

b98a3c90 808202b6 847d8b40 847d8be8 00000000 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

b98a3ca8 8081fb6e 00000000 00000000 00000000 nt!KiSwapThread+0x83 (FPO: [0,2,0])

b98a3cec 8090e64e 85d1eeb0 00000006 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

b98a3d50 8082350b 00000314 00000000 00000000 nt!NtWaitForSingleObject+0x9a (FPO: [SEH])

b98a3d50 7c8285ec 00000314 00000000 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b98a3d64)

4503fbc8 7c827d0b 7c83d236 00000314 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

4503fbcc 7c83d236 00000314 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])

4503fc08 7c83d281 00000314 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x1a3 (FPO: [2,7,4])

4503fc28 7c82ee3b 7c8877a0 00000000 7ffd8000 ntdll!RtlEnterCriticalSection+0xa8 (FPO: [1,1,0])

4503fcb8 7c82ec9f 4503fd28 4503fd28 00000000 ntdll!LdrpInitializeThread+0x68 (FPO: [SEH])

4503fd14 7c8284c5 4503fd28 7c800000 00000000 ntdll!_LdrpInitialize+0x16f (FPO: [SEH])

00000000 00000000 00000000 00000000 00000000 ntdll!KiUserApcDispatcher+0x25

 

kd> !thread 847a8db0

THREAD 847a8db0  Cid 03d8.4998  Teb: 7eed1000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

    85d1eeb0  SynchronizationEvent

Not impersonating

DeviceMap                 e1001150

Owning Process            85e021e0       Image:         svchost.exe

Attached Process          N/A            Image:         N/A

Wait Start TickCount      3487819        Ticks: 162863 (0:00:42:24.734)

Context Switch Count      1            

UserTime                  00:00:00.000

KernelTime                00:00:00.000

Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

Stack Init b9dc4000 Current b9dc3c78 Base b9dc4000 Limit b9dc1000 Call 0

Priority 8 BasePriority 8 PriorityDecrement 0

Kernel stack not resident.

ChildEBP RetAddr  Args to Child              

b9dc3c90 808202b6 847a8db0 847a8e58 00000000 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

b9dc3ca8 8081fb6e 00000000 00000000 00000000 nt!KiSwapThread+0x83 (FPO: [0,2,0])

b9dc3cec 8090e64e 85d1eeb0 00000006 00000001 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

b9dc3d50 8082350b 00000314 00000000 00000000 nt!NtWaitForSingleObject+0x9a (FPO: [SEH])

b9dc3d50 7c8285ec 00000314 00000000 00000000 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ b9dc3d64)

3f4bfbc8 7c827d0b 7c83d236 00000314 00000000 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

3f4bfbcc 7c83d236 00000314 00000000 00000000 ntdll!NtWaitForSingleObject+0xc (FPO: [3,0,0])

3f4bfc08 7c83d281 00000314 00000004 00000000 ntdll!RtlpWaitOnCriticalSection+0x1a3 (FPO: [2,7,4])

3f4bfc28 7c82ee3b 7c8877a0 00000000 7ffd8000 ntdll!RtlEnterCriticalSection+0xa8 (FPO: [1,1,0])

3f4bfcb8 7c82ec9f 3f4bfd28 3f4bfd28 00000000 ntdll!LdrpInitializeThread+0x68 (FPO: [SEH])

3f4bfd14 7c8284c5 3f4bfd28 7c800000 00000000 ntdll!_LdrpInitialize+0x16f (FPO: [SEH])

00000000 00000000 00000000 00000000 00000000 ntdll!KiUserApcDispatcher+0x25

 

kd> !thread 848e1db0

THREAD 848e1db0  Cid 03d8.2c10  Teb: 7f67a000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

    85d1eeb0  SynchronizationEvent

Not impersonating

DeviceMap                 e1001150

Owning Process            85e021e0       Image:         svchost.exe

Attached Process          N/A            Image:         N/A

Wait Start TickCount      3183097        Ticks: 467585 (0:02:01:46.015)

Context Switch Count      1             

UserTime                  00:00:00.000

KernelTime                00:00:00.000

Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

Stack Init f3570000 Current f356fc78 Base f3570000 Limit f356d000 Call 0

Priority 8 BasePriority 8 PriorityDecrement 0

Kernel stack not resident

 

kd> !thread 84890db0

THREAD 84890db0  Cid 03d8.31cc  Teb: 7f4e3000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

    85d1eeb0  SynchronizationEvent

Not impersonating

DeviceMap                 e1001150

Owning Process            85e021e0       Image:         svchost.exe

Attached Process          N/A            Image:         N/A

Wait Start TickCount      3244800        Ticks: 405882 (0:01:45:41.906)

Context Switch Count      1            

UserTime                  00:00:00.000

KernelTime                00:00:00.000

Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

Stack Init f2ee8000 Current f2ee7c78 Base f2ee8000 Limit f2ee5000 Call 0

Priority 8 BasePriority 8 PriorityDecrement 0

Kernel stack not resident.

 

kd> !thread 848223f0

THREAD 848223f0  Cid 03d8.3714  Teb: 7f3d8000 Win32Thread: 00000000 WAIT: (Unknown) UserMode Non-Alertable

    85d1eeb0  SynchronizationEvent

Not impersonating

DeviceMap                 e1001150

Owning Process            85e021e0       Image:         svchost.exe

Attached Process          N/A            Image:         N/A

Wait Start TickCount      3283235        Ticks: 367447 (0:01:35:41.359)

Context Switch Count      1            

UserTime                  00:00:00.000

KernelTime                00:00:00.000

Win32 Start Address srvsvc!XsProcessApisWrapper (0x74ed39a9)

Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

Stack Init f2ac4000 Current f2ac3c78 Base f2ac4000 Limit f2ac1000 Call 0

Priority 8 BasePriority 8 PriorityDecrement 0

Kernel stack not resident.

 

kd> dt ntdll!_RTL_CRITICAL_SECTION 7c8877a0

   +0x000 DebugInfo        : 0x7c8877c0 _RTL_CRITICAL_SECTION_DEBUG

   +0x004 LockCount        : -19514

   +0x008 RecursionCount   : 2

   +0x00c OwningThread     : 0x00001634

   +0x010 LockSemaphore    : 0x00000314

   +0x014 SpinCount        : 0

 

In Microsoft Windows Server 2003 Service Pack 1 and later versions of Windows, the LockCount field is parsed as follows: (also at link http://msdn.microsoft.com/en-us/library/cc267476.aspx)

  • The lowest bit shows the lock status. If this bit is 0, the critical section is locked; if it is 1, the critical section is not locked.
  • The next bit shows whether a thread has been woken for this lock. If this bit is 0, then a thread has been woken for this lock; if it is 1, no thread has been woken.
  • The remaining bits are the ones-complement of the number of threads waiting for the lock.

In our case, the LockCount is -19514. The lowest bit can be determined in this way:

kd> ? 0x1 & (-0n19514)

Evaluate expression: 0 = 00000000

 

kd>  (0x2 & (-0n19514)) >> 1

     ^ Syntax error in ' (0x2 & (-0n19514)) >> 1'

 

kd> ?(0x2 & (-0n19514)) >> 1

Evaluate expression: 1 = 00000001

 

kd> ? ((-1) - (-0n19514)) >> 2

Evaluate expression: 4878 = 0000130e

 

 

So, there are 4878 threads waiting for this particular critical section. Seeing the number of above threads in the waiting list, it makes lot of sense.

In RED above, we see the offender (0x00001634) who is not ready to leave the critical section.

 

So now, at least we know which thread is causing the server to be unresponsive. Let’s go further and find out what’s happening in that particular thread.

 

kd> !thread 85125020

THREAD 85125020  Cid 03d8.1634  Teb: 7ffdb000 Win32Thread: e1754ea8 WAIT: (Unknown) UserMode Non-Alertable

    8512520c  Semaphore Limit 0x1

Waiting for reply to LPC MessageId 001e295b:

Current LPC port e38140c8

IRP List:

    850eff68: (0006,0094) Flags: 00000800  Mdl: 00000000

Not impersonating

DeviceMap                 e1001150

Owning Process            85e021e0       Image:         svchost.exe

Attached Process          N/A            Image:         N/A

Wait Start TickCount      3470768        Ticks: 179914 (0:00:46:51.156)

Context Switch Count      93                 LargeStack

UserTime                  00:00:00.000

KernelTime                00:00:00.015

Win32 Start Address RPCRT4!ThreadStartRoutine (0x77c7b0f5)

Start Address kernel32!BaseThreadStartThunk (0x77e617ec)

Stack Init f5424000 Current f5423c20 Base f5424000 Limit f5421000 Call 0

Priority 10 BasePriority 8 PriorityDecrement 0

Kernel stack not resident.

ChildEBP RetAddr  Args to Child             

f5423c38 808202b6 85125020 851250c8 00000500 nt!KiSwapContext+0x25 (FPO: [Uses EBP] [0,0,4])

f5423c50 8081fb6e 8512520c 851251e0 85125020 nt!KiSwapThread+0x83 (FPO: [0,2,0])

f5423c94 80915355 8512520c 00000011 80912701 nt!KeWaitForSingleObject+0x2e0 (FPO: [5,12,4])

f5423d50 8082350b 00000a40 000e9dd8 000de270 nt!NtRequestWaitReplyPort+0x776 (FPO: [SEH])

f5423d50 7c8285ec 00000a40 000e9dd8 000de270 nt!KiFastCallEntry+0xf8 (FPO: [0,0] TrapFrame @ f5423d64)

00a0c580 7c82787b 77e77342 00000a40 000e9dd8 ntdll!KiFastSystemCallRet (FPO: [0,0,0])

00a0c584 77e77342 00000a40 000e9dd8 000de270 ntdll!NtRequestWaitReplyPort+0xc (FPO: [3,0,0])

00a0c5bc 77e77214 01b1f978 7c840936 00a0c604 kernel32!BasepQueryModuleData+0x121 (FPO: [5,6,4])

00a0c5dc 7c84086e 01b1f978 7c840936 00a0c604 kernel32!BaseQueryModuleData+0x3b (FPO: [5,1,0])

00a0c82c 7c8343b7 0009ec88 0009ec88 00000000 ntdll!LdrpCheckAppDatabase+0x9c (FPO: [1,138,4])

00a0c840 7c8333ba 0009ec88 0016ecb0 00a0ce98 ntdll!LdrpCheckNXCompatibility+0x27 (FPO: [1,1,4])

00a0c93c 7c834311 00000000 00000000 777964d0 ntdll!LdrpRunInitializeRoutines+0x20f (FPO: [SEH])

00a0cbd0 7c834065 00000000 0016ecb0 00a0ce98 ntdll!LdrpLoadDll+0x3cd (FPO: [SEH])

00a0ce4c 77e41bf3 0016ecb0 00a0ce98 00a0ce78 ntdll!LdrLoadDll+0x198 (FPO: [SEH])

00a0ceb4 776adc89 00a0cf30 00000000 00000008 kernel32!LoadLibraryExW+0x1b2 (FPO: [SEH])

00a0ced8 776adb95 00a0cf30 00a0cefc 00a0cf00 ole32!CClassCache::CDllPathEntry::LoadDll+0xb0 (FPO: [4,1,4])

00a0cf08 776ad2da 00a0cf30 00a0d208 00a0cf28 ole32!CClassCache::CDllPathEntry::Create_rl+0x37 (FPO: [3,3,4])

00a0d154 776ad1fd 00000001 00a0d208 00a0d184 ole32!CClassCache::CClassEntry::CreateDllClassEntry_rl+0xd8 (FPO: [3,139,4])

00a0d19c 776ad112 00000001 00105624 00a0d1c8 ole32!CClassCache::GetClassObjectActivator+0x1fe (FPO: [3,10,4])

00a0d1cc 776a1b7f 00a0d208 00a0dce8 00a0d7a0 ole32!CClassCache::GetClassObject+0x24 (FPO: [1,1,0])

00a0d240 776a19b5 77794964 00a0d7a0 00a0dce8 ole32!CServerContextActivator::GetClassObject+0xfd (FPO: [3,23,4])

00a0d278 776a1c4e 00a0d7a0 00a0dce8 00a0d7a0 ole32!ActivationPropertiesIn::DelegateGetClassObject+0xf3 (FPO: [2,7,0])

00a0d298 776a1bfa 77794978 00a0d7a0 00a0dce8 ole32!CApartmentActivator::GetClassObject+0x4d (FPO: [3,2,0])

00a0d2b0 776acb27 77794978 00000001 00000000 ole32!CProcessActivator::GCOCallback+0x2b (FPO: [6,0,4])

00a0d2d0 776acad8 77794960 00a0d5fc 00000000 ole32!CProcessActivator::AttemptActivation+0x2c (FPO: [7,0,0])

00a0d30c 776a1ca1 77794960 00a0d5fc 00000000 ole32!CProcessActivator::ActivateByContext+0x4f (FPO: [6,3,0])

00a0d334 776a19b5 77794960 00a0d7a0 00a0dce8 ole32!CProcessActivator::GetClassObject+0x48 (FPO: [3,1,4])

00a0d36c 776a1925 00a0d7a0 00a0dce8 0073006d ole32!ActivationPropertiesIn::DelegateGetClassObject+0xf3 (FPO: [2,7,0])

00a0d5b4 776a19b5 7779487c 00000001 00a0dce8 ole32!CClientContextActivator::GetClassObject+0x88 (FPO: [3,3,0])

00a0d5ec 776a1a07 00a0d7a0 00a0dce8 7767c9b0 ole32!ActivationPropertiesIn::DelegateGetClassObject+0xf3 (FPO: [2,7,0])

00a0dda4 776a187e 00a0ded8 00000001 00000000 ole32!ICoGetClassObject+0x3a5 (FPO: [7,52,0])

00a0ddd4 776a1841 00a0ded8 00000002 00000000 ole32!CComActivator::DoGetClassObject+0xe0 (FPO: [6,0,4])

00a0ddf4 772d7218 00a0ded8 00000001 00000000 ole32!CoGetClassObject+0x20 (FPO: [5,0,0])

00a0de60 772d65ce 01ab48d8 01aeba70 00a0de80 urlmon!CProtMgr::FindFirstCF+0x11a (FPO: [4,17,0])

00a0de84 772c4408 01ab4870 01aeba70 00000000 urlmon!COInetSession::CreateHandler+0x2d (FPO: [6,1,0])

00a0deec 772d6b6c 00083ff8 01aeba70 000841b0 urlmon!CTransaction::LoadHandler+0xbd (FPO: [5,15,4])

00a0df18 772c8302 00083ff8 0000000d 00000001 urlmon!CTransaction::DispatchReport+0x203 (FPO: [8,1,4])

00a0df44 772c874b 00083ff8 01b092e8 00000000 urlmon!CTransaction::DispatchPacket+0x31 (FPO: [2,0,4])

00a0df64 772c6681 00083ff8 00000000 00a0e014 urlmon!CTransaction::OnINetCallback+0x92 (FPO: [2,1,0])

00a0df9c 7739b6e3 00c60048 00000465 00000000 urlmon!TransactionWndProc+0x33 (FPO: [SEH])

00a0dfc8 7739b874 772c664e 00c60048 00000465 USER32!InternalCallWinProc+0x28

00a0e040 7739ba92 00000000 772c664e 00c60048 USER32!UserCallWinProcCheckWow+0x151 (FPO: [SEH])

00a0e0a8 773a16e5 00a0e0d0 00000001 00a0e10c USER32!DispatchMessageWorker+0x327 (FPO: [SEH])

00a0e0b8 772de54a 00a0e0d0 00084100 00000000 USER32!DispatchMessageA+0xf (FPO: [1,0,0])

00a0e10c 772ca8f5 00000000 00000000 01ad6588 urlmon!CTransaction::CompleteOperation+0x15a (FPO: [1,15,0])

00a0e148 772c77ee 00083ff8 01ac6930 01ad64e0 urlmon!CTransaction::Start+0x52c (FPO: [6,9,4])

00a0e1cc 772c744f 00a0e214 01aa2b30 772c9c00 urlmon!CBinding::StartBinding+0x4d8 (FPO: [6,22,4])

00a0f264 772c7319 01aa7230 00000000 01aa2b30 urlmon!CUrlMon::StartBinding+0x1d8 (FPO: [6,1051,4])

00a0f29c 772eb8f5 01aa7230 01aa2b30 00000000 urlmon!CUrlMon::BindToStorage+0x67 (FPO: [5,3,4])

00a0f2e0 7732238b 001422e0 00a0f344 001422e0 urlmon!CBaseBSCB::KickOffDownload+0x191 (FPO: [2,8,0])

00a0f2f4 7732296f 001422e0 00a0f344 0000000c urlmon!CFileDownload::KickOffDownload+0x2d (FPO: [2,0,4])

00a0f30c 77322ce6 00000000 00a0f344 00a0f3c4 urlmon!URLDownloadToFileW+0x51 (FPO: [5,0,0])

00a0f444 00a0f59d 00000000 00a0f63e 00a0f632 urlmon!URLDownloadToFileA+0xd8 (FPO: [5,68,4])

WARNING: Frame IP not in any known module. Following frames may be wrong.

00a0f474 71bf396b 48544950 71bf3969 554a4649 0xa0f59d

 77430b8c 77e40000 00000000 00000004 0000ffff 000000b8 WS2HELP!WahOpenHandleHelper+0xf7 (FPO: [1,114,0])

 

Now, looking at the thread, lets list down the observations and our interpretation from it:

 

1)      So, by looking at API URLDownloadToFileW(), it seems this thread is busy downloading a file from the internet. The API and parameters are documented at  http://msdn.microsoft.com/en-us/library/ms836094.aspx Let’s find out which file are we trying to download here:

 

kd> du 00a0f344

00a0f344  http://10.162.13.115:31797/x

 

kd> du 00a0f3c4

00a0f3c4  "x.exe"

 

So we are trying to download an executable here? It’s worth having the customer investigate this binary?

 

2)      This thread is waiting for a reply to a LPC call issued (LPC MessageId 001e295b), so let’s find out who do we have at the server end of this LPC call:

 

kd> !lpc message 001e295b

Searching message 1e295b in threads ...

Client thread 85125020 waiting a reply from 1e295b                         

Searching thread 85125020 in port rundown queues ...

 

Server connection port e1395030  Name: AELPort

    Handles: 1   References: 22

    Server process  : 85e021e0 (svchost.exe)

    Queue semaphore : 85c593f8

    Semaphore state 0 (0x0)

    The message queue is empty

 

So, as you see above, the server piece of this LPC call is this process itself hence a straightforward deadlock situation. Also, please remember that critical section is process specific.

 

3)      The stack below URLMON looks messed up so we shall have to look at the raw stack and reconstruct the correct stack. 

 

kd> kv =00a0f8cc 0x00a0f8cc 71c49573

 

ChildEBP RetAddr  Args to Child             

00a0f8cc 71c49578 000c9620 000c93ac 00104100 NETAPI32!NetpwPathCanonicalize+0x76 (FPO: [6,0,4])

00a0f8f4 74edc916 000c93ac 00104100 0000019a NETAPI32!NetpwPathCanonicalize+0x7b (FPO: [6,0,4])

00a0f914 77c80193 000c9398 000c93ac 00104100 srvsvc!NetprPathCanonicalize+0x1c (FPO: [7,0,0])

00a0f944 77ce33e1 74edc8fa 00a0fb28 00000007 RPCRT4!Invoke+0x30

00a0fd44 77ce35c4 00000000 00000000 000b9fd8 RPCRT4!NdrStubCall2+0x299 (FPO: [SEH])

00a0fd60 77c7ff7a 000b9fd8 000a80d8 000b9fd8 RPCRT4!NdrServerCall2+0x19 (FPO: [1,1,0])

00a0fd94 77c8042d 74ed31d7 000b9fd8 00a0fe34 RPCRT4!DispatchToStubInCNoAvrf+0x38 (FPO: [SEH])

00a0fde8 77c80353 0000001f 00000000 74ee3f0c RPCRT4!RPC_INTERFACE::DispatchToStubWorker+0x11f (FPO: [4,13,4])

00a0fe0c 77c68e0d 000b9fd8 00000000 74ee3f0c RPCRT4!RPC_INTERFACE::DispatchToStub+0xa3 (FPO: [4,0,4])

00a0fe40 77c68cb3 000b9f98 000002a4 000b9f60 RPCRT4!OSF_SCALL::DispatchHelper+0x149 (FPO: [0,4,4])

00a0fe54 77c68c2b 00000000 0000001f 000c9370 RPCRT4!OSF_SCALL::DispatchRPCCall+0x10d (FPO: [2,0,4])

00a0fe84 77c68b5e 000c9370 030002bc 0000001f RPCRT4!OSF_SCALL::ProcessReceivedPDU+0x57f (FPO: [3,5,4])

00a0fea4 77c6e8db 00000000 000002bc 00000000 RPCRT4!OSF_SCALL::BeginRpcCall+0x194 (FPO: [2,0,4])

00a0ff04 77c6e7b4 00000000 000c9370 000002bc RPCRT4!OSF_SCONNECTION::ProcessReceiveComplete+0x435 (FPO: [3,17,0])

00a0ff18 77c7b799 0008cd68 0000000c 00000000 RPCRT4!ProcessConnectionServerReceivedEvent+0x21 (FPO: [7,0,0])

00a0ff84 77c7b9b5 00a0ffac 77c8872d 0008cd68 RPCRT4!LOADABLE_TRANSPORT::ProcessIOEvents+0x1b8 (FPO: [0,15,0])

00a0ff8c 77c8872d 0008cd68 00000000 00000000 RPCRT4!ProcessIOEventsWrapper+0xd (FPO: [1,0,0])

00a0ffac 77c7b110 0008b120 00a0ffec 77e64829 RPCRT4!BaseCachedThreadRoutine+0x9d (FPO: [1,2,4])

00a0ffb8 77e64829 001262f0 00000000 00000000 RPCRT4!ThreadStartRoutine+0x1b (FPO: [1,0,0])

00a0ffec 00000000 77c7b0f5 001262f0 00000000 kernel32!BaseThreadStart+0x34 (FPO: [SEH])

 

Our first course of action was to install the latest and greatest netapi32.dll binary which cleared up the issue.

 

 

I hope that helps!!

 

Thanks and regards,

Aman

Leave a Comment
  • Please add 1 and 7 and type the answer here:
  • Post
Page 1 of 1 (2 items)