[main] [ 2019-08-21 22:08:23.099 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:08:23.105 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:08:23.140 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:08:23.142 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:08:23.156 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:08:23.156 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:08:23.159 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:08:23.160 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:08:23.160 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:08:23.160 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:08:23.161 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:08:23.161 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:08:23.162 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:08:23.166 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:08:23.167 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:08:23.167 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:08:23.167 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:08:23.168 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:08:23.168 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:08:23.168 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@5679c6c6 [main] [ 2019-08-21 22:08:23.173 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.cluster.util.SRVMContext.init(SRVMContext.java:123) oracle.cluster.util.SRVMContext.init(SRVMContext.java:84) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:301) [main] [ 2019-08-21 22:08:23.173 AST ] [SRVMContext.init:126] No CRS configuration found [main] [ 2019-08-21 22:08:23.174 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:08:23.175 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:08:23.175 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:08:23.175 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:08:23.176 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:08:23.176 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:08:23.181 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:08:23.181 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:08:23.184 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:08:23.185 AST ] [ClusterwareCkpt.executeCkpt:1105] Processing chkckpt command line arguments [main] [ 2019-08-21 22:08:23.194 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:08:23.194 AST ] [ClusterwareCkpt.isCkptExists:308] Checking if checkpoint:ROOTCRS_FIRSTNODE exists [main] [ 2019-08-21 22:08:23.197 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:08:23.208 AST ] [CheckPointIndexSessionImpl.:94] Checkpoint:Index file :/u01/app/grid/crsdata/@global/crsconfig/index.xml not found. [main] [ 2019-08-21 22:08:23.209 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:08:23.210 AST ] [CheckPointSessionImpl.:101] Checkpoint:checkpointfile :/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml not found, one will be created for this session [main] [ 2019-08-21 22:08:23.211 AST ] [ClusterwareCkpt.isCkptExists:322] ckpt = null [main] [ 2019-08-21 22:08:23.211 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:10:14.757 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:10:14.768 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:10:14.811 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:10:14.814 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:10:14.827 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:14.828 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:14.831 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:14.834 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:10:14.834 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:10:14.835 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:10:14.836 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:10:14.836 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:10:14.836 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:14.839 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:14.840 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:14.840 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:14.840 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:14.841 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:14.841 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:14.842 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@5679c6c6 [main] [ 2019-08-21 22:10:14.847 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.cluster.util.SRVMContext.init(SRVMContext.java:123) oracle.cluster.util.SRVMContext.init(SRVMContext.java:84) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:301) [main] [ 2019-08-21 22:10:14.847 AST ] [SRVMContext.init:126] No CRS configuration found [main] [ 2019-08-21 22:10:14.848 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:10:14.849 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:10:14.849 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:10:14.849 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:10:14.850 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:10:14.850 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:10:14.858 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:10:14.858 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE,-status [main] [ 2019-08-21 22:10:14.861 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:10:14.863 AST ] [ClusterwareCkpt.executeCkpt:1105] Processing chkckpt command line arguments [main] [ 2019-08-21 22:10:14.872 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE,-status [main] [ 2019-08-21 22:10:14.873 AST ] [ClusterwareCkpt.getCkptStatus:329] Checking to see if checkpoint:ROOTCRS_FIRSTNODEhas successfuly completed [main] [ 2019-08-21 22:10:14.877 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:10:14.889 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/crsdata/@global/crsconfig/index.xml found. [main] [ 2019-08-21 22:10:15.011 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:10:15.011 AST ] [ClusterwareCkpt.getCkptStatus:353] Reading data for checkpoint: ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:10:15.012 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:10:28.216 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:10:28.228 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:10:28.299 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:10:28.302 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:10:28.324 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:28.324 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:28.329 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:28.330 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:10:28.331 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:10:28.331 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:10:28.333 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:10:28.333 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:10:28.333 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:28.340 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:28.342 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:28.342 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:28.343 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:28.343 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:28.344 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:28.344 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@5679c6c6 [main] [ 2019-08-21 22:10:28.352 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.cluster.util.SRVMContext.init(SRVMContext.java:123) oracle.cluster.util.SRVMContext.init(SRVMContext.java:84) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:301) [main] [ 2019-08-21 22:10:28.353 AST ] [SRVMContext.init:126] No CRS configuration found [main] [ 2019-08-21 22:10:28.354 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:10:28.355 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:10:28.355 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:10:28.356 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:10:28.357 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:10:28.357 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:10:28.365 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:10:28.366 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_FIRSTNODE,-state,START,-nodelist,testdb1,testdb2,-transferfile [main] [ 2019-08-21 22:10:28.371 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:10:28.373 AST ] [ClusterwareCkpt.executeCkpt:1122] Processing writeckpt command line arguments [main] [ 2019-08-21 22:10:28.386 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_FIRSTNODE,-state,START,-nodelist,testdb1,testdb2,-transferfile [main] [ 2019-08-21 22:10:28.387 AST ] [ClusterwareCkpt.writeCheckPoint:544] Writing checkpoint [main] [ 2019-08-21 22:10:28.388 AST ] [ClusterwareCkpt.writeCheckPoint:545] Ckpt Name: ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:10:28.388 AST ] [ClusterwareCkpt.writeCheckPoint:546] Ckpt Desc: null [main] [ 2019-08-21 22:10:28.389 AST ] [ClusterwareCkpt.writeCheckPoint:547] Ckpt Level: null [main] [ 2019-08-21 22:10:28.390 AST ] [ClusterwareCkpt.writeCheckPoint:548] Ckpt State: START [main] [ 2019-08-21 22:10:28.390 AST ] [ClusterwareCkpt.writeCheckPoint:552] after assert of checkpoint name [main] [ 2019-08-21 22:10:28.394 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:10:28.412 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/crsdata/@global/crsconfig/index.xml found. [main] [ 2019-08-21 22:10:28.584 AST ] [ClusterwareCkpt.writeCheckPoint:567] ckpt debug 1 [main] [ 2019-08-21 22:10:28.585 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:10:28.585 AST ] [ClusterwareCkpt.writeCheckPoint:570] ckpt debug 2 [main] [ 2019-08-21 22:10:28.586 AST ] [ClusterwareCkpt.writeCheckPoint:574] ckpt debug 3 [main] [ 2019-08-21 22:10:28.586 AST ] [ClusterwareCkpt.writeCheckPoint:586] Setting checkpoint state to: 1 [main] [ 2019-08-21 22:10:28.586 AST ] [ClusterwareCkpt.writeCheckPoint:590] ckpt debug 4 [main] [ 2019-08-21 22:10:28.587 AST ] [ClusterwareCkpt.writeCheckPoint:595] ckpt debug 5 [main] [ 2019-08-21 22:10:28.597 AST ] [CheckPointSessionImpl.saveCheckPointSession:143] Checkpoint:Index file written and updated [main] [ 2019-08-21 22:10:28.597 AST ] [ClusterwareCkpt.writeCheckPoint:599] ckpt debug 6 [main] [ 2019-08-21 22:10:28.602 AST ] [ClusterwareCkpt.propagateGlobalCheckpoint:871] Propagating global checkpoints to nodes: testdb1,testdb2 [main] [ 2019-08-21 22:10:28.602 AST ] [ClusterwareCkpt.propagateGlobalCheckpoint:876] Closing global checkpoint session [main] [ 2019-08-21 22:10:28.603 AST ] [CheckPointIndexWriter.generatePropertiesNode:220] Checkpoint:Setting status in index file as passed,as no last failed checkpoint is available. [main] [ 2019-08-21 22:10:28.604 AST ] [CheckPointSessionImpl.closeCheckPointSession:183] Sending checkpoint files to remote nodes [main] [ 2019-08-21 22:10:28.604 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:10:28.605 AST ] [Utils.getNodeName:571] Hostname : testdb1 is converted to nodeName : testdb1 [main] [ 2019-08-21 22:10:28.605 AST ] [ClusterUtil.findLiveNodes:218] Attempt to find live nodes [main] [ 2019-08-21 22:10:28.615 AST ] [ClusterConfig.:240] ClusterConfig:Number of workers = 0 [main] [ 2019-08-21 22:10:28.618 AST ] [ClusterConfig.createWorkers:325] Started worker threads count=1 [main] [ 2019-08-21 22:10:28.626 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:10:28.627 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:28.634 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:28.636 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:28.636 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:10:28.637 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:28.637 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:28.638 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:28.641 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:10:28.641 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:28.641 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:28.642 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:28.642 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:28.642 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:28.643 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:28.643 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:28.644 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@337d0578 [main] [ 2019-08-21 22:10:28.644 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.cluster.util.SRVMContext.init(SRVMContext.java:123) oracle.cluster.util.SRVMContext.init(SRVMContext.java:84) oracle.ops.mgmt.rawdevice.OCR.isCluster(OCR.java:1047) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:263) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.ops.mgmt.cluster.ClusterConfig.isClusterInstalled(ClusterConfig.java:388) oracle.ops.mgmt.cluster.ClusterConfig.(ClusterConfig.java:248) oracle.ops.mgmt.cluster.ClusterConfig.init(ClusterConfig.java:434) oracle.ops.mgmt.cluster.ClusterCmd.areNodesAlive(ClusterCmd.java:2886) oracle.ops.util.ClusterUtil.findLiveNodes(ClusterUtil.java:219) oracle.cluster.impl.checkpoints.CheckPointUtil.transferGlobalCkptToNodes(CheckPointUtil.java:191) oracle.cluster.impl.checkpoints.CheckPointSessionImpl.closeCheckPointSession(CheckPointSessionImpl.java:186) oracle.ops.util.ClusterwareCkpt.propagateGlobalCheckpoint(ClusterwareCkpt.java:877) oracle.ops.util.ClusterwareCkpt.writeCheckPoint(ClusterwareCkpt.java:601) oracle.ops.util.ClusterwareCkpt.executeCkpt(ClusterwareCkpt.java:1210) oracle.ops.util.ClusterUtil.execute(ClusterUtil.java:158) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:332) [main] [ 2019-08-21 22:10:28.644 AST ] [SRVMContext.init:126] No CRS configuration found [main] [ 2019-08-21 22:10:28.645 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:28.645 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:28.645 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:28.647 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:28.649 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:28.649 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:28.651 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:28.651 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@59e84876 [main] [ 2019-08-21 22:10:28.651 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.ops.mgmt.cluster.ClusterConfig.isClusterInstalled(ClusterConfig.java:388) oracle.ops.mgmt.cluster.ClusterConfig.(ClusterConfig.java:248) oracle.ops.mgmt.cluster.ClusterConfig.init(ClusterConfig.java:434) oracle.ops.mgmt.cluster.ClusterCmd.areNodesAlive(ClusterCmd.java:2886) oracle.ops.util.ClusterUtil.findLiveNodes(ClusterUtil.java:219) oracle.cluster.impl.checkpoints.CheckPointUtil.transferGlobalCkptToNodes(CheckPointUtil.java:191) oracle.cluster.impl.checkpoints.CheckPointSessionImpl.closeCheckPointSession(CheckPointSessionImpl.java:186) oracle.ops.util.ClusterwareCkpt.propagateGlobalCheckpoint(ClusterwareCkpt.java:877) oracle.ops.util.ClusterwareCkpt.writeCheckPoint(ClusterwareCkpt.java:601) oracle.ops.util.ClusterwareCkpt.executeCkpt(ClusterwareCkpt.java:1210) oracle.ops.util.ClusterUtil.execute(ClusterUtil.java:158) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:332) [main] [ 2019-08-21 22:10:28.652 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:10:28.654 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-08-21 22:10:28.655 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:10:28.655 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-08-21 22:10:28.655 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-08-21 22:10:28.655 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:10:28.655 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 0] [ 2019-08-21 22:10:28.659 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:10:28.659 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:10:28.664 AST ] [sPlatform.getPingCmdArgs:89] Node=testdb2 Timeout=10 [Worker 0] [ 2019-08-21 22:10:28.879 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Worker 0] [ 2019-08-21 22:10:28.883 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Thread-2] [ 2019-08-21 22:10:28.883 AST ] [StreamReader.run:62] In StreamReader.run [Thread-1] [ 2019-08-21 22:10:28.886 AST ] [StreamReader.run:62] In StreamReader.run [Thread-1] [ 2019-08-21 22:10:28.886 AST ] [StreamReader.run:66] OUTPUT>testdb2 is alive [Worker 0] [ 2019-08-21 22:10:28.890 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 0] [ 2019-08-21 22:10:28.891 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 0] [ 2019-08-21 22:10:28.891 AST ] [UnixSystem.isNodeAlive:5164] msgBuf=testdb2 is alive [Worker 0] [ 2019-08-21 22:10:28.894 AST ] [NodeLivenessCommand.postEvent:103] Inside NodeLivenessCommand.postEvent, listener size=0 [Worker 0] [ 2019-08-21 22:10:28.895 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 0] [ 2019-08-21 22:10:28.895 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 0 m_count=50 [Worker 0] [ 2019-08-21 22:10:28.896 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:10:28.896 AST ] [ClientResource.getListener:157] Calling getListener [Worker 0] [ 2019-08-21 22:10:28.896 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 0] [ 2019-08-21 22:10:28.907 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 0] [ 2019-08-21 22:10:28.908 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 0 m_count=1 [main] [ 2019-08-21 22:10:28.908 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:10:28.909 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-08-21 22:10:28.909 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-08-21 22:10:28.909 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:10:28.910 AST ] [ClusterUtil.findLiveNodes:258] All nodes are up [main] [ 2019-08-21 22:10:28.910 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:10:28.913 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:28.914 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:28.914 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:28.915 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:10:28.916 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:28.918 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:28.924 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:28.931 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:10:28.932 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:28.933 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:28.933 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:28.934 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:28.934 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:28.934 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:28.935 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:28.935 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@5cc7c2a6 [main] [ 2019-08-21 22:10:28.936 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.cluster.util.SRVMContext.init(SRVMContext.java:123) oracle.cluster.util.SRVMContext.init(SRVMContext.java:84) oracle.ops.mgmt.rawdevice.OCR.isCluster(OCR.java:1047) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:263) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.ops.mgmt.cluster.ClusterConfig.isClusterInstalled(ClusterConfig.java:388) oracle.ops.mgmt.cluster.ClusterConfig.init(ClusterConfig.java:405) oracle.ops.mgmt.cluster.ClusterCmd.createDirOnNodes(ClusterCmd.java:1183) oracle.ops.mgmt.cluster.ClusterCmd.createDirWithPermissionsOnNodes(ClusterCmd.java:1030) oracle.cluster.impl.checkpoints.CheckPointUtil.transferFiles(CheckPointUtil.java:275) oracle.cluster.impl.checkpoints.CheckPointUtil.transferGlobalCkptToNodes(CheckPointUtil.java:224) oracle.cluster.impl.checkpoints.CheckPointSessionImpl.closeCheckPointSession(CheckPointSessionImpl.java:186) oracle.ops.util.ClusterwareCkpt.propagateGlobalCheckpoint(ClusterwareCkpt.java:877) oracle.ops.util.ClusterwareCkpt.writeCheckPoint(ClusterwareCkpt.java:601) oracle.ops.util.ClusterwareCkpt.executeCkpt(ClusterwareCkpt.java:1210) oracle.ops.util.ClusterUtil.execute(ClusterUtil.java:158) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:332) [main] [ 2019-08-21 22:10:28.937 AST ] [SRVMContext.init:126] No CRS configuration found [main] [ 2019-08-21 22:10:28.937 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:28.937 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:28.938 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:28.939 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:28.939 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:28.939 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:28.939 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:28.949 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@b97c004 [main] [ 2019-08-21 22:10:28.949 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.ops.mgmt.cluster.ClusterConfig.isClusterInstalled(ClusterConfig.java:388) oracle.ops.mgmt.cluster.ClusterConfig.init(ClusterConfig.java:405) oracle.ops.mgmt.cluster.ClusterCmd.createDirOnNodes(ClusterCmd.java:1183) oracle.ops.mgmt.cluster.ClusterCmd.createDirWithPermissionsOnNodes(ClusterCmd.java:1030) oracle.cluster.impl.checkpoints.CheckPointUtil.transferFiles(CheckPointUtil.java:275) oracle.cluster.impl.checkpoints.CheckPointUtil.transferGlobalCkptToNodes(CheckPointUtil.java:224) oracle.cluster.impl.checkpoints.CheckPointSessionImpl.closeCheckPointSession(CheckPointSessionImpl.java:186) oracle.ops.util.ClusterwareCkpt.propagateGlobalCheckpoint(ClusterwareCkpt.java:877) oracle.ops.util.ClusterwareCkpt.writeCheckPoint(ClusterwareCkpt.java:601) oracle.ops.util.ClusterwareCkpt.executeCkpt(ClusterwareCkpt.java:1210) oracle.ops.util.ClusterUtil.execute(ClusterUtil.java:158) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:332) [Worker 0] [ 2019-08-21 22:10:28.951 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 0 [Worker 0] [ 2019-08-21 22:10:28.951 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [main] [ 2019-08-21 22:10:28.949 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:10:28.952 AST ] [ClusterConfig.createWorkers:327] Started additional worker threads count=3 [main] [ 2019-08-21 22:10:28.953 AST ] [ClusterConfig.createDirInNode:1940] Creating dir in nodes: testdb2, /u01/app/grid/crsdata/@global/crsconfig, true, 700 [main] [ 2019-08-21 22:10:28.954 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:10:28.954 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-08-21 22:10:28.954 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:10:28.955 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 0] [ 2019-08-21 22:10:28.955 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:10:28.955 AST ] [DirCreateCommand.execute:70] In DirCreateCommand.execute, recurseFlag=false, modeFlag=false [Worker 0] [ 2019-08-21 22:10:28.956 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 0] [ 2019-08-21 22:10:28.957 AST ] [UnixSystem.checkRemoteExecutionSetup:3071] Client didn't specify for remote shell or remote copy [Worker 0] [ 2019-08-21 22:10:28.959 AST ] [Library.load:202] library.load [Worker 0] [ 2019-08-21 22:10:28.959 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [Worker 0] [ 2019-08-21 22:10:28.962 AST ] [UnixSystem.checkRemoteExecutionSetup:3082] checkRemoteExecutionSetup:: Checking user equivalence using Secured Shell '/usr/bin/ssh' [Worker 0] [ 2019-08-21 22:10:28.962 AST ] [UnixSystem.checkRemoteExecutionSetup:3084] checkRemoteExecutionSetup:: Running Unix command: /usr/bin/ssh -o FallBackToRsh=no -o PasswordAuthentication=no -o StrictHostKeyChecking=yes -o NumberOfPasswordPrompts=0 testdb2 /usr/bin/true [Worker 1] [ 2019-08-21 22:10:28.963 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=0 [Worker 2] [ 2019-08-21 22:10:28.964 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [Worker 3] [ 2019-08-21 22:10:28.965 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 3 m_count=0 [Worker 0] [ 2019-08-21 22:10:28.980 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-4] [ 2019-08-21 22:10:28.982 AST ] [StreamReader.run:62] In StreamReader.run [Thread-3] [ 2019-08-21 22:10:28.984 AST ] [StreamReader.run:62] In StreamReader.run [Worker 0] [ 2019-08-21 22:10:29.224 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 0] [ 2019-08-21 22:10:29.225 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 0] [ 2019-08-21 22:10:29.225 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 0] [ 2019-08-21 22:10:29.225 AST ] [UnixSystem.checkRemoteExecutionSetup:3211] Using Remote Shell Command: '/usr/bin/ssh -o FallBackToRsh=no -o PasswordAuthentication=no -o StrictHostKeyChecking=yes -o NumberOfPasswordPrompts=0 ' [Worker 0] [ 2019-08-21 22:10:29.226 AST ] [UnixSystem.checkRemoteExecutionSetup:3212] Using Remote Copy Command: '/usr/bin/scp' [Worker 0] [ 2019-08-21 22:10:29.246 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-6] [ 2019-08-21 22:10:29.248 AST ] [StreamReader.run:62] In StreamReader.run [Thread-5] [ 2019-08-21 22:10:29.251 AST ] [StreamReader.run:62] In StreamReader.run [Worker 0] [ 2019-08-21 22:10:29.482 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 0] [ 2019-08-21 22:10:29.482 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 0] [ 2019-08-21 22:10:29.483 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 0] [ 2019-08-21 22:10:29.483 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/ssh -o FallBackToRsh=no -o PasswordAuthentication=no -o StrictHostKeyChecking=yes -o NumberOfPasswordPrompts=0 testdb2 -n /usr/bin/mkdir -p -m 700 /u01/app/grid/crsdata/@global/crsconfig] [Worker 0] [ 2019-08-21 22:10:29.488 AST ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/ssh is present. [Worker 0] [ 2019-08-21 22:10:29.489 AST ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/ssh is a file. [Worker 0] [ 2019-08-21 22:10:29.489 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned true [Worker 0] [ 2019-08-21 22:10:29.490 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 0] [ 2019-08-21 22:10:29.490 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 0] [ 2019-08-21 22:10:29.492 AST ] [NativeResult.:101] The status string is: 1 [Worker 0] [ 2019-08-21 22:10:29.493 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 0] [ 2019-08-21 22:10:29.493 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 0] [ 2019-08-21 22:10:29.494 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 0 m_count=50 [Worker 0] [ 2019-08-21 22:10:29.494 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:10:29.494 AST ] [ClientResource.getListener:157] Calling getListener [Worker 0] [ 2019-08-21 22:10:29.495 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 0] [ 2019-08-21 22:10:29.496 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 0] [ 2019-08-21 22:10:29.496 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:10:29.496 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 0 [Worker 0] [ 2019-08-21 22:10:29.497 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [main] [ 2019-08-21 22:10:29.497 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:10:29.498 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:10:29.498 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:10:29.498 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:29.499 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:29.499 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:29.499 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:10:29.499 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:29.500 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:29.500 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:29.500 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:10:29.501 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:29.501 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:29.502 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:29.502 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:29.503 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:29.503 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:29.503 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:29.505 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@4590c9c3 [main] [ 2019-08-21 22:10:29.505 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.cluster.util.SRVMContext.init(SRVMContext.java:123) oracle.cluster.util.SRVMContext.init(SRVMContext.java:84) oracle.ops.mgmt.rawdevice.OCR.isCluster(OCR.java:1047) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:263) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.ops.mgmt.cluster.ClusterConfig.isClusterInstalled(ClusterConfig.java:388) oracle.ops.mgmt.cluster.ClusterConfig.init(ClusterConfig.java:405) oracle.ops.mgmt.cluster.ClusterCmd.copyFileToNodes(ClusterCmd.java:786) oracle.ops.mgmt.cluster.ClusterCmd.copyFileToNodes(ClusterCmd.java:764) oracle.cluster.impl.checkpoints.CheckPointUtil.transferFiles(CheckPointUtil.java:278) oracle.cluster.impl.checkpoints.CheckPointUtil.transferGlobalCkptToNodes(CheckPointUtil.java:224) oracle.cluster.impl.checkpoints.CheckPointSessionImpl.closeCheckPointSession(CheckPointSessionImpl.java:186) oracle.ops.util.ClusterwareCkpt.propagateGlobalCheckpoint(ClusterwareCkpt.java:877) oracle.ops.util.ClusterwareCkpt.writeCheckPoint(ClusterwareCkpt.java:601) oracle.ops.util.ClusterwareCkpt.executeCkpt(ClusterwareCkpt.java:1210) oracle.ops.util.ClusterUtil.execute(ClusterUtil.java:158) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:332) [main] [ 2019-08-21 22:10:29.506 AST ] [SRVMContext.init:126] No CRS configuration found [main] [ 2019-08-21 22:10:29.506 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:29.506 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:29.509 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:29.509 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:29.510 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:29.510 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:29.510 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:29.511 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@32e6e9c3 [main] [ 2019-08-21 22:10:29.511 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.ops.mgmt.cluster.ClusterConfig.isClusterInstalled(ClusterConfig.java:388) oracle.ops.mgmt.cluster.ClusterConfig.init(ClusterConfig.java:405) oracle.ops.mgmt.cluster.ClusterCmd.copyFileToNodes(ClusterCmd.java:786) oracle.ops.mgmt.cluster.ClusterCmd.copyFileToNodes(ClusterCmd.java:764) oracle.cluster.impl.checkpoints.CheckPointUtil.transferFiles(CheckPointUtil.java:278) oracle.cluster.impl.checkpoints.CheckPointUtil.transferGlobalCkptToNodes(CheckPointUtil.java:224) oracle.cluster.impl.checkpoints.CheckPointSessionImpl.closeCheckPointSession(CheckPointSessionImpl.java:186) oracle.ops.util.ClusterwareCkpt.propagateGlobalCheckpoint(ClusterwareCkpt.java:877) oracle.ops.util.ClusterwareCkpt.writeCheckPoint(ClusterwareCkpt.java:601) oracle.ops.util.ClusterwareCkpt.executeCkpt(ClusterwareCkpt.java:1210) oracle.ops.util.ClusterUtil.execute(ClusterUtil.java:158) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:332) [main] [ 2019-08-21 22:10:29.512 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:10:29.512 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:947] Number of nodes :1 [main] [ 2019-08-21 22:10:29.512 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:949] 0th CopyFileToNodes localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:10:29.513 AST ] [ClusterConfig.copyFileBetweenNodes:684] Checking: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:10:29.513 AST ] [ClusterConfig.copyFileBetweenNodes:696] Checking 2: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:10:29.514 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:10:29.514 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-08-21 22:10:29.514 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:10:29.515 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 1] [ 2019-08-21 22:10:29.516 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:10:29.519 AST ] [UnixSystem.copyFile:1084] Copy file localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [Worker 1] [ 2019-08-21 22:10:29.520 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 1] [ 2019-08-21 22:10:29.521 AST ] [UnixSystem.remoteCopyFile:808] Copying files localnode/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [Worker 1] [ 2019-08-21 22:10:29.523 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 1] [ 2019-08-21 22:10:29.523 AST ] [UnixSystem.remoteCopyFile:826] UnixSystem: /usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml' [Worker 1] [ 2019-08-21 22:10:29.532 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-8] [ 2019-08-21 22:10:29.549 AST ] [StreamReader.run:62] In StreamReader.run [Thread-7] [ 2019-08-21 22:10:29.552 AST ] [StreamReader.run:62] In StreamReader.run [Worker 1] [ 2019-08-21 22:10:29.778 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 1] [ 2019-08-21 22:10:29.778 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 1] [ 2019-08-21 22:10:29.785 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 1] [ 2019-08-21 22:10:29.793 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml'] [Worker 1] [ 2019-08-21 22:10:29.826 AST ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/scp is present. [Worker 1] [ 2019-08-21 22:10:29.840 AST ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/scp is a file. [Worker 1] [ 2019-08-21 22:10:29.841 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned true [Worker 1] [ 2019-08-21 22:10:29.841 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 1] [ 2019-08-21 22:10:29.841 AST ] [CopyCommand.execute:171] CopyCommand.execute: native copyFile returns `1| :successful' [Worker 1] [ 2019-08-21 22:10:29.842 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 1] [ 2019-08-21 22:10:29.842 AST ] [NativeResult.:101] The status string is: 1 [Worker 1] [ 2019-08-21 22:10:29.842 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 1] [ 2019-08-21 22:10:29.842 AST ] [CopyCommand.execute:179] The copy command failed. Details: :successful [Worker 1] [ 2019-08-21 22:10:29.849 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 1] [ 2019-08-21 22:10:29.849 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 1 m_count=50 [Worker 1] [ 2019-08-21 22:10:29.850 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:10:29.850 AST ] [ClientResource.getListener:157] Calling getListener [Worker 1] [ 2019-08-21 22:10:29.850 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 1] [ 2019-08-21 22:10:29.850 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 1] [ 2019-08-21 22:10:29.851 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:10:29.851 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 1 [Worker 1] [ 2019-08-21 22:10:29.851 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=0 [main] [ 2019-08-21 22:10:29.851 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:10:29.852 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:10:29.852 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:10:29.852 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:29.853 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:29.853 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:29.853 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:10:29.854 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:29.854 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:29.854 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:29.854 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:10:29.855 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:29.855 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:29.855 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:29.856 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:29.856 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:29.856 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:29.857 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:29.857 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@5056dfcb [main] [ 2019-08-21 22:10:29.859 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.cluster.util.SRVMContext.init(SRVMContext.java:123) oracle.cluster.util.SRVMContext.init(SRVMContext.java:84) oracle.ops.mgmt.rawdevice.OCR.isCluster(OCR.java:1047) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:263) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.ops.mgmt.cluster.ClusterConfig.isClusterInstalled(ClusterConfig.java:388) oracle.ops.mgmt.cluster.ClusterConfig.init(ClusterConfig.java:405) oracle.ops.mgmt.cluster.ClusterCmd.copyFileToNodes(ClusterCmd.java:786) oracle.ops.mgmt.cluster.ClusterCmd.copyFileToNodes(ClusterCmd.java:764) oracle.cluster.impl.checkpoints.CheckPointUtil.transferFiles(CheckPointUtil.java:279) oracle.cluster.impl.checkpoints.CheckPointUtil.transferGlobalCkptToNodes(CheckPointUtil.java:224) oracle.cluster.impl.checkpoints.CheckPointSessionImpl.closeCheckPointSession(CheckPointSessionImpl.java:186) oracle.ops.util.ClusterwareCkpt.propagateGlobalCheckpoint(ClusterwareCkpt.java:877) oracle.ops.util.ClusterwareCkpt.writeCheckPoint(ClusterwareCkpt.java:601) oracle.ops.util.ClusterwareCkpt.executeCkpt(ClusterwareCkpt.java:1210) oracle.ops.util.ClusterUtil.execute(ClusterUtil.java:158) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:332) [main] [ 2019-08-21 22:10:29.859 AST ] [SRVMContext.init:126] No CRS configuration found [main] [ 2019-08-21 22:10:29.860 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:29.860 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:29.861 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:29.861 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:29.861 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:29.861 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:29.862 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:29.862 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@6574b225 [main] [ 2019-08-21 22:10:29.862 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.ops.mgmt.cluster.ClusterConfig.isClusterInstalled(ClusterConfig.java:388) oracle.ops.mgmt.cluster.ClusterConfig.init(ClusterConfig.java:405) oracle.ops.mgmt.cluster.ClusterCmd.copyFileToNodes(ClusterCmd.java:786) oracle.ops.mgmt.cluster.ClusterCmd.copyFileToNodes(ClusterCmd.java:764) oracle.cluster.impl.checkpoints.CheckPointUtil.transferFiles(CheckPointUtil.java:279) oracle.cluster.impl.checkpoints.CheckPointUtil.transferGlobalCkptToNodes(CheckPointUtil.java:224) oracle.cluster.impl.checkpoints.CheckPointSessionImpl.closeCheckPointSession(CheckPointSessionImpl.java:186) oracle.ops.util.ClusterwareCkpt.propagateGlobalCheckpoint(ClusterwareCkpt.java:877) oracle.ops.util.ClusterwareCkpt.writeCheckPoint(ClusterwareCkpt.java:601) oracle.ops.util.ClusterwareCkpt.executeCkpt(ClusterwareCkpt.java:1210) oracle.ops.util.ClusterUtil.execute(ClusterUtil.java:158) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:332) [main] [ 2019-08-21 22:10:29.863 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:10:29.863 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:947] Number of nodes :1 [main] [ 2019-08-21 22:10:29.863 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:949] 0th CopyFileToNodes localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [main] [ 2019-08-21 22:10:29.863 AST ] [ClusterConfig.copyFileBetweenNodes:684] Checking: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [main] [ 2019-08-21 22:10:29.864 AST ] [ClusterConfig.copyFileBetweenNodes:696] Checking 2: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [main] [ 2019-08-21 22:10:29.864 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:10:29.864 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-08-21 22:10:29.865 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:10:29.865 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 2] [ 2019-08-21 22:10:29.865 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-08-21 22:10:29.866 AST ] [UnixSystem.copyFile:1084] Copy file localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [Worker 2] [ 2019-08-21 22:10:29.866 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 2] [ 2019-08-21 22:10:29.867 AST ] [UnixSystem.remoteCopyFile:808] Copying files localnode/u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2/u01/app/grid/crsdata/@global/crsconfig/index.xml [Worker 2] [ 2019-08-21 22:10:29.867 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 2] [ 2019-08-21 22:10:29.867 AST ] [UnixSystem.remoteCopyFile:826] UnixSystem: /usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/index.xml' [Worker 2] [ 2019-08-21 22:10:29.876 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-10] [ 2019-08-21 22:10:29.895 AST ] [StreamReader.run:62] In StreamReader.run [Thread-9] [ 2019-08-21 22:10:29.897 AST ] [StreamReader.run:62] In StreamReader.run [Worker 2] [ 2019-08-21 22:10:30.134 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 2] [ 2019-08-21 22:10:30.134 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 2] [ 2019-08-21 22:10:30.135 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 2] [ 2019-08-21 22:10:30.135 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/index.xml'] [Worker 2] [ 2019-08-21 22:10:30.136 AST ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/scp is present. [Worker 2] [ 2019-08-21 22:10:30.136 AST ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/scp is a file. [Worker 2] [ 2019-08-21 22:10:30.136 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned true [Worker 2] [ 2019-08-21 22:10:30.136 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 2] [ 2019-08-21 22:10:30.137 AST ] [CopyCommand.execute:171] CopyCommand.execute: native copyFile returns `1| :successful' [Worker 2] [ 2019-08-21 22:10:30.137 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 2] [ 2019-08-21 22:10:30.137 AST ] [NativeResult.:101] The status string is: 1 [Worker 2] [ 2019-08-21 22:10:30.137 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 2] [ 2019-08-21 22:10:30.138 AST ] [CopyCommand.execute:179] The copy command failed. Details: :successful [Worker 2] [ 2019-08-21 22:10:30.138 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 2] [ 2019-08-21 22:10:30.138 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 2 m_count=50 [Worker 2] [ 2019-08-21 22:10:30.138 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-08-21 22:10:30.139 AST ] [ClientResource.getListener:157] Calling getListener [Worker 2] [ 2019-08-21 22:10:30.139 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 2] [ 2019-08-21 22:10:30.139 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 2] [ 2019-08-21 22:10:30.139 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-08-21 22:10:30.140 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 2 [Worker 2] [ 2019-08-21 22:10:30.140 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [main] [ 2019-08-21 22:10:30.140 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:10:30.140 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:10:30.141 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:10:45.398 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:10:45.406 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:10:45.445 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:10:45.447 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:10:45.462 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:10:45.463 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:10:45.466 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:10:45.469 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:10:45.469 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:10:45.469 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:10:45.470 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:10:45.470 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:10:45.471 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:10:45.473 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:10:45.474 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:10:45.475 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:10:45.475 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:10:45.475 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:10:45.475 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:10:45.476 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@5679c6c6 [main] [ 2019-08-21 22:10:45.481 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.cluster.util.SRVMContext.init(SRVMContext.java:123) oracle.cluster.util.SRVMContext.init(SRVMContext.java:84) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:301) [main] [ 2019-08-21 22:10:45.482 AST ] [SRVMContext.init:126] No CRS configuration found [main] [ 2019-08-21 22:10:45.483 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:10:45.483 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:10:45.483 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:10:45.484 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:10:45.484 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:10:45.484 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:10:45.491 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:10:45.492 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE,-status [main] [ 2019-08-21 22:10:45.494 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:10:45.496 AST ] [ClusterwareCkpt.executeCkpt:1105] Processing chkckpt command line arguments [main] [ 2019-08-21 22:10:45.505 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE,-status [main] [ 2019-08-21 22:10:45.506 AST ] [ClusterwareCkpt.getCkptStatus:329] Checking to see if checkpoint:ROOTCRS_FIRSTNODEhas successfuly completed [main] [ 2019-08-21 22:10:45.509 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:10:45.522 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/crsdata/@global/crsconfig/index.xml found. [main] [ 2019-08-21 22:10:45.643 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:10:45.644 AST ] [ClusterwareCkpt.getCkptStatus:353] Reading data for checkpoint: ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:10:45.644 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:11:38.448 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:11:38.455 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:11:38.490 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:11:38.492 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:11:38.507 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:11:38.508 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:11:38.511 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:11:38.511 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:11:38.512 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:11:38.512 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:11:38.513 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:11:38.513 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:11:38.513 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:11:38.517 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:11:38.518 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 41 [main] [ 2019-08-21 22:11:38.519 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_config failed with error code = 41 [main] [ 2019-08-21 22:11:38.519 AST ] [nativesystem.OCRNative.Native] JNI: error = Error retrieving ocrconfig_loc property. [main] [ 2019-08-21 22:11:38.519 AST ] [nativesystem.OCRNative.Native] getConf: procr_get_conf failed: invalid configuration [main] [ 2019-08-21 22:11:38.519 AST ] [OCR.isCluster:1059] OCR Result status = false [main] [ 2019-08-21 22:11:38.520 AST ] [OCR.isCluster:1066] error Message = [Ljava.lang.String;@5679c6c6 [main] [ 2019-08-21 22:11:38.525 AST ] [Cluster.isCluster:234] Failed to detect cluster: Error retrieving ocrconfig_loc property. Failed to detect cluster: Error retrieving ocrconfig_loc property. oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:283) oracle.ops.mgmt.cluster.Cluster.isCluster(Cluster.java:223) oracle.cluster.util.SRVMContext.init(SRVMContext.java:123) oracle.cluster.util.SRVMContext.init(SRVMContext.java:84) oracle.ops.util.ClusterUtil.main(ClusterUtil.java:301) [main] [ 2019-08-21 22:11:38.525 AST ] [SRVMContext.init:126] No CRS configuration found [main] [ 2019-08-21 22:11:38.526 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:11:38.527 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:11:38.527 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:11:38.527 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:11:38.528 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:11:38.528 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:11:38.532 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:11:38.533 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_OLR,-state,START [main] [ 2019-08-21 22:11:38.535 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:11:38.537 AST ] [ClusterwareCkpt.executeCkpt:1122] Processing writeckpt command line arguments [main] [ 2019-08-21 22:11:38.545 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_OLR,-state,START [main] [ 2019-08-21 22:11:38.546 AST ] [ClusterwareCkpt.writeCheckPoint:544] Writing checkpoint [main] [ 2019-08-21 22:11:38.546 AST ] [ClusterwareCkpt.writeCheckPoint:545] Ckpt Name: ROOTCRS_OLR [main] [ 2019-08-21 22:11:38.547 AST ] [ClusterwareCkpt.writeCheckPoint:546] Ckpt Desc: null [main] [ 2019-08-21 22:11:38.547 AST ] [ClusterwareCkpt.writeCheckPoint:547] Ckpt Level: null [main] [ 2019-08-21 22:11:38.548 AST ] [ClusterwareCkpt.writeCheckPoint:548] Ckpt State: START [main] [ 2019-08-21 22:11:38.548 AST ] [ClusterwareCkpt.writeCheckPoint:552] after assert of checkpoint name [main] [ 2019-08-21 22:11:38.551 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:11:38.562 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/testdb1/checkpoints/crsconfig/index.xml found. [main] [ 2019-08-21 22:11:38.696 AST ] [ClusterwareCkpt.writeCheckPoint:567] ckpt debug 1 [main] [ 2019-08-21 22:11:38.696 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/testdb1/crsconfig/ckptGridHA_testdb1.xml [main] [ 2019-08-21 22:11:38.696 AST ] [ClusterwareCkpt.writeCheckPoint:570] ckpt debug 2 [main] [ 2019-08-21 22:11:38.697 AST ] [ClusterwareCkpt.writeCheckPoint:574] ckpt debug 3 [main] [ 2019-08-21 22:11:38.697 AST ] [ClusterwareCkpt.writeCheckPoint:580] inside create new ckpt [main] [ 2019-08-21 22:11:38.697 AST ] [CheckPointFactory.constructCheckPoint:229] Checkpoint:constructing checkpoint with name:ROOTCRS_OLR in checkpoint factory [main] [ 2019-08-21 22:11:38.697 AST ] [ClusterwareCkpt.writeCheckPoint:590] ckpt debug 4 [main] [ 2019-08-21 22:11:38.698 AST ] [ClusterwareCkpt.writeCheckPoint:595] ckpt debug 5 [main] [ 2019-08-21 22:11:38.720 AST ] [CheckPointSessionImpl.saveCheckPointSession:143] Checkpoint:Index file written and updated [main] [ 2019-08-21 22:11:38.724 AST ] [ClusterwareCkpt.writeCheckPoint:599] ckpt debug 6 [main] [ 2019-08-21 22:11:38.724 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:11:54.272 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:11:54.278 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:11:54.313 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:11:54.316 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:11:54.329 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:11:54.329 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:11:54.332 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:11:54.333 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:11:54.333 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:11:54.333 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:11:54.334 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:11:54.334 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:11:54.335 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:11:54.339 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:11:54.340 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 0 [main] [ 2019-08-21 22:11:54.340 AST ] [nativesystem.OCRNative.Native] The OCR file is configured & local_only=false [main] [ 2019-08-21 22:11:54.341 AST ] [OCR.isCluster:1059] OCR Result status = true [main] [ 2019-08-21 22:11:54.341 AST ] [OCR.isCluster:1071] Bolean result = true [main] [ 2019-08-21 22:11:54.342 AST ] [cnative.ClusterNative.Native] Native:: CLSBInit [main] [ 2019-08-21 22:11:54.353 AST ] [cnative.ClusterNative.Native] in prcr_clsb:: successfully setup callback [main] [ 2019-08-21 22:11:54.353 AST ] [SRVMContext.init:140] SRVM Context init-ed [main] [ 2019-08-21 22:11:54.354 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:11:54.354 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:11:54.355 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:11:54.355 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:11:54.356 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:11:54.356 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:11:54.360 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:11:54.360 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_FIRSTNODE,-state,START,-nodelist,testdb1,testdb2,-transferfile [main] [ 2019-08-21 22:11:54.360 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:11:54.363 AST ] [ClusterwareCkpt.executeCkpt:1122] Processing writeckpt command line arguments [main] [ 2019-08-21 22:11:54.364 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_FIRSTNODE,-state,START,-nodelist,testdb1,testdb2,-transferfile [main] [ 2019-08-21 22:11:54.373 AST ] [ClusterwareCkpt.writeCheckPoint:544] Writing checkpoint [main] [ 2019-08-21 22:11:54.373 AST ] [ClusterwareCkpt.writeCheckPoint:545] Ckpt Name: ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:11:54.373 AST ] [ClusterwareCkpt.writeCheckPoint:546] Ckpt Desc: null [main] [ 2019-08-21 22:11:54.373 AST ] [ClusterwareCkpt.writeCheckPoint:547] Ckpt Level: null [main] [ 2019-08-21 22:11:54.374 AST ] [ClusterwareCkpt.writeCheckPoint:548] Ckpt State: START [main] [ 2019-08-21 22:11:54.374 AST ] [ClusterwareCkpt.writeCheckPoint:552] after assert of checkpoint name [main] [ 2019-08-21 22:11:54.378 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:11:54.391 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/crsdata/@global/crsconfig/index.xml found. [main] [ 2019-08-21 22:11:54.576 AST ] [ClusterwareCkpt.writeCheckPoint:567] ckpt debug 1 [main] [ 2019-08-21 22:11:54.577 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:11:54.577 AST ] [ClusterwareCkpt.writeCheckPoint:570] ckpt debug 2 [main] [ 2019-08-21 22:11:54.577 AST ] [ClusterwareCkpt.writeCheckPoint:574] ckpt debug 3 [main] [ 2019-08-21 22:11:54.578 AST ] [ClusterwareCkpt.writeCheckPoint:586] Setting checkpoint state to: 1 [main] [ 2019-08-21 22:11:54.579 AST ] [ClusterwareCkpt.writeCheckPoint:590] ckpt debug 4 [main] [ 2019-08-21 22:11:54.579 AST ] [ClusterwareCkpt.writeCheckPoint:595] ckpt debug 5 [main] [ 2019-08-21 22:11:54.586 AST ] [CheckPointSessionImpl.saveCheckPointSession:143] Checkpoint:Index file written and updated [main] [ 2019-08-21 22:11:54.588 AST ] [ClusterwareCkpt.writeCheckPoint:599] ckpt debug 6 [main] [ 2019-08-21 22:11:54.588 AST ] [ClusterwareCkpt.propagateGlobalCheckpoint:871] Propagating global checkpoints to nodes: testdb1,testdb2 [main] [ 2019-08-21 22:11:54.591 AST ] [ClusterwareCkpt.propagateGlobalCheckpoint:876] Closing global checkpoint session [main] [ 2019-08-21 22:11:54.592 AST ] [CheckPointIndexWriter.generatePropertiesNode:220] Checkpoint:Setting status in index file as passed,as no last failed checkpoint is available. [main] [ 2019-08-21 22:11:54.592 AST ] [CheckPointSessionImpl.closeCheckPointSession:183] Sending checkpoint files to remote nodes [main] [ 2019-08-21 22:11:54.593 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:11:54.593 AST ] [Utils.getNodeName:571] Hostname : testdb1 is converted to nodeName : testdb1 [main] [ 2019-08-21 22:11:54.594 AST ] [ClusterUtil.findLiveNodes:218] Attempt to find live nodes [main] [ 2019-08-21 22:11:54.601 AST ] [ClusterConfig.:240] ClusterConfig:Number of workers = 0 [main] [ 2019-08-21 22:11:54.603 AST ] [ClusterConfig.createWorkers:325] Started worker threads count=1 [main] [ 2019-08-21 22:11:54.606 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:11:54.608 AST ] [GetActiveNodes.create:220] Going into GetActiveNodes constructor... [main] [ 2019-08-21 22:11:54.616 AST ] [HASContext.:125] moduleInit = 19 [main] [ 2019-08-21 22:11:54.623 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=3 [main] [ 2019-08-21 22:11:54.623 AST ] [HASContext.:136] Initialised SRVMContext [main] [ 2019-08-21 22:11:54.624 AST ] [has.HASContextNative.Native] prsr_trace: no lsf ctx, line=Native: allocHASContext [main] [ 2019-08-21 22:11:54.625 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 19 [main] [ 2019-08-21 22:11:54.625 AST ] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [ 2019-08-21 22:11:54.625 AST ] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [ 2019-08-21 22:11:54.626 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [Worker 0] [ 2019-08-21 22:11:54.626 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [Thread-1] [ 2019-08-21 22:11:54.628 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.626: [ CSSCLNT][2]clsssInitNative [Thread-2] [ 2019-08-21 22:11:54.629 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.628: [ CSSCLNT][2]clsssInitNative: proplist len 16 properties - 1,2,3,4,5,6,7 [Thread-3] [ 2019-08-21 22:11:54.672 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.671: [ CSSCLNT][2]clsssConnect: Connect to CSSD completed, endpt 1b [Thread-4] [ 2019-08-21 22:11:54.675 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.673: [ CSSCLNT][2]clsssConnect: CSS daemon not up (1b) [Thread-5] [ 2019-08-21 22:11:54.678 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.676: [ CSSCLNT][2]clsssConnect: gipcDestroy 0 [Thread-6] [ 2019-08-21 22:11:54.679 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.679: [ CSSCLNT][2]clsssInitNative: CSS daemon in (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_testdb1_)) not up [Thread-7] [ 2019-08-21 22:11:54.681 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.679: [ CSSCLNT][2]clssgsAttrInit:attrdesc grpcount=6 mbrcount 8 [Thread-8] [ 2019-08-21 22:11:54.683 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.682: [ CSSCLNT][2]clsssterm: terminating gbl ctx 112f1b0 [Thread-9] [ 2019-08-21 22:11:54.685 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.684: [ CSSCLNT][2]clsss_gterm: terminating connection [Thread-10] [ 2019-08-21 22:11:54.686 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.685: [ CSSCLNT][2]clsss_gterm: destroying GIPC ctx [Thread-11] [ 2019-08-21 22:11:54.688 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.686: [ CSSCLNT][2]clsss_gterm: Shutting down GIPC [Thread-12] [ 2019-08-21 22:11:54.693 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.691: [ CSSCLNT][2]clsss_gterm: Completing LSF cleanup [Thread-13] [ 2019-08-21 22:11:54.695 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.694: [ CSSCLNT][2]clsss_gterm: Completing LPM cleanup [main] [ 2019-08-21 22:11:54.699 AST ] [has.HASContextNative.Native] prsr_trace: Native: clss error 3 [main] [ 2019-08-21 22:11:54.700 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_freeCLSS [main] [ 2019-08-21 22:11:54.703 AST ] [has.HASContextNative.Native] prsr_trace: prsr_throwException: class=oracle/ops/mgmt/has/HASContextException, prkhMsgID=CLSS_COM_ERROR, arg1=null, nativeError=null, debugMsg=Native: prsr_initCLSS [main] [ 2019-08-21 22:11:54.709 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:11:54.711 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-08-21 22:11:54.711 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:11:54.712 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 0] [ 2019-08-21 22:11:54.712 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 0 m_count=1 [main] [ 2019-08-21 22:11:54.715 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-08-21 22:11:54.715 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:11:54.715 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 0] [ 2019-08-21 22:11:54.726 AST ] [sPlatform.getPingCmdArgs:89] Node=testdb2 Timeout=10 [Worker 0] [ 2019-08-21 22:11:54.948 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Worker 0] [ 2019-08-21 22:11:54.951 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Thread-15] [ 2019-08-21 22:11:54.951 AST ] [StreamReader.run:62] In StreamReader.run [Thread-14] [ 2019-08-21 22:11:54.957 AST ] [StreamReader.run:62] In StreamReader.run [Thread-14] [ 2019-08-21 22:11:54.957 AST ] [StreamReader.run:66] OUTPUT>testdb2 is alive [Worker 0] [ 2019-08-21 22:11:54.958 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 0] [ 2019-08-21 22:11:54.958 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 0] [ 2019-08-21 22:11:54.961 AST ] [UnixSystem.isNodeAlive:5164] msgBuf=testdb2 is alive [Worker 0] [ 2019-08-21 22:11:54.962 AST ] [NodeLivenessCommand.postEvent:103] Inside NodeLivenessCommand.postEvent, listener size=0 [Worker 0] [ 2019-08-21 22:11:54.962 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 0] [ 2019-08-21 22:11:54.962 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 0 m_count=50 [Worker 0] [ 2019-08-21 22:11:54.963 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:11:54.963 AST ] [ClientResource.getListener:157] Calling getListener [Worker 0] [ 2019-08-21 22:11:54.963 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 0] [ 2019-08-21 22:11:54.964 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 0] [ 2019-08-21 22:11:54.964 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:11:54.964 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 0 [Worker 0] [ 2019-08-21 22:11:54.972 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [main] [ 2019-08-21 22:11:54.973 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:11:54.973 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-08-21 22:11:54.973 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-08-21 22:11:54.974 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:11:54.974 AST ] [ClusterUtil.findLiveNodes:258] All nodes are up [main] [ 2019-08-21 22:11:54.974 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:11:54.975 AST ] [GetActiveNodes.create:220] Going into GetActiveNodes constructor... [main] [ 2019-08-21 22:11:54.977 AST ] [HASContext.:125] moduleInit = 19 [main] [ 2019-08-21 22:11:54.978 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=4 [main] [ 2019-08-21 22:11:54.978 AST ] [HASContext.:136] Initialised SRVMContext [main] [ 2019-08-21 22:11:54.979 AST ] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [ 2019-08-21 22:11:54.979 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 19 [main] [ 2019-08-21 22:11:54.981 AST ] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [ 2019-08-21 22:11:54.985 AST ] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [ 2019-08-21 22:11:54.990 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [Thread-16] [ 2019-08-21 22:11:54.992 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.991: [ CSSCLNT][2]clsssInitNative [Thread-17] [ 2019-08-21 22:11:54.993 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.993: [ CSSCLNT][2]clsssInitNative: proplist len 16 properties - 1,2,3,4,5,6,7 [Thread-18] [ 2019-08-21 22:11:54.997 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.996: [ CSSCLNT][2]clsssConnect: Connect to CSSD completed, endpt 1b [Thread-19] [ 2019-08-21 22:11:54.999 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.998: [ CSSCLNT][2]clsssConnect: CSS daemon not up (1b) [Thread-20] [ 2019-08-21 22:11:54.999 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:54.999: [ CSSCLNT][2]clsssConnect: gipcDestroy 0 [Thread-21] [ 2019-08-21 22:11:55.001 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.000: [ CSSCLNT][2]clsssInitNative: CSS daemon in (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_testdb1_)) not up [Thread-22] [ 2019-08-21 22:11:55.003 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.002: [ CSSCLNT][2]clssgsAttrInit:attrdesc grpcount=6 mbrcount 8 [Thread-23] [ 2019-08-21 22:11:55.003 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.003: [ CSSCLNT][2]clsssterm: terminating gbl ctx 117b8b0 [Thread-24] [ 2019-08-21 22:11:55.004 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.003: [ CSSCLNT][2]clsss_gterm: terminating connection [Thread-25] [ 2019-08-21 22:11:55.006 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.004: [ CSSCLNT][2]clsss_gterm: destroying GIPC ctx [Thread-26] [ 2019-08-21 22:11:55.007 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.006: [ CSSCLNT][2]clsss_gterm: Shutting down GIPC [Thread-27] [ 2019-08-21 22:11:55.008 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.008: [ CSSCLNT][2]clsss_gterm: Completing LSF cleanup [Thread-28] [ 2019-08-21 22:11:55.009 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.008: [ CSSCLNT][2]clsss_gterm: Completing LPM cleanup [main] [ 2019-08-21 22:11:55.010 AST ] [has.HASContextNative.Native] prsr_trace: Native: clss error 3 [main] [ 2019-08-21 22:11:55.011 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_freeCLSS [main] [ 2019-08-21 22:11:55.011 AST ] [has.HASContextNative.Native] prsr_trace: prsr_throwException: class=oracle/ops/mgmt/has/HASContextException, prkhMsgID=CLSS_COM_ERROR, arg1=null, nativeError=null, debugMsg=Native: prsr_initCLSS [main] [ 2019-08-21 22:11:55.017 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:11:55.017 AST ] [ClusterConfig.createWorkers:327] Started additional worker threads count=3 [main] [ 2019-08-21 22:11:55.017 AST ] [ClusterConfig.createDirInNode:1940] Creating dir in nodes: testdb2, /u01/app/grid/crsdata/@global/crsconfig, true, 700 [main] [ 2019-08-21 22:11:55.018 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:11:55.019 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-08-21 22:11:55.019 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:11:55.019 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 1] [ 2019-08-21 22:11:55.020 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:11:55.021 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:11:55.021 AST ] [DirCreateCommand.execute:70] In DirCreateCommand.execute, recurseFlag=false, modeFlag=false [Worker 1] [ 2019-08-21 22:11:55.022 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 1] [ 2019-08-21 22:11:55.022 AST ] [UnixSystem.checkRemoteExecutionSetup:3071] Client didn't specify for remote shell or remote copy [Worker 1] [ 2019-08-21 22:11:55.024 AST ] [Library.load:202] library.load [Worker 1] [ 2019-08-21 22:11:55.024 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [Worker 1] [ 2019-08-21 22:11:55.029 AST ] [UnixSystem.checkRemoteExecutionSetup:3082] checkRemoteExecutionSetup:: Checking user equivalence using Secured Shell '/usr/bin/ssh' [Worker 1] [ 2019-08-21 22:11:55.030 AST ] [UnixSystem.checkRemoteExecutionSetup:3084] checkRemoteExecutionSetup:: Running Unix command: /usr/bin/ssh -o FallBackToRsh=no -o PasswordAuthentication=no -o StrictHostKeyChecking=yes -o NumberOfPasswordPrompts=0 testdb2 /usr/bin/true [Worker 2] [ 2019-08-21 22:11:55.030 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [Worker 3] [ 2019-08-21 22:11:55.031 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 3 m_count=0 [Worker 1] [ 2019-08-21 22:11:55.044 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-30] [ 2019-08-21 22:11:55.048 AST ] [StreamReader.run:62] In StreamReader.run [Thread-29] [ 2019-08-21 22:11:55.048 AST ] [StreamReader.run:62] In StreamReader.run [Worker 1] [ 2019-08-21 22:11:55.297 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 1] [ 2019-08-21 22:11:55.298 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 1] [ 2019-08-21 22:11:55.298 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 1] [ 2019-08-21 22:11:55.298 AST ] [UnixSystem.checkRemoteExecutionSetup:3211] Using Remote Shell Command: '/usr/bin/ssh -o FallBackToRsh=no -o PasswordAuthentication=no -o StrictHostKeyChecking=yes -o NumberOfPasswordPrompts=0 ' [Worker 1] [ 2019-08-21 22:11:55.299 AST ] [UnixSystem.checkRemoteExecutionSetup:3212] Using Remote Copy Command: '/usr/bin/scp' [Worker 1] [ 2019-08-21 22:11:55.319 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-32] [ 2019-08-21 22:11:55.321 AST ] [StreamReader.run:62] In StreamReader.run [Thread-31] [ 2019-08-21 22:11:55.325 AST ] [StreamReader.run:62] In StreamReader.run [Worker 1] [ 2019-08-21 22:11:55.538 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 1] [ 2019-08-21 22:11:55.539 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 1] [ 2019-08-21 22:11:55.539 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 1] [ 2019-08-21 22:11:55.540 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/ssh -o FallBackToRsh=no -o PasswordAuthentication=no -o StrictHostKeyChecking=yes -o NumberOfPasswordPrompts=0 testdb2 -n /usr/bin/mkdir -p -m 700 /u01/app/grid/crsdata/@global/crsconfig] [Worker 1] [ 2019-08-21 22:11:55.542 AST ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/ssh is present. [Worker 1] [ 2019-08-21 22:11:55.543 AST ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/ssh is a file. [Worker 1] [ 2019-08-21 22:11:55.543 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned true [Worker 1] [ 2019-08-21 22:11:55.543 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 1] [ 2019-08-21 22:11:55.544 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 1] [ 2019-08-21 22:11:55.544 AST ] [NativeResult.:101] The status string is: 1 [Worker 1] [ 2019-08-21 22:11:55.544 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 1] [ 2019-08-21 22:11:55.545 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 1] [ 2019-08-21 22:11:55.545 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 1 m_count=50 [Worker 1] [ 2019-08-21 22:11:55.545 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:11:55.546 AST ] [ClientResource.getListener:157] Calling getListener [Worker 1] [ 2019-08-21 22:11:55.546 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 1] [ 2019-08-21 22:11:55.546 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 1] [ 2019-08-21 22:11:55.547 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:11:55.547 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 1 [Worker 1] [ 2019-08-21 22:11:55.547 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=0 [main] [ 2019-08-21 22:11:55.552 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:11:55.552 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:11:55.553 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:11:55.553 AST ] [GetActiveNodes.create:220] Going into GetActiveNodes constructor... [main] [ 2019-08-21 22:11:55.554 AST ] [HASContext.:125] moduleInit = 19 [main] [ 2019-08-21 22:11:55.554 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=5 [main] [ 2019-08-21 22:11:55.556 AST ] [HASContext.:136] Initialised SRVMContext [main] [ 2019-08-21 22:11:55.556 AST ] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [ 2019-08-21 22:11:55.557 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 19 [main] [ 2019-08-21 22:11:55.557 AST ] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [ 2019-08-21 22:11:55.558 AST ] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [ 2019-08-21 22:11:55.558 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [Thread-33] [ 2019-08-21 22:11:55.559 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.558: [ CSSCLNT][2]clsssInitNative [Thread-34] [ 2019-08-21 22:11:55.561 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.559: [ CSSCLNT][2]clsssInitNative: proplist len 16 properties - 1,2,3,4,5,6,7 [Thread-35] [ 2019-08-21 22:11:55.580 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.564: [ CSSCLNT][2]clsssConnect: Connect to CSSD completed, endpt 1b [Finalizer] [ 2019-08-21 22:11:55.582 AST ] [ClusterUtil.finalize:119] ClusterUtil: finalized called for oracle.ops.mgmt.has.ClusterUtil@5dc940c3 [Finalizer] [ 2019-08-21 22:11:55.583 AST ] [ClusterUtil.finalize:119] ClusterUtil: finalized called for oracle.ops.mgmt.has.ClusterUtil@530eb50a [Thread-36] [ 2019-08-21 22:11:55.593 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.593: [ CSSCLNT][2]clsssConnect: CSS daemon not up (1b) [Thread-37] [ 2019-08-21 22:11:55.594 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.594: [ CSSCLNT][2]clsssConnect: gipcDestroy 0 [Thread-38] [ 2019-08-21 22:11:55.595 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.595: [ CSSCLNT][2]clsssInitNative: CSS daemon in (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_testdb1_)) not up [Thread-39] [ 2019-08-21 22:11:55.596 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.595: [ CSSCLNT][2]clssgsAttrInit:attrdesc grpcount=6 mbrcount 8 [Thread-40] [ 2019-08-21 22:11:55.596 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.596: [ CSSCLNT][2]clsssterm: terminating gbl ctx 11839b0 [Thread-41] [ 2019-08-21 22:11:55.597 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.597: [ CSSCLNT][2]clsss_gterm: terminating connection [Thread-42] [ 2019-08-21 22:11:55.598 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.598: [ CSSCLNT][2]clsss_gterm: destroying GIPC ctx [Thread-43] [ 2019-08-21 22:11:55.599 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.599: [ CSSCLNT][2]clsss_gterm: Shutting down GIPC [Thread-44] [ 2019-08-21 22:11:55.602 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.602: [ CSSCLNT][2]clsss_gterm: Completing LSF cleanup [Thread-45] [ 2019-08-21 22:11:55.603 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.602: [ CSSCLNT][2]clsss_gterm: Completing LPM cleanup [main] [ 2019-08-21 22:11:55.603 AST ] [has.HASContextNative.Native] prsr_trace: Native: clss error 3 [main] [ 2019-08-21 22:11:55.604 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_freeCLSS [main] [ 2019-08-21 22:11:55.605 AST ] [has.HASContextNative.Native] prsr_trace: prsr_throwException: class=oracle/ops/mgmt/has/HASContextException, prkhMsgID=CLSS_COM_ERROR, arg1=null, nativeError=null, debugMsg=Native: prsr_initCLSS [main] [ 2019-08-21 22:11:55.605 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:11:55.606 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:947] Number of nodes :1 [main] [ 2019-08-21 22:11:55.606 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:949] 0th CopyFileToNodes localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:11:55.606 AST ] [ClusterConfig.copyFileBetweenNodes:684] Checking: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:11:55.607 AST ] [ClusterConfig.copyFileBetweenNodes:696] Checking 2: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:11:55.608 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:11:55.608 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-08-21 22:11:55.608 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:11:55.609 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 2] [ 2019-08-21 22:11:55.609 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-08-21 22:11:55.611 AST ] [UnixSystem.copyFile:1084] Copy file localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [Worker 2] [ 2019-08-21 22:11:55.612 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 2] [ 2019-08-21 22:11:55.612 AST ] [UnixSystem.remoteCopyFile:808] Copying files localnode/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [Worker 2] [ 2019-08-21 22:11:55.614 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 2] [ 2019-08-21 22:11:55.615 AST ] [UnixSystem.remoteCopyFile:826] UnixSystem: /usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml' [Worker 2] [ 2019-08-21 22:11:55.625 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-47] [ 2019-08-21 22:11:55.642 AST ] [StreamReader.run:62] In StreamReader.run [Thread-46] [ 2019-08-21 22:11:55.645 AST ] [StreamReader.run:62] In StreamReader.run [Worker 2] [ 2019-08-21 22:11:55.904 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 2] [ 2019-08-21 22:11:55.904 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 2] [ 2019-08-21 22:11:55.907 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 2] [ 2019-08-21 22:11:55.907 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml'] [Worker 2] [ 2019-08-21 22:11:55.913 AST ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/scp is present. [Worker 2] [ 2019-08-21 22:11:55.915 AST ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/scp is a file. [Worker 2] [ 2019-08-21 22:11:55.915 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned true [Worker 2] [ 2019-08-21 22:11:55.921 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 2] [ 2019-08-21 22:11:55.928 AST ] [CopyCommand.execute:171] CopyCommand.execute: native copyFile returns `1| :successful' [Worker 2] [ 2019-08-21 22:11:55.930 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 2] [ 2019-08-21 22:11:55.931 AST ] [NativeResult.:101] The status string is: 1 [Worker 2] [ 2019-08-21 22:11:55.931 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 2] [ 2019-08-21 22:11:55.931 AST ] [CopyCommand.execute:179] The copy command failed. Details: :successful [Worker 2] [ 2019-08-21 22:11:55.932 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 2] [ 2019-08-21 22:11:55.932 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 2 m_count=50 [Worker 2] [ 2019-08-21 22:11:55.932 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-08-21 22:11:55.932 AST ] [ClientResource.getListener:157] Calling getListener [Worker 2] [ 2019-08-21 22:11:55.933 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 2] [ 2019-08-21 22:11:55.933 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 2] [ 2019-08-21 22:11:55.933 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-08-21 22:11:55.933 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 2 [Worker 2] [ 2019-08-21 22:11:55.934 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [main] [ 2019-08-21 22:11:55.934 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:11:55.934 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:11:55.934 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:11:55.935 AST ] [GetActiveNodes.create:220] Going into GetActiveNodes constructor... [main] [ 2019-08-21 22:11:55.935 AST ] [HASContext.:125] moduleInit = 19 [main] [ 2019-08-21 22:11:55.935 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=6 [main] [ 2019-08-21 22:11:55.936 AST ] [HASContext.:136] Initialised SRVMContext [main] [ 2019-08-21 22:11:55.936 AST ] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [ 2019-08-21 22:11:55.936 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 19 [main] [ 2019-08-21 22:11:55.937 AST ] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [ 2019-08-21 22:11:55.937 AST ] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [ 2019-08-21 22:11:55.937 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [Thread-48] [ 2019-08-21 22:11:55.938 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.938: [ CSSCLNT][2]clsssInitNative [Thread-49] [ 2019-08-21 22:11:55.938 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.938: [ CSSCLNT][2]clsssInitNative: proplist len 16 properties - 1,2,3,4,5,6,7 [Thread-50] [ 2019-08-21 22:11:55.942 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.941: [ CSSCLNT][2]clsssConnect: Connect to CSSD completed, endpt 1b [Thread-51] [ 2019-08-21 22:11:55.949 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.949: [ CSSCLNT][2]clsssConnect: CSS daemon not up (1b) [Thread-52] [ 2019-08-21 22:11:55.950 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.950: [ CSSCLNT][2]clsssConnect: gipcDestroy 0 [Thread-53] [ 2019-08-21 22:11:55.951 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.950: [ CSSCLNT][2]clsssInitNative: CSS daemon in (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_testdb1_)) not up [Thread-54] [ 2019-08-21 22:11:55.951 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.951: [ CSSCLNT][2]clssgsAttrInit:attrdesc grpcount=6 mbrcount 8 [Thread-55] [ 2019-08-21 22:11:55.952 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.951: [ CSSCLNT][2]clsssterm: terminating gbl ctx 120d590 [Thread-56] [ 2019-08-21 22:11:55.952 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.952: [ CSSCLNT][2]clsss_gterm: terminating connection [Thread-57] [ 2019-08-21 22:11:55.953 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.952: [ CSSCLNT][2]clsss_gterm: destroying GIPC ctx [Thread-58] [ 2019-08-21 22:11:55.953 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.953: [ CSSCLNT][2]clsss_gterm: Shutting down GIPC [Thread-59] [ 2019-08-21 22:11:55.955 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.954: [ CSSCLNT][2]clsss_gterm: Completing LSF cleanup [Thread-60] [ 2019-08-21 22:11:55.955 AST ] [Trace.nativeOut:838] 2019-08-21 22:11:55.955: [ CSSCLNT][2]clsss_gterm: Completing LPM cleanup [main] [ 2019-08-21 22:11:55.956 AST ] [has.HASContextNative.Native] prsr_trace: Native: clss error 3 [main] [ 2019-08-21 22:11:55.956 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_freeCLSS [main] [ 2019-08-21 22:11:55.956 AST ] [has.HASContextNative.Native] prsr_trace: prsr_throwException: class=oracle/ops/mgmt/has/HASContextException, prkhMsgID=CLSS_COM_ERROR, arg1=null, nativeError=null, debugMsg=Native: prsr_initCLSS [main] [ 2019-08-21 22:11:55.957 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:11:55.957 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:947] Number of nodes :1 [main] [ 2019-08-21 22:11:55.957 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:949] 0th CopyFileToNodes localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [main] [ 2019-08-21 22:11:55.958 AST ] [ClusterConfig.copyFileBetweenNodes:684] Checking: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [main] [ 2019-08-21 22:11:55.958 AST ] [ClusterConfig.copyFileBetweenNodes:696] Checking 2: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [main] [ 2019-08-21 22:11:55.958 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:11:55.958 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-08-21 22:11:55.959 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:11:55.959 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 3] [ 2019-08-21 22:11:55.959 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-08-21 22:11:55.960 AST ] [UnixSystem.copyFile:1084] Copy file localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [Worker 3] [ 2019-08-21 22:11:55.961 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 3] [ 2019-08-21 22:11:55.961 AST ] [UnixSystem.remoteCopyFile:808] Copying files localnode/u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2/u01/app/grid/crsdata/@global/crsconfig/index.xml [Worker 3] [ 2019-08-21 22:11:55.961 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 3] [ 2019-08-21 22:11:55.962 AST ] [UnixSystem.remoteCopyFile:826] UnixSystem: /usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/index.xml' [Worker 3] [ 2019-08-21 22:11:55.970 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-62] [ 2019-08-21 22:11:55.987 AST ] [StreamReader.run:62] In StreamReader.run [Thread-61] [ 2019-08-21 22:11:55.992 AST ] [StreamReader.run:62] In StreamReader.run [Worker 3] [ 2019-08-21 22:11:56.223 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 3] [ 2019-08-21 22:11:56.224 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 3] [ 2019-08-21 22:11:56.224 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 3] [ 2019-08-21 22:11:56.225 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/index.xml'] [Worker 3] [ 2019-08-21 22:11:56.225 AST ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/scp is present. [Worker 3] [ 2019-08-21 22:11:56.225 AST ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/scp is a file. [Worker 3] [ 2019-08-21 22:11:56.226 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned true [Worker 3] [ 2019-08-21 22:11:56.226 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 3] [ 2019-08-21 22:11:56.226 AST ] [CopyCommand.execute:171] CopyCommand.execute: native copyFile returns `1| :successful' [Worker 3] [ 2019-08-21 22:11:56.227 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 3] [ 2019-08-21 22:11:56.227 AST ] [NativeResult.:101] The status string is: 1 [Worker 3] [ 2019-08-21 22:11:56.227 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 3] [ 2019-08-21 22:11:56.227 AST ] [CopyCommand.execute:179] The copy command failed. Details: :successful [Worker 3] [ 2019-08-21 22:11:56.228 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 3] [ 2019-08-21 22:11:56.228 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 3 m_count=50 [Worker 3] [ 2019-08-21 22:11:56.228 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-08-21 22:11:56.228 AST ] [ClientResource.getListener:157] Calling getListener [Worker 3] [ 2019-08-21 22:11:56.229 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 3] [ 2019-08-21 22:11:56.229 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 3] [ 2019-08-21 22:11:56.229 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-08-21 22:11:56.230 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 3 [Worker 3] [ 2019-08-21 22:11:56.230 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 3 m_count=0 [main] [ 2019-08-21 22:11:56.230 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:11:56.230 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:11:56.231 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:12:49.832 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:12:49.838 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:12:49.878 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:12:49.880 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:12:49.894 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:12:49.895 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:12:49.898 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:12:49.901 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:12:49.901 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:12:49.902 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:12:49.903 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:12:49.903 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:12:49.903 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:12:49.906 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:12:49.908 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 0 [main] [ 2019-08-21 22:12:49.908 AST ] [nativesystem.OCRNative.Native] The OCR file is configured & local_only=false [main] [ 2019-08-21 22:12:49.908 AST ] [OCR.isCluster:1059] OCR Result status = true [main] [ 2019-08-21 22:12:49.909 AST ] [OCR.isCluster:1071] Bolean result = true [main] [ 2019-08-21 22:12:49.909 AST ] [cnative.ClusterNative.Native] Native:: CLSBInit [main] [ 2019-08-21 22:12:49.921 AST ] [cnative.ClusterNative.Native] in prcr_clsb:: successfully setup callback [main] [ 2019-08-21 22:12:49.922 AST ] [SRVMContext.init:140] SRVM Context init-ed [main] [ 2019-08-21 22:12:49.923 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:12:49.924 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:12:49.924 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:12:49.924 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:12:49.925 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:12:49.925 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:12:49.929 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:12:49.930 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_INITRES,-state,START [main] [ 2019-08-21 22:12:49.930 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:12:49.933 AST ] [ClusterwareCkpt.executeCkpt:1122] Processing writeckpt command line arguments [main] [ 2019-08-21 22:12:49.935 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_INITRES,-state,START [main] [ 2019-08-21 22:12:49.945 AST ] [ClusterwareCkpt.writeCheckPoint:544] Writing checkpoint [main] [ 2019-08-21 22:12:49.945 AST ] [ClusterwareCkpt.writeCheckPoint:545] Ckpt Name: ROOTCRS_INITRES [main] [ 2019-08-21 22:12:49.945 AST ] [ClusterwareCkpt.writeCheckPoint:546] Ckpt Desc: null [main] [ 2019-08-21 22:12:49.946 AST ] [ClusterwareCkpt.writeCheckPoint:547] Ckpt Level: null [main] [ 2019-08-21 22:12:49.946 AST ] [ClusterwareCkpt.writeCheckPoint:548] Ckpt State: START [main] [ 2019-08-21 22:12:49.947 AST ] [ClusterwareCkpt.writeCheckPoint:552] after assert of checkpoint name [main] [ 2019-08-21 22:12:49.951 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:12:49.964 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/testdb1/checkpoints/crsconfig/index.xml found. [main] [ 2019-08-21 22:12:50.106 AST ] [ClusterwareCkpt.writeCheckPoint:567] ckpt debug 1 [main] [ 2019-08-21 22:12:50.106 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/testdb1/crsconfig/ckptGridHA_testdb1.xml [main] [ 2019-08-21 22:12:50.106 AST ] [ClusterwareCkpt.writeCheckPoint:570] ckpt debug 2 [main] [ 2019-08-21 22:12:50.107 AST ] [ClusterwareCkpt.writeCheckPoint:574] ckpt debug 3 [main] [ 2019-08-21 22:12:50.107 AST ] [ClusterwareCkpt.writeCheckPoint:580] inside create new ckpt [main] [ 2019-08-21 22:12:50.107 AST ] [CheckPointFactory.constructCheckPoint:229] Checkpoint:constructing checkpoint with name:ROOTCRS_INITRES in checkpoint factory [main] [ 2019-08-21 22:12:50.107 AST ] [ClusterwareCkpt.writeCheckPoint:590] ckpt debug 4 [main] [ 2019-08-21 22:12:50.107 AST ] [ClusterwareCkpt.writeCheckPoint:595] ckpt debug 5 [main] [ 2019-08-21 22:12:50.132 AST ] [CheckPointSessionImpl.saveCheckPointSession:143] Checkpoint:Index file written and updated [main] [ 2019-08-21 22:12:50.133 AST ] [ClusterwareCkpt.writeCheckPoint:599] ckpt debug 6 [main] [ 2019-08-21 22:12:50.136 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:13:24.228 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:13:24.234 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:13:24.274 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:13:24.276 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:13:24.290 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:13:24.290 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:13:24.293 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:13:24.294 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:13:24.294 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:13:24.294 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:13:24.295 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:13:24.296 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:13:24.296 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:13:24.300 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:13:24.301 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 0 [main] [ 2019-08-21 22:13:24.302 AST ] [nativesystem.OCRNative.Native] The OCR file is configured & local_only=false [main] [ 2019-08-21 22:13:24.302 AST ] [OCR.isCluster:1059] OCR Result status = true [main] [ 2019-08-21 22:13:24.302 AST ] [OCR.isCluster:1071] Bolean result = true [main] [ 2019-08-21 22:13:24.303 AST ] [cnative.ClusterNative.Native] Native:: CLSBInit [main] [ 2019-08-21 22:13:24.314 AST ] [cnative.ClusterNative.Native] in prcr_clsb:: successfully setup callback [main] [ 2019-08-21 22:13:24.314 AST ] [SRVMContext.init:140] SRVM Context init-ed [main] [ 2019-08-21 22:13:24.315 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:13:24.316 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:13:24.316 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:13:24.316 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:13:24.317 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:13:24.317 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:13:24.321 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:13:24.322 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE,-status [main] [ 2019-08-21 22:13:24.322 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:13:24.324 AST ] [ClusterwareCkpt.executeCkpt:1105] Processing chkckpt command line arguments [main] [ 2019-08-21 22:13:24.326 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE,-status [main] [ 2019-08-21 22:13:24.335 AST ] [ClusterwareCkpt.getCkptStatus:329] Checking to see if checkpoint:ROOTCRS_FIRSTNODEhas successfuly completed [main] [ 2019-08-21 22:13:24.339 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:13:24.351 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/crsdata/@global/crsconfig/index.xml found. [main] [ 2019-08-21 22:13:24.474 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:13:24.474 AST ] [ClusterwareCkpt.getCkptStatus:353] Reading data for checkpoint: ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:13:24.475 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:14:23.218 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:14:23.222 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:14:23.257 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:14:23.260 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:14:23.272 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:14:23.272 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:14:23.276 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:14:23.278 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:14:23.279 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:14:23.279 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:14:23.280 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:14:23.280 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:14:23.280 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:14:23.282 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:14:23.284 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 0 [main] [ 2019-08-21 22:14:23.284 AST ] [nativesystem.OCRNative.Native] The OCR file is configured & local_only=false [main] [ 2019-08-21 22:14:23.285 AST ] [OCR.isCluster:1059] OCR Result status = true [main] [ 2019-08-21 22:14:23.285 AST ] [OCR.isCluster:1071] Bolean result = true [main] [ 2019-08-21 22:14:23.285 AST ] [cnative.ClusterNative.Native] Native:: CLSBInit [main] [ 2019-08-21 22:14:23.297 AST ] [cnative.ClusterNative.Native] in prcr_clsb:: successfully setup callback [main] [ 2019-08-21 22:14:23.297 AST ] [SRVMContext.init:140] SRVM Context init-ed [main] [ 2019-08-21 22:14:23.298 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:14:23.299 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:14:23.300 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:14:23.300 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:14:23.300 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:14:23.301 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:14:23.304 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:14:23.305 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_FIRSTNODE,-state,START,-nodelist,testdb1,testdb2,-transferfile [main] [ 2019-08-21 22:14:23.305 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:14:23.308 AST ] [ClusterwareCkpt.executeCkpt:1122] Processing writeckpt command line arguments [main] [ 2019-08-21 22:14:23.309 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_FIRSTNODE,-state,START,-nodelist,testdb1,testdb2,-transferfile [main] [ 2019-08-21 22:14:23.318 AST ] [ClusterwareCkpt.writeCheckPoint:544] Writing checkpoint [main] [ 2019-08-21 22:14:23.318 AST ] [ClusterwareCkpt.writeCheckPoint:545] Ckpt Name: ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:14:23.318 AST ] [ClusterwareCkpt.writeCheckPoint:546] Ckpt Desc: null [main] [ 2019-08-21 22:14:23.319 AST ] [ClusterwareCkpt.writeCheckPoint:547] Ckpt Level: null [main] [ 2019-08-21 22:14:23.319 AST ] [ClusterwareCkpt.writeCheckPoint:548] Ckpt State: START [main] [ 2019-08-21 22:14:23.320 AST ] [ClusterwareCkpt.writeCheckPoint:552] after assert of checkpoint name [main] [ 2019-08-21 22:14:23.324 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:14:23.336 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/crsdata/@global/crsconfig/index.xml found. [main] [ 2019-08-21 22:14:23.483 AST ] [ClusterwareCkpt.writeCheckPoint:567] ckpt debug 1 [main] [ 2019-08-21 22:14:23.483 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:14:23.484 AST ] [ClusterwareCkpt.writeCheckPoint:570] ckpt debug 2 [main] [ 2019-08-21 22:14:23.484 AST ] [ClusterwareCkpt.writeCheckPoint:574] ckpt debug 3 [main] [ 2019-08-21 22:14:23.484 AST ] [ClusterwareCkpt.writeCheckPoint:586] Setting checkpoint state to: 1 [main] [ 2019-08-21 22:14:23.486 AST ] [ClusterwareCkpt.writeCheckPoint:590] ckpt debug 4 [main] [ 2019-08-21 22:14:23.486 AST ] [ClusterwareCkpt.writeCheckPoint:595] ckpt debug 5 [main] [ 2019-08-21 22:14:23.494 AST ] [CheckPointSessionImpl.saveCheckPointSession:143] Checkpoint:Index file written and updated [main] [ 2019-08-21 22:14:23.494 AST ] [ClusterwareCkpt.writeCheckPoint:599] ckpt debug 6 [main] [ 2019-08-21 22:14:23.496 AST ] [ClusterwareCkpt.propagateGlobalCheckpoint:871] Propagating global checkpoints to nodes: testdb1,testdb2 [main] [ 2019-08-21 22:14:23.499 AST ] [ClusterwareCkpt.propagateGlobalCheckpoint:876] Closing global checkpoint session [main] [ 2019-08-21 22:14:23.500 AST ] [CheckPointIndexWriter.generatePropertiesNode:220] Checkpoint:Setting status in index file as passed,as no last failed checkpoint is available. [main] [ 2019-08-21 22:14:23.500 AST ] [CheckPointSessionImpl.closeCheckPointSession:183] Sending checkpoint files to remote nodes [main] [ 2019-08-21 22:14:23.501 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:14:23.505 AST ] [Utils.getNodeName:571] Hostname : testdb1 is converted to nodeName : testdb1 [main] [ 2019-08-21 22:14:23.506 AST ] [ClusterUtil.findLiveNodes:218] Attempt to find live nodes [main] [ 2019-08-21 22:14:23.513 AST ] [ClusterConfig.:240] ClusterConfig:Number of workers = 0 [main] [ 2019-08-21 22:14:23.516 AST ] [ClusterConfig.createWorkers:325] Started worker threads count=1 [main] [ 2019-08-21 22:14:23.519 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [Worker 0] [ 2019-08-21 22:14:23.520 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [main] [ 2019-08-21 22:14:23.522 AST ] [GetActiveNodes.create:220] Going into GetActiveNodes constructor... [main] [ 2019-08-21 22:14:23.530 AST ] [HASContext.:125] moduleInit = 19 [main] [ 2019-08-21 22:14:23.531 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=3 [main] [ 2019-08-21 22:14:23.532 AST ] [HASContext.:136] Initialised SRVMContext [main] [ 2019-08-21 22:14:23.533 AST ] [has.HASContextNative.Native] prsr_trace: no lsf ctx, line=Native: allocHASContext [main] [ 2019-08-21 22:14:23.533 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 19 [main] [ 2019-08-21 22:14:23.533 AST ] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [ 2019-08-21 22:14:23.534 AST ] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [ 2019-08-21 22:14:23.534 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [Thread-1] [ 2019-08-21 22:14:23.535 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.534: [ CSSCLNT][2]clsssInitNative [Thread-2] [ 2019-08-21 22:14:23.536 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.536: [ CSSCLNT][2]clsssInitNative: proplist len 16 properties - 1,2,3,4,5,6,7 [Thread-3] [ 2019-08-21 22:14:23.541 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.541: [ CSSCLNT][2]clsssConnect: Connect to CSSD completed, endpt 1b [Thread-4] [ 2019-08-21 22:14:23.543 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.542: [ CSSCLNT][2]clsssConnect: CSS daemon not up (1b) [Thread-5] [ 2019-08-21 22:14:23.544 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.543: [ CSSCLNT][2]clsssConnect: gipcDestroy 0 [Thread-6] [ 2019-08-21 22:14:23.545 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.544: [ CSSCLNT][2]clsssInitNative: CSS daemon in (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_testdb1_)) not up [Thread-7] [ 2019-08-21 22:14:23.546 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.545: [ CSSCLNT][2]clssgsAttrInit:attrdesc grpcount=6 mbrcount 8 [Thread-8] [ 2019-08-21 22:14:23.547 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.546: [ CSSCLNT][2]clsssterm: terminating gbl ctx 1132950 [Thread-9] [ 2019-08-21 22:14:23.548 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.547: [ CSSCLNT][2]clsss_gterm: terminating connection [Thread-10] [ 2019-08-21 22:14:23.548 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.548: [ CSSCLNT][2]clsss_gterm: destroying GIPC ctx [Thread-11] [ 2019-08-21 22:14:23.549 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.549: [ CSSCLNT][2]clsss_gterm: Shutting down GIPC [Thread-12] [ 2019-08-21 22:14:23.551 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.551: [ CSSCLNT][2]clsss_gterm: Completing LSF cleanup [Thread-13] [ 2019-08-21 22:14:23.552 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.552: [ CSSCLNT][2]clsss_gterm: Completing LPM cleanup [main] [ 2019-08-21 22:14:23.555 AST ] [has.HASContextNative.Native] prsr_trace: Native: clss error 3 [main] [ 2019-08-21 22:14:23.555 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_freeCLSS [main] [ 2019-08-21 22:14:23.556 AST ] [has.HASContextNative.Native] prsr_trace: prsr_throwException: class=oracle/ops/mgmt/has/HASContextException, prkhMsgID=CLSS_COM_ERROR, arg1=null, nativeError=null, debugMsg=Native: prsr_initCLSS [main] [ 2019-08-21 22:14:23.559 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:14:23.560 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-08-21 22:14:23.561 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:14:23.561 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 0] [ 2019-08-21 22:14:23.561 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 0 m_count=1 [main] [ 2019-08-21 22:14:23.562 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-08-21 22:14:23.562 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [Worker 0] [ 2019-08-21 22:14:23.568 AST ] [sPlatform.getPingCmdArgs:89] Node=testdb2 Timeout=10 [main] [ 2019-08-21 22:14:23.643 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 0] [ 2019-08-21 22:14:23.675 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Worker 0] [ 2019-08-21 22:14:23.677 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Thread-15] [ 2019-08-21 22:14:23.677 AST ] [StreamReader.run:62] In StreamReader.run [Thread-14] [ 2019-08-21 22:14:23.681 AST ] [StreamReader.run:62] In StreamReader.run [Thread-14] [ 2019-08-21 22:14:23.681 AST ] [StreamReader.run:66] OUTPUT>testdb2 is alive [Worker 0] [ 2019-08-21 22:14:23.682 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 0] [ 2019-08-21 22:14:23.682 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 0] [ 2019-08-21 22:14:23.682 AST ] [UnixSystem.isNodeAlive:5164] msgBuf=testdb2 is alive [Worker 0] [ 2019-08-21 22:14:23.684 AST ] [NodeLivenessCommand.postEvent:103] Inside NodeLivenessCommand.postEvent, listener size=0 [Worker 0] [ 2019-08-21 22:14:23.684 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 0] [ 2019-08-21 22:14:23.685 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 0 m_count=50 [Worker 0] [ 2019-08-21 22:14:23.685 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:14:23.685 AST ] [ClientResource.getListener:157] Calling getListener [Worker 0] [ 2019-08-21 22:14:23.685 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 0] [ 2019-08-21 22:14:23.685 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 0] [ 2019-08-21 22:14:23.686 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-08-21 22:14:23.686 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 0 [Worker 0] [ 2019-08-21 22:14:23.690 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [main] [ 2019-08-21 22:14:23.691 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:14:23.691 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-08-21 22:14:23.691 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-08-21 22:14:23.691 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:14:23.692 AST ] [ClusterUtil.findLiveNodes:258] All nodes are up [main] [ 2019-08-21 22:14:23.692 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:14:23.692 AST ] [GetActiveNodes.create:220] Going into GetActiveNodes constructor... [main] [ 2019-08-21 22:14:23.694 AST ] [HASContext.:125] moduleInit = 19 [main] [ 2019-08-21 22:14:23.694 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=4 [main] [ 2019-08-21 22:14:23.694 AST ] [HASContext.:136] Initialised SRVMContext [main] [ 2019-08-21 22:14:23.695 AST ] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [ 2019-08-21 22:14:23.695 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 19 [main] [ 2019-08-21 22:14:23.696 AST ] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [ 2019-08-21 22:14:23.699 AST ] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [ 2019-08-21 22:14:23.703 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [Thread-16] [ 2019-08-21 22:14:23.705 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.704: [ CSSCLNT][2]clsssInitNative [Thread-17] [ 2019-08-21 22:14:23.705 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.705: [ CSSCLNT][2]clsssInitNative: proplist len 16 properties - 1,2,3,4,5,6,7 [Thread-18] [ 2019-08-21 22:14:23.708 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.707: [ CSSCLNT][2]clsssConnect: Connect to CSSD completed, endpt 1b [Thread-19] [ 2019-08-21 22:14:23.709 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.709: [ CSSCLNT][2]clsssConnect: CSS daemon not up (1b) [Thread-20] [ 2019-08-21 22:14:23.710 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.710: [ CSSCLNT][2]clsssConnect: gipcDestroy 0 [Thread-21] [ 2019-08-21 22:14:23.711 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.710: [ CSSCLNT][2]clsssInitNative: CSS daemon in (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_testdb1_)) not up [Thread-22] [ 2019-08-21 22:14:23.712 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.711: [ CSSCLNT][2]clssgsAttrInit:attrdesc grpcount=6 mbrcount 8 [Thread-23] [ 2019-08-21 22:14:23.712 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.712: [ CSSCLNT][2]clsssterm: terminating gbl ctx 1176bb0 [Thread-24] [ 2019-08-21 22:14:23.713 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.712: [ CSSCLNT][2]clsss_gterm: terminating connection [Thread-25] [ 2019-08-21 22:14:23.714 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.713: [ CSSCLNT][2]clsss_gterm: destroying GIPC ctx [Thread-26] [ 2019-08-21 22:14:23.715 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.714: [ CSSCLNT][2]clsss_gterm: Shutting down GIPC [Thread-27] [ 2019-08-21 22:14:23.716 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.716: [ CSSCLNT][2]clsss_gterm: Completing LSF cleanup [Thread-28] [ 2019-08-21 22:14:23.717 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:23.716: [ CSSCLNT][2]clsss_gterm: Completing LPM cleanup [main] [ 2019-08-21 22:14:23.717 AST ] [has.HASContextNative.Native] prsr_trace: Native: clss error 3 [main] [ 2019-08-21 22:14:23.717 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_freeCLSS [main] [ 2019-08-21 22:14:23.718 AST ] [has.HASContextNative.Native] prsr_trace: prsr_throwException: class=oracle/ops/mgmt/has/HASContextException, prkhMsgID=CLSS_COM_ERROR, arg1=null, nativeError=null, debugMsg=Native: prsr_initCLSS [main] [ 2019-08-21 22:14:23.722 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:14:23.722 AST ] [ClusterConfig.createWorkers:327] Started additional worker threads count=3 [main] [ 2019-08-21 22:14:23.722 AST ] [ClusterConfig.createDirInNode:1940] Creating dir in nodes: testdb2, /u01/app/grid/crsdata/@global/crsconfig, true, 700 [main] [ 2019-08-21 22:14:23.722 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:14:23.723 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-08-21 22:14:23.723 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:14:23.723 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 1] [ 2019-08-21 22:14:23.724 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:14:23.724 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:14:23.724 AST ] [DirCreateCommand.execute:70] In DirCreateCommand.execute, recurseFlag=false, modeFlag=false [Worker 1] [ 2019-08-21 22:14:23.725 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 1] [ 2019-08-21 22:14:23.725 AST ] [UnixSystem.checkRemoteExecutionSetup:3071] Client didn't specify for remote shell or remote copy [Worker 1] [ 2019-08-21 22:14:23.727 AST ] [Library.load:202] library.load [Worker 1] [ 2019-08-21 22:14:23.727 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [Worker 1] [ 2019-08-21 22:14:23.731 AST ] [UnixSystem.checkRemoteExecutionSetup:3082] checkRemoteExecutionSetup:: Checking user equivalence using Secured Shell '/usr/bin/ssh' [Worker 1] [ 2019-08-21 22:14:23.731 AST ] [UnixSystem.checkRemoteExecutionSetup:3084] checkRemoteExecutionSetup:: Running Unix command: /usr/bin/ssh -o FallBackToRsh=no -o PasswordAuthentication=no -o StrictHostKeyChecking=yes -o NumberOfPasswordPrompts=0 testdb2 /usr/bin/true [Worker 2] [ 2019-08-21 22:14:23.731 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [Worker 3] [ 2019-08-21 22:14:23.733 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 3 m_count=0 [Worker 1] [ 2019-08-21 22:14:23.743 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-30] [ 2019-08-21 22:14:23.746 AST ] [StreamReader.run:62] In StreamReader.run [Thread-29] [ 2019-08-21 22:14:23.746 AST ] [StreamReader.run:62] In StreamReader.run [Worker 1] [ 2019-08-21 22:14:23.938 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 1] [ 2019-08-21 22:14:23.938 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 1] [ 2019-08-21 22:14:23.939 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 1] [ 2019-08-21 22:14:23.939 AST ] [UnixSystem.checkRemoteExecutionSetup:3211] Using Remote Shell Command: '/usr/bin/ssh -o FallBackToRsh=no -o PasswordAuthentication=no -o StrictHostKeyChecking=yes -o NumberOfPasswordPrompts=0 ' [Worker 1] [ 2019-08-21 22:14:23.939 AST ] [UnixSystem.checkRemoteExecutionSetup:3212] Using Remote Copy Command: '/usr/bin/scp' [Worker 1] [ 2019-08-21 22:14:23.960 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-32] [ 2019-08-21 22:14:23.962 AST ] [StreamReader.run:62] In StreamReader.run [Thread-31] [ 2019-08-21 22:14:23.966 AST ] [StreamReader.run:62] In StreamReader.run [Worker 1] [ 2019-08-21 22:14:24.188 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 1] [ 2019-08-21 22:14:24.188 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 1] [ 2019-08-21 22:14:24.189 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 1] [ 2019-08-21 22:14:24.189 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/ssh -o FallBackToRsh=no -o PasswordAuthentication=no -o StrictHostKeyChecking=yes -o NumberOfPasswordPrompts=0 testdb2 -n /usr/bin/mkdir -p -m 700 /u01/app/grid/crsdata/@global/crsconfig] [Worker 1] [ 2019-08-21 22:14:24.191 AST ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/ssh is present. [Worker 1] [ 2019-08-21 22:14:24.191 AST ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/ssh is a file. [Worker 1] [ 2019-08-21 22:14:24.192 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned true [Worker 1] [ 2019-08-21 22:14:24.192 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 1] [ 2019-08-21 22:14:24.193 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 1] [ 2019-08-21 22:14:24.194 AST ] [NativeResult.:101] The status string is: 1 [Worker 1] [ 2019-08-21 22:14:24.194 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 1] [ 2019-08-21 22:14:24.194 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 1] [ 2019-08-21 22:14:24.195 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 1 m_count=50 [Worker 1] [ 2019-08-21 22:14:24.195 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:14:24.198 AST ] [ClientResource.getListener:157] Calling getListener [Worker 1] [ 2019-08-21 22:14:24.198 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 1] [ 2019-08-21 22:14:24.198 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 1] [ 2019-08-21 22:14:24.199 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-08-21 22:14:24.199 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 1 [Worker 1] [ 2019-08-21 22:14:24.199 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=0 [main] [ 2019-08-21 22:14:24.200 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:14:24.201 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:14:24.201 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:14:24.201 AST ] [GetActiveNodes.create:220] Going into GetActiveNodes constructor... [main] [ 2019-08-21 22:14:24.202 AST ] [HASContext.:125] moduleInit = 19 [main] [ 2019-08-21 22:14:24.202 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=5 [main] [ 2019-08-21 22:14:24.204 AST ] [HASContext.:136] Initialised SRVMContext [main] [ 2019-08-21 22:14:24.204 AST ] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [ 2019-08-21 22:14:24.205 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 19 [main] [ 2019-08-21 22:14:24.205 AST ] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [ 2019-08-21 22:14:24.205 AST ] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [ 2019-08-21 22:14:24.206 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [Thread-33] [ 2019-08-21 22:14:24.206 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.206: [ CSSCLNT][2]clsssInitNative [Thread-34] [ 2019-08-21 22:14:24.208 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.207: [ CSSCLNT][2]clsssInitNative: proplist len 16 properties - 1,2,3,4,5,6,7 [Finalizer] [ 2019-08-21 22:14:24.233 AST ] [ClusterUtil.finalize:119] ClusterUtil: finalized called for oracle.ops.mgmt.has.ClusterUtil@5dc940c3 [Finalizer] [ 2019-08-21 22:14:24.234 AST ] [ClusterUtil.finalize:119] ClusterUtil: finalized called for oracle.ops.mgmt.has.ClusterUtil@530eb50a [Thread-35] [ 2019-08-21 22:14:24.241 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.212: [ CSSCLNT][2]clsssConnect: Connect to CSSD completed, endpt 1b [Thread-36] [ 2019-08-21 22:14:24.242 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.242: [ CSSCLNT][2]clsssConnect: CSS daemon not up (1b) [Thread-37] [ 2019-08-21 22:14:24.243 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.243: [ CSSCLNT][2]clsssConnect: gipcDestroy 0 [Thread-38] [ 2019-08-21 22:14:24.244 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.244: [ CSSCLNT][2]clsssInitNative: CSS daemon in (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_testdb1_)) not up [Thread-39] [ 2019-08-21 22:14:24.244 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.244: [ CSSCLNT][2]clssgsAttrInit:attrdesc grpcount=6 mbrcount 8 [Thread-40] [ 2019-08-21 22:14:24.245 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.245: [ CSSCLNT][2]clsssterm: terminating gbl ctx 117fe10 [Thread-41] [ 2019-08-21 22:14:24.245 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.245: [ CSSCLNT][2]clsss_gterm: terminating connection [Thread-42] [ 2019-08-21 22:14:24.246 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.246: [ CSSCLNT][2]clsss_gterm: destroying GIPC ctx [Thread-43] [ 2019-08-21 22:14:24.247 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.246: [ CSSCLNT][2]clsss_gterm: Shutting down GIPC [Thread-44] [ 2019-08-21 22:14:24.248 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.248: [ CSSCLNT][2]clsss_gterm: Completing LSF cleanup [Thread-45] [ 2019-08-21 22:14:24.248 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.248: [ CSSCLNT][2]clsss_gterm: Completing LPM cleanup [main] [ 2019-08-21 22:14:24.249 AST ] [has.HASContextNative.Native] prsr_trace: Native: clss error 3 [main] [ 2019-08-21 22:14:24.253 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_freeCLSS [main] [ 2019-08-21 22:14:24.253 AST ] [has.HASContextNative.Native] prsr_trace: prsr_throwException: class=oracle/ops/mgmt/has/HASContextException, prkhMsgID=CLSS_COM_ERROR, arg1=null, nativeError=null, debugMsg=Native: prsr_initCLSS [main] [ 2019-08-21 22:14:24.254 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:14:24.254 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:947] Number of nodes :1 [main] [ 2019-08-21 22:14:24.255 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:949] 0th CopyFileToNodes localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:14:24.255 AST ] [ClusterConfig.copyFileBetweenNodes:684] Checking: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:14:24.256 AST ] [ClusterConfig.copyFileBetweenNodes:696] Checking 2: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:14:24.257 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:14:24.257 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 2] [ 2019-08-21 22:14:24.257 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-08-21 22:14:24.258 AST ] [UnixSystem.copyFile:1084] Copy file localnode:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [Worker 2] [ 2019-08-21 22:14:24.259 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 2] [ 2019-08-21 22:14:24.260 AST ] [UnixSystem.remoteCopyFile:808] Copying files localnode/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [Worker 2] [ 2019-08-21 22:14:24.260 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 2] [ 2019-08-21 22:14:24.261 AST ] [UnixSystem.remoteCopyFile:826] UnixSystem: /usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml' [Worker 2] [ 2019-08-21 22:14:24.271 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-47] [ 2019-08-21 22:14:24.291 AST ] [StreamReader.run:62] In StreamReader.run [Thread-46] [ 2019-08-21 22:14:24.292 AST ] [StreamReader.run:62] In StreamReader.run [main] [ 2019-08-21 22:14:24.292 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:14:24.293 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 2] [ 2019-08-21 22:14:24.514 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 2] [ 2019-08-21 22:14:24.515 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 2] [ 2019-08-21 22:14:24.515 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 2] [ 2019-08-21 22:14:24.515 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml'] [Worker 2] [ 2019-08-21 22:14:24.516 AST ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/scp is present. [Worker 2] [ 2019-08-21 22:14:24.516 AST ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/scp is a file. [Worker 2] [ 2019-08-21 22:14:24.517 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned true [Worker 2] [ 2019-08-21 22:14:24.517 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 2] [ 2019-08-21 22:14:24.517 AST ] [CopyCommand.execute:171] CopyCommand.execute: native copyFile returns `1| :successful' [Worker 2] [ 2019-08-21 22:14:24.518 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 2] [ 2019-08-21 22:14:24.518 AST ] [NativeResult.:101] The status string is: 1 [Worker 2] [ 2019-08-21 22:14:24.518 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 2] [ 2019-08-21 22:14:24.519 AST ] [CopyCommand.execute:179] The copy command failed. Details: :successful [Worker 2] [ 2019-08-21 22:14:24.519 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 2] [ 2019-08-21 22:14:24.519 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 2 m_count=50 [Worker 2] [ 2019-08-21 22:14:24.519 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-08-21 22:14:24.520 AST ] [ClientResource.getListener:157] Calling getListener [Worker 2] [ 2019-08-21 22:14:24.520 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 2] [ 2019-08-21 22:14:24.520 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 2] [ 2019-08-21 22:14:24.521 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-08-21 22:14:24.521 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 2 [Worker 2] [ 2019-08-21 22:14:24.521 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [main] [ 2019-08-21 22:14:24.529 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:14:24.529 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:14:24.530 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-08-21 22:14:24.530 AST ] [GetActiveNodes.create:220] Going into GetActiveNodes constructor... [main] [ 2019-08-21 22:14:24.530 AST ] [HASContext.:125] moduleInit = 19 [main] [ 2019-08-21 22:14:24.531 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=6 [main] [ 2019-08-21 22:14:24.531 AST ] [HASContext.:136] Initialised SRVMContext [main] [ 2019-08-21 22:14:24.532 AST ] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [ 2019-08-21 22:14:24.532 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 19 [main] [ 2019-08-21 22:14:24.533 AST ] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [ 2019-08-21 22:14:24.533 AST ] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [ 2019-08-21 22:14:24.533 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [Thread-48] [ 2019-08-21 22:14:24.534 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.534: [ CSSCLNT][2]clsssInitNative [Thread-49] [ 2019-08-21 22:14:24.535 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.534: [ CSSCLNT][2]clsssInitNative: proplist len 16 properties - 1,2,3,4,5,6,7 [Thread-50] [ 2019-08-21 22:14:24.538 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.537: [ CSSCLNT][2]clsssConnect: Connect to CSSD completed, endpt 1b [Thread-51] [ 2019-08-21 22:14:24.539 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.539: [ CSSCLNT][2]clsssConnect: CSS daemon not up (1b) [Thread-52] [ 2019-08-21 22:14:24.540 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.539: [ CSSCLNT][2]clsssConnect: gipcDestroy 0 [Thread-53] [ 2019-08-21 22:14:24.540 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.540: [ CSSCLNT][2]clsssInitNative: CSS daemon in (ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_testdb1_)) not up [Thread-54] [ 2019-08-21 22:14:24.541 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.541: [ CSSCLNT][2]clssgsAttrInit:attrdesc grpcount=6 mbrcount 8 [Thread-55] [ 2019-08-21 22:14:24.541 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.541: [ CSSCLNT][2]clsssterm: terminating gbl ctx 1211780 [Thread-56] [ 2019-08-21 22:14:24.545 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.544: [ CSSCLNT][2]clsss_gterm: terminating connection [Thread-57] [ 2019-08-21 22:14:24.545 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.545: [ CSSCLNT][2]clsss_gterm: destroying GIPC ctx [Thread-58] [ 2019-08-21 22:14:24.548 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.547: [ CSSCLNT][2]clsss_gterm: Shutting down GIPC [Thread-59] [ 2019-08-21 22:14:24.549 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.549: [ CSSCLNT][2]clsss_gterm: Completing LSF cleanup [Thread-60] [ 2019-08-21 22:14:24.549 AST ] [Trace.nativeOut:838] 2019-08-21 22:14:24.549: [ CSSCLNT][2]clsss_gterm: Completing LPM cleanup [main] [ 2019-08-21 22:14:24.550 AST ] [has.HASContextNative.Native] prsr_trace: Native: clss error 3 [main] [ 2019-08-21 22:14:24.550 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_freeCLSS [main] [ 2019-08-21 22:14:24.551 AST ] [has.HASContextNative.Native] prsr_trace: prsr_throwException: class=oracle/ops/mgmt/has/HASContextException, prkhMsgID=CLSS_COM_ERROR, arg1=null, nativeError=null, debugMsg=Native: prsr_initCLSS [main] [ 2019-08-21 22:14:24.551 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-08-21 22:14:24.552 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:947] Number of nodes :1 [main] [ 2019-08-21 22:14:24.552 AST ] [ClusterConfig.copyFileToNodesNonSynchronized:949] 0th CopyFileToNodes localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [main] [ 2019-08-21 22:14:24.552 AST ] [ClusterConfig.copyFileBetweenNodes:684] Checking: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [main] [ 2019-08-21 22:14:24.553 AST ] [ClusterConfig.copyFileBetweenNodes:696] Checking 2: Copying files between nodes: localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [main] [ 2019-08-21 22:14:24.553 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=1 [main] [ 2019-08-21 22:14:24.553 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 3] [ 2019-08-21 22:14:24.553 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-08-21 22:14:24.554 AST ] [UnixSystem.copyFile:1084] Copy file localnode:/u01/app/grid/crsdata/@global/crsconfig/index.xml to testdb2:/u01/app/grid/crsdata/@global/crsconfig/index.xml [Worker 3] [ 2019-08-21 22:14:24.555 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 3] [ 2019-08-21 22:14:24.555 AST ] [UnixSystem.remoteCopyFile:808] Copying files localnode/u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2/u01/app/grid/crsdata/@global/crsconfig/index.xml [Worker 3] [ 2019-08-21 22:14:24.557 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [Worker 3] [ 2019-08-21 22:14:24.558 AST ] [UnixSystem.remoteCopyFile:826] UnixSystem: /usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/index.xml' [Worker 3] [ 2019-08-21 22:14:24.568 AST ] [RuntimeExec.runCommand:269] runCommand: Waiting for the process [Thread-62] [ 2019-08-21 22:14:24.586 AST ] [StreamReader.run:62] In StreamReader.run [Thread-61] [ 2019-08-21 22:14:24.587 AST ] [StreamReader.run:62] In StreamReader.run [main] [ 2019-08-21 22:14:24.589 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-08-21 22:14:24.598 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 3] [ 2019-08-21 22:14:24.834 AST ] [RuntimeExec.runCommand:271] runCommand: process returns 0 [Worker 3] [ 2019-08-21 22:14:24.834 AST ] [RuntimeExec.runCommand:297] RunTimeExec: error> [Worker 3] [ 2019-08-21 22:14:24.835 AST ] [RuntimeExec.runCommand:323] Returning from RunTimeExec.runCommand [Worker 3] [ 2019-08-21 22:14:24.835 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/scp -p /u01/app/grid/crsdata/@global/crsconfig/index.xml testdb2:'/u01/app/grid/crsdata/@global/crsconfig/index.xml'] [Worker 3] [ 2019-08-21 22:14:24.837 AST ] [NativeSystem.isCmdScv:597] isCmdScv: /usr/bin/scp is present. [Worker 3] [ 2019-08-21 22:14:24.837 AST ] [NativeSystem.isCmdScv:599] isCmdScv: /usr/bin/scp is a file. [Worker 3] [ 2019-08-21 22:14:24.838 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned true [Worker 3] [ 2019-08-21 22:14:24.838 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 3] [ 2019-08-21 22:14:24.838 AST ] [CopyCommand.execute:171] CopyCommand.execute: native copyFile returns `1| :successful' [Worker 3] [ 2019-08-21 22:14:24.838 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 3] [ 2019-08-21 22:14:24.839 AST ] [NativeResult.:101] The status string is: 1 [Worker 3] [ 2019-08-21 22:14:24.839 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 3] [ 2019-08-21 22:14:24.839 AST ] [CopyCommand.execute:179] The copy command failed. Details: :successful [Worker 3] [ 2019-08-21 22:14:24.839 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 3] [ 2019-08-21 22:14:24.840 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 3 m_count=50 [Worker 3] [ 2019-08-21 22:14:24.840 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-08-21 22:14:24.841 AST ] [ClientResource.getListener:157] Calling getListener [Worker 3] [ 2019-08-21 22:14:24.842 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 3] [ 2019-08-21 22:14:24.842 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 3] [ 2019-08-21 22:14:24.842 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-08-21 22:14:24.842 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 3 [Worker 3] [ 2019-08-21 22:14:24.843 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 3 m_count=0 [main] [ 2019-08-21 22:14:24.843 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-08-21 22:14:24.843 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-08-21 22:14:24.844 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:15:27.578 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:15:27.586 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:15:27.622 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:15:27.624 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:15:27.636 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:15:27.637 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:15:27.640 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:15:27.643 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:15:27.643 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:15:27.643 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:15:27.644 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:15:27.644 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:15:27.645 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:15:27.647 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:15:27.648 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 0 [main] [ 2019-08-21 22:15:27.649 AST ] [nativesystem.OCRNative.Native] The OCR file is configured & local_only=false [main] [ 2019-08-21 22:15:27.649 AST ] [OCR.isCluster:1059] OCR Result status = true [main] [ 2019-08-21 22:15:27.649 AST ] [OCR.isCluster:1071] Bolean result = true [main] [ 2019-08-21 22:15:27.650 AST ] [cnative.ClusterNative.Native] Native:: CLSBInit [main] [ 2019-08-21 22:15:27.661 AST ] [cnative.ClusterNative.Native] in prcr_clsb:: successfully setup callback [main] [ 2019-08-21 22:15:27.662 AST ] [SRVMContext.init:140] SRVM Context init-ed [main] [ 2019-08-21 22:15:27.663 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:15:27.663 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:15:27.664 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:15:27.664 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:15:27.664 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:15:27.665 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:15:27.669 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:15:27.669 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_OKAINST,-state,SUCCESS [main] [ 2019-08-21 22:15:27.669 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:15:27.672 AST ] [ClusterwareCkpt.executeCkpt:1122] Processing writeckpt command line arguments [main] [ 2019-08-21 22:15:27.673 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-oraclebase,/u01/app/grid,-writeckpt,-name,ROOTCRS_OKAINST,-state,SUCCESS [main] [ 2019-08-21 22:15:27.682 AST ] [ClusterwareCkpt.writeCheckPoint:544] Writing checkpoint [main] [ 2019-08-21 22:15:27.682 AST ] [ClusterwareCkpt.writeCheckPoint:545] Ckpt Name: ROOTCRS_OKAINST [main] [ 2019-08-21 22:15:27.683 AST ] [ClusterwareCkpt.writeCheckPoint:546] Ckpt Desc: null [main] [ 2019-08-21 22:15:27.683 AST ] [ClusterwareCkpt.writeCheckPoint:547] Ckpt Level: null [main] [ 2019-08-21 22:15:27.684 AST ] [ClusterwareCkpt.writeCheckPoint:548] Ckpt State: SUCCESS [main] [ 2019-08-21 22:15:27.684 AST ] [ClusterwareCkpt.writeCheckPoint:552] after assert of checkpoint name [main] [ 2019-08-21 22:15:27.688 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:15:27.700 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/testdb1/checkpoints/crsconfig/index.xml found. [main] [ 2019-08-21 22:15:27.842 AST ] [ClusterwareCkpt.writeCheckPoint:567] ckpt debug 1 [main] [ 2019-08-21 22:15:27.842 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/testdb1/crsconfig/ckptGridHA_testdb1.xml [main] [ 2019-08-21 22:15:27.843 AST ] [ClusterwareCkpt.writeCheckPoint:570] ckpt debug 2 [main] [ 2019-08-21 22:15:27.843 AST ] [ClusterwareCkpt.writeCheckPoint:574] ckpt debug 3 [main] [ 2019-08-21 22:15:27.843 AST ] [ClusterwareCkpt.writeCheckPoint:586] Setting checkpoint state to: 3 [main] [ 2019-08-21 22:15:27.844 AST ] [ClusterwareCkpt.writeCheckPoint:590] ckpt debug 4 [main] [ 2019-08-21 22:15:27.844 AST ] [ClusterwareCkpt.writeCheckPoint:595] ckpt debug 5 [main] [ 2019-08-21 22:15:27.870 AST ] [CheckPointSessionImpl.saveCheckPointSession:143] Checkpoint:Index file written and updated [main] [ 2019-08-21 22:15:27.870 AST ] [ClusterwareCkpt.writeCheckPoint:599] ckpt debug 6 [main] [ 2019-08-21 22:15:27.871 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:15:50.530 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:15:50.536 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:15:50.573 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:15:50.575 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:15:50.589 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:15:50.590 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:15:50.593 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:15:50.594 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:15:50.594 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:15:50.594 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:15:50.595 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:15:50.595 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:15:50.596 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:15:50.600 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:15:50.601 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 0 [main] [ 2019-08-21 22:15:50.602 AST ] [nativesystem.OCRNative.Native] The OCR file is configured & local_only=false [main] [ 2019-08-21 22:15:50.602 AST ] [OCR.isCluster:1059] OCR Result status = true [main] [ 2019-08-21 22:15:50.602 AST ] [OCR.isCluster:1071] Bolean result = true [main] [ 2019-08-21 22:15:50.603 AST ] [cnative.ClusterNative.Native] Native:: CLSBInit [main] [ 2019-08-21 22:15:50.615 AST ] [cnative.ClusterNative.Native] in prcr_clsb:: successfully setup callback [main] [ 2019-08-21 22:15:50.615 AST ] [SRVMContext.init:140] SRVM Context init-ed [main] [ 2019-08-21 22:15:50.616 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:15:50.617 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:15:50.617 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:15:50.617 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:15:50.618 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:15:50.618 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:15:50.622 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:15:50.623 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:15:50.623 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:15:50.626 AST ] [ClusterwareCkpt.executeCkpt:1105] Processing chkckpt command line arguments [main] [ 2019-08-21 22:15:50.627 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-global,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_FIRSTNODE [main] [ 2019-08-21 22:15:50.636 AST ] [ClusterwareCkpt.isCkptExists:308] Checking if checkpoint:ROOTCRS_FIRSTNODE exists [main] [ 2019-08-21 22:15:50.640 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:15:50.652 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/crsdata/@global/crsconfig/index.xml found. [main] [ 2019-08-21 22:15:50.779 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/@global/crsconfig/ckptGridHA_global.xml [main] [ 2019-08-21 22:15:50.781 AST ] [ClusterwareCkpt.isCkptExists:322] ckpt = oracle.cluster.impl.checkpoints.CheckPointImpl@13fee20c [main] [ 2019-08-21 22:15:50.782 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0 [main] [ 2019-08-21 22:17:43.536 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:17:43.541 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:17:43.606 AST ] [ClusterUtil.main:296] Trace enabled [main] [ 2019-08-21 22:17:43.608 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-08-21 22:17:43.616 AST ] [Version.isPre:661] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-08-21 22:17:43.616 AST ] [Version.isPre:672] isPre.java: Returning FALSE [main] [ 2019-08-21 22:17:43.620 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-08-21 22:17:43.621 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-08-21 22:17:43.621 AST ] [Library.load:202] library.load [main] [ 2019-08-21 22:17:43.621 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-08-21 22:17:43.623 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-08-21 22:17:43.623 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-08-21 22:17:43.623 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-08-21 22:17:43.626 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-08-21 22:17:43.628 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 0 [main] [ 2019-08-21 22:17:43.628 AST ] [nativesystem.OCRNative.Native] The OCR file is configured & local_only=false [main] [ 2019-08-21 22:17:43.628 AST ] [OCR.isCluster:1059] OCR Result status = true [main] [ 2019-08-21 22:17:43.629 AST ] [OCR.isCluster:1071] Bolean result = true [main] [ 2019-08-21 22:17:43.629 AST ] [cnative.ClusterNative.Native] Native:: CLSBInit [main] [ 2019-08-21 22:17:43.643 AST ] [cnative.ClusterNative.Native] in prcr_clsb:: successfully setup callback [main] [ 2019-08-21 22:17:43.644 AST ] [SRVMContext.init:140] SRVM Context init-ed [main] [ 2019-08-21 22:17:43.645 AST ] [ClusterUtil.parseArgs:138] m_ckpt=true [main] [ 2019-08-21 22:17:43.645 AST ] [ClusterUtil.parseArgs:139] m_copy=false [main] [ 2019-08-21 22:17:43.645 AST ] [ClusterUtil.parseArgs:140] m_isshared=false [main] [ 2019-08-21 22:17:43.646 AST ] [ClusterUtil.parseArgs:141] m_exec=false [main] [ 2019-08-21 22:17:43.646 AST ] [ClusterUtil.parseArgs:142] m_rmFile=false [main] [ 2019-08-21 22:17:43.646 AST ] [ClusterUtil.parseArgs:143] m_help=false [main] [ 2019-08-21 22:17:43.666 AST ] [Utils.getLocalHost:448] Hostname retrieved: testdb1.alfarisad.local, returned: testdb1 [main] [ 2019-08-21 22:17:43.667 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_BOOTCFG,-status [main] [ 2019-08-21 22:17:43.668 AST ] [ClusterwareCkpt.executeCkpt:1079] Parsed Arguments [main] [ 2019-08-21 22:17:43.672 AST ] [ClusterwareCkpt.executeCkpt:1105] Processing chkckpt command line arguments [main] [ 2019-08-21 22:17:43.674 AST ] [ClusterwareCkpt.parseArgs:284] args = -ckpt,-oraclebase,/u01/app/grid,-chkckpt,-name,ROOTCRS_BOOTCFG,-status [main] [ 2019-08-21 22:17:43.696 AST ] [ClusterwareCkpt.getCkptStatus:329] Checking to see if checkpoint:ROOTCRS_BOOTCFGhas successfuly completed [main] [ 2019-08-21 22:17:43.717 AST ] [CheckPointFactory.getIndexSession:92] Checkpoint:getting indexSession from checkpoint factory [main] [ 2019-08-21 22:17:43.780 AST ] [CheckPointIndexSessionImpl.:98] Checkpoint:Index file :/u01/app/grid/testdb1/checkpoints/crsconfig/index.xml found. [main] [ 2019-08-21 22:17:44.077 AST ] [ClusterwareCkpt.getCkptFileLoc:274] ckpt file location is /u01/app/grid/crsdata/testdb1/crsconfig/ckptGridHA_testdb1.xml [main] [ 2019-08-21 22:17:44.078 AST ] [ClusterwareCkpt.getCkptStatus:353] Reading data for checkpoint: ROOTCRS_BOOTCFG [main] [ 2019-08-21 22:17:44.080 AST ] [ClusterUtil.main:333] ClusterUtil.execute rc: 0