We were ocassionally hitting “ORA-12269: client uses weak encryption\/crypto-checksumming version” when creating CDB catalog with catcdb.sql script on Oracle database releases 19.13, 21.3 and 21.4 running on Oracle Linux 8.4. It wasn’t clear which operation was failing, because catcdb.sql had already deleted all the useful information. In order to obtain diagnostic information, we first analyzed how Oracle creates CDB catalog.<\/p>\n
The following call to catcdb.sql creates a CDB catalog:<\/p>\n
@?\/rdbms\/admin\/catcdb.sql '\/u00\/oracle\/orabase\/admin\/DB\/create' 'catcdb.log'<\/code><\/pre>\ncatcdb.sql basically just calls the Perl program catcdb.pl:<\/p>\n
\n...\ncolumn rdbms_admin_catcdb new_value rdbms_admin_catcdb noprint\nselect '&&rdbms_admin'||'&&slash'||'catcdb.pl' as rdbms_admin_catcdb from dual;\n\nhost perl -I &&rdbms_admin &&rdbms_admin_catcdb --logDirectory &&1 --logFilename &&2\n<\/code><\/pre>\ncatcdb.pl<\/h1>\n
The Perl program catcdb.pl creates the catalog by calling a series of SQL scripts. SQL Scripts are stored in an array of hash pointers:<\/p>\n
\nmy @START_SCRIPTS = (\n {\n LOG_FILENAME_OPT => 'catalog',\n SCRIPT_COMMAND_OPT => sub { return 'catalog.sql' },\n USERNAME_OPT => SYS_USER,\n SCRIPT_DIRECTORY_OPT => $rdbms_admin,\n },\n {\n LOG_FILENAME_OPT => 'catproc',\n SCRIPT_COMMAND_OPT => sub { return 'catproc.sql' },\n USERNAME_OPT => SYS_USER,\n SCRIPT_DIRECTORY_OPT => $rdbms_admin,\n },\n {\n LOG_FILENAME_OPT => 'catoctk',\n SCRIPT_COMMAND_OPT => sub { return 'catoctk.sql '},\n USERNAME_OPT => SYS_USER,\n SCRIPT_DIRECTORY_OPT => $rdbms_admin,\n },\n {\n LOG_FILENAME_OPT => 'owminst',\n SCRIPT_COMMAND_OPT => sub { return 'owminst.plb' },\n USERNAME_OPT => SYS_USER,\n SCRIPT_DIRECTORY_OPT => $rdbms_admin,\n },\n...\n<\/code><\/pre>\ncatcdb.pl iterates through the array START_SCRIPTS and executes the configured scripts. Unfortunately, it neither parses the log files nor does it stop processing on error. Consequently, it deletes all the diagnostic information. So I was looking for a way to interrupt processing on error.<\/p>\n
catcdb.pl calls catcon.pl which, in turn, imports functions from the Perl module catcon.pm. One of those functions calls sqlplus to execute catalog scripts.<\/p>\n
catcon.pm<\/h1>\n
The function exec_DB_script is the central function that executes generated SQL scripts.<\/p>\n
exec_DB_script arguments<\/h2>\n
There is an anomaly in this function, though, not related to our issue. I decided to include the information anyway.<\/p>\n
The last parameter is the path to the sqlplus<\/span> and is stored in the variable $sqlplus<\/span>.<\/p>\n\nsub exec_DB_script (\\@$) {\n my ($statements, $marker, $DoneCmd, $DoneFilePathBase, $sqlplus<\/span>) = @_;\n<\/code><\/pre>\nBut the $sqlplus<\/span> variable is never used. Below is the call to sqlplus<\/span>:<\/p>\n open my $Reader, \"sqlplus<\/span> \/nolog \\@$scriptFile | \";<\/code><\/pre>\n“$” is missing in front of sqlplus. In Perl $sqlplus<\/span> is the value of the variable called $sqlplus<\/span> and sqlplus<\/span> is just a string:<\/p>\nmy $sqlplus<\/span> = \"\/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\" ;\nprint \"variable: $sqlplus<\/span> \\n\" ;\nprint \"string: sqlplus<\/span> \\n\" ;<\/code><\/pre>\nperl demo.pl\nvariable: \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a<\/span>\nstring: sqlplus<\/span><\/code><\/pre>\nThe sqlplus path passed through the function argument was ignored and the sqlplus was resolved through the PATH variable. Since PATH was set correctly, the correct sqlplus was picked up, so it doesn’t make a difference in this case.<\/p>\n
Interrupting exec_DB_script<\/h2>\n
Our goal was to check the environment and find out the command in the script where the problem happened. Therefore, I introduced the following code in the procedure exec_DB_script in the while loop that parses the output (I did those changes in the lab environment):<\/p>\n
if ( $_ =~ m{ORA-12269} ) {\nopen(FH, '>', '\/tmp\/failed_' . time );\nprint FH \"$scriptFile \\n\" ;\nprint FH \"$ENV{PATH}\\n\" ;\nprint FH \"$ENV{LD_LIBRARY_PATH}\\n\" ;\nprint FH join \"\\n\", @Spool ;\nclose FH ;\ndie \"Killed\" ;\n}<\/code><\/pre>\nThe code above spools the environment and stops the execution. After the execution stopped we examined the scripts and outputs in the working directory. The error was raised while establishing connection.<\/p>\n
connect sys\/\"manager\" as sysdba<\/code><\/pre>\nNotice that this connection string produces a local connection with OS authentication. As long as you specify “as sysdba” and don’t specify the TNS connect string, you can provide any username and password:<\/p>\n
sqlplus non-existing-user\/invalid_password<\/span> as sysdba\n\nSQL*Plus: Release 19.0.0.0.0 - Production on Wed Jan 12 13:27:10 2022\nVersion 19.13.0.0.0\n\nCopyright (c) 1982, 2021, Oracle. All rights reserved.\n\n\nConnected<\/span> to:\nOracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production\nVersion 19.13.0.0.0\n\nSQL><\/code><\/pre>\nThis is expected behavior, documented in the MOS note “Why Can I Login AS SYSDBA With Any Username and Password? (Doc ID 242258.1)”:<\/p>\n
connect sys\/”manager” as sysdba worked fine. Just when we ran it in a loop for a while, the error was raised. In contrast, we couldn’t reproduce the error with the usual connect string “\/ as sysdba”.<\/p>\n
Call Stack<\/h1>\n
We configured the event to gather the call stack on the error, which should provide a context where the error was generated:<\/p>\n
event='12269 TRACE NAME ERRORSTACK LEVEL 3'<\/code><\/pre>\nkgerelv()+137 call kgeade() 7F1FE0CB59C0 ? 7F1FE0CB5C08 ?\n 7F1FE0B50050 ? 000002FED ?\n 000000000 000000000\nkserecl0()+189 call kgerelv() 7F1FE0CB59C0 ? 7F1FE0B50050 ?\n 7F1FE0B50050 ? 0134B62F0 ?\n 000000000 ? 000000000 ?\nksulbem<\/span>()+454 call kserecl0() 7F1FE0CB59C0 ? 7F1FE0B50050 ?\n 7F1FE0B50050 ? 0000007FF\n 000000000 006E9AD80\nopitsk()+3292 call ksulbem() 000000001 ? 000002FED ?\n 7FFFBA5E3C20 ? 0000007FF ?\n 000000000 ? 006E9AD80 ?\nopiino()+936 call opitsk() 000000000 000000000\n 7FFFBA5E3C20 ? 0000007FF ?\n 000000000 ? 006E9AD80 ?\n<\/code><\/pre>\nThe lower functions on the stack beginning with “kge” and “kse” handle errors. Prima vista, the error seems to originate from ksulbem<\/span>, which according to its naming convention shouldn’t have anything to do with error handling. ksulbem was called by opitsk, a generic function for handling local connections.<\/p>\nSince nobody outside Oracle seems to know about the purpose of this function, Stefan Koehler suggested tracing with Intel pin debugtrace<\/a>.<\/p>\nBy running debugtrace on sqlplus in a loop, we managed to capture the trace of a failed connection.<\/p>\n
.\/pin -follow_execv -t source\/tools\/DebugTrace\/obj-intel64\/debugtrace.so -- sqlplus sys\/\"manager\" as sysdba<\/code><\/pre>\n\nCall \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:opitsk+0x00000000170f -> 0x00000000149e7a80 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ksulbem<\/span>(0x1, 0x2fed<\/span>, ...)\n| Call 0x00000000149e7c41 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ksulbem+0x0000000001c1 -> 0x0000000000ea35a0 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:kserecl0(0x15a279c0, 0x15a279d4, ...)\n<\/code><\/pre>\nPay attention to the second argument of ksulbem<\/span>: 0x2fed<\/span>. 0x2fed<\/span> is 12269<\/span> in decimal notation, which is our error code! Since the error code was passed to ksulbem, the error was not generated inthere. In other words, ksulbem is just an error handling function (“em” might stand for “error management”).<\/p>\nThe error was generated before, in the function naedacc<\/span>, when reading incoming packets:<\/p>\n\nCall 0x0000000014419a71 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:nsfull_pkt_rcv+0x0000000046f1 -> 0x00000000144d8870 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:naedacc(0x7ff1d79e4058, 0x7ff1d79e12e0, ...)\nReturn 0x00000000144d91d8 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:naedacc<\/span>+0x000000000968 returns: 0x2fed<\/span>\nCall 0x0000000014419afc \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:nsfull_pkt_rcv+0x00000000477c -> 0x0000000006e32d40 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:nserrbc(0x7ff1d79df928, 0, ...)\n<\/code><\/pre>\nnsfull_pkt_rcv called naedacc<\/span>. naedacc<\/span> is one of the functions handling encryption\/decryption. It seems to be short-circuited – it exited quickly, without calling any other functions. Presumably, it found something in the byte stream that misled it to the wrong conclusion that weak ciphers are being used. As a result, it returned the error code 0x2fed<\/span>.<\/p>\nThis is how the naedacc<\/span> stack looks like for a good execution (the indentation removed to improve the readability):<\/p>\n.\/pin -follow_execv -t source\/tools\/DebugTrace\/obj-intel64\/debugtrace.so -- sqlplus sys\/\"manager\" as sysdba<\/code><\/pre>\nCall 0x00000000144d8a4e \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:naedacc<\/span>+0x0000000001de -> 0x00000000143420a0 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:naeaesd(0x7fcd39987c38, 0x7fcd399812e0, ...)\nCall 0x00000000143420ee \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:naeaesd+0x00000000004e -> 0x0000000014faa9c0 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ssMemMalloc(0x31, 0x7fcd399812e0, ...)\nTailcall 0x0000000014faa9d5 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ssMemMalloc+0x000000000015 -> 0x00000000149ffca0 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ksmem_malloc(0x31, 0x7fcd399812e0, ...)\nReturn 0x00000000149ffe62 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ksmem_malloc+0x0000000001c2 returns: 0x7fcd3997f730\nCall 0x000000001434211d \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:naeaesd+0x00000000007d -> 0x0000000006fa8480 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ztcedec<\/span>(0x7008001, 0x7fcd3998cd30, ...)\nCall 0x0000000006fa84a7 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ztcedec<\/span>+0x000000000027 -> 0x0000000006fa84d0 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ztcedec2(0x7008001, 0x7fcd3998cd30, ...)\nTailcall 0x0000000006fa84da \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ztcedec2<\/span>+0x00000000000a -> 0x000000001540f0b0 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ztcecrypto_2<\/span>(0x7008001, 0x7fcd3998cd30, ...)\nCall 0x000000001540f135 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ztcecrypto_2<\/span>+0x000000000085 -> 0x000000001540f1f0 \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle:ztcei2(0x7ffede9f0b70, 0x7008001, ...)\n...\n<\/code><\/pre>\nWe can see a long list of encryption handling functions (all beginning with “zt<\/span>“, see Frits Hogland’s orafun.info<\/a>“).<\/p>\nHow does the program flow look like without encryption?<\/p>\n
I’m setting TNS_ADMIN to a directory without sqlnet.ora (no encryption by default) and starting sqlplus with pin debugtrace:<\/p>\n
export TNS_ADMIN=\/tmp\n.\/pin -follow_execv -t source\/tools\/DebugTrace\/obj-intel64\/debugtrace.so -- sqlplus sys\/\"manager\" as sysdba<\/code><\/pre>\nExpectedly, no naedacc call was made:<\/p>\n
grep naedacc debugtrace.out<\/code><\/pre>\nWe indeed couldn’t reproduce the problem without encryption.<\/p>\n
Summary<\/h1>\n
If you specify username and password despite using OS authentication, you might get “ORA-12269: client uses weak encryption\/crypto-checksumming version”. The issue isn’t reproducible at will. I assume there’s a boundary condition where a byte in the encrypted stream is wrongly recognized as a flag that marks weak encryption algorithms. Comparing the condition in the function naedacc with the byte stream in SQLNet trace should provide a clue for a bug fix.<\/p>\n
Specifying username and password with OS authentication is unnecessary. Therefore, the best way to avoid it to use the connect string without username and password, for example “\/ as sysdba”.<\/p>\n
CDB catalog creation, however, specifies username and password and may occasionally fail. The workaround consists of pointing TNS_ADMIN to a configuration without encryption before starting sqlplus that will run the catalog creation. Alternatively, you can point it to any directory without sqlnet.ora as encryption is switched off by default.<\/p>\n
Update on January 20, 2022 – Internals<\/h1>\n
Meanwhile, I figured out the flag which triggers the error. I did the analysis on 21.3. The data structure that stores the flag might change with each release.<\/p>\n
After logging in with sqlplus, I’m attaching with gdb to the dedicated server process:<\/p>\n
attach 1506475\nAttaching to process 1506475\nReading symbols from \/u00\/oracle\/orabase\/product\/21.3.0.0.0_a\/bin\/oracle...<\/code><\/pre>\nI’m setting the breakpoint at naedacc:<\/p>\n
(gdb) b naedacc\nBreakpoint 1 at 0x144d8870\n(gdb) c\nContinuing.<\/code><\/pre>\nIn the SQLPlus I’m running a query and hitting the breakpoint:<\/p>\n
Breakpoint 1, 0x00000000144d8870 in naedacc ()<\/code><\/pre>\nThe CPU register contains the pointer to the structure that contains the flag that is tested for raising the error:<\/p>\n
(gdb) p\/x $rdi<\/span>\n$1 = 0x7fceede60058<\/span><\/code><\/pre>\nThe flag is stored in the byte 0x74 of the structure and is set to zero:<\/p>\n
(gdb) x\/u $rdi+0x74<\/span>\n0x7fceede600cc<\/span>: 0<\/code><\/pre>\nHow can we verify that we’re looking at the correct location?<\/p>\n
We can set it to a non-zero value and continue with the execution:<\/p>\n
(gdb) set *0x7fceede600cc<\/span> = 1\n(gdb) x\/u $rdi+0x74<\/span>\n0x7fceede600cc<\/span>: 1\n(gdb) c\nContinuing.<\/code><\/pre>\nSetting the flag to a non-zero value indeed causes the error:<\/p>\n
SQL> select * from dba_users ;\nselect * from dba_users\n*\nERROR at line 1:\nORA-12269: client uses weak encryption\/crypto-checksumming version<\/code><\/pre>\nStefan Koehler suggested using pintools debugtrace with the memory option for finding out who sets this flag<\/a>.<\/p>\nFirst, we have to find out the flag address in the debugtrace output (the address remains constant for the session, but changes for each connection, when a new dedicated server process is forked.)<\/p>\n
Below is the first call to naedacc<\/span> during connection:<\/p>\n21.3.0.0.0_a\/bin\/oracle:nsfull_pkt_rcv+0x0000000046f1 -> 0x00000000144d8870 21.3.0.0.0_a\/\nbin\/oracle:naedacc<\/span>(0x7fb24c76c058<\/span>, 0x7fb24c7692e0, ...)\nWrite *(UINT64*)0x00007ffec34c87a8 = 0x14419a76\nWrite *(UINT64*)0x00007ffec34c87a0 = 0x7ffec34c8c40\nWrite *(UINT64*)0x00007ffec34c8798 = 0x7fb24c756060\nWrite *(UINT64*)0x00007ffec34c8790 = 0x7fb24cef62e8\nWrite *(UINT64*)0x00007ffec34c8788 = 0\nWrite *(UINT64*)0x00007ffec34c8780 = 0x7fb24c759858\nWrite *(UINT64*)0x00007ffec34c8778 = 0x7fb24c767928\nRead 0x7fb24f0f07c8 = *(UINT64*)0x00007fb24c76c070\nRead 0x7fb24cef62e8 = *(UINT64*)0x00007fb24f0f0820\nRead 0x20 = *(UINT8*)0x00007fb24cef62f1\nWrite *(UINT64*)0x00007ffec34c8770 = 0\nRead 0x1 = *(UINT32*)0x00007fb24c76c0c8\nRead 0x7fb24c76e6f0 = *(UINT64*)0x00007fb24c76c230\nRead 0x7fb24c76fcf8 = *(UINT64*)0x00007fb24c76c238\nRead 0x7fb24c76fc38 = *(UINT64*)0x00007fb24c76c240\nRead 0 = *(UINT8*)0x00007fb24c769311\nRead 0x3c = *(UINT64*)0x00007fb24c7562e8\nWrite *(UINT64*)0x00007fb24c7562e8 = 0x3b\nRead 0x7fb24c76c058 = *(UINT64*)0x00007fb24c76e720\nRead 0x1 = *(UINT32*)0x00007fb24c76c060 \nRead 0 = *(UINT8*)0x00007fb24c76eb34\nRead 0 = *(UINT32*)0x00007fb24c76c0cc<\/span>\nRead 0x11 = *(UINT8*)0x00007fb24c76fc40\nRead 0 = *(UINT32*)0x00007fb24c76fc70\nRead 0 = *(UINT8*)0x00007fb24c76fc50\nWrite *(UINT64*)0x00007ffec34c8748 = 0x7fb24c76fcf8<\/code><\/pre>\nThe pointer to the structure 0x7fb24c76c058<\/span> is passed through the first parameter. We know this because the first argument is passed through the RDI CPU register according to the x86 calling convention<\/a>, and we previously verified that the pointer is stored in the RDI register when entering naedacc. The flag is stored on the memory location 0x00007fb24c76c0cc<\/span> (0x7fb24c76c058<\/span> + 0x74). We can see that a read from this location returned 0.<\/p>\nNext, we have to look in the debugtrace output where this location was set before naedacc call:<\/p>\n
Tailcall 0x0000000007c9b024 21.3.0.0.0_a\/bin\/oracle:_intel_fast_memset.V+0x000000000004 -> 0x0000000007ca1fd0 21.3.0.0.0_a\/bin\/oracle:__intel_avx_rep_memset<\/span>(0x7fb24c76c058, 0, ...)\nRead 0x1c0 = *(UINT64*)0x0000000007ca2330\nWrite *(UINT64*)0x00007fb24c76c058 = 0\nRead 0x8000 = *(UINT32*)0x000000001a46f528\nWrite *(UINT256)0x00007fb24c76c060 = 00000000_00000000_00000000_00000000_00000000_00000000_00000000_00000000\nWrite *(UINT256)0x00007fb24c76c080 = 00000000_00000000_00000000_00000000_00000000_00000000_00000000_00000000\nWrite *(UINT256)0x00007fb24c76c0a0 = 00000000_00000000_00000000_00000000_00000000_00000000_00000000_00000000\nWrite *(UINT256)0x00007fb24c76c0c0<\/span> = 00000000_00000000_00000000_00000000_00000000_00000000_00000000_00000000<\/code><\/pre>\nThe function __intel_fast_memset<\/span> is too generic – we know that it initializes the memory locations, but it doesn’t tell us anything about the Oracle context. So we have to scroll further up until the next Oracle function:<\/p>\nCall 0x0000000006ede8b7 21.3.0.0.0_a\/bin\/oracle:nainit<\/span>+0x000000000107 -> 0x0000000003e98f70 21.3.0.0.0_a\/bin\/oracle:ssMemCalloc(0x248, 0x1, ...)<\/code><\/pre>\nThe Oracle function nainit<\/span> initialized the whole structure. Since after the initialization nobody has changed the flag, it has remained zero when naedacc was called. This means that in case of error, the flag is probably overwritten between nainit and naedacc calls. We need a trace of failed connection. Therefore, I’m currently running the following command in a loop:<\/p>\npin -follow_execv -t source\/tools\/DebugTrace\/obj-intel64\/debugtrace.so -- sqlplus sys\/manager as sysdba<\/code><\/pre>\nAs pin debugtrace with the memory option is extremely slow, the expected time to error is a couple of weeks.<\/p>\n","protected":false},"excerpt":{"rendered":"
Oracle internals analysis with pintools; workaround provided Continue Reading