windbg 분석 - webengine4.dll의 MgdExplicitFlush에서 발생한 System.AccessViolationException의 crash 문제
이 글은 MgdExplicitFlush에서 비정상 종료가 왜 발생했는지에 대한 이유를 밝히는 것이 목적이 아닙니다. 순수하게 그냥 windbg의 명령어 실습 겸 원인 분석을 위한 것이므로 이 글을 읽는다고 해서 webengine4.dll의 MgdExplicitFlush에서 발생한 예외의 근본적인 원인을 알 수는 없습니다. (혹시, 실망하실까 봐 미리 공지하는 것입니다. ^^)
우선, 해당 예외가 발생하면 w3wp.exe가 crash되므로 다음과 같이 인자를 주어 procdump.exe를 실행해야 예외 시점의 풀 덤프를 남길 수 있습니다.
procdump w3wp.exe -ma -e 1 -f System.AccessViolationException
이후, windbg에서 풀 덤프를 로드하고 sos.dll의 확장을 통해 !pe 명령을 내리면 다음과 같은 예외 정보를 얻습니다.
0:210> !pe
Exception object: 0000000270b15410
Exception type: System.AccessViolationException
Message: 보호된 메모리를 읽거나 쓰려고 했습니다. 대부분 이러한 경우는 다른 메모리가 손상되었음을 나타냅니다.
InnerException: <none>
StackTrace (generated):
SP IP Function
0000000026C8D290 0000000000000001 System_Web!System.Web.Hosting.UnsafeIISMethods.MgdExplicitFlush(IntPtr)+0x2
StackTraceString: <none>
HResult: 80004003
210번 스레드의 clrstack 정보를 얻어도 크게 도움이 되는 것은 없습니다.
0:210> !clrstack
OS Thread Id: 0x18b0 (210)
Child SP IP Call Site
0000000026c8d2c8 0000000076dabd7a [NDirectMethodFrameStandalone: 0000000026c8d2c8] System.Web.Hosting.UnsafeIISMethods.MgdExplicitFlush(IntPtr)
0000000026c8d290 000007ff01aded10 System.Web.Hosting.IIS7WorkerRequest.ExplicitFlush()
0000000026c8d350 000007ff01adbbcc System.Web.HttpResponse.Flush(Boolean)
0000000026c8d7a8 000007fef87fc9e4 [HelperMethodFrame_PROTECTOBJ: 0000000026c8d7a8] System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr, System.Object[], System.Object, Int32, Boolean, System.Object[] ByRef)
0000000026c8dc10 000007ff006a3ab4 System.Runtime.Remoting.Messaging.StackBuilderSink.PrivateProcessMessage(System.RuntimeMethodHandle, System.Object[], System.Object, Int32, Boolean, System.Object[] ByRef)
0000000026c8dc70 000007ff01ada135 System.Runtime.Remoting.Messaging.StackBuilderSink.AsyncProcessMessage(System.Runtime.Remoting.Messaging.IMessage, System.Runtime.Remoting.Messaging.IMessageSink)
0000000026c8dd30 000007ff011b6c98 System.Threading.ExecutionContext.runTryCode(System.Object)
0000000026c8e458 000007fef87fc9e4 [HelperMethodFrame_PROTECTOBJ: 0000000026c8e458] System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode, CleanupCode, System.Object)
0000000026c8e580 000007ff011b4bf6 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
0000000026c8e5e0 000007ff011b45d9 System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
0000000026c8e630 000007ff011b1363 System.Threading.ThreadPoolWorkQueue.Dispatch()
0000000026c8e6b0 000007ff011b0d41 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()
0000000026c8ed10 000007fef87fc9e4 [DebuggerU2MCatchHandlerFrame: 0000000026c8ed10]
0000000026c8eee8 000007fef87fc9e4 [ContextTransitionFrame: 0000000026c8eee8]
0000000026c8f0d0 000007fef87fc9e4 [DebuggerU2MCatchHandlerFrame: 0000000026c8f0d0]
sos.dll로는 여기까지가 최선입니다.
자, 그럼 native로 들어가 볼까요? k 명령어로 다음과 같이 native 콜 스택을 얻을 수 있고,
0:210> k
# Child-SP RetAddr Call Site
00 00000000`26c8ab08 000007fe`fd0110ac ntdll!ZwWaitForSingleObject+0xa
01 00000000`26c8ab10 000007fe`f87f2817 KERNELBASE!WaitForSingleObjectEx+0x79
...[생략]...
10 00000000`26c8b1a0 000007fe`f889a22b clr!ExceptionTracker::ProcessOSExceptionNotification+0x1cc
11 00000000`26c8c120 00000000`76d8812d clr!ProcessCLRException+0x21b
12 00000000`26c8c1f0 00000000`76d7855f ntdll!RtlpExecuteHandlerForException+0xd
13 00000000`26c8c220 00000000`76dabcb8 ntdll!RtlDispatchException+0x45a
14 00000000`26c8c900 000007fe`fae4769c ntdll!KiUserExceptionDispatch+0x2e
15 00000000`26c8d020 000007fe`fae420fd iiscore!W3_RESPONSE::DoActualSendResponse+0x6c
16 00000000`26c8d0d0 000007fe`fae475d6 iiscore!NOTIFICATION_SEND_RESPONSE::DoWork+0xbd
17 00000000`26c8d130 000007fe`facddce4 iiscore!W3_RESPONSE::Flush+0x2b6
18 00000000`26c8d1b0 000007fe`f87c19c2 webengine4!W3_MGD_HANDLER::ExplicitFlush+0x85
19 00000000`26c8d200 000007ff`01aded10 clr!DoNDirectCallWorker+0x62
...[생략]...
보면, 예외 처리로 들어가기 전 실질적인 예외는 iiscore!W3_RESPONSE::DoActualSendResponse+0x6c에서 발생했음을 알 수 있습니다. 프레임 번호가 0x15인데 아쉽게도 private PDB 정보가 아니고서는 더 이상 실질적인 단서를 알아낼 수는 없습니다.
0:210> .frame 0n21;dv /t /v
ntdll!ZwWaitForSingleObject+0xa:
00000000`76dabd7a c3 ret
15 00000000`26c8d020 000007fe`fae420fd iiscore!W3_RESPONSE::DoActualSendResponse+0x6c
Unable to enumerate locals, HRESULT 0x80004005
Private symbols (symbols.pri) are required for locals.
Type ".hh dbgerr005" for details.
그럼, 코드 수행에 따른 문맥 상황이 어땠길래 예외가 발생한 것일까요? 이를 위해 Disassembly 창에서 "iiscore!W3_RESPONSE::DoActualSendResponse" 값으로 어셈블리 코드를 얻을 수 있습니다.
iiscore!W3_RESPONSE::DoActualSendResponse:
000007fe`fae47630 4c894c2420 mov qword ptr [rsp+20h],r9
000007fe`fae47635 4489442418 mov dword ptr [rsp+18h],r8d
000007fe`fae4763a 89542410 mov dword ptr [rsp+10h],edx
000007fe`fae4763e 53 push rbx
000007fe`fae4763f 55 push rbp
000007fe`fae47640 56 push rsi
000007fe`fae47641 57 push rdi
000007fe`fae47642 4154 push r12
000007fe`fae47644 4155 push r13
000007fe`fae47646 4157 push r15
000007fe`fae47648 4883ec70 sub rsp,70h
000007fe`fae4764c 488bd9 mov rbx,rcx
000007fe`fae4764f 488b4920 mov rcx,qword ptr [rcx+20h]
000007fe`fae47653 418bf0 mov esi,r8d
000007fe`fae47656 4c8ba1d0010000 mov r12,qword ptr [rcx+1D0h]
000007fe`fae4765d 4533ff xor r15d,r15d
000007fe`fae47660 83e602 and esi,2
000007fe`fae47663 418be8 mov ebp,r8d
000007fe`fae47666 7528 jne iiscore!W3_RESPONSE::DoActualSendResponse+0x60 (000007fe`fae47690)
000007fe`fae47668 81791000080000 cmp dword ptr [rcx+10h],800h
000007fe`fae4766f 761f jbe iiscore!W3_RESPONSE::DoActualSendResponse+0x60 (000007fe`fae47690)
000007fe`fae47671 4439b9dc1f0000 cmp dword ptr [rcx+1FDCh],r15d
000007fe`fae47678 7416 je iiscore!W3_RESPONSE::DoActualSendResponse+0x60 (000007fe`fae47690)
000007fe`fae4767a 488b81d01f0000 mov rax,qword ptr [rcx+1FD0h]
000007fe`fae47681 f08380d4000000ff lock add dword ptr [rax+0D4h],0FFFFFFFFh
000007fe`fae47689 4489b9dc1f0000 mov dword ptr [rcx+1FDCh],r15d
000007fe`fae47690 488b4b20 mov rcx,qword ptr [rbx+20h]
000007fe`fae47694 4c89742468 mov qword ptr [rsp+68h],r14
000007fe`fae47699 488b01 mov rax,qword ptr [rcx]
000007fe`fae4769c ff5028 call qword ptr [rax+28h] // 바로 이 지점(DoActualSendResponse+0x6c)에서 예외 발생
...[생략]...
DoActualSendResponse를 호출했을 당시의 인자 값 상황을 한번 구성해 볼까요? ^^
먼저 예전 글에도 언급했지만,
x64 콜 스택 인자 추적과 windbg의 Child-SP, RetAddr, Args to Child 값 확인
; https://www.sysnet.pe.kr/2/0/10832
kv 명령어로 나오는 인자 값 정보를 믿을 수 없기 때문에 어쩔 수 없이 스택과 코드를 통해 구성해 봐야 합니다.
우선, DoActualSendResponse의 prolog/epilog의 스택 점유 코드를 확인해 보면,
iiscore!W3_RESPONSE::DoActualSendResponse:
000007fe`fae47630 4c894c2420 mov qword ptr [rsp+20h],r9
000007fe`fae47635 4489442418 mov dword ptr [rsp+18h],r8d
000007fe`fae4763a 89542410 mov dword ptr [rsp+10h],edx
000007fe`fae4763e 53 push rbx
000007fe`fae4763f 55 push rbp
000007fe`fae47640 56 push rsi
000007fe`fae47641 57 push rdi
000007fe`fae47642 4154 push r12
000007fe`fae47644 4155 push r13
000007fe`fae47646 4157 push r15 (총 7번의 push == 56bytes)
000007fe`fae47648 4883ec70 sub rsp,70h (0x70 == 112, 56bytes + 112bytes == 168bytes / 8 == 21개의 슬롯)
...[생략]...
000007fe`fae47855 4883c470 add rsp,70h
000007fe`fae47859 415f pop r15
000007fe`fae4785b 415d pop r13
000007fe`fae4785d 415c pop r12
000007fe`fae4785f 5f pop rdi
000007fe`fae47860 5e pop rsi
000007fe`fae47861 5d pop rbp
000007fe`fae47862 5b pop rbx
000007fe`fae47863 c3 ret
이렇게 DoActualSendResponse 함수는 내부적으로 총 21개의 qword 공간이 스택으로 할당되어 있습니다. 그리고, 알아야 할 것이 DoActualSendResponse 함수가 실행되기 바로 전의 RSP 주소인데요, 이는 k 명령어로 출력된 Child-SP 값을 통해 알 수 있습니다.
0:210> k
# Child-SP RetAddr Call Site
...[생략]...
14 00000000`26c8c900 000007fe`fae4769c ntdll!KiUserExceptionDispatch+0x2e
15 00000000`26c8d020 000007fe`fae420fd iiscore!W3_RESPONSE::DoActualSendResponse+0x6c
16 00000000`26c8d0d0 000007fe`fae475d6 iiscore!NOTIFICATION_SEND_RESPONSE::DoWork+0xbd
...[생략]...
따라서, Child SP == 00000000`26c8d020 값을 기준으로 21개의 qword 공간에 있는 값들은 DoActualSendResponse의 prolog에서 사용된 공간입니다. 메모리 덤프로 보면 다음과 같이 값을 확인할 수 있습니다.
00000000`26c8d020 {0000f37771821f66 000007fef8897f95 0000000026c8d1d8 0000000024a5f960 0000000026c8d150
00000000`26c8d048 0000f37771826b78 00000000ffffffff 0000000003af3000 0000000000000000 0000000026c8d208
00000000`26c8d070 0000000003af2e20 000007fefae4a775 fffffffffffffffe 0000000003af3000} [00000000ffffffff
00000000`26c8d098 0000000000000000 0000000026c8d208 00000000249644e8 0000000024964568 0000000003af2e20
00000000`26c8d0c0 0000000000503350] 000007fefae420fd ...[child-sp로부터 23번째 이후의 값들]...
덤프된 메모리에 "{", "}"로 표시된 구간은 sub rsp, 70h로 점유된 공간이며 "[", "]" 구간은 일련의 push로 넣어진 공간입니다. 그리고 마지막에 보이는 "000007fefae420fd" 값은 DoActualSendResponse 함수가 ret 문이 실행되었을 때 돌아갈 주소로 역시 k 출력 결과의 값과 일치합니다.
0:210> k
# Child-SP RetAddr Call Site
...[생략]...
14 00000000`26c8c900 000007fe`fae4769c ntdll!KiUserExceptionDispatch+0x2e
15 00000000`26c8d020 000007fe`fae420fd iiscore!W3_RESPONSE::DoActualSendResponse+0x6c
16 00000000`26c8d0d0 000007fe`fae475d6 iiscore!NOTIFICATION_SEND_RESPONSE::DoWork+0xbd
...[생략]...
자, 그럼 이 상태에서 "[", "]"로 쌓인 공간의 값을 기반으로 DoActualSendResponse 함수의 prolog 시점에 push...로 보관한 레지스터들의 상태를 복원할 수 있습니다.
rbx == 0000000000503350
rbp == 0000000003af2e20
rsi == 0000000024964568
rdi == 00000000249644e8
r12 == 0000000026c8d208
r13 == 0000000000000000
r15 == 00000000ffffffff
또한 prolog에 있던 다음의 코드에 따라,
000007fe`fae47630 4c894c2420 mov qword ptr [rsp+20h],r9
000007fe`fae47635 4489442418 mov dword ptr [rsp+18h],r8d
000007fe`fae4763a 89542410 mov dword ptr [rsp+10h],edx
DoActualSendResponse 함수에 전달된 인자의 값을 확인할 수 있습니다. 왜냐하면 x64 ABI에 따라 함수의 첫 4개에 대한 인자를 각각 rcx, rdx, r8, r9로 전달하기 때문이고, 결과적으로 위의 코드는 그 값들 중 3개의 변숫값을 "Parameter Homing Space"에 보관하고 있습니다. 문제는 이때 기준이 되는 RSP 주소의 값입니다. 이 값은 DoActualSendResponse가 호출된 바로 이후의 시점이기 때문에 ret으로 돌아갈 주소 000007fefae420fd의 스택 위치를 [RSP + 0h]로 놓고 계산하거나, 아니면 호출한 부모 함수의 Child-SP를 적용해도 됩니다.
0:210> k
# Child-SP RetAddr Call Site
...[생략]...
14 00000000`26c8c900 000007fe`fae4769c ntdll!KiUserExceptionDispatch+0x2e
15 00000000`26c8d020 000007fe`fae420fd iiscore!W3_RESPONSE::DoActualSendResponse+0x6c
16 00000000`26c8d0d0 000007fe`fae475d6 iiscore!NOTIFICATION_SEND_RESPONSE::DoWork+0xbd
...[생략]...
그래서 결국 r9, r8d, edx의 값은 다음과 같이 구할 수 있습니다.
000007fe`fae47630 4c894c2420 mov qword ptr [rsp+20h],r9
000007fe`fae47635 4489442418 mov dword ptr [rsp+18h],r8d
000007fe`fae4763a 89542410 mov dword ptr [rsp+10h],edx
00000000`26c8d0c0 0000000000503350 ...childsp+0h... 000007ff00612020 000007fe00503350 0000000100000002
00000000`26c8d0e8 0000000026c8d110 0000000000000000 0000000000000001 0000000026c8d130 0000000003af2e28
rsp+20h == 0000000026c8d110 == r9
rsp+18h == 0000000100000002 == r8d == 2
rsp+10h == 000007fe00503350 == edx == 00503350
그런데, 아쉽게도 첫 번째 인자인 rcx의 값이 스택에 보관되어 있지 않습니다. 어쩔 수 없이 이런 경우에는 부모 함수의 코드까지 살펴봐야 합니다.
iiscore!NOTIFICATION_SEND_RESPONSE::DoWork:
...[생략]...
000007fe`fae420bc 488b8f88000000 mov rcx,qword ptr [rdi+88h]
000007fe`fae420c3 448b8794000000 mov r8d,dword ptr [rdi+94h]
000007fe`fae420ca 488d442460 lea rax,[rsp+60h]
000007fe`fae420cf 4c8d4c2440 lea r9,[rsp+40h]
000007fe`fae420d4 4881c1e0010000 add rcx,1E0h
000007fe`fae420db 4889442430 mov qword ptr [rsp+30h],rax
000007fe`fae420e0 8b87ac000000 mov eax,dword ptr [rdi+0ACh]
000007fe`fae420e6 8bd3 mov edx,ebx
000007fe`fae420e8 89442428 mov dword ptr [rsp+28h],eax
000007fe`fae420ec 488b87a0000000 mov rax,qword ptr [rdi+0A0h]
000007fe`fae420f3 4889442420 mov qword ptr [rsp+20h],rax
000007fe`fae420f8 e833550000 call iiscore!W3_RESPONSE::DoActualSendResponse (000007fe`fae47630)
...[생략]...
DoActualSendResponse를 호출하기까지 rcx가 변경되는 곳은 다음의 2개 코드만 있습니다.
000007fe`fae420bc 488b8f88000000 mov rcx,qword ptr [rdi+88h]
...[생략]...
000007fe`fae420d4 4881c1e0010000 add rcx,1E0h
오호... 그런데 rdi 값은 이전에 DoActualSendResponse의 prolog에서 스택에 보관해 둔 적이 있습니다. 게다가 NOTIFICATION_SEND_RESPONSE::DoWork의 코드를 봐도 W3_RESPONSE::DoActualSendResponse 함수가 호출되기까지 rdi를 딱히 변경한 코드가 없으니 그대로 사용해도 되겠습니다.
이렇게 해서 rdi == 00000000249644e8 값에 0x88을 더하고 그 주소의 값을 windbg의 메모리 창으로 살펴보니 0000000003af2e00 값이 나왔습니다. 이로써 첫 번째 인자에 해당하는 rcx의 값까지 구했습니다.
mov rcx, qword ptr [rdi+88h] ; 0000000003af2e00 at 00000000`24964570 (00000000249644e8 + 0x88)
add rcx, 1E0h
// 따라서 0000000003af2e00 + 1e0 == 0000000003af2fe0 (10진수 61,812,704)
rcx == 0000000003af2fe0
rdx == 000007fe00503350
r8 == 0000000100000002
r9 == 0000000026c8d110
이 값을 kv로 나온 인자 값과 비교해 볼까요?
0:210> kv
...[생략]...
# Child-SP RetAddr : Args to Child
14 00000000`26c8c900 000007fe`fae4769c : 0000f377`71821f66 000007fe`f8897f95 00000000`26c8d1d8 00000000`24a5f960 : ntdll!KiUserExceptionDispatch+0x2e (TrapFrame @ 00000000`26c8cd28)
15 00000000`26c8d020 000007fe`fae420fd : 000007ff`00612020 000007fe`00503350 00000001`00000002 00000000`26c8d110 : iiscore!W3_RESPONSE::DoActualSendResponse+0x6c
16 00000000`26c8d0d0 000007fe`fae475d6 : 00000000`24964178 00000000`00000001 00000000`26c8d210 000007fe`fd01197f : iiscore!NOTIFICATION_SEND_RESPONSE::DoWork+0xbd
...[생략]...
보는 바와 같이 첫 번째 인자의 값이 다릅니다.
rcx == 0000000003af2fe0 != 000007ff`00612020
rdx == 000007fe00503350 == 000007fe`00503350
r8 == 0000000100000002 == 00000001`00000002
r9 == 0000000026c8d110 == 00000000`26c8d110
그래도 이 정도 했으면 요령이 생겼습니다. 함수의 prolog 코드에 나온 mov 명령어만 잘 봐도,
iiscore!W3_RESPONSE::DoActualSendResponse:
000007fe`fae47630 4c894c2420 mov qword ptr [rsp+20h],r9
000007fe`fae47635 4489442418 mov dword ptr [rsp+18h],r8d
000007fe`fae4763a 89542410 mov dword ptr [rsp+10h],edx
...[생략]...
kv의 출력 결과에 나온 값들 중 몇 개를 신뢰할 수 있는지 알 수 있으므로 이제부터는 일일이 인자 값을 구해야 하는 수고는 약간 덜 수 있습니다.
자, 그럼 지금까지 모은 정보를 가지고 DoActualSendResponse의 충돌 원인을 (수작업으로) 재현해 보겠습니다.
어셈블리 코드에 따라 레지스터 정보와 그것이 가리키는 주소를 메모리 창에 확인해 보니 대충 다음과 같은 결과를 얻었습니다.
iiscore!W3_RESPONSE::DoActualSendResponse:
...[생략]...
000007fe`fae4764c 488bd9 mov rbx,rcx ; rbx == 0000000003af2fe0
000007fe`fae4764f 488b4920 mov rcx,qword ptr [rcx+20h] ; rcx == 000007fefae76738
000007fe`fae47653 418bf0 mov esi,r8d ; esi == 2
000007fe`fae47656 4c8ba1d0010000 mov r12,qword ptr [rcx+1D0h] ; r12 == ffffffff00000018
000007fe`fae4765d 4533ff xor r15d,r15d ; r15d == 0
000007fe`fae47660 83e602 and esi,2 ; esi == 2 & 2 == 2
000007fe`fae47663 418be8 mov ebp,r8d ; ebp == 2
000007fe`fae47666 7528 jne iiscore!W3_RESPONSE::DoActualSendResponse+0x60 (000007fe`fae47690)
000007fe`fae47668 81791000080000 cmp dword ptr [rcx+10h],800h ; 000007fefae44050, 800h
000007fe`fae4766f 761f jbe iiscore!W3_RESPONSE::DoActualSendResponse+0x60 (000007fe`fae47690)
000007fe`fae47671 4439b9dc1f0000 cmp dword ptr [rcx+1FDCh],r15d
000007fe`fae47678 7416 je iiscore!W3_RESPONSE::DoActualSendResponse+0x60 (000007fe`fae47690)
000007fe`fae4767a 488b81d01f0000 mov rax,qword ptr [rcx+1FD0h]
000007fe`fae47681 f08380d4000000ff lock add dword ptr [rax+0D4h],0FFFFFFFFh
000007fe`fae47689 4489b9dc1f0000 mov dword ptr [rcx+1FDCh],r15d
000007fe`fae47690 488b4b20 mov rcx,qword ptr [rbx+20h] ; rcx == 000007fefae76738
000007fe`fae47694 4c89742468 mov qword ptr [rsp+68h],r14
000007fe`fae47699 488b01 mov rax,qword ptr [rcx] ; rax == 000007fefae5a140
000007fe`fae4769c ff5028 call qword ptr [rax+28h] ; [rax + 0x28h] == 90909090909090c3 at 000007fe`fae5a168
...[생략]...
사실 대부분의 코드는 볼 필요 없고, 위의 코드에서 call 연산과 관계된 파란색 굵은 코드만 살피면 됩니다.
rcx 값이 일단 rbx로 보존되었고, 이후 rbx 값은 전혀 변하지 않았습니다. 따라서, 마지막 4줄의 코드에서 [rbx + 20h]의 값은 사실상 DoActualSendResponse 함수가 시작된 시점의 rcx 값을 사용할 수 있으므로 [rcx + 20h] == [00000000`03af3000]에 해당합니다. [00000000`03af3000] 주소의 값을 확인해 보니 000007fefae76738이었고, 다시 그 주소의 값을 rax에 대입하고 있는데 그 값이 "000007fefae5a140"이었습니다. 결국 call 코드는 [000007fefae5a140 + 28h] == [000007fe`fae5a168] 주소가 가리키는 값을 꺼내와 호출하는데 그 값이 "90909090909090c3"입니다. 그냥 봐도 알 수 있지만 이는 올바르지 않는 코드 영역이고 실제로 u 명령어로도 확인할 수 있습니다.
0:210> u 90909090909090c3
90909090`909090c3 ?? ???
^ Memory access error in 'u 90909090909090c3'
자, 여기까지 힘겹게 분석을 했는데 약간 맥빠지는 이야기일 수 있지만 이러한 과정을 한 방에 알아낼 수 있는 명령어가 있습니다. 바로 "!analyze -v"가 그것입니다.
0:210> !analyze -v
...[생략]...
CONTEXT: 0000000026c8c900 -- (.cxr 0x26c8c900)
rax=000007fefae5a140 rbx=0000000003af2fe0 rcx=000007fefae76738
rdx=0000000000503350 rsi=0000000000000002 rdi=00000000249644e8
rip=000007fefae4769c rsp=0000000026c8d020 rbp=0000000000000002
r8=0000000000000002 r9=0000000026c8d110 r10=0000000000000000
r11=0000000026c8cee0 r12=ffffffff00000018 r13=0000000000000000
r14=0000000003af3000 r15=0000000000000000
iopl=0 nv up ei pl nz na pe nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010202
iiscore!W3_RESPONSE::DoActualSendResponse+0x6c:
000007fe`fae4769c ff5028 call qword ptr [rax+28h] ds:000007fe`fae5a168=90909090909090c3
Resetting default scope
FAULTING_IP:
iiscore!W3_RESPONSE::DoActualSendResponse+6c
000007fe`fae4769c ff5028 call qword ptr [rax+28h]
EXCEPTION_RECORD: 0000000026c8cdf0 -- (.exr 0x26c8cdf0)
ExceptionAddress: 000007fefae4769c (iiscore!W3_RESPONSE::DoActualSendResponse+0x000000000000006c)
ExceptionCode: c0000005 (Access violation)
ExceptionFlags: 00000000
NumberParameters: 2
Parameter[0]: 0000000000000000
Parameter[1]: ffffffffffffffff
Attempt to read from address ffffffffffffffff
...[생략]...
위의 "call qword ptr [rax+28h] ds:000007fe`fae5a168=90909090909090c3" 결과에서 보듯이 [rax+28h]의 값이 90909090909090c3임을 간단하게 분석해서 출력해 주고 있습니다.
여기서, "!analyze -v"가 수행하는 2가지 명령어가 핵심입니다.
.cxr 0x26c8c900
.exr 0x26c8cdf0
그런데 .cxr, .exr의 명령어에 전달한 값은 어디서 온 것일까요? 일단, x86 환경에서는 다음의 글에 방법이 나옵니다.
HOW TO: Find the Problem Exception Stack When You Receive an UnhandledExceptionFilter Call in the Stack Trace
; https://support.microsoft.com/en-us/help/313109/how-to-find-the-problem-exception-stack-when-you-receive-an-unhandlede
위의 글을 읽고 보니, 왠지 x64의 경우 호출 스택에 혹시 있지 않을까 싶었는데요, 실제로 kv 명령어로 출력된 값을 보니,
0:210> kv
# Child-SP RetAddr : Args to Child : Call Site
00 00000000`26c8ab08 000007fe`fd0110ac : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!ZwWaitForSingleObject+0xa
...[생략]...
0e 00000000`26c8b0d0 000007fe`f8899f42 : 00000000`00000001 00000000`13ddeaa0 00000000`1a161168 00000000`00000001 : clr!ExceptionTracker::NotifyDebuggerOfStub+0x58
0f 00000000`26c8b120 000007fe`f8a01e0d : 00000000`26c8d2c8 00000000`26c8b2a0 00000000`26c8d290 00000000`00000000 : clr!ExceptionTracker::ProcessExplicitFrame+0x122
10 00000000`26c8b1a0 000007fe`f889a22b : 00000000`00000000 00000000`13ddeaa0 00000000`26c8c2b0 00000000`26c8d290 : clr!ExceptionTracker::ProcessOSExceptionNotification+0x1cc
11 00000000`26c8c120 00000000`76d8812d : 00000000`26c8cdf0 00000000`26c8d290 00000000`26c8c900 00000000`26c8c2b0 : clr!ProcessCLRException+0x21b
12 00000000`26c8c1f0 00000000`76d7855f : 00000000`00000000 000007fe`fad1b500 00000001`00000000 00000000`26c8d290 : ntdll!RtlpExecuteHandlerForException+0xd
13 00000000`26c8c220 00000000`76dabcb8 : 00000000`26c8cdf0 00000000`26c8c900 00000000`00000000 00000000`00000000 : ntdll!RtlDispatchException+0x45a
14 00000000`26c8c900 000007fe`fae4769c : 0000f377`71821f66 000007fe`f8897f95 00000000`26c8d1d8 00000000`24a5f960 : ntdll!KiUserExceptionDispatch+0x2e (TrapFrame @ 00000000`26c8cd28)
15 00000000`26c8d020 000007fe`fae420fd : 000007ff`00612020 000007fe`00503350 00000001`00000002 00000000`26c8d110 : iiscore!W3_RESPONSE::DoActualSendResponse+0x6c
...
exr에 전달할 주소의 값이 ProcessCLRException, RtlDispatchException의 첫 번째 인자로 있는 것을 볼 수 있습니다. 그다음, cxr의 주소 역시 ProcessCLRException, RtlDispatchException 함수의 인자 목록에도 있고 결정적으로 KiUserExceptionDispatch의 Child-SP인 점을 알 수 있습니다.
11 00000000`26c8c120 00000000`76d8812d : 00000000`26c8cdf0 00000000`26c8d290 00000000`26c8c900 00000000`26c8c2b0 : clr!ProcessCLRException+0x21b
12 00000000`26c8c1f0 00000000`76d7855f : 00000000`00000000 000007fe`fad1b500 00000001`00000000 00000000`26c8d290 : ntdll!RtlpExecuteHandlerForException+0xd
13 00000000`26c8c220 00000000`76dabcb8 : 00000000`26c8cdf0 00000000`26c8c900 00000000`00000000 00000000`00000000 : ntdll!RtlDispatchException+0x45a
14 00000000`26c8c900 000007fe`fae4769c : 0000f377`71821f66 000007fe`f8897f95 00000000`26c8d1d8 00000000`24a5f960 : ntdll!KiUserExceptionDispatch+0x2e (TrapFrame @ 00000000`26c8cd28)
15 00000000`26c8d020 000007fe`fae420fd : 000007ff`00612020 000007fe`00503350 00000001`00000002 00000000`26c8d110 : iiscore!W3_RESPONSE::DoActualSendResponse+0x6c
16 00000000`26c8d0d0 000007fe`fae475d6 : 00000000`24964178 00000000`00000001 00000000`26c8d210 000007fe`fd01197f : iiscore!NOTIFICATION_SEND_RESPONSE::DoWork+0xbd
...
일단, 메모해 두고 나중에 한번 더 확인해야겠습니다. ^^
참고로 .cxr의 경우 해당 시점의 문맥으로 복원하는 것이기 때문에 예외가 발생한 시점의 레지스터 상태들이 구해집니다. 즉, 이 글의 처음에 시작했던 방법으로 레지스터를 애써 복원할 필요도 없었던 것입니다.
0:210> .cxr 00000000`26c8c900
rax=000007fefae5a140 rbx=0000000003af2fe0 rcx=000007fefae76738
rdx=0000000000503350 rsi=0000000000000002 rdi=00000000249644e8
rip=000007fefae4769c rsp=0000000026c8d020 rbp=0000000000000002
r8=0000000000000002 r9=0000000026c8d110 r10=0000000000000000
r11=0000000026c8cee0 r12=ffffffff00000018 r13=0000000000000000
r14=0000000003af3000 r15=0000000000000000
iopl=0 nv up ei pl nz na pe nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010202
iiscore!W3_RESPONSE::DoActualSendResponse+0x6c:
000007fe`fae4769c ff5028 call qword ptr [rax+28h] ds:000007fe`fae5a168=90909090909090c3
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]