eons daemon cannot be started on one of the db nodes
895680Feb 25 2013 — edited Feb 26 2013Hi,
Today I noticed that one of the db node was down. 2nd node was up and running fine
pendle[home/oracrs]$ srvctl status database -d NFT
PRCR-1007 : Failed to check status of resource ora.nft.db
PRCR-1055 : Cluster membership check failed for node tatton
I brought down both db nodes using srvctl and then tried bringing up. 1st node didnt come up but 2nd came up.
pendle[u02/oracle/11.2.0/grid/bin]$ srvctl start database -d NFT
PRCR-1079 : Failed to start resource ora.nft.db
CRS-5016: Process "/u02/oracle/11.2.0/grid/bin/scrctl" spawned by agent "/u02/oracle/11.2.0/grid/bin/oraagent.bin" for action "start" failed: details at "(:CLSN00010:)" in "/u02/oracle/11.2.0/grid/log/pendle/agent/crsd/oraagent_oracrs/oraagent_oracrs.log"
CRS-2674: Start of 'ora.eons' on 'pendle' failed
CRS-2674: Start of 'ora.nft.db' on 'pendle' failed
CRS-2632: There are no more servers to try to place resource 'ora.nft.db' on that would satisfy its placement policy
CRS-5016: Process "/u02/oracle/11.2.0/grid/bin/scrctl" spawned by agent "/u02/oracle/11.2.0/grid/bin/oraagent.bin" for action "start" failed: details at "(:CLSN00010:)" in "/u02/oracle/11.2.0/grid/log/pendle/agent/crsd/oraagent_oracrs/oraagent_oracrs.log"
CRS-2674: Start of 'ora.eons' on 'pendle' failed
Here are the contents of log file */u02/oracle/11.2.0/grid/log/pendle/agent/crsd/oraagent_oracrs/oraagent_oracrs.log:*
2013-02-25 11:22:37.808: [ AGFW][2057] Preparing START command for: ora.eons pendle 1
2013-02-25 11:22:37.808: [ AGFW][2057] ora.eons pendle 1 state changed from: OFFLINE to: STARTING
2013-02-25 11:22:37.810: [ AGFW][6387] Executing command: start for resource: ora.eons pendle 1
2013-02-25 11:22:37.811: [ora.eons][6387] [start] clsn_agent::start {
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Filling Environment Map
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Filling Environment Map
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Filling Environment Map
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Filling Environment Map
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Filling Environment Map
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Filling Environment Map
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Arg Value = start
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Arg Value = eons
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Total Count of Environment Variables = 9
2013-02-25 11:22:37.811: [ora.eons][6387] [start] Adding Environment Variables SRVM_TRACE=true
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Adding Environment Variables ORAAGENT_ACTION=TRUE
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Adding Environment Variables ORADISCOVERY_METHOD=multicast
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Adding Environment Variables ORAMCAST_ADDRESS=234.238.183.112:21157
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Adding Environment Variables ORAMEMBER_LIST=
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Adding Environment Variables ORAPORT=2016
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Adding Environment Variables ORAPROPERTIES=
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Adding Environment Variables __IS_HASD_AGENT=
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Skipping empty Env variable from USR_ORA_ENV
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Utils:execCmd action = 1 flags = 6 ohome = (null) cmdname = scrctl.
2013-02-25 11:22:37.812: [ora.eons][6387] [start] getOracleHomeAttrib: oracle_home = /u02/oracle/11.2.0/grid
2013-02-25 11:22:37.812: [ora.eons][6387] [start] Utils:execCmd Running the binary from /u02/oracle/11.2.0/grid/bin/scrctl
2013-02-25 11:22:38.632: [ora.eons][6387] [start] (:CLSN00010:)Utils:execCmd scls_process_join() uret 1
*2013-02-25 11:22:38.632: [ora.eons][6387] [start] Exception type=2 string=CRS-5016: Process "/u02/oracle/11.2.0/grid/bin/scrctl" spawned by agent "/u02/oracle/11.2.0/*
*grid/bin/oraagent.bin" for action "start" failed: details at "(:CLSN00010:)" in "/u02/oracle/11.2.0/grid/log/pendle/agent/crsd/oraagent_oracrs/oraagent_oracrs.log*"
2013-02-25 11:22:38.635: [ AGFW][2057] Agent sending reply for: RESOURCE_START[ora.eons pendle 1] ID 4098:5925290
2013-02-25 11:22:38.639: [ora.eons][6387] [start] execCmd ret = 1
2013-02-25 11:22:38.639: [ora.eons][6387] [start] }DaemonAgent::start
2013-02-25 11:22:38.639: [ora.eons][6387] [start] clsn_agent::start }
2013-02-25 11:22:38.639: [ AGFW][6387] Command: start for resource: ora.eons pendle 1 completed with status: SUCCESS
2013-02-25 11:22:38.639: [ora.eons][6387] [start] clsn_agent::start }
2013-02-25 11:22:38.639: [ AGFW][6387] Command: start for resource: ora.eons pendle 1 completed with status: SUCCESS
2013-02-25 11:22:38.640: [ AGFW][6387] Executing command: check for resource: ora.eons pendle 1
2013-02-25 11:22:38.640: [ora.eons][6387] [check] Utils::getCrsHome crsHome /u02/oracle/11.2.0/grid
2013-02-25 11:22:38.641: [ AGFW][2057] Agent sending reply for: RESOURCE_START[ora.eons pendle 1] ID 4098:5925290
2013-02-25 11:22:41.649: [ora.eons][6387] [check] check: Exception GipcException
2013-02-25 11:22:41.649: [ora.eons][6387] [check] gipcretTimeout
2013-02-25 11:22:41.649: [ora.eons][6387] [check] Filling Environment Map
2013-02-25 11:22:41.649: [ora.eons][6387] [check] Filling Environment Map
2013-02-25 11:22:41.649: [ora.eons][6387] [check] Filling Environment Map
2013-02-25 11:22:41.649: [ora.eons][6387] [check] Filling Environment Map
2013-02-25 11:22:41.649: [ora.eons][6387] [check] Filling Environment Map
2013-02-25 11:22:41.649: [ora.eons][6387] [check] Filling Environment Map
2013-02-25 11:22:41.649: [ora.eons][6387] [check] Arg Value = status
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Arg Value = eons
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Total Count of Environment Variables = 9
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Adding Environment Variables SRVM_TRACE=true
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Adding Environment Variables ORAAGENT_ACTION=TRUE
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Adding Environment Variables ORADISCOVERY_METHOD=multicast
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Adding Environment Variables ORAMCAST_ADDRESS=234.238.183.112:21157
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Adding Environment Variables ORAMEMBER_LIST=
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Adding Environment Variables ORAPORT=2016
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Adding Environment Variables ORAPROPERTIES=
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Adding Environment Variables __IS_HASD_AGENT=
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Skipping empty Env variable from USR_ORA_ENV
2013-02-25 11:22:41.650: [ora.eons][6387] [check] Utils:execCmd action = 3 flags = 6 ohome = (null) cmdname = scrctl.
2013-02-25 11:22:41.650: [ora.eons][6387] [check] getOracleHomeAttrib: oracle_home = /u02/oracle/11.2.0/grid
2013-02-25 11:22:41.651: [ora.eons][6387] [check] Utils:execCmd Running the binary from /u02/oracle/11.2.0/grid/bin/scrctl
2013-02-25 11:22:42.915: [ora.eons][6387] [check] execCmd ret = 1
2013-02-25 11:22:42.915: [ AGFW][6387] check for resource: ora.eons pendle 1 completed with status: OFFLINE
2013-02-25 11:22:42.916: [ AGFW][2057] ora.eons pendle 1 state changed from: STARTING to: OFFLINE
2013-02-25 11:22:42.917: [ AGFW][2057] Agent sending last reply for: RESOURCE_START[ora.eons pendle 1] ID 4098:5925290
2013-02-25 11:22:43.906: [ AGFW][2057] Agent received the message: RESOURCE_START[ora.eons pendle 1] ID 4098:5925382
2013-02-25 11:22:43.906: [ AGFW][2057] Preparing START command for: ora.eons pendle 1
2013-02-25 11:22:43.906: [ AGFW][2057] ora.eons pendle 1 state changed from: OFFLINE to: STARTING
2013-02-25 11:22:43.906: [ AGFW][2057] Preparing START command for: ora.eons pendle 1
2013-02-25 11:22:43.906: [ AGFW][2057] ora.eons pendle 1 state changed from: OFFLINE to: STARTING
2013-02-25 11:22:43.907: [ AGFW][6130] Executing command: start for resource: ora.eons pendle 1
2013-02-25 11:22:43.908: [ora.eons][6130] [start] clsn_agent::start {
2013-02-25 11:22:43.908: [ora.eons][6130] [start] Filling Environment Map
2013-02-25 11:22:43.908: [ora.eons][6130] [start] Filling Environment Map
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Filling Environment Map
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Filling Environment Map
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Filling Environment Map
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Filling Environment Map
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Arg Value = start
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Arg Value = eons
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Total Count of Environment Variables = 9
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Adding Environment Variables SRVM_TRACE=true
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Adding Environment Variables ORAAGENT_ACTION=TRUE
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Adding Environment Variables ORADISCOVERY_METHOD=multicast
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Adding Environment Variables ORAMCAST_ADDRESS=234.238.183.112:21157
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Adding Environment Variables ORAMEMBER_LIST=
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Adding Environment Variables ORAPORT=2016
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Adding Environment Variables ORAPROPERTIES=
2013-02-25 11:22:43.909: [ora.eons][6130] [start] Adding Environment Variables __IS_HASD_AGENT=
2013-02-25 11:22:43.910: [ora.eons][6130] [start] Skipping empty Env variable from USR_ORA_ENV
2013-02-25 11:22:43.910: [ora.eons][6130] [start] Utils:execCmd action = 1 flags = 6 ohome = (null) cmdname = scrctl.
2013-02-25 11:22:43.910: [ora.eons][6130] [start] getOracleHomeAttrib: oracle_home = /u02/oracle/11.2.0/grid
2013-02-25 11:22:43.910: [ora.eons][6130] [start] Utils:execCmd Running the binary from /u02/oracle/11.2.0/grid/bin/scrctl
2013-02-25 11:22:45.129: [ora.eons][6130] [start] (:CLSN00010:)Utils:execCmd scls_process_join() uret 1
*2013-02-25 11:22:45.130: [ora.eons][6130] [start] Exception type=2 string=CRS-5016: Process "/u02/oracle/11.2.0/grid/bin/scrctl" spawned by agent "/u02/oracle/11.2.0/*
*grid/bin/oraagent.bin" for action "start" failed: details at "(:CLSN00010:)" in "/u02/oracle/11.2.0/grid/log/pendle/agent/crsd/oraagent_oracrs/oraagent_oracrs.log"*
2013-02-25 11:22:45.130: [ora.eons][6130] [start] execCmd ret = 1
2013-02-25 11:22:45.130: [ora.eons][6130] [start] }DaemonAgent::start
2013-02-25 11:22:45.132: [ AGFW][2057] Agent sending reply for: RESOURCE_START[ora.eons pendle 1] ID 4098:5925382
2013-02-25 11:22:45.134: [ora.eons][6130] [start] clsn_agent::start }
2013-02-25 11:22:45.134: [ AGFW][6130] Command: start for resource: ora.eons pendle 1 completed with status: SUCCESS
2013-02-25 11:22:45.134: [ora.eons][6130] [start] clsn_agent::start }
2013-02-25 11:22:45.134: [ AGFW][6130] Command: start for resource: ora.eons pendle 1 completed with status: SUCCESS
2013-02-25 11:22:45.135: [ AGFW][6130] Executing command: check for resource: ora.eons pendle 1
2013-02-25 11:22:45.136: [ora.eons][6130] [check] Utils::getCrsHome crsHome /u02/oracle/11.2.0/grid
2013-02-25 11:22:45.139: [ AGFW][2057] Agent sending reply for: RESOURCE_START[ora.eons pendle 1] ID 4098:5925382
2013-02-25 11:22:48.138: [ora.eons][6130] [check] check: Exception GipcException
2013-02-25 11:22:48.138: [ora.eons][6130] [check] gipcretTimeout
2013-02-25 11:22:48.138: [ora.eons][6130] [check] Filling Environment Map
2013-02-25 11:22:48.138: [ora.eons][6130] [check] Filling Environment Map
2013-02-25 11:22:48.138: [ora.eons][6130] [check] Filling Environment Map
2013-02-25 11:22:48.138: [ora.eons][6130] [check] Filling Environment Map
2013-02-25 11:22:48.138: [ora.eons][6130] [check] Filling Environment Map
2013-02-25 11:22:48.138: [ora.eons][6130] [check] Filling Environment Map
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Arg Value = status
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Arg Value = eons
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Total Count of Environment Variables = 9
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Adding Environment Variables SRVM_TRACE=true
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Adding Environment Variables ORAAGENT_ACTION=TRUE
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Adding Environment Variables ORADISCOVERY_METHOD=multicast
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Adding Environment Variables ORAMCAST_ADDRESS=234.238.183.112:21157
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Adding Environment Variables ORAMEMBER_LIST=
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Adding Environment Variables ORAPORT=2016
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Adding Environment Variables ORAPROPERTIES=
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Adding Environment Variables __IS_HASD_AGENT=
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Skipping empty Env variable from USR_ORA_ENV
2013-02-25 11:22:48.139: [ora.eons][6130] [check] Utils:execCmd action = 3 flags = 6 ohome = (null) cmdname = scrctl.
2013-02-25 11:22:48.139: [ora.eons][6130] [check] getOracleHomeAttrib: oracle_home = /u02/oracle/11.2.0/grid
2013-02-25 11:22:48.140: [ora.eons][6130] [check] Utils:execCmd Running the binary from /u02/oracle/11.2.0/grid/bin/scrctl
2013-02-25 11:22:49.635: [ora.eons][6130] [check] execCmd ret = 1
2013-02-25 11:22:49.635: [ AGFW][6130] check for resource: ora.eons pendle 1 completed with status: OFFLINE
2013-02-25 11:22:49.636: [ AGFW][2057] ora.eons pendle 1 state changed from: STARTING to: OFFLINE
2013-02-25 11:22:49.637: [ AGFW][2057] Agent sending last reply for: RESOURCE_START[ora.eons pendle 1] ID 4098:5925382
2013-02-25 11:23:00.772: [ AGFW][2057] CHECK initiated by timer for: ora.LISTENER_NFT.lsnr pendle 1
2013-02-25 11:23:00.773: [ AGFW][6130] Executing command: check for resource: ora.LISTENER_NFT.lsnr pendle 1
2013-02-25 11:23:00.773: [ora.LISTENER_NFT.lsnr][6130] [check] LsnrAgent::check {
2013-02-25 11:23:00.773: [ AGFW][6130] Executing command: check for resource: ora.LISTENER_NFT.lsnr pendle 1
2013-02-25 11:23:00.773: [ora.LISTENER_NFT.lsnr][6130] [check] LsnrAgent::check {
2013-02-25 11:23:00.773: [ora.LISTENER_NFT.lsnr][6130] [check] lsnrctl status LISTENER_NFT
2013-02-25 11:23:00.774: [ora.LISTENER_NFT.lsnr][6130] [check] Total Count of Environment Variables = 2
2013-02-25 11:23:00.774: [ora.LISTENER_NFT.lsnr][6130] [check] Adding Environment Variables ORACLE_HOME=/u01/oracle/NFT/product/11.2.0/dbhome_1
2013-02-25 11:23:00.774: [ora.LISTENER_NFT.lsnr][6130] [check] Adding Environment variable from USR_ORA_ENV TNS_ADMIN=/u01/oracle/NFT/product/11.2.0/dbhome_1/network/
admin
2013-02-25 11:23:00.774: [ora.LISTENER_NFT.lsnr][6130] [check] Utils:execCmd action = 3 flags = 6 ohome = (null) cmdname = lsnrctl.
2013-02-25 11:23:00.774: [ora.LISTENER_NFT.lsnr][6130] [check] getOracleHomeAttrib: oracle_home = /u01/oracle/NFT/product/11.2.0/dbhome_1
2013-02-25 11:23:00.775: [ora.LISTENER_NFT.lsnr][6130] [check] Utils:execCmd Running the binary from /u01/oracle/NFT/product/11.2.0/dbhome_1/bin/lsnrctl
2013-02-25 11:23:00.892: [ora.LISTENER_NFT.lsnr][6130] [check]
(:CLSN00010:)
2013-02-25 11:23:00.892: [ora.LISTENER_NFT.lsnr][6130] [check]
(:CLSN00010:)LSNRCTL for IBM/AIX RISC System/6000: Version 11.2.0.1.0 - Production on 25-FEB-2013 11:23:00
2013-02-25 11:23:00.892: [ora.LISTENER_NFT.lsnr][6130] [check]
(:CLSN00010:)
***********************************************************************************************************************************************
I even tried bringing up eons service manually on 1st node:
pendle[home/oracrs]$ crsctl start res ora.eons
CRS-2672: Attempting to start 'ora.eons' on 'pendle'
CRS-5016: Process "/u02/oracle/11.2.0/grid/bin/scrctl" spawned by agent "/u02/oracle/11.2.0/grid/bin/oraagent.bin" for action "start" failed: details at "(:CLSN00010:)" in "/u02/oracle/11.2.0/grid/log/pendle/agent/crsd/oraagent_oracrs/oraagent_oracrs.log"
CRS-2674: Start of 'ora.eons' on 'pendle' failed
CRS-4000: Command Start failed, or completed with errors.
***********************************************************************************************************************************************
Cluster services are running fine on 1st node:
pendle[home/oracrs]$ crsctl check crs
CRS-4638: Oracle High Availability Services is online
CRS-4537: Cluster Ready Services is online
CRS-4529: Cluster Synchronization Services is online
CRS-4533: Event Manager is online
***********************************************************************************************************************************************
pendle[home/oracrs]$ crsctl stat res
NAME=ora.DATA1.dg
TYPE=ora.diskgroup.type
TARGET=ONLINE , ONLINE
STATE=ONLINE on pendle, ONLINE on tatton
NAME=ora.LISTENER.lsnr
TYPE=ora.listener.type
TARGET=ONLINE , ONLINE
STATE=ONLINE on pendle, ONLINE on tatton
NAME=ora.LISTENER_NFT.lsnr
TYPE=ora.listener.type
TARGET=ONLINE , ONLINE
STATE=ONLINE on pendle, ONLINE on tatton
NAME=ora.LISTENER_PENDLE.lsnr
TYPE=ora.listener.type
TARGET=OFFLINE, OFFLINE
STATE=OFFLINE, OFFLINE
NAME=ora.LISTENER_SCAN1.lsnr
TYPE=ora.scan_listener.type
TARGET=ONLINE
STATE=ONLINE on tatton
NAME=ora.LISTENER_SCAN2.lsnr
TYPE=ora.scan_listener.type
TARGET=ONLINE
STATE=ONLINE on pendle
NAME=ora.LISTENER_SCAN3.lsnr
TYPE=ora.scan_listener.type
TARGET=ONLINE
STATE=ONLINE on pendle
NAME=ora.VOTING.dg
TYPE=ora.diskgroup.type
TARGET=ONLINE , ONLINE
STATE=ONLINE on pendle, ONLINE on tatton
NAME=ora.asm
TYPE=ora.asm.type
TARGET=ONLINE , ONLINE
STATE=ONLINE on pendle, ONLINE on tatton
NAME=ora.eons
TYPE=ora.eons.type
TARGET=ONLINE , ONLINE
STATE=OFFLINE, ONLINE on tatton
NAME=ora.gsd
TYPE=ora.gsd.type
TARGET=ONLINE , ONLINE
STATE=ONLINE on pendle, ONLINE on tatton
NAME=ora.net1.network
TYPE=ora.network.type
TARGET=ONLINE , ONLINE
STATE=ONLINE on pendle, ONLINE on tatton
NAME=ora.nft.db
TYPE=ora.database.type
TARGET=ONLINE , ONLINE
STATE=OFFLINE, ONLINE on tatton
NAME=ora.oc4j
TYPE=ora.oc4j.type
TARGET=OFFLINE
STATE=OFFLINE
NAME=ora.ons
TYPE=ora.ons.type
TARGET=ONLINE , ONLINE
STATE=ONLINE on pendle, ONLINE on tatton
NAME=ora.pendle.vip
TYPE=ora.cluster_vip_net1.type
TARGET=ONLINE
STATE=ONLINE on pendle
NAME=ora.scan1.vip
TYPE=ora.scan_vip.type
TARGET=ONLINE
STATE=ONLINE on tatton
NAME=ora.scan2.vip
TYPE=ora.scan_vip.type
TARGET=ONLINE
STATE=ONLINE on pendle
NAME=ora.scan3.vip
TYPE=ora.scan_vip.type
TARGET=ONLINE
STATE=ONLINE on pendle
NAME=ora.tatton.vip
TYPE=ora.cluster_vip_net1.type
TARGET=ONLINE
STATE=ONLINE on tatton
***********************************************************************************************************************************************
Any pointers on what could be the reason for eons and db not coming up on 1st node would be helpful. It would be better if issue could be resolved without bouncing cluster.
Regards,
Purnima Johari
Edited by: 892677 on Feb 25, 2013 8:18 AM