记一次异常排查过程：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. 异常堆栈信息最好还是要打出来的，不然项目一复杂、调用一多，短短的一句异常信息，可能看不出是在哪里抛出来的，不利于排查。