关于VIP的奇怪故障一例
OS：HP-UX 11.31 DB:Oracle 10.0.2.5 RAC （2nodes）
问题描述：节点二在服务启动后，经过1分钟至3分钟会发生VIP导致的服务切换，切换后节点二VIP在节点一上启动，检查日志主要报错为：
1 | Invalid parameters, or failed to bring up VIP (host=essrzc2) |
经过检查，系统网关配置正常，响应速度正常，系统日志无异常。开启服务debug后收获如下日志：
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 | 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: Mon Dec 16 14:57:03 EAT 2013 [ 21730 ] Checking interface existance Mon Dec 16 14:57:03 EAT 2013 [ 21730 ] Calling getifbyip Mon Dec 16 14:57:03 EAT 2013 [ 21730 ] getifbyip: started for 132.42.37.144 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: Mon Dec 16 14:57:03 EAT 2013 [ 21730 ] Completed getifbyip lan900:801 Mon Dec 16 14:57:03 EAT 2013 [ 21730 ] Completed with initial interface test Mon Dec 16 14:57:03 EAT 2013 [ 21730 ] Broadcast = 132.42.37.255 <span id="more-707"></span> 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: Mon Dec 16 14:57:03 EAT 2013 [ 21730 ] checkIf: start for if=lan900 Mon Dec 16 14:57:07 EAT 2013 [ 21730 ] checkIf: RX packets checked if=lan900 ok Mon Dec 16 14:57:07 EAT 2013 [ 21730 ] checkIf: end for if=lan900 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: Mon Dec 16 14:57:07 EAT 2013 [ 21730 ] main: interface is okay, exit success 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=/oracle/product/10.2/crs 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcexecut: cmd = /oracle/product/10.2/crs/bin/racgeut -e _USR_ORA_DEBUG=5 54 /oracle/product/10.2/crs/bin/racgvip check essrzc2 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcexecut: rc = 0, time = 4.624s 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcaction: restyp=0 act_typ=2 stat=0 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcaction: return CLSR_CAA_SUCCESS 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcaction: init 0.000s 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcaction: action ok, 4.653s 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcaction: post 0.000s 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcaction: all 4.653s 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: end for resource = ora.essrzc2.vip, action = check, status = 0, time = 4.692s 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrccln: exiting ora.essrzc2.vip refcount=1 2013-12-16 14:57:08.192: [ RACG][1] [21721][1][ora.essrzc2.vip]: clsrcprsrgter: gctx->prsrcfgref_clsrcgctx = 0 2013-12-16 14:57:38.420: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcprsrgini: gctx->prsrcfgref_clsrcgctx = 0 2013-12-16 14:57:38.420: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcini_ext: starting ora.essrzc2.vip refcount=1 global 2013-12-16 14:57:38.421: [ RACG][1] [21974][1][ora.essrzc2.vip]: begin for resource = ora.essrzc2.vip, action = check 2013-12-16 14:57:38.428: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrccssgetctx: all 0.007s 2013-12-16 14:57:38.436: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcgetprsrctx: all 0.015s 2013-12-16 14:57:38.448: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcnodeapp: prsr num_env = 0 2013-12-16 14:57:38.449: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcnodeapp: setting ORACLE_CONFIG_HOME=/oracle/product/10.2/crs 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: Unable to get IPv6 interface information. Permission denied to 127.0.0.1 cmviewcl: Cannot view the cluster configuration: Permission denied. This user doesn't have access to view the cluster configuration. 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: Mon Dec 16 14:57:38 EAT 2013 [ 21979 ] Checking interface existance Mon Dec 16 14:57:38 EAT 2013 [ 21979 ] Calling getifbyip Mon Dec 16 14:57:38 EAT 2013 [ 21979 ] getifbyip: started for 132.42.37.144 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: Mon Dec 16 14:57:38 EAT 2013 [ 21979 ] Completed getifbyip lan900:801 Mon Dec 16 14:57:38 EAT 2013 [ 21979 ] Completed with initial interface test Mon Dec 16 14:57:38 EAT 2013 [ 21979 ] Broadcast = 132.42.37.255 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: Mon Dec 16 14:57:38 EAT 2013 [ 21979 ] checkIf: start for if=lan900 Mon Dec 16 14:57:42 EAT 2013 [ 21979 ] checkIf: RX packets checked if=lan900 failed Interface lan900 checked failed (host=essrzc2) 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: Mon Dec 16 14:57:42 EAT 2013 [ 21979 ] checkIf: end for if=lan900 Mon Dec 16 14:57:42 EAT 2013 [ 21979 ] Performing CRS_STAT testing Mon Dec 16 14:57:42 EAT 2013 [ 21979 ] Completed CRS_STAT testing 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: Mon Dec 16 14:57:43 EAT 2013 [ 21979 ] Completed second gateway test Mon Dec 16 14:57:43 EAT 2013 [ 21979 ] Interface tests Mon Dec 16 14:57:43 EAT 2013 [ 21979 ] DEBUG: FAIL_WHEN_ALL_LINK_DOWN = 1 and IF_USING = lan900 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: Invalid parameters, or failed to bring up VIP (host=essrzc2) 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcexecut: env ORACLE_CONFIG_HOME=/oracle/product/10.2/crs 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcexecut: cmd = /oracle/product/10.2/crs/bin/racgeut -e _USR_ORA_DEBUG=5 54 /oracle/product/10.2/crs/bin/racgvip check essrzc2 2013-12-16 14:57:43.181: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcexecut: rc = 1, time = 4.731s 2013-12-16 14:57:43.182: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcaction: restyp=0 act_typ=2 stat=1 2013-12-16 14:57:43.182: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcaction: init 0.000s 2013-12-16 14:57:43.182: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcaction: action failed, 4.761s 2013-12-16 14:57:43.182: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcaction: post 0.000s 2013-12-16 14:57:43.182: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcaction: all 4.761s 2013-12-16 14:57:43.182: [ RACG][1] [21974][1][ora.essrzc2.vip]: end for resource = ora.essrzc2.vip, action = check, status = 1, time = 4.801s 2013-12-16 14:57:43.182: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrccln: exiting ora.essrzc2.vip refcount=1 2013-12-16 14:57:43.182: [ RACG][1] [21974][1][ora.essrzc2.vip]: clsrcprsrgter: gctx->prsrcfgref_clsrcgctx = 0 2013-12-16 14:57:43.434: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrcprsrgini: gctx->prsrcfgref_clsrcgctx = 0 2013-12-16 14:57:43.434: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrcini_ext: starting ora.essrzc2.vip refcount=1 global 2013-12-16 14:57:43.435: [ RACG][1] [22058][1][ora.essrzc2.vip]: begin for resource = ora.essrzc2.vip, action = stop 2013-12-16 14:57:43.466: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrccssgetnodename: all 0.030s 2013-12-16 14:57:43.466: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrcnodeapps: calling FAILSRVSA 2013-12-16 14:57:43.483: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrcrundetach: cmd = /oracle/product/10.2/crs/bin/racgmain ora.essrzc2.vip rundetach 1 failsrvsa essrzc2, rc = 0, time = 0.016s 2013-12-16 14:57:43.483: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrcnodeapps: Posting PNWDOWN_EVENT 2013-12-16 14:57:43.484: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrccssgetnodename: all 0.000s 2013-12-16 14:57:43.484: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrccssgetnodename: all 0.000s 2013-12-16 14:57:43.484: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrcssgetrhost: using cached local host name 2013-12-16 14:57:43.486: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrccssgetlhost: all 0.002s 2013-12-16 14:57:43.493: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrcpostevt: EvmEventPost 1 0.001s 2013-12-16 14:57:43.493: [ RACG][1] [22058][1][ora.essrzc2.vip]: clsrcposthaevt: forward to EVM |
从日志基本看出，出现问题是从“checkIf: RX packets checked if=lan900 failed”开始，从而导致资源切换，执行检测的命令为“racgvip”，此命令在完成2次“Completed second gateway test”后如果失败就进行切换，因此要解决问题，需要增加test次数，修改racgvip如下参数。
打开$CRS_HOME/bin/racgvip，修改CHECK_TIMES=2为CHECK_TIMES=10，之后不再出现异常。
评论已关闭。