实战：结合Dr.Watson系统日志和Vc6来定位多线程环境下程序异常退出的错误

当开发的软件发布以后，在客户那运行时可能会因为各种原因导致程序退出。这种情况很尴尬，很明显我们无法在客户机器上装个Visual Studio调试，所以必须有机制来收集出错的信息。软件本身的运行日志能提供部分信息，但是可能还不够。Windows系统为此提供了解决方案：Dr.Watson工具。Dr.Watson也算是一个小巧的调试器，32位的版本名字是drwtsn32.exe。可用于当系统中有进程发生异常崩溃时采集信息。下面结合一个例子看一下其用法。

先把测试代码贴一下：

/********************************************************************/
/* 程序：lesson_2, 结合Dr.Watson与工程map文件定位错误 */
/* 功能：多线程环境中利用除0错误使程序产生异常，被Dr.Watson捕获之 */
/* 作者：coding (http://blog.csdn.net/coding_hello) */
/* 日期：2008-09-29 */
/********************************************************************/

#include <stdio.h>
#include <process.h>
#include <windows.h>

const int cnThreadnum = 4;

UINT WINAPI Worker(LPVOID lpParam)
{
srand((DWORD)lpParam);

DWORD dwTid = GetCurrentThreadId();
int k=100;
while(k--)
{
printf("tid[%u] tmp = %d/n", dwTid, RAND_MAX/(rand()%cnThreadnum));
Sleep(10);
}
return 0;
}

int main(int argc, char* argv[])
{
HANDLE hThd[cnThreadnum] = {0};
for(DWORD i=0; i<cnThreadnum; i++)
{
hThd[i] = (HANDLE)_beginthreadex(NULL, 0, Worker, (LPVOID)i, 0, NULL);
}

printf("Wait.../n");
WaitForMultipleObjects(cnThreadnum, hThd, TRUE, INFINITE);

for(int k=0; k<cnThreadnum; k++)
{
CloseHandle(hThd[k]);
}

printf("Finish!/n");
system("pause");
return 0;
}

程序已开始就启动了4个线程，然后主线程等待所有的线程结束。线程函数中可能会因为RAND_MAX/(rand()%10)导致出现除0的错误。这里注意，编译的时候选择Link页，把"Generate mapfile"前面勾上。一般来说我就这样用了。但是还可以让map信息更详细一些，在最下面的"Project Options"的最后面手工敲入："/mapinfo:lines"，注意，跟前面内容要用空格隔开。然后再编译。

因为是要演示Dr.Waston，所以我们在命令行先用drwtsn32 -i的命令注册Dr.Watson为默认调试器（下次启动VC6的时候，在菜单option-->debug里面确认just-in-time debugging选中，就会把VC6恢复为默认调试器的）。注册完以后，我们看看注册表是否满足需要了。



看看注册表中HKEY_LOCAL_MACHINE/SOFTWARE/Microsoft/Windows NT/CurrentVersion/AeDebug，其中的Auto键的值如果是0的话，程序出错后还会弹出错误提示。我们需要的是出错后安静的处理掉，客户知道了多不好~所以，改成1。下面的Debugger已经是drwtsn32了，很好。最后的UserDebuggerHotKey是调试器的热键，我们不需要。接下来，还是在命令行敲Drwtsn32，回车，终于看到Drwtsn32的庐山真面目了：



上面是日志文件和dump文件的保存路径。这次我们要看的是日志，dump文件下次再说。符号表我一般都勾上了，有的话就更好不是~ 重点是下面的应用程序错误(&R)这里，如果日志中有信息，就会在下面一条一条以纪录的形式显示出来。如果你的Drwatson中确实有日志的话，可以点清除把以前的都删掉。既然已经见过面了，那就把它关掉吧，需要时再打开，反正它自己也不会实施刷新。

好，现在一切就绪了！运行一下程序~ 只见嗖的一下，程序就停了。赶紧再把Dr.Watson请出来看看~



这次我们看到应用程序错误那里有了一条记录，把它选中变蓝后点上面的查看按钮。于是又出来一个对话框，显示“发生应用程序意外错误:”云云，内容很长，信息相当多。嗯，很好，很强大，这就是我们要的。考虑到这个框小了点，可以Ctrl+Shift+END全选后copy出来，用记事本看哈。在记事本中查找"错误 ->"，然后就会看到个这：

错误 ->00401087 f7f9 idiv eax,ecx

没错，这就是错误的位置。仔细看看上下文，分析分析。由于是一个多线程的程序，所以这里把出错的线程单独剥离出来。如下所示，每个线程的信息分为几个部分：一开始是错误发生时寄存器的信息；然后是当前发生错误的指令的前后各10条指令(什么是10条，不是20条或者2条？因为Dr.Watson里面默认设置的就是10条呀~，你刚才又没改)；接下来是堆栈反向跟踪信息，也就是函数的逆向调用序列；最后是原始堆栈信息，可以获得参数，返回地址，局部变量之类的信息。

