本文的上下文环境
操作系统：Win7 x64 Professional
开发工具：Visual Studio 2017 语言：C#
数据库ORM：IBatisNet 1.6.2
一、前言
这个项目的前端有Web端，公众号，微信小程序，后端是用WCF写的，部署成windows service。后端使用了IBatisNet这样的轻量级ORM框架，sql是写在xml里面的，每个模块都有一个xml文件。sql的返回值对应的实体类配置在同一个xml文件里，像这样。
二、问题出现
这个项目一直运行的很正常，直到有一天发布了某一个功能之后，问题就出现了，异常日志经常看到这样的文字“SqlMap could not invoke BeginTransaction(). A Transaction is already started. Call CommitTransaction() or RollbackTransaction first”，一看代码，这个异常是从SqlMapper.BeginTransaction方法里面抛出的，字面意思就是启动事务，不能正常启动，需要首先调用提交或回归事务。按着这个逻辑来说，应该是某一次事务忘记提交或回归了。但是这个错误在本地开发环境复现不了，线上环境时不时的出现。如果本地能够reproduce，应该会比较好解决一些。
三、查看bug起因
我们项目中事务用了PostSharp里面的AOP编程，只要在需要事务的方法上面加个attribute就能实现事务支持。代码如下：
[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(); ???????????} ???????} ???}这样就是很方便写代码，不用在每个操作数据库多表的地方都显式地调用事务。
一开始怀疑这个地方可能有问题，在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; ???????????} ???????}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(); ???????????} ???????} ?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(); ???????????} ???????}结果出乎意料的是，事务一个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; ???????????????} ???????????} ???????}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); ???????????} ???????}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); ???????????} ???????}找到上一个日志文件出错的时间，再和这个日志文件对照，顿时发现有一个session id只有Store，没有Dispose。并且通过CallStack知道是哪个方法在调用和使用这个session，简直欣喜若狂啊：）
Finally，问题找到了，是一个业务方法不经意地调用了一个获取Sql的方法，来获取当前执行的sql，但是这个方法的写法有问题，session只有open，没有close。
四、总结
一沙一世界，一叶一菩提
用心去看，去体悟，哪怕再小的事物都可以成为一个独立的空间，哪怕是一粒沙子都可以是一个世界，容纳万物。问题在那里啊？就在那一叶上。
一次寻找IBatisNet事务bug的过程
原文地址：https://www.cnblogs.com/lhking/p/9645791.html