Direct Path Read Write Temp while Selecting CLOB from GV$ in RAC

I was intestigating why a simple SELECT * FROM GV$SQL started working much slower in 19c compared to 11.2.0.4. It turns out Oracle introduced some changes there in 18c. This blog post is written to demonstrate the new behavior.

A simple test case which I constructed for this example is below:

set echo on
set timing on

select banner from v$version;
alter session set events 'sql_trace wait=true';
begin
  for r in (
    select sql_fulltext
      from gv$sql)
  loop
    null;
  end loop;
end;
/
alter session set events 'sql_trace off';

select value
  from v$diag_info
 where name='Default Trace File';

I ran it in 19.10 and got the following results:

SQL> select banner from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production

Elapsed: 00:00:00.00
SQL> alter session set events 'sql_trace wait=true';

Session altered.

Elapsed: 00:00:00.00
SQL> begin
  2    for r in (
  3      select sql_fulltext
  4        from gv$sql)
  5    loop
  6      null;
  7    end loop;
  8  end;
  9  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:02.14
SQL> alter session set events 'sql_trace off';

Session altered.

Elapsed: 00:00:00.00
SQL>
SQL> select value
  2    from v$diag_info
  3   where name='Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl19/orcl191/trace/orcl191_ora_19616.trc

Elapsed: 00:00:00.00

I processed the trace file using tkprof and got the output below:

SQL ID: 250c8asaww0wz Plan Hash: 1891717107

SELECT SQL_FULLTEXT
FROM
 GV$SQL


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       21      0.44       2.13        288        288      25355        2011
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       23      0.44       2.13        288        288      25355        2011

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: SYS   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      2011       2011       2011  PX COORDINATOR  (cr=288 pr=288 pw=2259 time=2499846 us starts=1)
         0          0          0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=1638400 card=100)
         0          0          0    VIEW  GV$SQL (cr=0 pr=0 pw=0 time=0 us starts=0)
         0          0          0     FIXED TABLE FULL X$KGLCURSOR_CHILD (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=1638400 card=100)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                           18        0.00          0.00
  PX Deq: reap credit                           232        0.00          0.00
  PX Deq: Join ACK                                2        0.00          0.00
  PX Deq: Parse Reply                             2        0.00          0.00
  PX Deq: Execute Reply                         146        0.00          0.00
  Disk file operations I/O                        5        0.00          0.00
  CSS initialization                              2        0.00          0.00
  CSS operation: query                            6        0.00          0.00
  CSS operation: action                           2        0.00          0.00
  asynch descriptor resize                        1        0.00          0.00
  ASM IO for non-blocking poll                 6769        0.00          0.00
  direct path write temp                       2158        0.00          1.59
  db file sequential read                       144        0.00          0.06
  direct path read temp                         144        0.00          0.06
  reliable message                                1        0.00          0.00
  PX Deq: Signal ACK EXT                          2        0.00          0.00
  IPC send completion sync                        1        0.00          0.00
  PX Deq: Slave Session Stats                     2        0.00          0.00
  IPC group service call                          1        0.00          0.00
  enq: PS - contention                            1        0.00          0.00

It is worth noting that the number of rows is 2011 while the number of direct path write temp wait events is 2158. I believe it is a general pattern rather than a coincidence based on my tests. I found that the number of direct path write temp is always greater than the number of rows but not much. That basically means that Oracle does at least one write per CLOB returned.
Let us now compare it with 12.2 (I tested both 12.2 and 12.2 with the latest release update):

SQL> select banner from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
PL/SQL Release 12.2.0.1.0 - Production
CORE    12.2.0.1.0      Production
TNS for Linux: Version 12.2.0.1.0 - Production
NLSRTL Version 12.2.0.1.0 - Production

Elapsed: 00:00:00.01
SQL> alter session set events 'sql_trace wait=true';

Session altered.

Elapsed: 00:00:00.00
SQL> begin
  2    for r in (
  3      select sql_fulltext
  4        from gv$sql)
  5    loop
  6      null;
  7    end loop;
  8  end;
  9  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.05
SQL> alter session set events 'sql_trace off';

Session altered.

Elapsed: 00:00:00.00
SQL>
SQL> select value
  2    from v$diag_info
  3   where name='Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/o122a/o122a1/trace/o122a1_ora_24892.trc

It can be seen that 12.2 is much faster than 19.10.
Here is a tkprof processed output:

SQL ID: 250c8asaww0wz Plan Hash: 1891717107

SELECT SQL_FULLTEXT
FROM
 GV$SQL


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       21      0.02       0.03          0          0          0        2069
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       23      0.03       0.05          0          0          0        2069

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 76     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      2069       2069       2069  PX COORDINATOR  (cr=0 pr=0 pw=0 time=138102 us starts=1)
         0          0          0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=200200 card=100)
         0          0          0    VIEW  GV$SQL (cr=0 pr=0 pw=0 time=0 us starts=0)
         0          0          0     FIXED TABLE FULL X$KGLCURSOR_CHILD (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=200200 card=100)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  enq: PS - contention                            3        0.00          0.00
  PX Deq: Join ACK                                5        0.00          0.00
  PX Deq: reap credit                           277        0.00          0.00
  IPC send completion sync                        3        0.00          0.00
  PX Deq: Parse Reply                             2        0.00          0.00
  PGA memory operation                           28        0.00          0.00
  PX Deq: Execute Reply                         132        0.00          0.01
  reliable message                                1        0.00          0.00
  PX Deq: Signal ACK EXT                          2        0.00          0.00
  PX Deq: Slave Session Stats                     2        0.00          0.00

Although the number of rows is roughly the same (2069 in 12.2 vs 2011 in 19.10), the runtime performance and wait events are drastically different. Please bear in mind, that I initially asked to investigate why the same query in 11.2 was running in 1 second while the same query in 19.10 was running in 90 seconds with about the same number of rows as in 11.2.
I also reviewed the trace file in 19c to see if I can spot any pattern there:

[oracle@rac1 ~]$ grep 'WAIT #139925193433952' /u01/app/oracle/diag/rdbms/orcl19/orcl191/trace/orcl191_ora_19616.trc | grep -E 'direct path (read|write) temp|db file sequential read'
WAIT #139925193433952: nam='direct path write temp' ela= 758 file number=201 first dba=4355 block cnt=1 obj#=-1 tim=20569064799
WAIT #139925193433952: nam='direct path write temp' ela= 674 file number=201 first dba=4356 block cnt=1 obj#=-1 tim=20569065748
..59 direct path write temp in total
WAIT #139925193433952: nam='direct path write temp' ela= 680 file number=201 first dba=4413 block cnt=1 obj#=-1 tim=20569114649
..then there are groups consisting of one db file sequential read/one direct path read temp (the same block)/multiple direct path write temp:
..group 1
WAIT #139925193433952: nam='db file sequential read' ela= 473 file#=201 block#=4413 blocks=1 obj#=-1 tim=20569115200
WAIT #139925193433952: nam='direct path read temp' ela= 449 file number=201 first dba=4413 block cnt=1 obj#=-1 tim=20569115739
WAIT #139925193433952: nam='direct path write temp' ela= 699 file number=201 first dba=4413 block cnt=1 obj#=-1 tim=20569116529
WAIT #139925193433952: nam='direct path write temp' ela= 643 file number=201 first dba=4414 block cnt=1 obj#=-1 tim=20569117342
WAIT #139925193433952: nam='direct path write temp' ela= 753 file number=201 first dba=4415 block cnt=1 obj#=-1 tim=20569118266
WAIT #139925193433952: nam='direct path write temp' ela= 706 file number=201 first dba=4416 block cnt=1 obj#=-1 tim=20569119134
WAIT #139925193433952: nam='direct path write temp' ela= 593 file number=201 first dba=4417 block cnt=1 obj#=-1 tim=20569119882
WAIT #139925193433952: nam='direct path write temp' ela= 626 file number=201 first dba=4418 block cnt=1 obj#=-1 tim=20569120652
WAIT #139925193433952: nam='direct path write temp' ela= 807 file number=201 first dba=4419 block cnt=1 obj#=-1 tim=20569121585
WAIT #139925193433952: nam='direct path write temp' ela= 625 file number=201 first dba=4420 block cnt=1 obj#=-1 tim=20569122348
WAIT #139925193433952: nam='direct path write temp' ela= 605 file number=201 first dba=4421 block cnt=1 obj#=-1 tim=20569123097
WAIT #139925193433952: nam='direct path write temp' ela= 509 file number=201 first dba=4422 block cnt=1 obj#=-1 tim=20569123753
WAIT #139925193433952: nam='direct path write temp' ela= 577 file number=201 first dba=4423 block cnt=1 obj#=-1 tim=20569124476
WAIT #139925193433952: nam='direct path write temp' ela= 667 file number=201 first dba=4424 block cnt=1 obj#=-1 tim=20569125286
WAIT #139925193433952: nam='direct path write temp' ela= 501 file number=201 first dba=4425 block cnt=1 obj#=-1 tim=20569125930
WAIT #139925193433952: nam='direct path write temp' ela= 617 file number=201 first dba=4426 block cnt=1 obj#=-1 tim=20569126698
WAIT #139925193433952: nam='direct path write temp' ela= 634 file number=201 first dba=4427 block cnt=1 obj#=-1 tim=20569127473
WAIT #139925193433952: nam='direct path write temp' ela= 577 file number=201 first dba=4428 block cnt=1 obj#=-1 tim=20569128188
WAIT #139925193433952: nam='direct path write temp' ela= 868 file number=201 first dba=4429 block cnt=1 obj#=-1 tim=20569129188
WAIT #139925193433952: nam='direct path write temp' ela= 609 file number=201 first dba=4430 block cnt=1 obj#=-1 tim=20569130099
..group 2
WAIT #139925193433952: nam='db file sequential read' ela= 399 file#=201 block#=4430 blocks=1 obj#=-1 tim=20569130544
WAIT #139925193433952: nam='direct path read temp' ela= 454 file number=201 first dba=4430 block cnt=1 obj#=-1 tim=20569131072
WAIT #139925193433952: nam='direct path write temp' ela= 669 file number=201 first dba=4430 block cnt=1 obj#=-1 tim=20569131834
WAIT #139925193433952: nam='direct path write temp' ela= 686 file number=201 first dba=4431 block cnt=1 obj#=-1 tim=20569132665
WAIT #139925193433952: nam='direct path write temp' ela= 588 file number=201 first dba=4432 block cnt=1 obj#=-1 tim=20569133416
WAIT #139925193433952: nam='direct path write temp' ela= 794 file number=201 first dba=4433 block cnt=1 obj#=-1 tim=20569134366
WAIT #139925193433952: nam='direct path write temp' ela= 648 file number=201 first dba=4434 block cnt=1 obj#=-1 tim=20569135192
WAIT #139925193433952: nam='direct path write temp' ela= 792 file number=201 first dba=4435 block cnt=1 obj#=-1 tim=20569136134
WAIT #139925193433952: nam='direct path write temp' ela= 682 file number=201 first dba=4436 block cnt=1 obj#=-1 tim=20569136961
WAIT #139925193433952: nam='direct path write temp' ela= 609 file number=201 first dba=4437 block cnt=1 obj#=-1 tim=20569137753
WAIT #139925193433952: nam='direct path write temp' ela= 563 file number=201 first dba=4438 block cnt=1 obj#=-1 tim=20569138501
WAIT #139925193433952: nam='direct path write temp' ela= 645 file number=201 first dba=4439 block cnt=1 obj#=-1 tim=20569139298
WAIT #139925193433952: nam='direct path write temp' ela= 807 file number=201 first dba=4440 block cnt=1 obj#=-1 tim=20569140265
WAIT #139925193433952: nam='direct path write temp' ela= 679 file number=201 first dba=4441 block cnt=1 obj#=-1 tim=20569141079
WAIT #139925193433952: nam='direct path write temp' ela= 626 file number=201 first dba=4442 block cnt=1 obj#=-1 tim=20569141844
WAIT #139925193433952: nam='direct path write temp' ela= 740 file number=201 first dba=4443 block cnt=1 obj#=-1 tim=20569142718
WAIT #139925193433952: nam='direct path write temp' ela= 753 file number=201 first dba=4444 block cnt=1 obj#=-1 tim=20569143615
WAIT #139925193433952: nam='direct path write temp' ela= 686 file number=201 first dba=4445 block cnt=1 obj#=-1 tim=20569144450
WAIT #139925193433952: nam='direct path write temp' ela= 673 file number=201 first dba=4446 block cnt=1 obj#=-1 tim=20569145257
WAIT #139925193433952: nam='direct path write temp' ela= 728 file number=201 first dba=4447 block cnt=1 obj#=-1 tim=20569146129
WAIT #139925193433952: nam='direct path write temp' ela= 589 file number=201 first dba=4448 block cnt=1 obj#=-1 tim=20569146857
WAIT #139925193433952: nam='direct path write temp' ela= 658 file number=201 first dba=4449 block cnt=1 obj#=-1 tim=20569147672
WAIT #139925193433952: nam='direct path write temp' ela= 666 file number=201 first dba=4450 block cnt=1 obj#=-1 tim=20569148478
WAIT #139925193433952: nam='direct path write temp' ela= 602 file number=201 first dba=4451 block cnt=1 obj#=-1 tim=20569149255
WAIT #139925193433952: nam='direct path write temp' ela= 841 file number=201 first dba=4452 block cnt=1 obj#=-1 tim=20569150247
WAIT #139925193433952: nam='direct path write temp' ela= 763 file number=201 first dba=4453 block cnt=1 obj#=-1 tim=20569151167
WAIT #139925193433952: nam='direct path write temp' ela= 779 file number=201 first dba=4454 block cnt=1 obj#=-1 tim=20569152208
..group 3
WAIT #139925193433952: nam='db file sequential read' ela= 206 file#=201 block#=4454 blocks=1 obj#=-1 tim=20569152457
WAIT #139925193433952: nam='direct path read temp' ela= 711 file number=201 first dba=4454 block cnt=1 obj#=-1 tim=20569153234
WAIT #139925193433952: nam='direct path write temp' ela= 575 file number=201 first dba=4454 block cnt=1 obj#=-1 tim=20569153905
WAIT #139925193433952: nam='direct path write temp' ela= 930 file number=201 first dba=4455 block cnt=1 obj#=-1 tim=20569155093
WAIT #139925193433952: nam='direct path write temp' ela= 809 file number=201 first dba=4355 block cnt=1 obj#=-1 tim=20569156069
WAIT #139925193433952: nam='direct path write temp' ela= 820 file number=201 first dba=4356 block cnt=1 obj#=-1 tim=20569157024
WAIT #139925193433952: nam='direct path write temp' ela= 976 file number=201 first dba=4357 block cnt=1 obj#=-1 tim=20569158174
WAIT #139925193433952: nam='direct path write temp' ela= 683 file number=201 first dba=4358 block cnt=1 obj#=-1 tim=20569159165
WAIT #139925193433952: nam='db file sequential read' ela= 638 file#=201 block#=4358 blocks=1 obj#=-1 tim=20569159850
WAIT #139925193433952: nam='direct path read temp' ela= 183 file number=201 first dba=4358 block cnt=1 obj#=-1 tim=20569160107
..

