AIX平台Rac Listener offline问题分析

 

接到电话时候是下午4点多，长沙的天气有点闷热，外面正准备下雷雨。客户来电咨询集群2个节点的listener自动offline，问我大概的会是什么原因造成的，现场有个其他公司的Oracle工程师回复可能是Oracle bug导致，用户觉得不靠谱直接联系我了。从用户的反馈的信息来看，不能直接说明就是bug导致，但是第一反应就是vip offline 裙带关系把listener也带下去了，Listener与vip 这一对基友出的问题还少？但是也不排除其他的bug因为listener auto offline的bug虽然不是很多，但是也不是1只手数的过来的，从用户手上获取相关的log后着手进行分析。

分析思路：

一般碰到这类问题，首先要获取查看的日志就是
1.数据库告警日志（2个实例）
2.RAC的告警日志（其实这个不是很重要）
3.CRSD日志
4.RACG相关日志（VIP,ONS）
5.系统日志

因为是2个节点之间的都发生了listener offline，首先检测了2个节点的告警日志，只发现了现场工程师重启集群的log记录如下：
节点1

Wed Aug  6 10:59:19 2014
Thread 1 advanced to log sequence 227 (LGWR switch)
  Current log# 13 seq# 227 mem# 0: +DATA/orcl/onlinelog/redo13.log
Wed Aug  6 13:58:02 2014
Thread 1 advanced to log sequence 228 (LGWR switch)
  Current log# 18 seq# 228 mem# 0: +DATA/orcl/onlinelog/redo10.log
Wed Aug  6 14:47:15 2014
Shutting down instance: further logons disabled
Wed Aug  6 14:47:15 2014
Stopping background process CJQ0
Wed Aug  6 14:47:15 2014

节点2

Wed Aug 6 08:17:37 2014
Thread 2 advanced to log sequence 205 (LGWR switch)
Current log# 14 seq# 205 mem# 0: +DATA/orcl/onlinelog/redo14.log
Wed Aug 6 11:00:24 2014
Thread 2 advanced to log sequence 206 (LGWR switch)
Current log# 15 seq# 206 mem# 0: +DATA/orcl/onlinelog/redo15.log
Wed Aug 6 14:48:12 2014
Reconfiguration started (old inc 12, new inc 14)
List of nodes:
1
Global Resource Directory frozen
* dead instance detected - domain 0 invalid = TRUE
Communication channels reestablished
Master broadcasted resource hash value bitmaps
Non-local Process blocks cleaned out
Wed Aug 6 14:48:13 2014
LMS 0: 0 GCS shadows cancelled, 0 closed
Wed Aug 6 14:48:13 2014
LMS 1: 0 GCS shadows cancelled, 0 closed
Wed Aug 6 14:48:13 2014
LMS 3: 0 GCS shadows cancelled, 0 closed
Wed Aug 6 14:48:13 2014
LMS 2: 0 GCS shadows cancelled, 0 closed
...

告警日志并未给我们有用的信息，下来按老习惯直接分析CRSD日志了，具体的日志信息以及分析如下：

1.节点一日志分析

2014-08-06 14:13:57.778: [  CRSAPP][11095]32CheckResource error for ora.his-ora1.vip error code = 1
==>可以发现在14点13分57秒vip服务异常
2014-08-06 14:13:57.818: [  CRSRES][11095]32In stateChanged, ora.his-ora1.vip target is ONLINE
2014-08-06 14:13:57.819: [  CRSRES][11095]32ora.his-ora1.vip on his-ora1 went OFFLINE unexpectedly
==>集群将vip服务状态标记为offline
2014-08-06 14:13:57.820: [  CRSRES][11095]32StopResource: setting CLI values
2014-08-06 14:13:57.825: [  CRSRES][11095]32Attempting to stop `ora.his-ora1.vip` on member `his-ora1`
2014-08-06 14:13:58.418: [  CRSRES][11095]32Stop of `ora.his-ora1.vip` on member `his-ora1` succeeded.
==>集群停止ora1的vip服务
2014-08-06 14:13:58.419: [  CRSRES][11095]32ora.his-ora1.vip RESTART_COUNT=0 RESTART_ATTEMPTS=0
2014-08-06 14:13:58.423: [  CRSRES][11095]32ora.his-ora1.vip failed on his-ora1 relocating.
==>ora1.vip漂移失败
2014-08-06 14:13:58.520: [  CRSRES][11095]32StopResource: setting CLI values
2014-08-06 14:13:58.525: [  CRSRES][11095]32Attempting to stop `ora.his-ora1.LISTENER_HIS-ORA1.lsnr` on member `his-ora1`
==>由于裙带关系crs把listener资源也关闭了
2014-08-06 14:15:15.951: [  CRSRES][11095]32Stop of `ora.his-ora1.LISTENER_HIS-ORA1.lsnr` on member `his-ora1` succeeded.
==>同上
2014-08-06 14:15:16.022: [  CRSRES][11095]32Attempting to start `ora.his-ora1.vip` on member `his-ora2`
2014-08-06 14:15:17.882: [  CRSRES][11095]32Start of `ora.his-ora1.vip` on member `his-ora2` succeeded.
2014-08-06 14:15:24.997: [  CRSRES][11185]32startRunnable: setting CLI values

