GreeMate의 끄적끄적

덤프분석보다는 live debugging 중에 종종 사용하는 명령어들을 설명합니다.

.reboot (Reboot Target Computer)

커널디버깅을 하다가 시스템을 재부팅하고 싶을 때 사용합니다.
.reboot 명령어만 입력하면 아래와 같이 바로 재부팅 됩니다.

kd> .reboot
Shutdown occurred...unloading all symbol tables.
Waiting to reconnect...

.crash (Force System Crash)

커널디버깅을 하다가 현재 상태를 덤프파일로 남기고 싶을 때 사용합니다.
.crash 명령어만 입력하면 아래와 같이 덤프를 만들고 바로 재부팅 됩니다.

kd> .crash
Shutdown occurred...unloading all symbol tables.
Waiting to reconnect...

만들어지는 덤프파일은 시스템의 설정에 따라갑니다. (미니덤프 or 커널덤프 or 전체덤프)
그리고 생성되는 덤프파일의 BugCheck 코드는 BugCheck 0xE2(MANUALLY_INITIATED_CRASH)입니다.

.dump (Create Dump File)

커널모드에서는 시스템을 죽이지 않고 덤프파일을 생성하고 싶을 때 사용합니다.
유저모드에서는 프로세스를 죽이지 않고 덤프파일을 생성하고 싶을 때 사용합니다.

커널모드나 유저모드나 /f 옵션을 주면 전체덤프를 생성합니다.
세부적인 다양한 옵션이 있지만 저 같은 경우 무조건 다 들어있는 /f 만 사용합니다.
나머지는 모릅니다. ^^

다음은 커널모드에서 실행한 예입니다.

kd> .dump /f c:\temp\nocrash.dmp
Creating a full kernel dump over the COM port is a VERY VERY slow operation.
This command may take many HOURS to complete.  Ctrl-C if you want to terminate the command.
Creating c:\temp\nocrash.dmp - Full kernel dump
Percent written 0
Percent written 1
Percent written 2
Percent written 3
...

Serial 로 연결했더니 너무 느려서 중간에 끊었습니다. -_-;;;
1394 로 연결하면 시간이 많이 걸리지 않습니다.

유저모드에서 전체덤프를 생성할 때는 /f 옵션보다 /ma 가 조금 더 많은 정보가 있다고 권장하네요.

0:000> .dump /ma c:\temp\ie.dmp
Creating c:\temp\ie.dmp - mini user dump
Dump successfully written

mini dump 라고 나오지만 full dump 보다 크기도 크고 정보도 좀 더 들어간다고 합니다.

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

Jeff 님의 예제를 그대로 들고와서 손을 좀 봤습니다.
그렇게라도 시작하니 일단 감은 좀 잡겠더라구요.

메모리 4GB 를 장착한 시스템에서 덤프를 받았는데 덤프상에서 물리 메모리 2GB 위쪽의 데이터는 덤프파일에 포함되지 않는 것 같아서 이것을 검증해 보고 싶었습니다. 물리 메모리 2GB 위쪽 전체를 뒤지는 방법으로... -_-;;; 물론 노가다는 스크립트가 합니다. ^^

스크립트 testmem.txt 는 다음과 같습니다.
물리주소 80000000 부터 ffffffff 까지 4000 씩 더해 가면서 살펴보는 스크립트입니다.

$$ WinDbg script to get data above 2GB of physical memory in complete memory dump
r $t0 = 0
.for (r $t0 = 80000000; (@$t0 < ffffffff ); r $t0 = @$t0 + 4000)
{
    dc /p @$t0
}

출력은 다음과 같습니다.

3: kd> $$><myscript\testmem.txt
Last set context:
Last set context:
80000000  ???????? ???????? ???????? ????????  ????????????????
Last set context:
80010000  ???????? ???????? ???????? ????????  ????????????????
...

8ffb0000  ???????? ???????? ???????? ????????  ????????????????
Last set context:
8ffc0000  ???????? ???????? ???????? ????????  ????????????????
Last set context:
...

