Troubleshooting a failure when upgrading to Oracle 18c

Posted in: Technical Track

WhenI was upgrading Grid to 18c, the final step was to run gridSetup.sh -executeConfigTools, which failed. Unfortunately, the error provided was not very descriptive or useful. In this post, I will demonstrate how I went about troubleshooting the failure.

To start the 18c upgrade, run script gridSetup_applyRU.sh

(Please note: I have scripted the process.)

[oracle@racnode-dc1-1 ~]$ /media/patch/gridSetup_applyRU.sh
+ . /media/patch/gi.env
++ set +x
The Oracle base has been set to /u01/app/oracle
ORACLE_SID=+ASM1
ORACLE_BASE=/u01/app/oracle
GRID_HOME=/u01/app/12.1.0.1/grid
ORACLE_HOME=/u01/app/12.1.0.1/grid
Oracle Instance alive for sid "+ASM1"
+ crsctl query crs releaseversion
Oracle High Availability Services release version on the local node is [12.1.0.2.0]
+ crsctl query crs softwareversion
Oracle Clusterware version on node [racnode-dc1-1] is [12.1.0.2.0]
+ crsctl query crs softwarepatch
Oracle Clusterware patch level on node racnode-dc1-1 is [1721139106].
+ crsctl query crs releasepatch
Oracle Clusterware release patch level is [1721139106] and the complete list of patches [20243804 20415006 20594149 20788771 20950328 21125181 21359749 21527488 21694919 21949015 22806133 23144544 24340679 24732088 25397136 25869760 26609798 26717470 26925263 26983807 27338029 27547374 28259867 28729213 28729220 28731800 ] have been applied on the local node.
+ crsctl query crs activeversion -f
Oracle Clusterware active version on the cluster is [12.1.0.2.0]. The cluster upgrade state is [NORMAL]. The cluster active patch level is [1721139106].
+ exit
+ unset ORACLE_HOME ORACLE_BASE ORACLE_SID GRID_HOME ORACLE_UNQNAME
+ env
+ egrep -i 'ora|home'
USER=oracle
PATH=/usr/local/bin:/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/home/oracle/.local/bin:/home/oracle/bin
MAIL=/var/spool/mail/oracle
PWD=/home/oracle
HOME=/home/oracle
LOGNAME=oracle
+ cat /etc/oratab
#Backup file is  /u01/app/12.1.0.1/grid/srvm/admin/oratab.bak.racnode-dc1-1 line added by Agent
+ASM1:/u01/app/12.1.0.1/grid:N
hawk1:/u01/app/oracle/12.1.0.1/db1:N
hawk:/u01/app/oracle/12.1.0.1/db1:N             # line added by Agent
-MGMTDB:/u01/app/12.1.0.1/grid:N                # line added by Agent
+ ssh racnode-dc1-2 'ls -lh /u01/18.3.0.0/grid'
total 0
+ ssh racnode-dc1-2 'cat /etc/oratab'
#Backup file is  /u01/app/oracle/12.1.0.1/db1/srvm/admin/oratab.bak.racnode-dc1-2 line added by Agent
+ASM2:/u01/app/12.1.0.1/grid:N
hawk2:/u01/app/oracle/12.1.0.1/db1:N
-MGMTDB:/u01/app/12.1.0.1/grid:N                # line added by Agent
hawk:/u01/app/oracle/12.1.0.1/db1:N             # line added by Agent
+ ls -lh /media/patch/Jan2019/28828717
total 128K
drwxrwxrwx 1 vagrant vagrant    0 Feb 27 19:24 28435192
drwxrwxrwx 1 vagrant vagrant    0 Feb 27 19:24 28547619
drwxrwxrwx 1 vagrant vagrant    0 Feb 27 19:26 28822489
drwxrwxrwx 1 vagrant vagrant    0 Feb 27 19:27 28864593
drwxrwxrwx 1 vagrant vagrant    0 Feb 27 19:29 28864607
drwxrwxrwx 1 vagrant vagrant 4.0K Feb 27 19:26 automation
-rwxrwxrwx 1 vagrant vagrant 5.7K Jan  9 16:02 bundle.xml
-rwxrwxrwx 1 vagrant vagrant 115K Jan  9 15:43 README.html
-rwxrwxrwx 1 vagrant vagrant    0 Jan  9 23:37 README.txt

