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.
No Comments Yet
Let us know what you think