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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

首先看實(shí)現(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)試過(guò)程中，一步步斷點(diǎn)，便會(huì)出現(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時(shí)會(huì)拋出異常。那么只要定位到修改closed變量值的方法不就知道了。通過(guò)idea工具的搜索只找到了一個(gè)修改該變量值的地方。

那就是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
    }
  }

于是將斷點(diǎn)添加到finally代碼塊中，看看什么時(shí)候會(huì)走到這個(gè)方法。

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

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

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

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

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

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

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

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

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

那為什么idea展示變量,調(diào)用toString()方法會(huì)導(dǎo)致此時(shí)查詢所使用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動(dòng)態(tài)代理中的一個(gè)攔截器實(shí)現(xiàn)類，因?yàn)橥ㄟ^(guò)jdk動(dòng)態(tài)代理，代理了Mybatis中的SqlSession接口,在idea中變量視圖展示時(shí)被調(diào)用了toString()方法,導(dǎo)致被攔截。

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

為了驗(yàn)證這個(gè)想法，在SqlSessionInterceptor中對(duì)攔截到的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)試，果然不會(huì)再出現(xiàn)Executor was closed.異常。

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

代碼如下:

@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中斷點(diǎn)執(zhí)行，經(jīng)過(guò)幾次debug，嘗試還原這個(gè)bug時(shí)，程序盡然一路暢通完美通過(guò),沒(méi)有任何異常。

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

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

而示例中重寫(xiě)的plugin方法，每次都對(duì)Executor重新賦值，實(shí)際上這是線程不安全的。

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

解決方案

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

為什么線上程序沒(méi)有報(bào)Executor was closed問(wèn)題???

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

總結(jié)

實(shí)際上還是MybatisExecutorInterceptor中將Executor做為成員變量，對(duì)Executor更改，出現(xiàn)線程不安全導(dǎo)致的異常。而idea中顯示變量值調(diào)用toString()方法只是讓異常發(fā)生的誘因。

以上為個(gè)人經(jīng)驗(yàn)，希望能給大家一個(gè)參考，也希望大家多多支持腳本之家。

最新評(píng)論