'BugCheck' 태그의 글 목록

'BugCheck'에 해당되는 글 10건

2007.09.17 [WinDbg 분석] BugCheck 0xC4-60
2007.09.17 [WinDbg 분석] BugCheck 0xCE
2007.09.17 [WinDbg 분석] BugCheck 0x7F
2007.09.17 [WinDbg 분석] BugCheck 0xA (분석가능)
2007.09.17 [WinDbg 분석] BugCheck 0xA (분석불가능)
2007.09.16 [WinDbg 분석] BugCheck 0x19 1
2007.06.29 [WinDbg 분석] BugCheck 0xC1 2
2007.06.29 [WinDbg 분석] BugCheck 0xD6
2007.06.29 [WinDbg 분석] BugCheck 0x50
2007.05.07 [WinDbg 분석] BugCheck 0x19 (원인분석불가능) 1

[WinDbg 분석] BugCheck 0xC4-60

오늘은 BugCheck 0xC4-60 을 보도록 하겠습니다.
지금까지와 다르게 버그체크 코드에 60 이 붙었는데요.
60 이 의미하는 것은 Arg1 즉 첫번째 파라미터가 표시하는 값이 되겠습니다.

BugCheck 0xC4 에 대해서 WinDbg Help 를 찾아보면 Arg1 에 따라서 BugCheck 0xC4
는 엄청나게 많은 다른 의미를 가진다는 것을 알 수 있습니다. Arg1 이 중요한 의미
를 가지게 되므로 BugCheck 0xC4 에는 Arg1 을 붙여서 표시하도록 하겠습니다.

BugCheck 0xC4-60 은 드라이버에 메모리 릭이 존재한다는 것을 알려줍니다.
이것은 Verifier 에서 Pool Tracking 옵션을 사용해야 발생합니다.

예제를 보면서 설명합니다.

kd> !analyze -v
****************************************************************************
*    *
*    Bugcheck Analysis    *
*    *
****************************************************************************

DRIVER_VERIFIER_DETECTED_VIOLATION (c4)
A device driver attempting to corrupt the system has been caught. This is
because the driver was specified in the registry as being suspect (by the
administrator) and the kernel has enabled substantial checking of this driver.
If the driver attempts to corrupt the system, bugchecks 0xC4, 0xC1 and 0xA will
be among the most commonly seen crashes.
Parameter 1 = 0x1000 .. 0x1020 - deadlock verifier error codes.
Typically the code is 0x1001 (deadlock detected) and you can
issue a '!deadlock' KD command to get more information.
Arguments:
Arg1: 00000060, A driver has forgotten to free its pool allocations prior to unloading.
Arg2: 00000000, paged bytes
Arg3: 00000010, nonpaged bytes,
Arg4: 00000002, total # of (paged+nonpaged) allocations that weren't freed.
To get the name of the driver at fault, type
dp ViBadDriver l1; dS @$p
Then type !verifier 3 drivername.sys for info on the allocations
that were leaked that caused the bugcheck.

Debugging Details:
------------------

BUGCHECK_STR: 0xc4_60

IMAGE_NAME: MyDrv.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 3f963fa3

MODULE_NAME: MyDrv

FAULTING_MODULE: f9d6c000 MyDrv

DEFAULT_BUCKET_ID: DRIVER_FAULT

PROCESS_NAME: services.exe

LAST_CONTROL_TRANSFER: from 80628271 to 804f14c9

STACK_TEXT:
f9cafad8 80628271 000000c4 00000060 00000000 nt!KeBugCheckEx+0x19
f9cafb00 80583885 813f2b98 80f56848 80f56870 nt!MiVerifyingDriverUnloading+0x11f
f9cafb2c 8055c1e0 813f2b98 80f56858 80591517 nt!MmUnloadSystemImage+0x179
f9cafb38 80591517 80f56870 80f56858 00000000 nt!IopDeleteDriver+0x2e
f9cafb54 80513095 80f56870 00000000 f9cafc34 nt!ObpRemoveObjectRoutine+0xdd
f9cafb78 804ed83d f9cafc34 f9cafcb0 8055d706 nt!ObfDereferenceObject+0x5d
f9cafc1c 8055d711 f9cafd1c 00000000 8052a421 nt!IopUnloadDriver+0x28f
f9cafc28 8052a421 f9cafd1c f9cafc4c 805c9c00 nt!NtUnloadDriver+0xb
f9cafc28 804f6c29 f9cafd1c f9cafc4c 805c9c00 nt!KiSystemService+0xc4
f9cafca4 804ed69d f9cafd1c f9cafd64 0076f8d4 nt!ZwUnloadDriver+0x11
f9cafd4c 8055d711 0076f8dc 00000000 8052a421 nt!IopUnloadDriver+0xef
f9cafd58 8052a421 0076f8dc 00000000 00000000 nt!NtUnloadDriver+0xb
f9cafd58 7ffe0304 0076f8dc 00000000 00000000 nt!KiSystemService+0xc4
0076f8e4 00000000 00000000 00000000 00000000 SharedUserData!SystemCallStub+0x4

STACK_COMMAND: kb

FOLLOWUP_NAME: MachineOwner

FAILURE_BUCKET_ID: 0xc4_60_VRF_IMAGE_MyDrv.sys_DATE_2003_10_22

BUCKET_ID: 0xc4_60_VRF_IMAGE_MyDrv.sys_DATE_2003_10_22

Followup: MachineOwner
---------

BugCheck 설명에서 드라이버가 시스템을 망치려고 할 때 잡아준다고 하고 있습니다.
포괄적인 설명이구요. Parameter 1 이 0x1001 일 때는 deadlock 이니 !deadlock
명령어 를 사용하라고 설명해 주기도 하네요.
이번은 Parameter 1 이 0x60 이니 상관없는 사항입니다.

파라미터 메시지를 보면

Arg1: 00000060, A driver has forgotten to free its pool allocations prior to unloading.
드라이버가 언로드되기 전에 할당한 메모리들을 해제하지 않은 경우인 것을 알 수 있습니다.

Arg2: 00000000, paged bytes
Paged Pool 할당한 것은 없네요.

Arg3: 00000010, nonpaged bytes,
NonPaged Pool 할당한 것이 16 바이트 남았다고 합니다.

Arg4: 00000002, total # of (paged+nonpaged) allocations that weren't freed.
할당은 했는데 해제하지 않은 수가 2 개 라고 합니다.

아주 친절한 설명이네요. 문제의 기본적인 상황을 이해하는데 도움이 많이 됩니다.

그 밑에 메시지 보이시죠? 하라는 것도 보이시나요? 그대로 합니다.
기억하시죠? 드래그, 클릭, 클릭, Enter ^^

kd> dp ViBadDriver l1; dS @$p
8054029c 81581f18
81581f68 "MyDrv.sys"

두 명령어가 한번에 실행된 것인데요. ; 를 이용해서 한 것입니다.
첫번째는 dp 명령어를 사용했네요. 지정된 영역을 포인터 값으로 보여줍니다.
dS 는 display string 인데 UNICODE_STRING 을 보이라는 겁니다.
@$p 가 81581f18 을 지시하는 역할을 했네요.
@$p 가 어떤 문법적인 기능을 가지고 있는지 잘 모르겠습니다.
나중에 좀 더 연구해 보기로 하구요. 일단 넘어갑니다.

그 다음에 또 하라는게 있습니다. 또 합니다.
drivername.sys 자리에 이름 바꿔 넣는거 주의하시구요.

kd> !verifier 3 MyDrv.sys

Verify Level 79 ... enabled options are:
Special pool
All pool allocations checked on unload
Io subsystem checking enabled
Deadlock detection enabled
Enhanced Io checking enabled

Summary of All Verifier Statistics

RaiseIrqls 0x0
AcquireSpinLocks 0x0
Synch Executions 0x0
Trims 0x0

Pool Allocations Attempted 0x2
Pool Allocations Succeeded 0x2
Pool Allocations Succeeded SpecialPool 0x2
Pool Allocations With NO TAG 0x0
Pool Allocations Failed 0x0
Resource Allocations Failed Deliberately 0x0

Current paged pool allocations 0x0 for 00000000 bytes
Peak paged pool allocations 0x0 for 00000000 bytes
Current nonpaged pool allocations 0x2 for 00000010 bytes
Peak nonpaged pool allocations 0x2 for 00000010 bytes

Driver Verification List

Entry State NonPagedPool PagedPool Module

81581f08 Loaded 00000010 00000000 MyDrv.sys

Current Pool Allocations 00000000    00000002
Current Pool Bytes    00000000    00000010
Peak Pool Allocations 00000000    00000002
Peak Pool Bytes 00000000    00000010

PoolAddress SizeInBytes Tag CallersAddress
b8104ff8 0x00000008 Ddk f9d6c50b
b86e6ff8 0x00000008 Ddk f9d6c50b

자세한 메시지들이 나왔습니다. 잘 읽어보시면 메모리 사용에 대한 정보를 알수 있구요.
마지막을 보면 해제되지 않은 메모리 주소 2개와 그것을 할당한 함수 주소가 보입니다.

할당한 함수 주소를 알고 있으니 그 함수로 가서 할당하는 부분과 해제하는 부분을
검토해 보면 문제가 바로 풀릴 수 있습니다. 이건 운이 아주 좋은 경우이구요.

드라이버에서 ExAllocatePool 을 호출하는 my_malloc 이라는 Wrapper 함수를 만들어서
사용중이었다면 위의 CallerAddress는 모두 my_malloc 만 보여줄 테니 별로 도움이
되지 않습니다. CallerAddress란 ExAllocaePool 을 호출한 함수의 주소이기 때문입니다.

이럴 땐 메모리의 내용까지 들여다 보고 메모리의 내용을 해석해서 어떤 것을 넣어서
사용하고 있던 메모리인지 확인해야 합니다. 메모리 내용에 문자열이 있었다면 그나마
아주 다행스러운 일입니다. 그 문자열이 사용되는 곳을 찾으면 되니까요.

예제에서의 메모리를 보면

kd> db b8104ff8
b8104ff8 46 69 6e 64 20 4d 65 00-?? ?? ?? ?? ?? ?? ?? ?? Find Me.????????
b8105008 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????

kd> db b86e6ff8
b86e6ff8 46 69 6e 64 20 4d 65 00-?? ?? ?? ?? ?? ?? ?? ?? Find Me.????????
b86e7008 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????

"Find Me" 라는 아주 귀여운 문자열이 들어있네요.
소스코드에서 Find Me 를 검색하면 다 나올 것 같습니다.

여기에 숫자들만 들어있었다면 메모리 내용을 잘 보면서 분석해야 합니다.
무슨 네오도 아니고... 잘 될까요? 아무래도 쉽지 않겠죠. ^^

이제 함수도 확인해 봅니다.

kd> u f9d6c50b
MyDrv!BugCheckC4+0x13 [d:\project\test\mydrv\mydrv.c @ 315]:
f9d6c50b 8945fc    mov dword ptr [ebp-4],eax
f9d6c50e 8b45fc    mov eax,dword ptr [ebp-4]
f9d6c511 8b0df0c4d6f9    mov ecx,dword ptr [MyDrv!BugCheckBE+0x10 (f9d6c4f0)]

