2016年5月4日 星期三

記憶體除錯經驗:到底是誰在我的堆疊裡寫了個“2”?!

作者:TAUTVYDAS ZILYS 原文連結

Hi! 我叫Tautvydas,是Unity官方Windows團隊的一名軟體工程師。今天這篇文章將為大家分享一個難以循跡的記憶體除錯Bug故事。


幾個星期之前我們收到了客戶的一個Bug回報,說他們的遊戲在使用IL2CPP時當機了。QA確認了這個Bug並將這Bug分配給我來修。這個專案很大(當然還不是最大的),在我的機器上打包這個專案就花了40分鐘。Bug報告上的操作指示是這麼寫的“玩這個遊戲5-10分鐘直到它當機”。果然在遵照指示玩了一段時間後遊戲當了。我打開WinDbg準備定位Bug位置。不幸的是堆疊追蹤是有問題的:

0:049> k
# Child-SP RetAddr Call Site
00 00000022`e25feb10 00000000`00000010 0x00007ffa`00000102
0:050> u 0x00007ffa`00000102 L10
00007ffa`00000102 ?? ???
^ Memory access error in ‘u 0x00007ffa`00000102 l10’


顯然系統在嘗試執行一個無效的記憶體位址。儘管堆疊回溯(stacktrace)已毀損,我希望只是整個堆疊裡的部分毀損了,這樣我還可以重過去的記憶體堆疊指標來重建它。這讓我意識到下一步應該查看哪裡:

0:049> dps @rsp L200
……………
00000022`e25febd8 00007ffa`b1fdc65c ucrtbased!heap_alloc_dbg+0x1c [d:\th\minkernel\crts\ucrt\src\appcrt\heap\debug_heap.cpp @ 447]
00000022`e25febe0 00000000`00000004
00000022`e25febe8 00000022`00000001
00000022`e25febf0 00000022`00000000
00000022`e25febf8 00000000`00000000
00000022`e25fec00 00000022`e25fec30
00000022`e25fec08 00007ffa`99b3d3ab UnityPlayer!std::_Vector_alloc<std::_Vec_base_types<il2cpp::os::PollRequest,std::allocator<il2cpp::os::PollRequest> > >::_Get_data+0x2b [ c:\program files (x86)\microsoft visual studio 14.0\vc\include\vector @ 642]
00000022`e25fec10 00000022`e25ff458
00000022`e25fec18 cccccccc`cccccccc
00000022`e25fec20 cccccccc`cccccccc
00000022`e25fec28 00007ffa`b1fdf54c ucrtbased!_calloc_dbg+0x6c [d:\th\minkernel\crts\ucrt\src\appcrt\heap\debug_heap.cpp @ 511]
00000022`e25fec30 00000000`00000010
00000022`e25fec38 00007ffa`00000001
……………
00000022`e25fec58 00000000`00000010
00000022`e25fec60 00000022`e25feca0
00000022`e25fec68 00007ffa`b1fdb69e ucrtbased!calloc+0x2e [d:\th\minkernel\crts\ucrt\src\appcrt\heap\calloc.cpp @ 25]
00000022`e25fec70 00000000`00000001
00000022`e25fec78 00000000`00000010
00000022`e25fec80 cccccccc`00000001
00000022`e25fec88 00000000`00000000
00000022`e25fec90 00000022`00000000
00000022`e25fec98 cccccccc`cccccccc
00000022`e25feca0 00000022`e25ff3f0
00000022`e25feca8 00007ffa`99b3b646 UnityPlayer!il2cpp::os::SocketImpl::Poll+0x66 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\win32\socketimpl.cpp @ 1429]
00000022`e25fecb0 00000000`00000001
00000022`e25fecb8 00000000`00000010
……………
00000022`e25ff3f0 00000022`e25ff420
00000022`e25ff3f8 00007ffa`99c1caf4 UnityPlayer!il2cpp::os::Socket::Poll+0x44 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\socket.cpp @ 324]
00000022`e25ff400 00000022`e25ff458
00000022`e25ff408 cccccccc`ffffffff
00000022`e25ff410 00000022`e25ff5b4
00000022`e25ff418 00000022`e25ff594
00000022`e25ff420 00000022`e25ff7e0
00000022`e25ff428 00007ffa`99b585f8 UnityPlayer!il2cpp::vm::SocketPollingThread::RunLoop+0x268 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\vm\threadpool.cpp @ 452]
00000022`e25ff430 00000022`e25ff458
00000022`e25ff438 00000000`ffffffff
……………
00000022`e25ff7d8 00000022`e25ff6b8
00000022`e25ff7e0 00000022`e25ff870
00000022`e25ff7e8 00007ffa`99b58d2c UnityPlayer!il2cpp::vm::SocketPollingThreadEntryPoint+0xec [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\vm\threadpool.cpp @ 524]
00000022`e25ff7f0 00007ffa`9da83610 UnityPlayer!il2cpp::vm::g_SocketPollingThread
00000022`e25ff7f8 00007ffa`99b57700 UnityPlayer!il2cpp::vm::FreeThreadHandle [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\vm\threadpool.cpp @ 488]
00000022`e25ff800 00000000`0000106c
00000022`e25ff808 cccccccc`cccccccc
00000022`e25ff810 00007ffa`9da83610 UnityPlayer!il2cpp::vm::g_SocketPollingThread
00000022`e25ff818 000001c4`1705f5c0
00000022`e25ff820 cccccccc`0000106c
……………
00000022`e25ff860 00005eaa`e9a6af86
00000022`e25ff868 cccccccc`cccccccc
00000022`e25ff870 00000022`e25ff8d0
00000022`e25ff878 00007ffa`99c63b52 UnityPlayer!il2cpp::os::Thread::RunWrapper+0xd2 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\thread.cpp @ 106]
00000022`e25ff880 00007ffa`9da83610 UnityPlayer!il2cpp::vm::g_SocketPollingThread
00000022`e25ff888 00000000`00000018
00000022`e25ff890 cccccccc`cccccccc
……………
00000022`e25ff8a8 000001c4`15508c90
00000022`e25ff8b0 cccccccc`00000002
00000022`e25ff8b8 00007ffa`99b58c40 UnityPlayer!il2cpp::vm::SocketPollingThreadEntryPoint [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\vm\threadpool.cpp @ 494]
00000022`e25ff8c0 00007ffa`9da83610 UnityPlayer!il2cpp::vm::g_SocketPollingThread
00000022`e25ff8c8 000001c4`155a5890
00000022`e25ff8d0 00000022`e25ff920
00000022`e25ff8d8 00007ffa`99c19a14 UnityPlayer!il2cpp::os::ThreadStartWrapper+0x54 [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\win32\threadimpl.cpp @ 31]
00000022`e25ff8e0 000001c4`155a5890
……………
00000022`e25ff900 cccccccc`cccccccc
00000022`e25ff908 00007ffa`99c63a80 UnityPlayer!il2cpp::os::Thread::RunWrapper [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\thread.cpp @ 80]
00000022`e25ff910 000001c4`155a5890
……………
00000022`e25ff940 000001c4`1e0801b0
00000022`e25ff948 00007ffa`e6858102 KERNEL32!BaseThreadInitThunk+0x22
00000022`e25ff950 000001c4`1e0801b0
00000022`e25ff958 00000000`00000000
00000022`e25ff960 00000000`00000000
00000022`e25ff968 00000000`00000000
00000022`e25ff970 00007ffa`99c199c0 UnityPlayer!il2cpp::os::ThreadStartWrapper [ c:\users\tautvydas\builds\bin2\il2cppoutputproject\il2cpp\libil2cpp\os\win32\threadimpl.cpp @ 26]
00000022`e25ff978 00007ffa`e926c5b4 ntdll!RtlUserThreadStart+0x34
00000022`e25ff980 00007ffa`e68580e0 KERNEL32!BaseThreadInitThunk
這是對追蹤堆疊的粗略重建:
00000022`e25febd8 00007ffa`b1fdc65c ucrtbased!heap_alloc_dbg+0x1c […\appcrt\heap\debug_heap.cpp @ 447]
00000022`e25fec28 00007ffa`b1fdf54c ucrtbased!_calloc_dbg+0x6c […\appcrt\heap\debug_heap.cpp @ 511]
00000022`e25fec68 00007ffa`b1fdb69e ucrtbased!calloc+0x2e […\appcrt\heap\calloc.cpp @ 25]
00000022`e25feca8 00007ffa`99b3b646 UnityPlayer!il2cpp::os::SocketImpl::Poll+0x66 […\libil2cpp\os\win32\socketimpl.cpp @ 1429]
00000022`e25ff3f8 00007ffa`99c1caf4 UnityPlayer!il2cpp::os::Socket::Poll+0x44 […\libil2cpp\os\socket.cpp @ 324]
00000022`e25ff428 00007ffa`99b585f8 UnityPlayer!il2cpp::vm::SocketPollingThread::RunLoop+0x268 […\libil2cpp\vm\threadpool.cpp @ 452]
00000022`e25ff7e8 00007ffa`99b58d2c UnityPlayer!il2cpp::vm::SocketPollingThreadEntryPoint+0xec […\libil2cpp\vm\threadpool.cpp @ 524]
00000022`e25ff878 00007ffa`99c63b52 UnityPlayer!il2cpp::os::Thread::RunWrapper+0xd2 […\libil2cpp\os\thread.cpp @ 106]
00000022`e25ff8d8 00007ffa`99c19a14 UnityPlayer!il2cpp::os::ThreadStartWrapper+0x54 […\libil2cpp\os\win32\threadimpl.cpp @ 31]
00000022`e25ff948 00007ffa`e6858102 KERNEL32!BaseThreadInitThunk+0x22
00000022`e25ff978 00007ffa`e926c5b4 ntdll!RtlUserThreadStart+0x34 
很了,現在我知道哪個執行緒崩潰了,就是IL2CPP執行時runtime socket輪詢處理執行緒。它的工作是當其它執行緒的socket準備好發送或接收資料時通知這些執行緒。運行機制是這樣的:有一個先進先出佇列來放置其它執行緒的socket輪詢請求。Socket輪詢處理執行緒會一個接一個從佇列中取出這些請求,呼叫select() 函數,當select()函數返回一個結果時,它會將執行緒池中原始請求的callback函數放入佇列。 

