Fails to Join the Cluster as CRSD and EVMD are in INTERMEDIATE State

yewushang發表於2014-04-11

Applies to:

Oracle Database - Enterprise Edition - Version 11.2.0.1 and later
IBM AIX on POWER Systems (64-bit)

Description

11gR2 non-first node (second or any subsequent node after the first) fails to join the cluster as CRSD and EVMD stay in INTERMEDIATE state.

Occurrence

The issue can happen during new 11gR2 GI installation if AIX is at 6.1 TL8 or 7.1 TL2, or on existing 11gR2 GI installations where AIX has been patched to 6.1 TL8 or 7.1 TL2.

Symptoms

The key symptom of this issue is non-first nodes (second or any subsequent node after the first) fails to join the cluster as CRSD and EVMD stay in INTERMEDIATE state. The relevant problem diagnosis is as follows:

Output of "crsctl stat res -t -init" on non-first node

--------------------------------------------------------------------------------
NAME TARGET STATE SERVER STATE_DETAILS
--------------------------------------------------------------------------------
Cluster Resources
--------------------------------------------------------------------------------
ora.asm
1 ONLINE ONLINE racnode2 Started

ora.cluster_interconnect.haip
1 ONLINE ONLINE racnode2

ora.crf
1 ONLINE ONLINE racnode2

ora.crsd
1 ONLINE INTERMEDIATE racnode2

ora.cssd
1 ONLINE ONLINE racnode2

ora.cssdmonitor
1 ONLINE ONLINE racnode2

ora.ctssd
1 ONLINE ONLINE racnode2 OBSERVER

ora.diskmon
1 OFFLINE OFFLINE

ora.drivers.acfs
1 ONLINE ONLINE racnode2

ora.evmd
1 ONLINE INTERMEDIATE racnode2

ora.gipcd
1 ONLINE ONLINE racnode2

ora.gpnpd
1 ONLINE ONLINE racnode2

ora.mdnsd
1 ONLINE ONLINE racnode2

/log//crsd/crsd.log

2013-01-30 15:39:55.626: [ OCRMAS][3342]th_connect_master:10: Master host name [racnode1]
2013-01-30 15:39:55.626: [ OCRMAS][3342]proath_connect_master: Attempting to connect to master at address [racnode1:92e5-4b5d-6878-b0a1]
2013-01-30 15:39:55.627: [GIPCXCPT][3342] gipchaInternalResolve: failed to resolve ret gipcretKeyNotFound (36), host 'racnode2', port '934f-fa82-9ee1-d157', hctx 110ebcdb0 [0000000000000010] { gipchaContext : host 'racnode2', name '9b2c-587d-1c38-f6bf', luid '8ea35e5d-00000000', numNode 0, numInf 1, usrFlags 0x0, flags 0x1 }, ret gipcretKeyNotFound (36)
2013-01-30 15:39:55.627: [GIPCHGEN][3342] gipchaResolveF [gipcmodGipcResolve : gipcmodGipc.c : 804]: EXCEPTION[ ret gipcretKeyNotFound (36) ] failed to resolve ctx 110ebcdb0 [0000000000000010] { gipchaContext : host 'racnode2', name '9b2c-587d-1c38-f6bf', luid '8ea35e5d-00000000', numNode 0, numInf 1, usrFlags 0x0, flags 0x1 }, host 'racnode2', port '934f-fa82-9ee1-d157', flags 0x0
2013-01-30 15:40:24.533: [ CRSMAIN][515] Policy Engine is not initialized yet!
2013-01-30 15:40:54.533: [ CRSMAIN][515] Policy Engine is not initialized yet!
2013-01-30 15:41:24.534: [ CRSMAIN][515] Policy Engine is not initialized yet!
2013-01-30 15:41:54.534: [ CRSMAIN][515] Policy Engine is not initialized yet!
2013-01-30 15:42:24.533: [ CRSMAIN][515] Policy Engine is not initialized yet!
2013-01-30 15:42:54.542: [ CRSMAIN][515] Policy Engine is not initialized yet!
2013-01-30 15:43:24.543: [ CRSMAIN][515] Policy Engine is not initialized yet! ==>> repeated for many times

/log//ohasd/ohasd.log

