节点失败,VIP不能切换分析

最新推荐文章于 2021-09-26 11:38:42 发布

iteye_4537

最新推荐文章于 2021-09-26 11:38:42 发布

阅读量2.5k

点赞数

文章标签：数据库网络 ui

高可用对于核心的数据库是一个保障，我们的核心库中，每个月都要进行高可用演练，在这次演练的时候RAC的VIP切换出现了点怪异的问题，目前还没有找到可以信服的原因。
下面看下这个切换过程的不正常：
我先大致描述下这个演练的过程:1,node1 reboot -q>check the node1-vip's failover 2,node2 reboot -q>check the node2-vip's failover
当我们reboot -q node1的时候node1-vip很快切换到node2，但是当我们reboot -q node2的时候node2的node2-vip足足花了将近8分钟时间，直到node2 reboot完成后
node2-vip才在node1上startup sucessfully。
note：the time for reboot -q on node2 is 00:00左右,我们使用VCS，所以timecount是600s。
node1's crsd.log:

2012-06-21 00:04:49.873: [  OCRMSG][11227]prom_rpc: CLSC recv failure..ret code 7
2012-06-21 00:04:49.873: [  OCRMSG][11227]prom_rpc: possible OCR retry scenario
2012-06-21 00:04:49.873: [ COMMCRS][11740]clscsendx: (113900410) Physical connection (1138ffb90) not active
2012-06-21 00:04:49.873: [  OCRMSG][11740]prom_rpc: CLSC send failure..ret code 11
2012-06-21 00:04:49.873: [  OCRMSG][11740]prom_rpc: possible OCR retry scenario
2012-06-21 00:04:49.874: [ COMMCRS][12255]clscsendx: (113900410) Connection not active
2012-06-21 00:04:49.874: [  OCRMSG][12255]prom_rpc: CLSC send failure..ret code 6
2012-06-21 00:04:49.874: [  OCRMSG][12255]prom_rpc: possible OCR retry scenario
2012-06-21 00:04:49.874: [ COMMCRS][12514]clscsendx: (113900410) Connection not active
2012-06-21 00:04:49.874: [  OCRMSG][12514]prom_rpc: CLSC send failure..ret code 6
2012-06-21 00:04:49.874: [  OCRMSG][12514]prom_rpc: possible OCR retry scenario
2012-06-21 00:07:31.242: [ CRSCOMM][12777]32CLEANUP: Searching for connections to failed node node2
2012-06-21 00:07:31.242: [  CRSEVT][12777]32Processing member leave for node2, incarnation: 4
2012-06-21 00:07:31.243: [    CRSD][12777]32SM: recovery in process: 8
2012-06-21 00:07:31.243: [  CRSEVT][12777]32Do failover for: node2
2012-06-21 00:07:31.247: [ COMMCRS][12777]clscsendx: (113900410) Connection not active
2012-06-21 00:07:31.247: [  OCRMSG][12777]prom_rpc: CLSC send failure..ret code 6
2012-06-21 00:07:31.247: [  OCRMSG][12777]prom_rpc: possible OCR retry scenario
2012-06-21 00:07:31.320: [  OCRMAS][3366]th_master:13: I AM THE NEW OCR MASTER at incar 4. Node Number 1
2012-06-21 00:07:31.322: [  OCRRAW][3366]proprioo: for disk 0 (/crsdata/ocr1), id match (1), my id set (725219174,2133226085) total id sets (1), 1st set (725219174,2133226085), 2nd set (0,0) my votes (1), total votes (2)
2012-06-21 00:07:31.322: [  OCRRAW][3366]proprioo: for disk 1 (/crsdata/ocr2), id match (1), my id set (725219174,2133226085) total id sets (1), 1st set (725219174,2133226085), 2nd set (0,0) my votes (1), total votes (2)
2012-06-21 00:07:31.324: [  OCRMAS][3366]th_master: Deleted ver keys from cache (master)
2012-06-21 00:07:31.713: [  CRSRES][12777]32 startup = 0
2012-06-21 00:07:31.720: [  CRSRES][12777]32 startup = 0
2012-06-21 00:07:31.726: [  CRSRES][12777]32 startup = 0
2012-06-21 00:07:31.732: [  CRSRES][12777]32 startup = 0
2012-06-21 00:07:31.737: [  CRSRES][12777]32 startup = 0
2012-06-21 00:07:31.743: [  CRSRES][12777]32 startup = 0
2012-06-21 00:07:31.749: [  CRSRES][12777]32 startup = 0
2012-06-21 00:07:31.829: [  CRSRES][13293]32startRunnable: setting CLI values
2012-06-21 00:07:31.918: [  CRSRES][13550]32startRunnable: setting CLI values
2012-06-21 00:07:31.955: [  CRSRES][13293]32Attempting to start `ora.node2.vip` on member `node1`
2012-06-21 00:07:31.955: [  CRSRES][13550]32Attempting to start `ora.node1.gsd` on member `node1`
2012-06-21 00:07:32.045: [  CRSRES][13807]32startRunnable: setting CLI values
2012-06-21 00:07:32.071: [  CRSRES][13807]32Attempting to start `ora.rac.db` on member `node1`>>注意这里的时间和vip启动

