Resource not starting after stack restart (Doc ID 2029838.1)

Last updated on JULY 16, 2015

Applies to:

Oracle Database - Enterprise Edition - Version 11.2.0.2 to 12.1.0.1 [Release 11.2 to 12.1]
Information in this document applies to any platform.

Symptoms

3-node 11.2.0.4 cluster, scan1.vip was running on node2, after stack restart on node2, scan1.vip fails to start:

$ srvctl start scan
PRCR-1079 : Failed to start resource ora.scan1.vip
CRS-0215: Could not start resource 'ora.scan1.vip 1 1'.
PRCC-1014 : scan2 was already running
PRCR-1004 : Resource ora.scan2.vip is already running
PRCR-1079 : Failed to start resource ora.scan2.vip
CRS-5702: Resource 'ora.scan2.vip' is already running on 'racnode1'
PRCC-1014 : scan3 was already running
PRCR-1004 : Resource ora.scan3.vip is already running
PRCR-1079 : Failed to start resource ora.scan3.vip
CRS-5702: Resource 'ora.scan3.vip' is already running on 'racnode3'

 

crsd.log - node2 

2015-05-17 11:53:04.502: [UiServer][3236992768]{2:54584:2034} Container [ Name: SHUTDOWNAPPS
LOCALE:
TextMessage[AMERICAN_AMERICA.US7ASCII]
]
2015-05-17 11:53:04.502: [UiServer][3236992768]{2:54584:2034} Sending message to PE. ctx= 0x7f6bcc2b40f0
2015-05-17 11:53:04.535: [UiServer][3236992768]{2:54584:2034} Container [ Name: UI_DATA
RESULT:
TextMessage[0]
]
2015-05-17 11:53:04.535: [UiServer][3236992768]{2:54584:2034} Done for ctx=0x7f6bcc2b40f0
2015-05-17 11:53:04.535: [ CRSD][3236992768]{2:54584:2034} Exiting on request of the Policy Engine...
2015-05-17 11:53:04.535: [ CRSD][3236992768]{2:54584:2034} Done.

