一次客户的监听跟踪过程
客户的数据库在进行了10g单机升级到11g RAC后，部分外网连接的应用无法连接到数据库,报错信息如下：
C:\Documents and Settings\tzyy>sqlplus "drb/drbmc@tbsrun"
ERROR:
ORA-12543: TNS:destination host unreachable

我们首次通过tnsping确认连接问题：
C:\Documents and Settings\tzyy>tnsping tbsrun
TNS Ping Utility for 32-bit Windows: Version 10.2.0.1.0 - Production on 10-SEP-2
014 09:49:22
Copyright (c) 1997, 2005, Oracle. All rights reserved.
Used parameter files:
E:\oracle\product\10.2.0\client_1\network\admin\sqlnet.ora
Used TNSNAMES adapter to resolve the alias
Attempting to contact (DESCRIPTION = (ADDRESS_LIST = (ADDRESS = (PROTOCOL = TCP)
(HOST = 172.16.1.246)(PORT = 1521))) (CONNECT_DATA = (SERVER = DEDICATED) (servi
ce_name = bsrun)))
OK (20 msec)
发现tnsping没有任何问题，返回成功，对于我们来说，一般tnsping没有问题的话我们一般都认为从客户端主机到服务器端的网络环境都应该没有问题。
接下来我们通过对一次连接进行跟踪来分析问题：
首先设置跟踪参数：
TRACE_LEVEL_CLIENT=16
TRACE_FILE_CLIENT=CLIENT
TRACE_TIMESTAMP_CLIENT=ON
trace_directory_client=E:\oracle\product\10.2.0\client_1\NETWORK\ADMIN
具体的设置过程及参数解释在本文中不加叙述，我们只分析该过程

以下为详细的分析日志：

