上週在升級時候，客戶反饋某個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

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