After logon trigger in user schema and FRA full situation hang the database

This blog post is about a scenario where a combination of a logon trigger performing DML operations at user login time (writing to a custom audit table), and a Fast recovery area (FRA) full situation brings the database to a halted state where even the sys user can’t create a regular new session.

There are two goals to this post. One is to illustrate the blocking scenario, so that when using logon triggers, care is taken to think about possible side effects and consequences. The other is to present how I researched it, and show some of the techniques I used trying to fix it, possibly avoiding an instance restart. This can hopefully be useful when troubleshooting similar scenarios, as not all readers might be aware about them.

Testcase setup

For this example, I’m using a non-CDB 19c database. Lower Oracle versions can also be used. In a CDB architecture, the issue could also be reproduced in case the logon trigger resides in the root container, even though it’s not recommended to create user objects in there. If the trigger is created in a PDB, the issue can be fixed without a database restart. Also, if the logon trigger performs the INSERT into the audit table only for non-SYS users (for example by having an “IF (USERNAME<>’SYS’) THEN INSERT INTO..” statement), the issue can be avoided.

1) In order to reproduce the problem, let’s artificially limit the FRA size to 400MB:

SQL> show parameter db_recovery_file

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
db_recovery_file_dest                string      /u02/fast_recovery_area
db_recovery_file_dest_size           big integer 400M

On this test database, the size of the online redo logs is 200MB:

SQL> select GROUP#, BYTES, BLOCKSIZE, STATUS from  v$log;

    GROUP#      BYTES  BLOCKSIZE STATUS
---------- ---------- ---------- ----------------
         1  209715200        512 INACTIVE
         2  209715200        512 INACTIVE
         3  209715200        512 CURRENT

SQL>

2) Create a user “u1” with the following privileges:

create user u1 identified by oracle default tablespace users;
grant create session to u1;
grant create table to u1;
grant create trigger to u1;
grant administer database trigger to u1;
alter user u1 quota unlimited on users;

3) Logged in as user “u1”, create a table which the login trigger will INSERT into. This will simulate an audit table the trigger might be actually writing to:

SQL> conn u1/oracle@localhost/orcl
Connected.
SQL> show user
USER is "U1"
SQL>

Side note: Though it’s not strictly relevant to this particular test case, the explicit CAST is used to make sure the columns’ datatypes are NUMBER and VARCHAR2(4000) respectively.

SQL> create table t1 (id, text)
as 
select cast (rownum as number) id,
       cast (rpad('x',4000) as varchar2(4000))
from dual
connect by level <= 100;

4) Logged in as the same “u1” user, create a “LOGON ON DATABASE” trigger which will simulate writing into an audit table at user logon time:

CREATE OR REPLACE TRIGGER trg
AFTER LOGON ON DATABASE
begin
  insert into t1 select * from t1 where rownum <= 100;
end;
/

The trigger fires for all logons, SYS included.

5) In a separate sqlplus session (doesn’t matter as which user we’re logged in), start generating REDO, so that the FRA fills up. The SID of this session is 34 (we’ll need it later):

SQL> create table t2 as select * from all_source;

Table created.

SQL> begin
 while (true) loop
  insert into t2 select * from t2;
  commit;
 end loop;
end;
/

6) Short after that, the FRA fills up, and the archiver process is unable to archive the online redo logs:

2022-08-22T16:05:05.695477+02:00
ORACLE Instance orcl - Cannot allocate log, archival required
2022-08-22T16:05:05.695568+02:00
Thread 1 cannot allocate new log, sequence 17
All online logs need archiving
Examine archive trace files for archiving errors
  Current log# 1 seq# 16 mem# 0: /u02/oradata/ORCL/redo01.log
2022-08-22T16:05:14.474371+02:00
Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_tt00_20161.trc:
ORA-19809: limit exceeded for recovery files
ORA-19804: cannot reclaim 209715200 bytes disk space from 419430400 bytes limit

And just to confirm, there’s still room available on the filesystem where the FRA resides:

[oracle@hol ~]$ df -kh /u02/fast_recovery_area
Filesystem           Size  Used Avail Use% Mounted on
/dev/mapper/ol-root   50G   45G  5.3G  90% /

Trying to fix the problem in five different ways

1. In case enough disk storage is available, one of the fastest solutions to alleviate a critical FRA full situation could be to temporarily increase the FRA size. If we have an existing session where we’re logged in as a user with enough privileges to change the FRA size, that can be done. However, new connections to the database, even as sys, are not possible, as the logon trigger is blocking the creation of a new session:

