运用Log和Trace文件排除Oracle Net问题

有时候已经正常安装和配置了 Oracle Net 相关组建，比如服务端的 TNS Listener，以及客户端的 tnsnames.ora，在 Oracle Server 驻留的机器上也能正常连接，但是从客户机器上出现了无法连接 Oracle 数据库服务的情况。

通常出现这种情况，一般要按照以下两个步骤来排除故障：首先，需要定位发生问题的位置或者说环节；然后，根据发生问题的位置或环节找出相应的解决办法。

由于 Oracle Net 是按照 OSI 的七层模型来设计的（它包括了会话层、表示层和应用层三个 OSI 层的功能），而底下其他层的网络功能由网络软硬件提供，因此，故障发生的环节可大体分为两种情况：一是 Oracle Net 的配置有问题，二是底层的网络出了问题。

要定位故障，首先得把故障从整体中分离出来，分成不同的环节，单独进行考虑和测试验证，逐步找出故障所在。

一般的做法是，分别排除相应情况：

1、物理连接有没有问题？验证这个的最简单办法就是看是否能够 ping 通服务主机。

2、如果第 1 步没有问题，主机和客户机之间能够 ping 通，那么就需要检测服务器上的服务是否正常，即从本地是否能够连接到数据库（本地连接 oracle 数据库时，一般不用网络协议，而用进程间通信协议），在数据库驻留的主机上，既可以利用 tnsping 工具，也可以直接使用 sqlplus 等客户端软件直接连接数据库服务。

3、如果前两步均能够正常完成，那么就要考虑网络连接是否被防火墙阻塞？在能够由于 ping 工具和 Oracle 的网络测试工具 tnsping 使用的端口不相同，因此数据库服务器上的防火墙可能允许其他机器 ping 本机，但不一定允许 Oracle Listener 的端口（默认为1521）对外提供服务（也就是外部程序试图连接到1521这个端口的尝试会被防火墙阻挡），因此，即使能 ping 通，也不一定能 tnsping 通或用 sqlplus 等应用程序连接到数据库。

对于1出现问题的情况，就需要排除物理网络连接的问题，对于2出现问题的情况，就需要考虑重新验证和配置相应的 Oracle Net 的相关配置文件，对于 3 出现的问题，就要考虑防火墙策略和Selinux（如果是 Linux 操作系统）以及其他类型的防护手段的配置问题。

但是，有时候，即使你前面3步都完成了，还是无法从客户机上连接数据库服务器，这时恐怕就得动用 log 文件和 trace 文件来查看出问题的细节了。

笔者本人就遇到过一次 redhat enterprise linux 7下面的类似情况，1、2步不用说，正常通过，问题就是进行到第三步时，防火墙也关闭了，但始终无法连接到服务器。最后只好通过分析 trace 文件来定位问题。

要使用 trace 文件来分析问题，首先要配置 SQL*Net 来启用 trace 功能，因为该功能默认情况下是停用的。

要启用 SQL*Net 的 Trace，需要在 $ORACLE_HOME/network/admin/ 下面的 sqlnet.ora 中添加如下代码：

<pre name="code" class="html">TRACE_UNIQUE_CLIENT = ON  TRACE_LEVEL_CLIENT = 16  TRACE_DIRECTORY_CLIENT = /home/u01/app/oracle/product/11.2.0/network/trace  TRACE_FILE_CLIENT = SQLNetTrace  TRACE_TIMESTAMP_CLIENT = ON  DIAG_ADR_ENABLED = OFF  #TRACE_FILELEN_CLIENT = 2048  #TRACE_FILENO_CLIENT = 2  

注意：

• TRACE_DIRECTORY_CLIENT的路径自己随意，但不要以 / 结尾
• 以上8个参数，每个参数务必顶格写，即:不要以空格开头
• 以#开头表示注释。

各个参数含义：