fffe0000  ???????? ???????? ???????? ????????  ????????????????
Last set context:
ffff0000  ???????? ???????? ???????? ????????  ????????????????
Last set context:

살펴본 메모리들이 전혀 존재하지 않음을 간단하게 확인할 수 있었답니다.

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

메모리릭과 마찬가지로 핸들릭도 원인을 찾기 어려운 문제중 하나입니다.

그 많은 핸들중에서 어떤 것이 릭이 발생하는 핸들인지 알아내는 것도 어렵고
도대체 어느 함수에서 그 핸들을 생성하고 닫지 않고 있는 것인지 알아내는 것도
어려운 문제입니다.

이 문제를 쉽게 풀어주는 명령어가 있으니 이것이 바로 !htrace 입니다.
XP 이후에서만 사용할 수 있고 커널모드 보다는 유저모드에서 좀 더 유용합니다.

자세한 사용법은 WinDbg Help 를 참고하시고 여기서는 사용예로 설명합니다.

일단 이 명령어는 그냥 사용할 수는 없습니다.
WinDbg Help 에는 해당 프로세스에 대해서 Application Verifier로 Detect invalid handle usage
옵션을 켜줘야 한다고 나와 있습니다. 반드시 이런 식으로 사용해야 한다면 무지 불편하겠지만
다행스럽게도 Applicaton Verifier 를 설치하지 않아도 아래와 같이 사용하면 동작합니다.

[사용예]
notepad.exe 가 핸들릭을 발생시키는 우리의 프로세스라고 가정합니다.

notepad.exe 를 실행하고 WinDbg 의 Attach Process 로 attach 합니다.
이 상태에서 !htrace 를 사용하면 다음과 같이 오류 메시지가 발생합니다.

0:001> !htrace
Handle tracing is not enabled for this process. Use "!htrace -enable" to enable it.

하지만 친절하게도 사용할 수 있는 방법을 가르쳐 주네요.
Application Verifier 없이도 -enable 옵션을 사용하면 동작합니다.

0:001> !htrace -enable
Handle tracing enabled.
Handle tracing information snapshot successfully taken.

이 때부터 사용하는 핸들은 내용 추적이 가능합니다.
g 로 진행시키고 notepad 에 몇자 적어놓고 나서 Break 를 잡습니다.

이제 !htrace 명령어를 수행하면 그동안 Open/Close 된 핸들의 정보가 나옵니다.
가장 유용한 정보는 Open/Close 가 수행된 콜스택을 보여준다는 부분입니다.
어떤 API 에 의해 Open 된 것인지 보이기 때문에 핸들의 타입을 정확히 알 수 있고
콜스택이 보이기 때문에 어떤 목적으로 어떤 행위를 하고 있었다는 것이 확인됩니다.

0:001> !htrace
--------------------------------------
Handle = 0x00000238 - CLOSE
Thread ID = 0x00000df8, Process ID = 0x00000708

0x77f56c74: ADVAPI32!RegCloseKey+0x00000076
0x3af3c261: imekr70!ImeToAsciiEx+0x00008278
0x3af3c285: imekr70!ImeToAsciiEx+0x0000829c
0x3af3b3c1: imekr70!ImeToAsciiEx+0x000073d8
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cfb89b: USER32!SendMessageWorker+0x000004a5
0x77d4b63b: USER32!SendMessageToUI+0x00000052
0x77d4c2de: USER32!ImeSetContextHandler+0x000001b8
0x77d4c6ec: USER32!ImeWndProcWorker+0x000002f4
--------------------------------------
Handle = 0x00000238 - OPEN
Thread ID = 0x00000df8, Process ID = 0x00000708

