12.2 database Alert log shows ORA-20001: Latest xml inventory is not loaded into table

While 12.2 database is being started by srvctl, the alert log shows following messages,

Unable to obtain current patch information due to error: 20001, ORA-20001: Latest xml inventory is not loaded into table
ORA-06512: at "SYS.DBMS_QOPATCH", line 777
ORA-06512: at "SYS.DBMS_QOPATCH", line 864
ORA-06512: at "SYS.DBMS_QOPATCH", line 2222
ORA-06512: at "SYS.DBMS_QOPATCH", line 740
ORA-06512: at "SYS.DBMS_QOPATCH", line 2247
===========================================================
Dumping current patch information
===========================================================
Unable to obtain current patch information due to error: 20001
===========================================================

DBMS_QOPATCH is introduced by 12.1 database as a cool new feature 'Queryable OPatch'. It is implemented with a PL/SQL package (DBMS_QOPATCH) and a set of tables and directories. In order to understand what the errors really are, let's do some details research,

system@orcl> select * from dba_directories where directory_name like 'OPATCH%';

OWNER   DIRECTORY_NAME       DIRECTORY_PATH                                     ORIGIN_CON_ID
------- -------------------- -------------------------------------------------- -------------
SYS     OPATCH_INST_DIR      /u01/app/oracle/product/12.2.0/dbhome_1/OPatch              0
SYS     OPATCH_SCRIPT_DIR    /u01/app/oracle/product/12.2.0/dbhome_1/QOpatch             0
SYS     OPATCH_LOG_DIR       /u01/app/oracle/product/12.2.0/dbhome_1/rdbms/log           0

system@orcl> exit

[oracle@host01]$ ls -lrt /u01/app/oracle/product/12.2.0/dbhome_1/rdbms/log
-rw-r-----   1 oracle   osasm        120 Feb  9 17:07 qopatch.log
-rw-r--r--   1 oracle   osasm     144227 Feb 10 17:32 qopatch_log.log
[oracle@host01]$

It should be a good guess to start from looking into the log file qopatch_log.log which modification time is very close to the time when errors was reported in alert log,

 LOG file opened at 02/10/18 17:32:22

KUP-05007:   Warning: Intra source concurrency disabled because the preprocessor option is being used.

Field Definitions for table OPATCH_XML_INV
  Record format DELIMITED BY NEWLINE
  Data in file has same endianness as the platform
  Reject rows with all null fields

  Fields in Data Source:

    XML_INVENTORY                   CHAR (100000000)
      Terminated by "UIJSVTBOEIZBEFFQBL"
      Trim whitespace same as SQL Loader
KUP-04095: preprocessor command /u01/app/oracle/product/12.2.0/dbhome_1/QOpatch/qopiprep.bat encountered error
   "/u01/app/oracle/product/12.2.0/dbhome_1/QOpatch/qopiprep.bat[55]: /u01/app/oracle/product/12.2.0/dbhome_1/rdbms/log/stout_orcl.txt: cannot create [Permission de"

The database starting got ORA-20001 while accessing external table OPATCH_XML_INV which has
preprocessor command '$ORACLE_HOME/QOpatch/qopiprep.bat'. The table definition is,

system@orcl> select owner,table_name from dba_external_tables where table_name='OPATCH_XML_INV';

OWNER      TABLE_NAME
---------- --------------------
SYS        OPATCH_XML_INV

system@orcl> select dbms_metadata.get_ddl('TABLE','OPATCH_XML_INV','SYS') from dual;

