Analyze CRSD logfiles using TINTs

Table of Contents

Find Policy Master

11.2 CRSD is implemented via master-slave model. Add any time we have one master ( PE MASTER )  and multiple slaves.

Find the current Policy Master:
# grep "PE MASTER" grac1/crsd.log  | tail -n 1
2013-08-15 11:55:03.476: [   CRSPE][3256813312] {1:27577:2} PE MASTER NAME: grac1
#  grep "PE MASTER" grac2/crsd.log  | tail -n 1
2013-08-15 11:55:19.864: [   CRSPE][809375488] {2:41059:2} PE MASTER NAME: grac1
-> Both crsd logiles reports grac1 as our CRSD Policy Master

 

Working with TINTs

A TINT is a EVENT identifier which allows us to track the operations done be clusterware. In the sample below 1:27577:445 is our TINT .
2013-08-15 13:41:55.624: [UiServer][3254712064] {1:27577:445} Container [ Name: UI_START

Let’s startup an instance and see what is happening. We run the srvctl on our PE Master ( grac1 ) and restart the instance on grac2. Following Threads/Actions are involved:

  • grac1: UI Interface get the request to to start the server
  • grac1: Policy engine ( PE ) checks the current state of the resource
  • grac1: Agfw Proxy Server on grac1 is sending the request to grac2
  • grac2: Agfw Proxy Server on grac2 is receiving this message
  • grac2: Agent starts resource on grac2
  • grac2: Agfw Proxy Server on grac2 sends status change to PE Master on grac1
$ srvctl start instance   -d GRACE2  -i  GRACE22

Check logfiles: crsd.log on grac1:
2013-08-15 13:41:55.624: [UiServer][3254712064] {1:27577:445} Container [ Name: UI_START
        API_HDR_VER:
        TextMessage[2]
        CLIENT:
        TextMessage[]
        CLIENT_NAME:
        TextMessage[/usr/bin/java]
        CLIENT_PID:
        TextMessage[22016]
        CLIENT_PRIMARY_GROUP:
        TextMessage[oinstall]
        FORCE_TAG:
        TextMessage[1]
        HOST:
        TextMessage[grac2]
        HOST_TAG:
        TextMessage[1]
        LOCALE:
        TextMessage[AMERICAN_AMERICA.US7ASCII]
        QUEUE_TAG:
        TextMessage[1]
        RESOURCE:
        TextMessage[ora.grace2.db] ]
2013-08-15 13:41:55.624: [UiServer][3254712064] {1:27577:445} Sending message to PE. ctx= 0x7f5dd4231ea0, Client PID: 22016
2013-08-15 13:41:55.624: [   CRSPE][3256813312] {1:27577:445} Cmd : 0x7f5dc813d8b0 : flags: FORCE_TAG | HOST_TAG | QUEUE_TAG
2013-08-15 13:41:55.631: [   CRSPE][3256813312] {1:27577:445} Processing PE command id=475. Description: [Start Resource : 0x7f5dc813d8b0]
2013-08-15 13:41:55.734: [   CRSPE][3256813312] {1:27577:445} Cant place WEAK DEP for:ora.gns exeption: CRS-0222: Resource 'ora.gns' has dependency error.
2013-08-15 13:41:55.738: [   CRSPE][3256813312] {1:27577:445} RI [ora.grace2.db 2 1] new target state: [ONLINE] old value: [OFFLINE]
2013-08-15 13:41:55.753: [  CRSOCR][3261015808] {1:27577:445} Multi Write Batch processing...
2013-08-15 13:41:55.761: [   CRSPE][3256813312] {1:27577:445} RI [ora.grace2.db 2 1] new internal state: [STARTING] old value: [STABLE]
2013-08-15 13:41:55.762: [   CRSPE][3256813312] {1:27577:445} Sending message to agfw: id = 3250
2013-08-15 13:41:55.767: [   CRSPE][3256813312] {1:27577:445} CRS-2672: Attempting to start 'ora.grace2.db' on 'grac2'
2013-08-15 13:41:55.768: [UiServer][3254712064] {1:27577:445} Container [ Name: ORDER
        MESSAGE:
        TextMessage[CRS-2672: Attempting to start 'ora.grace2.db' on 'grac2']
        MSGTYPE:
        TextMessage[3]
        OBJID:
        TextMessage[ora.grace2.db 2 1]
        WAIT:
        TextMessage[0]
]

crsd.log on grac2
2013-08-15 13:44:09.232: [    AGFW][819881728] {1:27577:445} Agfw Proxy Server received the message: RESOURCE_START[ora.grace2.db 2 1] ID 4098:3250
2013-08-15 13:44:09.232: [    AGFW][819881728] {1:27577:445} Creating the resource: ora.grace2.db 2 1
2013-08-15 13:44:09.232: [    AGFW][819881728] {1:27577:445} Initializing the resource ora.grace2.db 2 1 for type ora.database.type
2013-08-15 13:44:09.232: [    AGFW][819881728] {1:27577:445} SR: acl = owner:oracle:rwx,pgrp:oinstall:rwx,other::r--
2013-08-15 13:44:09.232: [    AGFW][819881728] {1:27577:445} Starting the agent: /u01/app/11203/grid/bin/oraagent with user id: oracle and incarnation:2
2013-08-15 13:44:09.236: [    AGFW][819881728] {1:27577:445} Starting the HB [Interval =  30000, misscount = 6kill allowed=1] for agent: /u01/app/11203/grid/bin/oraagent_oracle
2013-08-15 13:44:09.272: [CLSFRAME][826185472] New IPC Member:{Relative|Node:0|Process:6|Type:3}:AGENT
2013-08-15 13:44:09.272: [CLSFRAME][826185472] New process connected to us ID:{Relative|Node:0|Process:6|Type:3} Info:AGENT

oraagent_oracle on grac2 receives message and starts resouce 
2013-08-15 13:44:09.277: [    AGFW][819881728] {1:27577:445} Agfw Proxy Server forwarding the message: RESOURCE_START[ora.grace2.db 2 1] ID 4098:3250 to the agent /u01/app/11203/grid/bin/oraagent_oracle
2013-08-15 13:44:09.280: [    AGFW][819881728] {1:27577:445} Agfw Proxy Server replying to the message: AGENT_HANDSHAKE[Proxy] ID 20484:11
Agent log on grac2
2013-08-15 13:44:09.308: [    AGFW][3388983040] {1:27577:445} Agent received the message: RESOURCE_START[ora.grace2.db 2 1] ID 4098:1566
2013-08-15 13:44:09.308: [    AGFW][3388983040] {1:27577:445} Preparing START command for: ora.grace2.db 2 1
2013-08-15 13:44:09.308: [    AGFW][3388983040] {1:27577:445} ora.grace2.db 2 1 state changed from: UNKNOWN to: STARTING
2013-08-15 13:44:09.309: [ora.grace2.db][3422541568] {1:27577:445} [start] (:CLSN00107:) clsn_agent::start {
2013-08-15 13:44:09.309: [ora.grace2.db][3422541568] {1:27577:445} [start] Utils::getCrsHome crsHome /u01/app/11203/grid
2013-08-15 13:44:09.309: [ora.grace2.db][3422541568] {1:27577:445} [start] synchStatic {
2013-08-15 13:44:09.309: [ora.grace2.db][3422541568] {1:27577:445} [start] synchStatic }
2013-08-15 13:44:09.309: [ora.grace2.db][3422541568] {1:27577:445} [start] unsynchStatic {
2013-08-15 13:44:09.309: [ora.grace2.db][3422541568] {1:27577:445} [start] unsynchStatic }
2013-08-15 13:44:09.309: [ USRTHRD][3422541568] {1:27577:445} Worker::schedule thread 'ReconnectingSubscribers' not already created. Creating
2013-08-15 13:44:09.309: [ USRTHRD][3422541568] {1:27577:445} Worker::schedule adding worker 'ReconnSub-ScanRegSub-GRACE2' to thread 'ReconnectingSubscribers'
2013-08-15 13:44:09.309: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker starting self
2013-08-15 13:44:09.309: [ USRTHRD][3422541568] {1:27577:445} Thread:ReconnectingSubscribers start {
2013-08-15 13:44:09.309: [ USRTHRD][3422541568] {1:27577:445} Thread:ReconnectingSubscribers start }
2013-08-15 13:44:09.310: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:09.312: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:09.313: [ USRTHRD][3623876352] {1:27577:445} Thread:ReconnectingSubscribers run {
2013-08-15 13:44:09.314: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:09.314: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker total workers: 1
2013-08-15 13:44:09.314: [ USRTHRD][3422541568] {1:27577:445} Worker::schedule thread 'ClusterSubscriber' not already created. Creating
2013-08-15 13:44:09.314: [ USRTHRD][3422541568] {1:27577:445} Worker::schedule adding worker 'ClusterSubscriber ' to thread 'ClusterSubscriber'
2013-08-15 13:44:09.314: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker starting self
2013-08-15 13:44:09.315: [ USRTHRD][3422541568] {1:27577:445} Thread:ClusterSubscriber start {
2013-08-15 13:44:09.315: [ USRTHRD][3422541568] {1:27577:445} Thread:ClusterSubscriber start }
2013-08-15 13:44:09.315: [ USRTHRD][3355424512] {1:27577:445} Thread:ClusterSubscriber run {
2013-08-15 13:44:09.316: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:09.316: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker total workers: 1
2013-08-15 13:44:09.316: [ USRTHRD][3422541568] {1:27577:445} Thread:DedicatedThreadstop {
2013-08-15 13:44:09.316: [ USRTHRD][3422541568] {1:27577:445} Thread:DedicatedThreadstop }
013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent:getOracleSid 13 oracle_sid = GRACE22
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent:getOracleSid  oracle_sid = GRACE22
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] getOracleHomeAttrib: oracle_home = /u01/app/oracle/product/11203/racdb
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::ConnectionPool 2 m_oracleHome:/u01/app/oracle/product/11203/racdb, m_oracleSid:GRACE22, m_usrOraEnv:
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] InstAgent::start {
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::stopConnection
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::removeConnection connection count 0
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::removeConnection freed 0
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::stopConnection sid GRACE22 status  1
2013-08-15 13:44:09.316: [ USRTHRD][3422541568] {1:27577:445} ConnectionPool::~ConnectionPool m_oracleHome:/u01/app/oracle/product/11203/racdb, m_oracleSid:GRACE22, m_usrOraEnv:
2013-08-15 13:44:09.316: [ USRTHRD][3422541568] {1:27577:445} Thread:DedicatedThreadstop {
2013-08-15 13:44:09.316: [ USRTHRD][3422541568] {1:27577:445} Thread:DedicatedThreadstop }
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent:getOracleSid 13 oracle_sid = GRACE22
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent:getOracleSid  oracle_sid = GRACE22
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] getOracleHomeAttrib: oracle_home = /u01/app/oracle/product/11203/racdb
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::ConnectionPool 2 m_oracleHome:/u01/app/oracle/product/11203/racdb, m_oracleSid:GRACE22, m_usrOraEnv:
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent::setOracleSidAttrib updating GEN_USR_ORA_INST_NAME@SERVERNAME(grac2) to GRACE22
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] clsnUtils::setResAttrib nonPerX current value GEN_USR_ORA_INST_NAME value GRACE22
2013-08-15 13:44:09.316: [ora.grace2.db][3422541568] {1:27577:445} [start] CrsCmd::ClscrsCmdData::stat entity 1 statflag 32 useFilter 0
2013-08-15 13:44:09.342: [ora.grace2.db][3422541568] {1:27577:445} [start] setResAttrib: attr GEN_USR_ORA_INST_NAME@SERVERNAME(grac2) clsagfw attribVal GRACE22 clscrs tmpAttrValue GRACE22
2013-08-15 13:44:09.342: [ora.grace2.db][3422541568] {1:27577:445} [start] setResAttrib clsagfw_modify_attribute attr GEN_USR_ORA_INST_NAME@SERVERNAME(grac2) value GRACE22 retCode 0
2013-08-15 13:44:09.342: [ora.grace2.db][3422541568] {1:27577:445} [start] sModifyConfig for GRACE2
2013-08-15 13:44:09.343: [ora.grace2.db][3422541568] {1:27577:445} [start] getOracleHomeAttrib: oracle_home = /u01/app/oracle/product/11203/racdb
2013-08-15 13:44:09.343: [ora.grace2.db][3422541568] {1:27577:445} [start] Utils::getCrsHome crsHome /u01/app/11203/grid
2013-08-15 13:44:09.352: [ora.grace2.db][3422541568] {1:27577:445} [start] sclsnInstAgent::sUpdateOratab oratab is /etc/oratab
2013-08-15 13:44:09.352: [ora.grace2.db][3422541568] {1:27577:445} [start] sclsnInstAgent::sUpdateOratab CssLock
2013-08-15 13:44:09.355: [ora.grace2.db][3422541568] {1:27577:445} [start] ConfigFile::getValue name grace2 value
2013-08-15 13:44:09.357: [ora.grace2.db][3422541568] {1:27577:445} [start] ConfigFile::updateInPlace file /etc/oratab is updated
2013-08-15 13:44:09.357: [ora.grace2.db][3422541568] {1:27577:445} [start] sclsnInstAgent::sUpdateOratab file updated with dbName GRACE2 value /u01/app/oracle/product/11203/racdb:N
2013-08-15 13:44:09.357: [ora.grace2.db][3422541568] {1:27577:445} [start] sclsnInstAgent::sUpdateOratab CSS unlock
2013-08-15 13:44:09.368: [ora.grace2.db][3422541568] {1:27577:445} [start] ConfigFile:update file is /u01/app/oracle/product/11203/racdb/dbs/initGRACE22.ora not modified
2013-08-15 13:44:09.368: [ora.grace2.db][3422541568] {1:27577:445} [start] Utils::getCrsHome crsHome /u01/app/11203/grid
2013-08-15 13:44:09.368: [ora.grace2.db][3422541568] {1:27577:445} [start] crsHome = /u01/app/11203/grid
2013-08-15 13:44:09.368: [ora.grace2.db][3422541568] {1:27577:445} [start] oracleHome = /u01/app/oracle/product/11203/racdb
2013-08-15 13:44:09.368: [ora.grace2.db][3422541568] {1:27577:445} [start] command = '/u01/app/11203/grid/bin/setasmgidwrap oracle_binary_path=/u01/app/oracle/product/11203/racdb/bin/oracle'
2013-08-15 13:44:09.368: [ora.grace2.db][3422541568] {1:27577:445} [start] start dependency = hard(ora.DATA.dg) weak(type:ora.listener.type,global:type:ora.scan_listener.type,uniform:ora.ons,global:ora.gns) pullup(ora.DATA.dg)
2013-08-15 13:44:09.368: [ora.grace2.db][3422541568] {1:27577:445} [start] ASM disk group dependency found
2013-08-15 13:44:09.368: [ora.grace2.db][3422541568] {1:27577:445} [start] Utils:execCmd action = 1 flags = 6 ohome = /u01/app/11203/grid cmdname = setasmgidwrap.
2013-08-15 13:44:09.471: [ora.grace2.db][3422541568] {1:27577:445} [start] execCmd ret = 0
2013-08-15 13:44:09.472: [ USRTHRD][3422541568] {1:27577:445} InstConnection::initMutex AttachLock 00a8a6b8 DetachLock 00a8a6d0
2013-08-15 13:44:09.472: [ora.grace2.db][3422541568] {1:27577:445} [start] Utils::getCrsHome crsHome /u01/app/11203/grid
2013-08-15 13:44:09.472: [ora.grace2.db][3422541568] {1:27577:445} [start] clsnInstConnection::makeConnectStr UsrOraEnv  m_oracleHome /u01/app/oracle/product/11203/racdb Crshome /u01/app/11203/grid
2013-08-15 13:44:09.472: [ora.grace2.db][3422541568] {1:27577:445} [start] Utils::getCrsHome crsHome /u01/app/11203/grid
2013-08-15 13:44:09.473: [ora.grace2.db][3422541568] {1:27577:445} [start] clsnInstConnection::makeConnectStr LIBRARY_PATH1 ,LD_LIBRARY_PATH=
2013-08-15 13:44:09.473: [ora.grace2.db][3422541568] {1:27577:445} [start] makeConnectStr = (DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/u01/app/oracle/product/11203/racdb/bin/oracle)(ARGV0=oracleGRACE22)(ENVS='ORACLE_HOME=/u01/app/oracle/product/11203/racdb,ORACLE_SID=GRACE22,LD_LIBRARY_PATH=')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))(CONNECT_DATA=(SID=GRACE22)))
2013-08-15 13:44:09.477: [ora.grace2.db][3422541568] {1:27577:445} [start] Container:start oracle home /u01/app/oracle/product/11203/racdb
2013-08-15 13:44:09.477: [ora.grace2.db][3422541568] {1:27577:445} [start] InstConnection::connectInt: server not attached
2013-08-15 13:44:11.252: [ora.grace2.db][3422541568] {1:27577:445} [start] InstAgent::startup
2013-08-15 13:44:23.959: [ora.grace2.db][3422541568] {1:27577:445} [start] InstConnection::connectInt: server not attached
2013-08-15 13:44:24.073: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent::startCbk: {
2013-08-15 13:44:24.073: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent::startCbk: {
2013-08-15 13:44:24.075: [ USRTHRD][3422541568] {1:27577:445} Ocr Context init default level -1206663616
2013-08-15 13:44:24.076: [ USRTHRD][3422541568] {1:27577:445} Worker::schedule adding worker 'ClusterSubscriber ' to thread 'ClusterSubscriber'
2013-08-15 13:44:24.076: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker total workers: 2
2013-08-15 13:44:24.076: [ USRTHRD][3422541568] {1:27577:445} Worker::schedule thread 'EventBridges' not already created. Creating
2013-08-15 13:44:24.076: [ USRTHRD][3422541568] {1:27577:445} Worker::schedule adding worker 'DBAGENT-GRACE2' to thread 'EventBridges'
2013-08-15 13:44:24.076: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker starting self
2013-08-15 13:44:24.076: [ USRTHRD][3422541568] {1:27577:445} Thread:EventBridges start {
2013-08-15 13:44:24.076: [ USRTHRD][3422541568] {1:27577:445} Thread:EventBridges start }
2013-08-15 13:44:24.077: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:24.078: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:24.079: [ USRTHRD][2952787712] {1:27577:445} Thread:EventBridges run {
2013-08-15 13:44:24.080: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:24.080: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker total workers: 1
2013-08-15 13:44:24.080: [ USRTHRD][3422541568] {1:27577:445} Worker::schedule adding worker 'RLB-GRACE2' to thread 'EventBridges'
2013-08-15 13:44:24.080: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker total workers: 2
2013-08-15 13:44:24.080: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgentEventModule::keepRunning starting event bridge
2013-08-15 13:44:24.080: [ USRTHRD][3422541568] {1:27577:445} Worker::schedule adding worker 'SubscriberWorker ' to thread 'ClusterSubscriber'
2013-08-15 13:44:24.080: [ USRTHRD][3422541568] {1:27577:445} WorkerThread::addWorker total workers: 3
2013-08-15 13:44:24.080: [ USRTHRD][3422541568] {1:27577:445} In DedicatedThread::generateLocalListener
2013-08-15 13:44:24.080: [ USRTHRD][3422541568] {1:27577:445} synchStatic {
2013-08-15 13:44:24.080: [ USRTHRD][3422541568] {1:27577:445} synchStatic }
2013-08-15 13:44:24.081: [ USRTHRD][3422541568] {1:27577:445} unsynchStatic {
2013-08-15 13:44:24.081: [ USRTHRD][3422541568] {1:27577:445} unsynchStatic }
2013-08-15 13:44:24.081: [ USRTHRD][3422541568] {1:27577:445} CrsCmd::ClscrsCmdData::stat entity 1 statflag 1 useFilter 0
2013-08-15 13:44:24.085: [ USRTHRD][3355424512] ClusterSubscriber::SubscriberWorker::InternalClusterSubscriber::handleEventCBexecuting for reason 2
2013-08-15 13:44:24.100: [ USRTHRD][3422541568] {1:27577:445} CrsCmd::ClscrsCmdData::stat entity 1 statflag 1 useFilter 0
2013-08-15 13:44:24.121: [ USRTHRD][3422541568] {1:27577:445} Local dynamic VIP address is 192.168.1.112
2013-08-15 13:44:24.121: [ USRTHRD][3422541568] {1:27577:445} vipVector[0]=192.168.1.112
2013-08-15 13:44:24.121: [ USRTHRD][3422541568] {1:27577:445} m_crsHome = /u01/app/11203/grid
2013-08-15 13:44:24.155: [ USRTHRD][3422541568] {1:27577:445} CrsCmd::ClscrsCmdData::stat entity 5 statflag 16 useFilter 0
2013-08-15 13:44:24.188: [ USRTHRD][3422541568] {1:27577:445} CrsCmd::ClscrsCmdData::stat entity 1 statflag 1 useFilter 0
2013-08-15 13:44:24.211: [ USRTHRD][3422541568] {1:27577:445} ORACLE_HOME = /u01/app/11203/grid, START_DEPENDENCIES = hard(type:ora.cluster_vip_net1.type) pullup(type:ora.cluster_vip_net1.type) for ora.LISTENER.lsnr
2013-08-15 13:44:24.211: [ USRTHRD][3422541568] {1:27577:445} Add endpoint from ora.LISTENER.lsnr to LOCAL_LISTENER
2013-08-15 13:44:24.212: [ USRTHRD][3422541568] {1:27577:445} CrsCmd::ClscrsCmdData::stat entity 1 statflag 32 useFilter 0
2013-08-15 13:44:24.230: [ USRTHRD][3422541568] {1:27577:445} CrsCmd::ClscrsCmdData::stat 2-ClscrsCmdData::check clscrs_res_get_attr clscrsret:5  attribute:ENDPOINTS@SERVERNAME(grac2) value:null
2013-08-15 13:44:24.230: [ USRTHRD][3422541568] {1:27577:445} CrsCmd::ClscrsCmdData::stat entity 1 statflag 33 useFilter 0
2013-08-15 13:44:24.486: [ USRTHRD][3422541568] {1:27577:445} ORA-01405: fetched column value is NULL
2013-08-15 13:44:24.487: [ USRTHRD][3422541568] {1:27577:445} Value of LOCAL_LISTENER is
2013-08-15 13:44:24.487: [ USRTHRD][3422541568] {1:27577:445} sqlStmt = ALTER SYSTEM SET LOCAL_LISTENER=' (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=192.168.1.112)(PORT=1521))))' SCOPE=MEMORY SID='GRACE22' /* db agent *//* {1:27577:445} */
2013-08-15 13:44:24.491: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent::startCbk option 2 mount ALTER DATABASE MOUNT /* db agent *//* {1:27577:445} */
2013-08-15 13:44:30.448: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent::startCbk open ALTER DATABASE OPEN /* db agent *//* {1:27577:445} */
2013-08-15 13:44:33.586: [ USRTHRD][3422541568] {1:27577:445} DbAgentEventModule::notifyDbOpen database is now open
2013-08-15 13:44:33.586: [ USRTHRD][3422541568] {1:27577:445} DbAgentEventModule::notifyDbOpen starting AQ
2013-08-15 13:44:33.586: [ USRTHRD][3422541568] {1:27577:445} DbAgentEventModule::notifyDbOpen starting RLB
2013-08-15 13:44:33.586: [ CRSCEVT][3422541568] {1:27577:445} ClusterPublisher::connect connecting
2013-08-15 13:44:33.593: [ USRTHRD][2952787712] Worker::schedule thread 'CssSemaphores' not already created. Creating
2013-08-15 13:44:33.593: [ USRTHRD][2952787712] Worker::schedule adding worker 'Sem-CLSN.AQPROC.GRACE2.MASTER' to thread 'CssSemaphores'
2013-08-15 13:44:33.593: [ USRTHRD][2952787712] WorkerThread::addWorker starting self
2013-08-15 13:44:33.593: [ USRTHRD][2952787712] Thread:CssSemaphores start {
2013-08-15 13:44:33.593: [ USRTHRD][2952787712] Thread:CssSemaphores start }
2013-08-15 13:44:33.594: [ USRTHRD][2952787712] WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:33.595: [ USRTHRD][2952787712] WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:33.596: [ CRSCEVT][3422541568] {1:27577:445} ClusterPublisher::connect Connected
2013-08-15 13:44:33.596: [ora.grace2.db][3422541568] {1:27577:445} [start] DbAgent::startCbk: }
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] InstAgent::start: startConnection pool
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::stopConnection
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::removeConnection connection count 0
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::removeConnection freed 0
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::stopConnection sid GRACE22 status  1
2013-08-15 13:44:33.597: [ USRTHRD][3422541568] {1:27577:445} ConnectionPool::~ConnectionPool m_oracleHome:/u01/app/oracle/product/11203/racdb, m_oracleSid:GRACE22, m_usrOraEnv:
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::ConnectionPool 2 m_oracleHome:/u01/app/oracle/product/11203/racdb, m_oracleSid:GRACE22, m_usrOraEnv:
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::startConnection  s_statusOfConnectionMap 00a907a0
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::startConnection sid GRACE22 status  2
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] InstAgent::start release pConnxn 00825190 pConnxn
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] ConnectionPool::releaseConnection InstConnection b800dc90
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] InstAgent::start: }
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [start] (:CLSN00107:) clsn_agent::start }
2013-08-15 13:44:33.597: [    AGFW][3422541568] {1:27577:445} Command: start for resource: ora.grace2.db 2 1 completed with status: SUCCESS
2013-08-15 13:44:33.597: [ora.grace2.db][3422541568] {1:27577:445} [check] Gimh::check OH /u01/app/oracle/product/11203/racdb SID GRACE22
2013-08-15 13:44:33.598: [    AGFW][3388983040] {1:27577:445} Agent sending reply for: RESOURCE_START[ora.grace2.db 2 1] ID 4098:1566
2013-08-15 13:44:33.598: [CLSFRAME][3945805600] TM [MultiThread] is changing desired thread # to 3. Current # is 2
2013-08-15 13:44:33.598: [CLSFRAME][3945805600] TM [MultiThread] is changing desired thread # to 4. Current # is 3
2013-08-15 13:44:33.600: [ USRTHRD][2952787712] WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:33.600: [ora.grace2.db][3422541568] {1:27577:445} [check] Gimh::check condition changes to (GIMH_NEXT_NUM) 9 exists
2013-08-15 13:44:33.601: [ora.grace2.db][3422541568] {1:27577:445} [check] updating GEN_START_OPTIONS from  to open
2013-08-15 13:44:33.601: [ USRTHRD][3422541568] {1:27577:445} Thread:DedicatedThreadstart {
2013-08-15 13:44:33.601: [ USRTHRD][3422541568] {1:27577:445} Thread:DedicatedThreadstart }
2013-08-15 13:44:33.601: [    AGFW][3388983040] {1:27577:445} ora.grace2.db 2 1 state changed from: STARTING to: ONLINE
2013-08-15 13:44:33.601: [    AGFW][3388983040] {1:27577:445} Started implicit monitor for [ora.grace2.db 2 1] interval=1000 delay=1000
2013-08-15 13:44:33.601: [    AGFW][3388983040] {1:27577:445} ora.grace2.db 2 1 state details has changed from:  to: Open
2013-08-15 13:44:33.601: [    AGFW][3388983040] {1:27577:445} Agent sending last reply for: RESOURCE_START[ora.grace2.db 2 1] ID 4098:1566
2013-08-15 13:44:33.603: [ USRTHRD][2952787712] WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:33.604: [ USRTHRD][2952787712] WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:33.605: [ USRTHRD][2852112128] Thread:CssSemaphores run {
2013-08-15 13:44:33.605: [ USRTHRD][2751436544] {1:27577:445} DbAgent::Dedicated Thread {
2013-08-15 13:44:33.605: [ USRTHRD][2751436544] {1:27577:445} CrsCmd::ClscrsCmdData::stat entity 1 statflag 32 useFilter 0
2013-08-15 13:44:33.606: [ USRTHRD][2952787712] WorkerThread::addWorker waiting for thread to start
2013-08-15 13:44:33.606: [ USRTHRD][2952787712] WorkerThread::addWorker total workers: 1
2013-08-15 13:44:33.619: [ USRTHRD][2952787712] Utils::getCrsHome crsHome /u01/app/11203/grid
2013-08-15 13:44:33.619: [ USRTHRD][2952787712] clsnInstConnection::makeConnectStr UsrOraEnv  m_oracleHome /u01/app/oracle/product/11203/racdb Crshome /u01/app/11203/grid
2013-08-15 13:44:33.619: [ USRTHRD][2952787712] Utils::getCrsHome crsHome /u01/app/11203/grid
2013-08-15 13:44:33.619: [ USRTHRD][2952787712] clsnInstConnection::makeConnectStr LIBRARY_PATH1 ,LD_LIBRARY_PATH=
2013-08-15 13:44:33.619: [ USRTHRD][2952787712] makeConnectStr = (DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/u01/app/oracle/product/11203/racdb/bin/oracle)(ARGV0=oracleGRACE22)(ENVS='ORACLE_HOME=/u01/app/oracle/product/11203/racdb,ORACLE_SID=GRACE22,LD_LIBRARY_PATH=')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))(CONNECT_DATA=(SID=GRACE22)))
2013-08-15 13:44:33.619: [ USRTHRD][2952787712] InstConnection::connectInt: server not attached
2013-08-15 13:44:33.654: [ USRTHRD][2751436544] {1:27577:445} setResAttrib: attr GEN_START_OPTIONS@SERVERNAME(grac2) clsagfw attribVal open clscrs tmpAttrValue open
2013-08-15 13:44:33.654: [ USRTHRD][2751436544] {1:27577:445} setResAttrib clsagfw_modify_attribute attr GEN_START_OPTIONS@SERVERNAME(grac2) value open retCode 0
2013-08-15 13:44:33.654: [ USRTHRD][2751436544] {1:27577:445} DbAgent::DThread getConnxn
2013-08-15 13:44:33.655: [ USRTHRD][2751436544] {1:27577:445} Utils::getCrsHome crsHome /u01/app/11203/grid
2013-08-15 13:44:33.655: [ USRTHRD][2751436544] {1:27577:445} clsnInstConnection::makeConnectStr UsrOraEnv  m_oracleHome /u01/app/oracle/product/11203/racdb Crshome /u01/app/11203/grid
2013-08-15 13:44:33.656: [ USRTHRD][2751436544] {1:27577:445} Utils::getCrsHome crsHome /u01/app/11203/grid
2013-08-15 13:44:33.656: [ USRTHRD][2751436544] {1:27577:445} clsnInstConnection::makeConnectStr LIBRARY_PATH1 ,LD_LIBRARY_PATH=
2013-08-15 13:44:33.656: [ USRTHRD][2751436544] {1:27577:445} makeConnectStr = (DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/u01/app/oracle/product/11203/racdb/bin/oracle)(ARGV0=oracleGRACE22)(ENVS='ORACLE_HOME=/u01/app/oracle/product/11203/racdb,ORACLE_SID=GRACE22,LD_LIBRARY_PATH=')(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))(CONNECT_DATA=(SID=GRACE22)))
2013-08-15 13:44:33.656: [ USRTHRD][2751436544] {1:27577:445} InstConnection::connectInt: server not attached
2013-08-15 13:44:33.707: [ USRTHRD][3355424512] ClusterSubscriber::SubscriberWorker::InternalClusterSubscriber::handleEventCBexecuting for reason 1
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] event type is CRS_RESOURCE_STATE_CHANGE
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] bodylen = 744
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445} -----------BodyBlock----------
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  CLS_TINT='{1:27577:445}'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  COMPOSITE_RESOURCE_STATUS=''
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  CURRENT_STATE='ONLINE'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  DATABASE_TYPE='RAC'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  DB_UNIQUE_NAME='grace2'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  DEGREE='1'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  DERIVED_STATE='ONLINE'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  ID='32092222'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  INSTANCE_NAME='GRACE22'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  INTERMEDIATE_INSTANCE_COUNT='0'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  NAME='ora.grace2.db'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  ONLINE_INSTANCE_COUNT='2'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  PREVIOUS_STATE='OFFLINE'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  PREV_STATE_DETAILS='Instance Shutdown'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  REASON='USER_ACTION'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  RESOURCE_CLASS='database'
2013-08-15 13:44:33.708: [ USRTHRD][3355424512] {1:27579:445}  RESOURCE_INCARNATION_NUMBER='1'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  RESOURCE_INSTANCE_ID='ora.grace2.db 2 1'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  RESOURCE_LOCATION='grac2'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  SEQUENCE_NUMBER='2400058'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  STATE_DETAILS='Open'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  TIMESTAMP='2013-08-15 13:42:19'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  TOTAL_INSTANCE_COUNT='2'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  TYPE='ora.database.type'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  UNKNOWN_INSTANCE_COUNT='0'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  USER='grid'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  Version='11.2.0.3.0'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  CLUSTER_NAME='GRACE2'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  DB_UNIQUE_NAME='grace2'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  ORACLE_CLUSTERWARE.SUBCOMPONENT='CRSD'
2013-08-15 13:44:33.710: [ USRTHRD][3355424512] {1:27579:445}  RESOURCE_CLASS='database'
2013-08-15 13:44:33.894: [ USRTHRD][2751436544] {1:27577:445} ORA-01405: fetched column value is NULL
2013-08-15 13:44:33.894: [ USRTHRD][2751436544] {1:27577:445} CrsCmd::ClscrsCmdData::stat entity 1 statflag 32 useFilter 0
2013-08-15 13:44:33.912: [ USRTHRD][2952787712] RLB-GRACE2.GRACE2 RlbEventPoller::poll purging messages before starting to read
2013-08-15 13:44:33.929: [ USRTHRD][2751436544] {1:27577:445} setResAttrib: attr USR_ORA_DOMAIN clsagfw attribVal  clscrs tmpAttrValue
2013-08-15 13:44:33.929: [ USRTHRD][2751436544] {1:27577:445} setResAttrib clsagfw_modify_attribute attr USR_ORA_DOMAIN value  retCode 0
2013-08-15 13:44:33.929: [ USRTHRD][2751436544] {1:27577:445} DbAgent::check set domain to
2013-08-15 13:44:33.929: [ USRTHRD][2751436544] {1:27577:445} DbAgent::check set domain to
2013-08-15 13:44:33.932: [ USRTHRD][2751436544] {1:27577:445} CrsCmd::ClscrsCmdData::stat entity 1 statflag 32 useFilter 0
2013-08-15 13:44:33.953: [ USRTHRD][2751436544] {1:27577:445} setResAttrib: attr GEN_AUDIT_FILE_DEST clsagfw attribVal /u01/app/oracle/admin/GRACE2/adump clscrs tmpAttrValue /u01/app/oracle/admin/GRACE2/adump
2013-08-15 13:44:33.953: [ USRTHRD][2751436544] {1:27577:445} setResAttrib clsagfw_modify_attribute attr GEN_AUDIT_FILE_DEST value /u01/app/oracle/admin/GRACE2/adump retCode 0
2013-08-15 13:44:33.953: [ USRTHRD][2751436544] {1:27577:445} DbAgent::check Audit file dest is /u01/app/oracle/admin/GRACE2/adump
2013-08-15 13:44:33.953: [ USRTHRD][2751436544] {1:27577:445} InstConnection:~InstConnection: this c0007a00
2013-08-15 13:44:33.953: [ USRTHRD][2751436544] {1:27577:445} Dedicated Thread }
2013-08-15 13:44:33.953: [ USRTHRD][2751436544] {1:27577:445} Thread:DedicatedThreadisRunning is reset to false here
2013-08-15 13:44:34.605: [ USRTHRD][3422541568] {1:27577:445} Thread:DedicatedThreadstop {
2013-08-15 13:44:34.607: [ USRTHRD][3422541568] {1:27577:445} Thread:DedicatedThreadstop }
2013-08-15 13:44:44.331: [ USRTHRD][2952787712] Worker::schedule adding worker 'Sem-CLSN.RLB.GRACE2.MASTER' to thread 'CssSemaphores'
2013-08-15 13:44:44.331: [ USRTHRD][2952787712] WorkerThread::addWorker total workers: 2
2013-08-15 13:45:03.610: [CLSFRAME][3945805600] TM [MultiThread] is changing desired thread # to 3. Current # is 4
2013-08-15 13:45:09.251: [    AGFW][3388983040] {1:27577:445} Agent received the message: AGENT_HB[Engine] ID 12293:1632
2013-08-15 13:45:32.635: [ora.grace2.db][2784995072] {1:27577:445} [check] InstAgent::check checkCounter 60 prev clsagfw_res_status 0 current clsagfw_res_status 0
2013-08-15 13:46:09.255: [    AGFW][3388983040] {1:27577:445} Agent received the message: AGENT_HB[Engine] ID 12293:1643
2013-08-15 13:46:32.677: [ora.grace2.db][2818553600] {1:27577:445} [check] InstAgent::check checkCounter 60 prev clsagfw_res_status 0 current clsagfw_res_status 0
2013-08-15 13:46:33.669: [CLSFRAME][3945805600] TM [MultiThread] is changing desired thread # to 3. Current # is 4
2013-08-15 13:46:39.258: [    AGFW][3388983040] {1:27577:445} Agent received the message: AGENT_HB[Engine] ID 12293:1652

