先交待下项目背景,项目中有个功能是从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
这个发生在数据库操作时,神奇之处在于:
- 异常偶尔会发生,同一时间的连接,有的会成功,而有的会报异常;
- 异常信息为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 从异常信息来看,可以得出如下判断:
- 异常是由SQLException捕获到的,因此代码运行到了try代码块;
- 异常的message是null,很容易联想到抛出的是NullPointerException,但SQLException捕获不到NPE,因此不会是NPE;
- 从运行日志排查,没有运行到代码
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();
}
发现两个问题:
- if块里的代码执行了,说明enable为false了,只需找到导致enable为false的地方就可以查到异常原因了;
- 抛出异常时,没有指定任何的异常信息,如
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.总结
写了这么多,总结如下:
- 吐槽下ali大厂,异常信息竟然不写。
- 实际开发中,异常信息应尽量简洁明了,不能啥都不写,更不能故意制造混乱。只有异常发生了,才懂异常信息的可贵。
- 异常堆栈信息最好还是要打出来的,不然项目一复杂、调用一多,短短的一句异常信息,可能看不出是在哪里抛出来的,不利于排查。
所有评论(0)