10046 trace buggy with deferred constraints

From: Henry Poras <henry_at_itasoftware.com>
Date: Tue, 13 Feb 2007 16:52:16 -0500
Message-ID: <00fa01c74fb9$3a70bf00$3800040a@itasoftware.com>

I turned on tracing to track an application bug and found what looks to be an Oracle bug (though Oracle doesn't think so quite yet). Here is my simple test case. I created a Parent table with two Child tables referencing the parent, Child_imm had a deferred constraint (which was never deferred) and Child_def had an initially deferred constraint. I left the parent table empty in order to generate a FK constraint error (ORA-2291). When I inserted a row into Child_imm, I immediately got the ORA-2291 error. This also appeared in the trace file. When I inserted a row into Child_def, it inserted successfully (as expected). On commit, it rolled_back and gave me the ORA-2291. When I looked at the trace file, however, it looked as though the insert was successful (no error, EXEC for the insert had r=1, and the commit (XCTEND rlbk=0, rd_only=0) succeeded).

I've seen this on 10.1.0.3 and 10.2.0.2 on RedHat (the 10.2 is AS4)

SQL> CREATE TABLE parent (p_id number constraint PARENT_P_ID PRIMARY KEY ) 2 /

Table created.

SQL>
SQL> CREATE TABLE child_imm (c_id number constraint CHILD_IMM_C_ID PRIMARY KEY,
2 c_p_id number constraint FK_P_ID_IMM references parent(p_id) DEFERRABLE)
3 /

Table created.

SQL> CREATE TABLE child_def (c_id number constraint CHILD_DEF_C_ID PRIMARY KEY,
2 c_p_id number constraint FK_P_ID_DEF references parent(p_id) INITIALLY DEFERRED)
3 /

Table created.

SQL> 
SQL> 
SQL> 
SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';

Session altered.

SQL>
SQL> INSERT INTO child_imm VALUES (5,5); INSERT INTO child_imm VALUES (5,5)
*
ERROR at line 1:
ORA-02291: integrity constraint (HENRY.FK_P_ID_IMM) violated - parent key not
found

SQL> COMMIT; Commit complete.

PARSING IN CURSOR #6 len=34 dep=0 uid=28 oct=2 lid=28 tim=1143861822500419 hv=1593902885 ad='784dccc8'
INSERT INTO child_imm VALUES (5,5)
END OF STMT
PARSE
#6:c=10000,e=9049,p=0,cr=4,cu=0,mis=1,r=0,dep=0,og=1,tim=1143861822500407 BINDS #6:

PARSING IN CURSOR #3 len=80 dep=1 uid=0 oct=3 lid=0 tim=1143861822504138 hv=1395529870 ad='7c061ffc'
select o.name, c.name from con$ c, user$ o where c.con# = :1 and owner# = user#
END OF STMT
PARSE
#3:c=10000,e=3092,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1143861822504131 BINDS #3:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=0001 size=24 offset=0

bfp=40a6bbb8 bln=22 avl=04 flg=05
value=26355
EXEC #3:c=0,e=1469,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,tim=1143861822505797 FETCH #3:c=0,e=85,p=0,cr=5,cu=0,mis=0,r=1,dep=1,og=4,tim=1143861822505941 ...
EXEC
#6:c=10000,e=5816,p=0,cr=6,cu=31,mis=0,r=0,dep=0,og=1,tim=1143861822506359 ERROR #6:err=2291 tim=182992045
...

PARSING IN CURSOR #4 len=6 dep=0 uid=28 oct=44 lid=28 tim=1143861822507910 hv=255718823 ad='7d92336c'
COMMIT
END OF STMT
PARSE #4:c=0,e=109,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1143861822507900 XCTEND rlbk=0, rd_only=1
EXEC #4:c=0,e=61,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1143861822508083

SQL> INSERT INTO child_def VALUES (6,6);

1 row created.

SQL> COMMIT;
COMMIT
*
ERROR at line 1:
ORA-02091: transaction rolled back
ORA-02291: integrity constraint (HENRY.FK_P_ID_DEF) violated - parent key not
found

SQL>
SQL> ALTER SESSION SET EVENTS '10046 trace name context off';

Session altered.

SQL>
SQL> exit

PARSING IN CURSOR #5 len=34 dep=0 uid=28 oct=2 lid=28 tim=1143861822510717 hv=3536007002 ad='7c20eee4'
INSERT INTO child_def VALUES (6,6)
END OF STMT
PARSE #5:c=0,e=1803,p=0,cr=1,cu=0,mis=1,r=0,dep=0,og=1,tim=1143861822510705 BINDS #5:
EXEC #5:c=0,e=522,p=0,cr=1,cu=24,mis=0,r=1,dep=0,og=1,tim=1143861822511366 ...

PARSING IN CURSOR #12 len=6 dep=0 uid=28 oct=44 lid=28 tim=1143861822512290 hv=255718823 ad='7d92336c'
COMMIT
END OF STMT

PARSE #12:c=0,e=70,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1143861822512280
XCTEND rlbk=0, rd_only=0


=====================

PARSING IN CURSOR #13 len=80 dep=1 uid=0 oct=3 lid=0 tim=1143861822512555

hv=1395529870 ad='7c061ffc'
select o.name, c.name from con$ c, user$ o where c.con# = :1 and owner# = user#
END OF STMT
PARSE #13:c=0,e=76,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1143861822512549 BINDS #13:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=0001 size=24 offset=0

bfp=409dbd2c bln=22 avl=04 flg=05
value=26357
EXEC #13:c=0,e=181,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1143861822512883 FETCH #13:c=0,e=87,p=0,cr=5,cu=0,mis=0,r=1,dep=1,og=4,tim=1143861822513010 ...

PARSING IN CURSOR #14 len=55 dep=0 uid=28 oct=42 lid=28 tim=1143861822514852 hv=2655499671 ad='7bbc4a6c'
ALTER SESSION SET EVENTS '10046 trace name context off' END OF STMT
PARSE #14:c=0,e=124,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1143861822514842 BINDS #14:
EXEC #14:c=0,e=103,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1143861822515068

Henry

--
http://www.freelists.org/webpage/oracle-l

Received on Tue Feb 13 2007 - 15:52:16 CST