记一次 .NET 某教育系统异常崩溃分析

一：背景

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。