0x77f576eb: ADVAPI32!RegOpenKeyExA+0x00000119
0x3af3c232: imekr70!ImeToAsciiEx+0x00008249
0x3af3c285: imekr70!ImeToAsciiEx+0x0000829c
0x3af3b3c1: imekr70!ImeToAsciiEx+0x000073d8
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cfb89b: USER32!SendMessageWorker+0x000004a5
0x77d4b63b: USER32!SendMessageToUI+0x00000052
0x77d4c2de: USER32!ImeSetContextHandler+0x000001b8
0x77d4c6ec: USER32!ImeWndProcWorker+0x000002f4
--------------------------------------
Handle = 0x00000234 - CLOSE
Thread ID = 0x00000df8, Process ID = 0x00000708

0x746615d9: MSCTF!CCicEvent::Uninit+0x00000012
0x7467faff: MSCTF!CicMarshalWndProc+0x00000161
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
0x01002a12: notepad!WinMain+0x000000dc
0x01007511: notepad!WinMainCRTStartup+0x00000174
0x7c816fd7: kernel32!BaseProcessStart+0x00000023
--------------------------------------
Handle = 0x00000230 - CLOSE
Thread ID = 0x00000df8, Process ID = 0x00000708

0x746615d9: MSCTF!CCicEvent::Uninit+0x00000012
0x7467faff: MSCTF!CicMarshalWndProc+0x00000161
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
0x01002a12: notepad!WinMain+0x000000dc
0x01007511: notepad!WinMainCRTStartup+0x00000174
0x7c816fd7: kernel32!BaseProcessStart+0x00000023
--------------------------------------
Handle = 0x00000234 - OPEN
Thread ID = 0x00000df8, Process ID = 0x00000708

0x7c81325a: kernel32!OpenEventA+0x0000006a
0x7467d2a8: MSCTF!CCicEvent::Open+0x00000022
0x7467f672: MSCTF!HandleSendReceiveMsg+0x0000028c
0x7467faff: MSCTF!CicMarshalWndProc+0x00000161
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
0x01002a12: notepad!WinMain+0x000000dc
0x01007511: notepad!WinMainCRTStartup+0x00000174
0x7c816fd7: kernel32!BaseProcessStart+0x00000023
--------------------------------------
Handle = 0x00000230 - OPEN
Thread ID = 0x00000df8, Process ID = 0x00000708

0x7c81325a: kernel32!OpenEventA+0x0000006a
0x7467d2a8: MSCTF!CCicEvent::Open+0x00000022
0x7467f424: MSCTF!HandleSendReceiveMsg+0x0000005c
0x7467faff: MSCTF!CicMarshalWndProc+0x00000161
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
0x01002a12: notepad!WinMain+0x000000dc
0x01007511: notepad!WinMainCRTStartup+0x00000174
0x7c816fd7: kernel32!BaseProcessStart+0x00000023
--------------------------------------
Handle = 0x0000022c - CLOSE
Thread ID = 0x00000df8, Process ID = 0x00000708

0x746615d9: MSCTF!CCicEvent::Uninit+0x00000012
0x7467faff: MSCTF!CicMarshalWndProc+0x00000161
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
0x01002a12: notepad!WinMain+0x000000dc
0x01007511: notepad!WinMainCRTStartup+0x00000174
0x7c816fd7: kernel32!BaseProcessStart+0x00000023
--------------------------------------
Handle = 0x00000228 - CLOSE
Thread ID = 0x00000df8, Process ID = 0x00000708

0x746615d9: MSCTF!CCicEvent::Uninit+0x00000012
0x7467faff: MSCTF!CicMarshalWndProc+0x00000161
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
0x01002a12: notepad!WinMain+0x000000dc
0x01007511: notepad!WinMainCRTStartup+0x00000174
0x7c816fd7: kernel32!BaseProcessStart+0x00000023
--------------------------------------
Handle = 0x0000022c - OPEN
Thread ID = 0x00000df8, Process ID = 0x00000708

0x7c81325a: kernel32!OpenEventA+0x0000006a
0x7467d2a8: MSCTF!CCicEvent::Open+0x00000022
0x7467f672: MSCTF!HandleSendReceiveMsg+0x0000028c
0x7467faff: MSCTF!CicMarshalWndProc+0x00000161
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
0x01002a12: notepad!WinMain+0x000000dc
0x01007511: notepad!WinMainCRTStartup+0x00000174
0x7c816fd7: kernel32!BaseProcessStart+0x00000023
--------------------------------------
Handle = 0x00000150 - CLOSE
Thread ID = 0x00000df8, Process ID = 0x00000708