DBMS_METADATA.GET_DDL('TABLE','OPATCH_XML_INV','SYS')
--------------------------------------------------------------------------------

  CREATE TABLE "SYS"."OPATCH_XML_INV" SHARING=METADATA
   (    "XML_INVENTORY" CLOB
   )
   ORGANIZATION EXTERNAL
    ( TYPE ORACLE_LOADER
      DEFAULT DIRECTORY "OPATCH_SCRIPT_DIR"
      ACCESS PARAMETERS
      ( RECORDS DELIMITED BY NEWLINE CHARACTERSET UTF8
      DISABLE_DIRECTORY_LINK_CHECK
      READSIZE 8388608
      preprocessor opatch_script_dir:'qopiprep.bat'
      BADFILE opatch_script_dir:'qopatch_bad.bad'
      LOGFILE opatch_log_dir:'qopatch_log.log'
      FIELDS TERMINATED BY 'UIJSVTBOEIZBEFFQBL'
      MISSING FIELD VALUES ARE NULL
      REJECT ROWS WITH ALL NULL FIELDS
      (
        xml_inventory    CHAR(100000000)
      )
        )
      LOCATION
       ( "OPATCH_SCRIPT_DIR":'qopiprep.bat'
       )
    )
   REJECT LIMIT UNLIMITED

system@orcl>

File 'qopatch_log.log' is defined as log file of the external table, and will be generated by external table utility while table 'OPATCH_XML_INV' is accessed.

According to the table's definition, PREPROCESSOR-specified command (script file) 'qopiprep.bat' will convert 'raw' data to records of the table before the table is accessible. That's why execution error of script 'qopiprep.bat' is found in log 'qopatch_log.log'. The log shows file 'stout_orcl.txt' cannot be created while line 55 of the script is being executed, the script code looks as following,

 54 rm -rf $ORABASE/rdbms/log/xml_file_$DBSID.xml
 55 $ORACLE_HOME/OPatch/opatch lsinventory -xml  $ORABASE/rdbms/log/xml_file_$DBSID.xml \
    -retry 0 -invPtrLoc $ORACLE_HOME/oraInst.loc >> $ORABASE/rdbms/log/stout_$DBSID.txt
 56 cat $ORABASE/rdbms/log/xml_file_$DBSID.xml | sed 's/^ *//' | tr '\n' ' '
 57 echo "UIJSVTBOEIZBEFFQBL"
 58 rm $ORABASE/rdbms/log/xml_file_$DBSID.xml
 59 rm $ORABASE/rdbms/log/stout_$DBSID.txt

Check the log directory $ORABASE/rdbms/log (here $ORABASE is same as $ORACLE_HOME) permission,

[oracle@host01]$ ls -ld $ORACLE_HOME/rdbms/log
drwxr-xr-x   3 oracle   oinstall      14 Feb 10 18:36 /u01/app/oracle/product/12.2.0/dbhome_1/rdbms/log

[oracle@host01]$ id -a
uid=504(oracle) gid=512(oinstall) groups=512(oinstall),513(dba),515(asmdba),519(osasm),520(osdba)

[oracle@host01]$ ls -ld $ORACLE_HOME
drwxr-xr-x  77 oracle   oinstall      81 Feb 10 19:22 /u01/app/oracle/product/12.2.0/dbhome_1

The database home owner 'oracle' is also the owner of the log directory, and both 'sqlplus' and'srvctl' are executed by 'oracle' to start database, all read/write privilges should be inherited from user 'oracle' who has full control on the log directory. However, it is only true for sqlplus but not for srvctl.

IS srvctl accessing the external table as user other than oracle? Try to prove it by adding touch command to the script,

 54 rm -rf $ORABASE/rdbms/log/xml_file_$DBSID.xml
 55 touch /tmp/stout_$DBSID.test
 56 $ORACLE_HOME/OPatch/opatch lsinventory -xml  $ORABASE/rdbms/log/xml_file_$DBSID.xml -retry 0 -invPtrLoc $ORACLE_HOME/oraInst.loc >> $ORABASE/rdbms/log/stout_$DBSID.txt
 57 cat $ORABASE/rdbms/log/xml_file_$DBSID.xml | sed 's/^ *//' | tr '\n' ' '
 58 echo "UIJSVTBOEIZBEFFQBL"

Try to start database with sqlplus and srvctl respectively,

[oracle@host01]$ . oraenv
ORACLE_SID = [orcl] ? orcl
The Oracle base remains unchanged with value /u01/app/oracle

[oracle@host01]$ ls -l /tmp/stout*.test
/tmp/stout*.test: No such file or directory

