来源:格友
作者:格蠹老雷

大家都常用微信吧?肯定的啊。那么,遇到过微信程序出问题么?“有还是没有?”哈哈,这个问题不好回答了,“没有啊,挺稳定的”,“好像有过,界面一闪就消失了,但再启动就好了”,“前段时间,遇到一串奇怪字符就死”。

不轻信不迷信,本于事实说话,老雷昨天真的遇到微信程序出现问题,而且还是比较严重的问题。

首先澄清一下,出问题的是微信的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,如果粘贴板里有图片的话,那么每次上传新图片后,都会自动选择粘贴板的图片(如下图),而不是用户希望的新上传图片。


Paper 本文由 Seebug Paper 发布,如需转载请注明来源。本文地址:https://paper.seebug.org/413/