2015-05-17 12:06:48.579: [ CRSMAIN][3046860576] First attempt: init CSS context succeeded.
[ clsdmt][2947864320]Listening to (ADDRESS=(PROTOCOL=ipc)(KEY=racnode2DBG_CRSD))
2015-05-17 12:06:48.583: [ clsdmt][2947864320]PID for the Process [54892], connkey 1
2015-05-17 12:06:48.583: [ clsdmt][2947864320]Creating PID [54892] file for home /u01/app/grid/11.2.0.4 host racnode2 bin crs to /u01/app/grid/11.2.0.4/crs/init/
2015-05-17 12:06:48.583: [ clsdmt][2947864320]Writing PID [54892] to the file [/u01/app/grid/11.2.0.4/crs/init/racnode2.pid]
2015-05-17 12:06:49.533: [ CRSMAIN][2947864320] Policy Engine is not initialized yet!
2015-05-17 12:06:49.533: [ CRSMAIN][3046860576] CRS Daemon Starting
2015-05-17 12:06:49.534: [ CRSD][3046860576] Logging level for Module: allcomp 0
....
....
2015-05-17 12:06:58.978: [ AGFW][2661238528]{2:61164:2} Received the reply to the message: RESOURCE_PROBE[ora.scan1.vip 1 1] ID 4097:130 from the agent /u01/app/grid/11.2.0.4/bin/orarootagent_root
2015-05-17 12:06:58.978: [ AGFW][2661238528]{2:61164:2} ora.scan1.vip 1 1 received state from probe request. Old state = UNKNOWN, New state = ONLINE
2015-05-17 12:06:58.978: [ AGFW][2661238528]{2:61164:2} Agfw Proxy Server sending the last reply to PE for message:RESOURCE_PROBE[ora.scan1.vip 1 1] ID 4097:525579
2015-05-17 12:06:58.978: [ AGFW][2661238528]{2:61164:2} Agfw Proxy Server received the message: CLSAGFW_RESOURCE_PROBEACK[ora.net1.network racnode2 1] ID 4101:525586
2015-05-17 12:06:58.978: [ AGFW][2661238528]{2:61164:2} Agfw Proxy Server sending the last reply to PE for message:CLSAGFW_RESOURCE_PROBEACK[ora.net1.network racnode2 1] ID 4101:525586
....
2015-05-17 12:06:58.984: [ AGFW][2661238528]{2:61164:2} Agfw Proxy Server received the message: RESOURCE_DELETE[ora.scan1.vip 1 1] ID 4358:525590
2015-05-17 12:06:58.984: [ AGFW][2661238528]{2:61164:2} ora.scan1.vip 1 1 marked as deleted.
2015-05-17 12:06:58.984: [ AGFW][2661238528]{2:61164:2} Agfw config version set to: 223
2015-05-17 12:06:58.984: [ AGFW][2661238528]{2:61164:2} Agfw Proxy Server forwarding the message: RESOURCE_DELETE[ora.scan1.vip 1 1] ID 4358:525590 to the agent /u01/app/grid/11.2.0.4/bin/orarootagent_root
2015-05-17 12:06:58.985: [ AGFW][2661238528]{2:61164:2} Received the reply to the message: RESOURCE_DELETE[ora.scan1.vip 1 1] ID 4358:152 from the agent /u01/app/grid/11.2.0.4/bin/orarootagent_root
2015-05-17 12:06:58.985: [ AGFW][2661238528]{2:61164:2} Deleting the resource: ora.scan1.vip 1 1
2015-05-17 12:06:58.985: [ AGFW][2661238528]{2:61164:2} Agfw Proxy Server sending the last reply to PE for message:RESOURCE_DELETE[ora.scan1.vip 1 1] ID 4358:525590
....
2015-05-18 16:04:12.120: [UiServer][2648631040]{2:61164:1612} Container [ Name: UI_START
API_HDR_VER:
TextMessage[2]
CLIENT:
TextMessage[]
CLIENT_NAME:
TextMessage[/etc/java]
CLIENT_PID:
TextMessage[41856]
CLIENT_PRIMARY_GROUP:
TextMessage[oinstall]
FORCE_TAG:
TextMessage[1]
LOCALE:
TextMessage[AMERICAN_AMERICA.US7ASCII]
QUEUE_TAG:
TextMessage[1]
RESOURCE:
TextMessage[ora.scan1.vip]
]
2015-05-18 16:04:12.120: [UiServer][2648631040]{2:61164:1612} Sending message to PE. ctx= 0x7f71a8345a30, Client PID: 41856
2015-05-18 16:04:12.124: [UiServer][2648631040]{2:61164:1612} Container [ Name: ORDER
MESSAGE:
TextMessage[CRS-0215: Could not start resource 'ora.scan1.vip 1 1'.]
MSGTYPE:
TextMessage[1]
OBJID:
TextMessage[ora.scan1.vip]
WAIT:
TextMessage[0]
]
2015-05-18 16:04:12.124: [UiServer][2648631040]{2:61164:1612} Container [ Name: UI_DATA
ora.scan1.vip:
TextMessage[223]
]

 

crsd.log - PE master

2015-05-17 12:06:58.979: [ CRSPE][2399106816]{2:61164:2} Received reply to the intial check for: ora.scan1.vip 1 1 on racnode2
2015-05-17 12:06:58.979: [ CRSPE][2399106816]{2:61164:2} Evaluating the initial state change for ora.scan1.vip 1 1 last server:racnode2 current state: OFFLINE new state: ONLINE
2015-05-17 12:06:58.979: [ CRSPE][2399106816]{2:61164:2} State change detected for ora.scan1.vip 1 1 during initial check on racnode2
2015-05-17 12:06:58.979: [ CRSD][2399106816]{2:61164:2} {2:61164:2} Created alert : (:CRSPE00104:) : ora.scan1.vip 1 1 has unexpected state ONLINE on racnode2
....
2015-05-17 13:00:14.801: [ CRSPE][2399106816]{3:3297:54123} Expression Filter : ((NAME == ora.scan1.vip) AND ((STATE == ONLINE) OR (STATE == INTERMEDIATE)))
....
2015-05-17 13:13:30.324: [ CRSPE][2399106816]{1:8708:4617} Expression Filter : ((NAME == ora.scan1.vip) AND ((STATE != OFFLINE) OR (TARGET != OFFLINE)))
2015-05-17 13:13:30.325: [ CRSPE][2399106816]{1:8708:4617} Filtering duplicate ops: server [] state [OFFLINE]
2015-05-17 13:13:30.325: [ CRSPE][2399106816]{1:8708:4617} Op 0x7fe484015d60 has 8 WOs
2015-05-17 13:13:30.325: [ CRSPE][2399106816]{1:8708:4617} RI [ora.scan1.vip 1 1] new target state: [OFFLINE] old value: [ONLINE]

 



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