Database Upgrade Fails With “unexpected error in validate_credentials”

This is a blog post about an issue that can occur during a database upgrade and produces a misleading error message. If you’re already aware of it, the workaround is trivial. However, when it happened to me during the testing phases of an action plan, I couldn’t find an existing article describing it. So I decided to share it  here.

As the root cause of the problem is in the $ORACLE_HOME/rdbms/admin/catcon.pm file, the issue can happen when using the dbupgrade shell command, while directly calling catctl.pl or when using AutoUpgrade. All of those tools call catcon.pm at some point in time. The returned error is “unexpected error in validate_credentials when trying to validate user credentials” however in this case, the issue doesn’t have anything to do with validating user credentials, which is very misleading.

Reproducing the problem

We want to upgrade a 12.2 database to 19c (19.13.0.0.211019). The issue isn’t limited to this version combination; I reproduced it while testing an  upgrade from 12.2 to 21.4.0.0.211019. For reference, catcon.pm in the 21c home isn’t the same as the one in 19c home, meaning the 21c version has some bug fixes and features integrated.

1. Manual upgrade using dbupgrade

Following the directions in “Oracle 19c – Complete checklist for Manual Upgrade for upgrading Oracle 12.x, 18c Container database (CDB) to Oracle 19c (19.x) (Doc ID 2549866.1)”, or the Oracle docs, we come to the phase where we run the upgrade.

We start it using “dbupgrade -l /home/oracle/TESTORA-123/upgrade_logs” and it fails with “unexpected error in validate_credentials when trying to validate user credentials” :

[oracle@hol admin]$ /u02/app/oracle/product/19/bin/dbupgrade -l /home/oracle/TESTORA-123/upgrade_logs

Argument list for [/u02/app/oracle/product/19/rdbms/admin/catctl.pl]
For Oracle internal use only A = 0
Run in                       c = 0
Do not run in                C = 0
Input Directory              d = 0
Echo OFF                     e = 1
Simulate                     E = 0
Forced cleanup               F = 0
Log Id                       i = 0
Child Process                I = 0
Log Dir                      l = /home/oracle/TESTORA-123/upgrade_logs
Priority List Name           L = 0
Upgrade Mode active          M = 0
SQL Process Count            n = 0
SQL PDB Process Count        N = 0
Open Mode Normal             o = 0
Start Phase                  p = 0
End Phase                    P = 0
Reverse Order                r = 0
AutoUpgrade Resume           R = 0
Script                       s = 0
Serial Run                   S = 0
RO User Tablespaces          T = 0
Display Phases               y = 0
Debug catcon.pm              z = 0
Debug catctl.pl              Z = 0

catctl.pl VERSION: [19.0.0.0.0]
           STATUS: [Production]
            BUILD: [RDBMS_19.13.0.0.0DBRU_LINUX.X64_211004]


/u02/app/oracle/product/19/rdbms/admin/orahome = [/u02/app/oracle/product/19]
/u02/app/oracle/product/19/bin/orabasehome = [/u02/app/oracle/product/19]
catctlGetOraBaseLogDir = [/u02/app/oracle/product/19]

Analyzing file /u02/app/oracle/product/19/rdbms/admin/catupgrd.sql

Log file directory = [/home/oracle/TESTORA-123/upgrade_logs]

catcon::set_log_file_base_path: ALL catcon-related output will be written to [/home/oracle/TESTORA-123/upgrade_logs/catupgrd_catcon_14127.lst]

catcon::set_log_file_base_path: catcon: See [/home/oracle/TESTORA-123/upgrade_logs/catupgrd*.log] files for output generated by scripts

catcon::set_log_file_base_path: catcon: See [/home/oracle/TESTORA-123/upgrade_logs/catupgrd_*.lst] files for spool files, if any

catcon::print_exec_DB_script_output:   ] end of output produced in exec_DB_script

catcon::catconInit2: unexpected error in validate_credentials when trying to validate user credentials



Unexpected error encountered in catconInit; exiting
 No child processes

Unexpected error encountered in catctlMain; Error Stack Below; exiting
Died at /u02/app/oracle/product/19/rdbms/admin/catctl.pl line 9252.
 at /u02/app/oracle/product/19/rdbms/admin/catctl.pl line 9252.
        main::catctlDie("\x{a}Unexpected error encountered in catconInit; exiting\x{a} No chil"...) called at /u02/app/oracle/product/19/rdbms/admin/catctl.pl line 3773
        main::catctlDBLogon("/u02/app/oracle/product/19/rdbms/admin", "/home/oracle/TESTORA-123/upgrade_logs", "catupgrd", 0, 0, 4) called at /u02/app/oracle/product/19/rdbms/admin/catctl.pl line 3828
        main::catctlLogon() called at /u02/app/oracle/product/19/rdbms/admin/catctl.pl line 1450
        main::catctlMain() called at /u02/app/oracle/product/19/rdbms/admin/catctl.pl line 1398
        eval {...} called at /u02/app/oracle/product/19/rdbms/admin/catctl.pl line 1396

.
.
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:985 catcon::sureunlink - confirmed that /home/oracle/TESTORA-123/upgrade_logs/catupgrd_catcon_14127_exec_DB_script.done no longer exists after 1 attempts

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1258 catcon::exec_DB_script - deleted /home/oracle/TESTORA-123/upgrade_logs/catupgrd_catcon_14127_exec_DB_script.done after running a script

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1262 catcon::exec_DB_script - closed Reader

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1326 catcon::print_exec_DB_script_output - validate_credentials: unexpected error in exec_DB_script

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1332 catcon::print_exec_DB_script_output -   output produced in exec_DB_script [

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     SQL*Plus: Release 19.0.0.0.0 - Production on Fri Nov 5 23:11:25 2021
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     Version 19.13.0.0.0
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     Copyright (c) 1982, 2021, Oracle.  All rights reserved.
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     set newpage 1#LF#
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     set pagesize 14#LF#
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     connect / AS sysdba#LF#
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     Connected.
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     #LF#host echo >  /home/oracle/TESTORA-123/upgrade_logs/catupgrd_catcon_14127_exec_DB_script.done#LF#
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     exit#LF#
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     Version 19.13.0.0.0
2021-11-05 23:11:25 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -

}
End of diagnostic output

2021-11-05 23:11:25 ERROR> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1340 catcon::print_exec_DB_script_output -   ] end of output produced in exec_DB_script

2021-11-05 23:11:25 ERROR> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:13188 catcon::catconInit2 - unexpected error in validate_credentials when trying to validate user credentials


Grand Total Time: 0s

 LOG FILES: (/home/oracle/TESTORA-123/upgrade_logs/catupgrd*.log)
[oracle@hol admin]$

Analyzing the cause of the error

There’s no specific error message in the above output; we only see that there was a failure when trying to validate user credentials. Based on that,  and without further analysis or tracing, we could start checking for any problems related to the password file, OS groups or something similar. However, it turns out that the problem resides in the below code block from the “validate_credentials” subroutine in $ORACLE_HOME/rdbms/admin/catcon.pm, specifically in the grep expression at line #12:

# we need to examine output to see if it contained any errors.
# Since the "script" we are executing just does a connect, an error would
# indicate that credentials supplied by the caller are invalid (or the DB
# is down, or some other error precluding the use from connecting to the
# database, but the important thing is that we are unlikely to be able to
# connect to the database using those credentials)
if (!$Spool_ref || !@$Spool_ref) {
  log_msg_error("exec_DB_script produced no output");
  return 0;
}

my @errors = grep {/ORA-[0-9]/} @$Spool_ref;

if (@errors) {
  # we were unable to connect using caller-supplied credentials
  print_exec_DB_script_output("validate_credentials", $Spool_ref, 1);
  return 0;
}

return 1;

Debugging at runtime, @$Spool_ref contains this text:

SQL*Plus: Release 19.0.0.0.0 - Production on Sat Nov 6 00:07:08 2021
Version 19.13.0.0.0

Copyright (c) 1982, 2021, Oracle.  All rights reserved.

set newpage 1#LF#
set pagesize 14#LF#
connect / AS sysdba#LF#
Connected.
#LF#host echo >  /home/oracle/TESTORA-123/upgrade_logs/catupgrd_catcon_17854_exec_DB_script.done#LF#

exit#LF#
Disconnected from Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.13.0.0.0

And @errors contains the result that grep returns:

#LF#host echo >  /home/oracle/TESTORA-123/upgrade_logs/catupgrd_catcon_17854_exec_DB_script.done#LF#

Cause of the error

The error is thus triggered because the path of the log directory contains “TESTORA-123,” which is then grep-ed out and interpreted as an error. As mentioned, the workaround is trivial—don’t use the substring “ORA-NN” as a directory name. Sure enough, if I run dbupgrade using just a slightly different log directory name, for example: /home/oracle/TESTORA123/upgrade_logs, it succeeds.

2) AutoUpgrade

