記一次 .NET 某教育系統API 異常崩潰分析

一：背景

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