[10-SEP-2014 09:23:19:671] --- TRACE CONFIGURATION INFORMATION FOLLOWS ---
[10-SEP-2014 09:23:19:671] New trace stream is E:\oracle\product\10.2.0\client_1\NETWORK\ADMIN\client_2052_1.trc
[10-SEP-2014 09:23:19:671] New trace level is 16
[10-SEP-2014 09:23:19:671] --- TRACE CONFIGURATION INFORMATION ENDS ---
[10-SEP-2014 09:23:19:671] --- PARAMETER SOURCE INFORMATION FOLLOWS ---
[10-SEP-2014 09:23:19:671] Attempted load of system pfile source E:\oracle\product\10.2.0\client_1\network\admin\sqlnet.ora
[10-SEP-2014 09:23:19:671] Parameter source loaded successfully
[10-SEP-2014 09:23:19:671]
[10-SEP-2014 09:23:19:671] Attempted load of local pfile source C:\Documents and Settings\tzyy\sqlnet.ora
[10-SEP-2014 09:23:19:671] Parameter source was not loaded
[10-SEP-2014 09:23:19:671]
[10-SEP-2014 09:23:19:671] -> PARAMETER TABLE LOAD RESULTS FOLLOW <- [10-SEP-2014 09:23:19:671] Successful parameter table load [10-SEP-2014 09:23:19:671] -> PARAMETER TABLE HAS THE FOLLOWING CONTENTS <- [10-SEP-2014 09:23:19:671] TRACE_LEVEL_CLIENT = 16 [10-SEP-2014 09:23:19:671] TRACE_TIMESTAMP_CLIENT = ON [10-SEP-2014 09:23:19:671] SQLNET.AUTHENTICATION_SERVICES = (NTS) [10-SEP-2014 09:23:19:671] TRACE_FILE_CLIENT = CLIENT [10-SEP-2014 09:23:19:671] trace_directory_client = E:\oracle\product\10.2.0\client_1\NETWORK\ADMIN [10-SEP-2014 09:23:19:671] --- PARAMETER SOURCE INFORMATION ENDS --- [10-SEP-2014 09:23:19:671] --- LOG CONFIGURATION INFORMATION FOLLOWS --- [10-SEP-2014 09:23:19:671] Log stream will be "C:\Documents and Settings\tzyy\sqlnet.log" [10-SEP-2014 09:23:19:671] Log stream validation not requested [10-SEP-2014 09:23:19:671] --- LOG CONFIGURATION INFORMATION ENDS --- ###########################以上为本次跟踪的信息读取，包括跟踪级别，基本的跟踪参数读取位置########################### #####################以下为开始跟踪过程################################### [10-SEP-2014 09:23:19:671] nlstdipi: entry [10-SEP-2014 09:23:19:671] nlstdipi: exit [10-SEP-2014 09:23:19:671] nigini: entry [10-SEP-2014 09:23:19:671] nigini: Count in the NL global area is now 1 [10-SEP-2014 09:23:19:671] nigini: Count in NI global area now: 1 [10-SEP-2014 09:23:19:671] nrigbi: entry [10-SEP-2014 09:23:19:671] nrigbni: entry [10-SEP-2014 09:23:19:671] nrigbni: Unable to get data from navigation file tnsnav.ora [10-SEP-2014 09:23:19:671] nrigbni: exit [10-SEP-2014 09:23:19:671] nrigbi: exit [10-SEP-2014 09:23:19:671] nigini: exit [10-SEP-2014 09:23:19:671] niqname: Hst is already an NVstring. [10-SEP-2014 09:23:19:671] niqname: Inserting CID. [10-SEP-2014 09:23:19:671] niotns: entry [10-SEP-2014 09:23:19:671] niotns: niotns: setting up interrupt handler... [10-SEP-2014 09:23:19:671] niotns: Not trying to enable dead connection detection. #############################对连接串进行解析并确认################################### [10-SEP-2014 09:23:19:671] niotns: Calling address: (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=172.16.1.246)(PORT=1521)))(CONNECT_DATA=(SERVER=DEDICATED)(service_name=bsrun)(CID=(PROGRAM=E:\oracle\product\10.2.0\client_1\bin\sqlplus.exe)(HOST=CZDL_CGZX104)(USER=tzyy)))) [10-SEP-2014 09:23:19:671] nscall: entry [10-SEP-2014 09:23:19:671] nsmal: entry [10-SEP-2014 09:23:19:671] nsmal: 212 bytes at 0xe42d10 [10-SEP-2014 09:23:19:671] nsmal: normal exit [10-SEP-2014 09:23:19:671] nscall: connecting... [10-SEP-2014 09:23:19:671] nladini: entry [10-SEP-2014 09:23:19:671] nladini: exit [10-SEP-2014 09:23:19:671] nladget: entry [10-SEP-2014 09:23:19:671] nladget: exit [10-SEP-2014 09:23:19:671] nsc2addr: entry [10-SEP-2014 09:23:19:671] nsc2addr: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=172.16.1.246)(PORT=1521))(CONNECT_DATA=(SERVER=DEDICATED)(service_name=bsrun)(CID=(PROGRAM=E:\oracle\product\10.2.0\client_1\bin\sqlplus.exe)(HOST=CZDL_CGZX104)(USER=tzyy)))) [10-SEP-2014 09:23:19:671] nttbnd2addr: entry [10-SEP-2014 09:23:19:671] snlinGetAddrInfo: entry [10-SEP-2014 09:23:19:671] snlinGetAddrInfo: exit [10-SEP-2014 09:23:19:671] nttbnd2addr: using host IP address: 172.16.1.246 [10-SEP-2014 09:23:19:671] snlinFreeAddrInfo: entry [10-SEP-2014 09:23:19:671] snlinFreeAddrInfo: exit [10-SEP-2014 09:23:19:671] nttbnd2addr: exit [10-SEP-2014 09:23:19:671] nsc2addr: normal exit [10-SEP-2014 09:23:19:671] nsopen: entry [10-SEP-2014 09:23:19:671] nsmal: entry [10-SEP-2014 09:23:19:671] nsmal: 736 bytes at 0xeb5e08 [10-SEP-2014 09:23:19:671] nsmal: normal exit [10-SEP-2014 09:23:19:671] nsopenmplx: entry [10-SEP-2014 09:23:19:671] nsmal: entry [10-SEP-2014 09:23:19:671] nsmal: 1644 bytes at 0xeb60f0 [10-SEP-2014 09:23:19:671] nsmal: normal exit [10-SEP-2014 09:23:19:671] nsiorini: entry [10-SEP-2014 09:23:19:671] nsbal: entry [10-SEP-2014 09:23:19:671] nsbgetfl: entry [10-SEP-2014 09:23:19:671] nsbgetfl: normal exit [10-SEP-2014 09:23:19:671] nsmal: entry [10-SEP-2014 09:23:19:671] nsmal: 84 bytes at 0xd9f570 [10-SEP-2014 09:23:19:671] nsmal: normal exit [10-SEP-2014 09:23:19:671] nsbal: normal exit [10-SEP-2014 09:23:19:671] nsiorini: exit (0) [10-SEP-2014 09:23:19:671] nscpxget: entry [10-SEP-2014 09:23:19:671] nscpxget: normal exit [10-SEP-2014 09:23:19:671] nsopenalloc_nsntx: nlhthput on mplx_ht_nsgbu:ctx=eb5e08, nsntx=eb60f0 [10-SEP-2014 09:23:19:671] nsopenmplx: normal exit ###################开始创建连接，发起连接###################### [10-SEP-2014 09:23:19:671] nsopen: opening transport... [10-SEP-2014 09:23:19:671] nttcon: entry [10-SEP-2014 09:23:19:671] nttcon: toc = 1 [10-SEP-2014 09:23:19:671] nttcnp: entry [10-SEP-2014 09:23:19:671] nttcnp: creating a socket. [10-SEP-2014 09:23:19:671] nttcnp: exit [10-SEP-2014 09:23:19:671] nttcni: entry [10-SEP-2014 09:23:19:671] nttcni: trying to connect to socket 1864. [10-SEP-2014 09:23:19:671] snlinGetNameInfo: entry [10-SEP-2014 09:23:19:671] snlinGetNameInfo: Using numeric form of host's address 172.18.115.203 [10-SEP-2014 09:23:19:671] snlinGetNameInfo: exit [10-SEP-2014 09:23:19:671] nttcni: connected on ipaddr 172.18.115.203 [10-SEP-2014 09:23:19:671] nttcni: exit [10-SEP-2014 09:23:19:671] nttcon: NT layer TCP/IP connection has been established. [10-SEP-2014 09:23:19:671] nttcon: set TCP_NODELAY on 1864 [10-SEP-2014 09:23:19:671] nttcon: exit ########################以下发送274 bytes的包#################### [10-SEP-2014 09:23:19:671] nsopen: transport is open [10-SEP-2014 09:23:19:671] nsoptions: entry [10-SEP-2014 09:23:19:671] nsoptions: lcl[0]=0x0, lcl[1]=0x102000, gbl[0]=0x0, gbl[1]=0x0, cha=0x0 [10-SEP-2014 09:23:19:671] nsoptions: lcl[0]=0xf4ffefff, lcl[1]=0x102000, gbl[0]=0xfabf, gbl[1]=0x0 [10-SEP-2014 09:23:19:671] nsoptions: normal exit [10-SEP-2014 09:23:19:671] nsnainit: entry [10-SEP-2014 09:23:19:671] nsnainit: call [10-SEP-2014 09:23:19:671] nsnadct: entry [10-SEP-2014 09:23:19:671] nsnadct: normal exit [10-SEP-2014 09:23:19:671] nsnasvnainfo: entry [10-SEP-2014 09:23:19:671] nsnasvnainfo: normal exit [10-SEP-2014 09:23:19:671] nainit: entry [10-SEP-2014 09:23:19:671] nagblini: entry [10-SEP-2014 09:23:19:671] nau_gin: entry [10-SEP-2014 09:23:19:671] nau_gparams: entry [10-SEP-2014 09:23:19:671] nam_gbp: Reading parameter "sqlnet.authentication_required" from parameter file [10-SEP-2014 09:23:19:671] nam_gbp: Parameter not found [10-SEP-2014 09:23:19:671] nau_gparams: Using default value "FALSE" [10-SEP-2014 09:23:19:671] nau_gslf: entry [10-SEP-2014 09:23:19:671] nam_gic: entry [10-SEP-2014 09:23:19:671] nam_gic: Counting # of items in "sqlnet.authentication_services" parameter [10-SEP-2014 09:23:19:671] nam_gic: Found 1 items [10-SEP-2014 09:23:19:671] nam_gic: exit [10-SEP-2014 09:23:19:671] nam_gnsp: Reading parameter "sqlnet.authentication_services" from parameter file [10-SEP-2014 09:23:19:671] nam_gnsp: Found value "NTS" [10-SEP-2014 09:23:19:671] nauss_set_state: entry [10-SEP-2014 09:23:19:671] nauss_set_state: exit [10-SEP-2014 09:23:19:671] nau_gslf: exit [10-SEP-2014 09:23:19:671] nau_gparams: exit [10-SEP-2014 09:23:19:671] nau_gin: exit [10-SEP-2014 09:23:19:671] nagblini: exit [10-SEP-2014 09:23:19:671] na_saveprot: entry [10-SEP-2014 09:23:19:671] na_saveprot: exit [10-SEP-2014 09:23:19:671] nacomin: entry [10-SEP-2014 09:23:19:671] nas_init: entry [10-SEP-2014 09:23:19:671] nas_init: exit [10-SEP-2014 09:23:19:671] nau_ini: entry [10-SEP-2014 09:23:19:671] naugcp_get_connect_parameters: entry [10-SEP-2014 09:23:19:671] nauss_set_state: entry [10-SEP-2014 09:23:19:671] nauss_set_state: exit [10-SEP-2014 09:23:19:671] naugcp_get_connect_parameters: exit [10-SEP-2014 09:23:19:671] nau_gettab: entry [10-SEP-2014 09:23:19:671] nau_gettab: using authentication adapter table "nautab" [10-SEP-2014 09:23:19:671] nau_gettab: nautab contains the following services: [10-SEP-2014 09:23:19:671] nau_gettab: KERBEROS5 [10-SEP-2014 09:23:19:671] nau_gettab: NTS [10-SEP-2014 09:23:19:671] nau_gettab: RADIUS [10-SEP-2014 09:23:19:671] nau_gettab: exit [10-SEP-2014 09:23:19:671] nau_sini: entry [10-SEP-2014 09:23:19:671] nau_sini: exit [10-SEP-2014 09:23:19:671] nau_ini: connection type: "standard" [10-SEP-2014 09:23:19:671] nau_ini: exit [10-SEP-2014 09:23:19:671] naeeinit: entry [10-SEP-2014 09:23:19:671] nam_gbp: Reading parameter "SQLNET.FIPS_140" from parameter file [10-SEP-2014 09:23:19:671] nam_gbp: Parameter not found [10-SEP-2014 09:23:19:671] nam_gnsp: Reading parameter "SQLNET.ENCRYPTION_CLIENT" from parameter file [10-SEP-2014 09:23:19:671] nam_gnsp: Parameter not found [10-SEP-2014 09:23:19:671] naequad: Using default value "ACCEPTED" [10-SEP-2014 09:23:19:671] nam_gic: entry [10-SEP-2014 09:23:19:671] nam_gic: Counting # of items in "SQLNET.ENCRYPTION_TYPES_CLIENT" parameter [10-SEP-2014 09:23:19:671] nam_gic: Parameter not found [10-SEP-2014 09:23:19:671] nam_gic: exit [10-SEP-2014 09:23:19:671] naesno: Using default value "all available algorithms" [10-SEP-2014 09:23:19:671] naeshow: entry [10-SEP-2014 09:23:19:671] naeshow: These are the encryption algorithms that the client will accept: [10-SEP-2014 09:23:19:671] naeshow: Choice 0: no algorithm; encryption inactive [10-SEP-2014 09:23:19:671] naeshow: Choice 1: 'AES256' (ID 17) [10-SEP-2014 09:23:19:671] naeshow: Choice 2: 'RC4_256' (ID 6) [10-SEP-2014 09:23:19:671] naeshow: Choice 3: 'AES192' (ID 16) [10-SEP-2014 09:23:19:671] naeshow: Choice 4: '3DES168' (ID 12) [10-SEP-2014 09:23:19:671] naeshow: Choice 5: 'AES128' (ID 15) [10-SEP-2014 09:23:19:671] naeshow: Choice 6: 'RC4_128' (ID 10) [10-SEP-2014 09:23:19:671] naeshow: Choice 7: '3DES112' (ID 11) [10-SEP-2014 09:23:19:671] naeshow: Choice 8: 'RC4_56' (ID 8) [10-SEP-2014 09:23:19:671] naeshow: Choice 9: 'DES' (ID 2) [10-SEP-2014 09:23:19:671] naeshow: Choice 10: 'RC4_40' (ID 1) [10-SEP-2014 09:23:19:671] naeshow: Choice 11: 'DES40' (ID 3) [10-SEP-2014 09:23:19:671] naeshow: exit [10-SEP-2014 09:23:19:671] naeeinit: exit [10-SEP-2014 09:23:19:671] naecinit: entry [10-SEP-2014 09:23:19:671] nam_gnsp: Reading parameter "SQLNET.CRYPTO_CHECKSUM_CLIENT" from parameter file [10-SEP-2014 09:23:19:671] nam_gnsp: Parameter not found [10-SEP-2014 09:23:19:671] naequad: Using default value "ACCEPTED" [10-SEP-2014 09:23:19:671] nam_gic: entry [10-SEP-2014 09:23:19:671] nam_gic: Counting # of items in "SQLNET.CRYPTO_CHECKSUM_TYPES_CLIENT" parameter [10-SEP-2014 09:23:19:671] nam_gic: Parameter not found [10-SEP-2014 09:23:19:671] nam_gic: exit [10-SEP-2014 09:23:19:671] naesno: Using default value "all available algorithms" [10-SEP-2014 09:23:19:671] naeshow: entry [10-SEP-2014 09:23:19:671] naeshow: These are the checksumming algorithms that the client will accept: [10-SEP-2014 09:23:19:671] naeshow: Choice 0: no algorithm; checksumming inactive [10-SEP-2014 09:23:19:671] naeshow: Choice 1: 'SHA1' (ID 3) [10-SEP-2014 09:23:19:671] naeshow: Choice 2: 'MD5' (ID 1) [10-SEP-2014 09:23:19:671] naeshow: exit [10-SEP-2014 09:23:19:671] naecinit: exit [10-SEP-2014 09:23:19:671] nainit: exit [10-SEP-2014 09:23:19:671] nagetctxinfo: entry [10-SEP-2014 09:23:19:671] nagetctxinfo: exit [10-SEP-2014 09:23:19:671] nsnainit: NS Connection version: 313 [10-SEP-2014 09:23:19:671] nsnainit: inf->nsinfflg[0]: 0x61 inf->nsinfflg[1]: 0x61
[10-SEP-2014 09:23:19:671] nsnainit: "or" info flags: 0x61 Translations follow:
native service(s) is (are) wanted

