Oracle RAC备库启动service报"ORA-16000: database open for read-only access"
Oracle RAC备库启动service报"ORA-16000: database open for read-only access"
还是2019.03.01那天的事了,当时在KFT客户就遇到这个问题,最近在规整一些资料看到当时待整理的文档,就抽空做做实验整理下。
报错信息如下,ADG备库:
[oracle@xxxprdoradb01 ~]$ srvctl start service -d xxxdbdr2 -s xxxdbcss PRCD-1084 : Failed to start service xxxdbcss PRCR-1079 : Failed to start resource ora.xxxdbdr2.xxxdbcss.svc CRS-5017: The resource action "ora.xxxdbdr2.xxxdbcss.svc start" encountered the following error: ORA-16000: database open for read-only access ORA-06512: at "SYS.DBMS_SERVICE", line 433 ORA-06512: at "SYS.DBMS_SERVICE", line 304 ORA-06512: at line 1 . For details refer to "(:CLSN00107:)" in "/u01/oracle/grid/110203/log/xxxprdoradb01/agent/crsd/oraagent_oracle/oraagent_oracle.log". CRS-2674: Start of 'ora.xxxdbdr2.xxxdbcss.svc' on 'xxxprdoradb01' failed CRS-5017: The resource action "ora.xxxdbdr2.xxxdbcss.svc start" encountered the following error: ORA-16000: database open for read-only access ORA-06512: at "SYS.DBMS_SERVICE", line 433 ORA-06512: at "SYS.DBMS_SERVICE", line 304 ORA-06512: at line 1 . For details refer to "(:CLSN00107:)" in "/u01/oracle/grid/110203/log/xxxprdoradb02/agent/crsd/oraagent_oracle/oraagent_oracle.log". CRS-2674: Start of 'ora.xxxdbdr2.xxxdbcss.svc' on 'xxxprdoradb02' failed CRS-2632: There are no more servers to try to place resource 'ora.xxxdbdr2.xxxdbcss.svc' on that would satisfy its placement policy
其中,/u01/oracle/grid/110203/log/xxxprdoradb01/agent/crsd/oraagent_oracle/oraagent_oracle.log文件相关内容如下:
2019-03-01 19:55:48.191: [ AGFW][3892311808] {1:14336:11864} Agent received the message: AGENT_HB[Engine] ID 12293:2664818 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] ClusterSubscriber::SubscriberWorker::InternalClusterSubscriber::handleEventCBexecuting for reason 1 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] event type is CRS_ACTION_FAILURE 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] bodylen = 538 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} -----------BodyBlock---------- 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} ACTION='1' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} CLS_TINT='{1:14336:56597}' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} CURRENT_STATE='OFFLINE' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} DB_UNIQUE_NAME='xxxdbdr2' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} INSTANCE_NAME='xxxdb2' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} NAME='ora.xxxdbdr2.xxxdbcss.svc' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} NUMBER_OF_ATTEMPTS='0' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} REASON='USER_ACTION' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} RESOURCE_CLASS='service' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} RESOURCE_INCARNATION_NUMBER='0' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} RESOURCE_LOCATION='xxxprdoradb02' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} SEQUENCE_NUMBER='1400583' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} SERVICE_NAME='' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} TARGET_STATE='ONLINE' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} TIMESTAMP='2019-03-01 19:55:49' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} TYPE='ora.service.type' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} USER='oracle' 2019-03-01 19:55:49.300: [ USRTHRD][3758094080] {1:14338:56597} Version='11.2.0.3.0' 2019-03-01 19:55:49.301: [ USRTHRD][3758094080] {1:14338:56597} CLUSTER_NAME='xxxdb01-scan' 2019-03-01 19:55:49.301: [ USRTHRD][3758094080] {1:14338:56597} DB_UNIQUE_NAME='xxxdbdr2' 2019-03-01 19:55:49.301: [ USRTHRD][3758094080] {1:14338:56597} ORACLE_CLUSTERWARE.SUBCOMPONENT='CRSD' 2019-03-01 19:55:49.301: [ USRTHRD][3758094080] {1:14338:56597} RESOURCE_CLASS='service' 2019-03-01 19:55:49.301: [ USRTHRD][3758094080] {1:14338:56597} SERVICE_NAME='' 2019-03-01 19:55:49.301: [ USRTHRD][3758094080] {1:14338:56597} DbAgentEventModule::LsnrRegSubscriber::handleEvent { 2019-03-01 19:55:49.301: [ USRTHRD][3758094080] {1:14338:56597} DbAgentEventModule::LsnrRegSubscriber::handleEvent } 2019-03-01 19:55:49.316: [ AGFW][3892311808] {1:14336:56597} Agent received the message: RESOURCE_START[ora.xxxdbdr2.xxxdbcss.svc 1 1] ID 4098:2664821 2019-03-01 19:55:49.316: [ AGFW][3892311808] {1:14336:56597} Preparing START command for: ora.xxxdbdr2.xxxdbcss.svc 1 1 2019-03-01 19:55:49.317: [ AGFW][3892311808] {1:14336:56597} ora.xxxdbdr2.xxxdbcss.svc 1 1 state changed from: OFFLINE to: STARTING 2019-03-01 19:55:49.318: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] (:CLSN00107:) clsn_agent::start { 2019-03-01 19:55:49.318: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getSvcName SERVICE_NAME xxxdbcss 2019-03-01 19:55:49.318: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::start: enter { 2019-03-01 19:55:49.318: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::start m_pConnxn lost 2019-03-01 19:55:49.318: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::refresh 2019-03-01 19:55:49.318: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getSvcName SERVICE_NAME xxxdbcss 2019-03-01 19:55:49.318: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] ConnectionPool::ConnectionPool 2 m_oracleHome:/u01/oracle/oracle/product/110203, m_oracleSid:xxxdb2, m_usrOraEnv: 2019-03-01 19:55:49.318: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] ConnectionPool::getConnection 260 pConnxn ac0b52e0 2019-03-01 19:55:49.319: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::start: query network name of xxxdbcss 2019-03-01 19:55:49.319: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::execSql 2 xxxdbcss 2019-03-01 19:55:49.319: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::execSql:QUERY_SVC_STMT m_defineCount 11 m_resServiceName xxxdbcss 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::execSql:QUERY_SVC_STMT result m_dbServiceName xxxdbcss m_dbNetworkName xxxdbcss m_dbRlbGoal NONE m_dbDtp 0 m_dbAqHaNotification 0 m_dbFailoverMethod NONE m_dbFailoverType NONE m_dbFailoverRetries 0 m_dbFailoverDelay 0 m_dbClbGoal LONG m_dbEdition 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getAndSetBindVal placeholder :goal_name attrib RLB_GOAL value NONE 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getAndSetBindVal placeholder :dtp attrib DTP value 0 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getAndSetBindVal placeholder :aq_ha_notification attrib AQ_HA_NOTIFICATION value 0 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getAndSetBindVal placeholder :failover_method attrib FAILOVER_METHOD value NONE 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getAndSetBindVal placeholder :failover_type attrib FAILOVER_TYPE value SESSION 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getAndSetBindVal placeholder :failover_retries attrib FAILOVER_RETRIES value 0 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::setBindVal placeHolder :failover_retries value 0 value length 1 intValue 0 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getAndSetBindVal placeholder :failover_delay attrib FAILOVER_DELAY value 0 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::setBindVal placeHolder :failover_delay value 0 value length 1 intValue 0 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getAndSetBindVal placeholder :clb_goal_name attrib CLB_GOAL value LONG 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::getAndSetBindVal placeholder :edition attrib EDITION value 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::bindResValues m_resServiceName xxxdbcss m_resNetworkName xxxdbcss m_resRlbGoal NONE m_resDtp 0 m_resAqHaNotification 0 m_resFailoverMethod NONE m_resFailoverType SESSION m_resFailoverRetries 0 m_resFailoverDelay 0 m_resIntFailoverRetries 0 m_resIntFailoverDelay 0 m_resClbGoal LONG m_resEdition 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::execSql 3 xxxdbcss 2019-03-01 19:55:49.320: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::execSql:MODIFY_SVC_STMT m_bindCount 11 m_resServiceName xxxdbcss 2019-03-01 19:55:49.325: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] ORA-16000: database open for read-only access ORA-06512: at "SYS.DBMS_SERVICE", line 433 ORA-06512: at "SYS.DBMS_SERVICE", line 304 ORA-06512: at line 1 2019-03-01 19:55:49.325: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::execSql action 3 error ORA-16000: database open for read-only access ORA-06512: at "SYS.DBMS_SERVICE", line 433 ORA-06512: at "SYS.DBMS_SERVICE", line 304 ORA-06512: at line 1 2019-03-01 19:55:49.326: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] InstConnection::connectInt: server not attached 2019-03-01 19:55:49.376: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] InstConnection:connectInt connected 2019-03-01 19:55:49.377: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::execSql:MODIFY_SVC_STMT m_bindCount 11 m_resServiceName xxxdbcss 2019-03-01 19:55:49.380: [CLSFRAME][502269728] TM [MultiThread] is changing desired thread # to 5. Current # is 4 2019-03-01 19:55:49.381: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] ORA-16000: database open for read-only access ORA-06512: at "SYS.DBMS_SERVICE", line 433 ORA-06512: at "SYS.DBMS_SERVICE", line 304 ORA-06512: at line 1 2019-03-01 19:55:49.381: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] SvcAgent::execSql action 3 error ORA-16000: database open for read-only access ORA-06512: at "SYS.DBMS_SERVICE", line 433 ORA-06512: at "SYS.DBMS_SERVICE", line 304 ORA-06512: at line 1 2019-03-01 19:55:49.382: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] ConnectionPool::releaseConnection InstConnection ac0b52e0 2019-03-01 19:55:49.382: [ AGENT][2885678848] {1:14336:56597} UserErrorException: Locale is 2019-03-01 19:55:49.382: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] clsnUtils::error Exception type=2 string= CRS-5017: The resource action "ora.xxxdbdr2.xxxdbcss.svc start" encountered the following error: ORA-16000: database open for read-only access ORA-06512: at "SYS.DBMS_SERVICE", line 433 ORA-06512: at "SYS.DBMS_SERVICE", line 304 ORA-06512: at line 1 . For details refer to "(:CLSN00107:)" in "/u01/oracle/grid/110203/log/xxxprdoradb02/agent/crsd/oraagent_oracle/oraagent_oracle.log". 2019-03-01 19:55:49.382: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [start] (:CLSN00107:) clsn_agent::start } 2019-03-01 19:55:49.382: [ AGFW][2885678848] {1:14336:56597} Command: start for resource: ora.xxxdbdr2.xxxdbcss.svc 1 1 completed with status: FAIL 2019-03-01 19:55:49.383: [ AGFW][3892311808] {1:14336:56597} Agent sending reply for: RESOURCE_START[ora.xxxdbdr2.xxxdbcss.svc 1 1] ID 4098:2664821 2019-03-01 19:55:49.383: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] isCheckDone m_isCheckDone ac056eb8 1 2019-03-01 19:55:49.383: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] DbAgent::isFailed m_lastState 0 2019-03-01 19:55:49.383: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::refresh 2019-03-01 19:55:49.383: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::getSvcName SERVICE_NAME xxxdbcss 2019-03-01 19:55:49.383: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] ConnectionPool::getConnection 260 pConnxn ac0b52e0 2019-03-01 19:55:49.383: [ AGFW][3892311808] {1:14336:56597} Agent sending reply for: RESOURCE_START[ora.xxxdbdr2.xxxdbcss.svc 1 1] ID 4098:2664821 2019-03-01 19:55:49.384: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::check OCI error 1403 2019-03-01 19:55:49.384: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] ConnectionPool::releaseConnection InstConnection ac0b52e0 2019-03-01 19:55:49.384: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::check 4 ret 1 2019-03-01 19:55:49.384: [ USRTHRD][2885678848] {1:14336:56597} ConnectionPool::~ConnectionPool m_oracleHome:/u01/oracle/oracle/product/110203, m_oracleSid:xxxdb2, m_usrOraEnv: 2019-03-01 19:55:49.384: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::check ret:1 exit } 2019-03-01 19:55:49.385: [ AGFW][3892311808] {1:14336:56597} ora.xxxdbdr2.xxxdbcss.svc 1 1 state changed from: STARTING to: OFFLINE 2019-03-01 19:55:49.385: [ AGFW][3892311808] {1:14336:56597} Agent sending last reply for: RESOURCE_START[ora.xxxdbdr2.xxxdbcss.svc 1 1] ID 4098:2664821 2019-03-01 19:55:49.396: [ AGFW][3892311808] {1:14336:56597} Agent received the message: RESOURCE_CLEAN[ora.xxxdbdr2.xxxdbcss.svc 1 1] ID 4100:2664826 2019-03-01 19:55:49.396: [ AGFW][3892311808] {1:14336:56597} Preparing CLEAN command for: ora.xxxdbdr2.xxxdbcss.svc 1 1 2019-03-01 19:55:49.396: [ AGFW][3892311808] {1:14336:56597} ora.xxxdbdr2.xxxdbcss.svc 1 1 state changed from: OFFLINE to: CLEANING 2019-03-01 19:55:49.396: [ USRTHRD][3758094080] {1:14338:56597} ClusterSubscriber::SubscriberWorker::InternalClusterSubscriber::handleEventCBexecuting for reason 1 2019-03-01 19:55:49.396: [ USRTHRD][3758094080] {1:14338:56597} event type is CRS_ACTION_FAILURE 2019-03-01 19:55:49.396: [ USRTHRD][3758094080] {1:14338:56597} bodylen = 538 2019-03-01 19:55:49.396: [ USRTHRD][3758094080] {1:14338:56597} -----------BodyBlock---------- 2019-03-01 19:55:49.396: [ USRTHRD][3758094080] {1:14338:56597} ACTION='1' 2019-03-01 19:55:49.396: [ USRTHRD][3758094080] {1:14338:56597} CLS_TINT='{1:14336:56597}' 2019-03-01 19:55:49.396: [ USRTHRD][3758094080] {1:14338:56597} CURRENT_STATE='OFFLINE' 2019-03-01 19:55:49.396: [ USRTHRD][3758094080] {1:14338:56597} DB_UNIQUE_NAME='xxxdbdr2' 2019-03-01 19:55:49.396: [ USRTHRD][3758094080] {1:14338:56597} INSTANCE_NAME='xxxdb1' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} NAME='ora.xxxdbdr2.xxxdbcss.svc' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} NUMBER_OF_ATTEMPTS='0' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} REASON='USER_ACTION' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} RESOURCE_CLASS='service' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} RESOURCE_INCARNATION_NUMBER='0' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} RESOURCE_LOCATION='xxxprdoradb01' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} SEQUENCE_NUMBER='1400584' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} SERVICE_NAME='' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} TARGET_STATE='ONLINE' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} TIMESTAMP='2019-03-01 19:55:49' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} TYPE='ora.service.type' 2019-03-01 19:55:49.397: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] (:CLSN00106:) clsn_agent::clean { 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} USER='oracle' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} Version='11.2.0.3.0' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} CLUSTER_NAME='xxxdb01-scan' 2019-03-01 19:55:49.397: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] clean { 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} DB_UNIQUE_NAME='xxxdbdr2' 2019-03-01 19:55:49.397: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] SvcAgent::stop: enter { 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} ORACLE_CLUSTERWARE.SUBCOMPONENT='CRSD' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} RESOURCE_CLASS='service' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} SERVICE_NAME='' 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} DbAgentEventModule::LsnrRegSubscriber::handleEvent { 2019-03-01 19:55:49.397: [ USRTHRD][3758094080] {1:14338:56597} DbAgentEventModule::LsnrRegSubscriber::handleEvent } 2019-03-01 19:55:49.397: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] DbAgent::isFailed m_lastState 0 2019-03-01 19:55:49.397: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] SvcAgent::stop m_pConnxn lost 2019-03-01 19:55:49.397: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] SvcAgent::refresh 2019-03-01 19:55:49.397: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] SvcAgent::getSvcName SERVICE_NAME xxxdbcss 2019-03-01 19:55:49.397: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] ConnectionPool::ConnectionPool 2 m_oracleHome:/u01/oracle/oracle/product/110203, m_oracleSid:xxxdb2, m_usrOraEnv: 2019-03-01 19:55:49.397: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] ConnectionPool::getConnection 260 pConnxn ac0b52e0 2019-03-01 19:55:49.398: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] SvcAgent::stop: stopping xxxdbcss 2019-03-01 19:55:49.399: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] ORA-44311: service xxxdbcss not running ORA-06512: at "SYS.DBMS_SYS_ERROR", line 86 ORA-06512: at "SYS.DBMS_SERVICE", line 466 ORA-06512: at "SYS.DBMS_SERVICE", line 400 ORA-06512: at line 1 2019-03-01 19:55:49.399: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] SvcAgent::stop: ignoring OCI error 44311 } 2019-03-01 19:55:49.399: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] ConnectionPool::releaseConnection InstConnection ac0b52e0 2019-03-01 19:55:49.399: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] SvcAgent::stop: m_pConnxn 00000000m_pConnectionPool a40149b0 2019-03-01 19:55:49.399: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] SvcAgent::stop: } 2019-03-01 19:55:49.399: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] clean } 2019-03-01 19:55:49.399: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [clean] (:CLSN00106:) clsn_agent::clean } 2019-03-01 19:55:49.399: [ AGFW][2885678848] {1:14336:56597} Command: clean for resource: ora.xxxdbdr2.xxxdbcss.svc 1 1 completed with status: SUCCESS 2019-03-01 19:55:49.400: [ AGFW][3892311808] {1:14336:56597} Agent sending reply for: RESOURCE_CLEAN[ora.xxxdbdr2.xxxdbcss.svc 1 1] ID 4100:2664826 2019-03-01 19:55:49.400: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] isCheckDone m_isCheckDone ac056eb8 1 2019-03-01 19:55:49.400: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] DbAgent::isFailed m_lastState 0 2019-03-01 19:55:49.400: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::refresh 2019-03-01 19:55:49.400: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::getSvcName SERVICE_NAME xxxdbcss 2019-03-01 19:55:49.400: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] ConnectionPool::getConnection 260 pConnxn ac0b52e0 2019-03-01 19:55:49.401: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::check OCI error 1403 2019-03-01 19:55:49.401: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] ConnectionPool::releaseConnection InstConnection ac0b52e0 2019-03-01 19:55:49.401: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::check 4 ret 1 2019-03-01 19:55:49.401: [ USRTHRD][2885678848] {1:14336:56597} ConnectionPool::~ConnectionPool m_oracleHome:/u01/oracle/oracle/product/110203, m_oracleSid:xxxdb2, m_usrOraEnv: 2019-03-01 19:55:49.401: [ora.xxxdbdr2.xxxdbcss.svc][2885678848] {1:14336:56597} [check] SvcAgent::check ret:1 exit } 2019-03-01 19:55:49.401: [ AGFW][3892311808] {1:14336:56597} ora.xxxdbdr2.xxxdbcss.svc 1 1 state changed from: CLEANING to: OFFLINE 2019-03-01 19:55:49.401: [ AGFW][3892311808] {1:14336:56597} Agent sending last reply for: RESOURCE_CLEAN[ora.xxxdbdr2.xxxdbcss.svc 1 1] ID 4100:2664826
2019.03.05进行了问题复现,原因是主库通过srvctl添加的service和备库添加的service名字一样但是个别细节属性定义不同。比如主库添加了服务名s_test:
srvctl add service -d zkm -s s_test -e SELECT -m BASIC -w 10 -z 15 -r zkm1,zkm2
备库同步添加服务名s_test:个别属性不同于主库
srvctl add service -d zkmstd -s s_test -e none -m none -w 10 -z 15 -r zkm
这个时候使用“srvctl start service -d zkmstd -s s_test”启动则会由一样的报错。
此刻修改为属性均一致:
srvctl modify service -d zkmstd -s s_test -e select -m basic -w 10 -z 15
再次启动则正常。防。
当在主备环境中以完全相同的方式定义服务时,可以启动 dataguard 环境中的服务,(-r,-a可以不同)请参阅参考:
http://docs.oracle.com/cd/E11882_01/server.112/e40771/sofo.htm#DGBKR3548
如果主备定义服务存在差异,引起报错的根本原因是,
主库中:通过srvctl add service的时候并不会修改在数据库中修改数据库的数据字段表,但是,将新增的service启动的时候,会在表service$中添加记录,这时候你查询dba_services能够查询到服务的信息。
而备库的表service$的数据是同主库同步过来的,备库定义的服务名中由属性存在差异的时候,服务的启动需要更改数据库中的该值,但这是在只读状态下无法完成的,因此报错:ORA-16000: database open for read-only access
上边的oraagent_oracle.log日志也可以看到如下关键字:
MODIFY_SVC_STMT
当你在备库使用srvctl add service添加一个主库当前也没有的服务名并试图在备库启动的时候,oraagent_oracle.log日志的关键字就不是modify_svc_stmt了,而是create_svc_stmt。但是报错类似ORA-44317: database open read-only。
至此。
参考文档:
https://www.cnblogs.com/PiscesCanon/p/18191840
Service Startup Results ORA-16000 ORA-06512 on Active Data Guard When Attached With Edition (文档 ID 2169426.1)
http://docs.oracle.com/cd/E11882_01/server.112/e40771/sofo.htm#DGBKR3548