寻找锁定数据库用户的真凶

前几天，一位兄弟部门的同事，提过来一个问题，有一台开发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很久前写过的一篇短文，介绍的很清楚： 

http://www.eygle.com/archives/2009/07/profile_failed_login_attempts.html

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的魅力就在于此。