记一次网络波动导致druid连接池无法创建新连接的BUG
背景
项目使用了阿里druid jdbc连接池。某天环境出现网络波动，持续20分钟后，网络恢复，单服务一直无法连接数据库。重启之后正常运行
druid 版本：1.1.21
项目配置
spring.datasource.druid.game.driver-class-name = com.mysql.cj.jdbc.Driver
spring.datasource.druid.game.initial-size = 5
spring.datasource.druid.game.min-idle = 5
spring.datasource.druid.game.max-active = 100
spring.datasource.druid.game.max-wait = 30000
spring.datasource.druid.game.time-between-eviction-runs-millis = 60000
spring.datasource.druid.game.min-evictable-idle-time-millis = 300000
spring.datasource.druid.game.validationQuery = SELECT 'x'
spring.datasource.druid.game.test-while-idle = true
spring.datasource.druid.game.test-on-borrow = false
spring.datasource.druid.game.test-on-return = false
spring.datasource.druid.game.poolPreparedStatements = true
spring.datasource.druid.game.maxPoolPreparedStatementPerConnectionSize = 20
spring.datasource.druid.game.maxOpenPreparedStatements = 20
Druid的Bug现场
翻看当时日志，发现大量CannotGetJdbcConnectionException异常日志：
|
org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException:
### Error querying database. Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 100, creating 1, createElapseMillis 686180, createErrorCount 3
|
Caused by: org.apache.ibatis.exceptions.PersistenceException: ### Error querying database. Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 100, creating 1, createElapseMillis 686180, createErrorCount 3 ### The error may exist in class path resource [mapper/SysDictMapper.xml] ### The error may involve com.stnts.suileyoo.game.api.dao.SysDictDao.select ### The error occurred while executing a query ### Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 100, creating 1, createElapseMillis 686180, createErrorCount 3 at org.apache.ibatis.exceptions.ExceptionFactory.wrapException(ExceptionFactory.java:30) at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:149) at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:140) at org.apache.ibatis.session.defaults.DefaultSqlSession.selectOne(DefaultSqlSession.java:76) at sun.reflect.GeneratedMethodAccessor135.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:426) ... 95 common frames omitted Caused by: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 100, creating 1, createElapseMillis 686180, createErrorCount 3 at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:82) at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:80) at org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:67) at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:336) at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:86) at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:62) at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:324) at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156) at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109) at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:83) at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:147) ... 101 common frames omitted Caused by: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 100, creating 1, createElapseMillis 686180, createErrorCount 3 at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1722) at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1402) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1382) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1372) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:109) at org.springframework.jdbc.datasource.DataSourceUtils.fetchConnection(DataSourceUtils.java:158) at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:116) at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:79) ... 111 common frames omitted
Bug定位
系统是通过Druid连接
获取连接超时(GetConnectionTimeoutException)此错误的出现，只有两种可能:
1.业务系统本身Druid获取连接失败。
2.网络有问题或者数据库不可用。
在这个Bug里面很明显是Druid创建连接失败，原因如下:
1.之前网络的确有问题，单已恢复，另外还有另外一个服务也是访问这个数据库的。但是那个访问正常。
2.重启服务之后一切正常。
如果说还是网络连接异常，那么并不能解释重启后正常这一现象。
Druid获取连接的过程
在分析这个问题之前，先得看下Druid是如何创建连接的,下面是本人在上网查找到的，示意图:
（备注：来源 https://my.oschina.net/alchemystar/blog/899987）
可见druid创建连接都是通过一个专门的线程来进行的，此图省略了大量的源码细节。
然后对比DruidDataSource源码，验证了的确是上图所示的流程。
定位源码
根据日志“
Failed to obtain JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 0, maxActive 100, creating 1, createElapseMillis 686180, createErrorCount 3
”，发现日志打印位置，如下图：
holder == null 是关键。然后查找holder是如果被赋值的，经查找源码，发现其如下图：
因为已经配置过maxWait属性，故定位到pollLast方法中，再结合druid连接流程，找到CreateConnectionTask的runInternal方法。仔细阅读发现如下逻辑
经过比对日志输出，最终发现创建连接时，没有创建就直接返回了。真相了，原来是未设置keepAlive属性导致的。。。。。泪奔
起伏
已经定位到了问题，但是在查找资料的过程中，发现有人说在1.1.21版本中配置了keepAlive也是出现类似的情况
详见https://github.com/alibaba/druid/issues/3889
后查找druid发版日志，找到如下日志：
随将druid版本到1.1.24版本，但是发现日志中会频繁出现“discard long time none received connection”的错误日志。然后进一步查找相关问题，找到下面的一篇文章https://gitee.com/y_project/RuoYi-Vue/issues/I1XWZE?_from=gitee_search
此错误不影响链接数据库，去除需要设置System.setProperty("druid.mysql.usePingMethod", "false"); 因为采用的spring-boot,随将这行代码加入到Application的main方法中，经测试之后，已无此错误日志频繁出现的问题。
解决
最终，升级druid版本到1.1.24版本，另外在配置中增加了keepAlive属性，并在Application的main方法中加入System.setProperty("druid.mysql.usePingMethod", "false");
题外
不配置maxWait可能带了的BUG https://zhuanlan.zhihu.com/p/144446516
