Skip to Main Content
Forums

Database Software

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

Rac 12c+ASM ,cluster start is failing

Mallik SAug 19 2017 — edited Aug 21 2017

Hi All,

I am having RAC+ASMLIB setup on RHEL 7.2, I am able to see all the Disk using "oracleasm listdisks" , whereas while starting cluster , i have noticed failure as follows.

Please ,let me know ,how to debug such issue and resolve them?

[root@rac2node2 disks]# crsctl start cluster -all

CRS-2672: Attempting to start 'ora.evmd' on 'rac2node2'

CRS-2672: Attempting to start 'ora.cssdmonitor' on 'rac2node2'

CRS-2672: Attempting to start 'ora.cssdmonitor' on 'rac2node1'

CRS-2672: Attempting to start 'ora.evmd' on 'rac2node1'

CRS-2676: Start of 'ora.cssdmonitor' on 'rac2node2' succeeded

CRS-2672: Attempting to start 'ora.cssd' on 'rac2node2'

CRS-2672: Attempting to start 'ora.diskmon' on 'rac2node2'

CRS-2676: Start of 'ora.diskmon' on 'rac2node2' succeeded

CRS-2676: Start of 'ora.cssdmonitor' on 'rac2node1' succeeded

CRS-2672: Attempting to start 'ora.cssd' on 'rac2node1'

CRS-2672: Attempting to start 'ora.diskmon' on 'rac2node1'

CRS-2676: Start of 'ora.diskmon' on 'rac2node1' succeeded

CRS-2676: Start of 'ora.evmd' on 'rac2node2' succeeded

CRS-2676: Start of 'ora.evmd' on 'rac2node1' succeeded

CRS-2676: Start of 'ora.cssd' on 'rac2node2' succeeded

CRS-2672: Attempting to start 'ora.ctssd' on 'rac2node2'

CRS-2672: Attempting to start 'ora.cluster_interconnect.haip' on 'rac2node2'

CRS-2676: Start of 'ora.cssd' on 'rac2node1' succeeded

CRS-2672: Attempting to start 'ora.ctssd' on 'rac2node1'

CRS-2672: Attempting to start 'ora.cluster_interconnect.haip' on 'rac2node1'

CRS-2676: Start of 'ora.ctssd' on 'rac2node2' succeeded

CRS-2676: Start of 'ora.ctssd' on 'rac2node1' succeeded

CRS-2676: Start of 'ora.cluster_interconnect.haip' on 'rac2node2' succeeded

CRS-2672: Attempting to start 'ora.asm' on 'rac2node2'

CRS-2676: Start of 'ora.cluster_interconnect.haip' on 'rac2node1' succeeded

CRS-2672: Attempting to start 'ora.asm' on 'rac2node1'

CRS-2676: Start of 'ora.asm' on 'rac2node1' succeeded

CRS-2672: Attempting to start 'ora.storage' on 'rac2node1'

CRS-2676: Start of 'ora.asm' on 'rac2node2' succeeded

CRS-2672: Attempting to start 'ora.storage' on 'rac2node2'

ORA-27300: OS system dependent operation:sslssunreghdlr failed with status: 0

ORA-27301: OS failure message: Error 0

ORA-27302: failure occurred at: sskgpreset1diskgroup OCR_VOTER not mounted ()

CRS-2674: Start of 'ora.storage' on 'rac2node2' failed

CRS-2679: Attempting to clean 'ora.storage' on 'rac2node2'

CRS-2681: Clean of 'ora.storage' on 'rac2node2' succeeded

CRS-2673: Attempting to stop 'ora.asm' on 'rac2node2'

CRS-2674: Start of 'ora.storage' on 'rac2node1' failed

CRS-2679: Attempting to clean 'ora.storage' on 'rac2node1'

CRS-2681: Clean of 'ora.storage' on 'rac2node1' succeeded

CRS-2673: Attempting to stop 'ora.asm' on 'rac2node1'

CRS-2677: Stop of 'ora.asm' on 'rac2node1' succeeded

CRS-2677: Stop of 'ora.asm' on 'rac2node2' succeeded

CRS-4705: Start of Clusterware failed on node rac2node1.

CRS-4705: Start of Clusterware failed on node rac2node2.

CRS-4000: Command Start failed, or completed with errors.

In /u01/app/grid/diag/crs/rac2node2/crs/trace/Alert.log ,following Messages is seen,

