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