Crsd.log on grac1 receives that resource status change 
2013-08-15 13:42:19.652: [   CRSPE][3256813312] {1:27577:445} Received reply to action [Start] message ID: 3250
2013-08-15 13:42:19.655: [   CRSPE][3256813312] {1:27577:445} Received reply to action [Start] message ID: 3250
2013-08-15 13:42:19.655: [   CRSPE][3256813312] {1:27577:445} RI [ora.grace2.db 2 1] new internal state: [STABLE] old value: [STARTING]
2013-08-15 13:42:19.655: [   CRSPE][3256813312] {1:27577:445} RI [ora.grace2.db 2 1] new external state [ONLINE] old value: [OFFLINE] on grac2 label = [Open]
2013-08-15 13:42:19.655: [   CRSPE][3256813312] {1:27577:445} Set State Details to [Open] from [ Instance Shutdown] for [ora.grace2.db 2 1]
2013-08-15 13:42:19.669: [   CRSPE][3256813312] {1:27577:445} CRS-2676: Start of 'ora.grace2.db' on 'grac2' succeeded
2013-08-15 13:42:19.706: [  CRSRPT][3254712064] {1:27577:445} Published to EVM CRS_RESOURCE_STATE_CHANGE for ora.grace2.db
2013-08-15 13:42:19.706: [UiServer][3254712064] {1:27577:445} Container [ Name: ORDER
        MESSAGE:
        TextMessage[CRS-2676: Start of 'ora.grace2.db' on 'grac2' succeeded]
        MSGTYPE:
        TextMessage[3]
        OBJID:
        TextMessage[ora.grace2.db 2 1]
        WAIT:
        TextMessage[0]]
