OJVM and DBA_REGISTRY_SQLPATCH

I woke up this morning and did what I do most days - doomscroll through twitter. One of the benefits of being in the US is that there are usually some interesting discussions going on with people I follow in Europe. I saw an interesting question from Martin Berger:

Does anyone know why the @Oracle OJVM patch is listed twice after an RU Apply - OL7 / EE with the actual date? How does it looks like in your environment?@MikeDietrichDE @Trivadis @AccentureTech @oracleace pic.twitter.com/McILGSN6kY

— Martin Berger - Deheim@Jurasüdfuss.SO.CH (@martinberger_ch) February 8, 2022

I've had my fights with datapatch over the years, so I was curious by what I saw. Initially, you may suspect it's a bug, but I thought about the issue being with the OJVM patch, and how that particular patch is handled by datapatch.

Patching the Oracle database is a two-step process. First, the Oracle binaries are patched by the opatch command. After the Oracle home is patched, the datapatch script must be run on a database to apply any fixes that include post-patch SQL.

The OJVM patch in particular has been a thorn in the side of many DBAs. In database 19c and lower, a mismatch between the Java classes in the database and the files in the home will cause an ORA-29548 error to occur.

Operations performed by datapatch will create rows in the dba_registry_sqlpatch view, which goes back to Martin's original question. Why was the 19.9 OJVM patch listed twice when querying the view? I believe the hint lies in the data that we see from the ACTION_TIME column.

To confirm, I went to my lab system with the same 19.9 patch set installed:

SQL> select PATCH_ID, PATCH_TYPE, ACTION_TIME, DESCRIPTION, STATUS from dba_registry_sqlpatch;

  PATCH_ID PATCH_TYPE ACTION_TIME                    DESCRIPTION                                                  STATUS
---------- ---------- ------------------------------ ------------------------------------------------------------ -------
  31668882 INTERIM    20-OCT-21 06.27.39.120263 PM   OJVM RELEASE UPDATE: 19.9.0.0.201020 (31668882)              SUCCESS
  31771877 RU         20-OCT-21 06.27.39.117792 PM   Database Release Update : 19.9.0.0.201020 (31771877)         SUCCESS

I applied the 19.13 patches, as shown below:

[oracle@acolvin-dg-1 ~]$ $ORACLE_HOME/OPatch/opatch lspatches
33192694;OJVM RELEASE UPDATE: 19.13.0.0.211019 (33192694)
33208123;OCW RELEASE UPDATE 19.13.0.0.0 (33208123)
33192793;Database Release Update : 19.13.0.0.211019 (33192793)

OPatch succeeded.

Once I finished, I ran datapatch, which completed successfully. I checked the dba_registry_sqlpatch, and I saw the same thing:

SQL> select PATCH_ID, PATCH_TYPE, ACTION_TIME, DESCRIPTION, STATUS from dba_registry_sqlpatch;

  PATCH_ID PATCH_TYPE ACTION_TIME                    DESCRIPTION                                                  STATUS
---------- ---------- ------------------------------ ------------------------------------------------------------ -------
  31668882 INTERIM    20-OCT-21 06.27.39.120263 PM   OJVM RELEASE UPDATE: 19.9.0.0.201020 (31668882)          SUCCESS
  31771877 RU         20-OCT-21 06.27.39.117792 PM   Database Release Update : 19.9.0.0.201020 (31771877)     SUCCESS
  31668882 INTERIM    08-FEB-22 06.00.13.069042 PM   OJVM RELEASE UPDATE: 19.9.0.0.201020 (31668882)          SUCCESS
  33192694 INTERIM    08-FEB-22 06.00.18.341368 PM   OJVM RELEASE UPDATE: 19.13.0.0.211019 (33192694)         SUCCESS
  33192793 RU         08-FEB-22 06.00.18.335540 PM   Database Release Update : 19.13.0.0.211019 (33192793)    SUCCESS

Sure enough, we have 2 entries for the 19.9 OJVM patch. What could be causing this? If you look at the output from datapatch, you can see that the script performs a rollback of the 19.9 OJVM patch before applying the 19.13 version:

[oracle@acolvin-dg-1 OPatch]$ ./datapatch -verbose
SQL Patching tool version 19.13.0.0.0 Production on Tue Feb  8 17:54:18 2022
Copyright (c) 2012, 2021, Oracle.  All rights reserved.

Log file for this invocation: /u01/app/oracle/cfgtoollogs/sqlpatch/sqlpatch_6659_2022_02_08_17_54_18/sqlpatch_invocation.log

Connecting to database...OK
Gathering database info...done
Bootstrapping registry and package to current versions...done
Determining current state...done

Current state of interim SQL patches:
Interim patch 31668882 (OJVM RELEASE UPDATE: 19.9.0.0.201020 (31668882)):
  Binary registry: Not installed
  SQL registry: Applied successfully on 20-OCT-21 06.27.39.120263 PM
Interim patch 33192694 (OJVM RELEASE UPDATE: 19.13.0.0.211019 (33192694)):
  Binary registry: Installed
  SQL registry: Not installed

Current state of release update SQL patches:
  Binary registry:
    19.13.0.0.0 Release_Update 211004165050: Installed
  SQL registry:
    Applied 19.9.0.0.0 Release_Update 200930183249 successfully on 20-OCT-21 06.27.39.117792 PM

Adding patches to installation queue and performing prereq checks...done
Installation queue:
  The following interim patches will be rolled back:
    31668882 (OJVM RELEASE UPDATE: 19.9.0.0.201020 (31668882))
  Patch 33192793 (Database Release Update : 19.13.0.0.211019 (33192793)):
    Apply from 19.9.0.0.0 Release_Update 200930183249 to 19.13.0.0.0 Release_Update 211004165050
  The following interim patches will be applied:
    33192694 (OJVM RELEASE UPDATE: 19.13.0.0.211019 (33192694))

Installing patches...
Patch installation complete.  Total patches installed: 3

Validating logfiles...done
Patch 31668882 rollback: SUCCESS
  logfile: /u01/app/oracle/cfgtoollogs/sqlpatch/31668882/23790068/31668882_rollback_COLVINP_2022Feb08_17_54_43.log (no errors)
Patch 33192793 apply: SUCCESS
  logfile: /u01/app/oracle/cfgtoollogs/sqlpatch/33192793/24462514/33192793_apply_COLVINP_2022Feb08_17_55_28.log (no errors)
Patch 33192694 apply: SUCCESS
  logfile: /u01/app/oracle/cfgtoollogs/sqlpatch/33192694/24421575/33192694_apply_COLVINP_2022Feb08_17_55_28.log (no errors)
SQL Patching tool complete on Tue Feb  8 18:00:18 2022

When checking dba_registry_sqlpatch there is another column, ACTION. This column shows what happened during the operation in euqstion. When I add this column to my query, it all comes in to focus:

SQL> select PATCH_ID, PATCH_TYPE, ACTION, ACTION_TIME, DESCRIPTION, STATUS from dba_registry_sqlpatch;

  PATCH_ID PATCH_TYPE ACTION          ACTION_TIME                    DESCRIPTION                                              STATUS
---------- ---------- --------------- ------------------------------ -------------------------------------------------------  --------
  31668882 INTERIM    APPLY           20-OCT-21 06.27.39.120263 PM   OJVM RELEASE UPDATE: 19.9.0.0.201020 (31668882)          SUCCESS
  31771877 RU         APPLY           20-OCT-21 06.27.39.117792 PM   Database Release Update : 19.9.0.0.201020 (31771877)     SUCCESS
  31668882 INTERIM    ROLLBACK        08-FEB-22 06.00.13.069042 PM   OJVM RELEASE UPDATE: 19.9.0.0.201020 (31668882)          SUCCESS
  33192694 INTERIM    APPLY           08-FEB-22 06.00.18.341368 PM   OJVM RELEASE UPDATE: 19.13.0.0.211019 (33192694)         SUCCESS
  33192793 RU         APPLY           08-FEB-22 06.00.18.335540 PM   Database Release Update : 19.13.0.0.211019 (33192793)    SUCCESS

Going back to Martin's original question, I believe this is what he is seeing. Checking the ACTION_TIME column in his results shows that the second operation on the 19.9 OJVM patch occurred three seconds before the operation on the 19.11 OJVM patch.