313: void BugCheckC4(void)
314: {
315: PCHAR p = (PCHAR)ExAllocatePool( NonPagedPool, 8 );
316:
317: strcpy( p, "Find Me" );

메모리를 할당하고 "Find Me" 까지 넣어주는게 바로 보입니다.

할당은 했는데 해제하지를 않아서 발생한 문제이니 해제하는 부분이 어디인지 확인해서
문제를 해결해야 합니다. 하지만 이 소스에서는 해제하는 부분을 찾을 수 없었습니다.
제가 만들지 않았거든요. ^^ 함수 이름도 너무 정직하지 않습니까? BugCheckC4()

이번 예제에서 !analyze -v 메시지에 보이는 콜스택은 분석에 전혀 도움이 되지 않았습니다.
그저 드라이버를 언로드하다가 잡혔다는 내용 정도만 참고하시기 바랍니다.

마무리하기 전에 !verifier 3 의 활용에 대한 이야기를 조금 더 하지요.
이 명령은 메모리 할당 상황에 대한 정보를 제공해 주기 때문에 동작중인 드라이버의 메모리
사용 현황에 대한 분석을 할 때도 사용할 수 있습니다.

개발을 하다 보면 자신이 작성한 드라이버가 메모리를 얼마나 많이 차지하는가, 할당과
해제는 얼마나 많이 하는가를 측정해야 할 일도 있는데요.

드라이버를 동작시키고 WinDbg 로 멈춘 다음 그냥 !verifier 3 MyDrv.sys 를 실행해 줍니다.
그러면 위와 같은 메시지가 발생하는데 다음 항목을 위주로 보시면 됩니다.

Entry State NonPagedPool PagedPool Module
81581f08 Loaded 00000040 00000340    MyDrv.sys

Current Pool Allocations 00000000    00000020 => 현재 할당된 메모리 갯수
Current Pool Bytes    00000000    00000380 => 현재 할당된 총 바이트수
Peak Pool Allocations 00000000    00000142 => 최고로 많이 할당했을 때의 메모리 갯수
Peak Pool Bytes 00000000    00001220 => 최고로 많이 할당했을 때의 총 바이트수

여러분의 드라이버가 메모리를 얼마나 차지하고 있을까요?
한번 확인해 보시죠. ^^

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&GotoPage=6&s_bulu=&s_key=&no=33

Posted by GreeMate

[WinDbg 분석] BugCheck 0xCE

BugCheck 0xCE 는 드라이버가 언로드된 이후에 드라이버 코드가 실행될 때 발생하는 오류입니다.
드라이버가 언로드되었는데 어떻게 드라이버 코드가 실행된다는 말일까요?
문제 정의가 어려운 것처럼 문제 잡기도 쉽지 않은 종류의 오류입니다.

하지만 간단한 예제를 통해서 어떻게 분석해야 할지 알아보도록 합니다.

kd> !analyze -v
***************************************************************************
* *
* Bugcheck Analysis *
* *
***************************************************************************

DRIVER_UNLOADED_WITHOUT_CANCELLING_PENDING_OPERATIONS (ce)
A driver unloaded without cancelling timers, DPCs, worker threads, etc.
The broken driver's name is displayed on the screen.
Arguments:
Arg1: b16569c8, memory referenced
Arg2: 00000000, value 0 = read operation, 1 = write operation
Arg3: b16569c8, If non-zero, the instruction address which referenced the bad memory
address.
Arg4: 00000000, Mm internal code.

Debugging Details:
------------------

FAULTING_MODULE: 804d6000 nt

DEBUG_FLR_IMAGE_TIMESTAMP: 0

READ_ADDRESS: unable to get nt!MmSpecialPoolStart
unable to get nt!MmSpecialPoolEnd
unable to get nt!MmPoolCodeStart
unable to get nt!MmPoolCodeEnd
b16569c8

FAULTING_IP:
MyDrv+29c8
b16569c8 ?? ???

CUSTOMER_CRASH_COUNT: 1

DEFAULT_BUCKET_ID: WRONG_SYMBOLS

BUGCHECK_STR: 0xCE

IP_MODULE_UNLOADED:
MyDrv+29c8
b16569c8 ?? ???

LAST_CONTROL_TRANSFER: from 00000000 to b16569c8

FAILED_INSTRUCTION_ADDRESS:
MyDrv+29c8
b16569c8 ?? ???

STACK_TEXT:
b0f127d8 00000000 00000000 00000000 b0f12b1c <Unloaded_MyDrv.sys>+0x29c8

STACK_COMMAND: kb

FOLLOWUP_IP:
MyDrv+29c8
b16569c8 ?? ???

SYMBOL_STACK_INDEX: 0

SYMBOL_NAME: MyDrv+29c8

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: MyDrv

IMAGE_NAME: MyDrv.sys

BUCKET_ID: WRONG_SYMBOLS

Followup: MachineOwner
---------

BugCheck 의 제목과 설명에서 문제를 잘 알려주고 있습니다.
드라이버가 timer, DPC, worker thread 등을 해제하지 않고 언로드 되었다는군요.

Arg1: b16569c8, memory referenced
Arg2: 00000000, value 0 = read operation, 1 = write operation
Arg3: b16569c8, If non-zero, the instruction address which referenced the bad memory
address.

Arg1 에서 시스템이 죽었을 때 참조된 메모리 주소가 b16569c8 임을 알 수 있습니다.
Arg3 에서 그 주소가 바로 우리 드라이버 코드의 주소였음을 알 수 있구요.

다음 메시지들에서도 이 주소는 계속해서 반복됩니다.
결국 이 주소가 어느 드라이버 영역인지 확인까지 해 줍니다.

FAILED_INSTRUCTION_ADDRESS:
MyDrv+29c8
b16569c8 ?? ???

MyDrv+29c8 실행주소가 실행에 실패했다는 뜻으로 보입니다.
실패한 이유는 b16569c8 라는 주소가 메모리에 존재하지 않아서 발생한 것입니다.
메시지에 나타나는 수많은 ??? 는 해당 주소가 메모리에 존재하지 않는다는 것을 나타내고 있습니다.

메모리에 존재하지 않는 이유는 BugCheck 코드에서 이미 설명되었습니다.
드라이버가 내려간 것이죠. lm 명령으로 간단히 확인해 봅니다.

kd> lm
start end module name
804d6000 806c8180 nt T (no symbols)
806c9000 806dbe80 hal (deferred)
b09fc000 b0a22e80 kmixer (deferred)
b11cb000 b11d9900 Cdfs (deferred)
...
f7b55000 f7bde300 Ntfs (deferred)

Unloaded modules:
b1654000 b1674000 MyDrv.sys
b160a000 b1631000 kmixer.sys
b1e6e000 b1e6f000 drmkaud.sys
b1a19000 b1a26000 DMusic.sys
b1631000 b1654000 aec.sys
...

상단 모듈 리스트에는 MyDrv 가 존재하지 않습니다. 로드된 MyDrv 는 현재 없다는 뜻이구요.
Unloaded modules 첫번째에 MyDrv 가 보입니다.
Unloaded modules 는 이미 아시는 바 대로 가장 최근에 Unload 된 것부터 순차적으로 보여줍니다.
MyDrv 는 문제가 발생하기 직전에 Unload 되었다는 것을 알 수 있습니다.

기본적인 정황은 파악되었습니다.
이제는 드라이버가 내려갔는데도 불구하고 도대체 어떤 함수가 실행되고 있었는지 찾아야 합니다.
어떤 함수인지 알면 DriverUnload 루틴에서 그 함수가 더 이상 실행되지 않도록 처리하고 드라이버를 Unload 할 수 있을 것입니다.

어떤 함수인지 알고 싶은데 메시지에서 콜스택을 보면 마지막으로 호출된 함수의 주소만 나옵니다.

STACK_TEXT:
b0f127d8 00000000 00000000 00000000 b0f12b1c <Unloaded_MyDrv.sys>+0x29c8

MyDrv 의 심볼파일이 존재해도 Unload된 모듈이기 때문에 함수이름을 보여주지 않습니다.
또한 함수호출의 흐름도 보여주지 않습니다.

앞으로 다소 험한 여정이 될 것임이 느껴지시지요?

자... 일단 콜스택을 확인해 봅시다.
이번 예제 이외에도 WinDbg 가 콜스택을 제대로 보여주지 못하는 경우는 종종 있습니다.
이런 경우 콜스택을 수동으로 확인해야 하는데요. 수동으로 확인하더라도 그나마 노가다를 덜하는 방법은 바로 dds 명령을 사용하는 것입니다.

dds 명령은 메모리를 나열해 주면서 메모리에 존재하는 값과 일치하는 심볼이 있으면 그것을 보여줍니다.
콜스택 보기를 원하는 것이므로 죽었을 당시의 스택포인터인 esp 를 살펴봅니다.

kd> dds esp
b0f127dc 00000000
b0f127e0 00000000
b0f127e4 00000000
b0f127e8 b0f12b1c
b0f127ec b0f128a0
b0f127f0 b165eb2f <Unloaded_MyDrv.sys>+0xab2f
b0f127f4 b1670780 <Unloaded_MyDrv.sys>+0x1c780
b0f127f8 b0f12800
b0f127fc b165e4a0 <Unloaded_MyDrv.sys>+0xa4a0
b0f12800 006f0064
b0f12804 006f006d
b0f12808 006c0062
b0f1280c 00000069
b0f12810 00000000
b0f12814 00000000
b0f12818 00000000
b0f1281c 00000000
b0f12820 00000000
b0f12824 00000000
b0f12828 00000000
b0f1282c 00000000
b0f12830 00000000
b0f12834 00000000
b0f12838 00000000
b0f1283c 00000000
b0f12840 00000000
b0f12844 00000000
b0f12848 00000000
b0f1284c 00000000
b0f12850 00000000
b0f12854 00000000
b0f12858 00000000
kd> dds
b0f1285c 00000000
b0f12860 00000000
b0f12864 00000000
b0f12868 00000000
b0f1286c 00000000
b0f12870 00000000
b0f12874 00000000
b0f12878 00000000
b0f1287c 00000000
b0f12880 b0f128d4
b0f12884 00000044
b0f12888 893ca9e8
b0f1288c 00000000
b0f12890 00000000
b0f12894 00000000
b0f12898 00000000
b0f1289c b0f12b1c
b0f128a0 b0f128b8
b0f128a4 b165bb93 <Unloaded_MyDrv.sys>+0x7b93
b0f128a8 b1670780 <Unloaded_MyDrv.sys>+0x1c780
b0f128ac 893ca9e8
b0f128b0 b0f12b1c
b0f128b4 b0f128d4
b0f128b8 b0f1291c
b0f128bc b165c934 <Unloaded_MyDrv.sys>+0x8934
b0f128c0 893ca9e8
b0f128c4 b0f12b1c
b0f128c8 b0f128d4
b0f128cc e22847c7
b0f128d0 00000000
b0f128d4 b0f12918

스택을 충분히 보기 위해서 dds 를 2번 해 봤습니다.
Unload 된 드라이버의 함수호출 흔적들이 보입니다. 이 흔적들 중에서 진짜를 찾아내야 하는데요.
마치 닌자의 분신들로부터 진짜를 찾아내는 기분이군여. ^^

함수 호출시의 스택프레임 생성에 대해서 이해하고 있는 분들은 쉽게 진짜를 찾으실 겁니다.
그렇지 않은 분들은 다소 괴로우실텐데요. 이것을 설명하고자 하면 무지하게 길어지므로 생략하고 다음 설명을 하면서 간단히 언급하겠습니다.

b0f127ec b0f128a0
b0f127f0 b165eb2f <Unloaded_MyDrv.sys>+0xab2f
b0f127f4 b1670780 <Unloaded_MyDrv.sys>+0x1c780
b0f127f8 b0f12800
b0f127fc b165e4a0 <Unloaded_MyDrv.sys>+0xa4a0

어떤 것이 진짜 함수 호출이었을까요?
물론 모두 진짜 함수 호출이었습니다. 스택이기 때문에 함수들이 호출되면서 계속 재사용되구요.
과거에 호출된 함수들의 흔적이 남아 있어서 위와 같이 어지럽게 보이는 것입니다.
우리가 지금 찾고자 하는 것은 죽기 직전에 호출된 함수들의 흐름입니다.

세 개중에서 죽기 직전에 호출된 함수는 <Unloaded_MyDrv.sys>+0xab2f 입니다.
왜냐하면 깨지지 않은 정상적인 함수의 스택프레임은 다음과 같은 형태를 가지기 때문입니다.

스택주소 내용
xxxx000c 호출하는 함수의 ebp (스택주소 영역의 값)
xxxx0010 호출하는 함수의 복귀주소(return address)

<Unloaded_MyDrv.sys>+0x1c780 는 이런 형태가 깨져 버렸으므로 쓰레기 데이터로 보면 됩니다.

b0f127f0 b165eb2f <Unloaded_MyDrv.sys>+0xab2f <= 요부분이 맞지 않습니다.
b0f127f4 b1670780 <Unloaded_MyDrv.sys>+0x1c780

<Unloaded_MyDrv.sys>+0xa4a0 은 형태가 같아서 유력한 후보중에 하나였는데요.

b0f127f8 b0f12800 <= 스택주소 영역의 값
b0f127fc b165e4a0 <Unloaded_MyDrv.sys>+0xa4a0

이것이 쓰레기 데이터로 밝혀진 이유는 b0f12800 을 따라가 봤을 때 상위함수의 스택프레임이 나오지 않았기 때문입니다.

b0f12800 006f0064 <= 스택주소 영역의 값이 아님
b0f12804 006f006d <= 함수주소 영역의 값이 아님

<Unloaded_MyDrv.sys>+0xab2f 는 스택프레임 모양이 일치하구요 상위를 따라가 봐도 스택프레임이 보입니다.

b0f127ec b0f128a0 <= 스택주소 영역의 값
b0f127f0 b165eb2f <Unloaded_MyDrv.sys>+0xab2f <= 상위함수 복귀주소

호출하는 함수의 ebp 인 b0f128a0 에는 상위함수의 ebp 가 들어있습니다.

b0f128a0 b0f128b8
b0f128a4 b165bb93 <Unloaded_MyDrv.sys>+0x7b93

한번을 더 따라가 봐도

b0f128b8 b0f1291c
b0f128bc b165c934 <Unloaded_MyDrv.sys>+0x8934

ebp, retaddr 형태가 계속됩니다.

이것을 통해서 함수호출의 흐름을 재구성할 수가 있습니다.
콜스택은 다음과 같다는 뜻이지요.

b0f127d8 b0f12b1c <Unloaded_MyDrv.sys>+0x29c8
b0f127f0 b165eb2f <Unloaded_MyDrv.sys>+0xab2f
b0f128a4 b165bb93 <Unloaded_MyDrv.sys>+0x7b93
b0f128bc b165c934 <Unloaded_MyDrv.sys>+0x8934

일단 콜스택이 확인 되었습니다.
하지만 아직도 어떤 함수들이 호출되고 있었는지는 알 수가 없네요.

함수이름을 찾기 위해서 특별한 방법을 동원하려고 합니다. 맵파일을 이용하는 건데요.
맵파일이란 빌드된 바이너리 파일안에서 전역변수, 함수 등의 이름과 위치를 기록해 놓은 텍스트 파일입니다.
일반적으로는 생성되지 않구요. 링크타임에 링커 옵션 /MAP 을 줘야 링커가 맵파일을 생성해 줍니다.
저같은 경우 모든 작업을 할 때 기본적으로 맵파일 생성 옵션을 설정합니다.
물론 이와 같은 문제를 해결해야 할 경우를 대비해서 하는 일입니다.

맵파일 내용은 대강 다음과 같습니다.

MyDrv.map 파일 내용

MyDrv

Timestamp is 446be6ec (Thu May 18 12:15:56 2006)

Preferred load address is 00010000

Start Length Name Class
0001:00000000 000154aaH .text CODE
0002:00000000 00000118H .idata$5    DATA
0002:00000120 000050a8H .rdata    DATA
0002:000051c8 0000005dH .rdata$debug    DATA
0003:00000000 000004b0H .data DATA
0003:000004c0 000027ceH .bss    DATA
0004:00000000 00000028H .idata$2    CODE
0004:00000028 00000014H .idata$3    CODE
0004:0000003c 00000118H .idata$4    CODE
0004:00000154 00000578H .idata$6    CODE
0005:00000000 00000058H .rsrc$01    DATA
0005:00000060 00000310H .rsrc$02    DATA

Address Publics by Value Rva+Base Lib:Object

0001:00000141 _DriverEntry@8 00010441 f mydrv.obj
0001:000006be _DriverUnload@4    000109be f mydrv.obj
0001:000007e1 _MyDrv_DriverEntry@4 00010ae1 f mydrv.obj
0001:00000930 _MyDrv_DriverUnload@0    00010c30 f mydrv.obj
0001:00000950 _MyDrv_Create@0    00010c50 f mydrv.obj
0001:00000970 _MyDrv_Close@0 00010c70 f mydrv.obj
...

주요하게 봐주셔야 할 부분은 Rva+Base 가 되겠습니다.

맵파일에서 위 함수들을 하나씩 찾아 봅니다.

<Unloaded_MyDrv.sys>+0x29c8

이것은 MyDrv.sys 가 로드되었을 때 ImageBase+0x29c8 에 위치한 함수였다는 뜻입니다.

맵파일을 생성할 당시는 ImageBase 가 어떻게 될지 알 수 없으므로 링커는 Preferred load address is 00010000 로 가정하고 함수주소들을 기록합니다.
ImageBase = 00010000 이라는 뜻입니다.

Rva = 0x29c8, Base = 00010000 이므로 Rva+Base = 000129c8 입니다.
따라서 맵파일에서 Rva+Base 가 000129c8 인 곳을 찾으면 됩니다.

0001:00002640 _DoSomething1@12 00012940 f mydrv.obj
0001:000026e0 _DoSomething2@12 000129e0 f mydrv.obj

000129c8 은 00012940 과 000129e0 사이에 있으므로 00012940 함수 내부의 코드인 것을 알 수 있습니다.
_DoSomething1 함수 내부의 코드에서 죽었다는 뜻이지요.

다음으로

<Unloaded_MyDrv.sys>+0xab2f = 0001ab2f

0001:0000a750 _BugCheckCE@16 0001aa50 f mydrv.obj
0001:0000a870 _BugCheckD6@8 0001ab70 f mydrv.obj

0001aa50 < 0001ab2f < 0001ab70 이므로 _BugCheckCE 함수 내부의 코드입니다.

<Unloaded_MyDrv.sys>+0x7b93 = 00017b93

0001:00007870 _DoBugCheck@12 00017b70 f mydrv.obj
0001:000078a0 _SelectBugCheck@4 00017ba0 f mydrv.obj

00017b70 < 00017b93 < 00017ba0 이므로 _DoBugCheck 함수 내부의 코드입니다.

<Unloaded_MyDrv.sys>+0x8934 = 00018934

0001:0000852e _MyDrvWorkerThread@18 0001882e f mydrv.obj
0001:000086e0 _MyDrvQueueItem@8 000189e0 f mydrv.obj

0001882e < 00018934 < 000189e0 이므로 _MyDrvWorkerThread 함수 내부의 코드입니다.

콜스택을 찾아진 함수이름으로 다시 정리해 보면

_DoSomething1
_BugCheckCE
_DoBugCheck
_MyDrvWorkerThread

과 같음을 알 수 있습니다.

드라이버가 Unload 됨에도 불구하고 WorkerThread 가 계속 돌고 있었다는 것이 밝혀졌습니다.
그러므로 드라이버가 Unload 될 때 WorkerThread 를 정리하는 코드를 추가하면 문제가 해결될 것입니다.

오늘의 키포인트는 드라이버 이미지가 내려가 버렸을 때 디버깅하는 방법입니다.
첫번째는 콜스택을 스스로 찾아내는 방법이었고 두번째는 메모리 주소만 가지고 맵파일로 부터 함수이름을 찾아내는 것이었습니다.
익숙하지 않으신 분들은 다소 생소한 방법일테지만 나중에 비슷한 경우가 있을 때마다 활용하시다 보면 익숙해지실 겁니다.

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&GotoPage=5&s_bulu=&s_key=&no=34

Posted by GreeMate

[WinDbg 분석] BugCheck 0x7F

오래간만에 덤프분석 하나 해 보겠습니다.
오늘은 BugCheck 0x7F 입니다.

사실 결론부터 말하자면 BugCheck 0x7F-8 는 Kernel Stack Overflow 입니다.
이 바닥에서 잔뼈가 굵으신 몇몇 분들은 이미 BugCheck Code 만 보고 이것을 짐작하시고 계실 겁니다. ^^

BugCheck 0x7F 이고 첫번째 인자가 8 인 경우 WinDbg Help 조차 kernel stack overflow 일 수 있다고 친절하게 설명하고 있습니다. 저희같이 하드웨어를 가지지 않는 필터 드라이버 종류를 주로 작성하는 경우 7F 덤프를 받으시면 kernel stack overflow 겠거니 하고 분석을 시작하시면 됩니다.
극소수의 경우 BugCheck 0x7F-8 이 하드웨어 오류인 경우를 나타내는데 저는 이런 것을 받아본 적이 한번도 없습니다. MS 같은 곳에서는 이런 가능성까지 신경쓰면서 분석을 해야 겠지요.

덤프 분석에서 BugCheck Code 가 중요한 이유가 바로 이것입니다. 문제의 방향을 미리 설정하고 분석을 시작할 수 있다는 것이죠.

자... 시작해 보겠습니다.

0: kd> !analyze -v
***************************************************************************
* *
* Bugcheck Analysis *
* *
***************************************************************************

UNEXPECTED_KERNEL_MODE_TRAP (7f)
This means a trap occurred in kernel mode, and it's a trap of a kind
that the kernel isn't allowed to have/catch (bound trap) or that
is always instant death (double fault). The first number in the
bugcheck params is the number of the trap (8 = double fault, etc)
Consult an Intel x86 family manual to learn more about what these
traps are. Here is a *portion* of those codes:
If kv shows a taskGate
use .tss on the part before the colon, then kv.
Else if kv shows a trapframe
use .trap on that value
Else
.trap on the appropriate frame will show where the trap was taken
(on x86, this will be the ebp that goes with the procedure KiTrap)
Endif
kb will then show the corrected stack.
Arguments:
Arg1: 00000008, EXCEPTION_DOUBLE_FAULT
Arg2: 80042000
Arg3: 00000000
Arg4: 00000000

Debugging Details:
------------------

BUGCHECK_STR: 0x7f_8

TSS: 00000028 -- (.tss 28)
eax=ebee4010 ebx=00000000 ecx=ebee4010 edx=00000000 esi=867818e8 edi=86781900
eip=80701ab8 esp=ebee4000 ebp=ebee401c iopl=0 nv up ei pl zr na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010246
hal!KeReleaseQueuedSpinLock+0x10:
80701ab8 53 push ebx
Resetting default scope

DEFAULT_BUCKET_ID: DRIVER_FAULT
PROCESS_NAME: MyApp.exe
LAST_CONTROL_TRANSFER: from 804de605 to 80701ab8

STACK_TEXT:
ebee3ffc 804de605 ebee42cc e1023cc8 00000000 hal!KeReleaseQueuedSpinLock+0x10
ebee401c f769b89b ebee429c ebee4040 f769d3a9 nt!ExReleaseResourceLite+0x8d
ebee4028 f769d3a9 ebee429c e1023cc8 00000000 Ntfs!NtfsReleaseFcb+0x4e
ebee4040 f769b497 ebee429c 00000000 ebee429c Ntfs!NtfsReleaseAllResources+0x62
ebee4058 f769b6e6 ebee429c 00000001 e1023cc8 Ntfs!NtfsCleanupIrpContext+0x23
ebee4070 f76c0cd3 ebee429c 858b2420 00000000 Ntfs!NtfsCompleteRequest+0x35
ebee4280 f76c0d83 ebee429c 858b2420 86739488 Ntfs!NtfsCommonCleanup+0x2601
ebee43f8 804e33d9 8677b020 858b2420 86717270 Ntfs!NtfsFsdCleanup+0xcf
ebee4408 f7743bbf 85d89160 858b2430 ebee4444 nt!IopfCallDriver+0x31
ebee4418 804e33d9 867393d0 858b2420 8609a6f0 sr!SrCleanup+0xb3
ebee4428 ec631f92 85d89160 00000000 8644bf20 nt!IopfCallDriver+0x31
WARNING: Stack unwind information not available. Following frames may be wrong.
ebee4444 ec62de51 8644be68 858b2420 00000000 AhnFlt2K+0x4f92
ebee445c 804e33d9 8644be68 858b2420 858b2420 AhnFlt2K+0xe51
ebee446c 8057e627 85d89148 867e7e70 00000001 nt!IopfCallDriver+0x31
ebee449c 80570943 858b2978 8644be68 00120089 nt!IopCloseFile+0x26b
ebee44cc 80570a96 858b2978 01d89148 867e7e70 nt!ObpDecrementHandleCount+0x11b
ebee44f4 805709bc e26299e0 85d89160 000000c8 nt!ObpCloseHandleTableEntry+0x14d
ebee453c 80570a06 000000c8 00000000 00000000 nt!ObpCloseHandle+0x87
ebee4550 804df99f 000000c8 ebee4de8 804e5487 nt!NtClose+0x1d
ebee4550 804e5487 000000c8 ebee4de8 804e5487 nt!KiFastCallEntry+0xfc
ebee45cc f7d86552 000000c8 00000160 00000000 nt!ZwClose+0x11
ebee4de8 f7d8661d f7d865b0 00000000 00000000 MyDrv!OpenClose+0xc2 [e:\test\mydrv\mydrv.c @ 264]
ebee5d9c f7d86648 00000000 00000000 00000000 MyDrv!UseStack2+0x1d [e:\test\mydrv\mydrv.c @ 286]
ebee6d4c f7d86678 00000000 00000000 00000000 MyDrv!UseStack1+0x18 [e:\test\mydrv\mydrv.c @ 293]
ebee7cfc f7d871c2 0000004c 00000000 ebee7d1c MyDrv!BugCheck7F+0x18 [e:\test\mydrv\mydrv.c @ 300]
ebee8c40 804e33d9 85ad7030 866af7d8 80701410 MyDrv!MyDrvDeviceControl+0x312 [e:\test\mydrv\mydrv.c @ 460]
ebee8c50 8057150b 866af848 86409b88 866af7d8 nt!IopfCallDriver+0x31
ebee8c64 80582fb1 85ad7030 866af7d8 86409b88 nt!IopSynchronousServiceTail+0x60
ebee8d00 8058909e 000000d4 00000000 00000000 nt!IopXxxControlFile+0x5ef
ebee8d34 804df99f 000000d4 00000000 00000000 nt!NtDeviceIoControlFile+0x2a
ebee8d34 7c93eb94 000000d4 00000000 00000000 nt!KiFastCallEntry+0xfc
0012f898 00000000 00000000 00000000 00000000 0x7c93eb94

STACK_COMMAND: .tss 0x28 ; kb

FOLLOWUP_IP:
AhnFlt2K+4f92
ec631f92 e99e010000 jmp AhnFlt2K+0x5135 (ec632135)

SYMBOL_STACK_INDEX: b
SYMBOL_NAME: AhnFlt2K+4f92
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: AhnFlt2K
IMAGE_NAME: AhnFlt2K.sys
DEBUG_FLR_IMAGE_TIMESTAMP: 451abe53
FAILURE_BUCKET_ID: 0x7f_8_AhnFlt2K+4f92
BUCKET_ID: 0x7f_8_AhnFlt2K+4f92
Followup: MachineOwner
---------

메시지를 읽어보면 KERNEL MODE TRAP 인데 뭐 여러가지 가능성이 있다고 설명합니다.
어떤 상황이면 어떻게 해보라고 알려주기도 하는데 그 아래에서 WinDbg 가 알아서 분석한 정보들을 보여주고 우리가 어떻게 해야 할지도 보여줍니다.
첫번째 인자 8 에 대해서는 EXCEPTION_DOUBLE_FAULT 라고 알려주네요.

메시지 중간에 보여주는 다음 라인이 우리가 처음에 해야할 일입니다.

TSS: 00000028 -- (.tss 28)
STACK_COMMAND: .tss 0x28 ; kb

!analyze 에서 보여준 콜스택과 정보는 WinDbg 가 이것을 적용한 결과를 출력해 주는 것입니다.
현재 상태를 확인해 보시면 아직 위에서 보이는 콜스택과 같은 상태가 아님을 알 수 있습니다.

0: kd> kv
ChildEBP RetAddr Args to Child
00000000 80701ab8 00000000 00000000 00000000 nt!KiTrap08+0x48 (FPO: TSS 28:0)
ebee3ffc 804de605 ebee42cc e1023cc8 00000000 hal!KeReleaseQueuedSpinLock+0x10 (FPO: [0,0,0])
ebee401c f769b89b ebee429c ebee4040 f769d3a9 nt!ExReleaseResourceLite+0x8d (FPO: [Non-Fpo])
ebee4028 f769d3a9 ebee429c e1023cc8 00000000 Ntfs!NtfsReleaseFcb+0x4e (FPO: [Non-Fpo])
...

이제 메시지에서 하라는대로 해야죠? ^^ 두 메시지는 결국 .tss 0x28 을 하라는 뜻입니다.
바로 위에서 보이는 nt!KiTrap08+0x48 (FPO: TSS 28:0) 를 봤을 때도 이것을 알아채는 센스가 있어야 합니다. ^^

0: kd> .tss 0x28
eax=ebee4010 ebx=00000000 ecx=ebee4010 edx=00000000 esi=867818e8 edi=86781900
eip=80701ab8 esp=ebee4000 ebp=ebee401c iopl=0 nv up ei pl zr na pe nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010246
hal!KeReleaseQueuedSpinLock+0x10:
80701ab8 53 push ebx

레지스터값들이 죽었을 때 상황으로 돌아갔네요.

0: kd> kv
*** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr Args to Child
ebee3ffc 804de605 ebee42cc e1023cc8 00000000 hal!KeReleaseQueuedSpinLock+0x10 (FPO: [0,0,0])
ebee401c f769b89b ebee429c ebee4040 f769d3a9 nt!ExReleaseResourceLite+0x8d (FPO: [Non-Fpo])
ebee4028 f769d3a9 ebee429c e1023cc8 00000000 Ntfs!NtfsReleaseFcb+0x4e (FPO: [Non-Fpo])
...

위에서 보였던 KiTrap08 이 사라졌습니다.
자... 이제 완전하게 죽었을 때 상황으로 돌아온 것입니다.

.tss 를 하는 이유는 인텔 CPU 구조에 있는 TSS(Task State Segment) 에 죽었을 때의 상황이 저장되어 있기 때문입니다. 이것은 Kernel stack overflow 와 double fault 라는 특성때문에 그런건데요.
Kernel stack overflow 가 발생하면 일단 fault 가 한번 발생합니다. 보통 fault 가 발생하면 스택에 exception record 를 기록하려고 하는데 이 경우는 이미 스택을 사용할 수 없는 상황이므로 exception record 를 기록하려다가 다시 한번 fault 가 발생합니다. 이렇게 해서 double fault 가 되고 이와 같이 스택에 exception record 를 저장할 수 없는 상황에 이 정보가 TSS 에 저장되기 때문에 .tss 를 사용해서 이것을 추출하는 것입니다.

정말 kernel stack overflow 인지 확인해 볼까요?
위에서 마지막에 보이는 ChildEBP 는 ebee3ffc 입니다. 이것이 현재 쓰레드의 커널 스택 영역과 어떤 관계가 있는지 보면 됩니다.

0: kd> !thread
THREAD 85a604d8 Cid 0c1c.0c20 Teb: 7ffdf000 Win32Thread: e27122d0 RUNNING on processor 0
...
Context Switch Count 1044 LargeStack
...
Stack Init ebee9000 Current ebee405c Base ebee9000 Limit ebee4000 Call 0

Stack Base 는 ebee9000 이고 Limit 는 ebee4000 입니다.
일단 ebee3ffc 는 Limit 인 ebee4000 보다 아래에 있는 주소이므로 스택 경계를 넘어간 overflow 가 맞습니다.
재미있는 것은 보통 커널 스택은 12KB 인 것으로 알고 있는데 여기서는 LargeStack 이라고 표시되어 있고 20KB 를 사용하고 있습니다. 어떤 경우에 LargeStack 이 사용되는 것인지는 잘 모르겠네요.

현장검증은 이정도로 하고 이제 범인을 잡으러가야 겠네요. ^^
!analyze 가 해준 초동수사에서 유력한 용의자는 다음과 같이 AhnFlt2K 로 지목되었습니다.

MODULE_NAME: AhnFlt2K
IMAGE_NAME: AhnFlt2K.sys

대부분의 경우 !analyze 의 날카로운 추리력에 의해 범인이 바로 지목되는데요.
이번 경우는 좀 다릅니다.

현장을 마지막으로 방문했었던 AhnFlt2K 를 범인으로 지목하기에는 좀 성급한 면이 있다는 거죠.
이번 문제가 Kernel stack overflow 로 밝혀진 이상 stack 을 많이 사용하는 녀석을 찾아야 진짜 범인을 찾는다는 겁니다. 위 콜스택에서 봤을 때 커널을 제외하고 추가로 용의선상에 올려놓을 수 있는 녀석들은 Ntfs, sr, MyDrv 입니다. 가만 보니 현장을 마지막으로 방문했었던 녀석들은 Ntfs, sr 인데 자기네 편이라고 용의선상에서 제외시켰군여. 나쁜넘들...

실제로 스택 사용량을 검토하는 방법은 위 콜스택에서 맨 왼쪽에 나오는 ChildEBP 의 변화량을 모듈별로 보는 것입니다. 일일이 손으로 계산해도 상관없으나 kf 명령어를 사용하면 노가다가 필요없습니다. 콜스택이 다소 길어서 최대한 보여주라고 인자로 100 을 줬습니다.

0: kd> kf 100
Memory ChildEBP RetAddr
ebee3ffc 804de605 hal!KeReleaseQueuedSpinLock+0x10
   20 ebee401c f769b89b nt!ExReleaseResourceLite+0x8d
c ebee4028 f769d3a9 Ntfs!NtfsReleaseFcb+0x4e
   18 ebee4040 f769b497 Ntfs!NtfsReleaseAllResources+0x62
   18 ebee4058 f769b6e6 Ntfs!NtfsCleanupIrpContext+0x23
   18 ebee4070 f76c0cd3 Ntfs!NtfsCompleteRequest+0x35
210 ebee4280 f76c0d83 Ntfs!NtfsCommonCleanup+0x2601
178 ebee43f8 804e33d9 Ntfs!NtfsFsdCleanup+0xcf
   10 ebee4408 f7743bbf nt!IopfCallDriver+0x31
   10 ebee4418 804e33d9 sr!SrCleanup+0xb3
   10 ebee4428 ec631f92 nt!IopfCallDriver+0x31
WARNING: Stack unwind information not available. Following frames may be wrong.
   1c ebee4444 ec62de51 AhnFlt2K+0x4f92
   18 ebee445c 804e33d9 AhnFlt2K+0xe51
   10 ebee446c 8057e627 nt!IopfCallDriver+0x31
   30 ebee449c 80570943 nt!IopCloseFile+0x26b
   30 ebee44cc 80570a96 nt!ObpDecrementHandleCount+0x11b
   28 ebee44f4 805709bc nt!ObpCloseHandleTableEntry+0x14d
   48 ebee453c 80570a06 nt!ObpCloseHandle+0x87
   14 ebee4550 804df99f nt!NtClose+0x1d
0 ebee4550 804e5487 nt!KiFastCallEntry+0xfc
   7c ebee45cc f7d86552 nt!ZwClose+0x11
81c ebee4de8 f7d8661d MyDrv!OpenClose+0xc2 [e:\test\mydrv\mydrv.c @ 264]
fb4 ebee5d9c f7d86648 MyDrv!UseStack2+0x1d [e:\test\mydrv\mydrv.c @ 286]
fb0 ebee6d4c f7d86678 MyDrv!UseStack1+0x18 [e:\test\mydrv\mydrv.c @ 293]
fb0 ebee7cfc f7d871c2 MyDrv!BugCheck7F+0x18 [e:\test\mydrv\mydrv.c @ 300]
f44 ebee8c40 804e33d9 MyDrv!MyDrvDeviceControl+0x312 [e:\test\mydrv\mydrv.c @ 460]
   10 ebee8c50 8057150b nt!IopfCallDriver+0x31
   14 ebee8c64 80582fb1 nt!IopSynchronousServiceTail+0x60
   9c ebee8d00 8058909e nt!IopXxxControlFile+0x5ef
   34 ebee8d34 804df99f nt!NtDeviceIoControlFile+0x2a
0 ebee8d34 7c93eb94 nt!KiFastCallEntry+0xfc

맨 왼쪽에 보이는 숫자들이 각 함수가 소진한 스택의 량입니다.
한 눈에 보면 MyDrv 가 문제가 있는 녀석이라고 느껴집니다.
사용한 양을 계산해 보면

0: kd> ? 81c + fb4 + fb0 + fb0 + f44
Evaluate expression: 18036 = 00004674

우와~~~ 자그마치 18KB 를 사용하고 있습니다.
도대체 뭘 하느라고 스택을 저렇게 사용할까요? 함수 이름도 범상치 않군여... 한번 봅시다.

void UseStack1(void)
{
char szBuf[4000];

UseStack2();

아... 네... 지역변수를 4000 바이트 사용했네요. 이런일 없어야 겠습니다.
이 녀석이야 예제라지만 이름이 UseStack 도 아니면서 저렇게 사용하는 경우.... 실제 상황에서 종종 봤습니다. -_-;;;
4000 바이트 까지야 없겠지만 100 바이트 이상은 많았습니다. 하나의 함수가 사용하는 지역변수 크기의 합이 100 바이트 넘어가면 문제 있다고 보셔야 합니다.
그런 관점에서 Ntfs 저 녀석도 범인으로 봐야 합니다. 스택 사용량이 가장 큰 함수 두개만 더해봐도

0: kd> ? 210 + 178
Evaluate expression: 904 = 00000388

거의 1KB 가까이 사용하고 있습니다. 치사하게 커널 스택을 아껴쓰라고 주장하는 MS 에서는 스택을 마음대로 사용하고 자기들은 OS 의 일부라고 우깁니다. 뭐... 힘이 없으니 어쩔 수 없구요. ^^

여하튼 범인은 MyDrv 로 밝혀 졌습니다. MyDrv 의 함수들이 스택을 아껴쓰도록 수정하면 문제가 해결될 것입니다.
만약 파일시스템 필터 드라이버를 작성하신다면 스택사용량에 더욱 각별히 신경쓰셔야 할 겁니다.
Kernel stack overflow 는 파일 필터 분야에서 늘 있어왔던 문제이고 필터들이 워낙 많기 때문에 우리 드라이버가 사용할 공간이 늘 협소하다고 가정해야 합니다.
함수 하나당 100 바이트 이하... 너무 엄격한 기준은 아니겠지요? ^^

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&GotoPage=4&s_bulu=&s_key=&no=47

Posted by GreeMate

[WinDbg 분석] BugCheck 0xA (분석가능)

저는 개인적으로 BugCheck 0xA 를 굉장히 싫어합니다. ^^
솔직히 제가 BugCheck 0xA 를 만났을 때 정확한 원인을 분석할 확율은 50% 정도 밖에 되지 않기 때문입니다.
개인적인 능력의 차이일 수 있으므로 여러분 모두 그러리라 단정하지는 마시기 바랍니다. ^^ 제 주변에도 저보다 훨씬 분석을 잘하시는 분들이 몇분 계십니다.

BugCheck 0xA 는 기본적으로 IRQL 이 올라간 상태에서 낮은 IRQL 에서만 해야하는 기능을 수행할 때 발생합니다. 하지만 몇년 경험을 해 보니 너무나도 다양한 원인에 의해서 이런 현상이 벌어진다는 것을 알게 되었습니다.
지금까지 설명했던 BugCheck 들은 대체로 Code 만 보고 어떤 문제인지 짐작할 수 있었지만 이 BugCheck 0xA 는 그야말로 전형적인 패턴이라는 것이 거의 없어서 분석의 실마리라고는 '아 고생 좀 하겠구나' 라는 느낌을 주는 정도입니다.

오늘은 첫번째 시간으로 원인 분석이 가능한 BugCheck 0xA 예제를 살펴보도록 하겠습니다.

kd> !analyze -v
***************************************************************************
* *
* Bugcheck Analysis *
* *
***************************************************************************

IRQL_NOT_LESS_OR_EQUAL (a)
An attempt was made to access a pageable (or completely invalid) address at an
interrupt request level (IRQL) that is too high. This is usually
caused by drivers using improper addresses.
If a kernel debugger is available get the stack backtrace.
Arguments:
Arg1: 00000016, memory referenced
Arg2: 00000002, IRQL
Arg3: 00000000, value 0 = read operation, 1 = write operation
Arg4: 804f84dd, address which referenced memory

Debugging Details:
------------------

READ_ADDRESS: 00000016

CURRENT_IRQL: 2

FAULTING_IP:
nt!KiWaitTest+31
804f84dd 6683781601 cmp word ptr [eax+16h],1

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0xA

PROCESS_NAME: MyApp.exe

TRAP_FRAME: f2526c18 -- (.trap fffffffff2526c18)
ErrCode = 00000000
eax=00000000 ebx=f9da06a8 ecx=f2526c98 edx=00000000 esi=f9da06a0 edi=00000000
eip=804f84dd esp=f2526c8c ebp=f2526ca8 iopl=0 nv up ei pl nz ac po cy
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010213
nt!KiWaitTest+0x31:
804f84dd 6683781601 cmp word ptr [eax+16h],1 ds:0023:00000016=????
Resetting default scope

LAST_CONTROL_TRANSFER: from 8052d1c5 to 804f14c9

STACK_TEXT:
f2526bfc 8052d1c5 0000000a 00000016 00000002 nt!KeBugCheckEx+0x19
f2526bfc 804f84dd 0000000a 00000016 00000002 nt!KiTrap0E+0x2ad
f2526ca8 804f17a0 8119fa80 80f84f10 926e4f00 nt!KiWaitTest+0x31
f2526cb8 f9da03e2 f9da06a0 00000000 00000000 nt!KeSetEvent+0x56
f2526ccc f9da0e57 00000040 ffffffff ffffffff MyDrv!BugCheckA+0x12 [d:\project\test\mydrv\mydrv.c @ 272]
f2527c10 804e8185 8119fa80 926e4f68 8069f524 MyDrv!MyDrvDeviceControl+0x2c7 [d:\project\test\mydrv\mydrv.c @ 440]
f2527c20 80626d10 814ab9b0 8069f2f0 926e4f68 nt!IopfCallDriver+0x31
f2527c44 8055887c 81421360 926e4fd8 926e4f68 nt!IovCallDriver+0x9e
f2527c58 805595a7 8119fa80 926e4f68 81421360 nt!IopSynchronousServiceTail+0x5e
f2527d00 80552468 000000bc 00000000 00000000 nt!IopXxxControlFile+0x5a5
f2527d34 8052a421 000000bc 00000000 00000000 nt!NtDeviceIoControlFile+0x28
f2527d34 7ffe0304 000000bc 00000000 00000000 nt!KiSystemService+0xc4
0012f5f8 00000000 00000000 00000000 00000000 SharedUserData!SystemCallStub+0x4

STACK_COMMAND: kb

FOLLOWUP_IP:
MyDrv!BugCheckA+12 [d:\project\test\mydrv\mydrv.c @ 272]
f9da03e2 5d pop ebp

SYMBOL_STACK_INDEX: 4

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: MyDrv

IMAGE_NAME: MyDrv.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 3f963fa3

SYMBOL_NAME: MyDrv!BugCheckA+12

FAILURE_BUCKET_ID: 0xA_VRF_MyDrv!BugCheckA+12

BUCKET_ID: 0xA_VRF_MyDrv!BugCheckA+12

Followup: MachineOwner
---------

IRQL_NOT_LESS_OR_EQUAL 설명에서 pagable 메모리나 invalid 메모리를 높은 IRQL 에서 접근했다고 알려주네요. 결과적으로 그렇게 된 것은 맞습니다만 그 원인은 너무나도 다양한 유형이 있습니다.
자... 그래도 기죽지 말고 꿋꿋하게 진행해 봅니다.

Arg1: 00000016, memory referenced
READ_ADDRESS: 00000016

이 메시지들에서 접근한 메모리가 00000016 이라는 사실을 알 수 있습니다.
메시지 중간쯤에 ds:0023:00000016=???? 보이시나요? invalid 한 메모리입니다.

Arg2: 00000002, IRQL
CURRENT_IRQL: 2

그리고 이 메시지들에서 죽었을 당시의 IRQL 은 2 (DISPATCH_LEVEL) 였다는 것을 알 수 있습니다.
딱 맞네요. 높은 IRQL 에서 invalid 메모리를 참조한 것... 왜 이렇게 되었을까요?

메시지에서 하라는 대로 .trap 먼저 합니다.

kd> .trap fffffffff2526c18
ErrCode = 00000000
eax=00000000 ebx=f9da06a8 ecx=f2526c98 edx=00000000 esi=f9da06a0 edi=00000000
eip=804f84dd esp=f2526c8c ebp=f2526ca8 iopl=0 nv up ei pl nz ac po cy
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010213
nt!KiWaitTest+0x31:
804f84dd 6683781601 cmp word ptr [eax+16h],1 ds:0023:00000016=????

k 로 죽었을 당시의 콜스택을 확인해 봅니다.

kd> k
*** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr
f2526ca8 804f17a0 nt!KiWaitTest+0x31
f2526cb8 f9da03e2 nt!KeSetEvent+0x56
f2526ccc f9da0e57 MyDrv!BugCheckA+0x12 [d:\project\test\mydrv\mydrv.c @ 272]
f2527c10 804e8185 MyDrv!MyDrvDeviceControl+0x2c7 [d:\project\test\mydrv\mydrv.c @ 440]
f2527c20 80626d10 nt!IopfCallDriver+0x31
f2527c44 8055887c nt!IovCallDriver+0x9e
f2527c58 805595a7 nt!IopSynchronousServiceTail+0x5e
f2527d00 80552468 nt!IopXxxControlFile+0x5a5
f2527d34 8052a421 nt!NtDeviceIoControlFile+0x28
f2527d34 7ffe0304 nt!KiSystemService+0xc4
0012f5f8 00000000 SharedUserData!SystemCallStub+0x4

우리 드라이버인 MyDrv 가 보이고 nt 커널로 들어가서 죽은 것이네요.
보통 이런 경우 MyDrv 가 범인이지요. MyDrv 가 뭘 잘못하고 nt 커널을 호출하는 경우이지요.
친절하게 소스라인을 보여주므로 소스를 봅니다.

268: KEVENT event;
269:
270: void BugCheckA(void)
271: {
272: KeSetEvent( &event, IO_NO_INCREMENT, FALSE );

KeSetEvent 를 호출하다가 죽은 것이군요.
그런데 뭘 잘못했길래 KeSetEvent 호출이 죽었는지 잘 모르겠습니다.

이런 경우 콜스택의 마지막 위치인 nt 커널의 KiWaitTest 가 왜 죽었는지부터 분석하기 시작해야만 MyDrv 에서 어떤 잘못을 했는지 찾을 수 있습니다. 사실 어떤 덤프를 분석하더라도 사실 콜스택의 마지막 위치가 가장 명확한 단서를 제공하므로 여기부터 분석을 시작하는 것이 정석입니다. 문제는 MyDrv 가 마지막이라면 좀 더 쉽겠지만 이번 예제처럼 nt 커널이거나 남의 모듈이라면 다소 괴로운 작업이 된다는 것이죠.

이제부터 정신을 좀 가다듬으셔야 겠습니다.
소스가 없는 남의 모듈이므로 assembly 를 보면서 따라가야 하거든요. 저에게는 늘 진땀나는 작업입니다. -_-;

죽은 곳이 nt!KiWaitTest+0x31 이고 이에 대한 정보가 있습니다.

nt!KiWaitTest+0x31:
804f84dd 6683781601 cmp word ptr [eax+16h],1 ds:0023:00000016=????

00000016 이라는 메모리는 eax+16 입니다. 결국 eax 가 0 이었었다는 얘깁니다.

이제부터 KiWaitTest 라는 함수에서 도대체 왜 eax 가 0 이 되었는지를 알아내야 합니다.
다행스럽게도 KiWaitTest 함수의 시작과 죽은 곳 사이는 얼마 차이나지 않네요.

KiWaitTest 함수를 보면서 확인해 봅니다.

kd> u KiWaitTest L13
nt!KiWaitTest:
804f84ac 55    push    ebp
804f84ad 8bec    mov ebp,esp
804f84af 83ec10    sub esp,10h
804f84b2 53    push    ebx
804f84b3 56    push    esi
804f84b4 8bf1    mov esi,ecx    ; 4) esi = ecx
804f84b6 837e0400    cmp dword ptr [esi+4],0
804f84ba 8d4df0    lea ecx,[ebp-10h]
804f84bd 894df4    mov dword ptr [ebp-0Ch],ecx
804f84c0 8d5e08    lea ebx,[esi+8]    ; 3) ebx = esi+8
804f84c3 8b03    mov eax,dword ptr [ebx]    ; 2) eax = [ebx]
804f84c5 8d4df0    lea ecx,[ebp-10h]
804f84c8 8955f8    mov dword ptr [ebp-8],edx
804f84cb 894df0    mov dword ptr [ebp-10h],ecx
804f84ce 0f8eb0000000    jle nt!KiWaitTest+0xd8 (804f8584)
804f84d4 57    push    edi
804f84d5 3bc3    cmp eax,ebx
804f84d7 0f8487000000    je    nt!KiWaitTest+0xb8 (804f8564)
804f84dd 6683781601    cmp word ptr [eax+16h],1 ; 1) eax = 0