0x74661eeb: MSCTF!CCicFileMappingStatic::Close+0x00000021
0x7467faff: MSCTF!CicMarshalWndProc+0x00000161
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
0x01002a12: notepad!WinMain+0x000000dc
0x01007511: notepad!WinMainCRTStartup+0x00000174
0x7c816fd7: kernel32!BaseProcessStart+0x00000023
--------------------------------------
Handle = 0x00000228 - OPEN
Thread ID = 0x00000df8, Process ID = 0x00000708

0x7c81325a: kernel32!OpenEventA+0x0000006a
0x7467d2a8: MSCTF!CCicEvent::Open+0x00000022
0x7467f424: MSCTF!HandleSendReceiveMsg+0x0000005c
0x7467faff: MSCTF!CicMarshalWndProc+0x00000161
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
0x01002a12: notepad!WinMain+0x000000dc
0x01007511: notepad!WinMainCRTStartup+0x00000174
0x7c816fd7: kernel32!BaseProcessStart+0x00000023
--------------------------------------

...

--------------------------------------
Parsed 0xB2 stack traces.
Dumped 0xB2 stack traces.

주의할 점은 같은 핸들에 대해서 Open 되고 Close 된 것이 모두 나오기 때문에
차근차근 확인해 보셔야 합니다.

이 정보만 가지고도 많은 도움이 되지만 핸들이 닫히지 않고 계속 남아 있는 릭
상황을 확인할 때는 -diff 옵션을 사용하면 더 좋습니다.

-diff 옵션을 사용하면 -enable 을 실행할 때 snapshot 잡힌 정보와 -diff 할 때의
정보를 비교하여 닫히지 않고 열려있는 핸들만 보여줍니다. 핸들릭을 잡는 상황이면
이렇게 보여지는 핸들중에서 문제의 핸들을 찾는 것이 훨씬 쉬울 것입니다.

0:001> !htrace -diff
Handle tracing information snapshot successfully taken.
0xb2 new stack traces since the previous snapshot.
Ignoring handles that were already closed...
Outstanding handles opened since the previous snapshot:
--------------------------------------
Handle = 0x000000f4 - OPEN
Thread ID = 0x00000df8, Process ID = 0x00000708

0x7c8094b1: kernel32!CreateFileMappingA+0x0000006e
0x746657f3: MSCTF!CSharedBlockNT::Init+0x00000147
0x746949f9: MSCTF!CSharedHeap::Init+0x00000072
0x74694b22: MSCTF!EnsureSharedHeap+0x0000004a
0x74680357: MSCTF!CProxy::proxy_Param+0x00000031
0x74680ec5: MSCTF!CProxyITfLangBarItemSink::OnUpdate+0x0000003c
0x7467cd8f: MSCTF!CLangBarItemMgr::OnUpdateHandler+0x00000036
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
0x77cf8a10: USER32!DispatchMessageW+0x0000000f
--------------------------------------
Handle = 0x000000cc - OPEN
Thread ID = 0x00000df8, Process ID = 0x00000708

0x7c80e98b: kernel32!CreateMutexA+0x00000065
0x7466245b: MSCTF!CCicMutex::Init+0x00000016
0x74664b22: MSCTF!CSharedBlockNT::Init+0x000000c5
0x746949f9: MSCTF!CSharedHeap::Init+0x00000072
0x74694b22: MSCTF!EnsureSharedHeap+0x0000004a
0x74680357: MSCTF!CProxy::proxy_Param+0x00000031
0x74680ec5: MSCTF!CProxyITfLangBarItemSink::OnUpdate+0x0000003c
0x7467cd8f: MSCTF!CLangBarItemMgr::OnUpdateHandler+0x00000036
0x77cf8734: USER32!InternalCallWinProc+0x00000028
0x77cf8816: USER32!UserCallWinProcCheckWow+0x00000150
0x77cf89cd: USER32!DispatchMessageWorker+0x00000306
--------------------------------------
Displayed 0x2 stack traces for outstanding handles opened since the previous snapshot.