2013-08-15 13:42:19.707: [UiServer][3254712064] {1:27577:445} Container [ Name: UI_DATA
        ora.grace2.db 2 1:
        TextMessage[0]]
2013-08-15 13:42:19.707: [UiServer][3254712064] {1:27577:445} Done for ctx=0x7f5dd4231ea0

crsd.log on grac2 
2013-08-15 13:44:33.599: [    AGFW][819881728] {1:27577:445} Received the reply to the message: RESOURCE_START[ora.grace2.db 2 1] ID 4098:1566 from the agent /u01/app/11203/grid/bin/oraagent_oracle
2013-08-15 13:44:33.599: [    AGFW][819881728] {1:27577:445} Agfw Proxy Server sending the reply to PE for message:RESOURCE_START[ora.grace2.db 2 1] ID 4098:3250
2013-08-15 13:44:33.602: [    AGFW][819881728] {1:27577:445} Received the reply to the message: RESOURCE_START[ora.grace2.db 2 1] ID 4098:1566 from the agent /u01/app/11203/grid/bin/oraagent_oracle
2013-08-15 13:44:33.602: [    AGFW][819881728] {1:27577:445} Agfw Proxy Server sending the last reply to PE for message:RESOURCE_START[ora.grace2.db 2 1] ID 4098:3250

Leave a Reply

Your email address will not be published. Required fields are marked *