記一次異常排查過程：druid鏈接池拋出DataSourceDisableException

先交待下項目背景，項目中有個功能是從mysql中獲取數據庫信息來建立數據庫鏈接，用的鏈接池是druid，jar包版本是1.0.9。

1. 異常的發生

最近項目中出現了一個神奇的異常：

讀取MySQL數據錯誤: jdbc:mysql://61.160.xxx.xxx:3306/xxx?characterEncoding=utf-8&autoReconnect=false&connectTimeout=15000&socketTimeout=60000, taskId=xxxxx, message: null

這個發生在數據庫操做時，神奇之處在於：

1. 異常偶爾會發生，同一時間的鏈接，有的會成功，而有的會報異常；
2. 異常信息爲null。

2. 異常拋出位置

拋出異常的代碼以下：

@Override
protected Result<Date> doImportData() {
   String url = getJdbcUrl();
   String host = getHost();
   int port = getPort();
   String username = getUsername();
   String password = getPassword();
   Connection con = null;

   DataSource dataSource = null;
   try {
      long t1 = System.currentTimeMillis();
      dataSource = DataSourceProvider.getDataSource(host, port, username, 
	  		password, url, MAX_POOL_SIZE, MIN_POOL_SIZE, INITIAL_POOL_SZIE);
      con = dataSource.getConnection();
      long getConnectionCostTime = System.currentTimeMillis() - t1;
      logger.info("taskId=" + task.getTaskId() + "，getConnection()=" + getConnectionCostTime + "ms");
      ···
   } catch (SQLException e) {
      logger.error("讀取MySQL數據錯誤: " + url + ", taskId=" + task.getTaskId() + ", message: " + e.getMessage());
      ···
   } finally {
      if (con != null) {
         try {
            con.close();
         } catch (SQLException e) {
            // ignore
         }
      }
   }
   return result;
}

3. 異常分析與推斷

3.1 從異常信息來看，能夠得出以下判斷：

1. 異常是由SQLException捕獲到的，所以代碼運行到了try代碼塊；
2. 異常的message是null，很容易聯想到拋出的是NullPointerException，但SQLException捕獲不到NPE，所以不會是NPE;
3. 從運行日誌排查，沒有運行到代碼 logger.info("taskId=" + task.getTaskId() + "，getConnection()=" + getConnectionCostTime + "ms");

3.2 從以上信息來排除，發現可疑問代碼只有三行了：

long t1 = System.currentTimeMillis();
dataSource = DataSourceProvider.getDataSource(host, port, username, 
		password, url, MAX_POOL_SIZE, MIN_POOL_SIZE, INITIAL_POOL_SZIE);
con = dataSource.getConnection();

3.3 再看看方法的具體實現，發現異常的拋出是在

con = dataSource.getConnection();
// 項目中用的是druid鏈接池
// com.alibaba.druid.pool.DruidDataSource
public DruidPooledConnection getConnection() throws SQLException

在方法裏往下找下去，沒找到什麼有用的信息，終於仍是放棄了...

4.峯迴跳轉-打印異常堆棧信息

項目中的異常還在報，好想僞裝異常沒發生...嗯，仍是繼續排查吧。

接下來，恰好碰上項目發佈，果斷修改了打印異常信息的方式，此次直接打出異常堆棧而不單單是message了：

logger.error("讀取MySQL數據錯誤: " + url + ", taskId=" + task.getTaskId() 
		+ ", message: " + ExceptionUtils.getStackTrace(e));

ExceptionUtils是apache commmons包提供的類，封裝了異常相關的操做方法。

等待着，等待着，異常信息終於來了：

[遊戲數據採集異常]讀取MySQL數據錯誤: jdbc:mysql://61.160.xxx.xxx:3306/xxx?characterEncoding=utf-8&autoReconnect=false&connectTimeout=15000&socketTimeout=60000, taskId=xxxxxx, message: com.alibaba.druid.pool.DataSourceDisableException
    at com.alibaba.druid.pool.DruidDataSource.pollLast(DruidDataSource.java:1482)
    at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1074)
    at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:941)
    at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:921)
    at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:911)
    at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:98)
	···

5.異常排查

從異常堆棧信息來看，報錯的異常是DataSourceDisableException，代碼是DruidDataSource.java的1482行。

5.1 DataSourceDisableException異常：

首先來認識下DataSourceDisableException異常：

public class DataSourceDisableException extends SQLException

這個類繼承了SQLException，因此代碼中能catch到。

5.2 異常相關代碼

再看看異常拋出的的位置：

if (!enable) {
	connectErrorCount.incrementAndGet();
	throw new DataSourceDisableException();
}

發現兩個問題：

1. if塊裏的代碼執行了，說明enable爲false了，只需找到致使enable爲false的地方就能夠查到異常緣由了；
2. 拋出異常時，沒有指定任何的異常信息，如new DataSourceDisableException('出現異常了')，這就致使了異常信息是null。

狀況已經很明顯了，接下來只要找到致使enable爲false的位置就好了。

經過搜索得知，enable初始化時爲true，對外暴露了setEnable(boolean)方法：

public void setEnable(boolean enable) {
	···
	this.enable = enable;
	···
}

同時在close()方法中明確地將enable設置成了false：

public void close() {
	···
	enable = false;
	···
}

5.3 得出結論

進一步排查，發現setEnable()方法沒有地方調用，而close()方法有地訪問在調用。對照代碼邏輯，得出的結論以下：

代碼裏有這樣一個操做：數據庫鏈接時，以host、port爲key，從緩存中獲取dataSource，若username、password與鏈接裏的不一致時，就會關閉獲取到的dataSource，並以新的username、password建立新的dataSource.可是，當同一個host、port有多個帳號跟密碼時，這種操做會有問題，緣由是多線程狀況下，關閉的dataSource能夠會被其餘線程獲取到。

5.4 問題的解決

知道了問題的所在，解決辦法就很簡單了：保證dataSource只能被一個線程獲取，這裏用的緩存數據結構是ConcurrentHashMap，獲取數據源時，用的是操做是get()方法，這裏只要將操做改爲remove()，而且使用完以後，再將dataSource用put()方法返還就能夠了。

6.反思

這個異常困擾了我兩天，緣由與解決方法並不複雜，難點在於異常信息。對於異常信息爲null的狀況，實在無人下午，只能對着代碼乾瞪眼。本次排查的起色出如今異常堆棧信息的打印，詳細的異常信息有助於問題的快速解決。

7.總結

寫了這麼多，總結以下：

1. 吐槽下ali大廠，異常信息居然不寫。
2. 實際開發中，異常信息應儘可能簡潔明瞭，不能啥都不寫，更不能故意製造混亂。只有異常發生了，才懂異常信息的難得。
3. 異常堆棧信息最好仍是要打出來的，否則項目一複雜、調用一多，短短的一句異常信息，可能看不出是在哪裏拋出來的，不利於排查。