一次尋找IBatisNet事務bug的過程

時間 2019-11-08

標籤一次尋找 ibatisnet 事務 bug 過程欄目 MyBatis 简体版

原文原文鏈接

本文的上下文環境前端

操做系統：Win7 x64 Professionalsql

開發工具：Visual Studio 2017 語言：C#數據庫

數據庫ORM：IBatisNet 1.6.2編程

1、前言小程序

這個項目的前端有Web端，公衆號，微信小程序，後端是用WCF寫的，部署成windows service。後端使用了IBatisNet這樣的輕量級ORM框架，sql是寫在xml裏面的，每一個模塊都有一個xml文件。sql的返回值對應的實體類配置在同一個xml文件裏，像這樣。windows

2、問題出現後端

這個項目一直運行的很正常，直到有一天發佈了某一個功能以後，問題就出現了，異常日誌常常看到這樣的文字「SqlMap could not invoke BeginTransaction(). A Transaction is already started. Call CommitTransaction() or RollbackTransaction first」，一看代碼，這個異常是從SqlMapper.BeginTransaction方法裏面拋出的，字面意思就是啓動事務，不能正常啓動，須要首先調用提交或回滾事務。按着這個邏輯來講，應該是某一次事務忘記提交或回滾了。可是這個錯誤在本地開發環境復現不了，線上環境時不時的出現。若是本地可以reproduce，應該會比較好解決一些。微信小程序

3、查看bug原由微信

咱們項目中事務用了PostSharp裏面的AOP編程，只要在須要事務的方法上面加個attribute就能實現事務支持。代碼以下：session

