WinDBg定位asp.net mvc项目异常崩溃源码位置

项目介绍:asp.net mvc + angular +iis(windows)+windows server

系统莫名崩溃

最近有个系统默认奇妙崩溃50x,服务整体变成无响应,当运维告知我只有重启应用程序池项目才能正常。

我问他如何重现,得到的回复是我这里无法重现,但客户使用一段时间后,就会崩溃。

于是我崩溃了。因为查日志没有任何错误,查windows系统日志上也只有一个错误 System.AccessViolationException 尝试读取或写入受保护的内存。这通常指示其他内存已损坏,从系统的日志也无法定位到错误代码。搜索关键字,未找到任何有用的信息。

寻求其他方案定位错误

正好最近看到一线码农 通过dump文件定位程序异常情况,分析内存,分析线程的操作。我这才有了新的思路,不然也只能二眼干瞪,无计可施。

第一步是抓取dump文件。

首先,在服务器端:

1.开启Windows Error Reporting Service服务。

2.将下面的脚本保存成 dumps.reg ,在服务器上执行。

.执行注册表脚本后,在w3wp.exe程序挂掉的时候,自动将dump文件保存到D:\dumps文件夹中:

Windows Registry Editor Version 5.00
[HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\Windows Error Reporting\LocalDumps\w3wp.exe]
"DumpFolder"=hex(2):64,00,3a,00,5c,00,64,00,75,00,6d,00,70,00,73,00,00,00
"DumpCount"=dword:00000002
"DumpType"=dword:00000002

正好服务器没有d盘,我们就打开cmd,输入 regedit 打开服务器的注册表。找到 HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\Windows Error Reporting\LocalDumps\w3wp.exe, 我们可以看到DumpFolder的设置项,可以根据自己需要改成相应的目录。

WinDBg定位asp.net mvc项目异常崩溃源码位置

过了半天,程序又崩溃了,我先让实施先重启IIS应用池,再拿过来dmp文件,发现会有二个。

WinDBg定位asp.net mvc项目异常崩溃源码位置

一开始我按一些文档,将抓取的dump文件,用vs打开,尝试vs调试,即时设置了符号服务器,调试源文件增加源代码路径,也无法定位到源代码。浪费了许多时间。我决定去找下专业的工具。

WinDbg出场

工具:WinDbg

从Microsoft Store下载windbg Preview,

WinDBg定位asp.net mvc项目异常崩溃源码位置

For analysis of this file, run !analyze -v

点击后!analyze -v得到的一些信息,和之前的windows系统日志差不多。此时处于busy状态,无法操作,标记处是输入查询命令处。

WinDBg定位asp.net mvc项目异常崩溃源码位置

经过一段时间分析,得到如下结果。

Key  : CLR.Exception.System.AccessViolationException._message
Value: 尝试读取或写入受保护的内存。这通常指示其他内存已损坏。 Key : CLR.Exception.Type
Value: System.AccessViolationException

还有一段,我一直看不懂。因为当时看到了 如何从 dump 文件中提取出 C# 源代码? 这个文章,我就想,能不能,定位错误的源码,所以用 !savemodule 76c656e8 d:\dumps\xxx.dll ,生成dll,再用ILspy,是无法反编译的,可能这段错,实际上是c++上报的错。我想应该,那篇文章就只是从dump文件中找到相应的模块,然后导出整体dll。由于 源码非常 多,在一个dll上,也是无法找到错误的。

CONTEXT:  (.ecxr)
eax=1c8cf308 ebx=00000005 ecx=00000005 edx=00000000 esi=1c8cf3d0 edi=00000001
eip=76c656e8 esp=1c8cf308 ebp=1c8cf364 iopl=0 nv up ei pl nz ac po nc
cs=0023 ss=002b ds=002b es=002b fs=0053 gs=002b efl=00000212
KERNELBASE!RaiseException+0x48:
76c656e8 8b4c2454 mov ecx,dword ptr [esp+54h] ss:002b:1c8cf35c=69c84946
Resetting default scope EXCEPTION_RECORD: (.exr -1)
ExceptionAddress: 76c656e8 (KERNELBASE!RaiseException+0x00000048)
ExceptionCode: e0434352 (CLR exception)
ExceptionFlags: 00000001
NumberParameters: 5
Parameter[0]: 80004003
Parameter[1]: 00000000
Parameter[2]: 00000000
Parameter[3]: 00000000
Parameter[4]: 70880000
PROCESS_NAME: w3wp.exe EXCEPTION_CODE_STR: 80004003 FAULTING_THREAD: ffffffff STACK_TEXT:
00000000 00000000 w3wp!unknown_function+0x0
STACK_COMMAND: ** Pseudo Context ** ManagedPseudo ** Value: ffffffff ** ; kb SYMBOL_NAME: w3wp!unknown_function MODULE_NAME: w3wp IMAGE_NAME: w3wp.exe FAILURE_BUCKET_ID: CLR_EXCEPTION_System.AccessViolationException_80004003_w3wp.exe!unknown_function

