快捷導(dǎo)航

Mybatis?Interceptor線程安全引發(fā)的bug問題

更新時間：2023年02月17日 10:34:53 作者：brucelwl

這篇文章主要介紹了Mybatis?Interceptor線程安全引發(fā)的bug問題及解決，具有很好的參考價值，希望對大家有所幫助。如有錯誤或未考慮完全的地方，望不吝賜教

Interceptor線程安全引發(fā)的bug

先看下發(fā)現(xiàn)這個bug的一個背景，但背景中的問題，并非這個bug導(dǎo)致：

最近業(yè)務(wù)部門的一位開發(fā)同事找過來說，自己在使用公司的框架向數(shù)據(jù)庫新增數(shù)據(jù)時，新增的數(shù)據(jù)被莫名其妙的回滾了，并且本地開發(fā)環(huán)境能夠復(fù)現(xiàn)這個問題。

公司的框架是基于SpringBoot+Mybatis整合實現(xiàn)，按道理這么多項目已經(jīng)在使用了，如果是bug那么早就應(yīng)該出現(xiàn)問題。

我的第一想法是不是他的業(yè)務(wù)邏輯有啥異常導(dǎo)致事務(wù)回滾了，但是也并沒有出現(xiàn)什么明顯的異常，并且新增的數(shù)據(jù)在數(shù)據(jù)庫中是可以看到的。

于是猜測有定時任務(wù)在刪數(shù)據(jù)。詢問了這位同事，得到的答案卻是否定的。

沒有辦法，既然能本地復(fù)現(xiàn)那便是最好解決了，決定在本地開發(fā)環(huán)境跟源碼找問題。

剛開始調(diào)試時只設(shè)置了幾個斷點，代碼執(zhí)行流程一切正常，查看數(shù)據(jù)庫中新增的數(shù)據(jù)也確實存在，但是當(dāng)代碼全部執(zhí)行完成后，數(shù)據(jù)庫中的數(shù)據(jù)卻不存在了，程序也沒有任何異常。

繼續(xù)深入斷點調(diào)試，經(jīng)過十幾輪的斷點調(diào)試發(fā)現(xiàn)偶爾會出現(xiàn)org.apache.ibatis.executor.ExecutorException: Executor was closed.，但是程序跳過一些斷點時，就一切正常。

在經(jīng)過n輪調(diào)試未果之后，還是懷疑數(shù)據(jù)庫有定時任務(wù)或者數(shù)據(jù)庫有問題。

于是重新創(chuàng)建一個測試庫新增數(shù)據(jù)，這次數(shù)據(jù)新增一切正常，此時還是滿心歡喜，至少已經(jīng)定位出問題的大致原因了，趕緊找了DBA幫忙查詢是否有SQL在刪數(shù)據(jù)，果然證實了自己的想法。

后來讓這位開發(fā)同事再次確認(rèn)是否在開發(fā)環(huán)境的機(jī)器上有定時任務(wù)有刪除數(shù)據(jù)的服務(wù)。

這次盡然告訴我確實有定時任務(wù)刪數(shù)據(jù)，問題得以解決，原來他是新接手這個項目，對項目不是很熟悉，真的。。。。。。

現(xiàn)在我們回到標(biāo)題重點沒有考慮Interceptor線程安全,導(dǎo)致斷點調(diào)試時才會出現(xiàn)的bug

晚上下班后，突然想到調(diào)試中遇到的org.apache.ibatis.executor.ExecutorException: Executor was closed.是啥情況？難道這地方還真的是有bug？

馬上雙十一到了，這要是在雙十一時整個大bug，那問題可大了。第二天上班后，決定要深入研究一下這個問題。由于不知道是什么情況下才能觸發(fā)這個異常，只能還是一步一步斷點調(diào)試。

首先看實現(xiàn)的Mybatis攔截器，主要代碼如下：

