尋找鎖定資料庫使用者的真兇

前幾天，一位兄弟部門的同事，提過來一個問題，有一臺開發Oracle資料庫伺服器，修改了一個應用使用者的密碼，然後就發現這個賬戶隔幾分鐘就會被鎖，需要手工unlock解鎖才行，但沒過一會又被鎖了，問了一圈開發人員，基本都說使用這個賬戶的應用要麼停了，要麼跟著改了密碼。很是撓人。

從現象看，推測可能還是有未修改使用者密碼的應用仍在執行中，接下來就按照當時探究的過程覆盤。

1.首先看下這個環境。 
11.2.0.4版本：
SQL> select * from v$version where rownum=1;
BANNER
---------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

雙節點的RAC：
[oracle@db1 ~]$ cat /etc/hosts

# Do not remove the following line, or various programs
# that require network functionality will fail.
127.0.0.1       localhost
#Public
x.x.x.11   db1
x.x.x.12   db2
#Private
x.x.x.1   db1-priv
x.x.x.2   db2-priv
#Virtual
x.x.x.13   db1-vip
x.x.x.14   db2-vip
#SCAN
x.x.x.15   db-cluster


2.現象是使用者隔幾分鐘就會被鎖定，從使用者profile的角度確認是否設定了密碼嘗試錯誤次數的引數。

假設這使用者名稱是USER，首先查詢到其使用的profile是預設的DEFAULT
SQL> select username, profile from dba_users where username='USER';
USERNAME            PROFILE
------------------- --------------------------
USER                       DEFAULT

再查詢出DEFAULT這個profile的FAILED_LOGIN_ATTEMPTS引數值是10：
SQL> select resource_name, limit from dba_profiles where profile='DEFAULT';
RESOURCE_NAME                    LIMIT
-------------------------------- ------------------------
COMPOSITE_LIMIT                  UNLIMITED
SESSIONS_PER_USER                UNLIMITED
CPU_PER_SESSION                  UNLIMITED
CPU_PER_CALL                     UNLIMITED
LOGICAL_READS_PER_SESSION        UNLIMITED
LOGICAL_READS_PER_CALL           UNLIMITED
IDLE_TIME                        UNLIMITED
CONNECT_TIME                     UNLIMITED
PRIVATE_SGA                      UNLIMITED
FAILED_LOGIN_ATTEMPTS            10
PASSWORD_LIFE_TIME               180
PASSWORD_REUSE_TIME              UNLIMITED
PASSWORD_REUSE_MAX               UNLIMITED
PASSWORD_VERIFY_FUNCTION         NULL
PASSWORD_LOCK_TIME               1
PASSWORD_GRACE_TIME              7
16 rows selected.

首先，這就能解釋為什麼USER使用者unlock解鎖後，隔幾分鐘就又會被鎖，就是由這個引數決定的，至於Oracle如何統計登入失敗次數，可以參考eygle很久前寫過的一篇短文，介紹的很清楚： 

3.從以上現象來推斷，還是有未修改使用者密碼的應用在執行，接下來看看監聽的資訊：
[oracle@db1 ~]$ lsnrctl status

LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 25-MAR-2016 18:38:31

Copyright (c) 1991, 2013, Oracle.  All rights reserved.

Connecting to (ADDRESS=(PROTOCOL=tcp)(HOST=)(PORT=1521))
STATUS of the LISTENER
------------------------
Alias                     LISTENER
Version                   TNSLSNR for Linux: Version 11.2.0.4.0 - Production
Start Date                04-FEB-2015 10:05:52
Uptime                    415 days 8 hr. 32 min. 39 sec
Trace Level               off
Security                  ON: Local OS Authentication
SNMP                      OFF
Listener Parameter File   /oracle/app/11.2.0/grid/network/admin/listener.ora
Listener Log File         /oracle/app/grid/diag/tnslsnr/depdb1/listener/alert/log.xml
Listening Endpoints Summary...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=LISTENER)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=x.x.x.11)(PORT=1521)))
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=x.x.x.13)(PORT=1521)))
Services Summary...
Service "+ASM" has 1 instance(s).
  Instance "+ASM1", status READY, has 1 handler(s) for this service...
Service "DB" has 1 instance(s).
  Instance "DB1", status READY, has 1 handler(s) for this service...
Service "DBXDB" has 1 instance(s).
  Instance "DB1", status READY, has 1 handler(s) for this service...
The command completed successfully

我們得知監聽日誌位置： 

/oracle/app/grid/diag/tnslsnr/db1/listener/alert/log.xml

看到有一些令人興奮的記錄：

 10-MAR-2016 13:11:17 * (CONNECT_DATA=(SID=db2)(CID=(PROGRAM=)(HOST=__jdbc__)(USER=))) 
 * (ADDRESS=(PROTOCOL=tcp)(HOST=x.x.x.24)(PORT=43428)) * establish * db2 * 0
 
 

我們可以清楚的看到有一個x.x.x.24的IP，使用jdbc連線方式連線到這臺資料庫伺服器，準確的說是db2，即RAC的第二個節點。而且這個資訊是有時幾乎1秒鐘就會記錄一次。

說到這，有個細節，就是dbsnake提醒，由於這是一套RAC環境，因此監聽日誌不是一份，而是每一個節點都有，開始我碰巧看的是沒有x.x.x.24連線記錄節點的日誌，還懷疑自己之前的判斷，後來到另外一個節點就發現了這個IP。

這裡埠PORT是43428，會發現每次記錄的埠是變化的，即應用連線監聽listener經歷的兩次握手過程。

4.找到了這個IP，是不是就完事兒了？反饋給同事，廣播開發人員，但無人有印象在這臺機器上有部署過應用。。。

沒辦法，就自己來唄。

登入這臺x.x.x.24機器，root的home目錄下就有一個晃眼的dataSync.jar檔案。資料同步？ 
解壓這檔案，搜尋資料庫IP，幸運的發現com/xxx/xxx/xxx/datasync/config/jdbc.properties這個檔案，開啟看看，有一段正是連線這個RAC節點的配置：

jdbc.jdbcUrl=jdbc:oracle:thin:@x.x.x.14:1521:db2 

再看看，這個目錄下還有一個go的指令碼，內容是：

java -Xms1024m -Xmx1024m -XX:MaxPermSize=256m -jar dataSync.jar xx  10 & 

感覺越來越接近真相，從這推測，是後臺呼叫dataSync.jar，而且有一個引數10，有可能就是時間間隔。

再找一找，發現有log資料夾，裡面有日誌，開啟看：

2016-03-11 00:04:07,881 - ... While trying to acquire a needed new resource, we failed to succeed more than the maximum number of allowed acquisition attempts (30). Last acquisition attempt exception: 
java.sql.SQLException: ORA-28000: the account is locked

at oracle.jdbc.driver.DatabaseError.throwSqlException(DatabaseError.java:111) 

(1).這個日誌當前還在不停滾動。 
(2).日誌中已經明確寫出ORA-28000，提示當前使用者被鎖定了。

基於以上所有線索，百分百確認x.x.x.24的dataSync.jar應用就是因庫使用者密碼變更，其未改變，導致使用者頻繁被鎖的真兇！

5.接下來的工作，就是“找到部署這個應用的人，打一頓”(開玩笑:))。可能有幾種方法：

(1) 後臺kill這個程式，刪除go指令碼的可執行許可權，或移動位置。

(2) 修改dataSync配置中使用者錯誤的密碼。

6.在上面監聽日誌中，除了x.x.x.24的IP外，還有一條記錄：

這條記錄也是頻繁出現，他是做什麼用？dbsnake指點，“這個應該是OHASD定期（每隔1分鐘）去連一下本機的listener，目的可能是為了監控本機 listener的健康狀況—— Oracle11gR2 Grid Control Oracle High Availability Services OHASD Oracle Agent, (ora_agent) manages the TNS Listener(s) when the ‘ENABLE_GLOBAL_DYNAMIC_ENDPOINT_LISTENER = ON’ parameter is set in the listener.ora file for the Grid Control configuration. ”

7.lsnrctl status：

Trace Level   off
Security  ON: Local OS Authentication
SNMP  OFF
Listener Parameter File   /oracle/app/11.2.0/grid/network/admin/listener.ora
Listener Log File /oracle/app/grid/diag/tnslsnr/db1/listener/alert/log.xml 

這塊顯示的Listener Log File是預設開啟的更宏觀的連線資訊，使用log_status。

另外的Trace Level=off應該表示的是更細粒度的資訊，預設關閉，可以在sqlnet.ora配置：

TRACE_LEVEL_CLIENT=16
TRACE_FILE_CLIENT=CLIENT
TRACE_TIMESTAMP_CLIENT=OFF
trace_directory_client=/u01/app/oracle/11.2.0.4/dbhome_1/network/admin 

總結：

1.無論應用大小，都應該有比較完善的維護機制，至少有一個簡易文件，不至於移交工作之後，這個應用成為黑洞，造成不必要的麻煩。

2.Oracle中每個現象是都會有其相應的原因，正所謂因果聯絡，更不要輕易放過任何一個細節，比如之前要找兩個節點的監聽日誌，比如檢索dataSync中有沒有檔案制定了資料庫IP資訊。

3.Oracle很多知識點都是相互串聯的，監聽、監聽日誌、監聽trace日誌、profile等等，很多的小點匯聚為了一個龐大的系統，同樣，對於這麼個問題也是，需要抽絲撥繭般排查每個問題，研究每一個現象後，才能得出最後的結論，往往是更有說服力的。Oracle的魅力就在於此。