node1的alert：

2012-06-21 00:07:31.229
[cssd(589846)]CRS-1601:CSSD Reconfiguration complete. Active nodes are node1 .
2012-06-21 00:07:31.323
[crsd(405814)]CRS-1005:The OCR upgrade was completed. Version has changed from 169870080 to 169870080. Details in /u01/oracle/app/oracle/product/10.2.0/crs/log/node1/crsd/crsd.log.
2012-06-21 00:07:32.318
[cssd(589846)]CRS-1601:CSSD Reconfiguration complete. Active nodes are node1 node2 .

从以上alert可以看到在00:07:32，reconfiguration完成了,两个active nodes。
再来看看node1 ocssd.log:

[    CSSD]2012-06-21 00:00:36.287 [1029] >TRACE:   clssnm_skgxncheck: CSS daemon failed on node 2>>>>这个时间我们reboot -q on node2
[    CSSD]2012-06-21 00:04:43.355 [3085] >WARNING: clssnmeventhndlr: Receive failure with node 2 (node2), state 3, con(111aa2c70), probe(0), rc=11
[    CSSD]2012-06-21 00:04:43.355 [3085] >TRACE:   clssnmDiscHelper: node2, node(2) connection failed, con (111aa2c70), probe(0)
[    CSSD]2012-06-21 00:04:57.225 [4370] >WARNING: clssnmPollingThread: node node2 (2) at 50% heartbeat fatal, eviction in 299.398 seconds>>>>我们使用VCS，默认的misscount是600s，所以这里
大概过了300s,节点node2还没有被eviction。
[    CSSD]2012-06-21 00:07:20.343 [1029] >TRACE:   clssnm_skgxncheck: completing eviction for bounced node 2
[    CSSD]2012-06-21 00:07:20.343 [1029] >TRACE:   clssnmDiscHelper: node2, node(2) connection failed, con (0), probe(0)
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmDoSyncUpdate: Initiating sync 4
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmDoSyncUpdate: diskTimeout set to (597000)ms
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmSetupAckWait: Ack message type (11) 
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmSetupAckWait: node(1) is ALIVE
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmSendSync: syncSeqNo(4)
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmWaitForAcks: Ack message type(11), ackCount(1)
[    CSSD]2012-06-21 00:07:21.189 [3085] >TRACE:   clssnmHandleSync: diskTimeout set to (597000)ms
[    CSSD]2012-06-21 00:07:21.189 [3085] >TRACE:   clssnmHandleSync: Acknowledging sync: src[1] srcName[node1] seq[1] sync[4]
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmWaitForAcks: done, msg type(11)
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmDoSyncUpdate: Terminating node 2, node2, misstime(444564) state(5)
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmSetupAckWait: Ack message type (13) 
[    CSSD]2012-06-21 00:07:21.189 [1] >USER:    NMEVENT_SUSPEND [00][00][00][06]
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmSetupAckWait: node(1) is ACTIVE
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmSendVote: syncSeqNo(4)
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmWaitForAcks: Ack message type(13), ackCount(1)
[    CSSD]2012-06-21 00:07:21.189 [3085] >TRACE:   clssnmSendVoteInfo: node(1) syncSeqNo(4)
[    CSSD]2012-06-21 00:07:21.189 [4884] >TRACE:   clssnmWaitForAcks: done, msg type(13)
[    CSSD]2012-06-21 00:07:21.190 [4884] >TRACE:   clssnmCheckDskInfo: Checking disk info...
[    CSSD]2012-06-21 00:07:21.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(443932) state_network(5) state_disk(3) misstime(444564)
[    CSSD]2012-06-21 00:07:22.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(444932) state_network(5) state_disk(3) misstime(445566)
[    CSSD]2012-06-21 00:07:23.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(445932) state_network(5) state_disk(3) misstime(446568)
[    CSSD]2012-06-21 00:07:24.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(446932) state_network(5) state_disk(3) misstime(447569)
[    CSSD]2012-06-21 00:07:25.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(447932) state_network(5) state_disk(3) misstime(448569)
[    CSSD]2012-06-21 00:07:26.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(448932) state_network(5) state_disk(3) misstime(449571)
[    CSSD]2012-06-21 00:07:27.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(449932) state_network(5) state_disk(3) misstime(450572)
[    CSSD]2012-06-21 00:07:28.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(450932) state_network(5) state_disk(3) misstime(451572)
[    CSSD]2012-06-21 00:07:29.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(451932) state_network(5) state_disk(3) misstime(452575)
[    CSSD]2012-06-21 00:07:30.226 [4884] >TRACE:   clssnmCheckDskInfo: node(2) timeout(452932) state_network(5) state_disk(3) misstime(453575)
[    CSSD]2012-06-21 00:07:30.639 [1543] >TRACE:   clssnmReadDskHeartbeat: node(2) is down. rcfg(1) wrtcnt(1) LATS(775519945) Disk lastSeqNo(1)
[    CSSD]2012-06-21 00:07:30.666 [1286] >TRACE:   clssnmReadDskHeartbeat: node(2) is down. rcfg(1) wrtcnt(2) LATS(775519972) Disk lastSeqNo(2)
[    CSSD]2012-06-21 00:07:30.715 [1800] >TRACE:   clssnmReadDskHeartbeat: node(2) is down. rcfg(1) wrtcnt(3) LATS(775520021) Disk lastSeqNo(3)
[    CSSD]2012-06-21 00:07:31.226 [4884] >TRACE:   clssnmCheckDskInfo: node 2, node2, state 5 with leader 2 has smaller cluster size 0; my cluster size 1 with leader 1
[    CSSD]2012-06-21 00:07:31.226 [4884] >TRACE:   clssnmEvict: Start
[    CSSD]2012-06-21 00:07:31.226 [4884] >TRACE:   clssnmWaitOnEvictions: Start
[    CSSD]2012-06-21 00:07:31.226 [4884] >TRACE:   clssnmWaitOnEvictions: Node(0) down, LATS(0),timeout(775520533)
[    CSSD]2012-06-21 00:07:31.226 [4884] >TRACE:   clssnmSetupAckWait: Ack message type (15) 
[    CSSD]2012-06-21 00:07:31.226 [4884] >TRACE:   clssnmSetupAckWait: node(1) is ACTIVE
[    CSSD]2012-06-21 00:07:31.226 [4884] >TRACE:   clssnmSendUpdate: syncSeqNo(4)
[    CSSD]2012-06-21 00:07:31.227 [4884] >TRACE:   clssnmWaitForAcks: Ack message type(15), ackCount(1)
[    CSSD]2012-06-21 00:07:31.227 [3085] >TRACE:   clssnmUpdateNodeState: node 0, state (0/0) unique (0/0) prevConuni(0) birth (0/0) (old/new)
[    CSSD]2012-06-21 00:07:31.227 [3085] >TRACE:   clssnmUpdateNodeState: node 1, state (3/3) unique (1340205072/1340205072) prevConuni(0) birth (3/3) (old/new)
[    CSSD]2012-06-21 00:07:31.227 [3085] >TRACE:   clssnmUpdateNodeState: node 2, state (0/0) unique (1339991520/1339991520) prevConuni(1339991520) birth (1/0) (old/new)
[    CSSD]2012-06-21 00:07:31.227 [3085] >USER:    clssnmHandleUpdate: SYNC(4) from node(1) completed
[    CSSD]2012-06-21 00:07:31.227 [3085] >USER:    clssnmHandleUpdate: NODE 1 (node1) IS ACTIVE MEMBER OF CLUSTER
[    CSSD]2012-06-21 00:07:31.227 [3085] >TRACE:   clssnmHandleUpdate: diskTimeout set to (597000)ms
[    CSSD]2012-06-21 00:07:31.227 [4884] >TRACE:   clssnmWaitForAcks: done, msg type(15)
[    CSSD]2012-06-21 00:07:31.227 [4884] >TRACE:   clssnmDoSyncUpdate: Sync Complete!
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmReconfigThread:  started for reconfig (4)
[    CSSD]2012-06-21 00:07:31.227 [5142] >USER:    NMEVENT_RECONFIG [00][00][00][02]
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_node1 type 3
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock _ORA_CRS_MEMBER_node2 type 3
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(0) grock(_ORA_CRS_MEMBER_node2) birth(1/1)
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock crs_version type 2
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(crs_version) birth(1/1)
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock ORA_CLSRD_1_rac type 2
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock ORA_CLSRD_1_rac type 3
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock ORA_CLSRD_2_rac type 3
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(0) grock(ORA_CLSRD_2_rac) birth(1/1)
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock ORA_CLSRD_2_rac type 2
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(0) grock(ORA_CLSRD_2_rac) birth(1/1)
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock DBrac type 2
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(DBrac) birth(1/1)
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock DGrac type 2
[    CSSD]2012-06-21 00:07:31.227 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(DGrac) birth(1/1)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock DAALL_DB type 2
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(1) grock(DAALL_DB) birth(1/1)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock CRSDMAIN type 2
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(2) grock(CRSDMAIN) birth(1/1)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock EVMDMAIN type 2
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(2) grock(EVMDMAIN) birth(1/1)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock IGracALL type 2
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(2) grock(IGracALL) birth(1/1)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock ocr_crs type 2
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(2) grock(ocr_crs) birth(1/1)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock IGracrac1 type 2
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock IGracrac2 type 2
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(2) grock(IGracrac2) birth(1/1)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupGrocks: cleaning up grock #CSS_CLSSOMON type 2
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmCleanupOrphanMembers: cleaning up remote mbr(2) grock(#CSS_CLSSOMON) birth(1/1)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmEstablishConnections: 1 nodes in cluster incarn 4
[    CSSD]2012-06-21 00:07:31.228 [4113] >TRACE:   clssgmPeerDeactivate: node 2 (node2), death 4, state 0x80000000 connstate 0xf
[    CSSD]2012-06-21 00:07:31.228 [4113] >TRACE:   clssgmPeerListener: connects done (1/1)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmEstablishMasterNode: MASTER for 4 is node(1) birth(3)
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmChangeMasterNode: requeued 0 RPCs
[    CSSD]2012-06-21 00:07:31.228 [5142] >TRACE:   clssgmMasterCMSync: Synchronizing group/lock status
[    CSSD]2012-06-21 00:07:31.229 [5142] >TRACE:   clssgmMasterSendDBDone: group/lock status synchronization complete
[    CSSD]CLSS-3000: reconfiguration successful, incarnation 4 with 1 nodes
[    CSSD]CLSS-3001: local node number 1, master node number 1
[    CSSD]2012-06-21 00:07:31.229 [5142] >TRACE:   clssgmReconfigThread:  completed for reconfig(4), with status(1)
[    CSSD]2012-06-21 00:07:31.818 [3085] >TRACE:   clssnmConnComplete: MSGSRC 2, type 5, node 2, flags 0x0001, con 112c2e470, probe 0
[    CSSD]2012-06-21 00:07:31.818 [3085] >TRACE:   clssnmConnComplete: connecting to node 2 con(112c2e470), msg state 1, birth 0, probcon(0), ninfcon(0), prevConuni(0), node state 0
[    CSSD]2012-06-21 00:07:31.818 [3085] >TRACE:   clssnmsendConnAck: node 2, node state 0
[    CSSD]2012-06-21 00:07:31.818 [3085] >TRACE:   clssnmSendConnAck: connected to node 2 , ninfcon (112c2e470), state (0)
[    CSSD]2012-06-21 00:07:31.818 [3085] >TRACE:   clssnmConnComplete: connecting to node 2 (con 112c2e470), ninfcon (112c2e470), state (0)
[    CSSD]2012-06-21 00:07:32.203 [4884] >TRACE:   clssnmDoSyncUpdate: Initiating sync 5
[    CSSD]2012-06-21 00:07:32.203 [4884] >TRACE:   clssnmDoSyncUpdate: diskTimeout set to (597000)ms
[    CSSD]2012-06-21 00:07:32.203 [4884] >TRACE:   clssnmSetupAckWait: Ack message type (11) 
[    CSSD]2012-06-21 00:07:32.203 [4884] >TRACE:   clssnmSetupAckWait: node(1) is ALIVE
[    CSSD]2012-06-21 00:07:32.203 [4884] >TRACE:   clssnmSetupAckWait: node(2) is ALIVE
[    CSSD]2012-06-21 00:07:32.203 [4884] >TRACE:   clssnmSendSync: syncSeqNo(5)
[    CSSD]2012-06-21 00:07:32.203 [3085] >TRACE:   clssnmHandleSync: diskTimeout set to (597000)ms
[    CSSD]2012-06-21 00:07:32.203 [4884] >TRACE:   clssnmWaitForAcks: Ack message type(11), ackCount(2)
[    CSSD]2012-06-21 00:07:32.203 [3085] >TRACE:   clssnmHandleSync: Acknowledging sync: src[1] srcName[node1] seq[5] sync[5]
[    CSSD]2012-06-21 00:07:32.203 [1] >USER:    NMEVENT_SUSPEND [00][00][00][02]
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmWaitForAcks: done, msg type(11)
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmDoSyncUpdate: node(2) is transitioning from joining state to active state
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmSetupAckWait: Ack message type (13) 
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmSetupAckWait: node(1) is ACTIVE
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmSetupAckWait: node(2) is ACTIVE
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmSendVote: syncSeqNo(5)
[    CSSD]2012-06-21 00:07:32.204 [3085] >TRACE:   clssnmSendVoteInfo: node(1) syncSeqNo(5)
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmWaitForAcks: Ack message type(13), ackCount(2)
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmWaitForAcks: done, msg type(13)
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmCheckDskInfo: Checking disk info...
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmEvict: Start
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmWaitOnEvictions: Start
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmWaitOnEvictions: Node(0) down, LATS(0),timeout(775521510)
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmSetupAckWait: Ack message type (15) 
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmSetupAckWait: node(1) is ACTIVE
[    CSSD]2012-06-21 00:07:32.204 [4884] >TRACE:   clssnmSetupAckWait: node(2) is ACTIVE

从以上可以看出当node2 reoot -q的时候并没有立即对node2做 [ CRSEVT]Do failover for: node2，而是当node2已经起来的时候足足过了7分多钟以后，node2-vip才切换成功。
node2 crsd.log:

2012-06-21 00:07:17.032: [ default][1][ENTER]32
Oracle Database 10g CRS Release 10.2.0.3.0 Production Copyright 1996, 2004, Oracle.  All rights reserved
2012-06-21 00:07:17.038: [ default][1]32CRS Daemon Starting
2012-06-21 00:07:17.039: [ CRSMAIN][1]32Checking the OCR device
2012-06-21 00:07:17.042: [ CRSMAIN][1]32Connecting to the CSS Daemon
2012-06-21 00:07:17.383: [ COMMCRS][259]clsc_connect: (1109a9e90) no listener at (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_node2_crs))
2012-06-21 00:07:17.383: [ CSSCLNT][1]clsssInitNative: connect failed, rc 9
2012-06-21 00:07:17.384: [  CRSRTI][1]32CSS is not ready. Received status 3 from CSS. Waiting for good status .. 
2012-06-21 00:07:18.717: [ COMMCRS][261]clsc_connect: (1109a9e90) no listener at (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_node2_crs))
2012-06-21 00:07:18.717: [ CSSCLNT][1]clsssInitNative: connect failed, rc 9
2012-06-21 00:07:18.717: [  CRSRTI][1]32CSS is not ready. Received status 3 from CSS. Waiting for good status .. 
2012-06-21 00:07:20.047: [ COMMCRS][263]clsc_connect: (1109a9e90) no listener at (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_node2_crs))
……
2012-06-21 00:07:29.361: [  CRSRTI][1]32CSS is not ready. Received status 3 from CSS. Waiting for good status .. 
2012-06-21 00:07:30.691: [ COMMCRS][279]clsc_connect: (1109a9e90) no listener at (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_node2_crs))
2012-06-21 00:07:30.691: [ CSSCLNT][1]clsssInitNative: connect failed, rc 9
2012-06-21 00:07:30.691: [  CRSRTI][1]32CSS is not ready. Received status 3 from CSS. Waiting for good status .. 
2012-06-21 00:07:32.699: [    CRSD][1]32Daemon Version: 10.2.0.3.0 Active Version: 10.2.0.3.0
2012-06-21 00:07:32.699: [    CRSD][1]32Active Version and Software Version are same
2012-06-21 00:07:32.700: [ CRSMAIN][1]32Initializing OCR
2012-06-21 00:07:32.701: [  OCRRAW][1]proprioo: for disk 0 (/crsdata/ocr1), id match (1), my id set (725219174,2133226085) total id sets (1), 1st set (725219174,2133226085), 2nd set (0,0) my votes (1), total votes (2)
2012-06-21 00:07:32.701: [  OCRRAW][1]proprioo: for disk 1 (/crsdata/ocr2), id match (1), my id set (725219174,2133226085) total id sets (1), 1st set (725219174,2133226085), 2nd set (0,0) my votes (1), total votes (2)
2012-06-21 00:07:32.826: [    CRSD][1]32ENV Logging level for Module: allcomp  0
……
2012-06-21 00:07:32.848: [    CRSD][1]32ENV Logging level for Module: OCRMAS  0
2012-06-21 00:07:32.848: [ CRSMAIN][1]32Filename is /u01/oracle/app/oracle/product/10.2.0/crs/crs/init/node2.pid
2012-06-21 00:07:32.889: [ CRSMAIN][1]32Using Authorizer location: /u01/oracle/app/oracle/product/10.2.0/crs/crs/auth/
[  clsdmt][7992]Listening to (ADDRESS=(PROTOCOL=ipc)(KEY=node2DBG_CRSD))
2012-06-21 00:07:32.901: [ CRSMAIN][1]32Initializing RTI
2012-06-21 00:07:32.990: [CRSTIMER][8506]32Timer Thread Starting.
2012-06-21 00:07:33.012: [  CRSRES][1]32Parameter SECURITY = 1, running in USER Mode
2012-06-21 00:07:33.012: [ CRSMAIN][1]32Initializing EVMMgr
2012-06-21 00:07:33.213: [ COMMCRS][8763]clsc_connect: (1158d9410) no listener at (ADDRESS=(PROTOCOL=ipc)(KEY=SYSTEM.evm.acceptor.auth))
2012-06-21 00:07:35.148: [  CRSRES][1]32Skipping locked resource ora.node2.vip
2012-06-21 00:07:35.149: [  CRSRES][1]32Skipping locked resource ora.node1.gsd
2012-06-21 00:07:35.191: [ CRSMAIN][1]32CRSD locked during state recovery, please wait.
2012-06-21 00:07:35.254: [ CRSMAIN][1]32CRSD recovered, unlocked.
2012-06-21 00:07:35.288: [ CRSMAIN][1]32QS socket on: (ADDRESS=(PROTOCOL=ipc)(KEY=ora_crsqs))
2012-06-21 00:07:35.312: [ CRSMAIN][1]32CRSD UI socket on: (ADDRESS=(PROTOCOL=ipc)(KEY=CRSD_UI_SOCKET))
2012-06-21 00:07:35.324: [ CRSMAIN][1]32E2E socket on: (ADDRESS=(PROTOCOL=tcp)(HOST=node2_priv)(PORT=49896))
2012-06-21 00:07:35.324: [ CRSMAIN][1]32Starting Threads
2012-06-21 00:07:35.324: [ CRSMAIN][10049]32Starting runCommandServer for (UI = 1, E2E = 0). 0
2012-06-21 00:07:35.325: [ CRSMAIN][10306]32Starting runCommandServer for (UI = 1, E2E = 0). 1
2012-06-21 00:07:35.325: [ CRSMAIN][1]32CRS Daemon Started.
2012-06-21 00:07:35.389: [  CRSRTI][1]32...lock denied for _ORA_CRS_MEMBER_node2
2012-06-21 00:07:38.986: [    CRSD][10049]32SM: rE2Ec: 4
2012-06-21 00:07:39.078: [  CRSRES][11077]32startRunnable: setting CLI values
2012-06-21 00:07:43.030: [    CRSD][11077]32SM:dE2Ec: all E2E cmds done. 0
2012-06-21 00:07:43.034: [    CRSD][10049]32SM: rE2Ec: 4
2012-06-21 00:07:43.045: [  CRSRES][11079]32startRunnable: setting CLI values
2012-06-21 00:07:46.235: [    CRSD][11079]32SM:dE2Ec: all E2E cmds done. 0
2012-06-21 00:08:14.044: [  CRSRES][1]32 startup = 1
2012-06-21 00:08:14.050: [  CRSRES][1]32 startup = 1
2012-06-21 00:08:14.066: [  CRSRES][1]32 startup = 1
2012-06-21 00:08:14.084: [  CRSEVT][11084]32Processing RecoveryDone
2012-06-21 00:08:14.088: [  CRSRES][1]32 startup = 1
2012-06-21 00:08:14.208: [  CRSRES][11085]32startRunnable: setting CLI values
2012-06-21 00:08:14.229: [  CRSRES][11085]32Attempting to start `ora.rac.rac2.inst` on member `node2`
2012-06-21 00:08:43.134: [  CRSAPP][11085]32StartResource error for ora.rac.rac2.inst error code = 1
2012-06-21 00:08:51.023: [  CRSRES][11085]32Start of `ora.rac.rac2.inst` on member `node2` failed.
2012-06-21 00:08:51.135: [  CRSRES][11097]32startRunnable: setting CLI values
2012-06-21 00:08:51.168: [  CRSRES][11610]32startRunnable: setting CLI values
2012-06-21 00:08:51.169: [  CRSRES][11097]32Attempting to start `ora.node2.gsd` on member `node2`
2012-06-21 00:08:51.200: [  CRSRES][11610]32Attempting to start `ora.node2.ons` on member `node2`
2012-06-21 00:08:53.647: [  CRSRES][11610]32Start of `ora.node2.ons` on member `node2` succeeded.
2012-06-21 00:09:30.893: [  CRSAPP][11097]32StartResource error for ora.node2.gsd error code = 1
2012-06-21 00:09:32.552: [  CRSRES][11097]32Start of `ora.node2.gsd` on member `node2` failed.
2012-06-21 00:10:06.054: [  CRSRES][11614]32startRunnable: setting CLI values
2012-06-21 00:10:06.064: [  CRSRES][11614]32Attempting to start `ora.rac.rac2.inst` on member `node2`
2012-06-21 00:10:07.215: [  OCRUTL][7478]u_freem: mem passed is null
2012-06-21 00:10:08.703: [  CRSRES][11614]32Start of `ora.rac.rac2.inst` on member `node2` succeeded.>>>node2 数据库启动成功。