2017-08-20 06:53:19.946 [ORAROOTAGENT(27031)]CRS-5019: All OCR locations are on ASM disk groups [OCR_VOTER], and none of these disk groups are mounted. Details are at "(:CLSN00140:)" in "/u01/app/grid/diag/crs/rac2node2/crs/trace/ohasd_orarootagent_root.trc".

In "/u01/app/grid/diag/crs/rac2node2/crs/trace/ohasd_orarootagent_root.trc" logs , following is seen,

2017-08-20 09:13:41.360 : USRTHRD:2411714304: {0:0:12901} 8033 Error 4 querying length of attr ASM_STATIC_DISCOVERY_ADDRESS

2017-08-20 09:13:41.390 : CLSCRED:2411714304: (:CLSCRED1079:)clsCredOcrKeyExists: Obj dom : SYSTEM.credentials.domains.root.ASM.Self.40b62903af826f90ff8b9921dc771dc8.root not found

2017-08-20 09:13:41.390 : USRTHRD:2411714304: {0:0:12901} 7755 Error 4 opening dom root in 0x7efcb4147c90

2017-08-20 09:13:41.406 : CSSCLNT:2411714304: clsssinit: initialized context: (0x7efcb43d8010) flags 0x104

2017-08-20 09:13:41.407 : CSSCLNT:2411714304: clsssterm: terminating context (0x7efcb43d8010)

2017-08-20 09:13:41.407 : default:2411714304: clsCredDomClose: Credctx deleted 0x7efcb403b530

2017-08-20 09:13:41.408 : USRTHRD:2411714304: {0:0:12901} -- trace dump on error exit --

2017-08-20 09:13:41.408 : USRTHRD:2411714304: {0:0:12901} Error [kgfoAl06] in [kgfokge] at kgfo.c:3083

2017-08-20 09:13:41.408 : USRTHRD:2411714304: {0:0:12901} ORA-27300: OS system dependent operation:sslssunreghdlr failed with status: 0

ORA-27301: OS failure message: Error 0

ORA-27302: failure occurred at: sskgpreset1

2017-08-20 09:13:41.408 : USRTHRD:2411714304: {0:0:12901} Category: 7

2017-08-20 09:13:41.408 : USRTHRD:2411714304: {0:0:12901} DepInfo: 27300

2017-08-20 09:13:41.408 : USRTHRD:2411714304: {0:0:12901} -- trace dump end --

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check] StorageAgent::parsekgforetcodes retcode = 7, kgfoCheckMount(OCR_VOTER), flag 2

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check] (null) category: 7, operation: kgfoAl06, loc: kgfokge, OS error: 27300, other: ORA-27300: OS system dependent operation:sslssunreghdlr failed with status: 0

ORA-27301: OS failure message: Error 0

ORA-27302: failure occurred at: sskgpreset1

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check] StorageAgent::check kgfo returncode 1

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check] (:CLSN00140:)StorageAgent::parsekgforretcodes OCR dgName OCR_VOTER state 1

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check] (:CLSN00109:) Agent::commonCheck check failed action:0104 retval:1

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check] Agent::doStateDump Default Agent Dump

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check] Agent::doStateDump  last call info:

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:12:35.627 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck exit clsagfw_res_status:1 }

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:35.571 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck entry {

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:35.571 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck notifyObservers

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:35.571 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck call check

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:35.571 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Calling targetcheck API

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:35.619 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:targetcheck API returned

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:35.619 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::check NODEROLE_HUB getOCRdetails

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:35.622 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::parsekgforetcodes Calling kgfoCheckMount OCR_VOTER

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:41.408 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::parsekgforetcodes retcode = 7, kgfoCheckMount(OCR_VOTER), flag 2

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:41.408 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::check kgfo returncode 1

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:41.408 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::check exit clsagfw_res_status:1

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:41.408 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck check clsagfw_res_status:1

2017-08-20 09:13:41.408 :CLSDYNAM:2411714304: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:41.408 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:(:CLSN00109:) Agent::commonCheck check failed action:0104 retval:1

2017-08-20 09:13:50.501 :CLSDYNAM:3982132992: [ora.ctssd]{0:0:12901} [check] translateReturnCodes, return = 0, state detail = ACTIVE:0Checkcb data [0x7efccc05a7f0]: mode[0xcc] offset[0 ms].

2017-08-20 09:13:56.302 : USRTHRD:3989649152: {0:0:12901} Check: 0-1

2017-08-20 09:14:07.056 :CLSDYNAM:2415916800: [ ora.crf]{0:23:30} [check] Check return = 0, state detail = NULL

2017-08-20 09:14:09.709 :    AGFW:4003964672: {0:0:61523} Agent received the message: AGENT_HB[Engine] ID 12293:653587

2017-08-20 09:14:20.501 :CLSDYNAM:2415916800: [ora.ctssd]{0:0:12901} [check] translateReturnCodes, return = 0, state detail = ACTIVE:0Checkcb data [0x7efc9c01af20]: mode[0xcc] offset[0 ms].

2017-08-20 09:14:26.302 : USRTHRD:3973728000: {0:0:12901} Check: 0-1

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Arg Value = check

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Utils::getOracleHomeAttrib getEnvVar oracle_home:/home/grid/grid

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Utils::getOracleHomeAttrib oracle_home:/home/grid/grid

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Utils::execCmd 1 USR_ORA_ENV: oracleHome:/home/grid/grid CrsHome:/home/grid/grid

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Adding Environment Variables ORA_DAEMON_TRACE_FILE_OPTIONS=filesize=26214400,numsegments=10

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Adding Environment Variables _ORA_AGENT_ACTION=TRUE

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Adding Environment Variables __IS_HASD_AGENT=

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Utils:execCmd action = 3 flags = 6 ohome = (null) cmdname = acfsload.

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Utils::getOracleHomeAttrib getEnvVar oracle_home:/home/grid/grid

2017-08-20 09:14:31.684 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] Utils::getOracleHomeAttrib oracle_home:/home/grid/grid

