关于SQLRecoverableException问题的排查和分析

上周在升级的时候，客户反馈某个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

好了，日志的问题解决了。我们来查看一些明细的信息。    

结果在问题的时间点发现了一处错误日志。

type='UNKNOWN' level='16' host_id='ccbdbpr3'

host_addr='127.0.0.1'>

TNS-12547:

TNS:lost contact

TNS-12560: TNS:protocol

adapter error

  TNS-00517: Lost

contact

   Linux Error:

104: Connection reset by peer

有了这个日志，能够判断出了问题，但是还不能判断出来问题倒底是由什么原因导致的。

其实tns的日志也是一个辅助，我们还可以参考更多的日志。这个时候需要推荐的就是11g的ADR特性。

假设数据库实例是CUST01,那么路径就是

$ORACLE_BASE/diag/rdbms/cust01/CUST01/alert

底下也是log.xml的日志文件，这个和alert_CUST01.log的日志内容还是有些差别的。

log.xml中发现的内容如下：

--

host_id='ccbdbpr3' host_addr='127.0.0.1'

module='sqlplus@ccbdbpr3 (TNS V1-V3)'

pid='22321'>

Immediate Kill

Session: sess: 0xa52fe0740  OS pid: 8314

Session#: 239, Serial#: 63057

Session: sess: 0xa512cff40  OS pid: 19222

可以看到在指定的时间点在做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的操作是否可以做耕细粒度的设置，或者提供临时解决方案来解决。

从目前的问题情况来说，客户还是倾向于保持现有的设置.

所以说一个看似很普通的错误日志，后面还是和数据库的各个方面紧密相关，需要耐心地查看日志，不断的排除和分析，最终找到发现问题，解决问题的钥匙。