寻找锁定数据库用户的真凶
前几天，一位兄弟部门的同事，提过来一个问题，有一台开发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-cluster2.现象是用户隔几分钟就会被锁定，从用户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/db1/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
看到有一些令人兴奋的记录：
<msg time='2016-03-10T13:11:17.467+08:00' org_id='oracle' comp_id='tnslsnr'
type='UNKNOWN' level='16' host_id='db2'
host_addr='x.x.x.12'>
<txt>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
</txt>
</msg>我们可以清楚的看到有一个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外，还有一条记录：
<msg time='2016-03-10T13:11:17.467+08:00' org_id='oracle' comp_id='tnslsnr'
type='UNKNOWN' level='16' host_id='db2'
host_addr='x.x.x.12'>这条记录也是频繁出现，他是做什么用？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的魅力就在于此。
腾讯云开发者
