Kernel Dump로 본 Handle Leak 이슈

일전에 Handle Leak Issue를 Check 하기 위해서 !htrace 를 이용하는 방법을 언급한 적이 있는 데, handle Leak 여부를 인식하기도 전에 kernel Dump를 통해서 우연찮게 드러나는 경우가 발생하기도 한다. 처음 문제 현상은 IOCP를 사용하는 통신 애플리케이션의 서버 단에서 일정 시간이 지나고 나면 더 이상 연결이 되지 않는 상황이 발생하였고, WinDbg를 통해서 User Mode Hang Memory Dump를 수집하려고 시도했으나 .dmp file이 생성되지 않는 현상이 발생하였다. 하여 문제 발생시 Kernel Dump를 수집하여 확인한 결과 Handle Leak이 발생한 경우였다.

 

1: kd> !process 0 0

**** NT ACTIVE PROCESS DUMP ****

. . .

PROCESS 85b07d88  SessionId: 0  Cid: 03d0    Peb: 7ffd5000  ParentCid: 01a4

    DirBase: 3fbd6180  ObjectTable: e140a9c0  HandleCount: 137.

    Image: spoolsv.exe

 

PROCESS 85ae1458  SessionId: 0  Cid: 03e8    Peb: 7ffd4000  ParentCid: 01a4

    DirBase: 3fbd61a0  ObjectTable: e16397d0  HandleCount: 154.

    Image: msdtc.exe

 

PROCESS 85ac7d88  SessionId: 0  Cid: 0444    Peb: 7ffde000  ParentCid: 01a4

    DirBase: 3fbd61c0  ObjectTable: e1aa3ac8  HandleCount:  71.

    Image: svchost.exe

 

PROCESS 85b04908  SessionId: 0  Cid: 0474    Peb: 7ffde000  ParentCid: 01a4

    DirBase: 3fbd61e0  ObjectTable: e13d0ad0  HandleCount: 149797.

    Image: TestLauncher.exe

 

PROCESS 85af4d88  SessionId: 0  Cid: 0484    Peb: 7ffde000  ParentCid: 0474

    DirBase: 3fbd6200  ObjectTable: e1529820  HandleCount:  64.

    Image: Client.exe

 

PROCESS 85b022c0  SessionId: 0  Cid: 049c    Peb: 7ffde000  ParentCid: 01a4

    DirBase: 3fbd6220  ObjectTable: e1937340  HandleCount: 360.

    Image: MainServer.exe

. . .

 

그러므로, PROCESS 85b04908, TestLauncher.exe 에서 Handle 정보를 확인할 필요가 있다.

 

1: kd> .PROCESS 85b04908 

Implicit process is now 85b04908

1: kd> !handle

processor number 1, process 85b04908

PROCESS 85b04908  SessionId: 0  Cid: 0474    Peb: 7ffde000  ParentCid: 01a4

    DirBase: 3fbd61e0  ObjectTable: e13d0ad0  HandleCount: 149797.

    Image: TestLauncher.exe

 

Handle table at e1032000 with 149797 Entries in use

0004: Object: e10016f8  GrantedAccess: 00000003 Entry: e1b69008

Object: e10016f8  Type: (8658b390) KeyedEvent

    ObjectHeader: e10016e0 (old version)

        HandleCount: 36  PointerCount: 37

        Directory Object: e1002a88  Name: CritSecOutOfMemoryEvent

 

...

 

0054: Object: 85af4d88  GrantedAccess: 001f0fff Entry: e1b690a8

Object: 85af4d88  Type: (86590e38) Process

    ObjectHeader: 85af4d70 (old version)

        HandleCount: 149766  PointerCount: 150010

 

. . .

00dc: Object: 85af4d88  GrantedAccess: 001f0fff Entry: e1b691b8

Object: 85af4d88  Type: (86590e38) Process

    ObjectHeader: 85af4d70 (old version)

        HandleCount: 149766  PointerCount: 150010

 

00e0: Object: 85af4d88  GrantedAccess: 001f0fff Entry: e1b691c0

