一:背景
1. 講故事
這篇文章起源於 搬磚隊大佬
的精彩文章 WinDBg定位asp.net mvc專案異常崩潰原始碼位置 ,寫的非常好,不過美中不足的是通覽全文之後,總覺得有那麼一點不過癮,就是沒有把當時拋異常前的引數給找出來。。。這一篇我就試著彌補這個遺憾???。
為了能夠讓文章行雲流水,我就按照自己的偵察思路吧,首先看一下現狀:iis上的應用程式崩潰, catch 不到錯誤,windows日誌中只記錄了一個 AccessViolationException
異常,如何分析?
說實話我也是第一次在託管語言 C# 中遇到這種異常,夠奇葩,先看看 MSDN 上的解釋。
好了,先不管奇葩不奇葩,反正有了一份 dump + AccessViolationException
,還是可以挖一挖的,老規矩,上windbg說話。
二: windbg 分析
1. 尋找異常的執行緒
如果是在 異常崩潰
的時候抓的dump,一般來說這個異常會掛在這個執行執行緒上,不相信的話,可以看看dump。
0:0:037> !t
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)
上面的第37號
執行緒清楚的記錄了異常 System.AccessViolationException
,後面還跟了一個異常物件的地址 0ebee9dc
,接下來就可以用 !do
給列印出來。
0:0:037> !do 0ebee9dc
Name: System.AccessViolationException
MethodTable: 6fc1bf4c
EEClass: 6f926bec
Size: 96(0x60) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
6fc146a4 4000005 10 System.String 0 instance 0ebf02f0 _message
6fc1be98 4000006 14 ...tions.IDictionary 0 instance 00000000 _data
6fc146a4 400000c 2c System.String 0 instance 0ebfd24c _remoteStackTraceString
這個 Exception 上面有很多的屬性,比如最後一行的 _remoteStackTraceString
顯示的就是異常堆疊資訊,接下來我再給 do 一下。
0:0:037> !do 0ebfd24c
Name: System.String
MethodTable: 6fc146a4
EEClass: 6f8138f0
Size: 10444(0x28cc) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
String: 在 System.Data.Common.UnsafeNativeMethods.ICommandText.Execute(IntPtr pUnkOuter, Guid& riid, tagDBPARAMS pDBParams, IntPtr& pcRowsAffected, Object& ppRowset)
在 System.Data.OleDb.OleDbCommand.ExecuteCommandTextForMultpleResults(tagDBPARAMS dbParams, Object& executeResult)
在 System.Data.OleDb.OleDbCommand.ExecuteCommandText(Object& executeResult)
在 System.Data.OleDb.OleDbCommand.ExecuteCommand(CommandBehavior behavior, Object& executeResult)
在 System.Data.OleDb.OleDbCommand.ExecuteReaderInternal(CommandBehavior behavior, String method)
在 System.Data.OleDb.OleDbCommand.ExecuteNonQuery()
在 xxx.Model.xxx.getOneData(OleDbCommand comm)
在 xxx.Model.xxx.getOtherDataSource(List`1 keys, Dictionary`2 data)
在 xxx.Controllers.xxxOtherController.Post(JObject json)
在 System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.<>c__DisplayClass10.<GetExecutor>b__9(Object instance, Object[] methodParameters)
在 System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ActionExecutor.Execute(Object instance, Object[] arguments)
在 System.Web.Http.Controllers.ReflectedHttpActionDescriptor.ExecuteAsync(HttpControllerContext controllerContext, IDictionary`2 arguments, CancellationToken cancellationToken)
我去,原來是執行資料庫的時候丟擲的 AccessViolationException
,哈哈,有點意思,究竟是個什麼樣的神操作能搞出這個異常? 好,接下來我就來挖一下 getOneData()
方法到底幹了什麼?
2.尋找問題程式碼 getOneData()
要想找到 getOneData()
的原始碼,還是老規矩,使用 !name2ee + !savemodule
匯出。
0:0:037> !name2ee *!xxx.Model.xxx.getOneData
--------------------------------------
Module: 1b9679c0
Assembly: xxx.dll
Token: 06000813
MethodDesc: 0149faec
Name: xxx.Model.xxx.getOneData(System.Data.OleDb.OleDbCommand)
JITTED Code Address: 1ede0050
--------------------------------------
0:0:037> !savemodule 1b9679c0 E:\dumps\2.dll
3 sections in file
section 0 - VA=2000, VASize=d8d74, FileAddr=200, FileSize=d8e00
section 1 - VA=dc000, VASize=318, FileAddr=d9000, FileSize=400
section 2 - VA=de000, VASize=c, FileAddr=d9400, FileSize=200
有了 2.dll
,接下來就可以用 ILSPY 看一看原始碼。
從原始碼上看也都是一些中規中矩的操作,沒啥特別的地方,既然寫法上沒問題,我也只能懷疑是某些資料方面出了問題,接下來準備挖一挖 OleDbCommand
。
3. 從執行緒棧上提取 OleDbCommand 物件
玩過 ADO.NET 的都知道,最後的 sql + parameters
都是藏在 OleDbCommand 上的,參考程式碼如下:
public sealed class OleDbCommand : DbCommand, ICloneable, IDbCommand, IDisposable
{
public override string CommandText { get; set; }
public new OleDbParameterCollection Parameters
{
get
{
OleDbParameterCollection oleDbParameterCollection = _parameters;
if (oleDbParameterCollection == null)
{
oleDbParameterCollection = (_parameters = new OleDbParameterCollection());
}
return oleDbParameterCollection;
}
}
}
所以目標很明確,就是把 CommandText + Parameters
給挖出來,說幹就幹,用 !clrstack -a
提取執行緒棧上的所有引數,如下圖所示:
真是悲劇,由於異常的丟擲搗毀了執行緒呼叫棧,尼瑪,也就是說呼叫棧上的 區域性變數 + 方法引數
都被銷燬了,這該如何是好呀?好想哭???。
在迷茫了一段時間後,突然靈光一現,對,雖然呼叫棧被搗毀了,但 OleDbCommand
是引用型別啊,棧地址沒了就沒了,OleDbCommand 本尊肯定還是在熱乎的 gen0 上,畢竟也是剛丟擲來的異常,這時候 GC 還在打呼嚕,肯定不會回收它的,哈哈,突然又充滿能量了。
4. 從託管堆中尋找 OleDbCommand
要想在託管堆上找 OleDbCommand 的話,使用如下命令: !dumpheap -type OleDbCommand
即可。
||0:0:037> !dumpheap -type OleDbCommand
Address MT Size
02a8393c 6c74a6a8 84
02bc280c 6c74a6a8 84
02bd98dc 6c74a6a8 84
02be1d74 6c74a6a8 84
02be3c68 6c74a6a8 84
02be5b3c 6c74a6a8 84
0696f978 6c74a6a8 84
0a94ea54 6c74a6a8 84
0a9678b8 6c74a6a8 84
0a96a5a0 6c74a6a8 84
0aabefe4 6c74a6a8 84
0eb10e08 6c74a6a8 84
Statistics:
MT Count TotalSize Class Name
6c74a6a8 12 1008 System.Data.OleDb.OleDbCommand
Total 12 objects
還不錯,託管堆上只有 12 個 OleDbCommand,說明這程式也是剛起來沒溜兩圈就掛掉了,接下來要做的事就是逐個排查裡面的 Sql + Parameter
是否有異常,用人肉去檢查,能把眼睛給弄瞎,所以得把這髒活累活留給 script
去實現,為此我花了一個小時寫了一個指令碼,都差點寫睡著了???。
"use strict";
function initializeScript() {
return [new host.apiVersionSupport(1, 7)];
}
function invokeScript() {
//獲取所有 oledbComamand 物件
var output = exec("!dumpheap -type System.Data.OleDb.OleDbCommand -short");
for (var line of output) {
showOleDb(line);
log("------------------------------------------------------------------------");
}
}
//遍歷oledb
function showOleDb(oledb) {
log("oledb: " + oledb);
showsql(oledb);
showparameters(oledb);
}
//show sql
function showsql(oledb) {
var command = "!do -nofields poi(" + oledb + "+0x10)";
var output = exec(command).Skip(5);
for (var line of output) {
log(line);
}
}
//show parameters
function showparameters(oledb) {
var address = "poi(poi(poi(" + oledb + "+0x1c)+0x8)+0x4)"
var arrlen = "poi(" + address + "+0x4)";
var command = "!da -nofields -details " + address;
//var str = "";
var output = exec(command).Where(k => k.indexOf("[") == 0).Select(k => k.split(' ')[1])
.Where(k => k != "null").Select(k => k);
for (var line of output) {
var name = showparamname(line);
var value = showparamvalue(line);
log(name + " -> " + value);
}
}
//show parametername
function showparamname(param) {
var command = "!do -nofields poi(" + param + "+0xc)";
var output = exec(command);
output = output.Skip(5).First().replace("String: ", "");
return output;
}
//show paramtervalue
function showparamvalue(param, offset) {
//第一步: 判斷是否為引用型別
var address = "poi(" + param + "+0x14)";
var isGtZero = parseInt(exec(".printf \"%d\"," + address).First()) > 0;
if (!isGtZero) return "0";
var command = "!do -nofields " + address;
var output = exec(command);
//第二步: 判斷是否為 System.DateTime
var isDateTime = output.First().indexOf("System.DateTime") > -1;
if (isDateTime) return getFormatDate(address);
output = output.Skip(5).First().replace("String: ", "");
return output;
}
function getFormatDate(address) {
//16hex
var dtstr = ".printf \"%02X%02X\",poi(" + address + "+0x8),poi(" + address + "+0x4);";
//10hex
var num = parseInt("0x" + exec(dtstr).First(), 16);
var command = "!filetime ((0n" + num + " & 0x3fffffffffffffff) - 0n504911519999995142)";
var time = exec(command).First().split("(")[0].trim();
return time;
}
function log(instr) {
host.diagnostics.debugLog("\n" + instr + "\n");
}
function exec(str) {
return host.namespace.Debugger.Utility.Control.ExecuteCommand(str);
}
簡單說一下,上面的 poi
表示取地址上的值,這個值可能是數字,也可能是引用地址,接下來把指令碼跑起來, 由於這資訊太敏感了,只能虛擬化了哈。
------------------------------------------------------------------------
oledb: 0eb10e08
String: update xxx set a=:a, b=:b, c=:c where info_id = :info_id
a -> 'xxx'
b -> 'yyy'
c -> File: C:\Windows\Microsoft.NET\Framework\v4.0.30319\Temporary ASP.NET Files\collegeappxy\e05a2cb1\4405de9e\assembly\dl3\d914f432\c1375f08_c05cd201\Newtonsoft.Json.dll
info_id -> 1
在 1s 的等待後,終於發現上面這條 sql 的引數化 c 出了問題,因為它是一個 Newtonsoft.Json.dll
的 File,真奇葩,稍微修改一下指令碼把這個引數的 address 找出來。
||0:0:037> !do -nofields poi(0eb9ba40+0x14)
Name: Newtonsoft.Json.Linq.JObject
MethodTable: 1c600d98
EEClass: 1c5f31d0
CCW: 1bbd0020
Size: 68(0x44) bytes
File: C:\Windows\Microsoft.NET\Framework\v4.0.30319\Temporary ASP.NET Files\collegeappxy\e05a2cb1\4405de9e\assembly\dl3\d914f432\c1375f08_c05cd201\Newtonsoft.Json.dll
到此基本確定是因為把 JObject
放入了引數化導致了異常的發生,為此我還特意查了下 JObject
,一個挺有意思的玩意,將它 ToString() 之後居然是以格式化方式顯示的,如下圖所示:
如果想要去掉這種格式化,需要在 ToString() 中配一個 None 列舉,哈哈,就是這麼出乎意料 ??? 。
三:總結
總的來說,我覺得這是 OleDbCommand 的一個bug,既然是做引數化,就算我把 ? 投下去了,你也要給我正確入庫,不是嘛? 其次從分析結果看,知道了這種異常的呼叫堆疊,解決起來也是非常容易的,使用日誌記錄下當時的 OleDbCommand
就可以了,使用 script 暴力搜尋那也是萬不得已的事情???, 最後感謝 搬磚隊大佬
的精彩文章和dump。
更多高質量乾貨:參見我的 GitHub: dotnetfly