在调试里看 NV 驱动栈溢出导致的连环死锁原创
最近我使用的一台PC随机出现应用程序卡死。卡死的程序可能是VirtualBox虚拟机,可能是资源管理器,也可能是其它软件。有时是一个程序卡死,有时是几个程序卡死,甚至是卡死一大片,整个系统不能动弹,只好触发蓝屏,或者强按4秒,关机重启。
三次挂死
现在回想起来,第一次发生这个问题时,是在写一篇文章,正在收尾完工的时候,整个系统突然不能反应,屏幕全黑,但是老雷没有放弃,插了个USB键盘上去,过了一会,键盘居然有反应了(数字键盘锁定灯可以亮或者暗),于是老雷按下Ctrl + ScrollLock,触发蓝屏,虽然屏幕已经死了,没有显示,但是根据多年的经验,老雷感觉到了蓝屏是成功的,仿佛看到了那缕蓝光冲破黑暗,闪现出来…重启之后,真的发现有dump保存下来,说明老雷的感觉是对的。
第二次发生这个问题是在北京讲课,讲着讲着老雷兴起,想做个即兴的演示给大家看,没想到在搜索要启动的程序时整个系统卡死,突然的事故让老雷有点措手不及,赶紧解释了一下,然后趁课间休息的时间重启系统。
第三次发生是今天,一方面考虑到周五要做的公开课,另一方面考虑到,已经忍了两次,第三次不能忍了,是可忍孰不可忍:-)
这一次挂死的是WinDBG,老雷唤起它是要做内核调试的,目标机冻结,熟悉的int 3出现,一切顺利,但是WinDBG的命令行始终处于BUSY状态。
通常这样的等待是因为WinDBG在找符号,老雷用这个间隙倒茶。
但这一次,倒好茶还是BUSY,老雷意识到是“小鬼”出现了。
偷摸发信被卡牢
再启动一个WinDBG,附加到已经挂死的WinDBG上,~* k,先是看到调试引擎线程卡在一个关键区上:
1 Id: e24.2fb8 Suspend: 1 Teb: 00000063`3def0000 Unfrozen
# Child-SP RetAddr Call Site
00 00000063`3e2ff278 00007fff`3f43be9b ntdll!NtWaitForAlertByThreadId+0x14
01 00000063`3e2ff280 00007fff`3f43bd01 ntdll!RtlpWaitOnAddressWithTimeout+0x43
02 00000063`3e2ff2b0 00007fff`3f414571 ntdll!RtlpWaitOnCriticalSection+0x1a1
03 00000063`3e2ff360 00007fff`3f414490 ntdll!RtlpEnterCriticalSectionContended+0xd1
04 00000063`3e2ff390 00007fff`28b92d69 ntdll!RtlEnterCriticalSection+0x40
05 00000063`3e2ff3c0 00007fff`28b97ade sqmapi!AcquireSessionFromHandle+0x21
*** ERROR: Symbol file could not be found. Defaulted to export symbols for C:\wd10x64\dbgeng.dll -
06 00000063`3e2ff3f0 00007fff`03849482 sqmapi!SqmAddToStreamString+0x82
07 00000063`3e2ff440 00007fff`038fcbf0 dbgeng!Ordinal327+0x23ce2
08 00000063`3e2ff490 00007fff`038304bb dbgeng!Ordinal327+0xd7450
09 00000063`3e2ff520 00007fff`038307a3 dbgeng!Ordinal327+0xad1b
0a 00000063`3e2ffa10 00007ff6`57094948 dbgeng!Ordinal327+0xb003
0b 00000063`3e2ffa70 00007ff6`57093b1b windbg+0x34948
0c 00000063`3e2ffab0 00007ff6`57095419 windbg+0x33b1b
0d 00000063`3e2ffae0 00007ff6`5707c0c4 windbg+0x35419
0e 00000063`3e2ffb10 00007fff`3eb52774 windbg+0x1c0c4
0f 00000063`3e2ffba0 00007fff`3f470d51 KERNEL32!BaseThreadInitThunk+0x14
10 00000063`3e2ffbd0 00000000`00000000 ntdll!RtlUserThreadStart+0x21
观察这个管件区:
0:010> !locks
CritSec sqmapi!WPP_REGISTRATION_GUIDS+2298 at 00007fff28bc97d0
WaiterWoken No
LockCount 1
RecursionCount 1
OwningThread 3520
EntryCount 0
ContentionCount 1
*** Locked
Scanned 31 critical sections
看来这个关键区是被3520线程捷足先登了,切到这个线程,观察:
2 Id: e24.3520 Suspend: 1 Teb: 00000063`3def2000 Unfrozen
# Child-SP RetAddr Call Site
00 00000063`3e37e538 00007fff`3cf32bf2 ntdll!NtAlpcSendWaitReceivePort+0x14
01 00000063`3e37e540 00007fff`3cfc9b61 RPCRT4!LRPC_BASE_CCALL::DoSendReceive+0x112
02 00000063`3e37e5f0 00007fff`3cfc85bd RPCRT4!NdrpClientCall3+0xa61
03 00000063`3e37ea30 00007fff`2d081090 RPCRT4!NdrClientCall3+0xed
04 00000063`3e37edc0 00007fff`28b9b829 SensApi!IsNetworkAlive+0x80
05 00000063`3e37ee20 00007fff`28ba965e sqmapi!IsNetworkAvailable+0xc9
06 00000063`3e37ee50 00007fff`28b983b8 sqmapi!CSqmHttpUploadManager::AddFilesToUploadQueue+0x7a
07 00000063`3e37f360 00007fff`038498e7 sqmapi!SqmStartUpload+0x1e0
08 00000063`3e37f3c0 00007fff`03849a5b dbgeng!Ordinal327+0x24147
09 00000063`3e37f830 00007fff`3eb52774 dbgeng!Ordinal327+0x242bb
0a 00000063`3e37f860 00007fff`3f470d51 KERNEL32!BaseThreadInitThunk+0x14
0b 00000063`3e37f890 00000000`00000000 ntdll!RtlUserThreadStart+0x21
从#7看,sqmapi!SqmStartUpload,是著名的遥感机制(Telemetry)试图往家里发数据(各位看官,可有读过老雷的“在调试器里看Windows 7发信回家”)。
从IsNetworkAlive看,是在发信之前判断是否有网络。但这个看似简单的问题其实不是那么容易,于是利用RPC发起远程调用。
我们暂不评论偷摸发信是否合理,还是继续追踪为啥判断是否联网这点小事就能把骁勇的WinDBG卡死?
寻找RPC的服务端
又是RPC,仍使用上次的方法,使用本地内核调试找到3520线程,可以看到它真的在等待RPC回应。
THREAD ffffcb008241c080 Cid 0e24.3520 Teb: 000000633def2000 Win32Thread: 0000000000000000 WAIT: (WrLpcReply) UserMode Non-Alertable
ffffcb008241c6c8 Semaphore Limit 0x1
Waiting for reply to ALPC Message ffff8a8281d7b650 : queued at port ffffcb007146c6e0 : owned by process ffffcb00713c2640
Not impersonating
DeviceMap ffff8a8283d9b630
Owning Process ffffcb0082fa2640 Image: windbg.exe
Attached Process N/A Image: N/A
Wait Start TickCount 3574818 Ticks: 89602 (0:00:23:20.031)
Context Switch Count 7 IdealProcessor: 1
观察服务进程:
lkd> !process ffffcb00713c2640 0
PROCESS ffffcb00713c2640
SessionId: 0 Cid: 07c8 Peb: 93377db000 ParentCid: 033c
DirBase: 11145b000 ObjectTable: ffff8a827e09d340 HandleCount: 199.
Image: svchost.exe
原来是svchost,根据进程ID(7c8,即1992)到服务列表里查找,可以知道它是“系统事件通知服务” System Event Notification Service (SENS)
SENS机制是有文档的,MSDN很详细。
探索SENS服务
接下来观察SENS服务进程的情况,特别注意WinDBG所调用RPC的服务线程(通过!alpc -m消息可以知道)。
结果让人吃惊,和上次微信的例子有点类似,又是连环的RPC,这个服务线程又发起RPC了,在等待回复。
THREAD ffffcb0081b95040 Cid 07c8.1dc0 Teb: 000000933765c000 Win32Thread: 0000000000000000 WAIT: (WrLpcReply) UserMode Non-Alertable
ffffcb0081b95688 Semaphore Limit 0x1
Waiting for reply to ALPC Message ffff8a827dcca040 : queued at port ffffcb007f2d0890 : owned by process ffffcb007e967080
Not impersonating
DeviceMap ffff8a826f602090
Owning Process ffffcb00713c2640 Image: svchost.exe
Attached Process N/A Image: N/A
Wait Start TickCount 3658023 Ticks: 456617 (0:01:58:54.640)
Context Switch Count 237 IdealProcessor: 2
UserTime 00:00:00.000
KernelTime 00:00:00.000
Win32 Start Address ntdll!TppWorkerThread (0x00007fff3f4412c0)
Stack Init ffff9e01ddd7fc10 Current ffff9e01ddd7f3c0
Base ffff9e01ddd80000 Limit ffff9e01ddd79000 Call 0000000000000000
Priority 8 BasePriority 8 PriorityDecrement 0 IoPriority 2 PagePriority 5
Kernel stack not resident.
它为啥要发起RPC呢?可以再挂一个调试器在SENS服务上观察。
从#0a看,上面这个线程真的是在处理WinDBG发起的网络是否可用的请求,执行的函数是sens!RPC_IsNetworkAlive。但是这个问题,对于它来说也不能做主,要继续调用RasApi32!RasEnumConnectionsW。这个函数是有文档的:
DWORD RasEnumConnections(
_Inout_ LPRASCONN lprasconn,
_Inout_ LPDWORD lpcb,
_Out_ LPDWORD lpcConnections
);
不过我们不想读,因为从栈上来看,它内部又发起了RPC,与我们在内核态看到的结论是一致的。
RAS服务
从函数名可以看出,SENS服务调用的是RAS服务。有了这个信息可以从服务列表里找RAS服务,也可以继续用我们的内核调试会话找。无论哪种方法,结论都是,SENS服务调用的是进程ID为3488的svchost进程。
再开一个WinDBG(上调试器),以非入侵方式附加到3488进程,~* k观察。立刻发现了特殊情况:第31号线程的栈帧特别多,显示的很长,而且感觉还没有显示完整。
切换到31号线程,k 2000。用了几十秒,才显示完毕,一共有3130(c3a)个栈帧。
根据老雷的经验,这样疯狂的调用,很可能把栈用光了。
观察寄存器现场:
0:031> r
rax=0000000000000001 rbx=00007fff03fb3060 rcx=000000046db83f10
rdx=0000000000000000 rsi=000001fd79f640a0 rdi=000000046db84140
rip=00007fff03fb3103 rsp=000000046db83ee0 rbp=000000046db83fe0
r8=0000000000000180 r9=000000046db84404 r10=0000000000000004
r11=000000046db840c8 r12=0000000000000001 r13=000001fd78a82c30
r14=0000000000000000 r15=0000000000000000
iopl=0 nv up ei pl zr na po nc
cs=0033 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00010244
D3D12!NDXGI::CDevice::SubmitCommandCB+0xa3:
00007fff`03fb3103 e8f07b0200 call D3D12!memset (00007fff`03fdacf8)
显示栈指针附近的内存:
0:031> dd 000000046db83ee0
00000004`6db83ee0 00000000 00000000 00000000 00000000
可以显示,说明栈上有可用内存。
但是从内核态观察这个线程,明明是有异常发生了。
这是怎么回事呢?
听过老雷课的或者认真读过《软件调试》的,或许已经想出了原因。
用户态的栈式可以自动增长的,一般是先保留1MB,提交一点点,提交部分上面放一个保护页,用完了就会碰到保护页,于是再提交。
但是这个过程不是无止境的,在32位时,当栈的保护页已经到了保留的最后一个页时,保护页无处可移,系统这时会发出栈溢出异常,通知应用程序,栈要用完了。
观察31号线程的栈,果然已经没有保护页了(带PAGE_GUARD属性)。
看来真的是栈溢出了。
谁用光了栈
那么是谁用光了栈空间呢?浏览k命令的结果,很容易看出答案,名为nvwgf2umx_cfg的模块似乎陷入了死循环,反复调用数千次:
这个模块是谁家的呢?nv啊!GPU时代的一号公司。
看文件日期,还是很新的文件。
辕门失火
那么RAS服务内部为什么要调用NV的模块呢?浏览31号线程的栈帧,看它为何发起长调用。
发起模块是wuaueng,微软给出的大名叫Windows Update Agent,全称或许为Windows更新自动引擎。
从下面的这些栈帧来看,自动更新引擎是在努力的找活干(FindUpdates),从服务器那边拿到信息后评估在本机的适用性(EvaluateUpdateApplicabilityRules),规则似乎挺复杂的,支持表达式,在评估表达式时,先调用了D3D接口,而后转到了NV的驱动模块。
c1d nvwgf2umx_cfg!OpenAdapter12
c1e nvwgf2umx_cfg!OpenAdapter12
c1f nvwgf2umx_cfg!OpenAdapter12
c20 nvwgf2umx_cfg!NVENCODEAPI_Thunk
c21 nvwgf2umx_cfg!NVENCODEAPI_Thunk
c22 D3D12!NDXGI::CDevice::CreateDriverInstance
c23 D3D12!CDevice::LLOCompleteLayerConstruction
c24 D3D12!NDXGI::CDevice::LLOCompleteLayerConstruction
c25 D3D12!D3D12CreateLayeredDevice
c26 D3D12!D3D12CoreCreateLayeredDevice
c27 D3D12!D3D12CoreCreateDevice
c28 D3D12!D3D12CreateDeviceImpl
c29 D3D12!D3D12CreateDevice
c2a wuaueng!Direct3DEvaluator::GetMaxSupportedD3D12FeatureLevel
c2b wuaueng!Direct3DEvaluator::EvaluateFeatureLevel
c2c wuaueng!CSystemExprEvaluator::EvaluateDirect3D
c2d wuaueng!CSystemExprEvaluator::Evaluate
c2e wuaueng!CBaseEEHandler::Evaluate3
c2f wuaueng!CExprElementTreeNode::Evaluate
c30 wuaueng!CAgentUpdateManager::EvaluateUpdateApplicabilityRules
c31 wuaueng!CAgentUpdateManager::DetectForUpdate
c32 wuaueng!CAgentUpdateManager::EvaluateUpdateSet
c33 wuaueng!CAgentUpdateManager::DetectForUpdates
c34 wuaueng!CAgentProtocolTalker::SyncServerUpdatesInternal
c35 wuaueng!CAgentProtocolTalker::SyncServerUpdates
c36 wuaueng!CAgentUpdateManager::FindUpdates
看来是自动更新逻辑引发了NV模块的疯狂逻辑。两个逻辑可能没有磨合太好。一个说“兄弟你啥版本啊,需要更新不”,“另一个说,更新更新,整天更新个锤子啊”,一言不合,索性把栈用光。哈哈,结果大家都动不了了。
那么自动更新增么和RAS扯到一起的呢?
它们本来真的没有一毛钱关系。只是租房子的时候住到了一起,就为了节约点开销啊。
这样分析下来,可以比较确定的说,随机卡死案件的起因是有人检查网络是否可用(IsNetworkAvailable),RPC调用先是到了SENS服务,又到了RAS服务。在调用时,不想刚好遇到与RAS服务合租的WUAU服务屋里“起火”,更新引擎的表达式平谷逻辑调用NV的驱动模块,后者把栈用完,导致整个进程被挂起,于是RAS和WUAU都动不了了,SENS服务卡住了,调用者也卡住了。
这个结论与曾经分析过的微信挂死颇为类似,结论都与第三方驱动相关。上次是MaxxAudio,这次是大名鼎鼎的NV…