@Intercepts({
        @Signature(method = "query", type = Executor.class, args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
        @Signature(method = "query", type = Executor.class, args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
        @Signature(method = "update", type = Executor.class, args = {MappedStatement.class, Object.class})
})
public class MybatisExecutorInterceptor implements Interceptor {

    private static final String DB_URL = "DB_URL";

    private Executor target;

    private ConcurrentHashMap<Object, Object> cache = new ConcurrentHashMap<>();

    @Override
    public Object intercept(Invocation invocation) throws Throwable {
        Object proceed = invocation.proceed();
        //Executor executor = (Executor) invocation.getTarget();
        Transaction transaction = target.getTransaction();
        if (cache.get(DB_URL) != null) {
            //其他邏輯處理
            System.out.println(cache.get(DB_URL));
        } else if (transaction instanceof SpringManagedTransaction) {
            Field dataSourceField = SpringManagedTransaction.class.getDeclaredField("dataSource");
            ReflectionUtils.makeAccessible(dataSourceField);
            DataSource dataSource = (DataSource) ReflectionUtils.getField(dataSourceField, transaction);
            String dbUrl = dataSource.getConnection().getMetaData().getURL();
            cache.put(DB_URL, dbUrl);
            //其他邏輯處理
            System.out.println(cache.get(DB_URL));
        }
        //其他邏輯略...
        return proceed;
    }

    @Override
    public Object plugin(Object target) {
        if (target instanceof Executor) {
            this.target = (Executor) target;
            return Plugin.wrap(target, this);
        }
        return target;
    }
}

調(diào)試過程中，一步步斷點，便會出現(xiàn)如下異常：

Caused by: org.apache.ibatis.executor.ExecutorException: Executor was closed.
   at org.apache.ibatis.executor.BaseExecutor.getTransaction(BaseExecutor.java:78)
   at org.apache.ibatis.executor.CachingExecutor.getTransaction(CachingExecutor.java:51)
   at com.bruce.integration.mybatis.plugin.MybatisExecutorInterceptor.intercept(MybatisExecutorInterceptor.java:37)
   at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)

根據(jù)異常信息,將代碼定位到了org.apache.ibatis.executor.BaseExecutor.getTransaction() 方法

 @Override
  public Transaction getTransaction() {
    if (closed) {
      throw new ExecutorException("Executor was closed.");
    }
    return transaction;
  }

發(fā)現(xiàn)當(dāng)變量closed為true時會拋出異常。那么只要定位到修改closed變量值的方法不就知道了。通過idea工具的搜索只找到了一個修改該變量值的地方。

那就是org.apache.ibatis.executor.BaseExecutor#close()方法

@Override
  public void close(boolean forceRollback) {
    try {
      ....省略
    } catch (SQLException e) {
      // Ignore. There's nothing that can be done at this point.
      log.warn("Unexpected exception on closing transaction.  Cause: " + e);
    } finally {
      ....省略
      closed = true; //只有該處修改為true
    }
  }

于是將斷點添加到finally代碼塊中，看看什么時候會走到這個方法。

當(dāng)一步步debug時，發(fā)現(xiàn)還沒有走到close方法時，closed的值已經(jīng)被修改為true，又拋出了Executor was closed.異常。

奇怪了？難道還有其他代碼會反射修改這個變量，按道理Mybatis要是修改自己代碼中的變量值，不至于用這種方式啊，太不優(yōu)雅了，還增加代碼復(fù)雜度。

沒辦法，又是經(jīng)過n次一步步的斷點調(diào)試。

終于偶然的發(fā)現(xiàn)在idea debug窗口顯示出這樣的提示信息。

Skipped breakpoint at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor:423 because it happened inside debugger evaluation

從提示上看，不過是跳過了某個斷點而已，其實之前就已經(jīng)注意到這個提示，但是這次懷著好奇搜索了下解決方案。

原來idea在展示類的成員變量，或者方法參數(shù)時會調(diào)用對象的toString()，懷著試試看的心態(tài)，去掉了idea中的toString選項。

再次斷點調(diào)試，這次竟然不再出現(xiàn)異常，原來是idea顯示變量時調(diào)用對象的toString()方法搞得鬼？？？

難怪在BaseExecutor#close()方法中的斷點一直進(jìn)不去，卻修改了變量值。

那為什么idea展示變量,調(diào)用toString()方法會導(dǎo)致此時查詢所使用Executor被close呢?

根據(jù)上面的提示，查看org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor源碼，看看具體是什么邏輯

private class SqlSessionInterceptor implements InvocationHandler {
    @Override
    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
      SqlSession sqlSession = getSqlSession(SqlSessionTemplate.this.sqlSessionFactory,
          SqlSessionTemplate.this.executorType, SqlSessionTemplate.this.exceptionTranslator);
      try {
        Object result = method.invoke(sqlSession, args);
        if (!isSqlSessionTransactional(sqlSession, SqlSessionTemplate.this.sqlSessionFactory)) {
          // force commit even on non-dirty sessions because some databases require
          // a commit/rollback before calling close()
          sqlSession.commit(true);
        }
        return result;
      } catch (Throwable t) {
        Throwable unwrapped = unwrapThrowable(t);
        if (SqlSessionTemplate.this.exceptionTranslator != null && unwrapped instanceof PersistenceException) {
          // release the connection to avoid a deadlock if the translator is no loaded. See issue #22
          closeSqlSession(sqlSession, SqlSessionTemplate.this.sqlSessionFactory);
          sqlSession = null;
          Throwable translated = SqlSessionTemplate.this.exceptionTranslator
              .translateExceptionIfPossible((PersistenceException) unwrapped);
          if (translated != null) {
            unwrapped = translated;
          }
        }
        throw unwrapped;
      } finally {
        if (sqlSession != null) {
          closeSqlSession(sqlSession, SqlSessionTemplate.this.sqlSessionFactory);
        }
      }
    }
  }