함수시작부터 죽은곳까지 보이고 있습니다.
죽은 곳에서부터 거꾸로 찾아가 봅니다.

1) 죽은 곳이구요 그 위쪽 어디에서 eax 에 0 을 채웠는지 찾아봐야 합니다.
2) ebx 주소의 내용을 eax 에 넣은 것이군요. ebx 주소의 내용이 0 인가 봅니다.
확인해 봐야죠. .trap 명령에서 나온 레지스터 값에 ebx=f9da06a8 가 보입니다.

kd> dd f9da06a8 L1
f9da06a8 00000000

역시 0 이 들어 있었습니다.

3) ebx 는 esi+8 에서 나온 값이네요. esi=f9da06a0 이네요.
4) esi 는 함수가 시작될 때 ecx 값을 저장해 놓은 것이구요.
   ecx 값이 어디서 왔는지는 보이지 않습니다.
   이것을 보면 바로 이 함수가 fastcall 호출규약의 함수라는 것을 알 수 있습니다.
   fastcall 은 첫번째 파라미터를 ecx에 두번째 파라미터를 edx 에 넣고 함수를 호출하지요.
   상위 함수에서 ecx 에 f9da06a0 라는 값을 채워서 이 함수를 호출했다는 뜻입니다.

상위 함수를 계속 봅니다.

kd> u KeSetEvent L20
nt!KeSetEvent:
804f174a 53    push    ebx
804f174b 56    push    esi
804f174c 57    push    edi
804f174d ff1594264d80    call    dword ptr [nt!_imp__KeRaiseIrqlToDpcLevel (804d2694)]
804f1753 8b4c2410    mov ecx,dword ptr [esp+10h]    ; 4) ecx = [esp+10h]
804f1757 8b7904    mov edi,dword ptr [ecx+4]
804f175a 8ad8    mov bl,al
804f175c 8d4108    lea eax,[ecx+8]
804f175f 8b30    mov esi,dword ptr [eax]
804f1761 3bf0    cmp esi,eax
804f1763 7509    jne nt!KeSetEvent+0x24 (804f176e)
804f1765 c7410401000000 mov dword ptr [ecx+4],1
804f176c eb32    jmp nt!KeSetEvent+0x56 (804f17a0)
804f176e 33c0    xor eax,eax
804f1770 40    inc eax
804f1771 803900    cmp byte ptr [ecx],0
804f1774 741a    je    nt!KeSetEvent+0x46 (804f1790)
804f1776 66394616    cmp word ptr [esi+16h],ax
804f177a 7514    jne nt!KeSetEvent+0x46 (804f1790)
804f177c 0fb75614    movzx edx,word ptr [esi+14h]
804f1780 8b4e08    mov ecx,dword ptr [esi+8]    ; 2) ecx = [esi+8]
804f1783 6a00    push    0
804f1785 ff742418    push    dword ptr [esp+18h]
804f1789 e8d66b0000    call    nt!KiUnwaitThread (804f8364)
804f178e eb10    jmp nt!KeSetEvent+0x56 (804f17a0) ; 3) 804f17a0 로 점프
804f1790 85ff    test    edi,edi
804f1792 750c    jne nt!KeSetEvent+0x56 (804f17a0)
804f1794 8b542414    mov edx,dword ptr [esp+14h]
804f1798 894104    mov dword ptr [ecx+4],eax
804f179b e80c6d0000    call    nt!KiWaitTest (804f84ac) ; 1) KiWaitTest 호출
804f17a0 8a4c2418    mov cl,byte ptr [esp+18h]

아... 머리가 아파옵니다. 어지럽기도 하지요. @.@
하지만 쓰러지면 안됩니다. 조금만 더 가 보시지요. ^^

1) 문제의 함수를 호출한 것이구요.
2) ecx 에 esi+8 주소의 내용을 채우는 것이 보이네요.
3) 하지만 2) 의 흐름을 탔다고 하면 여기로 와서 바로 804f17a0 로 점프합니다.
   그러면 KiWaitTest 가 호출되지 않죠.
   따라서 2) 에 해당하는 라인은 타지 않았다고 봐야 합니다.
4) 그러므로 ecx 는 여기서 설정되어 KiWaitTest 호출까지 전달된 것입니다.
   ecx 는 esp+10h 주소에 있는 내용을 가져온 겁니다. esp 는 스택포인터이므로 스택에서 가져온 것이지요.
   이 함수의 파라미터가 스택에 저장되어 있고 이것을 가져왔다는 의미입니다.
   함수가 시작하자마자 push 가 3번 되었으므로 이 시점에서 스택은 다음과 같은 모양입니다.

   esp    ->    | edi    |
   esp+4 -> |    esi    |
   esp+8 -> |    ebx       |
   esp+C -> |    return address    |
   esp+10 -> | KeSetEvent 의 첫번째 파라미터 |
   esp+14 -> | KeSetEvent 의 두번째 파라미터 |
   esp+18 -> | KeSetEvent 의 세번째 파라미터 |

