Introduction

In this blog post I will share a example of issue that I faced sometime ago. This post was saved as “draft” in my blog for months while I was thinking about to reproduce the issue and try the identifiy the root cause, but It was unable to me for many reasons. So I will just share the problem and the workaround that I used

Please be aware that I will not show how to apply the patch in this blog post, this is just a demo of a unexpected behavior and how I managed to workaround the issue.

Scenario

This was a Out Of Place patching for Grid home and DB Home using opatchauto tool. I have created the new Oracle Home in advance using the -prepare-clone option, and the maintenace window shoud be used only for the -switch-clone operation, which I was expecting to get this complete in 5 to 10 minutes.

Problem

After the Grid home has been switched to the new one, the opatchauto was hang for 20 minutes in this stage:

Performing postpatch operations on CRS - starting CRS service on home /u01/app/grid/product/19.0.0/grid_1

In the opatchautoYYYY-MM-DD_HH-MI-SSPM.log, the last command executed was the “roothas.pl -postpatch” from the new Grid home:

Executing command as root: 
 bash -c "LD_LIBRARY_PATH=/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/srvm/lib:/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/srvm/lib:/u01/app/grid/product/19.0.0/grid_1/lib /u01/app/grid/product/19.0.0/grid_1/perl/bin/perl -I/u01/app/grid/product/19.0.0/grid_1/perl/lib -I/u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/crs/install -I/u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/xag /u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/crs/install/roothas.pl -postpatch"
2025-06-05 19:57:41,642 INFO  [396] com.oracle.glcm.patch.auto.db.product.executor.PatchingStepExecutor - COMMAND Looks like this: bash -c "LD_LIBRARY_PATH=/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/srvm/lib:/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/srvm/lib:/u01/app/grid/product/19.0.0/grid_1/lib /u01/app/grid/product/19.0.0/grid_1/perl/bin/perl -I/u01/app/grid/product/19.0.0/grid_1/perl/lib -I/u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/crs/install -I/u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/xag /u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/crs/install/roothas.pl -postpatch"
2025-06-05 19:57:41,642 INFO  [396] com.oracle.glcm.patch.auto.db.product.executor.PatchingStepExecutor - Starting command execution...
bash -c "LD_LIBRARY_PATH=/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/srvm/lib:/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/srvm/lib:/u01/app/grid/product/19.0.0/grid_1/lib /u01/app/grid/product/19.0.0/grid_1/perl/bin/perl -I/u01/app/grid/product/19.0.0/grid_1/perl/lib -I/u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/crs/install -I/u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/xag /u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/crs/install/roothas.pl -postpatch"
2025-06-05 19:57:41,642 INFO  [396] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, -, root, -m, -c, bash -c "LD_LIBRARY_PATH=/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/srvm/lib:/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/lib:/u01/app/grid/product/19.0.0/grid_1/srvm/lib:/u01/app/grid/product/19.0.0/grid_1/lib /u01/app/grid/product/19.0.0/grid_1/perl/bin/perl -I/u01/app/grid/product/19.0.0/grid_1/perl/lib -I/u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/crs/install -I/u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/xag /u01/app/grid/product/19.0.0/grid_1/opatchautocfg/db/dbtmp/bootstrap_oraparantex/patchwork/crs/install/roothas.pl -postpatch"]

The last message in HAS alert log was Detecting control device ‘/dev/ofsctl’:

2025-06-05 19:57:44.934 [CLSECHO(2763280)]AFD-0627: AFD distribution files found.
2025-06-05 19:57:45.243 [CLSECHO(2763331)]AFD-9155: Checking for existing 'oracleafd.ko' driver installation.
2025-06-05 19:57:45.325 [CLSECHO(2763347)]AFD-0632: Existing AFD installation detected.
2025-06-05 19:57:45.350 [CLSECHO(2763358)]AFD-0634: Removing previous AFD installation.
2025-06-05 19:57:53.293 [CLSECHO(2763451)]AFD-0635: Previous AFD components successfully removed.
2025-06-05 19:57:53.381 [CLSECHO(2763465)]AFD-9294: updating file /etc/sysconfig/oracledrivers.conf
2025-06-05 19:57:53.406 [CLSECHO(2763473)]AFD-0636: Installing requested AFD software.
2025-06-05 19:57:53.432 [CLSECHO(2763481)]AFD-0626: AFD driver media location is '/u01/app/grid/product/19.0.0/grid_1/usm/install/Oracle/EL8UEK/x86_64/5.15.0-201.135.6/5.15.0-201.135.6-x86_64/bin'
2025-06-05 19:57:53.458 [CLSECHO(2763489)]AFD-9504: Copying file '/u01/app/grid/product/19.0.0/grid_1/usm/install/Oracle/EL8UEK/x86_64/5.15.0-201.135.6/5.15.0-201.135.6-x86_64/bin/oracleafd.ko' to the path '/lib/modules/5.15.0-304.171.4.3.el8uek.x86_64/extra/oracle/oracleafd.ko'
2025-06-05 19:57:53.494 [CLSECHO(2763498)]AFD-9504: Copying file '/u01/app/grid/product/19.0.0/grid_1/bin/afdboot' to the path '/sbin/afdboot'
2025-06-05 19:57:53.576 [CLSECHO(2763508)]AFD-0637: Loading installed AFD drivers.
2025-06-05 19:57:53.694 [CLSECHO(2763527)]AFD-9321: Creating udev for AFD.
2025-06-05 19:57:53.725 [CLSECHO(2763535)]AFD-9323: Creating module dependencies - this may take some time.
2025-06-05 19:58:01.202 [CLSECHO(2763592)]AFD-9154: Loading 'oracleafd.ko' driver.
2025-06-05 19:58:01.350 [CLSECHO(2763615)]AFD-9504: Copying file '/u01/app/grid/product/19.0.0/grid_1/lib/libafd19.so' to the path '/opt/oracle/extapi/64/asm/orcl/1/'
2025-06-05 19:58:01.380 [CLSECHO(2763625)]AFD-0649: Verifying AFD devices.
2025-06-05 19:58:01.406 [CLSECHO(2763633)]AFD-9156: Detecting control device '/dev/oracleafd/admin'.
2025-06-05 19:58:01.497 [CLSECHO(2763651)]AFD-0638: AFD installation correctness verified.
2025-06-05 19:58:01.776 [CLSECHO(2763671)]AFD-9294: updating file /etc/sysconfig/oracledrivers.conf
2025-06-05 19:58:05.400 [CLSECHO(2764438)]ACFS-9300: ADVM/ACFS distribution files found.
2025-06-05 19:58:09.795 [CLSECHO(2764639)]ACFS-9314: Removing previous ADVM/ACFS installation.
2025-06-05 19:58:17.816 [CLSECHO(2764773)]ACFS-9315: Previous ADVM/ACFS components successfully removed.
2025-06-05 19:58:17.904 [CLSECHO(2764787)]ACFS-9294: updating file /etc/sysconfig/oracledrivers.conf
2025-06-05 19:58:17.986 [CLSECHO(2764816)]ACFS-9307: Installing requested ADVM/ACFS software.
2025-06-05 19:58:18.013 [CLSECHO(2764824)]ACFS-9503: ADVM and ACFS driver media location is '/u01/app/grid/product/19.0.0/grid_1/usm/install/Oracle/EL8UEK/x86_64/5.15.0-201.135.6/5.15.0-201.135.6-x86_64/bin'
2025-06-05 19:58:19.563 [CLSECHO(2765194)]ACFS-9294: updating file /etc/sysconfig/oracledrivers.conf
2025-06-05 19:58:19.593 [CLSECHO(2765204)]ACFS-9308: Loading installed ADVM/ACFS drivers.
2025-06-05 19:58:19.619 [CLSECHO(2765212)]ACFS-9321: Creating udev for ADVM/ACFS.
2025-06-05 19:58:19.645 [CLSECHO(2765220)]ACFS-9323: Creating module dependencies - this may take some time.
2025-06-05 19:58:27.155 [CLSECHO(2765278)]ACFS-9154: Loading 'oracleoks.ko' driver.
2025-06-05 19:58:27.310 [CLSECHO(2765305)]ACFS-9154: Loading 'oracleadvm.ko' driver.
2025-06-05 19:58:27.482 [CLSECHO(2765343)]ACFS-9154: Loading 'oracleacfs.ko' driver.
2025-06-05 19:58:27.973 [CLSECHO(2765396)]ACFS-9327: Verifying ADVM/ACFS devices.
2025-06-05 19:58:28.077 [CLSECHO(2765432)]ACFS-9156: Detecting control device '/dev/asm/.asm_ctl_spec'.
2025-06-05 19:58:28.141 [CLSECHO(2765452)]ACFS-9156: Detecting control device '/dev/ofsctl'.

After 20 minutes, a new entry:

2025-06-05 19:58:28.141 [CLSECHO(2765452)]ACFS-9156: Detecting control device '/dev/ofsctl'.
2025-06-05 20:18:43.389 [CLSECHO(2818548)]ACFS-9309: ADVM/ACFS installation correctness verified.

And the opatchauto log shows the CRS startup as completed, but the database instances startup fails with ORA-03113 error:

Performing postpatch operations on CRS - starting CRS service on home /u01/app/grid/product/19.0.0/grid_1
Postpatch operation log file location: /u01/app/grid/crsdata/srvora01/crsconfig/hapatch_2025-06-05_06-56-10PM.log
CRS service started successfully on home /u01/app/grid/product/19.0.0/grid_1


Starting database service on home /u01/app/oracle/product/19.0.0/dbhome_1
Failed to start database service on home /u01/app/oracle/product/19.0.0/dbhome_1

