关于SQLRecoverableException问题的排查和分析(r4笔记第13天)

上周在升级时候，客户反馈某个job报了下面的错误，想让我们查看一下是不是数据库这边有什么问题。报错的内容如下。


Caused by: java.sql.SQLRecoverableException: No more data to read from socket
        at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1142)
        at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1099)
        at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:288)
        at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:191)
        at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:523)
        at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207)
        at oracle.jdbc.driver.T4CPreparedStatement.executeForDescribe(T4CPreparedStatement.java:863)
        at oracle.jdbc.driver.OracleStatement.executeMaybeDescribe(OracleStatement.java:1153)
        at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1275)
        at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3576)
        at oracle.jdbc.driver.OraclePreparedStatement.executeQuery(OraclePreparedStatement.java:3620)
        at oracle.jdbc.driver.OraclePreparedStatementWrapper.executeQuery(OraclePreparedStatementWrapper.java:1491)
        at amdocs.jf.dbutils.connection.impl.BatchPreparedStatementWrapper.executeQuery(BatchPreparedStatementWrapper.java:43)
        at amdocs.ac.db.views.AcGetNextFilesDBView.select(AcGetNextFilesDBView.java:970)
        at amdocs.ac.impl.file.AcFileOperationImpl.retrieveFileBuffer(AcFileOperationImpl.java:274)
        ... 9 more

一般这种类型的问题，错误从应用层抛出来是很难复现的。所以这种问题的排查也是比较棘手的。首先查看了metalink，看是否有一些特殊的设置引起。但是从目前查到的结果来看，大多是由于bug引起，和目前的这个问题还是不太一致。因为问题已经发生了好久，需要查看的地方就是tns的日志。日志还是最有说服力的。但是查了半天，奇怪的是日志竟然都找不到。 10g的版本中tns的日志是在$ORACLE_HOME/network/log下面这个库是SQL*Plus: Release 11.2.0.2.0 Production,没有找到日志还能理解。因为11g中启用了adr特性，日志应该是在$ORACLE_BASE/diag下面但是查找了半天，里面的日志只有去年11月份以前的，没有最近的日志。 > ls -lrt -rw-r----- 1 xxxx dba 433364 Oct 8 20:04 log_1106.xml.gz -rw-r----- 1 xxxxx dba 3321677 Oct 8 23:17 log.xml 没有日志这可是很郁闷的事情，更郁闷的是还找不到日志。静下心来查看，首先可以排除是人为操作，肯定是做了某些变更导致的。能够想到的就是sqlnet.ora，一查还确实是这个原因。

network/admin> cat sqlnet.ora
DIAG_SIGHANDLER_ENABLED=FALSE
DIAG_ADR_ENABLED=OFF
DIAG_DDE_ENABLED=OFF
bequeath_detach=yes
SQLNET.INBOUND_CONNECT_TIMEOUT=240

看到这个变更就豁然开朗了，这个变更是在去年升级数据库10g到11g之后做的变更。既然ADR中的tns日志禁用了，那么日志应该在哪呢。其实万变不离其宗，这个根本就是listener。我们可以通过lsnrctl查看listener的状态。

network/admin> lsnrctl status listener_cust01
LSNRCTL for Linux: Version 11.2.0.2.0 - Production on 12-JAN-2015 17:08:49
Copyright (c) 1991, 2010, Oracle.  All rights reserved.
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=xxxx)(PORT=1548)))
STATUS of the LISTENER
------------------------
Alias                     LISTENER_CUST01
Version                   TNSLSNR for Linux: Version 11.2.0.2.0 - Production
Start Date                15-DEC-2014 01:58:58
Uptime                    28 days 15 hr. 9 min. 50 sec
Trace Level               off
Security                  ON: Local OS Authentication
SNMP                      OFF
Listener Parameter File   /opt/app/oracle/xxxxx/product/11.2.0/network/admin/listener.ora
Listener Log File         /opt/app/oracle/xxxxx/product/11.2.0/log/diag/tnslsnr/xxxxx/listener_cust01/alert/log.xml

好了，日志的问题解决了。我们来查看一些明细的信息。结果在问题的时间点发现了一处错误日志。

<msg time='2015-01-07T02:00:13.352+07:00' org_id='oracle' comp_id='tnslsnr'
type='UNKNOWN' level='16' host_id='ccbdbpr3'
host_addr='127.0.0.1'>
<txt>TNS-12547: TNS:lost contact
TNS-12560: TNS:protocol adapter error
TNS-00517: Lost contact
Linux Error: 104: Connection reset by peer
</txt>
</msg>

有了这个日志，能够判断出了问题，但是还不能判断出来问题倒底是由什么原因导致的。其实tns的日志也是一个辅助，我们还可以参考更多的日志。这个时候需要推荐的就是11g的ADR特性。假设数据库实例是CUST01,那么路径就是

$ORACLE_BASE/diag/rdbms/cust01/CUST01/alert 底下也是log.xml的日志文件，这个和alert_CUST01.log的日志内容还是有些差别的。 log.xml中发现的内容如下：

<msg time='2015-01-07T02:00:02.186+07:00' org_id='oracle' comp_id='rdbms'
--
host_id='ccbdbpr3' host_addr='127.0.0.1' module='sqlplus@ccbdbpr3 (TNS V1-V3)'
pid='22321'>
<txt>Immediate Kill Session: sess: 0xa52fe0740  OS pid: 8314 
</txt>
</msg>
<msg time='2015-01-07T02:00:02.253+07:00' org_id='oracle' comp_id='rdbms'
--
host_id='ccbdbpr3' host_addr='127.0.0.1' module='sqlplus@ccbdbpr3 (TNS V1-V3)'
pid='22321'>
<txt>Immediate Kill Session#: 239, Serial#: 63057 
</txt>
</msg>
<msg time='2015-01-07T02:00:02.254+07:00' org_id='oracle' comp_id='rdbms'
--
host_id='ccbdbpr3' host_addr='127.0.0.1' module='sqlplus@ccbdbpr3 (TNS V1-V3)'
pid='22321'>
<txt>Immediate Kill Session: sess: 0xa512cff40  OS pid: 19222 
</txt>
</msg>

可以看到在指定的时间点在做kill session的操作，这个操作从应用的角度来说是没有权限做的。然后和开发做了确认，让他们帮忙提供其它时间点的错误信息。结果通过tns日志和alert日志查看，时间点都是完全吻合的。都在指定的时间点做了kill session的操作。这个时候问题就有些奇怪的了，倒底是什么原因导致的这种问题呢？一种可能是schedule job，这个是数据库层面的，一种可能是crontab，这个是操作系统级别的设置。简单排查了下，发现在crontab中的一处设置引起了我的注意。 #------------------------------------------------ # Kill inactive session that come from JDBC Thin Client:xxxxx@xxxx and logon time more than 24 Hours # 30-DEC-2014 最后和客户反馈这个情况，发现是由这个crontab做的kill session操作，所以最后这个问题就可以进一步分解。从开发的角度来说，这个job的session为什么能够超过24个小时，是否是由于连接没有正确释放导致的。从dba的角度来说，这个kill session的操作是否可以做耕细粒度的设置，或者提供临时解决方案来解决。从目前的问题情况来说，客户还是倾向于保持现有的设置. 所以说一个看似很普通的错误日志，后面还是和数据库的各个方面紧密相关，需要耐心地查看日志，不断的排除和分析，最终找到发现问题，解决问题的钥匙。