2017-08-20 09:14:31.789 :CLSDYNAM:2411714304: [ora.drivers.acfs]{0:23:2} [check] execCmd ret = 0

2017-08-20 09:14:35.621 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check] StorageAgent::check NODEROLE_HUB getOCRdetails

2017-08-20 09:14:35.623 :    GPNP:2415916800: clsgpnp_dbmsGetItem_profile: [at clsgpnp_dbms.c:399] Result: (0) CLSGPNP_OK. (:GPNP00401:)got ASM-Profile.Mode='remote'

2017-08-20 09:14:35.624 : CSSCLNT:2415916800: clsssinit: initialized context: (0x7efc9c0402f0) flags 0x215

2017-08-20 09:14:35.625 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check] StorageAgent::parsekgforetcodes retcode = 6, kgfoCheckMount(OCR_VOTER), flag 4

2017-08-20 09:14:35.625 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check] (null) category: 0, operation: ▒~, loc: ~, OS error: 32508, other:

2017-08-20 09:14:35.625 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check] StorageAgent::check kgfo returncode 1

2017-08-20 09:14:35.625 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check] (:CLSN00140:)StorageAgent::parsekgforretcodes OCR dgName OCR_VOTER state 1

2017-08-20 09:14:35.625 : CSSCLNT:2415916800: clsssterm: terminating context (0x7efc9c0402f0)

2017-08-20 09:14:35.625 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check] (:CLSN00109:) Agent::commonCheck check failed action:0104 retval:1

2017-08-20 09:14:35.625 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check] Agent::doStateDump Default Agent Dump

2017-08-20 09:14:35.625 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check] Agent::doStateDump  last call info:

2017-08-20 09:14:35.625 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:13:41.408 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck exit clsagfw_res_status:1 }

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.573 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck entry {

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.573 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck notifyObservers

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.573 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck call check

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.573 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Calling targetcheck API

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.621 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:targetcheck API returned

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.621 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::check NODEROLE_HUB getOCRdetails

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.623 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::parsekgforetcodes Calling kgfoCheckMount OCR_VOTER

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.625 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::parsekgforetcodes retcode = 6, kgfoCheckMount(OCR_VOTER), flag 4

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.625 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::check kgfo returncode 1

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.625 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:StorageAgent::check exit clsagfw_res_status:1

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.625 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:Agent::commonCheck check clsagfw_res_status:1

2017-08-20 09:14:35.626 :CLSDYNAM:2415916800: [ora.storage]{0:0:12901} [check]  Time:08/20/2017 09:14:35.625 Tint:{0:0:12901} action:104 resname:ora.storage lastCall:(:CLSN00109:) Agent::commonCheck check failed action:0104 retval:1

Please ,let me know any other logs will be required for troubleshooting .

Thanks,

Mallik S
Comments
Locked Post
New comments cannot be posted to this locked post.
Post Details
Locked on Sep 18 2017
Added on Aug 19 2017
#performance-availability, #rac-asm-clusterware-installation
2 comments
2,231 views