My next thought was to test how 19c processes CLOB's in traditional tables - I have not found any issues there. There have been no direct path read/write temp on copies of GV$SQL.
I then tried to select the same persistent tables (non-GV$) via database link in 19c - again everything worked as it should.
It seems that only GV$ views are affected. Local selects are not affected at all (the output below is from the first instance):

SQL ID: 87myh1vhjdcf8 Plan Hash: 1891717107

SELECT SQL_FULLTEXT
FROM
 GV$SQL WHERE INST_ID = 1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       13      0.02       0.02          0          0          0        1231
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       15      0.03       0.03          0          0          0        1231

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1231       1231       1231  PX COORDINATOR  (cr=0 pr=0 pw=0 time=13516 us starts=1)
      1231       1231       1231   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=13283 us starts=1 cost=0 size=1639700 card=100)
      1231       1231       1231    VIEW  GV$SQL (cr=0 pr=0 pw=0 time=12908 us starts=1)
      1231       1231       1231     FIXED TABLE FULL X$KGLCURSOR_CHILD (cr=0 pr=0 pw=0 time=12657 us starts=1 cost=0 size=1639700 card=100)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                           99        0.00          0.00

Whereas any select when non-local instance is involved is done utilizing a temporary tablespace:

SQL ID: 4p7vm0hhw6u1v Plan Hash: 1891717107

SELECT SQL_FULLTEXT
FROM
 GV$SQL WHERE INST_ID = 2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       10      0.21       1.06        118        118      11953         968
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12      0.21       1.07        118        118      11953         968

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       968        968        968  PX COORDINATOR  (cr=118 pr=118 pw=1075 time=907430 us starts=1)
         0          0          0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=1639700 card=100)
         0          0          0    VIEW  GV$SQL (cr=0 pr=0 pw=0 time=0 us starts=0)
         0          0          0     FIXED TABLE FULL X$KGLCURSOR_CHILD (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=1639700 card=100)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: reap credit                           158        0.00          0.00
  PX Deq: Join ACK                                1        0.00          0.00
  PX Deq: Parse Reply                             1        0.00          0.00
  PGA memory operation                           11        0.00          0.00
  PX Deq: Execute Reply                          61        0.00          0.01
  Disk file operations I/O                        3        0.00          0.00
  CSS initialization                              2        0.00          0.00
  CSS operation: query                            6        0.00          0.00
  CSS operation: action                           2        0.00          0.00
  asynch descriptor resize                        1        0.00          0.00
  ASM IO for non-blocking poll                 3208        0.00          0.00
  direct path write temp                       1029        0.00          0.81
  db file sequential read                        59        0.00          0.02
  direct path read temp                          59        0.00          0.02
  reliable message                                1        0.00          0.00
  PX Deq: Signal ACK EXT                          1        0.00          0.00
  IPC send completion sync                        1        0.00          0.00
  PX Deq: Slave Session Stats                     1        0.00          0.00
  IPC group service call                          1        0.00          0.00
  enq: PS - contention                            1        0.00          0.00

I then shut one instance down, and rechecked the queries against GV$ - there were no direct path read/write temp wait events.

Conclusion

It is still not clear why Oracle started writing every CLOB from GV$ to a temporary tablespace. I tried several different GV$ views and the same behaviour was observed everywhere. It looks like something was changed inside those GV$ functions.
My initial thought was that it is some kind of a temporary tablespace flush for persistence in case some parallel processes got terminated. However, parallel slaves started on remote instances are sending the blocks to the QC bypassing any temp.
Then I was thinking that it might be done to reduce memory usage. It has little sense to write every CLOB to temp anyway. Why do not keep a small memory area and write to temp everything that exceeded some threshold?
I also do not know how to alter this behavior to make the things the same as they were before 18c. I tested 11.2.0.4, 12.2(vanilla and with the latest RU), 18c, 19c (vanilla and with the latest RU - 19.10). Both 18c and 19c are affected, so that they wait for direct path read/write temp when a CLOB column is selected from GV$ with more than one instance.
I will update the blog post if I get to the bottom of it and identify the root cause.

OPATCHAUTO-72043 and JCE

I was applying Grid Infrastructure Jan 2021 Release Update (GI RU) 18.13.0.0.210119 to an 18c cluster the other day.
opatchauto failed with the errors as follows:

[root@rac1 ~]# /u01/app/18.3.0/grid/OPatch/opatchauto apply -analyze /u01/swtmp/32226219/ -oh /u01/app/18.3.0/grid/

OPatchauto session is initiated at Wed Jan 27 20:40:45 2021

System initialization log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb/systemconfig2021-01-27_08-40-48PM.log.

Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-40-51PM.log
The id for this session is 56VW
OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.
OPatchAuto failed.

OPatchauto session completed at Wed Jan 27 20:40:53 2021
Time taken to complete the session 0 minute, 8 seconds

 opatchauto failed with error code 42

The session log file:

2021-01-27 20:40:51,664 INFO  [1] com.oracle.glcm.patch.auto.OPatchAuto - OPatchAuto version: 13.9.4.5.0
2021-01-27 20:40:51,666 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-40-51PM.log'}
2021-01-27 20:40:51,733 INFO  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - crsType: SOFTWARE_INSTALLATION_ONLY
2021-01-27 20:40:51,733 INFO  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - running: false
2021-01-27 20:40:52,354 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - OPatchAutoOptions configured options:
2021-01-27 20:40:52,354 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: patch.location:patch-location Value:/u01/swtmp/32226219/
2021-01-27 20:40:52,354 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: home:-oh Value:/u01/app/18.3.0/grid/
2021-01-27 20:40:52,354 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: log:-log Value:/u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-40-51PM.log
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: log_priority:-logLevel Value:INFO
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: customLogDir:-customLogDir Value:/u01/app/18.3.0/grid/cfgtoollogs
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: analyze:-analyze Value:true
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: inventory.pointer.location:-invPtrLoc Value:/u01/app/18.3.0/grid//oraInst.loc
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: host:-host Value:rac1.example.com
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: patch.plan:-plan Value:crs-rolling
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: format:-format Value:xml
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: output:-output Value:console
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: customconfigdir:-customConfigDir Value:/u01/app/18.3.0/grid/opatchautocfg/db
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: nonrolling:-nonrolling Value:false
2021-01-27 20:40:52,355 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: session:-session Value:56VW
2021-01-27 20:40:52,545 INFO  [1] com.oracle.glcm.patch.auto.OPatchAuto - The id for this session is 56VW
2021-01-27 20:40:52,545 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='The id for this session is 56VW'}
2021-01-27 20:40:52,549 WARNING [1] com.oracle.glcm.patch.auto.credential.CredentialManager - Unable to locate credential for host rac1
2021-01-27 20:40:52,584 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoHelper - Executing command [bash, -c, ORACLE_HOME=/u01/app/18.3.0/grid /u01/app/18.3.0/grid/bin/orabasehome]
2021-01-27 20:40:52,602 INFO  [1] com.oracle.helper.util.HelperUtility - Orabasehome Output :
/u01/app/18.3.0/grid

