기억속으로 날다(Walking on Memory) : 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의 형태로 문제가 발생한 것으로 추정할 수 있다.