項目介紹: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也無法抓取,
-
相似的問題:https://stackoverflow.com/questions/27383472/executenonquery-exception-not-caught-by-try-catch
-
Runtime中也有類似的issues :https://github.com/dotnet/runtime/issues/981
網上看到一些方法是重置網絡,由於是生產環境,我對服務器環境一無所知,有實施管理,所以未嘗試。
netsh winsock reset
重新定位了最后幾個請求的參數,的確發現了有些奇怪。這個變量是換行了。我一開始也看到這個語句,當時是很奇怪,而且拿到plSQL中執行,發現是正常的,就沒在意,但現在發現可能是這個參數導致的。
update xxx set xxx='
"$$hashKey": "object:231"
' where info_id = '792094'
定位下前台源碼,原來某個下拉區選擇,代碼取的是object,沒取到對應的值,直接傳給后台,而后台sql是配置的,該變量直接是拼接的,不是參數化。所以我決定先改掉這個再看情況,給實施發布打包,最近已經10天(2021-4-29),也沒有說程序崩潰的問題。
在此之前,我還查了內存,死鎖情況,然而一無所獲。
在此非常 感謝 一線碼農 ,原本也沒打算寫個文章,但大佬說也整理分享下遇到的坑。才有此文章。
也正是了解到了windbg這種方式去調試,去分析,才能定位,並解決這種問題。
不然程序崩潰,我也要一起崩潰。。。