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

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

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

先把测试代码贴一下:

  1. /********************************************************************/
  2. /*程序:lesson_2, 结合Dr.Watson与工程map文件定位错误 */
  3. /*功能:多线程环境中利用除0错误使程序产生异常,被Dr.Watson捕获之 */
  4. /*作者:coding(http://blog.****.net/coding_hello) */
  5. /*日期:2008-09-29 */
  6. /********************************************************************/
  7. #include<stdio.h>
  8. #include<process.h>
  9. #include<windows.h>
  10. constintcnThreadnum=4;
  11. UINTWINAPIWorker(LPVOIDlpParam)
  12. {
  13. srand((DWORD)lpParam);
  14. DWORDdwTid=GetCurrentThreadId();
  15. intk=100;
  16. while(k--)
  17. {
  18. printf("tid[%u]tmp=%d/n",dwTid,RAND_MAX/(rand()%cnThreadnum));
  19. Sleep(10);
  20. }
  21. return0;
  22. }
  23. intmain(intargc,char*argv[])
  24. {
  25. HANDLEhThd[cnThreadnum]={0};
  26. for(DWORDi=0;i<cnThreadnum;i++)
  27. {
  28. hThd[i]=(HANDLE)_beginthreadex(NULL,0,Worker,(LPVOID)i,0,NULL);
  29. }
  30. printf("Wait.../n");
  31. WaitForMultipleObjects(cnThreadnum,hThd,TRUE,INFINITE);
  32. for(intk=0;k<cnThreadnum;k++)
  33. {
  34. CloseHandle(hThd[k]);
  35. }
  36. printf("Finish!/n");
  37. system("pause");
  38. return0;
  39. }

程序已开始就启动了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恢复为默认调试器的)。注册完以后,我们看看注册表是否满足需要了。

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

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

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

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

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

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

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

错误 ->00401087 f7f9 idiv eax,ecx

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

  1. *---->线程ID0x2714的状态转储<----*
  2. eax=00007fffebx=003724b8ecx=00000000edx=00000000esi=0063ff2cedi=0063ff80
  3. eip=00401087esp=0063ff2cebp=0063ff80iopl=0nvupeiplzrnapenc
  4. cs=001bss=0023ds=0023es=0023fs=003bgs=0000efl=00010246
  5. 函数:lesson_2!Worker
  6. 0040106b7441 jelesson_2!Worker+0x8e(004010ae)
  7. 0040106de86e020000 calllesson_2!rand(004012e0)
  8. 004010728bc8 movecx,eax
  9. 0040107481e103000080andecx,80000003h
  10. 0040107a7905 jnslesson_2!Worker+0x61(00401081)
  11. 0040107c49 dececx
  12. 0040107d83c9fc orecx,0FFFFFFFCh
  13. 0040108041incecx
  14. 00401081b8ff7f0000moveax,7FFFh
  15. 0040108699 cdq
  16. 错误->00401087f7f9 idiveax,ecx
  17. 0040108950 pusheax
  18. 0040108a8b55fc movedx,dwordptr[ebp-4]
  19. 0040108d52 pushedx
  20. 0040108e681cd04200 pushoffsetlesson_2!`string'(0042d01c)
  21. 00401093e898010000 calllesson_2!printf(00401230)
  22. 0040109883c40c addesp,0Ch
  23. 0040109b8bf4 movesi,esp
  24. 0040109d6a0a push0Ah
  25. 0040109fff15d8714300calldwordptr[lesson_2!_imp__Sleep(004371d8)]
  26. 004010a53bf4 cmpesi,esp
  27. *---->堆栈反向跟踪<---*
  28. ChildEBP RetAddr ArgstoChild
  29. 0063ff80 004015e2 00000001 00000000 00000000 lesson_2!Worker+0x67
  30. 0063ffb8 7c824829 003724b8 00000000 00000000 lesson_2!_threadstartex+0xb2
  31. WARNING:Stackunwindinformationnotavailable.Followingframesmaybewrong.
  32. 0063ffec 00000000 00401530 003724b8 00000000 kernel32!GetModuleHandleA+0xdf
  33. *---->原始堆栈转储<----*
  34. 000000000063ff2c 0000000000000000-b8243700 cc cc cc cc.........$7.....
  35. 000000000063ff3c cc cccc cc cc cccc cc-cc cc cc cc cc cc cc cc................
  36. 000000000063ff4c cc cccc cc cc cccc cc-cc cc cc cc cc cc cc cc................
  37. 000000000063ff5c cc cccc cc cc cc cccc-cc cc cc cc cc cc cc cc................
  38. 000000000063ff6c cc cccc cc cc cc cccc-cc cc cc cc 060000 00................
  39. 000000000063ff7c 14270000b8ff 6300-e21540 00 010000 00.'[email protected]
  40. 000000000063ff8c 0000000000000000-b8243700 9400 00c0.........$7.....
  41. 000000000063ff9c 000000008cff 6300-60fb6300 dc ff 6300......c.`.c...c.
  42. 000000000063ffac b4654000b0d14200-00000000ec ff [email protected]
  43. 000000000063ffbc 2948 827cb8243700-000000000000 0000)H.|.$7.........
  44. 000000000063ffcc b8243700940000c0-c4 ff 630060fb 63 00.$7.......c.`.c.
  45. 000000000063ffdc ff ff ff ff 601a 827c-3048827c000000 00....`..|0H.|....
  46. 000000000063ffec 0000000000000000-30154000b82437 [email protected]$7.
  47. 000000000063fffc 0000000000000000-0000000000 000000................
  48. 000000000064000c0000000000000000-0000000000 000000................
  49. 000000000064001c0000000000000000-0000000000 000000................
  50. 000000000064002c0000000000000000-0000000000 000000................
  51. 000000000064003c0000000000000000-0000000000 000000................
  52. 000000000064004c0000000000000000-0000000000 000000................
  53. 000000000064005c0000000000000000-0000000000 000000................

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