Execution of [SIDBStartupAction] patch action failed, check log for more details. Failures:
Patch Target : srvora01->/u01/app/oracle/product/19.0.0/dbhome_1 Type[sidb]
Details: [
---------------------------Patching Failed---------------------------------
Command execution failed during patching in home: /u01/app/oracle/product/19.0.0/dbhome_1, host: srvora01.
Command failed:  /bin/sh -c 'ORACLE_HOME=/u01/app/oracle/product/19.0.0/dbhome_1 /u01/app/oracle/product/19.0.0/dbhome_1/bin/srvctl start home -o /u01/app/oracle/product/19.0.0/dbhome_1 -s /u01/app/oracle/product/19.0.0/dbhome_1/opatchautocfg/db/sessioninfo/statfile/srvora01/OracleHome-45b29e96-1096-4484-8e0a-7aedd9644bc1_srvora01_567J.stat'
Command failure output: 
PRCH-1001 : Failed to start resources in Oracle home /u01/app/oracle/product/19.0.0/dbhome_1
PRCR-1095 : Failed to start resources using filter ((NAME == ora.orclprd.db) OR (NAME == ora.hmgorcl.db))
CRS-5017: The resource action "ora.hmgorcl.db start" encountered the following error: 
ORA-03113: end-of-file on communication channel
Process ID: 2645989
Session ID: 128 Serial number: 63270
. For details refer to "(:CLSN00107:)" in "/u01/app/grid/diag/crs/srvora01/crs/trace/ohasd_oraagent_grid.trc".

CRS-2674: Start of 'ora.hmgorcl.db' on 'srvora01' failed
CRS-5017: The resource action "ora.orclprd.db start" encountered the following error: 
ORA-03113: end-of-file on communication channel
Process ID: 2645998
Session ID: 388 Serial number: 38738
. For details refer to "(:CLSN00107:)" in "/u01/app/grid/diag/crs/srvora01/crs/trace/ohasd_oraagent_grid.trc".

CRS-2674: Start of 'ora.orclprd.db' on 'srvora01' failed 

After fixing the cause of failure Run opatchauto resume

]
OPATCHAUTO-68061: The orchestration engine failed.
OPATCHAUTO-68061: The orchestration engine failed with return code 1
OPATCHAUTO-68061: Check the log for more details.
OPatchAuto failed.

OPatchauto session completed at Thu Jun  5 19:18:05 2025
Time taken to complete the session 39 minutes, 50 seconds

When investigating the DB alert log, I found these messages about the ASM:

Errors in file /u01/app/oracle/diag/rdbms/orclprd/orclprd/trace/orclprd_rbal_2825149.trc:
ORA-15183: ASMLIB initialization error [permission to access asmlib denied]
2025-06-05T20:20:49.989946-03:00
WARNING: FAILED to load library: /opt/oracle/extapi/64/asm/orcl/1/libafd19.so 
2025-06-05T20:20:49.998493-03:00
NOTE: ASMB (index:0) (2825151) connected to ASM instance +ASM, osid: 2825157 (Standard mode; client id 0xffffffffffffffff)
NOTE: initiating MARK startup 
Starting background process MARK
2025-06-05T20:20:50.010659-03:00
MARK started with pid=40, OS id=2825167 
2025-06-05T20:20:50.012626-03:00
NOTE: MARK has subscribed
2025-06-05T20:20:50.050667-03:00
ALTER DATABASE MOUNT /* db agent *//* {0:0:239} */
2025-06-05T20:20:53.078373-03:00
NOTE: ASMB mounting group 1 (DATA)
2025-06-05T20:20:53.093477-03:00
WARNING: cellinit.ora is missing. RBAL is terminating the instance.
RBAL (ospid: ): terminating the instance due to ORA error 
2025-06-05T20:20:53.159459-03:00
System state dump requested by (instance=1, osid=2825149 (RBAL)), summary=[abnormal instance termination].
System State dumped to trace file /u01/app/oracle/diag/rdbms/orclprd/orclprd/trace/orclprd_diag_2825100.trc
2025-06-05T20:20:53.318564-03:00
Dumping diagnostic data in directory=[cdmp_20250605202053], requested by (instance=1, osid=2825149 (RBAL)), summary=[abnormal instance termination].

The most interesting are:

ORA-15183: ASMLIB initialization error [permission to access asmlib denied]

WARNING: FAILED to load library: /opt/oracle/extapi/64/asm/orcl/1/libafd19.so 

Note that this library is copied from GRID_HOME/lib to “/opt/oracle/extapi/64/asm/orcl/1/” location everytime we execute the “roothas.sh -postpatch” script.

So, initially I was concerned about the “libafd19.so” delivered with the new RU 19.27, and I tried to rollback to the original version (19.23), but I got the same behavior while trying to startup database instances after the “opatchauto rollback” session (which switches the GI home to the old one).

Solution (workaround)

I started to suspect that something related to this library could be locked in the kernel, and I decided to restart the the OS as simple solution. After the reboot, the database instances just started normally without additional actions. I have also tested switch to the new GI home again and I got the same behavior, and I just restarted the OS again in order to have the Grid Home updated.