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