Object: 85af4d88  Type: (86590e38) Process

    ObjectHeader: 85af4d70 (old version)

        HandleCount: 149766  PointerCount: 150010

 

00e4: Object: 85af4d88  GrantedAccess: 001f0fff Entry: e1b691c8

Object: 85af4d88  Type: (86590e38) Process

    ObjectHeader: 85af4d70 (old version)

        HandleCount: 149766  PointerCount: 150010

. . .

 

1: kd> !process 85af4d88 7  

PROCESS 85af4d88  SessionId: 0  Cid: 0484    Peb: 7ffde000  ParentCid: 0474

    DirBase: 3fbd6200  ObjectTable: e1529820  HandleCount:  64.

    Image: client.exe

    VadRoot 85b1de18 Vads 72 Clone 0 Private 2380. Modified 0. Locked 2.

    DeviceMap e1000930

    Token                             e1b06558

    ElapsedTime                       1 Day 17:39:41.791

    UserTime                          00:00:00.031

    KernelTime                        00:00:00.015

    QuotaPoolUsage[PagedPool]         28620

    QuotaPoolUsage[NonPagedPool]      34632

    Working Set Sizes (now,min,max)  (2927, 50, 345) (11708KB, 200KB, 1380KB)

    PeakWorkingSetSize                2927

    VirtualSize                       32 Mb

    PeakVirtualSize                   32 Mb

    PageFaultCount                    2921

    MemoryPriority                    BACKGROUND

    BasePriority                      8

    CommitCharge                      2434

 

        THREAD 85b20908  Cid 0484.0488  Teb: 7ffdd000 Win32Thread: e15b0a38 WAIT: (Unknown) UserMode Non-Alertable

            85af3d08  Semaphore Limit 0xffff

            85b20980  NotificationTimer

        IRP List:

            865e2dd8: (0006,0190) Flags: 00000000  Mdl: 85b5c628

            85b18008: (0006,0190) Flags: 00000000  Mdl: 85b4aa98

        Not impersonating

        DeviceMap                 e1000930

        Owning Process            85af4d88       Image:         client.exe

        Attached Process          N/A            Image:         N/A

        Wait Start TickCount      9586717        Ticks: 7 (0:00:00:00.109)

        Context Switch Count      81771                 LargeStack

        UserTime                  00:00:00.015

        KernelTime                00:00:00.015

        Win32 Start Address 0x00431523

        Start Address 0x7c8217f8

        Stack Init f6848000 Current f6847c60 Base f6848000 Limit f6844000 Call 0

        Priority 8 BasePriority 8 PriorityDecrement 0

        ChildEBP RetAddr  Args to Child             

        f6847c78 80833485 85b20908 85b209b0 00000001 nt!KiSwapContext+0x26 (FPO: [Uses EBP] [0,0,4])

        f6847ca4 80829a82 00000000 f6847d14 00000000 nt!KiSwapThread+0x2e5 (FPO: [0,7,0])

        f6847cec 80938d0c 85af3d08 00000006 8088d701 nt!KeWaitForSingleObject+0x346 (FPO: [5,13,4])

        f6847d50 808897bc 0000006c 00000000 f6847d14 nt!NtWaitForSingleObject+0x9a (FPO: [SEH])

        f6847d50 7c9685ec 0000006c 00000000 f6847d14 nt!KiFastCallEntry+0xfc (FPO: [0,0] TrapFrame @ f6847d64)

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

        0012fcec 00383bb0 00000000 00000005 65534847 0x7c9685ec

        00000000 00000000 00000000 00000000 00000000 0x383bb0

 

Handle 정보를 확인한 결과, Type이 Process인 Handle이 과다하게 존재하는 것으로 봐서 해당 Issue는 상당히 많은 Process Leak(client.exe)으로 인한 handle Leak이 발생한 것을 알 수 있다. 쉽게 예상할 수 있는 원인은 TestLauncher.exe process가 CreateProcess* API 를 통하여 client process의 launch후에 정상적으로 handle 를 Close 하지 않아서 이와 같은 Handle Leak의 형태로 문제가 발생한 것으로 추정할 수 있다.