• TRACE_UNIQUE_CLIENT 设置是否为每个客户跟踪会话创建单独的 trace 文件，如果设置为 ON，那么 trace 文件将会设置为 SQLNetTracepid.trc（假设默认文件名为 SQLNetTrace.trc）。
• TRACE_LEVEL_CLIENT 开启客户跟踪的级别，取值为：off 或 0 表示没有 trace 信息输出，user 或 4 表示用户级跟踪信息，admin 或 10 表示管理级跟踪信息，support 或 16 表示 Oracle 支持服务级跟踪信息。
• TRACE_DIRECTORY_CLIENT 指定存放客户端 trace 文件的目录，默认为当前工作目录。需要注意的是，启动 oracle net 的用户应该对该目录有写权限。 
• TRACE_FILE_CLIENT  指定客户端会话 trace 文件的名称。
• TRACE_TIMESTAMP_CLIENT 指定客户端 trace 的事件记录中是否包含时间戳，默认为 on
• TRACE_ADR_ENABLED 是否开启 Automatic Diagnosic Repository ，默认为 on，注意：开启 ADR 的情况下，TRACE_DIRECTORY_CLIENT、TRACE_FILE_CLIENT 、TRACE_UNIQUE_CLIENT、 TRACE_FILELEN_CLIENT 和 TRACE_FILENO_CLIENT 5个参数将不起作用。这时的跟踪文件将保存在 ADR 库中，该库的位置由 ADR_BASE 参数设置，ADR_BASE 的默认值为 $ORACLE_BASE ，实际的跟踪文件将放在该目录下的 diag/client/user_USERNAME/HOSTID 下面。
• TRACE_FILELEN_CLIENT 和 TRACE_FILENO_CLIENT 控制 trace 文件大小（以KB计）和数量。

然后开始 tracing。通过 SQL*Plus 连接到相应的 tnsname，这时开始跟踪。

获得跟踪文件后，打开 trace 文件，分析内容，截取部分内容如下：

[28-1月 -2016 22:07:53:132] --- TRACE CONFIGURATION INFORMATION FOLLOWS ---        <span style="color:#ff0000;">--读取跟踪文件的配置情况</span>[28-1月 -2016 22:07:53:132] New trace stream is C:\sqltrace\sqlnettrace_2028.trc[28-1月 -2016 22:07:53:132] New trace level is 16[28-1月 -2016 22:07:53:132] --- TRACE CONFIGURATION INFORMATION ENDS ---[28-1月 -2016 22:07:53:132] --- PARAMETER SOURCE INFORMATION FOLLOWS ---[28-1月 -2016 22:07:53:132] Attempted load of system pfile source C:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\ADMIN\sqlnet.ora[28-1月 -2016 22:07:53:132] Parameter source loaded successfully[28-1月 -2016 22:07:53:132] [28-1月 -2016 22:07:53:132] Attempted load of local pfile source c:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\sqlnet.ora[28-1月 -2016 22:07:53:132] Parameter source was not loaded[28-1月 -2016 22:07:53:132] [28-1月 -2016 22:07:53:132]  -> PARAMETER TABLE LOAD RESULTS FOLLOW <-<span style="white-space:pre"></span><span style="color:#ff0000;">--显示装载的参数值</span>[28-1月 -2016 22:07:53:132] Successful parameter table load