所以這裡一定有什麼東西在作怪。為了縮小範圍,我決定在這個執行緒裡大部分堆疊中放入“堆疊定位”。這是它的結構:

當這個結構體被建立時,它會向暫存中寫入 “0xDD”。被釋放時會檢查這些值有沒有變化。這個方法OK,遊戲不再當了!但是會出現斷言(asserting):


有甚麼東西觸發了堆疊定位的私有變數 - 這傢伙絕對不是甚麼好東西。我跑了好幾次結果都是一樣,它每次都會先在暫存中寫入一個“2”。查看記憶體圖,我發現看到的內容其實很熟悉:



這些值與一開始堆疊被篡改時看到的值是一樣的。我意識到之前導致程式當掉東西也正想修改定位。我先想到的是有某種緩衝區溢位,對記憶體的寫入超出了變數範圍。所以我開始在這個執行緒中的每個函式呼叫之前放置更多的定位。但是這個破壞行為似乎是隨機出現的,這方法無法找出導致這些問題的原因。

我發現當執行到其中一個定位時總會產生記憶體篡改。我需要能夠當場抓到導致記憶體被篡改的原因。所以我讓定位中的記憶體在整個生命週期都是唯讀的,所以我在建構函式中呼叫VirtualProtect() 將記憶體頁標記唯讀,在釋放時標記為可寫:

讓我驚訝的是,記憶體仍然會被篡改!Log如下:

