RAC One Node database crash post GI upgrade to 12.2.0.1 (Doc ID 2274982.1)

Last updated on JUNE 10, 2017

Applies to:

Oracle Database - Enterprise Edition - Version 12.2.0.1 to 12.2.0.1 [Release 12.2]
Information in this document applies to any platform.

Symptoms

RAC One Node databases are shutting down without any manual intervention.

Logs from second node
---------------------------

alert_orcl_2.log:

Thu Mar 09 19:26:55 2017
Shutting down instance (immediate) <----------------
Stopping background process SMCO
Shutting down instance: further logons disabled
Stopping background process QMNC
Stopping background process MMNL
Stopping background process MMON
License high water mark = 11
ALTER SYSTEM SET _shutdown_completion_timeout_mins=30 SCOPE=MEMORY;
ALTER DATABASE CLOSE NORMAL /* db agent *//* {0:51:84} */
.

 

crsd_oraagent_oracle.trc (<oracle base>/diag/crs/<hostname>/crs/trace): 

2017-03-09 19:26:42.153 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] SvcAgent::checkDbQry 280 no cached value ret unplanned offline
2017-03-09 19:26:42.154 : USRTHRD:49624832: {0:51:2} InstConnection:connectInt 200 connected
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] (:CLSN00109:) Agent::commonCheck check failed action:0109 retval:1
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Agent::doStateDump Default Agent Dump
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Agent::doStateDump last call info:
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:none resname:ora.orcl.orclsrv.svc lastCall:DbQrySvcThread::serviceExists 000 ora.orcl.db orclsrv acquire &m_dbQrySvcThreadDsXLock:0x7f5d98040f98
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:none resname:ora.orcl.orclsrv.svc lastCall:DbQrySvcThread::serviceExists 010 checkMap dbResName:ora.orcl.db svcResName:orclsrv
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:none resname:ora.orcl.orclsrv.svc lastCall:DbQrySvcThread::serviceExists 020 svcvec values:orclsrv
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:none resname:ora.orcl.orclsrv.svc lastCall:DbQrySvcThread::serviceExists 021 svcvec values:orclsrv found
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:none resname:ora.orcl.orclsrv.svc lastCall:DbQrySvcThread::serviceExists 990 release &m_dbQrySvcThreadDsXLock:0x7f5d98040f98
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:none resname:ora.orcl.orclsrv.svc lastCall:DbQrySvcThread::serviceExists 999 svc:orclsrv found:1 release &m_dbQrySvcThreadDsXLock:0x7f5d98040f98
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::checkDbQry 200 dbResName:ora.orcl.db svc:orclsrv exists:1
2017-03-09 19:26:42.154 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::checkDbQry 220 serviceExists:1 cts:1489105602 lts:0 dts:1489105602 ci:600 (dts <= ci):0
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::checkDbQry 280 no cached value ret unplanned offline
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::checkDbQry 300 m_pDbQrySvcThread retryDbQrySvc:0 ret:1
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::checkDbQry 999 m_pDbQrySvcThread ret:1
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::check 363 checkDbQry ret:1
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::check 900 leave clsagfw_res_status:1
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::check 930 release m_pConnxn:(nil) state:1
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.153 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::releaseConnection exit *ppConnxn:0 should be null }
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.154 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::check 931 ret 1
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.154 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::check 940 m_dThread:(nil) pdb: state:1 action:104 check_type:3 reasonUser:0 reset listener:0
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.154 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:SvcAgent::check 999 clsagfw_res_status:1 exit }
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.154 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:Agent::commonCheck check clsagfw_res_status:1
2017-03-09 19:26:42.155 :CLSDYNAM:37017344: [ora.orcl.orclsrv.svc]{0:51:2} [check] Time:03/09/2017 19:26:42.154 Tint:{0:51:2} action:104 resname:ora.orcl.orclsrv.svc lastCall:(:CLSN00109:) Agent::commonCheck check failed action:0109 retval:1
2017-03-09 19:26:42.155 : AGFW:685893376: {0:51:2} ora.orcl.orclsrv.svc 1 1 state changed from: ONLINE to: OFFLINE
2017-03-09 19:26:42.155 : AGFW:685893376: {0:51:84} Generating new Tint for unplanned state change. Original Tint: {0:51:2}
2017-03-09 19:26:42.156 : AGFW:685893376: {0:51:84} Agent sending message to PE: RESOURCE_STATUS[Proxy] ID 20481:1093
2017-03-09 19:26:42.156 : AGFW:685893376: {0:51:84} Agent sending last reply for: RESOURCE_ADD[ora.orcl.orclsrv.svc 1 1] ID 4356:5877697
2017-03-09 19:26:42.168 : AGFW:685893376: {0:51:84} Agent received the message: RESOURCE_STOP[ora.orcl.db 1 1] ID 4099:5879202
2017-03-09 19:26:42.168 : AGFW:685893376: {0:51:84} Preparing STOP command for: ora.orcl.db 1 1
2017-03-09 19:26:42.168 : AGFW:685893376: {0:51:84} ora.orcl.db 1 1 state changed from: ONLINE to: STOPPING
2017-03-09 19:26:42.169 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] (:CLSN00108:) clsn_agent::stop {
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] InstAgent::getStopModeAttrib stop mode immediate option 1
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] InstAgent::stop 000 {
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] Agent::valueOfAttribIs attrib: CRS_ORIGINAL_REASON compare value: system attribute value:
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] Agent::valueOfAttribIs returns 0
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] Utils::getResAttrib entry attribName:USR_ORA_OPI required:0 loglevel:1
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] Utils::getResAttrib: attribname USR_ORA_OPI value false len 5
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] Utils::getResAttrib attribname:USR_ORA_OPI value:false exit
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] Agent::valueOfAttribIs attrib: REASON compare value: user attribute value: dependency
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] Agent::valueOfAttribIs returns 0
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] Agent::valueOfAttribIs attrib: CRS_ORIGINAL_REASON compare value: tha attribute value:
2017-03-09 19:26:42.170 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] Agent::valueOfAttribIs returns 0
2017-03-09 19:26:42.171 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] InstAgent::stop 120 shutdown mode:3
2017-03-09 19:26:42.171 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] DbAgent::preStopCbk {
2017-03-09 19:26:42.171 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] DbAgentEventModule::stop stopping event bridge
2017-03-09 19:26:42.171 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] DbAgentEventModule::stop stopping rlb event bridge
2017-03-09 19:26:42.171 :CLSDYNAM:37017344: [ora.orcl.db]{0:51:84} [stop] DbAgent::preStopCbk dThread stop
 