1.定位出错的模块。

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

  1. *---->模块清单<----*
  2. 0000000000400000-000000000043a000:D:/DebugEasy/lesson_2/Debug/lesson_2.exe
  3. 0000000074ae0000-0000000074b45000:C:/windows/system32/USP10.dll
  4. 0000000076180000-000000007619d000:C:/windows/system32/IMM32.DLL
  5. 0000000076eb0000-0000000076ec3000:C:/windows/system32/Secur32.dll
  6. 0000000077bd0000-0000000077c18000:C:/windows/system32/GDI32.dll
  7. 0000000077c20000-0000000077cbf000:C:/windows/system32/RPCRT4.dll
  8. 0000000077e10000-0000000077ea0000:C:/windows/system32/USER32.dll
  9. 0000000077f30000-0000000077fdb000:C:/windows/system32/ADVAPI32.dll
  10. 000000007c800000-000000007c92b000:C:/windows/system32/kernel32.dll
  11. 000000007c930000-000000007ca00000:C:/windows/system32/ntdll.dll
  12. 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的文件,用一般的文本编辑器就能打开。这文件太长了,节选一部分看看:

  1. lesson_2
  2. Timestampis48e0197a(MonSep2906:50:112008)
  3. Preferredloadaddressis00400000
  4. Start LengthNameClass
  5. 0001:000000000001bae7H.text CODE
  6. 0001:0001bae700010009H.textbssCODE
  7. 0002:0000000000002207H.rdataDATA
  8. 0002:0000220700000000H.edataDATA
  9. 0003:0000000000000104H.CRT$XCADATA
  10. 0003:0000010400000104H.CRT$XCZDATA
  11. 0003:0000020800000104H.CRT$XIADATA
  12. 0003:0000030c00000109H.CRT$XICDATA
  13. 0003:0000041800000104H.CRT$XIZDATA
  14. 0003:0000051c00000104H.CRT$XPADATA
  15. 0003:0000062000000104H.CRT$XPX DATA
  16. 0003:0000072400000104H.CRT$XPZDATA
  17. 0003:0000082800000104H.CRT$XTADATA
  18. 0003:0000092c00000104H.CRT$XTZDATA
  19. 0003:00000a300000407cH.data DATA
  20. 0003:00004ab000001b94H.bss DATA
  21. 0004:0000000000000014H.idata$2DATA
  22. 0004:0000001400000014H.idata$3DATA
  23. 0004:00000028000001b0H.idata$4DATA
  24. 0004:000001d8000001b0H.idata$5DATA
  25. 0004:000003880000076bH.idata$6DATA
  26. AddressPublicsbyValueRva+BaseLib:Object
  27. 0001:[email protected]@[email protected]_2.obj
  28. 0001:000000f0_main 004010f0flesson_2.obj
  29. 0001:[email protected] 00401212fkernel32:KERNEL32.dll
  30. 0001:[email protected] 00401218fkernel32:KERNEL32.dll
  31. 0001:[email protected] 0040121efkernel32:KERNEL32.dll
  32. 0001:00000224[email protected] 00401224fkernel32:KERNEL32.dll
  33. 0001:00000230_printf 00401230f LIBCMTD:printf.obj
  34. 0001:000002d0_srand 004012d0f LIBCMTD:rand.obj
  35. 0001:000002e0_rand 004012e0fLIBCMTD:rand.obj
  36. 0001:00000320__chkesp 00401320fLIBCMTD:chkesp.obj
  37. 0001:00000360_system00401360fLIBCMTD:system.obj
  38. 0001:00000470__beginthreadex 00401470fLIBCMTD:threadex.obj
  39. 0001:00000630__endthreadex 00401630fLIBCMTD:threadex.obj
  40. 0001:00000680_mainCRTStartup00401680fLIBCMTD:crt0.obj
  41. 0001:000007d0__amsg_exit 004017d0fLIBCMTD:crt0.obj
  42. 。。。。。。省略若干。。。。。
  43. Linenumbersfor./Debug/lesson_2.obj(d:/debugeasy/lesson_2/lesson_2.cpp)segment.text
  44. 180001:00000020190001:00000038210001:00000044220001:00000056
  45. 230001:0000005d250001:0000006d260001:0000009b270001:000000ac
  46. 280001:000000ae290001:000000b0320001:000000f0330001:00000108
  47. 340001:0000011a360001:00000132370001:00000152390001:00000154
  48. 400001:00000161420001:0000017a440001:00000192450001:000001a9
  49. 470001:000001ab480001:000001b8490001:000001c5500001:000001c7

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

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

  1. Linenumbersfor./Debug/lesson_2.obj(d:/debugeasy/lesson_2/lesson_2.cpp)segment.text
  2. 150001:00000020160001:00000038180001:00000044190001:00000056
  3. 200001:0000005d220001:0000006d230001:0000009b240001:000000ac
  4. 250001:000000ae260001:000000b0290001:000000f0300001:00000108
  5. 310001:0000011a330001:00000132340001:00000152460001:00000154
  6. 370001:00000161390001:0000017a410001:00000192420001:000001a9
  7. 440001:000001ab450001:000001b8460001:000001c5470001: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辅助生成错误日志,对于开发人员确实是很有帮助的。有需要的朋友,可以考虑这么试试。

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