Memory was corrupted at 0xd046ffeea8. It was readonly when it got corrupted.
CrashingGame.exe has triggered a breakpoint.

對我來說這是一個危險信號。居然有人有更改唯讀記憶體的權利,或者是在我設定唯讀之前就篡改了記憶體。因為我的存取權限是正常的,我只能假設是後者,所以我修改了程式來檢查記憶體內容是否在設定了值之後被修改:


我的懷疑得到了證實:

Memory was corrupted at 0x79b3bfea78.
CrashingGame.exe has triggered a breakpoint.

這時我想:“好吧,肯定是另外一個執行緒改了我的堆疊。肯定是。對吧?”唯一的調查途徑是使用資料(記憶體)中斷點來找出犯人。不幸的是在x86下同時只能監控四個記憶體位元,也就是說我只能監控最多32個位元組,而被篡改的記憶體的範圍有16KB。所以我需要找出在哪裡設置中斷點最好。我觀察篡改模式。首先,篡改似乎是隨機的,但這僅僅只是一個錯覺,這是由於ASLR(英文)的特性:每次我啟動遊戲,堆疊會被放置到記憶體的隨機位置,所以篡改的位置肯定是不同的。當我意識到這點之後,我就沒有在每次發現記憶體篡改後重啟遊戲,而是繼續執行。我發現在每次除錯過程中被篡改的記憶體位置是固定的。這就是說,一旦一次篡改過後,只要程式沒有中止,篡改都會發生在相同的記憶體位址:

Memory was corrupted at 0x90445febd8.
CrashingGame.exe has triggered a breakpoint.
Memory was corrupted at 0x90445febd8.
CrashingGame.exe has triggered a breakpoint.

我在這個記憶體位址加了中斷點不斷的觀察每次進入時的值0xDD。Visual Studio可以設置中斷點條件:所以我設定只在值是2的時候才中斷:


一分鐘之後,終於到了中斷點。我在除錯了3天之後才到達這一步。我終究取得了勝利,宣佈“終於逮到你了!”,我很樂觀的這麼認為:


接下來我充滿懷疑的看著除錯器,心裡不但沒有答案反而湧現更多疑問:“什麼?這怎麼可能?我要瘋掉了。。。”,我決定看一下反組譯的碼:



果然,它在修改這段記憶體的內容。但是它是寫入0xDD,不是0x02!通過查看記憶體視窗,發現整個區域都被篡改了:


我都快要用頭去撞牆了!我叫我的同事過來看看是不是漏掉了什麼。我們一起檢查了程式,卻找不出一點點可能導致這個奇怪問題的原因。然後我退一步嘗試想像可能會導致除錯器認為那段程式不是寫入“2”的原因。然後我得到了這麼一個假設的流程:
  1. mov byte ptr [rax], 寫入0DDh 到記憶體,CPU中斷執行來讓除錯工具檢視程式狀態 
  2. 記憶體被什麼東西篡改 
  3. 除錯工具檢視記憶體位址,發現裡面的值是“2”並且認為這個就是修改後的值 
那麼,當整個程式被除錯器凍結的時候誰可以修改記憶體內容呢?就我所知有兩種可能:另外一個緒或是作業系統核心幹的。對於這兩種情況傳統除錯工具無法查出,我們要使用Kernel除錯工具。

還好在Windows中設定
Kernel除錯非常容易。你需要兩台機器:一台執行除錯工具,另外一台被除錯的電腦,打開你要工作列視窗,然後輸入:


Host IP是執行除錯工具的機器的IP位址。它會使用指定埠來連接。埠可以選擇49152和65535之間的任意值。在輸入第二個命令並按下Enter,視窗會顯示金鑰(圖片已修改),這個金鑰會作為連接到除錯工具的密碼。在完成上述步驟後,重啟機器。
在另外一台機器上,打開WinDbg,點功能表中的File -> Kernel Debug,然後輸入埠和金鑰。