*----> 线程 ID 0x2714 的状态转储 <----*

eax=00007fff ebx=003724b8 ecx=00000000 edx=00000000 esi=0063ff2c edi=0063ff80
eip=00401087 esp=0063ff2c ebp=0063ff80 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00010246

函数: lesson_2!Worker
0040106b 7441 je lesson_2!Worker+0x8e (004010ae)
0040106d e86e020000 call lesson_2!rand (004012e0)
00401072 8bc8 mov ecx,eax
00401074 81e103000080 and ecx,80000003h
0040107a 7905 jns lesson_2!Worker+0x61 (00401081)
0040107c 49 dec ecx
0040107d 83c9fc or ecx,0FFFFFFFCh
00401080 41 inc ecx
00401081 b8ff7f0000 mov eax,7FFFh
00401086 99 cdq
错误 ->00401087 f7f9 idiv eax,ecx
00401089 50 push eax
0040108a 8b55fc mov edx,dword ptr [ebp-4]
0040108d 52 push edx
0040108e 681cd04200 push offset lesson_2!`string' (0042d01c)
00401093 e898010000 call lesson_2!printf (00401230)
00401098 83c40c add esp,0Ch
0040109b 8bf4 mov esi,esp
0040109d 6a0a push 0Ah
0040109f ff15d8714300 call dword ptr [lesson_2!_imp__Sleep (004371d8)]
004010a5 3bf4 cmp esi,esp

*----> 堆栈反向跟踪 <---*
ChildEBP RetAddr Args to Child
0063ff80 004015e2 00000001 00000000 00000000 lesson_2!Worker+0x67
0063ffb8 7c824829 003724b8 00000000 00000000 lesson_2!_threadstartex+0xb2
WARNING: Stack unwind information not available. Following frames may be wrong.
0063ffec 00000000 00401530 003724b8 00000000 kernel32!GetModuleHandleA+0xdf

*----> 原始堆栈转储 <----*
000000000063ff2c 00 00 00 00 00 00 00 00 - b8 24 37 00 cc cc cc cc .........$7.....
000000000063ff3c cc cc cc cc cc cc cc cc - cc cc cc cc cc cc cc cc ................
000000000063ff4c cc cc cc cc cc cc cc cc - cc cc cc cc cc cc cc cc ................
000000000063ff5c cc cc cc cc cc cc cc cc - cc cc cc cc cc cc cc cc ................
000000000063ff6c cc cc cc cc cc cc cc cc - cc cc cc cc 06 00 00 00 ................
000000000063ff7c 14 27 00 00 b8 ff 63 00 - e2 15 40 00 01 00 00 00 .'....c...@.....
000000000063ff8c 00 00 00 00 00 00 00 00 - b8 24 37 00 94 00 00 c0 .........$7.....
000000000063ff9c 00 00 00 00 8c ff 63 00 - 60 fb 63 00 dc ff 63 00 ......c.`.c...c.
000000000063ffac b4 65 40 00 b0 d1 42 00 - 00 00 00 00 ec ff 63 00 .e@...B.......c.
000000000063ffbc 29 48 82 7c b8 24 37 00 - 00 00 00 00 00 00 00 00 )H.|.$7.........
000000000063ffcc b8 24 37 00 94 00 00 c0 - c4 ff 63 00 60 fb 63 00 .$7.......c.`.c.
000000000063ffdc ff ff ff ff 60 1a 82 7c - 30 48 82 7c 00 00 00 00 ....`..|0H.|....
000000000063ffec 00 00 00 00 00 00 00 00 - 30 15 40 00 b8 24 37 00 ........0.@..$7.
000000000063fffc 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 ................
000000000064000c 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 ................
000000000064001c 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 ................
000000000064002c 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 ................
000000000064003c 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 ................
000000000064004c 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 ................
000000000064005c 00 00 00 00 00 00 00 00 - 00 00 00 00 00 00 00 00 ................

尽管这里可以简单的利用错误处指出的地址0x401087直接定位，那是因为这是很简单的情况。所以我决定还是简单讲一下在实际的复杂得多的环境中如何分析这些数据。

1.定位出错的模块。

我们看到错误的地址是0x401087，应该先确认这个地址是在哪个模块中。在错误日志中查找“模块清单”，能找到以下内容：

