一次寻找IBatisNet事务bug的过程

本文的上下文环境

操作系统：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(); } } }

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);}}

Remove Session

找到上一个日志文件出错的时间，再和这个日志文件对照，顿时发现有一个session id只有Store，没有Dispose。并且通过CallStack知道是哪个方法在调用和使用这个session，简直欣喜若狂啊：）

Finally，问题找到了，是一个业务方法不经意地调用了一个获取Sql的方法，来获取当前执行的sql，但是这个方法的写法有问题，session只有open，没有close。

四、总结

一沙一世界，一叶一菩提

用心去看，去体悟，哪怕再小的事物都可以成为一个独立的空间，哪怕是一粒沙子都可以是一个世界，容纳万物。问题在那里啊？就在那一叶上。

转载于:https://www.cnblogs.com/lhking/p/9645791.html

一次寻找IBatisNet事务bug的过程相关推荐

java redis使用卡死_记一次找因 redis 使用不当导致应用卡死 bug 的过程
原标题:记一次找因 redis 使用不当导致应用卡死 bug 的过程作者:小木 my.oschina.net/xiaomu0082/blog/2990388 首先说下问题现象:内网sandbox环境 ...
Redis 事务机制实现过程及原理，以及使用事务机制防止库存超卖
一.Redis 事务实现的过程和原理第一步:观察数据客户端在修改数据之前,先使用watch命令观察要修改的数据,这一步相当于记下了数据的版本号第二步:开启事务使用 multi 命令开启事务. ...
Go运行时bug调试过程解析
原文:Debugging an evil Go runtime bug 作者:Hector Martin 翻译:雁惊寒摘要:本文讲述了作者通过对硬件.内核进行分析来调试程序bug的整个过程.以下是译 ...
mysql bug_MySQL 记一次 Bug发现过程
水平有限有误请谅解这个问题是一位朋友@DBA-老庄的,他们使用的是PXC环境如下: MySQL:5.7.18-15 wsrep:29.20 os:Red Hat Enterprise Linux S ...
IBatisNet 升级到 .Net Framework 4.0 时发现 IBatisNet 一小BUG
今天在将一网站用ASP.NET MVC4 重做的时候,原来的 IBatisNet 没支持到 .NET Framework 4.0 ,于是就花了点时间将其等级.升级工作一切顺利,但在最后做一动态查询测试 ...
td中bug处理过程_特斯拉的致命BUG，埃安LX的L3能解开吗？
关注并标星电动星球News 每天打卡阅读更深刻理解汽车产业变革 -------- 前两天,广汽新能源发布了一个视频,展示了埃安 LX 搭载 ADiGO3.0 自动驾驶系统之后,脱手情况下的能力. 其 ...
一次心脏滴血漏洞的bug处理过程
一个p2p平台,一次内部安全事件的处理过程,一个关乎投资人利益的网络投资平台,一个无知者无畏的年代.口口声声对外宣称安全.可靠.高收益.-- [步骤] 1.对应用https的系统进行ssl协议已公开漏 ...
BFS广度优先遍历寻找最短路径(超详细实现过程)
广度优先遍历寻找最短路径最近一直想搞A*算法,发现有部分没理解清楚.于是找到了广度优先遍历寻路算法学习了下,想看看可不可以对写A*有什么帮助.广度优先遍历寻路算法本身并不难,概括来说就是像雷达一样, ...
浅谈HTTP事务的一个过程
一个腾讯在职的朋友问道,当我们在浏览器的地址栏输入 www.baidu.com ,然后回车,这一瞬间页面发生了什么?下面以谷歌浏览器一一解释．一.域名解析首先Chrome浏览器会解析www.bai ...

一次寻找IBatisNet事务bug的过程

一次寻找IBatisNet事务bug的过程相关推荐

最新文章

热门文章