案例背景 一个以前运行良好的 Windows 程序,在添加了少量功能之后,在若干台测试机中的某一台上运行后一直得不到预期结果,并且能比较高机率地复现。排错过程如下:
听完测试同学的描述后,以为是程序执行完了但是没有结果不对,于是以为是因为什么原因提前退出了,就复查代码中的分支逻辑,发现必经的路径中都有没有执行到的,而且写了一个小例过去发现必经路径能正常执行,感觉很诡异也很纳闷。
偶然发现是进程一直卡在后台没有正确执行也没有退出(之前寻找原因的过程中思路有点被测试同学的描述带跑了,导致居然是「偶然」才发现的,这个要反思)。
用 WinDbg 工具 Attach 卡死进程并分析之。
WinDbg 分析过程 使用 ~*kv
查看完整堆栈如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 0:002> ~*kv 0 Id: 18a4.20f0 Suspend: 1 Teb: 7efdd000 Unfrozen ChildEBP RetAddr Args to Child 0037e9e0 77518e44 0000012c 00000000 00000000 ntdll!ZwWaitForSingleObject+0x15 (FPO: [3,0,0]) 0037ea44 77518d28 00000000 00000000 0037eaac ntdll!RtlpWaitOnCriticalSection+0x13e (FPO: [Non-Fpo]) 0037ea6c 775102c9 775e20c0 768b6af6 756cdc60 ntdll!RtlEnterCriticalSection+0x150 (FPO: [Non-Fpo]) 0037eb08 77510202 766c0000 0037eb44 00000000 ntdll!LdrGetProcedureAddressEx+0x159 (FPO: [Non-Fpo]) 0037eb24 768e1e59 766c0000 0037eb44 00000000 ntdll!LdrGetProcedureAddress+0x18 (FPO: [Non-Fpo]) 0037eb4c 75393962 766c0000 756cdc60 0037ed08 KERNELBASE!GetProcAddress+0x44 (FPO: [Non-Fpo]) 0037eb94 753939a7 766c0000 756da27c 00000002 SHELL32!__delayLoadHelper2+0xe9 (FPO: [Non-Fpo]) 0037ec30 7539439a 0037f0b8 00020019 0037ed08 SHELL32!_tailMerge_ole32_dll+0xd 0037ed88 7539498a 0037f0b8 0037ee1c 87ee6cf8 SHELL32!kfapi::CFolderDefinitionStorage::_LoadRegistry+0x44 (FPO: [Non-Fpo]) 0037ef04 7539483e 0037f0b8 0037efc0 0037efbb SHELL32!kfapi::CFolderDefinitionStorage::Load+0x49 (FPO: [Non-Fpo]) 0037f03c 753934c4 0037f0b8 0037f078 87ee7308 SHELL32!kfapi::CFolderDefinitionCache::Load+0x7b (FPO: [Non-Fpo]) 0037f0f4 75323d49 0037f2ec 20004600 007a8fa8 SHELL32!kfapi::CFolderPathResolver::GetPath+0x96 (FPO: [Non-Fpo]) 0037f1c4 753bcbfa 0037f2ec 00000000 20004600 SHELL32!kfapi::CFolderCache::GetPath+0xd7 (FPO: [Non-Fpo]) 0037f278 753bcb36 0037f2ec 20004600 00000000 SHELL32!kfapi::CKFFacade::GetFolderPath+0xd5 (FPO: [Non-Fpo]) 0037f2a0 753955d5 0037f2ec 20004600 00000000 SHELL32!SHGetKnownFolderPath_Internal+0x96 (FPO: [Non-Fpo]) 0037f2bc 75395714 0037f2ec 00000000 00000000 SHELL32!SHGetFolderPathEx+0x30 (FPO: [Non-Fpo]) *** ERROR: Module load completed but symbols could not be loaded for C:\Users\mazhuang\Desktop\ProblemProgram.exe 0037f300 00c16d30 00000000 0000002e 00000000 SHELL32!SHGetFolderPathW+0x114 (FPO: [Non-Fpo]) WARNING: Stack unwind information not available. Following frames may be wrong. 0037f448 00c122ab 0037f508 00000104 00c92858 ProblemProgram+0x6d30 0037f4a4 77519dec ffffffff 009915c0 00000000 ProblemProgram+0x22ab 0037f4dc 01000000 00000005 00000007 0044005c ntdll!RtlDecodePointer+0x17 (FPO: [Non-Fpo]) 0037f4e4 00000000 0044005c 00760065 00630069 ProblemProgram+0x3f0000 1 Id: 18a4.1e84 Suspend: 1 Teb: 7efda000 Unfrozen ChildEBP RetAddr Args to Child 02a8e270 77518e44 0000014c 00000000 00000000 ntdll!ZwWaitForSingleObject+0x15 (FPO: [3,0,0]) 02a8e2d4 77518d28 00000000 00000000 02a8e4b8 ntdll!RtlpWaitOnCriticalSection+0x13e (FPO: [Non-Fpo]) 02a8e2fc 753bc3b5 007a8fcc 007a8fa8 02a8e43c ntdll!RtlEnterCriticalSection+0x150 (FPO: [Non-Fpo]) 02a8e30c 753bc64d 007a8fcc 857167c0 756daf98 SHELL32!kfapi::CCriticalSectionLock::CCriticalSectionLock+0x14 (FPO: [Non-Fpo]) 02a8e43c 753934c4 02a8e4b8 02a8e478 85716708 SHELL32!kfapi::CFolderDefinitionCache::Load+0x2c (FPO: [Non-Fpo]) 02a8e4f4 75394a87 02a8e6ec 20008000 007a8fa8 SHELL32!kfapi::CFolderPathResolver::GetPath+0x96 (FPO: [Non-Fpo]) 02a8e5c4 753bcbfa 02a8e6ec 00000000 20008000 SHELL32!kfapi::CFolderCache::GetPath+0x23d (FPO: [Non-Fpo]) 02a8e678 753bcb36 02a8e6ec 20008000 00000000 SHELL32!kfapi::CKFFacade::GetFolderPath+0xd5 (FPO: [Non-Fpo]) 02a8e6a0 753955d5 02a8e6ec 20008000 00000000 SHELL32!SHGetKnownFolderPath_Internal+0x96 (FPO: [Non-Fpo]) 02a8e6bc 75395714 02a8e6ec 00000000 00000000 SHELL32!SHGetFolderPathEx+0x30 (FPO: [Non-Fpo]) 02a8e700 754277a7 00000000 0000801a 00000000 SHELL32!SHGetFolderPathW+0x114 (FPO: [Non-Fpo]) *** ERROR: Symbol file could not be found. Defaulted to export symbols for C:\Users\mazhuang\AppData\Roaming\TaobaoProtect\TaobaoProtectSE.dll - 02a8e930 663261e7 00000000 0000801a 00000000 SHELL32!SHGetFolderPathA+0x3e (FPO: [Non-Fpo]) WARNING: Stack unwind information not available. Following frames may be wrong. 02a8ee98 66324a65 775138aa 86d8babf 02a8f364 TaobaoProtectSE+0x61e7 02a8f220 6633f57e 66320000 86d8a657 00000001 TaobaoProtectSE+0x4a65 02a8f240 66356dc5 66320000 00000001 00000000 TaobaoProtectSE+0x1f57e 02a8f280 66356d4c 66320000 00000001 00000000 TaobaoProtectSE!UninstallMonitor+0x176e5 02a8f294 775199a0 66320000 00000001 00000000 TaobaoProtectSE!UninstallMonitor+0x1766c 02a8f2b4 7751d939 663a9650 66320000 00000001 ntdll!LdrpCallInitRoutine+0x14 02a8f3a8 7751d7fc 00000000 741474ea 00000000 ntdll!LdrpRunInitializeRoutines+0x26f (FPO: [Non-Fpo]) 02a8f514 7751c558 02a8f578 02a8f540 00000000 ntdll!LdrpLoadDll+0x4d1 (FPO: [Non-Fpo]) 02a8f54c 768e2ca2 02a8f540 02a8f590 02a8f578 ntdll!LdrLoadDll+0xaa (FPO: [Non-Fpo]) 02a8f588 75f7aac3 00000000 00000000 007a904c KERNELBASE!LoadLibraryExW+0x1f1 (FPO: [Non-Fpo]) 02a8f6c8 774f010a 02a8f6e0 00000000 02a8f7b0 USER32!__ClientLoadLibrary+0x66 (FPO: [Non-Fpo]) 02a8f6dc 00000000 00000090 00000000 0c580a20 ntdll!KiUserCallbackDispatcher+0x2e (FPO: [0,0,0])
程序就两个线程且都是卡在 ntdll!ZwWaitForSingleObject
,很有可能是发生了死锁。使用 !cs
和两个线程堆栈中 ntdll!RtlEnterCriticalSection
这一行的第一个参数来看它们等待的临界区的情况:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 0:002> !cs 775e20c0 ----------------------------------------- Critical section = 0x775e20c0 (ntdll!LdrpLoaderLock+0x0) DebugInfo = 0x775e4380 LOCKED LockCount = 0x1 WaiterWoken = No OwningThread = 0x00001e84 RecursionCount = 0x1 LockSemaphore = 0x12C SpinCount = 0x00000000 0:002> !cs 007a8fcc ----------------------------------------- Critical section = 0x007a8fcc (+0x7A8FCC) DebugInfo = 0x00796af8 LOCKED LockCount = 0x1 WaiterWoken = No OwningThread = 0x000020f0 RecursionCount = 0x1 LockSemaphore = 0x14C SpinCount = 0x00000000
从它们各自的 OwningThread 可以得出这两个线程等待的临界区分别被对方占用,即它们在相互等待,典型的死锁。
可以看到 1e84
线程的堆栈中出现了 TaobaoProtectSE
,很显然程序被注入了一个 DLL,并且死锁与这个注入的 DLL 有关。
我留意到 20f0
线程堆栈中有 KERNELBASE!GetProcAddress
,看一下它正在尝试找到什么函数的入口点:
1 2 0:002> da 756cdc60 756cdc60 "StringFromGUID2"
这是 ole32.dll 中的一个函数,看起来应该是在 SHGetFolderPathW
函数中对传入的 CSIDL 参数进行转换的。
两个堆栈中都出现了 SHELL32!SHGetFolderPathW
,是否这个函数执行时需要占用一个临界区呢?1e84
线程中比较靠近栈顶的 SHELL32!kfapi::CCriticalSectionLock::CCriticalSectionLock
这一帧应该就能给出肯定的答案了。
看了一下任务管理器中的进程,推测是 TaobaoProtect.exe 进程执行的注入,对它用 WinDbg 下了一些断点调了一下,发现是它使用 SetWindowsHookExW
下了全局的 WH_GETMESSAGE
和 WH_MOUSE_LL
钩子。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 Breakpoint 0 hit *** ERROR: Symbol file could not be found. Defaulted to export symbols for C:\Users\mazhuang\AppData\Roaming\TaobaoProtect\TaobaoProtectSE.dll - eax=00000000 ebx=007a1c78 ecx=d53fa1d7 edx=00000094 esi=6633f680 edi=76f11222 eip=75f87603 esp=0a10f8cc ebp=0a10ff1c iopl=0 nv up ei pl zr na pe nc cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000246 USER32!SetWindowsHookExW: 75f87603 8bff mov edi,edi 0:020> kv ChildEBP RetAddr Args to Child 0a10f8c8 6633f69d 00000003 6633f660 66320000 USER32!SetWindowsHookExW (FPO: [Non-Fpo]) WARNING: Stack unwind information not available. Following frames may be wrong. 0a10ff1c 0044e75c df2f5e93 00000000 00a7bc60 TaobaoProtectSE!InstallMonitor+0x1d 0a10ff44 005f6911 007a1c78 df2f5eab 00000000 image00400000+0x4e75c 0a10ff7c 005f6a39 00000000 0a10ff94 76f1338a image00400000+0x1f6911 0a10ff88 76f1338a 00a7bc60 0a10ffd4 77519f72 image00400000+0x1f6a39 0a10ff94 77519f72 00a7bc60 7f47b808 00000000 kernel32!BaseThreadInitThunk+0xe (FPO: [Non-Fpo]) 0a10ffd4 77519f45 005f69bd 00a7bc60 00000000 ntdll!__RtlUserThreadStart+0x70 (FPO: [Non-Fpo]) 0a10ffec 00000000 005f69bd 00a7bc60 00000000 ntdll!_RtlUserThreadStart+0x1b (FPO: [Non-Fpo])
USER32!SetWindowsHookExW
这一帧的第一个参数 00000003
对应 WH_GETMESSAGE
。
死锁情景分析 结合自己了解到的一些知识和搜索引擎里查到的,得出死锁发生时的场景如下:
简化后的程序代码示例
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 UINT WINAPI ThreadProc(PVOID pParam) { MSG msg; while (GetMessage(&msg, 0, 0, 0)) { ... } ... } int _tmain(int argc, _TCHAR* argv[]) { UINT nThreadId = 0; HANDLE hThread = (HANDLE)_beginthreadex(NULL, 0, ThreadProc, NULL, 0, &nThreadId); ... ::SHGetFolderPath(NULL, CSIDL_APPDATA, NULL, 0, szPath); ... }
主线程在启动辅助线程后,调用了 SHGetFolderPath
,在此函数的执行过程中需要进入一个临界区,它成功进入了此临界区。而随后解析 CSIDL 需要用到 ole32.dll 中的 StringFromGUID2
函数,此时进程还未完成找到函数入口点的工作,所以需要调用 LoadLibraryEx
或 GetProcAddress
去获取此函数的入口点,需要申请 LoaderLock。 (参考 http://technet.microsoft.com/zh-cn/magazine/ms172219(VS.80).aspx 可知 LoadLibrary、GetProcAddress、FreeLibrary 和 GetModuleHandle 等函数是需要申请 LoaderLock 的。)
辅助线程在调用 GetMessage
时被注入 TaobaoProtectSE.dll,已获取 LoaderLock 去 LoadLibraryEx
该 DLL 和执行 DLL 的入口函数,由于此 DLL 的入口函数中直接或间接调用了 SHGetFolderPathW
,同主线程中的调用过程,它需要进入主线程占用的临界区去完成调用。
即主线程进入了临界区,要申请 LoaderLock;辅助线程获取了 LoaderLock,要申请进入临界区,形成死锁。
对比分析与解决方案 以前的程序之所以在新程序出问题的测试机上没有问题,是因为这个调用了 GetMessage
的辅助线程是新加的,以前的程序没有调用过 GetMessage
,所以没有被注入 TaobaoProtectSE.dll。
解决方案:
让 SHGetFolderPathW
的首次调用在起辅助线程之前就完成,再次调用它时应该不需要再寻找函数入口点,不需要再申请 LoaderLock 即可消除死锁风险。在起辅助线程前后都有对 SHGetFolderPathW
的调用经多次试验未再发生死锁现象。
添加对 LoadLibrary
系列函数的 HOOK(即对 LoadLibraryA/LoadLibraryW/LoadLibraryExA/LoadLibraryExW 都进行 HOOK),拒绝 TaobaoProtectSE.dll 注入。已验证可生效。
其它设想:
将 GetMessage
替换为 PeekMessage
,结果发现当 PeekMessage
返回 TRUE
的时候仍然被注入。查找 MSDN 看到如下解释:
GetMsgProc callback function
An application-defined or library-defined callback function used with the SetWindowsHookEx function. The system calls this function whenever the GetMessage or PeekMessage function has retrieved a message from an application message queue. Before returning the retrieved message to the caller, the system passes the message to the hook procedure.