2.节点二日志分析

2014-07-14 17:35:59.469: [  CRSRES][11648]32Start of `ora.orcl.orcl2.inst` on member `his-ora2` succeeded.
2014-08-06 14:14:06.866: [  CRSAPP][11469]32CheckResource error for ora.his-ora2.vip error code = 1
==>同样可以发现在14点14分06秒vip服务异常，和节点1前后相差9秒
2014-08-06 14:14:06.879: [  CRSRES][11469]32In stateChanged, ora.his-ora2.vip target is ONLINE
2014-08-06 14:14:06.881: [  CRSRES][11469]32ora.his-ora2.vip on his-ora2 went OFFLINE unexpectedly
==>集群将ora2.vip服务状态标记为offline
2014-08-06 14:14:06.881: [  CRSRES][11469]32StopResource: setting CLI values
2014-08-06 14:14:06.886: [  CRSRES][11469]32Attempting to stop `ora.his-ora2.vip` on member `his-ora2`
2014-08-06 14:14:07.473: [  CRSRES][11469]32Stop of `ora.his-ora2.vip` on member `his-ora2` succeeded.
==>集群停止ora2.vip服务
2014-08-06 14:14:07.474: [  CRSRES][11469]32ora.his-ora2.vip RESTART_COUNT=0 RESTART_ATTEMPTS=0
2014-08-06 14:14:07.479: [  CRSRES][11469]32ora.his-ora2.vip failed on his-ora2 relocating.
==>ora2.vip漂移失败
2014-08-06 14:14:07.524: [  CRSRES][11469]32StopResource: setting CLI values
2014-08-06 14:14:07.528: [  CRSRES][11469]32Attempting to stop `ora.his-ora2.LISTENER_HIS-ORA2.lsnr` on member `his-ora2`
2014-08-06 14:15:16.008: [  CRSRES][11548]32startRunnable: setting CLI values
2014-08-06 14:15:24.982: [  CRSRES][11469]32Stop of `ora.his-ora2.LISTENER_HIS-ORA2.lsnr` on member `his-ora2` succeeded.
==>由于裙带关系crs把listener资源也关闭了
2014-08-06 14:15:25.013: [  CRSRES][11469]32Attempting to start `ora.his-ora2.vip` on member `his-ora1`
2014-08-06 14:15:27.911: [  CRSRES][11469]32Start of `ora.his-ora2.vip` on member `his-ora1` succeeded.

从以上的CRSD日志可以发现，故障的发生确实是因为VIP的异常offline导致listener也被offline导致；故障的发生时间点为14：13分后，两个节点前后vip服务出现异常，导致offline的产生，并且并未restart，vip在漂移失败后crs将LISTENER进程offline。由此可以判断出监听资源offline的根源为vip的原因导致，这与我在客户通电话时候获取的信息得出判断是一致的。

那么现在的问题就比较明显了，原因是vip异常offline导致，那么vip offline的根源是什么？而且是2个vip几乎同时都offline了，一般vip的offline的原因，我个人是个归纳如下：

1.不少bug会导致vip offline
2.网络波动导致ping timeout超时
3.网络故障，比如交换机或者网路，网卡问题
4.网关设错等

但是这里集群的日志信息已经没有其他的信息可以告诉我们其他有助于我们定位vip offline的根源了，下来从系统层面判断是否存在异常信息的告警，这里是AIX所有采用errpt -a的方式查找最新的报错，2个主机最新的错误信息都是2014年7月3号，离现在太久了，而且这期间并未发生类似的故障，基本初步排除系统方面的问题。那到底是不是网络的问题？还是bug的问题？
这个时候一方面可以对VIP服务采用crsctl debug log resource ora.his-ora2.vip:1的方式在两个节点上开启trace跟踪，然后对trace的日志进行分析，另一方面通过加大ping time out时间的方式来避免偶尔的网络波动导致的vip 资源进程offline的情况，这2方面的执行命令如下：

1.debug vip 进程

To increase the trace level, issue
crsctl debug log resource :1

To turn off this tracing use:
crsctl debug log res :0

2.延长vip检测time out时间

修改racgvip文件，将PING_TIMEOUT=" -c 1 -w 1"改为PING_TIMEOUT=" -c 1 -w 3"

日志方面已经没有可以给我们有帮助的信息了，此时电话用户告知目前的诊断情况并建议对网络方面进行排查，检测整体rac相关网络的波动异常情况，其次对当前的vip进程进行trace根据trace文件进行分析以及增加time out时间。庆幸的是正在准备做trace的时候，用户来电反应下午14：13分与rac相关的交换机发生failover，整个过程持续了一段时间，由此可以判断在此过程由于无法ping通导致vip offine，进而出现客户反应的现象。但是我还是不放心，给vip进程做了trace，等些时间再关掉再关掉检测trace。

在后续的检测中我也发现一个问题，那就是节点的priv网关和pub网关是一样的，在rac环境中我是不建议这种设置的，如下2图：