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的設置項,可以根據自己需要改成相應的目錄。

過了半天,程序又崩潰了,我先讓實施先重啟IIS應用池,再拿過來dmp文件,發現會有二個。

一開始我按一些文檔,將抓取的dump文件,用vs打開,嘗試vs調試,即時設置了符號服務器,調試源文件增加源代碼路徑,也無法定位到源代碼。浪費了許多時間。我決定去找下專業的工具。

WinDbg出場

工具:WinDbg

從Microsoft Store下載windbg Preview,

For analysis of this file, run !analyze -v

點擊后!analyze -v得到的一些信息,和之前的windows系統日志差不多。此時處於busy狀態,無法操作,標記處是輸入查詢命令處。

經過一段時間分析,得到如下結果。

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

定位到源碼,一切就會很清楚了,雖然感覺這行不可能報錯,但事實就是普普通通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這種方式去調試,去分析,才能定位,並解決這種問題。

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


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM