ORAAGENT DID NOT BRING UP THE DATABASE ON TIME (Doc ID 2173522.1)

Last updated on NOVEMBER 20, 2016

Applies to:

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

Symptoms

ORAAGENT took long time(20 to 25 mins) to bring up the RAC DB's after server reboot.

Cluster alert log shows CRS-5011 soon minute after startup with the check of the database resource failing. It took long time(almost 20 min) for the database resource to come online.

alertah3hi039.log
=================
2016-04-16 10:20:58.269:
[ohasd(1766)]CRS-1301:Oracle High Availability Service started on node ah3hi039.
........
2016-04-16 10:21:52.048:
[/oracle/grid/product/11204/grid/bin/oraagent.bin(11643)]CRS-5011:Check of resource "OWTS003P" failed: details at "(:CLSN00007:)" in "/oracle/grid/product/11204/grid/log/ah3hi039/agent/crsd/oraagent_orcldb/oraagent_orcldb.log" <<<

 

ora.owts003p.db resource can not start because of errors in scan vip and scan listeners.

2016-04-16 10:27:02.707: [ CRSPE][2459911936]{3:10242:2} ICE has queued an operation. Details: Operation [START of [ora.owts003p.db 3 1] on [ah3hi045] :
local=0, unplanned=00x7f1f80097e70] cannot run cause it needs W lock for: WO for Placement Path RI:[ora.LISTENER.lsnr ah3hi045 1] server [ah3hi045] target
states [ONLINE ], locked by op [START of [ora.ah3hi045.vip 1 1] on [ah3hi045] : local=0, unplanned=00x7f1f880e7450]. Owner: CRS-2682: It is locked by
'root' for command 'Relocate Resource' issued from 'ah3hi045'

2016-04-16 10:27:03.695: [ CRSPE][2459911936]{3:10242:2} ICE has queued an operation. Details: Operation [START of [ora.owts003p.db 2 1] on [ah3hi039] :
local=0, unplanned=00x23b6d90] cannot run cause it needs W lock for: WO for Placement Path RI:[ora.LISTENER_SCAN2.lsnr 1 1] server [ah3hi037] target
states [ONLINE ], locked by op [START of [ora.scan2.vip 1 1] on [ah3hi051] : local=0, unplanned=00x7f1f80098390]. Owner: CRS-2683: It is locked by
'SYSTEM' for command 'Resource Autostart : ah3hi039 ah3hi041 ah3hi043 ah3hi045 ah3hi047 ah3hi049 ah3hi051'

2016-04-16 10:32:22.466: [ CRSPE][2459911936]{3:10242:2} ICE has queued an operation. Details: Operation [START of [ora.owts003p.db 3 1] on [ah3hi045] :
local=0, unplanned=00x7f1f94372f50] cannot run cause it needs W lock for: WO for Placement Path RI:[ora.LISTENER_SCAN2.lsnr 1 1] server [ah3hi043] target
states [ONLINE ], locked by op [START of [ora.owsh72ep.db 1 1] on [ah3hi043] : local=0, unplanned=00x7f1f94367ad0]. Owner: CRS-2683: It is locked by
'SYSTEM' for command 'Resource Autostart : ah3hi039 ah3hi041 ah3hi043 ah3hi045 ah3hi047 ah3hi049 ah3hi051 ah3hi053'

2016-04-16 10:32:22.526: [ CRSPE][2459911936]{3:10242:2} ICE has queued an operation. Details: Operation [START of [ora.owts003p.db 2 1] on [ah3hi039] :
local=0, unplanned=00x7f1f942ef340] cannot run cause it needs W lock for: WO for Placement Path RI:[ora.LISTENER_SCAN2.lsnr 1 1] server [ah3hi043] target
states [ONLINE ], locked by op [START of [ora.owsh72ep.db 1 1] on [ah3hi043] : local=0, unplanned=00x7f1f94367ad0]. Owner: CRS-2683: It is locked by
'SYSTEM' for command 'Resource Autostart : ah3hi039 ah3hi041 ah3hi043 ah3hi045 ah3hi047 ah3hi049 ah3hi051 ah3hi053'

2016-04-16 10:40:11.694: [ CRSPE][2459911936]{3:10242:2} CRS-2672: Attempting to start 'ora.owts003p.db' on 'ah3hi045'
2016-04-16 10:40:22.753: [ CRSPE][2459911936]{3:10242:2} CRS-2672: Attempting to start 'ora.owts003p.db' on 'ah3hi039'
2016-04-16 10:41:21.736: [ CRSPE][2459911936]{3:10242:2} CRS-2676: Start of 'ora.owts003p.db' on 'ah3hi039' succeeded

 

ora.LISTENER_SCAN2.lsnr is ready until ~10:38:15, after this database is able to start.

2016-04-16 10:27:05.762: [ CRSPE][2459911936]{3:10242:2} CRS-2672: Attempting to start 'ora.scan2.vip' on 'ah3hi051'
2016-04-16 10:27:26.311: [ CRSPE][2459911936]{3:10242:2} Got agent-specific msg: CRS-5017: The resource action "ora.scan2.vip start" encountered the following error: CRS-5005: IP Address: 10.27.45.202 is already in use in the network
2016-04-16 10:27:31.675: [ CRSPE][2459911936]{3:10242:2} CRS-2676: Start of 'ora.scan2.vip' on 'ah3hi043' succeeded
2016-04-16 10:27:31.699: [ CRSPE][2459911936]{3:10242:2} CRS-2672: Attempting to start 'ora.LISTENER_SCAN2.lsnr' on 'ah3hi043'
2016-04-16 10:38:15.619: [ CRSPE][2459911936]{3:10242:2} CRS-2676: Start of 'ora.LISTENER_SCAN2.lsnr' on 'ah3hi043' succeeded
.........

Changes

So scan vips can not start because of errors in checking the interface
==========================
2016-04-16 10:27:05.918: [ora.scan2.vip][2823366400]{3:10242:2} [start] Ip Address = 10.27.45.202
2016-04-16 10:27:06.418: [ora.scan2.vip][2823366400]{3:10242:2} [start] Failed to check 10.27.45.202 on eth2
2016-04-16 10:27:06.419: [ora.scan2.vip][2823366400]{3:10242:2} [start] (null) category: 0, operation: , loc: , OS error: 0, other:  <<<<<<<<

 

This error is seen all the time before and after issue and point to likely a problem in network layer.
=========================
2016-04-09 21:57:24.882: [ora.ah3hi037.vip][1754060544]{1:36968:3295} [check] Failed to check 10.27.45.137 on eth2
2016-04-09 21:57:24.882: [ora.ah3hi037.vip][1754060544]{1:36968:3295} [check] (null) category: 0, operation: , loc: , OS error: 0, other:
2016-04-09 21:57:24.882: [ora.ah3hi037.vip][1754060544]{1:36968:3295} [check] VipAgent::checkIp returned false

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