[main] [ 2019-09-04 10:31:45.094 AST ] [UsmcaCmdLineParser.isOraHomeCheckRequired:423] Skipping Oracle Home check for local operation. [main] [ 2019-09-04 10:31:45.329 AST ] [HASContext.:125] moduleInit = 7 [main] [ 2019-09-04 10:31:45.330 AST ] [Library.load:202] library.load [main] [ 2019-09-04 10:31:45.331 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-09-04 10:31:45.332 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-09-04 10:31:45.332 AST ] [Library.load:290] Loading library /u01/app/12.2.0.1/setup/lib/libsrvmhas12.so [main] [ 2019-09-04 10:31:45.383 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=1 [main] [ 2019-09-04 10:31:45.405 AST ] [Version.isPre:678] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-09-04 10:31:45.405 AST ] [Version.isPre:689] isPre.java: Returning FALSE [main] [ 2019-09-04 10:31:45.409 AST ] [OCR.loadLibrary:333] Inside constructor of OCR [main] [ 2019-09-04 10:31:45.409 AST ] [OCR.loadLibrary:341] Going to load the ocr library [main] [ 2019-09-04 10:31:45.409 AST ] [Library.load:202] library.load [main] [ 2019-09-04 10:31:45.410 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-09-04 10:31:45.411 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-09-04 10:31:45.411 AST ] [Library.load:290] Loading library /u01/app/12.2.0.1/setup/lib/libsrvmocr12.so [main] [ 2019-09-04 10:31:45.412 AST ] [OCR.loadLibrary:343] loaded ocr libraries [main] [ 2019-09-04 10:31:45.412 AST ] [SRVMContext.init:115] Performing SRVM Context init. Init Counter=2 [main] [ 2019-09-04 10:31:45.413 AST ] [OCR.isCluster:1055] Calling OCRNative for isCluster() [main] [ 2019-09-04 10:31:45.415 AST ] [nativesystem.OCRNative.Native] JNI: isCluster() Successfully initialized meta context [main] [ 2019-09-04 10:31:45.416 AST ] [nativesystem.OCRNative.Native] JNI: procr_get_conf() retValue = 0 [main] [ 2019-09-04 10:31:45.417 AST ] [nativesystem.OCRNative.Native] The OCR file is configured & local_only=false [main] [ 2019-09-04 10:31:45.417 AST ] [OCR.isCluster:1059] OCR Result status = true [main] [ 2019-09-04 10:31:45.417 AST ] [OCR.isCluster:1071] Bolean result = true [main] [ 2019-09-04 10:31:45.418 AST ] [cnative.ClusterNative.Native] Native:: CLSBInit [main] [ 2019-09-04 10:31:45.435 AST ] [cnative.ClusterNative.Native] in prcr_clsb:: successfully setup callback [main] [ 2019-09-04 10:31:45.437 AST ] [SRVMContext.init:140] SRVM Context init-ed [main] [ 2019-09-04 10:31:45.445 AST ] [HASContext.:136] Initialised SRVMContext [main] [ 2019-09-04 10:31:45.446 AST ] [has.HASContextNative.Native] prsr_trace: no lsf ctx, line=Native: allocHASContext [main] [ 2019-09-04 10:31:45.446 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 7 [main] [ 2019-09-04 10:31:45.447 AST ] [has.HASContextNative.Native] allocHASContext: META context [1] [main] [ 2019-09-04 10:31:45.448 AST ] [has.HASContextNative.Native] allocHASContext: LSF context [1] [main] [ 2019-09-04 10:31:45.450 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initSCLS [main] [ 2019-09-04 10:31:45.450 AST ] [has.HASContextNative.Native] allocHASContext: SCLS context [1] [main] [ 2019-09-04 10:31:45.450 AST ] [has.HASContextNative.Native] allocHASContext: retval [1] [main] [ 2019-09-04 10:31:45.450 AST ] [Util.:103] Util Instance created. [main] [ 2019-09-04 10:31:45.458 AST ] [has.UtilNative.Native] prsr_trace: Native: getCRSHome [main] [ 2019-09-04 10:31:45.458 AST ] [has.UtilNative.Native] prsr_trace: Native: getCRSHome crs_home=/u01/app/12.2.0.1/setup(**) [main] [ 2019-09-04 10:31:45.462 AST ] [HASContext.getCRSHome:642] /u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:45.462 AST ] [Util.getCRSHome:612] getCRSHome: ret=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:45.498 AST ] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [ 2019-09-04 10:31:45.499 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 64 [main] [ 2019-09-04 10:31:45.500 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSCRS [main] [ 2019-09-04 10:31:45.500 AST ] [has.HASContextNative.Native] prsr_trace: prsr_initCLSCRS: before calling prcr_init_crs [main] [ 2019-09-04 10:31:45.511 AST ] [has.HASContextNative.Native] allocHASContext: CLSCRS context [1] [main] [ 2019-09-04 10:31:45.516 AST ] [has.HASContextNative.Native] allocHASContext: retval [1] [main] [ 2019-09-04 10:31:45.525 AST ] [cops.EntityOperations.Native] prsr_trace: e_type=1 [main] [ 2019-09-04 10:31:45.691 AST ] [Usmca.execute:266] PRCR-1070 : Failed to check if resource ora.asm is registered CRS-0184 : Cannot communicate with the CRS daemon. [main] [ 2019-09-04 10:31:45.703 AST ] [Util.:103] Util Instance created. [main] [ 2019-09-04 10:31:45.704 AST ] [has.UtilNative.Native] prsr_trace: Native: hasHAPrivilege [main] [ 2019-09-04 10:31:45.728 AST ] [has.HASContextNative.Native] prsr_trace: Native: allocHASContext [main] [ 2019-09-04 10:31:45.728 AST ] [has.HASContextNative.Native] allocHASContext: module_init = 56 [main] [ 2019-09-04 10:31:45.729 AST ] [has.HASContextNative.Native] allocHASContext: SLTS context [1] [main] [ 2019-09-04 10:31:45.732 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSS [main] [ 2019-09-04 10:31:45.737 AST ] [has.HASContextNative.Native] allocHASContext: CLSS context [1] [main] [ 2019-09-04 10:31:45.738 AST ] [has.HASContextNative.Native] prsr_trace: Native: prsr_initCLSR [main] [ 2019-09-04 10:31:45.751 AST ] [has.HASContextNative.Native] prsr_trace: prsr_initCLSR: before calling clsrcini [main] [ 2019-09-04 10:31:45.765 AST ] [has.HASContextNative.Native] prsr_trace: prsr_initCLSR: before calling clsrcerrini [main] [ 2019-09-04 10:31:45.766 AST ] [has.HASContextNative.Native] allocHASContext: CLSR context [1] [main] [ 2019-09-04 10:31:45.766 AST ] [has.HASContextNative.Native] allocHASContext: retval [1] [main] [ 2019-09-04 10:31:45.767 AST ] [ClusterAlias.:89] ClusterAlias Instance created. [main] [ 2019-09-04 10:31:46.352 AST ] [InventoryUtil.getOUIInvSession:349] setting OUI READ level to ACCESSLEVEL_READ_LOCKLESS [main] [ 2019-09-04 10:31:46.359 AST ] [HAUtils.:331] oui location /u01/app/oraInventory/ContentsXML [main] [ 2019-09-04 10:31:46.378 AST ] [InventoryUtil.getOUIInvSession:349] setting OUI READ level to ACCESSLEVEL_READ_LOCKLESS [main] [ 2019-09-04 10:31:46.379 AST ] [OracleHome.isClientHome:1755] Homeinfo /u01/app/12.2.0.1/setup,1 [Finalizer] [ 2019-09-04 10:31:46.613 AST ] [Util.finalize:134] Util: finalized called for oracle.ops.mgmt.has.Util@635cb856 [main] [ 2019-09-04 10:31:47.398 AST ] [HAUtils.:364] isClientHome: false [main] [ 2019-09-04 10:31:47.401 AST ] [ClusterUtil.:87] ClusterUtil Instance created [main] [ 2019-09-04 10:31:47.401 AST ] [ClusterUtil.:90] ClusterUtil m_bSKGXN=true [main] [ 2019-09-04 10:31:47.401 AST ] [ClusterUtil.getCSSMode:717] Returned from native code [main] [ 2019-09-04 10:31:47.402 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getCSSMod [main] [ 2019-09-04 10:31:47.402 AST ] [has.ClusterUtilNative.Native] prsr_trace: mode of css: 1 [main] [ 2019-09-04 10:31:47.402 AST ] [ClusterUtil.getCSSMode:722] Returned from native code [main] [ 2019-09-04 10:31:47.403 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeActiveRole [main] [ 2019-09-04 10:31:47.404 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeActiveRole: after clssnsqueryrole [main] [ 2019-09-04 10:31:47.404 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeActiveRole:active role is [1] [main] [ 2019-09-04 10:31:47.404 AST ] [ClusterUtil.getNodeActiveRole:433] Get NodeActiveRole 1 [main] [ 2019-09-04 10:31:47.404 AST ] [ClusterUtil.:87] ClusterUtil Instance created [main] [ 2019-09-04 10:31:47.404 AST ] [ClusterUtil.:90] ClusterUtil m_bSKGXN=true [main] [ 2019-09-04 10:31:47.404 AST ] [ClusterUtil.getASMMode:771] Calling native code getASMMode [main] [ 2019-09-04 10:31:47.404 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getASMMode() [main] [ 2019-09-04 10:31:47.794 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getASMMode(): returned ASM mode is [1] [main] [ 2019-09-04 10:31:47.795 AST ] [ClusterUtil.getASMMode:775] Returned from native code [main] [ 2019-09-04 10:31:47.795 AST ] [ClusterUtil.getASMMode:776] mode string returned from native code is LEGACY [main] [ 2019-09-04 10:31:47.796 AST ] [ASMFactoryImpl.getASMMode:4388] ASMMode = legacy [main] [ 2019-09-04 10:31:47.796 AST ] [Usmca.checkIfBigClusterAndHubNode:622] isBigCluster false [main] [ 2019-09-04 10:31:47.796 AST ] [Usmca.checkIfBigClusterAndHubNode:623] isHubNode true [main] [ 2019-09-04 10:31:47.797 AST ] [Usmca.checkIfBigClusterAndHubNode:624] isClientcluster false [main] [ 2019-09-04 10:31:47.804 AST ] [UsmcaCmdLineParser.discoverRAC:470] Cluster Existence Check [main] [ 2019-09-04 10:31:47.804 AST ] [UsmcaCmdLineParser.discoverRAC:474] cluster existence:true [main] [ 2019-09-04 10:31:47.822 AST ] [UsmcaLogger.logInfo:156] AFD driver state script exists true [main] [ 2019-09-04 10:31:47.822 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.util.UsmcaUtil Method : executeCommand [main] [ 2019-09-04 10:31:47.822 AST ] [UsmcaLogger.logInfo:156] Command: /u01/app/12.2.0.1/setup/bin/afddriverstate loaded [main] [ 2019-09-04 10:31:48.319 AST ] [UsmcaLogger.logInfo:156] AFD-9205: AFD device driver loaded status: 'true' [main] [ 2019-09-04 10:31:48.323 AST ] [UsmcaLogger.logInfo:156] AFD driver state status code 0 [main] [ 2019-09-04 10:31:48.334 AST ] [UsmcaCmdLineParser.setDataForOperation:4507] resolving size of disks [main] [ 2019-09-04 10:31:48.334 AST ] [UsmcaCmdLineParser.resolveSizeOfDisks:4899] Disk String: '/dev/rdsk/*' [main] [ 2019-09-04 10:31:48.336 AST ] [KfodUtil.kfodOutput:375] /u01/app/12.2.0.1/setup/bin/kfod [main] [ 2019-09-04 10:31:48.336 AST ] [KfodUtil.kfodOutput:375] nohdr=TRUE [main] [ 2019-09-04 10:31:48.337 AST ] [KfodUtil.kfodOutput:375] OP=DISKS [main] [ 2019-09-04 10:31:48.337 AST ] [KfodUtil.kfodOutput:375] status=true [main] [ 2019-09-04 10:31:48.337 AST ] [KfodUtil.kfodOutput:375] asm_diskstring='/dev/rdsk/*' disks=all [main] [ 2019-09-04 10:31:48.532 AST ] [KfodUtil.kfodOutput:386] Kfod result 51167 CANDIDATE /dev/rdsk/c1t2d0s6 grid asmadmin [main] [ 2019-09-04 10:31:48.536 AST ] [UsmcaCmdLineParser.resolveSizeOfDisks:4923] getting size of disk: /dev/rdsk/c1t2d0s6 [main] [ 2019-09-04 10:31:48.536 AST ] [UsmcaCmdLineParser.getSizeOfDisk:4956] disk path retrieved: /dev/rdsk/c1t2d0s6 [main] [ 2019-09-04 10:31:48.537 AST ] [UsmcaCmdLineParser.getSizeOfDisk:4959] disk's size found [main] [ 2019-09-04 10:31:48.537 AST ] [UsmcaCmdLineParser.resolveSizeOfDisks:4927] size of disk: 51167 [main] [ 2019-09-04 10:31:48.538 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.cli.UsmcaCmdLineParser Method : validateForConfigureLocalASM [main] [ 2019-09-04 10:31:48.540 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.cli.UsmcaCmdLineParser Method : validateDiskGroups() [main] [ 2019-09-04 10:31:48.540 AST ] [OracleHome.getBannerVersion:1166] OracleHome.getBannerVersion called [main] [ 2019-09-04 10:31:48.541 AST ] [OracleHome.getBannerVersion:1200] adding oracle home to sqlplus env [main] [ 2019-09-04 10:31:48.542 AST ] [OracleHome.getBannerVersion:1204] LD_LIBRARY_PATH=/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/network/lib:.:/usr/jdk/packages/lib/amd64:/lib/64:/usr/lib/64 [main] [ 2019-09-04 10:31:48.542 AST ] [OracleHome.getBannerVersion:1204] ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:48.593 AST ] [OracleHome.getBannerVersion:1209] Banner: SQL*Plus: Release 12.2.0.1.0 Production [main] [ 2019-09-04 10:31:48.594 AST ] [OracleHome.getBannerVersion:1166] OracleHome.getBannerVersion called [main] [ 2019-09-04 10:31:48.594 AST ] [OracleHome.getBannerVersion:1200] adding oracle home to sqlplus env [main] [ 2019-09-04 10:31:48.595 AST ] [OracleHome.getBannerVersion:1204] LD_LIBRARY_PATH=/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/network/lib:.:/usr/jdk/packages/lib/amd64:/lib/64:/usr/lib/64 [main] [ 2019-09-04 10:31:48.596 AST ] [OracleHome.getBannerVersion:1204] ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:48.639 AST ] [OracleHome.getBannerVersion:1209] Banner: SQL*Plus: Release 12.2.0.1.0 Production [main] [ 2019-09-04 10:31:48.643 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.cli.UsmcaCmdLineParser Method : validateDiskGroups() [main] [ 2019-09-04 10:31:48.644 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.cli.UsmcaCmdLineParser Method : validateForConfigureLocalASM [main] [ 2019-09-04 10:31:48.647 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.model.UsmcaModel Method : initialize [main] [ 2019-09-04 10:31:48.647 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: null [main] [ 2019-09-04 10:31:48.651 AST ] [InventoryUtil.getOUIInvSession:349] setting OUI READ level to ACCESSLEVEL_READ_LOCKLESS [main] [ 2019-09-04 10:31:48.651 AST ] [OracleHome.getVersion:1037] Homeinfo /u01/app/12.2.0.1/setup,1 [main] [ 2019-09-04 10:31:48.892 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: null [main] [ 2019-09-04 10:31:48.892 AST ] [OracleHome.getVersion:1093] using sqlplus: /u01/app/12.2.0.1/setup/bin/sqlplus [main] [ 2019-09-04 10:31:48.892 AST ] [OracleHome.getVersion:1125] adding oracle home to sqlplus env [main] [ 2019-09-04 10:31:48.893 AST ] [OracleHome.getVersion:1129] LD_LIBRARY_PATH=/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/network/lib:.:/usr/jdk/packages/lib/amd64:/lib/64:/usr/lib/64 [main] [ 2019-09-04 10:31:48.893 AST ] [OracleHome.getVersion:1129] ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:48.944 AST ] [OracleHome.getVersion:1134] /u01/app/12.2.0.1/setup/bin/sqlplus Banner: SQL*Plus: Release 12.2.0.1.0 Production [main] [ 2019-09-04 10:31:48.944 AST ] [OracleHome.getVersion:1152] Current version from sqlplus: 12.2.0.1.0 [main] [ 2019-09-04 10:31:48.944 AST ] [UsmcaLogger.logInfo:156] Software Version: 12.2.0.1.0 [Finalizer] [ 2019-09-04 10:31:48.962 AST ] [ClusterUtil.finalize:119] ClusterUtil: finalized called for oracle.ops.mgmt.has.ClusterUtil@6d9b5a4d [main] [ 2019-09-04 10:31:49.210 AST ] [OsUtilsBase.getBaseFromOrabase:688] oraBaseUtility /u01/app/12.2.0.1/setup/bin/orabase [main] [ 2019-09-04 10:31:49.210 AST ] [OsUtilsBase.getBaseFromOrabase:697] cmds: /u01/app/12.2.0.1/setup/bin/orabase [main] [ 2019-09-04 10:31:49.210 AST ] [OsUtilsBase.getBaseFromOrabase:701] envs: ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:49.210 AST ] [OsUtilsBase.deleteFromEnvironment:2261] Removed from env ORACLE_BASE=/u01/app/grid [main] [ 2019-09-04 10:31:49.227 AST ] [OsUtilsBase.getBaseFromOrabase:711] baseLocation from orabase /u01/app/grid [main] [ 2019-09-04 10:31:49.227 AST ] [OsUtilsBase.getBaseFromOrabase:736] orabaseLocation= /u01/app/grid [main] [ 2019-09-04 10:31:49.364 AST ] [NetworkUtils.checkListenerStatus:520] Checking default listener status [main] [ 2019-09-04 10:31:49.364 AST ] [NetworkUtils.checkListenerStatus:525] Checking listener status: LISTENER [main] [ 2019-09-04 10:31:49.451 AST ] [NetworkUtils.checkListenerStatus:531] lsnrct status output LSNRCTL for Solaris: Version 12.2.0.1.0 - Production on 04-SEP-2019 10:31:49 Copyright (c) 1991, 2016, Oracle. All rights reserved. Connecting to (ADDRESS=(PROTOCOL=tcp)(HOST=)(PORT=1521)) TNS-12541: TNS:no listener TNS-12560: TNS:protocol adapter error TNS-00511: No listener Solaris Error: 146: Connection refused [main] [ 2019-09-04 10:31:49.453 AST ] [UsmcaLogger.logInfo:156] ignoreprereqsfalse [main] [ 2019-09-04 10:31:49.454 AST ] [UsmcaLogger.logInfo:156] ACFS driver state script exists true [main] [ 2019-09-04 10:31:49.454 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.util.UsmcaUtil Method : executeCommand [main] [ 2019-09-04 10:31:49.454 AST ] [UsmcaLogger.logInfo:156] Command: /u01/app/12.2.0.1/setup/bin/acfsdriverstate loaded [main] [ 2019-09-04 10:31:49.816 AST ] [UsmcaLogger.logInfo:156] ACFS-9203: true [main] [ 2019-09-04 10:31:49.817 AST ] [UsmcaLogger.logInfo:156] ACFS driver state status code 0 [main] [ 2019-09-04 10:31:49.817 AST ] [UsmcaLogger.logInfo:156] AFD driver state script exists true [main] [ 2019-09-04 10:31:49.817 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.util.UsmcaUtil Method : executeCommand [main] [ 2019-09-04 10:31:49.817 AST ] [UsmcaLogger.logInfo:156] Command: /u01/app/12.2.0.1/setup/bin/afddriverstate loaded [main] [ 2019-09-04 10:31:50.076 AST ] [UsmcaLogger.logInfo:156] AFD-9205: AFD device driver loaded status: 'true' [main] [ 2019-09-04 10:31:50.076 AST ] [UsmcaLogger.logInfo:156] AFD driver state status code 0 [main] [ 2019-09-04 10:31:50.076 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.model.UsmcaModel Method : loadandSetSecEncrInit [main] [ 2019-09-04 10:31:50.076 AST ] [UsmcaLogger.logInfo:156] Security command [main] [ 2019-09-04 10:31:50.076 AST ] [UsmcaLogger.logArrayInfo:207] /sbin/acfsutil sec info -i [main] [ 2019-09-04 10:31:50.253 AST ] [UsmcaLogger.logInfo:156] Security command exit code 1 [main] [ 2019-09-04 10:31:50.254 AST ] [UsmcaLogger.logInfo:156] Encryption command [main] [ 2019-09-04 10:31:50.255 AST ] [UsmcaLogger.logArrayInfo:207] /sbin/acfsutil encr info -i [main] [ 2019-09-04 10:31:50.449 AST ] [UsmcaLogger.logInfo:156] Encryption command exit code 1 [main] [ 2019-09-04 10:31:50.450 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.model.UsmcaModel Method : loadandSetSecEncrInit [main] [ 2019-09-04 10:31:50.450 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.model.UsmcaModel Method : initialize [main] [ 2019-09-04 10:31:50.450 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.model.UsmcaModel Method : performOperation [main] [ 2019-09-04 10:31:50.455 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.model.UsmcaModel Method : performConfigureLocalASM [main] [ 2019-09-04 10:31:50.496 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.backend.USMInstance Method : discoverASMInstance [main] [ 2019-09-04 10:31:50.496 AST ] [UsmcaLogger.logInfo:156] oracle home discovered /u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:50.523 AST ] [OsUtilsBase.deleteFromEnvironment:2261] Removed from env ORACLE_BASE=/u01/app/grid [main] [ 2019-09-04 10:31:50.660 AST ] [InstallUtils.getOraBaseConfigLocation:583] orabaseconfig location from orabaseconfig util /u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:50.681 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.backend.USMInstance Method : findOSAuthentication [main] [ 2019-09-04 10:31:50.681 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.backend.USMInstance Method : createSQLEngine [main] [ 2019-09-04 10:31:50.685 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: null [main] [ 2019-09-04 10:31:50.700 AST ] [InventoryUtil.getOUIInvSession:349] setting OUI READ level to ACCESSLEVEL_READ_LOCKLESS [main] [ 2019-09-04 10:31:50.700 AST ] [OracleHome.getVersion:1037] Homeinfo /u01/app/12.2.0.1/setup,1 [main] [ 2019-09-04 10:31:50.885 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: null [main] [ 2019-09-04 10:31:50.885 AST ] [OracleHome.getVersion:1093] using sqlplus: /u01/app/12.2.0.1/setup/bin/sqlplus [main] [ 2019-09-04 10:31:50.886 AST ] [OracleHome.getVersion:1125] adding oracle home to sqlplus env [main] [ 2019-09-04 10:31:50.886 AST ] [OracleHome.getVersion:1129] LD_LIBRARY_PATH=/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/network/lib:.:/usr/jdk/packages/lib/amd64:/lib/64:/usr/lib/64 [main] [ 2019-09-04 10:31:50.886 AST ] [OracleHome.getVersion:1129] ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:51.028 AST ] [OracleHome.getVersion:1134] /u01/app/12.2.0.1/setup/bin/sqlplus Banner: SQL*Plus: Release 12.2.0.1.0 Production [main] [ 2019-09-04 10:31:51.028 AST ] [OracleHome.getVersion:1152] Current version from sqlplus: 12.2.0.1.0 [main] [ 2019-09-04 10:31:51.028 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: 12.2.0.1.0 [main] [ 2019-09-04 10:31:51.029 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: 12.2.0.1.0 [main] [ 2019-09-04 10:31:51.029 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: 12.2.0.1.0 [main] [ 2019-09-04 10:31:51.030 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: 12.2.0.1.0 [main] [ 2019-09-04 10:31:51.030 AST ] [SQLPlusEngine.getCmmdParams:226] m_home 12.2.0.1.0 [main] [ 2019-09-04 10:31:51.031 AST ] [SQLPlusEngine.getCmmdParams:227] version > 112 true [main] [ 2019-09-04 10:31:51.031 AST ] [SQLEngine.getEnvParams:607] Default NLS_LANG: AMERICAN_AMERICA.AL32UTF8 [main] [ 2019-09-04 10:31:51.031 AST ] [SQLEngine.getEnvParams:617] NLS_LANG: AMERICAN_AMERICA.AL32UTF8 [main] [ 2019-09-04 10:31:51.032 AST ] [SQLEngine.initialize:363] Execing SQLPLUS/SVRMGR process... [main] [ 2019-09-04 10:31:51.063 AST ] [SQLEngine.initialize:400] m_bReaderStarted: false [main] [ 2019-09-04 10:31:51.064 AST ] [SQLEngine.initialize:404] Starting Reader Thread... [main] [ 2019-09-04 10:31:51.064 AST ] [SQLEngine.initialize:453] Waiting for m_bReaderStarted to be true [main] [ 2019-09-04 10:31:51.140 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.backend.USMInstance Method : createSQLEngine [main] [ 2019-09-04 10:31:51.140 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: null [main] [ 2019-09-04 10:31:51.142 AST ] [InventoryUtil.getOUIInvSession:349] setting OUI READ level to ACCESSLEVEL_READ_LOCKLESS [main] [ 2019-09-04 10:31:51.142 AST ] [OracleHome.getVersion:1037] Homeinfo /u01/app/12.2.0.1/setup,1 [main] [ 2019-09-04 10:31:51.249 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: null [main] [ 2019-09-04 10:31:51.250 AST ] [OracleHome.getVersion:1093] using sqlplus: /u01/app/12.2.0.1/setup/bin/sqlplus [main] [ 2019-09-04 10:31:51.250 AST ] [OracleHome.getVersion:1125] adding oracle home to sqlplus env [main] [ 2019-09-04 10:31:51.251 AST ] [OracleHome.getVersion:1129] LD_LIBRARY_PATH=/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/network/lib:.:/usr/jdk/packages/lib/amd64:/lib/64:/usr/lib/64 [main] [ 2019-09-04 10:31:51.251 AST ] [OracleHome.getVersion:1129] ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:51.304 AST ] [OracleHome.getVersion:1134] /u01/app/12.2.0.1/setup/bin/sqlplus Banner: SQL*Plus: Release 12.2.0.1.0 Production [main] [ 2019-09-04 10:31:51.304 AST ] [OracleHome.getVersion:1152] Current version from sqlplus: 12.2.0.1.0 [main] [ 2019-09-04 10:31:52.788 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.backend.USMInstance Method : findOSAuthentication [main] [ 2019-09-04 10:31:52.788 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.backend.USMInstance Method : discoverASMInstance [main] [ 2019-09-04 10:31:52.788 AST ] [UsmcaLogger.logInfo:156] Reuse Diskgroup false [main] [ 2019-09-04 10:31:52.789 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.backend.USMInstance Method : isDiskgroupsExistsForConfigure [main] [ 2019-09-04 10:31:52.789 AST ] [KfodUtil.kfodOutput:375] /u01/app/12.2.0.1/setup/bin/kfod [main] [ 2019-09-04 10:31:52.789 AST ] [KfodUtil.kfodOutput:375] nohdr=TRUE [main] [ 2019-09-04 10:31:52.790 AST ] [KfodUtil.kfodOutput:375] OP=DISKS DISKS=ASM DS=TRUE [main] [ 2019-09-04 10:31:52.790 AST ] [KfodUtil.kfodOutput:375] status=true [main] [ 2019-09-04 10:31:52.790 AST ] [KfodUtil.kfodOutput:375] asm_diskstring='/dev/rdsk/*' [main] [ 2019-09-04 10:31:53.062 AST ] [KfodUtil.kfodOutput:386] Kfod result [main] [ 2019-09-04 10:31:53.063 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.backend.USMInstance Method : isDiskgroupsExistsForConfigure [main] [ 2019-09-04 10:31:53.066 AST ] [ClusterUtil.:87] ClusterUtil Instance created [main] [ 2019-09-04 10:31:53.066 AST ] [ClusterUtil.:90] ClusterUtil m_bSKGXN=true [main] [ 2019-09-04 10:31:53.066 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getClusterName [main] [ 2019-09-04 10:31:53.066 AST ] [has.ClusterUtilNative.Native] prsr_trace: 1. Native: getClusterName: rc:13 sz: 9 [main] [ 2019-09-04 10:31:53.067 AST ] [has.ClusterUtilNative.Native] prsr_trace: 3. Native: getClusterName: rc:0 sz:9 cluname:scan-rac [main] [ 2019-09-04 10:31:53.067 AST ] [ClusterUtil.:87] ClusterUtil Instance created [main] [ 2019-09-04 10:31:53.067 AST ] [ClusterUtil.:90] ClusterUtil m_bSKGXN=true [main] [ 2019-09-04 10:31:53.067 AST ] [ClusterUtil.getCSSMode:717] Returned from native code [main] [ 2019-09-04 10:31:53.067 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getCSSMod [main] [ 2019-09-04 10:31:53.067 AST ] [has.ClusterUtilNative.Native] prsr_trace: mode of css: 1 [main] [ 2019-09-04 10:31:53.067 AST ] [ClusterUtil.getCSSMode:722] Returned from native code [main] [ 2019-09-04 10:31:53.068 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.backend.USMInstance Method : setUpForLocalCreation [main] [ 2019-09-04 10:31:53.068 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.backend.USMInstance Method : setUpForLocalCreation [main] [ 2019-09-04 10:31:53.068 AST ] [UsmcaLogger.logInfo:156] Creating ASM with SID: +ASM1 [main] [ 2019-09-04 10:31:53.068 AST ] [UsmcaLogger.logInfo:156] Creating temp ora file: /u01/app/12.2.0.1/setup/dbs/init+ASM1.ora [main] [ 2019-09-04 10:31:53.229 AST ] [ClusterVerification.getInstance:509] Method Entry [main] [ 2019-09-04 10:31:53.234 AST ] [CVUVariables.initialize:1456] Start parse all variables from variables.xml... [main] [ 2019-09-04 10:31:53.239 AST ] [VerificationUtil.getVariablesXmlURI:10733] ==== XML variables file: file:/u01/app/12.2.0.1/setup/cv/cvdata/variables.xml [main] [ 2019-09-04 10:31:53.239 AST ] [VerificationUtil.getVariablesXmlSchemaURI:10715] ==== XML variables schema file: file:/u01/app/12.2.0.1/setup/cv/cvdata/variables.xsd [main] [ 2019-09-04 10:31:53.239 AST ] [CVUVariables.getRootElement:1721] ==== URIs obtained :xsd URI = file:/u01/app/12.2.0.1/setup/cv/cvdata/variables.xsd [main] [ 2019-09-04 10:31:53.239 AST ] [CVUVariables.getRootElement:1722] ==== URIs obtained :xml URI = file:/u01/app/12.2.0.1/setup/cv/cvdata/variables.xml [main] [ 2019-09-04 10:31:53.240 AST ] [CVUVariables.getRootElement:1735] xsdFile exists : file:/u01/app/12.2.0.1/setup/cv/cvdata/variables.xsd [main] [ 2019-09-04 10:31:53.241 AST ] [CVUVariables.getRootElement:1750] xmlFile exists : file:/u01/app/12.2.0.1/setup/cv/cvdata/variables.xml [main] [ 2019-09-04 10:31:53.241 AST ] [CVUVariables.getRootElement:1763] setting xmlFactory to use xsdFile : file:/u01/app/12.2.0.1/setup/cv/cvdata/variables.xsd [main] [ 2019-09-04 10:31:53.474 AST ] [CVUVariables.getRootElement:1794] The xml variables file: file:/u01/app/12.2.0.1/setup/cv/cvdata/variables.xml, was parsed correctly [main] [ 2019-09-04 10:31:53.480 AST ] [CVUVariables.parse:1521] Version found ALL [main] [ 2019-09-04 10:31:53.480 AST ] [CVUVariables.parse:1524] Process common variables [main] [ 2019-09-04 10:31:53.486 AST ] [CVUVariableData.:98] CVUVariableData created with names: "s_silent,SILENT" [main] [ 2019-09-04 10:31:53.487 AST ] [CVUVariables.parse:1521] Version found 12.2 [main] [ 2019-09-04 10:31:53.488 AST ] [CVUVariables.parse:1529] Process variables for the release: 12.2 [main] [ 2019-09-04 10:31:53.502 AST ] [CVUVariableData.:98] CVUVariableData created with names: "OwnerId,INSTALL_USER,BACKUP_USER,ORACLE_OWNER,LISTENER_USERNAME" [main] [ 2019-09-04 10:31:53.505 AST ] [CVUVariableData.:98] CVUVariableData created with names: "s_usergroup,oracle.install.asm.OSDBA,DBA_GROUP,ORA_DBA_GROUP" [main] [ 2019-09-04 10:31:53.507 AST ] [CVUVariableData.:98] CVUVariableData created with names: "s_racdbagroup,oracle.install.OSRACDBA,RACDBA_GROUP,ORA_RACDBA_GROUP" [main] [ 2019-09-04 10:31:53.508 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_OSASM,oracle.install.asm.OSASM,ASM_GROUP,ORA_ASM_GROUP" [main] [ 2019-09-04 10:31:53.516 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.asm.OSOPER,OPER_GROUP" [main] [ 2019-09-04 10:31:53.518 AST ] [CVUVariableData.:98] CVUVariableData created with names: "s_languageid,LANGUAGE_ID" [main] [ 2019-09-04 10:31:53.521 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_Timezone,TZ" [main] [ 2019-09-04 10:31:53.523 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_isRolling,ISROLLING,ISROLLING" [main] [ 2019-09-04 10:31:53.524 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_asm_UseExistingDG,oracle.install.asm.useExistingDiskGroup,ASM_DISKGROUP_REUSE_OPTION,REUSEDG" [main] [ 2019-09-04 10:31:53.524 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_asm_DisGroupAUSize,oracle.install.asm.diskGroup.AUSize,ASM_AU_SIZE,CDATA_AUSIZE" [main] [ 2019-09-04 10:31:53.540 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_cres_prereq_Ignored,ORA_IGNORE_CVU_ERRORS,USER_IGNORED_PREREQ" [main] [ 2019-09-04 10:31:53.541 AST ] [CVUVariableData.:98] CVUVariableData created with names: "ORACLE_HOSTNAME,ORACLE_HOSTNAME,INSTALL_NODE,INSTALL_NODE" [main] [ 2019-09-04 10:31:53.541 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_ConfigureMgmtDB,MGMT_DB" [main] [ 2019-09-04 10:31:53.542 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.config.managementOption" [main] [ 2019-09-04 10:31:53.543 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_IsBigCluster,BIGCLUSTER,BIG_CLUSTER" [main] [ 2019-09-04 10:31:53.543 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_TargetHubSize,TARGET_HUB_SIZE,HUB_SIZE" [main] [ 2019-09-04 10:31:53.544 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_HUBNodesList,HUB_LIST,HUB_NODE_LIST" [main] [ 2019-09-04 10:31:53.545 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_RIMNodesList,RIM_LIST,RIM_NODE_LIST" [main] [ 2019-09-04 10:31:53.545 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_HUBVipList,HUB_NODE_VIPS" [main] [ 2019-09-04 10:31:53.546 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_Ping_Targets,PING_TARGETS,PING_TARGETS" [main] [ 2019-09-04 10:31:53.546 AST ] [CVUVariableData.:98] CVUVariableData created with names: "ORACLE_HOME,ORACLE_HOME,ORACLE_HOME,ORACLE_HOME,GPNPCONFIGDIR,GPNPGCONFIGDIR,CRFHOME" [main] [ 2019-09-04 10:31:53.546 AST ] [CVUVariableData.:98] CVUVariableData created with names: "ORACLE_BASE,ORACLE_BASE,ORACLE_BASE,ORACLE_BASE" [main] [ 2019-09-04 10:31:53.546 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_configuredCRSHome,CONFIGURED_CRS_HOME,OLD_CRS_HOME" [main] [ 2019-09-04 10:31:53.547 AST ] [CVUVariableData.:98] CVUVariableData created with names: "s_jreLocation,JREDIR" [main] [ 2019-09-04 10:31:53.548 AST ] [CVUVariableData.:98] CVUVariableData created with names: "s_jlibDir,JLIBDIR" [main] [ 2019-09-04 10:31:53.549 AST ] [CVUVariableData.:98] CVUVariableData created with names: "s_cluster,VNDR_CLUSTER" [main] [ 2019-09-04 10:31:53.549 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_OCRDeviceList,oracle.install.crs.config.sharedFileSystemStorage.ocrLocations,OCR_LOCATIONS,OCR_LOCATIONS" [main] [ 2019-09-04 10:31:53.549 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_ClusterName,oracle.install.crs.config.clusterName,CLUSTER_NAME,CLUSTER_NAME" [main] [ 2019-09-04 10:31:53.550 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.clusterNodes,RSP_CLUSTER_NODES" [main] [ 2019-09-04 10:31:53.562 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_CommaSeparatedNodes,NODE_LIST,NODE_NAME_LIST,HOST_NAME_LIST,NODELIST" [main] [ 2019-09-04 10:31:53.562 AST ] [CVUVariableData.:98] CVUVariableData created with names: "s_privatenamelist,PRIVATE_NAME_LIST" [main] [ 2019-09-04 10:31:53.562 AST ] [CVUVariableData.:98] CVUVariableData created with names: "QUORUM_DISKS,QUORUM_DISKS,QUORUM_DISKS" [main] [ 2019-09-04 10:31:53.563 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_VotingDiskList,oracle.install.crs.config.sharedFileSystemStorage.VotingDiskLocations,VOTING_LOCATIONS,VOTING_DISKS" [main] [ 2019-09-04 10:31:53.563 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_asm_DiskGroupName,oracle.install.asm.diskGroup.name,ASM_DISKGROUP,CDATA_DISK_GROUP" [main] [ 2019-09-04 10:31:53.563 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_asm_DiskDiscoveryString,oracle.install.asm.diskGroup.diskDiscoveryString,ASM_DISK_DISCOVERY_STRING,ASM_DISCOVERY_STRING" [main] [ 2019-09-04 10:31:53.563 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_asm_Disks,oracle.install.asm.diskGroup.disks,ASM_DISKGROUP_DISKS,CDATA_DISKS" [main] [ 2019-09-04 10:31:53.564 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_asm_DiskGroupRedundancy,oracle.install.asm.diskGroup.redundancy,CDATA_REDUNDANCY" [main] [ 2019-09-04 10:31:53.564 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_asm_FailureGroups,oracle.install.asm.diskGroup.FailureGroups,ASM_DISKGROUP_FAILUREGROUPS,CDATA_FAILURE_GROUPS" [main] [ 2019-09-04 10:31:53.565 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.asm.diskGroup.disksWithFailureGroupNames,ASM_DISKGROUP_DISKSWITHFAILUREGROUPNAMES" [main] [ 2019-09-04 10:31:53.565 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_asm_ConfigurationType,ASM_CONFIG" [main] [ 2019-09-04 10:31:53.567 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_asm_ClientDataFile,oracle.install.asm.ClientDataFile,ASM_CLIENTDATA,ASM_CREDENTIALS" [main] [ 2019-09-04 10:31:53.569 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_StorageOption,CRS_STORAGE_OPTION" [main] [ 2019-09-04 10:31:53.570 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.storageOption,RSP_STORAGE_OPT" [main] [ 2019-09-04 10:31:53.570 AST ] [CVUVariableData.:98] CVUVariableData created with names: "CSS_LEASEDURATION" [main] [ 2019-09-04 10:31:53.572 AST ] [CVUVariableData.:98] CVUVariableData created with names: "HOST_VIP_NAMES" [main] [ 2019-09-04 10:31:53.573 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_NodeVips,CFG_CRS_NODEVIPS,CRS_NODEVIPS,NEW_NODEVIPS" [main] [ 2019-09-04 10:31:53.575 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_FinalInterfaceList,CFG_NETWORKS,NETWORKS" [main] [ 2019-09-04 10:31:53.582 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.networkInterfaceList,RSP_NETWORK_IFLIST" [main] [ 2019-09-04 10:31:53.582 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_SCANName,oracle.install.crs.config.gpnp.scanName,SCAN_NAME,SCAN_NAME" [main] [ 2019-09-04 10:31:53.583 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_SCANPortNumber,oracle.install.crs.config.gpnp.scanPort,SCAN_PORT,SCAN_PORT" [main] [ 2019-09-04 10:31:53.583 AST ] [CVUVariableData.:98] CVUVariableData created with names: "s_paLocation,GPNP_PA" [main] [ 2019-09-04 10:31:53.585 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_ConfigureGNS,oracle.install.crs.config.gpnp.configureGNS,CONFIGURE_GNS,GNS_CONF" [main] [ 2019-09-04 10:31:53.585 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_GNSType,GNS_TYPE" [main] [ 2019-09-04 10:31:53.588 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.gpnp.gnsOption,RSP_GNS_OPT" [main] [ 2019-09-04 10:31:53.588 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_GNSVIPAddress,oracle.install.crs.config.gpnp.gnsVIPAddress,GNS_VIP_ADDRESS,GNS_ADDR_LIST" [main] [ 2019-09-04 10:31:53.589 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_GNSSubDomain,oracle.install.crs.config.gpnp.gnsSubDomain,GNS_SUB_DOMAIN,GNS_DOMAIN_LIST" [main] [ 2019-09-04 10:31:53.590 AST ] [CVUVariableData.:98] CVUVariableData created with names: "sl_allowDomainList,GNS_ALLOW_NET_LIST" [main] [ 2019-09-04 10:31:53.591 AST ] [CVUVariableData.:98] CVUVariableData created with names: "sl_denyDomainList,GNS_DENY_NET_LIST" [main] [ 2019-09-04 10:31:53.591 AST ] [CVUVariableData.:98] CVUVariableData created with names: "sl_denyInterfaceList,GNS_DENY_ITF_LIST" [main] [ 2019-09-04 10:31:53.592 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_GNSClientDataFile,oracle.install.crs.config.gpnp.gnsClientDataFile,GNS_CLIENT_DATA_FILE,GNS_CREDENTIALS" [main] [ 2019-09-04 10:31:53.592 AST ] [CVUVariableData.:98] CVUVariableData created with names: "slHostNames,NEW_HOST_NAME_LIST" [main] [ 2019-09-04 10:31:53.593 AST ] [CVUVariableData.:98] CVUVariableData created with names: "slNewNodes,NEW_NODE_NAME_LIST" [main] [ 2019-09-04 10:31:53.597 AST ] [CVUVariableData.:98] CVUVariableData created with names: "slPrivateNodes,NEW_PRIVATE_NAME_LIST" [main] [ 2019-09-04 10:31:53.599 AST ] [CVUVariableData.:98] CVUVariableData created with names: "OCRLOC" [main] [ 2019-09-04 10:31:53.601 AST ] [CVUVariableData.:98] CVUVariableData created with names: "OLRLOC" [main] [ 2019-09-04 10:31:53.602 AST ] [CVUVariableData.:98] CVUVariableData created with names: "OCRID" [main] [ 2019-09-04 10:31:53.603 AST ] [CVUVariableData.:98] CVUVariableData created with names: "CLUSTER_GUID" [main] [ 2019-09-04 10:31:53.604 AST ] [CVUVariableData.:98] CVUVariableData created with names: "CLSCFG_MISSCOUNT" [main] [ 2019-09-04 10:31:53.604 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.responseFileVersion" [main] [ 2019-09-04 10:31:53.605 AST ] [CVUVariableData.:98] CVUVariableData created with names: "INVENTORY_LOCATION" [main] [ 2019-09-04 10:31:53.606 AST ] [CVUVariableData.:98] CVUVariableData created with names: "SELECTED_LANGUAGES" [main] [ 2019-09-04 10:31:53.607 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.option,INSTALL_OPTION" [main] [ 2019-09-04 10:31:53.608 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.asm.SYSASMPassword" [main] [ 2019-09-04 10:31:53.608 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.asm.monitorPassword" [main] [ 2019-09-04 10:31:53.609 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.ClusterConfiguration,RSP_CLUSTERTYPE_OPT" [main] [ 2019-09-04 10:31:53.609 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.configureAsExtendedCluster,EXTENDED_CLUSTER,EXTENDED_CLUSTER" [main] [ 2019-09-04 10:31:53.610 AST ] [CVUVariableData.:98] CVUVariableData created with names: "CLUSTER_TYPE" [main] [ 2019-09-04 10:31:53.610 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.autoConfigureClusterNodeVIP,AUTO_CONFIGURE_CLUSTER_NODE_VIP" [main] [ 2019-09-04 10:31:53.611 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.sharedFileSystemStorage.votingDiskRedundancy" [main] [ 2019-09-04 10:31:53.612 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.sharedFileSystemStorage.ocrRedundancy" [main] [ 2019-09-04 10:31:53.612 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.useIPMI,USE_IPMI" [main] [ 2019-09-04 10:31:53.613 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.ipmi.bmcUsername" [main] [ 2019-09-04 10:31:53.615 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.ipmi.bmcPassword" [main] [ 2019-09-04 10:31:53.616 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.config.ignoreDownNodes" [main] [ 2019-09-04 10:31:53.617 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.installer.autoupdates.option" [main] [ 2019-09-04 10:31:53.618 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.installer.autoupdates.downloadUpdatesLoc" [main] [ 2019-09-04 10:31:53.618 AST ] [CVUVariableData.:98] CVUVariableData created with names: "AUTOUPDATES_MYORACLESUPPORT_USERNAME" [main] [ 2019-09-04 10:31:53.619 AST ] [CVUVariableData.:98] CVUVariableData created with names: "AUTOUPDATES_MYORACLESUPPORT_PASSWORD" [main] [ 2019-09-04 10:31:53.620 AST ] [CVUVariableData.:98] CVUVariableData created with names: "PROXY_HOST" [main] [ 2019-09-04 10:31:53.721 AST ] [CVUVariableData.:98] CVUVariableData created with names: "PROXY_PORT" [main] [ 2019-09-04 10:31:53.721 AST ] [CVUVariableData.:98] CVUVariableData created with names: "PROXY_USER" [main] [ 2019-09-04 10:31:53.722 AST ] [CVUVariableData.:98] CVUVariableData created with names: "PROXY_PWD" [main] [ 2019-09-04 10:31:53.723 AST ] [CVUVariableData.:98] CVUVariableData created with names: "PROXY_REALM" [main] [ 2019-09-04 10:31:53.724 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.config.omsHost" [main] [ 2019-09-04 10:31:53.726 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.config.omsPort" [main] [ 2019-09-04 10:31:53.727 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.config.emAdminUser" [main] [ 2019-09-04 10:31:53.727 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.config.emAdminPassword" [main] [ 2019-09-04 10:31:53.728 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_crs_app_VIPAddress,oracle.install.crs.app.applicationAddress,APPLICATION_VIP" [main] [ 2019-09-04 10:31:53.728 AST ] [CVUVariableData.:98] CVUVariableData created with names: "POST_SW_INSTALL_API_MODE,POST_SW_INSTALL_API_MODE" [main] [ 2019-09-04 10:31:53.729 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.crs.configureAFD,CONFIGURE_AFD" [main] [ 2019-09-04 10:31:53.730 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_OracleHomeUserName,oracle.install.OracleHomeUserName,WINSEC_SERVICE_USERNAME" [main] [ 2019-09-04 10:31:53.730 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_OracleHomeUserPassword,oracle.install.OracleHomeUserPassword,WINSEC_SERVICE_PASSWORD" [main] [ 2019-09-04 10:31:53.730 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle_install_IsBuiltInAccount,oracle.install.IsBuiltInAccount" [main] [ 2019-09-04 10:31:53.731 AST ] [CVUVariableData.:98] CVUVariableData created with names: "oracle.install.IsVirtualAccount,oracle_install_IsVirtualAccount" [main] [ 2019-09-04 10:31:53.731 AST ] [CVUVariables.setReleaseForVariablesXml:257] Initialize CVUVariables for release : 12.2 [main] [ 2019-09-04 10:31:53.731 AST ] [CVUVariables.setValue:329] CVUVarConstant : MODE_API [main] [ 2019-09-04 10:31:53.731 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:53.732 AST ] [CVUVariableData.:98] CVUVariableData created with names: "MODE_API" [main] [ 2019-09-04 10:31:53.732 AST ] [CVUVariables.secureVariableValueTrace:715] setting CVUVariableConstant : VAR = MODE_API VAL = TRUE [main] [ 2019-09-04 10:31:53.732 AST ] [CVUVariables.setValue:329] CVUVarConstant : MODE_CLI [main] [ 2019-09-04 10:31:53.732 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:53.732 AST ] [CVUVariableData.:98] CVUVariableData created with names: "MODE_CLI" [main] [ 2019-09-04 10:31:53.733 AST ] [CVUVariables.secureVariableValueTrace:715] setting CVUVariableConstant : VAR = MODE_CLI VAL = FALSE [main] [ 2019-09-04 10:31:53.733 AST ] [ParamManager.:390] m_paramInstantiated set to TRUE [main] [ 2019-09-04 10:31:53.733 AST ] [VerificationUtil.getLocalHost:1601] Hostname retrieved: racnode1.testdomain.com, returned: racnode1 [main] [ 2019-09-04 10:31:53.734 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = MODE_API VAL = TRUE [main] [ 2019-09-04 10:31:53.735 AST ] [Version.isPre:678] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-09-04 10:31:53.735 AST ] [Version.isPre:689] isPre.java: Returning FALSE [main] [ 2019-09-04 10:31:53.735 AST ] [Version.isPre:678] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-09-04 10:31:53.735 AST ] [Version.isPre:689] isPre.java: Returning FALSE [main] [ 2019-09-04 10:31:53.735 AST ] [UnixSystem.isCRSConfigured:3536] configFile=/var/opt/oracle/ocr.loc [main] [ 2019-09-04 10:31:53.736 AST ] [Utils.getPropertyValue:371] propName=ocrconfig_loc propValue=+OCR [main] [ 2019-09-04 10:31:53.736 AST ] [UnixSystem.isCRSConfigured:3543] ocrconfig_loc=+OCR [main] [ 2019-09-04 10:31:53.737 AST ] [Utils.getPropertyValue:371] propName=local_only propValue=FALSE [main] [ 2019-09-04 10:31:53.737 AST ] [VerificationUtil.isCRSConfigured:5155] crsConfigured=true [main] [ 2019-09-04 10:31:53.737 AST ] [VerificationUtil.getCRSHome:4778] Executing getCRSHome() [main] [ 2019-09-04 10:31:53.737 AST ] [VerificationUtil.getCRSHome:4792] Checking Configured CRS Home on local node [main] [ 2019-09-04 10:31:53.738 AST ] [VerificationUtil.getCRSHome:2602] Executing getCRSHome(node=racnode1, result) [main] [ 2019-09-04 10:31:53.739 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = MODE_API VAL = TRUE [main] [ 2019-09-04 10:31:53.740 AST ] [Version.isPre:678] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-09-04 10:31:53.741 AST ] [Version.isPre:689] isPre.java: Returning FALSE [main] [ 2019-09-04 10:31:53.741 AST ] [Version.isPre:678] version to be checked 12.2.0.1.0 major version to check against 10 [main] [ 2019-09-04 10:31:53.741 AST ] [Version.isPre:689] isPre.java: Returning FALSE [main] [ 2019-09-04 10:31:53.741 AST ] [UnixSystem.isCRSConfigured:3536] configFile=/var/opt/oracle/ocr.loc [main] [ 2019-09-04 10:31:53.742 AST ] [Utils.getPropertyValue:371] propName=ocrconfig_loc propValue=+OCR [main] [ 2019-09-04 10:31:53.742 AST ] [UnixSystem.isCRSConfigured:3543] ocrconfig_loc=+OCR [main] [ 2019-09-04 10:31:53.742 AST ] [Utils.getPropertyValue:371] propName=local_only propValue=FALSE [main] [ 2019-09-04 10:31:53.742 AST ] [VerificationUtil.isCRSConfigured:5155] crsConfigured=true [main] [ 2019-09-04 10:31:53.742 AST ] [Utils.getLocalHost:478] Hostname retrieved: racnode1.testdomain.com, returned: racnode1 [main] [ 2019-09-04 10:31:53.742 AST ] [UnixSystem.getCRSHome:3676] olrFileName = /var/opt/oracle/olr.loc [main] [ 2019-09-04 10:31:53.744 AST ] [UnixSystem.getCRSHome:3720] configFile=/var/opt/oracle/olr.loc [main] [ 2019-09-04 10:31:53.744 AST ] [Utils.getPropertyValue:311] keyName=olrconfig_loc props.val=/u01/app/12.2.0.1/setup/cdata/racnode1.olr propValue=/u01/app/12.2.0.1/setup/cdata/racnode1.olr [main] [ 2019-09-04 10:31:53.744 AST ] [Utils.getPropertyValue:311] keyName=crs_home props.val=/u01/app/12.2.0.1/setup propValue=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:53.745 AST ] [Utils.getPropertyValue:371] propName=crs_home propValue=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:53.745 AST ] [UnixSystem.getCRSHome:3728] crs_home=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:53.745 AST ] [VerificationUtil.getCRSHome:2633] Returning CRS home '/u01/app/12.2.0.1/setup' from olr.loc [main] [ 2019-09-04 10:31:53.745 AST ] [VerificationUtil.getCRSHome:4796] CONFIGURED_CRS_HOME is correctly resolved, save it [main] [ 2019-09-04 10:31:53.745 AST ] [CVUVariables.setValue:329] CVUVarConstant : CONFIGURED_CRS_HOME [main] [ 2019-09-04 10:31:53.745 AST ] [CVUVariables.secureVariableValueTrace:715] setting CVUVariableConstant : VAR = CONFIGURED_CRS_HOME VAL = /u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:53.745 AST ] [VerificationUtil.getCRSHome:4801] Returning Configured CRS home as '/u01/app/12.2.0.1/setup' [main] [ 2019-09-04 10:31:53.745 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:53.746 AST ] [VerificationUtil.getExecutionEnvironment:9140] RDBMS Version is -->12.2.0.1.0 [main] [ 2019-09-04 10:31:53.751 AST ] [ConfigUtil.importConfig:97] ==== CVU config file: /u01/app/12.2.0.1/setup/cv/admin/cvu_config [main] [ 2019-09-04 10:31:53.759 AST ] [ConfigUtil.importConfig:114] ==== Picked up config variable: cv_raw_check_enabled : TRUE [main] [ 2019-09-04 10:31:53.759 AST ] [ConfigUtil.importConfig:114] ==== Picked up config variable: cv_sudo_binary_location : /usr/local/bin/sudo [main] [ 2019-09-04 10:31:53.759 AST ] [ConfigUtil.importConfig:114] ==== Picked up config variable: cv_pbrun_binary_location : /usr/local/bin/pbrun [main] [ 2019-09-04 10:31:53.761 AST ] [ConfigUtil.importConfig:114] ==== Picked up config variable: cv_assume_cl_version : 12.1 [main] [ 2019-09-04 10:31:53.761 AST ] [ConfigUtil.isDefined:200] ==== Is ORACLE_SRVM_REMOTESHELL defined? : false [main] [ 2019-09-04 10:31:53.761 AST ] [Library.load:202] library.load [main] [ 2019-09-04 10:31:53.761 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-09-04 10:31:53.761 AST ] [sPlatform.isHybrid:69] osName=SunOS osArch=amd64 JVM=64 rc=false [main] [ 2019-09-04 10:31:53.761 AST ] [Library.load:290] Loading library /u01/app/12.2.0.1/setup/lib/libsrvm12.so [main] [ 2019-09-04 10:31:53.763 AST ] [nativesystem.Native.Native] Native_getEnvironment: envName=ORACLE_SRVM_REMOTESHELL [main] [ 2019-09-04 10:31:53.763 AST ] [nativesystem.Native.Native] Native_getEnvironment: envValue= [main] [ 2019-09-04 10:31:53.763 AST ] [ConfigUtil.getConfiguredValue:182] ==== Fallback to env var 'ORACLE_SRVM_REMOTESHELL'=null [main] [ 2019-09-04 10:31:53.764 AST ] [ConfigUtil.isDefined:200] ==== Is ORACLE_SRVM_REMOTECOPY defined? : false [main] [ 2019-09-04 10:31:53.764 AST ] [nativesystem.Native.Native] Native_getEnvironment: envName=ORACLE_SRVM_REMOTECOPY [main] [ 2019-09-04 10:31:53.764 AST ] [nativesystem.Native.Native] Native_getEnvironment: envValue= [main] [ 2019-09-04 10:31:53.764 AST ] [ConfigUtil.getConfiguredValue:182] ==== Fallback to env var 'ORACLE_SRVM_REMOTECOPY'=null [main] [ 2019-09-04 10:31:53.764 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:53.766 AST ] [sVerificationUtil.resolve:803] condition variable SSH_ONLY not handled [main] [ 2019-09-04 10:31:53.766 AST ] [CVUVariables.setValue:329] CVUVarConstant : SSH_ONLY [main] [ 2019-09-04 10:31:53.766 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:53.766 AST ] [CVUVariables.setValue:357] Unable to set value for variable : SSH_ONLY [main] [ 2019-09-04 10:31:53.767 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = SSH_ONLY VAL = null [main] [ 2019-09-04 10:31:53.767 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:53.767 AST ] [sVerificationUtil.resolve:803] condition variable CVU_CHECK_AGAIN not handled [main] [ 2019-09-04 10:31:53.767 AST ] [CVUVariables.setValue:329] CVUVarConstant : CVU_CHECK_AGAIN [main] [ 2019-09-04 10:31:53.768 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:53.768 AST ] [CVUVariables.setValue:357] Unable to set value for variable : CVU_CHECK_AGAIN [main] [ 2019-09-04 10:31:53.768 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = CVU_CHECK_AGAIN VAL = null [main] [ 2019-09-04 10:31:53.769 AST ] [ClusterVerification.checkFrameworkSetup:7990] Method Entry. nodeList=racnode1 [main] [ 2019-09-04 10:31:53.769 AST ] [ClusterVerification.checkFrameworkSetup:8021] creating NodeManager [main] [ 2019-09-04 10:31:53.770 AST ] [sVerificationUtil.resolve:803] condition variable INSTALL_OPTION not handled [main] [ 2019-09-04 10:31:53.770 AST ] [CVUVariables.resolve:752] Resolution failed, cached value is left untouched for variable : INSTALL_OPTION [main] [ 2019-09-04 10:31:53.770 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = INSTALL_OPTION VAL = null [main] [ 2019-09-04 10:31:53.770 AST ] [NodeManagerFactory.getNodeManager:155] creating new NodeManager [main] [ 2019-09-04 10:31:53.773 AST ] [sVerificationUtil.resolve:803] condition variable INSTALL_OPTION not handled [main] [ 2019-09-04 10:31:53.773 AST ] [CVUVariables.resolve:752] Resolution failed, cached value is left untouched for variable : INSTALL_OPTION [main] [ 2019-09-04 10:31:53.774 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = INSTALL_OPTION VAL = null [main] [ 2019-09-04 10:31:53.774 AST ] [sVerificationUtil.resolve:803] condition variable INSTALL_OPTION not handled [main] [ 2019-09-04 10:31:53.774 AST ] [CVUVariables.resolve:752] Resolution failed, cached value is left untouched for variable : INSTALL_OPTION [main] [ 2019-09-04 10:31:53.775 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = INSTALL_OPTION VAL = null [main] [ 2019-09-04 10:31:53.775 AST ] [nativesystem.Native.Native] Native_getEnvironment: envName=ORA_CRS_HOME [main] [ 2019-09-04 10:31:53.775 AST ] [nativesystem.Native.Native] Native_getEnvironment: envValue= [main] [ 2019-09-04 10:31:53.775 AST ] [nativesystem.Native.Native] Native_getEnvironment: envName=CVU_TEST_ENV [main] [ 2019-09-04 10:31:53.775 AST ] [nativesystem.Native.Native] Native_getEnvironment: envValue= [main] [ 2019-09-04 10:31:53.777 AST ] [VerificationUtil.traceAndLogInternal:15777] [ClusterVerification.verifyFrameworkSetup:8449] Input nodelist: racnode1 [main] [ 2019-09-04 10:31:53.777 AST ] [VerificationUtil.traceAndLogInternal:15777] [ClusterVerification.verifyFrameworkSetup:8449] Framework setup cache is empty..perform setup check on all the nodes [main] [ 2019-09-04 10:31:53.777 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:53.778 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:53.778 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:53.778 AST ] [VerificationUtil.checkDestLoc:6247] destloc is--->/var/tmp/ [main] [ 2019-09-04 10:31:53.778 AST ] [VerificationUtil.checkDestLoc:6248] subDirPath is--->/var/tmp/CVU_12.2.0.1.0_grid/ [main] [ 2019-09-04 10:31:53.778 AST ] [VerificationUtil.traceAndLogInternal:15777] [ClusterVerification.verifyFrameworkSetup:8449] Input nodelist: racnode1 [main] [ 2019-09-04 10:31:53.778 AST ] [VerificationUtil.traceAndLogInternal:15777] [ClusterVerification.verifyFrameworkSetup:8449] Framework setup cache is empty..perform setup check on all the nodes [main] [ 2019-09-04 10:31:53.778 AST ] [VerificationUtil.traceAndLogInternal:15777] [ClusterVerification.verifyFrameworkSetup:8449] Creating directory /var/tmp/ [main] [ 2019-09-04 10:31:53.783 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-09-04 10:31:53.786 AST ] [GetActiveNodes.create:220] Going into GetActiveNodes constructor... [main] [ 2019-09-04 10:31:53.786 AST ] [ClusterUtil.:87] ClusterUtil Instance created [main] [ 2019-09-04 10:31:53.786 AST ] [ClusterUtil.:90] ClusterUtil m_bSKGXN=true [main] [ 2019-09-04 10:31:53.786 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getLocalNodeName [main] [ 2019-09-04 10:31:53.786 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getLocalNodeName:nodenumber: 1 [main] [ 2019-09-04 10:31:53.788 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getLocalNodeName:nodename: racnode1 [main] [ 2019-09-04 10:31:53.788 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeNames [main] [ 2019-09-04 10:31:53.789 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeNames:number of nodes: 1 [main] [ 2019-09-04 10:31:53.790 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeNames:node 1 is alive k = 0 [main] [ 2019-09-04 10:31:53.791 AST ] [has.ClusterUtilNative.Native] prsr_trace: Native: getNodeNames:1 nodename: racnode1 [main] [ 2019-09-04 10:31:53.791 AST ] [GetActiveNodes.:192] Inside GetActiveNodes :racnode1 [main] [ 2019-09-04 10:31:53.792 AST ] [GetActiveNodes.:204] Started clusterware daemon thread [main] [ 2019-09-04 10:31:53.792 AST ] [GetActiveNodes.create:222] Out of GetActiveNodes constructor. [main] [ 2019-09-04 10:31:53.792 AST ] [ClusterConfig.:240] ClusterConfig:Number of workers = 0 [main] [ 2019-09-04 10:31:53.794 AST ] [ClusterConfig.createWorkers:325] Started worker threads count=4 [main] [ 2019-09-04 10:31:53.794 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-09-04 10:31:53.794 AST ] [GetActiveNodes.create:226] Returning an existing instance of GetActiveNodes [main] [ 2019-09-04 10:31:53.794 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-09-04 10:31:53.795 AST ] [ClusterConfig.createDirInNode:1940] Creating dir in nodes: racnode1, /var/tmp/CVU_12.2.0.1.0_grid/, true, null [main] [ 2019-09-04 10:31:53.795 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=4 [main] [ 2019-09-04 10:31:53.795 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-09-04 10:31:53.795 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-09-04 10:31:53.795 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [GetActiveNodesThread] [ 2019-09-04 10:31:53.796 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread GetActiveNodesThread m_count=0 [Worker 0] [ 2019-09-04 10:31:53.796 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=1 [Worker 3] [ 2019-09-04 10:31:53.806 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 3 m_count=0 [Worker 2] [ 2019-09-04 10:31:53.806 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [Worker 1] [ 2019-09-04 10:31:53.806 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=0 [Worker 0] [ 2019-09-04 10:31:53.806 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 0 m_count=4 [Worker 0] [ 2019-09-04 10:31:53.807 AST ] [DirCreateCommand.execute:70] In DirCreateCommand.execute, recurseFlag=false, modeFlag=true [Worker 0] [ 2019-09-04 10:31:53.813 AST ] [RuntimeExec.runCommand:259] runCommand: input length=1 [Worker 0] [ 2019-09-04 10:31:53.813 AST ] [RuntimeExec.runCommand:268] runCommand: closed input for process [Worker 0] [ 2019-09-04 10:31:53.813 AST ] [RuntimeExec.runCommand:274] runCommand: submitted input [Worker 0] [ 2019-09-04 10:31:53.814 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Thread-41] [ 2019-09-04 10:31:53.814 AST ] [StreamReader.run:62] In StreamReader.run [Thread-40] [ 2019-09-04 10:31:53.815 AST ] [StreamReader.run:62] In StreamReader.run [Thread-40] [ 2019-09-04 10:31:53.864 AST ] [StreamReader.run:66] OUTPUT>u=rwx,g=rx,o= [Worker 0] [ 2019-09-04 10:31:53.866 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Worker 0] [ 2019-09-04 10:31:53.866 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 0] [ 2019-09-04 10:31:53.866 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 0] [ 2019-09-04 10:31:53.866 AST ] [Utils.getLocalHost:478] Hostname retrieved: racnode1.testdomain.com, returned: racnode1 [Worker 0] [ 2019-09-04 10:31:53.869 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Worker 0] [ 2019-09-04 10:31:53.869 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Thread-43] [ 2019-09-04 10:31:53.869 AST ] [StreamReader.run:62] In StreamReader.run [Thread-42] [ 2019-09-04 10:31:53.870 AST ] [StreamReader.run:62] In StreamReader.run [Worker 0] [ 2019-09-04 10:31:53.870 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 0] [ 2019-09-04 10:31:53.871 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 0] [ 2019-09-04 10:31:53.872 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/mkdir -p -m u=rwx,g=rx,o= /var/tmp/CVU_12.2.0.1.0_grid/] [Worker 0] [ 2019-09-04 10:31:53.872 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned false [Worker 0] [ 2019-09-04 10:31:53.872 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 0] [ 2019-09-04 10:31:53.872 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 0] [ 2019-09-04 10:31:53.872 AST ] [NativeResult.:101] The status string is: 1 [Worker 0] [ 2019-09-04 10:31:53.872 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 0] [ 2019-09-04 10:31:53.872 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 0] [ 2019-09-04 10:31:53.873 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 0 m_count=50 [Worker 0] [ 2019-09-04 10:31:53.873 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-09-04 10:31:53.873 AST ] [ClientResource.getListener:157] Calling getListener [Worker 0] [ 2019-09-04 10:31:53.873 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 0] [ 2019-09-04 10:31:53.873 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 0] [ 2019-09-04 10:31:53.874 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-09-04 10:31:53.874 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 0 [Worker 0] [ 2019-09-04 10:31:53.874 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [main] [ 2019-09-04 10:31:53.874 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-09-04 10:31:53.874 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-09-04 10:31:53.874 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:53.874 AST ] [VerificationUtil.pathExists:6135] nodeList: 'racnode1' path: '/var/tmp/' pathType: '4' isLocalNodeOperation(): 'true' [main] [ 2019-09-04 10:31:53.874 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:53.875 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-09-04 10:31:53.875 AST ] [GetActiveNodes.create:226] Returning an existing instance of GetActiveNodes [main] [ 2019-09-04 10:31:53.876 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-09-04 10:31:53.876 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-09-04 10:31:53.876 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=4 [main] [ 2019-09-04 10:31:53.876 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-09-04 10:31:53.876 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-09-04 10:31:53.876 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-09-04 10:31:53.876 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 3] [ 2019-09-04 10:31:53.876 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 3 m_count=4 [Worker 3] [ 2019-09-04 10:31:53.876 AST ] [PathExistCommand.execute:82] Checking path: '/var/tmp' on node: 'localnode' [Worker 3] [ 2019-09-04 10:31:53.876 AST ] [PathExistCommand.execute:89] NativeSystem status returned: 'true' [Worker 3] [ 2019-09-04 10:31:53.876 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 3] [ 2019-09-04 10:31:53.876 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 3 m_count=50 [Worker 3] [ 2019-09-04 10:31:53.876 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-09-04 10:31:53.877 AST ] [ClientResource.getListener:157] Calling getListener [Worker 3] [ 2019-09-04 10:31:53.877 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 3] [ 2019-09-04 10:31:53.877 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 3] [ 2019-09-04 10:31:53.877 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-09-04 10:31:53.877 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 3 [Worker 3] [ 2019-09-04 10:31:53.877 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 3 m_count=0 [main] [ 2019-09-04 10:31:53.877 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-09-04 10:31:53.877 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-09-04 10:31:53.877 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-09-04 10:31:53.877 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-09-04 10:31:53.877 AST ] [VerificationUtil.pathExists:6204] returning success [main] [ 2019-09-04 10:31:53.877 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:53.877 AST ] [VerificationUtil.pathExists:6135] nodeList: 'racnode1' path: '/var/tmp/CVU_12.2.0.1.0_grid/' pathType: '4' isLocalNodeOperation(): 'true' [main] [ 2019-09-04 10:31:53.877 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:53.878 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-09-04 10:31:53.878 AST ] [GetActiveNodes.create:226] Returning an existing instance of GetActiveNodes [main] [ 2019-09-04 10:31:53.878 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-09-04 10:31:53.878 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-09-04 10:31:53.878 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=4 [main] [ 2019-09-04 10:31:53.878 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [main] [ 2019-09-04 10:31:53.878 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-09-04 10:31:53.878 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-09-04 10:31:53.878 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=0 [Worker 2] [ 2019-09-04 10:31:53.878 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 2 m_count=4 [Worker 2] [ 2019-09-04 10:31:53.878 AST ] [PathExistCommand.execute:82] Checking path: '/var/tmp/CVU_12.2.0.1.0_grid' on node: 'localnode' [Worker 2] [ 2019-09-04 10:31:53.878 AST ] [PathExistCommand.execute:89] NativeSystem status returned: 'true' [Worker 2] [ 2019-09-04 10:31:53.878 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 2] [ 2019-09-04 10:31:53.879 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 2 m_count=50 [Worker 2] [ 2019-09-04 10:31:53.879 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-09-04 10:31:53.879 AST ] [ClientResource.getListener:157] Calling getListener [Worker 2] [ 2019-09-04 10:31:53.879 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 2] [ 2019-09-04 10:31:53.879 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 2] [ 2019-09-04 10:31:53.879 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-09-04 10:31:53.879 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 2 [Worker 2] [ 2019-09-04 10:31:53.879 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [main] [ 2019-09-04 10:31:53.879 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-09-04 10:31:53.879 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-09-04 10:31:53.879 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-09-04 10:31:53.879 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-09-04 10:31:53.879 AST ] [VerificationUtil.pathExists:6204] returning success [main] [ 2019-09-04 10:31:53.886 AST ] [GlobalExecution.getExectaskVer:1069] GlobalExecution: inside getExectaskVer... [main] [ 2019-09-04 10:31:53.888 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:53.893 AST ] [VerificationDataManager.:65] **** VDM constructed [main] [ 2019-09-04 10:31:53.893 AST ] [VerificationDataManager.isDataSegmentLoaded:111] **** Load status for segment admin_data is false [main] [ 2019-09-04 10:31:53.893 AST ] [VerificationDataManager.getDataSegment:134] DataSegment 'admin_data' to be loaded [main] [ 2019-09-04 10:31:53.894 AST ] [VDMUtil.getAdminDataFilename:221] ==== Admin data file: /u01/app/12.2.0.1/setup/cv/cvdata/admin.xml [main] [ 2019-09-04 10:31:53.940 AST ] [AdminLoader.createSegment:136] Parser validation set to: true [main] [ 2019-09-04 10:31:53.940 AST ] [AdminLoader.createSegment:139] /u01/app/12.2.0.1/setup/cv/cvdata/admin.xml is well-formed [main] [ 2019-09-04 10:31:53.945 AST ] [VDMUtil.getCmd4RemExec:159] ==== getCmd4RemExec() called... [main] [ 2019-09-04 10:31:53.946 AST ] [VDMUtil.getCmd4RemExec:166] ==== PROP_REM_COMMAND = 'exectask.sh' [main] [ 2019-09-04 10:31:53.946 AST ] [VerificationUtil.getCmd4RemExec:4736] ==== Remote Exec name: exectask.sh [Finalizer] [ 2019-09-04 10:31:54.034 AST ] [ClusterUtil.finalize:119] ClusterUtil: finalized called for oracle.ops.mgmt.has.ClusterUtil@69a4d326 [Finalizer] [ 2019-09-04 10:31:54.034 AST ] [ClusterUtil.finalize:119] ClusterUtil: finalized called for oracle.ops.mgmt.has.ClusterUtil@2ca65076 [main] [ 2019-09-04 10:31:54.035 AST ] [CVUAutoUpdateManager.getCmdFiles4RemExec:176] cvHome=/u01/app/12.2.0.1/setup/ [main] [ 2019-09-04 10:31:54.036 AST ] [CVUAutoUpdateManager.getCmdFiles4RemExec:177] derivedCVHomeString=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:54.037 AST ] [CVUAutoUpdateManager.getCmdFiles4RemExec:194] s_remExecFiles=/u01/app/12.2.0.1/setup/cv/remenv/orarun.sh,/u01/app/12.2.0.1/setup/cv/remenv/runfixup.sh,/u01/app/12.2.0.1/setup/cv/remenv/cvuhelper,/u01/app/12.2.0.1/setup/cv/remenv/exectask.sh,/u01/app/12.2.0.1/setup/cv/remenv/exectask.sh.ouibak,/u01/app/12.2.0.1/setup/cv/remenv/exectask.sh.ouibak.1,/u01/app/12.2.0.1/setup/cv/remenv/exectask,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checkportavail.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/getNICSpeed.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/ora_00600_errors_analyzer2.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checkLogindIPCSettings.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_network_packet_reassembly.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_network_bonding.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/bdump_dest_trace_analyzer2.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checkmemlock.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_symvers.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/common_include.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_jumbo_frames.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_tcp_packet_retransmit.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/alert_log_file_size_analyzer2.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checkFSMountOptions.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_network_param.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checkIPHostModel.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/css_reboot_time.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_vip_restart_attempt.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/mus_check.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/hangcheck_margin.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/localenam_check.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/css_disk_timeout.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/css_diagwait.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checktmpfs.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/core_dump_dest_analyzer2.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checkhugepage.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/remove_cvuresource_baseline.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checkIOCPDeviceStatus.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/ora_07445_errors_analyzer2.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_ofsctl.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_disk_asynch_io_linking.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/bdump_dest_trace_analyzer.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_default_gateway.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checkcorefile.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/ora_07445_errors_analyzer.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checksyslog.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/shutdown_hwclock_sync.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/ora_00600_errors_analyzer.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_non_routable_network_interconnect.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/zeroconf.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checksshd.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_rp_filter.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_bpf_devices.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_vmm.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_dax_access.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/core_dump_dest_analyzer.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/checkGSDResourceStatus.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/css_misscount.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/alert_log_file_size_analyzer.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/listener_naming_convention.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_e1000.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/check_afd_drivers.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/hangcheck_tick.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/hangcheck_reboot.sh,/u01/app/12.2.0.1/setup/cv/remenv/pluggable/hangchecktimer.sh,/u01/app/12.2.0.1/setup/cv/remenv/jlib/cvuhelper122.jar,/u01/app/12.2.0.1/setup/cv/remenv/jlib/cvuhelper111.jar,/u01/app/12.2.0.1/setup/cv/remenv/jlib/cvuhelper112.jar,/u01/app/12.2.0.1/setup/cv/remenv/jlib/cvuhelper121.jar,/u01/app/12.2.0.1/setup/cv/remenv/jlib/cvuhelper102.jar [main] [ 2019-09-04 10:31:54.037 AST ] [CVUAutoUpdateManager.getFiles4RemExecServer:260] s_remExecServerFiles= [main] [ 2019-09-04 10:31:54.037 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.038 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:54.038 AST ] [NativeResult.:93] NativeResult: The String obtained is0 [main] [ 2019-09-04 10:31:54.038 AST ] [NativeResult.:101] The status string is: 0 [main] [ 2019-09-04 10:31:54.045 AST ] [RemoteExecCommand.:820] End of constructor call (called by many other constructors internally): RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String srcLoc, String[] remExecServerFiles, String destLoc, boolean chkException [main] [ 2019-09-04 10:31:54.045 AST ] [RemoteExecCommand.:719] End of constructor call: RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String[] remExecFiles, String destLoc [main] [ 2019-09-04 10:31:54.045 AST ] [RemoteExecCommand.setSubDirAndGroup:1736] Calling setSubDirAndGroup(String subDir, String group) with 'subDir ='CVU_12.2.0.1.0_grid' and 'group = 'null [main] [ 2019-09-04 10:31:54.045 AST ] [VerificationUtil.isLocalNode:10462] Comparing 'racnode1' to localHOST 'racnode1' [main] [ 2019-09-04 10:31:54.045 AST ] [VerificationCommand.checkAndSetLocalExecution:294] Setting local execution to TRUE for this command on node (racnode1) [main] [ 2019-09-04 10:31:54.046 AST ] [RemoteExecCommand.setLocalExecution:1720] Changed ivar value for m_localExecution to true [main] [ 2019-09-04 10:31:54.053 AST ] [RemoteExecCommand.setArgs:1677] Setting value for ivar 'm_args' [main] [ 2019-09-04 10:31:54.061 AST ] [ResultSet.traceResultSet:902] ResultSet BEFORE adding Result data ===> Overall Status->UNKNOWN Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: false [main] [ 2019-09-04 10:31:54.061 AST ] [ResultSet.traceResultSet:902] ResultSet AFTER adding Result data ===> Overall Status->SUCCESSFUL Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.062 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-09-04 10:31:54.062 AST ] [GetActiveNodes.create:226] Returning an existing instance of GetActiveNodes [main] [ 2019-09-04 10:31:54.062 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-09-04 10:31:54.063 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-09-04 10:31:54.063 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=4 [main] [ 2019-09-04 10:31:54.063 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 1] [ 2019-09-04 10:31:54.063 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 1 m_count=4 [Worker 1] [ 2019-09-04 10:31:54.063 AST ] [GetExectaskVerCommand.execute:88] GetExectaskVerCommand::Inside execute() Worker 1 [Worker 1] [ 2019-09-04 10:31:54.063 AST ] [VerificationCommand.execute:331] :: Inside execute() [Thread: [Worker 1] [ 2019-09-04 10:31:54.063 AST ] [RemoteExecCommand.validateCmdArgs:1294] Calling validateCmdArgs [Worker 1] [ 2019-09-04 10:31:54.068 AST ] [RemoteExecCommand.validateCmdArgs:1301] Checking for arguments validity [Worker 1] [ 2019-09-04 10:31:54.068 AST ] [RemoteExecCommand.executeInternal:1235] Calling executeInternal() [Worker 1] [ 2019-09-04 10:31:54.068 AST ] [RemoteExecCommand.executeInternal:1251] executing the command: '/var/tmp/CVU_12.2.0.1.0_grid//exectask.sh' with args '-getver ', 'm_stdin == null ->true', 'm_localExecution ->true', 'm_chkException ->false' [Worker 1] [ 2019-09-04 10:31:54.068 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[] [Worker 1] [ 2019-09-04 10:31:54.068 AST ] [UnixSystem.dorunRemoteExecCmd:4180] Final unix SSH command: /var/tmp/CVU_12.2.0.1.0_grid//exectask.sh -getver [Worker 1] [ 2019-09-04 10:31:54.073 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Thread-45] [ 2019-09-04 10:31:54.075 AST ] [StreamReader.run:62] In StreamReader.run [Thread-44] [ 2019-09-04 10:31:54.075 AST ] [StreamReader.run:62] In StreamReader.run [Thread-44] [ 2019-09-04 10:31:54.096 AST ] [StreamReader.run:66] OUTPUT>012.2.0.1.0.07_10_19_i86pc0/var/tmp/CVU_12.2.0.1.0_grid/exectask -getver racnode1.testdomain.com [Worker 1] [ 2019-09-04 10:31:54.100 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Worker 1] [ 2019-09-04 10:31:54.100 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 1] [ 2019-09-04 10:31:54.100 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 1] [ 2019-09-04 10:31:54.100 AST ] [UnixSystem.dorunRemoteExecCmd:4192] retval = 0 [Worker 1] [ 2019-09-04 10:31:54.101 AST ] [UnixSystem.dorunRemoteExecCmd:4216] exitValue = 0 [Worker 1] [ 2019-09-04 10:31:54.101 AST ] [RemoteExecCommand.executeInternal:1282] cmdSuccess status: true [Worker 1] [ 2019-09-04 10:31:54.101 AST ] [RemoteExecCommand.execute:1052] cmdSuccess status: true [Worker 1] [ 2019-09-04 10:31:54.101 AST ] [VerificationUtil.logAllCommandDetails:4291] No command execution details are available for node 'racnode1' [Worker 1] [ 2019-09-04 10:31:54.102 AST ] [VerificationUtil.logAllAPIDetails:4390] No API execution details are available for node 'racnode1' [Worker 1] [ 2019-09-04 10:31:54.103 AST ] [VerificationCommand.fetchExecutionLogDetails:1130] cmdArr=outputArr=exitValArr= [Worker 1] [ 2019-09-04 10:31:54.103 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:12.2.0.1.0.07_10_19_i86pc [Worker 1] [ 2019-09-04 10:31:54.103 AST ] [VerificationUtil.fetchError:4074] No errors to return. [Worker 1] [ 2019-09-04 10:31:54.103 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:0 [Worker 1] [ 2019-09-04 10:31:54.103 AST ] [VerificationCommand.execute:376] VfyCode is: 0 [Worker 1] [ 2019-09-04 10:31:54.103 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:0 [Worker 1] [ 2019-09-04 10:31:54.103 AST ] [GetExectaskVerCommand.execute:110] super.execute() was succcessful for GetExectaskVerCommand... [Worker 1] [ 2019-09-04 10:31:54.103 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:0 [Worker 1] [ 2019-09-04 10:31:54.103 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:12.2.0.1.0.07_10_19_i86pc [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [GetExectaskVerCommand.execute:134] after calling fetchVerificationValue() [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [GetExectaskVerCommand.execute:138] The version of exectask at node 'racnode1' is '12.2.0.1.0.07_10_19_i86pc' [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 1 m_count=50 [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [ClientResource.getListener:157] Calling getListener [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 1 [Worker 1] [ 2019-09-04 10:31:54.104 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=0 [main] [ 2019-09-04 10:31:54.104 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-09-04 10:31:54.104 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-09-04 10:31:54.104 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=1 [main] [ 2019-09-04 10:31:54.104 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-09-04 10:31:54.105 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-09-04 10:31:54.105 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-09-04 10:31:54.105 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-09-04 10:31:54.105 AST ] [GlobalExecution.dumpTraceInfo:1472] ---- Execution Trace for getExectaskVer from node: racnode1 ----- [main] [ 2019-09-04 10:31:54.105 AST ] [GlobalExecution.dumpTraceInfo:1480] ::Inside execute() [main] [ 2019-09-04 10:31:54.105 AST ] [GlobalExecution.dumpTraceInfo:1480] The version of exectask at node 'racnode1' is '12.2.0.1.0.07_10_19_i86pc' [main] [ 2019-09-04 10:31:54.105 AST ] [VerificationUtil.checkGetExectaskVerResults:7631] Exectask version on node 'racnode1' is '12.2.0.1.0.07_10_19_i86pc" [main] [ 2019-09-04 10:31:54.105 AST ] [VerificationUtil.compatibleExectask:9155] Comparing framework version '12.2.0.1.0.07_10_19_i86pc' with exectask version '12.2.0.1.0.07_10_19_i86pc' [main] [ 2019-09-04 10:31:54.105 AST ] [VerificationUtil.checkGetExectaskVerResults:7634] Compatible exectask found on node: racnode1 [main] [ 2019-09-04 10:31:54.124 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.124 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.124 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.124 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.124 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.124 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.124 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.124 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.125 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.125 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.125 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.125 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.125 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.125 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.126 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.127 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.128 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.129 AST ] [GlobalExecution.getFileInfo:3424] GlobalExecution: inside getFileInfo... [main] [ 2019-09-04 10:31:54.129 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.439 AST ] [GlobalExecution.copyFile:3253] GlobalExecution::inside checkFileExistence... [main] [ 2019-09-04 10:31:54.440 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:54.440 AST ] [NativeResult.:93] NativeResult: The String obtained is0 [main] [ 2019-09-04 10:31:54.440 AST ] [NativeResult.:101] The status string is: 0 [main] [ 2019-09-04 10:31:54.441 AST ] [RemoteExecCommand.:511] End of constructor call (called by many other constructors internally): RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String srcLoc, String destLoc, boolean chkException [main] [ 2019-09-04 10:31:54.441 AST ] [RemoteExecCommand.:387] End of constructor call: RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String srcLoc, String destLoc [main] [ 2019-09-04 10:31:54.441 AST ] [RemoteExecCommand.setSubDirAndGroup:1736] Calling setSubDirAndGroup(String subDir, String group) with 'subDir ='CVU_12.2.0.1.0_grid' and 'group = 'null [main] [ 2019-09-04 10:31:54.441 AST ] [VerificationCommand.checkAndSetLocalExecution:294] Setting local execution to TRUE for this command on node (racnode1) [main] [ 2019-09-04 10:31:54.441 AST ] [RemoteExecCommand.setLocalExecution:1720] Changed ivar value for m_localExecution to true [main] [ 2019-09-04 10:31:54.443 AST ] [ResultSet.traceResultSet:902] ResultSet BEFORE adding Result data ===> Overall Status->UNKNOWN Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: false [main] [ 2019-09-04 10:31:54.443 AST ] [ResultSet.traceResultSet:902] ResultSet AFTER adding Result data ===> Overall Status->SUCCESSFUL Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.443 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-09-04 10:31:54.443 AST ] [GetActiveNodes.create:226] Returning an existing instance of GetActiveNodes [main] [ 2019-09-04 10:31:54.443 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-09-04 10:31:54.443 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-09-04 10:31:54.443 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=4 [main] [ 2019-09-04 10:31:54.443 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 0] [ 2019-09-04 10:31:54.443 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 0 m_count=4 [Worker 0] [ 2019-09-04 10:31:54.443 AST ] [CopyFileCommand.execute:91] CopyFileCommand:: Inside execute() [Thread:Worker 0] [Worker 0] [ 2019-09-04 10:31:54.444 AST ] [UnixSystem.copyFile:1105] Copy file localnode:/var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_2754687450323958673.txt to racnode1:/var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txt [Worker 0] [ 2019-09-04 10:31:54.444 AST ] [Utils.getLocalHost:478] Hostname retrieved: racnode1.testdomain.com, returned: racnode1 [Worker 0] [ 2019-09-04 10:31:54.445 AST ] [UnixSystem.copyFile:1179] Copying a file within the same directory [Worker 0] [ 2019-09-04 10:31:54.445 AST ] [Utils.getLocalHost:478] Hostname retrieved: racnode1.testdomain.com, returned: racnode1 [Worker 0] [ 2019-09-04 10:31:54.445 AST ] [UnixSystem.copyFile:1234] UnixSystem: /usr/bin/cp -p /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_2754687450323958673.txt /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txt [Worker 0] [ 2019-09-04 10:31:54.449 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Worker 0] [ 2019-09-04 10:31:54.449 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Thread-47] [ 2019-09-04 10:31:54.450 AST ] [StreamReader.run:62] In StreamReader.run [Thread-46] [ 2019-09-04 10:31:54.450 AST ] [StreamReader.run:62] In StreamReader.run [Worker 0] [ 2019-09-04 10:31:54.450 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 0] [ 2019-09-04 10:31:54.450 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 0] [ 2019-09-04 10:31:54.450 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/cp -p /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_2754687450323958673.txt /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txt] [Worker 0] [ 2019-09-04 10:31:54.450 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned false [Worker 0] [ 2019-09-04 10:31:54.451 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 0] [ 2019-09-04 10:31:54.451 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 0] [ 2019-09-04 10:31:54.451 AST ] [NativeResult.:101] The status string is: 1 [Worker 0] [ 2019-09-04 10:31:54.451 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 0] [ 2019-09-04 10:31:54.451 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 0] [ 2019-09-04 10:31:54.451 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 0 m_count=50 [Worker 0] [ 2019-09-04 10:31:54.452 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-09-04 10:31:54.452 AST ] [ClientResource.getListener:157] Calling getListener [Worker 0] [ 2019-09-04 10:31:54.452 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 0] [ 2019-09-04 10:31:54.452 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 0] [ 2019-09-04 10:31:54.452 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 0 m_count=1 [Worker 0] [ 2019-09-04 10:31:54.452 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 0 [Worker 0] [ 2019-09-04 10:31:54.452 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 0 m_count=0 [main] [ 2019-09-04 10:31:54.452 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-09-04 10:31:54.453 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-09-04 10:31:54.453 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=1 [main] [ 2019-09-04 10:31:54.453 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-09-04 10:31:54.453 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-09-04 10:31:54.453 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-09-04 10:31:54.454 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-09-04 10:31:54.454 AST ] [VerificationUtil.logAllCommandDetails:4291] No command execution details are available for node 'racnode1' [main] [ 2019-09-04 10:31:54.454 AST ] [VerificationUtil.logAllAPIDetails:4390] No API execution details are available for node 'racnode1' [main] [ 2019-09-04 10:31:54.455 AST ] [VerificationCommand.fetchExecutionLogDetails:1130] cmdArr=outputArr=exitValArr= [main] [ 2019-09-04 10:31:54.455 AST ] [GlobalExecution.dumpTraceInfo:1472] ---- Execution Trace for copyFile from node: racnode1 ----- [main] [ 2019-09-04 10:31:54.455 AST ] [GlobalExecution.dumpTraceInfo:1480] CopyFileCommand::Inside execute() Worker 0 [main] [ 2019-09-04 10:31:54.456 AST ] [ResultSet.addResultTable:465] addResultTable, called from: GlobalExecution.getFileInfo:3478 [main] [ 2019-09-04 10:31:54.456 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '0' [main] [ 2019-09-04 10:31:54.456 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable [main] [ 2019-09-04 10:31:54.456 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.457 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.457 AST ] [ResultSet.setStatus:369] m_resultTable has size of zero, setting m_status to: UNKNOWN [main] [ 2019-09-04 10:31:54.457 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = MODE_API VAL = TRUE [main] [ 2019-09-04 10:31:54.457 AST ] [ResultSet.traceResultSet:902] Target ResultSet AFTER Upload===> Overall Status->UNKNOWN Uploaded Overall Status->SUCCESSFUL GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.457 AST ] [ResultSet.addResultTable:465] addResultTable, called from: GlobalExecution.getFileInfo:3480 [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '0' [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.getSuccNodes:1364] Checking for Success nodes from in the ResultSet hashtables [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.addResultTable:465] addResultTable, called from: GlobalExecution.getFileInfo:3491 [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '0' [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.458 AST ] [ResultSet.getSuccNodes:1388] Adding node racnode1 to list of Succ nodes [main] [ 2019-09-04 10:31:54.460 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.460 AST ] [VDMUtil.getCmd4RemExec:159] ==== getCmd4RemExec() called... [main] [ 2019-09-04 10:31:54.460 AST ] [VDMUtil.getCmd4RemExec:166] ==== PROP_REM_COMMAND = 'exectask.sh' [main] [ 2019-09-04 10:31:54.460 AST ] [VerificationUtil.getCmd4RemExec:4736] ==== Remote Exec name: exectask.sh [main] [ 2019-09-04 10:31:54.460 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:54.460 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.460 AST ] [NativeResult.:93] NativeResult: The String obtained is0 [main] [ 2019-09-04 10:31:54.460 AST ] [NativeResult.:101] The status string is: 0 [main] [ 2019-09-04 10:31:54.461 AST ] [RemoteExecCommand.:820] End of constructor call (called by many other constructors internally): RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String srcLoc, String[] remExecServerFiles, String destLoc, boolean chkException [main] [ 2019-09-04 10:31:54.461 AST ] [RemoteExecCommand.:719] End of constructor call: RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String[] remExecFiles, String destLoc [main] [ 2019-09-04 10:31:54.461 AST ] [RemoteExecCommand.setSubDirAndGroup:1736] Calling setSubDirAndGroup(String subDir, String group) with 'subDir ='CVU_12.2.0.1.0_grid' and 'group = 'null [main] [ 2019-09-04 10:31:54.461 AST ] [VerificationCommand.checkAndSetLocalExecution:294] Setting local execution to TRUE for this command on node (racnode1) [main] [ 2019-09-04 10:31:54.461 AST ] [RemoteExecCommand.setLocalExecution:1720] Changed ivar value for m_localExecution to true [main] [ 2019-09-04 10:31:54.462 AST ] [RemoteExecCommand.setArgs:1677] Setting value for ivar 'm_args' [main] [ 2019-09-04 10:31:54.463 AST ] [ResultSet.traceResultSet:902] ResultSet BEFORE adding Result data ===> Overall Status->UNKNOWN Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: false [main] [ 2019-09-04 10:31:54.463 AST ] [ResultSet.traceResultSet:902] ResultSet AFTER adding Result data ===> Overall Status->SUCCESSFUL Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.464 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-09-04 10:31:54.464 AST ] [GetActiveNodes.create:226] Returning an existing instance of GetActiveNodes [main] [ 2019-09-04 10:31:54.464 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-09-04 10:31:54.464 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-09-04 10:31:54.464 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=4 [main] [ 2019-09-04 10:31:54.464 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 3] [ 2019-09-04 10:31:54.464 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 3 m_count=4 [Worker 3] [ 2019-09-04 10:31:54.464 AST ] [GetFileInfoCommand.execute:115] GetFileVerCommand::Inside execute() Worker 3 [Worker 3] [ 2019-09-04 10:31:54.464 AST ] [VerificationCommand.execute:331] :: Inside execute() [Thread: [Worker 3] [ 2019-09-04 10:31:54.464 AST ] [RemoteExecCommand.validateCmdArgs:1294] Calling validateCmdArgs [Worker 3] [ 2019-09-04 10:31:54.465 AST ] [RemoteExecCommand.validateCmdArgs:1301] Checking for arguments validity [Worker 3] [ 2019-09-04 10:31:54.465 AST ] [RemoteExecCommand.executeInternal:1235] Calling executeInternal() [Worker 3] [ 2019-09-04 10:31:54.465 AST ] [RemoteExecCommand.executeInternal:1251] executing the command: '/var/tmp/CVU_12.2.0.1.0_grid/exectask.sh' with args '-getfileinfo /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txt ', 'm_stdin == null ->true', 'm_localExecution ->true', 'm_chkException ->false' [Worker 3] [ 2019-09-04 10:31:54.465 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[] [Worker 3] [ 2019-09-04 10:31:54.465 AST ] [UnixSystem.dorunRemoteExecCmd:4180] Final unix SSH command: /var/tmp/CVU_12.2.0.1.0_grid/exectask.sh -getfileinfo /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txt [Worker 3] [ 2019-09-04 10:31:54.470 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Worker 3] [ 2019-09-04 10:31:54.509 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Thread-48] [ 2019-09-04 10:31:54.509 AST ] [StreamReader.run:62] In StreamReader.run [Thread-48] [ 2019-09-04 10:31:54.509 AST ] [StreamReader.run:66] OUTPUT>/var/tmp/CVU_12.2.0.1.0_grid/scratch/getFileInfo17052.out00/var/tmp/CVU_12.2.0.1.0_grid/exectask -getfileinfo /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txt racnode1.testdomain.comfopen /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txtNULL0fopen /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txtNULL0Exectask:getfsInfo success [Thread-49] [ 2019-09-04 10:31:54.510 AST ] [StreamReader.run:62] In StreamReader.run [Worker 3] [ 2019-09-04 10:31:54.510 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 3] [ 2019-09-04 10:31:54.510 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 3] [ 2019-09-04 10:31:54.510 AST ] [UnixSystem.dorunRemoteExecCmd:4192] retval = 0 [Worker 3] [ 2019-09-04 10:31:54.510 AST ] [UnixSystem.dorunRemoteExecCmd:4216] exitValue = 0 [Worker 3] [ 2019-09-04 10:31:54.510 AST ] [RemoteExecCommand.executeInternal:1282] cmdSuccess status: true [Worker 3] [ 2019-09-04 10:31:54.510 AST ] [RemoteExecCommand.execute:1052] cmdSuccess status: true [Worker 3] [ 2019-09-04 10:31:54.512 AST ] [VerificationCommand.fetchExecutionLogDetails:1130] cmdArr=fopen /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txt,fopen /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txtoutputArr=NULL,NULLexitValArr=0,0 [Worker 3] [ 2019-09-04 10:31:54.512 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:/var/tmp/CVU_12.2.0.1.0_grid/scratch/getFileInfo17052.out [Worker 3] [ 2019-09-04 10:31:54.512 AST ] [VerificationUtil.fetchError:4074] No errors to return. [Worker 3] [ 2019-09-04 10:31:54.512 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:0 [Worker 3] [ 2019-09-04 10:31:54.512 AST ] [VerificationCommand.execute:376] VfyCode is: 0 [Worker 3] [ 2019-09-04 10:31:54.512 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:0 [Worker 3] [ 2019-09-04 10:31:54.512 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:/var/tmp/CVU_12.2.0.1.0_grid/scratch/getFileInfo17052.out [Worker 3] [ 2019-09-04 10:31:54.512 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [Worker 3] [ 2019-09-04 10:31:54.513 AST ] [UnixSystem.copyFile:1105] Copy file racnode1:/var/tmp/CVU_12.2.0.1.0_grid/scratch/getFileInfo17052.out to localnode:/var/tmp/racnode1.getFileInfo17052.out [Worker 3] [ 2019-09-04 10:31:54.513 AST ] [Utils.getLocalHost:478] Hostname retrieved: racnode1.testdomain.com, returned: racnode1 [Worker 3] [ 2019-09-04 10:31:54.513 AST ] [UnixSystem.isACLSet:733] Input src :getFileInfo17052.out [Worker 3] [ 2019-09-04 10:31:54.514 AST ] [nativesystem.UnixNative.Native] UnixNative_isAclSet: Path count = 1 [Worker 3] [ 2019-09-04 10:31:54.514 AST ] [nativesystem.UnixNative.Native] UnixNative_isAclSet: srcName=/var/tmp/CVU_12.2.0.1.0_grid/scratch/getFileInfo17052.out [Worker 3] [ 2019-09-04 10:31:54.514 AST ] [nativesystem.UnixNative.Native] UnixNative_isAclSet: Acl set on /var/tmp/CVU_12.2.0.1.0_grid/scratch/getFileInfo17052.out [Worker 3] [ 2019-09-04 10:31:54.514 AST ] [nativesystem.UnixNative.Native] UnixNative_isAclSupported: srcName=/var/tmp [Worker 3] [ 2019-09-04 10:31:54.514 AST ] [nativesystem.UnixNative.Native] UnixNative_isAclSupported: status=TRUE [Worker 3] [ 2019-09-04 10:31:54.515 AST ] [Utils.getLocalHost:478] Hostname retrieved: racnode1.testdomain.com, returned: racnode1 [Worker 3] [ 2019-09-04 10:31:54.515 AST ] [UnixSystem.copyFile:1234] UnixSystem: /usr/bin/cp -p /var/tmp/CVU_12.2.0.1.0_grid/scratch/getFileInfo17052.out /var/tmp/racnode1.getFileInfo17052.out [Worker 3] [ 2019-09-04 10:31:54.520 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Worker 3] [ 2019-09-04 10:31:54.520 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Thread-51] [ 2019-09-04 10:31:54.520 AST ] [StreamReader.run:62] In StreamReader.run [Thread-50] [ 2019-09-04 10:31:54.520 AST ] [StreamReader.run:62] In StreamReader.run [Worker 3] [ 2019-09-04 10:31:54.520 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 3] [ 2019-09-04 10:31:54.520 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 3] [ 2019-09-04 10:31:54.520 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/cp -p /var/tmp/CVU_12.2.0.1.0_grid/scratch/getFileInfo17052.out /var/tmp/racnode1.getFileInfo17052.out] [Worker 3] [ 2019-09-04 10:31:54.521 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned false [Worker 3] [ 2019-09-04 10:31:54.521 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 3] [ 2019-09-04 10:31:54.521 AST ] [GetFileInfoCommand.execute:175] [Worker 3] [ 2019-09-04 10:31:54.521 AST ] [Utils.getLocalHost:478] Hostname retrieved: racnode1.testdomain.com, returned: racnode1 [Worker 3] [ 2019-09-04 10:31:54.526 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Worker 3] [ 2019-09-04 10:31:54.526 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Thread-53] [ 2019-09-04 10:31:54.526 AST ] [StreamReader.run:62] In StreamReader.run [Thread-52] [ 2019-09-04 10:31:54.526 AST ] [StreamReader.run:62] In StreamReader.run [Worker 3] [ 2019-09-04 10:31:54.527 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 3] [ 2019-09-04 10:31:54.527 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 3] [ 2019-09-04 10:31:54.527 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/rm -f /var/tmp/CVU_12.2.0.1.0_grid/scratch/getFileInfo17052.out] [Worker 3] [ 2019-09-04 10:31:54.527 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned false [Worker 3] [ 2019-09-04 10:31:54.527 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 3] [ 2019-09-04 10:31:54.530 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Worker 3] [ 2019-09-04 10:31:54.530 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Thread-55] [ 2019-09-04 10:31:54.531 AST ] [StreamReader.run:62] In StreamReader.run [Thread-54] [ 2019-09-04 10:31:54.531 AST ] [StreamReader.run:62] In StreamReader.run [Worker 3] [ 2019-09-04 10:31:54.531 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 3] [ 2019-09-04 10:31:54.531 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 3] [ 2019-09-04 10:31:54.531 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/rm -f /var/tmp/racnode1.getFileInfo17052.out] [Worker 3] [ 2019-09-04 10:31:54.531 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned false [Worker 3] [ 2019-09-04 10:31:54.531 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 3] [ 2019-09-04 10:31:54.535 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 3] [ 2019-09-04 10:31:54.535 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 3 m_count=50 [Worker 3] [ 2019-09-04 10:31:54.535 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-09-04 10:31:54.536 AST ] [ClientResource.getListener:157] Calling getListener [Worker 3] [ 2019-09-04 10:31:54.536 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 3] [ 2019-09-04 10:31:54.536 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 3] [ 2019-09-04 10:31:54.536 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 3 m_count=1 [Worker 3] [ 2019-09-04 10:31:54.536 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 3 [Worker 3] [ 2019-09-04 10:31:54.536 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 3 m_count=0 [main] [ 2019-09-04 10:31:54.536 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-09-04 10:31:54.536 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-09-04 10:31:54.536 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=1 [main] [ 2019-09-04 10:31:54.536 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-09-04 10:31:54.536 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-09-04 10:31:54.536 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-09-04 10:31:54.536 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-09-04 10:31:54.537 AST ] [ResultSet.addResultTable:465] addResultTable, called from: GlobalExecution.getFileInfo:3507 [main] [ 2019-09-04 10:31:54.537 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '1' [main] [ 2019-09-04 10:31:54.537 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.537 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Info type : Hashtable Errors : [main] [ 2019-09-04 10:31:54.537 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Info type : Hashtable Errors : [main] [ 2019-09-04 10:31:54.537 AST ] [ResultSet.setStatus:369] m_resultTable has size of zero, setting m_status to: UNKNOWN [main] [ 2019-09-04 10:31:54.537 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = MODE_API VAL = TRUE [main] [ 2019-09-04 10:31:54.538 AST ] [ResultSet.traceResultSet:902] Target ResultSet AFTER Upload===> Overall Status->UNKNOWN Uploaded Overall Status->SUCCESSFUL GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.538 AST ] [GlobalExecution.deleteFile:3287] GlobalExecution::inside checkFileExistence... [main] [ 2019-09-04 10:31:54.538 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:54.538 AST ] [NativeResult.:93] NativeResult: The String obtained is0 [main] [ 2019-09-04 10:31:54.539 AST ] [NativeResult.:101] The status string is: 0 [main] [ 2019-09-04 10:31:54.540 AST ] [RemoteExecCommand.:511] End of constructor call (called by many other constructors internally): RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String srcLoc, String destLoc, boolean chkException [main] [ 2019-09-04 10:31:54.540 AST ] [RemoteExecCommand.:387] End of constructor call: RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String srcLoc, String destLoc [main] [ 2019-09-04 10:31:54.540 AST ] [RemoteExecCommand.setSubDirAndGroup:1736] Calling setSubDirAndGroup(String subDir, String group) with 'subDir ='CVU_12.2.0.1.0_grid' and 'group = 'null [main] [ 2019-09-04 10:31:54.540 AST ] [VerificationCommand.checkAndSetLocalExecution:294] Setting local execution to TRUE for this command on node (racnode1) [main] [ 2019-09-04 10:31:54.540 AST ] [RemoteExecCommand.setLocalExecution:1720] Changed ivar value for m_localExecution to true [main] [ 2019-09-04 10:31:54.541 AST ] [ResultSet.traceResultSet:902] ResultSet BEFORE adding Result data ===> Overall Status->UNKNOWN Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: false [main] [ 2019-09-04 10:31:54.541 AST ] [ResultSet.traceResultSet:902] ResultSet AFTER adding Result data ===> Overall Status->SUCCESSFUL Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.541 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-09-04 10:31:54.542 AST ] [GetActiveNodes.create:226] Returning an existing instance of GetActiveNodes [main] [ 2019-09-04 10:31:54.542 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-09-04 10:31:54.542 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-09-04 10:31:54.542 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=4 [main] [ 2019-09-04 10:31:54.542 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 2] [ 2019-09-04 10:31:54.542 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 2 m_count=4 [Worker 2] [ 2019-09-04 10:31:54.543 AST ] [DeleteFileCommand.execute:66] DeleteFileCommand:: Inside execute() [Thread:Worker 2] [Worker 2] [ 2019-09-04 10:31:54.543 AST ] [Utils.getLocalHost:478] Hostname retrieved: racnode1.testdomain.com, returned: racnode1 [Worker 2] [ 2019-09-04 10:31:54.547 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Worker 2] [ 2019-09-04 10:31:54.547 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Thread-57] [ 2019-09-04 10:31:54.547 AST ] [StreamReader.run:62] In StreamReader.run [Thread-56] [ 2019-09-04 10:31:54.547 AST ] [StreamReader.run:62] In StreamReader.run [Worker 2] [ 2019-09-04 10:31:54.547 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 2] [ 2019-09-04 10:31:54.548 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 2] [ 2019-09-04 10:31:54.548 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[/usr/bin/rm -f /var/tmp/CVU_12.2.0.1.0_grid/getfileinfoconfigfile_4668186492341307782.txt] [Worker 2] [ 2019-09-04 10:31:54.548 AST ] [NativeSystem.isCmdScv:616] isCmdScv: returned false [Worker 2] [ 2019-09-04 10:31:54.548 AST ] [NativeSystem.rununixcmd:1283] NativeSystem.rununixcmd: RetString 1| :successful [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [NativeResult.:93] NativeResult: The String obtained is1| :successful [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [NativeResult.:101] The status string is: 1 [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [NativeResult.:114] The result string is: :successful 1 [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 2 m_count=50 [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [ClientResource.getListener:157] Calling getListener [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 2 m_count=1 [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 2 [Worker 2] [ 2019-09-04 10:31:54.549 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 2 m_count=0 [main] [ 2019-09-04 10:31:54.549 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-09-04 10:31:54.549 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-09-04 10:31:54.549 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=1 [main] [ 2019-09-04 10:31:54.549 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-09-04 10:31:54.550 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-09-04 10:31:54.550 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-09-04 10:31:54.550 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-09-04 10:31:54.550 AST ] [VerificationUtil.logAllCommandDetails:4291] No command execution details are available for node 'racnode1' [main] [ 2019-09-04 10:31:54.551 AST ] [VerificationUtil.logAllAPIDetails:4390] No API execution details are available for node 'racnode1' [main] [ 2019-09-04 10:31:54.551 AST ] [VerificationCommand.fetchExecutionLogDetails:1130] cmdArr=outputArr=exitValArr= [main] [ 2019-09-04 10:31:54.551 AST ] [GlobalExecution.dumpTraceInfo:1472] ---- Execution Trace for copyFile from node: racnode1 ----- [main] [ 2019-09-04 10:31:54.552 AST ] [GlobalExecution.dumpTraceInfo:1480] DeleteFileCommand::Inside execute() Worker 2 [main] [ 2019-09-04 10:31:54.552 AST ] [ResultSet.addResultTable:465] addResultTable, called from: GlobalExecution.getFileInfo:3511 [main] [ 2019-09-04 10:31:54.552 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '1' [main] [ 2019-09-04 10:31:54.552 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Info type : Hashtable Errors : [main] [ 2019-09-04 10:31:54.552 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.552 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Info type : Hashtable Errors : [main] [ 2019-09-04 10:31:54.552 AST ] [ResultSet.setStatus:369] m_resultTable has size of zero, setting m_status to: UNKNOWN [main] [ 2019-09-04 10:31:54.552 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = MODE_API VAL = TRUE [main] [ 2019-09-04 10:31:54.553 AST ] [ResultSet.traceResultSet:902] Target ResultSet AFTER Upload===> Overall Status->UNKNOWN Uploaded Overall Status->SUCCESSFUL GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.649 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = MODE_CLI VAL = FALSE [main] [ 2019-09-04 10:31:54.649 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = MODE_API VAL = TRUE [main] [ 2019-09-04 10:31:54.678 AST ] [TaskAnonymousProxy.:120] Defining proxy task with: 'ReportUtilDummy' nodeList: '' from task: 'null' Called from: 'ReportUtil.:470' [main] [ 2019-09-04 10:31:54.678 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = MODE_CLI VAL = FALSE [main] [ 2019-09-04 10:31:54.678 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:54.678 AST ] [sVerificationUtil.resolve:803] condition variable OLDFORMAT_FLAG not handled [main] [ 2019-09-04 10:31:54.679 AST ] [CVUVariables.setValue:329] CVUVarConstant : OLDFORMAT_FLAG [main] [ 2019-09-04 10:31:54.679 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:54.679 AST ] [CVUVariables.setValue:357] Unable to set value for variable : OLDFORMAT_FLAG [main] [ 2019-09-04 10:31:54.680 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = OLDFORMAT_FLAG VAL = null [main] [ 2019-09-04 10:31:54.680 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:54.680 AST ] [sVerificationUtil.resolve:803] condition variable FORMAT_FLAG not handled [main] [ 2019-09-04 10:31:54.680 AST ] [CVUVariables.setValue:329] CVUVarConstant : FORMAT_FLAG [main] [ 2019-09-04 10:31:54.680 AST ] [CVUVariables.getCVUVariable:560] The variable name : is not listed [main] [ 2019-09-04 10:31:54.680 AST ] [CVUVariables.setValue:357] Unable to set value for variable : FORMAT_FLAG [main] [ 2019-09-04 10:31:54.680 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = FORMAT_FLAG VAL = null [main] [ 2019-09-04 10:31:54.681 AST ] [ReportUtil.:503] s_usePre122Format set to: false isFormat set to: false [main] [ 2019-09-04 10:31:54.681 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/orarun.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.681 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/runfixup.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.681 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/cvuhelper Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.681 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/exectask.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.681 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/exectask.sh.ouibak Owner: grid Group: oinstall Perms: 0640 [main] [ 2019-09-04 10:31:54.681 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/exectask.sh.ouibak.1 Owner: grid Group: oinstall Perms: 0640 [main] [ 2019-09-04 10:31:54.681 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/exectask Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.681 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checkportavail.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.685 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/getNICSpeed.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.685 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/ora_00600_errors_analyzer2.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.685 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checkLogindIPCSettings.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.685 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_network_packet_reassembly.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.685 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_network_bonding.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.713 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/bdump_dest_trace_analyzer2.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.715 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checkmemlock.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.719 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_symvers.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.719 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/common_include.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.719 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_jumbo_frames.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.719 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_tcp_packet_retransmit.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.719 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/alert_log_file_size_analyzer2.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.719 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checkFSMountOptions.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.719 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_network_param.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.742 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checkIPHostModel.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.742 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/css_reboot_time.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_vip_restart_attempt.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/mus_check.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/hangcheck_margin.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/localenam_check.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/css_disk_timeout.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/css_diagwait.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checktmpfs.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/core_dump_dest_analyzer2.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checkhugepage.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.743 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/remove_cvuresource_baseline.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.744 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checkIOCPDeviceStatus.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.744 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/ora_07445_errors_analyzer2.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.744 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_ofsctl.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.744 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_disk_asynch_io_linking.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.744 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/bdump_dest_trace_analyzer.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.744 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_default_gateway.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.744 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checkcorefile.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.744 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/ora_07445_errors_analyzer.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.747 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checksyslog.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.747 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/shutdown_hwclock_sync.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.747 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/ora_00600_errors_analyzer.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.747 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_non_routable_network_interconnect.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.748 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/zeroconf.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.748 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checksshd.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.748 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_rp_filter.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.748 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_bpf_devices.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.748 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_vmm.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.749 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_dax_access.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.749 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/core_dump_dest_analyzer.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.749 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/checkGSDResourceStatus.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.749 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/css_misscount.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.749 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/alert_log_file_size_analyzer.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.749 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/listener_naming_convention.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.749 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_e1000.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.749 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/check_afd_drivers.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.749 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/hangcheck_tick.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.751 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/hangcheck_reboot.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.759 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/hangchecktimer.sh Owner: grid Group: oinstall Perms: 0750 [main] [ 2019-09-04 10:31:54.759 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/cvuhelper122.jar Owner: grid Group: oinstall Perms: 0755 [main] [ 2019-09-04 10:31:54.760 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/cvuhelper111.jar Owner: grid Group: oinstall Perms: 0755 [main] [ 2019-09-04 10:31:54.760 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/cvuhelper112.jar Owner: grid Group: oinstall Perms: 0755 [main] [ 2019-09-04 10:31:54.761 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/cvuhelper121.jar Owner: grid Group: oinstall Perms: 0755 [main] [ 2019-09-04 10:31:54.761 AST ] [VerificationUtil.checkFileAttributes:7296] Checking file: /var/tmp/CVU_12.2.0.1.0_grid/cvuhelper102.jar Owner: grid Group: oinstall Perms: 0755 [main] [ 2019-09-04 10:31:54.761 AST ] [VerificationUtil.checkDestLoc:6546] destloc setup on local node succeeded [main] [ 2019-09-04 10:31:54.761 AST ] [GlobalExecution.getExectaskVer:1069] GlobalExecution: inside getExectaskVer... [main] [ 2019-09-04 10:31:54.761 AST ] [ResultSet.setStatus:369] m_resultTable has size of zero, setting m_status to: UNKNOWN [main] [ 2019-09-04 10:31:54.761 AST ] [VerificationUtil.checkDestLoc:6579] VerificationUtil::getExectaskVer() performed!! [main] [ 2019-09-04 10:31:54.761 AST ] [ResultSet.getSuccNodes:1364] Checking for Success nodes from in the ResultSet hashtables [main] [ 2019-09-04 10:31:54.761 AST ] [ResultSet.traceResultSet:902] Before return from checkDestLoc with #succNodes=1;#failNodes=0;#nodes=1 Overall Status->SUCCESSFUL Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.769 AST ] [ResultSet.addResultTable:465] addResultTable, called from: ClusterVerification.assertFrameworkSetup:10578 [main] [ 2019-09-04 10:31:54.769 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '0' [main] [ 2019-09-04 10:31:54.770 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable [main] [ 2019-09-04 10:31:54.770 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.770 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.770 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.770 AST ] [VDMUtil.getCmd4RemExec:159] ==== getCmd4RemExec() called... [main] [ 2019-09-04 10:31:54.770 AST ] [VDMUtil.getCmd4RemExec:166] ==== PROP_REM_COMMAND = 'exectask.sh' [main] [ 2019-09-04 10:31:54.774 AST ] [VerificationUtil.getCmd4RemExec:4736] ==== Remote Exec name: exectask.sh [main] [ 2019-09-04 10:31:54.774 AST ] [VerificationUtil.isLocalNodeOperation:10321] Returning saved value of: true [main] [ 2019-09-04 10:31:54.774 AST ] [VerificationUtil.getDestLoc:4616] ==== CV_DESTLOC(pre-fetched value): '/var/tmp/' [main] [ 2019-09-04 10:31:54.774 AST ] [NativeResult.:93] NativeResult: The String obtained is0 [main] [ 2019-09-04 10:31:54.774 AST ] [NativeResult.:101] The status string is: 0 [main] [ 2019-09-04 10:31:54.775 AST ] [RemoteExecCommand.:820] End of constructor call (called by many other constructors internally): RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String srcLoc, String[] remExecServerFiles, String destLoc, boolean chkException [main] [ 2019-09-04 10:31:54.775 AST ] [RemoteExecCommand.:719] End of constructor call: RemoteExecCommand(String cmd, String[] args, String[] env, String node, boolean localExecution, String[] cmdFiles, String[] remExecFiles, String destLoc [main] [ 2019-09-04 10:31:54.775 AST ] [RemoteExecCommand.setSubDirAndGroup:1736] Calling setSubDirAndGroup(String subDir, String group) with 'subDir ='CVU_12.2.0.1.0_grid' and 'group = 'null [main] [ 2019-09-04 10:31:54.775 AST ] [VerificationCommand.checkAndSetLocalExecution:294] Setting local execution to TRUE for this command on node (racnode1) [main] [ 2019-09-04 10:31:54.775 AST ] [RemoteExecCommand.setLocalExecution:1720] Changed ivar value for m_localExecution to true [main] [ 2019-09-04 10:31:54.776 AST ] [RemoteExecCommand.setArgs:1677] Setting value for ivar 'm_args' [main] [ 2019-09-04 10:31:54.776 AST ] [ResultSet.traceResultSet:902] ResultSet BEFORE adding Result data ===> Overall Status->UNKNOWN Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: false [main] [ 2019-09-04 10:31:54.777 AST ] [ResultSet.traceResultSet:902] ResultSet AFTER adding Result data ===> Overall Status->SUCCESSFUL Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.777 AST ] [ClusterConfig.isClusterInstalled:373] hasJarPresent=true [main] [ 2019-09-04 10:31:54.777 AST ] [GetActiveNodes.create:226] Returning an existing instance of GetActiveNodes [main] [ 2019-09-04 10:31:54.777 AST ] [ClusterConfig.init:437] Returning same instance to clientmain [main] [ 2019-09-04 10:31:54.777 AST ] [ClusterConfig.submit:502] Entering submit, cmdCount=1 [main] [ 2019-09-04 10:31:54.777 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread main m_count=4 [main] [ 2019-09-04 10:31:54.777 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread main m_count=1 [Worker 1] [ 2019-09-04 10:31:54.777 AST ] [Semaphore.release:85] SyncBufferEmpty:Release called by thread Worker 1 m_count=4 [Worker 1] [ 2019-09-04 10:31:54.777 AST ] [CheckDiskAFDCapableCommand.execute:68] CheckDiskAFDCapableCommand::Inside execute() Worker 1 [Worker 1] [ 2019-09-04 10:31:54.777 AST ] [VerificationCommand.execute:331] :: Inside execute() [Thread: [Worker 1] [ 2019-09-04 10:31:54.777 AST ] [RemoteExecCommand.validateCmdArgs:1294] Calling validateCmdArgs [Worker 1] [ 2019-09-04 10:31:54.778 AST ] [RemoteExecCommand.validateCmdArgs:1301] Checking for arguments validity [Worker 1] [ 2019-09-04 10:31:54.778 AST ] [RemoteExecCommand.executeInternal:1235] Calling executeInternal() [Worker 1] [ 2019-09-04 10:31:54.778 AST ] [RemoteExecCommand.executeInternal:1251] executing the command: '/var/tmp/CVU_12.2.0.1.0_grid/exectask.sh' with args '-checkAFDCapable /dev/rdsk/c1t2d0s6 ', 'm_stdin == null ->true', 'm_localExecution ->true', 'm_chkException ->false' [Worker 1] [ 2019-09-04 10:31:54.778 AST ] [NativeSystem.isCmdScv:547] isCmdScv: cmd=[] [Worker 1] [ 2019-09-04 10:31:54.778 AST ] [UnixSystem.dorunRemoteExecCmd:4180] Final unix SSH command: /var/tmp/CVU_12.2.0.1.0_grid/exectask.sh -checkAFDCapable /dev/rdsk/c1t2d0s6 [Worker 1] [ 2019-09-04 10:31:54.783 AST ] [RuntimeExec.runCommand:296] runCommand: Waiting for the process [Thread-59] [ 2019-09-04 10:31:54.785 AST ] [StreamReader.run:62] In StreamReader.run [Thread-58] [ 2019-09-04 10:31:54.785 AST ] [StreamReader.run:62] In StreamReader.run [Thread-58] [ 2019-09-04 10:31:54.802 AST ] [StreamReader.run:66] OUTPUT>00/var/tmp/CVU_12.2.0.1.0_grid/exectask -checkAFDCapable /dev/rdsk/c1t2d0s6 racnode1.testdomain.comExectask: Disk AFD capable check successful [Worker 1] [ 2019-09-04 10:31:54.803 AST ] [RuntimeExec.runCommand:298] runCommand: process returns 0 [Worker 1] [ 2019-09-04 10:31:54.803 AST ] [RuntimeExec.runCommand:325] RunTimeExec: error> [Worker 1] [ 2019-09-04 10:31:54.803 AST ] [RuntimeExec.runCommand:351] Returning from RunTimeExec.runCommand [Worker 1] [ 2019-09-04 10:31:54.803 AST ] [UnixSystem.dorunRemoteExecCmd:4192] retval = 0 [Worker 1] [ 2019-09-04 10:31:54.803 AST ] [UnixSystem.dorunRemoteExecCmd:4216] exitValue = 0 [Worker 1] [ 2019-09-04 10:31:54.803 AST ] [RemoteExecCommand.executeInternal:1282] cmdSuccess status: true [Worker 1] [ 2019-09-04 10:31:54.803 AST ] [RemoteExecCommand.execute:1052] cmdSuccess status: true [Worker 1] [ 2019-09-04 10:31:54.803 AST ] [VerificationCommand.fetchExecutionLogDetails:1130] cmdArr=outputArr=exitValArr= [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [VerificationUtil.fetchError:4074] No errors to return. [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:0 [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [VerificationCommand.execute:376] VfyCode is: 0 [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:0 [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:0 [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [VerificationUtil.fetchTextByTags:3963] Tags and contains:0 [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [ClusterConfig$ExecuteCommand.returnCommandToClient:3301] returnCommandToClient; fillCount=0 is full=false [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [Semaphore.acquire:109] SyncBufferEmpty:Acquire called by thread Worker 1 m_count=50 [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [Semaphore.release:85] SyncBufferFull:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [ClientResource.getListener:157] Calling getListener [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [ClusterConfig$ExecuteCommand.run:3396] Owner Thread name of the blocking Semaphore main [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [ClusterConfig$ExecuteCommand.run:3404] Obtained Semaphore [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [Semaphore.release:85] ClientResource Constructor:Blocking Semaphore owned by main:Release called by thread Worker 1 m_count=1 [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [ClusterConfig$ExecuteCommand.run:3419] Released Semaphore by worker=Worker 1 [Worker 1] [ 2019-09-04 10:31:54.804 AST ] [Semaphore.acquire:109] SyncBufferFull:Acquire called by thread Worker 1 m_count=0 [main] [ 2019-09-04 10:31:54.804 AST ] [ClusterConfig.submit:537] submitted commands=1 [main] [ 2019-09-04 10:31:54.804 AST ] [ClusterConfig.block:610] block called by thread main commandNum 1 [main] [ 2019-09-04 10:31:54.805 AST ] [Semaphore.acquire:109] ClientResource Constructor:Blocking Semaphore owned by main:Acquire called by thread main m_count=1 [main] [ 2019-09-04 10:31:54.805 AST ] [ClusterConfig.block:622] block acquired semnum=0 [main] [ 2019-09-04 10:31:54.805 AST ] [ClusterConfig.submit:571] Out of block [main] [ 2019-09-04 10:31:54.805 AST ] [ClusterConfig.submit:588] status=true [main] [ 2019-09-04 10:31:54.805 AST ] [ClusterConfig.destroy:466] destroying resources for client thread Thread[main,5,main] [main] [ 2019-09-04 10:31:54.805 AST ] [GlobalExecution.dumpTraceInfo:1472] ---- Execution Trace for checkDiskAFDCapable from node: racnode1 ----- [main] [ 2019-09-04 10:31:54.805 AST ] [GlobalExecution.dumpTraceInfo:1480] ::Inside execute() [main] [ 2019-09-04 10:31:54.805 AST ] [GlobalExecution.dumpTraceInfo:1480] Disk is AFD capable [main] [ 2019-09-04 10:31:54.805 AST ] [GlobalExecution.checkDiskAFDCapable:747] The disk (/dev/rdsk/c1t2d0s6) was found AFD capable on node racnode1 [main] [ 2019-09-04 10:31:54.805 AST ] [ResultSet.addResultTable:465] addResultTable, called from: GlobalExecution.checkDiskAFDCapable:774 [main] [ 2019-09-04 10:31:54.805 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '0' [main] [ 2019-09-04 10:31:54.805 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable [main] [ 2019-09-04 10:31:54.805 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.806 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.806 AST ] [ResultSet.setStatus:369] m_resultTable has size of zero, setting m_status to: UNKNOWN [main] [ 2019-09-04 10:31:54.807 AST ] [CVUVariables.secureVariableValueTrace:715] getting CVUVariableConstant : VAR = MODE_API VAL = TRUE [main] [ 2019-09-04 10:31:54.807 AST ] [ResultSet.traceResultSet:902] Target ResultSet AFTER Upload===> Overall Status->UNKNOWN Uploaded Overall Status->SUCCESSFUL GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.811 AST ] [ResultSet.addResultSetData:770] addResultSetData, called from: ClusterVerification.checkDevicesAsmFilterDriverCapable:3536 [main] [ 2019-09-04 10:31:54.811 AST ] [ResultSet.traceResultSet:902] ResultSet BEFORE adding ResultSet data ===> Overall Status->UNKNOWN Uploaded Overall Status->SUCCESSFUL GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.812 AST ] [ResultSet.traceResultSet:902] Source ResultSet ===> Overall Status->SUCCESSFUL Uploaded Overall Status->UNKNOWN GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.812 AST ] [ResultSet.traceResultSet:902] ResultSet AFTER adding ResultSet data ===> Overall Status->SUCCESSFUL Uploaded Overall Status->SUCCESSFUL GlobalErrors: UploadedGlobalErrors: HasNodeResults: true [main] [ 2019-09-04 10:31:54.812 AST ] [ResultSet.addResultTable:465] addResultTable, called from: UsmcaUtil.isAllDisksAFDCapable:2463 [main] [ 2019-09-04 10:31:54.812 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '0' [main] [ 2019-09-04 10:31:54.812 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable [main] [ 2019-09-04 10:31:54.812 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.832 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.832 AST ] [ResultSet.addResultTable:465] addResultTable, called from: UsmcaUtil.isAllDisksAFDCapable:2463 [main] [ 2019-09-04 10:31:54.832 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '1' [main] [ 2019-09-04 10:31:54.832 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.832 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.832 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.833 AST ] [ResultSet.addResultTable:465] addResultTable, called from: UsmcaUtil.isAllDisksAFDCapable:2464 [main] [ 2019-09-04 10:31:54.833 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '0' [main] [ 2019-09-04 10:31:54.833 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable [main] [ 2019-09-04 10:31:54.833 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.833 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.833 AST ] [ResultSet.addResultTable:465] addResultTable, called from: UsmcaUtil.isAllDisksAFDCapable:2464 [main] [ 2019-09-04 10:31:54.833 AST ] [ResultSet.addResultTable:468] Adding source result table size: '1' to target result table size: '1' [main] [ 2019-09-04 10:31:54.838 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable BEFORE ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.838 AST ] [ResultSet.traceResultTable:927] SOURCE ResultTable to ADD ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.838 AST ] [ResultSet.traceResultTable:927] TARGET ResultTable AFTER ===> contents of resultTable Dumping Result data. Status : SUCCESSFUL Name : racnode1 Type : Node Has Results: No Exp. value : null Act. value : null Errors : [main] [ 2019-09-04 10:31:54.838 AST ] [UsmcaUtil.isAllDisksAFDCapable:2476] null [main] [ 2019-09-04 10:31:54.839 AST ] [UsmcaUtil.isAllDisksAFDCapable:2478] OverallStatus SUCCESSFUL [main] [ 2019-09-04 10:31:54.839 AST ] [ResultSet.getNodeResults:1947] ResultList size: 1 localList size: 1 [main] [ 2019-09-04 10:31:54.840 AST ] [UsmcaUtil.isAllDisksAFDCapable:2486] NodeResultStatus SUCCESSFUL [main] [ 2019-09-04 10:31:54.841 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.backend.USMInstance Method : createASMInitFile [main] [ 2019-09-04 10:31:54.841 AST ] [USMInstance.createASMInitFile:4174] creating init file /u01/app/12.2.0.1/setup/dbs/init+ASM1.ora [main] [ 2019-09-04 10:31:54.848 AST ] [InitParamAttributes.sortParams:3986] m_sortOn:-1 sortOn:4 [main] [ 2019-09-04 10:31:54.851 AST ] [InitParamAttributes.createInitFile:1877] Processing init param asm_diskstring [main] [ 2019-09-04 10:31:54.851 AST ] [InitParamAttributes.createInitFile:1882] The value is '/dev/rdsk/*','AFD:*' [main] [ 2019-09-04 10:31:54.852 AST ] [InitParamAttributes.createInitFile:1877] Processing init param asm_power_limit [main] [ 2019-09-04 10:31:54.852 AST ] [InitParamAttributes.createInitFile:1882] The value is 1 [main] [ 2019-09-04 10:31:54.852 AST ] [InitParamAttributes.createInitFile:1877] Processing init param large_pool_size [main] [ 2019-09-04 10:31:54.852 AST ] [InitParamAttributes.createInitFile:1882] The value is 12M [main] [ 2019-09-04 10:31:54.852 AST ] [InitParamAttributes.createInitFile:1877] Processing init param remote_login_passwordfile [main] [ 2019-09-04 10:31:54.852 AST ] [InitParamAttributes.createInitFile:1882] The value is EXCLUSIVE [main] [ 2019-09-04 10:31:54.853 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.backend.USMInstance Method : createASMInitFile [main] [ 2019-09-04 10:31:54.854 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.backend.USMInstance Method : createSQLEngine [main] [ 2019-09-04 10:31:54.854 AST ] [SQLEngine.done:2314] Done called [main] [ 2019-09-04 10:31:54.952 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: null [main] [ 2019-09-04 10:31:54.956 AST ] [InventoryUtil.getOUIInvSession:349] setting OUI READ level to ACCESSLEVEL_READ_LOCKLESS [main] [ 2019-09-04 10:31:54.956 AST ] [OracleHome.getVersion:1037] Homeinfo /u01/app/12.2.0.1/setup,1 [main] [ 2019-09-04 10:31:55.096 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: null [main] [ 2019-09-04 10:31:55.096 AST ] [OracleHome.getVersion:1093] using sqlplus: /u01/app/12.2.0.1/setup/bin/sqlplus [main] [ 2019-09-04 10:31:55.096 AST ] [OracleHome.getVersion:1125] adding oracle home to sqlplus env [main] [ 2019-09-04 10:31:55.097 AST ] [OracleHome.getVersion:1129] LD_LIBRARY_PATH=/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/network/lib:.:/usr/jdk/packages/lib/amd64:/lib/64:/usr/lib/64 [main] [ 2019-09-04 10:31:55.097 AST ] [OracleHome.getVersion:1129] ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:55.138 AST ] [OracleHome.getVersion:1134] /u01/app/12.2.0.1/setup/bin/sqlplus Banner: SQL*Plus: Release 12.2.0.1.0 Production [main] [ 2019-09-04 10:31:55.138 AST ] [OracleHome.getVersion:1152] Current version from sqlplus: 12.2.0.1.0 [main] [ 2019-09-04 10:31:55.139 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: 12.2.0.1.0 [main] [ 2019-09-04 10:31:55.139 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: 12.2.0.1.0 [main] [ 2019-09-04 10:31:55.139 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: 12.2.0.1.0 [main] [ 2019-09-04 10:31:55.139 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: 12.2.0.1.0 [main] [ 2019-09-04 10:31:55.139 AST ] [SQLPlusEngine.getCmmdParams:226] m_home 12.2.0.1.0 [main] [ 2019-09-04 10:31:55.139 AST ] [SQLPlusEngine.getCmmdParams:227] version > 112 true [main] [ 2019-09-04 10:31:55.139 AST ] [SQLEngine.getEnvParams:607] Default NLS_LANG: AMERICAN_AMERICA.AL32UTF8 [main] [ 2019-09-04 10:31:55.139 AST ] [SQLEngine.getEnvParams:617] NLS_LANG: AMERICAN_AMERICA.AL32UTF8 [main] [ 2019-09-04 10:31:55.142 AST ] [SQLEngine.initialize:363] Execing SQLPLUS/SVRMGR process... [main] [ 2019-09-04 10:31:55.168 AST ] [SQLEngine.initialize:400] m_bReaderStarted: false [main] [ 2019-09-04 10:31:55.168 AST ] [SQLEngine.initialize:404] Starting Reader Thread... [main] [ 2019-09-04 10:31:55.169 AST ] [SQLEngine.initialize:453] Waiting for m_bReaderStarted to be true [main] [ 2019-09-04 10:31:55.193 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.backend.USMInstance Method : createSQLEngine [main] [ 2019-09-04 10:31:55.193 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: null [main] [ 2019-09-04 10:31:55.218 AST ] [InventoryUtil.getOUIInvSession:349] setting OUI READ level to ACCESSLEVEL_READ_LOCKLESS [main] [ 2019-09-04 10:31:55.218 AST ] [OracleHome.getVersion:1037] Homeinfo /u01/app/12.2.0.1/setup,1 [main] [ 2019-09-04 10:31:55.452 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: null [main] [ 2019-09-04 10:31:55.452 AST ] [OracleHome.getVersion:1093] using sqlplus: /u01/app/12.2.0.1/setup/bin/sqlplus [main] [ 2019-09-04 10:31:55.452 AST ] [OracleHome.getVersion:1125] adding oracle home to sqlplus env [main] [ 2019-09-04 10:31:55.453 AST ] [OracleHome.getVersion:1129] LD_LIBRARY_PATH=/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/network/lib:.:/usr/jdk/packages/lib/amd64:/lib/64:/usr/lib/64 [main] [ 2019-09-04 10:31:55.453 AST ] [OracleHome.getVersion:1129] ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:55.484 AST ] [OracleHome.getVersion:1134] /u01/app/12.2.0.1/setup/bin/sqlplus Banner: SQL*Plus: Release 12.2.0.1.0 Production [main] [ 2019-09-04 10:31:55.484 AST ] [OracleHome.getVersion:1152] Current version from sqlplus: 12.2.0.1.0 [main] [ 2019-09-04 10:31:55.484 AST ] [UsmcaLogger.logInfo:156] Role SYSASM [main] [ 2019-09-04 10:31:55.484 AST ] [UsmcaLogger.logInfo:156] OS Auth true [main] [ 2019-09-04 10:31:56.526 AST ] [UsmcaLogger.logInfo:156] Shutdown running instance, if any. [main] [ 2019-09-04 10:31:59.628 AST ] [UsmcaLogger.logEntry:131] Entering oracle.sysman.assistants.usmca.backend.USMInstance Method : createSQLEngine [main] [ 2019-09-04 10:31:59.629 AST ] [SQLEngine.done:2314] Done called [main] [ 2019-09-04 10:31:59.640 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: null [main] [ 2019-09-04 10:31:59.644 AST ] [InventoryUtil.getOUIInvSession:349] setting OUI READ level to ACCESSLEVEL_READ_LOCKLESS [main] [ 2019-09-04 10:31:59.644 AST ] [OracleHome.getVersion:1037] Homeinfo /u01/app/12.2.0.1/setup,1 [main] [ 2019-09-04 10:31:59.838 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: null [main] [ 2019-09-04 10:31:59.839 AST ] [OracleHome.getVersion:1093] using sqlplus: /u01/app/12.2.0.1/setup/bin/sqlplus [main] [ 2019-09-04 10:31:59.839 AST ] [OracleHome.getVersion:1125] adding oracle home to sqlplus env [main] [ 2019-09-04 10:31:59.839 AST ] [OracleHome.getVersion:1129] LD_LIBRARY_PATH=/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/network/lib:.:/usr/jdk/packages/lib/amd64:/lib/64:/usr/lib/64 [main] [ 2019-09-04 10:31:59.839 AST ] [OracleHome.getVersion:1129] ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:31:59.944 AST ] [OracleHome.getVersion:1134] /u01/app/12.2.0.1/setup/bin/sqlplus Banner: SQL*Plus: Release 12.2.0.1.0 Production [main] [ 2019-09-04 10:31:59.945 AST ] [OracleHome.getVersion:1152] Current version from sqlplus: 12.2.0.1.0 [main] [ 2019-09-04 10:31:59.945 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: 12.2.0.1.0 [main] [ 2019-09-04 10:31:59.945 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: 12.2.0.1.0 [main] [ 2019-09-04 10:31:59.945 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: 12.2.0.1.0 [main] [ 2019-09-04 10:31:59.945 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: 12.2.0.1.0 [main] [ 2019-09-04 10:31:59.945 AST ] [SQLPlusEngine.getCmmdParams:226] m_home 12.2.0.1.0 [main] [ 2019-09-04 10:31:59.945 AST ] [SQLPlusEngine.getCmmdParams:227] version > 112 true [main] [ 2019-09-04 10:31:59.945 AST ] [SQLEngine.getEnvParams:607] Default NLS_LANG: AMERICAN_AMERICA.AL32UTF8 [main] [ 2019-09-04 10:31:59.946 AST ] [SQLEngine.getEnvParams:617] NLS_LANG: AMERICAN_AMERICA.AL32UTF8 [main] [ 2019-09-04 10:31:59.946 AST ] [SQLEngine.initialize:363] Execing SQLPLUS/SVRMGR process... [main] [ 2019-09-04 10:31:59.980 AST ] [SQLEngine.initialize:400] m_bReaderStarted: false [main] [ 2019-09-04 10:31:59.980 AST ] [SQLEngine.initialize:404] Starting Reader Thread... [main] [ 2019-09-04 10:31:59.982 AST ] [SQLEngine.initialize:453] Waiting for m_bReaderStarted to be true [main] [ 2019-09-04 10:32:00.009 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.backend.USMInstance Method : createSQLEngine [main] [ 2019-09-04 10:32:00.009 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: null [main] [ 2019-09-04 10:32:00.011 AST ] [InventoryUtil.getOUIInvSession:349] setting OUI READ level to ACCESSLEVEL_READ_LOCKLESS [main] [ 2019-09-04 10:32:00.011 AST ] [OracleHome.getVersion:1037] Homeinfo /u01/app/12.2.0.1/setup,1 [main] [ 2019-09-04 10:32:00.189 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: null [main] [ 2019-09-04 10:32:00.189 AST ] [OracleHome.getVersion:1093] using sqlplus: /u01/app/12.2.0.1/setup/bin/sqlplus [main] [ 2019-09-04 10:32:00.189 AST ] [OracleHome.getVersion:1125] adding oracle home to sqlplus env [main] [ 2019-09-04 10:32:00.189 AST ] [OracleHome.getVersion:1129] LD_LIBRARY_PATH=/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/lib:/u01/app/12.2.0.1/setup/network/lib:.:/usr/jdk/packages/lib/amd64:/lib/64:/usr/lib/64 [main] [ 2019-09-04 10:32:00.189 AST ] [OracleHome.getVersion:1129] ORACLE_HOME=/u01/app/12.2.0.1/setup [main] [ 2019-09-04 10:32:00.227 AST ] [OracleHome.getVersion:1134] /u01/app/12.2.0.1/setup/bin/sqlplus Banner: SQL*Plus: Release 12.2.0.1.0 Production [main] [ 2019-09-04 10:32:00.227 AST ] [OracleHome.getVersion:1152] Current version from sqlplus: 12.2.0.1.0 [main] [ 2019-09-04 10:32:00.228 AST ] [UsmcaLogger.logInfo:156] Role SYSASM [main] [ 2019-09-04 10:32:00.228 AST ] [UsmcaLogger.logInfo:156] OS Auth true [main] [ 2019-09-04 10:32:45.788 AST ] [SQLEngine.done:2314] Done called [main] [ 2019-09-04 10:32:45.797 AST ] [USMInstance.configureLocalASM:3367] ORA-03113: end-of-file on communication channel [main] [ 2019-09-04 10:32:45.797 AST ] [SQLEngine.reInitialize:806] Reinitializing SQLEngine... [main] [ 2019-09-04 10:32:45.798 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: 12.2.0.1.0 [main] [ 2019-09-04 10:32:45.798 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: 12.2.0.1.0 [main] [ 2019-09-04 10:32:45.798 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: 12.2.0.1.0 [main] [ 2019-09-04 10:32:45.798 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: 12.2.0.1.0 [main] [ 2019-09-04 10:32:45.798 AST ] [OracleHome.getVersion:1018] OracleHome.getVersion called. Current Version: 12.2.0.1.0 [main] [ 2019-09-04 10:32:45.799 AST ] [OracleHome.getVersion:1086] Current Version From Inventory: 12.2.0.1.0 [main] [ 2019-09-04 10:32:45.799 AST ] [SQLPlusEngine.getCmmdParams:226] m_home 12.2.0.1.0 [main] [ 2019-09-04 10:32:45.799 AST ] [SQLPlusEngine.getCmmdParams:227] version > 112 true [main] [ 2019-09-04 10:32:45.799 AST ] [SQLEngine.getEnvParams:607] Default NLS_LANG: AMERICAN_AMERICA.AL32UTF8 [main] [ 2019-09-04 10:32:45.799 AST ] [SQLEngine.getEnvParams:617] NLS_LANG: AMERICAN_AMERICA.AL32UTF8 [main] [ 2019-09-04 10:32:45.799 AST ] [SQLEngine.initialize:363] Execing SQLPLUS/SVRMGR process... [main] [ 2019-09-04 10:32:45.820 AST ] [SQLEngine.initialize:400] m_bReaderStarted: false [main] [ 2019-09-04 10:32:45.820 AST ] [SQLEngine.initialize:404] Starting Reader Thread... [main] [ 2019-09-04 10:32:45.820 AST ] [SQLEngine.initialize:453] Waiting for m_bReaderStarted to be true [main] [ 2019-09-04 10:32:46.973 AST ] [SQLEngine.done:2314] Done called [main] [ 2019-09-04 10:32:46.974 AST ] [UsmcaLogger.logException:186] SEVERE:method oracle.sysman.assistants.usmca.backend.USMInstance:configureLocalASM [main] [ 2019-09-04 10:32:46.974 AST ] [UsmcaLogger.logException:187] ORA-01012: not logged on [main] [ 2019-09-04 10:32:46.974 AST ] [UsmcaLogger.logException:188] oracle.sysman.assistants.util.sqlEngine.SQLFatalErrorException: ORA-01012: not logged on oracle.sysman.assistants.util.sqlEngine.SQLEngine.executeImpl(SQLEngine.java:1767) oracle.sysman.assistants.util.sqlEngine.SQLEngine.executeQuery(SQLEngine.java:899) oracle.sysman.assistants.usmca.backend.USMInstance.configureLocalASM(USMInstance.java:3371) oracle.sysman.assistants.usmca.service.UsmcaService.configureLocalASM(UsmcaService.java:1349) oracle.sysman.assistants.usmca.model.UsmcaModel.performConfigureLocalASM(UsmcaModel.java:1110) oracle.sysman.assistants.usmca.model.UsmcaModel.performOperation(UsmcaModel.java:906) oracle.sysman.assistants.usmca.Usmca.execute(Usmca.java:320) oracle.sysman.assistants.usmca.Usmca.main(Usmca.java:653) [main] [ 2019-09-04 10:32:47.083 AST ] [UsmcaLogger.logException:186] SEVERE:method oracle.sysman.assistants.usmca.backend.USMInstance:configureLocalASM [main] [ 2019-09-04 10:32:47.083 AST ] [UsmcaLogger.logException:187] ORA-03113: end-of-file on communication channel [main] [ 2019-09-04 10:32:47.084 AST ] [UsmcaLogger.logException:188] oracle.sysman.assistants.util.sqlEngine.SQLFatalErrorException: ORA-03113: end-of-file on communication channel oracle.sysman.assistants.util.sqlEngine.SQLEngine.executeImpl(SQLEngine.java:1767) oracle.sysman.assistants.util.sqlEngine.SQLEngine.startup(SQLEngine.java:2209) oracle.sysman.assistants.usmca.backend.USMInstance.configureLocalASM(USMInstance.java:3361) oracle.sysman.assistants.usmca.service.UsmcaService.configureLocalASM(UsmcaService.java:1349) oracle.sysman.assistants.usmca.model.UsmcaModel.performConfigureLocalASM(UsmcaModel.java:1110) oracle.sysman.assistants.usmca.model.UsmcaModel.performOperation(UsmcaModel.java:906) oracle.sysman.assistants.usmca.Usmca.execute(Usmca.java:320) oracle.sysman.assistants.usmca.Usmca.main(Usmca.java:653) [main] [ 2019-09-04 10:32:47.084 AST ] [UsmcaLogger.logInfo:156] ASM failed to start. Check /u01/app/grid/cfgtoollogs/asmca/asmca-190904AM103145.log for details. [main] [ 2019-09-04 10:32:47.084 AST ] [UsmcaLogger.logInfo:156] Instance running false [main] [ 2019-09-04 10:32:47.084 AST ] [UsmcaLogger.logInfo:156] ASM failed to start. Check /u01/app/grid/cfgtoollogs/asmca/asmca-190904AM103145.log for details. [main] [ 2019-09-04 10:32:47.084 AST ] [OsUtilsBase.deleteFile:1832] OsUtilsBase.deleteFile: /u01/app/12.2.0.1/setup/dbs/init+ASM1.ora [main] [ 2019-09-04 10:32:47.085 AST ] [UsmcaLogger.logInfo:156] deleting temp ora file. for sid: /u01/app/12.2.0.1/setup/dbs/init+ASM1.ora [main] [ 2019-09-04 10:32:47.085 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.backend.USMInstance Method : configureLocalASM [main] [ 2019-09-04 10:32:47.085 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.model.UsmcaModel Method : performConfigureLocalASM [main] [ 2019-09-04 10:32:47.085 AST ] [UsmcaLogger.logExit:139] Exiting oracle.sysman.assistants.usmca.model.UsmcaModel Method : performOperation