/u01/oracle/crs/jdk/jre/bin/java -classpath /u01/oracle/crs/jlib/netcfg.jar:/u01/oracle/crs/jdk/jre/lib/rt.jar:/u01/oracle/crs/jdk/jre/lib/i18n.jar:/u01/oracle/crs/jlib/srvm.jar:/u01/oracle/crs/jlib/srvmhas.jar:/u01/oracle/crs/jlib/srvmasm.jar:/u01/oracle/crs/srvm/jlib/srvctl.jar -DTRACING.ENABLED=true -DTRACING.LEVEL=2 oracle.ops.opsctl.OPSCTLDriver start database -d DUPL [main] [9:49:12:745] [OPSCTLDriver.setInternalDebugLevel:165] tracing is true at level 2 to file null [main] [9:49:12:785] [OPSCTLDriver.:95] Security manager is set [main] [9:49:12:801] [CommandLineParser.parse:174] parsing cmdline args [main] [9:49:12:801] [CommandLineParser.parse2WordCommandOptions:948] parsing 2-word cmdline [main] [9:49:12:802] [OPSCTLDriver.execute:174] executing srvctl command [main] [9:49:12:802] [OPSCTLDriver.execute:199] executing 2-word command verb=3 noun=101 [main] [9:49:12:820] [CommandLineParser.obtainOPS:1360] srvctl: get reference to : DUPL [main] [9:49:12:843] [GetActiveNodes.create:215] Going into GetActiveNodes constructor... [main] [9:49:12:849] [HASContext.getInstance:197] Module init : 16 [main] [9:49:12:849] [HASContext.getInstance:221] Local Module init : 19 [main] [9:49:12:849] [HASContext.:90] moduleInit = 19 [main] [9:49:12:879] [Library.getInstance:95] Created instance of Library. [main] [9:49:12:879] [Library.load:195] Loading libsrvmhas10.so... [main] [9:49:12:879] [Library.load:201] oracleHome null [main] [9:49:12:879] [Library.load:236] Loading library srvmhas10 from path= /u01/oracle/crs/jdk/jre/lib/i386/client:/u01/oracle/crs/jdk/jre/lib/i386:/u01/oracle/crs/jdk/jre/../lib/i386:/u01/oracle/crs/lib:/u01/oracle/crs/srvm/lib: [main] [9:49:12:911] [Library.load:244] Loaded library srvmhas10 from path= /u01/oracle/crs/jdk/jre/lib/i386/client:/u01/oracle/crs/jdk/jre/lib/i386:/u01/oracle/crs/jdk/jre/../lib/i386:/u01/oracle/crs/lib:/u01/oracle/crs/srvm/lib: [main] [9:49:12:913] [has.HASContextNative.Native] prsr_trace: no lsf ctx, line=Native: allocHASContext [main] [9:49:12:914] [has.HASContextNative.Native] allocHASContext: Came in [main] [9:49:12:914] [has.HASContextNative.Native] allocHASContext: module_init = 19 [main] [9:49:12:914] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [9:49:12:915] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [9:49:12:915] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [main] [9:49:12:921] [has.HASContextNative.Native] allocHASContext: CLSS context [1] [main] [9:49:12:921] [has.HASContextNative.Native] allocHASContext: retval [1] [main] [9:49:12:921] [HASContext.getInstance:256] HAS Context Allocated: 1 to oracle.ops.mgmt.has.ClusterUtil@df8ff1 [main] [9:49:12:922] [ClusterUtil.:55] ClusterUtil Instance created [main] [9:49:12:922] [ClusterUtil.:58] ClusterUtil m_bSKGXN=true [main] [9:49:12:923] [has.ClusterUtilNative.Native] prsr_trace: Native: getLocalNodeName [main] [9:49:12:923] [has.ClusterUtilNative.Native] prsr_trace: Native: getLocalNodeName:nodenumber: 1 [main] [9:49:12:923] [has.ClusterUtilNative.Native] prsr_trace: Native: getLocalNodeName:nodename: cpbttodevorra001 [main] [9:49:12:924] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeNames [main] [9:49:12:924] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeNames:number of nodes: 1 [main] [9:49:12:925] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeNames:node 1 is alive k = 0 [main] [9:49:12:925] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeNames:1 nodename: cpbttodevorra001 [main] [9:49:12:925] [GetActiveNodes.:187] Inside GetActiveNodes :cpbttodevorra001 [main] [9:49:12:928] [GetActiveNodes.:199] Started clusterware daemon thread [main] [9:49:12:928] [GetActiveNodes.create:217] Out of GetActiveNodes constructor. [GetActiveNodesThread] [9:49:12:932] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread GetActiveNodesThread m_count=0 [main] [9:49:12:941] [OCRTree.init:202] calling OCRTree.init [main] [9:49:12:941] [Version.isPre10i:189] isPre10i.java: Returning FALSE [main] [9:49:12:947] [OCRTree.:158] calling OCR.init at level 7 [main] [9:49:12:950] [OCR.:228] Called into OCR.java Constructor: level =7 [main] [9:49:12:950] [OCR.loadLibrary:284] Inside constructor of OCR [main] [9:49:12:950] [OCR.loadLibrary:292] Going to load the ocr library [main] [9:49:12:950] [Library.load:195] Loading libsrvmocr10.so... [main] [9:49:12:950] [Library.load:201] oracleHome null [main] [9:49:12:951] [Library.load:236] Loading library srvmocr10 from path= /u01/oracle/crs/jdk/jre/lib/i386/client:/u01/oracle/crs/jdk/jre/lib/i386:/u01/oracle/crs/jdk/jre/../lib/i386:/u01/oracle/crs/lib:/u01/oracle/crs/srvm/lib: [main] [9:49:12:952] [Library.load:244] Loaded library srvmocr10 from path= /u01/oracle/crs/jdk/jre/lib/i386/client:/u01/oracle/crs/jdk/jre/lib/i386:/u01/oracle/crs/jdk/jre/../lib/i386:/u01/oracle/crs/lib:/u01/oracle/crs/srvm/lib: [main] [9:49:12:952] [OCR.loadLibrary:294] loaded ocr libraries [main] [9:49:12:952] [OCR.:241] Calling Native function [main] [9:49:12:953] [nativesystem.OCRNative.Native] initializeOCRLevel: NEW level = 7 [main] [9:49:12:954] [nativesystem.OCRNative.Native] initializeOCRLevel: NEW procr_init retval = 0 [main] [9:49:12:954] [OCR.:245] Returned after initializing OCR [main] [9:49:12:955] [HASContext.getInstance:197] Module init : 6 [main] [9:49:12:955] [HASContext.getInstance:221] Local Module init : 4 [main] [9:49:12:955] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [9:49:12:955] [has.HASContextNative.Native] allocHASContext: Came in [main] [9:49:12:955] [has.HASContextNative.Native] allocHASContext: module_init = 4 [main] [9:49:12:956] [has.HASContextNative.Native] prsr_trace: Native: prsr_initSCLS [main] [9:49:12:956] [has.HASContextNative.Native] allocHASContext: SCLS context [1] [main] [9:49:12:956] [has.HASContextNative.Native] allocHASContext: retval [1] [main] [9:49:12:956] [HASContext.getInstance:256] HAS Context Allocated: 2 to oracle.ops.mgmt.has.Util@1d05c81 [main] [9:49:12:956] [Util.:87] Util Instance created. [main] [9:49:12:959] [has.UtilNative.Native] prsr_trace: Native: getCurrentUserPrimaryGroup [main] [9:49:12:959] [has.UtilNative.Native] prsr_trace: got primary group name=root [main] [9:49:12:959] [OCR.:259] Primary Group of Current User: root [main] [9:49:12:960] [HASContext.getInstance:197] Module init : 24 [main] [9:49:12:960] [HASContext.getInstance:221] Local Module init : 8 [main] [9:49:12:960] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [9:49:12:961] [has.HASContextNative.Native] allocHASContext: Came in [main] [9:49:12:961] [has.HASContextNative.Native] allocHASContext: module_init = 8 [main] [9:49:12:961] [has.HASContextNative.Native] allocHASContext: SLTS context [1] [main] [9:49:12:961] [has.HASContextNative.Native] allocHASContext: retval [1] [main] [9:49:12:961] [HASContext.getInstance:256] HAS Context Allocated: 3 to oracle.ops.mgmt.has.ClusterLock@1ccb029 [main] [9:49:12:961] [ClusterLock.:60] ClusterLock Instance created. [main] [9:49:12:963] [OCRTree.isDatabaseConfigured:677] Acquiring shared CSS lock SRVM.DATABASE.DATABASES [main] [9:49:12:963] [has.ClusterLockNative.Native] prsr_trace: Native: acquireShared [main] [9:49:12:964] [OCR.keyExists:664] OCR.keyExists(DATABASE.DATABASES.dupl) [main] [9:49:12:964] [nativesystem.OCRNative.Native] keyExists: calling procr_open_key(DATABASE.DATABASES.dupl) [main] [9:49:12:964] [nativesystem.OCRNative.Native] keyExists: procr_open_key retval = 0 [main] [9:49:12:965] [nativesystem.OCRNative.Native] keyExists: procr_close_key retval = 0 [main] [9:49:12:965] [OCRTree.isDatabaseConfigured:707] Releasing shared CSS lock SRVM.DATABASE.DATABASES [main] [9:49:12:965] [has.ClusterLockNative.Native] prsr_trace: Native: unlock [main] [9:49:12:987] [Version.isPre10i:189] isPre10i.java: Returning FALSE [main] [9:49:13:4] [OCRTree.init:176] in OCRTree.init, version = 10.2.0.0.0 [main] [9:49:13:6] [ParallelServer.addEventListener:4904] srvctl event listener already registered [main] [9:49:13:6] [ParallelServerHA.start:944] getting configuration for the db [main] [9:49:13:8] [Operation.:63] Setting to be a synchronized operation [main] [9:49:13:8] [LocalCommand.execute:54] LocalCommand.execute: Calling run method [main] [9:49:13:9] [GetConfigurationOperation.run:66] in GetConfigurationOperation.run() [main] [9:49:13:11] [RawDeviceConfig.init:149] RawDeviceConfig instance is null [main] [9:49:13:11] [Version.equals:152] PRINTING FROM VERSION10.2.0.0.0 [main] [9:49:13:11] [Version.equals:153] 10.2.0.0.0 [main] [9:49:13:12] [Version.equals:159] Version.java: RETURNING TRUE [main] [9:49:13:12] [RawDeviceConfig.init:152] Creating a RawDeviceConfigHA instance [main] [9:49:13:13] [RawDeviceConfig.:118] initializing RawDeviceConfig [main] [9:49:13:14] [OCRTree.init:176] in OCRTree.init, version = 10.2.0.0.0 [main] [9:49:13:14] [RawDeviceConfigHA.:66] initializing RawDeviceConfig [main] [9:49:13:14] [OCRTree.init:176] in OCRTree.init, version = 10.2.0.0.0 [main] [9:49:13:14] [GetConfigurationOperation.run:68] initialized raw device config [main] [9:49:13:14] [RawDeviceConfig.getConfiguration:197] calling ocrtree.getDBConfig [main] [9:49:13:14] [OCRTreeHA.getDatabaseConfiguration:150] Acquiring shared CSS lock SRVM.DATABASE.DATABASES.dupl [main] [9:49:13:15] [has.ClusterLockNative.Native] prsr_trace: Native: acquireShared [main] [9:49:13:15] [OCR.keyExists:664] OCR.keyExists(DATABASE.DATABASES.dupl) [main] [9:49:13:16] [nativesystem.OCRNative.Native] keyExists: calling procr_open_key(DATABASE.DATABASES.dupl) [main] [9:49:13:17] [nativesystem.OCRNative.Native] keyExists: procr_open_key retval = 0 [main] [9:49:13:17] [nativesystem.OCRNative.Native] keyExists: procr_close_key retval = 0 [main] [9:49:13:17] [OCRTreeHA.getDatabaseConfiguration:177] found the db key DATABASE.DATABASES.dupl [main] [9:49:13:17] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl) [main] [9:49:13:17] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:18] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 5 [main] [9:49:13:18] [nativesystem.OCRNative.Native] getKeyValue: value is [DUPL] dtype = 3 [main] [9:49:13:18] [OCRTreeHA.getDatabaseConfiguration:183] case preserving db name is DUPL [main] [9:49:13:18] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.ORACLE_HOME) [main] [9:49:13:18] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:19] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 16 [main] [9:49:13:19] [nativesystem.OCRNative.Native] getKeyValue: value is [/u01/oracle/10g] dtype = 3 [main] [9:49:13:19] [OCR.keyExists:664] OCR.keyExists(DATABASE.DATABASES.dupl.CONFIG_VERSION) [main] [9:49:13:19] [nativesystem.OCRNative.Native] keyExists: calling procr_open_key(DATABASE.DATABASES.dupl.CONFIG_VERSION) [main] [9:49:13:20] [nativesystem.OCRNative.Native] keyExists: procr_open_key retval = 0 [main] [9:49:13:20] [nativesystem.OCRNative.Native] keyExists: procr_close_key retval = 0 [main] [9:49:13:20] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.CONFIG_VERSION) [main] [9:49:13:20] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:20] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 11 [main] [9:49:13:21] [nativesystem.OCRNative.Native] getKeyValue: value is [10.2.0.0.0] dtype = 3 [main] [9:49:13:21] [OCR.keyExists:664] OCR.keyExists(DATABASE.DATABASES.dupl.INSTANCE) [main] [9:49:13:21] [nativesystem.OCRNative.Native] keyExists: calling procr_open_key(DATABASE.DATABASES.dupl.INSTANCE) [main] [9:49:13:21] [nativesystem.OCRNative.Native] keyExists: procr_open_key retval = 0 [main] [9:49:13:21] [nativesystem.OCRNative.Native] keyExists: procr_close_key retval = 0 [main] [9:49:13:21] [OCR.listSubKeys:615] OCR.listSubKeys(DATABASE.DATABASES.dupl.INSTANCE) [main] [9:49:13:22] [nativesystem.OCRNative.Native] listSubKeys: key_name=[DATABASE.DATABASES.dupl.INSTANCE] [main] [9:49:13:22] [nativesystem.OCRNative.Native] listSubKeys: open key retval = 0 [main] [9:49:13:22] [nativesystem.OCRNative.Native] listSubKeys: setting num_remaining_subkey to -1 [main] [9:49:13:22] [nativesystem.OCRNative.Native] listSubKeys: procr_enum_subkey retval = 0 [main] [9:49:13:23] [nativesystem.OCRNative.Native] listSubKeys: num of remaining subkeys is 0 [main] [9:49:13:23] [OCR.listSubKeys:634] got 1 subKeys [main] [9:49:13:23] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.INSTANCE.dupl1) [main] [9:49:13:23] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:23] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 6 [main] [9:49:13:23] [nativesystem.OCRNative.Native] getKeyValue: value is [DUPL1] dtype = 3 [main] [9:49:13:24] [OCR.listSubKeys:641] subKeys[0]=[dupl1], val=[DUPL1] [main] [9:49:13:24] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.INSTANCE.dupl1.NODE) [main] [9:49:13:24] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:24] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 17 [main] [9:49:13:24] [nativesystem.OCRNative.Native] getKeyValue: value is [cpbttodevorra001] dtype = 3 [main] [9:49:13:25] [OCR.getKeyValues:425] OCR.getKeyValues(DATABASE.DATABASES.dupl.INSTANCE.dupl1.ENVIRONMENT) [main] [9:49:13:25] [nativesystem.OCRNative.Native] getKeyValues: open_key retval = 0 [main] [9:49:13:25] [nativesystem.OCRNative.Native] getKeyValues: procr_get_value retval = 0, dtype is 0 size = 0 [main] [9:49:13:25] [nativesystem.OCRNative.Native] getKeyValues: key [DATABASE.DATABASES.dupl.INSTANCE.dupl1.ENVIRONMENT] has NULL value [main] [9:49:13:25] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.INSTANCE.dupl1.ENABLED) [main] [9:49:13:26] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:26] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 5 [main] [9:49:13:26] [nativesystem.OCRNative.Native] getKeyValue: value is [true] dtype = 3 [main] [9:49:13:27] [OCR.keyExists:664] OCR.keyExists(DATABASE.DATABASES.dupl.SERVICE) [main] [9:49:13:27] [nativesystem.OCRNative.Native] keyExists: calling procr_open_key(DATABASE.DATABASES.dupl.SERVICE) [main] [9:49:13:27] [nativesystem.OCRNative.Native] keyExists: procr_open_key retval = 0 [main] [9:49:13:27] [nativesystem.OCRNative.Native] keyExists: procr_close_key retval = 0 [main] [9:49:13:28] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl) [main] [9:49:13:28] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:29] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 5 [main] [9:49:13:29] [nativesystem.OCRNative.Native] getKeyValue: value is [DUPL] dtype = 3 [main] [9:49:13:29] [OCR.listSubKeys:615] OCR.listSubKeys(DATABASE.DATABASES.dupl.SERVICE) [main] [9:49:13:29] [nativesystem.OCRNative.Native] listSubKeys: key_name=[DATABASE.DATABASES.dupl.SERVICE] [main] [9:49:13:29] [nativesystem.OCRNative.Native] listSubKeys: open key retval = 0 [main] [9:49:13:29] [nativesystem.OCRNative.Native] listSubKeys: setting num_remaining_subkey to -1 [main] [9:49:13:30] [nativesystem.OCRNative.Native] listSubKeys: procr_enum_subkey retval = 16 [main] [9:49:13:30] [nativesystem.OCRNative.Native] listSubKeys: num of remaining subkeys is -1 [main] [9:49:13:30] [OCR.listSubKeys:631] got null subKeys [main] [9:49:13:31] [OCR.getKeyValues:425] OCR.getKeyValues(DATABASE.DATABASES.dupl.ENVIRONMENT) [main] [9:49:13:31] [nativesystem.OCRNative.Native] getKeyValues: open_key retval = 0 [main] [9:49:13:31] [nativesystem.OCRNative.Native] getKeyValues: procr_get_value retval = 0, dtype is 5 size = 0 [main] [9:49:13:31] [nativesystem.OCRNative.Native] getKeyValues: key [DATABASE.DATABASES.dupl.ENVIRONMENT] has NULL value [main] [9:49:13:32] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.DOMAIN) [main] [9:49:13:32] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:32] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 1 [main] [9:49:13:32] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.SPFILE) [main] [9:49:13:33] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:33] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 26 [main] [9:49:13:33] [nativesystem.OCRNative.Native] getKeyValue: value is [+DATA/DUPL/spfileDUPL.ora] dtype = 3 [main] [9:49:13:33] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.DB_NAME) [main] [9:49:13:33] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:34] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 5 [main] [9:49:13:34] [nativesystem.OCRNative.Native] getKeyValue: value is [DUPL] dtype = 3 [main] [9:49:13:34] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.ROLE) [main] [9:49:13:34] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:35] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 1 [main] [9:49:13:35] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.START_OPTIONS) [main] [9:49:13:35] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:35] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 1 [main] [9:49:13:35] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.DB_CLU_ALIAS.IP) [main] [9:49:13:36] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 4 [main] [9:49:13:36] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.ENABLED) [main] [9:49:13:37] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:37] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 5 [main] [9:49:13:37] [nativesystem.OCRNative.Native] getKeyValue: value is [true] dtype = 3 [main] [9:49:13:37] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.POLICY) [main] [9:49:13:38] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:38] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 10 [main] [9:49:13:38] [nativesystem.OCRNative.Native] getKeyValue: value is [AUTOMATIC] dtype = 3 [main] [9:49:13:38] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.PRIOR_POLICY) [main] [9:49:13:39] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:39] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 10 [main] [9:49:13:39] [nativesystem.OCRNative.Native] getKeyValue: value is [AUTOMATIC] dtype = 3 [main] [9:49:13:39] [OCRTreeHA.getDatabaseConfiguration:296] Releasing shared CSS lock SRVM.DATABASE.DATABASES.dupl [main] [9:49:13:39] [has.ClusterLockNative.Native] prsr_trace: Native: unlock [main] [9:49:13:41] [OCRTree.printParallelServerConfig:719] Printing content of database name=DUPL [main] [9:49:13:41] [OCRTree.printParallelServerConfig:720] domain=null [main] [9:49:13:41] [OCRTree.printParallelServerConfig:721] oraclehome=/u01/oracle/10g [main] [9:49:13:41] [OCRTree.printParallelServerConfig:722] spfile=+DATA/DUPL/spfileDUPL.ora [main] [9:49:13:41] [OCRTree.printParallelServerConfig:723] enabled=true [main] [9:49:13:41] [OCRTree.printParallelServerConfig:730] Finishing printing content of database name=DUPL [main] [9:49:13:41] [RawDeviceConfig.getConfiguration:200] returning from ocrtree.getDBConfig [main] [9:49:13:42] [GetConfigurationOperation.run:70] got configuration for ops DUPL [main] [9:49:13:42] [GetConfigurationOperation.run:84] result says 0 [main] [9:49:13:42] [LocalCommand.execute:56] LocalCommand.execute: Returned from run method [main] [9:49:13:42] [ParallelServerHA.startInstance:1111] open mode = null, pfile = null [main] [9:49:13:42] [ParallelServer.isForceWithYou:2158] found = false [main] [9:49:13:42] [OCR.keyExists:664] OCR.keyExists(DATABASE.DATABASES.dupl.INSTANCE.dupl1) [main] [9:49:13:42] [nativesystem.OCRNative.Native] keyExists: calling procr_open_key(DATABASE.DATABASES.dupl.INSTANCE.dupl1) [main] [9:49:13:43] [nativesystem.OCRNative.Native] keyExists: procr_open_key retval = 0 [main] [9:49:13:43] [nativesystem.OCRNative.Native] keyExists: procr_close_key retval = 0 [main] [9:49:13:43] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.INSTANCE.dupl1.ENABLED) [main] [9:49:13:43] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:43] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 5 [main] [9:49:13:44] [nativesystem.OCRNative.Native] getKeyValue: value is [true] dtype = 3 [main] [9:49:13:44] [ParallelServerHA.isEnabled:4056] isEnabled=true [main] [9:49:13:44] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl) [main] [9:49:13:44] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:44] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 5 [main] [9:49:13:45] [nativesystem.OCRNative.Native] getKeyValue: value is [DUPL] dtype = 3 [main] [9:49:13:45] [OCR.getKeyValue:411] OCR.getKeyValue(DATABASE.DATABASES.dupl.INSTANCE.dupl1) [main] [9:49:13:45] [nativesystem.OCRNative.Native] getKeyValue: procr_open_key retval = 0 [main] [9:49:13:45] [nativesystem.OCRNative.Native] getKeyValue: procr_get_value retval = 0, size = 6 [main] [9:49:13:45] [nativesystem.OCRNative.Native] getKeyValue: value is [DUPL1] dtype = 3 [main] [9:49:13:45] [ParallelServerHA.getInstResourceName:4261] dbName=DUPL instName=DUPL1 config=null [main] [9:49:13:46] [ParallelServerHA.getInstResourceName:4266] resname is ora.DUPL.DUPL1.inst [main] [9:49:13:48] [Operation.:63] Setting to be a synchronized operation [main] [9:49:13:48] [HASContext.getInstance:197] Module init : 6 [main] [9:49:13:48] [HASContext.getInstance:221] Local Module init : 0 [main] [9:49:13:48] [HASContext.getInstance:256] HAS Context Allocated: 4 to oracle.ops.mgmt.has.Util@1b26af3 [main] [9:49:13:48] [Util.:87] Util Instance created. [main] [9:49:13:48] [has.UtilNative.Native] prsr_trace: Native: getCRSHome [main] [9:49:13:49] [has.UtilNative.Native] prsr_trace: Native: getCRSHome crs_home=/u01/oracle/crs(**) [main] [9:49:13:49] [HASContext.getCRSHome:457] /u01/oracle/crs [main] [9:49:13:49] [Util.getCRSHome:458] getCRSHome: ret=/u01/oracle/crs [main] [9:49:13:49] [HAOperation.setCRSHome:148] CRS_HOME: /u01/oracle/crs [main] [9:49:13:49] [HAOperation.checkCommandVerb:211] Checking an existence of CRS command [main] [9:49:13:49] [LocalCommand.execute:54] LocalCommand.execute: Calling run method [main] [9:49:13:49] [HAStatusOperation.run:124] Executing the HA operation /u01/oracle/crs/bin/crs_statora.DUPL.DUPL1.inst [main] [9:49:13:53] [HAOperationImpl.runCommand:1246] CRS cmd is: /u01/oracle/crs/bin/crs_stat -u ora.DUPL.DUPL1.inst [main] [9:49:13:54] [RuntimeExec.runCommand:74] Calling Runtime.exec() with the command [main] [9:49:13:54] [RuntimeExec.runCommand:76] /u01/oracle/crs/bin/crs_stat [main] [9:49:13:54] [RuntimeExec.runCommand:76] -u [main] [9:49:13:54] [RuntimeExec.runCommand:76] ora.DUPL.DUPL1.inst [Thread-1] [9:49:13:58] [StreamReader.run:61] In StreamReader.run [main] [9:49:13:58] [RuntimeExec.runCommand:131] runCommand: Waiting for the process [Thread-0] [9:49:13:58] [StreamReader.run:61] In StreamReader.run [Thread-0] [9:49:13:74] [StreamReader.run:65] OUTPUT>NAME=ora.DUPL.DUPL1.inst [Thread-0] [9:49:13:74] [StreamReader.run:65] OUTPUT>TYPE=application [Thread-0] [9:49:13:74] [StreamReader.run:65] OUTPUT>TARGET=ONLINE [Thread-0] [9:49:13:74] [StreamReader.run:65] OUTPUT>STATE=OFFLINE [Thread-0] [9:49:13:74] [StreamReader.run:65] OUTPUT> [main] [9:49:13:74] [RuntimeExec.runCommand:133] runCommand: process returns 0 [main] [9:49:13:75] [RuntimeExec.runCommand:147] RunTimeExec: output> [main] [9:49:13:75] [RuntimeExec.runCommand:150] NAME=ora.DUPL.DUPL1.inst [main] [9:49:13:75] [RuntimeExec.runCommand:150] TYPE=application [main] [9:49:13:75] [RuntimeExec.runCommand:150] TARGET=ONLINE [main] [9:49:13:75] [RuntimeExec.runCommand:150] STATE=OFFLINE [main] [9:49:13:75] [RuntimeExec.runCommand:150] [main] [9:49:13:75] [RuntimeExec.runCommand:155] RunTimeExec: error> [main] [9:49:13:76] [RuntimeExec.runCommand:175] Returning from RunTimeExec.runCommand [main] [9:49:13:76] [HAOperationImpl.runCommand:1275] set status OK [main] [9:49:13:76] [HAStatusOperation.run:127] Returned from executing the HA Operation [main] [9:49:13:76] [HAStatusOperation.run:132] OUTPUT> NAME=ora.DUPL.DUPL1.inst [main] [9:49:13:76] [HAStatusOperation.run:132] OUTPUT> TYPE=application [main] [9:49:13:76] [HAStatusOperation.run:132] OUTPUT> TARGET=ONLINE [main] [9:49:13:77] [HAStatusOperation.run:132] OUTPUT> STATE=OFFLINE [main] [9:49:13:77] [HAStatusOperation.run:132] OUTPUT> [main] [9:49:13:77] [HAStatusOperation.run:138] ERROR> [main] [9:49:13:77] [LocalCommand.execute:56] LocalCommand.execute: Returned from run method [main] [9:49:13:78] [HAResourceStatus.parseHAStatusOutput:293] got status: resource=ora.DUPL.DUPL1.insttarget=ONLINE status=OFFLINE host=null [main] [9:49:13:105] [RemoteResponseEvent.:62] Creating Rmi Data Event [main] [9:49:13:108] [ParallelServerHA.getInstResourceName:4261] dbName=DUPL instName=DUPL1 config=oracle.ops.mgmt.database.ParallelServerConfig@17e6a96 [main] [9:49:13:109] [ParallelServerHA.getInstResourceName:4286] found this instName in config [main] [9:49:13:109] [ParallelServerHA.getInstResourceName:4294] resname is ora.DUPL.DUPL1.inst [main] [9:49:13:109] [Operation.:63] Setting to be a synchronized operation [main] [9:49:13:110] [HASContext.getInstance:197] Module init : 6 [main] [9:49:13:110] [HASContext.getInstance:221] Local Module init : 0 [main] [9:49:13:110] [HASContext.getInstance:256] HAS Context Allocated: 5 to oracle.ops.mgmt.has.Util@b42cbf [main] [9:49:13:110] [Util.:87] Util Instance created. [main] [9:49:13:111] [has.UtilNative.Native] prsr_trace: Native: getCRSHome [main] [9:49:13:111] [has.UtilNative.Native] prsr_trace: Native: getCRSHome crs_home=/u01/oracle/crs(**) [main] [9:49:13:111] [HASContext.getCRSHome:457] /u01/oracle/crs [main] [9:49:13:112] [Util.getCRSHome:458] getCRSHome: ret=/u01/oracle/crs [main] [9:49:13:112] [HAOperation.setCRSHome:148] CRS_HOME: /u01/oracle/crs [main] [9:49:13:112] [HAOperation.checkCommandVerb:211] Checking an existence of CRS command [main] [9:49:13:112] [ParallelServerHA.startInstance:1253] parallel execution [main] [9:49:13:127] [ParallelServerHA.startInstance:1259] submitting startinstance command [main] [9:49:13:137] [ClusterConfig.isClusterInstalled:315] hasJarPresent=true [main] [9:49:13:137] [GetActiveNodes.create:221] Returning an existing instance of GetActiveNodes [main] [9:49:13:137] [ClusterConfig.:220] ClusterConfig:Number of workers = 0 [Worker 0] [9:49:13:138] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [Worker 1] [9:49:13:139] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=0 [Worker 2] [9:49:13:139] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [main] [9:49:13:139] [ClusterConfig.createWorkers:265] Started worker threads count=4 [main] [9:49:13:139] [ClusterConfig.isClusterInstalled:315] hasJarPresent=true [main] [9:49:13:139] [GetActiveNodes.create:221] Returning an existing instance of GetActiveNodes [main] [9:49:13:139] [ClusterConfig.init:362] Returning same instance to clientmain [main] [9:49:13:140] [ClusterConfig.submit:427] Entering submit, cmdCount=1 [main] [9:49:13:140] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=4 [main] [9:49:13:140] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 0] [9:49:13:141] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 0 m_count=4 [Worker 0] [9:49:13:141] [LocalCommand.execute:54] LocalCommand.execute: Calling run method [Worker 0] [9:49:13:141] [HAStartOperation.run:81] Executing the HA operation /u01/oracle/crs/bin/crs_startora.DUPL.DUPL1.inst [Worker 0] [9:49:13:141] [HAOperationImpl.runCommand:1246] CRS cmd is: /u01/oracle/crs/bin/crs_start ora.DUPL.DUPL1.inst -f -c cpbttodevorra001 [Worker 0] [9:49:13:141] [RuntimeExec.runCommand:74] Calling Runtime.exec() with the command [Worker 0] [9:49:13:141] [RuntimeExec.runCommand:76] /u01/oracle/crs/bin/crs_start [Worker 0] [9:49:13:141] [RuntimeExec.runCommand:76] ora.DUPL.DUPL1.inst [Worker 0] [9:49:13:141] [RuntimeExec.runCommand:76] -f [Worker 0] [9:49:13:141] [RuntimeExec.runCommand:76] -c [Worker 0] [9:49:13:141] [RuntimeExec.runCommand:76] cpbttodevorra001 [main] [9:49:13:141] [ClusterConfig.submit:462] submitted commands=1 [main] [9:49:13:141] [ClusterConfig.block:535] block called by thread main commandNum 1 [main] [9:49:13:142] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 3] [9:49:13:142] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 3 m_count=0 [Thread-3] [9:49:13:144] [StreamReader.run:61] In StreamReader.run [Worker 0] [9:49:13:144] [RuntimeExec.runCommand:131] runCommand: Waiting for the process [Thread-2] [9:49:13:144] [StreamReader.run:61] In StreamReader.run [Thread-2] [9:49:13:177] [StreamReader.run:65] OUTPUT>Attempting to start `ora.DUPL.DUPL1.inst` on member `cpbttodevorra001` [Thread-2] [9:49:22:587] [StreamReader.run:65] OUTPUT>Start of `ora.DUPL.DUPL1.inst` on member `cpbttodevorra001` failed. [Thread-3] [9:49:22:591] [StreamReader.run:65] ERROR>CRS-0215: Could not start resource 'ora.DUPL.DUPL1.inst'. [Thread-3] [9:49:22:591] [StreamReader.run:65] ERROR> [Worker 0] [9:49:22:592] [RuntimeExec.runCommand:133] runCommand: process returns 115 [Worker 0] [9:49:22:593] [RuntimeExec.runCommand:147] RunTimeExec: output> [Worker 0] [9:49:22:593] [RuntimeExec.runCommand:150] Attempting to start `ora.DUPL.DUPL1.inst` on member `cpbttodevorra001` [Worker 0] [9:49:22:593] [RuntimeExec.runCommand:150] Start of `ora.DUPL.DUPL1.inst` on member `cpbttodevorra001` failed. [Worker 0] [9:49:22:593] [RuntimeExec.runCommand:155] RunTimeExec: error> [Worker 0] [9:49:22:593] [RuntimeExec.runCommand:158] CRS-0215: Could not start resource 'ora.DUPL.DUPL1.inst'. [Worker 0] [9:49:22:593] [RuntimeExec.runCommand:158] [Worker 0] [9:49:22:593] [RuntimeExec.runCommand:175] Returning from RunTimeExec.runCommand [Worker 0] [9:49:22:593] [HAOperationImpl.runCommand:1290] set status FAILED [Worker 0] [9:49:22:594] [HAStartOperation.run:84] Returned from executing the HA Operation [Worker 0] [9:49:22:594] [HAStartOperation.run:89] OUTPUT> Attempting to start `ora.DUPL.DUPL1.inst` on member `cpbttodevorra001` [Worker 0] [9:49:22:594] [HAStartOperation.run:89] OUTPUT> Start of `ora.DUPL.DUPL1.inst` on member `cpbttodevorra001` failed. [Worker 0] [9:49:22:594] [HAStartOperation.run:95] ERROR> CRS-0215: Could not start resource 'ora.DUPL.DUPL1.inst'. [Worker 0] [9:49:22:594] [LocalCommand.execute:56] LocalCommand.execute: Returned from run method [Worker 0] [9:49:22:594] [ClusterConfig$ExecuteCommand.returnCommandToClient:2532] returnCommandToClient; fillCount=0 is full=false [Worker 0] [9:49:22:594] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 0 m_count=50 [Worker 0] [9:49:22:595] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 0 m_count=1 [Worker 0] [9:49:22:595] [ClientResource.getListener:157] Calling getListener [Worker 0] [9:49:22:595] [ClusterConfig$ExecuteCommand.run:2614] Owner Thread name of the blocking Semaphore main [Worker 0] [9:49:22:596] [ClusterConfig$ExecuteCommand.run:2622] Obtained Semaphore [Worker 0] [9:49:22:596] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 0 m_count=1 [main] [9:49:22:596] [ClusterConfig.block:547] block acquired semnum=0 [main] [9:49:22:596] [ClusterConfig.submit:496] Out of block [main] [9:49:22:596] [ClusterConfig.submit:513] status=true [main] [9:49:22:596] [ClusterConfig.destroy:391] destroying resources for client thread Thread[main,5,main] [main] [9:49:22:596] [ParallelServerHA.startInstance:1272] serialized execution [main] [9:49:22:597] [HAOperationResult.getOutputAll:114] outLine is [] [main] [9:49:22:597] [HAOperationResult.getOutputAll:115] errLine is [CRS-0215: Could not start resource 'ora.DUPL.DUPL1.inst'.] [main] [9:49:22:597] [ParallelServerHA.startInstance:1391] Failed to start DUPL1 on cpbttodevorra001 error=CRS-0215: Could not start resource 'ora.DUPL.DUPL1.inst'. [main] [9:49:22:597] [RemoteResponseEvent.:62] Creating Rmi Data Event [Worker 0] [9:49:22:598] [ClusterConfig$ExecuteCommand.run:2637] Released Semaphore by worker=Worker 0 [Worker 0] [9:49:22:598] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [main] [9:49:22:603] [HAOperationResult.getOutputAll:114] outLine is [] [main] [9:49:22:604] [HAOperationResult.getOutputAll:115] errLine is [CRS-0215: Could not start resource 'ora.DUPL.DUPL1.inst'.] PRKP-1001 : Error starting instance DUPL1 on node cpbttodevorra001 CRS-0215: Could not start resource 'ora.DUPL.DUPL1.inst'.