In this blog post, I am going to describe a strange error with OPatch while I was trying to deploy a new Oracle Home to one of our VM clusters.
Table of Contents
Error
After 15 minutes, the deployment of my new Oracle Home failed with the following error message.
Database job: Failed. [FATAL] [DBAAS-60018] Unable to get patch version of oracle home '/u02/app/oracle/product/19.0.0.0/dbhome_2'.
ACTION: Make sure that home exist and registered to central inventory.
SUMMARY:
- [DBAAS-60018] Unable to get patch version of oracle home '/u02/app/oracle/product/19.0.0.0/dbhome_2'.
- [DBAAS-60022] Command '/u02/app/oracle/product/19.0.0.0/dbhome_2/OPatch/opatch lspatches|egrep -i 'DATABASE BUNDLE PATCH|DATABASE.*RELEASE|DAT... Operation failed with exit code 25...
In the last line, we can see the executed command. Unfortunately, you cannot execute this command to see what went wrong, because the Oracle Home is automatically removed when an error occurred.
Analysis
Logfiles of the Oracle Home deployment can be found on each cluster node in the directory /var/opt/oracle/log/dbaasapi/db/dbhome.
$> ls -ltr /var/opt/oracle/log/dbaasapi/db/dbhome
total 49232
...
lrwxrwxrwx 1 oracle oinstall 84 May 23 14:05 8c02b6a1-23fb-89bc-a354-36b1b1e83dec.log -> /var/opt/oracle/log/dbaasapi/db/dbhome/dbaasapi_2022-05-23_14:05:41.452680_76138.log
-rw-r----- 1 oracle oinstall 1864860 May 23 14:23 pilot_2022-05-23_02-05-54-PM
-rw-r----- 1 oracle oinstall 677821 May 23 14:24 pilot_2022-05-23_02-23-06-PM
-rw-rw---- 1 oracle oinstall 17925 May 23 14:24 dbaasapi_2022-05-23_14:05:41.452680_76138.log
lrwxrwxrwx 1 oracle oinstall 84 May 23 14:25 dfac3373-0f5e-12fe-b7a9-568ee28e4fc9.log -> /var/opt/oracle/log/dbaasapi/db/dbhome/dbaasapi_2022-05-23_14:25:10.908633_86157.log
-rw-rw---- 1 oracle oinstall 6741 May 23 14:25 dbaasapi_2022-05-23_14:25:10.908633_86157.log
lrwxrwxrwx 1 oracle oinstall 84 May 23 14:25 2aeb51e5-5ae3-47a3-9418-4d6c42aaf603.log -> /var/opt/oracle/log/dbaasapi/db/dbhome/dbaasapi_2022-05-23_14:25:34.823169_89702.log
-rw-rw---- 1 oracle oinstall 6740 May 23 14:25 dbaasapi_2022-05-23_14:25:34.823169_89702.log
Let’s start the analysis with the first dbaasapi logfile. This log file includes the executed steps of the Oracle Home deployment. There we will find the output of PILOT, the internally used workflow engine.
$> vi dbaasapi_2022-05-23_14:05:41.452680_76138.log
...
2022-05-23 14:05:53.071339 - Loading PILOT...
2022-05-23 14:05:54.346639 - Session ID of the current execution is: 53
2022-05-23 14:05:54.346806 - Log file location: /var/opt/oracle/log/dbaasapi/db/dbhome/pilot_2022-05-23_02-05-54-PM
2022-05-23 14:05:54.350684 - -----------------
2022-05-23 14:05:54.350817 - Running Plugin_initialization job
2022-05-23 14:07:00.793083 - Completed Plugin_initialization job
2022-05-23 14:07:01.200334 - -----------------
2022-05-23 14:07:01.200546 - Running OH_image_validate job
2022-05-23 14:07:20.055367 - Completed OH_image_validate job
2022-05-23 14:07:20.117264 - -----------------
2022-05-23 14:07:20.117508 - Running OH_image_download job
2022-05-23 14:07:20.117926 - Skipping. Job is detected as not applicable.
2022-05-23 14:07:20.163506 - -----------------
2022-05-23 14:07:20.163736 - Running OH_image_version_check job
2022-05-23 14:07:39.501370 - Completed OH_image_version_check job
2022-05-23 14:07:39.536829 - -----------------
2022-05-23 14:07:39.537124 - Running OH_pre_existence_check job
2022-05-23 14:07:40.737483 - Completed OH_pre_existence_check job
2022-05-23 14:07:40.777679 - -----------------
2022-05-23 14:07:40.777892 - Running Disk_space_check job
2022-05-23 14:09:07.097187 - Completed Disk_space_check job
2022-05-23 14:09:07.138680 - -----------------
2022-05-23 14:09:07.138917 - Running Cluster_nodes_check job
2022-05-23 14:09:07.139056 - Completed Cluster_nodes_check job
2022-05-23 14:09:07.177196 - -----------------
2022-05-23 14:09:07.177388 - Running OH_creation_acquire_lock job
2022-05-23 14:09:08.171954 - Completed OH_creation_acquire_lock job
2022-05-23 14:09:08.198978 - -----------------
2022-05-22 02:37:53.813029 - Running Local_node_oh_image_unzip job
2022-05-22 02:39:56.887526 - Completed Local_node_oh_image_unzip job
2022-05-22 02:39:56.914783 - -----------------
2022-05-22 02:39:56.915116 - Running OH_creation_cvu_prechecks job
2022-05-22 02:40:09.814269 - Completed OH_creation_cvu_prechecks job
2022-05-22 02:40:09.833340 - -----------------
2022-05-22 02:40:09.833535 - Running Local_node_oh_clone job
2022-05-22 02:42:43.351264 - Completed Local_node_oh_clone job
2022-05-22 02:42:43.374284 - -----------------
2022-05-22 02:42:43.374517 - Running Update_dbnid_bits job
2022-05-22 02:42:44.331325 - Execution of Update_dbnid_bits failed
2022-05-22 02:42:44.343331 - [FATAL] [DBAAS-60018] Unable to get patch version of oracle home '/u02/app/oracle/product/19.0.0.0/dbhome_1'.
2022-05-22 02:42:44.343537 - ACTION: Make sure that home exist and registered to central inventory.
2022-05-22 02:42:44.343629 - SUMMARY:
2022-05-22 02:42:44.343702 - - [DBAAS-60018] Unable to get patch version of oracle home '/u02/app/oracle/product/19.0.0.0/dbhome_1'.
2022-05-22 02:42:44.343773 - - [DBAAS-60022] Command '/u02/app/oracle/product/19.0.0.0/dbhome_1/OPatch/opatch lspatches|egrep -i 'DATABASE BUNDLE PATCH|DATABASE.*RELEASE|DATABASE PATCH FOR EXADATA'' execution has failed on nodes [localnode].
2022-05-22 02:42:44.362227 -
2022-05-22 02:42:44.362446 - ******** PLUGIN EXECUTION FAILED ********
2022-05-22 02:42:44.362587 -
2022-05-22 02:42:44.362702 - Executing jobs which need to be run always...
2022-05-22 02:42:44.364153 - -----------------
2022-05-22 02:42:44.364319 - Running OH_creation_release_lock job
2022-05-22 02:42:55.387907 - Completed OH_creation_release_lock job
2022-05-22 02:42:55.407077 - -----------------
2022-05-22 02:42:55.407502 - Running Plugin_cleanup job
2022-05-22 02:42:57.582787 - Completed Plugin_cleanup job
2022-05-22 02:42:57.602863 - Completed execution.
2022-05-22 02:42:57.658445 - Reverting Local_node_oh_clone job
2022-05-22 02:43:00.259021 - Reverted Local_node_oh_clone job
2022-05-22 02:43:00.273643 - Reverting Local_node_oh_image_unzip job
2022-05-22 02:43:00.273865 - Reverted Local_node_oh_image_unzip job
2022-05-22 02:43:00.294410 - Reverting OH_creation_acquire_lock job
2022-05-22 02:43:01.033879 - Reverted OH_creation_acquire_lock job
2022-05-22 02:43:01.050927 - Reverting OH_image_download job
2022-05-22 02:43:01.051167 - Reverted OH_image_download job
We can see that the error occurs for the step Running Update_dbnid_bits job.
Let’s check the logfile of the PILOT execution – search for the failed command (opatch lspatches).
$> vi pilot_2022-05-23_02-05-54-PM
...
INFO: [2022-05-23 13:47:20.904 CEST][pool-1-thread-1][DefaultCommandExecutor.run:345] Execution of /u02/app/oracle/product/19.0.0.0/dbhome_2/OPatch/opatch lspatches|egrep -i 'DATABASE BUNDLE PATCH|DATABASE.*RELEASE|DATABASE PATCH FOR EXADATA' script is failed/unexecuted on nodes : [localnode]
Execution status of failed node:localnode
Errors : [Inventory load failed... LsPatchesSession::loadAndPrintInstalledPatch()
, LsPatchesSession failed: OPatch failed to locate Central Inventory.
, Possible causes are:
, The Central Inventory is corrupted
, The oraInst.loc file specified is not valid.
]
Execution status of localnode is:true
Execution exit code of localnode is:1
Okay, these messages say that there is an issue with the Oracle Inventory. Let’s verify this by running opatch lspatches from an existing Oracle Home – for example, the Grid Infrastructure Home.
$> $ORACLE_HOME/OPatch/opatch lspatches
33911149;TOMCAT RELEASE UPDATE 19.0.0.0.0 (33911149)
33815607;ACFS RELEASE UPDATE 19.15.0.0.0 (33815607)
33815596;OCW RELEASE UPDATE 19.15.0.0.0 (33815596)
33806152;Database Release Update : 19.15.0.0.220419 (33806152)
33575402;DBWLM RELEASE UPDATE 19.0.0.0.0 (33575402)
OPatch succeeded.
No problem found here.
Cause
In the end and with the help of Oracle Support, the cause of this issue was a missing oraInst.loc file in the /u01/app/oraInventory location.
$> ssh node1 ls -l /u01/app/oraInventory
total 56
drwxrwx--- 79 oracle oinstall 4096 May 23 14:20 backup
drwxrwx--- 2 grid oinstall 106 May 23 14:13 ContentsXML
drwxrwx--- 2 oracle oinstall 28 May 23 14:20 locks
drwxrwx--- 73 grid oinstall 32768 May 23 14:20 logs
$> ssh node2 ls -l /u01/app/oraInventory
total 36
drwxrwx--- 48 grid oinstall 4096 May 23 14:20 backup
drwxrwx--- 2 grid oinstall 81 May 14 23:25 ContentsXML
drwxrwx--- 2 oracle oinstall 28 May 23 14:20 locks
drwxrwx--- 7 grid oinstall 20480 May 23 14:20 logs
-rw-rw---- 1 oracle oinstall 56 Nov 26 2020 oraInst.loc
-rwxrwx--- 1 oracle oinstall 1617 Nov 26 2020 orainstRoot.sh
As you can see, two files were missing in the Oracle Inventory directory on the first node – the reason for this is currently unknown. The file oraInst.loc is mandatory and without it, the deployment will fail.
Solution
The solution is very easy, just copy the file(s) from another node (connect to user oracle) and set the correct permissions.
$> cd /u01/app/oraInventory
$> scp node2:/u01/app/oraInventory/ora* .
oraInst.loc 100% 56 38.3KB/s 00:00
orainstRoot.sh 100% 1617 50.4KB/s 00:00
$> chown 660 oraInst.loc
$> chown 770 orainstRoot.sh
After copying the files, the next Oracle Home deployment was successful.