使用strace诊断奇怪的sqlplus登录问题

今天刚到公司，印度同事就开始急忙找我，说客户有一个环境sqlplus连不上了。我第一反应是数据库是不是停了，连接资源满了等等，赶紧查收邮件，看到报错信息还是比较生疏的。

> sqlplus CHIDB7/xxxx@TDB1

SQL*Plus: Release 11.2.0.3.0 Production on Thu May 7 09:31:19 2015

Copyright (c) 1982, 2011, Oracle.  All rights reserved.

ERROR:

ORA-21561: OID generation failed

这个错误还是比较生疏的，看了oerr的提示，更糊涂了。
21561, 00000, "OID generation failed"
// *Cause:  The handles passed in may not be valid
// *Action: Check the validity of the env, svc handles

首先登录到客户端复现这个问题，问题还在，使用tnsping没有问题。
然后登录到数据库服务端，使用tnsping,sqlplus连接都没问题。
>tnsping uatdb1
TNS Ping Utility for Linux: Version 11.2.0.3.0 - Production on 07-MAY-2015 10:28:20
Used TNSNAMES adapter to resolve the alias
Attempting to contact (description=(address=(protocol=tcp)(host=guatdb01)(port=1521))(connect_data=(sid=TDB1)))
OK (0 msec)

查看metalink中有一篇文章 Ora-21561: OID Generation Failed (Doc ID 1335327.1)
说应该是/etc/hosts里面的配置错误。官方的解释如下：
Cause

This could be caused by not having the host name for the target database fully qualified in the hosts file.
To verify if you are hitting this issue, the following symptoms should be met:

- ORA-21561: OID generation failed.
- Hosts file has un-fully qualified entry for the target database host:

127.0.0.1 loopback localhost # loopback (lo0) name/address
10.210.9.111 dbhost

In this sample, dbhost is the target db host.

但是我的印象中/etc/hosts这种文件我们也没有权限去修改配置，都是由专门的unix team去配置的。
自己也查看了下/etc/hosts中的内容，里面有上百个配置，查看要连接的那台机器，配置如下，实在没看出有什么问题。
10.xxxxx.xxx.12           guatdb01        gpnuatndb01.xxxx.com  gpnuatndb01 

使用一个最简单的ping命令，也没有发现有什么异常。
> ping guatdb01
PING guatdb01 (10.xxxx.xxx.12) 56(84) bytes of data.
64 bytes from guatdb01 (10.xxxx.xxx.12): icmp_seq=1 ttl=63 time=0.101 ms
64 bytes from guatdb01 (10.xxxx.xxx.12): icmp_seq=2 ttl=63 time=0.095 ms

查看 tnsnames.ora的内容，没有问题。
这个问题陷入了僵局，但是客户那边催的还是蛮紧的。最后开始试试用strace来看看有什么收获吧。
使用的命令如下： strace  sqlplus CHIDB7/xxxx@TDB1
得到的内容是相当的多，看起来确实很费劲，里面会有调用的一些细节信息，打印出来的内容有1000多行，自己尝试从后往前看，看了一会就放弃了，内容实在是太多了，有些引用的链接库可能不是必须的，如果报错，自己就得再上面琢磨一下，逐个排除。
试了一会就放弃了，为了更加高效，自己在另外一个客户端中使用sqlplus可以正常连接，也做了一个strace的报告，第二个报告在900多行，使用文本比较工具来看就能看出很多端倪了。
看到一半的时候发现了一个关键的地方，就是网络相关的错误。


在有问题的客户端中，内容如下：
socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = -1 EAFNOSUPPORT (Address family not supported by protocol)
access("/etc/sqlnet.ora", F_OK)         = -1 ENOENT (No such file or directory)
access("/oravl01/oracle/11.2.0.3/network/admin/sqlnet.ora", F_OK) = 0

