关于使用druid数据源连接Oracle导致的SQLRecoverableException（socket read timeout,关闭的连接等）

背景

数据源初始化后,获取Oracle的连接进行查询操作,相隔 半个小时 左右,再次对同一数据库进行查询操作。

问题

第二次查询的时候,就会出现如下一些异常情况

2019-06-05 14:17:58.247 [CorePoolHandler-thread-6] ERROR [LOGID:] com.alibaba.druid.pool.DruidDataSource - discard connection
java.sql.SQLRecoverableException: IO 错误: Socket read timed out
	at oracle.jdbc.driver.T4CPreparedStatement.fetch(T4CPreparedStatement.java:1031) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at oracle.jdbc.driver.OracleStatement.fetchMoreRows(OracleStatement.java:3590) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at oracle.jdbc.driver.InsensitiveScrollableResultSet.fetchMoreRows(InsensitiveScrollableResultSet.java:937) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at oracle.jdbc.driver.InsensitiveScrollableResultSet.absoluteInternal(InsensitiveScrollableResultSet.java:901) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at oracle.jdbc.driver.InsensitiveScrollableResultSet.next(InsensitiveScrollableResultSet.java:572) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at com.alibaba.druid.filter.FilterChainImpl.resultSet_next(FilterChainImpl.java:917) ~[druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.filter.FilterAdapter.resultSet_next(FilterAdapter.java:1907) ~[druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.filter.FilterChainImpl.resultSet_next(FilterChainImpl.java:913) ~[druid-1.1.10.jar:1.1.10]
1
2
3
4
5
6
7
8
9
10

2019-06-05 14:22:32.714 [Druid-ConnectionPool-Destroy-1030806200] ERROR [LOGID:] com.alibaba.druid.util.JdbcUtils - close connection error
java.sql.SQLRecoverableException: IO 错误: Socket read timed out
	at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:770) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at oracle.jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:4581) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:186) ~[druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.filter.stat.StatFilter.connection_close(StatFilter.java:261) ~[druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:181) ~[druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl.close(ConnectionProxyImpl.java:115) ~[druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.util.JdbcUtils.close(JdbcUtils.java:73) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.pool.DruidDataSource.shrink(DruidDataSource.java:2797) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.pool.DruidDataSource$DestroyTask.run(DruidDataSource.java:2562) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.pool.DruidDataSource$DestroyConnectionThread.run(DruidDataSource.java:2549) [druid-1.1.10.jar:1.1.10]
1
2
3
4
5
6
7
8
9
10
11
12

2019-06-17 18:11:18.995 [task-scheduler-5] ERROR [LOGID:] com.alibaba.druid.util.JdbcUtils - close statement error
java.sql.SQLRecoverableException: 关闭的连接
	at oracle.jdbc.driver.PhysicalConnection.needLine(PhysicalConnection.java:6291) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at oracle.jdbc.driver.OracleStatement.closeOrCache(OracleStatement.java:1364) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at oracle.jdbc.driver.OracleStatement.close(OracleStatement.java:1343) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at oracle.jdbc.driver.OracleStatementWrapper.close(OracleStatementWrapper.java:100) ~[ojdbc6-12.1.0.1-atlassian-hosted.jar:12.1.0.1.0]
	at com.alibaba.druid.util.JdbcUtils.close(JdbcUtils.java:84) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.pool.vendor.OracleValidConnectionChecker.isValidConnection(OracleValidConnectionChecker.java:88) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.pool.DruidAbstractDataSource.testConnectionInternal(DruidAbstractDataSource.java:1400) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1299) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5007) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:680) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:5003) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1233) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1225) [druid-1.1.10.jar:1.1.10]
	at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:90) [druid-1.1.10.jar:1.1.10]
	at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111) [spring-jdbc-4.3.14.RELEASE.jar:4.3.14.RELEASE]
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17

排查原因过程

一开始以为是查询的数据量太大（7.9W+），于是网上查了druid对Oracle数据库的读超时时间相关的设置,配置如下,设置后发现仍旧是socket read timeout，继续增大socket read timeout的值，虽然“socket read timeout”没有出现了，但是“关闭的连接”字样冒了出来。

spring.datasource.traffic.connectionProperties=oracle.net.CONNECT_TIMEOUT=6000;oracle.jdbc.ReadTimeout=180000

1
2

查看出错日志，跟踪方法栈，发现是获取连接时执行了testConnectionInternal()方法，继续跟踪方法栈发现是执行数据源配置中的validationQuery语句时，抛出了异常。但这个是测试连接是否可用的方法，不会影响下一步对数据库的操作，因为druid数据源会创建新的一条数据库连接。
但是！打印异常的logger明明是debug，这XX为什么要以error的形式写进日志里！！！如果没有仔细看上下文的代码，能把人纠结个好几天!!!

    public static void close(Statement x) {
        if (x == null) {
            return;
        }
        try {
            x.close();
        } catch (Exception e) {
            LOG.debug("close statement error", e);
        }
    }
1
2
3
4
5
6
7
8
9
10

总结

查看出错日志检查问题的时候，不能只看抛出错误最近的那几行代码，一定要看过整体的方法栈，知道运行的流程，再仔细看抛出异常的代码，看看该行代码执行的前后逻辑。