srvctl Fails to Start Database but sqlplus Works Fine as Instance Health Check is Incorrect (Doc ID 1504777.1)

Last updated on APRIL 09, 2014

Applies to:

Oracle Database - Enterprise Edition - Version 11.2.0.1 and later
Information in this document applies to any platform.

Symptoms

11gR2 srvctl fails to start database/instance but sqlplus starts fine.

 

Output of "srvctl start database" or "srvctl start instance" 

PRCR-1013 : Failed to start resource ora.racdb.db
PRCR-1064 : Failed to start resource ora.racdb.db on node racnode1
CRS-2674: Start of 'ora.racdb.db' on 'racnode1' failed

 

Case 1:
2012-11-04 02:48:42.833: [ora.racdb.db][1112095040] {4:5459:372} [start] Utils::getCrsHome crsHome /ocw/grid
2012-11-04 02:48:42.833: [ora.racdb.db][1112095040] {4:5459:372} [start] clsnInstConnection::makeConnectStr LIBRARY_PATH1 ,LD_LIBRARY_PATH=
2012-11-04 02:48:42.833: [ora.racdb.db][1112095040] {4:5459:372} [start] makeConnectStr = (DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/oracle/db/11203/bin/or
acle)(ARGV0=oracleracdb003)(ENVS='ORACLE_HOME=/oracle/db/11203,ORACLE_SID=racdb003,LD_LIBRARY_PATH=')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))(CONNECT_DATA=(SID=S
E1003)))
2012-11-04 02:48:42.833: [ora.racdb.db][1112095040] {4:5459:372} [start] Container:start oracle home /oracle/db/11203
2012-11-04 02:48:42.833: [ora.racdb.db][1112095040] {4:5459:372} [start] InstConnection::connectInt: server not attached
2012-11-04 02:48:43.684: [ora.racdb.db][1112095040] {4:5459:372} [start] InstAgent::startup
2012-11-04 02:48:43.693: [ora.racdb.db][1112095040] {4:5459:372} [start] ORA-01012: not logged on
2012-11-04 02:48:43.693: [ora.racdb.db][1112095040] {4:5459:372} [start] InstAgent::start: 1 errcode 1012
2012-11-04 02:48:43.693: [ora.racdb.db][1112095040] {4:5459:372} [start] ConnectionPool::resetConnection  s_statusOfConnectionMap 00a907a0
2012-11-04 02:48:43.693: [ora.racdb.db][1112095040] {4:5459:372} [start] ConnectionPool::resetConnection sid racdb003 status  2
2012-11-04 02:48:43.693: [ora.racdb.db][1112095040] {4:5459:372} [start] Gimh::check OH /oracle/db/11203 SID racdb003
2012-11-04 02:48:43.693: [ora.racdb.db][1112095040] {4:5459:372} [start] Gimh::check condition changes to (GIMH_NEXT_NUM) 1 exists
2012-11-04 02:48:43.693: [ora.racdb.db][1112095040] {4:5459:372} [start] clsnDbAgent:checkCbk clsagfw_res_status 22
2012-11-04 02:48:43.694: [ora.racdb.db][1112095040] {4:5459:372} [start] ConnectionPool::stopConnection
2012-11-04 02:48:43.694: [ora.racdb.db][1112095040] {4:5459:372} [start] ConnectionPool::removeConnection connection count 0
2012-11-04 02:48:43.694: [ora.racdb.db][1112095040] {4:5459:372} [start] ConnectionPool::removeConnection freed 0
2012-11-04 02:48:43.694: [ora.racdb.db][1112095040] {4:5459:372} [start] ConnectionPool::stopConnection sid racdb003 status  1
2012-11-04 02:48:43.694: [ora.racdb.db][1112095040] {4:5459:372} [start] InstAgent::check checkCounter 0 prev clsagfw_res_status 2 current clsagfw_res_status 2
2012-11-04 02:48:43.694: [ora.racdb.db][1112095040] {4:5459:372} [start] InstAgent::start not  logged on check state details Instance Shutdown
2012-11-04 02:48:43.694: [ora.racdb.db][1112095040] {4:5459:372} [start] InstAgent::start: ORA-1012 error state is Instance Shutdown
2012-11-04 02:48:43.694: [ora.racdb.db][1112095040] {4:5459:372} [start] InstAgent::start: 2 errcode 1012
2012-11-04 02:48:43.694: [ora.racdb.db][1112095040] {4:5459:372} [start] InstAgent::start exception }
2012-11-04 02:48:43.695: [ora.racdb.db][1112095040] {4:5459:372} [start] clsnUtils::error Exception type=2 string=
CRS-5017: The resource action "ora.racdb.db start" encountered the following error:
2012-11-04 02:48:43.695: [ora.racdb.db][1112095040] {4:5459:372} [start] (:CLSN00107:) clsn_agent::start }
2012-11-04 02:48:43.695: [    AGFW][1112095040] {4:5459:372} Command: start for resource: ora.racdb.db 1 1 completed with status: FAIL
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] ConnectionPool::resetConnection  s_statusOfConnectionMap 00a907a0
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] ConnectionPool::resetConnection sid racdb003 status  2
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] Gimh::check OH /oracle/db/11203 SID racdb003
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] Gimh::check condition changes to (GIMH_NEXT_NUM) 1 exists
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] clsnDbAgent:checkCbk clsagfw_res_status 22
2012-11-04 02:48:43.696: [    AGFW][1092651328] {4:5459:372} Agent sending reply for: RESOURCE_START[ora.racdb.db 1 1] ID 4098:2384
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] ConnectionPool::stopConnection
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] ConnectionPool::removeConnection connection count 0
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] ConnectionPool::removeConnection freed 0
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] ConnectionPool::stopConnection sid racdb003 status  1
2012-11-04 02:48:43.696: [ora.racdb.db][1112095040] {4:5459:372} [check] InstAgent::check checkCounter 0 prev clsagfw_res_status 2 current clsagfw_res_status 2
2012-11-04 02:48:43.697: [    AGFW][1092651328] {4:5459:372} Agent sending reply for: RESOURCE_START[ora.racdb.db 1 1] ID 4098:2384
2012-11-04 02:48:43.697: [    AGFW][1092651328] {4:5459:372} ora.racdb.db 1 1 state changed from: STARTING to: PLANNED_OFFLINE
2012-11-04 02:48:43.697: [    AGFW][1092651328] {4:5459:372} Agent sending last reply for: RESOURCE_START[ora.racdb.db 1 1] ID 4098:2384
2012-11-04 02:48:43.702: [ USRTHRD][1094752576] {4:5467:372}  NAME='ora.racdb.db'
2012-11-04 02:48:43.703: [    AGFW][1092651328] {4:5459:372} Agent received the message: RESOURCE_CLEAN[ora.racdb.db 1 1] ID 4100:2395
2012-11-04 02:48:43.704: [    AGFW][1092651328] {4:5459:372} Preparing CLEAN command for: ora.racdb.db 1 1
2012-11-04 02:48:43.704: [    AGFW][1092651328] {4:5459:372} ora.racdb.db 1 1 state changed from: PLANNED_OFFLINE to: CLEANING

 