如果一切正常,當你按下Debug -> Break後會中斷執行。這時被除錯的機器會凍結,按下”g”會繼續執行。

然後我啟動了遊戲並且等著被中斷,這樣就可以找到被篡改的記憶體位址。

Memory was corrupted at 0x49d05fedd8.
CrashingGame.exe has triggered a breakpoint.

很好,現在我知道該在哪裡設定中斷點了,我從Kernel除錯工具來設定:

kd> !process 0 0
PROCESS ffffe00167228080
SessionId: 1 Cid: 26b8 Peb: 49cceca000 ParentCid: 03d8
DirBase: 1ae5e3000 ObjectTable: ffffc00186220d80 HandleCount:
Image: CrashingGame.exe
kd> .process /i ffffe00167228080
You need to continue execution (press ‘g’ ) for the context
to be switched. When the debugger breaks in again, you will be in
the new process context.
kd> g
Break instruction exception – code 80000003 (first chance)
nt!DbgBreakPointWithStatus:
fffff801`7534beb0 cc int 3
kd> .process
Implicit process is now ffffe001`66e9e080
kd> .reload /f
kd> ba w 1 0x00000049D05FEDD8 “.if (@@c++(*(char*)0x00000049D05FEDD8 == 2)) { k } .else { gc }”


一段時間過後,終於進入中斷點了。

# Child-SP RetAddr Call Site
00 ffffd000`23c1e980 fffff801`7527dc64 nt!IopCompleteRequest+0xef
01 ffffd000`23c1ea70 fffff801`75349953 nt!KiDeliverApc+0x134
02 ffffd000`23c1eb00 00007ffd`7e08b4bd nt!KiApcInterrupt+0xc3
03 00000049`d05fad50 cccccccc`cccccccc UnityPlayer!StackSentinel::StackSentinel+0x4d […\libil2cpp\utils\memory.cpp @ 21]

OK,這裡發生什麼事呢?堆疊定位在很開心的設定數值之後就出現了一個硬體中斷,然後它會做一些例行公事,並且將“2”寫入到我的堆疊中。挖喔! 好吧,因為某種原因Windows在篡改我的記憶體,但為什麼

一開始,我以為是因為我們呼叫了一些Windows API並且傳遞了非法的參數。所以我又掃過了整個socket輪詢執行緒程式,發現唯一的系統呼叫就是select()函數。我查閱MSDN,花了一個小時閱讀select()函數的文檔並且重新檢查確認所有的東西我們都做對了。確實沒有什麼問題,文檔中沒有任何地方說:“如果你傳遞了錯誤的參數,我們就會往你的堆疊裡面寫入2”。似乎所有的東西都是對的。

在做完所有的嘗試之後,我決定透過除錯工具進到select()函數內部,單步執行程式瞭解它是如何運作的。這個動作花了我幾個小時,但我終究完成了。看起來select()函數包裝了WSPSelect(),WSPSelect()函數大概是這個樣子的:

auto completionEvent = TlsGetValue(MSAFD_SockTlsSlot);
/* setting up some state

*/
IO_STATUS_BLOCK statusBlock;
auto result = NtDeviceIoControlFile(networkDeviceHandle, completionEvent, nullptr, nullptr, &statusBlock, 0x12024,
buffer, bufferLength, buffer, bufferLength);
if (result == STATUS_PENDING)
WaitForSingleObjectEx(completionEvent, INFINITE, TRUE);
/* convert result and return it

*/

這裡最重要的部分是對NtDeviceIoControlFile()的呼叫,事實上呼叫它會傳遞本地變數statusBlock作為一個傳出參數,最後它使用一個alertable wait來等待事件信號。到目前為止都沒問題:它呼叫了內核函數,該函數在當它無法立即完成請求時返回STATUS_PENDING。在這種情況下,WSPSelect()會等待直到事件被設定。一旦NtDeviceIoControlFile()完成,它會將結果寫入到statusBlock變數中並且設定事件。等待結束然後WSPSelect()返回。
IO_STATUS_BLOCK結構體是這樣的:


IO_STATUS_BLOCK struct looks like this:
typedef struct _IO_STATUS_BLOCK
{
union
{
NTSTATUS Status;
PVOID Pointer;
};
ULONG_PTR Information;
} IO_STATUS_BLOCK, *PIO_STATUS_BLOCK;

在64位元環境下面,該結構體長度為16位元組。這引起了我的注意,因為這個結構體符合我的記憶體篡改模式:頭4個位元組被篡改(NTSTATUS長度為4位元組),接著4個位元組被跳過(PVOID所佔據的空間)然後最後的8個或更多位元組被篡改。如果這就是寫入記憶體中內容,那麼頭四個位元組應該包含結果狀態的值。頭4個被篡改的位元組的內容總是0x00000102。這個似乎是...STATUS_TIMEOUT的錯誤碼。如果WSPSelect()沒有等待NtDeviceIOControlFile()結束,這個就說的通。但它等待了。

在瞭解了select()函數的工作機制後,我決定全面瞭解下socket輪詢執行緒是如何工作的。結果讓我像被成噸的磚頭砸中了一樣!

當另外一個執行緒向socket輪詢執行緒推送一個需要處理的socket時,socket輪詢執行緒會呼叫select()函數,因為select()是一個阻擋呼叫(Blocking call),當另外一個socket推送到socket輪詢執行緒佇列中以後,就需要以某種方式中斷select()執行,這樣新的socket可以被儘快處理。如何中斷select()函數呢?似乎我們在select()被阻塞時使用了QueueUserAPC() 來執行非同步過程...然後就會異常!然後會打開堆疊,執行更多的程式碼,然後未來在某個點上核心完成它的工作並且將結果寫入本地變數statusBlock中(但在這個點上變數實際上已經不存在了)。如果正好命中堆疊中的一個返回位址,就會發生當機。

修復方法很簡單:不使用QueueUserAPC(),我們建立了一個loopback socket,在需要中斷select()時會向它發送一個位元組。這種方法在POSIX上已經使用了相當長一段時間,現在也應用到了Windows中。這個Bug會在Unity 5.3.4p1中修復。

這是讓人夜不能寐的Bug之一 。它花費了我5天時間來解決,或許是我碰到過最困難的Bug之一。而帶來的深刻教訓就是:鄉親們! 
系統呼叫絕對不要在非同步情況下拋出異常,可能會干涉到其他執行緒!

8 則留言:

  1. 感謝翻譯,以下幾點翻譯調整建議,請參考:
    * stack sentinel 可翻譯為「堆疊定位」,或者保留原文,照字面翻成「哨兵」,令人誤解
    * stacktrace 可翻譯為「堆疊回溯」,或保留原文
    * 「現在我知道哪個執行緒當了」 => 原文是 "so now I knew which thread was crashing",「當了」這詞令人誤解,可改翻譯為「崩潰」
    * 「暫存溢出」對應的原文是 buffer overflow,台灣的翻譯慣例是「緩衝區溢位」
    * 構造函數 => 「建構函式」或「建構子」
    * 反彙編 => 「反組譯」

    回覆刪除
  2. * 代碼 => 程式碼
    * 系統級呼叫 => 系統呼叫

    回覆刪除
  3. 文末的結論是似乎有點脫離原作者的意思。原文是「do not throw exceptions out of asynchronous procedures if you’re inside a system call!」。該句原意應該是「不要使用丟出例外的方式,破壞非同步機制,尤其在系統呼叫下」。因為此bug就是使用QueueUserAPC破壞socket的select()等待機制,select在非預期的狀態下結束導致錯誤的記憶體寫入。

    回覆刪除
    回覆
    1. Hi Yao,
      感謝你的指正,我們稍微改了一下。讓他更貼近本地使用方式! 感謝!

      刪除
  4. 這種技術文的翻譯不是一般翻譯可以做的....
    Unity Taiwan的翻譯哥果然強大!!

    回覆刪除

著作人