Testing with the latest AutoUpgrade version available at the time of writing this post (build.version 21.2.210721, build.date 2021/07/21 11:14:54) and using the below config file for a 12.2 to 19.13 upgrade:

global.autoupg_log_dir=/home/oracle/TESTORA-123/upgrade_logs/autoupgrade
upg1.log_dir=/home/oracle/TESTORA-123/upgrade_logs/autoupgrade/testdb       
upg1.sid=testdb                                           
upg1.source_home=/u01/app/oracle/product/12.2.0.1 
upg1.target_home=/u02/app/oracle/product/19  
upg1.start_time=NOW                            
upg1.upgrade_node=hol.localdomain                             
upg1.run_utlrp=yes                                 
upg1.timezone_upg=yes                              
upg1.target_version=19

The upgrade job fails:

[oracle@hol upgrade_logs]$ /u02/app/oracle/product/19/jdk/jre/bin/java -jar /u02/app/oracle/product/19/rdbms/admin/autoupgrade.jar -config /home/oracle/TESTORA-123/config_testdb.cfg -mode deploy
.
.
upg> status -job 101
Progress
-----------------------------------
Start time:      21/11/06 09:32
Elapsed (min):   12
End time:        N/A
Last update:     2021-11-06T09:35:04.985
Stage:           DBUPGRADE
Operation:       STOPPED
Status:          ERROR
Pending stages:  7
Stage summary:
    SETUP             <1 min
    GRP               <1 min
    PREUPGRADE        <1 min
    PRECHECKS         <1 min
    PREFIXUPS         1 min
    DRAIN             <1 min
    DBUPGRADE         <1 min

Job Logs Locations
-----------------------------------
Logs Base:    /home/oracle/TESTORA-123/upgrade_logs/autoupgrade/testdb/testdb
Job logs:     /home/oracle/TESTORA-123/upgrade_logs/autoupgrade/testdb/testdb/101
Stage logs:   /home/oracle/TESTORA-123/upgrade_logs/autoupgrade/testdb/testdb/101/dbupgrade
TimeZone:     /home/oracle/TESTORA-123/upgrade_logs/autoupgrade/testdb/testdb/temp

Additional information
-----------------------------------
Details:
testdb-Return status is ERROR

Error Details:

Error: UPG-1400
UPGRADE FAILED [testdb]
Cause: Database upgrade failed with errors
For further details, see the log file located at /home/oracle/TESTORA-123/upgrade_logs/autoupgrade/testdb/testdb/101/autoupgrade_20211106_user.log

The catupgrd20211106093225testdb0.log contains the same error we saw above:

2021-11-06 09:35:00 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output -     Version 19.13.0.0.0
2021-11-06 09:35:00 DEBUG> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1336 catcon::print_exec_DB_script_output - 

}
End of diagnostic output

2021-11-06 09:35:00 ERROR> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:1340 catcon::print_exec_DB_script_output -   ] end of output produced in exec_DB_script

2021-11-06 09:35:00 ERROR> /u02/app/oracle/product/19/rdbms/admin/catcon.pm:13188 catcon::catconInit2 - unexpected error in validate_credentials when trying to validate user credentials

Repeating the test on a 12.2 to 21.4 upgrade yields the same outcome:

2021-11-06 18:44:32 DEBUG> /u02/app/oracle/product/21/rdbms/admin/catcon.pm:1325 catcon::print_exec_DB_script_output -     Version 21.4.0.0.0
2021-11-06 18:44:32 DEBUG> /u02/app/oracle/product/21/rdbms/admin/catcon.pm:1325 catcon::print_exec_DB_script_output - 

}
End of diagnostic output

2021-11-06 18:44:32 ERROR> /u02/app/oracle/product/21/rdbms/admin/catcon.pm:1329 catcon::print_exec_DB_script_output -   ] end of output produced in exec_DB_script

2021-11-06 18:44:32 ERROR> /u02/app/oracle/product/21/rdbms/admin/catcon.pm:13219 catcon::catconInit2 - unexpected error in validate_credentials when trying to validate user credentials

You might be wondering about the reason for naming a directory “TESTORA-123”. It’s simply because some of our ticketing system’s ticket IDs have the following format: “[CUSTOMER_ABBREVIATION]ORA–[TICKET_NUMBER],“ for example SAMPLECSTORA–123. When performing a maintenance, the ticket ID is sometimes also used as a directory name where the files related to that maintenance are kept.

Have you come across this, or a similar issue? Share your experience or ask me more about it in the comments.

Don’t forget to sign up for more updates here.