2012-11-04 09:48:01.274: [UiServer][1174600000] {3:33482:3505} Container [
Name: ORDER
MESSAGE:
TextMessage[CRS-2672: Attempting to start 'ora.racdb.db' on 'racnode1']
MSGTYPE:
TextMessage[3]
OBJID:
TextMessage[ora.racdb.db 1 1]
WAIT:
TextMessage[0]
]
2012-11-04 09:48:01.274: [ COMMCRS][1174600000]clscsendx: (0x180a800) Connection not active

2012-11-04 09:48:01.274: [UiServer][1174600000] {3:33482:3505} CS(0x2aaaab273580)Error sending msg over socket.6
2012-11-04 09:48:01.275: [UiServer][1174600000] {3:33482:3505} Communication exception sending reply back to client.FatalCommsException : Failed to send response to client. (File: clsMessageStream.cpp, line: 275

2012-11-04 09:48:01.275: [   CRSPE][1172498752] {3:33482:3505} PE Command [ Start Resource : 0x2aaaabc7f720 ] has completed

 

SMR is corrupted and will be recreated. All Health Check clients should disconnect and reconnect to the instance.
WARNING: Could not create SMR

 

Case 2:

2013-04-14 11:24:13.726: [ora.racdb.db][1177999680] {2:17464:2} [check] Gimh::check OH /oracle/db/11201 SID racdb1
2013-04-14 11:24:13.748: [ora.racdb.db][1177999680] {2:17464:2} [check] Gimh::check condition changes to (GIMH_NEXT_NUM) 0,19 exists
2013-04-14 11:24:13.748: [ora.racdb.db][1177999680] {2:17464:2} [check] (:CLSN00007:)DbAgent::check failed gimh state 0
2013-04-14 11:24:13.748: [ora.racdb.db][1177999680] {2:17464:2} [check] clsnDbAgent:checkCbk 20 clsagfw_res_status 19
2013-04-14 11:24:13.748: [ora.racdb.db][1177999680] {2:17464:2} [check] clsnDbAgent:checkCbk clsagfw_res_status 22
2013-04-14 11:24:13.748: [ USRTHRD][1177999680] {2:17464:2} Thread:DedicatedThreadstart {
2013-04-14 11:24:13.748: [ USRTHRD][1177999680] {2:17464:2} Thread:DedicatedThreadstart }
2013-04-14 11:24:13.748: [ora.racdb.db][1177999680] {2:17464:2} [check] ConnectionPool::startConnection s_statusOfConnectionMap 00a87d90
2013-04-14 11:24:13.748: [ USRTHRD][1146530112] {2:17464:2} DbAgent::Dedicated Thread {
2013-04-14 11:24:13.748: [ USRTHRD][1146530112] {2:17464:2} DbAgent::DThread getConnxn
2013-04-14 11:24:13.748: [ USRTHRD][1146530112] {2:17464:2} InstConnection::initMutex AttachLock 00a82400 DetachLock 00a82418
2013-04-14 11:24:13.748: [ora.racdb.db][1177999680] {2:17464:2} [check] ConnectionPool::startConnection sid racdb1 status 2
2013-04-14 11:24:13.748: [ora.racdb.db][1177999680] {2:17464:2} [check] InstAgent::check checkCounter 0 prev clsagfw_res_status 51 current clsagfw_res_status 4
2013-04-14 11:24:13.749: [ AGFW][1188489536] {2:17464:2} ora.racdb.db 2 1 state changed from: UNKNOWN to: PARTIAL
2013-04-14 11:24:13.749: [ AGFW][1188489536] {2:17464:2} Started implicit monitor for [ora.racdb.db 2 1] interval=1000 delay=1000
2013-04-14 11:24:13.749: [ AGFW][1188489536] {2:17464:2} ora.racdb.db 2 1 state details has changed from: to: Startup Initiated

 

 

 



Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms