1. 문제 현상
프로세스 오브젝트가 손상되어 Bugcheck 0x3B가 발생하는 경우를 맞이하게 되어 정리해 본다.
Bugcheck의 내용은 다음과 같다.
0: kd> !analyze -v
*******************************************************************************
* *
* Bugcheck Analysis *
* *
*******************************************************************************
SYSTEM_SERVICE_EXCEPTION (3b)
An exception happened while executing a system service routine.
Arguments:
Arg1: 00000000c0000005, Exception code that caused the bugcheck
Arg2: fffff80002f6df33, Address of the instruction which caused the bugcheck
Arg3: fffff88003ae63c0, Address of the context record for the exception that caused the bugcheck
Arg4: 0000000000000000, zero.
Debugging Details:
------------------
EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - 0x%08lx
FAULTING_IP:
nt!ObInsertObjectEx+193
fffff800`02f6df33 4c8b6320 mov r12,qword ptr [rbx+20h]
CONTEXT: fffff88003ae63c0 -- (.cxr 0xfffff88003ae63c0)
rax=fffffa8001b2c8e0 rbx=0000000000000001 rcx=0000000000000000
rdx=0000000000000000 rsi=fffff980000b6f30 rdi=fffff88003ae7840
rip=fffff80002f6df33 rsp=fffff88003ae6da0 rbp=0000000000000000
r8=0000000002000000 r9=0000000000000000 r10=0000000000000000
r11=fffff80002c09000 r12=0000000000000000 r13=0000000000000001
r14=0000000000000000 r15=fffff98028094b30
iopl=0 nv up ei ng nz na pe nc
cs=0010 ss=0018 ds=002b es=002b fs=0053 gs=002b efl=00010282
nt!ObInsertObjectEx+0x193:
fffff800`02f6df33 4c8b6320 mov r12,qword ptr [rbx+20h] ds:002b:00000000`00000021=????????????????
Resetting default scope
DEFAULT_BUCKET_ID: VISTA_DRIVER_FAULT
BUGCHECK_STR: 0x3B
PROCESS_NAME: MyApp.exe
CURRENT_IRQL: 2
LAST_CONTROL_TRANSFER: from fffff80002f2ee8f to fffff80002f6df33
STACK_TEXT:
fffff880`03ae6da0 fffff800`02f2ee8f : ffffffff`ffffffff 00000000`00000000 00000000`00000000 fffff980`28094b30 : nt!ObInsertObjectEx+0x193
fffff880`03ae6ff0 fffff800`02f2d5be : fffff980`28094b00 fffff980`18986e30 fffff880`02000000 fffff880`03ae76f0 : nt!PspInsertProcess+0x23f
fffff880`03ae7080 fffff800`02c87453 : 00000000`00000000 0000007f`ffffffff 00000000`00000000 00000980`00000000 : nt!NtCreateUserProcess+0x6c9
fffff880`03ae7bb0 00000000`77011dea : 00000000`7471b9eb 00000000`001740c0 00000000`009ad368 00000000`0008eab0 : nt!KiSystemServiceCopyEnd+0x13
00000000`0008dd38 00000000`7471b9eb : 00000000`001740c0 00000000`009ad368 00000000`0008eab0 00000000`0008eab0 : ntdll!NtCreateUserProcess+0xa
00000000`0008dd40 00000000`747313e7 : 00000000`0008e268 00000000`009ad368 00000000`009ad9d8 00000000`0008eab0 : wow64!Wow64NtCreateUserProcess+0x15f
00000000`0008e130 00000000`7471cf87 : 00000000`00000000 00000000`7efdb000 00000000`7efdd000 00000000`74730bf8 : wow64!whNtCreateUserProcess+0x7ef
00000000`0008e350 00000000`74852776 : 00000000`7547977a 00000000`74710023 00000000`00000246 00000000`009af01c : wow64!Wow64SystemServiceEx+0xd7
00000000`0008ec10 00000000`7471d07e : 00000000`00000000 00000000`74851920 00000000`0008eea0 00000000`76feecd1 : wow64cpu!TurboDispatchJumpAddressEnd+0x2d
00000000`0008ecd0 00000000`7471c549 : 00000000`00000000 00000000`00000000 00000000`74714ac8 00000000`7ffe0030 : wow64!RunCpuSimulation+0xa
00000000`0008ed20 00000000`77004956 : 00000000`00173c20 00000000`00000000 00000000`770f2670 00000000`770c5978 : wow64!Wow64LdrpInitialize+0x429
00000000`0008f270 00000000`77001a17 : 00000000`00000000 00000000`77004061 00000000`0008f820 00000000`00000000 : ntdll!LdrpInitializeProcess+0x17e4
00000000`0008f760 00000000`76fec32e : 00000000`0008f820 00000000`00000000 00000000`7efdf000 00000000`00000000 : ntdll! ?? ::FNODOBFM::`string'+0x29220
00000000`0008f7d0 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!LdrInitializeThunk+0xe
FOLLOWUP_IP:
nt!ObInsertObjectEx+193
fffff800`02f6df33 4c8b6320 mov r12,qword ptr [rbx+20h]
SYMBOL_STACK_INDEX: 0
SYMBOL_NAME: nt!ObInsertObjectEx+193
FOLLOWUP_NAME: MachineOwner
MODULE_NAME: nt
IMAGE_NAME: ntkrnlmp.exe
DEBUG_FLR_IMAGE_TIMESTAMP: 4fa390f3
STACK_COMMAND: .cxr 0xfffff88003ae63c0 ; kb
FAILURE_BUCKET_ID: X64_0x3B_VRFK_nt!ObInsertObjectEx+193
BUCKET_ID: X64_0x3B_VRFK_nt!ObInsertObjectEx+193
Followup: MachineOwner
---------
0: kd> .cxr 0xfffff88003ae63c0
rax=fffffa8001b2c8e0 rbx=0000000000000001 rcx=0000000000000000
rdx=0000000000000000 rsi=fffff980000b6f30 rdi=fffff88003ae7840
rip=fffff80002f6df33 rsp=fffff88003ae6da0 rbp=0000000000000000
r8=0000000002000000 r9=0000000000000000 r10=0000000000000000
r11=fffff80002c09000 r12=0000000000000000 r13=0000000000000001
r14=0000000000000000 r15=fffff98028094b30
iopl=0 nv up ei ng nz na pe nc
cs=0010 ss=0018 ds=002b es=002b fs=0053 gs=002b efl=00010282
nt!ObInsertObjectEx+0x193:
fffff800`02f6df33 4c8b6320 mov r12,qword ptr [rbx+20h] ds:002b:00000000`00000021=????????????????
nt!ObInsertObjectEx에서 죽어버리는 문제다.
rbx=1 이었기 때문에 죽은 것인데 이 rbx 값은 프로세스 오브젝트의 헤더 + 20 위치에 있던 값이다.
프로세스 오브젝트의 포인터가 r15에 들어 있으므로 다음과 같이 확인할 수 있다.
0: kd> dt _OBJECT_HEADER fffff98028094b30-30
nt!_OBJECT_HEADER
+0x000 PointerCount : 0n4
+0x008 HandleCount : 0n0
+0x008 NextToFree : (null)
+0x010 Lock : _EX_PUSH_LOCK
+0x018 TypeIndex : 0x7 ''
+0x019 TraceFlags : 0 ''
+0x01a InfoMask : 0x8 ''
+0x01b Flags : 0 ''
+0x020 ObjectCreateInfo : 0x00000000`00000001 _OBJECT_CREATE_INFORMATION
+0x020 QuotaBlockCharged : 0x00000000`00000001 Void
+0x028 SecurityDescriptor : (null)
+0x030 Body : _QUAD
ObjectCreateInfo의 1이 rbx로 전달되어 죽은 것이다.
ObjectCreateInfo는 1이 아니라 어떤 포인터가 들어 있어야 했다.
어째서 이런 값이 들어 갔는지는 덤프 분석을 통해서는 알 길이 없었다.
콜스택을 보고 프로세스가 생성되는 시점이라는 정도의 정보만 가늠할 수 있었다.
0: kd> k
*** Stack trace for last set context - .thread/.cxr resets it
Child-SP RetAddr Call Site
fffff880`03ae6da0 fffff800`02f2ee8f nt!ObInsertObjectEx+0x193
fffff880`03ae6ff0 fffff800`02f2d5be nt!PspInsertProcess+0x23f
fffff880`03ae7080 fffff800`02c87453 nt!NtCreateUserProcess+0x6c9
fffff880`03ae7bb0 00000000`77011dea nt!KiSystemServiceCopyEnd+0x13
00000000`0008dd38 00000000`7471b9eb ntdll!NtCreateUserProcess+0xa
00000000`0008dd40 00000000`747313e7 wow64!Wow64NtCreateUserProcess+0x15f
00000000`0008e130 00000000`7471cf87 wow64!whNtCreateUserProcess+0x7ef
00000000`0008e350 00000000`74852776 wow64!Wow64SystemServiceEx+0xd7
00000000`0008ec10 00000000`7471d07e wow64cpu!TurboDispatchJumpAddressEnd+0x2d
00000000`0008ecd0 00000000`7471c549 wow64!RunCpuSimulation+0xa
00000000`0008ed20 00000000`77004956 wow64!Wow64LdrpInitialize+0x429
00000000`0008f270 00000000`77001a17 ntdll!LdrpInitializeProcess+0x17e4
00000000`0008f760 00000000`76fec32e ntdll! ?? ::FNODOBFM::`string'+0x29220
00000000`0008f7d0 00000000`00000000 ntdll!LdrInitializeThunk+0xe
2. 문제 원인
결국에는 100% 문제가 재현되는 시스템을 섭외해서 원인을 확인하고야 말았다.
ObjectCreateInfo가 1로 변하는 순간을 잡아 보니 MyDrv.sys가 ObOpenObjectByPointer()를 호출한 순간이었다.
0: kd> kL
Child-SP RetAddr Call Site
fffff880`03ae62f0 fffff800`02f7c5ec nt!ObpIncrementHandleCountEx+0x205
fffff880`03ae63b0 fffff800`02f6f4f1 nt!ObpCreateHandle+0x19c
fffff880`03ae64c0 fffff800`02f612cc nt!ObOpenObjectByPointerWithTag+0x109
fffff880`03ae66e0 fffff880`02f6c0e5 nt!ObOpenObjectByPointer+0x30
fffff880`03ae6730 fffff880`02f6c04d MyDrv!DoSomething+0x75
...
fffff880`03ae6cc0 fffff800`02f2c7da nt!PspSetupUserProcessAddressSpace+0x13b
fffff880`03ae6da0 fffff800`02f2d398 nt!PspAllocateProcess+0x11fa
fffff880`03ae7080 fffff800`02c87453 nt!NtCreateUserProcess+0x4a3
fffff880`03ae7bb0 00000000`77011dea nt!KiSystemServiceCopyEnd+0x13
커널 내부 함수인 ObpIncrementHandleCountEx() 내부에서 ObjectCreateInfo를 1로 만드는 것이었다!!!
OS 버그란 말인가?
ObOpenObjectByPointer()를 호출하는 것이 특별할 것도 없는데 왜 이런 일이 생기는지 조사해야 했다.
이 함수에 전달한 프로세스 오브젝트의 헤더를 살펴봤다.
0: kd> dt _OBJECT_HEADER fffff98028094b30-30
nt!_OBJECT_HEADER
+0x000 PointerCount : 0n2
+0x008 HandleCount : 0n0
+0x008 NextToFree : (null)
+0x010 Lock : _EX_PUSH_LOCK
+0x018 TypeIndex : 0x7 ''
+0x019 TraceFlags : 0 ''
+0x01a InfoMask : 0x8 ''
+0x01b Flags : 0x1 '' ; OB_FLAG_CREATE_INFO
+0x020 ObjectCreateInfo : 0xfffffa80`02b26220 _OBJECT_CREATE_INFORMATION
+0x020 QuotaBlockCharged : 0xfffffa80`02b26220 Void
+0x028 SecurityDescriptor : (null)
+0x030 Body : _QUAD
ObjectCreateInfo에는 1로 변경되기 전까지는 어떤 포인터가 존재하고 있었다.
Flags는 1인데 OB_FLAG_CREATE_INFO를 의미한다.
좀 찾아보니 오브젝트를 생성하고 있는 중이라는 뜻으로 보였다.
OB_FLAG_CREATE_INFO는 오브젝트 생성이 완료되고 나면 없어진다.
실제로 문제를 일으키는 ObpIncrementHandleCountEx() 함수를 따라 들어가다 보면 Flags가 1인 것을 확인하고 ObjectCreateInfo를 망가뜨리는 코드로 점프하는 것을 볼 수 있다.
즉, OB_FLAG_CREATE_INFO가 아직 존재할 때 ObOpenObjectByPointer()를 호출하면 OS에서 이를 제대로 처리 못하는 버그가 있는 것이다.
3. 부록
이 내용을 보더니 우리팀 배주임님이 검색해서 찾아준 링크
http://uninformed.org/index.cgi?v=1&a=5&p=5
내가 얼추 추정하고 지나갔던 것들을 상세하게 분석해서 명쾌하게 설명하고 있다.
아... 부(끄)러워라... *^^*