[Serializable]
    [AttributeUsage(AttributeTargets.Method, AllowMultiple = true)] public class AopTransactionMethodAttribute : MethodInterceptionAspect { //調用本函數時截取異常 public override void OnInvoke(MethodInterceptionArgs args) { Mapper.Instance().BeginTransaction(); try { //執行方法 base.OnInvoke(args); } catch { Mapper.Instance().RollBackTransaction(); throw; } TData result = args.ReturnValue as TData; if (result == null || result.Tag <= 0) { //回滾事務  Mapper.Instance().RollBackTransaction(); } else { //提交事務  Mapper.Instance().CommitTransaction(); } } }

AopTransactionMethodAttribute

這樣就是很方便寫代碼，不用在每一個操做數據庫多表的地方都顯式地調用事務。

一開始懷疑這個地方可能有問題，在try catch的基礎上又加了一個try catch finally 用來完全提交或迴歸事務。發佈到線上以後，錯誤仍然時不時的出現。

因爲只能在線上環境能夠重現，考慮只能使用日誌來記錄執行過程了，我把事務的BeginTransaction，CommitTransaction，RollbackTransaction的執行所有記上日誌，考慮業務會併發執行，日誌確定要加鎖，而且把每次事務的CallStack和ThreadId給輸出來，代碼以下：

 public static readonly object LockTransaction = new object();
public ISqlMapSession BeginTransaction()
        {
            lock (LockTransaction)
            {
                string file = string.Format(AppDomain.CurrentDomain.BaseDirectory + "Log\\{0}\\{1}.log", DateTime.Now.ToString("yyyy-MM"), DateTime.Now.ToString("yyyy-MM-dd"));
                System.IO.StreamWriter sw = new System.IO.StreamWriter(file, true);
                sw.Write(DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"));
                sw.Write(" Begin  Transaction Thread Id:" + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                if (_sessionStore.LocalSession != null)
                {
                    sw.WriteLine();
                    StackTrace trace = new StackTrace(true);
                    for (int i = 0; i < trace.FrameCount; i++)
                    {
                        StackFrame frame = trace.GetFrame(i);
                        MethodBase method = frame.GetMethod();
                        if (method.DeclaringType != null)
                        {
                            sw.WriteLine(method.DeclaringType.FullName + " " + method.Name);
                        }
                        else
                        {
                            sw.WriteLine(method.Name);
                        }
                    }
                    sw.WriteLine(" SqlMap could not invoke BeginTransaction(). A Transaction is already started. Call CommitTransaction() or RollbackTransaction first");
                    //throw new DataMapperException("SqlMap could not invoke BeginTransaction(). A Transaction is already started. Call CommitTransaction() or RollbackTransaction first.");
                }
                ISqlMapSession session = CreateSqlMapSession();
                _sessionStore.Store(session);
                session.BeginTransaction();
                sw.WriteLine();
                sw.Close();
                return session;
            }
        }

BeginTransaction

public void CommitTransaction()
        {
            lock (LockTransaction)
            {
                string file = string.Format(AppDomain.CurrentDomain.BaseDirectory + "Log\\{0}\\{1}.log", DateTime.Now.ToString("yyyy-MM"), DateTime.Now.ToString("yyyy-MM-dd"));
                System.IO.StreamWriter sw = new System.IO.StreamWriter(file, true);
                sw.Write(DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"));
                sw.Write(" Commit Transaction Thread Id:" + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                if (_sessionStore.LocalSession == null)
                {
                    throw new DataMapperException("SqlMap could not invoke CommitTransaction(). No Transaction was started. Call BeginTransaction() first.");
                }
                try
                {
                    ISqlMapSession session = _sessionStore.LocalSession;
                    session.CommitTransaction();
                }
                finally
                {
                    _sessionStore.Dispose();
                }
                if (_sessionStore.LocalSession != null)
                {
                    sw.Write(" Commit Transaction Not Successfully " + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                }
                else
                {
                    sw.Write(" Commit Transaction " + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                }
                sw.WriteLine();
                sw.Close();
            }
        }

CommitTransaction

  public void RollBackTransaction()
        {
            lock (LockTransaction)
            {
                string file = string.Format(AppDomain.CurrentDomain.BaseDirectory + "Log\\{0}\\{1}.log", DateTime.Now.ToString("yyyy-MM"), DateTime.Now.ToString("yyyy-MM-dd"));
                System.IO.StreamWriter sw = new System.IO.StreamWriter(file, true);
                sw.Write(DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"));
                sw.Write(" Roll   Transaction Thread Id:" + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                if (_sessionStore.LocalSession == null)
                {
                    throw new DataMapperException("SqlMap could not invoke RollBackTransaction(). No Transaction was started. Call BeginTransaction() first.");
                }
                try
                {
                    ISqlMapSession session = _sessionStore.LocalSession;
                    session.RollBackTransaction();
                }
                finally
                {
                    _sessionStore.Dispose();
                }
                if (_sessionStore.LocalSession != null)
                {
                    sw.Write(" Roll Transaction Not Successfully " + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                }
                else
                {
                    sw.Write(" Roll Transaction " + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                }
                sw.WriteLine();
                sw.Close();
            }
        }

RollbackTransaction

結果出乎意料的是，事務一個BeginTransaction後面要麼跟一個Rollback Transaction，要麼跟一個Commit Transaction，這徹底是正確的啊，內心頓時真不是滋味，什麼破代碼居然沒問題。

不過，問題總歸是須要解決的，否則永遠都是止步不前。

回到最開始錯誤的地方，由於在BeginTransaction的時候，_sessionStore.LocalSession != null，拋出了那個錯誤，我就須要調查這個LocalSession。

由於LocalSession對應的對象SqlMapSession裏面沒有標識對象惟一性的建，我就在SqlMapSession裏面加了一個Id標識，用來肯定這個LocalSession到底有沒有被銷燬。

public SqlMapSession(ISqlMapper sqlMapper)
        {
            _dataSource = sqlMapper.DataSource;
            _sqlMapper = sqlMapper;
            lock (IBatisNet.DataMapper.SqlMapper.LockTransaction)
            {
                id = long.Parse(DateTime.Now.ToString("yyyyMMddHHmmssfff"));
            }
        }

IBatisNet在保存session的時候，在Winform程序裏面使用CallContextSessionStore這個類來獲取、保存、銷燬session。CallContextSessionStore類裏面用CallContext.GetData(name)獲取，CallContext.SetData(name, session)保存，CallContext.SetData(name, null)銷燬。CallContext這個類支持在同一個線程內，訪問的是同一個對象，也就是說，當前線程對對象進行儲存到線程本地儲存區，對象隨着線程的銷燬而銷燬。

一樣地，我把每一個方法的調用輸出在另一個日誌文件裏面，輸出在同一個文件會報文件拒絕訪問，多是因爲在Dispose的時候，我去調用GetSession所致。代碼以下：

public override ISqlMapSession LocalSession
        {
            get
            {
                lock (IBatisNet.DataMapper.SqlMapper.LockTransaction)
                {
                    var session = CallContext.GetData(sessionName) as SqlMapSession;
                    if (session != null)
                    {
                        string file = string.Format(AppDomain.CurrentDomain.BaseDirectory + "Log\\{0}\\{1}_1.log", DateTime.Now.ToString("yyyy-MM"), DateTime.Now.ToString("yyyy-MM-dd"));
                        System.IO.StreamWriter sw = new System.IO.StreamWriter(file, true);
                        sw.Write(DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"));
                        sw.Write(" LocalSession Thread Id:" + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                        sw.Write(" session Id:" + session.Id);
                        sw.WriteLine();
                        sw.Close();
                    }
                    return session;
                }
            }
        }

Get Session

public override void Store(ISqlMapSession session)
        {
            lock (IBatisNet.DataMapper.SqlMapper.LockTransaction)
            {
                string file = string.Format(AppDomain.CurrentDomain.BaseDirectory + "Log\\{0}\\{1}_1.log", DateTime.Now.ToString("yyyy-MM"), DateTime.Now.ToString("yyyy-MM-dd"));
                System.IO.StreamWriter sw = new System.IO.StreamWriter(file, true);
                sw.Write(DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"));
                sw.Write(" Store        Thread Id:" + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                sw.Write(" session Id:" + session.Id);
                sw.WriteLine();

                StackTrace trace = new StackTrace(true);
                for (int i = 0; i < trace.FrameCount; i++)
                {
                    StackFrame frame = trace.GetFrame(i);
                    MethodBase method = frame.GetMethod();
                    if (method.DeclaringType != null)
                    {
                        sw.WriteLine(method.DeclaringType.FullName + " " + method.Name);
                    }
                    else
                    {
                        sw.WriteLine(method.Name);
                    }
                }

                sw.Close();
                CallContext.SetData(sessionName, session);
            }
        }

Store Session

public override void Dispose()
        {
            lock (IBatisNet.DataMapper.SqlMapper.LockTransaction)
            {
                var session = CallContext.GetData(sessionName) as SqlMapSession;
                string file = string.Format(AppDomain.CurrentDomain.BaseDirectory + "Log\\{0}\\{1}_1.log", DateTime.Now.ToString("yyyy-MM"), DateTime.Now.ToString("yyyy-MM-dd"));
                System.IO.StreamWriter sw = new System.IO.StreamWriter(file, true);
                sw.Write(DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss"));
                sw.Write(" Dispose      Thread Id:" + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(2, '0'));
                sw.Write(" session Id:" + session.Id);
                sw.WriteLine();
                sw.Close();

                CallContext.SetData(sessionName, null);
            }
        }