一次寻找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

时间： 2024-10-01 04:18:46

一次寻找IBatisNet事务bug的过程的相关文章

spring internalTransactionAdvisor 事务 advisor 初始化过程

spring internalTransactionAdvisor 事务 advisor 初始化过程: 原文地址:https://www.cnblogs.com/xiluhua/p/10200629.html

找bug的过程

关于昨天程序出差我找bug的过程记录 昨天才程序 https://www.cnblogs.com/pythonywy/p/11006273.html ├── xxxx │ ├── src.py │ └── fil_mode.py │ └── data_time.py │ └── loading.py │ └── data_time.py │ └── logger.py src.py与打印日志相关片段 if __name__ == '__main__': logger_start('程序主界面')

STM32 .ld链接文件分析及一次bug解决过程

目录 STM32 .ld链接文件分析及一次bug解决过程 问题描述 解决办法 ld文件解析 后续 STM32 .ld链接文件分析及一次bug解决过程 问题描述 原子板的代码中含有一个关于使用外部SRAM的功能,由于本人的开发板的SRAM只有512K,因此稍微修改了一下代码,同时使用GCC进行编译,但是这里却报错了,源码如下: //内存池(4字节对齐) __align(4) u8 mem1base[MEM1_MAX_SIZE]; __align(4) u8 mem2base[MEM2_MAX_SI

记录一次bug解决过程：resultType和手动开启事务

一.总结 二.BUG描述:MyBatis中resultType使用 MyBatis中的resultType类似于入参:parameterType.先看IDCM项目中的实际使用案例代码,如下: // List<Integer> orderIds = assetBeanMapperExt.getOrderIdsByParentIds(SqlStringUtil.formatInStr(logisticsOrder.getParentIds())); 我们的目的是通过*Ext层直接返回一个list,

四十二、视图、触发器、事务、储存过程、函数、流程控制和索引等知识的应用

一.视图 1.什么是视图 视图就是通过查询得到一张虚拟表,然后保存下来,下次直接使用即可 2.为什么用视图 当反复用到两张表的连接操作时,可以将连成的表当做视图保存下来,下次直接使用 3.怎么用视图 create view teacher2course as select * from teacher inner join course on teacher.tid = course.teacher_id; 删除视图:drop view teacher2course 4.注意: 在硬盘中,视图只

记录一次bug解决过程：规范变量名称和mybatis的使用以及代码优化

一.总结 Mybatis中当parameterType为基本数据类型的时候,统一采用_parameter来代替基本数据类型变量. Mybatis中resultMap返回一个对象,resultType返回一个Map简单数据类型(由于需要缓存到JVM中)的映射关系. String类型转Integer类型:String类型转int类型用到的方法是不一样的. 方法入口处第一行写new Date(),防止时间在23:59:59跨界对逻辑带来影响. 考虑到上线app_resource表忘记配置供应商比例,在

记录一次bug解决过程：eclipse Installed JREs 配置引出的问题

一 总结 eclipse Installed JREs 配置引出的问题:编译以来JDK,不是JRE spring boot内嵌tomcat运行程序,tomcat:run 二 Bug描述:eclipse Installed JREs 配置引出的问题 刚新鲜检索出的代码,同学们编译都ok的,自己编译总是出错.原因在于eclipse Installed JREs 配置出错引出的问题.路径:windows->preferences->输入jre->Installed JRES->要依赖JD

Bug解决过程复盘

反思了下,解决问题无外乎3w1h when where who how 就是查询出来的事情多了,现在不知道哪个地方出问题,应该根据日志一步一步梳理,查看每一步的输出结果是否与预期一致 顺藤摸瓜 觉得不清楚的地方,可以新增打印,或通过其它方法获取这些不可知的信息. 已经确认没有问题的代码,不能出异常情况时,就开始漫无目的的怀疑,张驰有度... 严格的讲这个Bug还没有彻底解决,因为没有找到真正的原因 重启下服务就好了!!!!!!!!!!!!!!!! 主要想梳理下操作流程: 当时的反应: bug出现

记录一次bug解决过程：可维护性和性能优化

一.总结 使用某些变量的地方在2次以上的,强烈建议使用枚举值来维护变量,日后方便扩展. 查数据库的方法调用,能合并就净量去合并. 二.Bug描述 枚举变量的维护以及方法使用: public class UsedOnce { public static enum ruleDetailsEnum { SOURCEREGIN("原区域"), TARGETREGIN("目的区域"), SOURCECITY("原城市"), TARGETCITY("