node2 ocssd.log:

[    CSSD]2012-06-21 00:07:19.681 >USER:    Oracle Database 10g CSS Release 10.2.0.3.0 Production Copyright 1996, 2004 Oracle.  All rights reserved.
[    CSSD]2012-06-21 00:07:19.681 >USER:    CSS daemon log for node node2, number 2, in cluster crs
[    CSSD]2012-06-21 00:07:19.698 [1] >TRACE:   clssscmain: local-only set to false
[  clsdmt]Listening to (ADDRESS=(PROTOCOL=ipc)(KEY=node2DBG_CSSD))
[    CSSD]2012-06-21 00:07:19.726 [1] >TRACE:   clssnmReadNodeInfo: added node 1 (node1) to cluster
[    CSSD]2012-06-21 00:07:19.727 [1] >TRACE:   clssnmReadNodeInfo: added node 2 (node2) to cluster
[    CSSD]2012-06-21 00:07:19.751 [1029] >TRACE:   clssnm_skgxninit: initialized skgxn version (2/0/Veritas Cluster Server MM)
[    CSSD]2012-06-21 00:07:29.753 [1] >TRACE:   clssnmNMInitialize: misscount set to (600), impending reconfig threshold set to (596000)
[    CSSD]2012-06-21 00:07:29.753 [1] >TRACE:   clssnmNMInitialize: diskShortTimeout set to (597000)ms
[    CSSD]2012-06-21 00:07:29.753 [1] >TRACE:   clssnmNMInitialize: diskLongTimeout set to (597000)ms
[    CSSD]2012-06-21 00:07:29.754 [1] >TRACE:   clssnmDiskStateChange: state from 1 to 2 disk (0//crsdata/vote1)
[    CSSD]2012-06-21 00:07:29.755 [1] >TRACE:   clssnmDiskStateChange: state from 1 to 2 disk (1//crsdata/vote2)
[    CSSD]2012-06-21 00:07:29.755 [1286] >TRACE:   clssnmvDPT: spawned for disk 0 (/crsdata/vote1)
[    CSSD]2012-06-21 00:07:29.755 [1543] >TRACE:   clssnmvDPT: spawned for disk 1 (/crsdata/vote2)
[    CSSD]2012-06-21 00:07:29.755 [1] >TRACE:   clssnmDiskStateChange: state from 1 to 2 disk (2//crsdata/vote3)
[    CSSD]2012-06-21 00:07:29.755 [1800] >TRACE:   clssnmvDPT: spawned for disk 2 (/crsdata/vote3)
[    CSSD]2012-06-21 00:07:31.760 [1286] >TRACE:   clssnmDiskStateChange: state from 2 to 4 disk (0//crsdata/vote1)
[    CSSD]2012-06-21 00:07:31.787 [1543] >TRACE:   clssnmDiskStateChange: state from 2 to 4 disk (1//crsdata/vote2)
[    CSSD]2012-06-21 00:07:31.787 [2057] >TRACE:   clssnmvKillBlockThread: spawned for disk 0 (/crsdata/vote1) initial sleep interval (1000)ms
[    CSSD]2012-06-21 00:07:31.787 [1800] >TRACE:   clssnmDiskStateChange: state from 2 to 4 disk (2//crsdata/vote3)
[    CSSD]2012-06-21 00:07:31.787 [2314] >TRACE:   clssnmvKillBlockThread: spawned for disk 1 (/crsdata/vote2) initial sleep interval (1000)ms
[    CSSD]2012-06-21 00:07:31.787 [2571] >TRACE:   clssnmvKillBlockThread: spawned for disk 2 (/crsdata/vote3) initial sleep interval (1000)ms
[    CSSD]2012-06-21 00:07:31.789 [1543] >TRACE:   clssnmReadDskHeartbeat: node(1) is down. rcfg(4) wrtcnt(3315) LATS(3042964870) Disk lastSeqNo(3315)
[    CSSD]2012-06-21 00:07:31.795 [1] >TRACE:   clssnmFatalInit: fatal mode enabled
[    CSSD]2012-06-21 00:07:31.795 [1286] >TRACE:   clssnmReadDskHeartbeat: node(1) is down. rcfg(4) wrtcnt(3315) LATS(3042964875) Disk lastSeqNo(3315)
[    CSSD]2012-06-21 00:07:31.800 [1800] >TRACE:   clssnmReadDskHeartbeat: node(1) is down. rcfg(4) wrtcnt(3315) LATS(3042964880) Disk lastSeqNo(3315)
[    CSSD]2012-06-21 00:07:31.813 [3085] >TRACE:   clssnmClusterListener: Listening on (ADDRESS=(PROTOCOL=tcp)(HOST=node2_priv)(PORT=49895))
[    CSSD]2012-06-21 00:07:31.813 [3085] >TRACE:   clssnmClusterListener: skgxn node  (0) down
[    CSSD]2012-06-21 00:07:31.815 [3085] >TRACE:   clssnmconnect: connecting to node(1), con(111aa2c70), flags 0x0003
[    CSSD]2012-06-21 00:07:31.816 [3085] >TRACE:   clssnmConnComplete: MSGSRC 1, type 6, node 1, flags 0x0003, con 111aa2c70, probe 0
[    CSSD]2012-06-21 00:07:31.816 [3085] >TRACE:   clssnmConnComplete: connecting to node 1 con(111aa2c70), msg state 3, birth 0, probcon(0), ninfcon(111aa2c70), prevConuni(0), node state 0
[    CSSD]2012-06-21 00:07:31.816 [3085] >TRACE:   clssnmConnComplete: connected to node 1 (con 111aa2c70), ninfcon (111aa2c70), state (0), flag (1039)
[    CSSD]2012-06-21 00:07:31.869 [3342] >TRACE:   clssgmclientlsnr: listening on (ADDRESS=(PROTOCOL=ipc)(KEY=Oracle_CSS_LclLstnr_crs_2))
[    CSSD]2012-06-21 00:07:31.869 [3342] >TRACE:   clssgmclientlsnr: listening on (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_node2_crs))
[    CSSD]2012-06-21 00:07:31.881 [4113] >TRACE:   clssgmPeerListener: Listening on (ADDRESS=(PROTOCOL=tcp)(DEV=26)(HOST=10.70.206.69)(PORT=32888))
[    CSSD]2012-06-21 00:07:32.201 [3085] >TRACE:   clssnmHandleSync: diskTimeout set to (597000)ms
[    CSSD]2012-06-21 00:07:32.201 [4884] >TRACE:   clssnmRcfgMgrThread: initial lastleader(1) unique(1340205072)
[    CSSD]2012-06-21 00:07:32.201 [3085] >TRACE:   clssnmHandleSync: Acknowledging sync: src[1] srcName[node1] seq[5] sync[5]
[    CSSD]2012-06-21 00:07:32.202 [3085] >TRACE:   clssnmSendVoteInfo: node(1) syncSeqNo(5)
[    CSSD]2012-06-21 00:07:32.203 [3085] >TRACE:   clssnmUpdateNodeState: node 0, state (0/0) unique (0/0) prevConuni(0) birth (0/0) (old/new)
[    CSSD]2012-06-21 00:07:32.203 [3085] >TRACE:   clssnmUpdateNodeState: node 1, state (4/3) unique (1340205072/1340205072) prevConuni(0) birth (0/3) (old/new)
[    CSSD]2012-06-21 00:07:32.203 [3085] >TRACE:   clssnmUpdateNodeState: node 2, state (1/3) unique (1340208439/1340208439) prevConuni(0) birth (0/5) (old/new)
[    CSSD]2012-06-21 00:07:32.203 [3085] >USER:    clssnmHandleUpdate: SYNC(5) from node(1) completed
[    CSSD]2012-06-21 00:07:32.203 [3085] >USER:    clssnmHandleUpdate: NODE 1 (node1) IS ACTIVE MEMBER OF CLUSTER
[    CSSD]2012-06-21 00:07:32.203 [3085] >USER:    clssnmHandleUpdate: NODE 2 (node2) IS ACTIVE MEMBER OF CLUSTER
[    CSSD]2012-06-21 00:07:32.203 [3085] >TRACE:   clssnmHandleUpdate: diskTimeout set to (597000)ms
[    CSSD]2012-06-21 00:07:32.283 [1] >USER:    NMEVENT_SUSPEND [00][00][00][00]
[    CSSD]2012-06-21 00:07:32.284 [5141] >TRACE:   clssgmReconfigThread:  started for reconfig (5)
[    CSSD]2012-06-21 00:07:32.284 [5141] >USER:    NMEVENT_RECONFIG [00][00][00][06]
[    CSSD]2012-06-21 00:07:32.284 [5141] >TRACE:   clssgmEstablishConnections: 2 nodes in cluster incarn 5
[    CSSD]2012-06-21 00:07:32.285 [4113] >TRACE:   clssgmInitialRecv: (112d34e10) accepted a new connection from node 1 born at 3 active (2, 2), vers (10,3,1,2)
[    CSSD]2012-06-21 00:07:32.285 [4113] >TRACE:   clssgmInitialRecv: conns done (2/2)
[    CSSD]2012-06-21 00:07:32.285 [5141] >TRACE:   clssgmEstablishMasterNode: MASTER for 5 is node(1) birth(3)
[    CSSD]2012-06-21 00:07:32.285 [5141] >TRACE:   clssgmChangeMasterNode: requeued 0 RPCs
[    CSSD]2012-06-21 00:07:32.316 [4113] >TRACE:   clssgmHandleDBDone(): src/dest (1/65535) size(72) incarn 5
[    CSSD]CLSS-3000: reconfiguration successful, incarnation 5 with 2 nodes
[    CSSD]CLSS-3001: local node number 2, master node number 1
[    CSSD]2012-06-21 00:07:32.316 [5141] >TRACE:   clssgmReconfigThread:  completed for reconfig(5), with status(1)>>>>完成了群集重新配置。

从node2 alert里面也可以看到：

2012-06-21 00:07:31.784
[cssd(446818)]CRS-1605:CSSD voting file is online: /crsdata/vote1. Details in /u01/oracle/app/oracle/product/10.2.0/crs/log/node2/cssd/ocssd.log.
2012-06-21 00:07:31.787
[cssd(446818)]CRS-1605:CSSD voting file is online: /crsdata/vote2. Details in /u01/oracle/app/oracle/product/10.2.0/crs/log/node2/cssd/ocssd.log.
2012-06-21 00:07:31.787
[cssd(446818)]CRS-1605:CSSD voting file is online: /crsdata/vote3. Details in /u01/oracle/app/oracle/product/10.2.0/crs/log/node2/cssd/ocssd.log.
2012-06-21 00:07:32.316
[cssd(446818)]CRS-1601:CSSD Reconfiguration complete. Active nodes are node1 node2 .
2012-06-21 00:07:32.791
[crsd(267178)]CRS-1012:The OCR service started on node node2.
2012-06-21 00:07:32.862
[evmd(577634)]CRS-1401:EVMD started on node node2.
2012-06-21 00:07:35.325
[crsd(267178)]CRS-1201:CRSD started on node node2.

我们大概来理一下,当在node2 reboot -q的时候，node2-vip并未立即切换到node1，而是当node2启动，群集reconfigration完成后在node1启动了node2-vip，这个过程足足花费了8分钟多点。

目前这个问题还在分析中，再继续更新。
这个问题已经有个了结论，遇到了bug：7001987
看下面的描述：

An induced node panic is not being recognised by Oracle CSS/CRS until 10 
minutes after the node has gone down. The CRS reources for the failed node 
are reminaing online until CSSD has performed the node eviction itself after 
waiting for 10 minutes (default behaviour when Sun Cluster is in place) 
rather than as soon as the Sun Cluster notification regarding the panic has 
occurred

我们用clustereware是VCS，其实和上面的情况是类似的。

iteye_4537

关注

0
点赞
踩
1

收藏

觉得还不错? 一键收藏
0
评论
节点失败,VIP不能切换分析

高可用对于核心的数据库是一个保障，我们的核心库中，每个月都要进行高可用演练，在这次演练的时候RAC的VIP切换出现了点怪异的问题，目前还没有找到可以信服的原因。下面看下这个切换过程的不正常：我先大致描述下这个演练的过程:1,node1 reboot -q&gt;check the node1-vip's failover 2,node2 reboot -q&gt;check the nod...
复制链接

扫一扫