來源：格友
作者：格蠹老雷
大家都常用微信吧？肯定的啊。那么，遇到過微信程序出問題么？“有還是沒有？”哈哈，這個問題不好回答了，“沒有啊，挺穩定的”，“好像有過，界面一閃就消失了，但再啟動就好了”，“前段時間，遇到一串奇怪字符就死”。
不輕信不迷信，本于事實說話，老雷昨天真的遇到微信程序出現問題，而且還是比較嚴重的問題。
首先澄清一下，出問題的是微信的PC版本，不是手機版本。為了便于區分，不妨把PC版本稱為“微信大程序”（與手機上的小程序之名對應）。
大程序掛死
大多時候使用微信小程序就夠了，這一次啟動微信大程序的原因是為了從手機向PC傳遞文件。傳遞文件后就沒有關閉它。昨天下午，有朋友發起語音聊天，托盤區域彈出漂亮的提示界面。看到后，我知道是要開一個約定好的“電話”會議。猶豫了一下是該在PC上接聽，還是從手機上接聽。考慮到伏案半天了，想站起來活動活動，于是就拿起手機接聽。20多分鐘后，會議結束，放下手機，坐到電腦前，看到托盤區域的語音聊天提示還在。當時就有點好奇，不知道騰訊的同行是如何設計這個邏輯的，如果手機接聽了，是不是應該把PC上的這個提示自動關閉啊？還是允許兩邊同時接聽，誒呀，還挺復雜的......
一邊想，一邊移動鼠標想把這個提示界面關閉掉。但是鼠標移過去后，光標的形狀由尖尖的箭頭變為一個圓環，中心透明。在窗口里移動鼠標，圓環跟著移動，移動的同時在不停的旋轉。嘗試著把鼠標移動到按鈕，沒有任何變化，仍是不停的旋轉。看起來，窗口里的所有元素都都凝固成了一團，分不出按鈕還是背景。點擊鼠標，感覺硬邦邦的，點不動，似乎一切都凍結了，凍得還很牢，仿佛嚴冬的水面經歷過了零下40度的低溫......
過了幾秒鐘再點擊，出現了一個對話框。上面寫著：“WeChat未響應”。
根據老雷多年的經驗，可以很肯定的說：微信掛死了。準確地說，是微信大程序掛死了。
上調試器
今天的軟件太復雜了，程序本身復雜，環境也復雜，二者對接，復雜度以排列組合的方式激增。CPU在五花八門的各類函數間縱橫馳騁，所到之處難以預估。而其中任何一個地方出問題，都可能導致CPU脫離正常軌道，出現上面所描述的情形。
那么，是到底是什么問題導致洋洋微信大程序翻身落馬，動彈不得呢？
或許有人說，費什么事啊？重啟算了。
非也，一旦重啟就湮滅了第一手的證據，錯過了找到問題根源的最好機會。接下里便可能有一大堆模棱兩可的推測，或者稀里糊涂地產生一些錯誤結論，甚至冤假錯案。作為一個認真的軟件工程師，怎么能那么不負責任呢？不禁想起《竇娥冤》里的經典臺詞：只合把清濁分辨，可怎生糊突了盜跖，顏淵？
閑言打住，上調試器。
喚出 WinDBG，嘗試附加到 WeChat 進程，失敗，錯誤碼5，訪問被拒絕。以管理員方式運行WinDBG再試，成功。看來微信大程序是以較高權限運行的（為何？姑且不論）。
因為是界面掛死，直接觀察0號UI線程的執行軌跡。
從下向上看，雖然因為缺少騰訊模塊的調試符號，少了一些信息，但是總的執行脈絡還是很清楚的，#1d是編譯器的入口函數，#1c是WeChat程序的Main函數，而后進入WeChat程序的主DLL，調用導出函數StartWechat，而后是消息循環（#18-19），之后應該是某個消息觸發執行消息處理函數，在處理消息的過程中，調用了waveInOpen API。查看這個API的文檔，可知其精確的函數原型。
MMRESULT waveInOpen(
LPHWAVEIN phwi,
UINT uDeviceID,
LPCWAVEFORMATEX pwfx,
DWORD_PTR dwCallback,
DWORD_PTR dwCallbackInstance,
DWORD fdwOpen
);waveXXX 系列 API 是 Windows 平臺上經典的多媒體編程接口，用來輸出和輸入聲音，從函數名中的 waveIn 看便知道它是用來接收聲音（錄音）的。如此看來，微信程序的UI線程是在打開錄音設備時遇到了障礙，并且卡住不能動了。
瀏覽進程中的其它線程的執行軌跡，發現有多個線程在執行聲音有關的邏輯，包括30號線程在打開聲音輸出設備。
31號線程在執行打開聲音輸出設備句柄的內部邏輯，并因此發起了RPC（遠程過程調用）。
苦尋RPC服務線程
RPC 是著名的故障源（trouble maker），調試時看到它就看到了線索，但同時也可能到了絕境。因為很多時候，調試到這里便到了終點，接下來無處可追了。
“追到哪里了？”
“追到 RPC 了”
“然后呢？”
“然后就不知道call到哪里去了.......”
因為 RPC 常常是跨進程的，甚至是跨機器的，所以天生就比較難以調試，更糟糕的是，RPC 有關的調試工具，大多陳舊不堪，多年沒有更新，因此辛辛苦苦找到一種方法，但是試一下卻不好用。悲哉 RPC，令眾多調試高手折戟而歸！
對于眼下的問題，老雷也嘗試了幾種 RPC 工具，包括 WinDBG 的插件 rpcexts，WinDBG 附帶的 dbgrpc 工具，以及第三方的 rpcview（不能支持筆者系統中的 rpc 運行 rpcrt4），但是都差了一點點，或者兩點點，未能到達彼岸。
從上面棧回溯中的 NdrClientCall4 函數來看，該線程是RPC的客戶端，接下來的關鍵是找到處理這個調用的服務端，把斷了的線索銜接起來。
一條路不行，只好找下一條。嘗試本地內核調試，需要事先啟用，但是老雷確實啟用好了的，但是 windbg 報錯失敗，原因是某處有個bug，啟動之后，只能用一次，第二次便出現下圖所示的錯誤。我確實是用過了一次的。
LiveKD顯身手
躊躇之間，忽然想到了 MarkR 的 livekd，啟動一個管理員權限的控制臺，切換到 livekd 目錄，發出命令：livekd -k c:\wd10x64\windbg.exe
WinDBG 跳出，順利建立內核調試會話，太棒了，一切順利，真是天無絕人之路啊。
有了強大的內核調試會話，頓時感覺鳥槍換炮了。列出WeChat進程的所有線程，找到剛才發起RPC的31號線程（系統ID 4898）。
從線程的基本信息中，果然看到它在等待ALPC消息（RPC在本機時經常使用的通信方式）。
Waiting for reply to ALPC Message ffffa4807ec1dce0 : queued at port ffffc48d8bee3cb0 : owned by process ffffc48d8bdf5080讓人高興的是WinDBG給出了豐富的細節。使用!alpc -m顯示消息詳情：
其中的Server Thread就是我們夢寐以求的（可惡的）服務線程。服務進程是svchost.exe。系統里有很多個svchost進程實例，不依賴強大的工具，如何能找到這個進程啊！
觀察服務線程的內核態信息，可以看到它在等待（暈倒）。記下它的線程ID（230c）和進程ID（994）。
這個服務線程為何發起等待呢？因為是用戶態發起的，所以使用用戶態調試器會更方便。
第三駕馬車
再開啟一個 WinDBG 實例，附加到 svchost 進程（進程ID 994）。~* k列出所有線程的執行軌跡，找到230c號線程（RPC服務線程）。
從#10的RPCRT4!LRPC_SCALL::HandleRequest來看，這個線程真的在處理RPC請求。
不過，在處理過程中，它要進臨界區，卻失敗了，因為里面已經有人了。發起進臨界區的函數是：
audiosrv!CAudioDGProcess::LockADGProcess當你急著要用高鐵的衛生間而其處于有人狀態時，你只好等，等啊等啊的時候，你或許思考人生，你或許刷屏，你或許明白了，有些天價酒店的原因不是有多好，只是因為客人少......但此時你腦海里拂之不去的一個問題可能是“誰在里面呢？”
在軟件世界里，這個好辦，只要執行!locks:
WinDBG 告訴我們有兩個臨界區處于鎖狀態。因為臨界區是不可以跨進程的，所以可以確定剛才的230c線程一定在等待其中的一個。哪一個呢？
如果是32位進程，那么很容易通過分析參數確定下來，64位下，參數回溯變得如登月般困難。不過只有兩個，分別看一下吧。細節略過，老雷使用了大約2秒確定下來是下面一個。也就是說，230c想要進的臨界區，被4fcc線程捷足先登了。干脆一點，是4fcc占著衛生間不出來。
切換到這個4fcc線程，看它在做啥？
天啊，它也在做 RPC。任何技術一旦被濫用后果都是很重的，比如塑料，還有......
尋找另一個RPC服務進程
4fcc 在調用誰呢？服務進程是哪一個？重用剛才的套路，切換到本地內核調試會話，找到 4fcc 線程，觀察它的狀態。
繼續觀察 ALPC 消息的信息：
哦，服務進程的名字叫 audiodg.exe，著名的人物啊，其大名叫 Windows Audio Device Graph Isolation。很有博士范的一個名字。
注意上面顯示的信息中 ServerThread 條目為空。不過，這并不代表沒有服務線程，觀察服務端口（QueuePort），可以看到有三個線程登記注冊了完成端口（線程間快速協作機制，名字翻譯為中文后有點不通，姑且不論），記下它們的線程ID，分別是2c1c、441c和493c。
值得注意的是，這個端口的隊列有61條消息在排隊。堵車堵的非常厲害。
不妨與沒有排隊的端口比較一下。
第四架馬車
下一步應該調試 audiodg 進程了，看它在忙什么，有那么多消息排隊而不處理。
在LKD會話里觀察它的概要信息，老雷意外發現它已經在被調試。
0: kd> !process ffffc48d958a1080
PROCESS ffffc48d958a1080
SessionId: 0 Cid: 323c Peb: e327bdb000 ParentCid: 0994
FreezeCount 1
ElapsedTime 3 Days 15:38:12.880
DebugPort ffffc48d9b413760誰在調試它呢？老雷沒有啊。這個信息讓老雷很詫異。
思考片刻，有了推測，或許是它崩潰了，觸發了JIT調試。打開任務管理器觀察，果然如此，在會話0里有 windbg 附加在它身上了。還有另外幾個 WinDBG 實例，看來后臺服務崩潰了好幾個，分別是 vmms、DELL 預裝的 DDV 服務、以及windows自動更新服務。（這么多的崩潰或許與前幾天的 Windows 10 自動升級有關，留待以后討論。）
啟動第四個 WinDBG 實例，以非入侵方式附加到 auduidg 進程，觀察上面記錄的三個監聽線程。從棧回溯來看，它們都在調用NtWaitForWorkViaWorkerFactory，進入內核等待任務了。
0:005> kc
# Call Site
00 ntdll!NtWaitForWorkViaWorkerFactory
01 ntdll!TppWorkerThread
02 KERNEL32!BaseThreadInitThunk
03 ntdll!RtlUserThreadStart看起來沒什么問題啊？怎么回事呢？
沿著這個方向繼續思考的話，方向就錯了。上上下下，跟來跟去，跑了幾百公里了吧，老雷有點累了，差點進入死胡同。
看線程列表，可以看到所有線程的掛起計數都是2，說明它們都處于掛起狀態。
為什么都被掛起來了呢？因為某個地方發生爆炸了。
爆炸現場
瀏覽所有線程，6號線程果然硝煙彌漫。
0:006> kc
# Call Site
00 ntdll!RtlReportCriticalFailure
01 ntdll!RtlpHeapHandleError
02 ntdll!RtlpLogHeapFailure
03 ntdll!RtlFreeHeap
04 MaxxAudioRenderAVX64!DllUnregisterServer
05 MaxxAudioRenderAVX64!DllUnregisterServer
06 MaxxAudioRenderAVX64!DllUnregisterServer
07 kernel32!BaseThreadInitThunk
08 ntdll!RtlUserThreadStart從 RtlpLogHeapFailure 和 RtlFreeHeap 就可以看出，是堆有關的問題。執行!heap，觸發 WinDBG 檢查堆的錯誤記錄，果然報告錯誤：
錯誤類型：HEAP_FAILURE_BLOCK_NOT_BUSY，釋放并非處于占用狀態的塊，簡單說就是釋放空閑塊，或者說多次釋放，double free。
如此看來，追到源頭了。可以很負責任的說，音頻驅動模塊 MaxxAudioRenderAVX64 內部多次釋放堆塊，引發堆的錯誤檢查機制發起異常，MaxxAudioRenderAVX64 模塊應負全部責任。
前些天，安卓版的微信小程序在處理一個特別的字符串時會陷入死循環。今天，微信開發團隊的同行公開發文，承認問題，并詳細描述了bug的來龍去脈，這種開放的心態和實事求是的精神真是值得表揚。
無獨有偶，老雷今日花了幾個小時的時間，上下求索，四個調試器實例齊上陣，終于讓問題水落石出，證明不是微信本身模塊的問題，還微信程序以清白。
想到大半天的時間沒有了，多少有些可惜。不過，想到搞清楚了一個問題，定位到了根源（希望maxx audio的同行聯系老雷獲取崩潰現場的dump），而且記錄下來的分析過程或許對軟件同行們解決類似問題有所幫助，那么時間花的也值得了。分析過程中，老雷保存下了幾個關鍵現場的轉儲文件，供以后交流和研習使用（有興趣的同行請關注軟件調試研習班針對Windows的特別專題）。
在寫這篇文章的時候，還發現公眾號編輯環境上傳圖片功能的一個bug，如果粘貼板里有圖片的話，那么每次上傳新圖片后，都會自動選擇粘貼板的圖片（如下圖），而不是用戶希望的新上傳圖片。
本文由 Seebug Paper 發布，如需轉載請注明來源。本文地址：http://www.bjnorthway.com/413/
暫無評論