2021-01-27 20:40:52,602 INFO  [1] com.oracle.helper.util.HelperUtility - Oracle Base Home for /u01/app/18.3.0/grid is /u01/app/18.3.0/grid
2021-01-27 20:40:52,603 WARNING [1] com.oracle.glcm.patch.auto.credential.CredentialManager - Unable to locate credential for host rac1
2021-01-27 20:40:52,616 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Entering getPatchPackageFromDir, getting patch object for the given patch location /u01/swtmp/32226219
2021-01-27 20:40:53,135 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchBundlePatchValidatorAndGenerator - Bundle.xml does not exist
2021-01-27 20:40:53,135 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator - inventory.xml found at /u01/swtmp/32226219/32216973/etc/config/inventory.xml which implies it is an OPatch Singleton patch
2021-01-27 20:40:53,137 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.PatchMetadaReader - Command for patch metadata::/u01/app/18.3.0/grid/perl/bin/perl  /u01/app/18.3.0/grid/OPatch/auto/database/bin/OPatchAutoBinary.pl query patchinfo -patch_location /u01/swtmp/32226219/32216973 -result /u01/app/18.3.0/grid/OPatch/auto/dbtmp/result.ser
2021-01-27 20:40:53,741 INFO  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Is retry required=false
2021-01-27 20:40:53,742 WARNING [1] com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer - Patch Collection failed: 
2021-01-27 20:40:53,743 INFO  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport - Space available after session: 32874 MB
2021-01-27 20:40:53,766 SEVERE [1] com.oracle.glcm.patch.auto.OPatchAuto - OPatchAuto failed.
com.oracle.glcm.patch.auto.OPatchAutoException: OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:97)
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.processInit(PatchingProcessInitializer.java:66)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.initializePatchData(DBCommonSupport.java:126)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.initializePatchData(DBBaseProductSupport.java:408)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.loadTopology(DBCommonSupport.java:163)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.loadTopology(DBBaseProductSupport.java:195)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport.loadTopology(DBProductSupport.java:69)
	at com.oracle.glcm.patch.auto.OPatchAuto.loadTopology(OPatchAuto.java:1732)
	at com.oracle.glcm.patch.auto.OPatchAuto.prepareOrchestration(OPatchAuto.java:730)
	at com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:397)
	at com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:344)
	at com.oracle.glcm.patch.auto.OPatchAuto.main(OPatchAuto.java:212)
Caused by: com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchCollectionException: 
	at com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator.generate(OPatchSingletonPatchValidatorAndGenerator.java:151)
	at oracle.dbsysmodel.patchsdk.PatchFactory.getInstance(PatchFactory.java:246)
	at com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl.getPatchPackageFromDir(PatchPackageFactoryImpl.java:75)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.prcoessPatch(BundlePatchObject.java:131)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.createPatchBagForPatchLocation(BundlePatchObject.java:124)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.<init>(BundlePatchObject.java:77)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchInformationInitializer.createPatch(PatchInformationInitializer.java:43)
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:80)
	... 11 more
2021-01-27 20:40:53,767 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.'}
2021-01-27 20:40:53,767 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='OPatchAuto failed.'}

There are several common scenarios when I see such errors:

• Wrong permissions on patch files
• A wrong folder passed to opatchauto
• Wrong opatch version

None of these was the case:

[grid@rac1 ~]$ /u01/app/18.3.0/grid/OPatch/opatch version
OPatch Version: 12.2.0.1.23

OPatch succeeded.

After checking the usual suspects, I had to enable logging:

[root@rac1 ~]# /u01/app/18.3.0/grid/OPatch/opatchauto apply -analyze /u01/swtmp/32226219/ -logLevel FINEST -oh /u01/app/18.3.0/grid/

OPatchauto session is initiated at Wed Jan 27 20:52:04 2021

System initialization log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb/systemconfig2021-01-27_08-52-07PM.log.

Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-52-10PM.log
The id for this session is 7NBB
OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.
OPatchAuto failed.

OPatchauto session completed at Wed Jan 27 20:52:12 2021
Time taken to complete the session 0 minute, 8 seconds

 opatchauto failed with error code 42

This time around I got something new:

2021-01-27 20:52:10,508 FINEST [1] com.oracle.cie.common.util.reporting.Reporting - Adding reporter com.oracle.cie.common.util.reporting.console.ConsoleReporter@4445629
2021-01-27 20:52:10,510 INFO  [1] com.oracle.glcm.patch.auto.OPatchAuto - OPatchAuto version: 13.9.4.5.0
2021-01-27 20:52:10,511 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-52-10PM.log'}
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  ShardedDatabase set as false
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  DataGuard primary set as : null
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  ShardGroup set as : null
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  ShardSpace set as : null
2021-01-27 20:52:10,517 FINER [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport -  productSupport initialize: com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport@48fa0f47
2021-01-27 20:52:10,517 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:10,577 INFO  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - crsType: SOFTWARE_INSTALLATION_ONLY
2021-01-27 20:52:10,577 INFO  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - running: false
2021-01-27 20:52:10,577 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - ENTRY
2021-01-27 20:52:10,577 FINE  [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - CRS stack is down. Now getting crs version by OUI.
2021-01-27 20:52:10,660 FINEST [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - Added Component:oracle.crs
2021-01-27 20:52:10,660 FINEST [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - Added OUI Info to:OraGI18Home1
2021-01-27 20:52:10,660 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - ENTRY
2021-01-27 20:52:10,660 FINEST [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - Executing OPatch/opatch version for OracleHome at /u01/app/18.3.0/grid
2021-01-27 20:52:10,968 FINE  [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - /u01/app/18.3.0/grid has OPatch Version 12.2.0.1.23
2021-01-27 20:52:10,968 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - RETURN
2021-01-27 20:52:10,969 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - ENTRY
2021-01-27 20:52:10,969 FINE  [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - ORACLE_BASE for /u01/app/18.3.0/grid is /u01/app/grid
2021-01-27 20:52:10,969 FINER [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - RETURN
2021-01-27 20:52:10,969 FINEST [1] oracle.dbsysmodel.driver.sdk.productdriver.OUIDriver - Found Local Home:/u01/app/18.3.0/grid
2021-01-27 20:52:10,969 CONFIG [1] oracle.dbsysmodel.driver.sdk.productdriver.ClusterInformationLoader - Found local home at /u01/app/18.3.0/grid
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - isSingleSession: false
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - prepareSession: false
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:11,108 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - oopEnabled: false
2021-01-27 20:52:11,112 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.CRSTopologyBuilder - SIDBonly is set to false
2021-01-27 20:52:11,113 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property LocalHost
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property logDir
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property SessionID
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property OracleHome
2021-01-27 20:52:11,142 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property LogFileLevel
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ConsoleLogLevel
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property OPlanLocation
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ConfigXML
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property invPtrLoc
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property UserInvokingOplan
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property RootUser
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property TmpFilesDir
2021-01-27 20:52:11,143 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ExecutionMode
2021-01-27 20:52:11,144 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property AdminServerURL
2021-01-27 20:52:11,144 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property AdminServerUser
2021-01-27 20:52:11,144 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property AdminServerPassword
2021-01-27 20:52:11,144 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property BundlePatchLocation
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property RACPatchLocations
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property GIPatchLocations
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property AllPatchLocations
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property PatchIDs
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property Operation
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property SkipConfigValidation
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ProductFamily
2021-01-27 20:52:11,145 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property NodeNumberPerReadme
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property MoveConfigToOH
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property SelectivePatchingEnabled
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property ConfigurationSnapshot
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property MinimumOPatchVersion
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property IntgFactoryClass
2021-01-27 20:52:11,146 FINEST [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Found property customLogPath
2021-01-27 20:52:11,154 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.CRSTopologyBuilder - Creating config graph from instance
2021-01-27 20:52:11,179 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport - Actions loaded...
2021-01-27 20:52:11,182 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.SDBProductSupport - Actions loaded...
2021-01-27 20:52:11,208 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - isSingleSession: false
2021-01-27 20:52:11,208 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - prepareSession: false
2021-01-27 20:52:11,208 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - switchSession: false
2021-01-27 20:52:11,208 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - oopEnabled: false
2021-01-27 20:52:11,211 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - OPatchAutoOptions configured options:
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: patch.location:patch-location Value:/u01/swtmp/32226219/
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: home:-oh Value:/u01/app/18.3.0/grid/
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: log:-log Value:/u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_08-52-10PM.log
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: log_priority:-logLevel Value:FINEST
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: customLogDir:-customLogDir Value:/u01/app/18.3.0/grid/cfgtoollogs
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: analyze:-analyze Value:true
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: inventory.pointer.location:-invPtrLoc Value:/u01/app/18.3.0/grid//oraInst.loc
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: host:-host Value:rac1.example.com
2021-01-27 20:52:11,212 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: patch.plan:-plan Value:crs-rolling
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: format:-format Value:xml
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: output:-output Value:console
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: customconfigdir:-customConfigDir Value:/u01/app/18.3.0/grid/opatchautocfg/db
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: nonrolling:-nonrolling Value:false
2021-01-27 20:52:11,213 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoOptions - Option: session:-session Value:7NBB
2021-01-27 20:52:11,215 FINE  [1] com.oracle.glcm.patch.auto.tracking.PatchTracking - Adding new execution with id 1 to patch tracking session 7NBB
2021-01-27 20:52:11,222 FINE  [1] com.oracle.glcm.patch.auto.tracking.PatchTracking - Saving patch tracking session to /u01/app/18.3.0/grid/opatchautocfg/db/sessioninfo/7NBB.json
2021-01-27 20:52:11,421 INFO  [1] com.oracle.glcm.patch.auto.OPatchAuto - The id for this session is 7NBB
2021-01-27 20:52:11,422 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='The id for this session is 7NBB'}
2021-01-27 20:52:11,424 FINEST [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - requestedHostName: rac1.example.com
2021-01-27 20:52:11,425 FINEST [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - formattedHostName: rac1
2021-01-27 20:52:11,425 WARNING [1] com.oracle.glcm.patch.auto.credential.CredentialManager - Unable to locate credential for host rac1
2021-01-27 20:52:11,425 FINE  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.topology.DBPatchingHelper - Permissions: 700
2021-01-27 20:52:11,428 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, root, -m, -c, chmod 700 /u01/app/18.3.0/grid/.patch_storage]
2021-01-27 20:52:11,448 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:11,448 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 0
2021-01-27 20:52:11,448 FINEST [1] com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer - Operation type:apply
2021-01-27 20:52:11,453 FINER [1] com.oracle.glcm.patch.auto.db.framework.sdk.patchplanner.PatchPlanEnv - Unrecognized property "autoDeploymentSubType"
2021-01-27 20:52:11,460 INFO  [1] com.oracle.glcm.patch.auto.OPatchAutoHelper - Executing command [bash, -c, ORACLE_HOME=/u01/app/18.3.0/grid /u01/app/18.3.0/grid/bin/orabasehome]
2021-01-27 20:52:11,461 FINE  [1] com.oracle.glcm.patch.auto.OPatchAutoHelper - Executing command [bash, -c, ORACLE_HOME=/u01/app/18.3.0/grid /u01/app/18.3.0/grid/bin/orabasehome] in dir null with env null
2021-01-27 20:52:11,477 INFO  [1] com.oracle.helper.util.HelperUtility - Orabasehome Output :
/u01/app/18.3.0/grid

2021-01-27 20:52:11,477 INFO  [1] com.oracle.helper.util.HelperUtility - Oracle Base Home for /u01/app/18.3.0/grid is /u01/app/18.3.0/grid
2021-01-27 20:52:11,478 WARNING [1] com.oracle.glcm.patch.auto.credential.CredentialManager - Unable to locate credential for host rac1
2021-01-27 20:52:11,478 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.oplan.IOUtils - Change the permission of the file /u01/app/18.3.0/grid/cfgtoollogs/opatchautodbto 775
2021-01-27 20:52:11,478 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, grid, -m, -c, chmod 775 /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb]
2021-01-27 20:52:11,492 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:11,492 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 0
2021-01-27 20:52:11,494 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Entering getPatchPackageFromDir, getting patch object for the given patch location /u01/swtmp/32226219
2021-01-27 20:52:11,495 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding to the patch factory all supported PatchValidatorsAndGenerators. 
2021-01-27 20:52:11,499 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchBundlePatchValidatorAndGenerator
2021-01-27 20:52:11,499 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,499 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator
2021-01-27 20:52:11,499 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,499 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.CompositePatchValidatorAndGenerator
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,500 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.ExapatchPatchValidatorAndGenerator
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,500 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl - Adding PatchValidatorAndGenerator class com.oracle.glcm.patch.auto.db.framework.core.patch.DefaultPatchValidatorAndGenerator
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - ENTRY
2021-01-27 20:52:11,500 FINEST [1] oracle.dbsysmodel.patchsdk.PatchFactory - patchLocation /u01/swtmp/32226219
2021-01-27 20:52:12,036 FINE  [1] oracle.dbsysmodel.patchsdk.PatchFactory - Patch represented by the given patch location /u01/swtmp/32226219 is an Engineered System Patch.
2021-01-27 20:52:12,078 FINE  [1] oracle.dbsysmodel.patchsdk.PatchFactory - Trying to create sub patch with the PatchValidatorAndGenerator com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchBundlePatchValidatorAndGenerator
2021-01-27 20:52:12,078 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchBundlePatchValidatorAndGenerator - Bundle.xml does not exist
2021-01-27 20:52:12,079 FINE  [1] oracle.dbsysmodel.patchsdk.PatchFactory - Trying to create sub patch with the PatchValidatorAndGenerator com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator
2021-01-27 20:52:12,079 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator - inventory.xml found at /u01/swtmp/32226219/32216973/etc/config/inventory.xml which implies it is an OPatch Singleton patch
2021-01-27 20:52:12,081 INFO  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.PatchMetadaReader - Command for patch metadata::/u01/app/18.3.0/grid/perl/bin/perl  /u01/app/18.3.0/grid/OPatch/auto/database/bin/OPatchAutoBinary.pl query patchinfo -patch_location /u01/swtmp/32226219/32216973 -result /u01/app/18.3.0/grid/OPatch/auto/dbtmp/result.ser
2021-01-27 20:52:12,081 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, grid, -m, -c, /u01/app/18.3.0/grid/perl/bin/perl  /u01/app/18.3.0/grid/OPatch/auto/database/bin/OPatchAutoBinary.pl query patchinfo -patch_location /u01/swtmp/32226219/32216973 -result /u01/app/18.3.0/grid/OPatch/auto/dbtmp/result.ser]
2021-01-27 20:52:12,657 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Error message:Exception in thread "main" java.util.ServiceConfigurationError: java.nio.file.spi.FileSystemProvider: Provider org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider could not be instantiated
	at java.util.ServiceLoader.fail(ServiceLoader.java:232)
	at java.util.ServiceLoader.access$100(ServiceLoader.java:185)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:384)
	at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
	at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
	at java.nio.file.spi.FileSystemProvider.loadInstalledProviders(FileSystemProvider.java:119)
	at java.nio.file.spi.FileSystemProvider.access$000(FileSystemProvider.java:77)
	at java.nio.file.spi.FileSystemProvider$1.run(FileSystemProvider.java:169)
	at java.nio.file.spi.FileSystemProvider$1.run(FileSystemProvider.java:166)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.nio.file.spi.FileSystemProvider.installedProviders(FileSystemProvider.java:166)
	at java.nio.file.FileSystems.newFileSystem(FileSystems.java:388)
	at oracle.opatch.wrappers.WrapperFactory.loadWrapperProvider(WrapperFactory.java:144)
	at oracle.opatch.wrappers.WrapperFactory.loadWrapperProvider(WrapperFactory.java:103)
	at oracle.opatch.wrappers.WrapperFactory.getNioServiceWrapper(WrapperFactory.java:71)
	at oracle.opatch.opatchutil.OUSession.phbasedir(OUSession.java:2594)
	at oracle.opatch.opatchsdk.OPatchPatch.getPatches(OPatchPatch.java:486)
	at oracle.opatch.opatchsdk.OPatchPatch.getPatchesNoSymbolResolve(OPatchPatch.java:456)
	at oracle.opatchauto.core.utility.operation.PatchMetadataQueryOperation.getPatchInfo(PatchMetadataQueryOperation.java:45)
	at oracle.opatchauto.core.utility.operation.PatchMetadataQueryOperation.execute(PatchMetadataQueryOperation.java:26)
	at oracle.opatchauto.core.OpatchAutoCoreUtility.main(OpatchAutoCoreUtility.java:41)
Caused by: java.lang.ExceptionInInitializerError
	at javax.crypto.JceSecurityManager.<clinit>(JceSecurityManager.java:65)
	at javax.crypto.Cipher.getConfiguredPermission(Cipher.java:2590)
	at javax.crypto.Cipher.getMaxAllowedKeyLength(Cipher.java:2614)
	at org.apache.sshd.common.cipher.Cipher.checkSupported(Cipher.java:80)
	at org.apache.sshd.common.cipher.BuiltinCiphers.<init>(BuiltinCiphers.java:104)
	at org.apache.sshd.common.cipher.BuiltinCiphers.<clinit>(BuiltinCiphers.java:55)
	at org.apache.sshd.common.BaseBuilder.<clinit>(BaseBuilder.java:70)
	at org.apache.sshd.client.SshClient.setUpDefaultClient(SshClient.java:778)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:170)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:161)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:157)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:144)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(Class.java:442)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:380)
	... 18 more
Caused by: java.lang.SecurityException: Can not initialize cryptographic mechanism
	at javax.crypto.JceSecurity.<clinit>(JceSecurity.java:93)
	... 36 more
Caused by: java.lang.SecurityException: The jurisdiction policy files are not signed by the expected signer! (Policy files are specific per major JDK release.Ensure the correct version is installed.)
	at javax.crypto.JarVerifier.verifyPolicySigned(JarVerifier.java:336)
	at javax.crypto.JceSecurity.loadPolicies(JceSecurity.java:378)
	at javax.crypto.JceSecurity.setupJurisdictionPolicies(JceSecurity.java:323)
	at javax.crypto.JceSecurity.access$000(JceSecurity.java:50)
	at javax.crypto.JceSecurity$1.run(JceSecurity.java:85)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.crypto.JceSecurity.<clinit>(JceSecurity.java:82)
	... 36 more

2021-01-27 20:52:12,657 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:12,657 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 1
2021-01-27 20:52:12,657 INFO  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Is retry required=false
2021-01-27 20:52:12,657 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.PatchMetadaReader - Query output::
2021-01-27 20:52:12,657 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.patch.PatchMetadaReader - Query err::Exception in thread "main" java.util.ServiceConfigurationError: java.nio.file.spi.FileSystemProvider: Provider org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider could not be instantiated
	at java.util.ServiceLoader.fail(ServiceLoader.java:232)
	at java.util.ServiceLoader.access$100(ServiceLoader.java:185)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:384)
	at java.util.ServiceLoader$LazyIterator.next(ServiceLoader.java:404)
	at java.util.ServiceLoader$1.next(ServiceLoader.java:480)
	at java.nio.file.spi.FileSystemProvider.loadInstalledProviders(FileSystemProvider.java:119)
	at java.nio.file.spi.FileSystemProvider.access$000(FileSystemProvider.java:77)
	at java.nio.file.spi.FileSystemProvider$1.run(FileSystemProvider.java:169)
	at java.nio.file.spi.FileSystemProvider$1.run(FileSystemProvider.java:166)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.nio.file.spi.FileSystemProvider.installedProviders(FileSystemProvider.java:166)
	at java.nio.file.FileSystems.newFileSystem(FileSystems.java:388)
	at oracle.opatch.wrappers.WrapperFactory.loadWrapperProvider(WrapperFactory.java:144)
	at oracle.opatch.wrappers.WrapperFactory.loadWrapperProvider(WrapperFactory.java:103)
	at oracle.opatch.wrappers.WrapperFactory.getNioServiceWrapper(WrapperFactory.java:71)
	at oracle.opatch.opatchutil.OUSession.phbasedir(OUSession.java:2594)
	at oracle.opatch.opatchsdk.OPatchPatch.getPatches(OPatchPatch.java:486)
	at oracle.opatch.opatchsdk.OPatchPatch.getPatchesNoSymbolResolve(OPatchPatch.java:456)
	at oracle.opatchauto.core.utility.operation.PatchMetadataQueryOperation.getPatchInfo(PatchMetadataQueryOperation.java:45)
	at oracle.opatchauto.core.utility.operation.PatchMetadataQueryOperation.execute(PatchMetadataQueryOperation.java:26)
	at oracle.opatchauto.core.OpatchAutoCoreUtility.main(OpatchAutoCoreUtility.java:41)