*----> 模块清单 <----*
0000000000400000 - 000000000043a000: D:/DebugEasy/lesson_2/Debug/lesson_2.exe
0000000074ae0000 - 0000000074b45000: C:/windows/system32/USP10.dll
0000000076180000 - 000000007619d000: C:/windows/system32/IMM32.DLL
0000000076eb0000 - 0000000076ec3000: C:/windows/system32/Secur32.dll
0000000077bd0000 - 0000000077c18000: C:/windows/system32/GDI32.dll
0000000077c20000 - 0000000077cbf000: C:/windows/system32/RPCRT4.dll
0000000077e10000 - 0000000077ea0000: C:/windows/system32/USER32.dll
0000000077f30000 - 0000000077fdb000: C:/windows/system32/ADVAPI32.dll
000000007c800000 - 000000007c92b000: C:/windows/system32/kernel32.dll
000000007c930000 - 000000007ca00000: C:/windows/system32/ntdll.dll
000000007f000000 - 000000007f009000: C:/windows/system32/LPK.DLL

这里清楚的指出0000000000400000 - 0000000000439000这个范围的地址是系统分配给lesson_2.exe的。我们得到的错误地址是0x401087，所以可以确定错误就是发生的lesson_2.exe模块。实际上很多应用都还有些自己的动态库之类的，定位到具体的模块后才能更具体的结合代码分析。有时候出错的地址是属于kernel32,ntdll.dll之类的系统函数，这种情况下需要分析堆栈信息来确定错误模块。

2.分析当前发生错误的直接原因
我们看到错误的指令是:idiv eax,ecx。基本上访问eax和ecx都不会有问题，不然就是cpu有问题了。所以应该是除法指令出错。看看前面的寄存器的信息，eax=00007fff，也就是RAND_MAX，ecx=00000000，除0错误。对于我们这个例子，有了这个信息就足够定位到问题了。不过还是看看我们还能收集到些什么信息，毕竟实际环境可不会这么简单。

3.分析当前线程的调用堆栈。
ChildEBP RetAddr Args to Child
0063ff80 004015e2 00000001 00000000 00000000 lesson_2!Worker+0x67
0063ffb8 7c824829 003724b8 00000000 00000000 lesson_2!_threadstartex+0xb2

在堆栈反向跟踪部分，这个信息很清晰。_threadstartex系统函数调用了我们的线程函数Worker。当前函数的返回地址是0x4015e2，接着是3个参数（注意：不一定都有效，显然不是所有的函数都有3个参数。实际上通过分析其dump文件能看到我们的例子中只有第一个参数有效，即1，是作为线程参数传入的lpParam）。这里我们结合map文件看看是不是跟这里记录的一样。在工程的debug目录里，有个扩展名为map的文件，用一般的文本编辑器就能打开。这文件太长了，节选一部分看看：

lesson_2

Timestamp is 48e0197a (Mon Sep 29 06:50:11 2008)

Preferred load address is 00400000

Start Length Name Class
0001:00000000 0001bae7H .text CODE
0001:0001bae7 00010009H .textbss CODE
0002:00000000 00002207H .rdata DATA
0002:00002207 00000000H .edata DATA
0003:00000000 00000104H .CRT$XCA DATA
0003:00000104 00000104H .CRT$XCZ DATA
0003:00000208 00000104H .CRT$XIA DATA
0003:0000030c 00000109H .CRT$XIC DATA
0003:00000418 00000104H .CRT$XIZ DATA
0003:0000051c 00000104H .CRT$XPA DATA
0003:00000620 00000104H .CRT$XPX DATA
0003:00000724 00000104H .CRT$XPZ DATA
0003:00000828 00000104H .CRT$XTA DATA
0003:0000092c 00000104H .CRT$XTZ DATA
0003:00000a30 0000407cH .data DATA
0003:00004ab0 00001b94H .bss DATA
0004:00000000 00000014H .idata$2 DATA
0004:00000014 00000014H .idata$3 DATA
0004:00000028 000001b0H .idata$4 DATA
0004:000001d8 000001b0H .idata$5 DATA
0004:00000388 0000076bH .idata$6 DATA

Address Publics by Value Rva+Base Lib:Object

0001:00000020 ?Worker@@YGIPAX@Z 00401020 f lesson_2.obj
0001:000000f0 _main 004010f0 f lesson_2.obj
0001:00000212 _Sleep@4 00401212 f kernel32:KERNEL32.dll
0001:00000218 _GetCurrentThreadId@0 00401218 f kernel32:KERNEL32.dll
0001:0000021e _CloseHandle@4 0040121e f kernel32:KERNEL32.dll
0001:00000224 _WaitForMultipleObjects@16 00401224 f kernel32:KERNEL32.dll
0001:00000230 _printf 00401230 f LIBCMTD:printf.obj
0001:000002d0 _srand 004012d0 f LIBCMTD:rand.obj
0001:000002e0 _rand 004012e0 f LIBCMTD:rand.obj
0001:00000320 __chkesp 00401320 f LIBCMTD:chkesp.obj
0001:00000360 _system 00401360 f LIBCMTD:system.obj
0001:00000470 __beginthreadex 00401470 f LIBCMTD:threadex.obj
0001:00000630 __endthreadex 00401630 f LIBCMTD:threadex.obj
0001:00000680 _mainCRTStartup 00401680 f LIBCMTD:crt0.obj
0001:000007d0 __amsg_exit 004017d0 f LIBCMTD:crt0.obj