esp+10 이 의미하는 것은 KeSetEvent의 첫번째 파라미터 입니다.
KeSetEvent를 호출하는 아래 코드를 보면 KeSetEvent의 파라미터 3개를 push 하고 KeSetEvent를 호출하는 것을 확인할 수 있습니다.

kd> u MyDrv!BugCheckA
MyDrv!BugCheckA [d:\project\test\mydrv\mydrv.c @ 270]:
f9da03d0 55    push    ebp
f9da03d1 8bec    mov ebp,esp
f9da03d3 6a00    push    0 ; 세번째 파라미터
f9da03d5 6a00    push    0 ; 두번째 파라미터
f9da03d7 68a006daf9    push    offset MyDrv!event (f9da06a0) ; 첫번째 파라미터
f9da03dc ff15b805daf9    call    dword ptr [MyDrv!_imp__KeSetEvent (f9da05b8)] ; 자동으로 return address push 됨
f9da03e2 5d    pop ebp
f9da03e3 c3    ret

도대체 무슨 소린지 모르겠다는 분들 있으실 줄 압니다. 너무 실망하지 마시기 바랍니다. 저는 이거 이해하는데 3년 걸렸습니다. ^^
함수 호출시 스택구성에 대한 이해가 있으면 되는데 설명하자면 복잡하므로 여기서는 생략합니다. 나중에 기회가 있으면 다시 다루도록 하구요.

여하튼 BugCheckA 함수에서 KeSetEvent 의 첫번째 파라미터로 넘긴 값이 f9da06a0 였다는 결론이 나옵니다.
BugCheckA 소스코드를 보면 다음과 같으므로

272: KeSetEvent( &event, IO_NO_INCREMENT, FALSE );

event 변수의 주소가 f9da06a0 라는 뜻입니다.

ln 명령으로 확인해 봅니다.

kd> ln f9da06a0
(f9da06a0) MyDrv!event | (f9da06c0) MyDrv!EresourceB
Exact matches:
MyDrv!event = struct _KEVENT

정확히 MyDrv!event 의 주소와 일치한다고 나오네요.

이 주소가 _KEVENT 타입이라는 것을 알았으니 좀 더 자세히 살펴봅니다.

kd> dt -r _KEVENT f9da06a0
   +0x000 Header : _DISPATCHER_HEADER
+0x000 Type : 0 ''
+0x001 Absolute : 0 ''
+0x002 Size : 0 ''
+0x003 Inserted : 0 ''
+0x004 SignalState    : 1
+0x008 WaitListHead : _LIST_ENTRY [ 0x0 - 0x0 ]
   +0x000 Flink    : (null)
   +0x004 Blink    : (null)

f9da06a0 주소에 있는 내용이 SignalState만 제외하고 모두 0으로 채워져 있습니다.

이것까지 확인하고 나니 머리속에 '아차' 하고 떠오르는게 있습니다.
KeSetEvent를 호출하기 전에 event 전역변수를 KeInitializeEvent로 초기화 하지 않은겁니다.
사소한 실수가 BSOD 라는 재앙을 불러왔군요. 이 고생스러운 분석을 하게 만들었구요. -_-;

오늘 분석은 아주 숨가쁜 시간이었을 것으로 생각됩니다. 설명하는 저도 무지하게 숨가쁩니다.
Assembly를 보면서 호출 흐름과 데이터를 따라가는 작업은 분명 쉽지 않은 일이지만 분석에 성공했을 때의 기쁨은 더더욱 크답니다. ^^

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&GotoPage=3&s_bulu=&s_key=&no=58

Posted by GreeMate

[WinDbg 분석] BugCheck 0xA (분석불가능)

오늘은 BugCheck 0xA 의 두번째 시간으로 분석은 열심히 하지만 결국 원인을 찾을 수 없는 예제를 살펴보겠습니다. ^^

제가 BugCheck 0xA 를 싫어하는 가장 큰 이유는 누군가가 메모리를 깨뜨렸을 경우에도 BugCheck 0xA 가 많이 발생한다는 점입니다. 메모리를 깨먹는 것 만큼 잡기어려운 버그도 없지요.
BugCheck 0xA 가 IRQL 을 잘못 사용할 경우에만 발생한다면 여기에 촛점을 맞출 수 있겠지만 메모리를 깨뜨려서 이러한 효과가 발생하는 등 다른 경우가 있기 때문에 아주 골치가 아프게 됩니다.
은둔고수중에는 메모리를 깨뜨려서 죽은 덤프도 예리하게 분석하여 원인을 알아내는 분들도 계시지만 저에게는 아직 더 수련이 필요한 부분입니다.

시작부터 너무 기를 죽였네요. -_-;
원인을 알아낼 수 있는 건지 없는 건지는 분석을 시도하지 않고서는 알 수 없습니다.
죽이되든 밥이되든 일단은 가보는 겁니다. ^^

kd> !analyze -v
****************************************************************************
*    *
* Bugcheck Analysis    *
*    *
****************************************************************************

IRQL_NOT_LESS_OR_EQUAL (a)
An attempt was made to access a pageable (or completely invalid) address at an
interrupt request level (IRQL) that is too high. This is usually
caused by drivers using improper addresses.
If a kernel debugger is available get the stack backtrace.
Arguments:
Arg1: 00ed0fab, memory referenced
Arg2: 00000002, IRQL
Arg3: 00000000, value 0 = read operation, 1 = write operation
Arg4: 804eead8, address which referenced memory

Debugging Details:
------------------

READ_ADDRESS: 00ed0fab
CURRENT_IRQL: 2

FAULTING_IP:
nt!KiUnwaitThread+3a
804eead8 80b80302000002 cmp byte ptr [eax+0x203],0x2

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0xA

LAST_CONTROL_TRANSFER: from 804eed19 to 804eead8

TRAP_FRAME: f7f27a08 -- (.trap fffffffff7f27a08)
ErrCode = 00000000
eax=00ed0da8 ebx=00000009 ecx=00000008 edx=820ec808 esi=822c8980 edi=0000000a
eip=804eead8 esp=f7f27a7c ebp=f7f27a8c iopl=0 nv up ei pl nz na po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010206
nt!KiUnwaitThread+0x3a:
804eead8 80b80302000002 cmp byte ptr [eax+0x203],0x2 ds:0023:00ed0fab=??
Resetting default scope

STACK_TEXT:
f7f27a8c 804eed19 00000002 00000000 0000000a nt!KiUnwaitThread+0x3a
f7f27aa4 bf80229d 81ece808 00000002 00000000 nt!KeSetEvent+0x44
f7f27ae4 bf801267 00000022 0073fff4 f7f27d44 win32k!SetWakeBit+0xb7
f7f27d44 bf801e46 f7f374e4 f7f27d64 0073fff4 win32k!RawInputThread+0x585
f7f27d54 804dc1dd 00000000 00000022 00000000 win32k!NtUserCallOneParam+0x20
f7f27d54 7ffe0304 00000000 00000022 00000000 nt!KiSystemService+0xc4
0073ffe0 75aa4faa 75aac27b 00000000 00000022 SharedUserData!SystemCallStub+0x4
0073ffe8 00000000 00000022 00000004 00000000 winsrv!NtUserCallOneParam+0xc

FOLLOWUP_IP:
win32k!SetWakeBit+b7
bf80229d e90cf3ffff jmp win32k!SetWakeBit+0xb7 (bf8015ae)

SYMBOL_STACK_INDEX: 2

FOLLOWUP_NAME: MachineOwner

SYMBOL_NAME: win32k!SetWakeBit+b7

MODULE_NAME: win32k

IMAGE_NAME: win32k.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 41127907

STACK_COMMAND: .trap fffffffff7f27a08 ; kb

FAILURE_BUCKET_ID: 0xA_win32k!SetWakeBit+b7

BUCKET_ID: 0xA_win32k!SetWakeBit+b7

Followup: MachineOwner
---------

그동안 우리의 주인공이었던 MyDrv.sys 가 콜스택에서 보이지 않습니다.
분석을 더 해야 할까요? 말아야 할까요?

보통 우리는 자신이 작성한 드라이버가 콜스택에서 보이지 않으면 분석을 바로 중단합니다.
하지만 자신의 제품 또는 드라이버가 동작한 후에 이런 덤프가 발생했다고 보고된다면 심도있는 분석을 해 볼 필요가 있습니다.

콜스택에 OS 모듈들만 보이는 것으로 보아 괴로운 분석이 될 것이라 예상되는군요. ^^
자... 일단 하라는 거 해야죠.

kd> .trap fffffffff7f27a08 ; kb
ErrCode = 00000000
eax=00ed0da8 ebx=00000009 ecx=00000008 edx=820ec808 esi=822c8980 edi=0000000a
eip=804eead8 esp=f7f27a7c ebp=f7f27a8c iopl=0 nv up ei pl nz na po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010206
nt!KiUnwaitThread+0x3a:
804eead8 80b80302000002 cmp byte ptr [eax+0x203],0x2 ds:0023:00ed0fab=??
*** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr Args to Child
f7f27a8c 804eed19 00000002 00000000 0000000a nt!KiUnwaitThread+0x3a
f7f27aa4 bf80229d 81ece808 00000002 00000000 nt!KeSetEvent+0x44
f7f27ae4 bf801267 00000022 0073fff4 f7f27d44 win32k!SetWakeBit+0xb7
f7f27d44 bf801e46 f7f374e4 f7f27d64 0073fff4 win32k!RawInputThread+0x585
f7f27d54 804dc1dd 00000000 00000022 00000000 win32k!NtUserCallOneParam+0x20
f7f27d54 7ffe0304 00000000 00000022 00000000 nt!KiSystemService+0xc4
0073ffe0 75aa4faa 75aac27b 00000000 00000022 SharedUserData!SystemCallStub+0x4
0073ffe8 00000000 00000022 00000004 00000000 winsrv!NtUserCallOneParam+0xc

죽은 곳을 보면

nt!KiUnwaitThread+0x3a:
804eead8 80b80302000002 cmp byte ptr [eax+0x203],0x2 ds:0023:00ed0fab=??

이때 eax 가 다음과 같은 값이라 eax+203 = 00ed0fab 를 읽다가 죽은 겁니다.
이 주소가 존재하지 않는 엉뚱한 주소구요.

kd> r eax
Last set context:
eax=00ed0da8

KiUnwaitThread 함수 시작부터 보면

kd> u nt!KiUnwaitThread L20
nt!KiUnwaitThread:
804eea9e 55 push    ebp
804eea9f 8bec mov ebp,esp
804eeaa1 51 push    ecx
804eeaa2 53 push    ebx
804eeaa3 56 push    esi
804eeaa4 8955fc mov [ebp-0x4],edx
804eeaa7 8bf1 mov esi,ecx ; 3) esi = ecx
804eeaa9 e8d8010000 call    nt!KiUnlinkThread (804eec86)
804eeaae 8a5e33 mov bl,[esi+0x33]
804eeab1 80fb10 cmp bl,0x10
804eeab4 8b4644 mov eax,[esi+0x44]    ; 2) eax = [esi+0x44]
804eeab7 0f8d79130000 jnl nt!KiUnwaitThread+0xa6 (804efe36)
804eeabd 807e6e00 cmp byte ptr [esi+0x6e],0x0
804eeac1 7530 jnz nt!KiUnwaitThread+0x70 (804eeaf3)
804eeac3 80bebb01000000 cmp byte ptr [esi+0x1bb],0x0
804eeaca 7527 jnz nt!KiUnwaitThread+0x70 (804eeaf3)
804eeacc 8a566c mov dl,[esi+0x6c]
804eeacf 0fbeca movsx ecx,dl
804eead2 57 push    edi
804eead3 8b7d08 mov edi,[ebp+0x8]
804eead6 03f9 add edi,ecx
804eead8 80b80302000002 cmp byte ptr [eax+0x203],0x2 ; 1) eax = 00ed0da8
804eeadf 8bcf mov ecx,edi
804eeae1 0f84d5190000 je    nt!KiUnwaitThread+0x45 (804f04bc)

1) 죽은 곳이구요 그 위쪽 어디에서 eax 에 00ed0da8 을 채웠는지 찾아봐야 합니다.
2) 여기서 eax 를 채우는 코드가 보이므로 esi가 뭔지 알 필요가 있습니다.
kd> r esi
Last set context:
esi=822c8980
3) 여기서 esi 가 설정되는데 이것은 nt!KiUnwaitThread로 넘겨진 ecx가 됩니다.
nt!KiUnwaitThread은 FASTCALL 타입의 함수이므로 ecx는 첫번째 파라미터구요
nt!KiUnwaitThread의 첫번째 파라미터는 KTHREAD 포인터 입니다.

그래서 이 쓰레드를 살펴보면

kd> dt _KTHREAD 822c8980
   +0x000 Header : _DISPATCHER_HEADER
   +0x010 MutantListHead : _LIST_ENTRY [ 0x822c8990 - 0x822c8990 ]
   +0x018 InitialStack : 0xf7f98000
   +0x01c StackLimit : 0xf7f92000
   +0x020 Teb    : 0x7ffde000
   +0x024 TlsArray : (null)
   +0x028 KernelStack    : 0xf7f97c20
   +0x02c DebugActive    : 0 ''
   +0x02d State    : 0x5 ''
   +0x02e Alerted    : [2] ""
   +0x030 Iopl : 0 ''
   +0x031 NpxState : 0xa ''
   +0x032 Saturation : 0 ''
   +0x033 Priority : 9 ''
   +0x034 ApcState : _KAPC_STATE
   +0x04c ContextSwitches : 0x820387be
   +0x050 IdleSwapBlock    : 0 ''
   +0x051 Spare0 : [3] ""
   +0x054 WaitStatus : 0
   +0x058 WaitIrql : 0 ''
   +0x059 WaitMode : 1 ''
   +0x05a WaitNext : 0 ''
   +0x05b WaitReason : 0xd ''
   +0x05c WaitBlockList    : 0x822c89f0
   +0x060 WaitListEntry    : _LIST_ENTRY [ 0x8215dbf8 - 0x820ec8d0 ]
   +0x060 SwapListEntry    : _SINGLE_LIST_ENTRY
   +0x068 WaitTime : 0x45f99c
   +0x06c BasePriority : 8 ''
   +0x06d DecrementCount : 0x10 ''
   +0x06e PriorityDecrement : 0 ''
   +0x06f Quantum    : -127 ''
   +0x070 WaitBlock    : [4] _KWAIT_BLOCK
   +0x0d0 LegoData : (null)
   +0x0d4 KernelApcDisable : 0
   +0x0d8 UserAffinity : 1
   +0x0dc SystemAffinityActive : 0 ''
   +0x0dd PowerState : 0 ''
   +0x0de NpxIrql    : 0 ''
   +0x0df InitialNode    : 0 ''
   +0x0e0 ServiceTable : 0x8054e500
   +0x0e4 Queue    : (null)
   +0x0e8 ApcQueueLock : 0
   +0x0f0 Timer    : _KTIMER
   +0x118 QueueListEntry : _LIST_ENTRY [ 0x0 - 0x0 ]
   +0x120 SoftAffinity : 1
   +0x124 Affinity : 1
   +0x128 Preempted    : 0 ''
   +0x129 ProcessReadyQueue : 0 ''
   +0x12a KernelStackResident : 0x1 ''
   +0x12b NextProcessor    : 0 ''
   +0x12c CallbackStack    : (null)
   +0x130 Win32Thread    : 0xe22acaa8
   +0x134 TrapFrame    : 0xf7f97d64
   +0x138 ApcStatePointer : [2] 0x822c89b4
   +0x140 PreviousMode : 1 ''
   +0x141 EnableStackSwap : 0x1 ''
   +0x142 LargeStack : 0x1 ''
   +0x143 ResourceIndex    : 0x1 ''
   +0x144 KernelTime : 0xe
   +0x148 UserTime : 0x12
   +0x14c SavedApcState    : _KAPC_STATE
   +0x164 Alertable    : 0 ''
   +0x165 ApcStateIndex    : 0 ''
   +0x166 ApcQueueable : 0x1 ''
   +0x167 AutoAlignment    : 0 ''
   +0x168 StackBase    : 0xf7f98000
   +0x16c SuspendApc : _KAPC
   +0x19c SuspendSemaphore : _KSEMAPHORE
   +0x1b0 ThreadListEntry : _LIST_ENTRY [ 0x821a05c0 - 0x81ed0df8 ]
   +0x1b8 FreezeCount    : 0 ''
   +0x1b9 SuspendCount : 0 ''
   +0x1ba IdealProcessor : 0 ''
   +0x1bb DisableBoost : 0 ''

문제의 esi+44 즉, KTHREAD + 44 는

+0x034 ApcState : _KAPC_STATE
+0x04c ContextSwitches : 0x820387be

ApcState 와 ContextSwitches 사이의 영역이므로 ApcState 구조체의 영역입니다.
이것을 살펴보면

kd> dt _KAPC_STATE 822c8980+34
   +0x000 ApcListHead    : [2] _LIST_ENTRY [ 0x822c89b4 - 0x822c89b4 ]
   +0x010 Process    : 0x00ed0da8
   +0x014 KernelApcInProgress : 0 ''
   +0x015 KernelApcPending : 0 ''
   +0x016 UserApcPending : 0 ''

에서 문제의 esi+44 는 esi+34+10 (822c8980+34+10) 이고 Process의 포인터라는 것을 알 수 있습니다.
즉, KTHREAD 구조체중의 ApcState의 Process 포인터에 0x00ed0da8 라는 엉뚱한 값이 들어가 있어서 죽은 겁니다.
822c8980 가 KTHREAD 포인터이므로 다음과 같이 !thread 로 확인해 보면

kd> !thread 822c8980
THREAD 822c8980 Cid 0644.0648 Teb: 7ffde000 Win32Thread: e22acaa8 WAIT: (WrUserRequest) UserMode Non-Alertable
00ece808 NotificationEvent
Not impersonating
Owning Process    ed0da8 Image: <Unknown>
Wait Start TickCount    4585884    Ticks: 100 (0:00:00:01.001)
Context Switch Count    -2113697858 LargeStack
UserTime    00:00:00.0180
KernelTime    00:00:00.0140
Start Address KERNEL32!BaseProcessStartThunk (0x77e413f2)
Win32 Start Address 0x0040e760
Stack Init f7f98000 Current f7f97c20 Base f7f98000 Limit f7f92000 Call 0
Priority 9 BasePriority 8 PriorityDecrement 0 DecrementCount 16
ChildEBP RetAddr Args to Child
f7f97c38 804ee05a 822c89f0 822c8980 804eec74 nt!KiSwapContext+0x2e (FPO: [EBP 0xf7f97c6c] [0,0,4])
f7f97c44 804eec74 000025ff e22acaa8 00000000 nt!KiSwapThread+0x44 (FPO: [0,0,2])
f7f97c6c bf8024a2 00000001 0000000d 00000001 nt!KeWaitForSingleObject+0x1c0 (FPO: [Non-Fpo])
f7f97ca8 bf80292c 000025ff 00000000 00000001 win32k!xxxSleepThread+0x189 (FPO: [Non-Fpo])
f7f97cec bf8028e1 f7f97d18 000025ff 00000000 win32k!xxxRealInternalGetMessage+0x40f (FPO: [Non-Fpo])
f7f97d4c 804dc1dd 00416f5c 00000000 00000000 win32k!NtUserGetMessage+0x27 (FPO: [Non-Fpo])
f7f97d4c 7ffe0304 00416f5c 00000000 00000000 nt!KiSystemService+0xc4 (FPO: [0,0] TrapFrame @ f7f97d64)
0012fec4 00000000 00000000 00000000 00000000 SharedUserData!SystemCallStub+0x4 (FPO: [0,0,0])

Process 정보를 다음과 같이 Image: <Unknown>로 올바로 보여주지 못하고 있습니다.
다른 정보들은 멀쩡한것 같은데 프로세스 포인터만 잘못되어 있는게 좀 특이하네요.

이 상태에서는 어떤 원인에 의해서 이 부분만 잘못 되었는지는 파악이 불가능합니다.
추정해 볼 수 있는 것이라고는 어떤 녀석이 아무렇게나 깨먹은게 재수없게 이 부분이었다라는 정도구요.
그래도 최소한 메모리를 깨뜨리는 문제가 있다는 것으로 결론을 낼 수가 있었습니다.
이런 분석도 하지 않는다면 소스에서 IRQL 다루는 부분만 열심히 쏘아보는 헛수고를 하고 있어야 겠지요. ^^

편집후기) 어떤 은둔고수는 유사한 케이스에서 깨뜨린 값 0x00ed0da8 4바이트의 형태를 가지고 메모리의 이곳 저곳을 비교해가면서 깨뜨리는 녀석을 찾아내는 경이로움을 보여주시는 분도 있었답니다.

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&GotoPage=3&s_bulu=&s_key=&no=65

Posted by GreeMate

[WinDbg 분석] BugCheck 0x19

오늘은 메모리가 깨졌을 경우에 발생하는 BugCheck 0x19: BAD_POOL_HEADER 에 대해서 분석해 보겠습니다.
이것은 메모리를 할당 또는 해제할 때 커널에서 Pool Header 를 체크하여 발생시키는 버그체크입니다.
Verifier 의 Special Pool 을 사용하지 않아도 커널의 자체적인 체크에 의하여 발생합니다.

먼저 !analyze 로 기본적인 사항을 검토해 봅니다.

kd> !analyze -v
***************************************************************************
* *
* Bugcheck Analysis *
* *
***************************************************************************

BAD_POOL_HEADER (19)
The pool is already corrupt at the time of the current request.
This may or may not be due to the caller.
The internal pool links must be walked to figure out a possible cause of
the problem, and then special pool applied to the suspect tags or the driver
verifier to a suspect driver.
Arguments:
Arg1: 00000020, a pool block header size is corrupt.
Arg2: 827b49f8, The pool entry we were looking for within the page.
Arg3: 827b4a08, The next pool entry.
Arg4: 0a020001, (reserved)

Debugging Details:
------------------