Caused by: java.lang.ExceptionInInitializerError
	at javax.crypto.JceSecurityManager.<clinit>(JceSecurityManager.java:65)
	at javax.crypto.Cipher.getConfiguredPermission(Cipher.java:2590)
	at javax.crypto.Cipher.getMaxAllowedKeyLength(Cipher.java:2614)
	at org.apache.sshd.common.cipher.Cipher.checkSupported(Cipher.java:80)
	at org.apache.sshd.common.cipher.BuiltinCiphers.<init>(BuiltinCiphers.java:104)
	at org.apache.sshd.common.cipher.BuiltinCiphers.<clinit>(BuiltinCiphers.java:55)
	at org.apache.sshd.common.BaseBuilder.<clinit>(BaseBuilder.java:70)
	at org.apache.sshd.client.SshClient.setUpDefaultClient(SshClient.java:778)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:170)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:161)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:157)
	at org.apache.sshd.client.subsystem.sftp.fs.SftpFileSystemProvider.<init>(SftpFileSystemProvider.java:144)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
	at java.lang.Class.newInstance(Class.java:442)
	at java.util.ServiceLoader$LazyIterator.nextService(ServiceLoader.java:380)
	... 18 more
Caused by: java.lang.SecurityException: Can not initialize cryptographic mechanism
	at javax.crypto.JceSecurity.<clinit>(JceSecurity.java:93)
	... 36 more
Caused by: java.lang.SecurityException: The jurisdiction policy files are not signed by the expected signer! (Policy files are specific per major JDK release.Ensure the correct version is installed.)
	at javax.crypto.JarVerifier.verifyPolicySigned(JarVerifier.java:336)
	at javax.crypto.JceSecurity.loadPolicies(JceSecurity.java:378)
	at javax.crypto.JceSecurity.setupJurisdictionPolicies(JceSecurity.java:323)
	at javax.crypto.JceSecurity.access$000(JceSecurity.java:50)
	at javax.crypto.JceSecurity$1.run(JceSecurity.java:85)
	at java.security.AccessController.doPrivileged(Native Method)
	at javax.crypto.JceSecurity.<clinit>(JceSecurity.java:82)
	... 36 more

2021-01-27 20:52:12,658 FINE  [1] com.oracle.cie.common.util.ResourceBundleManager - The code () is null or not an integer.
2021-01-27 20:52:12,658 WARNING [1] com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer - Patch Collection failed: 
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator.generate(OPatchSingletonPatchValidatorAndGenerator.java:151)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - oracle.dbsysmodel.patchsdk.PatchFactory.getInstance(PatchFactory.java:246)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl.getPatchPackageFromDir(PatchPackageFactoryImpl.java:75)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.prcoessPatch(BundlePatchObject.java:131)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.createPatchBagForPatchLocation(BundlePatchObject.java:124)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.<init>(BundlePatchObject.java:77)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchInformationInitializer.createPatch(PatchInformationInitializer.java:43)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:80)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.processInit(PatchingProcessInitializer.java:66)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.initializePatchData(DBCommonSupport.java:126)
2021-01-27 20:52:12,659 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.initializePatchData(DBBaseProductSupport.java:408)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.loadTopology(DBCommonSupport.java:163)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.loadTopology(DBBaseProductSupport.java:195)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport.loadTopology(DBProductSupport.java:69)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.loadTopology(OPatchAuto.java:1732)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.prepareOrchestration(OPatchAuto.java:730)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:397)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:344)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.glcm.patch.auto.db.product.GILogger - com.oracle.glcm.patch.auto.OPatchAuto.main(OPatchAuto.java:212)
2021-01-27 20:52:12,660 FINE  [1] com.oracle.cie.common.util.ResourceBundleManager - The code (OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.) is null or not an integer.
2021-01-27 20:52:12,660 INFO  [1] com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport - Space available after session: 32877 MB
2021-01-27 20:52:12,662 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, root, -m, -c, cp /tmp/patchingsummary.xml /u01/app/18.3.0/grid/opatchautocfg/db/sessioninfo/]
2021-01-27 20:52:12,673 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:12,673 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 0
2021-01-27 20:52:12,674 FINE  [1] com.oracle.glcm.patch.auto.db.framework.core.oplan.IOUtils - Change the permission of the file /u01/app/18.3.0/grid/opatchautocfg/db/sessioninfo/patchingsummary.xmlto 775
2021-01-27 20:52:12,674 FINE  [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - System Call command is: [/bin/su, root, -m, -c, chmod 775 /u01/app/18.3.0/grid/opatchautocfg/db/sessioninfo/patchingsummary.xml]
2021-01-27 20:52:12,683 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Output message:
2021-01-27 20:52:12,684 FINEST [1] com.oracle.glcm.patch.auto.db.product.executor.GISystemCall - Return code: 0
2021-01-27 20:52:12,684 SEVERE [1] com.oracle.glcm.patch.auto.OPatchAuto - OPatchAuto failed.
com.oracle.glcm.patch.auto.OPatchAutoException: OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:97)
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.processInit(PatchingProcessInitializer.java:66)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.initializePatchData(DBCommonSupport.java:126)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.initializePatchData(DBBaseProductSupport.java:408)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBCommonSupport.loadTopology(DBCommonSupport.java:163)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBBaseProductSupport.loadTopology(DBBaseProductSupport.java:195)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.DBProductSupport.loadTopology(DBProductSupport.java:69)
	at com.oracle.glcm.patch.auto.OPatchAuto.loadTopology(OPatchAuto.java:1732)
	at com.oracle.glcm.patch.auto.OPatchAuto.prepareOrchestration(OPatchAuto.java:730)
	at com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:397)
	at com.oracle.glcm.patch.auto.OPatchAuto.orchestrate(OPatchAuto.java:344)
	at com.oracle.glcm.patch.auto.OPatchAuto.main(OPatchAuto.java:212)
Caused by: com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchCollectionException: 
	at com.oracle.glcm.patch.auto.db.framework.core.patch.OPatchSingletonPatchValidatorAndGenerator.generate(OPatchSingletonPatchValidatorAndGenerator.java:151)
	at oracle.dbsysmodel.patchsdk.PatchFactory.getInstance(PatchFactory.java:246)
	at com.oracle.glcm.patch.auto.db.framework.core.patch.impl.PatchPackageFactoryImpl.getPatchPackageFromDir(PatchPackageFactoryImpl.java:75)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.prcoessPatch(BundlePatchObject.java:131)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.createPatchBagForPatchLocation(BundlePatchObject.java:124)
	at com.oracle.glcm.patch.auto.db.product.patch.BundlePatchObject.<init>(BundlePatchObject.java:77)
	at com.oracle.glcm.patch.auto.db.integration.model.productsupport.patch.PatchInformationInitializer.createPatch(PatchInformationInitializer.java:43)
	at com.oracle.glcm.patch.auto.db.integration.model.plan.PatchingProcessInitializer.initializePatchPackageBag(PatchingProcessInitializer.java:80)
	... 11 more
2021-01-27 20:52:12,685 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='OPATCHAUTO-72043: Patch collection failed.
OPATCHAUTO-72043: Failed to create bundle patch object.
OPATCHAUTO-72043: Please verify the patch supplied.'}
2021-01-27 20:52:12,685 INFO  [1] com.oracle.cie.common.util.reporting.CommonReporter - Reporting console output : Message{id='null', message='OPatchAuto failed.'}

The errors pointed out to Java: Bug 31997805 - Exception In Thread "root thread" java.lang.exceptionininitializererror in 12.2 Database (Doc ID 31997805.8). To verify that hypothesis, I downloaded Java Cryptography Extension (JCE) Unlimited Strength Jurisdiction Policy Files 8. I copied both local_policy.jar and US_export_policy.jar to /u01/app/18.3.0/grid/OPatch/jre/lib/security, and reran opatchauto.
Sure enough, the analyze command was successful:

[root@rac1 ~]# /u01/app/18.3.0/grid/OPatch/opatchauto apply -analyze /u01/swtmp/32226219/ -oh /u01/app/18.3.0/grid/  
OPatchauto session is initiated at Wed Jan 27 21:02:05 2021

System initialization log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb/systemconfig2021-01-27_09-02-08PM.log.

Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_09-02-10PM.log
The id for this session is D2B1

Executing OPatch prereq operations to verify patch applicability on home /u01/app/18.3.0/grid
Patch applicability verified successfully on home /u01/app/18.3.0/grid


Executing patch validation checks on home /u01/app/18.3.0/grid
Patch validation checks successfully completed on home /u01/app/18.3.0/grid

OPatchAuto successful.

--------------------------------Summary--------------------------------

Analysis for applying patches has completed successfully:

Host:rac1
CRS Home:/u01/app/18.3.0/grid
Version:18.0.0.0.0


==Following patches were SUCCESSFULLY analyzed to be applied:

Patch: /u01/swtmp/32226219/32216973
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log

Patch: /u01/swtmp/32226219/32216944
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log

Patch: /u01/swtmp/32226219/28655963
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log

Patch: /u01/swtmp/32226219/32240606
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log

Patch: /u01/swtmp/32226219/32204699
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-02-24PM_1.log



OPatchauto session completed at Wed Jan 27 21:02:38 2021
Time taken to complete the session 0 minute, 33 seconds

The policy files themselves should not be needed since Java 8 Update 161: Unlimited cryptography enabled by default.
The Java version that comes with OPatch 12.2.0.1.23 is newer, so that it should contain the fix:

[grid@rac1 bin]$ /u01/app/18.3.0/grid/OPatch/jre/bin/java -version
java version "1.8.0_271"
Java(TM) SE Runtime Environment (build 1.8.0_271-b03)
Java HotSpot(TM) 64-Bit Server VM (build 25.271-b03, mixed mode)

I also checked with several 19c clusters that these policy files were not there. How come if the OPatch version was the same?

Turns out that when the OPatch was updated, the proper update procedure was not followed: How To Download And Install The Latest OPatch(6880880) Version (Doc ID 274526.1):

• Policy files are present in a vanilla 18c home:

  [grid@rac1 grid]$ unzip -l /u01/swtmp/LINUX.X64_180000_grid_home.zip | grep "OPatch/jre/lib/security/.*.jar"
       3026  06-04-2018 00:52   OPatch/jre/lib/security/US_export_policy.jar
       3527  06-04-2018 00:52   OPatch/jre/lib/security/local_policy.jar
  

• The old OPatch directory was not removed. Instead a newer OPatch version was copied over the existing OPatch folder.
• Since the old OPatch directory was not removed, the policy files were kept after the newer OPatch version was deployed

I just moved the existing OPatch folder and did a clean OPatch deployment:

[grid@rac1 grid]$ mv OPatch/ OPatch_$(date +%Y%m%d)/
[grid@rac1 grid]$ unzip /u01/swtmp/p6880880_190000_Linux-x86-64.zip

The apply analyze command ran without errors and I applied the release update later on:

[root@rac1 ~]# /u01/app/18.3.0/grid/OPatch/opatchauto apply -analyze /u01/swtmp/32226219/ -oh /u01/app/18.3.0/grid/

OPatchauto session is initiated at Wed Jan 27 21:12:01 2021