從代碼上看，這是jdk動態(tài)代理中的一個攔截器實現(xiàn)類，因為通過jdk動態(tài)代理，代理了Mybatis中的SqlSession接口,在idea中變量視圖展示時被調(diào)用了toString()方法,導(dǎo)致被攔截。

而invoke()方法中最后一定會在finally中關(guān)閉當(dāng)前線程所關(guān)聯(lián)的sqlSession,導(dǎo)致調(diào)用BaseExecutor.close()方法。

為了驗證這個想法，在SqlSessionInterceptor中對攔截到的toString()方法做了如下處理，如果是toString()方法不再向下繼續(xù)執(zhí)行,只要返回是哪些接口的代碼類即可.

private class SqlSessionInterceptor implements InvocationHandler {
        @Override
        public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {

            if (args == null && "toString".equals(method.getName())) {
                return Arrays.toString(proxy.getClass().getInterfaces());
            }
           ... 其他代碼省略
        }
}

恢復(fù)idea中的設(shè)置，再次調(diào)試，果然不會再出現(xiàn)Executor was closed.異常。

這看似mybatis-spring在實現(xiàn)SqlSessionInterceptor 時考慮不周全導(dǎo)致的一個bug，為了不泄露公司的框架代碼還原這個bug，于是單獨搭建了SpringBoot+Mybatis整合工程，并且寫了一個類似邏輯的攔截器。

代碼如下:

@Intercepts({
        @Signature(method = "query", type = Executor.class, args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}),
        @Signature(method = "query", type = Executor.class, args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class, CacheKey.class, BoundSql.class}),
        @Signature(method = "update", type = Executor.class, args = {MappedStatement.class, Object.class})
})
public class MybatisExecutorInterceptor implements Interceptor {
    @Override
    public Object intercept(Invocation invocation) throws Throwable {

        Object proceed = invocation.proceed();
        Executor executor = (Executor) invocation.getTarget();
        Transaction transaction = executor.getTransaction();
        //其他邏輯略...
        return proceed;
    }

    @Override
    public Object plugin(Object target) {
        return Plugin.wrap(target, this);
    }
}

再次在SqlSessionInterceptor中斷點執(zhí)行，經(jīng)過幾次debug，嘗試還原這個bug時，程序盡然一路暢通完美通過,沒有任何異常。

此刻我立刻想起了之前觀察到的一段不合理代碼，在文章開頭的實例代碼中Executor被做為成員變量保存，但是mybatis中Interceptor實現(xiàn)類是在程序啟動時就被實例化的，并且是一個單實例對象。

而在每次執(zhí)行SQL時都會去創(chuàng)建一個新的Executor對象并且會經(jīng)過Interceptor的public Object plugin(Object target)，用于判斷是否需要對該Executor對象進(jìn)行代理。

而示例中重寫的plugin方法，每次都對Executor重新賦值，實際上這是線程不安全的。

由于在idea中debug時展示變量調(diào)用了toString()方法，同樣會創(chuàng)建SqlSession、Executor經(jīng)過plugin方法，導(dǎo)致Executor成員變量實際上是被替換的。

解決方案

直接通過invocation.getTarget()去獲取被代理對象即可，而不是使用成員變量。

為什么線上程序沒有報Executor was closed問題???

因為線上不會像在idea中一樣去調(diào)用toString() 方法
代碼中使用了緩存，當(dāng)使用了Executor 獲取到url后，下次請求過來就不會再使用Executor對象，也就不會出現(xiàn)異常。
程序剛啟動時并發(fā)量不夠大，如果在程序剛起來時，立刻有足夠的請求量，仍然會拋出異常，但是只要有一次結(jié)果被緩存，后續(xù)也就不會出現(xiàn)異常。