我就在想会不会有死锁,或文件访问异常导致的。先把写日志的代码单独拿出来,再用Jmeter,并发访问写日志的接口,即时是我们自己写的日志,在疯狂请求时,也不会导致程序异常,。由于项目代码是旧代码,对内部可能哪里会问题也猜不到。

我先说正确的思路

  • !threads

    我们可以看到有一个线程Woker上有异常。

ThreadCount:      9
UnstartedThread: 0
BackgroundThread: 9
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
Lock
ID OSID ThreadOBJ State GC Mode GC Alloc Context Domain Count Apt Exception
8 1 2188 019da830 28220 Preemptive 10C08398:00000000 01a02bd8 0 Ukn
29 2 36b8 025d7738 2b220 Preemptive 00000000:00000000 01a02bd8 0 MTA (Finalizer)
31 3 1c6c 0260b568 102a220 Preemptive 00000000:00000000 01a02bd8 0 MTA (Threadpool Worker)
32 4 315c 02616678 21220 Preemptive 00000000:00000000 01a02bd8 0 Ukn
34 6 31c0 026180e0 1020220 Preemptive 00000000:00000000 01a02bd8 0 Ukn (Threadpool Worker)
35 7 1274 02618628 1029220 Preemptive 069745A0:00000000 01a02bd8 0 MTA (Threadpool Worker)
37 8 2484 02617108 1029220 Preemptive 0EBFFB18:00000000 01a02bd8 0 MTA (Threadpool Worker) System.AccessViolationException 0ebee9dc
38 9 2234 026156a0 1029220 Preemptive 0AAED5CC:00000000 01a02bd8 0 MTA (Threadpool Worker)
39 10 3858 02617b98 1029220 Preemptive 0CB7BEE0:00000000 01a02bd8 0 MTA (Threadpool Worker)

这时候我们就可以 使用 !pe ,这个命令 打印出exception

0:037> !pe
Exception object: 0ebee9dc
Exception type: System.AccessViolationException
Message: 尝试读取或写入受保护的内存。这通常指示其他内存已损坏。
InnerException: <none>
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80004003

0ebee9dc 这个在windbg上显示是绿色的。可以直接点击,就会生成如下命令。

0:037> !DumpObj /d 0ebee9dc

可以看到_stackTraceString的value是灰色,是无法点击的,我有好几次已经定位到这一步了,但我没有点击如下选中的value值。点击他就会展示具体的源码错误异常 ,没走对方向,主要原因不清楚 windbg是什么,这些变量代表的含义。

这是点击绿色的0ebfd24c这个地址执行的命令。

0:037> !DumpObj /d 0ebfd24c

WinDBg定位asp.net mvc项目异常崩溃源码位置

这是点击绿色的0ebfd24c这个地址执行的命令。

0:037> !DumpObj /d 0ebfd24c

WinDBg定位asp.net mvc项目异常崩溃源码位置

定位到源码,一切就会很清楚了,虽然感觉这行不可能报错,但事实就是普普通通Oralce 访问数据库的ExecuteNonQuery(),报的AccessViolationException` 错,这个错即使通过Try Catch也无法抓取,

网上看到一些方法是重置网络,由于是生产环境,我对服务器环境一无所知,有实施管理,所以未尝试。

netsh winsock reset

重新定位了最后几个请求的参数,的确发现了有些奇怪。这个变量是换行了。我一开始也看到这个语句,当时是很奇怪,而且拿到plSQL中执行,发现是正常的,就没在意,但现在发现可能是这个参数导致的。

update xxx set  xxx='
"$$hashKey": "object:231"
' where info_id = '792094'

定位下前台源码,原来某个下拉区选择,代码取的是object,没取到对应的值,直接传给后台,而后台sql是配置的,该变量直接是拼接的,不是参数化。所以我决定先改掉这个再看情况,给实施发布打包,最近已经10天(2021-4-29),也没有说程序崩溃的问题。

在此之前,我还查了内存,死锁情况,然而一无所获。

在此非常 感谢 一线码农 ,原本也没打算写个文章,但大佬说也整理分享下遇到的坑。才有此文章。

也正是了解到了windbg这种方式去调试,去分析,才能定位,并解决这种问题。

不然程序崩溃,我也要一起崩溃。。。

上一篇:Pro ASP.NET MVC 5 Framework.学习笔记.6.3.MVC的必备工具


下一篇:ASP.NET MVC显示异常信息