System initialization log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchautodb/systemconfig2021-01-27_09-12-04PM.log.

Session log file is /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/opatchauto2021-01-27_09-12-07PM.log
The id for this session is 3IKL

Executing OPatch prereq operations to verify patch applicability on home /u01/app/18.3.0/grid
Patch applicability verified successfully on home /u01/app/18.3.0/grid


Executing patch validation checks on home /u01/app/18.3.0/grid
Patch validation checks successfully completed on home /u01/app/18.3.0/grid

OPatchAuto successful.

--------------------------------Summary--------------------------------

Analysis for applying patches has completed successfully:

Host:rac1
CRS Home:/u01/app/18.3.0/grid
Version:18.0.0.0.0


==Following patches were SUCCESSFULLY analyzed to be applied:

Patch: /u01/swtmp/32226219/32216973
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log

Patch: /u01/swtmp/32226219/32216944
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log

Patch: /u01/swtmp/32226219/28655963
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log

Patch: /u01/swtmp/32226219/32240606
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log

Patch: /u01/swtmp/32226219/32204699
Log: /u01/app/18.3.0/grid/cfgtoollogs/opatchauto/core/opatch/opatch2021-01-27_21-12-21PM_1.log



OPatchauto session completed at Wed Jan 27 21:12:36 2021
Time taken to complete the session 0 minute, 35 seconds

It is crucial to follow Oracle instructions to the letter when it makes sense.
Otherwise, it can lead to such uncommon errors. It is also disappointing that opatchauto did not give any clue what was going on with the default logging level. Thankfully, the logging level can be easily changed. It is a bit verbose but it usually does the job and gives enough information about the cause of an issue.

SYS and Extended Data Types

It is a widely known fact that Oracle supports a maximum size of 32,767 bytes for the VARCHAR2, NVARCHAR2, and RAW data types (Extended Data Types) provided that MAX_STRING_SIZE = EXTENDED. What I recently discovered is that SYS can create such columns even when MAX_STRING_SIZE = STANDARD. It is possible in 12.2, 18c, 19c. I am unsure about 12.1 since I do not have any of those.

Firstly, let us try to create a table with a VARCHAR2(32767) column as non-SYS user:

SQL> conn tc/tc@localhost/pdb2
Connected.
SQL> sho parameter max_string_size

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_string_size                      string      STANDARD
SQL> select banner_full from v$version;

BANNER_FULL
--------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.10.0.0.0


SQL> create table t(c varchar2(32767));
create table t(c varchar2(32767))
                          *
ERROR at line 1:
ORA-00910: specified length too long for its datatype

It fails as expected.

Now I try the same as SYS - I also switch to my root container to verify that MAX_STRING_SIZE = STANDARD everywhere:

SQL> conn sys/Oracle123@localhost/orcl2 as sysdba
Connected.
SQL> alter session set container=cdb$root;

Session altered.

SQL> sho parameter max_string_size

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_string_size                      string      STANDARD
SQL> alter session set container=pdb2;

Session altered.

SQL> sho parameter max_string_size

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
max_string_size                      string      STANDARD
SQL> select banner_full from v$version;

BANNER_FULL
--------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.10.0.0.0


SQL> create table t(c varchar2(32767));

Table created.

SQL> desc t
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 C                                                  VARCHAR2(32767)

Let us try to run a DML command:

SQL> insert into t values (lpad('x',32767,'x'));

1 row created.

SQL> select length(c) from t;

 LENGTH(C)
----------
      4000

Although it was possible to create a 32K column, somewhere between LPAD and the data layer I still got 4,000 bytes only.
But is it limited to 4,000 bytes? Not really as the example below demonstrates:

SQL> update t
  2     set c=c||'y';

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
      4001

SQL>
SQL> update t
  2     set c=c||c;

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
      8002

SQL>
SQL> update t
  2     set c=c||c;

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
     16004

SQL>
SQL> update t
  2     set c=c||c;

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
     32008

SQL>
SQL> update t
  2     set c=c||c;
update t
*
ERROR at line 1:
ORA-01489: result of string concatenation is too long


SQL> select length(c) from t;

 LENGTH(C)
----------
     32008

SQL>
SQL> update t
  2     set c=c||lpad('x',759,'x');

1 row updated.

SQL> select length(c) from t;

 LENGTH(C)
----------
     32767

SQL>
SQL> update t
  2     set c=c||'x';
update t
       *
ERROR at line 1:
ORA-01489: result of string concatenation is too long


SQL> select length(c) from t;

 LENGTH(C)
----------
     32767

As expected Oracle stores the column as LOB under the hood:

SQL> select dbms_metadata.get_ddl('TABLE', 'T') from dual;

DBMS_METADATA.GET_DDL('TABLE','T')
--------------------------------------------------------------------------------

  CREATE TABLE "SYS"."T"
   (    "C" VARCHAR2(32767)
   ) PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255
 NOCOMPRESS LOGGING
  STORAGE(INITIAL 65536 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
  PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1
  BUFFER_POOL DEFAULT FLASH_CACHE DEFAULT CELL_FLASH_CACHE DEFAULT)
  TABLESPACE "SYSTEM"


SQL>
SQL> select column_name, segment_name, index_name, securefile
  2    from user_lobs
  3   where table_name='T';

COLUMN_NAME SEGMENT_NAME              INDEX_NAME                SECUREFILE
----------- ------------------------- ------------------------- ----------
C           SYS_LOB0000023954C00001$$ SYS_IL0000023954C00001$$  NO

Turns out that Oracle uses that internally:

SQL> drop table t;

Table dropped.

SQL>
SQL> select table_name, column_name, data_length
  2    from user_tab_cols
  3   where data_type = 'VARCHAR2'
  4     and data_length > 4000;

TABLE_NAME                COLUMN_NAME          DATA_LENGTH
------------------------- -------------------- -----------
OPATCH_SQL_PATCHES        NODE_NAMES                 32000
SYSDBIMFS_METADATA$       VALUE                       4096
SCHEDULER$_CREDENTIAL     KEY                        32767
V_$DIAG_LOG_EXT           SUPPLEMENTAL_DETAILS        4003

Originally I discovered that Oracle uses VARCHAR2(32767) in its scripts which threw me into a tizzy since the scripts were running without errors in MAX_STRING_SIZE = STANDARD databases.
It is yet another confirmation that it is not a good idea to use SYS to do things. SYS is a "special" user.

Creating RAC Physical Standby for Single Instance Primary

Oracle made some interesting improvements in Database Configuration Assistant (DBCA) in 18c, namely this:

Creating a copy of an Oracle RAC database
A copy of an Oracle RAC database can be created using the -createDuplicateDB command option -databaseConfigType with the value of RAC or RACONENODE.

It has been possible to create a standby database using the createDuplicateDB DBCA command since 12.2.
18c added a new capability to specify the database configuration type of a new standby, such as: RAC, RAC One Node, or a regular single instance database.

This method by itself requires some prerequisite actions. I do not see that these are documented, so that I am writing this blog post.

Setup

Primary

• Hostname: primary
• db_name: orcl
• db_unique_name: orcl
• Configuration Type: Single Instance

Standby

• Hostnames: rac1.example.com, rac2.example.com
• db_unique_name: racdb
• Configuration Type: RAC
• SCAN port: 1521
• Local listener port: 1522
• Grid Home: /u01/app/19.3.0/grid, owner=grid
• DB Home: /u01/app/oracle/product/19.3.0/dbhome_1, owner=oracle (role separation)
• ASM disk groups: single disk group DATA - it is a sandbox

The naming convention might be a bit odd, but the main purpose of this configuration is to provide some initial steps to setup a new RAC database with a view to making it a new primary.

DBCA Command

This is a DBCA command that I will run to create a standby database in 19.9:

dbca -createDuplicateDB -silent \
     -gdbName orcl \
     -primaryDBConnectionString primary:1521/orcl \
     -sid racdb \
     -initParams "dg_broker_start=true" \
     -sysPassword change_on_install \
     -adminManaged \
     -nodelist rac1,rac2 \
     -recoveryAreaDestination +DATA \
       -recoveryAreaSize 10000 \
     -databaseConfigType RAC \
     -useOMF true \
     -storageType ASM \
       -datafileDestination +DATA \
     -createAsStandby \
       -dbUniqueName racdb \
     -createListener rac1.example.com:1522

Firstly, let me go over the keys that are worth mentioning.

1. -primaryDBConnectionString primary:1521/orcl - it should have a specific port number even if it is default 1521
2. -createListener rac1.example.com:1522 - this is the most interesting part. This is part of the RMAN block that is run to create a physical standby database:

   duplicate target database
   for standby
   from active database
   dorecover
   nofilenamecheck
   ;

   It is the push-based method of active database duplication. Therefore, the primary database should be able to connect to the new standby. I specified the local listener endpoint (1522) in this example. Then, DBCA always tries to create a new listener in this configuration. I do not know how to avoid that here. Even worse, it attempts to create a new listener in DB home. Thankfully, it silently swallows an error if the listener already exists. Here is a sample excerpt from the DBCA log file to substantiate that remark with some facts:

   [progressPage.flowWorker] [ 2020-12-30 19:04:30.642 UTC ] [ClusterInfo.getHostName:462]  Hostname = rac1
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: Executing [/u01/app/oracle/product/19.3.0/dbhome_1/bin/lsnrctl, start, rac1.example.com]
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: Starting Output Reader Threads for process /u01/app/oracle/product/19.3.0/dbhome_1/bin/lsnrctl
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO:
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO: LSNRCTL for Linux: Version 19.0.0.0.0 - Production on 30-DEC-2020 19:04:30
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO:
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO: Copyright (c) 1991, 2020, Oracle.  All rights reserved.
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO:
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO: TNS-01106: Listener using listener name LISTENER has already been started
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: The process /u01/app/oracle/product/19.3.0/dbhome_1/bin/lsnrctl exited with code 1
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: Waiting for output processor threads to exit.
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: Output processor threads exited.
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper startListener
   INFO: Exit code of lsnrctl is:1
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.dbca.driver.backend.steps.ListenerConfigStep createStaticListener
   INFO: Static listener created.
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.dbca.driver.StepDBCAJob$1 update
   INFO: Percentage Progress got for job:Listener config step progress:100.0
   

   There is another little drawback with this approach - it creates listener.ora in DB home which uses a static configuration. It is harmless, but I would rather clean it up after the exercise to have a nice and tidy environment.

Prerequisite Steps

It should be possible to establish a connection from the primary host using the local listener endpoint: rac1.example.com:1522.
I do not discuss DNS setup - it is implied.
I need to configure a static registration for the new RAC instance. For that, I edit my GI listener.ora on the host I am going to run the duplicate command from (rac1):

# /u01/app/19.3.0/grid/network/admin/listener.ora
SID_LIST_LISTENER=
  (SID_LIST=
      (SID_DESC=
         (SID_NAME=racdb1)
         (ORACLE_HOME=/u01/app/oracle/product/19.3.0/dbhome_1)
       )
   )

