先交待下项目背景,项目中有个功能是从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(),并且使用完之后,再将dataSourceput()方法返还就可以了。

6.反思

这个异常困扰了我两天,原因与解决方法并不复杂,难点在于异常信息。对于异常信息为null的情况,实在无人下午,只能对着代码干瞪眼。本次排查的转机出现在异常堆栈信息的打印,详细的异常信息有助于问题的快速解决。

7.总结

写了这么多,总结如下:

  1. 吐槽下ali大厂,异常信息竟然不写。
  2. 实际开发中,异常信息应尽量简洁明了,不能啥都不写,更不能故意制造混乱。只有异常发生了,才懂异常信息的可贵。
  3. 异常堆栈信息最好还是要打出来的,不然项目一复杂、调用一多,短短的一句异常信息,可能看不出是在哪里抛出来的,不利于排查。

转载于:https://my.oschina.net/funcy/blog/1933131

GitHub 加速计划 / druid / druid
3
3
下载
阿里云计算平台DataWorks(https://help.aliyun.com/document_detail/137663.html) 团队出品,为监控而生的数据库连接池
最近提交(Master分支:4 个月前 )
9faeba9f - 3 天前
5a1a5f0f - 3 天前
Logo

旨在为数千万中国开发者提供一个无缝且高效的云端环境,以支持学习、使用和贡献开源项目。

更多推荐