記一次 .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