That is basically it. Once I reload the local listener, I am good to continue to the next step.

Creating RAC Physical Standby

[oracle@rac1 ~]$ dbca -createDuplicateDB -silent \
>      -gdbName orcl \
>      -primaryDBConnectionString primary:1521/orcl \
>      -sid racdb \
>      -initParams "dg_broker_start=true" \
>      -sysPassword change_on_install \
>      -adminManaged \
>      -nodelist rac1,rac2 \
>      -recoveryAreaDestination +DATA \
>        -recoveryAreaSize 10000 \
>      -databaseConfigType RAC \
>      -useOMF true \
>      -storageType ASM \
>        -datafileDestination +DATA \
>      -createAsStandby \
>        -dbUniqueName racdb \
>      -createListener rac1.example.com:1522
Prepare for db operation
22% complete
Listener config step
44% complete
Auxiliary instance creation
67% complete
RMAN duplicate
89% complete
Post duplicate database operations
100% complete

Look at the log file "/u01/app/oracle/cfgtoollogs/dbca/racdb/racdb.log" for further details.

That is it:

SQL> select database_role from v$database;

DATABASE_ROLE
----------------
PHYSICAL STANDBY

SQL> select instance_name, host_name from gv$instance;

INSTANCE_NAME    HOST_NAME
---------------- --------------------
racdb1           rac1.example.com
racdb2           rac2.example.com

Further Steps

1. Delete /u01/app/oracle/product/19.3.0/dbhome_1/network/admin/listener.ora. DBCA created this file with the following content:

   SID_LIST_RAC1.EXAMPLE.COM =
     (SID_LIST =
       (SID_DESC =
         (SID_NAME = racdb1)
       )
     )
   
   RAC1.EXAMPLE.COM =
     (ADDRESS_LIST =
       (ADDRESS = (PROTOCOL = TCP)(HOST = rac1.example.com)(PORT = 1522))
     )

2. Adding standby redo logs, creating a new Data Guard Configuration, enabling FORCE_LOGGING, Flashback database, etc. - I do not mention it here. The purpose of this post to show how to instantiate a new RAC standby database in one command after completing some simple preliminary steps.

Notable Downsides

There ain't no such thing as a free lunch.
Both slow connection between the sites, and a "huge" database size limits the applicability of this method.
I do not see how this method can utilize the restartable duplication too.
In all other cases, it is possible to quickly spin up a new RAC standby database using this excellent DBCA createDuplicateDB command.

Determining Oracle Database Edition

The other day I debugged some Oracle provided utilities and came across another way of determining an Oracle Database edition. It does not require a running database instance.

The Oracle code was checking what is inside the $ORACLE_HOME/lib/libedtn19.a library:

# Enterprise Edition
[oracle@rac1 lib]$ ar t /u01/app/oracle/product/19.3.0/dbhome_1/lib/libedtn19.a
vsnfent.o

# Standard Edition
[oracle@rac1 lib]$ ar t /u01/app/oracle/product/19.3.0/dbhome_2/lib/libedtn19.a
vsnfstd.o

As it can be seen, it is vsnfstd.o for Standard vs vsnfent.o for Enterprise.
It appears to be a file for each edition and the file libedtn19.a contains the edition of that specific Oracle Home:

[oracle@rac1 lib]$ find . -name 'libedtn19*a' -print -exec ar t '{}' \;
./libedtn19_xp.a
vsnfxp.o
./libedtn19_ent.a
vsnfent.o
./libedtn19_cse.a
vsnfcse.o
./libedtn19_cee.a
vsnfcee.o
./libedtn19.a
vsnfent.o
./libedtn19_hp.a
vsnfhp.o
./libedtn19_std.a
vsnfstd.o

It has no effect on V$VERSION output whatsoever, and it obviously cannot be used to change one edition to another.
Yet I discovered that srvctl checks that libedtn19.a file in certain scenarios to determine whether or not some edition specific features should be allowed.
Per my research, that library was introduced in Oracle 18c.

CURSOR Expressions Return Wrong Results in 18c/19c

That is a wrong results issue I stumbled upon this morning. A developer told me that one of their queries started returning wrong results after we upgraded one of our databases from 12.2.0.1 to 19.7. I constructed a simplified test case to demonstrate this issue which I ran on 19.4. I have been able to reproduce it on 18.3, 19.7, and Live SQL as well.

SQL> create table t1(id int);

Table created.

SQL> create table t2(id int);

Table created.

SQL>
SQL> insert into t1 values (1);

1 row created.

SQL> insert into t2 values (1);

1 row created.

In a nutshell, I created two tables that have one row with a numeric 1 value. Let's now run the following query:

SQL> select query_type
  2    from (select 'A' query_type
  3            from t1 t11
  4           where exists (
  5                   select null
  6                     from t2 t21
  7                    where t21.id = t11.id)
  8           union all
  9          select 'B' query_type
 10            from t1 t12
 11           where not exists (
 12                   select null
 13                     from t2 t22
 14                    where t22.id = t12.id)
 15         );

Q
-
A

Then, I am going to put that query into a CURSOR expression:

SQL> select cursor(
  2           select query_type
  3             from (select 'A' query_type
  4                     from t1 t11
  5                    where exists (
  6                            select null
  7                              from t2 t21
  8                             where t21.id = t11.id)
  9                    union all
 10                   select 'B' query_type
 11                     from t1 t12
 12                    where not exists (
 13                            select null
 14                              from t2 t22
 15                             where t22.id = t12.id)
 16                  )
 17         ) data
 18    from dual;

DATA
--------------------
CURSOR STATEMENT : 1

CURSOR STATEMENT : 1

Q
-
B

That is when it gets interesting. Somehow the query which returned 'A' being run separately starts returning 'B' after it comes as an input subquery into a CURSOR expression.

I initially started looking at the execution plan in an attempt to figure out what changed in the execution plan between 12.2 and 19c. There are some changes but nothing that drew my eye.

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
Plan hash value: 2197603499

-----------------------------------------------------------------------------
| Id  | Operation            | Name | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |     1 |       |    14   (0)| 00:00:01 |
|   1 |  VIEW                |      |     2 |     6 |    12   (0)| 00:00:01 |
|   2 |   UNION-ALL          |      |       |       |            |          |
|*  3 |    FILTER            |      |       |       |            |          |
|   4 |     TABLE ACCESS FULL| T1   |     1 |    13 |     3   (0)| 00:00:01 |
|*  5 |     TABLE ACCESS FULL| T2   |     1 |    13 |     3   (0)| 00:00:01 |
|*  6 |    FILTER            |      |       |       |            |          |
|   7 |     TABLE ACCESS FULL| T1   |     1 |    13 |     3   (0)| 00:00:01 |
|*  8 |     TABLE ACCESS FULL| T2   |     1 |    13 |     3   (0)| 00:00:01 |
|   9 |  FAST DUAL           |      |     1 |       |     2   (0)| 00:00:01 |
-----------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

   1 - SET$1 / from$_subquery$_001@SEL$2
   2 - SET$1
   3 - SEL$3
   4 - SEL$3 / T11@SEL$3
   5 - SEL$4 / T21@SEL$4
   6 - SEL$5
   7 - SEL$5 / T12@SEL$5
   8 - SEL$6 / T22@SEL$6
   9 - SEL$1 / DUAL@SEL$1

Outline Data
-------------

  /*+
      BEGIN_OUTLINE_DATA
      FULL(@"SEL$6" "T22"@"SEL$6")
      FULL(@"SEL$4" "T21"@"SEL$4")
      PQ_FILTER(@"SEL$3" SERIAL)
      FULL(@"SEL$3" "T11"@"SEL$3")
      PQ_FILTER(@"SEL$5" SERIAL)
      FULL(@"SEL$5" "T12"@"SEL$5")
      NO_ACCESS(@"SEL$2" "from$_subquery$_001"@"SEL$2")
      OUTLINE_LEAF(@"SEL$1")
      OUTLINE_LEAF(@"SEL$2")
      OUTLINE_LEAF(@"SET$1")
      OUTLINE_LEAF(@"SEL$5")
      OUTLINE_LEAF(@"SEL$6")
      OUTLINE_LEAF(@"SEL$3")
      OUTLINE_LEAF(@"SEL$4")
      ALL_ROWS
      DB_VERSION('19.1.0')
      OPTIMIZER_FEATURES_ENABLE('19.1.0')
      IGNORE_OPTIM_EMBEDDED_HINTS
      END_OUTLINE_DATA
  */

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - filter( EXISTS (SELECT 0 FROM "T2" "T21" WHERE "T21"."ID"=:B1))
   5 - filter("T21"."ID"=:B1)
   6 - filter( NOT EXISTS (SELECT 0 FROM "T2" "T22" WHERE
              "T22"."ID"=:B1))
   8 - filter("T22"."ID"=:B1)

Note
-----
   - dynamic statistics used: dynamic sampling (level=2)

68 rows selected.

The gather_plan_statistics hint was not really helpful as it is a nested cursor, so that it does not show the rowsource statistics from that level - the nested cursor runs separately and its rowsource statistics are not included in the top-level cursor ones:

-----------------------------------------------------------------------------
| Id  | Operation            | Name | Starts | E-Rows | A-Rows |   A-Time   |
-----------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |      |      1 |        |      1 |00:00:00.01 |
|   1 |  VIEW                |      |      0 |      2 |      0 |00:00:00.01 |
|   2 |   UNION-ALL          |      |      0 |        |      0 |00:00:00.01 |
|*  3 |    FILTER            |      |      0 |        |      0 |00:00:00.01 |
|   4 |     TABLE ACCESS FULL| T1   |      0 |      1 |      0 |00:00:00.01 |
|*  5 |     TABLE ACCESS FULL| T2   |      0 |      1 |      0 |00:00:00.01 |
|*  6 |    FILTER            |      |      0 |        |      0 |00:00:00.01 |
|   7 |     TABLE ACCESS FULL| T1   |      0 |      1 |      0 |00:00:00.01 |
|*  8 |     TABLE ACCESS FULL| T2   |      0 |      1 |      0 |00:00:00.01 |
|   9 |  FAST DUAL           |      |      1 |      1 |      1 |00:00:00.01 |
-----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - filter( IS NOT NULL)
   5 - filter("T21"."ID"=:B1)
   6 - filter( IS NULL)
   8 - filter("T22"."ID"=:B1)

I found the explanation of this issue in the SQL trace file:

=====================
PARSING IN CURSOR #139973723001152 len=579 dep=0 uid=78 oct=3 lid=78 tim=4622189819 hv=2185287422 ad='68d3c950' sql
id='0mkkpha141pry'
select cursor(
         select query_type
           from (select 'A' query_type
                   from t1 t11
                  where exists (
                          select null
                            from t2 t21
                           where t21.id = t11.id)
                  union all
                 select 'B' query_type
                   from t1 t12
                  where not exists (
                          select null
                            from t2 t22
                           where t22.id = t12.id)
                )
       ) data
  from dual