……[28-1月 -2016 22:07:53:132] --- PARAMETER SOURCE INFORMATION ENDS ---<span style="white-space:pre"></span>[28-1月 -2016 22:07:53:132] --- LOG CONFIGURATION INFORMATION FOLLOWS ---<span style="white-space:pre"></span><span style="color:#ff0000;">--解析 SQL*NET 配置参数值，并按此连接数据库</span>……[28-1月 -2016 22:07:53:132] nrigbni: Unable to get data from navigation file tnsnav.ora<span style="white-space:pre"></span><span style="color:#ff0000;">--首先尝试 tnsnav.ora 配置文件，失败</span>[28-1月 -2016 22:07:53:132] nrigbni: exit……[28-1月 -2016 22:07:53:148] nnfgrne: Switching to TNSNAMES adapter<span style="white-space:pre"></span><span style="color:#ff0000;">-- 开始尝试 tnsnames.ora 配置文件</span>……[28-1月 -2016 22:07:53:148] nnftmlf_make_system_addrfile: system names file is C:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\ADMIN\tnsnames.ora……<span style="white-space:pre"></span><span style="color:#ff0000;">--解析 tnsnames.ora 内容</span>[28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: --- C:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\ADMIN\tnsnames.ora TABLE HAS THE FOLLOWING CONTENTS ---[28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: ORA11GR2 = (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = XY7B7F)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = ora11gr2)))[28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: ORA11G_linux = (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = 10.211.55.10)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = ora11g)))[28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: ORACLR_CONNECTION_DATA = (DESCRIPTION = (ADDRESS_LIST = (ADDRESS = (PROTOCOL = IPC)(KEY = EXTPROC1521))) (CONNECT_DATA = (SID = CLRExtProc) (PRESENTATION = RO)))[28-1月 -2016 22:07:53:148] nncpdpt_dump_ptable: --- END C:\app\xiaoxiao\product\11.2.0\dbhome_2\NETWORK\ADMIN\tnsnames.ora TABLE ---[28-1月 -2016 22:07:53:148] nnfttran: exit[28-1月 -2016 22:07:53:148] nnftrne: Using tnsnames.ora address (DESCRIPTION = (ADDRESS = (PROTOCOL = TCP)(HOST = 10.211.55.10)(PORT = 1521)) (CONNECT_DATA = (SERVER = DEDICATED) (SERVICE_NAME = ora11g))) for name ora11g_linux……[28-1月 -2016 22:07:53:148] niotns: niotns: setting up interrupt handler...[28-1月 -2016 22:07:53:148] niotns: Not trying to enable dead connection detection.[28-1月 -2016 22:07:53:148] niotns: Calling address: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=10.211.55.10)(PORT=1521))(CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=ora11g)(CID=(PROGRAM=C:\app\xiaoxiao\product\11.2.0\dbhome_2\bin\sqlplus.exe)(HOST=XY7B7F)(USER=xiaoxiao))))<span style="white-space:pre"></span><span style="color:#ff0000;">-- 确定使用从 tnsnames.ora 中 ora11g_linux 解析出来的连接串</span>[28-1月 -2016 22:07:53:148] nsgettrans_bystring: entry[28-1月 -2016 22:07:53:148] nttbnd2addr: entry[28-1月 -2016 22:07:53:148] snlinGetAddrInfo: entry[28-1月 -2016 22:07:53:148] snlinGetAddrInfo: exit[28-1月 -2016 22:07:53:148] nttbnd2addr: using host IP address: 10.211.55.10[28-1月 -2016 22:07:53:148] snlinFreeAddrInfo: entry[28-1月 -2016 22:07:53:148] snlinFreeAddrInfo: exit[28-1月 -2016 22:07:53:148] nttbnd2addr: exit[28-1月 -2016 22:07:53:148] ntgettrans: entry[28-1月 -2016 22:07:53:148] ntgettrans: exit[28-1月 -2016 22:07:53:148] nsgettrans_bystring: exit[28-1月 -2016 22:07:53:148] nscall: entry[28-1月 -2016 22:07:53:148] nsmal: entry[28-1月 -2016 22:07:53:148] nsmal: 280 bytes at 0x54fe70[28-1月 -2016 22:07:53:148] nsmal: normal exit[28-1月 -2016 22:07:53:148] nscall: connecting...[28-1月 -2016 22:07:53:148] nlad_expand_hst: Adding an ADDRESS_LIST binding<span style="white-space:pre"></span>[28-1月 -2016 22:07:53:148] nlad_expand_hst: Expanding 10.211.55.10<span style="white-space:pre"></span>[28-1月 -2016 22:07:53:148] snlinGetAddrInfo: entry[28-1月 -2016 22:07:53:148] snlinGetAddrInfo: exit[28-1月 -2016 22:07:53:148] nlad_expand_hst: Already an IP address<span style="white-space:pre"></span><span style="font-family: Arial, Helvetica, sans-serif;"><span style="color:#ff0000;">--解析连接串时发现已经是 IP 地址</span></span><span style="white-space:pre"></span>……[28-1月 -2016 22:07:53:148] nttbnd2addr: using host IP address: 10.211.55.10……[28-1月 -2016 22:07:53:148] nsopen: opening transport...<span style="white-space:pre"></span><span style="color:#ff0000;">--尝试打开传输端口</span>[28-1月 -2016 22:07:53:148] nttcon: entry[28-1月 -2016 22:07:53:148] nttcon: toc = 1[28-1月 -2016 22:07:53:148] nttcnp: entry[28-1月 -2016 22:07:53:148] nttcnp: creating a socket.<span style="white-space:pre"></span><span style="color:#ff0000;">--创建网络套接字</span>[28-1月 -2016 22:07:53:148] nttcnp: exit[28-1月 -2016 22:07:53:148] nttcni: entry[28-1月 -2016 22:07:53:148] nttcni: Tcp conn timeout = 60000 (ms)[28-1月 -2016 22:07:53:148] nttcni: TCP Connect TO enabled. Switching to NB[28-1月 -2016 22:07:53:148] nttctl: entry[28-1月 -2016 22:07:53:148] nttctl: Setting connection into non-blocking mode[28-1月 -2016 22:07:53:148] nttcni: trying to connect to socket 484.<span style="white-space:pre"></span><span style="color:#ff0000;">--开始尝试通过套接字连接</span>[28-1月 -2016 22:07:53:148] ntt2err: entry[28-1月 -2016 22:07:53:148] ntt2err: exit[28-1月 -2016 22:07:53:148] ntctst: size of NTTEST list is 1 - not calling poll[28-1月 -2016 22:07:53:148] sntseltst: Testing for WRITE on socket 484<span style="white-space:pre"></span><span style="color:#ff0000;">--尝试向套接字写数据</span>[28-1月 -2016 22:08:14:161] sntseltst: FOUND: write request on socket 484[28-1月 -2016 22:08:14:176] ntt2err: entry<span style="white-space:pre"></span>[28-1月 -2016 22:08:14:176] ntt2err: soc 484 error - operation=1, ntresnt[0]=505, ntresnt[1]=60, ntresnt[2]=0<span style="white-space:pre"></span><span style="color:#ff0000;">--发生错误</span>[28-1月 -2016 22:08:14:176] ntt2err: exit[28-1月 -2016 22:08:14:286] nttcni: exit[28-1月 -2016 22:08:14:286] nttcon: exit……[28-1月 -2016 22:08:14:286] nladtrm: exit[28-1月 -2016 22:08:14:286] nscall: error exit[28-1月 -2016 22:08:14:286] nioqper:  error from nscall<span style="white-space:pre"></span><span style="color:#ff0000;">--报告错误</span>[28-1月 -2016 22:08:14:286] nioqper:    ns main err code: 12535[28-1月 -2016 22:08:14:286] nioqper:    ns (2)  err code: 12560[28-1月 -2016 22:08:14:286] nioqper:    nt main err code: 505[28-1月 -2016 22:08:14:286] nioqper:    nt (2)  err code: 60[28-1月 -2016 22:08:14:286] nioqper:    nt OS   err code: 0[28-1月 -2016 22:08:14:286] niomapnserror: entry[28-1月 -2016 22:08:14:286] niqme: entry[28-1月 -2016 22:08:14:286] niqme: reporting NS-12535 error as ORA-12535[28-1月 -2016 22:08:14:286] niqme: exit[28-1月 -2016 22:08:14:286] niomapnserror: exit[28-1月 -2016 22:08:14:286] niotns: Couldn't connect, returning 12170[28-1月 -2016 22:08:14:286] nioqer: entry[28-1月 -2016 22:08:14:286] nioqer:  incoming err = 12170[28-1月 -2016 22:08:14:286] nioqce: entry[28-1月 -2016 22:08:14:286] nioqce: exit[28-1月 -2016 22:08:14:286] nioqer:  returning err = 3113[28-1月 -2016 22:08:14:286] nioqer: exit[28-1月 -2016 22:08:14:286] niotns: exit[28-1月 -2016 22:08:14:286] nsbfrfl: entry[28-1月 -2016 22:08:14:286] nsbrfr: entry[28-1月 -2016 22:08:14:286] nsbrfr: nsbfs at 0x6088300, data at 0x608b040.[28-1月 -2016 22:08:14:286] nsbrfr: normal exit[28-1月 -2016 22:08:14:286] nsbfrfl: normal exit[28-1月 -2016 22:08:14:286] nigtrm: Count in the NI global area is now 1[28-1月 -2016 22:08:14:286] nigtrm: Count in the NL global area is now 1

