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 * &lt;unknown connect data&gt; * 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 * &lt;unknown connect data&gt; * 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 * &lt;unknown connect data&gt; * 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 * &lt;unknown connect data&gt; * (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.1.150)(PORT=34811)) * establish * &lt;unknown sid&gt; * 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&apos;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 * &lt;unknown connect data&gt; * 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)...

View Code

根据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)...

View Code

这种情况下，就有'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>