END OF STMT
PARSE #139973723001152:c=11048,e=12511,p=0,cr=45,cu=12,mis=1,r=0,dep=0,og=1,plh=2197603499,tim=4622189819
EXEC #139973723001152:c=13,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2197603499,tim=4622189873
=====================
PARSING IN CURSOR #139973720520408 len=272 dep=2 uid=78 oct=3 lid=78 tim=4622190302 hv=3362864010 ad='68d141b0' sqlid='faj0udr472fwa'
SELECT "A2"."QUERY_TYPE" "QUERY_TYPE" 
  FROM  ( 
          (SELECT 'A' "QUERY_TYPE" 
             FROM "T1" "A5"
            WHERE  EXISTS (
                     SELECT 0 
                       FROM "T2" "A6"
                      WHERE "A6"."ID"=:CV1$))
           UNION ALL
          (SELECT 'B' "QUERY_TYPE" 
             FROM "T1" "A4"
            WHERE  NOT EXISTS (
                     SELECT 0 
                       FROM "T2" "A7"
                      WHERE "A7"."ID"=:CV2$))) "A2"
END OF STMT
PARSE #139973720520408:c=375,e=375,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=1,plh=0,tim=4622190302
..skip..
BINDS #139973720520408:

 Bind#0
  oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
  oacflg=11 fl2=0001 frm=00 csi=00 siz=48 off=0
  kxsbbbfp=7f4e2be3b278  bln=22  avl=00  flg=05
 Bind#1
  oacdty=02 mxl=22(00) mxlc=00 mal=00 scl=00 pre=00
  oacflg=11 fl2=0001 frm=00 csi=00 siz=0 off=24
  kxsbbbfp=7f4e2be3b290  bln=22  avl=00  flg=01
EXEC #139973720520408:c=9732,e=9360,p=0,cr=37,cu=0,mis=1,r=0,dep=2,og=1,plh=489056501,tim=4622199711
FETCH #139973723001152:c=10218,e=9845,p=0,cr=37,cu=0,mis=0,r=1,dep=0,og=1,plh=2197603499,tim=4622199753
STAT #139973723001152 id=1 cnt=0 pid=0 pos=1 obj=0 op='VIEW  (cr=0 pr=0 pw=0 str=0 time=0 us cost=12 size=6 card=2)'
STAT #139973723001152 id=2 cnt=0 pid=1 pos=1 obj=0 op='UNION-ALL  (cr=0 pr=0 pw=0 str=0 time=0 us)'
STAT #139973723001152 id=3 cnt=0 pid=2 pos=1 obj=0 op='FILTER  (cr=0 pr=0 pw=0 str=0 time=0 us)'
STAT #139973723001152 id=4 cnt=0 pid=3 pos=1 obj=25013 op='TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 str=0 time=0 us cost=3 size=13 card=1)'
STAT #139973723001152 id=5 cnt=0 pid=3 pos=2 obj=25014 op='TABLE ACCESS FULL T2 (cr=0 pr=0 pw=0 str=0 time=0 us cost=3 size=13 card=1)'
STAT #139973723001152 id=6 cnt=0 pid=2 pos=2 obj=0 op='FILTER  (cr=0 pr=0 pw=0 str=0 time=0 us)'
STAT #139973723001152 id=7 cnt=0 pid=6 pos=1 obj=25013 op='TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 str=0 time=0 us cost=3 size=13 card=1)'
STAT #139973723001152 id=8 cnt=0 pid=6 pos=2 obj=25014 op='TABLE ACCESS FULL T2 (cr=0 pr=0 pw=0 str=0 time=0 us cost=3 size=13 card=1)'
STAT #139973723001152 id=9 cnt=1 pid=0 pos=2 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 str=1 time=0 us cost=2 size=0 card=1)'
FETCH #139973720520408:c=178,e=177,p=0,cr=8,cu=0,mis=0,r=1,dep=0,og=1,plh=489056501,tim=4622200599
STAT #139973720520408 id=1 cnt=1 pid=0 pos=1 obj=0 op='VIEW  (cr=9 pr=0 pw=0 str=1 time=179 us cost=12 size=6 card=2)'
STAT #139973720520408 id=2 cnt=1 pid=1 pos=1 obj=0 op='UNION-ALL  (cr=9 pr=0 pw=0 str=1 time=177 us)'
STAT #139973720520408 id=3 cnt=0 pid=2 pos=1 obj=0 op='FILTER  (cr=1 pr=0 pw=0 str=1 time=8 us)'
STAT #139973720520408 id=4 cnt=0 pid=3 pos=1 obj=25013 op='TABLE ACCESS FULL T1 (cr=0 pr=0 pw=0 str=0 time=0 us cost=3 size=0 card=1)'
STAT #139973720520408 id=5 cnt=0 pid=3 pos=2 obj=25014 op='TABLE ACCESS FULL T2 (cr=1 pr=0 pw=0 str=1 time=6 us cost=3 size=13 card=1)'
STAT #139973720520408 id=6 cnt=1 pid=2 pos=2 obj=0 op='FILTER  (cr=8 pr=0 pw=0 str=1 time=164 us)'
STAT #139973720520408 id=7 cnt=1 pid=6 pos=1 obj=25013 op='TABLE ACCESS FULL T1 (cr=7 pr=0 pw=0 str=1 time=144 us cost=3 size=0 card=1)'
STAT #139973720520408 id=8 cnt=0 pid=6 pos=2 obj=25014 op='TABLE ACCESS FULL T2 (cr=1 pr=0 pw=0 str=1 time=9 us cost=3 size=13 card=1)'
FETCH #139973723001152:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=2197603499,tim=4622200901
CLOSE #139973720520408:c=3,e=2,dep=1,type=0,tim=4622201312
CLOSE #139973723001152:c=6,e=193,dep=0,type=0,tim=4622201500

That is where the most remarkable part happens. The subquery is modified in an awfully wrong way: the columns of the outer queries disappear from the inner queries, and they are replaced with some bind variables: CV1$, CV2$.
Those variables, which are of the NUMBER data type, are set to NULL.
Then, the 'A' branch of the UNION ALL, which uses EXISTS, returns nothing. The 'B' branch, which uses NOT EXISTS, returns the 'B' row since the NOT EXISTS subquery brings back an empty result set.

At this stage the root cause of the wrong results issue is known. Obviously, I have no clue why those variables were introduced but I know why that query returns that result.

I tried to tinker around with that query a little bit to see what can be done to make it work, and here is a short summary of my findings:

• Correlated subqueries are essential. The query starts returning the correct results (one 'A' row) once I decorrelate the subqueries:
  

  SQL> select cursor(
    2           select query_type
    3             from (select 'A' query_type
    4                     from t1 t11
    5                    where id in (
    6                            select id
    7                              from t2 t21)
    8                    union all
    9                   select 'B' query_type
   10                     from t1 t12
   11                    where id not in (
   12                            select id
   13                              from t2 t22)
   14                  )
   15         ) data
   16    from dual;
  
  DATA
  --------------------
  CURSOR STATEMENT : 1
  
  CURSOR STATEMENT : 1
  
  Q
  -
  A
      

• Nesting of the subqueries does matter. For instance, the query returns the correct results after I reduce the nesting level:

  SQL> select cursor(
    2           select 'A' query_type
    3             from t1 t11
    4            where exists (
    5                    select null
    6                      from t2 t21
    7                     where t21.id = t11.id)
    8            union all
    9           select 'B' query_type
   10             from t1 t12
   11            where not exists (
   12                    select null
   13                      from t2 t22
   14                     where t22.id = t12.id)
   15         ) data
   16    from dual;
  
  DATA
  --------------------
  CURSOR STATEMENT : 1
  
  CURSOR STATEMENT : 1
  
  Q
  -
  A
  

Based on how Oracle modifies the subquery under the hood, certain CURSOR expressions can return:

• Less rows:

  SQL> doc
  DOC>##############################
  DOC>   Less rows
  DOC>##############################
  DOC>#
  SQL>
  SQL> select cursor(
    2           select query_type
    3             from (select 'A' query_type
    4                     from t1 t11
    5                    where exists (
    6                            select null
    7                              from t2 t21
    8                             where t21.id = t11.id)
    9                    union all
   10                   select 'B' query_type
   11                     from t1 t12
   12                    where exists (
   13                            select null
   14                              from t2 t22
   15                             where t22.id = t12.id)
   16                  )
   17         ) data
   18    from dual;
  
  DATA
  --------------------
  CURSOR STATEMENT : 1
  
  CURSOR STATEMENT : 1
  
  no rows selected
  
  
  SQL>
  SQL> doc
  DOC>   The cursor subquery
  DOC>#
  SQL> select query_type
    2    from (select 'A' query_type
    3            from t1 t11
    4           where exists (
    5                   select null
    6                     from t2 t21
    7                    where t21.id = t11.id)
    8           union all
    9          select 'B' query_type
   10            from t1 t12
   11           where exists (
   12                   select null
   13                     from t2 t22
   14                    where t22.id = t12.id)
   15         )
   16  ;
  
  Q
  -
  A
  B
      

• More rows:

  SQL> doc
  DOC>##############################
  DOC>   More rows
  DOC>##############################
  DOC>#
  SQL>
  SQL> select cursor(
    2           select query_type
    3             from (select 'A' query_type
    4                     from t1 t11
    5                    union all
    6                   select 'B' query_type
    7                     from t1 t12
    8                    where not exists (
    9                            select null
   10                              from t2 t22
   11                             where t22.id = t12.id)
   12                  )
   13         ) data
   14    from dual;
  
  DATA
  --------------------
  CURSOR STATEMENT : 1
  
  CURSOR STATEMENT : 1
  
  Q
  -
  A
  B
  
  
  SQL>
  SQL> doc
  DOC>   The cursor subquery
  DOC>#
  SQL> select query_type
    2    from (select 'A' query_type
    3            from t1 t11
    4           union all
    5          select 'B' query_type
    6            from t1 t12
    7           where not exists (
    8                   select null
    9                     from t2 t22
   10                    where t22.id = t12.id)
   11         );
  
  Q
  -
  A
      

• Different values as it was demostrated in the beginning of this post

The good news is that it is a known documented issue: Bug 30528947 - Nested Query Using CURSOR Expression Returns Wrong Result (Doc ID 30528947.8). There are patches available for some release updates.
The bad news is that the issue is not mentioned on the document I would expect it to be: Things to Consider to Avoid Prominent Wrong Result Problems on 19C Proactively (Doc ID 2606585.1). How is one supposed to avoid such issues? I always read those 'things to consider' before I devise any upgrade plans.
The scripts, a sample trace file, and the spool file for this post are available on: GitHub.