2013-01-30 15:39:11.214: [GIPCXCPT][5408]gipchaLowerRecv: partial header received, discarding len 52 < hdr 80, from 'mcast://230.0.1.0:0/0.0.0.80', ret gipcretFail (1) ==>> partial header received messages
2013-01-30 15:39:11.214: [GIPCHALO][5408]gipchaLowerCallback: EXCEPTION[ ret gipcretFail (1) ] error while processing req 114be9698 { type gipcreqtypeRecv, endp 000000000000061b, ret gipcretSuccess, endpA 0000000000000000, peer 'mcast://230.0.1.0:0/0.0.0.80' buf 114e70418, len 10240, olen 52 }, hctx 111393fb0 [0000000000000010] { gipchaContext : host 'racnode2', name 'CLSFRAME_sisfvg-grid', luid '29860a18-00000000', numNode 1, numInf 1, usrFlags 0x0, flags 0x67 }
2013-01-30 15:39:11.214: [GIPCXCPT][5408]gipchaLowerRecv: partial header received, discarding len 52 < hdr 80, from 'mcast://224.0.0.251:0/0.0.0.80', ret gipcretFail (1)
2013-01-30 15:39:11.214: [GIPCHALO][5408]gipchaLowerCallback: EXCEPTION[ ret gipcretFail (1) ] error while processing req 114be9760 { type gipcreqtypeRecv, endp 0000000000000612, ret gipcretSuccess, endpA 0000000000000000, peer 'mcast://224.0.0.251:0/0.0.0.80' buf 114e6db78, len 10240, olen 52 }, hctx 111393fb0 [0000000000000010] { gipchaContext : host 'racnode2', name 'CLSFRAME_sisfvg-grid', luid '29860a18-00000000', numNode 1, numInf 1, usrFlags 0x0, flags 0x67 }
2013-01-30 15:39:11.214: [GIPCXCPT][5408]gipchaLowerRecv: invalid message header hdr '' != expected 'GHLbMsg1 (624c4847 3167734d)', from 'mcast://230.0.1.0:0/0.0.4.136', ret gipcretFail (1)
2013-01-30 15:39:11.214: [GIPCHALO][5408]gipchaLowerCallback: EXCEPTION[ ret gipcretFail (1) ] error while processing req 114be9828 { type gipcreqtypeRecv, endp 000000000000061b, ret gipcretSuccess, endpA 0000000000000000, peer 'mcast://230.0.1.0:0/0.0.4.136' buf 114e75ab8, len 10240, olen 1132 }, hctx 111393fb0 [0000000000000010] { gipchaContext : host 'racnode2', name 'CLSFRAME_sisfvg-grid', luid '29860a18-00000000', numNode 1, numInf 1, usrFlags 0x0, flags 0x67 }
2013-01-30 15:39:11.214: [GIPCXCPT][5408]gipchaLowerRecv: invalid message header hdr '' != expected 'GHLbMsg1 (624c4847 3167734d)', from 'mcast://224.0.0.251:0/0.0.4.136', ret gipcretFail (1)
2013-01-30 15:39:11.214: [GIPCHALO][5408]gipchaLowerCallback: EXCEPTION[ ret gipcretFail (1) ] error while processing req 114be98f0 { type gipcreqtypeRecv, endp 0000000000000612, ret gipcretSuccess, endpA 0000000000000000, peer 'mcast://224.0.0.251:0/0.0.4.136' buf 114e72e98, len 10240, olen 1132 }, hctx 111393fb0 [0000000000000010] { gipchaContext : host 'racnode2', name 'CLSFRAME_sisfvg-grid', luid '29860a18-00000000', numNode 1, numInf 1, usrFlags 0x0, flags 0x67 }
..
2013-01-30 15:39:11.214: [GIPCXCPT][5408]gipchaLowerRecv: partial header received, discarding len 52 < hdr 80, from 'mcast://230.0.1.0:0/0.0.0.80', ret gipcretFail (1)
2013-01-30 15:39:11.214: [GIPCHALO][5408]gipchaLowerCallback: EXCEPTION[ ret gipcretFail (1) ] error while processing req 114be9b48 { type gipcreqtypeRecv, endp 000000000000061b, ret gipcretSuccess, endpA 0000000000000000, peer 'mcast://230.0.1.0:0/0.0.0.80' buf 114e32bb8, len 10240, olen 52 }, hctx 111393fb0 [0000000000000010] { gipchaContext : host 'racnode2', name 'CLSFRAME_sisfvg-grid', luid '29860a18-00000000', numNode 1, numInf 1, usrFlags 0x0, flags 0x67 }
2013-01-30 15:39:11.214: [GIPCXCPT][5408]gipchaLowerRecv: partial header received, discarding len 52 < hdr 80, from 'mcast://224.0.0.251:0/0.0.0.80', ret gipcretFail (1)
..

Patches

The issue has been investigated in BUG 16277504, BUG 16285675 and BUG 16264027. With collaboration by IBM the root cause has been identified to be an issue on both AIX 6.1 TL08 SP01 and AIX 7.1 TL02 SP01 with truncation of multicast packets.

The solution is to contact IBM and apply the fix.

Revevant links:

AIX 6.1 TL08 SP01

APAR IV35888: UDP MULTICAST: SHORT PACKET FOR SOME LISTENERS. 13/02/08 PTF PECHANGE
http://www-01.ibm.com/support/docview.wss?uid=isg1IV35888&myns=apar&mynp=DOCTYPEcomponent&mync=E

AIX 7.1 TL02 SP01

APAR IV35893: UDP MULTICAST: SHORT PACKET FOR SOME LISTENERS. 13/02/08 PTF PECHANGE
http://www-01.ibm.com/support/docview.wss?uid=isg1IV35893&myns=apar&mynp=DOCTYPEcomponent&mync=E