이번 덤프는 지속적으로 CPU 사용율이 100%가 유지되는 행(Hang) 증상으로 수집된 덤프다.
이처럼 행과 같은 특수한 상황을 분석하기 위해서는 행 증상이 발생한 상태에서 강제로 BSOD를 발생시켜 덤프를 수집해야 한다.
대체로 행이나 메모리 누수 같은 문제는 당시 시스템 상황을 잘 분석해야 하므로 분석이 까다롭다.
참고로 이번에는 64비트 덤프로 준비해봤다. 혹시 64비트 덤프를 처음 보더라도 분석 방법은 동일하니 긴장하지 말고 시작해보자.
강제로 발생시킨 덤프이기 때문에 !analyze 명령이나 현재 스레드의 콜 스택 정보는 큰 의미가 없다.
행 덤프를 생성할 당시의 시스템 상황을 분석해내는 것이 핵심이다.
우선적으로 !running -it 명령으로 덤프 발생 당시 실행 중이던 스레드와 콜 스택 정보를 확인해보자.
kd> !running -it
System Processors: (000000000000000f)
Idle Processors: (0000000000000000) (0000000000000000) (0000000000000000) (0000000000000000)
Prcbs Current (pri) Next (pri) Idle
0 fffff80002bf8e80 fffffa802b447b60 ( 8) fffff80002c06cc0 ................
# Child-SP RetAddr Call Site
00 fffff880`02d2fcf8 fffff880`02e4d435 nt!KeBugCheckEx
01 fffff880`02d2fd00 fffff800`02d23cce MyDrv+0x1435
02 fffff880`02d2fd40 fffff800`02a77fe6 nt!PspSystemThreadStartup+0x5a
03 fffff880`02d2fd80 00000000`00000000 nt!KiStartSystemThread+0x16
1 fffff880009e8180 fffffa802b3ae060 ( 9) fffff880009f2fc0 ................
# Child-SP RetAddr Call Site
00 fffff880`041a5660 fffff800`02d44578 nt!ExfAcquirePushLockShared+0x21
01 fffff880`041a56e0 fffff800`02d8fef6 nt!ExpGetProcessInformation+0xaf2
02 fffff880`041a5830 fffff800`02d90949 nt!ExpQuerySystemInformation+0xfb4
03 fffff880`041a5be0 fffff800`02a858d3 nt!NtQuerySystemInformation+0x4d
04 fffff880`041a5c20 00000000`7733167a nt!KiSystemServiceCopyEnd+0x13
05 00000000`0504fd58 00000000`00000000 0x7733167a
2 fffff88003763180 fffffa802b3f8b60 ( 9) fffff8800376dfc0 ................
# Child-SP RetAddr Call Site
00 fffff880`057031a8 fffff800`02c7f3e0 kdcom+0x4c5f
01 fffff880`057031b0 00000000`00000002 nt!KdLogBuffer
02 fffff880`057031b8 00000000`00026200 0x2
03 fffff880`057031c0 00000000`00000001 0x26200
04 fffff880`057031c8 fffff800`00b9ca13 0x1
05 fffff880`057031d0 fffff800`00b9be4b kdcom+0x4a13
06 fffff880`05703210 fffff800`00b99699 kdcom+0x3e4b
07 fffff880`05703250 fffff800`00b9cf1b kdcom+0x1699
08 fffff880`057033a0 fffff800`02a9013d kdcom+0x4f1b
09 fffff880`057034d0 fffff800`02a92a3f nt!KdPollBreakIn+0xec
0a fffff880`05703520 fffff800`02a92741 nt!KeUpdateRunTime+0x13f
0b fffff880`05703550 fffff800`02d43f00 nt!KiSecondaryClockInterrupt+0x131
0c fffff880`057036e0 fffff800`02d8fef6 nt!ExpGetProcessInformation+0x472
0d fffff880`05703830 fffff800`02d90949 nt!ExpQuerySystemInformation+0xfb4
0e fffff880`05703be0 fffff800`02a858d3 nt!NtQuerySystemInformation+0x4d
0f fffff880`05703c20 00000000`7733167a nt!KiSystemServiceCopyEnd+0x13
10 00000000`0e30fd58 00000000`00000000 0x7733167a
3 fffff880037d3180 fffffa802b407060 ( 9) fffff880037ddfc0 ................
# Child-SP RetAddr Call Site
00 fffff880`057d46b0 fffff800`02d43f24 nt!ObReferenceObjectSafe+0xf
01 fffff880`057d46e0 fffff800`02d8fef6 nt!ExpGetProcessInformation+0x496
02 fffff880`057d4830 fffff800`02d90949 nt!ExpQuerySystemInformation+0xfb4
03 fffff880`057d4be0 fffff800`02a858d3 nt!NtQuerySystemInformation+0x4d
04 fffff880`057d4c20 00000000`7733167a nt!KiSystemServiceCopyEnd+0x13
05 00000000`0fdffd58 00000000`00000000 0x7733167a
NtQuerySystemInformation 함수의 원형은 다음과 같다.
NTSTATUS WINAPI NtQuerySystemInformation(
_In_ SYSTEM_INFORMATION_CLASS SystemInformationClass,
_Inout_ PVOID SystemInformation,
_In_ ULONG SystemInformationLength,
_Out_opt_ PULONG ReturnLength
유저 프로세스에서 NtQuerySystemInformation 함수를 사용해서 시스템 정보를 쿼리할 경우 요청한 SystemInformationClass에 맞는 커널 내부 함수가 호출된다.
내부에서 ExpGetProcessInformation 함수가 호출된 것으로 보아 프로세스 정보와 관련된 요청이었을 것이다.
1~3번 프로세서에서 모두 NtQuerySystemInformation 함수가 동작 중이었으므로 이 NtQuerySystemInformation 함수에서 지속적으로 CPU를 사용해서 행을 유발했을 가능성이 매우 높다.
우선 동작 중인 1번 프로세서의 스레드인 fffffa802b3ae060로 컨텍스트를 맞춰 SystemInformationClass가 어떤 값이었는지 확인해보자.
kd> .thread fffffa802b3ae060
Implicit thread is now fffffa80`2b3ae060
kd> kv
*** Stack trace for last set context - .thread/.cxr resets it
# Child-SP RetAddr : Args to Child : Call Site
00 fffff880`041a5660 fffff800`02d44578 : fffff880`00000000 00000000`00000000 00000000`00002500 00000000`00000005 : nt!ExfAcquirePushLockShared+0x21
01 fffff880`041a56e0 fffff800`02d8fef6 : 00000000`02170000 00000000`00010000 fffff880`041a5870 00000000`00000000 : nt!ExpGetProcessInformation+0xaf2 // 2) 프로세스 정보 획득 함수 호출
02 fffff880`041a5830 fffff800`02d90949 : 00000000`02170000 00000000`00000000 00000000`0504fed0 00000000`00000000 : nt!ExpQuerySystemInformation+0xfb4 // 1) SystemInformationClass에 따라 분기
03 fffff880`041a5be0 fffff800`02a858d3 : 00000000`00000001 00000000`0504ecb8 00000000`00000001 000007ff`fffdc000 : nt!NtQuerySystemInformation+0x4d
04 fffff880`041a5c20 00000000`7733167a : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ fffff880`041a5c20)
64비트 콜 스택이므로 첫 번째 파라미터를 찾기가 쉽지 않다. 64비트에서는 스택 포인터인 rsp 기준으로 동작하기 때문인데 이로 인해 k 명령으로 보이는 파라미터 값들은 실제 값과는 다르게 표시될 수 있다(5.3.2 숨겨진 콜 스택 케이스 참고).
그래도 최소한 1)번 쯤에서 SystemInformationClass를 비교하는 부분이 있을 것 같다. ExpQuerySystemInformation+0xfb4 부분을 디스어셈블링해서 살펴보자.
kd> u ExpQuerySystemInformation+0xfb4-3a L10
nt!ExpQuerySystemInformation+0xf78:
fffff800`02d8feba 0000 add byte ptr [rax],al
fffff800`02d8febc 89473c mov dword ptr [rdi+3Ch],eax
fffff800`02d8febf eb05 jmp nt!ExpQuerySystemInformation+0xf84 (fffff800`02d8fec6)
fffff800`02d8fec1 e9c5f2ffff jmp nt!ExpQuerySystemInformation+0x249 (fffff800`02d8f18b)
fffff800`02d8fec6 894c2440 mov dword ptr [rsp+40h],ecx
fffff800`02d8feca 8b742444 mov esi,dword ptr [rsp+44h]
fffff800`02d8fece e9b1f2ffff jmp nt!ExpQuerySystemInformation+0x242 (fffff800`02d8f184)
fffff800`02d8fed3 4183fa05 cmp r10d,5 // 1) SystemInformationClass가 5인지 비교
fffff800`02d8fed7 0f85b93e0500 jne nt! ?? ::NNGAKEGL::`string'+0x58c58 (fffff800`02de3d96) // 2) 5가 아니면 다음 위치로 이동
fffff800`02d8fedd 32c0 xor al,al
fffff800`02d8fedf 88442420 mov byte ptr [rsp+20h],al
fffff800`02d8fee3 4533c9 xor r9d,r9d
fffff800`02d8fee6 4c8d442440 lea r8,[rsp+40h]
fffff800`02d8feeb 418bd5 mov edx,r13d
fffff800`02d8feee 488bcf mov rcx,rdi
fffff800`02d8fef1 e89a3bfbff call nt!ExpGetProcessInformation (fffff800`02d43a90) // 3) 5인 경우 ExpGetProcessInformation 함수 호출
한 번에 찾아서 다행이다. 콜 스택을 보면 ExpGetProcessInformation 함수가 호출되었으므로 첫 번째 파라미터인 SystemInformationClass는 5다.
그렇다면 이제 SystemInformationClass 5번이 무엇을 의미하는지 알아야 한다.
typedef enum SYSTEM_INFORMATION_CLASS {
SystemBasicInformation, // 0
SystemProcessorInformation, // 1
SystemPerformanceInformation, // 2
SystemTimeOfDayInformation, // 3
SystemPathInformation, // 4
SystemProcessesAndThreadsInformation, // 5
SYSTEM_INFORMATION_CLASS의 enum 값을 확인해보면 5는 SystemProcessesAndThreadsInformation을 의미한다.
뭔가 프로세스나 스레드 관련된 정보를 얻을 때 사용하는 값이라고 추측해 볼 수 있다.
앞서 3개의 스레드 모두 ExpGetProcessInformation 함수 안에서 동작이 완료되지 않고 있었다. ExpGetProcessInformation 함수가 문제 발생 위치일 가능성이 높은 상황이다.
uf /c 명령으로 ExpGetProcessInformation 내부에서 호출되는 함수를 살펴보자.
kd> uf /c ExpGetProcessInformation
nt!ExpGetProcessInformation (fffff800`02d43a90)
nt!ExpGetProcessInformation+0x7a (fffff800`02d43b0a):
call to nt!KeFlushProcessWriteBuffers (fffff800`02a5bf7c)
nt!ExpGetProcessInformation+0xc9 (fffff800`02d43b58):
call to nt!PsGetProcessSessionId (fffff800`02a4bf94)
nt!ExpGetProcessInformation+0x146 (fffff800`02d43bd5):
call to nt!ExpCopyProcessInfo (fffff800`02d44c04)
nt!ExpGetProcessInformation+0x1d6 (fffff800`02d43c65):
call to nt!PsGetNextProcessThread (fffff800`02d278a8)
nt!ExpGetProcessInformation+0x24a (fffff800`02d43cd8):
call to nt!KeQueryValuesThread (fffff800`02a5bb50)
nt!ExpGetProcessInformation+0x491 (fffff800`02d43f1f):
call to nt!ObReferenceObjectSafe (fffff800`02aa2c00)
nt!ExpGetProcessInformation+0x4ea (fffff800`02d43f78):
call to nt!ObfDereferenceObject (fffff800`02a90440)
nt!ExpGetProcessInformation+0x541 (fffff800`02d43fcf):
call to nt!SeLocateProcessImageName (fffff800`02d279bc)
nt!ExpGetProcessInformation+0x631 (fffff800`02d440be):
call to nt!memmove (fffff800`02a7cff0)
nt!ExpGetProcessInformation+0x6bb (fffff800`02d44148):
call to nt!ExFreePoolWithTag (fffff800`02bb1d90)
nt!ExpGetProcessInformation+0x76f (fffff800`02d441fc):
call to nt!PsGetNextProcess (fffff800`02d44928) // 지연 의심 함수
nt!ExpGetProcessInformation+0x820 (fffff800`02d442ad):
call to nt!ExFreePoolWithTag (fffff800`02bb1d90)
nt!ExpGetProcessInformation+0xaaa (fffff800`02d44530):
call to nt!KeSynchronizeWithThreadInitialization (fffff800`02b25310)
nt!ExpGetProcessInformation+0xaed (fffff800`02d44573):
call to nt!ExfAcquirePushLockShared (fffff800`02ab6f20)
... ...
PETHREAD
PsGetNextProcessThread (
IN PEPROCESS Process,
IN PETHREAD Thread
첫 번째 파라미터가 프로세스 오브젝트인 것을 기억하자. 이제 PsGetNextProcessThread 함수를 디스어셈블링해서 살펴보자.
kd> u PsGetNextProcessThread L20
nt!PsGetNextProcessThread:
fffff800`02d278a8 48895c2408 mov qword ptr [rsp+8],rbx
fffff800`02d278ad 48896c2410 mov qword ptr [rsp+10h],rbp
fffff800`02d278b2 4889742418 mov qword ptr [rsp+18h],rsi
fffff800`02d278b7 57 push rdi
fffff800`02d278b8 4154 push r12
fffff800`02d278ba 4155 push r13
fffff800`02d278bc 4156 push r14
fffff800`02d278be 4157 push r15
fffff800`02d278c0 4883ec20 sub rsp,20h
fffff800`02d278c4 65488b3c2588010000 mov rdi,qword ptr gs:[188h]
fffff800`02d278cd 4533ff xor r15d,r15d
fffff800`02d278d0 488bf2 mov rsi,rdx
fffff800`02d278d3 66ff8fc4010000 dec word ptr [rdi+1C4h]
fffff800`02d278da 4d8bf7 mov r14,r15
fffff800`02d278dd 4c8da108030000 lea r12,[rcx+308h] // 1) 프로세스의 스레드 리스트 획득
fffff800`02d278e4 418bef mov ebp,r15d
fffff800`02d278e7 4c8da960010000 lea r13,[rcx+160h]
fffff800`02d278ee 33c0 xor eax,eax
fffff800`02d278f0 418d4f11 lea ecx,[r15+11h]
fffff800`02d278f4 f0490fb14d00 lock cmpxchg qword ptr [r13],rcx
fffff800`02d278fa 0f8594000000 jne nt!PsGetNextProcessThread+0xec (fffff800`02d27994)
fffff800`02d27900 493bf7 cmp rsi,r15
fffff800`02d27903 7575 jne nt!PsGetNextProcessThread+0xd2 (fffff800`02d2797a)
fffff800`02d27905 498b1c24 mov rbx,qword ptr [r12] // 2) 스레드 리스트의 Flink 획득
fffff800`02d27909 493bdc cmp rbx,r12 // 3) 리스트의 끝이면 종료하고 아니면 계속 루프를 돌게 되는 비교문
fffff800`02d2790c 747f je nt!PsGetNextProcessThread+0xe5 (fffff800`02d2798d)
fffff800`02d2790e 4c8db3e0fbffff lea r14,[rbx-420h]
fffff800`02d27915 498bce mov rcx,r14
fffff800`02d27918 e8e3b2d7ff call nt!ObReferenceObjectSafe (fffff800`02aa2c00)
fffff800`02d2791d 413ac7 cmp al,r15b
fffff800`02d27920 0f8485000000 je nt!PsGetNextProcessThread+0x103 (fffff800`02d279ab)
fffff800`02d27926
bb01000000 mov ebx,1
1)번을 보면 rcx+308을 참조하는 명령이 있는데 rcx 는 첫 번째 파라미터다. 이는 프로세스 오브젝트이므로 EPROCESS구조체의 +308 필드를 확인하면 된다.
kd> dt _EPROCESS ThreadListHead
nt!_EPROCESS
+0x308 ThreadListHead : _LIST_ENTRY
1)~3)번을 보면 EPROCESS 구조체의 +308 위치에 있는 ThreadListHead 리스트의 스레드 목록을 열거하고 있다.
링크드 리스트의 경우 리스트 목록이 증가하면 리스트 열거시 목록과 비례해서 성능 지연이 발생한다. 따라서 앞서 이 함수를 지연 의심 함수로 언급한 것이다.
혹시 시스템에 스레드가 엄청 많이 생성되어 ThreadListHead 리스트가 엄청 증가한 것은 아닐까?
이를 검증하려면 시스템의 모든 프로세스를 확인해서 이상한 부분은 없는지 살펴봐야 한다.
!for_each_process 명령을 사용하면 전체 프로세스의 간략한 정보를 알 수 있다.
kd> !for_each_process
PROCESS fffffa8000cda400
SessionId: none Cid: 0004 Peb: 00000000 ParentCid: 0000
DirBase: 00187000 ObjectTable: fffff8a0000017e0 HandleCount: 501525.
Image: System
PROCESS fffffa8002243b30
SessionId: none Cid: 0118 Peb: 7fffffd8000 ParentCid: 0004
DirBase: 24f55000 ObjectTable: fffff8a0004cce60 HandleCount: 32.
Image: smss.exe
PROCESS fffffa80021476f0
SessionId: 0 Cid: 017c Peb: 7fffffd7000 ParentCid: 016c
DirBase: 1cc2d000 ObjectTable: fffff8a000113630 HandleCount: 443.
Image: csrss.exe
PROCESS fffffa8002c02060
SessionId: 0 Cid: 01a4 Peb: 7fffffdd000 ParentCid: 016c
DirBase: 1c833000 ObjectTable: fffff8a005cca010 HandleCount: 77.
Image: wininit.exe
PROCESS fffffa80028d1060
SessionId: 1 Cid: 01b0 Peb: 7fffffd7000 ParentCid: 019c
DirBase: 19f96000 ObjectTable: fffff8a005ce5c20 HandleCount: 511.
Image: csrss.exe
PROCESS fffffa8002c08060
SessionId: 1 Cid: 01e8 Peb: 7fffffdf000 ParentCid: 019c
DirBase: 1999c000 ObjectTable: fffff8a005dae700 HandleCount: 121.
Image: winlogon.exe
PROCESS fffffa8002c874a0
SessionId: 0 Cid: 0218 Peb: 7fffffdf000 ParentCid: 01a4
DirBase: 1b6cc000 ObjectTable: fffff8a001242560 HandleCount: 230.
Image: services.exe
PROCESS fffffa8002c95770
SessionId: 0 Cid: 0224 Peb: 7fffffdf000 ParentCid: 01a4
DirBase: 1aaa4000 ObjectTable: fffff8a005d78ec0 HandleCount: 569.
Image: lsass.exe
PROCESS fffffa8002c9ab30
SessionId: 0 Cid: 022c Peb: 7fffffdf000 ParentCid: 01a4
DirBase: 1a72e000 ObjectTable: fffff8a005d7e9f0 HandleCount: 148.
Image: lsm.exe
... ...
이럴수가! 첫 번째 System 프로세스의 HandleCount를 보니 501,525개다. 50만 개가 넘는 핸들이 무지막지하게 열려 있는 상태다(보통의 정상적인 프로세스라면 수백~수천개 정도의 핸들만 유지하므로 비정상적인 수치다).
아무래도 시스템에 핸들 누수(Leak)가 발생하고 있는 심각한 상태로 의심된다.
이제 !handle 명령을 통해 Sysem 프로세스인 fffffa8000cda400의 모든 핸들 내역을 확인해보자.
kd> !handle 0 f fffffa80`075a8990
... ...
3734: Object: fffffa80014da060 GrantedAccess: 001fffff Entry: fffff8a00300bcd0
Object: fffffa80014da060 Type: (fffffa8000cdac40) Thread
ObjectHeader: fffffa80014da030 (new version)
HandleCount: 1 PointerCount: 1
3738: Object: fffffa80014dab60 GrantedAccess: 001fffff Entry: fffff8a00300bce0
Object: fffffa80014dab60 Type: (fffffa8000cdac40) Thread
ObjectHeader: fffffa80014dab30 (new version)
HandleCount: 1 PointerCount: 1
373c: Object: fffffa80014da660 GrantedAccess: 001fffff Entry: fffff8a00300bcf0
Object: fffffa80014da660 Type: (fffffa8000cdac40) Thread
ObjectHeader: fffffa80014da630 (new version)
HandleCount: 1 PointerCount: 1
3740: Object: fffffa80014db060 GrantedAccess: 001fffff Entry: fffff8a00300bd00
Object: fffffa80014db060 Type: (fffffa8000cdac40) Thread
ObjectHeader: fffffa80014db030 (new version)
HandleCount: 1 PointerCount: 1
3744: Object: fffffa80014dbb60 GrantedAccess: 001fffff Entry: fffff8a00300bd10
Object: fffffa80014dbb60 Type: (fffffa8000cdac40) Thread
ObjectHeader: fffffa80014dbb30 (new version)
HandleCount: 1 PointerCount: 1
3748: Object: fffffa80014db660 GrantedAccess: 001fffff Entry: fffff8a00300bd20
Object: fffffa80014db660 Type: (fffffa8000cdac40) Thread
ObjectHeader: fffffa80014db630 (new version)
HandleCount: 1 PointerCount: 1
374c: Object: fffffa80014dc060 GrantedAccess: 001fffff Entry: fffff8a00300bd30
Object: fffffa80014dc060 Type: (fffffa8000cdac40) Thread
ObjectHeader: fffffa80014dc030 (new version)
HandleCount: 1 PointerCount: 1
3750: Object: fffffa80014dcb60 GrantedAccess: 001fffff Entry: fffff8a00300bd40
Object: fffffa80014dcb60 Type: (fffffa8000cdac40) Thread
ObjectHeader: fffffa80014dcb30 (new version)
HandleCount: 1 PointerCount: 1
... ...
대부분 스레드 핸들로 확인된다. 참조 카운트인 HandleCount와 PointerCount는 각각 1이다.
50만 개가 넘는 스레드 핸들이 아직 열려 있는 상태이므로 ThreadListHead 리스트는 이미 열거가 불가능할 정도로 수 많은 스레드 목록이 추가된 상태일 것이다. 의심이 확신이 되는 순간이다.
이제 시스템을 이렇게 엉망으로 만든 범인을 찾기 위해 스레드를 자세히 확인해야 한다. 임의의 스레드 하나를 선택해 상태를 살펴보자.
kd> !thread fffffa80014dcb60
THREAD fffffa80014dcb60 Cid 0004.38d4 Teb: 0000000000000000 Win32Thread: 0000000000000000 TERMINATED // 종료된 상태
Not impersonating
DeviceMap fffff8a000008aa0
Owning Process fffffa8000cda400 Image: System
Attached Process N/A Image: N/A
Wait Start TickCount 0 Ticks: 40554 (0:00:10:33.656)
Context Switch Count 1 IdealProcessor: 3
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address MyDrv (0xfffff88002e4d3e0)
Stack Init 0 Current fffff880031a69f0
Base fffff880031a7000 Limit fffff880031a1000 Call 0
Priority
8 BasePriority 8 UnusualBoost 0 ForegroundBoost 0 IoPriority 2 PagePriority 5
이미 종료된 TERMINATED 상태의 스레드다. 이어 다른 스레드도 몇 개 확인해보니 모두TERMINATED 상태다. 참조 카운트가 아직 남아 있으므로 오픈된 핸들을 해제하지 않고 스레드가 종료된 상황으로 보인다.
왜냐하면 스레드가 종료될 때 참조 카운트가 0이 아니면 스레드가 제거되지 않고 TERMINATED 상태로 남기 때문이다.
50만개의 스레드가 시스템을 재부팅하기 전까지는 영원히 죽지 못하는 좀비 상태가 돼버렸다.
스레드 핸들이 모두 System 프로세스의 핸들 테이블에 있는 부분에 집중할 필요가 있다.
System 프로세스의 핸들 테이블은 커널 핸들의 테이블로 보통 커널 드라이버에서 nt!PsCreateSystemThread 함수를 통해 시스템 스레드를 생성할 경우 여기에 핸들이 생성된다.
이런 상황이면 커널 핸들을 생성하고 해제하지 않는 커널 드라이버가 범인일 가능성이 매우 높다.
스레드의 Win32 Start Address 정보를 보면 좀비 상태의 스레드 시작 주소가 MyDrv 모듈의 주소로 확인된다. MyDrv 모듈에서 생성한 스레드가 해제되고 있지 않은 상황이다. 따라서 스레드 생성 주체인 MyDrv 모듈이 강력한 용의자다.
최종 확인을 위해 !stacks 명령으로 전체 콜 스택에서 MyDrv의 동작을 살펴보자.
kd> !stacks 2 MyDrv
Proc.Thread .Thread Ticks ThreadState Blocker
[fffff80002c071c0 Idle]
[fffffa8000cda400 System]
4.1eac64 fffffa8003143b60 ffff623d READY nt!KiSwapContext+0x7a
nt!KiQuantumEnd+0x1b4
nt!KiDispatchInterruptContinue+0x16
nt!KiDpcInterruptBypass+0x13
nt!KiSecondaryClockInterrupt+0x1a8
nt!ExfAcquirePushLockExclusive+0xd2
nt!PspInsertThread+0x829
nt!PspCreateThread+0x246
nt!PsCreateSystemThread+0x125
MyDrv+0x1505
nt!PspSystemThreadStartup+0x5a
nt!KiStartSystemThread+0x16
... ...
역시 System 프로세스 중 fffffa8003143b60 스레드에서 지속적으로 시스템 스레드를 생산하고 있다!
이렇게 생성한 스레드를 정상적으로 해제하지 않아 좀비로 만든 것이다.
결국 행이 발생한 원인은 MyDrv 모듈에서 수 많은 시스템 스레드를 생성하면서 해제하지 않았고, 이어 NtQuerySystemInformation 함수 내부에서는 다량의 스레드를 열거하느라 CPU 사용율을 증가시켰기 때문이다.
MyDrv 모듈에 의해 좀비 스레드는 계속 증가하는데 NtQuerySystemInformation 함수는 매우 빈번하게 호출되므로 시스템은 아마 사용이 불가능할 정도로 끔찍하게 느려졌을 것이다.
어쨌든 원인을 찾아 정말 다행이다. 이제 남은 일은 MyDrv 모듈에서 시스템 스레드를 생성하고 해제하지 않은 부분을 찾아 문제를 고치는 것이다.
'Dump Analysis' 카테고리의 다른 글
| [0x133] DPC_WATCHDOG_VIOLATION (0) | 2018.07.29 |
|---|---|
| [0xC5] 해제 리스트 손상 (0) | 2018.07.19 |
| [0xC5] 풀 헤더 손상 (0) | 2018.07.16 |
| [0x1A] 페이지 손상 (0) | 2018.07.12 |
| [0x50] 해제된 핸들 (0) | 2018.07.09 |
이번 덤프는 윈도우 8과 서버 2012부터 많은 사람들을 괴롭혔던 BugCheck 0x133: DPC_WATCHDOG_VIOLATION 이라는 특이한 오류다.
이 오류는 BugCheck 0x7F_8에 해당하는 커널 스택 오버 플로우와 매우 유사하다. 커널 스택 오버 플로우가 커널 스택에 대한 사용량 문제라면 0x133은 커널 시간에 대한 사용량 문제다. 커널에서는 일반적인 요청보다 좀 더 중요한 일을 처리해야 할 때 DPC(Deferred Procudure Call)/Dispatch라는 인터럽트 레벨에서 동작하게 된다. 문제는 이 DPC/Dispatch 레벨이 스레드 스케쥴링 등의 운영체제 주요 동작보다도 더 높은 레벨이라 DPC/Dispatch 레벨에서 작업이 지연되면 시스템이 느려지거나 행 증상이 발생할 수도 있다. 물론 운영체제만 사용 가능한 인터럽트 레벨이라면 큰 문제가 없겠지만 불행히도 DPC/Dispatch 레벨은 커널 드라이버라면 스핀락(SpinLock) 함수를 통해 쉽게 사용 가능하다. 상황이 이렇다보니 잘못 작성된 커널 드라이버가 스핀락을 획득하고 오랜 시간 반환하지 않으면 시스템이 멈추는 불상사가 발생한다. 이 문제를 해결하기 위해 새로 추가된 오류 코드가 바로 0x133이다. 커널에서는 별도의 감시자(Watchdog)를 통해 DPC/Dispatch 레벨에서의 동작 시간이 정해진 제한 시간(Time Out)을 넘으면 지체없이 이 오류 코드를 발생시킨다. 여러 모듈이 지연시키는 경우도 각각 동작 시간을 누적하여 제한 시간을 넘기면 이 오류 코드가 발생할 수 있다. 따라서 원인 분석을 위해 성능 지연 구간에 대한 별도의 성능 로그를 수집해야 할 수도 있다. 나는 이런 점에서 0x133을 매우 어려운 커널 스택 오버 플로우 이슈 정도로 생각한다.
물론 여기서는 덤프에서 원인 분석이 가능하도록 단일 모듈에서 성능 지연이 발생한 경우를 살펴볼 것이다.
먼저 !analyze -v 명령을 통해 기본 분석부터 시작해보자.
kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************
DPC_WATCHDOG_VIOLATION (133)
The DPC watchdog detected a prolonged run time at an IRQL of DISPATCH_LEVEL
or above.
Arguments:
Arg1: 00000001, The system cumulatively spent an extended period of time at
DISPATCH_LEVEL or above. The offending component can usually be
identified with a stack trace.
Arg2: 00001e00, The watchdog period.
Arg3: 00000000, cast to nt!DPC_WATCHDOG_GLOBAL_TRIAGE_BLOCK, which contains
additional information regarding the cumulative timeout
Arg4: 00000000
Debugging Details:
------------------
DUMP_CLASS: 1
DUMP_QUALIFIER: 401
BUILD_VERSION_STRING: 14393.693.x86fre.rs1_release.161220-1747
SYSTEM_MANUFACTURER: SAMSUNG ELECTRONICS CO.,LTD
SYSTEM_PRODUCT_NAME: Samsung Desktop System
SYSTEM_SKU: System SKUNumber
SYSTEM_VERSION: CAAAAAAF
BIOS_VENDOR: SAMSUNG ELECTRONICS CO.,LTD
BIOS_VERSION: 04NS
BIOS_DATE: 08/16/2011
BASEBOARD_MANUFACTURER: SAMSUNG ELECTRONICS CO.,LTD
BASEBOARD_PRODUCT: Samsung DeskTop System
BASEBOARD_VERSION: CAAAAAAA
DUMP_TYPE: 1
BUGCHECK_P1: 1
BUGCHECK_P2: 1e00
BUGCHECK_P3: 0
BUGCHECK_P4: 0
DPC_TIMEOUT_TYPE: DPC_QUEUE_EXECUTION_TIMEOUT_EXCEEDED
CPU_COUNT: 4
CPU_MHZ: cdd
CPU_VENDOR: GenuineIntel
CPU_FAMILY: 6
CPU_MODEL: 2a
CPU_STEPPING: 7
CPU_MICROCODE: 6,2a,7,0 (F,M,S,R) SIG: 29'00000000 (cache) 29'00000000 (init)
DEFAULT_BUCKET_ID: WIN8_DRIVER_FAULT
BUGCHECK_STR: 0x133
PROCESS_NAME: SMSS.exe
CURRENT_IRQL: 1c
ANALYSIS_SESSION_HOST: PAUL-PC
ANALYSIS_SESSION_TIME: 06-11-2018 22:34:11.0900
ANALYSIS_VERSION: 10.0.16299.91 amd64fre
LAST_CONTROL_TRANSFER: from 81b48d4e to 81b284a8
STACK_TEXT:
d461b7d4 81b48d4e 00000133 00000001 00001e00 nt!KeBugCheckEx
d461b804 81a3b08c 85dc5120 00000002 00000000 nt! ?? ::FNODOBFM::`string'+0x9eae
d461b8d0 820336b7 81a3d64d 00000000 d461ba14 nt!KeClockInterruptNotify+0x36c
d461b8e0 82044cdb 00000002 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3f
d461b8e0 81a3d64d 00000002 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1f7
d461b9f0 81ba85d0 c786f3b8 8833d980 83000100 nt!KxWaitForSpinLockAndAcquire+0x1d
d461ba14 81a54003 00000000 830001c8 883125c7 nt!KiAcquireSpinLockInstrumented+0x53
d461ba20 883125c7 0032a582 d461bae0 8831f149 nt!KfAcquireSpinLock+0x33
d461ba2c 8831f149 8a352a0a c786f3b8 00000000 SomeDrv+0x25c7
d461bae0 81ca719d c786f3b8 00000001 00000000 SomeDrv+0xf149
d461bbb8 81ca6f6a 00000000 00000000 042ffdc8 nt!IopXxxControlFile+0x21d
d461bbe4 81b36987 00000300 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
d461bbe4 77ce4d50 00000300 00000000 00000000 nt!KiSystemServicePostCall
042ffde8 00000000 00000000 00000000 00000000 0x77ce4d50
THREAD_SHA1_HASH_MOD_FUNC: 2a46f69c6139803d83a04cedcad275f72ac07d42
THREAD_SHA1_HASH_MOD_FUNC_OFFSET: 6f2b762ab8d468cacab44d7f866169a56cdce50c
THREAD_SHA1_HASH_MOD: bd912fdd2f42d7d45cc2017c378e8c588d451ef1
FOLLOWUP_IP:
SomeDrv+25c7
883125c7 8845fe mov byte ptr [ebp-2],al
FAULT_INSTR_CODE: 81fe4588
SYMBOL_STACK_INDEX: 8
SYMBOL_NAME: SomeDrv+25c7
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: SomeDrv
IMAGE_NAME: SomeDrv.sys
DEBUG_FLR_IMAGE_TIMESTAMP: 57fde77c
STACK_COMMAND: .thread ; .cxr ; kb
BUCKET_ID_FUNC_OFFSET: 25c7
FAILURE_BUCKET_ID: 0x133_ISR_SomeDrv!unknown_function
BUCKET_ID: 0x133_ISR_SomeDrv!unknown_function
PRIMARY_PROBLEM_CLASS: 0x133_ISR_SomeDrv!unknown_function
TARGET_TIME: 2017-02-27T00:48:23.000Z
OSBUILD: 14393
OSSERVICEPACK: 0
SERVICEPACK_NUMBER: 0
OS_REVISION: 0
SUITE_MASK: 272
PRODUCT_TYPE: 1
OSPLATFORM_TYPE: x86
OSNAME: Windows 10
OSEDITION: Windows 10 WinNt TerminalServer SingleUserTS
OS_LOCALE:
USER_LCID: 0
OSBUILD_TIMESTAMP: 2016-12-21 13:24:07
BUILDDATESTAMP_STR: 161220-1747
BUILDLAB_STR: rs1_release
BUILDOSVER_STR: 10.0.14393.693.x86fre.rs1_release.161220-1747
ANALYSIS_SESSION_ELAPSED_TIME: ece
ANALYSIS_SOURCE: KM
FAILURE_ID_HASH_STRING: km:0x133_isr_SomeDrv!unknown_function
FAILURE_ID_HASH: {c26eac98-dd1d-7af7-3055-fbbff800604a}
Followup: MachineOwner
---------
출력 결과 중 BugCheck 파라미터 부분을 유심히 살펴보면 대략적인 발생 원인을 이해할 수 있다.
Arg1: 00000001, The system cumulatively spent an extended period of time at
DISPATCH_LEVEL or above. The offending component can usually be
identified with a stack trace.
Arg2: 00001e00, The watchdog period.
첫 번째 파라미터는 1이며, 시스템이 DISPATCH_LEVEL 이상에서 장시간 동작한 것이 원인이라고 말한다. 스택 추적을 통해 문제를 일으킨 원인을 확인할 수 있다고도 언급한다.
두 번째 파라미터는 감시 중인 제한 시간으로 Tick 단위다. 하나 혹은 복수의 커널 드라이버가 DISPATCH_LEVEL 이상에서 동작한 누적 시간 값이 제한 시간을 넘길 경우 이 오류가 발생한다.
이를 통해 누군가 DISPATCH_LEVEL 이상에서 0x1e00(7,680) Tick 만큼 장시간 동작한 것이 문제의 원인 임을 짐작할 수 있다. 커널에서 성능 지연이 감지되면 시스템을 멈추는 방식이므로 문제 발생 당시 실행 중인 스레드가 범인일 가능성이 높다. 첫 번째 파라미터 설명에서 실행 중인 콜 스택을 살펴보라는 것도 그런 이유에서다.
그렇다면 !thread 명령으로 현재 실행 중인 스레드 정보를 확인해보자.
kd> !thread
THREAD d8e548c0 Cid 2978.2c68 Teb: 0157e000 Win32Thread: 00000000 RUNNING on processor 0
Not impersonating
DeviceMap 88a03058
Owning Process d8bc6800 Image: SMSS.exe
Attached Process N/A Image: N/A
Wait Start TickCount 39290 Ticks: 7680 (0:00:02:00.000)
Context Switch Count 3651 IdealProcessor: 0
UserTime 00:00:00.062
KernelTime 00:02:00.046
Win32 Start Address 0x0fb738e0
Stack Init d461bca0 Current d461ba2c Base d461c000 Limit d4619000 Call 00000000
Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
ChildEBP RetAddr Args to Child
d461b7d4 81b48d4e 00000133 00000001 00001e00 nt!KeBugCheckEx
d461b804 81a3b08c 85dc5120 00000002 00000000 nt! ?? ::FNODOBFM::`string'+0x9eae
d461b8d0 820336b7 81a3d64d 00000000 d461ba14 nt!KeClockInterruptNotify+0x36c (FPO: [Non-Fpo])
d461b8e0 82044cdb 00000002 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3f (FPO: [0,0,4])
d461b8e0 81a3d64d 00000002 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1f7 (FPO: [0,2] TrapFrame @ d461b978)
d461b9f0 81ba85d0 c786f3b8 8833d980 83000100 nt!KxWaitForSpinLockAndAcquire+0x1d (FPO: [0,0,0])
d461ba14 81a54003 00000000 830001c8 883125c7 nt!KiAcquireSpinLockInstrumented+0x53 (FPO: [Non-Fpo])
d461ba20 883125c7 0032a582 d461bae0 8831f149 nt!KfAcquireSpinLock+0x33 (FPO: [0,0,0])
d461ba2c 8831f149 8a352a0a c786f3b8 00000000 SomeDrv+0x25c7
d461bae0 81ca719d c786f3b8 00000001 00000000 SomeDrv+0xf149
d461bbb8 81ca6f6a 00000000 00000000 042ffdc8 nt!IopXxxControlFile+0x21d (FPO: [Non-Fpo])
d461bbe4 81b36987 00000300 00000000 00000000 nt!NtDeviceIoControlFile+0x2a (FPO: [Non-Fpo])
d461bbe4 77ce4d50 00000300 00000000 00000000 nt!KiSystemServicePostCall (FPO: [0,3] TrapFrame @ d461bc14)
042ffde8 00000000 00000000 00000000 00000000
0x77ce4d50
스레드 정보의 Ticks 필드를 보면 정확하게 7680(0x1e00) Tick이 경과했음을 알 수 있다. 2분의 시간이 경과한 순간 커널이 제한 시간을 다 사용한 것으로 판단하여 0x133을 발생시킨 것이다.
이번에는 k명령으로 스레드의 콜 스택을 분석하며 문제가 발생한 상황을 좀 더 이해해보자.
kd> k
# ChildEBP RetAddr
00 d461b7d4 81b48d4e nt!KeBugCheckEx ç 3) 제한 시간이 경과하여 BSOD 발생
01 d461b804 81a3b08c nt! ?? ::FNODOBFM::`string'+0x9eae
02 d461b8d0 820336b7 nt!KeClockInterruptNotify+0x36c
03 d461b8e0 82044cdb hal!HalpTimerClockInterruptCommon+0x3f
04 d461b8e0 81a3d64d hal!HalpTimerClockInterrupt+0x1f7
05 d461b9f0 81ba85d0 nt!KxWaitForSpinLockAndAcquire+0x1d ç 2) 스핀락 획득 시도 중
06 d461ba14 81a54003 nt!KiAcquireSpinLockInstrumented+0x53
07 d461ba20 883125c7 nt!KfAcquireSpinLock+0x33
08 d461ba2c 8831f149 SomeDrv+0x25c7 ç 1) SomeDrv 모듈에서 스핀락 획득 함수 호출
09 d461bae0 81ca719d SomeDrv+0xf149
0a d461bbb8 81ca6f6a nt!IopXxxControlFile+0x21d
0b d461bbe4 81b36987 nt!NtDeviceIoControlFile+0x2a
0c d461bbe4 77ce4d50 nt!KiSystemServicePostCall
0d 042ffde8 00000000 0x77ce4d50
콜 스택을 보면 1)번에서 SomeDrv 모듈이 스핀락을 얻으려고 시도하고 있다. 하지만 스핀락을 획득하지 못해 2)번에서 nt! KxWaitForSpinLockAndAcquire 함수를 통해 획득하기를 기다리고 있다. 동작 자체로는 아무 문제가 없지만 락 획득을 빨리 하지 못한 것이 문제의 원인이다. 무려 2분 동안 락을 획득하지 못하고 있는 것은 정상적인 상황이 아니다. 하지만 이 문제를 분석하기에 앞서 확인해야할 부분이 하나 있다.
앞서 0x133이 발생하려면 제한 시간 외에도 인터럽트 레벨이 DISPATCH_LEVEL 이상이라는 조건이 있었다. 제한 시간 조건은 스레드의 Ticks 정보를 통해 만족함을 확인했지만 인터럽트 레벨 조건은 아직 확인하지 못했다.
문제 발생 당시 인터럽트 레벨을 어떻게 알 수 있을까? 문제의 콜 스택에서 스핀락을 얻으려는 부분이 보이는가? 커널에서 락이나 이벤트를 사용할 경우 내부에서는 동기화를 위해 인터럽트 레벨을 변경하는 경우가 많이 있다. 그렇다면 nt!KfAcquireSpinLock 함수를 디스어셈블링해서 인터럽트 레벨을 변경하는 부분이 있는지 살펴보면 답을 알 수 있다.
kd> u nt!KfAcquireSpinLock
nt!KfAcquireSpinLock:
81a53fd0 8bff mov edi,edi
81a53fd2 53 push ebx
81a53fd3 56 push esi
81a53fd4 8bf1 mov esi,ecx
81a53fd6 ff153891c381 call dword ptr [nt!_imp__KeRaiseIrqlToDpcLevel (81c39138)]
81a53fdc f60506b9c48121 test byte ptr [nt!PerfGlobalGroupMask+0x6 (81c4b906)],21h
81a53fe3 8ad8 mov bl,al
81a53fe5 7515 jne nt!KfAcquireSpinLock+0x2c (81a53ffc)
다행히 시작 부분에 KeRaiseIrqlToDpcLevel 함수를 통해 인터럽트 레벨을 Dpc/Dispatch로 상승시키는 코드가 확인된다. 0x133을 발생시키는 인터럽트 레벨과 제한 시간 조건 모두를 만족하는 상황이므로 SomeDrv 모듈에서 스핀락을 획득하는 동작이 문제의 발단이다.
이제 오랜 시간 동안 스핀락을 획득하지 못한 원인을 밝혀내야 한다. 먼저 스핀락을 획득하는 함수인 nt!KfAcquireSpinLock 함수의 원형을 살펴보자.
KIRQL
FASTCALL
KfAcquireSpinLock(
_Inout_ PKSPIN_LOCK SpinLock
);
<wdm.h>
typedef ULONG_PTR KSPIN_LOCK;
typedef KSPIN_LOCK *PKSPIN_LOCK;
KSPIN_LOCK 구조체의 포인터를 파라미터로 전달받고 있다. 뭔가 특별한 락 구조체인 것처럼 보이지만 wdm.h 헤더 파일을 보면 실은 단순한 unsigned long 변수다. 스핀락은 바로 이 변수를 통해 테스트 앤 셋(Test And Set) 방식으로 동기화를 수행한다. 이 방식을 단순하게 설명하면 락 변수 값이 0이면 스핀락 획득시 변수를 1로 설정하고 락 반환시 0으로 복원한다. 이미 1인 상태에서 스핀락 획득을 시도하면 0이 되길 지속적으로 기다린다(루프를 돌면서 기다리는 이 동작 때문에 스핀락이라고 부른다).
다시 본론으로 돌아와서 이번에는 nt! KfAcquireSpinLock 함수에 전달된 KSPIN_LOCK 변수가 정상인지 확인해야 한다. 콜 스택에서 nt!KfAcquireSpinLock 함수를 호출한 1)번 부분을 디스어셈블링해보자.
kd> ub SomeDrv+0x25c7
SomeDrv+0x25b1:
883125b1 cc int 3
883125b2 8bff mov edi,edi
883125b4 55 push ebp
883125b5 8bec mov ebp,esp
883125b7 51 push ecx
883125b8 c645ff00 mov byte ptr [ebp-1],0
883125bc b980d93388 mov ecx,offset SomeDrv+0x2d980 (8833d980) ç 1) 파라미터
883125c1 ff1508e03288 call
dword ptr [SomeDrv+0x1e008 (8832e008)] ç 2) nt!KfAcquireSpinLock 함수 호출
nt!KfAcquireSpinLock 함수 원형을 보면 호출 규약이 FASTCALL 이므로 첫 번째 파라미터는 ecx에 설정된다. 1)번을 보면 SomeDrv+0x2d980 위치의 값을 ecx에 설정하고 있다. 바로 SomeDrv+0x2d980가 KSPIN_LOCK 구조체 변수의 주소다. 2)번에서 호출된 함수는 ln 명령을 사용하면 nt!KfAcquireSpinLock 함수 임을 쉽게 알 수 있다.
kd> ln poi(8832e008)
Browse module
Set bu breakpoint
(81a53fd0) nt!KfAcquireSpinLock | (81a54010) nt!KfReleaseSpinLock
Exact matches:
nt!KfAcquireSpinLock (<no parameter info>)
KSPIN_LOCK 구조체 위치인 SomeDrv+0x2d980 주소도 dd 명령으로 확인해보자.
kd> dd SomeDrv+0x2d980 L1
8833d980 00490057
어라? KSPIN_LOCK 구조체 주소인 8833d980에 저장된 값이 뭔가 이상하다. 스핀락 획득 유무에 따라 0 아니면 1이 있어야 하는데 00490057이라는 비정상적인 값이 들어 있다. 왠지 불길한 예감이 든다. 이럴 때는 db 명령을 통해 8833d980 주소의 메모리를 확인해보면 의외의 단서를 찾을 수 있다.
kd> db 8833d980
8833d980 57 00 49 00 4e 00 44 00-4f 00 57 00 53 00 5c 00 W.I.N.D.O.W.S.\.
8833d990 53 00 59 00 53 00 54 00-45 00 4d 00 33 00 32 00 S.Y.S.T.E.M.3.2.
8833d9a0 5c 00 44 00 4e 00 53 00-41 00 50 00 49 00 2e 00 \.D.N.S.A.P.I...
8833d9b0 44 00 4c 00 4c 00 00 00-59 00 53 00 54 00 45 00 D.L.L...Y.S.T.E.
8833d9c0 4d 00 33 00 32 00 5c 00-44 00 4e 00 53 00 41 00 M.3.2.\.D.N.S.A.
8833d9d0 50 00 49 00 2e 00 44 00-4c 00 4c 00 43 00 3a 00 P.I...D.L.L.C.:.
8833d9e0 5c 00 57 00 49 00 4e 00-44 00 4f 00 57 00 53 00 \.W.I.N.D.O.W.S.
8833d9f0 5c 00
53 00 59 00 53 00-54 00 45 00 4d 00 33 00
\.S.Y.S.T.E.M.3.
역시 00490057은 KSPIN_LOCK 구조체의 정상적인 값이 아닌 어떤 문자열 값의 일부분이다. du 명령으로 약간 앞 쪽을 살펴보면 왠지 전체 문자열을 알 수 있을 것 같다.
kd> du 8833d980-6
8833d97a
"C:\WINDOWS\SYSTEM32\DNSAPI.DLL"
아하! "C:\WINDOWS\SYSTEM32\DNSAPI.DLL"이라는 파일 경로 문자열이 들어 있다. 아무래도 누군가 KSPIN_LOCK 구조체 위치에 이 문자열을 덮어 써버려 메모리를 손상시킨 것 같다. 정말 메모리 손상이 문제의 원인이 맞는지 알려면 스핀락을 획득하는 부분을 조금 더 분석할 필요가 있다. kv 명령으로 콜 스택을 다시 확인해보자.
kd> kv
# ChildEBP RetAddr Args to Child
00 d461b7d4 81b48d4e 00000133 00000001 00001e00 nt!KeBugCheckEx
01 d461b804 81a3b08c 85dc5120 00000002 00000000 nt! ?? ::FNODOBFM::`string'+0x9eae
02 d461b8d0 820336b7 81a3d64d 00000000 d461ba14 nt!KeClockInterruptNotify+0x36c (FPO: [Non-Fpo])
03 d461b8e0 82044cdb 00000002 000000d1 00000000 hal!HalpTimerClockInterruptCommon+0x3f (FPO: [0,0,4])
04 d461b8e0 81a3d64d 00000002 000000d1 00000000 hal!HalpTimerClockInterrupt+0x1f7 (FPO: [0,2] TrapFrame @ d461b978) ç 2) 트랩 프레임
05 d461b9f0 81ba85d0 c786f3b8 8833d980 83000100 nt!KxWaitForSpinLockAndAcquire+0x1d (FPO: [0,0,0]) ç 1) 락 대기 함수
06 d461ba14 81a54003 00000000 830001c8 883125c7 nt!KiAcquireSpinLockInstrumented+0x53 (FPO: [Non-Fpo])
07 d461ba20 883125c7 0032a582 d461bae0 8831f149 nt!KfAcquireSpinLock+0x33 (FPO: [0,0,0])
08 d461ba2c 8831f149 8a352a0a c786f3b8 00000000 SomeDrv+0x25c7
09 d461bae0 81ca719d c786f3b8 00000001 00000000 SomeDrv +0xf149
0a d461bbb8 81ca6f6a 00000000 00000000 042ffdc8 nt!IopXxxControlFile+0x21d (FPO: [Non-Fpo])
0b d461bbe4 81b36987 00000300 00000000 00000000 nt!NtDeviceIoControlFile+0x2a (FPO: [Non-Fpo])
0c d461bbe4 77ce4d50 00000300 00000000 00000000 nt!KiSystemServicePostCall (FPO: [0,3] TrapFrame @ d461bc14)
0d 042ffde8 00000000 00000000 00000000 00000000
0x77ce4d50
1)번 nt!KxWaitForSpinLockAndAcquire함수는 스핀락을 획득하기 위해 시도하는 함수다. 2)번에는 트랩 프레임(TrapFrame)이 확인된다. 트랩 프레임이 있다는 것은 직전 1)번 함수 동작에 문제가 있어 인터럽트가 발생했다는 의미다. .trap 명령을 사용해 문제 발생 당시 상황으로 컨텍스트를 복원해보자.
kd> .trap d461b978
ErrCode = 00000000
eax=00490057 ebx=83000100 ecx=8833d980 edx=00000000 esi=520f94a9 edi=8833d980
eip=81a3d64d esp=d461b9ec ebp=d461ba14 iopl=0 nv up ei pl nz na pe nc
cs=0008 ss=0010 ds=8c3b es=01c8 fs=6b68 gs=ba20 efl=00000206
nt!KxWaitForSpinLockAndAcquire+0x1d:
81a3d64d f390 pause
edi 레지스터에 설정된 8833d980 값을 기억해두자(앞서 확인한 KSPIN_LOCK 구조체 주소다). esi 레지스터 값도 봐두면 좋다. 문제가 발생했던1)번 시점의 동작을 확인하기 위해 nt!KxWaitForSpinLockAndAcquire 함수를 처음부터 살펴봐야한다. 함수가 짧으니 너무 걱정하지 말자.
kd> u nt!KxWaitForSpinLockAndAcquire L14
nt!KxWaitForSpinLockAndAcquire:
81a3d630 8bff mov edi,edi
81a3d632 56 push esi
81a3d633 57 push edi
81a3d634 8bf9 mov edi,ecx
81a3d636 33f6 xor esi,esi ç 1) esi = 0
81a3d638 eb06 jmp nt!KxWaitForSpinLockAndAcquire+0x10 (81a3d640)
81a3d63a 8d9b00000000 lea ebx,[ebx]
81a3d640 46 inc esi ç 2) esi + 1(루프 시작)
81a3d641 853530e0c381 test dword ptr [nt!HvlLongSpinCountMask (81c3e030)],esi
81a3d647 0f84a2bc1000 je nt! ?? ::FNODOBFM::`string'+0xa44f (81b492ef)
81a3d64d f390 pause ç 3) 인터럽트 발생 위치(트랩 프레임)
81a3d64f 8b07 mov eax,dword ptr [edi] ç 4) edi 값을 eax에 설정
81a3d651 85c0 test eax,eax ç 5) eax 값이 0인지 확인
81a3d653 75eb jne nt!KxWaitForSpinLockAndAcquire+0x10 (81a3d640) ç 6) 0이 아니면 2)번 루프 시작 위치로 이동
81a3d655 f00fba2f00 lock bts dword ptr [edi],0
81a3d65a 72e4 jb nt!KxWaitForSpinLockAndAcquire+0x10 (81a3d640)
81a3d65c 5f pop edi
81a3d65d 8bc6 mov eax,esi
81a3d65f 5e pop esi
81a3d660 c3 ret
중요 위치마다 주석이 있어 함수 동작을 이해하는 데 무리가 없을 것이다. 1)번부터 살펴보자. 우선 esi 레지스터는 단순한 카운터 변수다. 2)번을 보면 루프 진입시마다 1씩 증가한다. 4)번에는 edi 값을 eax에 설정하고 5)번에서 eax가 0인지 확인한다. 참고로 edi는 KSPIN_LOCK 구조체 변수의 주소였다.
eax에 설정한 edi 값을 확인해보자.
kd> dd edi L1
8833d980
00490057
edi에 00490057 값이 있으므로 eax에도 00490057 값이 설정된다(앞서 00490057 값은 문자열의 일부였다). 6)번에서는 eax 값이 0이 아니므로 루프 시작 위치인 2)번으로 다시 이동한다. eax는 이미 문자열로 덮어 써져 0이 될 수 없으므로 계속 이 루틴이 반복된다. 즉 무한 루프 상태다. 과연 이 루프는 얼마나 수행됐을까? 카운터 변수인 esi 레지스터 값을 확인해보자.
kd> r esi
Last set context:
esi=520f94a9
맙소사! 0x520f94a9(1,376,752,809)라는 엄청나게 큰 값이 설정되어 있다. 무려 13억번이나 루프가 돌고 있었던 것이다! 그리고는 결국 제한 시간이 다 되어 3)번 위치의 pause 명령에서 0x133이 발생했다. 이제야 모든 것이 명확해졌다. 누군가 스핀락 변수를 문자열로 손상시켜 스핀락 획득 함수 내부에서 무한 루프에 빠져 버린 것이 원인이다(물론 대부분의 경우 누군가는 스핀락 사용 중인 SomeDrv 자신이다).
스핀락을 획득하려고 인터럽트 레벨을 상승시키고 무한 루프에 빠졌으니 DPC_WATCHDOG_VIOLATION(0x133) 버그체크가 발생하는 것은 어찌보면 당연하다.
여기서는 메모리 손상에 의한 0x133을 소개했지만 훨씬 까다로운 경우도 있다. 바로 스핀락을 획득하고 수행한 작업들 하나하나가 조금씩 성능 지연을 일으켜 누적에 의해 제한 시간을 넘기는 경우다. 단일 모듈이 아닌 다수의 모듈에서 지연이 발생하는 경우라면 더욱 골치아프다. 이 경우 별도의 성능 측정을 통해 모듈별로 매 작업마다 성능 지연이 발생하는 구간을 찾아내야해서 굉장히 어렵다. 이런 이유로 스핀락을 획득하고 시간 걸리는 작업은 아예 하지 않는 것이 정신 건강에 이롭다. 주로 다량의 엔트리가 삽입된 리스트를 검색할 때 성능 지연이 발생하는데 해시 테이블 등으로 자료 구조를 변경하거나 리스트에 삽입되는 최대 개수를 제한하는 등의 수정이 필요할 수 있다. 물론 가장 좋은 것은 개발 초기부터 이런 문제를 예상하며 성능을 고려한 설계를 하는 것이다.
앞으로 이 오류 코드가 발생한다면 이것 하나만 기억하자. “스핀락과 연관된 코드를 살펴보라!”
'Dump Analysis' 카테고리의 다른 글
| [Hang] CPU 과점유 (0) | 2018.08.13 |
|---|---|
| [0xC5] 해제 리스트 손상 (0) | 2018.07.19 |
| [0xC5] 풀 헤더 손상 (0) | 2018.07.16 |
| [0x1A] 페이지 손상 (0) | 2018.07.12 |
| [0x50] 해제된 핸들 (0) | 2018.07.09 |
이번 덤프는 또 다른 BugCheck 0xC5: DRIVER_CORRUPTED_EXPOOL이다.
역시나 풀 메모리가 손상됐을 경우 주로 발생한다. 이번에는 nt 커널이 전역으로 관리하는 풀 해제 리스트가 손상되어 메모리 해제 중 문제가 발생했다.
미리 밝히지만 메모리 손상 방법이 악랄하여 일반적으로는 분석이 거의 불가능한 유형의 덤프다.
그럼에도 기존과는 다른 접근법으로 답을 찾아 가는 방법을 소개하려고 한다.
kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************
DRIVER_CORRUPTED_EXPOOL (c5)
An attempt was made to access a pageable (or completely invalid) address at an
interrupt request level (IRQL) that is too high. This is
caused by drivers that have corrupted the system pool. Run the driver
verifier against any new (or suspect) drivers, and if that doesn't turn up
the culprit, then use gflags to enable special pool.
Arguments:
Arg1: 11223344, memory referenced
Arg2: 00000002, IRQL
Arg3: 00000000, value 0 = read operation, 1 = write operation
Arg4: 82b5f795, address which referenced memory
Debugging Details:
------------------
DUMP_CLASS: 1
DUMP_QUALIFIER: 401
BUILD_VERSION_STRING: 7601.17514.x86fre.win7sp1_rtm.101119-1850
SYSTEM_MANUFACTURER: VMware, Inc.
VIRTUAL_MACHINE: VMware
SYSTEM_PRODUCT_NAME: VMware Virtual Platform
SYSTEM_VERSION: None
BIOS_VENDOR: Phoenix Technologies LTD
BIOS_VERSION: 6.00
BIOS_DATE: 07/31/2013
BASEBOARD_MANUFACTURER: Intel Corporation
BASEBOARD_PRODUCT: 440BX Desktop Reference Platform
BASEBOARD_VERSION: None
DUMP_TYPE: 1
BUGCHECK_P1: 11223344
BUGCHECK_P2: 2
BUGCHECK_P3: 0
BUGCHECK_P4: ffffffff82b5f795
BUGCHECK_STR: 0xC5_2
CURRENT_IRQL: 2
FAULTING_IP:
nt!ExDeferredFreePool+135
82b5f795 8b10 mov edx,dword ptr [eax]
CPU_COUNT: 4
CPU_MHZ: e07
CPU_VENDOR: GenuineIntel
CPU_FAMILY: 6
CPU_MODEL: 3c
CPU_STEPPING: 3
CPU_MICROCODE: 6,3c,3,0 (F,M,S,R) SIG: 19'00000000 (cache) 19'00000000 (init)
DEFAULT_BUCKET_ID: WIN7_DRIVER_FAULT
PROCESS_NAME: System
ANALYSIS_SESSION_HOST: PAUL-PC
ANALYSIS_SESSION_TIME: 12-01-2017 17:48:31.0130
ANALYSIS_VERSION: 10.0.10575.567 amd64fre
TRAP_FRAME: 82b65ab4 -- (.trap 0xffffffff82b65ab4)
ErrCode = 00000000
eax=11223344 ebx=000001ff ecx=000001ff edx=82b74d60 esi=8649a158 edi=82b74940
eip=82b5f795 esp=82b65b28 ebp=82b65b60 iopl=0 nv up ei pl nz na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010206
nt!ExDeferredFreePool+0x135:
82b5f795 8b10 mov edx,dword ptr [eax]
ds:0023:11223344=????????
Resetting default scope
LAST_CONTROL_TRANSFER: from 82b5f795 to 82a7e5cb
STACK_TEXT:
82b65ab4 82b5f795 badb0d00 82b74d60 82b65b08 nt!KiTrap0E+0x2cf
82b65b60 82b5f35f 82b74940 00000000 82b5eaba nt!ExDeferredFreePool+0x135
82b65bc8 8cb1294d 8458fd10 70627375 82a780e8 nt!ExFreePoolWithTag+0x8a4
82b65c00 8cb13178 8655c518 8544dc58 8643ee30 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x7c5
82b65c2c 8cb169af 8555a028 8555a0f0 8555aa98 USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b
82b65c54 8cb10d18 8555a028 8555aa98 8555a002 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc
82b65c78 82ab51b5 8555aaa4 8555a002 00000000 USBPORT!USBPORT_Xdpc_Worker+0x173
82b65cd4 82ab5018 82b68d20 82b72380 00000000 nt!KiExecuteAllDpcs+0xf9
82b65d20 82ab4e38 00000000 0000000e 00000000 nt!KiRetireDpcList+0xd5
82b65d24 00000000 0000000e 00000000 00000000 nt!KiIdleLoop+0x38
STACK_COMMAND: kb
THREAD_SHA1_HASH_MOD_FUNC: a81891ed81b7e7e7cf7e48a31a162387a34eb470
THREAD_SHA1_HASH_MOD_FUNC_OFFSET: e3429ed576cacf32e33aea2731862fb99fe1a8e9
THREAD_SHA1_HASH_MOD: d1ea541659404c79a51ef0cc026f2229287008dc
FOLLOWUP_IP:
nt!ExDeferredFreePool+135
82b5f795 8b10 mov edx,dword ptr [eax]
FAULT_INSTR_CODE: 44ff108b
SYMBOL_STACK_INDEX: 1
SYMBOL_NAME: nt!ExDeferredFreePool+135
FOLLOWUP_NAME: Pool_corruption
IMAGE_NAME: Pool_Corruption
DEBUG_FLR_IMAGE_TIMESTAMP: 0
IMAGE_VERSION: 6.1.7601.17514
MODULE_NAME: Pool_Corruption
FAILURE_BUCKET_ID: 0xC5_2_nt!ExDeferredFreePool+135
BUCKET_ID: 0xC5_2_nt!ExDeferredFreePool+135
PRIMARY_PROBLEM_CLASS: 0xC5_2_nt!ExDeferredFreePool+135
TARGET_TIME: 2017-11-30T09:55:42.000Z
OSBUILD: 7601
OSSERVICEPACK: 1000
SERVICEPACK_NUMBER: 0
OS_REVISION: 0
SUITE_MASK: 272
PRODUCT_TYPE: 1
OSPLATFORM_TYPE: x86
OSNAME: Windows 7
OSEDITION: Windows 7 WinNt (Service Pack 1) TerminalServer SingleUserTS
OS_LOCALE:
USER_LCID: 0
OSBUILD_TIMESTAMP: 2010-11-20 17:42:49
BUILDDATESTAMP_STR: 101119-1850
BUILDLAB_STR: win7sp1_rtm
BUILDOSVER_STR: 6.1.7601.17514.x86fre.win7sp1_rtm.101119-1850
ANALYSIS_SESSION_ELAPSED_TIME: 756
ANALYSIS_SOURCE: KM
FAILURE_ID_HASH_STRING: km:0xc5_2_nt!exdeferredfreepool+135
FAILURE_ID_HASH: {8f7dc44e-d604-b619-9e06-69593c07a8bc}
Followup: Pool_corruption
---------
풀 메모리 해제 중 메모리 손상이 감지되어 문제가 발생했다. BugCode 의 파라미터를 살펴보자.
Arguments:
Arg1: 11223344, memory referenced
Arg2: 00000002, IRQL
Arg3: 00000000, value 0 = read operation, 1 = write operation
Arg4:
82b5f795, address which referenced memory
첫 번째 파라미터를 보면 "11223344" 주소에 접근하다 문제가 발생했다.
"11223344"는 그냥 봐도 이상한 주소 값이기 때문에 "누가 또 메모리를 깼네"라고 생각하면 속 편하다.
메모리 손상 이슈는 많이 분석해 본 나도 결말이 어떻게 될지 예측할 수 없다.
덤프 상에 분석을 위한 최소한의 정보도 남아 있지 않으면 분석이 불가능하기 때문이다.
그러니, 이쯤에서 한숨을 크게 한 번 쉬어주자.
준비가 됐으면 kv 명령어로 파라미터를 포함한 콜 스택부터 살펴보자.
kd> kv
# ChildEBP RetAddr Args to Child
00 82b65ab4 82b5f795 badb0d00 82b74d60 82b65b08 nt!KiTrap0E+0x2cf (FPO: [0,0]
TrapFrame @ 82b65ab4)
01 82b65b60 82b5f35f 82b74940 00000000 82b5eaba nt!ExDeferredFreePool+0x135
02 82b65bc8 8cb1294d 8458fd10 70627375 82a780e8 nt!ExFreePoolWithTag+0x8a4
03 82b65c00 8cb13178 8655c518 8544dc58 8643ee30 USBPORT!USBPORT_Core_iCompleteDoneTransfer+0x7c5 (FPO: [Non-Fpo])
04 82b65c2c 8cb169af 8555a028 8555a0f0 8555aa98 USBPORT!USBPORT_Core_iIrpCsqCompleteDoneTransfer+0x33b (FPO: [Non-Fpo])
05 82b65c54 8cb10d18 8555a028 8555aa98 8555a002 USBPORT!USBPORT_Core_UsbIocDpc_Worker+0xbc (FPO: [Non-Fpo])
06 82b65c78 82ab51b5 8555aaa4 8555a002 00000000 USBPORT!USBPORT_Xdpc_Worker+0x173 (FPO: [Non-Fpo])
07 82b65cd4 82ab5018 82b68d20 82b72380 00000000 nt!KiExecuteAllDpcs+0xf9
08 82b65d20 82ab4e38 00000000 0000000e 00000000 nt!KiRetireDpcList+0xd5
09 82b65d24 00000000 0000000e 00000000 00000000 nt!KiIdleLoop+0x38 (FPO:
[0,0,0])
콜 스택을 보면 nt 커널의 ExDeferredFreePool 함수를 통해 풀 메모리를 해제하는 도중 해제 리스트 손상이 감지되어 0xC5 오류 코드가 발생했다.
참고로 ExDeferredFreePool 함수는 공개되지 않은 커널 내부 함수로 외부에서 사용 가능한 ExFreePoolWithTag 함수를 통해 호출된다.
ExFreePoolWithTag 함수 원형은 다음과 같다.
VOID ExFreePoolWithTag(
_In_ PVOID P,
_In_ ULONG Tag
);
첫 번째 파라미터가 해제하려는 풀 메모리의 포인터인데, 콜 스택에 보이는 ExFreePoolWithTag의 첫 번째 파라미터인 8458fd10 을 해제하는 과정에서 문제가 발생한 것으로 추측해볼 수 있다.
ExDeferredFreePool 함수는 이름 그대로 바로 해제가 어려울 경우 나중에 해제하기 위해 지연 해제 리스트에 넣는 작업을 처리하는 함수다.
해제를 요청한 풀이 문제가 없는지는 보통 해제 함수 앞 부분에서 검사한다. 따라서 여기서 문제가 발생하는 경우 해제를 요청한 풀 자체보다는 지연 해제 관련 작업 중에 문제가 발생하는 경우가 많다.
이제 본격적으로 문제가 발생한 부분을 살펴보자.
먼저 문제가 발생한 지점으로 trap 을 맞춰보자.
kd> .trap 0xffffffff82b65ab4
ErrCode = 00000000
eax=11223344 ebx=000001ff ecx=000001ff edx=82b74d60 esi=8649a158 edi=82b74940
eip=82b5f795 esp=82b65b28 ebp=82b65b60 iopl=0 nv up ei pl nz na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010206
nt!ExDeferredFreePool+0x135:
82b5f795 8b10 mov edx,dword ptr [eax]
nt!ExDeferredFreePool+0x135 위치에서 mov edx, dword ptr [eax] 명령을 수행하다 eax 가 11223344 로 접근할 수 없는 주소여서 문제가 발생했다고 보여준다.
앞서 다른 메모리 손상 덤프 분석을 통해 언급했듯이 메모리 손상 유형은 크게 2가지다.
1. 앞 쪽 메모리 영역에서 다음 메모리 영역을 침범한 경우
2. 해당 위치의 메모리만 손상시킨 경우
주로 첫 번째 유형인 경우가 많으며 대체로 분석이 가능하다. 하지만 두 번째 유형인 경우 분석이 거의 불가능하다.
메모리가 손상된 원인을 분석하기 위한 일반적인 방법은 손상된 값의 위치를 찾아 그 앞 부분을 살펴보는 것이다.
왜냐하면 첫 번째 유형의 경우 다음과 같은 과정으로 메모리가 손상되기 때문이다.1. 정상 상태
|
구분 |
주소 |
값 |
|
모듈 A의 풀 1 |
0xa0000000 |
0x11223344 ... ... |
|
모듈 B의 풀 2 |
0xa0000100 |
0xb0000000 ... ...
|
2. 풀 1에서 풀 2 영역 침범
|
구분 |
주소 |
값 |
|
모듈 A의 풀 1 |
0xa0000000 |
0x11223344 ... ... |
|
모듈 B의 풀 2 |
0xa0000100 |
0x11223344 ... ... |
1번은 서로 다른 모듈 A, B에서 각각 풀 메모리 1, 2 를 할당 받아 자신이 필요한 값을 설정한 상태를 나타낸다.
2번은 모듈 A에서 자신이 사용하는 풀 1 영역을 넘어 실수로 모듈 B가 사용하는 풀 2 영역의 메모리까지 0x11223344 값으로 덮어 쓴 상황이다.
이런 상황에서 모듈 B가 자신의 풀 2의 주소인 0xa0000100 에서 값을 읽어 참조하는 동작을 수행한다고 해보자.
모듈 B는 당연히 원래 설정해 놓은 유효한 주소값인 0xb0000000을 잘 가져오리라 기대하겠지만, 0xb0000000 값은 모듈 A에 의해 이미 0x11223344 값으로 변경되어 손상된 상태다.
모듈 B는 유효하지 않은 주소값인 0x11223344을 참조하다 문제를 발생시킨다.
이 과정이 이해가 된다면 자연스럽게 문제가 된 "0x11223344" 값을 담고 있는 풀 2 영역의 주소인 0xa0000100을 찾아 그 앞 쪽 풀이 어떤 모듈의 것인지 찾아 내는 것이 문제 해결의 열쇠임을 알 수 있을 것이다.
물론, 이번 덤프에서도 eax 레지스터에 담긴 "0x11223344" 값이 어디서부터 왔는지 찾아야 한다.
언제나처럼 문제가 발생한 함수인 ExDeferredFreePool 부터 차근히 살펴보자.
kd> u nt!ExDeferredFreePool L5d
nt!ExDeferredFreePool:
82b5f660 8bff mov edi,edi
82b5f662 55 push ebp
82b5f663 8bec mov ebp,esp
82b5f665 83e4f8 and esp,0FFFFFFF8h
82b5f668 83ec2c sub esp,2Ch
82b5f66b 53 push ebx
82b5f66c 56 push esi
82b5f66d 57 push edi
82b5f66e 8b7d08 mov edi,dword ptr [ebp+8]
82b5f671 8d4f4c lea ecx,[edi+4Ch]
82b5f674 33c0 xor eax,eax
82b5f676 8bd1 mov edx,ecx
82b5f678 40 inc eax
82b5f679 f00fc102 lock xadd dword ptr [edx],eax
82b5f67d 40 inc eax
82b5f67e 83f801 cmp eax,1
82b5f681 7412 je nt!ExDeferredFreePool+0x35 (82b5f695)
82b5f683 837d0c00 cmp dword ptr [ebp+0Ch],0
82b5f687 750c jne nt!ExDeferredFreePool+0x35 (82b5f695)
82b5f689 83c8ff or eax,0FFFFFFFFh
82b5f68c f00fc101 lock xadd dword ptr [ecx],eax
82b5f690 e9c4030000 jmp nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f695 33c0 xor eax,eax
82b5f697 f60701 test byte ptr [edi],1
82b5f69a c644243400 mov byte ptr [esp+34h],0
82b5f69f 8944241c mov dword ptr [esp+1Ch],eax
82b5f6a3 89442414 mov dword ptr [esp+14h],eax
82b5f6a7 89442418 mov dword ptr [esp+18h],eax
82b5f6ab 89442424 mov dword ptr [esp+24h],eax
82b5f6af 8d7704 lea esi,[edi+4]
82b5f6b2 750e jne nt!ExDeferredFreePool+0x62 (82b5f6c2)
82b5f6b4 8d54242c lea edx,[esp+2Ch]
82b5f6b8 8bce mov ecx,esi
82b5f6ba ff1534e1a382 call dword ptr [nt!_imp_KeAcquireInStackQueuedSpinLock (82a3e134)]
82b5f6c0 eb2d jmp nt!ExDeferredFreePool+0x8f (82b5f6ef)
82b5f6c2 648b1d24010000 mov ebx,dword ptr fs:[124h]
82b5f6c9 66ff8b86000000 dec word ptr [ebx+86h]
82b5f6d0 8bc6 mov eax,esi
82b5f6d2 f00fba3000 lock btr dword ptr [eax],0
82b5f6d7 7207 jb nt!ExDeferredFreePool+0x80 (82b5f6e0)
82b5f6d9 8bce mov ecx,esi
82b5f6db e8690df7ff call nt!KiAcquireGuardedMutex (82ad0449)
82b5f6e0 64a124010000 mov eax,dword ptr fs:[00000124h]
82b5f6e6 895e04 mov dword ptr [esi+4],ebx
82b5f6e9 fe808b020000 inc byte ptr [eax+28Bh]
82b5f6ef 8d9700010000 lea edx,[edi+100h]
82b5f6f5 8b02 mov eax,dword ptr [edx]
82b5f6f7 85c0 test eax,eax
82b5f6f9 0f858b000000 jne nt!ExDeferredFreePool+0x12a (82b5f78a)
82b5f6ff 8d474c lea eax,[edi+4Ch]
82b5f702 83c9ff or ecx,0FFFFFFFFh
82b5f705 f00fc108 lock xadd dword ptr [eax],ecx
82b5f709 f60701 test byte ptr [edi],1
82b5f70c 750f jne nt!ExDeferredFreePool+0xbd (82b5f71d)
82b5f70e 8d4c242c lea ecx,[esp+2Ch]
82b5f712 ff1530e1a382 call dword ptr [nt!_imp_KeReleaseInStackQueuedSpinLock (82a3e130)]
82b5f718 e93c030000 jmp nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f71d 64a124010000 mov eax,dword ptr fs:[00000124h]
82b5f723 fe888b020000 dec byte ptr [eax+28Bh]
82b5f729 83660400 and dword ptr [esi+4],0
82b5f72d 33c9 xor ecx,ecx
82b5f72f 41 inc ecx
82b5f730 8bc6 mov eax,esi
82b5f732 f00fc108 lock xadd dword ptr [eax],ecx
82b5f736 85c9 test ecx,ecx
82b5f738 741f je nt!ExDeferredFreePool+0xf9 (82b5f759)
82b5f73a f6c102 test cl,2
82b5f73d 751a jne nt!ExDeferredFreePool+0xf9 (82b5f759)
82b5f73f 41 inc ecx
82b5f740 8d41fe lea eax,[ecx-2]
82b5f743 8bd0 mov edx,eax
82b5f745 8bfe mov edi,esi
82b5f747 8bc1 mov eax,ecx
82b5f749 f00fb117 lock cmpxchg dword ptr [edi],edx
82b5f74d 3bc1 cmp eax,ecx
82b5f74f 7508 jne nt!ExDeferredFreePool+0xf9 (82b5f759)
82b5f751 8d460c lea eax,[esi+0Ch]
82b5f754 e806faf0ff call nt!KeSignalGateBoostPriority (82a6f15f)
82b5f759 648b0d24010000 mov ecx,dword ptr fs:[124h]
82b5f760 8d8186000000 lea eax,[ecx+86h]
82b5f766 66ff00 inc word ptr [eax]
82b5f769 0fb700 movzx eax,word ptr [eax]
82b5f76c 6685c0 test ax,ax
82b5f76f 0f85e4020000 jne nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f775 8d4140 lea eax,[ecx+40h]
82b5f778 3900 cmp dword ptr [eax],eax
82b5f77a 0f84d9020000 je nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f780 e8145df0ff call nt!KiCheckForKernelApcDelivery (82a65499)
82b5f785 e9cf020000 jmp nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f78a b9ff010000 mov ecx,1FFh
82b5f78f 8b02 mov eax,dword ptr [edx] 1) edx 값을 eax에 설정
82b5f791 89442420 mov dword ptr [esp+20h],eax 2) eax를 esp+20에 저장
82b5f795 8b10 mov edx,dword ptr [eax] 3) eax가
11223344 여서 문제 발생
1)번부터 순서대로 살펴보면, 우선 1)번에서 edx 값을 eax에 설정했고, 2)번에서 설정한 eax를 esp+20 에 저장한 부분이 나온다.
3)번에서 eax가 11223344 였으니 edx 의 값과 esp+20 에 11223344 값이 설정되어 있어야 앞뒤가 맞다.
예상이 맞는지 한 번 확인해보자.
kd> dd edx L1
82b74d60 8448ad20
kd> dd esp+20 L1
82b65b48
8457ec68
말도 안되는 값이 확인된다. edx에 설정된 값은 8448ad20이다. 심지어 esp+20에 설정된 값은 84d7ec68이다. 찾고 있는 11223344 값은 커녕 edx와 esp+20끼리도 서로 다르다.
이런 경우 실행 흐름을 잘못 잡고 있을 가능성이 크다.
아무래도 지금 보는 곳보다 더 아래 부분에서 문제가 발생한 3)번 82b5f795 주소로 바로 이동하는 코드가 있을 가능성이 의심된다.
ExDeferredFreePool 함수를 아래 부분까지 좀 더 살펴보자.
kd> u nt!ExDeferredFreePool Le6
nt!ExDeferredFreePool:
82b5f660 8bff mov edi,edi
82b5f662 55 push ebp
82b5f663 8bec mov ebp,esp
82b5f665 83e4f8 and esp,0FFFFFFF8h
82b5f668 83ec2c sub esp,2Ch
82b5f66b 53 push ebx
82b5f66c 56 push esi
82b5f66d 57 push edi
82b5f66e 8b7d08 mov edi,dword ptr [ebp+8]
82b5f671 8d4f4c lea ecx,[edi+4Ch]
82b5f674 33c0 xor eax,eax
82b5f676 8bd1 mov edx,ecx
82b5f678 40 inc eax
82b5f679 f00fc102 lock xadd dword ptr [edx],eax
82b5f67d 40 inc eax
82b5f67e 83f801 cmp eax,1
82b5f681 7412 je nt!ExDeferredFreePool+0x35 (82b5f695)
82b5f683 837d0c00 cmp dword ptr [ebp+0Ch],0
82b5f687 750c jne nt!ExDeferredFreePool+0x35 (82b5f695)
82b5f689 83c8ff or eax,0FFFFFFFFh
82b5f68c f00fc101 lock xadd dword ptr [ecx],eax
82b5f690 e9c4030000 jmp nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f695 33c0 xor eax,eax
82b5f697 f60701 test byte ptr [edi],1
82b5f69a c644243400 mov byte ptr [esp+34h],0
82b5f69f 8944241c mov dword ptr [esp+1Ch],eax
82b5f6a3 89442414 mov dword ptr [esp+14h],eax
82b5f6a7 89442418 mov dword ptr [esp+18h],eax
82b5f6ab 89442424 mov dword ptr [esp+24h],eax
82b5f6af 8d7704 lea esi,[edi+4]
82b5f6b2 750e jne nt!ExDeferredFreePool+0x62 (82b5f6c2)
82b5f6b4 8d54242c lea edx,[esp+2Ch]
82b5f6b8 8bce mov ecx,esi
82b5f6ba ff1534e1a382 call dword ptr [nt!_imp_KeAcquireInStackQueuedSpinLock (82a3e134)]
82b5f6c0 eb2d jmp nt!ExDeferredFreePool+0x8f (82b5f6ef)
82b5f6c2 648b1d24010000 mov ebx,dword ptr fs:[124h]
82b5f6c9 66ff8b86000000 dec word ptr [ebx+86h]
82b5f6d0 8bc6 mov eax,esi
82b5f6d2 f00fba3000 lock btr dword ptr [eax],0
82b5f6d7 7207 jb nt!ExDeferredFreePool+0x80 (82b5f6e0)
82b5f6d9 8bce mov ecx,esi
82b5f6db e8690df7ff call nt!KiAcquireGuardedMutex (82ad0449)
82b5f6e0 64a124010000 mov eax,dword ptr fs:[00000124h]
82b5f6e6 895e04 mov dword ptr [esi+4],ebx
82b5f6e9 fe808b020000 inc byte ptr [eax+28Bh]
82b5f6ef 8d9700010000 lea edx,[edi+100h] // 1) _POOL_DESCRIPTOR.PendingFrees 주소를 edx 에 저장
82b5f6f5 8b02 mov eax,dword ptr [edx]
82b5f6f7 85c0 test eax,eax
82b5f6f9 0f858b000000 jne nt!ExDeferredFreePool+0x12a (82b5f78a) // 2) 82b5f78a 로 이동
82b5f6ff 8d474c lea eax,[edi+4Ch]
82b5f702 83c9ff or ecx,0FFFFFFFFh
82b5f705 f00fc108 lock xadd dword ptr [eax],ecx
82b5f709 f60701 test byte ptr [edi],1
82b5f70c 750f jne nt!ExDeferredFreePool+0xbd (82b5f71d)
82b5f70e 8d4c242c lea ecx,[esp+2Ch]
82b5f712 ff1530e1a382 call dword ptr [nt!_imp_KeReleaseInStackQueuedSpinLock (82a3e130)]
82b5f718 e93c030000 jmp nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f71d 64a124010000 mov eax,dword ptr fs:[00000124h]
82b5f723 fe888b020000 dec byte ptr [eax+28Bh]
82b5f729 83660400 and dword ptr [esi+4],0
82b5f72d 33c9 xor ecx,ecx
82b5f72f 41 inc ecx
82b5f730 8bc6 mov eax,esi
82b5f732 f00fc108 lock xadd dword ptr [eax],ecx
82b5f736 85c9 test ecx,ecx
82b5f738 741f je nt!ExDeferredFreePool+0xf9 (82b5f759)
82b5f73a f6c102 test cl,2
82b5f73d 751a jne nt!ExDeferredFreePool+0xf9 (82b5f759)
82b5f73f 41 inc ecx
82b5f740 8d41fe lea eax,[ecx-2]
82b5f743 8bd0 mov edx,eax
82b5f745 8bfe mov edi,esi
82b5f747 8bc1 mov eax,ecx
82b5f749 f00fb117 lock cmpxchg dword ptr [edi],edx
82b5f74d 3bc1 cmp eax,ecx
82b5f74f 7508 jne nt!ExDeferredFreePool+0xf9 (82b5f759)
82b5f751 8d460c lea eax,[esi+0Ch]
82b5f754 e806faf0ff call nt!KeSignalGateBoostPriority (82a6f15f)
82b5f759 648b0d24010000 mov ecx,dword ptr fs:[124h]
82b5f760 8d8186000000 lea eax,[ecx+86h]
82b5f766 66ff00 inc word ptr [eax]
82b5f769 0fb700 movzx eax,word ptr [eax]
82b5f76c 6685c0 test ax,ax
82b5f76f 0f85e4020000 jne nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f775 8d4140 lea eax,[ecx+40h]
82b5f778 3900 cmp dword ptr [eax],eax
82b5f77a 0f84d9020000 je nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f780 e8145df0ff call nt!KiCheckForKernelApcDelivery (82a65499)
82b5f785 e9cf020000 jmp nt!ExDeferredFreePool+0x3f8 (82b5fa59)
82b5f78a b9ff010000 mov ecx,1FFh
82b5f78f 8b02 mov eax,dword ptr [edx] // 3) edx 가 가리키는 _POOL_DESCRIPTOR.PendingFrees 값을 eax에 저장
82b5f791 89442420 mov dword ptr [esp+20h],eax
82b5f795 8b10 mov edx,dword ptr [eax] // 4) eax 값을 edx에 설정 (문제 발생 위치)
82b5f797 ff44241c inc dword ptr [esp+1Ch]
82b5f79b 8364241000 and dword ptr [esp+10h],0
82b5f7a0 89542428 mov dword ptr [esp+28h],edx // 5) edx를 esp+28에 저장
82b5f7a4 83c0f8 add eax,0FFFFFFF8h
82b5f7a7 0fb710 movzx edx,word ptr [eax]
82b5f7aa 33db xor ebx,ebx
82b5f7ac c1ea09 shr edx,9
82b5f7af 8d7744 lea esi,[edi+44h]
82b5f7b2 43 inc ebx
82b5f7b3 f00fc11e lock xadd dword ptr [esi],ebx
82b5f7b7 0fb77002 movzx esi,word ptr [eax+2]
82b5f7bb 23f1 and esi,ecx
82b5f7bd 6bf6f8 imul esi,esi,0FFFFFFF8h
82b5f7c0 8bde mov ebx,esi
82b5f7c2 8d7750 lea esi,[edi+50h]
82b5f7c5 f00fc11e lock xadd dword ptr [esi],ebx
82b5f7c9 0fb77002 movzx esi,word ptr [eax+2]
82b5f7cd 23f1 and esi,ecx
82b5f7cf 8d34f0 lea esi,[eax+esi*8]
82b5f7d2 8974240c mov dword ptr [esp+0Ch],esi
82b5f7d6 f7c6ff0f0000 test esi,0FFFh
82b5f7dc 7468 je nt!ExDeferredFreePool+0x1e6 (82b5f846)
... ... (함수가 길어 중간 내용 생략)
82b5f93e 8930 mov dword ptr [eax],esi
82b5f940 895004 mov dword ptr [eax+4],edx
82b5f943 894604 mov dword ptr [esi+4],eax
82b5f946 8902 mov dword ptr [edx],eax
82b5f948 8b442428 mov eax,dword ptr [esp+28h] // 6) 앞서 저장했던 esp+28 값을 eax에 설정
82b5f94c 3b442424 cmp eax,dword ptr [esp+24h]
82b5f950 0f853ffeffff jne
nt!ExDeferredFreePool+0x135 (82b5f795) // 7) 4)번
82b5f795 로 이동
역시나 7)번을 보면 4)번 위치인 82b5f795로 이동하는 부분이 보인다(이전 함수 출력 결과에서는 3)번 위치).
kd> dd esp+28 L1
82b65b50
11223344
6)번의 esp+28 값을 확인해보니 우리가 찾던 "11223344" 값이 확인된다. 7)번까지 수행하고 다시 4)번으로 돌아가서 명령을 수행하다 문제가 발생한 것이 분명하다.
함수가 좀 복잡하여 이해하기 쉽게 미리 확인한 내용을 주석으로 적어 보았다.
1)~7)번까지 동작을 한 줄로 정리하면 다음과 같다.
Pool Descriptor 의 PendingFrees 리스트를 순회하다 해당 엔트리 하나가 11223344 여서 문제 발생
1)번 동작인 "lea edx,[edi+100h]"에서 edi 는 해제하려는 풀 메모리의 POOL_DESCRIPTOR 이다.
edi 값인 82b74940가 콜 스택의 첫 번째 파라미터와 동일하기 때문이다.
kd> r edi
Last set context:
edi=82b74940
kd> dd ebp+8 L1
82b65b68 82b74940
이어서, ExDeferredFreePool 함수 원형을 살펴보면 첫 번째 파라미터는 POOL_DESCRIPTOR다.
VOID
ExDeferredFreePool(
IN PPOOL_DESCRIPTOR PoolDesc
);
따라서 1)번 동작은 POOL_DESCRIPTOR의 +100번 위치의 필드를 구하는 동작이다.
edi 값인 82b74940를 dt _POOL_DESCRIPTOR 명령으로 확인해보자.
kd> dt _POOL_DESCRIPTOR 82b74940
nt!_POOL_DESCRIPTOR
+0x000 PoolType : 0 ( NonPagedPool )
+0x004 PagedLock : _KGUARDED_MUTEX
+0x004 NonPagedLock : 0x8b451858
+0x040 RunningAllocs : 0x7715b
+0x044 RunningDeAllocs : 0x6af0a
+0x048 TotalBigPages : 0xce1
+0x04c ThreadsProcessingDeferrals : 1
+0x050 TotalBytes : 0x128c1a0
+0x080 PoolIndex : 0
+0x0c0 TotalPages : 0x7b2
+0x100 PendingFrees : 0x8652f468 -> 0x8458fbd0 Void
+0x104 PendingFreeDepth : 0x22
+0x140
ListHeads : [512] _LIST_ENTRY [ 0x82b74a80 - 0x82b74a80 ]
+0x100 위치의 필드는 지연 해제할 리스트의 목록인 PendingFrees 이다.
3)~7)번을 살펴보면 이 PendingFrees 의 다음 포인터를 계속 가져오면서 리스트 순회를 하는 동작 중에 "11223344"라는 잘못된 값을 만나 문제가 발생한 것이다.
좋다. 이러면 PendingFrees 리스트 어딘가에 11223344 값을 담고 있는 엔트리가 있어야 할 것이다.
리스트를 출력하는 dl 명령으로 PendingFrees가 가리키는 0x8652f468을 넣어 살펴보자.
kd> dl 0x8652f468
8652f468 8458fbd0 00000000 00060940 8458fc00
8458fbd0 8457ec68 82b74bb8 00000000 00000000
8457ec68 82b74d70 82b74d70 00000000 00000000
82b74d70 82b74d70
82b74d70 84598008 84584008
어라? 11223344 값을 갖고 있는 엔트리가 있어야 하는데 보이지 않는다.
82b74d70에서 리스트가 끝나는데, 잘 보면 리스트 마지막이 NULL 이 아니다.
PendingFrees 리스트는 SINGLE_LIST_ENTRY 여서 마지막은 NULL로 끝나야 한다. 메모리 손상에 의해 리스트의 연결이 엉뚱하게 바뀐 것으로 보인다.
PendingFrees 리스트를 순회하다 손상된 엔트리에 있는 11223344 값을 가져왔지만, 손상된 엔트리의 흔적은 이후에 리스트의 링크가 변경되면서 없어져 버렸다.
참고로 이런 일이 가능한 이유는 PendingFrees 리스트가 여러 스레드에 의해 재구성될 수 있는 구조여서 중간에 바뀌어 버릴 수 있기 때문이다. 디버깅을 통해 확인된 내용으로 주제를 벗어나는 내용이라 자세히 다루지 않았다. 여기서는 리스트에서 손상된 부분을 찾을 수 없는 상황으로 이해하면 되겠다.
어쨌든 추적 중인 리스트가 정상적이지 않아 일반적인 방법으로는 더 이상 추적이 불가능한 상황이다.
한층 더 어려워진 문제를 풀기 위해서 잠시 생각을 정리할 시간이 필요해 보인다.
일단 풀 메모리가 해제될 때 풀의 상태가 어떻게 변할지 생각해보자.
풀 메모리가 ExFreePoolWithTag 함수로 해제되면 풀의 첫 부분에 이전 해제된 풀의 주소가 설정된다.
이전 해제된 풀의 첫 부분에는 마찬가지로 또 다른 해제된 풀 주소가 설정되므로 해제된 풀들의 싱글 링크드 리스트가 구성된다.
위에 dl 명령으로 확인했던 첫 번째 풀 주소인 8652f468을 다시 살펴보자.
kd> !pool 8652f468
Pool page 8652f468 region is Nonpaged pool
8652f000 size: 2e8 previous size: 0 (Allocated) Scbf
8652f2e8 size: 8 previous size: 2e8 (Free) }n=\
8652f2f0 size: 40 previous size: 8 (Allocated) Even (Protected)
8652f330 size: 50 previous size: 40 (Allocated) Vadl
8652f380 size: e0 previous size: 50 (Free) Thre
*8652f460 size: 208 previous size: e0 (Free ) *Irp Process: 85d35030
Pooltag Irp : Io, IRP packets
8652f668 size: 18 previous size: 208 (Allocated) ReEv
8652f680 size: 68 previous size: 18 (Allocated) FMsl
8652f6e8 size: 28 previous size: 68 (Allocated) VadS
8652f710 size: 68 previous size: 28 (Allocated) EtwR (Protected)
8652f778 size: 2e8 previous size: 68 (Allocated) Thre (Protected)
8652fa60 size: b8 previous size: 2e8 (Allocated) File (Protected)
8652fb18 size: 68 previous size: b8 (Allocated) FMsl
8652fb80 size: b0 previous size: 68 (Allocated) AfdC (Protected)
8652fc30 size: 68 previous size: b0 (Allocated) FMsl
8652fc98 size: 8 previous size: 68 (Free) KSpp
8652fca0 size: 48 previous size: 8 (Allocated) Vad
8652fce8 size: 68 previous size: 48 (Allocated) EtwR (Protected)
8652fd50 size: 138 previous size: 68 (Allocated) ALPC (Protected)
8652fe88 size: 138 previous size: 138 (Allocated) ALPC (Protected)
8652ffc0
size: 40 previous size: 138 (Allocated) Even (Protected)
역시 Irp 풀 태그를 갖고 있는 해제된 풀이 확인된다.
kd> db 8652f468
8652f468 d0 fb 58 84 00 00 00 00-40 09 06 00 00 fc 58 84 ..X.....@.....X.
8652f478 78 f4 52 86 78 f4 52 86-00 00 00 00 18 00 00 00 x.R.x.R.........
8652f488 00 01 0b 0d 00 00 00 01-38 da af ff 00 00 00 00 ........8.......
8652f498 0a 0f 52 82 10 da af ff-00 00 00 00 6c da af ff ..R.........l...
8652f4a8 12 00 30 00 00 00 00 00-30 00 f7 85 70 00 f7 85 ..0.....0...p...
8652f4b8 70 00 f7 85 6e 94 c1 82-72 53 cf 82 0a 0f 52 82 p...n...rS....R.
8652f4c8 10 da af ff 38 da af ff-00 00 00 00 00 00 00 00 ....8...........
8652f4d8 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00
00 ................
그리고, 첫 4바이트에 8458fbd0 (거꾸로 읽어야 한다!) 값이 확인된다.
8458fbd0 값이 어떤 메모리 영역인지 확인하기 위해 !pool 명령으로 확인해보자.
kd> !pool 8458fbd0
Pool page 8458fbd0 region is Nonpaged pool
8458f000 size: c8 previous size: 0 (Allocated) Ntfx
8458f0c8 size: 30 previous size: c8 (Free) ....
8458f0f8 size: c8 previous size: 30 (Allocated) Ntfx
8458f1c0 size: 90 previous size: c8 (Allocated) MmCa
8458f250 size: a8 previous size: 90 (Allocated) File (Protected)
8458f2f8 size: 68 previous size: a8 (Allocated) FMsl
8458f360 size: c8 previous size: 68 (Allocated) Ntfx
8458f428 size: 28 previous size: c8 (Free) usbp
8458f450 size: 68 previous size: 28 (Allocated) FMsl
8458f4b8 size: c8 previous size: 68 (Allocated) Ntfx
8458f580 size: 90 previous size: c8 (Allocated) MmCa
8458f610 size: a8 previous size: 90 (Allocated) File (Protected)
8458f6b8 size: 68 previous size: a8 (Allocated) FMsl
8458f720 size: 90 previous size: 68 (Allocated) MmCa
8458f7b0 size: c8 previous size: 90 (Allocated) Ntfx
8458f878 size: c8 previous size: c8 (Allocated) Ntfx
8458f940 size: 20 previous size: c8 (Free) XSav
8458f960 size: 90 previous size: 20 (Allocated) MmCa
8458f9f0 size: a8 previous size: 90 (Allocated) File (Protected)
8458fa98 size: 68 previous size: a8 (Allocated) FMsl
8458fb00 size: c8 previous size: 68 (Allocated) Ntfx
*8458fbc8 size: 140 previous size: c8 (Free ) *Io Process: 85d35030
Pooltag Io : general IO allocations, Binary : nt!io
8458fd08
size: 2f8 previous size: 140 (Free ) usbp
!pool 명령으로 확인해보면 역시나 다음 해제된 풀의 주소이다. 여기서 알 수 있는 사실은 해제된 풀의 첫 4바이트는 해제된 풀들의 리스트이고 이는 POOL_DESCRIPTOR의 PendingFrees 리스트와 연관이 있다는 것이다.
달리 말해 이 첫 4바이트가 손상되면 PendingFrees 리스트에도 문제가 생겨 이번과 같은 이슈가 발생하게 된다.
그렇다면 우리가 찾고 있는 "11223344" 값은 누군가에 의해 손상된 값이 아닐까?
이를 테면 누군가 메모리를 해제하고 해제된 메모리의 첫 4바이트에 11223344 값을 써서 의도치 않게 PendingFrees 리스트를 손상시키는 상황을 상상해보자.
그럴 듯 하다. 그렇다면... 그래! 모두 뒤져보자.
메모리 어딘가에는 11223344 값이 기록되어 있을 테니 전체 메모리 탐색을 통해 증거를 찾아보자.
메모리 검색을 위해 s 명령을 사용했으며 검색 범위는 커널 주소 영역 전체인 80000000 부터 ffffffff까지 설정했다.
참고로 검색 크기를 설정하는 L 옵션에 ? 를 사용해야 큰 범위 설정이 가능하다.
kd> s 80000000 L?80000000 44 33 22 11
// kdvm.dll 모듈
80bd0342 44 33 22 11 02 00 00 00-00 00 00 00 ff ff ff ff D3".............
// nt 모듈
82b656c4 44 33 22 11 50 2b ba 82-50 2b ba 82 95 f7 b5 82 D3".P+..P+......
// nt 모듈
82b656d8 44 33 22 11 95 f7 b5 82-60 5b b6 82 e7 13 01 87 D3".....`[......
// nt 모듈
82b6570c 44 33 22 11 00 00 00 00-80 23 b7 82 00 00 00 00 D3"......#......
// nt 모듈
82b65a30 44 33 22 11 58 a1 49 86-60 5b b6 82 03 01 00 00 D3".X.I.`[......
// nt 모듈
82b65aa0 44 33 22 11 02 00 00 00-00 00 00 00 95 f7 b5 82 D3".............
// nt 모듈
82b65af8 44 33 22 11 60 01 40 01-ff ff ff ff 30 00 13 8d D3".`.@.....0...
// nt 모듈
82b65b50 44 33 22 11 58 18 45 8b-46 49 b7 82 02 00 00 00 D3".X.E.FI......
// nt 모듈
82b69008 44 33 22 11 00 50 18 00-f9 06 00 00 00 00 00 00 D3"..P..........
// nt 모듈
82b9fa44 44 33 22 11 02 00 00 00-00 00 00 00 95 f7 b5 82 D3".............
// nt 모듈
82ba2138 44 33 22 11 95 f7 b5 82-60 5b b6 82 e7 13 01 87 D3".....`[......
// nt 모듈
82ba216c 44 33 22 11 03 00 00 00-80 23 b7 82 00 00 00 00 D3"......#......
// nt 모듈
82ba2490 44 33 22 11 58 a1 49 86-60 5b b6 82 03 01 00 00 D3".X.I.`[......
// nt 모듈
82ba2500 44 33 22 11 02 00 00 00-00 00 00 00 95 f7 b5 82 D3".............
// nt 모듈
82ba2558 44 33 22 11 60 01 40 01-ff ff ff ff 30 00 13 8d D3".`.@.....0...
// nt 모듈
82ba25b0 44 33 22 11 00 00 00 00-46 49 b7 82 02 00 00 00 D3".....FI......
// nt 모듈
82dab21c 44 33 22 11 00 50 18 00-f9 06 00 00 00 00 00 00 D3"..P..........
// nt 모듈
82dab4cc 44 33 22 11 02 00 00 00-00 00 00 00 ff ff ff ff D3".............
// ***
8448ae08 44 33 22 11 40 30 fb 85-10 ae 48 84 10 ae 48 84 D3".@0....H...H.
// BSOD 관련 crashdmp.sys 풀 영역
85b8102c 44 33 22 11 02 00 00 00-00 00 00 00 95 f7 b5 82 D3".............
// crashdmp.sys 모듈
8d1682d0 44 33 22 11 02 00 00 00-00 00 00 00 95 f7 b5 82 D3".............
// crashdmp.sys 모듈
8d1686e8 44 33 22 11 02 00 00 00-00 00 00 00 95 f7 b5 82 D3".............
// MyDrv.sys 모듈
90e01322 44 33 22 11 8b e5 5d c3-cc cc cc cc cc cc 8b
ff D3"...].........
우리는 해제된 풀을 찾을 목적이기 때문에 결과에서 모듈 영역 주소와 연관이 없는 풀 메모리 영역을 제외하면 8448ae08 주소 하나가 남는다.(주석 내용은 내가 lmva와 !pool 명령으로 하나씩 확인하면서 적은 것으로 *** 표시한 주소가 모듈 영역 주소도 아니면서 가장 의심이 가는 주소다)
8448ae08 내용을 풀 헤더를 포함해서 한 번 살펴보자.
kd> db 8448ae08-8
↓"MDrv" ↓"11223344"
8448ae00 1d 00 40 08 4d 44 72 76-44 33 22 11 40 30 fb 85 ..@.MDrvD3".@0..
8448ae10 10 ae 48 84 10 ae 48 84-00 00 00 00 18 00 00 00 ..H...H.........
8448ae20 00 01 0b 0d 00 00 00 01-38 da af ff 00 00 00 00 ........8.......
8448ae30 0a 0f 52 82 10 da af ff-00 00 00 00 6c da af ff ..R.........l...
8448ae40 12 00 30 00 00 00 00 00-30 00 f7 85 70 00 f7 85 ..0.....0...p...
8448ae50 70 00 f7 85 6e 94 c1 82-72 53 cf 82 0a 0f 52 82 p...n...rS....R.
8448ae60 10 da af ff 38 da af ff-00 00 00 00 00 00 00 00 ....8...........
8448ae70 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00
00 ................
8448ae08 주소에 찾고 있는 11223344 값이 보이고, 4바이트 앞 풀 태그 영역에는 "MDrv"라는 의미 있는 문자열이 확인된다.
검증을 위해 풀 헤더 시작 주소인 8448ae00을 POOL_HEADER 구조체로 확인해보자.
kd> dt _POOL_HEADER 8448ae00
nt!_POOL_HEADER
+0x000 PreviousSize : 0y000011101 (0x1d)
+0x000 PoolIndex : 0y0000000 (0)
+0x002 BlockSize : 0y001000000 (0x40) // 풀 크기
+0x002 PoolType : 0y0000100 (0x4)
+0x000 Ulong1 : 0x840001d
+0x004 PoolTag : 0x7672444d // MDrv 풀 태그
+0x004 AllocatorBackTraceIndex : 0x444d
+0x006 PoolTagHash : 0x7672
BlockSize가 0x40이라고 나온다. 실제 바이트로 환산하려면 8을 곱해줘야 한다.
kd> ?40*8
Evaluate expression: 512 = 00000200
0x200이 풀 크기로 계산된다. 만약 8448ae00이 유효한 풀 주소가 맞다면 전체 풀 크기인 8448ae00+0x200 뒤에 다음 풀 정보가 있을 것이다.
kd> db 8448ae00 L200+10
8448ae00 1d 00 40 08 4d 44 72 76-44 33 22 11 40 30 fb 85 ..@.MDrvD3".@0..
8448ae10 10 ae 48 84 10 ae 48 84-00 00 00 00 18 00 00 00 ..H...H.........
8448ae20 00 01 0b 0d 00 00 00 01-38 da af ff 00 00 00 00 ........8.......
8448ae30 0a 0f 52 82 10 da af ff-00 00 00 00 6c da af ff ..R.........l...
8448ae40 12 00 30 00 00 00 00 00-30 00 f7 85 70 00 f7 85 ..0.....0...p...
8448ae50 70 00 f7 85 6e 94 c1 82-72 53 cf 82 0a 0f 52 82 p...n...rS....R.
8448ae60 10 da af ff 38 da af ff-00 00 00 00 00 00 00 00 ....8...........
8448ae70 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448ae80 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448ae90 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448aea0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448aeb0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448aec0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448aed0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448aee0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448aef0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af00 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af10 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af20 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af30 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af40 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af50 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af60 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af70 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af80 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448af90 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448afa0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448afb0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448afc0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
8448afd0 00 00 00 00 00 00 00 00-03 00 00 00 00 00 00 00 ................
8448afe0 00 00 00 00 00 00 00 00-00 00 00 00 78 35 4a 85 ............x5J.
8448aff0 00 00 00 00 00 00 00 00-00 00 00 00 30 50 d3 85 ............0P..
// 다음 풀 주소 8448b000
8448b000 00 00 fb 15 49 6f 20 20-00 00 00 00 04 00 01 00 ....Io ........
다음 풀 주소 위치인 8448b000에 Io 라는 문자열이 확인된다. !pool 명령으로도 확인해보자.
kd> !pool 8448b000
Pool page 8448b000 region is Nonpaged pool
*8448b000 size: fd8 previous size: 0 (Allocated) *Io Process: 8618c1d0
Pooltag Io : general IO allocations, Binary : nt!io
8448bfd8
size: 28 previous size: fd8 (Allocated) VadS
Io 풀 태그를 갖는 정상적인 풀 메모리가 맞다.
그렇다면 찾은 8448ae00은 MDrv 풀 태그를 갖는 정상적으로 해제된 풀 메모리였을 것이다.
무엇보다 해제된 풀 헤더 다음 첫 4바이트에 해제된 풀의 주소가 아닌 "11223344" 값을 갖고 있는 것이 결정적인 증거다.
이는 풀의 소유자가 자신이 해제한 메모리를 재사용했다는 증거이다.
이제 앞서 배운 !for_each_module 명령과 lmva 명령을 통해 MDrv 풀 태그의 소유자를 찾아보자.
kd> !for_each_module s -a @#Base @#End MDrv
90e012f7 4d 44 72 76 68 f8 01 00-00 6a 00 ff 15 48 20 e0 MDrvh....j...H .
kd> lmva 90e012f7
Browse full module list
start end module name
90e00000 90e08000 MyDrv (private pdb symbols)
Loaded symbol image file: MyDrv.sys
Image path: \??\C:\WinDbg\MyDrv.sys
Image name: MyDrv.sys
Browse all global symbols functions data
Timestamp: Thu Nov 30 18:44:39 2017 (5A1FD307)
CheckSum: 000094C4
ImageSize: 00008000
Translations:
0000.04b0 0000.04e4 0409.04b0 0409.04e4
이런! MyDrv.sys 모듈이 범인이었다. 마지막 퍼즐 한 조각을 찾은 것 같은 가슴 벅찬 순간이다.
이쯤에서 MyDrv.sys 모듈에서 해제 리스트를 손상시킨 소스코드를 공개하겠다.
(참고로 오늘 덤프는 학습을 위해 아래 예제 코드를 통해 생성한 덤프다)
typedef struct _FREE_LIST_DATA
{
ULONG ulTag;
CHAR cBuffer[500];
} FREE_LIST_DATA, *PFREE_LIST_DATA;
void CorruptPoolHeader(void)
{
PFREE_LIST_DATA pData;
pData = ExAllocatePoolWithTag(NonPagedPool, sizeof(FREE_LIST_DATA), 'vrDM');
if (pData)
{
ExFreePool(pData);
}
// Oops!
pData->ulTag = 0x11223344;
}
메모리를 해제한 뒤에 첫 번째 필드인 ulTag 에 11223344 값을 쓰고 있다!
이런 단순한 실수로 이렇게 엄청난 덤프를 만들 수 있다는 사실이 놀랍다.
이번 예제는 일부러 눈에 잘 띄는 값으로 해제된 메모리를 손상시켰지만, 실제로는 비트 연산으로 1 비트만 손상시키는 경우도 있다. 이런 경우 분석이 거의 불가능하다. 이번처럼 분석이 성공하는 경우는 굉장히 운이 좋은 날이라고 생각하면 된다. 보통 메모리 손상의 유형 중 특정 위치의 메모리만 손상시키는 2번 시나리오는 손상된 위치에서 범인을 찾기가 매우 어렵기 때문이다.
예제를 통해 실수는 한 줄이지만 이로 인한 분석은 굉장히 어렵다는 사실을 충분히 느꼈으리라 생각한다.
이런 이유로 개발시 드라이버 확인 프로그램을 충분히 활용하고 해제된 메모리는 재사용하지 않게 주의해야 한다.
'Dump Analysis' 카테고리의 다른 글
| [Hang] CPU 과점유 (0) | 2018.08.13 |
|---|---|
| [0x133] DPC_WATCHDOG_VIOLATION (0) | 2018.07.29 |
| [0xC5] 풀 헤더 손상 (0) | 2018.07.16 |
| [0x1A] 페이지 손상 (0) | 2018.07.12 |
| [0x50] 해제된 핸들 (0) | 2018.07.09 |
