關於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

--

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

pid='22321'>

Immediate Kill Session#: 239, Serial#: 63057

--

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

pid='22321'>

Immediate Kill 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的操作是否可以做耕細粒度的設定，或者提供臨時解決方案來解決。
從目前的問題情況來說，客戶還是傾向於保持現有的設定.
所以說一個看似很普通的錯誤日誌，後面還是和資料庫的各個方面緊密相關，需要耐心地檢視日誌，不斷的排除和分析，最終找到發現問題，解決問題的鑰匙。