두 개의 핸들이 계속 남아 있었음을 보이고 있습니다.
하나는 파일맵핑 핸들이고 하나는 뮤텍스 핸들이네요.

이제 콜스택을 잘 보면서 어떤 목적으로 열어놓은 핸들인지 확인하고 이것을 왜 닫지 않는지
소스코드를 보면서 문제의 원인을 찾으면 됩니다.

좀 더 시간이 있었으면 예제를 만들어서 보기 좋게 보여드렸을 텐데 요즘 시간이 녹녹치 않네요. ^^
복잡하지만 활용하실 수 있을 정도만 적어 봤습니다. 모두에게 도움이 되시기 바랍니다.

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

두번째 스크립트는 핸들 테이블을 전부 보여주는 스크립트입니다.

덤프를 받아서 !handle 명령으로 핸들을 보고 싶은 경우가 있는데 어쩐 일인지 !handle
명령어가 오류가 발생하여 핸들 정보를 보여주지 못하는 경우가 있습니다.

어찌 할까 고심하다가 !process 명령에서 나오는 ObjectTable 이라는 부분이
결국 핸들 테이블이라는 사실을 알게되어 ObjectTable 을 따라가 보기로 했습니다.

kd> !process
PROCESS 866d1020  SessionId: 0  Cid: 09fc    Peb: 7ffde000  ParentCid: 02e0
    DirBase: 15662000  ObjectTable: 81bc0828  HandleCount: 295.
    Image: windbg.exe

ObjectTable 을 추적하는 과정이 쉽지는 않았지만 여러분들이 올려주신 핸들에 대한 자료와
정덕영 님의 "Windows 구조와 원리 그리고 Codes" 를 참고하여 해낼 수 있었습니다.

스크립트가 생각보다 복잡해서 괜히 보시는 분들 심란하게 하는게 아닌가 싶으면서도
언젠가 이런 것이 필요하신 분들이 그 때 가서라도 분석하며 활용할 수 있을 것 같아서
일단 공유합니다. 물론 저 개인의 갈무리이기도 합니다. ^^

이번 스크립트를 작성하면서 알게된 사실...

1. $t0 ~ $t19 는 미리 정의된 가상 레지스터(Pseudo-Register)이다.
   r $t0 = 0 이런식으로 쓰는 이유가 레지스터로 취급하기 때문이었더군요.
   r eax = 0 이렇게 사용하는 것과 같습니다.
   그래서 값을 읽을 때도 @eax 하는 것 처럼 @$t0 이렇게 하는 거구요.

2. 스트립트로 파라미터를 전달할 때는 명령이 약간 달라집니다.
   $$>a<myscript... 로 시작해야 합니다.
   a 를 끼워넣어서 파라미터가 존재한다는 것을 알리는 것입니다.

이제 스크립트를 보입니다.
주석은 자세히 달았으나 보기 쉽지는 않을 거라는거... 죄송합니다. ^^

$$
$$ WinDbg script to display ObjectTable in a process
$$
$$ 프로세스 정보중 ObjectTable 의 주소를 입력받아서 옵젝트 테이블(핸들 테이블)에
$$ 존재하는 모든 옵젝트(핸들의 대상)의 타입을 보여준다.
$$
$$ 대상 OS 는 Win2k 이다.
$$ XP 는 핸들 테이블 구조가 다르므로 이 스크립트를 적용할 수 없다.
$$
$$ 사용예) kd> $$>a<myscript\display_2k_objtbl.txt 81bc0828 
$$ Written by GreeMate
$$

$$ 파라미터로 전달된 arg1 값을 가상 레지스터 $t10 에 대입한다.
r $t10 = ${$arg1}
.printf "ObjectTable: %x\n", @$t10

