windbg 분석 - webengine4.dll의 MgdExplicitFlush에서 발생한 System.AccessViolationException의 crash 문제 (2)
예전에 아래의 글을 써본 경험으로,
x64 콜 스택 인자 추적과 windbg의 Child-SP, RetAddr, Args to Child 값 확인
; https://www.sysnet.pe.kr/2/0/10832
지난번의 crash 사례를 분석했었는데요. ^^
windbg 분석 - webengine4.dll의 MgdExplicitFlush에서 발생한 System.AccessViolationException의 crash 문제
; https://www.sysnet.pe.kr/2/0/11250
그렇다면 정상적인 경우 iiscore!W3_RESPONSE::DoActualSendResponse 함수는 어떤 문맥을 보였어야 할까요? 비정상 상황을 목격했으니 비교를 한번 해보고 싶어 구성해 봤습니다.
일단, 지난번 crash는 Windows Server 2008 R2의 IIS에서 DoActualSendResponse 함수 호출 시 발생한 것이므로 적어도 그 함수가 호출되면서 최대한 유사한 상황을 만들 수 있도록 역시 2008 R2에서 다음과 같이 간단한 ASP.NET 웹 페이지를 만든 후,
<%@ Page Language="C#" AutoEventWireup="true" CodeBehind="Default.aspx.cs" Inherits="WebApplication1.Default" %>
<!DOCTYPE html>
<html xmlns="http://www.w3.org/1999/xhtml">
<head runat="server">
<title></title>
</head>
<body>
<form id="form1" runat="server">
<div>
test
</div>
</form>
</body>
</html>
using System;
namespace WebApplication1
{
public partial class Default : System.Web.UI.Page
{
protected void Page_Load(object sender, EventArgs e)
{
}
}
}
w3wp.exe를 띄우고 windbg로 붙였습니다. 그다음 BreakPoint를 다음과 같이 걸어두고,
0:044> bp iiscore!W3_RESPONSE::DoActualSendResponse
웹 브라우저로 방문했더니 BP가 걸렸습니다.
0:033> g
Breakpoint 0 hit
iiscore!W3_RESPONSE::DoActualSendResponse:
000007fe`f4317630 4c894c2420 mov qword ptr [rsp+20h],r9 ss:00000000`08f4ec88=0000000000000000
DoActualSendResponse의 역어셈블 코드를 보고,
iiscore!W3_RESPONSE::DoActualSendResponse:
...[생략]...
000007fe`f4317690 488b4b20 mov rcx,qword ptr [rbx+20h]
000007fe`f4317694 4c89742468 mov qword ptr [rsp+68h],r14
000007fe`f4317699 488b01 mov rax,qword ptr [rcx]
000007fe`f431769c ff5028 call qword ptr [rax+28h] ds:000007fe`f43462a0={iiscore!W3_CONTEXT::GetResponseHeadersSent (000007fe`f4312ea8)}
000007fe`f431769f 85c0 test eax,eax
...[생략]...
지난번 문제가 되었던 "call qword ptr [rax+28h]" 코드에 BP를 걸어 진행하면,
0:027> bp 000007fe`f431769c
0:027> g
Breakpoint 1 hit
iiscore!W3_RESPONSE::DoActualSendResponse+0x6c:
000007fe`f431769c ff5028 call qword ptr [rax+28h] ds:000007fe`f43462a0={iiscore!W3_CONTEXT::GetResponseHeadersSent (000007fe`f4312ea8)}
벌써부터 결과가 다르군요. 문제가 발생했을 때는 [rax + 0x28h]의 값이 "90909090909090c3"이었는데 이제는 정상적으로 000007fe`f4312ea8를 가리키고 그 함수가 GetResponseHeadersSent라는 것도 알려주고 있습니다.
그럼, 인자 상황을 한번 볼까요? 지난번 실습을 했으니, 이제 DoActualSendResponse의 prolog로부터,
iiscore!W3_RESPONSE::DoActualSendResponse:
000007fe`f4317630 4c894c2420 mov qword ptr [rsp+20h],r9 ss:00000000`08f4ec88=0000000000000000
000007fe`f4317635 4489442418 mov dword ptr [rsp+18h],r8d
000007fe`f431763a 89542410 mov dword ptr [rsp+10h],edx
000007fe`f431763e 53 push rbx
000007fe`f431763f 55 push rbp
...[생략]...
처음 3개의 인자 값이 kv의 결과로 나온다는 것을 압니다.
0:027> kv
Child-SP RetAddr : Args to Child : Call Site
00000000`08f4ebc0 000007fe`f43120fd : 00000000`01303b08 000007fe`00000001 000007fe`00000000 00000000`08f4ecb0 : iiscore!W3_RESPONSE::DoActualSendResponse+0x6c
00000000`08f4ec70 000007fe`f43175d6 : 00000000`09875b78 00000000`00000000 00000000`08f4edb4 00000000`00000000 : iiscore!NOTIFICATION_SEND_RESPONSE::DoWork+0xbd
...[생략]...
00000000`08f4fc50 00000000`76d1a561 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : kernel32!BaseThreadInitThunk+0xd
00000000`08f4fc80 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!RtlUserThreadStart+0x1d
rdx == 000007fe`00000001
r8 == 000007fe`00000000
r9 == 00000000`08f4ecb0
rcx는 역시 지난번 글에서 설명한 x64 ABI 규칙에 따라 직접 구해야 합니다. 그럼 rcx == 0x1303a80이 나옵니다. 정리하면 대충 이렇습니다.
rcx == 00000000`01303c60
rdx == 000007fe`00000001, edx = 1
r8 == 000007fe`00000000, r8d = 0
r9 == 00000000`08f4ecb0
여기까지 정리해 보면, 대략 다음과 같은 코드를 유추할 수 있습니다.
class W3_RESPONSE
{
// ... class 필드들...
W3_CONTEXT *_pContext; // 이 필드는 W3_RESPONSE 클래스의 메모리 layout에서 +0x20 지점에 위치
... DoActualSendResponse(void *this, ...) // this == 01303c60
{
W3_CONTEXT *pContext = _pContext; // [this + 20h] 주소의 값 == 01303a80
if (pContext->GetResponseHeadersSent() == TRUE)
{
//....
}
}
}
그럼, 도대체
지난번의 문제는 뭐였을까요?
GetResponseHeadersSent 함수가 아닌 엉뚱하게 90909090909090c3 값을 가리키고 있는데, 어쩌면 GetResponseHeadersSent 함수 호출 시 넘겨져온 this 포인터 값이 비정상적이었음을 알 수 있습니다.
이를 알아보기 위해 (crash가 발생했던) DoActualSendResponse의 (rbx에 보관된) rcx 값이 진짜 W3_RESPONSE였는지 dqs 명령어로 확인해야 합니다.
0:210> dqs 0000000003af2fe0
00000000`03af2fe0 00000000`00000000
00000000`03af2fe8 0020d0b7`00000000
00000000`03af2ff0 00000000`03af2e20
00000000`03af2ff8 00000000`00000000
00000000`03af3000 000007fe`fae76738 iiscore!W3_RESPONSE::`vftable'
00000000`03af3008 000007fe`fae75f58 iiscore!W3_RESPONSE::`vftable'
00000000`03af3010 00000000`00000000
00000000`03af3018 000007fe`fae75f98 iiscore!W3_RESPONSE::`vftable'
00000000`03af3020 00000000`03af2e20
00000000`03af3028 00010001`00000000
00000000`03af3030 00560020`000200c8
00000000`03af3038 00000000`249643f0
00000000`03af3040 00000000`00000008
00000000`03af3048 00000000`03af32c0
00000000`03af3050 00000000`00000000
00000000`03af3058 00000000`00000000
보는 바와 같이 00000000`00000000 값을 가지고 있습니다. 반면, 정상적인 상황의 DoActualSendResponse에 넘겨졌던 this 포인터(rcx)는 이렇게 나옵니다.
0:027> dqs 1303c60
00000000`01303c60 000007fe`f4346738 iiscore!W3_RESPONSE::`vftable'
00000000`01303c68 000007fe`f4345f58 iiscore!W3_RESPONSE::`vftable'
00000000`01303c70 00000000`00000000
00000000`01303c78 000007fe`f4345f98 iiscore!W3_RESPONSE::`vftable'
00000000`01303c80 00000000`01303a80
00000000`01303c88 00010001`00000000
00000000`01303c90 00000000`000200c8
00000000`01303c98 000007fe`f4346c40 iiscore!`string'
00000000`01303ca0 00000000`00000003
00000000`01303ca8 00000000`01303f20
00000000`01303cb0 00000000`00000000
00000000`01303cb8 00000000`00000000
00000000`01303cc0 00000000`00000007
00000000`01303cc8 00000000`013059b8
00000000`01303cd0 00000000`00000000
00000000`01303cd8 00000000`00000000
위의 DoActualSendResponse는 W3_CONTEXT::GetResponseHeadersSent를 호출하기 위해 DoActualSendResponse this 포인터에 +20h 오프셋의 값을 전달하고 있습니다.
mov rcx,qword ptr [rbx+20h]
정상적인 경우 00000000`01303c60 + 0x20 == 00000000`01303c80인데, dqs 결과를 보면 이 주소는 00000000`01303a80 값이고 이를 확인하면,
0:027> dqs 00000000`01303a80
00000000`01303a80 000007fe`f4346278 iiscore!W3_MAIN_CONTEXT::`vftable'
00000000`01303a88 000007fe`f4345468 iiscore!W3_MAIN_CONTEXT::`vftable'
00000000`01303a90 00000000`00001000
00000000`01303a98 00000000`ffffffff
00000000`01303aa0 04222bc8`04222bc8
...[생략]...
0:027> dqs 000007fe`f4346278
000007fe`f4346278 000007fe`f4311800 iiscore!W3_CONTEXT::GetSite ; +0
000007fe`f4346280 000007fe`f43121ac iiscore!W3_CONTEXT::GetApplication ; +8
000007fe`f4346288 000007fe`f433ab90 iiscore!W3_CONTEXT::GetConnection ; +10
000007fe`f4346290 000007fe`f431acd0 iiscore!W3_CONTEXT::GetRequest ; +18
000007fe`f4346298 000007fe`f4312e98 iiscore!W3_CONTEXT::GetResponse ; +20
000007fe`f43462a0 000007fe`f4312ea8 iiscore!W3_CONTEXT::GetResponseHeadersSent ; +28h에 위치한 바로 그 함수
000007fe`f43462a8 000007fe`f43125c0 iiscore!W3_CONTEXT::GetUser
000007fe`f43462b0 000007fe`f43141c0 iiscore!W3_CONTEXT::GetModuleContextContainer
...[생략]...
vtable에 위치한 GetResponseHeadersSent 함수를 구하게 됩니다. 하지만 crash가 발생했던 경우를 다시 보면,
0:210> dqs 0000000003af2fe0
00000000`03af2fe0 00000000`00000000 ; 비정상적으로 쌓인 스택
00000000`03af2fe8 0020d0b7`00000000 ; 비정상적으로 쌓인 스택
00000000`03af2ff0 00000000`03af2e20 ; 비정상적으로 쌓인 스택
00000000`03af2ff8 00000000`00000000 ; 비정상적으로 쌓인 스택
00000000`03af3000 000007fe`fae76738 iiscore!W3_RESPONSE::`vftable' ; 원래 DoActualSendResponse를 호출했을 당시에 가리키고 있어야 할 this 포인터 값
00000000`03af3008 000007fe`fae75f58 iiscore!W3_RESPONSE::`vftable'
00000000`03af3010 00000000`00000000
00000000`03af3018 000007fe`fae75f98 iiscore!W3_RESPONSE::`vftable'
00000000`03af3020 00000000`03af2e20 ; 정상적인 경우였다면 이 값(this + 0x20h)이 "call qword ptr [rax+28h]" 호출의 this(rcx) 포인터 역할을 했어야 함.
00000000`03af3028 00010001`00000000
00000000`03af3030 00560020`000200c8
00000000`03af3038 00000000`249643f0
00000000`03af3040 00000000`00000008
00000000`03af3048 00000000`03af32c0
00000000`03af3050 00000000`00000000
00000000`03af3058 00000000`00000000
원래 00000000`03af3000 값이 DoActualSendResponse의 this 포인터(rcx)로 넘어왔다고 가정해 00000000`03af2e20를 crash 덤프 상에서 분석해 보니,
0:210> dqs 00000000`03af2e20
00000000`03af2e20 000007fe`fae76278 iiscore!W3_MAIN_CONTEXT::`vftable'
00000000`03af2e28 000007fe`fae75468 iiscore!W3_MAIN_CONTEXT::`vftable'
00000000`03af2e30 00000000`00000080
...[생략]...
00000000`03af2e90 00000000`0166c4ec
00000000`03af2e98 0020b97c`00000031
0:210> dqs 000007fe`fae76278
000007fe`fae76278 000007fe`fae41800 iiscore!W3_CONTEXT::GetSite ; +0
000007fe`fae76280 000007fe`fae421ac iiscore!W3_CONTEXT::GetApplication ; +8
000007fe`fae76288 000007fe`fae6ab90 iiscore!W3_CONTEXT::GetConnection ; +10
000007fe`fae76290 000007fe`fae4acd0 iiscore!W3_CONTEXT::GetRequest ; +18
000007fe`fae76298 000007fe`fae42e98 iiscore!W3_CONTEXT::GetResponse ; +20
000007fe`fae762a0 000007fe`fae42ea8 iiscore!W3_CONTEXT::GetResponseHeadersSent ; +28 바로 그 함수의 위치
000007fe`fae762a8 000007fe`fae425c0 iiscore!W3_CONTEXT::GetUser
...[생략]...
000007fe`fae762f0 000007fe`fae46230 iiscore!W3_CONTEXT::GetServerVariable
정상적인 GetResponseHeadersSent 함수의 위치를 구할 수 있었습니다. 그렇다면 결국 스택을 가리키는 RSP의 값이 정상적인 상황보다 +20h의 위치를 가리키고 있어서 DoActualSendResponse의 this 포인터 값이 틀어졌고 결국 crash로 이어졌던 것으로 결론을 내릴 수 있습니다.
그런데, 과연 어떤 코드가 스택의 비정상을 초래한 것일까요? 일단 IIS 쪽 소스 코드도 없고, 단순히 덤프 파일 하나만 가지고는 분석이 여간 힘든 것이 아닙니다. 그나마 이런 상황에서 쉬운 방법이 있다면 이렇게 유사한 상황을 만들어서 콜 스택을 확인 후 개별 호출 프레임마다 Child-SP의 값을 기준으로 dqs 출력의 값을 비교해 보고 스택의 비정상적인 동작이 있었던 함수를 찾아내 어셈블리 코드까지 보면서 검사하는 것이 최선입니다.
물론 그런 경우에는 동일한 콜 스택을 보이도록 유사 응용 프로그램을 만들어야 하는데, 아쉽게도 위의 사례에서는 해당 웹 애플리케이션의 콜 스택과 같은 상황을 재현할 수 없었습니다. (ASP.NET 분야도 프레임워크가 다양한데다 개발사 나름 확장하는 것도 있다 보니!)
실력 있는 분들이라면, 이런 상황에서도 순수하게 호출 스택에 나온 함수들의 어셈블리 코드를 파헤쳐 가며 보겠지만 제가 아직 그 수준까지는 안되는군요. ^^
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]