ORA-29516: AURORA ASSERTION FAILURE: ASSERTION FAILURE AT OEX.C:359
SYMPTOMS
During executing the PSU patch post-step script on one of the test databases, I had an unusual error that was intermittent. Sometimes the post-step script completed successfully without any errors and sometimes it failed. I tried many workarounds but none of them helped me out.
For instance, when I executed post-step script of the patch 31103343 Loading Modified SQL Files into the Database
cd $ORACLE_HOME/rdbms/admin sqlplus /nolog SQL> CONNECT / AS SYSDBA SQL> STARTUP SQL> @catbundle.sql psu apply SQL> QUIT
the @catbundle.sql script sometimes failed with the following error
DROP JAVA DATA "SYS"."LocaleData_da_DK" DROP JAVA DATA "SYS"."LocaleData_coll_es_HN" DROP JAVA DATA "SYS"."LocaleData_es_HN" DROP JAVA DATA "SYS"."prv//////ENOJBBPFAAAAAAAA" DROP JAVA DATA "SYS"."prv//////MDDMJLJNAAAAAAAA" DROP JAVA DATA "SYS"."prv//////NAPLGELEAAAAAAAA" DROP JAVA DATA "SYS"."prv//////IEIJPIEBAAAAAAAA" DROP JAVA DATA "SYS"."prv//////CLENFDMLAAAAAAAA" DROP JAVA DATA "SYS"."prv//////IHLOPGIJAAAAAAAA" DROP JAVA DATA "SYS"."prv//////MGBCBOLLAAAAAAAA" DROP JAVA DATA "SYS"."prv//////HHPHKFCGAAAAAAAA" DROP JAVA DATA "SYS"."prv//////OKMOMHMBAAAAAAAA" DROP JAVA DATA "SYS"."prv//////DNLOIFJFAAAAAAAA" DROP JAVA DATA "SYS"."prv//////KGLNECFEAAAAAAAA" DROP JAVA DATA "SYS"."prv//////DDJCFKNKAAAAAAAA" DROP JAVA DATA "SYS"."prv//////FOPOCDCGAAAAAAAA" DROP JAVA DATA "SYS"."prv//////JJNALOPFAAAAAAAA" DROP JAVA DATA "SYS"."prv//////IOLBDJNCAAAAAAAA" DROP JAVA DATA "SYS"."prv//////IIBABFJEAAAAAAAA" DROP JAVA DATA "SYS"."prv//////BCIHDMKEAAAAAAAA" DROP JAVA DATA "SYS"."prv//////IBPLEBPAAAAAAAAA" DROP JAVA DATA "SYS"."prv//////EFOLNLBEAAAAAAAA" DROP JAVA DATA "SYS"."prv//////JKBIENDKAAAAAAAA" DROP JAVA DATA "SYS"."prv//////HPNCBMNLAAAAAAAA" DROP JAVA DATA "SYS"."prv//////HNGLLGBAAAAAAAAA" DROP JAVA DATA "SYS"."prv//////PEACEFDBAAAAAAAA" DROP JAVA DATA "SYS"."prv//////KPKNOAIAAAAAAAAA" DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000015" DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000016" DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000017" DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000018" DROP JAVA DATA "SYS"."JAVA$POLICY$SHARED$00000019" DROP JAVA DATA "SYS"."prv//////DGFFDEIKAAAAAAAA" delete from java$policy$shared$table BEGIN * ERROR at line 1: ORA-29516: Aurora assertion failure: Assertion failure at eox.c:359 Uncaught exception Root of all Java exceptions: java.lang.NoClassDefFoundError sun/misc/Hashing ORA-06512: at line 25 SQL> SQL> SQL> commit; Commit complete. SQL> SQL> SQL> -- bug 25649873 create a policy SRO SQL> SQL> @@jvmsec6 SQL> -- Create the table now to avoid creation of a lot of SQL> -- unneccessary shared objects by the above grant_permissions, SQL> -- and redundantly grant something to cause creation of a shared object. SQL> call initjvmaux.create_if_not_present(' 2 create table java$policy$shared$table (version number) 3 '); create table java$policy$shared$table (version number) Call completed. SQL> SQL> call dbms_java.grant_permission('PUBLIC', 'SYS:oracle.aurora.security.JServerPermission', 'DUMMY', ''); call dbms_java.grant_permission('PUBLIC', 'SYS:oracle.aurora.security.JServerPermission', 'DUMMY', '') * ERROR at line 1: ORA-29516: Aurora assertion failure: Assertion failure at eox.c:359 Uncaught exception Root of all Java exceptions: java.lang.NoClassDefFoundError sun/misc/Hashing ORA-06512: at "SYS.DBMS_JAVA", line 793 SQL> call dbms_java.revoke_permission('PUBLIC', 'SYS:oracle.aurora.security.JServerPermission', 'DUMMY', ''); call dbms_java.revoke_permission('PUBLIC', 'SYS:oracle.aurora.security.JServerPermission', 'DUMMY', '') * ERROR at line 1: ORA-29516: Aurora assertion failure: Assertion failure at eox.c:359 Uncaught exception Root of all Java exceptions: java.lang.NoClassDefFoundError sun/misc/Hashing ORA-06512: at "SYS.DBMS_JAVA", line 819 SQL> SQL> commit; Commit complete. SQL> SQL> SQL> SQL> PROMPT Processing Oracle Text... Processing Oracle Text... SQL> ALTER SESSION SET current_schema = CTXSYS;
The failed part of the @catbundle.sql script belonged to the following part of the scipt code
SQL> BEGIN
2
3 :jvmversion := 'NONE';
4 :jitstate := 'FALSE';
5 SELECT value INTO :jitstate FROM v$parameter WHERE name='java_jit_enabled';
6 select nvl((SELECT name FROM obj$ WHERE name like 'JAVA$CBRLS%' and type#=30 and owner#=0), 'NONE') into :jvmversion from dual;
7 select to_char((select startup_time from v$instance),'DD-MON-YYYY HH24:MI:SS') INTO :dbtime from dual;
8 select to_char
9 ((select nvl((SELECT MTIME FROM obj$ WHERE name like 'JAVA$CBRLS%' and type#=30 and owner#=0),to_date('01-JAN-0001','DD-MON-YYYY'))
10 from dual),'DD-MON-YYYY HH24:MI:SS') INTO :cjstime from dual;
11
12
13 EXECUTE IMMEDIATE 'alter system set java_jit_enabled = false';
14
15
16 IF ((not(:jvmaction = 'APPLY' and :jvmversion = 'JAVA$CBRLS$11.2.0.4.200714'))
17 and (not(:jvmaction = 'ROLLBACK' and
18 :jvmversion != 'JAVA$CBRLS$11.2.0.4.200714'))) and
19 (to_date(:cjstime,'DD-MON-YYYY HH24:MI:SS') = to_date ('01-JAN-0001','DD-MON-YYYY HH24:MI:SS')
20 or to_date(:dbtime,'DD-MON-YYYY HH24:MI:SS') > to_date(:cjstime,'DD-MON-YYYY HH24:MI:SS')) THEN
21
22 initjvmaux.drop_sros();
23
24
25 EXECUTE IMMEDIATE 'create or replace java system';
26
27 update dependency$
28 set p_timestamp=(select stime from obj$ where obj#=p_obj#)
29 where (select stime from obj$ where obj#=p_obj#)!=p_timestamp and
30 (select type# from obj$ where obj#=p_obj#)=29 and
31 (select owner# from obj$ where obj#=p_obj#)=0;
32
33
34 -- Check the validity of JAVAVM and let the registry be updated accordingly.
35
36 initjvmaux.validate_javavm;
37
38 -- Add a row in registry$history to indicate this script was run.
39
40 EXECUTE IMMEDIATE 'insert into registry$history
41 (action_time, action, namespace, version, id, comments)
42 values(SYSTIMESTAMP, ''jvmpsu.sql'', ''SERVER'',
43 ''11.2.0.4.200714OJVMPSU'', 0, ''RAN jvmpsu.sql'')';
44
45 END IF;
46
47 EXECUTE IMMEDIATE 'alter system set java_jit_enabled = ' || :jitstate;
48
49 END;
50 /
According to the above excerpt of the code it was related to JAVA. I checked status for all Java components and all of them were in the VALID state.
set pages 999
set lines 300
col COMP_ID for a10
col COMP_NAME for a35
col VERSION for a15
col PROCEDURE for a45
col OTHER_SCHEMAS for a25
col STATUS for a10
col CONTROL for a15
col SCHEMA for a15
col MODIFIED for a20
select comp_id,comp_name,version,status,modified,schema,procedure from dba_registry
where upper(comp_name) like '%JAVA%';
COMP_ID COMP_NAME VERSION STATUS MODIFIED SCHEMA PROCEDURE
---------- -------------------------------- ------------- ---------- -------------------- ------- -----------------------------------
JAVAVM JServer JAVA Virtual Machine 11.2.0.4.0 VALID 28-OCT-2020 21:28:28 SYS INITJVMAUX.VALIDATE_JAVAVM
CATJAVA Oracle Database Java Packages 11.2.0.4.0 VALID 28-OCT-2020 21:28:28 SYS DBMS_REGISTRY_SYS.VALIDATE_CATJAVA
NOTE
Increasing the java pool size as mentioned in Doc ID 2185332.1 before the script execution had no effect
ROOT CAUSE
With the following query, I found out that there were many active sessions in the database after it was started. And it turned out that all those sessions were Oracle jobs (see PROGRAM column) that were started right after the database was OPEN.
COL SID FOR 99999
COL USERNAME FOR A10
COL STATUS FOR A10
COL SQL_ID FOR A15
COL EVENT FOR A35
COL ELAPSED_SECONDS FOR 999999
COL MODULE FOR A15
COL PROGRAM FOR A15
SET LINES 300
SET PAGES 999
SELECT SID,
SERIAL#,
USERNAME,
SQL_ID,
STATUS,
EVENT,
LAST_CALL_ET ELAPSED_SECONDS,
SUBSTR(MODULE,1,15) MODULE,
SUBSTR(PROGRAM,-15) PROGRAM
FROM
V$SESSION
WHERE
USERNAME IS NOT NULL
ORDER BY LAST_CALL_ET;
SID SERIAL# USERNAME SQL_ID STATUS EVENT ELAPSED_SECONDS MODULE PROGRAM
------ ---------- ---------- --------------- ---------- ----------------------------------- --------------- --------------- ---------------
387 7 SYS bf8szb5c6cffw ACTIVE SQL*Net message to client 0 sqlplus@s001tst .local (TNS V1-
776 189 POSC avcp8cxpdwjut ACTIVE buffer busy waits 34 ur.local (J014)
1552 121 POSC 3tpdp8s33jhqp ACTIVE buffer busy waits 76 ur.local (J022)
1930 133 MES_WEB 1g7hn33utrqaw ACTIVE buffer busy waits 138 ur.local (J001)
1177 63 POSC b0ks42hvpk9d2 ACTIVE buffer busy waits 149 ur.local (J000)
1161 113 POSC 2qq5h4u4ms5zk ACTIVE buffer busy waits 277 ur.local (J012)
8 51 POSC a5a94fbxt61z2 ACTIVE buffer busy waits 278 ur.local (J006)
791 37 POSC a5a94fbxt61z2 ACTIVE buffer busy waits 278 ur.local (J019)
391 151 POSC a5a94fbxt61z2 ACTIVE buffer busy waits 279 ur.local (J003)
1945 155 POSC a5a94fbxt61z2 ACTIVE buffer busy waits 429 ur.local (J017)
401 47 POSC a5a94fbxt61z2 ACTIVE buffer busy waits 541 ur.local (J009)
1926 5 RWC a9g4k0980a5b6 ACTIVE latch free 1018 DBMS_SCHEDULER ur.local (J007)
4 7 RWC a9g4k0980a5b6 ACTIVE latch: cache buffers chains 1019 DBMS_SCHEDULER ur.local (J002)
6 9 RWC a9g4k0980a5b6 ACTIVE latch free 1019 DBMS_SCHEDULER ur.local (J008)
1934 9 RWC a9g4k0980a5b6 ACTIVE latch: cache buffers chains 1019 DBMS_SCHEDULER ur.local (J031)
14 11 RWC a9g4k0980a5b6 ACTIVE latch: cache buffers chains 1020 DBMS_SCHEDULER ur.local (J032)
1558 3 RWC a9g4k0980a5b6 ACTIVE latch free 1025 DBMS_SCHEDULER ur.local (J048)
1163 11 RWC a9g4k0980a5b6 ACTIVE latch free 1027 DBMS_SCHEDULER ur.local (J011)
1938 3 RWC a9g4k0980a5b6 ACTIVE latch: cache buffers chains 1029 DBMS_SCHEDULER ur.local (J043)
10 13 RWC a9g4k0980a5b6 ACTIVE latch: cache buffers chains 1032 DBMS_SCHEDULER ur.local (J020)
395 5 RWC a9g4k0980a5b6 ACTIVE latch: cache buffers chains 1032 DBMS_SCHEDULER ur.local (J015)
1928 9 RWC a9g4k0980a5b6 ACTIVE latch: cache buffers chains 1035 DBMS_SCHEDULER ur.local (J013)
778 17 RWC a9g4k0980a5b6 ACTIVE latch free 1035 DBMS_SCHEDULER ur.local (J010)
1940 1 POSC c8hbs4fc84rda ACTIVE enq: TX - row lock contention 1035 ur.local (J049)
1173 1 POSC c8hbs4fc84rda ACTIVE enq: TX - row lock contention 1036 ur.local (J041)
1556 1 POSC 2qq5h4u4ms5zk ACTIVE buffer busy waits 1036 ur.local (J042)
1550 11 POSC a5a94fbxt61z2 ACTIVE local write wait 1036 ur.local (J024)
405 1 POSC a5a94fbxt61z2 ACTIVE buffer busy waits 1036 ur.local (J045)
780 7 PERFSTAT 2tx2sr9upcpqb ACTIVE db file sequential read 1037 ur.local (J016)
1554 3 POSC 20s4ppqvh5pt0 ACTIVE latch free 1037 ur.local (J036)
399 3 POSC c8hbs4fc84rda ACTIVE enq: TX - row lock contention 1037 ur.local (J027)
1932 5 POSC c8hbs4fc84rda ACTIVE enq: TX - row lock contention 1037 ur.local (J025)
32 rows selected.
The root cause of the issue was that a user created lots of jobs that executed ‘heavy’ queries continuously. The queries overloaded the database and ate up all available memory in the SGA. So if the script was executed while jobs were running the script session failed to allocate memory in a pool during its execution and then terminated with the error because of it.
For instance, most of the jobs were started at the same time and repeated every 30 minutes
SQL> select job,NEXT_DATE,INTERVAL from dba_jobs where INTERVAL like '%/1440%' and broken='N';
JOB NEXT_DATE INTERVAL
---------- ------------------ --------------------------------------------------
4002 21-OCT-20 sysdate + 10/1440
2264 21-OCT-20 SYSDATE+3/1440
2204 21-OCT-20 TRUNC(SYSDATE,'HH')+120/1440
1766 21-OCT-20 SYSDATE+30/1440
1964 21-OCT-20 SYSDATE+2/1440
1485 21-OCT-20 SYSDATE+30/1440
1484 21-OCT-20 SYSDATE+30/1440
1424 21-OCT-20 SYSDATE+30/1440
1444 21-OCT-20 SYSDATE+30/1440
501 21-OCT-20 SYSDATE+30/1440
499 21-OCT-20 SYSDATE+30/1440
500 21-OCT-20 SYSDATE+30/1440
502 21-OCT-20 SYSDATE+30/1440
503 21-OCT-20 SYSDATE+30/1440
505 21-OCT-20 SYSDATE+30/1440
507 21-OCT-20 SYSDATE+30/1440
509 21-OCT-20 SYSDATE+30/1440
583 21-OCT-20 SYSDATE+10/1440
343 21-OCT-20 SYSDATE+30/1440
244 21-OCT-20 SYSDATE+30/1440
247 21-OCT-20 SYSDATE+30/1440
248 21-OCT-20 SYSDATE+30/1440
563 21-OCT-20 SYSDATE+30/1440
267 21-OCT-20 SYSDATE+30/1440
268 21-OCT-20 SYSDATE+30/1440
269 21-OCT-20 SYSDATE+30/1440
965 21-OCT-20 SYSDATE+30/1440
404 21-OCT-20 SYSDATE+30/1440
428 21-OCT-20 SYSDATE+30/1440
406 21-OCT-20 SYSDATE+30/1440
445 21-OCT-20 SYSDATE+30/1440
1124 21-OCT-20 SYSDATE+3/1440
1086 21-OCT-20 SYSDATE + 1/1440
1185 21-OCT-20 SYSDATE+30/1440
1225 21-OCT-20 SYSDATE+30/1440
1286 21-OCT-20 SYSDATE+30/1440
23 21-OCT-20 SYSDATE+30/1440
33 21-OCT-20 SYSDATE+30/1440
83 21-OCT-20 SYSDATE+10/1440
204 21-OCT-20 SYSDATE+15/1440
303 21-OCT-20 SYSDATE+60/1440
344 21-OCT-20 SYSDATE+30/1440
463 21-OCT-20 SYSDATE+120/1440
484 01-NOV-20 TRUNC(LAST_DAY(SYSDATE)) + 1 + 8/24 + 30/1440
544 21-OCT-20 sysdate+5/1440
546 21-OCT-20 sysdate+20/1440
731 21-OCT-20 (SYSDATE+1/1440)
827 21-OCT-20 (SYSDATE+60/1440)
866 21-OCT-20 SYSDATE+1/1440
895 01-JAN-21 ADD_MONTHS(TRUNC(SYSDATE,'yyyy'),12)+1/1440
50 rows selected.
However when I tried to apply the post-step script with disabled the JOB_QUEUE_PROCESSES parameter (so no jobs were running after the database had been started) the script completed successfully every time.
SQL> show parameter job_
NAME TYPE VALUE
------------------------------------ --------------------------------- ------------------------------
job_queue_processes integer 0
cd $ORACLE_HOME/rdbms/admin
sqlplus /nolog
SQL> CONNECT / AS SYSDBA
SQL> STARTUP
SQL> @catbundle.sql psu apply
SQL> QUIT
REFERENCES
ORA-29516: Aurora Assertion Failure Eox.c:359 Java.lang.ExceptionInInitializerError (Doc ID 2185332.1)
Version : 18:07 05.11.2020
Database : 11.2.0.4.0 (OJVM and PSU JULY 2020)
Database : 11.2.0.4.0 (OJVM and PSU JULY 2020)