$$ ObjectTable 은 _HANDLE_TABLE 타입이므로 C++ 형식으로 접근해서 Table 주소를 구한다.
r $t10 = @@c++(((nt!_HANDLE_TABLE *)@$t10)->Table)
.printf "ObjectTable->Table: %x\n", @$t10

$$ Win2k 핸들 테이블은 3 Level 포인터로 256개씩 구성되어 있으므로 순차적으로 접근한다.
.for (r $t0 = 0; (@$t0 < 0n256); r $t0 = @$t0 + 1)
{
  $$ Table 포인터가 0 이면 중지하고 아니면 포인터의 값을 $t11 에 대입한다.
  .if (@$t10 == 0) { .break }
  r $t11 = poi(@$t10)

  $$ 다음 레벨의 포인터 테이블을 순차적으로 접근한다.
  .for (r $t1 = 0; (@$t1 < 0n256); r $t1 = @$t1 + 1)
  {
    $$ Table 포인터가 0 이면 중지하고 아니면 포인터의 값을 $t12 에 대입한다.
    .if (@$t11 == 0) { .break }
    r $t12 = poi(@$t11)
 
    $$ 다음 레벨의 포인터 테이블을 순차적으로 접근한다.
    .for (r $t2 = 0; (@$t2 < 0n256); r $t2 = @$t2 + 1)
    {
      .if (@$t12 == 0) { .break }
 
      $$ 실제 테이블에는 ObjectHeader 포인터와 AccessMask 가 저장되어 있다.
      $$ 따라서 8 바이트씩 건너 뛰어야 ObjectHeader 를 순차적으로 접근할 수 있다.
      r $t19 = @$t12 + (@$t2 * 8)
   
      $$ 저장된 ObjectHeader 포인터가 0 이면 건너뛴다.
      .if (poi(@$t19) == 0) { .continue }

      $$ 저장된 ObjectHeader 포인터는 특별한 목적으로 최상위 비트가 Clear 되어 저장되므로 최상위비트를 켜준다.
      r $t19 = poi(@$t19) + 0x80000000
      .printf "Object Header: %x\n", @$t19
   
      $$ $t19는 ObjectHeader이므로 C++ 형식으로 접근해서 Type 필드를 구한다.
      r $t19 = @@c++(((nt!_OBJECT_HEADER *)@$t19)->Type)
      .printf "Object Type : %x\n", @$t19

      $$ ObjectType 구조체에서 Name 필드를 표시한다.
      dt nt!_OBJECT_TYPE Name @$t19
    }
 
    $$ 테이블의 다음 엔트리로
    r $t11 = @$t11 + 4
    }

  $$ 테이블의 다음 엔트리로
  r $t10 = @$t10 + 4
}

실행예>

0: kd> $$>a<myscript\display_2k_objtbl.txt 81bc0828
ObjectTable: 81bc0828
ObjectTable->Table: e1e5f000
Object Header: e1e58078
Object Type : 8207c880
   +0x040 Name : _UNICODE_STRING "Section"
Object Header: 81bc1008
Object Type : 8207f1a0
   +0x040 Name : _UNICODE_STRING "Event"
Object Header: 81bc03a8
Object Type : 8207f1a0
   +0x040 Name : _UNICODE_STRING "Event"
Object Header: 81bbffc8
Object Type : 8207f1a0
   +0x040 Name : _UNICODE_STRING "Event"
Object Header: 81c4e238
Object Type : 82086040
   +0x040 Name : _UNICODE_STRING "Directory"
Object Header: 81ba6d08
Object Type : 8207f1a0
   +0x040 Name : _UNICODE_STRING "Event"
Object Header: 81bbfca8
Object Type : 8207f1a0
   +0x040 Name : _UNICODE_STRING "Event"
Object Header: 81d19bb8
Object Type : 82086040
   +0x040 Name : _UNICODE_STRING "Directory"
...

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

오늘은 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

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

오래간만에 덤프분석 하나 해 보겠습니다.
오늘은 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

저는 개인적으로 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

오늘은 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

오늘은 메모리가 깨졌을 경우에 발생하는 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