--------------------------------------------------------------------------------
+ /u01/18.3.0.0/grid/gridSetup.sh -silent -applyRU /media/patch/Jan2019/28828717 -responseFile /sf_OracleSoftware/18cLinux/gridsetup_upgrade.rsp -J-Doracle.install.mgmtDB=false -J-Doracle.install.mgmtDB.CDB=false -J Doracle.install.crs.enableRemoteGIMR=false
--------------------------------------------------------------------------------

Preparing the home to patch...
Applying the patch /media/patch/Jan2019/28828717...
Successfully applied the patch.
The log can be found at: /u01/app/oraInventory/logs/GridSetupActions2019-04-14_11-29-28PM/installerPatchActions_2019-04-14_11-29-28PM.log
Launching Oracle Grid Infrastructure Setup Wizard...

[WARNING] [INS-13014] Target environment does not meet some optional requirements.
   CAUSE: Some of the optional prerequisites are not met. See logs for details. 
   /u01/app/oraInventory/logs/GridSetupActions2019-04-14_11-29-28PM/gridSetupActions2019-04-14_11-29-28PM.log
   
   ACTION: Identify the list of failed prerequisite checks from the log: 
   /u01/app/oraInventory/logs/GridSetupActions2019-04-14_11-29-28PM/gridSetupActions2019-04-14_11-29-28PM.log. 
   Then either from the log file or from installation manual find the appropriate configuration to meet the prerequisites and fix it manually.
   
The response file for this session can be found at:
 /u01/18.3.0.0/grid/install/response/grid_2019-04-14_11-29-28PM.rsp

You can find the log of this install session at:
 /u01/app/oraInventory/logs/GridSetupActions2019-04-14_11-29-28PM/gridSetupActions2019-04-14_11-29-28PM.log

As a root user, execute the following script(s):
        1. /u01/18.3.0.0/grid/rootupgrade.sh

Execute /u01/18.3.0.0/grid/rootupgrade.sh on the following nodes:
[racnode-dc1-1, racnode-dc1-2]

Run the script on the local node first. After successful completion, you can start the script in parallel on all other nodes, except a node you designate as the last node. When all the nodes except the last node are done successfully, run the script on the last node.

Successfully Setup Software with warning(s).

--------------------------------------------------------------------------------
As install user, execute the following command to complete the configuration.
        /u01/18.3.0.0/grid/gridSetup.sh -executeConfigTools -responseFile /sf_OracleSoftware/18cLinux/gridsetup_upgrade.rsp [-silent]
--------------------------------------------------------------------------------

[oracle@racnode-dc1-1 ~]$

The last step: gridSetup.sh -executeConfigTools resulted in WARNINGS.

[oracle@racnode-dc1-1 ~]$ /u01/18.3.0.0/grid/gridSetup.sh -executeConfigTools -responseFile /sf_OracleSoftware/18cLinux/gridsetup_upgrade.rsp -silent
Launching Oracle Grid Infrastructure Setup Wizard...

--------------------------------------------------------------------------------
You can find the logs of this session at:
/u01/app/oraInventory/logs/GridSetupActions2019-04-15_01-02-06AM
--------------------------------------------------------------------------------

[WARNING] [INS-43080] Some of the configuration assistants failed, were cancelled or skipped.
   ACTION: Refer to the logs or contact Oracle Support Services.
[oracle@racnode-dc1-1 ~]$

Check directory: /u01/app/oraInventory/logs/GridSetupActions2019-04-15_01-02-06AM

[oracle@racnode-dc1-1 ~]$ cd /u01/app/oraInventory/logs/GridSetupActions2019-04-15_01-02-06AM


[oracle@racnode-dc1-1 GridSetupActions2019-04-15_01-02-06AM]$ ls -alrt
total 1072
-rw-r----- 1 oracle oinstall     129 Apr 15 01:02 installerPatchActions_2019-04-15_01-02-06AM.log
-rw-r----- 1 oracle oinstall       0 Apr 15 01:02 gridSetupActions2019-04-15_01-02-06AM.err
drwxrwx--- 5 oracle oinstall    4096 Apr 15 01:03 ..
-rw-r----- 1 oracle oinstall 1004340 Apr 15 01:03 gridSetupActions2019-04-15_01-02-06AM.out
-rw-r----- 1 oracle oinstall    2171 Apr 15 01:03 time2019-04-15_01-02-06AM.log
-rw-r----- 1 oracle oinstall   72336 Apr 15 01:03 gridSetupActions2019-04-15_01-02-06AM.log
drwxrwx--- 2 oracle oinstall    4096 Apr 15 01:03 .
[oracle@racnode-dc1-1 GridSetupActions2019-04-15_01-02-06AM]$

Check time2019-04-15_01-02-06AM.log was useful to identify failure.

[oracle@racnode-dc1-1 GridSetupActions2019-04-15_01-02-06AM]$ cat time2019-04-15_01-02-06AM.log
 # Message # ElapsedTime # Current Time ( ms )
 # Starting step:INITIALIZE_ACTION of state:init #  0  # 1555282933690
 # Finished step:INITIALIZE_ACTION of state:init # 0 # 1555282933690
 # Starting step:EXECUTE of state:init #  0  # 1555282933692
 # Finished step:EXECUTE of state:init # 3 # 1555282933696
 # Starting step:VALIDATE of state:init #  0  # 1555282933698
 # Finished step:VALIDATE of state:init # 3 # 1555282933701
 # Starting step:TRANSITION of state:init #  0  # 1555282933701
 # Finished step:TRANSITION of state:init # 2 # 1555282933703
 # Starting step:EXECUTE of state:CRSConfigTools #  0  # 1555282933703
 # Finished step:EXECUTE of state:CRSConfigTools # 714 # 1555282934417
 # Starting step:VALIDATE of state:CRSConfigTools #  0  # 1555282934418
 # Finished step:VALIDATE of state:CRSConfigTools # 0 # 1555282934418
 # Starting step:TRANSITION of state:CRSConfigTools #  0  # 1555282934418
 # Finished step:TRANSITION of state:CRSConfigTools # 20962 # 1555282955381
 # Starting step:INITIALIZE_ACTION of state:setup #  0  # 1555282955381
 # Finished step:INITIALIZE_ACTION of state:setup # 0 # 1555282955381
 # Starting step:EXECUTE of state:setup #  0  # 1555282955382
 # Finished step:EXECUTE of state:setup # 3 # 1555282955385
 # Configuration in progress. #  0  # 1555282958962
 # Update Inventory in progress. #  0  # 1555282959678
 # Update Inventory successful. # 41125 # 1555283000803
 # Upgrading RHP Repository in progress. #  0  # 1555283000839

--------------------------------------------------------------------------------
 # Upgrading RHP Repository failed. # 5904 # 1555283006743
-------------------------------------------------------------------------------- 

 # Starting step:VALIDATE of state:setup #  0  # 1555283006854
 # Finished step:VALIDATE of state:setup # 11 # 1555283006865
 # Starting step:TRANSITION of state:setup #  0  # 1555283006865
 # Finished step:TRANSITION of state:setup # 0 # 1555283006865
 # Starting step:EXECUTE of state:finish #  0  # 1555283006866
 # Finished step:EXECUTE of state:finish # 6 # 1555283006872
 # Starting step:VALIDATE of state:finish #  0  # 1555283006873
 # Finished step:VALIDATE of state:finish # 0 # 1555283006873
 # Starting step:TRANSITION of state:finish #  0  # 1555283006873
 # Finished step:TRANSITION of state:finish # 0 # 1555283006873
[oracle@racnode-dc1-1 GridSetupActions2019-04-15_01-02-06AM]$

Check gridSetupActions2019-04-15_01-02-06AM.log to find the same and Exit Status is -1

[oracle@racnode-dc1-1 GridSetupActions2019-04-15_01-02-06AM]$ grep -B2 -A100 'Executing RHPUPGRADE' gridSetupActions2019-04-15_01-02-06AM.log
INFO:  [Apr 15, 2019 1:03:20 AM] Starting 'Upgrading RHP Repository'
INFO:  [Apr 15, 2019 1:03:20 AM] Starting 'Upgrading RHP Repository'
INFO:  [Apr 15, 2019 1:03:20 AM] Executing RHPUPGRADE
INFO:  [Apr 15, 2019 1:03:20 AM] Command /u01/18.3.0.0/grid/bin/rhprepos upgradeSchema -fromversion 12.1.0.2.0
INFO:  [Apr 15, 2019 1:03:20 AM] ... GenericInternalPlugIn.handleProcess() entered.
INFO:  [Apr 15, 2019 1:03:20 AM] ... GenericInternalPlugIn: getting configAssistantParmas.
INFO:  [Apr 15, 2019 1:03:20 AM] ... GenericInternalPlugIn: checking secretArguments.
INFO:  [Apr 15, 2019 1:03:20 AM] No arguments to pass to stdin
INFO:  [Apr 15, 2019 1:03:20 AM] ... GenericInternalPlugIn: starting read loop.
INFO:  [Apr 15, 2019 1:03:26 AM] Completed Plugin named: rhpupgrade
INFO:  [Apr 15, 2019 1:03:26 AM] ConfigClient.saveSession method called
INFO:  [Apr 15, 2019 1:03:26 AM] Upgrading RHP Repository failed.
INFO:  [Apr 15, 2019 1:03:26 AM] Upgrading RHP Repository failed.
INFO:  [Apr 15, 2019 1:03:26 AM] ConfigClient.executeSelectedToolsInAggregate action performed
INFO:  [Apr 15, 2019 1:03:26 AM] Exiting ConfigClient.executeSelectedToolsInAggregate method
INFO:  [Apr 15, 2019 1:03:26 AM] Adding ExitStatus SUCCESS_MINUS_RECTOOL to the exit status set
INFO:  [Apr 15, 2019 1:03:26 AM] ConfigClient.saveSession method called
INFO:  [Apr 15, 2019 1:03:26 AM] Calling event ConfigSessionEnding
INFO:  [Apr 15, 2019 1:03:26 AM] ConfigClient.endSession method called
INFO:  [Apr 15, 2019 1:03:26 AM] Completed Configuration
INFO:  [Apr 15, 2019 1:03:26 AM] Adding ExitStatus FAILURE to the exit status set
INFO:  [Apr 15, 2019 1:03:26 AM] All forked task are completed at state setup
INFO:  [Apr 15, 2019 1:03:26 AM] Completed background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Validating state <setup>

--------------------------------------------------------------------------------
WARNING:  [Apr 15, 2019 1:03:26 AM] [WARNING] [INS-43080] Some of the configuration assistants failed, were cancelled or skipped.
   ACTION: Refer to the logs or contact Oracle Support Services.
--------------------------------------------------------------------------------

INFO:  [Apr 15, 2019 1:03:26 AM] Advice is CONTINUE
INFO:  [Apr 15, 2019 1:03:26 AM] Completed validating state <setup>
INFO:  [Apr 15, 2019 1:03:26 AM] Verifying route success
INFO:  [Apr 15, 2019 1:03:26 AM] Waiting for completion of background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Completed background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Waiting for completion of background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Completed background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Executing action at state finish
INFO:  [Apr 15, 2019 1:03:26 AM] FinishAction Actions.execute called
INFO:  [Apr 15, 2019 1:03:26 AM] Finding the most appropriate exit status for the current application
INFO:  [Apr 15, 2019 1:03:26 AM] Completed executing action at state <finish>
INFO:  [Apr 15, 2019 1:03:26 AM] Waiting for completion of background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Completed background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Waiting for completion of background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Completed background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Moved to state <finish>
INFO:  [Apr 15, 2019 1:03:26 AM] Waiting for completion of background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Completed background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Validating state <finish>
WARNING:  [Apr 15, 2019 1:03:26 AM] Validation disabled for the state finish
INFO:  [Apr 15, 2019 1:03:26 AM] Completed validating state <finish>
INFO:  [Apr 15, 2019 1:03:26 AM] Terminating all background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Terminated all background operations
INFO:  [Apr 15, 2019 1:03:26 AM] Successfully executed the flow in SILENT mode
INFO:  [Apr 15, 2019 1:03:26 AM] Finding the most appropriate exit status for the current application
INFO:  [Apr 15, 2019 1:03:26 AM] inventory location is/u01/app/oraInventory
INFO:  [Apr 15, 2019 1:03:26 AM] Finding the most appropriate exit status for the current application

--------------------------------------------------------------------------------
INFO:  [Apr 15, 2019 1:03:26 AM] Exit Status is -1
INFO:  [Apr 15, 2019 1:03:26 AM] Shutdown Oracle Grid Infrastructure 18c Installer
INFO:  [Apr 15, 2019 1:03:26 AM] Unloading Setup Driver
--------------------------------------------------------------------------------

INFO:  [Apr 15, 2019 1:03:26 AM] inventory location is/u01/app/oraInventory
[oracle@racnode-dc1-1 GridSetupActions2019-04-15_01-02-06AM]$

In conclusion, following the two steps provided may help to simply troubleshooting for gridSetup.sh -executeConfigTools failure since the information provided by the upgrade process is not very clear as to what logs need to be reviewed

1. Check time*.log to identify which step failed.
2. Check gridSetupActions*.log to identify more details.

 

email

Interested in working with Michael? Schedule a tech call.

No comments

Leave a Reply

Your email address will not be published. Required fields are marked *