[oracle@hol ~]$ sqlplus / as sysdba

SQL*Plus: Release 19.0.0.0.0 - Production on Mon Aug 22 16:34:19 2022
Version 19.5.0.0.0

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


<<-- login is blocked

Side note about logon trigger firing rules

As described in MOS note “Connecting as DBA Does not Fire RAISE_APPLICATION_ERROR in a AFTER LOGON ON DATABASE TRIGGER (Doc ID 226058.1)” and in the documentation, unhandled exceptions in the logon trigger don’t prevent logins to users having the ADMINISTER DATABASE TRIGGER privilege, so sys should be able to login even if the trigger raises an exception. However, our logon trigger is not raising an exception, it’s just blocked on a DML operation.

Before proceeding further, let’s take a note of the PID of the process created for our connection. I found it out by simply running the below ps command before and after starting “sqlplus / as sysdba”, and it’s PID=1767. We’ll use it later on, when inspecting a hanganalyze trace file:

[oracle@hol trace]$ ps -ef |grep beq
oracle    1767  1766  0 17:24 ?        00:00:00 oracleorcl (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))


[oracle@hol trace]$ pstree -lap 1766
sqlplus,1766   as sysdba
  |-oracle_1767_orc,1767 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
  |-{sqlplus},1768

2. The same hang occurs if we try to connect with “rman target /” in order to manage the archivedlogs by backing them up or removing them. RMAN even displays the issue with the trigger when executing the ‘U1.TRG’ trigger:

[oracle@hol ~]$ rman target /

Recovery Manager: Release 19.0.0.0.0 - Production on Mon Aug 22 17:04:53 2022
Version 19.5.0.0.0

Copyright (c) 1982, 2019, Oracle and/or its affiliates.  All rights reserved.

^CRMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-00554: initialization of internal recovery manager package failed
RMAN-04005: error from target database:
ORA-04088: error during execution of trigger 'U1.TRG'
ORA-00604: error occurred at recursive SQL level 1
ORA-01013: user requested cancel of current operation
[oracle@hol ~]$

3. Manually deleting the archivedlogs from disk won’t help either, as Oracle won’t be aware of this change.
4. As we know that the sqlplus logon is blocked by a trigger, what happens if I try to cancel the SQL call – would I still get the session? Following Tanel Poder’s article, the kill -URG <PID> can be used to cancel the current SQL call.

Let’s try that with a new login attempt, which hangs:

[oracle@hol ~]$ sqlplus / as sysdba
<<-- hangs

Verify the parent PID:

[oracle@hol trace]$ pstree -lap 12458
sqlplus,12458   as sysdba
  |-oracle_12459_or,12459 (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
  |-{sqlplus},12460

And let’s try to cancel the SQL call with:

[oracle@hol trace]$ kill -URG 12459

No luck – we can’t login, and sqlplus session reports the below error:

[oracle@hol ~]$ sqlplus / as sysdba

SQL*Plus: Release 19.0.0.0.0 - Production on Mon Aug 22 20:02:49 2022
Version 19.5.0.0.0

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

ERROR:
ORA-01075: you are currently logged on


Enter user-name:

5. Running alter system set "_system_trig_enabled"=false would prevent the trigger from firing, and thus allow us to login as sys either in sqlplus or rman. Though, assuming we don’t have an established session from where to run the command, we can’t dynamically set the parameter, not even with a preliminary sqlplus connection (discussed further down in the post).

So at this point the DB instance is stuck. Existing sessions can still perform SELECTs, but no DML is possible.

Initial research steps

Following are some techniques to illustrate how to find out what the blocked sessions are waiting for. For illustration purposes I had an already established session before the FRA full situation occurred, so I could run the below SQLs. If we don’t have such a session, I’ll show more advanced techniques later on.

1) Session with SID=34 (the one inserting in an infinite loop) is blocked by the logwriter (LGWR, SID=10) process:

SQL> select sid, program, event, status, state, last_call_et, blocking_session, blocking_session_status from v$session where sid=34;

SID PROGRAM                              EVENT                               STATUS   STATE    LAST_CALL_ET BLOCKING_SESSION BLOCKING_SE
--- ------------------------------------ ----------------------------------- -------- -------- ------------ ---------------- -----------
 34 sqlplus@hol.localdomain (TNS V1-V3)  log file switch (archiving needed)  ACTIVE   WAITING          1095               10 VALID