。。。。。。省略若干。。。。。

Line numbers for ./Debug/lesson_2.obj(d:/debugeasy/lesson_2/lesson_2.cpp) segment .text

18 0001:00000020 19 0001:00000038 21 0001:00000044 22 0001:00000056
23 0001:0000005d 25 0001:0000006d 26 0001:0000009b 27 0001:000000ac
28 0001:000000ae 29 0001:000000b0 32 0001:000000f0 33 0001:00000108
34 0001:0000011a 36 0001:00000132 37 0001:00000152 39 0001:00000154
40 0001:00000161 42 0001:0000017a 44 0001:00000192 45 0001:000001a9
47 0001:000001ab 48 0001:000001b8 49 0001:000001c5 50 0001:000001c7

其中显示了程序名，程序的时间戳，程序中的代码分布，预定的加载地址，各个函数的起始地址，包括相对虚拟地址(RVA)以及文件行与RVA的对应关系等信息。我们看到预定的加载地址和我们在模块清单中看到的加载地址相同。很好，省得计算相对位置。一般来说Exe总是加载到0x400000，并且总是能得到这个位置的。而动态库的话，墨认是0x10000000，显然如果有2个动态库就没法都加载到同一个地址，需要计算RVA。

刚才从堆栈反向跟踪信息中我们看到当前Worker函数的返回地址为0x401e52，在map文件中找找。很快就能看到__beginthreadex函数是从0x401470开始，到0x401630结束。那就说明地址0x401e52就在__beginthreadex函数中。这就对了，因为我们就是用__beginthreadex函数启动的线程函数Worker，是吧~。顺手看一下刚才出错的地址0x401087，看看是在哪。再看看map文件，第一个函数就是?Worker@@YGIPAX@Z，地址是0x00401020至0x4010f0(main函数），所以0x401087就是在执行Worker函数中的指令。那么具体在哪一行呢？因为出错的函数Worker在文件lesson_2.cpp中，所以我们查找lesson_2.cpp,就找到了下面的信息：

Line numbers for ./Debug/lesson_2.obj(d:/debugeasy/lesson_2/lesson_2.cpp) segment .text

15 0001:00000020 16 0001:00000038 18 0001:00000044 19 0001:00000056
20 0001:0000005d 22 0001:0000006d 23 0001:0000009b 24 0001:000000ac
25 0001:000000ae 26 0001:000000b0 29 0001:000000f0 30 0001:00000108
31 0001:0000011a 33 0001:00000132 34 0001:00000152 46 0001:00000154
37 0001:00000161 39 0001:0000017a 41 0001:00000192 42 0001:000001a9
44 0001:000001ab 45 0001:000001b8 46 0001:000001c5 47 0001:000001c7

我们看到前面是个数字，18、19、21啥的，后面是0001:00000020之类。前面的就是cpp文件中的行号，后面是相对虚拟地址，我们的0x401087在哪呢？又回到刚才说的默认加载地址了。map中看到默认加载地址是0x400000，而我们的exe在内存中也是加载到0x400000,所以相对位置就是RVA = 0x401087(错误地址) - 0x400000(模块在内存中实际加载的地址) = 0x1067。不对啊，这里最大才到0x1c7，这是怎~么个情况？因为每个PE模块之前都有0x1000字节的dos stub和PE格式信息。所以0x1087还要减掉0x1000，就剩下0x87了。再看看，大于0x5d,小于0x6d，所以就是第22行。看看代码中的22行，printf("tid[%u] tmp = %d/n", dwTid, RAND_MAX/(rand()%cnThreadnum));没错，就是在这里RAND_MAX/0了~。说明前面根据Dr.Watson的日志分析的结果都是正确的，没骗你噢~

有时候堆栈反向跟踪的信息并不准确，多半是因为函数中的局部变量在memcpy,strcpy之类的函数复制的数据过长，导致堆栈访问越界。这种情况下，要仔细分析原始堆栈转储，以后再说。

在实际工作中，利用Dr.Watson辅助生成错误日志，对于开发人员确实是很有帮助的。有需要的朋友，可以考虑这么试试。

那今天就写到这吧~ 天亮啦，饭去~