BUGCHECK_STR: 0x19_20
POOL_ADDRESS: 827b49f8 Nonpaged pool
DEFAULT_BUCKET_ID: DRIVER_FAULT
PROCESS_NAME: System
LAST_CONTROL_TRANSFER: from 8054de41 to 805359ae

STACK_TEXT:
f7975d00 8054de41 00000019 00000020 827b49f8 nt!KeBugCheckEx+0x1b
f7975d50 8054d7b9 827b4a00 00000000 f7975dac nt!ExFreePoolWithTag+0x2be
f7975d60 f7808d07 827b4a00 82c47718 80563b7c nt!ExFreePool+0xf
WARNING: Stack unwind information not available. Following frames may be wrong.
f7975dac 8057ffed 82c47718 00000000 00000000 MyDrv+0x2d07
f7975ddc 804fc477 804e6729 00000001 00000000 nt!PspSystemThreadStartup+0x34
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

STACK_COMMAND: kb

FOLLOWUP_IP:
MyDrv+2d07
f7808d07 56 push esi

SYMBOL_STACK_INDEX: 3
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: MyDrv
IMAGE_NAME: MyDrv.SYS
DEBUG_FLR_IMAGE_TIMESTAMP: 3cf1f0eb
SYMBOL_NAME: MyDrv+2d07
FAILURE_BUCKET_ID: 0x19_20_MyDrv+2d07
BUCKET_ID: 0x19_20_MyDrv+2d07

Followup: MachineOwner
---------

Pool 이 깨진 것 같다는 메시지로 시작합니다.
이 호출을 한 드라이버가 범인일 수도 아닐 수도 있다고 하구요.
원인을 찾기 위해서 internal pool link 를 따라가 보라구 하네요. 이건 밑에서 자세히 설명합니다.
그리고 verifier와 special pool 을 의심가는 드라이버에 적용해서 문제를 찾으라고 하네요.
정말 친절하지 않습니까? 사실 오늘의 분석도 하라는 대로 그대로 진행하는 내용입니다. ^^

Arg1: 00000020 는 pool block header 가 깨졌다는 것을 알려주는 코드입니다.
BugCheck 0x19 에 대한 WinDbg Help 를 보시면 몇가지 더 있는 것을 볼 수 있습니다.

Arg2: 827b49f8 는 현재 사용되던 문제의 메모리 주소네요.
콜스택상의 메모리 주소와 비교해 볼 필요가 있는데요...

f7975d60 f7808d07 827b4a00 82c47718 80563b7c nt!ExFreePool+0xf

ExFreePool 의 첫번째 파라미터로 들어간 저 827b4a00 과 어떤 관계가 있는 걸까요?
잘 보시면 827b4a00 - 8 한 결과가 바로 Arg2 에 나타난 827b49f8 입니다.

827b4a00 는 사용자가 할당받아 사용하던 메모리 시작주소이구요. 사실 이 메모리는 앞에 8 바이트의 헤더가 붙어있습니다. 따라서 실제 할당된 메모리영역은 827b49f8 부터 시작하게 되구요
커널에서 pool 관리를 할 때는 pool header 부터 관리하기 때문에 문제의 시점에 다루고 있던 메모리 주소를 827b49f8 라고 보여준겁니다.

827b49f8 이 어떤 메모리인지 !pool 을 통해서 알아봅니다.

