一次寻找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(, ''));
if (_sessionStore.LocalSession != null)
{
sw.WriteLine();
StackTrace trace = new StackTrace(true);
for (int i = ; 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(, ''));
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(, ''));
}
else
{
sw.Write(" Commit Transaction " + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(, ''));
}
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(, ''));
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(, ''));
}
else
{
sw.Write(" Roll Transaction " + System.Threading.Thread.CurrentThread.ManagedThreadId.ToString().PadLeft(, ''));
}
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(, ''));
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(, ''));
sw.Write(" session Id:" + session.Id);
sw.WriteLine(); StackTrace trace = new StackTrace(true);
for (int i = ; 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(, ''));
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。
四、总结
一沙一世界,一叶一菩提
用心去看,去体悟,哪怕再小的事物都可以成为一个独立的空间,哪怕是一粒沙子都可以是一个世界,容纳万物。问题在那里啊?就在那一叶上。
最新文章
- linux网站服务Apache+php+mysql的安装
- IIS网站发布若干问题
- jquery mobile 和phonegap开发总结之三跨域加载页面
- Java Script after Douglas Crockford&#39;s Training (JSON father)
- Node.js:JavaScript脚本运行环境
- SDUT 1305 查找基因序列问题 dp
- microsoft visual studio 不能逐句执行?
- Spring三 Bean的三种创建方式
- Rigidbody(刚体) and Collider(碰撞器)
- 从蓝光到4K,腾讯视频高码率下载背后的技术
- Shiro权限框架(二)
- Access数据类型和.NET数据类型映射
- 搭建日志收集系统时使用客户端连接etcd遇到的问题
- jQuery中删除方法empty(),remove()和detach()的区别
- VS2015 代码片段整理
- 配置Eclipse编写HTML/JS/CSS/JSP页面的自动提示
- TensorFlow学习路径【转】
- 20165310 Java实验四 《Android程序设计》
- (线段树)Just a Hook -- hdu -- 1689
- Alwayson--配置只读请求