[oracle@host01]$ sqlplus / as sysdba
  <<message truncated>>
SQL> startup
ORACLE instance started.
  <<message truncated>>
Database opened.
SQL> exit

[oracle@host01]$ ls -l /tmp/stout*.test
-rw-r--r--   1 oracle   oinstall       0 Feb 10 20:10 /tmp/stout_orcl.test
[oracle@host01]$
[oracle@host01]$ rm /tmp/stout_orcl.test
rm: remove /tmp/stout_orcl.test (yes/no)? yes

[oracle@host01]$ srvctl stop database -db orcl
[oracle@host01]$ srvctl start database -db orcl

[oracle@host01]$ ls -l /tmp/stout*.test
-rw-r--r--   1 grid     oinstall       0 Feb 10 20:13 /tmp/stout_orcl.test

See, the external table (running script qopiprep.bat) is accessed as grid while srvctl is run, but oracle while sqlplus. Here, grid is the owner of standalone Grid Infrastructure (Oracle Restart) home. What if the external table is accessed directely from sqlplus?

[oracle@host01]$ ls -l /tmp/stout*.test
/tmp/stout*.test: No such file or directory
[oracle@host01]$
[oracle@host01]$ sqlplus system/oracle
  <<message truncated>>
SQL> select count(*) from SYS.OPATCH_XML_INV;

  COUNT(*)
----------
         1

SQL> exit

[oracle@host01]$ ls -l /tmp/stout*.test
-rw-r--r--   1 oracle   oinstall       0 Feb 10 20:39 /tmp/stout_orcl.test

[oracle@host01]$ rm /tmp/stout_orcl.test
rm: remove /tmp/stout_orcl.test (yes/no)? yes

[oracle@host01]$ sqlplus system/oracle@host01/orcl
  <<message truncated>>
SQL> select count(*) from SYS.OPATCH_XML_INV;
select count(*) from SYS.OPATCH_XML_INV
                         *
ERROR at line 1:
ORA-29913: error in executing ODCIEXTTABLEFETCH callout
ORA-29400: data cartridge error
KUP-04095: preprocessor command
/u01/app/oracle/product/12.2.0/dbhome_1/QOpatch/qopiprep.bat encountered error
"/u01/app/oracle/product/12.2.0/dbhome_1/QOpatch/qopiprep.bat[56]:
/u01/app/oracle/product/12.2.0/dbhome_1/rdbms/log/stout_orcl.txt: cannot create
[Permission de"

SQL> exit

[oracle@host01]$
[oracle@host01]$ ls -l /tmp/stout*.test
-rw-r--r--   1 grid     oinstall       0 Feb 10 20:41 /tmp/stout_orcl.test

Apparently, it succeeded when logged onto database locally (bypass listener), and failed while remotely (going through listener. And the listener is running out of Oracle Restart home whose owner
is grid,

[oracle@host01]$ ps -ef | grep tnslsnr
    grid  1887     1   0   Jan 11 ?          19:54 /u01/app/12.2.0/grid/bin/tnslsnr LISTENER -no_crs_notify -inherit
  oracle 64664 36089   0 20:56:12 pts/3       0:00 grep tnslsnr

Although it, sometimes, made sense in previous version (10g? 11g?), it does not happen in 12.1. Therefore, it should be treated as bug :(.

As a temporary workaround, write permission can be granted to group of the log directory as grid is member of oinstall,

[oracle@magnum]$ id -a grid
uid=506(grid) gid=512(oinstall) groups=512(oinstall),514(asmadmin),515(asmdba),516(asmoper),519(osasm),520(osdba),513(dba)

[oracle@host01]$ cd $ORACLE_HOME/rdbms
[oracle@host01]$ ls -ld log
drwxr-xr-x   3 oracle   oinstall      16 Feb 10 20:39 log

[oracle@host01]$ chmod g+w log

[oracle@host01]$ ls -ld log
drwxrwxr-x   3 oracle   oinstall      16 Feb 10 20:39 log