kd> !pool 827b49f8
Pool page 827b49f8 region is Nonpaged pool
827b4000 size: 60 previous size:    0 (Allocated) Ddk
827b4060 size:    8 previous size: 60 (Free) ....
...
...
827b47e0 size: 18 previous size: 20 (Free) Ntfi
827b47f8 size: 68 previous size: 18 (Allocated) MmCa
827b4860 size: 98 previous size: 68 (Allocated) File (Protected)
827b48f8 size: 20 previous size: 98 (Allocated) VadS
827b4918 size: 38 previous size: 20 (Allocated) MmSd
827b4950 size: 38 previous size: 38 (Allocated) MmSd
827b4988 size: 38 previous size: 38 (Allocated) MmSd
827b49c0 size: 10 previous size: 38 (Free) CcSc
827b49d0 size: 20 previous size: 10 (Allocated) ReTa
827b49f0 size:    8 previous size: 20 (Free) Ntfi
*827b49f8 size: 10 previous size:    8 (Allocated) *Ddk
Pooltag Ddk : Default for driver allocated memory (user's of ntddk.h)
827b4a08 is not a valid small pool allocation, checking large pool...
unable to get pool big page table - either wrong symbols or pool tagging is disabled
827b4a08 is freed (or corrupt) pool
Bad previous allocation size @827b4a08, last size was 2

***
*** An error (or corruption) in the pool was detected;
*** Attempting to diagnose the problem.
***
*** Use !poolval 827b4000 for more details.
***

Pool page [ 827b4000 ] is __inVALID.

Analyzing linked list...
[ 827b4a08 ]: invalid previous size [ 0x0 ] should be [ 0x2 ]

Scanning for single bit errors...
[ 827b4a08 ]: previous size [ 0x0 ] should be [ 0x2 ]

!pool 명령이 827b49f8 까지는 잘 보여주다가 827b4a08 을 제대로 보여주지 못하네요.
이런 오류 메시지가 나오면 십중팔구 pool header 가 깨진 것입니다.
!pool 명령은 커널이 그렇게 하듯이 pool header의 size 와 previous size 를 보면서 위와 같은 결과를 출력합니다. internal pool link 라는 것은 이것을 의미합니다.
!pool 명령이 처음부터 잘 보여주다가 827b4a08 을 제대로 보여주지 못한다는 것은 827b4a08 메모리 pool header 헤더의 내용이 온전하지 못하다는 의미입니다.

827b49f8 메모리의 내용은 어떤 것인지 한번 볼까요?

kd> db 827b49f8
827b49f8 01 00 02 0a 44 64 6b 20-53 2d 31 2d 35 2d 31 38 ....Ddk S-1-5-18
827b4a08 00 00 13 0a 46 69 6c e5-00 00 00 00 00 00 00 00 ....Fil.........
827b4a18 01 00 00 00 00 00 00 00-40 b0 fe 82 00 08 00 42 ........@......B
827b4a28 01 00 00 00 00 00 00 00-05 00 70 00 d0 a1 fb 82 ..........p.....

!pool 명령의 결과에서 보면 이 메모리의 size 는 0x10 (16바이트) 이고 풀태그는 Ddk 입니다.
827b49f8 부터 16바이트만 보면 됩니다. 앞에 8바이트는 헤더이고 뒤에 8바이트가 실제 사용된 메모리입니다.
실제 메모리 내용에는 S-1-5-18 라는 문자열이 들어 있네요. 운이 좋으면 이 문자열이 중요한 단서가 됩니다. 이번 경우는 뭔지 잘 모르겠네요.

헤더에서 뒤 4바이트는 풀태그라는 것을 알 수 있습니다. Ddk 라고 정확히 적혀있네요.
헤더에서 앞 4바이트의 의미는 어디 나와있는 곳은 없구요 제가 파악한 바로는 다음과 같습니다.

1번째 바이트: previous size ( 1 은 8 바이트를 의미, 2는 16바이트 )
2번째 바이트: 모르겠네요 -_-;;;
3번재 바이트: size ( 1 은 8 바이트를 의미, 2는 16바이트 )
4번재 바이트: 00 = Free, 0a = Allocated (확실치 않음 ^^)

이 사실을 확인해 보기 위해서 조금 앞에 있는 메모리 827b49c0 부터 살펴봅니다.

kd> db 827b49c0
827b49c0 07 00 02 00 43 63 53 63-f0 97 76 82 70 06 78 82 ....CcSc..v.p.x.
827b49d0 02 00 04 0a 52 65 54 61-00 00 00 00 03 00 00 00 ....ReTa........
827b49e0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
827b49f0 04 00 01 00 4e 74 66 69-01 00 02 0a 44 64 6b 20 ....Ntfi....Ddk
827b4a00 53 2d 31 2d 35 2d 31 38-00 00 13 0a 46 69 6c e5 S-1-5-18....Fil.
827b4a10 00 00 00 00 00 00 00 00-01 00 00 00 00 00 00 00 ................

827b49d0 부터 보시면 첫번째 바이트 02 는 앞의 메모리 827b49c0 의 size 와 일치합니다.
827b49d0 의 세번째 바이트 04 는 8 만 곱하면 4*8 = 32 로 !pool 명령에서 보여주는 size: 20 hex = 32 decimal 과 일치합니다.

827b49d0 에서 size 만큼 더하면 다음 메모리인 827b49f0 가 나오고 이것의 첫번재 바이트 04 는 previous인 827b49d0 의 size: 04 와 일치합니다. 이런 식으로 계속 연결되어 있는 것이죠.

하지만 해제하려는 메모리 827b49f8 까지는 잘 연될되는데 827b4a08 를 보니 문제가 있습니다.
827b4a08 의 첫번째 바이트는 previous size 인 02 가 있어야 하는데 엉뚱하게 00 이 들어 있는 거죠.

이것을 감지한 커널은 ExFreePool 을 더 진행하지 않고 BugCheck 0x19 를 띄운 것입니다.

메모리를 깨먹는 녀석이 있다는 사실을 알았으니 어떤 녀석인지 찾아야 겠네요.
Verifier로 Special Pool 을 켜고 의심가는 드라이버를 지정합니다. 지난번에도 언급한 적이 있는지 모르겠지만 개발중에는 항상 자신의 드라이버를 먼저 의심해야 합니다. 따라서 이번에는 MyDrv.sys 를 지정했습니다.

사실 메모리를 깨먹는 문제는 어떤 녀석이 범인인지 예측하기가 거의 불가능합니다. MyDrv.sys 를 지정한 것이 효과가 없다면 다른 드라이버들을 적용해 봐야 하고 최악의 경우 모든 드라이버를 지정하는 상황까지 갈 수 있습니다. 이렇게 해서라도 문제의 드라이버를 찾을 수 있다면 그나마 다행이죠. ^^

Verifier 로 얻고자 하는 결과는 BugCheck 0xD6: DRIVER_PAGE_FAULT_BEYOND_END_OF_ALLOCATION 입니다. 지난번에 한번 분석해 본적이 있는 BugCheck 입니다. 그 내용을 잊지 않고 있다면 범인은 거의 다 잡은 셈입니다.

원하는 것은 BugCheck 0xD6 이지만 이 버그체크를 얻기가 사실 쉽지 않았습니다.
Verifier 를 걸었지만 BugCheck 0x19 가 다시 발생하기도 하고 다른 곳에서 죽기도 하고 해서 몇번의 시도 끝에 겨우 BugCheck 0xD6 을 얻을 수 있었습니다.

kd> !analyze -v
****************************************************************************
*    *
*    Bugcheck Analysis *
*    *
****************************************************************************

DRIVER_PAGE_FAULT_BEYOND_END_OF_ALLOCATION (d6)
N bytes of memory was allocated and more than N bytes are being referenced.
This cannot be protected by try-except.
When possible, the guilty driver's name (Unicode string) is printed on
the bugcheck screen and saved in KiBugCheckDriver.
Arguments:
Arg1: 83801000, memory referenced
Arg2: 00000001, value 0 = read operation, 1 = write operation
Arg3: f7828176, if non-zero, the address which referenced memory.
Arg4: 00000000, (reserved)

Debugging Details:
------------------

WRITE_ADDRESS: 83801000 Special pool

FAULTING_IP:
MyDrv+1176
f7828176 f3a4 rep movs byte ptr es:[edi],byte ptr [esi]

MM_INTERNAL_CODE: 0

IMAGE_NAME: MyDrv.SYS
DEBUG_FLR_IMAGE_TIMESTAMP: 3cf1f0eb
MODULE_NAME: MyDrv
FAULTING_MODULE: f7827000 MyDrv
DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0xD6

PROCESS_NAME: explorer.exe

TRAP_FRAME: b985c748 -- (.trap ffffffffb985c748)
ErrCode = 00000002
eax=00000009 ebx=8066e90d ecx=00000001 edx=83800ff8 esi=b985c7dc edi=83801000
eip=f7828176 esp=b985c7bc ebp=836a6fe8 iopl=0 nv up ei pl nz na po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010202
MyDrv+0x1176:
f7828176 f3a4 rep movs byte ptr es:[edi],byte ptr [esi] es:0023:83801000=?? ds:0023:b985c7dc=00
Resetting default scope

LAST_CONTROL_TRANSFER: from 805266fb to 805359ae

STACK_TEXT:
b985c6e4 805266fb 00000050 83801000 00000001 nt!KeBugCheckEx+0x1b
b985c730 804e3ff1 00000001 83801000 00000000 nt!MmAccessFault+0x6f5
b985c730 f7828176 00000001 83801000 00000000 nt!KiTrap0E+0xcc
WARNING: Stack unwind information not available. Following frames may be wrong.
b985c804 80674576 828aeda8 0000001f 80673bf9 MyDrv+0x1176
b985ca28 804e5d77 82c50b60 83864e00 806f02e8 MyDrv+0x3779
b985ca38 8066c2c5 83864e10 83864e00 82d1fd98 nt!IopfCallDriver+0x31
b985ca5c 80572f9c 82e358e8 82c67ce4 b985cc04 nt!IovCallDriver+0xa0
b985cb3c 8056586c 82e35900 00000000 82c67c40 nt!IopParseDevice+0xa58
b985cbc4 80569c63 00000000 b985cc04 00000042 nt!ObpLookupObjectName+0x56a
b985cc18 80573477 00000000 00000000 c50b6001 nt!ObOpenObjectByName+0xeb
b985cc94 80573546 00e5db2c 40100080 00e5dacc nt!IopCreateFile+0x407
b985ccf0 8057367c 00e5db2c 40100080 00e5dacc nt!IoCreateFile+0x8e
b985cd30 804e106b 00e5db2c 40100080 00e5dacc nt!NtCreateFile+0x30
b985cd30 7c93eb94 00e5db2c 40100080 00e5dacc nt!KiFastCallEntry+0xf8
00e5db24 00000000 00000000 00000000 00000000 0x7c93eb94

STACK_COMMAND: kb

FOLLOWUP_IP:
MyDrv+1176
f7828176 f3a4 rep movs byte ptr es:[edi],byte ptr [esi]

SYMBOL_STACK_INDEX: 3
FOLLOWUP_NAME: MachineOwner
SYMBOL_NAME: MyDrv+1176
FAILURE_BUCKET_ID: 0xD6_W_MyDrv+1176
BUCKET_ID: 0xD6_W_MyDrv+1176

Followup: MachineOwner
---------

할당된 영역을 넘어선 메모리 접근이 있었다는 내용이 나옵니다.
불행인지 다행인지 MyDrv 에서 한 짓이었군요. ^^

Arg2: 00000001, value 0 = read operation, 1 = write operation

이 메시지를 보니 쓰기 시도가 있었다는 것을 알 수 있습니다.

.trap 에 대한 메시지가 있네요. 그대로 해 줍니다.

kd> .trap ffffffffb985c748
ErrCode = 00000002
eax=00000009 ebx=8066e90d ecx=00000001 edx=83800ff8 esi=b985c7dc edi=83801000
eip=f7828176 esp=b985c7bc ebp=836a6fe8 iopl=0 nv up ei pl nz na po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010202
MyDrv+0x1176:
f7828176 f3a4 rep movs byte ptr es:[edi],byte ptr [esi] es:0023:83801000=?? ds:0023:b985c7dc=00

마지막 부분에서 죽었을 당시의 코드를 볼 수 있습니다.
esi 주소를 edi 로 한 바이트씩 복사하다가 edi=83801000 가 되었을 때 죽은 거네요.

kd> db 83801000
83801000 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????
83801010 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????
83801020 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????
83801030 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????

83801000 는 접근할 수 없는 메모리입니다. 왜냐하면 Guard Page 이기 때문입니다.
BugCheck 0xD6 에서 설명했었기 때문에 자세한 설명은 생략하구요.

83801000 주소 앞쪽에는 복사를 잘 했을 것이므로 약간 앞쪽 메모리를 살펴보겠습니다.

kd> db 83801000 - 10
83800ff0 cf cf cf cf cf cf cf cf-53 2d 31 2d 35 2d 31 38 ........S-1-5-18
83801000 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????
83801010 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????
83801020 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????

눈에 익은 문자열이 보입니다. 상황이 좀 파악되시나요?

메모리 할당은 8 바이트를 하고 나서 9 번째 바이트에 쓰기시도를 하면서 BugCheck 0xD6 가 발생한 겁니다.
이것은 이 메모리가 special pool 에 할당되었기 때문에 감지가 가능한 것입니다.

Verifier 를 설정하지 않은 상태에서는 BucCheck 0x19가 발생하는 이유를 이제야 이해할 수 있습니다.
일반 pool 이었다면 S-1-5-18 바로 다음은 다음 엔트리의 헤더가 됩니다.
헤더의 첫번재 바이트는 previous size 인데 이것을 깨뜨리게 되는 것이죠.
안타깝게도 이 때에는 문제가 노출되지 않습니다. 나중에 다른 메모리 할당/해제 요청이 있을 때 커널이 pool link 를 체크하다가 그제서야 문제를 알게 되지요. 이 시점에서는 원인을 찾을 수 없습니다. 이것이 바로 메모리 깨뜨리는 문제가 풀기 어려운 문제에 속하는 이유입니다.

따라서 이와 같은 상황에서는 위와 같이 Verifier 같은 툴을 잘 활용하여 원인을 찾아야 합니다.
이상 BugCheck 0x19 로 문제를 진단하고 BugCheck 0xD6 으로 범인을 잡는 협공이었습니다. ^^

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&GotoPage=2&s_bulu=&s_key=&no=79

Posted by GreeMate

[WinDbg 분석] BugCheck 0xC1

Verifier의 Special Pool 을 이용할 때 발견할 수 있는 오류를 하나 더 보겠습니다.
BugCheck 0xC1 입니다. 이번엔 바로 !analyze -v 를 해 봅니다.

kd> !analyze -v
****************************************************************************
*    *
* Bugcheck Analysis    *
*    *
****************************************************************************

SPECIAL_POOL_DETECTED_MEMORY_CORRUPTION (c1)
Special pool has detected memory corruption. Typically the current thread's
stack backtrace will reveal the guilty party.
Arguments:
Arg1: 83d76ff8, address trying to free
Arg2: 83d76ffc, address where bits are corrupted
Arg3: 0081c004, (reserved)
Arg4: 00000024, caller is freeing an address where bytes after the end of the allocation have been overwritten

Debugging Details:
------------------

BUGCHECK_STR: 0xC1_24

SPECIAL_POOL_CORRUPTION_TYPE: 24

DEFAULT_BUCKET_ID: DRIVER_FAULT

PROCESS_NAME: System

LAST_CONTROL_TRANSFER: from 8053425b to 804e5592

STACK_TEXT:
f88ee700 8053425b 00000003 f88eea5c 00000000 nt!RtlpBreakWithStatusInstruction
f88ee74c 80534d2e 00000003 83d76000 00000004 nt!KiBugCheckDebugBreak+0x19
f88eeb2c 8053531e 000000c1 83d76ff8 83d76ffc nt!KeBugCheck2+0x574
f88eeb4c 806811ae 000000c1 83d76ff8 83d76ffc nt!KeBugCheckEx+0x1b
f88eeb8c 8054d5aa 83d76ff8 81ac7550 e14374d2 nt!MmFreeSpecialPool+0x29b
f88eebcc 8066da60 83d76ff8 00000000 f88eebe8 nt!ExFreePoolWithTag+0x4a
f88eebdc f38e3da3 83d76ff8 f88eebf8 f38e3f23 nt!VerifierFreePool+0x1f
f88eebe8 f38e3f23 83d76ff8 01d76ff8 f88eec20 MyDrv!my_free+0x13 [d:\mytest\mydrv\my_mem.c @ 38]
f88eebf8 f38e1ce0 83d76ff8 83d76ff8 0013a8d9 MyDrv!my_close+0x43 [d:\mytest\mydrv\my_file.c @ 59]
f88eec20 f38e1047 e30c2970 e30c0000 f88eec48 MyDrv!Test_Open+0x130 [d:\mytest\mydrv\my_test.c @ 455]
...

STACK_COMMAND: kb

FOLLOWUP_IP:
MyDrv!my_free+13 [d:\mytest\mydrv\my_mem.c @ 38]
f38e3da3 5d pop ebp

FAULTING_SOURCE_CODE:
34:
35: if (pv)
36: ExFreePool(pv);
37:
> 38: }
39:
40: void my_copy(LPVOID pDest, LPCVOID pSrc, size_t nLength)
41: {

SYMBOL_STACK_INDEX: 7

SYMBOL_NAME: MyDrv!my_free+13

FOLLOWUP_NAME: MachineOwner

MODULE_NAME: MyDrv

IMAGE_NAME: MyDrv.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 45127eee

FAILURE_BUCKET_ID: 0xC1_24_VRF_MyDrv!my_free+13

BUCKET_ID: 0xC1_24_VRF_MyDrv!my_free+13

Followup: MachineOwner
---------

메시지를 읽어보면 이번에는 특별히 하라는 것은 없습니다.
그래도 메시지는 꼼꼼히 읽어봅시다. 이 BugCheck 의 원인을 정확히 설명해 주고 있습니다.

일단 메모리를 깨뜨려서 발생한 것이라고 설명하고 있습니다. 콜스택을 보면 문제 해결에
도움이 될 거라고 하네요. 콜스택은 조금 있다가 보기로 하구요.

아주 유용한 정보가 보입니다.

Arg4: 00000024, caller is freeing an address where bytes after the end of the allocation have been overwritten

문제가 발생한 원인을 말해주고 있습니다.
할당한 메모리를 넘어서는 부분을 깨뜨리고 메모리를 해제하려고 했다고 하네요.

Special Pool 을 이용하면 이런 문제를 잡을 수 있습니다. 메모리를 깨뜨리는 문제는
매우 까다로운 문제에 속합니다. 원인을 찾지 못하는 경우도 많습니다.
이럴 때 Verifier의 도움을 받으면 효과를 볼 수 있다는 것을 기억하시기 바랍니다.
아니 Verifier 는 개발중에 무조건 켜놓고 사용하는 것이라고 보면 되기 때문에
특별히 기억할 필요도 없겠네요. 그냥 습관적으로 사용하시기 바랍니다.

본론으로 돌아가서 Arg4 는 BugCheck 0xC1 을 발생시키는 원인을 지시하는 값이 들어갑니다.
0x24 는 위와 같은 뜻이구요. 다른 코드들과 그 의미는 WinDbg Help 를 참고하시기 바랍니다.
메모리 사용에 있어서 여러가지 오류 상황들을 잡아낼 수 있다는 것을 아시게 될 겁니다.

Arg1: 83d76ff8, address trying to free
Arg2: 83d76ffc, address where bits are corrupted

Arg1 은 메모리 주소네요. Arg2 는 깨진 곳의 주소입니다.

Verifier 는 어떻게 깨진 곳의 주소를 알고 있는 것일까요?
이제 콜스택을 봅니다.

f88ee700 8053425b 00000003 f88eea5c 00000000 nt!RtlpBreakWithStatusInstruction
f88ee74c 80534d2e 00000003 83d76000 00000004 nt!KiBugCheckDebugBreak+0x19
f88eeb2c 8053531e 000000c1 83d76ff8 83d76ffc nt!KeBugCheck2+0x574
f88eeb4c 806811ae 000000c1 83d76ff8 83d76ffc nt!KeBugCheckEx+0x1b
f88eeb8c 8054d5aa 83d76ff8 81ac7550 e14374d2 nt!MmFreeSpecialPool+0x29b
f88eebcc 8066da60 83d76ff8 00000000 f88eebe8 nt!ExFreePoolWithTag+0x4a
f88eebdc f38e3da3 83d76ff8 f88eebf8 f38e3f23 nt!VerifierFreePool+0x1f
f88eebe8 f38e3f23 83d76ff8 01d76ff8 f88eec20 MyDrv!my_free+0x13 [d:\mytest\mydrv\my_mem.c @ 38]
f88eebf8 f38e1ce0 83d76ff8 83d76ff8 0013a8d9 MyDrv!my_close+0x43 [d:\mytest\mydrv\my_file.c @ 59]
f88eec20 f38e1047 e30c2970 e30c0000 f88eec48 MyDrv!Test_Open+0x130 [d:\mytest\mydrv\my_test.c @ 455]

my_free() 함수에서 호출한 ExFreePool()이 결국 MmFreeSpecialPool() 을 호출하고 여기서
KeBugCheckEx() 를 호출하는 것을 볼 수 있습니다.

즉, Verifier는 메모리를 해제할 때 메모리의 내용을 체크해서 문제가 있는지 확인합니다.
메모리의 내용을 보면

kd> !pool 83d76ff8
Pool page 83d76ff8 region is Special pool
*83d76ff8 size: 4 pagable special pool, Tag is MDRV
Owning component : Unknown (update pooltag.txt)

kd> db 83d76ff8
83d76ff8 d8 03 00 80 10 d2 8e f3-?? ?? ?? ?? ?? ?? ?? ?? ........????????
83d77008 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????
83d77018 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????
83d77028 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????

size 4 의 메모리였네요. d8 03 00 80 가 할당해서 사용했던 데이터구요.
깨진 주소가 83d76ffc 이므로 10 d2 8e f3 에서 10 에 해당합니다.

깨진것을 판단하는 방법은 지나번에 설명한 Special Pool 의 구조로 설명됩니다.
할당된 메모리 조금 앞을 보면

kd> db 83d76ff8 - 10
83d76fe8 81 81 81 81 81 81 81 81-81 81 81 81 81 81 81 81 ................
83d76ff8 d8 03 00 80 10 d2 8e f3-?? ?? ?? ?? ?? ?? ?? ?? ........????????

81 이라는 값이 차 있는 것을 볼 수 있습니다.

이 페이지 맨 앞을 보면

kd> db 83d76000
83d76000 04 c0 81 00 4d 44 53 56-00 00 00 00 08 4f f1 81 ....MDRV.....O..
83d76010 81 81 81 81 81 81 81 81-81 81 81 81 81 81 81 81 ................
83d76020 81 81 81 81 81 81 81 81-81 81 81 81 81 81 81 81 ................
83d76030 81 81 81 81 81 81 81 81-81 81 81 81 81 81 81 81 ................

맨 앞에 size 4 가 보이고 그 다음 다음에 81 이 보이고 뒤부분이 모두 81 로 채워지
있는 것이 보입니다. 맨 뒤도 사실은 다음과 같이 채워져 있었습니다.

83d76ff8 d8 03 00 80 81 81 81 81-?? ?? ?? ?? ?? ?? ?? ?? ........????????

MmFreeSpecialPool()에서는 81 로 채워진 부분이 온전한지를 검사합니다.
할당해준 메모리 영역만 정확히 사용했는지 검사하는 겁니다.
할당된 영역을 넘어선 뒤부분 검사를 시작하자마자 딱 걸렸네요.
할당된 크기보다 큰 영역을 건드렸으므로 오류라는 뜻입니다.

메시지에서 보여주는 오류 소스코드를 보면

FAULTING_SOURCE_CODE:
34:
35: if (pv)
36: ExFreePool(pv);
37:

my_free() 내부의 소스코드인데 메모리 해제 밖에 없으니 원인을 알 수 없습니다.
상위 함수의 내용을 보면

BOOLEAN my_close(PMYHANDLE pMyHandle)
{
...

ZwClose(pMyHandle->Handle);
my_free(pMyHandle);

return bRet;
}

pMyHandle 을 해제하라고 넘겨준 것이므로 pMyHandle을 사용하는 곳들을 살펴보면
원인을 찾을 수 있습니다.

생성부터 살펴보니

PMYHANDLE my_open(LPCTSTR pszFile)
{
PMYHANDLE pMyHandle = my_malloc(sizeof(PMYHANDLE));
if (!pMyHandle) return 0;

...
}

바로 문제가 발견되었네요. 한 눈에 보이시나요?
흔히 하는 실수 중에 하나인데 sizeof() 에 구조체 타입이 아닌 구조체 포인터 타입을
주는 것이 문제였습니다. 포인터 타입이니 4바이트만 할당되겠죠. 구조체는 4바이트
보다 클테니 구조체에 어떤 값을 쓰다가 어디선가 깨뜨리게 됩니다.
이 문제는 다음과 같이 코드를 수정하면 해결됩니다.

PMYHANDLE pMyHandle = my_malloc(sizeof(MYHANDLE));

메모리를 깨뜨리는 문제에서 이런 경우는 아주 운이 좋은 케이스입니다.
문제의 메모리를 할당하는 곳부터 살펴보기 시작했는데 거기서 바로 문제가 발견된
경우이니까요. 저 부분이 정상이었다면 pMyHandle 을 사용하는 모든 곳을 살펴봐야
하는 상황이 됩니다. 복잡한 코드가 많이 있다면 더더욱 갑갑해 지겠죠.

이것이 BugCheck 0xC1 이 가지는 한계이기도 합니다.
메모리가 깨졌을 때 바로 BugCheck 를 발생시키는 것이 아니라 깨진 메모리가 해제될
때 체크하는 방식이기 때문입니다. 깨뜨린 곳이 어디인지를 찾는 고통의 시간이 항상
필요합니다. 그렇다고 하더라도 이렇게라도 잡아주는 것에 감사해야 합니다. ^^

좀 더 손쉽게 문제의 정확한 위치를 찾는 방법이 있기는 합니다.
덤프파일을 분석하는 상황이었다면 위에서 처럼 소스를 뒤져서 원인을 찾는 것 밖에
방법이 없습니다. 하지만 live debugging 중이었다면 메모리 브레이크 포인트를 활용
할 수 있습니다.

처음에 죽었을 때 깨지는 위치를 확인한 후에 리부팅하고 다시 죽기 전에 깨지는 위치에
메모리 브레이크 포인트를 걸면 되겠지요.

kd> ba w1 83d76ffc
kd> bl
0 e 83d76ffc w 1 0001 (0001)

이렇게 해 놓으면 누군가가 메모리를 꺠뜨리는 순간... 범인은 바로 잡힙니다.
생각만 해도 통쾌하네요. ^^

이번에는 메모리 깨뜨리는 문제에 대해서 살펴봤습니다.
골치아픈 문제지만 손쉽게 분석해서 해결하시기 바라겠습니다.

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&GotoPage=6&s_bulu=&s_key=&no=27

Posted by GreeMate

[WinDbg 분석] BugCheck 0xD6

드라이버를 개발할 때 Verifier 를 사용하면 매우 유용합니다.
사소 한 버그부터 심각한 오류까지 확실하게 체크해 주기 때문입니다.
Verifier가 오류를 발견했을 때 발생시키는 Bugcheck 중 오늘은 0xD6에 대 해서
살펴보도록 하겠습니다.

*** Fatal System Error: 0x000000d6
(0x82C5D000,0x00000000,0xF48BE08D,0x00000000)

Driver at fault:
*** MyDrv.sys - Address F48BE08D base at F48BA000, DateStamp 4507c937
.
Break instruction exception - code 80000003 (first chance)

A fatal system error has occurred.
Debugger entered on first try; Bugcheck callbacks have not been invoked.

A fatal system error has occurred.

Connected to Windows XP 2600 x86 compatible target, ptr64 FALSE
Loading Kernel Symbols
...........................................................................................................................
Loading User Symbols
.............................
Loading unloaded module list
....................
****************************************************************************
* *
* Bugcheck Analysis *
* *
****************************************************************************

Use !analyze -v to get detailed debugging information.

BugCheck D6, {82c5d000, 0, f48be08d, 0}

Probably caused by : MyDrv.sys ( MyDrv+408d )

Followup: MachineOwner
---------

nt!RtlpBreakWithStatusInstruction:
804e5592 cc int 3

기본적인 내용들이 보이지만 역시 하라는 대로 !analyze -v 먼저 해 봅 니다.

kd> !analyze -v
****************************************************************************
* *
* Bugcheck Analysis *
* *
****************************************************************************

DRIVER_PAGE_FAULT_BEYOND_END_OF_ALLOCATION (d6)
N bytes of memory was allocated and more than N bytes are being referenced.
This cannot be protected by try-except.
When possible, the guilty driver's name (Unicode string) is printed on
the bugcheck screen and saved in KiBugCheckDriver.
Arguments:
Arg1: 82c5d000, memory referenced
Arg2: 00000000, value 0 = read operation, 1 = write operation
Arg3: f48be08d, if non-zero, the address which referenced memory.
Arg4: 00000000, (reserved)

Debugging Details:
------------------

READ_ADDRESS: 82c5d000 Special pool

FAULTING_IP:
MyDrv!my_strlen+d [d:\mytest\mydrv\my_str.c @ 67]
f48be08d 0fbe11 movsx edx,byte ptr [ecx]

MM_INTERNAL_CODE: 0

IMAGE_NAME: MyDrv.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4507c937

MODULE_NAME: MyDrv

FAULTING_MODULE: f48ba000 MyDrv

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0xD6

PROCESS_NAME: explorer.exe

TRAP_FRAME: f490977c -- (.trap fffffffff490977c)
ErrCode = 00000000
eax=82c5d000 ebx=81b85c00 ecx=82c5d000 edx=ffffff83 esi=81bd5e30 edi=81bdbd38
eip=f48be08d esp=f49097f0 ebp=f49097f4 iopl=0 nv up ei ng nz na po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010282
MyDrv!my_strlen+0xd:
f48be08d 0fbe11 movsx edx,byte ptr [ecx] ds:0023:82c5d000=??
Resetting default scope

LAST_CONTROL_TRANSFER: from 8053425b to 804e5592

STACK_TEXT:
f49092cc 8053425b 00000003 82c5d000 00000000 nt!RtlpBreakWithStatusInstruction
f4909318 80534d2e 00000003 806f0298 c020b174 nt!KiBugCheckDebugBreak+0x19
f49096f8 8053531e 00000050 82c5d000 00000000 nt!KeBugCheck2+0x574
f4909718 80525f44 00000050 82c5d000 00000000 nt!KeBugCheckEx+0x1b
f4909764 804e3718 00000000 82c5d000 00000000 nt!MmAccessFault+0x6f5
f4909764 f48be08d 00000000 82c5d000 00000000 nt!KiTrap0E+0xcc
f49097f4 f48bce5f 82c5cfe0 f490980c 81bd1740 MyDrv!my_strlen+0xd [d:\mytest\mydrv\my_str.c @ 67]
f4909814 f48bcfa5 82c5cfe0 82c5cf00 f4909890 MyDrv!IsMyFilePath1+0xf [d:\mytest\mydrv\my_path.c @ 949]
f490982c f48bd01d 82c5cfe0 00000000 f4909890 MyDrv!IsMyFilePath+0x15 [d:\mytest\mydrv\my_path.c @ 990]
f490984c f48bb10f 81bd1710 81bd1700 f4909890 MyDrv!CompFilePath+0x4d [d:\mytest\mydrv\my_path.c @ 1013]
f4909864 f46eb2ce 81bd1710 81bd1700 f4909890 MyDrv!MyDrv_CompFilePath+0x2f [d:\mytest\mydrv\my_exp.c @ 142]
...

STACK_COMMAND: kb

FOLLOWUP_IP:
MyDrv!my_strlen+d [d:\mytest\mydrv\my_str.c @ 67]
f48be08d 0fbe11 movsx edx,byte ptr [ecx]

FAULTING_SOURCE_CODE:
63: size_t my_strlen(LPCSTR str)
64: {
65: const char *eos = str;
66:
> 67: while( *eos++ ) ;
68:
69: return( (int)(eos - str - 1) );
70: }
71:

SYMBOL_STACK_INDEX: 6

FOLLOWUP_NAME: MachineOwner

SYMBOL_NAME: MyDrv!my_strlen+d

FAILURE_BUCKET_ID: 0xD6_VRF_MyDrv!my_strlen+d

BUCKET_ID: 0xD6_VRF_MyDrv!my_strlen+d

Followup: MachineOwner
---------

역시 설명을 가만히 읽어보시기 바랍니다.
N 바이트 할당된 메모리인 데 N 바이트 보다 많이 읽으려고 시도했다는 내용입니다.
Verifier 에서 Special Memory Pool 옵션을 켜면 이런 상황을 잡아줍니다.
Verifier 의 도움없이 이런 버그를 잡는 일은 생각만 해도 끔찍합니다. ^^

메시지에서 하라는 대로 KiBugCheckDriver 변수의 내용을 살펴봅니다.

kd> db KiBugCheckDriver
8055be00 1c d2 d0 81 00 00 00 00-00 00 00 00 00 00 00 00 ................
8055be10 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................

이런... 포인터군요.

kd> dd KiBugCheckDriver
8055be00 81d0d21c 00000000 00000000 00000000
8055be10 00000000 00000000 00000000 00000000

kd> db 81d0d21c
81d0d21c 14 00 14 00 3c d2 d0 81-00 40 10 0b 01 00 04 00 ....<....@......
81d0d22c ff ff ff ff bf e5 01 00-fe ff ff ff 00 00 00 00 ................
81d0d23c 4d 00 79 00 44 00 72 00-76 00 2e 00 73 00 79 00 M.y.D.r.v...s.y.
81d0d24c 73 00 00 00 00 00 00 00-5c 00 57 00 0e 00 1f 0a s.......\.W.....

메모리의 내용을 보아하니 UNICODE_STRING 구조체인 것 같습니다.
dt 명령어로 구조체 내용을 확인해 봅니다.

kd> dt _UNICODE_STRING 81d0d21c
"MyDrv.sys"
+0x000 Length : 0x14
+0x002 MaximumLength : 0x14
+0x004 Buffer : 0x81d0d23c "MyDrv.sys"

문제의 드라이버 이름이 잘 보이고 있네요.
사실 !analyze -v 메시지 에 MyDrv.sys 라는 이름이 수도 없이 나오기 때문에 구지
이렇게 보지 않아도 됩니다만 그래도 WinDbg가 하라는 것은 한번 해보는 것이 좋습니다.

메시지 중간에 TRAP_FRAME: f490977c -- (.trap fffffffff490977c) 가 있었으므로
이것도 역시 실행해 줍니다.

kd> .trap fffffffff490977c
ErrCode = 00000000
eax=82c5d000 ebx=81b85c00 ecx=82c5d000 edx=ffffff83 esi=81bd5e30 edi=81bdbd38
eip=f48be08d esp=f49097f0 ebp=f49097f4 iopl=0 nv up ei ng nz na po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010282
MyDrv!my_strlen+0xd:
f48be08d 0fbe11 movsx edx,byte ptr [ecx] ds:0023:82c5d000=??

kv 명령으로 확인해 보면 위에 보였던 콜스택에서 변화가 생겼음을 확인 할 수 있습니다.

kd> kv
*** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr Args to Child
f49097f4 f48bce5f 82c5cfe0 f490980c 81bd1740 MyDrv!my_strlen+0xd
f4909814 f48bcfa5 82c5cfe0 82c5cf00 f4909890 MyDrv!IsMyFilePath1+0xf ...
f490982c f48bd01d 82c5cfe0 00000000 f4909890 MyDrv!IsMyFilePath+0x15 ...
f490984c f48bb10f 81bd1710 81bd1700 f4909890 MyDrv!CompFilePath+0x4d ...
f4909864 f46eb2ce 81bd1710 81bd1700 f4909890 MyDrv!MyDrv_CompFilePath+0x2f ...
...

이번에도 kn 으로 콜스택을 살펴보고 하나씩 따라 올라가면서 문제를 살 펴봅니다.

kd> kn
*** Stack trace for last set context - .thread/.cxr resets it
# ChildEBP RetAddr
00 f49097f4 f48bce5f MyDrv!my_strlen+0xd [d:\mytest\mydrv\my_str.c @ 67]
01 f4909814 f48bcfa5 MyDrv!IsMyFilePath1+0xf [d:\mytest\mydrv\my_path.c @ 949]
02 f490982c f48bd01d MyDrv!IsMyFilePath+0x15 [d:\mytest\mydrv\my_path.c @ 990]
03 f490984c f48bb10f MyDrv!CompFilePath+0x4d [d:\mytest\mydrv\my_path.c @ 1013]
04 f4909864 f46eb2ce MyDrv!MyDrv_CompFilePath+0x2f [d:\mytest\mydrv\my_exp.c @ 142]
...

스택 프레임 00 에서 문제가 발생한 것으로 보입니다.
바로 지역변수 를 확인해 봅니다.

kd> dv
str = 0x82c5cfe0 "\Device\HarddiskVolume1\???"
eos = 0x82c5d000 ""

eos 가 문제가 발생했다는 주소와 일치합니다.

Arguments:
Arg1: 82c5d000, memory referenced
Arg2: 00000000, value 0 = read operation, 1 = write operation

이 주소를 읽다가 죽었다는 의미입니다.
위 메시지에 나와있는 소스 코드를 보면 str 로부터 시작해서 eos까지 읽다가 죽은 것으로 보입니다.
str부터 eos까지 어떤 내용이 들어있는지 봅니다.

kd> db 0x82c5cfe0
82c5cfe0 5c 44 65 76 69 63 65 5c-48 61 72 64 64 69 73 6b \Device\Harddisk
82c5cff0 56 6f 6c 75 6d 65 31 5c-c3 c3 c3 c3 c3 c3 c3 c3 Volume1\........
82c5d000 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????
82c5d010 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????

문자열인데 NULL 로 끝나지 않는 것이 문제라는 것을 한눈에 알 수 있습 니다.
소스코드의 while( *eos++ )은 NULL 을 만나야 끝나는데 NULL 이 없으니 계속
진행하다가 ?? 에서 죽은 겁니다.

왜 NULL 로 끝나지 않은 문자열이 전달된 것인지 콜스택을 따라가며 알 아 봅니다.

kd> .frame 1
01 f4909814 f48bcfa5 MyDrv!IsMyFilePath1+0xf [d:\mytest\mydrv\my_path.c @ 949]
kd> dv
pszPath = 0x82c5cfe0 "\Device\HarddiskVolume1\???"

상위에서 전달받은 변수네요.

kd> .frame 2
02 f490982c f48bd01d MyDrv!IsMyFilePath+0x15 [d:\mytest\mydrv\my_path.c @ 990]
kd> dv
pszPath = 0x82c5cfe0 "\Device\HarddiskVolume1\???"

역시 상위에서 전달받은 변수군요.

kd> .frame 3
03 f490984c f48bb10f MyDrv!CompFilePath+0x4d [d:\mytest\mydrv\my_path.c @ 1013]
kd> dv
pszPath = 0x81bd1710 "\Device\HarddiskVolume1\"
nPathLen = 0x18
pszPathA = 0x82c5cfe0 "\Device\HarddiskVolume1\???"

여기에서 만들어져서 전달한 변수인 것 같습니다.
사실 이 내용은 kv 명령의 콜스택만 가만히 봐도 파악할 수 있는 사항입니다.

kd> kv
*** Stack trace for last set context - .thread/.cxr resets it
ChildEBP RetAddr Args to Child
f49097f4 f48bce5f 82c5cfe0 f490980c 81bd1740 MyDrv!my_strlen+0xd
f4909814 f48bcfa5 82c5cfe0 82c5cf00 f4909890 MyDrv!IsMyFilePath1+0xf
f490982c f48bd01d 82c5cfe0 00000000 f4909890 MyDrv!IsMyFilePath+0x15
f490984c f48bb10f 81bd1710 81bd1700 f4909890 MyDrv!CompFilePath+0x4d
f4909864 f46eb2ce 81bd1710 81bd1700 f4909890 MyDrv!MyDrv_CompFilePath+0x2f

각라인에서 세번째 보이는 값들이 첫번째 인자이므로 82c5cfe0 는 계속 첫번째 인자로
전달되었음을 알 수 있습니다. 이것을 시작한 녀석이 CompFilePath 라는 것도
보입니다. 이 함수의 내용을 보면

BOOL CompFilePath(IN LPCTSTR pszPath)
{
UINT nPathLen;
LPSTR pszPathA;
...
nPathLen = my_strlen(pszPath);
pszPathA = (LPSTR)my_malloc(nPathLen+4);
if (pszPathA)
{
UnicodeToAnsi(pszPath, pszPathA, nPathLen);
bRet = IsMyFilePath(pszPathA);
}
...
}

이 함수는 전달받았던 pszPath를 pazPathA 로 변환한 후에 하위함수들로 전달합니다.
두개의 내용을 비교해 봅니다.

kd> db 0x81bd1710
81bd1710 5c 00 44 00 65 00 76 00-69 00 63 00 65 00 5c 00 \.D.e.v.i.c.e.\.
81bd1720 48 00 61 00 72 00 64 00-64 00 69 00 73 00 6b 00 H.a.r.d.d.i.s.k.
81bd1730 56 00 6f 00 6c 00 75 00-6d 00 65 00 31 00 5c 00 V.o.l.u.m.e.1.\.
81bd1740 00 00 00 00 43 15 01 00-00 d4 01 00 71 10 01 00 ....C.......q...

kd> db 0x82c5cfe0
82c5cfe0 5c 44 65 76 69 63 65 5c-48 61 72 64 64 69 73 6b \Device\Harddisk
82c5cff0 56 6f 6c 75 6d 65 31 5c-c3 c3 c3 c3 c3 c3 c3 c3 Volume1\........
82c5d000 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????
82c5d010 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????

유니코드 문자열 일때는 NULL로 끝나는 것이 보이는데 ANSI 로 변환한 후에는 NULL
이 보이지 않습니다. 이렇게 되면 소스코드에서 보이는 변 환함수인 UnicodeToAnsi()
가 문제의 주범이라는 사실이 밝혀집니다. 왜 변환하면서 NULL을 붙이지 않는지
확인해 보면 이 덤프의 원인이 나오 게 됩니다.

덤프는 이렇게 분석이 끝났지만 위에서 보이는 문제의 메모리에서 c3 과 ?? 라는
내용에 대해서 조금 더 이해하고 있으면 좋을 것 같습니다.
!pool 명령으로 메모리를 살펴봅니다.

kd> !pool 82c5cfe0
Pool page 82c5cfe0 region is Special pool
*82c5cfe0 size: 1c pagable special pool, Tag is MDRV
Owning component : Unknown (update pooltag.txt)

Special pool 영역이라고 나옵니다.
Verifier 에서 Special Memory Pool 옵션을 켜야 BugCheck 0xD6가 발생한다고
이미 위에서 언급했습니 다. 이 Special Pool 이란 메모리 할당, 해제, 사용에
대한 버그를 잡기 위해서 특별히 사용되는 메모리 영역을 의미합니다.

Special Pool 은 메모리를 하나 할당할 때마다 최소 2 Page(4KB)를 사용 합니다.
첫번째 Page는 사용자가 사용하는 영역이고 두번째 Page는 Guard Page 입니다.
Invalid 한 메모리 영역을 지정해 놓고 만약 이곳 을 접근하게 되면 Fault 가
발생하도록 설정해 놓은 것입니다. 이것이 바로 ?? 로 나오는 부분의 의미입니다.

이번 예제도 NULL을 못찾은 코드가 계속 진행하여 이 Guard Page 에 접 근하면서
문제가 발견된 것입니다.

Speical Pool 은 사용자가 1c 만큼만 할당해도 실제로는 8KB 의 메모리 가 할당될
만큼 메모리 낭비가 심하기 때문에 Special Pool 로 예약된 영역을 모두 소진하면
Special Pool 에서 할당하지 않고 일반 메모리에 서 할당합니다. 물론 Special
Pool 이 여유가 생기면 다시 Special Pool 할당이 운영됩니다. 따라서 Special
Pool 이 항상 모든 문제를 체크할 수는 없다는 점도 참고하시기 바랍니다.

위에서 설명한 Special Pool 의 구조를 확인해 봅니다.
문제의 메모 리를 조금 당겨서 확인해 보면

kd> db 82c5cfe0 - 10
82c5cfd0 c3 c3 c3 c3 c3 c3 c3 c3-c3 c3 c3 c3 c3 c3 c3 c3 ................
82c5cfe0 5c 44 65 76 69 63 65 5c-48 61 72 64 64 69 73 6b \Device\Harddisk
82c5cff0 56 6f 6c 75 6d 65 31 5c-c3 c3 c3 c3 c3 c3 c3 c3 Volume1\........
82c5c000 ?? ?? ?? ?? ?? ?? ?? ??-?? ?? ?? ?? ?? ?? ?? ?? ????????????????

c3 으로 채워져 있고 Guard Page 가 나오기 전에 우리가 사용한 내용이 저장되어
있습니다. Guard Page 직전의 영역을 사용자에게 할당해서 Guard Page 가 효과를
보기 쉽도록 구성되어 있습니다. 사용자는 항상 첫번째 Page의 뒷부분을 기준으로
할당 받습니다.

이 메모리의 헤더는 첫 페이지의 맨 앞부분입니다.

kd> db 82c5c000
82c5c000 1c c0 c3 00 4d 44 53 56-00 00 00 00 08 4f f1 81 ....MDRV.....O..
82c5c010 c3 c3 c3 c3 c3 c3 c3 c3-c3 c3 c3 c3 c3 c3 c3 c3 ................
82c5c020 c3 c3 c3 c3 c3 c3 c3 c3-c3 c3 c3 c3 c3 c3 c3 c3 ................
82c5c030 c3 c3 c3 c3 c3 c3 c3 c3-c3 c3 c3 c3 c3 c3 c3 c3 ................

첫번째 바이트 1c 가 할당된 메모리 크기입니다.
두번째 바이트 c0 는 뭔지 모르겠네요.
세번째 바이트 c3 는 Page 를 채워놓는 값입니다. 82c5c010 ~ 82c5cfe0 모두 이 값
으로 채워져 있습니다. 이 값은 아마도 Verifier가 메모리가 깨진 것을 확인할 때
사용될 것입니다.
네번재 바이트부터 4바이트는 메모리 태그입니다.
그 뒤는 역시 뭔지 잘 모르겠 네요.
이 내용과 !pool 에서 출력된 결과를 보면 동일하다는 것을 알 수 있을 것입니다.

이렇게 해서 Special Pool 로 발생한 BugCheck와 Special Pool 에 대한 내용을
살펴봤습니다. 아주 유용한 Verifier와 Special Pool 모두 잘 활 용하시기 바랍니다.

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&GotoPage=6&s_bulu=&s_key=&no=26

Posted by GreeMate

[WinDbg 분석] BugCheck 0x50

덤프파일을 분석하는데 있어서 BugCheck Code는 아주 기본적인 정보일 뿐만아니라
분석을 풀어나가는 실마리가 됩니다. 그래서 누군가 BSOD 가 떴다고 문제를 풀어달라고
할 때 가장 먼저 물어 보게 되는게 "BugCheck Code 가 무엇입니까?" 가 되는 겁니다.

이제부터 여러가지 BugCheck Code 들에 대해서 기본적으로 어떻게 분석을 진행해
나가는지 예제를 통해서 설명하려고 합니다. BugCheck Code 마다 다소 다른점은
있지만 기본적인 맥락은 동일하다는 것을 곧 알게 될 것입니다. 기본적인 분석방법을
익혀서 BSOD 가 발생했을 때 당황하지 않고 스스로 문제의 원인을 찾고 해결할 수
있는 능력을 가지는 것이 중요합니다. WinDbg Help 에도 BugCheck Code 마다의
분석 방법 및 예제가 몇가지 있으므로 이것들을 확인하는 습관을 가지는 것도 좋습니다.

여기서는 기본적으로 개발한 모듈의 심볼(pdb파일)을 가지고 있다는 전제를 합니다.
심볼이 없다면 WinDbg 디버깅이 아주 갑갑해 지겠지요.

첫번째로 BugCheck 0x50 부터 시작합니다.
live debugging 시에 문제가 생기면 다음과 같이 시스템이 정지합니다.

*** Fatal System Error: 0x00000050
(0xE2BFD011,0x00000000,0xF2EF9C65,0x00000001)

Driver at fault:
*** mydrv.sys - Address F2EF9C65 base at F2E98000, DateStamp 44ed34b4
.
Break instruction exception - code 80000003 (first chance)

A fatal system error has occurred.
Debugger entered on first try; Bugcheck callbacks have not been invoked.

A fatal system error has occurred.

Connected to Windows XP 2600 x86 compatible target, ptr64 FALSE
Loading Kernel Symbols
...................................................................................................................
Loading User Symbols
PEB is paged out (Peb.Ldr = 7ffdf00c). Type ".hh dbgerr001" for details
Loading unloaded module list
.................
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

Use !analyze -v to get detailed debugging information.

BugCheck 50, {e2bfd011, 0, f2ef9c65, 1}

Probably caused by : mydrv.sys ( mydrv!My_strcmp+15 )

Followup: MachineOwner
---------

nt!RtlpBreakWithStatusInstruction:
804e5592 cc int 3

여기까지가 기본적으로 뿌려집니다.
안타깝게도 이 상태에서 더 뭘 해야할지 모르고 재부팅을 해 버리는 경우가 많은데요.
이때 문제의 원인을 정확히 파악하고 문제를 해결해야 합니다.

자... 덤프 분석의 초식 1장 나갑니다. "WinDbg 가 하라는 대로 따라하라!"

위에 이미 나온 메시지들을 주의깊게 살펴볼 필요가 있습니다.
WinDbg 가 많은 정보를 알려주고 있습니다. 그중에서 우리에게 하라고 하는 것을 눈여겨 보시기 바랍니다.

바로 이줄 입니다. => Use !analyze -v to get detailed debugging information.
단지 우리는 하라는대로 하면 됩니다. 특히 !analyze -v 는 모든 덤프분석에서 첫번째로 하게 되는 작업이
될테니 앞으로 우리는 자동적으로 이 명령을 내리게 될 것입니다. 하지만 그 이외에도 하라고 하는게 있는지
항상 살펴보시기 바랍니다.

이제 하라는대로 명령을 내려 봅니다.

kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************

PAGE_FAULT_IN_NONPAGED_AREA (50)
Invalid system memory was referenced. This cannot be protected by try-except,
it must be protected by a Probe. Typically the address is just plain bad or it
is pointing at freed memory.
Arguments:
Arg1: e2bfd011, memory referenced.
Arg2: 00000000, value 0 = read operation, 1 = write operation.
Arg3: f2ef9c65, If non-zero, the instruction address which referenced the bad memory
address.
Arg4: 00000001, (reserved)

Debugging Details:
------------------

READ_ADDRESS: e2bfd011 Paged pool

FAULTING_IP:
mydrv!My_strcmp+15 [d:\mytest\mydrv\my_string.c @ 179]
f2ef9c65 8a02 mov al,byte ptr [edx]

MM_INTERNAL_CODE: 1

IMAGE_NAME: mydrv.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 44ed34b4

MODULE_NAME: mydrv

FAULTING_MODULE: f2e98000 mydrv

DEFAULT_BUCKET_ID: DRIVER_FAULT

BUGCHECK_STR: 0x50

PROCESS_NAME: wuauclt.exe

TRAP_FRAME: f4674280 -- (.trap fffffffff4674280)
ErrCode = 00000000
eax=f2ee6f6c ebx=81cec900 ecx=e2bfd011 edx=e2bfd011 esi=81b1d3f8 edi=f4674634
eip=f2ef9c65 esp=f46742f4 ebp=f4674308 iopl=0 nv up ei ng nz na po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010282
mydrv!My_strcmp+0x15:
f2ef9c65 8a02 mov al,byte ptr [edx] ds:0023:e2bfd011=??
Resetting default scope

LAST_CONTROL_TRANSFER: from 8053425b to 804e5592

STACK_TEXT:
f4673dd0 8053425b 00000003 e2bfd011 00000000 nt!RtlpBreakWithStatusInstruction
f4673e1c 80534d2e 00000003 806f0298 c038aff4 nt!KiBugCheckDebugBreak+0x19
f46741fc 8053531e 00000050 e2bfd011 00000000 nt!KeBugCheck2+0x574
f467421c 80525f44 00000050 e2bfd011 00000000 nt!KeBugCheckEx+0x1b
f4674268 804e3718 00000000 e2bfd011 00000000 nt!MmAccessFault+0x6f5
f4674268 f2ef9c65 00000000 e2bfd011 00000000 nt!KiTrap0E+0xcc
f4674308 f2ee82d3 e2bfd011 f2ee6f6c 00000000 mydrv!My_strcmp+0x15 [d:\mytest\mydrv\my_string.c @ 179]
f467435c f2ee709a e2909008 f2f1af04 e1196008 mydrv!My_Func3+0x323 [d:\mytest\mydrv\my_func3.c @ 78]
f467439c f2f09c01 e22088d8 e24d5418 00000000 mydrv!My_Func2+0x109 [d:\mytest\mydrv\my_func2.c @ 24]
f46743c0 f2f09b6a e22088d8 e24d5418 00000001 mydrv!My_Func1+0x91 [d:\mytest\mydrv\my_func1.c @ 118]
...
f4674c88 805964bf e1efa000 00080000 81d57020 nt!CcPfPrefetchScenario+0x7b
f4674d04 805831af 81d57020 e254f158 00000000 nt!CcPfBeginAppLaunch+0x158
f4674d50 804fc4da 00000000 7c810665 00000001 nt!PspUserThreadStartup+0xeb
00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

STACK_COMMAND: kb

FOLLOWUP_IP:
mydrv!My_strcmp+15 [d:\mytest\mydrv\my_string.c @ 179]
f2ef9c65 8a02 mov al,byte ptr [edx]

FAULTING_SOURCE_CODE:
   175:
   176: int My_strcmp( const char* cs, const char* ct )
   177: {
   178: #ifdef HAVE_STRCMP
> 179: return strcmp( cs, ct );
   180: #else
   181: int res;
   182:
   183: for( ; ; )
   184: {

SYMBOL_STACK_INDEX: 6

SYMBOL_NAME: mydrv!My_strcmp+15

FOLLOWUP_NAME: MachineOwner

FAILURE_BUCKET_ID: 0x50_VRF_mydrv!My_strcmp+15

BUCKET_ID: 0x50_VRF_mydrv!My_strcmp+15

Followup: MachineOwner
---------

길게도 분석결과가 나왔습니다.
메시지를 처음부터 살펴보면 이 버그체크는 PAGE_FAULT_IN_NONPAGED_AREA 라는 것을 알려주고
이것은 잘못된 시스템 메모리를 참조해서 발생한 것이라고 친절하게 설명해 주고 있습니다.

앞으로 모든 덤프를 분석할 때 반드시 이 설명 문구를 읽으시기 바랍니다. 어떤 문제 때문에 발생한
것이고 심지어는 어떻게 분석하라는 내용까지 있는 경우도 있습니다. 그리고 WinDbg 가 업그레이드
될 때마다 메시지의 내용이 더더욱 심오해 집니다. 더 자세하게 기술되어 분석하기가 쉬워집니다.

이 내용을 읽었는데 여기서 하라는 것이 있으면 그대로 하면 됩니다. 이번 예제에서는 하라는 것은 없네요.
계속해서 전체적인 내용을 살펴봅니다.

친절하게도 콜스택까지 잘 보여주고 있습니다. 운이 좋으면 이 콜스택만 봐도 무슨 문제인지
금방 알 수도 있습니다. 하지만 이번에는 그런 경우는 아닌 것 같습니다. 좀 더 보도록 합시다.

최신 WinDbg 에서는 문제가 발생한 소스코드를 보여주는 기능이 추가되었습니다.
FAULTING_SOURCE_CODE 에서 보이고 있습니다. 역시 운이 좋으면 여기만 봐도 문제가 뭔지 알 수 있겠지요?

strcmp 에서 죽었는데 cs 에서 죽은건지 ct 에서 죽은건지 모르겠네요.
좀 더 분석해 봐야 할 것 같습니다.

메시지 중간에 다음과 같은 라인이 있습니다.
TRAP_FRAME: f4674280 -- (.trap fffffffff4674280)

앞으로 이와 같은 라인이 보이면 무조건 .trap fffffffff4674280 명령을 실행하기 바랍니다.

kd> .trap fffffffff4674280
ErrCode = 00000000
eax=f2ee6f6c ebx=81cec900 ecx=e2bfd011 edx=e2bfd011 esi=81b1d3f8 edi=f4674634
eip=f2ef9c65 esp=f46742f4 ebp=f4674308 iopl=0 nv up ei ng nz na po nc
cs=0008 ss=0010 ds=0023 es=0023 fs=0030 gs=0000 efl=00010282
mydrv!My_strcmp+0x15:
f2ef9c65 8a02 mov al,byte ptr [edx] ds:0023:e2bfd011=??

콜스택을 보면서 설명하면 strcmp 에서 문제가 발생했을 때 시스템은 Trap 을 발생시켰고
OS 가 Trap 을 핸들링하면서 결국 BugCheck 를 호출하고 시스템이 죽은 겁니다.
.trap 명령을 수행하기 전에 WinDbg 에 보이는 레지스터 값들을 보면 RtlpBreakWithStatusInstruction
를 호출했을 때의 값들이 보여지고 있습니다. 이것은 strcmp 에서 문제가 발생했을 때의
레지스터 값들이 아니므로 문제를 분석하는데 전혀 도움이 되지 않습니다. strcmp 에서 문제가
발생했을 때의 레지스터 값들은 Trap 이 발생하면서 Trap Frame 에 저장되었고 .trap 명령을 사용하면
trap 이 발생한 시점의 상황으로 레지스터 값들을 돌려줍니다. 친절하게 명령과 파라미터까지
보여주니 그대로 실행해 주면 되는 겁니다.

이렇게 하면 콜스택이 문제가 발생했을 때의 상황으로 정리됩니다.
k 명령을 사용해서 콜스택을 다시 봅니다.

kd> kn
*** Stack trace for last set context - .thread/.cxr resets it
# ChildEBP RetAddr
00 f4674308 f2ee82d3 mydrv!My_strcmp+0x15 [d:\mytest\mydrv\my_string.c @ 179]
01 f467435c f2ee709a mydrv!My_Func3+0x323 [d:\mytest\mydrv\my_func3.c @ 78]
02 f467439c f2f09c01 mydrv!My_Func2+0x109 [d:\mytest\mydrv\my_func2.c @ 24]
03 f46743c0 f2f09b6a mydrv!My_Func1+0x91 [d:\mytest\mydrv\my_func1.c @ 118]
...

n 옵션을 사용한 이유는 맨 앞에 스택 프레임 번호를 보이기 위함입니다. 나중에 k 명령 설명에서
자세하게 다루기로 하구요.

실제 디버깅 할 때는 콜스택 창에 위의 내용이 보이고 있을 것이고 첫번째 줄을 더블클릭하면
소스도 나타나고 지역변수 창에 변수들도 나올 텐데, 저는 지금 command 창에서만 설명해야 하니
여러가지 명령을 동원하게 되었습니다. MS 본사의 디버깅 고수들은 command 창 하나만 띄워놓고
현란한 명령어들로 디버깅하기도 합니다. 그걸 따라하고 싶어서 이러는 건 아닙니다. ^^

여하튼 저는 command 로 지역변수를 보고 싶습니다.
일단 스택 프레임을 첫번째 스택 라인에 맞춰 놓으려 합니다. 스택 프레임 번호가 00 이죠.
.frame 명령을 사용해서 스택 프레임을 변경합니다.

kd> .frame 0
00 f4674308 f2ee82d3 mydrv!My_strcmp+0x15 [d:\mytest\mydrv\my_string.c @ 179]

그리고 나서 지역변수를 보이는 dv 명령을 사용하면 이 함수가 호출되었을 때의 지역변수를 볼 수 있습니다.

kd> dv
cs = 0xe2bfd011 ""
ct = 0xf2ee6f6c "GetFileAttributesA"

이제 cs와 ct 가 뭔지 알 수 있습니다.

이렇게 찾고 보면 처음에 BugCheck에서 보여줬던 첫번째 값이 바로 cs 였다는 것을 알게 됩니다.
문제의 잘못된 메모리는 cs 라는 것입니다.

BugCheck 50, {e2bfd011, 0, f2ef9c65, 1}
Arguments:
Arg1: e2bfd011, memory referenced.
Arg2: 00000000, value 0 = read operation, 1 = write operation.

잘못된 메모리 e2bfd011 을 읽다가 죽었다는 뜻이었군요.

이렇게 되면 My_strcmp 함수는 혐의를 벗어나게 됩니다. 잘못된 메모리를 전달받은 죄 밖에 없거든요.
잘못된 메모리를 전달한 녀석이 문제지요. My_strcmp 를 호출한 녀석을 분석해야 합니다.
스택 프레임이 01 이군요.

kd> .frame 1
01 f467435c f2ee709a mydrv!MyFunc3+0x323 [d:\mytest\mydrv\my_func3.c @ 78]

지역변수도 보고 소스코드도 봅니다.

kd> dv
pNameStrBuffer = 0xe2bf8008
dwNameStr = 0x4ffd
pNameStr = 0xe2bfd011 ""
nFound = 0
j = 0

*** 소스코드 ***
pNameStr = (char*)pNameStrBuffer->abyData + dwNameStr;

nFound = 0;
for( j = 0; j < nNumOfFunctions; j++ )
{
if ( My_strcmp( pNameStr, ppNames[j] ) == 0 )

My_strcmp의 첫번재 파라미터는 pNameStr 입니다. 이게 문제구요.
호출하기 직전에 pNameStr 을 계산하는 것을 볼 수 있습니다. 이 계산이 뭐가 잘못된 것일까요?
결국 abyData + dwNameStr 의 결과가 e2bfd011 이라는 잘못된 메모리라는 뜻입니다.

abyData 를 살펴보기 위해 pNameStrBuffer 의 구조체 타입을 찾아서 살펴봅니다.
dt 명령은 구조체를 확인할 때 사용합니다. 역시 나중에 dt 명령 설명에서 자세히 다루도록 하구요.

kd> dt _MYNAMEBUFFER 0xe2bf8008
   +0x000 dwPos    : 0
   +0x004 ulFp : 0
   +0x008 nLen : 0x140000
   +0x00c abyData    : [1024] "???"

이렇게 보니 문제가 드러납니다.

abyData 는 1024 바이트의 공간만 존재하는데 dwNameStr(0x4ffd) 만큼 더한 뒤에 있는 영역은
이 범위를 벗어나는 잘못된 메모리인 것입니다.

정확한 원인을 밝혀내기 위해서는 dwNameStr 에 왜 0x4ffd 와 같은 터무니 없는 값이
들어갔는지를 알아야 합니다. 그것은 더 상위 함수를 분석해 본다던가 소스코드를 살펴본다던가
해서 추가로 진행하면 될 것입니다.

여기까지 분석한 방법을 응용하면 여러분들도 BugCheck 0x50 을 어렵지 않게 분석할 수 있을 것입니다.

이 첫번째 예제를 설명하면서 제가 강조하고 싶은 부분은 WinDbg 메시지 내용 중에는 분석에 사용할 수
있는 명령어들이 존재하고 있다는 점입니다. 이것들을 눈여겨 보고 적절히 사용하면 분석에 많은 도움이
되므로 십분 활용하시기 바랍니다.

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&GotoPage=6&s_bulu=&s_key=&no=24

Posted by GreeMate

[WinDbg 분석] BugCheck 0x19 (원인분석불가능)

BugCheck 0x19 의 또 다른 형태를 살펴보면서 메모리풀 관리에 대한 내용을 조금 더 깊게 확인해 보겠습니다. 좀처럼 풀리지 않는 메모리 깨짐 문제를 삽질하다 보니 커널의 메모리 할당/해제 방식을 살펴보게 되었습니다.
오늘은 커널이 small memory pool 을 어떻게 관리하는지에 대한 내용을 설명하게 될 것입니다.

kd> !analyze -v
****************************************************************************
*    *
*    Bugcheck Analysis *
*    *
****************************************************************************

BAD_POOL_HEADER (19)
The pool is already corrupt at the time of the current request.
This may or may not be due to the caller.
The internal pool links must be walked to figure out a possible cause of
the problem, and then special pool applied to the suspect tags or the driver
verifier to a suspect driver.
Arguments:
Arg1: 00000020, a pool block header size is corrupt.
Arg2: 8614b6c2, The pool entry we were looking for within the page.
Arg3: 8614b6ca, The next pool entry.
Arg4: 0a010000, (reserved)

Debugging Details:
------------------

BUGCHECK_STR: 0x19_20
POOL_ADDRESS: 8614b6c2 Nonpaged pool
DEFAULT_BUCKET_ID: DRIVER_FAULT
PROCESS_NAME: System

LAST_CONTROL_TRANSFER: from 8054d741 to 8053531e

STACK_TEXT:
f7a29928 8054d741 00000019 00000020 8614b6c2 nt!KeBugCheckEx+0x1b
f7a29978 8054d0b9 8614b6ca 00000000 f7a29994 nt!ExFreePoolWithTag+0x2be
f7a29988 a9f45c5f 8614b6ca f7a299a0 a9f43530 nt!ExFreePool+0xf
WARNING: Stack unwind information not available. Following frames may be wrong.
f7a29994 a9f43530 85629ae0 f7a299b0 a9f435b7 MyDrv+0xbc5f
f7a299a0 a9f435b7 85960418 85960418 f7a299c8 MyDrv+0x9530
f7a299b0 a9f42c05 85960418 00000000 85960418 MyDrv+0x95b7
f7a299c8 a9f40362 f7a299e0 856a866c 00000000 MyDrv+0x8c05
...

STACK_COMMAND: kb

FOLLOWUP_IP:
MyDrv+bc5f
a9f45c5f 8b4d08 mov ecx,dword ptr [ebp+8]

SYMBOL_STACK_INDEX: 3
SYMBOL_NAME: MyDrv+bc5f
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: MyDrv
IMAGE_NAME: MyDrv.sys

DEBUG_FLR_IMAGE_TIMESTAMP: 4501c758
FAILURE_BUCKET_ID: 0x19_20_MyDrv+bc5f
BUCKET_ID: 0x19_20_MyDrv+bc5f

Followup: MachineOwner
---------

지난 번에 봤던 BucCheck 0x19 입니다.
콜스택에서 ExFreePool 을 호출할 때 전달한 메모리 주소는 아래와 같이 8614b6ca 입니다.

f7a29988 a9f45c5f 8614b6ca f7a299a0 a9f43530 nt!ExFreePool+0xf

메시지에서 Arg2 를 보면 문제의 순간에 다루던 메모리 주소를 볼 수 있습니다.
Arg2: 8614b6c2, The pool entry we were looking for within the page.

ExFreePool 에 전달된 메모리 주소에서 8을 뺀 값이죠. ( 8614b6c2 = 8614b6ca - 8 )
8614b6c2 는 8614b6ca 메모리 영역의 헤더 영역입니다.
메모리 할당도 실제로는 여기부터 시작되는거구요.

일단 해제되는 메모리 8614b6ca 를 확인해 봅니다.

kd> !pool 8614b6ca
Pool page 8614b6ca region is Nonpaged pool
... ...
8614b520 size: 58 previous size: 58 (Allocated) RBev
8614b578 size: f8 previous size: 58 (Allocated) Driv
8614b670 size: 18 previous size: f8 (Free) HidU
8614b688 size: 28 previous size: 18 (Free ) NtFs
*8614b6b0 size: 28 previous size: 28 (Allocated) *NtFs
Pooltag NtFs : StrucSup.c, Binary : ntfs.sys
8614b6d8 is not a valid small pool allocation, checking large pool...
unable to get pool big page table - either wrong symbols or pool tagging is disabled
8614b6d8 is freed (or corrupt) pool
Bad previous allocation size @8614b6d8, last size was 5

***
*** An error (or corruption) in the pool was detected;
*** Attempting to diagnose the problem.
***
*** Use !poolval 8614b000 for more details.
***

Pool page [ 8614b000 ] is __inVALID.

Analyzing linked list...
[ 8614b6b0 --> 8614b730 (size = 0x80 bytes)]: Corrupt region

Scanning for single bit errors...
None found

지난 번과 뭐가 다른 것을 느끼셨나요?
다시 한번 잘 보시기 바랍니다. 뭘까요???

!pool 명령어의 리스트에는 제가 입력한 8614b6ca 의 헤더주소인 8614b6c2 가 존재하지 않습니다.
잘 보시면 8614b6c2 는 8614b6b0 ~ 8614b6d8 사이에 존재하는 메모리 주소인 것을 알 수 있습니다.

*8614b6b0 size: 28 previous size: 28 (Allocated) *NtFs
Pooltag NtFs : StrucSup.c, Binary : ntfs.sys
8614b6d8 is not a valid small pool allocation, checking large pool...

NTFS 가 사용중인 영역으로 나오는데요...
이게 어떤 상황인지 이해하는 것은 사실 쉽지 않습니다.

지난 번에 문제가 된 메모리 주소는 !pool 에서 나오는 리스트 중의 하나였고 이것은 커널에 의해서
정상적으로 할당된 메모리였습니다. 하지만 이번 경우는 !pool 리스트에 존재하는 메모리
주소가 아니기 때문에 커널에서 정상적으로 할당받은 것인지 아닌지 아리송 합니다. ^^

하지만 일단 ExFreePool 에 해제하라고 전달한 포인터이기 때문에 ExAllocatePool 에서
할당받은 포인터였을 거라고 인정하는게 좋을 것 같습니다.

그.렇.다.면...

어떻게 해서 저런 메모리주소가 ExAllocatePool 에서 나올 수 있었던 걸까요?
잘 보시면 정상적으로 할당된 메모리 주소는 모두 0 아니면 8 로 끝나는 형태를 가집니다.
하지만 문제의 메모리 주소는 8614b6ca 이므로 a로 끝납니다.

이런 일이 어떻게 있을 수 있을까 고민하다가 ExAllocatePoolWithTag와 ExFreePoolWithTag 를
분석하기에 이르렀습니다. -_-;;;

제가 알고 싶은 Small Pool 의 NonPagedPool 할당에 대한 부분만 집중해서 분석하고 나머지는 대충 무시했습니다. (Large Pool 이라는 것도 있죠? 이건 어떻게 동작하는지 아직 잘 모르겠습니다. 누가 좀... ^^)

ExAllocatePoolWithTag 과 ExFreePoolWithTag 의 pseudo 코드는 다음과 같습니다.

ExAllocatePoolWithTag(type, size, tag)
{
...
// size 에 헤더크기를 포함하여 8 byte 단위로 가리킬 수 있는 index를 만든다.
index = (size + f) / 8

// ProcessorBlock 주소를 구한다.
eax = ffdff120h

// ProcessorBlock 의 FreeNonPagedPoolList(598h옵셋) 에서 index에 해당하는 Head 를 구한다.
edi = eax + (index * 8) + 598h

// FreeNonPagedPoolList 에서 하나를 꺼낸다.
esi = ExInterlockedPopEntrySList(edi , ...)

// 헤더를 참조하게 한다.
esi = esi - 8

// 헤더+4 태그영역에 태그를 복사한다.
[esi+4] = tag

// 메모리 주소를 참조하게 한다.
eax = esi + 8

// 메모리 주소를 리턴한다.
return eax
...
}

ExFreePoolWithTag(ptr, tag)
{
...

// 헤더+2 에 저장된 index 를 구한다. (index * 8 은 실제 메모리 영역의 크기)
index = word ptr [ptr-6]
...

// ProcessorBlock 의 FreeNonPagedPoolList(598h옵셋) 에서 index에 해당하는 Head 를 구한다.
ebx = eax + (index * 8) + 598h

// FreeNonPagedPoolList 에 넣는다.
InterlockedPushEntrySList(ebx, ptr)

// ptr 에는 NextLink 주소가 기록된다.
...
}

이 분석을 통해 알게된 사실은 커널이 메모리 할당/해제를 효율적으로 운영하기 위해서 FreeList
를 관리한다는 점이었습니다. 해제되는 메모리는 같은 크기를 가지는 FreeList 에 넣어놓고 할당
요청이 오면 같은 크기의 FreeList 에서 바로 꺼내오는 방식으로 관리하는 것입니다.

이 FreeList 는 ffdff120h + 598h 에 위치하는데 ffdff120 의 의미가 궁금해져서 구글링을 좀 해보니 다음과 같이 KiProcessorBlock 이라는 커널 전역변수에 저장된 값이라는 것을 알게 되었습니다. 대부분 시스템에서 ffdff120h 로 같은 값을 가지고 있었습니다.

kd> dd KiProcessorBlock
8055b320 ffdff120 00000000 00000000 00000000
8055b330 00000000 00000000 00000000 00000000

계속해서 ffdff120h + 598h 에 위치한 FreeNonPagedPoolList 을 좀 더 자세히 살펴봅니다.

kd> dd ffdff120 + 598 + (0*8)
ffdff6b8 00000000 00000000 863b1000 80557000
ffdff6c8 863b1100 80557080 863b1200 80557100
ffdff6d8 863b1300 80557180 863b1400 80557200
ffdff6e8 863b1500 80557280 863b1600 80557300
ffdff6f8 863b1700 80557380 863b1800 80557400
ffdff708 863b1900 80557480 863b1a00 80557500
ffdff718 863b1b00 80557580 863b1c00 80557600
ffdff728 863b1d00 80557680 863b1e00 80557700

계산방식으로 볼때 8 바이트 단위로 배열되어 있는 것으로 보입니다.
여기서 863b1000, 863b1100, 863b1200, 863b1300 등은 index 1, 2, 3, 4 일 때 참조되는 값이고
이것을 Head 로 사용해서 실제 메모리를 링크드 리스트로 연결합니다.

예를 들어 863b1100 을 살펴보면

kd> dd 863b1100 L1
863b1100 855a6380

다음 링크 주소가 있으므로 dl 명령으로 다시 봤습니다.

kd> dl 863b1100
863b1100 855a6380 73500002 01000004 0009c075
855a6380 854ae808 85fea128 0a150002 e56c6946
854ae808 00000000 85e9c128 0a050002 7346744e

두개의 링크가 존재하네요.

어디선가 index 2 (헤더크기를 포함한 메모리크기 9 ~ 16) 에 해당하는 할당을 요청하면 ExAllocatePoolWithTag 는 855a6380 을 바로 꺼내서 리턴해 줍니다.

855a6380 의 헤더를 보면

kd> db 855a6380 - 8
855a6378 01 00 02 02 54 43 49 31-08 e8 4a 85 28 a1 fe 85 ....TCI1..J.(...
855a6388 02 00 15 0a 46 69 6c e5-70 00 00 00 e8 00 00 00 ....Fil.p.......

세번째 바이트인 size(사실은 index) 에 02 가 정확히 적혀 있습니다.
다음 링크인 854ae808 도 헤더를 보면 size 02 가 명확히 보입니다.

kd> db 854ae808 - 8
854ae800 01 00 02 02 54 43 49 31-00 00 00 00 28 c1 e9 85 ....TCI1....(...
854ae810 02 00 05 0a 4e 74 46 73-01 00 00 00 74 0a 7b aa ....NtFs....t.{.

즉, 같은 크기의 해제된 메모리 블럭 리스트라는 것을 확인한 것입니다.
재미있는 점은 메모리가 Free 되면 ExFreePoolWithTag 안에서

// FreeNonPagedPoolList 에 넣는다.
InterlockedPushEntrySList(ebx, ptr)

가 수행되는 바람에 ptr 의 내용은 사용자가 사용하던 데이터가 지워지고 NextLink 주소로
변경된다는 점입니다. 이 내용은 주목할 만한 부분이므로 잠시 기억해 두시기 바랍니다.

여하튼 전체적인 이해를 돕기위해 위 내용을 대강 그림으로 표현하면 다음과 같습니다.

ProcessorBlock( ffdff120 )
|-------------------------------|
| 0h ... |
| .    ... |
| .    ... |
| .    ... | ListHead NextLink NextLink
| 598h FreeNonPagedPoolList[x] | [0]-> 00000000
| .    ... | [1]-> 863b1000->xxxxxxxx->xxxxxxxx ( size 1~8 )
|-------------------------------| [2]-> 863b1100->855a6380->854ae808 ( size 9~16 )
[3]-> 863b1200->xxxxxxxx->xxxxxxxx ( size 17~24 )

이 ProcessorBlock 의 내용은 다음과 같이 확인할 수 있습니다.

kd> dt nt!_KPRCB ffdff120
   +0x000 MinorVersion : 1
   +0x002 MajorVersion : 1
   +0x004 CurrentThread    : 0x863b5b30 _KTHREAD
   +0x008 NextThread : (null)
   +0x00c IdleThread : 0x8055ac20 _KTHREAD
.    ...
.    ...
   +0x520 PPLookasideList : [16] _PP_LOOKASIDE_LIST
   +0x5a0 PPNPagedLookasideList : [32] _PP_LOOKASIDE_LIST
   +0x6a0 PPPagedLookasideList : [32] _PP_LOOKASIDE_LIST
.    ...
.    ...

제가 FreeNonPagedPoolList 라고 표현했던 필드의 이름이 실제로는 PPNPagedLookasideList 였네요.
이 리스트의 시작도 실제로는 0x5a0 (0x598 + 8) 이구요. 왜 Disassembly 상에서는 598h 를 기준으로 계산하는지는 잘 모르겠습니다. 그리고 그 밑에 PPPagedLookasideList 도 보입니다. PagedPool 도 같은 방식으로 관리된다는 것을 알 수 있습니다.

_PP_LOOKASIDE_LIST 구조체가 어떤 구조를 가지는지 살펴볼까요?

kd> dt _PP_LOOKASIDE_LIST
+0x000 P : Ptr32 _GENERAL_LOOKASIDE
+0x004 L : Ptr32 _GENERAL_LOOKASIDE

이중에서 P 에 해당하는 영역만 위에서 설명한 거네요.
L 은 어떤 용도인지 궁금하지만 더 이상 알아보지는 않았습니다.

이제야 메모리 할당/해제가 어떻게 이루어 지는지 이해했습니다.
다시 원래 문제로 돌아가서 8614b6ca 라는 주소가 어떻게 할당된 것인지 생각해 봅니다.

흠...
아무리 생각해도 말이 안되네요.

누군가 ExAllocatePoolWithTag 를 호출했을 때 8614b6ca 같은 비정상적인 값이 리턴되려면
FreeNonPagedPoolList 에 이미 8614b6ca 가 들어 있었어야 합니다.
어떻게 이런 일이 가능할까요?

이제부터는 추리소설입니다. ^^
첫번째 가정은 누군가가 ExFreePoolWithTag 를 호출할 때 8614b6ca 를 파라미터로 넘기는 겁니다.
그러면 ExFreePoolWithTag 내부의 코드에서 이것을 FreeNonPagedPoolList 에 넣게 되는거죠.
그 다음 누군가가 ExAllocatePoolWithTag 를 호출했을 때 이것이 꺼내지게 되구요.

이 가정을 검증하기 위해서 디버거로 ExFreePoolWithTag 의 파라미터를 강제로 xxxxxxx2나 xxxxxxxa
와 같은 이상한 값으로 변경해서 호출해 보았습니다. 하지만 안타깝게도 내부에서 헤더체크를
하는 코드에 걸려서 이런저런 BugCheck 를 띄우는 것만 확인되었습니다.

생각보다 헤더체크를 열심히 하더라구요.
헤더영역까지 조작하여 체크를 피하도록 조작한다면 무사히 FreeNonPagedPoolList 에 안착할 수도
있을 것 같았습니다. 하지만 일일이 그것을 맞춰주는 노가다는 하지 않았습니다.

그래서 만약 누군가가 잘못된 포인터 xxxxxxx2 나 xxxxxxxa 을 넣었는데 우연히 체크에 걸리지 않게
헤더의 데이터가 들어있었다면 이것이 FreeNonPagedPoolList 에 들어가면서 나중에 문제를 일으킬
것이라는 가정입니다.

이런 상황이었다면 누군가가 최초에 잘못된 포인터 xxxxxxx2 나 xxxxxxxa 를 ExFreePool 에 넣는 순간을 잡으면 될 것 같습니다.

그래서 생각한 것이 조건 브레이크 포인트 입니다.
ExFreePoolWithTag 에 브레이크 포인트를 걸되 조건은 포인터가 0 또는 8 로 끝나는 경우는 그냥 지나보내고 그렇지 않은 경우는 세우는 겁니다.

kd> bp nt!ExFreePoolWithTag "j (poi(esp+4) & 3) ' ' ; 'gc' "

esp+4 는 첫번째 파라미터인 해제하려는 메모리 주소이고 이것을 3 으로 마스킹하면 0 또는 8 이 아닌 경우에만 0 이 아닌 값이 나옵니다.

이렇게 하면 잡힐 것 같기는 하지만 시스템이 많이 느려지더군요. -_-;;;
문제가 발생할 때까지 너무 오래 기다려야 할 것 같다는...

게다가 곰곰히 생각해 보니 자기가 p = ExAllocatePool() 과 같이 할당받은 메모리 포인터에 p = p+2
같은 행위를 하고 ExFreePool(p) 를 호출하는 막되먹은 코드는 아무래도 존재하기 힘들것 같습니다.
그래서 다른 생각을 해보면...

두번째 가정은 누군가가 스스로 해제한 메모리를 계속 사용하면서 FreeNonPagedPoolList 를 깨먹는 겁니다.
위에서 주목할 만한 부분이라고 기억하자고 한 내용이 있었죠?
우리가 ExFreePoolWithTag 로 해제한 메모리는 이후에 절대로 건드려서는 안됩니다.
왜냐하면 이 메모리는 사라지는 것이 아니라 위에서 본 것처럼 리스트에 들어가서 관리되기 때문입니다.

우리가 사용하던 메모리 주소가 855a6380 였다고 가정하면 ExFreePoolWithTag 를 호출하는 순간 우리가 사용하던 메모리 시작영역(855a6380 부터 4바이트)에 NextLink의 주소가 저장됩니다.
이 링크 정보는 커널의 메모리 관리 구조에서 매우 중요한 부분입니다. 이것이 깨지면 메모리 할당에서 엉뚱한 주소가 나가기 시작하겠죠.

다시 한번 강조합니다. ExFreePool 로 해제한 메모리 주소는 절대로 사용하면 안됩니다.
사용하는 순간 BSOD 를 예약해 놓는 꼴이 됩니다. 시한폭탄이죠.

어느 가정이 맞을까요?
아무래도 프로그래밍 실수라고 하면 두번째 가정이 가능성이 더 높겠네요.
아니면 아무런 규칙성없이 무작위로 깨먹는 녀석에 의해서 우연히 FreeNonPagedPoolList 가 깨지는 것일 수도 있겠죠.

결국 추측만 하고 원인은 찾을 수 없었습니다. OTL

http://www.driveronline.org/bbs/view.asp?tb=tipbbs&no=84

Posted by GreeMate

GreeMate의 끄적끄적

'BugCheck'에 해당되는 글 10건

[WinDbg 분석] BugCheck 0xC4-60

[WinDbg 분석] BugCheck 0xCE

[WinDbg 분석] BugCheck 0x7F

[WinDbg 분석] BugCheck 0xA (분석가능)

[WinDbg 분석] BugCheck 0xA (분석불가능)

[WinDbg 분석] BugCheck 0x19

[WinDbg 분석] BugCheck 0xC1

[WinDbg 분석] BugCheck 0xD6

[WinDbg 분석] BugCheck 0x50

[WinDbg 분석] BugCheck 0x19 (원인분석불가능)

카테고리

공지사항

태그목록

최근에 올라온 글

최근에 달린 댓글

글 보관함

달력

링크

티스토리툴바

« » 2024.4
일	월	화	수	목	금	토
	1	2	3	4	5	6
7	8	9	10	11	12	13
14	15	16	17	18	19	20
21	22	23	24	25	26	27
28	29	30