可以看出，在试图向数据库服务器的侦听地址写数据时发生错误。

这就奇怪了，明明已经 ping 通，在数据库服务器驻留的机器上也能 tnsping 通，说明网络和 LISTENER 都正常。

这时突然想起，我在尝试关闭防火墙时，使用的命令是：

[root@linuxoracle db_1]# service iptables stopRedirecting to /bin/systemctl stop  iptables.service

出现了一个提示，我当时没有在意，从字面上看，貌似是 redhat 7 将停止网络服务的命令换成了 /bin/systemctl ，并正在重定向到那个命令。

可能是我当时理解错了，这条提示是告诉我应该使用 systemctl 来关闭防火墙，而不是系统已经帮我自动重定向过去了！！！

因此，防火墙根本没有关上！！！于是按照提示使用 systemctl 关闭了防火墙。再次尝试连接，结果连接成功了！！！

如果不想看这么详细的 trace 文件，oracle 还提供了一个 trcasst 实用工具来帮助我们分析跟踪文件：

c:\sqltrace>trcasst  sqlnettrace_2028.trcTrace Assistant 实用程序: 版本 11.2.0.1.0 Production, 平台: 2016年1月28日 22:50:49版权所有 (c) 2001, 2009, Oracle。保留所有权利。    *************************************************************************    *                        Trace Assistant                                *    *************************************************************************///////////////////////////////////////////////////////////////Error found. Error Stack follows:              id:0  Operation code:65      NS Error 1:12535      NS Error 2:12560NT Generic Error:505  Protocol Error:60        OS Error:0 NS & NT Errors Translation12535, 00000 "TNS: 操作超时" // *原因: 请求的连接无法在 listener.ora 中的 CONNECT_TIMEOUT//参数所指定的超时值到来前完成。此//错误源自 tnslsnr。// *操作: 要么将 CONNECT_TIMEOUT 重新配置为 0, 这表示可以无限期等待;//要么将 CONNECT_TIMEOUT 重新配置为某个更大的值。//如果超时值超出可接受的时间范围, 请启用跟踪//来获取详细信息。/12560, 00000 "TNS: 协议适配器错误" // *原因: 出现一般协议适配器错误。// *操作: 请检查所用的地址是否符合相应的协议说明。在//报告此错误之前, 请查看错误堆栈, 检查是否有更低层的//传输错误。启用跟踪后重新执行相关操作, 以获取更多详细//资料。完成相关操作后, 禁用跟踪。/00505, 00000 "操作已超时" // *原因: 请求的操作无法//在超时到来前完成。// *操作: 启用跟踪后重新执行相关操作, 以获取更多详细资料。////////////////////////////////////////////////////////////////----------------------跟踪文件统计数据:----------------------会话总数: 0数据库:  操作计数: 打开次数    0,  语法分析次数    0,  执行次数    0,  提取次数    0ORACLE NET SERVICES:  总调用数: 已发送         0 个, 已接收         0 个,           0 oci  总字节数: 已发送         0 字节,  已接收         0 字节    平均字节数: 每包发送  字节,  每包接收  字节    最大字节数: 已发送         0 字节,  已接收         0 字节  总计包数: 已发送      0 个,  已接收      0 个    *************************************************************************    *                    Trace Assistant 已经完成                      *    *************************************************************************