在一切正常的客户端中，内容如下：
socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = 6
bind(6, {sa_family=AF_INET6, sin6_port=htons(0), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 28) = 0
close(6)

有了这些信息，也算是有了进展，我记得metalink的文章( Doc ID 1335327.1)提到的文件配置问题，在查看了一些帖子之后，有的朋友碰到的主机名问题是在/etc/sysconfig/network中。
带着试试看的态度对比了一下，发现还真是有一处不一样。
有问题的客户端中network明显是在昨晚修改过。

> ll network

-rw-r--r-- 1 root root 91 May  6 23:09 network

> cat network

NETWORKING=yes

HOSTNAME=gpnchianap01

NETWORKING_IPV6=no

NOZEROCONF=yes

GATEWAY=10.235.60.1

但是在其它客户端中的内容如下：
> cat /etc/sysconfig/network

NETWORKING=yes

NETWORKING_IPV6=no

HOSTNAME=gpnuatndb01

GATEWAY=10.235.103.1

一个明显的不同就是多了 NOZEROCONF=yes
带着这个疑问去咨询unix 组的人，得到的反馈那个配置和sqlplus的问题应该没有关系。
不过带着这个问题的进展，他们也去做了分析，最后他们发现是host的配置问题。
这个结果让我有些意外，向他们讨教，才算明白问题的症结。
修改前
.
# grep gpnchiaapp01 /etc/hosts 
10.235.60.7             gchiaap01       gpnchianap01.globetel.com       gpnchianap01
.
修改后，追加了一个主机配置，他们发现真正的主机名没有加入到/etc/hosts里面，原有的 gpnchianap01  是一个主机别名
.
10.235.60.7             gchiaap01       gpnchianap01.globetel.com       gpnchianap01   gpnchiaapp01

好了，问题的原因不是出在要连接的数据库服务器在/etc/hosts中的配置，而是当前主机名的配置问题。
可是这种问题怎么会发生呢，既然已经运行很久了，很多测试环境都在用。得到的反馈是昨晚对这台服务器升级了kernel，这个配置应该是人为配错导致的。
这个案例带给我的其实就是strace在手足无措的时候还是能够定位到一些问题，但是不要过分去依赖，如果在知道了问题的缘由之后再去看相关的日志就能发现一些端倪了。但是在这个案例中自己也没有足够的理性去全面思考，两个network文件的配置不同不一定是最终的问题症结，所以在这个问题的排查上自己也迷失了方向。
最后的问题原因还是主机名的配置，不过这个主机名配置不是要连接的数据库服务器配置，竟然是本地的主机名问题导致的。如果明白了问题的大环境，很多问题的解释就行得通了。看来这些问题背景的掌握也是很重要的，有些时候问题发生的时候还是需要多问几句，可以避免很多挤牙膏似的被动。
最后来做一次事后诸葛亮，看看在有问题的strace日志中报错前的几行日志。似乎问题一下子明朗起来，日志中已经去查找主机名 gpnchiaapp01了 ，当时去/etc/hosts中确实是没有的。
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 8
connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(8, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(8, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
sendto(8, "\220\305\1\0\0\1\0\0\0\0\0\0\f gpnchiaapp01\0\0\1\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30
poll([{fd=8, events=POLLIN}], 1, 5000)  = 1 ([{fd=8, revents=POLLERR}])
close(8)                                = 0
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 8
connect(8, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("0.0.0.0")}, 28) = 0
fcntl(8, F_GETFL)                       = 0x2 (flags O_RDWR)
fcntl(8, F_SETFL, O_RDWR|O_NONBLOCK)    = 0
poll([{fd=8, events=POLLOUT}], 1, 0)    = 1 ([{fd=8, revents=POLLOUT}])
sendto(8, "\220\305\1\0\0\1\0\0\0\0\0\0\f gpnchiaapp01\0\0\1\0\1", 30, MSG_NOSIGNAL, NULL, 0) = 30
poll([{fd=8, events=POLLIN}], 1, 5000)  = 1 ([{fd=8, revents=POLLERR}])
close(8)                                = 0
open("/oravl01/oracle/11.2.0.3/rdbms/mesg/oraus.msb", O_RDONLY) = 8

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/23718752/viewspace-1627787/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/23718752/viewspace-1627787/