Oracle监听日志报错< unknown connect data>且TNS-12537&& TNS-12560&&TNS-00507&&Linux Error: 115: Operation now in progress
Oracle监听日志报错< unknown connect data>且TNS-12537&& TNS-12560&&TNS-00507&&Linux Error: 115: Operation now in progress
每隔1分钟，监听日志出现：
<msg time='2021-07-19T16:40:17.538+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='DB-Server' host_addr='172.30.17.59'> <txt>19-JUL-2021 16:40:17 * <unknown connect data> * 12537 </txt> </msg> <msg time='2021-07-19T16:40:17.538+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='DB-Server' host_addr='172.30.17.59'> <txt>TNS-12537: TNS:connection closed TNS-12560: TNS:protocol adapter error TNS-00507: Connection closed Linux Error: 115: Operation now in progress </txt> </msg> 1min.... <msg time='2021-07-19T16:41:17.537+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='DB-Server' host_addr='172.30.17.59'> <txt>19-JUL-2021 16:41:17 * <unknown connect data> * 12537 </txt> </msg> <msg time='2021-07-19T16:41:17.537+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='DB-Server' host_addr='172.30.17.59'> <txt>TNS-12537: TNS:connection closed TNS-12560: TNS:protocol adapter error TNS-00507: Connection closed Linux Error: 115: Operation now in progress </txt> </msg> <msg time='2021-07-19T16:42:17.535+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='DB-Server' host_addr='172.30.17.59'> <txt>19-JUL-2021 16:42:17 * <unknown connect data> * 12537 </txt> </msg> <msg time='2021-07-19T16:42:17.536+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='DB-Server' host_addr='172.30.17.59'> <txt>TNS-12537: TNS:connection closed TNS-12560: TNS:protocol adapter error TNS-00507: Connection closed Linux Error: 115: Operation now in progress </txt> </msg>
按照Listener Log Intermittently Reports: < unknown connect data> and either * 12537 or * 12569 errors (文档 ID 1664901.1)，
这是因为第3方工具探测侦听器。tnslsnr 无法理解该请求，因为该连接不使用 TNS 标头。
这些错误不是由 Oracle 产品引起的，而很可能是由 第3方工具引起的。这可以很容易地重现，以提供对错误的进一步理解。
正在发生的事情是某些东西，例如第3方探测器，正在尝试连接到侦听器，但侦听器不理解此连接，因为它不是 sqlnet 连接。它知道这一点，因为 sqlnet 使用唯一的标头来标识自己。60 秒后，侦听器将放弃尝试识别此连接并报告 TNS-12525 错误。
但是，如果未知连接尝试在 60 秒之前终止，那么您会在侦听器日志中收到错误
实际上在Linux7上，使用ssh模拟故障的话不需要60s那么久，而是一下子就报错了。
以下模拟该报错：
11.2.0.4.0，Linux6上：
监听开启trc_level为16或者support级别：
LSNRCTL> set trc_level 16 Connecting to (ADDRESS=(PROTOCOL=tcp)(HOST=)(PORT=1521)) LISTENER parameter "trc_level" set to support The command completed successfully LSNRCTL> set trc_level support Connecting to (ADDRESS=(PROTOCOL=tcp)(HOST=)(PORT=1521)) LISTENER parameter "trc_level" set to support The command completed successfully
运行命令：ssh -p 1521 oracle@192.168.1.150
此时会等待60s，然后断开。
[root@dbtest soft]# ssh -p 1521 oracle@192.168.1.150 ssh_exchange_identification: Connection closed by remote host
查看监听日志：
<msg time='2021-07-19T17:32:58.569+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='dbtest' host_addr='192.168.1.150'> <txt>19-JUL-2021 17:32:58 * <unknown connect data> * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.1.150)(PORT=34811)) * establish * <unknown sid> * 12525 </txt> </msg> <msg time='2021-07-19T17:32:58.569+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='dbtest' host_addr='192.168.1.150'> <txt>TNS-12525: TNS:listener has not received client's request in time allowed TNS-12535: TNS:operation timed out TNS-12606: TNS: Application timeout occurred </txt> </msg>
这种情况下，监听日志可以看出是谁（IP，标红加粗部分）在操作引起的报错。
如果不等待60s而是使用ctrl+c，则监听日志为（成功模拟）：
<msg time='2021-07-19T17:33:31.672+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='dbtest' host_addr='192.168.1.150'> <txt>19-JUL-2021 17:33:31 * <unknown connect data> * 12537 </txt> </msg> <msg time='2021-07-19T17:33:31.672+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='dbtest' host_addr='192.168.1.150'> <txt>TNS-12537: TNS:connection closed TNS-12560: TNS:protocol adapter error TNS-00507: Connection closed </txt> </msg>
文档中提出，os报错信息不一定会有。而且这里看不出是谁在做操作。
这个时候的trace信息如下：
2021-07-19 14:58:43.016925 : nsevwait:1 newly-posted event(s) 2021-07-19 14:58:43.017039 : nsevfnt:cxd: 0x267ec90 stage 0: NT events set: CONNECTION REQUEST 2021-07-19 14:58:43.017064 : nsevfnt:cxd: 0x267ec90 stage 0: NS events set: INCOMING CALL 2021-07-19 14:58:43.017088 : nsevrec:event is 0x1, on 1 2021-07-19 14:58:43.017108 : nsevwait:1 posted event(s) 2021-07-19 14:58:43.017127 : nsevwait:exit (0) 2021-07-19 14:58:43.017182 : nsglhe:entry 2021-07-19 14:58:43.017206 : nsglhe:Event on cxd 0x267ec90. 2021-07-19 14:58:43.017230 : nsglhc:Allocating cxd 0x26a04a0 2021-07-19 14:58:43.017251 : nsanswer:entry 2021-07-19 14:58:43.017271 : nsopen:entry 2021-07-19 14:58:43.017291 : nsmal:entry 2021-07-19 14:58:43.017311 : nsmal:1576 bytes at 0x26aa640 2021-07-19 14:58:43.017329 : nsmal:normal exit 2021-07-19 14:58:43.017349 : nsopenmplx:entry 2021-07-19 14:58:43.017369 : nsmal:entry 2021-07-19 14:58:43.017389 : nsmal:2760 bytes at 0x26bbc20 2021-07-19 14:58:43.017408 : nsmal:normal exit 2021-07-19 14:58:43.017427 : nsiorini:entry 2021-07-19 14:58:43.017447 : nsbal:entry 2021-07-19 14:58:43.017466 : nsbgetfl:entry 2021-07-19 14:58:43.017486 : nsbgetfl:normal exit 2021-07-19 14:58:43.017506 : nsbal:normal exit 2021-07-19 14:58:43.017525 : nsiorini:exit (0) 2021-07-19 14:58:43.017544 : nscpxget:entry 2021-07-19 14:58:43.017562 : nscpxget:normal exit 2021-07-19 14:58:43.017581 : nsopenalloc_nsntx:nlhthput on mplx_ht_nsgbu:ctx=26aa640, nsntx=26bbc20 2021-07-19 14:58:43.017602 : nsopenmplx:normal exit 2021-07-19 14:58:43.017626 : nstoSetupTimeout:entry 2021-07-19 14:58:43.017654 : nstoSetupTimeout:ATO enabled for ctx=0x0x26aa640, val=60000(millisecs) 2021-07-19 14:58:43.017670 : nstoUpdateActive:entry 2021-07-19 14:58:43.017683 : nstoUpdateActive:Active timeout is 0 (see nstotyp) 2021-07-19 14:58:43.017699 : nsopen:opening transport... 2021-07-19 14:58:43.017715 : nttcon:entry 2021-07-19 14:58:43.017738 : nttcon:toc = 3 2021-07-19 14:58:43.017757 : nttcnp:entry 2021-07-19 14:58:43.017773 : nttcnp:getting sockname 2021-07-19 14:58:43.017810 : nttcnp:getting peername 2021-07-19 14:58:43.017872 : nttcnp:exit 2021-07-19 14:58:43.017913 : nttcnr:entry 2021-07-19 14:58:43.017951 : nttcnr:waiting to accept a connection. 2021-07-19 14:58:43.018003 : nttcnr:getting sockname 2021-07-19 14:58:43.018041 : snlinGetNameInfo:entry 2021-07-19 14:58:43.018084 : snlinGetNameInfo:exit 2021-07-19 14:58:43.018122 : nttcnr:connected on ipaddr 192.168.1.150 2021-07-19 14:58:43.018162 : nttcnr:exit 2021-07-19 14:58:43.018205 : nttcon:NT layer TCP/IP connection has been established. 2021-07-19 14:58:43.018247 : nttcon:set TCP_NODELAY on 13 2021-07-19 14:58:43.018285 : nttcon:exit 2021-07-19 14:58:43.018327 : nsopen:transport is open 2021-07-19 14:58:43.018367 : nstoPostNTConn:entry 2021-07-19 14:58:43.018408 : nstoArmEventATO:entry 2021-07-19 14:58:43.018448 : nstoArmEventATO:exit (0) 2021-07-19 14:58:43.018486 : nstoPostNTConn:exit (0) 2021-07-19 14:58:43.018526 : nsnainit:entry 2021-07-19 14:58:43.018574 : nsnainit:answer 2021-07-19 14:58:43.018640 : nsnadct:entry 2021-07-19 14:58:43.018677 : nsnadct:normal exit 2021-07-19 14:58:43.018714 : nsnasvnainfo:entry 2021-07-19 14:58:43.018747 : nsnasvnainfo:NA disabled for this connection 2021-07-19 14:58:43.018784 : nsnasvnainfo:normal exit 2021-07-19 14:58:43.018844 : nainit:entry 2021-07-19 14:58:43.018881 : nagblini:entry 2021-07-19 14:58:43.018931 : nau_gin:entry 2021-07-19 14:58:43.018974 : nau_gparams:entry 2021-07-19 14:58:43.019017 : nam_gbp:Reading parameter "sqlnet.authentication_required" from parameter file 2021-07-19 14:58:43.019058 : nam_gbp:Parameter not found 2021-07-19 14:58:43.019101 : nau_gparams:Using default value "FALSE" 2021-07-19 14:58:43.019146 : nau_gslf:entry 2021-07-19 14:58:43.019191 : nam_gic:entry 2021-07-19 14:58:43.019231 : nam_gic:Counting # of items in "sqlnet.authentication_services" parameter 2021-07-19 14:58:43.019271 : nam_gic:Parameter not found 2021-07-19 14:58:43.019310 : nam_gic:Found 0 items 2021-07-19 14:58:43.019350 : nam_gic:exit 2021-07-19 14:58:43.019388 : nau_gslf:Using default value "all available adapters" 2021-07-19 14:58:43.019435 : nauss_set_state:entry 2021-07-19 14:58:43.019478 : nauss_set_state:exit 2021-07-19 14:58:43.019522 : nau_gslf:exit 2021-07-19 14:58:43.019564 : nau_gparams:exit 2021-07-19 14:58:43.019604 : nau_gin:exit 2021-07-19 14:58:43.019643 : nagblini:exit 2021-07-19 14:58:43.019682 : na_saveprot:entry 2021-07-19 14:58:43.019725 : na_saveprot:exit 2021-07-19 14:58:43.019765 : nacomin:entry 2021-07-19 14:58:43.019805 : nas_init:entry 2021-07-19 14:58:43.019853 : nas_init:exit 2021-07-19 14:58:43.019893 : nau_ini:entry 2021-07-19 14:58:43.019933 : naugcp_get_connect_parameters:entry 2021-07-19 14:58:43.019971 : nauss_set_state:entry 2021-07-19 14:58:43.020009 : nauss_set_state:exit 2021-07-19 14:58:43.020047 : naugcp_get_connect_parameters:exit 2021-07-19 14:58:43.020086 : nau_gfauth:entry 2021-07-19 14:58:43.020125 : nam_gbp:Reading parameter "sqlnet.fallback_authentication" from parameter file 2021-07-19 14:58:43.020163 : nam_gbp:Parameter not found 2021-07-19 14:58:43.020202 : nau_gfauth:Using default value "FALSE" 2021-07-19 14:58:43.020240 : nau_gfauth:exit 2021-07-19 14:58:43.020278 : nau_gettab:entry 2021-07-19 14:58:43.020316 : nau_gettab:using authentication adapter table "nautab" 2021-07-19 14:58:43.020358 : nau_gettab:nautab contains the following services: 2021-07-19 14:58:43.020402 : nau_gettab: KERBEROS5 2021-07-19 14:58:43.020441 : nau_gettab: RADIUS 2021-07-19 14:58:43.020486 : nau_gettab:exit 2021-07-19 14:58:43.020527 : nau_sini:entry 2021-07-19 14:58:43.020565 : nau_sini:exit 2021-07-19 14:58:43.020603 : nau_ini:connection type: "standard" 2021-07-19 14:58:43.020646 : nau_ini:exit 2021-07-19 14:58:43.020699 : naeeinit:entry 2021-07-19 14:58:43.020750 : nam_gbp:Reading parameter "SQLNET.FIPS_140" from parameter file 2021-07-19 14:58:43.020795 : nam_gbp:Parameter not found 2021-07-19 14:58:43.020851 : nam_gnsp:Reading parameter "SQLNET.ENCRYPTION_SERVER" from parameter file 2021-07-19 14:58:43.020898 : nam_gnsp:Parameter not found 2021-07-19 14:58:43.020936 : naequad:Using default value "ACCEPTED" 2021-07-19 14:58:43.020994 : nam_gbp:Reading parameter "SQLNET._ENHANCED_LOGON_PROTECTION" from parameter file 2021-07-19 14:58:43.021041 : nam_gbp:Parameter not found 2021-07-19 14:58:43.021077 : nam_gic:entry 2021-07-19 14:58:43.021124 : nam_gic:Counting # of items in "SQLNET.ENCRYPTION_TYPES_SERVER" parameter 2021-07-19 14:58:43.021168 : nam_gic:Parameter not found 2021-07-19 14:58:43.021208 : nam_gic:exit 2021-07-19 14:58:43.021252 : naesno:Using default value "all available algorithms" 2021-07-19 14:58:43.021300 : naeshow:entry 2021-07-19 14:58:43.021345 : naeshow:These are the encryption algorithms that the server will accept, in decreasing order of preference: 2021-07-19 14:58:43.021389 : naeshow:Choice 0: no algorithm; encryption inactive 2021-07-19 14:58:43.021440 : naeshow:Choice 1: 'AES256' (ID 17) 2021-07-19 14:58:43.021467 : naeshow:Choice 2: 'RC4_256' (ID 6) 2021-07-19 14:58:43.021488 : naeshow:Choice 3: 'AES192' (ID 16) 2021-07-19 14:58:43.021502 : naeshow:Choice 4: '3DES168' (ID 12) 2021-07-19 14:58:43.021537 : naeshow:Choice 5: 'AES128' (ID 15) 2021-07-19 14:58:43.021564 : naeshow:Choice 6: 'RC4_128' (ID 10) 2021-07-19 14:58:43.021585 : naeshow:Choice 7: '3DES112' (ID 11) 2021-07-19 14:58:43.021606 : naeshow:Choice 8: 'RC4_56' (ID 8) 2021-07-19 14:58:43.021627 : naeshow:Choice 9: 'DES' (ID 2) 2021-07-19 14:58:43.021648 : naeshow:Choice 10: 'RC4_40' (ID 1) 2021-07-19 14:58:43.021668 : naeshow:Choice 11: 'DES40' (ID 3) 2021-07-19 14:58:43.021693 : naeshow:exit 2021-07-19 14:58:43.021709 : naeeinit:exit 2021-07-19 14:58:43.021722 : naecinit:entry 2021-07-19 14:58:43.021739 : nam_gnsp:Reading parameter "SQLNET.CRYPTO_CHECKSUM_SERVER" from parameter file 2021-07-19 14:58:43.021755 : nam_gnsp:Parameter not found 2021-07-19 14:58:43.021794 : naequad:Using default value "ACCEPTED" 2021-07-19 14:58:43.021834 : nam_gic:entry 2021-07-19 14:58:43.021868 : nam_gic:Counting # of items in "SQLNET.CRYPTO_CHECKSUM_TYPES_SERVER" parameter 2021-07-19 14:58:43.021903 : nam_gic:Parameter not found 2021-07-19 14:58:43.021934 : nam_gic:exit 2021-07-19 14:58:43.021956 : naesno:Using default value "all available algorithms" 2021-07-19 14:58:43.021977 : naeshow:entry 2021-07-19 14:58:43.021998 : naeshow:These are the checksumming algorithms that the server will accept, in decreasing order of preference: 2021-07-19 14:58:43.022019 : naeshow:Choice 0: no algorithm; checksumming inactive 2021-07-19 14:58:43.022049 : naeshow:Choice 1: 'SHA1' (ID 3) 2021-07-19 14:58:43.022074 : naeshow:Choice 2: 'MD5' (ID 1) 2021-07-19 14:58:43.022089 : naeshow:exit 2021-07-19 14:58:43.022101 : naecinit:exit 2021-07-19 14:58:43.022114 : nainit:native services disabled - disconnecting 2021-07-19 14:58:43.022127 : nadisc:entry 2021-07-19 14:58:43.022164 : nacomtm:entry 2021-07-19 14:58:43.022205 : nacompd:entry 2021-07-19 14:58:43.022229 : nacompd:exit 2021-07-19 14:58:43.022248 : nacompd:entry 2021-07-19 14:58:43.022268 : nacompd:exit 2021-07-19 14:58:43.022288 : nacomtm:exit 2021-07-19 14:58:43.022309 : nas_dis:entry 2021-07-19 14:58:43.022329 : nas_dis:exit 2021-07-19 14:58:43.022350 : nau_dis:entry 2021-07-19 14:58:43.022372 : nau_dis:exit 2021-07-19 14:58:43.022392 : naeetrm:entry 2021-07-19 14:58:43.022413 : naeetrm:exit 2021-07-19 14:58:43.022434 : naectrm:entry 2021-07-19 14:58:43.022454 : naectrm:exit 2021-07-19 14:58:43.022489 : nagbltrm:entry 2021-07-19 14:58:43.022512 : nau_gtm:entry 2021-07-19 14:58:43.022533 : nau_gtm:exit 2021-07-19 14:58:43.022553 : nagbltrm:exit 2021-07-19 14:58:43.022574 : nadisc:exit 2021-07-19 14:58:43.022594 : nainit:exit 2021-07-19 14:58:43.022616 : nsnainit:NS Connection version: 314 2021-07-19 14:58:43.022637 : nsnainit:inf->nsinfflg[0]: 0xd inf->nsinfflg[1]: 0xd 2021-07-19 14:58:43.022661 : nsnainit:"or" info flags: 0xd Translations follow: native service(s) is (are) wanted NA disabled remotely for this connection NA services unavailable on both processes - negotiation not needed 2021-07-19 14:58:43.022683 : nsnainit:"or" info flags: 0xd Translations follow: native service(s) is (are) wanted NA disabled remotely for this connection NA services unavailable on both processes - negotiation not needed "and" info flags: 0xd Translations follow: native service(s) is (are) wanted NA disabled remotely for this connection NA services unavailable on both processes - negotiation not needed 2021-07-19 14:58:43.022700 : nsnainit:normal exit 2021-07-19 14:58:43.022741 : nsopen:global context check-in (to slot 5) complete 2021-07-19 14:58:43.022762 : nsopen:lcl[0]=0xf4ffe9ff, lcl[1]=0x12003, gbl[0]=0x7ebf, gbl[1]=0x2001, tdu=65535, sdu=8192 2021-07-19 14:58:43.022781 : nsfull_opn:entry 2021-07-19 14:58:43.022808 : nsfull_opn:cid=5, opcode=65, *bl=0, *what=0, uflgs=0x0, cflgs=0x0 2021-07-19 14:58:43.022851 : nsfull_opn:nsctx: state=7, flg=0x4000, mvd=0 2021-07-19 14:58:43.022872 : nsbal:entry 2021-07-19 14:58:43.022895 : nsbgetfl:entry 2021-07-19 14:58:43.022915 : nsbgetfl:normal exit 2021-07-19 14:58:43.022930 : nsbal:normal exit 2021-07-19 14:58:43.022942 : nsbal:entry 2021-07-19 14:58:43.022954 : nsbgetfl:entry 2021-07-19 14:58:43.022966 : nsbgetfl:normal exit 2021-07-19 14:58:43.022978 : nsbal:normal exit 2021-07-19 14:58:43.022991 : nsfull_opn:normal exit 2021-07-19 14:58:43.023003 : nsopen:normal exit 2021-07-19 14:58:43.023017 : nsanswer:deferring connect attempt; at stage 5 2021-07-19 14:58:43.023030 : nsanswer:normal exit 2021-07-19 14:58:43.023044 : nsevreg:entry 2021-07-19 14:58:43.023057 : nsevreg:begin registration process for 5 2021-07-19 14:58:43.023070 : nsevregPrePost:entry 2021-07-19 14:58:43.023082 : nsevregPrePost:normal exit 2021-07-19 14:58:43.023095 : nsevreg:sgt=0, evn=1, evt[2]=0x0 2021-07-19 14:58:43.023108 : nsevreg:begin notification process for 5 2021-07-19 14:58:43.023121 : nsevregAffectNotif:entry 2021-07-19 14:58:43.023134 : nsevregAffectNotif:exit (0) 2021-07-19 14:58:43.023147 : nsevreg:rdm=0, sgt=0, evt[0]=0x20, [1]=0x20, [2]=0x0, nrg=0 2021-07-19 14:58:43.023160 : nsevreg:registering for 0x20 2021-07-19 14:58:43.023176 : nsevreg:normal exit 2021-07-19 14:58:43.023190 : nsglhe:exit 2021-07-19 14:58:43.023212 : nsevwait:entry 2021-07-19 14:58:43.023225 : nsevwait:4 registered connection(s) 2021-07-19 14:58:43.023242 : nsevwait:0 pre-posted event(s) 2021-07-19 14:58:43.023255 : nsevwait:waiting for transport event (1 thru 5)... 2021-07-19 14:59:43.083393 : nsevwait:0 newly-posted event(s) 2021-07-19 14:59:43.083547 : nstoToqWalk:entry 2021-07-19 14:59:43.083589 : nstoHandleEventTO:entry 2021-07-19 14:59:43.083649 : nserror:entry 2021-07-19 14:59:43.083692 : nserror:nsres: id=0, op=0, ns=12535, ns2=12606; nt[0]=0, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0 2021-07-19 14:59:43.083721 : nstoSetupTimeout:entry 2021-07-19 14:59:43.083750 : nstoSetupTimeout:ATO enabled for ctx=0x0x26aa640, val=60000(millisecs) 2021-07-19 14:59:43.083785 : nstoUpdateActive:entry 2021-07-19 14:59:43.083847 : nstoUpdateActive:Active timeout is 0 (see nstotyp) 2021-07-19 14:59:43.083887 : nstoHandleEventTO:ATO occurred for ctx=0x0x26aa640 2021-07-19 14:59:43.083934 : nstoToqWalk:exit (0) 2021-07-19 14:59:43.083971 : nsevwait:1 posted event(s) 2021-07-19 14:59:43.084007 : nsevwait:exit (0) 2021-07-19 14:59:43.084089 : nsglhe:entry 2021-07-19 14:59:43.084142 : nsglhe:Event on cxd 0x26a04a0. 2021-07-19 14:59:43.084176 : nsglhe:received connect timeout event 2021-07-19 14:59:43.084225 : nttaddr2bnd:entry 2021-07-19 14:59:43.084266 : snlinGetNameInfo:entry 2021-07-19 14:59:43.084299 : snlinGetNameInfo:exit 2021-07-19 14:59:43.084323 : nttaddr2bnd:Resolved to 192.168.1.150 2021-07-19 14:59:43.084364 : nttaddr2bnd:exit 2021-07-19 14:59:43.084395 : nsgldissolve:entry 2021-07-19 14:59:43.084436 : nsdisc:entry 2021-07-19 14:59:43.084462 : nsclose:entry 2021-07-19 14:59:43.084485 : nsvntx_dei:entry 2021-07-19 14:59:43.084507 : nsvntx_dei:exit 2021-07-19 14:59:43.084544 : nstimarmed:entry 2021-07-19 14:59:43.084568 : nstimarmed:no timer allocated 2021-07-19 14:59:43.084592 : nstimarmed:normal exit 2021-07-19 14:59:43.084616 : nstoClearTimeout:entry 2021-07-19 14:59:43.084642 : nstoClearTimeout:ATO disabled for ctx=0x0x26aa640 2021-07-19 14:59:43.084665 : nstoClearTimeout:STO disabled for ctx=0x0x26aa640 2021-07-19 14:59:43.084701 : nstoClearTimeout:RTO disabled for ctx=0x0x26aa640 2021-07-19 14:59:43.084728 : nstoClearTimeout:PITO disabled for ctx=0x0x26aa640 2021-07-19 14:59:43.084751 : nstoUpdateActive:entry 2021-07-19 14:59:43.084773 : nstoUpdateActive:Active timeout is -1 (see nstotyp) 2021-07-19 14:59:43.084809 : nttctl:entry 2021-07-19 14:59:43.084868 : nttctl:entry 2021-07-19 14:59:43.084896 : nsfull_cls:entry 2021-07-19 14:59:43.084933 : nsfull_cls:cid=5, opcode=65, *bl=0, *what=0, uflgs=0x0, cflgs=0x40 2021-07-19 14:59:43.084959 : nsfull_cls:nsctx: state=14, flg=0x20004000, mvd=0 2021-07-19 14:59:43.084993 : nsevunreg:entry 2021-07-19 14:59:43.085021 : nsevunreg:cid=5, sgt=0, rdm=0 2021-07-19 14:59:43.085088 : nsevunreg:3 registered connection(s) 2021-07-19 14:59:43.085130 : nsevunreg:exit (0) 2021-07-19 14:59:43.085155 : nsbfr:entry 2021-07-19 14:59:43.085189 : nsbaddfl:entry 2021-07-19 14:59:43.085214 : nsbaddfl:normal exit 2021-07-19 14:59:43.085249 : nsbfr:normal exit 2021-07-19 14:59:43.085272 : nsbfr:entry 2021-07-19 14:59:43.085305 : nsbaddfl:entry 2021-07-19 14:59:43.085329 : nsbaddfl:normal exit 2021-07-19 14:59:43.085353 : nsbfr:normal exit 2021-07-19 14:59:43.085394 : nsfull_cls:normal exit 2021-07-19 14:59:43.085430 : nsiocancel:entry 2021-07-19 14:59:43.085455 : nsiofrrg:entry 2021-07-19 14:59:43.085490 : nsiofrrg:cur = 26b4ad8 2021-07-19 14:59:43.085514 : nsbfr:entry 2021-07-19 14:59:43.085536 : nsbaddfl:entry 2021-07-19 14:59:43.085566 : nsbaddfl:normal exit 2021-07-19 14:59:43.085588 : nsbfr:normal exit 2021-07-19 14:59:43.085613 : nsiofrrg:exit 2021-07-19 14:59:43.085634 : nsiocancel:exit 2021-07-19 14:59:43.085670 : nsclose:closing transport 2021-07-19 14:59:43.085694 : nttdisc:entry 2021-07-19 14:59:43.085757 : nttdisc:Closed socket 13 2021-07-19 14:59:43.085788 : nttdisc:exit 2021-07-19 14:59:43.085841 : nsclose:global context check-out (from slot 5) complete 2021-07-19 14:59:43.085888 : nsnadisc:entry 2021-07-19 14:59:43.085923 : nsnadisc:no native services in use - returning 2021-07-19 14:59:43.085950 : nsvntx_dei:entry 2021-07-19 14:59:43.085971 : nsvntx_dei:exit 2021-07-19 14:59:43.085994 : nsopenfree_nsntx:nlhthdel from mplx_ht_nsgbu, ctx=26aa640 nsntx=26bbc20 2021-07-19 14:59:43.086014 : nsiocancel:entry 2021-07-19 14:59:43.086034 : nsiofrrg:entry 2021-07-19 14:59:43.086054 : nsiofrrg:exit 2021-07-19 14:59:43.086074 : nsiocancel:exit 2021-07-19 14:59:43.086096 : nsmfr:entry 2021-07-19 14:59:43.086118 : nsmfr:2760 bytes at 0x26bbc20 2021-07-19 14:59:43.086139 : nsmfr:normal exit 2021-07-19 14:59:43.086165 : nsmfr:entry 2021-07-19 14:59:43.086187 : nsmfr:1576 bytes at 0x26aa640 2021-07-19 14:59:43.086208 : nsmfr:normal exit 2021-07-19 14:59:43.086228 : nsclose:normal exit 2021-07-19 14:59:43.086248 : nsdisc:exit (0) 2021-07-19 14:59:43.086269 : nsgldissolve:Deallocating cxd 0x26a04a0. 2021-07-19 14:59:43.086314 : nsgldissolve:exit 2021-07-19 14:59:43.086767 : nsglhe:exit 2021-07-19 14:59:43.086802 : nsevwait:entry 2021-07-19 14:59:43.086847 : nsevwait:3 registered connection(s) 2021-07-19 14:59:43.086871 : nsevwait:0 pre-posted event(s) 2021-07-19 14:59:43.086893 : nsevwait:waiting for transport event (1 thru 4)...
根据MOS文档：
侦听器跟踪文件将显示未知连接来自的机器的源 IP。但是，我们只识别 IP 地址 - 而不是程序名称。
要在跟踪文件中查找 IP，请搜索“ns=12537”。找到命中后，向上（错误上方）搜索“Accepted Entry”。这是源 IP 地址。
但是在trace信息中，只能搜索到ns=12537信息，搜索不到Accepted Entry，因此无法得到操作源IP。
做了几次均为如此。
于是换成19c做尝试。
19.11.0.0.0，Linux7上：
同样的操作步骤，trace信息如下：
2021-07-19 15:19:38.878 : nsevwait:0 newly-posted event(s) 2021-07-19 15:19:38.878 : nsgetaddr:entry 2021-07-19 15:19:38.878 : nttaddr2bnd:entry 2021-07-19 15:19:38.878 : snlinGetNameInfo:entry 2021-07-19 15:19:38.878 : snlinGetNameInfo:exit 2021-07-19 15:19:38.878 : nttaddr2bnd:Resolved to 192.168.1.227 2021-07-19 15:19:38.878 : nttaddr2bnd:exit 2021-07-19 15:19:38.878 : nsevfnt:cxd: 0x7e5f80 cid=6 stage 0: NT events set: CONNECTION REQUEST 2021-07-19 15:19:38.878 : nsgetaddr:entry 2021-07-19 15:19:38.878 : nttaddr2bnd:entry 2021-07-19 15:19:38.878 : snlinGetNameInfo:entry 2021-07-19 15:19:38.879 : snlinGetNameInfo:exit 2021-07-19 15:19:38.879 : nttaddr2bnd:Resolved to 192.168.1.227 2021-07-19 15:19:38.879 : nttaddr2bnd:exit 2021-07-19 15:19:38.879 : nsevfnt:cxd: 0x7e5f80 cid=6 stage 0: NS events set: INCOMING CALL 2021-07-19 15:19:38.879 : nsevrec:event is 0x1, on 6 2021-07-19 15:19:38.879 : nsevwait:1 pre-posted event(s) 2021-07-19 15:19:38.879 : nsevrec:event is 0x1, on 6 2021-07-19 15:19:38.879 : nsevwait:1 posted event(s) 2021-07-19 15:19:38.879 : nsevwait:exit (0) 2021-07-19 15:19:38.879 : nsglhe:entry 2021-07-19 15:19:38.879 : nsglhe:Event on cxd 0x7e5f80. 2021-07-19 15:19:38.879 : nsglhc:Allocating cxd 0x84d110 2021-07-19 15:19:38.879 : nsanswer:entry 2021-07-19 15:19:38.879 : nsopen:entry 2021-07-19 15:19:38.879 : nsmal:entry 2021-07-19 15:19:38.879 : nsmal:1952 bytes at 0x8a82e0 2021-07-19 15:19:38.879 : nsmal:normal exit 2021-07-19 15:19:38.879 : nsopenmplx:entry 2021-07-19 15:19:38.879 : nsmal:entry 2021-07-19 15:19:38.879 : nsmal:3368 bytes at 0x8a8a90 2021-07-19 15:19:38.879 : nsmal:normal exit 2021-07-19 15:19:38.879 : nsiorini:entry 2021-07-19 15:19:38.879 : nsbal:entry 2021-07-19 15:19:38.879 : nsbgetfl:entry 2021-07-19 15:19:38.879 : nsbgetfl:normal exit 2021-07-19 15:19:38.879 : nsbal:normal exit 2021-07-19 15:19:38.879 : nsiorini:exit (0) 2021-07-19 15:19:38.880 : nscpxget:entry 2021-07-19 15:19:38.880 : nscpxget:normal exit 2021-07-19 15:19:38.880 : nsopenmplx:normal exit 2021-07-19 15:19:38.880 : nstoSetupTimeout:entry 2021-07-19 15:19:38.880 : nstoSetupTimeout:ATO enabled for ctx=0x0x8a82e0, val=60000(millisecs) 2021-07-19 15:19:38.880 : nstoUpdateActive:entry 2021-07-19 15:19:38.880 : nstoUpdateActive:Active timeout is 0 (see nstotyp) 2021-07-19 15:19:38.880 : nsopen:opening transport... 2021-07-19 15:19:38.880 : nttcon:entry 2021-07-19 15:19:38.880 : nttcon:toc = 3 2021-07-19 15:19:38.880 : nttcnp:entry 2021-07-19 15:19:38.880 : nttcnp:getting sockname 2021-07-19 15:19:38.880 : nttcnp:getting peername 2021-07-19 15:19:38.880 : nttcnp:exit 2021-07-19 15:19:38.880 : nttcnr:entry 2021-07-19 15:19:38.880 : nttcnr:waiting to accept a connection. 2021-07-19 15:19:38.880 : nttcnr:getting sockname 2021-07-19 15:19:38.880 : snlinGetNameInfo:entry 2021-07-19 15:19:38.880 : snlinGetNameInfo:exit 2021-07-19 15:19:38.880 : nttcnr:connected on source ipaddr 192.168.1.227 port 1521 2021-07-19 15:19:38.880 : snlinGetNameInfo:entry 2021-07-19 15:19:38.880 : snlinGetNameInfo:exit 2021-07-19 15:19:38.880 : nttcnr:connected on destination ipaddr 192.168.1.227 port 53468 2021-07-19 15:19:38.880 : nttvlser:entry 2021-07-19 15:19:38.880 : nlvlsern:entry 2021-07-19 15:19:38.880 : snlinGetNameInfo:entry 2021-07-19 15:19:38.880 : snlinGetNameInfo:exit 2021-07-19 15:19:38.881 : nttvlser:valid node check on incoming node 192.168.1.227 2021-07-19 15:19:38.881 : nttvlser:Accepted Entry: 192.168.1.227 2021-07-19 15:19:38.881 : nttcnr:exit 2021-07-19 15:19:38.881 : nttctl:entry 2021-07-19 15:19:38.881 : nttctl:Setting connection into nodelay mode 2021-07-19 15:19:38.881 : nttctl:set TCP_NODELAY on 20 2021-07-19 15:19:38.881 : nttcon:exit 2021-07-19 15:19:38.881 : nsopen:transport is open 2021-07-19 15:19:38.881 : nstoPostNTConn:entry 2021-07-19 15:19:38.881 : nstoArmEventATO:entry 2021-07-19 15:19:38.881 : nstoArmEventATO:exit (0) 2021-07-19 15:19:38.881 : nstoPostNTConn:exit (0) 2021-07-19 15:19:38.881 : nsnainit:entry 2021-07-19 15:19:38.881 : nsnainit:answer 2021-07-19 15:19:38.881 : nsnadct:entry 2021-07-19 15:19:38.881 : nsnadct:normal exit 2021-07-19 15:19:38.881 : nsnasvnainfo:entry 2021-07-19 15:19:38.881 : nsnasvnainfo:NA disabled for this connection 2021-07-19 15:19:38.881 : nsnasvnainfo:normal exit 2021-07-19 15:19:38.881 : nainit:entry 2021-07-19 15:19:38.881 : nagblini:entry 2021-07-19 15:19:38.881 : nau_gin:entry 2021-07-19 15:19:38.881 : nau_gparams:entry 2021-07-19 15:19:38.881 : nam_gbp:Reading parameter "sqlnet.authentication_required" from parameter file 2021-07-19 15:19:38.881 : nam_gbp:Parameter not found 2021-07-19 15:19:38.881 : nau_gparams:Using default value "FALSE" 2021-07-19 15:19:38.881 : nau_gslf:entry 2021-07-19 15:19:38.881 : nam_gic:entry 2021-07-19 15:19:38.881 : nam_gic:Counting # of items in "sqlnet.authentication_services" parameter 2021-07-19 15:19:38.881 : nam_gic:Parameter not found 2021-07-19 15:19:38.881 : nam_gic:Found 0 items 2021-07-19 15:19:38.881 : nam_gic:exit 2021-07-19 15:19:38.882 : nau_gslf:Using default value "all available adapters" 2021-07-19 15:19:38.882 : nauss_set_state:entry 2021-07-19 15:19:38.882 : nauss_set_state:exit 2021-07-19 15:19:38.882 : nau_gslf:exit 2021-07-19 15:19:38.882 : nau_gparams:exit 2021-07-19 15:19:38.882 : nau_gin:exit 2021-07-19 15:19:38.882 : nagblini:exit 2021-07-19 15:19:38.882 : na_saveprot:entry 2021-07-19 15:19:38.882 : na_saveprot:exit 2021-07-19 15:19:38.882 : nacomin:entry 2021-07-19 15:19:38.882 : nas_init:entry 2021-07-19 15:19:38.882 : nas_init:exit 2021-07-19 15:19:38.882 : nau_ini:entry 2021-07-19 15:19:38.882 : naugcp_get_connect_parameters:entry 2021-07-19 15:19:38.882 : nauss_set_state:entry 2021-07-19 15:19:38.882 : nauss_set_state:exit 2021-07-19 15:19:38.882 : naugcp_get_connect_parameters:exit 2021-07-19 15:19:38.882 : nau_gfauth:entry 2021-07-19 15:19:38.882 : nam_gbp:Reading parameter "sqlnet.fallback_authentication" from parameter file 2021-07-19 15:19:38.882 : nam_gbp:Parameter not found 2021-07-19 15:19:38.882 : nau_gfauth:Using default value "FALSE" 2021-07-19 15:19:38.882 : nau_gfauth:exit 2021-07-19 15:19:38.882 : nau_gettab:entry 2021-07-19 15:19:38.882 : nau_gettab:using authentication adapter table "nautab" 2021-07-19 15:19:38.882 : nau_gettab:nautab contains the following services: 2021-07-19 15:19:38.882 : nau_gettab: KERBEROS5 2021-07-19 15:19:38.882 : nau_gettab: RADIUS 2021-07-19 15:19:38.882 : nau_gettab: KERBEROS5PRE 2021-07-19 15:19:38.882 : nau_gettab:exit 2021-07-19 15:19:38.882 : nau_sini:entry 2021-07-19 15:19:38.882 : nau_sini:exit 2021-07-19 15:19:38.882 : nau_ini:connection type: "standard" 2021-07-19 15:19:38.882 : nau_ini:exit 2021-07-19 15:19:38.883 : naeeinit:entry 2021-07-19 15:19:38.883 : nam_gbp:Reading parameter "SQLNET.FIPS_140" from parameter file 2021-07-19 15:19:38.883 : nam_gbp:Parameter not found 2021-07-19 15:19:38.883 : naeconp:entry 2021-07-19 15:19:38.883 : naeconp:Reading ENCRYPTION_CLIENT or CRYPTO_CHECKSUM_CLIENT parameter from connection string. 2021-07-19 15:19:38.883 : nam_gnsp:Reading parameter "SQLNET.ENCRYPTION_SERVER" from parameter file 2021-07-19 15:19:38.883 : nam_gnsp:Parameter not found 2021-07-19 15:19:38.883 : naequad:Using default value "ACCEPTED" 2021-07-19 15:19:38.883 : nae_get_boolean_param_from_conn_string:entry 2021-07-19 15:19:38.883 : nae_get_boolean_param_from_conn_string:Reading ENCRYPTION_CLIENT or CRYPTO_CHECKSUM_CLIENT parameter from connection string. 2021-07-19 15:19:38.883 : nam_gbp:Reading parameter "SQLNET.IGNORE_ANO_ENCRYPTION_FOR_TCPS" from parameter file 2021-07-19 15:19:38.883 : nam_gbp:Parameter not found 2021-07-19 15:19:38.883 : nam_gbp:Reading parameter "SQLNET._ENHANCED_LOGON_PROTECTION" from parameter file 2021-07-19 15:19:38.883 : nam_gbp:Parameter not found 2021-07-19 15:19:38.883 : nam_gic:entry 2021-07-19 15:19:38.883 : nam_gic:Counting # of items in "SQLNET.ENCRYPTION_TYPES_SERVER" parameter 2021-07-19 15:19:38.883 : nam_gic:Parameter not found 2021-07-19 15:19:38.883 : nam_gic:exit 2021-07-19 15:19:38.883 : naesno:Using default value "all available algorithms" 2021-07-19 15:19:38.883 : naeshow:entry 2021-07-19 15:19:38.883 : naeshow:These are the encryption algorithms that the server will accept, in decreasing order of preference: 2021-07-19 15:19:38.883 : naeshow:Choice 0: no algorithm; encryption inactive 2021-07-19 15:19:38.883 : naeshow:Choice 1: 'AES256' (ID 17) 2021-07-19 15:19:38.883 : naeshow:Choice 2: 'RC4_256' (ID 6) 2021-07-19 15:19:38.883 : naeshow:Choice 3: 'AES192' (ID 16) 2021-07-19 15:19:38.883 : naeshow:Choice 4: '3DES168' (ID 12) 2021-07-19 15:19:38.883 : naeshow:Choice 5: 'AES128' (ID 15) 2021-07-19 15:19:38.883 : naeshow:Choice 6: 'RC4_128' (ID 10) 2021-07-19 15:19:38.883 : naeshow:Choice 7: '3DES112' (ID 11) 2021-07-19 15:19:38.883 : naeshow:Choice 8: 'RC4_56' (ID 8) 2021-07-19 15:19:38.883 : naeshow:Choice 9: 'DES' (ID 2) 2021-07-19 15:19:38.883 : naeshow:Choice 10: 'RC4_40' (ID 1) 2021-07-19 15:19:38.884 : naeshow:Choice 11: 'DES40' (ID 3) 2021-07-19 15:19:38.884 : naeshow:exit 2021-07-19 15:19:38.884 : naeeinit:exit 2021-07-19 15:19:38.884 : naecinit:entry 2021-07-19 15:19:38.884 : naeconp:entry 2021-07-19 15:19:38.884 : naeconp:Reading ENCRYPTION_CLIENT or CRYPTO_CHECKSUM_CLIENT parameter from connection string. 2021-07-19 15:19:38.884 : nam_gnsp:Reading parameter "SQLNET.CRYPTO_CHECKSUM_SERVER" from parameter file 2021-07-19 15:19:38.884 : nam_gnsp:Parameter not found 2021-07-19 15:19:38.884 : naequad:Using default value "ACCEPTED" 2021-07-19 15:19:38.884 : nam_gic:entry 2021-07-19 15:19:38.884 : nam_gic:Counting # of items in "SQLNET.CRYPTO_CHECKSUM_TYPES_SERVER" parameter 2021-07-19 15:19:38.884 : nam_gic:Parameter not found 2021-07-19 15:19:38.884 : nam_gic:exit 2021-07-19 15:19:38.884 : naesno:Using default value "all available algorithms" 2021-07-19 15:19:38.884 : naeshow:entry 2021-07-19 15:19:38.884 : naeshow:These are the checksumming algorithms that the server will accept, in decreasing order of preference: 2021-07-19 15:19:38.884 : naeshow:Choice 0: no algorithm; checksumming inactive 2021-07-19 15:19:38.884 : naeshow:Choice 1: 'SHA1' (ID 3) 2021-07-19 15:19:38.884 : naeshow:Choice 2: 'MD5' (ID 1) 2021-07-19 15:19:38.884 : naeshow:Choice 3: 'SHA512' (ID 4) 2021-07-19 15:19:38.884 : naeshow:Choice 4: 'SHA256' (ID 5) 2021-07-19 15:19:38.884 : naeshow:Choice 5: 'SHA384' (ID 6) 2021-07-19 15:19:38.884 : naeshow:exit 2021-07-19 15:19:38.884 : naecinit:exit 2021-07-19 15:19:38.884 : nainit:native services disabled - disconnecting 2021-07-19 15:19:38.884 : nadisc:entry 2021-07-19 15:19:38.884 : nacomtm:entry 2021-07-19 15:19:38.884 : nacompd:entry 2021-07-19 15:19:38.884 : nacompd:exit 2021-07-19 15:19:38.884 : nacompd:entry 2021-07-19 15:19:38.884 : nacompd:exit 2021-07-19 15:19:38.884 : nacomtm:exit 2021-07-19 15:19:38.885 : nas_dis:entry 2021-07-19 15:19:38.885 : nas_dis:exit 2021-07-19 15:19:38.885 : nau_dis:entry 2021-07-19 15:19:38.885 : nau_dis:exit 2021-07-19 15:19:38.885 : naeetrm:entry 2021-07-19 15:19:38.885 : naeetrm:exit 2021-07-19 15:19:38.885 : naectrm:entry 2021-07-19 15:19:38.885 : naectrm:exit 2021-07-19 15:19:38.885 : nagbltrm:entry 2021-07-19 15:19:38.885 : nau_gtm:entry 2021-07-19 15:19:38.885 : nau_gtm:exit 2021-07-19 15:19:38.885 : nagbltrm:exit 2021-07-19 15:19:38.885 : nadisc:exit 2021-07-19 15:19:38.885 : nainit:exit 2021-07-19 15:19:38.885 : nsnainit:NS Connection version: 318 2021-07-19 15:19:38.885 : nsnainit:inf->nsinfflg[0]: 0xd inf->nsinfflg[1]: 0xd 2021-07-19 15:19:38.885 : nsnainit:"or" info flags: 0xd Translations follow: native service(s) is (are) wanted NA disabled remotely for this connection NA services unavailable on both processes - negotiation not needed 2021-07-19 15:19:38.885 : nsnainit:"or" info flags: 0xd Translations follow: native service(s) is (are) wanted NA disabled remotely for this connection NA services unavailable on both processes - negotiation not needed "and" info flags: 0xd Translations follow: native service(s) is (are) wanted NA disabled remotely for this connection NA services unavailable on both processes - negotiation not needed 2021-07-19 15:19:38.885 : nsnainit:normal exit 2021-07-19 15:19:38.885 : nsopen:global context check-in (to slot 10) complete 2021-07-19 15:19:38.885 : nsopen:lcl[0]=0xf4ffe9ff, lcl[1]=0x12003, gbl[0]=0x7ebf, gbl[1]=0x2001, tdu=2097152, sdu=8192 2021-07-19 15:19:38.885 : nsfull_opn:entry 2021-07-19 15:19:38.885 : nsfull_opn:cid=10, opcode=65, *bl=0, *what=0, uflgs=0x0, cflgs=0x0 2021-07-19 15:19:38.885 : nsfull_opn:nsctx: state=7, flg=0x4000, mvd=0 2021-07-19 15:19:38.885 : nsbal:entry 2021-07-19 15:19:38.885 : nsbgetfl:entry 2021-07-19 15:19:38.885 : nsbgetfl:normal exit 2021-07-19 15:19:38.885 : nsbal:normal exit 2021-07-19 15:19:38.885 : nsbal:entry 2021-07-19 15:19:38.885 : nsbgetfl:entry 2021-07-19 15:19:38.885 : nsbgetfl:normal exit 2021-07-19 15:19:38.885 : nsbal:normal exit 2021-07-19 15:19:38.885 : nsfull_opn:normal exit 2021-07-19 15:19:38.886 : nsopen:normal exit 2021-07-19 15:19:38.886 : nsanswer:deferring connect attempt; at stage 5 2021-07-19 15:19:38.886 : nsanswer:normal exit 2021-07-19 15:19:38.886 : nsgetaddr:entry 2021-07-19 15:19:38.886 : nttaddr2bnd:entry 2021-07-19 15:19:38.886 : snlinGetNameInfo:entry 2021-07-19 15:19:38.886 : snlinGetNameInfo:exit 2021-07-19 15:19:38.886 : nttaddr2bnd:Resolved to 192.168.1.227 2021-07-19 15:19:38.886 : nttaddr2bnd:exit 2021-07-19 15:19:38.886 : nsevreg:entry 2021-07-19 15:19:38.886 : nsevreg:begin registration process for 10 2021-07-19 15:19:38.886 : nsevregPrePost:entry 2021-07-19 15:19:38.886 : nsevregPrePost:normal exit 2021-07-19 15:19:38.886 : nsevreg:sgt=0, evn=1, evt[2]=0x0 2021-07-19 15:19:38.886 : nsevreg:begin notification process for 10 2021-07-19 15:19:38.886 : nsevregAffectNotif:entry 2021-07-19 15:19:38.886 : nsevregAffectNotif:exit (0) 2021-07-19 15:19:38.886 : nsevreg:rdm=0, sgt=0, evt[0]=0x20, [1]=0x20, [2]=0x0, nrg=0 2021-07-19 15:19:38.886 : nsevreg:registering for 0x20 2021-07-19 15:19:38.886 : nsevreg:normal exit 2021-07-19 15:19:38.886 : nsglhe:exit 2021-07-19 15:19:38.886 : nsevwait:entry 2021-07-19 15:19:38.886 : nsevwait:9 registered connection(s) 2021-07-19 15:19:38.886 : nsevwait:0 pre-posted event(s) 2021-07-19 15:19:38.886 : nsevwait:waiting for transport event (1 thru 10)... 2021-07-19 15:19:38.886 : nsevwait:0 newly-posted event(s) 2021-07-19 15:19:38.886 : nsgetaddr:entry 2021-07-19 15:19:38.886 : nttaddr2bnd:entry 2021-07-19 15:19:38.886 : snlinGetNameInfo:entry 2021-07-19 15:19:38.886 : snlinGetNameInfo:exit 2021-07-19 15:19:38.886 : nttaddr2bnd:Resolved to 192.168.1.227 2021-07-19 15:19:38.887 : nttaddr2bnd:exit 2021-07-19 15:19:38.887 : nsevfnt:cxd: 0x84d110 cid=10 stage 5: NT events set: READ 2021-07-19 15:19:38.887 : nsgetaddr:entry 2021-07-19 15:19:38.887 : nttaddr2bnd:entry 2021-07-19 15:19:38.887 : snlinGetNameInfo:entry 2021-07-19 15:19:38.887 : snlinGetNameInfo:exit 2021-07-19 15:19:38.887 : nttaddr2bnd:Resolved to 192.168.1.227 2021-07-19 15:19:38.887 : nttaddr2bnd:exit 2021-07-19 15:19:38.887 : nsevfnt:cxd: 0x84d110 cid=10 stage 5: NS events set: OUTGOING CALL COMPLETE (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.1.227)(PORT=53468)) 2021-07-19 15:19:38.887 : nsevdansw:entry 2021-07-19 15:19:38.887 : nsevdansw:at STAGE 5 2021-07-19 15:19:38.887 : nsdo:entry 2021-07-19 15:19:38.887 : nsdo:cid=10, opcode=68, *bl=2040, *what=8, uflgs=0x0, cflgs=0x3 2021-07-19 15:19:38.887 : nsdo:rank=64, nsctxrnk=0 2021-07-19 15:19:38.887 : nsdo:nsctx: state=14, flg=0x20004004, mvd=0 2021-07-19 15:19:38.887 : nsdo:gtn=10, gtc=10, ptn=10, ptc=8111 2021-07-19 15:19:38.887 : nscon:entry 2021-07-19 15:19:38.887 : nscon:doing connect handshake... 2021-07-19 15:19:38.887 : nscon:recving a packet 2021-07-19 15:19:38.887 : nsprecv:entry 2021-07-19 15:19:38.887 : nsprecv:reading from transport... 2021-07-19 15:19:38.887 : nttrd:entry 2021-07-19 15:19:38.887 : nttrd:socket 20 had bytes read=21 2021-07-19 15:19:38.887 : nttrd:exit 2021-07-19 15:19:38.887 : nsprecv:21 bytes from transport 2021-07-19 15:19:38.887 : nsprecv:header checksum error 2021-07-19 15:19:38.887 : nsprecv:packet hdr 2021-07-19 15:19:38.887 : nsprecv:53 53 48 2D 32 2E 00 00 |SSH-2...| 2021-07-19 15:19:38.887 : nsprecv:error exit 2021-07-19 15:19:38.887 : nserror:entry 2021-07-19 15:19:38.887 : nserror:nsres: id=10, op=68, ns=12569, ns2=0; nt[0]=0, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0 2021-07-19 15:19:38.888 : nscon:error exit 2021-07-19 15:19:38.888 : nsdo:nsctxrnk=0 2021-07-19 15:19:38.888 : nsdo:error exit 2021-07-19 15:19:38.888 : nsclose:entry 2021-07-19 15:19:38.888 : nsvntx_dei:entry 2021-07-19 15:19:38.888 : nsvntx_dei:exit 2021-07-19 15:19:38.888 : nstimarmed:entry 2021-07-19 15:19:38.888 : nstimarmed:no timer allocated 2021-07-19 15:19:38.888 : nstimarmed:normal exit 2021-07-19 15:19:38.888 : nstoClearTimeout:entry 2021-07-19 15:19:38.888 : nstoClearTimeout:ATO disabled for ctx=0x0x8a82e0 2021-07-19 15:19:38.888 : nstoClearTimeout:STO disabled for ctx=0x0x8a82e0 2021-07-19 15:19:38.888 : nstoClearTimeout:RTO disabled for ctx=0x0x8a82e0 2021-07-19 15:19:38.888 : nstoClearTimeout:PITO disabled for ctx=0x0x8a82e0 2021-07-19 15:19:38.888 : nstoUpdateActive:entry 2021-07-19 15:19:38.888 : nstoUpdateActive:Active timeout is -1 (see nstotyp) 2021-07-19 15:19:38.888 : nttctl:entry 2021-07-19 15:19:38.888 : nttctl:entry 2021-07-19 15:19:38.888 : nsfull_cls:entry 2021-07-19 15:19:38.888 : nsfull_cls:cid=10, opcode=65, *bl=0, *what=0, uflgs=0x0, cflgs=0x40 2021-07-19 15:19:38.888 : nsfull_cls:nsctx: state=14, flg=0x20004000, mvd=0 2021-07-19 15:19:38.888 : nsevunreg:entry 2021-07-19 15:19:38.888 : nsevunreg:cid=10, sgt=0, rdm=0 2021-07-19 15:19:38.888 : nsevunreg:8 registered connection(s) 2021-07-19 15:19:38.888 : nsevunreg:exit (0) 2021-07-19 15:19:38.888 : nsbfr:entry 2021-07-19 15:19:38.888 : nsbaddfl:entry 2021-07-19 15:19:38.888 : nsbaddfl:normal exit 2021-07-19 15:19:38.888 : nsbfr:normal exit 2021-07-19 15:19:38.888 : nsbfr:entry 2021-07-19 15:19:38.888 : nsbaddfl:entry 2021-07-19 15:19:38.888 : nsbaddfl:normal exit 2021-07-19 15:19:38.888 : nsbfr:normal exit 2021-07-19 15:19:38.888 : nsfull_cls:normal exit 2021-07-19 15:19:38.889 : nsiocancel:entry 2021-07-19 15:19:38.889 : nsiofrrg:entry 2021-07-19 15:19:38.889 : nsiofrrg:cur = 83adc0 2021-07-19 15:19:38.889 : nsbfr:entry 2021-07-19 15:19:38.889 : nsbaddfl:entry 2021-07-19 15:19:38.889 : nsbaddfl:normal exit 2021-07-19 15:19:38.889 : nsbfr:normal exit 2021-07-19 15:19:38.889 : nsiofrrg:exit 2021-07-19 15:19:38.889 : nsiocancel:exit 2021-07-19 15:19:38.889 : nsclose:closing transport 2021-07-19 15:19:38.889 : nttdisc:entry 2021-07-19 15:19:38.889 : nttdisc:Closed socket 20 2021-07-19 15:19:38.889 : nttdisc:exit 2021-07-19 15:19:38.889 : nsclose:global context check-out (from slot 10) complete 2021-07-19 15:19:38.889 : nsnadisc:entry 2021-07-19 15:19:38.889 : nsnadisc:no native services in use - returning 2021-07-19 15:19:38.889 : nsvntx_dei:entry 2021-07-19 15:19:38.889 : nsvntx_dei:exit 2021-07-19 15:19:38.889 : nsiocancel:entry 2021-07-19 15:19:38.889 : nsiofrrg:entry 2021-07-19 15:19:38.889 : nsiofrrg:exit 2021-07-19 15:19:38.889 : nsiocancel:exit 2021-07-19 15:19:38.889 : nsmfr:entry 2021-07-19 15:19:38.889 : nsmfr:3368 bytes at 0x8a8a90 2021-07-19 15:19:38.889 : nsmfr:normal exit 2021-07-19 15:19:38.889 : nsmfr:entry 2021-07-19 15:19:38.889 : nsmfr:1952 bytes at 0x8a82e0 2021-07-19 15:19:38.889 : nsmfr:normal exit 2021-07-19 15:19:38.889 : nsclose:normal exit 2021-07-19 15:19:38.889 : nsevdansw:exit 2021-07-19 15:19:38.889 : nsevrec:event is 0x20, on -1 2021-07-19 15:19:38.890 : nsevwait:1 posted event(s) 2021-07-19 15:19:38.890 : nsevwait:exit (0) 2021-07-19 15:19:38.890 : nsglhe:entry 2021-07-19 15:19:38.890 : nsglhe:Event on cxd 0x84d110. 2021-07-19 15:19:38.890 : nsglvlslvalidate:entry 2021-07-19 15:19:38.890 : nsgldissolve:entry 2021-07-19 15:19:38.890 : nsdisc:entry 2021-07-19 15:19:38.890 : nsclose:entry 2021-07-19 15:19:38.890 : nsclose:normal exit 2021-07-19 15:19:38.890 : nsdisc:exit (0) 2021-07-19 15:19:38.890 : nsgldissolve:Deallocating cxd 0x84d110. 2021-07-19 15:19:38.890 : nsgldissolve:exit 2021-07-19 15:19:38.891 : nsglhe:exit 2021-07-19 15:19:38.891 : nsevwait:entry 2021-07-19 15:19:38.891 : nsevwait:8 registered connection(s) 2021-07-19 15:19:38.891 : nsevwait:0 pre-posted event(s) 2021-07-19 15:19:38.891 : nsevwait:waiting for transport event (1 thru 9)...
这种情况下，就有'Accepted Entry'关键字了，并且也可以得到想要的IP地址。
另外，还有这类似的信息：
2021-07-19 15:19:38.887 : nsevfnt:cxd: 0x84d110 cid=10 stage 5: NS events set: OUTGOING CALL COMPLETE (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.1.227)(PORT=53468))
因此，这个问题无法从DB层面得知源IP是在哪里，只能知道第3方的程序引起的。
从Linux层面看（长达2h的时间监控），生产环境的信息了（去掉或者修改敏感信息）：
[root@db ~]# netstat -nputwc | grep tns | grep -v "::ffff:192.168.1.100:34708" tcp 0 218 ::ffff:192.168.1.100:1521 ::ffff:10.100.50.133:65202 ESTABLISHED 8700/tnslsnr tcp 0 0 ::ffff:192.168.1.100:1521 ::ffff:10.100.50.133:65363 ESTABLISHED 8700/tnslsnr tcp 0 0 ::ffff:192.168.1.100:1521 ::ffff:10.100.50.133:65405 ESTABLISHED 8700/tnslsnr tcp 0 0 ::ffff:192.168.1.100:1521 ::ffff:10.100.50.133:65445 ESTABLISHED 8700/tnslsnr tcp 0 218 ::ffff:192.168.1.100:1521 ::ffff:10.100.50.133:49317 ESTABLISHED 8700/tnslsnr tcp 0 0 ::ffff:192.168.1.100:1521 ::ffff:10.100.50.133:49348 ESTABLISHED 8700/tnslsnr
基本能确定是由于10.100.50.133这个ip引起的。
Linux没有触发器真的麻烦，netstat每秒输出不能保证每次都捕捉到。
另外，使用Linux7去用ssh -p 1521 oracle@ip去模拟的话，监听日志的报错信息则类似如下：
<msg time='2021-07-19T21:12:25.492+08:00' org_id='oracle' comp_id='tnslsnr' type='UNKNOWN' level='16' host_id='testdb' host_addr='192.168.1.150'> <txt>TNS-12569: TNS:packet checksum failure </txt> </msg>