crsd.trc (<oracle base>/diag/crs/<hostname>/crs/trace):

2017-03-09 19:26:42.156 : AGFW:1548158720: {0:51:84} Agfw Proxy Server received the message: RESOURCE_STATUS[Proxy] ID 20481:1093
2017-03-09 19:26:42.156 : AGFW:1548158720: {0:51:84} Verifying msg rid = ora.orcl.orclsrv.svc 1 1
2017-03-09 19:26:42.156 : AGFW:1548158720: {0:51:84} Received state change for ora.orcl.orclsrv.svc 1 1 [old state = ONLINE, new state = OFFLINE]
2017-03-09 19:26:42.156 : AGFW:1548158720: {0:51:84} Agfw Proxy Server sending message to PE, Contents = [MIDTo:2|OpID:3|FromA:{Invalid|Node:0|Process:0|Type:0}|ToA:{Invalid|Node:4294967295|Process:4294967295|Type:4294967295}|MIDFrom:0|Type:4|Pri3|Id:5879197:Ver:2]
2017-03-09 19:26:42.156 : AGFW:1548158720: {0:51:84} Agfw Proxy Server replying to the message: RESOURCE_STATUS[Proxy] ID 20481:1093
2017-03-09 19:26:42.157 : AGFW:1548158720: {0:51:2} Received the reply to the message: RESOURCE_ADD[ora.orcl.orclsrv.svc 1 1] ID 4356:5877697 from the agent /u01/app/12.2.0.1/grid/bin/oraagent_oracle
2017-03-09 19:26:42.157 : AGFW:1548158720: {0:51:2} ResAddMsg reply got, updating state
2017-03-09 19:26:42.164 :UiServer:522159872: {0:51:2} Sending to PE. ctx= 0x7f68b8a3c6a0, ClientPID=301977 set Properties (oracle,113162570), tint: {0:51:2}
2017-03-09 19:26:42.167 : AGFW:1548158720: {0:51:84} Agfw Proxy Server received the message: RESOURCE_STOP[ora.orcl.db 1 1] ID 4099:4759122
2017-03-09 19:26:42.168 : AGFW:1548158720: {0:51:84} Agfw Proxy Server forwarding the message: RESOURCE_STOP[ora.orcl.db 1 1] ID 4099:4759122 to the agent /u01/app/12.2.0.1/grid/bin/oraagent_oracle

 

Changes

Upgrade of Grid Infrastructure to 12.2.0.1 

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