1 row selected.

SQL>

LGWR is in turn waiting on the archiver (ARCn) processes, which can be inferred by the wait event “log file switch (archiving needed)” wait event.

An interesting side effect of the current database state is that some monitoring SQL scripts don’t work anymore. While researching blocking scenarios, I usually use the below SQL (for single instance databases), as it visually displays the hierarchy between blocking and blocker sessions. However, when I run it, it just hangs:

SQL> WITH sessions AS
   (SELECT
           sid, blocking_session, row_wait_obj#, sql_id, sql_child_number, event, program
      FROM v$session)
SELECT LPAD(' ', LEVEL ) || sid sid, object_name, event, s.sql_id, s.sql_child_number,
       substr(sql_text,1,55) sql_text, program
  FROM sessions s 
  LEFT OUTER JOIN dba_objects 
       ON (object_id = row_wait_obj#)
  LEFT OUTER JOIN v$sql sq on (s.sql_id = sq.sql_id and sq.child_number = s.sql_child_number)       
 WHERE sid IN (SELECT blocking_session FROM sessions)
    OR blocking_session IS NOT NULL
 CONNECT BY PRIOR sid = blocking_session
 START WITH blocking_session IS NULL; 


<<-- SQL hangs

The problem is that the table transformation with subquery factoring (= the WITH clause) causes the resultset to be materialized, and thus it’s gets blocked. It’s similar to using the “/*+materialize*/” hint. As a workaround we can instruct Oracle to not materialize the resultset in the WITH subquery by using the /*+inline*/ hint. After doing that, we get the result:

SQL> WITH sessions AS
   (SELECT /*+inline*/
           sid, blocking_session, row_wait_obj#, sql_id, sql_child_number, event, program
      FROM v$session)
SELECT LPAD(' ', LEVEL ) || sid sid, object_name, event, s.sql_id, s.sql_child_number,
       substr(sql_text,1,55) sql_text, program
  FROM sessions s 
  LEFT OUTER JOIN dba_objects 
       ON (object_id = row_wait_obj#)
  LEFT OUTER JOIN v$sql sq on (s.sql_id = sq.sql_id and sq.child_number = s.sql_child_number)       
 WHERE sid IN (SELECT blocking_session FROM sessions)
    OR blocking_session IS NOT NULL
 CONNECT BY PRIOR sid = blocking_session
 START WITH blocking_session IS NULL; 




SID        OBJECT_NAME      EVENT                                    SQL_ID          CH# SQL_TEXT                                                PROGRAM
---------- ---------------- ---------------------------------------- ------------- ----- ------------------------------------------------------- ----------------------------------------
 10                         rdbms ipc message                                          0                                                         oracle@hol.localdomain (LGWR)
  13                        log file switch (archiving needed)                                                                                   oracle@hol.localdomain (W000)
  31                        log file switch (archiving needed)                                                                                   oracle@hol.localdomain (W003)
  34                        log file switch (archiving needed)       7t74hdvmxrdn6     0 INSERT INTO T2 SELECT * FROM T2                         sqlplus@hol.localdomain (TNS V1-V3)
  43                        log file switch (archiving needed)                                                                                   oracle@hol.localdomain (W007)
  248      C_OBJ#           log file switch (archiving needed)       9wncfacx0nj9h     0 insert into smon_scn_time (thread, time_mp, time_dp, sc oracle@hol.localdomain (SMON)
  254                       log file switch (archiving needed)       g4gp07gt2z920     0 update sys.scheduler$_job set  last_start_date = :1, ru oracle@hol.localdomain (J002)
   15      SCHEDULER$_JOB   buffer busy waits                        g4gp07gt2z920     0 update sys.scheduler$_job set  last_start_date = :1, ru oracle@hol.localdomain (J003)
  261                       log file switch (archiving needed)                                                                                   oracle@hol.localdomain (W002)
  264                       log file switch (archiving needed)       g4gp07gt2z920     0 update sys.scheduler$_job set  last_start_date = :1, ru oracle@hol.localdomain (J000)
   282     SCHEDULER$_JOB   buffer busy waits                        g4gp07gt2z920     0 update sys.scheduler$_job set  last_start_date = :1, ru oracle@hol.localdomain (J001)
  265                       log file switch (archiving needed)                                                                                   oracle@hol.localdomain (W004)
  269                       log file switch (archiving needed)                                                                                   oracle@hol.localdomain (W001)
  271                       log file switch (archiving needed)                                                                                   oracle@hol.localdomain (W005)
  278                       log file switch (archiving needed)                                                                                   oracle@hol.localdomain (W006)
  283                       log file switch (archiving needed)       fz15hxcj83qzk     0 INSERT INTO T1 SELECT * FROM T1 WHERE ROWNUM <= 100     sqlplus@hol.localdomain (TNS V1-V3)

16 rows selected.

SQL>

SID=10 belongs to the logwriter process, which is in turn blocking quite a few other sessions. We can also see that SID=34 (the one inserting in an infinite loop) is trying to execute “INSERT INTO T2 SELECT * FROM T2”. More important, SID=283 is a blocked “sqlplus / as sysdba” login attempt, and it’s trying to execute the SQL “INSERT INTO T1 SELECT * FROM T1 WHERE ROWNUM <= 100” from the trigger. Knowing the blocked SQL text could give us a clue about the root cause of the issue. Unfortunately there’s no information in v$sql or v$session about the PL/SQL object (trigger) that the SQL is being called from:

SQL> select PLSQL_ENTRY_OBJECT_ID, PLSQL_ENTRY_SUBPROGRAM_ID,PLSQL_OBJECT_ID,PLSQL_SUBPROGRAM_ID
FROM   v$session
WHERE  sid = 283;
  2    3
PLSQL_ENTRY_OBJECT_ID PLSQL_ENTRY_SUBPROGRAM_ID PLSQL_OBJECT_ID PLSQL_SUBPROGRAM_ID
--------------------- ------------------------- --------------- -------------------


1 row selected.

SQL>

SQL> select PROGRAM_ID, PROGRAM_LINE#
  from   v$sql
 where  sql_id = 'fz15hxcj83qzk';
  
PROGRAM_ID PROGRAM_LINE#
---------- -------------
         0             2

1 row selected.

SQL> select owner, object_name
  from   dba_objects
 where  object_id = 0;
  2    3
no rows selected

SQL>

Another way to check the issue could be to use Tanel Poder’s ash_wait_chains script, which uses Active Session History (ASH) to show the whole chain of waiters and (final) blockers. This can be especially useful in case the blocking/waiting scenario is already resolved, and we’re researching the issue after the fact:

SQL> @ash/ash_wait_chains session_id||':'||event2||sql_opname session_id=34 sysdate-1/24/60 sysdate

-- Display ASH Wait Chain Signatures script v0.6 BETA by Tanel Poder ( http://blog.tanelpoder.com )

%This     SECONDS        AAS #Blkrs WAIT_CHAIN                                                                                                                                                                                                                                                                                                   FIRST_SEEN          LAST_SEEN
------ ---------- ---------- ------ ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ ------------------- -------------------
  97%          56         .9      1 -> 34:log file switch (archiving needed) INSERT -> [idle blocker 1,10,46017 (oracle@hol.localdomain (LGWR))]                                                                                                                                                                                                 2022-08-22 16:15:00 2022-08-22 16:15:59
   2%           1          0      1 -> 34:log file switch (archiving needed) INSERT -> 10:LGWR all worker groups  -> [idle blocker 1,11,19550 (oracle@hol.localdomain (LG00))]                                                                                                                                                                   2022-08-22 16:15:03 2022-08-22 16:15:03
   2%           1          0      1 -> 34:log file switch (archiving needed) INSERT -> 10:ON CPU                                                                                                                                                                                                                                                 2022-08-22 16:15:04 2022-08-22 16:15:04

3 rows selected.

SQL>

LGWR is again shown as the blocker of our session SID=34.

More advanced research techniques

Let’s assume we don’t know the issue was related to the logon trigger – we just got alerted about a FRA full situation, checked the alert log, and can’t login to the database with sqlplus or rman. As the database seems hung, we can follow the advice from the MOS note “SRDC – How to Collect Standard Information for a Database Hang (Doc ID 1594905.1)“. A preliminary sqlplus connection can be created, and we could run the “oradebug hanganalyze” command giving us more clues about the cause of the blocking scenario.

Following the advice in the MOS document, I attach to an existing instance’s process with oradebug. Even though the note says to attach to PMON/SMON process, I’ll try to stay away from critical background processes if possible, as crashing them will bring the whole instance down. Instead I’ll connect to the MMON process, and try to execute the hanganalyze command:

[oracle@hol ~]$ ps -ef |grep mmon
oracle   32221     1  0 16:57 ?        00:00:03 ora_mmon_orcl


[oracle@hol ~]$ sqlplus -prelim / as sysdba

SQL*Plus: Release 19.0.0.0.0 - Production on Mon Aug 22 20:55:31 2022
Version 19.5.0.0.0

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

SQL> oradebug setospid 32221
Oracle pid: 28, Unix process pid: 32221, image: oracle@hol.localdomain (MMON)
SQL> oradebug tracefile_name
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_mmon_32221.trc
SQL> oradebug hanganalyze 3
Statement processed.
SQL> exit
Disconnected from ORACLE
[oracle@hol ~]$

Checking the orcl_mmon_32221.trc trace and the session’s trace file, there’s unfortunately no hanganalyze information. That’s the issue which was mentioned the above MOS document, and which is the very reason we’re attaching to a process with an already established session context. The reason for this behavior, a workaround, and an explanation about preliminary connections is available in this Tanel Poder’s post.

Repeating the above steps, but this time using “oradebug dump hanganalyze 3″, we get a usable hanganalyze file:

$ sqlplus -prelim / as sysdba
SQL> oradebug setospid 32221
SQL> oradebug tracefile_name
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_mmon_32221.trc
SQL> oradebug dump hanganalyze 3
Statement processed.
SQL>

This MOS note provides more information on how to interpret the trace file: Interpreting HANGANALYZE Trace Files to Diagnose Hanging and Performance Problems for 9i and 10g. (Doc ID 215858.1). Inspecting the orcl_mmon_32221.trc file, we can search for the SID indicated as “LEAF” (or LEAF_NW, meaning “LEAF not in a wait”, so on CPU), as those indicate the final blocker. It’s SID=10:

State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[9]/1/10/46017/0x7f57f018/20115/LEAF/

As we’re interested in our PID=1767/SID=283 (remember we found those two in the listings above), we can search the trace file for that process. It’s in lines 7 and 9 in the below snippet:

-------------------------------------------------------------------------------
Chain 13:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (orcl.orcl)
                   os id: 1767
              process id: 37, oracle@hol.localdomain (TNS V1-V3)
              session id: 283
        session serial #: 55959
             module name: 0 (sqlplus@hol.localdomain (TNS V1-V3))
    }
    is waiting for 'log file switch (archiving needed)' with wait info:
    {
            time in wait: 1 min 40 sec (last interval)
            time in wait: 234 min 15 sec (total)
           timeout after: never
                 wait id: 6
                blocking: 0 sessions
          current sql_id: 4018450667
            wait history:
              * time between current wait and wait #1: 0.000000 sec
              1.       event: 'latch free'
                 time waited: 0.000191 sec
                     wait id: 187              p1: 'address'=0x7f353c20
                                               p2: 'number'=0x3
                                               p3: 'why'=0x23
              * time between wait #1 and #2: 0.000000 sec
              2.       event: 'log file switch (archiving needed)'
                 time waited: 7.664251 sec (last interval)
                 time waited: 232 min 35 sec (total)
                     wait id: 6
              * time between wait #2 and #3: 0.000000 sec
              3.       event: 'latch: redo writing'
                 time waited: 0.000156 sec
                     wait id: 186              p1: 'address'=0x6006d480
                                               p2: 'number'=0x16f
                                               p3: 'why'=0x10
    }
    and is blocked by 'instance: 1, os id: 20115, session id: 10',
    which is a member of 'Chain 1'.

Chain 13 Signature: 'rdbms ipc message'<='log file switch (archiving needed)'
Chain 13 Signature Hash: 0xfc07a352

“is blocked by ‘instance: 1, os id: 20115, session id: 10’, which is a member of ‘Chain 1’.” indicates the blocker, that’s the LGWR process:

=> Oracle session identified by:
   {
               instance: 1 (orcl.orcl)
                  os id: 20115
             process id: 20, oracle@hol.localdomain (LGWR)
             session id: 10
       session serial #: 46017

What we can’t see in the above trace is the SQL text our blocked sqlplus session is waiting to execute – there’s “current sql_id: 4018450667”, but no SQL text. Usually the sql_id line in trace file is followed by the SQL text and “short stack” lines, but in this case it’s missing.  One option to obtain more information is to repeat the steps of logging in with a preliminary connection and execute a systemstate dump with “oradebug dump systemstate 258”, though on systems with large shared memory structures, the produced tracefiles can be very large. Instead of a systemstate dump, we can opt for a more contained and focused dump, and thus generate a processtate dump, which limits the output to just the targeted process, or even only run “oradebug dump errorstack 3”:

$ sqlplus -prelim / as sysdba
SQL> oradebug setospid 1767  <<-- OSPID of our blocked sqlplus session
Oracle pid: 37, Unix process pid: 1767, image: oracle@hol.localdomain (TNS V1-V3)
SQL> oradebug tracefile_name
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_1767.trc
SQL> oradebug dump processstate 10
Statement processed.
(optionally also):
SQL> oradebug dump errorstack 3

If looking at the process state dump file, search for “Session Cursor Dump” (if looking at the systemstate dump, we first have to locate the State Object for the process 1767). The currently executing cursor is “Current cursor: 2”:

----- Session Cursor Dump -----
Current cursor: 2, pgadep=2

Searching the trace file for the text “Cursor#2”, the SQL which the session is trying to execute is:

ObjectName:  Name=INSERT INTO T1 SELECT * FROM T1 WHERE ROWNUM <= 100

Scrolling down the trace file, there’s a section with a more user-readable format:

SQL Information
user_id=107 user_name=U1 module=sqlplus@hol.localdomain (TNS V1-V3) action=
sql_id=fz15hxcj83qzk plan_hash_value=-458591652 problem_type=0 command_type=2
----- Current SQL Statement for this session (sql_id=fz15hxcj83qzk) -----
INSERT INTO T1 SELECT * FROM T1 WHERE ROWNUM <= 100
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x71d4c6e8         2  anonymous block
sql_text_length=52
sql=INSERT INTO T1 SELECT * FROM T1 WHERE ROWNUM <= 100

The SQL is being executed from an anonymous block, so we don’t see a direct connection with the U1.TRG trigger. Checking the trace file for the reported “object handle=0x71d4c6e8” (line 10 above), there’s a clue in the below excerpt:

        ObjectName:  Name=begin
  insert into t1 select * from t1 where rownum <= 100;
end; 
          FullHashValue=3c74be99dd87d9064bd57f96bbed98a1 Namespace=SQL AREA(00) Type=CURSOR(00) ContainerId=0 ContainerUid=0 Identifier=3152910497 OwnerIdn=107 
        Statistics:  InvalidationCount=1 ExecutionCount=22 LoadCount=3 ActiveLocks=1 TotalLockCount=22 TotalPinCount=1 
        Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=1 Version=0 BucketInUse=21 HandleInUse=21 HandleReferenceCount=0 
        Concurrency:  DependencyMutex=0x6ff6aff0(0, 2, 0, 0) Mutex=0x6ff6b090(0, 151, 0, 0) 
        Flags=RON/PIN/TIM/PN0/DBN/[10012841] Flags2=[0000] 
        WaitersLists:  
          Lock=0x6ff6afd0[0x6ff6afd0,0x6ff6afd0] 
          Pin=0x6ff6afb0[0x6ff6afb0,0x6ff6afb0] 
          LoadLock=0x6ff6b028[0x6ff6b028,0x6ff6b028] 
        Timestamp:  Current=08-22-2022 15:30:59 
        HandleReference:  Address=0x6ff6b148 Handle=(nil) Flags=[00] 
        LibraryObject:  Address=0x71d4c9c8 HeapMask=0000-0001-0001-0000 Flags=EXS[0000] Flags2=[0000] Flags3=[0000] PublicFlags=[0000] 
          ChildTable:  size='16' 
            Child:  id='0' Table=0x71d4d840 Reference=0x71d4d318 Handle=0x71d4c6e8 
        NamespaceDump:  
          Parent Cursor:  sql_id=4rpbzkuxyv651 parent=0x71d4ca98 maxchild=1 plk=y ppn=n prsfcnt=0 obscnt=0

Line 17 reports “Handle=0x71d4c6e8” as a “Child” for the state object in lines 1-3, which is the actual body of the trigger. That could give us clues for further research of the INSERT statement origin, as the whole trigger body is printed. In a “real” trigger there would probably be more code than just a simple INSERT, possibly even with comments. But again, there’s no direct connection to the U1.TRG state object.

For completeness – there actually is a state object for the U1.TRG trigger in the tracefile, though I couldn’t find a connection leading from the above PL/SQL block to the trigger’s state object.

Conclusion

In specific situations, after logon triggers can block all users from creating a session, and thus care has to be taken when implementing or deploying them. The research techniques presented above post can hopefully be useful to the reader when diagnosing similar, or even different, issues.