My Oracle Support Banner

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

Last updated on MARCH 06, 2019

Applies to:

Oracle Database - Enterprise Edition - Version 11.2.0.4 and later
Oracle Database Cloud Schema Service - Version N/A and later
Oracle Database Exadata Express Cloud Service - Version N/A and later
Oracle Database Exadata Cloud Machine - Version N/A and later
Oracle Cloud Infrastructure - Database Service - Version N/A 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.

alert<sid>.log
=================
2016-04-16 10:20:58.269:
[ohasd(1766)]CRS-1301:Oracle High Availability Service started on node <hostname>.
........
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.<sid>.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 [<hostname>] :
local=0, unplanned=00x7f1f80097e70] cannot run cause it needs W lock for: WO for Placement Path RI:[ora.LISTENER.lsnr <hostname> 1] server [<hostname>] target
states [ONLINE ], locked by op [START of [ora.<hostname>.vip 1 1] on [<hostname>] : local=0, unplanned=00x7f1f880e7450]. Owner: CRS-2682: It is locked by
'root' for command 'Relocate Resource' issued from '<hostname>'

2016-04-16 10:27:03.695: [ CRSPE][2459911936]{3:10242:2} ICE has queued an operation. Details: Operation [START of [ora.<sid>.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 [<hostname>] 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 : <hostname> '

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.<sid>.db 1 1] on [ah3hi043] : local=0, unplanned=00x7f1f94367ad0]. Owner: CRS-2683: It is locked by
'SYSTEM' for command 'Resource Autostart : <hostname>'

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

2016-04-16 10:40:11.694: [ CRSPE][2459911936]{3:10242:2} CRS-2672: Attempting to start 'ora.<sid>.db' on '<hostname>'
2016-04-16 10:40:22.753: [ CRSPE][2459911936]{3:10242:2} CRS-2672: Attempting to start 'ora.<sid>.db' on '<hostname>'
2016-04-16 10:41:21.736: [ CRSPE][2459911936]{3:10242:2} CRS-2676: Start of 'ora.<sid>.db' on '<hostname>' 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 '<hostname>'
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.xx.xx.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 '<hostname>' succeeded
2016-04-16 10:27:31.699: [ CRSPE][2459911936]{3:10242:2} CRS-2672: Attempting to start 'ora.LISTENER_SCAN2.lsnr' on '<hostname>'
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.xx.xx.202
2016-04-16 10:27:06.418: [ora.scan2.vip][2823366400]{3:10242:2} [start] Failed to check 10.xx.xx.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.xx.xx.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

To view full details, sign in with your My Oracle Support account.

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


In this Document
Symptoms
Changes
Cause
Solution
References


My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.