[10-SEP-2014 09:23:19:671] nsnainit: "or" info flags: 0x61 Translations follow:
native service(s) is (are) wanted
"and" info flags: 0x61 Translations follow:
native service(s) is (are) wanted

[10-SEP-2014 09:23:19:671] nsnainit: normal exit
[10-SEP-2014 09:23:19:671] nsopen: global context check-in (to slot 0) complete
[10-SEP-2014 09:23:19:671] nsopen: lcl[0]=0xf4ffefff, lcl[1]=0x102000, gbl[0]=0xfabf, gbl[1]=0x0, tdu=32767, sdu=2048
[10-SEP-2014 09:23:19:671] nsdo: entry
[10-SEP-2014 09:23:19:671] nsdo: cid=0, opcode=65, *bl=0, *what=0, uflgs=0x0, cflgs=0x2
[10-SEP-2014 09:23:19:671] nsdo: rank=64, nsctxrnk=0
[10-SEP-2014 09:23:19:671] nsdo: nsctx: state=7, flg=0x4001, mvd=0
[10-SEP-2014 09:23:19:671] nsbal: entry
[10-SEP-2014 09:23:19:671] nsbgetfl: entry
[10-SEP-2014 09:23:19:671] nsbgetfl: normal exit
[10-SEP-2014 09:23:19:671] nsmal: entry
[10-SEP-2014 09:23:19:671] nsmal: 84 bytes at 0xeb5d68
[10-SEP-2014 09:23:19:671] nsmal: normal exit
[10-SEP-2014 09:23:19:671] nsbal: normal exit
[10-SEP-2014 09:23:19:671] nsbal: entry
[10-SEP-2014 09:23:19:671] nsbgetfl: entry
[10-SEP-2014 09:23:19:671] nsbgetfl: normal exit
[10-SEP-2014 09:23:19:671] nsmal: entry
[10-SEP-2014 09:23:19:671] nsmal: 84 bytes at 0xe47e10
[10-SEP-2014 09:23:19:671] nsmal: normal exit
[10-SEP-2014 09:23:19:671] nsbal: normal exit
[10-SEP-2014 09:23:19:671] nsdo: nsctxrnk=0
[10-SEP-2014 09:23:19:671] nsdo: normal exit
[10-SEP-2014 09:23:19:671] nsopen: normal exit
[10-SEP-2014 09:23:19:671] nsdo: entry
[10-SEP-2014 09:23:19:671] nsdo: cid=0, opcode=67, *bl=216, *what=8, uflgs=0x0, cflgs=0x3
[10-SEP-2014 09:23:19:671] nsdo: rank=64, nsctxrnk=0
[10-SEP-2014 09:23:19:671] nsdo: nsctx: state=14, flg=0x4005, mvd=0
[10-SEP-2014 09:23:19:671] nsdo: gtn=10, gtc=10, ptn=10, ptc=2011
[10-SEP-2014 09:23:19:671] nscon: entry
[10-SEP-2014 09:23:19:671] nscon: doing connect handshake...
[10-SEP-2014 09:23:19:671] nscon: sending NSPTCN packet
[10-SEP-2014 09:23:19:671] nspsend: entry
[10-SEP-2014 09:23:19:671] nspsend: plen=274, type=1
[10-SEP-2014 09:23:19:671] nttwr: entry
[10-SEP-2014 09:23:19:671] nttwr: socket 1864 had bytes written=274
[10-SEP-2014 09:23:19:671] nttwr: exit
[10-SEP-2014 09:23:19:671] nspsend: packet dump
[10-SEP-2014 09:23:19:671] nspsend: 01 12 00 00 01 00 00 00 |........|
[10-SEP-2014 09:23:19:671] nspsend: 01 39 01 2C 00 00 08 00 |.9.,....|
[10-SEP-2014 09:23:19:671] nspsend: 7F FF C6 0E 00 00 01 00 |........|
[10-SEP-2014 09:23:19:671] nspsend: 00 D8 00 3A 00 00 02 00 |...:....|
[10-SEP-2014 09:23:19:671] nspsend: 61 61 00 00 00 00 00 00 |aa......|
[10-SEP-2014 09:23:19:671] nspsend: 00 00 00 00 00 00 00 00 |........|
[10-SEP-2014 09:23:19:671] nspsend: 00 00 00 00 00 00 00 00 |........|
[10-SEP-2014 09:23:19:671] nspsend: 00 00 28 44 45 53 43 52 |..(DESCR|
[10-SEP-2014 09:23:19:671] nspsend: 49 50 54 49 4F 4E 3D 28 |IPTION=(|
[10-SEP-2014 09:23:19:671] nspsend: 41 44 44 52 45 53 53 3D |ADDRESS=|
[10-SEP-2014 09:23:19:671] nspsend: 28 50 52 4F 54 4F 43 4F |(PROTOCO|
[10-SEP-2014 09:23:19:671] nspsend: 4C 3D 54 43 50 29 28 48 |L=TCP)(H|
[10-SEP-2014 09:23:19:671] nspsend: 4F 53 54 3D 31 37 32 2E |OST=172.|
[10-SEP-2014 09:23:19:671] nspsend: 31 36 2E 31 2E 32 34 36 |16.1.246|
[10-SEP-2014 09:23:19:671] nspsend: 29 28 50 4F 52 54 3D 31 |)(PORT=1|
[10-SEP-2014 09:23:19:671] nspsend: 35 32 31 29 29 28 43 4F |521))(CO|
[10-SEP-2014 09:23:19:671] nspsend: 4E 4E 45 43 54 5F 44 41 |NNECT_DA|
[10-SEP-2014 09:23:19:671] nspsend: 54 41 3D 28 53 45 52 56 |TA=(SERV|
[10-SEP-2014 09:23:19:671] nspsend: 45 52 3D 44 45 44 49 43 |ER=DEDIC|
[10-SEP-2014 09:23:19:671] nspsend: 41 54 45 44 29 28 73 65 |ATED)(se|
[10-SEP-2014 09:23:19:671] nspsend: 72 76 69 63 65 5F 6E 61 |rvice_na|
[10-SEP-2014 09:23:19:671] nspsend: 6D 65 3D 62 73 72 75 6E |me=bsrun|
[10-SEP-2014 09:23:19:671] nspsend: 29 28 43 49 44 3D 28 50 |)(CID=(P|
[10-SEP-2014 09:23:19:671] nspsend: 52 4F 47 52 41 4D 3D 45 |ROGRAM=E|
[10-SEP-2014 09:23:19:671] nspsend: 3A 5C 6F 72 61 63 6C 65 |:\oracle|
[10-SEP-2014 09:23:19:671] nspsend: 5C 70 72 6F 64 75 63 74 |\product|
[10-SEP-2014 09:23:19:671] nspsend: 5C 31 30 2E 32 2E 30 5C |\10.2.0\|
[10-SEP-2014 09:23:19:671] nspsend: 63 6C 69 65 6E 74 5F 31 |client_1|
[10-SEP-2014 09:23:19:671] nspsend: 5C 62 69 6E 5C 73 71 6C |\bin\sql|
[10-SEP-2014 09:23:19:671] nspsend: 70 6C 75 73 2E 65 78 65 |plus.exe|
[10-SEP-2014 09:23:19:671] nspsend: 29 28 48 4F 53 54 3D 43 |)(HOST=C|
[10-SEP-2014 09:23:19:671] nspsend: 5A 44 4C 5F 43 47 5A 58 |ZDL_CGZX|
[10-SEP-2014 09:23:19:671] nspsend: 31 30 34 29 28 55 53 45 |104)(USE|
[10-SEP-2014 09:23:19:671] nspsend: 52 3D 74 7A 79 79 29 29 |R=tzyy))|
[10-SEP-2014 09:23:19:671] nspsend: 29 29 |)) |
[10-SEP-2014 09:23:19:671] nspsend: 274 bytes to transport
########################以上为整个发包过程#########################
[10-SEP-2014 09:23:19:671] nspsend: normal exit
[10-SEP-2014 09:23:19:671] nscon: exit (0)
[10-SEP-2014 09:23:19:671] nsdo: nsctxrnk=0
[10-SEP-2014 09:23:19:671] nsdo: normal exit
[10-SEP-2014 09:23:19:671] nsdo: entry
[10-SEP-2014 09:23:19:671] nsdo: cid=0, opcode=68, *bl=512, *what=9, uflgs=0x0, cflgs=0x3
[10-SEP-2014 09:23:19:671] nsdo: rank=64, nsctxrnk=0
[10-SEP-2014 09:23:19:671] nsdo: nsctx: state=2, flg=0x4005, mvd=0
[10-SEP-2014 09:23:19:671] nsdo: gtn=10, gtc=10, ptn=10, ptc=2011
[10-SEP-2014 09:23:19:671] nscon: entry
############################开始从服务端的回包过程############################
[10-SEP-2014 09:23:19:671] nscon: recving a packet
[10-SEP-2014 09:23:19:671] nsprecv: entry
[10-SEP-2014 09:23:19:671] nsprecv: reading from transport...
[10-SEP-2014 09:23:19:671] nttrd: entry
[10-SEP-2014 09:23:19:671] nttrd: socket 1864 had bytes read=313
[10-SEP-2014 09:23:19:671] nttrd: exit
[10-SEP-2014 09:23:19:671] nsprecv: 313 bytes from transport
[10-SEP-2014 09:23:19:671] nsprecv: tlen=313, plen=10, type=5
[10-SEP-2014 09:23:19:671] nsprecv: 303 bytes to leftover
[10-SEP-2014 09:23:19:671] nsprecv: packet dump
[10-SEP-2014 09:23:19:671] nsprecv: 00 0A 00 00 05 02 00 00 |........|
[10-SEP-2014 09:23:19:671] nsprecv: 01 25 |.% |
[10-SEP-2014 09:23:19:671] nsprecv: normal exit
[10-SEP-2014 09:23:19:671] nscon: got NSPTRD packet
[10-SEP-2014 09:23:19:671] nscon: recving connect data
[10-SEP-2014 09:23:19:671] nsdo: entry
[10-SEP-2014 09:23:19:671] nsdo: cid=0, opcode=68, *bl=293, *what=1, uflgs=0x4001, cflgs=0x0
[10-SEP-2014 09:23:19:671] nsdo: nsctx: state=2, flg=0x804005, mvd=0
[10-SEP-2014 09:23:19:671] nsdo: gtn=10, gtc=10, ptn=10, ptc=2011
[10-SEP-2014 09:23:19:671] nsrdr: entry
[10-SEP-2014 09:23:19:671] nsrdr: recving a packet
[10-SEP-2014 09:23:19:671] nsprecv: entry
[10-SEP-2014 09:23:19:671] nsprecv: 303 bytes from leftover
[10-SEP-2014 09:23:19:671] nsprecv: tlen=303, plen=303, type=6
[10-SEP-2014 09:23:19:671] nsprecv: packet dump
[10-SEP-2014 09:23:19:671] nsprecv: 01 2F 00 00 06 00 00 00 |./......|
[10-SEP-2014 09:23:19:671] nsprecv: 00 40 28 41 44 44 52 45 |.@(ADDRE|
[10-SEP-2014 09:23:19:671] nsprecv: 53 53 3D 28 50 52 4F 54 |SS=(PROT|
[10-SEP-2014 09:23:19:671] nsprecv: 4F 43 4F 4C 3D 54 43 50 |OCOL=TCP|
[10-SEP-2014 09:23:19:671] nsprecv: 29 28 48 4F 53 54 3D 31 |)(HOST=1|
[10-SEP-2014 09:23:19:671] nsprecv: 37 32 2E 31 36 2E 31 2E |72.16.1.|
[10-SEP-2014 09:23:19:671] nsprecv: 32 34 38 29 28 50 4F 52 |248)(POR|
[10-SEP-2014 09:23:19:671] nsprecv: 54 3D 31 35 32 31 29 29 |T=1521))|
[10-SEP-2014 09:23:19:671] nsprecv: 00 28 44 45 53 43 52 49 |.(DESCRI|
[10-SEP-2014 09:23:19:671] nsprecv: 50 54 49 4F 4E 3D 28 41 |PTION=(A|
[10-SEP-2014 09:23:19:671] nsprecv: 44 44 52 45 53 53 3D 28 |DDRESS=(|
[10-SEP-2014 09:23:19:671] nsprecv: 50 52 4F 54 4F 43 4F 4C |PROTOCOL|
[10-SEP-2014 09:23:19:671] nsprecv: 3D 54 43 50 29 28 48 4F |=TCP)(HO|
[10-SEP-2014 09:23:19:671] nsprecv: 53 54 3D 31 37 32 2E 31 |ST=172.1|
[10-SEP-2014 09:23:19:671] nsprecv: 36 2E 31 2E 32 34 36 29 |6.1.246)|
[10-SEP-2014 09:23:19:671] nsprecv: 28 50 4F 52 54 3D 31 35 |(PORT=15|
[10-SEP-2014 09:23:19:671] nsprecv: 32 31 29 29 28 43 4F 4E |21))(CON|
[10-SEP-2014 09:23:19:671] nsprecv: 4E 45 43 54 5F 44 41 54 |NECT_DAT|
[10-SEP-2014 09:23:19:671] nsprecv: 41 3D 28 53 45 52 56 45 |A=(SERVE|
[10-SEP-2014 09:23:19:671] nsprecv: 52 3D 44 45 44 49 43 41 |R=DEDICA|
[10-SEP-2014 09:23:19:671] nsprecv: 54 45 44 29 28 73 65 72 |TED)(ser|
[10-SEP-2014 09:23:19:671] nsprecv: 76 69 63 65 5F 6E 61 6D |vice_nam|
[10-SEP-2014 09:23:19:671] nsprecv: 65 3D 62 73 72 75 6E 29 |e=bsrun)|
[10-SEP-2014 09:23:19:671] nsprecv: 28 43 49 44 3D 28 50 52 |(CID=(PR|
[10-SEP-2014 09:23:19:671] nsprecv: 4F 47 52 41 4D 3D 45 3A |OGRAM=E:|
[10-SEP-2014 09:23:19:671] nsprecv: 5C 6F 72 61 63 6C 65 5C |\oracle\|
[10-SEP-2014 09:23:19:671] nsprecv: 70 72 6F 64 75 63 74 5C |product\|
[10-SEP-2014 09:23:19:671] nsprecv: 31 30 2E 32 2E 30 5C 63 |10.2.0\c|
[10-SEP-2014 09:23:19:671] nsprecv: 6C 69 65 6E 74 5F 31 5C |lient_1\|
[10-SEP-2014 09:23:19:671] nsprecv: 62 69 6E 5C 73 71 6C 70 |bin\sqlp|
[10-SEP-2014 09:23:19:671] nsprecv: 6C 75 73 2E 65 78 65 29 |lus.exe)|
[10-SEP-2014 09:23:19:671] nsprecv: 28 48 4F 53 54 3D 43 5A |(HOST=CZ|
[10-SEP-2014 09:23:19:671] nsprecv: 44 4C 5F 43 47 5A 58 31 |DL_CGZX1|
[10-SEP-2014 09:23:19:671] nsprecv: 30 34 29 28 55 53 45 52 |04)(USER|
[10-SEP-2014 09:23:19:671] nsprecv: 3D 74 7A 79 79 29 29 28 |=tzyy))(|
[10-SEP-2014 09:23:19:671] nsprecv: 49 4E 53 54 41 4E 43 45 |INSTANCE|
[10-SEP-2014 09:23:19:671] nsprecv: 5F 4E 41 4D 45 3D 62 73 |_NAME=bs|
[10-SEP-2014 09:23:19:671] nsprecv: 72 75 6E 32 29 29 29 |run2))) |
[10-SEP-2014 09:23:19:671] nsprecv: normal exit
[10-SEP-2014 09:23:19:671] nsrdr: got NSPTDA packet
[10-SEP-2014 09:23:19:671] nsrdr: NSPTDA flags: 0x40
[10-SEP-2014 09:23:19:671] nsrdr: normal exit
[10-SEP-2014 09:23:19:671] nsdo: *what=1, *bl=293
[10-SEP-2014 09:23:19:671] nsdo: 293 bytes from NS buffer
##############################发回293字节的包############################
[10-SEP-2014 09:23:19:671] nsdo: normal exit
[10-SEP-2014 09:23:19:671] nscon: got 293 bytes connect data
[10-SEP-2014 09:23:19:671] nscon: exit (0)
[10-SEP-2014 09:23:19:671] nsdo: nsctxrnk=0
[10-SEP-2014 09:23:19:671] nsdo: normal exit
[10-SEP-2014 09:23:19:671] nscall: redirected
[10-SEP-2014 09:23:19:671] nsclose: entry
[10-SEP-2014 09:23:19:671] nstimarmed: entry
[10-SEP-2014 09:23:19:671] nstimarmed: no timer allocated
[10-SEP-2014 09:23:19:671] nstimarmed: normal exit
[10-SEP-2014 09:23:19:671] nttctl: entry
[10-SEP-2014 09:23:19:671] nttctl: entry
[10-SEP-2014 09:23:19:671] nsdo: entry
[10-SEP-2014 09:23:19:671] nsdo: cid=0, opcode=98, *bl=0, *what=0, uflgs=0x440, cflgs=0x2
[10-SEP-2014 09:23:19:671] nsdo: rank=64, nsctxrnk=0
[10-SEP-2014 09:23:19:671] nsdo: nsctx: state=3, flg=0x804001, mvd=0
[10-SEP-2014 09:23:19:671] nsbfr: entry
[10-SEP-2014 09:23:19:671] nsbaddfl: entry
[10-SEP-2014 09:23:19:671] nsbaddfl: normal exit
[10-SEP-2014 09:23:19:671] nsbfr: normal exit
[10-SEP-2014 09:23:19:671] nsbfr: entry
[10-SEP-2014 09:23:19:671] nsbaddfl: entry
[10-SEP-2014 09:23:19:671] nsbaddfl: normal exit
[10-SEP-2014 09:23:19:671] nsbfr: normal exit
[10-SEP-2014 09:23:19:671] nsdo: nsctxrnk=0
[10-SEP-2014 09:23:19:671] nsdo: normal exit
[10-SEP-2014 09:23:19:671] nsiocancel: entry
[10-SEP-2014 09:23:19:671] nsiofrrg: entry
[10-SEP-2014 09:23:19:671] nsbfr: entry
[10-SEP-2014 09:23:19:671] nsbaddfl: entry
[10-SEP-2014 09:23:19:671] nsbaddfl: normal exit
[10-SEP-2014 09:23:19:671] nsbfr: normal exit
[10-SEP-2014 09:23:19:671] nsiofrrg: exit
[10-SEP-2014 09:23:19:671] nsiocancel: exit
[10-SEP-2014 09:23:19:671] nsclose: closing transport
[10-SEP-2014 09:23:19:671] nttdisc: entry
[10-SEP-2014 09:23:19:671] nttdisc: Closed socket 1864
###########################以上为整个握手协议过程，到这里整个握手协议成功，也就是tnsping为什么成功的原因，接下来就要真正开始建立连接#################
[10-SEP-2014 09:23:19:671] nttdisc: exit
[10-SEP-2014 09:23:19:671] nsclose: global context check-out (from slot 0) complete
[10-SEP-2014 09:23:19:671] nsnadisc: entry
[10-SEP-2014 09:23:19:671] nadisc: entry
[10-SEP-2014 09:23:19:671] nacomtm: entry
[10-SEP-2014 09:23:19:671] nacompd: entry
[10-SEP-2014 09:23:19:671] nacompd: exit
[10-SEP-2014 09:23:19:671] nacompd: entry
[10-SEP-2014 09:23:19:671] nacompd: exit
[10-SEP-2014 09:23:19:671] nacomtm: exit
[10-SEP-2014 09:23:19:671] nas_dis: entry
[10-SEP-2014 09:23:19:671] nas_dis: exit
[10-SEP-2014 09:23:19:671] nau_dis: entry
[10-SEP-2014 09:23:19:671] nau_dis: exit
[10-SEP-2014 09:23:19:671] naeetrm: entry
[10-SEP-2014 09:23:19:671] naeetrm: exit
[10-SEP-2014 09:23:19:671] naectrm: entry
[10-SEP-2014 09:23:19:671] naectrm: exit
[10-SEP-2014 09:23:19:671] nagbltrm: entry
[10-SEP-2014 09:23:19:671] nau_gtm: entry
[10-SEP-2014 09:23:19:671] nau_gtm: exit
[10-SEP-2014 09:23:19:671] nagbltrm: exit
[10-SEP-2014 09:23:19:671] nadisc: exit
[10-SEP-2014 09:23:19:671] nsnadisc: normal exit
[10-SEP-2014 09:23:19:671] nsopenfree_nsntx: nlhthdel from mplx_ht_nsgbu, ctx=eb5e08 nsntx=eb60f0
[10-SEP-2014 09:23:19:671] nsiocancel: entry
[10-SEP-2014 09:23:19:671] nsiofrrg: entry
[10-SEP-2014 09:23:19:671] nsiofrrg: exit
[10-SEP-2014 09:23:19:671] nsiocancel: exit
[10-SEP-2014 09:23:19:671] nsmfr: entry
[10-SEP-2014 09:23:19:671] nsmfr: 1644 bytes at 0xeb60f0
[10-SEP-2014 09:23:19:671] nsmfr: normal exit
[10-SEP-2014 09:23:19:671] nsmfr: entry
[10-SEP-2014 09:23:19:671] nsmfr: 736 bytes at 0xeb5e08
[10-SEP-2014 09:23:19:671] nsmfr: normal exit
[10-SEP-2014 09:23:19:671] nsclose: normal exit
[10-SEP-2014 09:23:19:671] nscall: connecting...
[10-SEP-2014 09:23:19:671] nsc2addr: entry
############以下是我们需要重点关注的一点，172.16.1.248 该IP为二节点的VIP#####################
[10-SEP-2014 09:23:19:671] nsc2addr: (ADDRESS=(PROTOCOL=TCP)(HOST=172.16.1.248)(PORT=1521))
[10-SEP-2014 09:23:19:671] nttbnd2addr: entry
[10-SEP-2014 09:23:19:671] snlinGetAddrInfo: entry
[10-SEP-2014 09:23:19:671] snlinGetAddrInfo: exit
[10-SEP-2014 09:23:19:671] nttbnd2addr: using host IP address: 172.16.1.248
[10-SEP-2014 09:23:19:671] snlinFreeAddrInfo: entry
[10-SEP-2014 09:23:19:671] snlinFreeAddrInfo: exit
[10-SEP-2014 09:23:19:671] nttbnd2addr: exit
[10-SEP-2014 09:23:19:671] nsc2addr: normal exit
[10-SEP-2014 09:23:19:671] nsopen: entry
[10-SEP-2014 09:23:19:671] nsmal: entry
[10-SEP-2014 09:23:19:671] nsmal: 736 bytes at 0xeb5e08
[10-SEP-2014 09:23:19:671] nsmal: normal exit
[10-SEP-2014 09:23:19:671] nsopenmplx: entry
[10-SEP-2014 09:23:19:671] nsmal: entry
[10-SEP-2014 09:23:19:671] nsmal: 1644 bytes at 0xeb60f0
[10-SEP-2014 09:23:19:687] nsmal: normal exit
[10-SEP-2014 09:23:19:687] nsiorini: entry
[10-SEP-2014 09:23:19:687] nsbal: entry
[10-SEP-2014 09:23:19:687] nsbgetfl: entry
[10-SEP-2014 09:23:19:687] nsbgetfl: normal exit
[10-SEP-2014 09:23:19:687] nsbal: normal exit
[10-SEP-2014 09:23:19:687] nsiorini: exit (0)
[10-SEP-2014 09:23:19:687] nscpxget: entry
[10-SEP-2014 09:23:19:687] nscpxget: normal exit
[10-SEP-2014 09:23:19:687] nsopenalloc_nsntx: nlhthput on mplx_ht_nsgbu:ctx=eb5e08, nsntx=eb60f0
[10-SEP-2014 09:23:19:687] nsopenmplx: normal exit
[10-SEP-2014 09:23:19:687] nsopen: opening transport...
[10-SEP-2014 09:23:19:687] nttcon: entry
[10-SEP-2014 09:23:19:687] nttcon: toc = 1
[10-SEP-2014 09:23:19:687] nttcnp: entry
[10-SEP-2014 09:23:19:687] nttcnp: creating a socket.
[10-SEP-2014 09:23:19:687] nttcnp: exit
[10-SEP-2014 09:23:19:687] nttcni: entry
################可以看到从248IP建立的socket 1864开始建立连接出现了报错################################
[10-SEP-2014 09:23:19:687] nttcni: trying to connect to socket 1864.
[10-SEP-2014 09:23:40:625] ntt2err: entry
[10-SEP-2014 09:23:40:625] ntt2err: soc 1864 error - operation=1, ntresnt[0]=513, ntresnt[1]=51, ntresnt[2]=0
[10-SEP-2014 09:23:40:625] ntt2err: exit
[10-SEP-2014 09:23:40:734] nttcni: exit
[10-SEP-2014 09:23:40:734] nttcon: exit
[10-SEP-2014 09:23:40:734] nserror: entry
[10-SEP-2014 09:23:40:734] nserror: nsres: id=0, op=65, ns=12543, ns2=12560; nt[0]=513, nt[1]=51, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0
[10-SEP-2014 09:23:40:734] nsopen: unable to open transport
[10-SEP-2014 09:23:40:734] nsiocancel: entry
[10-SEP-2014 09:23:40:734] nsiofrrg: entry
[10-SEP-2014 09:23:40:734] nsbfr: entry
[10-SEP-2014 09:23:40:734] nsbaddfl: entry
[10-SEP-2014 09:23:40:734] nsbaddfl: normal exit
[10-SEP-2014 09:23:40:734] nsbfr: normal exit
[10-SEP-2014 09:23:40:734] nsiofrrg: exit
[10-SEP-2014 09:23:40:734] nsiocancel: exit
[10-SEP-2014 09:23:40:734] nsopenfree_nsntx: nlhthdel from mplx_ht_nsgbu, ctx=eb5e08 nsntx=eb60f0
[10-SEP-2014 09:23:40:734] nsiocancel: entry
[10-SEP-2014 09:23:40:734] nsiofrrg: entry
[10-SEP-2014 09:23:40:734] nsiofrrg: exit
[10-SEP-2014 09:23:40:734] nsiocancel: exit
[10-SEP-2014 09:23:40:734] nsmfr: entry
[10-SEP-2014 09:23:40:734] nsmfr: 1644 bytes at 0xeb60f0
[10-SEP-2014 09:23:40:734] nsmfr: normal exit
[10-SEP-2014 09:23:40:734] nsmfr: entry
[10-SEP-2014 09:23:40:734] nsmfr: 736 bytes at 0xeb5e08
[10-SEP-2014 09:23:40:734] nsmfr: normal exit
[10-SEP-2014 09:23:40:734] nsopen: error exit
[10-SEP-2014 09:23:40:734] nsmfr: entry
[10-SEP-2014 09:23:40:734] nsmfr: 216 bytes at 0xe48690
[10-SEP-2014 09:23:40:734] nsmfr: normal exit
[10-SEP-2014 09:23:40:734] nsmfr: entry
[10-SEP-2014 09:23:40:734] nsmfr: 212 bytes at 0xe42d10
[10-SEP-2014 09:23:40:734] nsmfr: normal exit
[10-SEP-2014 09:23:40:734] nladtrm: entry
[10-SEP-2014 09:23:40:734] nladtrm: exit
[10-SEP-2014 09:23:40:734] nscall: error exit
[10-SEP-2014 09:23:40:734] nioqper: error from nscall
[10-SEP-2014 09:23:40:734] nioqper: ns main err code: 12543
[10-SEP-2014 09:23:40:734] nioqper: ns (2) err code: 12560
[10-SEP-2014 09:23:40:734] nioqper: nt main err code: 513
[10-SEP-2014 09:23:40:734] nioqper: nt (2) err code: 51
[10-SEP-2014 09:23:40:734] nioqper: nt OS err code: 0
[10-SEP-2014 09:23:40:734] niomapnserror: entry
[10-SEP-2014 09:23:40:734] niqme: entry
#####################因为无法建立连接超时导致12543报错的产生###################
[10-SEP-2014 09:23:40:734] niqme: reporting NS-12543 error as ORA-12543
[10-SEP-2014 09:23:40:734] niqme: exit
[10-SEP-2014 09:23:40:734] niomapnserror: exit
[10-SEP-2014 09:23:40:734] niotns: Couldn't connect, returning 12543
[10-SEP-2014 09:23:40:734] niotns: exit
[10-SEP-2014 09:23:40:734] nsbfrfl: entry
[10-SEP-2014 09:23:40:734] nsbrfr: entry
[10-SEP-2014 09:23:40:734] nsbrfr: nsbfs at 0xe47e10, data at 0xe47e70.
[10-SEP-2014 09:23:40:734] nsbrfr: normal exit
[10-SEP-2014 09:23:40:734] nsbrfr: entry
[10-SEP-2014 09:23:40:734] nsbrfr: nsbfs at 0xd9f570, data at 0xeb6768.
[10-SEP-2014 09:23:40:734] nsbrfr: normal exit
[10-SEP-2014 09:23:40:734] nsbrfr: entry
[10-SEP-2014 09:23:40:734] nsbrfr: nsbfs at 0xeb5d68, data at 0xe475f0.
[10-SEP-2014 09:23:40:734] nsbrfr: normal exit
[10-SEP-2014 09:23:40:734] nsbfrfl: normal exit
[10-SEP-2014 09:23:40:734] nigtrm: Count in the NI global area is now 0
[10-SEP-2014 09:23:40:734] nrigbd: entry
[10-SEP-2014 09:23:40:734] nrigbd: exit
[10-SEP-2014 09:23:40:734] nigtrm: Count in the NL global area is now 0
[10-SEP-2014 09:23:40:734] nlse_term_audit: entry
[10-SEP-2014 09:23:40:734] nlse_term_audit: exit

其实到这里问题很明确，我们知道一般来说通过监听无法正常建立连接一般情况下都是网络设置，防火墙，长连接设置等等
在11g RAC中当用户链接scan ip时，scan ip接收到用户的链接请求，此时会根据rac各节点的资源情况来决定将连接分配给哪个vip的监听，这里vip监控就是各个节点的本地监听了。我们发现由于
从10g升级到了11g 新增加了本地IP及新的VIP信息，而在网络层面并没有对这几个IP开放。