[20240911]简单探究Failed Logon Delay等待事件.txt
--//从19c开始如果用户登录密码不对,大量密集登录不会出现library cache lock.而出现Failed Logon Delay.会延迟一定的时间继续登录.
1.环境:
SCOTT@book01p> @ver2
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 21.0.0.0.0
BANNER : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
SYS@book> @ hide _sys_logon_delay
SYS@book> @pr
==============================
NAME : _sys_logon_delay
DESCRIPTION : The failed logon delay for the database instance
DEFAULT_VALUE : TRUE
SESSION_VALUE : 1
SYSTEM_VALUE : 1
ISSES_MODIFIABLE : FALSE
ISSYS_MODIFIABLE : FALSE
PL/SQL procedure successfully completed.
SYS@book> @ hidez *failed*
SYS@book> @pr
==============================
NAME : sec_max_failed_login_attempts
DESCRIPTION : maximum number of failed login attempts on a connection
DEFAULT_VALUE : TRUE
SESSION_VALUE : 3
SYSTEM_VALUE : 3
ISSES_MODIFIABLE : FALSE
ISSYS_MODIFIABLE : FALSE
PL/SQL procedure successfully completed.
--//可以简单测试验证看看：
2.测试：
SYS@book01p> select * from dba_users where username='TEST';
no rows selected
$ time sqlplus -s -l test/a@book01p <<<quit 2>&1 >/dev/null
real 0m1.102s
user 0m0.018s
sys 0m0.014s
--//用户test不存在,real执行时间是1秒，实际上已经直接延迟1秒连续尝试。
$ time sqlplus -s -l scott/book@book01p <<<quit 2>&1 >/dev/null
real 0m0.191s
user 0m0.144s
sys 0m0.012s
--//口令正确,很快登录.
$ time sqlplus -s -l scott/a@book01p <<<quit 2>&1 >/dev/null
real 0m1.091s
user 0m0.024s
sys 0m0.008s
--//如果尝试10次失败，用户lock。由定义的profile决定：
CREATE PROFILE "DEFAULT" LIMIT
SESSIONS_PER_USER UNLIMITED
CPU_PER_SESSION UNLIMITED
CPU_PER_CALL UNLIMITED
CONNECT_TIME UNLIMITED
IDLE_TIME UNLIMITED
LOGICAL_READS_PER_SESSION UNLIMITED
LOGICAL_READS_PER_CALL UNLIMITED
COMPOSITE_LIMIT UNLIMITED
PRIVATE_SGA UNLIMITED
FAILED_LOGIN_ATTEMPTS 10
PASSWORD_LIFE_TIME 180
PASSWORD_REUSE_TIME UNLIMITED
PASSWORD_REUSE_MAX UNLIMITED
PASSWORD_LOCK_TIME 1
PASSWORD_GRACE_TIME 7
PASSWORD_VERIFY_FUNCTION NULL;
$ time sqlplus -s -l scott/a@book01p <<<quit 2>&1 >/dev/null
real 0m0.115s
user 0m0.021s
sys 0m0.012s
--//read时间很小,实际上现在已经lock了.
$ time sqlplus -s -l scott/a@book01p <<<quit
ERROR:
ORA-28000: The account is locked.
SP2-0751: Unable to connect to Oracle. Exiting SQL*Plus
real 0m0.061s
user 0m0.021s
sys 0m0.011s
SYS@book01p> alter user scott account unlock ;
User altered.
3.使用strace跟踪探究看看:
$ strace -f -Ttt -y -o /tmp/aa1.txt sqlplus -s -l scott/a@book01p <<<quit
ERROR:
ORA-01017: invalid username/password; logon denied
SP2-0751: Unable to connect to Oracle. Exiting SQL*Plus
4462 09:24:50.189966 write(9<socket:[26313]>, "\0\0\0W\6\0\0\0\0\0\2T\3T\3\203-\6\1\1\1o\1\1\20\1\1\1\1\1\1\1"..., 87) = 87 <0.000019>
4462 09:24:50.191024 read(9<socket:[26313]>, "\0\0\0\32\6\0\0\0\0\0\2\200\0\0\0<<<\200\0\0\0\0\0\0#", 8208) = 26 <0.000013>
4462 09:24:50.191932 write(9<socket:[26313]>, "\0\0\0\364\6\0\0\0\0\0\3v\2\376\377\377\377\377\377\377\377\5\0\0\0\1\0\0\0\376\377\377"..., 244) = 244 <0.000021>
4462 09:24:50.191996 read(9<socket:[26313]>, "\0\0\2\22\6\0\0\0\0\0\10\6\0\f\0\0\0\fAUTH_SESSKEY@\0"..., 8208) = 530 <0.009104>
4462 09:24:50.206561 write(9<socket:[26313]>, "\0\0\7\n\6\0\0\0\0\0\3s\3\376\377\377\377\377\377\377\377\5\0\0\0\1\1\0\0\376\377\377"..., 1802) = 1802 <0.000024>
4462 09:24:50.206635 read(9<socket:[26313]>, "\0\0\0\v\f \0\0\1\0\1\0\0\0\v\f \0\0\1\0\2", 8208) = 22 <1.013301>
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
4462 09:24:51.219995 write(9<socket:[26313]>, "\0\0\0\v\f \0\0\1\0\2", 11) = 11 <0.000062>
4462 09:24:51.220120 read(9<socket:[26313]>, "\0\0\0\327\6\0\0\0\0\0\4\1\0\0\0\0\0\1\0\0\0\0\371\3\0\0\0\0\0\0\0\0"..., 8208) = 215 <0.000074>
4462 09:24:51.220293 lseek(4</u01/app/oracle/product/21.0.0/dbhome_1/sqlplus/mesg/sp2us.msb>, 5120, SEEK_SET) = 5120 <0.000007>
4462 09:24:51.220331 read(4</u01/app/oracle/product/21.0.0/dbhome_1/sqlplus/mesg/sp2us.msb>, "\r\0\351\0\0\0V\0\352\0\0\0\220\0\353\0\0\0\240\0\356\0\0\0\320\0\357\0\0\0\344\0"..., 512) = 512 <0.000007>
4462 09:24:51.220385 fstat(1</dev/pts/2>, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 2), ...}) = 0 <0.000007>
4462 09:24:51.220439 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0df95f1000 <0.000010>
4462 09:24:51.220476 write(1</dev/pts/2>, "ERROR:\n", 7) = 7 <0.000026>
4462 09:24:51.220549 write(1</dev/pts/2>, "ORA-01017: invalid username/pass"..., 51) = 51 <0.000011>
4462 09:24:51.220645 write(1</dev/pts/2>, "\n", 1) = 1 <0.000012>
4462 09:24:51.220697 write(1</dev/pts/2>, "\n", 1) = 1 <0.000008>
4462 09:24:51.220743 write(1</dev/pts/2>, "SP2-0751: ", 10) = 10 <0.000009>
$ egrep "open.* = 9|1\.013301|close\(9|26313" /tmp/aa1.txt
....
4462 09:24:50.149919 open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 9 <0.000009>
4462 09:24:50.150064 close(9</etc/hosts>) = 0 <0.000007>
4462 09:24:50.150443 fcntl(9<socket:[26313]>, F_SETFL, O_RDONLY|O_NONBLOCK) = 0 <0.000007>
4462 09:24:50.150749 poll([{fd=9<socket:[26313]>, events=POLLOUT}], 1, 60000) = 1 ([{fd=9, revents=POLLOUT}]) <0.000009>
4462 09:24:50.150878 fcntl(9<socket:[26313]>, F_GETFL) = 0x802 (flags O_RDWR|O_NONBLOCK) <0.000007>
4462 09:24:50.150912 fcntl(9<socket:[26313]>, F_SETFL, O_RDWR) = 0 <0.000006>
4462 09:24:50.151043 fcntl(9<socket:[26313]>, F_SETFD, FD_CLOEXEC) = 0 <0.000008>
4462 09:24:50.151269 write(9<socket:[26313]>, "\1\35\0\0\1\0\0\0\1>\1,\fA \0\377\377\177\10\0\0\1\0\0\323\0J\0\0\24\0"..., 285) = 285 <0.000034>
4462 09:24:50.151343 read(9<socket:[26313]>, "\0\10\0\0\v\0\0\0", 8208) = 8 <0.023121>
4462 09:24:50.174517 write(9<socket:[26313]>, "\1\35\0\0\1\0\0\0\1>\1,\fA \0\377\377\177\10\0\0\1\0\0\323\0J\0\0\24\0"..., 285) = 285 <0.000020>
4462 09:24:50.174584 read(9<socket:[26313]>, "\0-\0\0\2\0\0\0\1>\fA\0\0\0\0\1\0\0\0\0-AA\0\0\0\0\0\0\0\0"..., 8208) = 45 <0.000087>
4462 09:24:50.174800 write(9<socket:[26313]>, "\0\0\0\n\f \0\0\2\0", 10) = 10 <0.000015>
4462 09:24:50.174932 write(9<socket:[26313]>, "\0\0\0\237\6 \0\0\0\0\336\255\276\357\0\225\0\0\0\0\0\4\0\0\4\0\3\0\0\0\0\0"..., 159) = 159 <0.000080>
4462 09:24:50.175149 read(9<socket:[26313]>, "\0\0\0\177\6 \0\0\0\0\336\255\276\357\0u\0\0\0\0\0\4\0\0\4\0\3\0\0\0\0\0"..., 8208) = 127 <0.000380>
4462 09:24:50.189243 write(9<socket:[26313]>, "\0\0\0\"\6\0\0\0\0\0\1\6\5\0x86_64/Linux 2.4.x"..., 34) = 34 <0.000021>"
4462 09:24:50.189298 read(9<socket:[26313]>, "\0\0\0\340\6\0\0\0\0\0\1\6\0x86_64/Linux 2.4.xx"..., 8208) = 224 <0.000057>
4462 09:24:50.189966 write(9<socket:[26313]>, "\0\0\0W\6\0\0\0\0\0\2T\3T\3\203-\6\1\1\1o\1\1\20\1\1\1\1\1\1\1"..., 87) = 87 <0.000019>
4462 09:24:50.191024 read(9<socket:[26313]>, "\0\0\0\32\6\0\0\0\0\0\2\200\0\0\0<<<\200\0\0\0\0\0\0#", 8208) = 26 <0.000013>
4462 09:24:50.191932 write(9<socket:[26313]>, "\0\0\0\364\6\0\0\0\0\0\3v\2\376\377\377\377\377\377\377\377\5\0\0\0\1\0\0\0\376\377\377"..., 244) = 244 <0.000021>
4462 09:24:50.191996 read(9<socket:[26313]>, "\0\0\2\22\6\0\0\0\0\0\10\6\0\f\0\0\0\fAUTH_SESSKEY@\0"..., 8208) = 530 <0.009104>
4462 09:24:50.206561 write(9<socket:[26313]>, "\0\0\7\n\6\0\0\0\0\0\3s\3\376\377\377\377\377\377\377\377\5\0\0\0\1\1\0\0\376\377\377"..., 1802) = 1802 <0.000024>
4462 09:24:50.206635 read(9<socket:[26313]>, "\0\0\0\v\f \0\0\1\0\1\0\0\0\v\f \0\0\1\0\2", 8208) = 22 <1.013301>
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
4462 09:24:51.219995 write(9<socket:[26313]>, "\0\0\0\v\f \0\0\1\0\2", 11) = 11 <0.000062>
4462 09:24:51.220120 read(9<socket:[26313]>, "\0\0\0\327\6\0\0\0\0\0\4\1\0\0\0\0\0\1\0\0\0\0\371\3\0\0\0\0\0\0\0\0"..., 8208) = 215 <0.000074>
4462 09:24:51.220961 write(9<socket:[26313]>, "\0\0\0\n\6 \0\0\0@", 10) = 10 <0.000076>
4462 09:24:51.221082 close(9<socket:[26313]>) = 0 <0.000020>
--//最后的文件句柄9,使用fcntl打开的socket:[26313]
$ man -a fcntl
PROLOG
This manual page is part of the POSIX Programmer's Manual. The Linux implementation of this interface may differ
(consult the corresponding Linux manual page for details of Linux behavior), or the interface may not be
implemented on Linux.
NAME
fcntl - file control
SYNOPSIS
#include <unistd.h>
#include <fcntl.h>
int fcntl(int fildes, int cmd, ...);
--//不熟悉这部分内容,先暂时放弃.
4.继续：
CREATE PROFILE "NEWDEFAULT" LIMIT
SESSIONS_PER_USER UNLIMITED
CPU_PER_SESSION UNLIMITED
CPU_PER_CALL UNLIMITED
CONNECT_TIME UNLIMITED
IDLE_TIME UNLIMITED
LOGICAL_READS_PER_SESSION UNLIMITED
LOGICAL_READS_PER_CALL UNLIMITED
COMPOSITE_LIMIT UNLIMITED
PRIVATE_SGA UNLIMITED
FAILED_LOGIN_ATTEMPTS UNLIMITED
PASSWORD_LIFE_TIME UNLIMITED
PASSWORD_REUSE_TIME UNLIMITED
PASSWORD_REUSE_MAX UNLIMITED
PASSWORD_LOCK_TIME UNLIMITED
PASSWORD_GRACE_TIME UNLIMITED
PASSWORD_VERIFY_FUNCTION NULL;
ALTER USER SCOTT PROFILE NEWDEFAULT;
--//取消全部限制.
$ uniq -c ay.sql
21 connect scott/a@book01p
$ zzdate; seq 30 | xargs -IQ -P 10 sqlplus -s -l /nolog @ay.sql 2>&1 >/dev/null ; zzdate
--//开启新的会话
$ time rlsql -s -l scott/book@book01p <<< 'select sysdate from dual;'
SYSDATE
-------------------
2024-09-12 09:43:37
real 0m0.202s
user 0m0.151s
sys 0m0.016s
--//可以发现并不影响其他会话正常登录,只要口令正确.
$ zzdate; seq 30 | xargs -IQ -P 10 sqlplus -s -l /nolog @ay.sql 2>&1 >/dev/null ; zzdate
trunc(sysdate)+09/24+42/1440+49/86400 == 2024/09/12 09:42:49
trunc(sysdate)+09/24+43/1440+56/86400 == 2024/09/12 09:43:56
SYS@book> @ ashtop event,p1hex,p2hex,p3hex 1=1 trunc(sysdate)+09/24+42/1440+49/86400 trunc(sysdate)+09/24+43/1440+56/86400
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1HEX P2HEX P3HEX FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- --------------------------- ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
620 9.3 91% | Failed Logon Delay 0000000000000064 0000000000000000 0000000000000000 2024-09-12 09:42:50 2024-09-12 09:43:55 1 65 65
47 .7 7% | 2024-09-12 09:42:51 2024-09-12 09:43:54 1 37 37
4 .1 1% | latch free 00000000600F5E40 000000000000025E 0000000000000000 2024-09-12 09:43:46 2024-09-12 09:43:46 1 1 1
3 .0 0% | log file parallel write 0000000000000001 0000000000000003 0000000000000001 2024-09-12 09:43:18 2024-09-12 09:43:49 1 2 2
1 .0 0% | LGWR all worker groups 0000000000000000 0000000000000000 0000000000000000 2024-09-12 09:43:05 2024-09-12 09:43:05 1 1 1
1 .0 0% | LGWR worker group ordering 0000000000000050 0000000000000001 0000000000000000 2024-09-12 09:43:05 2024-09-12 09:43:05 1 1 1
1 .0 0% | log file sync 0000000000000A2B 0000000000493272 0000000000000000 2024-09-12 09:43:05 2024-09-12 09:43:05 1 1 1
1 .0 0% | log file sync 0000000000000A30 0000000000493275 0000000000000000 2024-09-12 09:43:05 2024-09-12 09:43:05 1 1 1
1 .0 0% | log file sync 0000000000000B98 00000000004933E3 0000000000000000 2024-09-12 09:43:18 2024-09-12 09:43:18 1 1 1
1 .0 0% | log file sync 0000000000000EDF 000000000049370F 0000000000000000 2024-09-12 09:43:49 2024-09-12 09:43:49 1 1 1
1 .0 0% | log file sync 0000000000000EE2 0000000000493712 0000000000000000 2024-09-12 09:43:49 2024-09-12 09:43:49 1 1 1
11 rows selected.
--//出现少量的log file sync,是因为要写审计表unified_AUDIT_trail.
SELECT count( return_code),return_code
FROM unified_AUDIT_trail
WHERE EVENT_TIMESTAMP >= trunc(sysdate)+09/24+42/1440+48/86400
-- AND UNIFIED_AUDIT_POLICIES = 'ORA_LOGON_FAILURES'
group by return_code;
COUNT(RETURN_CODE) RETURN_CODE
------------------ -----------
630 1017
--//P1hex=0x64 = 100,估计单位cs,表示1秒.
SYS@book01p> alter system set "_sys_logon_delay"=2 scope=spfile;
alter system set "_sys_logon_delay"=2 scope=spfile
*
ERROR at line 1:
ORA-65040: operation not allowed from within a pluggable database
SYS@book> alter system set "_sys_logon_delay"=2 scope=spfile;
System altered.
--//重启数据库重复测试：
$ zzdate; seq 10 | xargs -IQ -P 10 sqlplus -s -l /nolog @ay.sql 2>&1 >/dev/null ; zzdate
trunc(sysdate)+09/24+55/1440+02/86400 == 2024/09/12 09:55:02
trunc(sysdate)+09/24+55/1440+46/86400 == 2024/09/12 09:55:46
SYS@book> @ ashtop event,p1hex,p2hex,p3hex 1=1 trunc(sysdate)+09/24+55/1440+02/86400 sysdate
Total Distinct Distinct Distinct
Seconds AAS %This EVENT P1HEX P2HEX P3HEX FIRST_SEEN LAST_SEEN Execs Seen Tstamps Execs Seen1
--------- ------- ------- ------------------------------------------ ----------------- ----------------- ----------------- ------------------- ------------------- ---------- -------- -----------
170 9.4 97% | Failed Logon Delay 00000000000000C8 0000000000000000 0000000000000000 2024-09-12 09:55:03 2024-09-12 09:55:19 1 17 17
3 .2 2% | 2024-09-12 09:55:02 2024-09-12 09:55:08 1 2 2
2 .1 1% | latch free 00000000600F5E40 000000000000025E 0000000000000000 2024-09-12 09:55:08 2024-09-12 09:55:08 1 1 1
1 .1 1% | log file parallel write 0000000000000001 0000000000000002 0000000000000001 2024-09-12 09:55:02 2024-09-12 09:55:02 1 1 1
--//c8=200. 猜测正确。
SELECT count( return_code),return_code
FROM unified_AUDIT_trail
WHERE EVENT_TIMESTAMP >= trunc(sysdate)+09/24+42/1440+48/86400
-- AND UNIFIED_AUDIT_POLICIES = 'ORA_LOGON_FAILURES'
5 group by return_code;
COUNT(RETURN_CODE) RETURN_CODE
------------------ -----------
2 65040
840 1017
$ time sqlplus -s -l test/a@book01p <<<quit 2>&1 >/dev/null
real 0m2.090s
user 0m0.021s
sys 0m0.011s
3.简单总结：
--//oracle 这项改进不会影响正常用户的登录，对数据库性能影响不是很大，仅仅需要注意的是会导致的审计表的增长速度有点快，导
--//致日志少量增加,因为显示密集登录有延迟.
--//一般生产系统的常用用户PROFILE都是很宽松的,不会出现多次尝试多次失败lock用户的情况,如果登录有这样限制,我估计大部分dba
--//是取消这些限制.
--//收尾还原:
SYS@book> alter system reset "_sys_logon_delay" ;
System altered.
来自 “ ITPUB博客 ” ，链接：https://blog.itpub.net/267265/viewspace-3027613/ ，如需转载，请注明出处，否则将追究法律责任。
最新文章
- [20261008]验证Shared Memory Segments key以及Semaphore Arrays Key(11g).txt
- [20261008]gdb引入结构体是否可行.txt
- [20261008]bpftrace定义结构体例子.txt
- [20261007]关于oracle sskgph2函数.txt
- [20261007]oracle Semaphore Arrays Key值的冲突.txt
- [20261004]oracle sskgph2函数等价c以及python脚本.txt
- [20261004]bpftrace查看oracle函数调用堆栈问题.txt
- [20261002]验证sskgphpjw函数参与运算的字符串是否存在规律.txt
- [20261002]oracle Semaphore Arrays Key值的计算2.txt
- [20261001]oracle Semaphore Arrays Key值的计算.txt
