说明
最近遇到一次OGG SQL error 1400 mapping SOURCE.FJJ_TAB1 to TARGET.FJJ_TAB1 OCI Error ORA-01400: cannot insert NULL 导致OGG REPLICATE ABENDED的问题，相关表近期未做DDL,进程配置了参置HandleCollisions，正文为该问题的模拟
报错信息
2020-05-13 10:04:44 WARNING OGG-01154 SQL error 1400 mapping SOURCE.FJJ_TAB1 to TARGET.FJJ_TAB1 OCI Error ORA-01400: cannot insert NULL int
o ("TARGET"."FJJ_TAB1"."C2") (status = 1400), SQL <INSERT INTO "TARGET"."FJJ_TAB1" ("ID","C1") VALUES (:a0,:a1)>.
Source Context :
SourceModule : [er.replicat.errors]
SourceID : [/scratch/aime/adestore/views/aime_adc00jza/oggcore/OpenSys/src/app/er/replicat/reperrors.cpp]
SourceMethod : [repError]
SourceLine : [1680]
ThreadBacktrace : [15] elements
: [_ZN3ggs5gglib14MultiThreading6Thread9RunThreadEPNS2_10ThreadArgsE]
: [/home/oracle/ggs/replicat(ggs::gglib::MultiThreading::Thread::RunThread(ggs::gglib::MultiThreading::Thread::Thre
adArgs*))]
2020-05-13 10:04:44 ERROR OGG-01296 Error mapping from SOURCE.FJJ_TAB1 to TARGET.FJJ_TAB1.
Reading /home/oracle/ggs/dirdat/e3000000001, current RBA 2437, 4 records, m_file_seqno = 1, m_file_rba = 2437
问题重现
SQL> alter database add supplemental log data;
Database altered.
---源目标为同一个库，表fjj_tab1，从用户source，复制到用户target中
SQL> create user source identified by source default tablespace users;
User created.
SQL> grant dba to source;
Grant succeeded.
SQL> create user target identified by target default tablespace users;
User created.
SQL> grant dba to target;
Grant succeeded.
SQL> create table source.fjj_tab1(id number,c1 varchar2(20),c2 varchar2(20),primary key(id));
Table created.
SQL> create table target.fjj_tab1(id number,c1 varchar2(20),c2 varchar2(20),primary key(id));
Table created.
[oracle@db1 ~]$ ggsci
GGSCI (db1) 1> dblogin userid ggs,password ggs
Successfully logged into database.
GGSCI (testa as ggs@testa) 19> add trandata source.fjj_tab1
2020-05-13 09:25:32 INFO OGG-15132 Logging of supplemental redo data enabled for table SOURCE.FJJ_TAB1.
2020-05-13 09:25:32 INFO OGG-15133 TRANDATA for scheduling columns has been added on table SOURCE.FJJ_TAB1.
2020-05-13 09:25:32 INFO OGG-15135 TRANDATA for instantiation CSN has been added on table SOURCE.FJJ_TAB1.
GGSCI (testa as ggs@testa) 20> info trandata source.fjj_tab1
Logging of supplemental redo log data is enabled for table SOURCE.FJJ_TAB1.
Columns supplementally logged for table SOURCE.FJJ_TAB1: "ID".
Prepared CSN for table SOURCE.FJJ_TAB1: 1750476
---编辑抽取进程e_test3的参数
edit param e_test3
extract e_test3
setenv (NLS_LANG="AMERICAN_AMERICA.ZHS16GBK")
USERID ggs, password ggs
exttrail ./dirdat/e3, FORMAT RELEASE 12.2
TRANLOGOPTIONS LOGRETENTION DISABLED
FETCHOPTIONS NOUSESNAPSHOT
BR BRINTERVAL 30M
REPORTCOUNT EVERY 30 MINUTES, RATE
FETCHOPTIONS FETCHPKUPDATECOLS
dynamicresolution
GETUPDATEBEFORES
NOCOMPRESSUPDATES
NOCOMPRESSDELETES
table source.fjj_tab1;
----创建抽取进程e_test3
add extract e_test3,tranlog,begin now
---创建抽取进程e_test3的trail文件,e_test3抽取的数据会写到这个文件中，MEGABYTES 10限制文件大小为10M
add exttrail ./dirdat/e3,extract e_test3 MEGABYTES 10
--启动抽取进程e_test3
start e_test3
---编辑replicat进程的参数
EDIT PARAMS r_test3
REPLICAT r_test3
userid ggs,password ggs
MaxDiscardRecs 10
REPERROR DEFAULT ABEND
--DBOPTIONS DEFERREFCONST
DBOPTIONS NOSUPPRESSTRIGGERS
--GetUpdateBefores
AllowNoopUpdates
ASSUMETARGETDEFS
CHECKSEQUENCEVALUE
Insertmissingupdates
HandleCollisions
GETTRUNCATES
BatchSQL
MAP source.fjj_tab1, TARGET target.fjj_tab1;
---创建replicat进程
ADD REPLICAT r_test3,EXTTRAIL ./dirdat/e3,checkpointtable ggs.checkpoint_tab
insert into source.fjj_tab1 values (1,'c1','c2');
commit;
SQL> select * from target.fjj_tab1;
ID C1 C2
---------- -------------------- --------------------
1 c1 c2
SQL> delete target.fjj_tab1 where id=1;
1 row deleted.
SQL> commit;
Commit complete.
SQL> update source.fjj_tab1 set c1='20200513' where id=1;
1 row updated.
SQL>
SQL> commit;
Commit complete.
SQL> select * from source.fjj_tab1;
ID C1 C2
---------- -------------------- --------------------
1 20200513 c2
SQL> select * from target.fjj_tab1;
ID C1 C2
---------- -------------------- --------------------
1 20200513 <<<<<
SQL> alter table source.fjj_tab1 modify c2 not null;
Table altered.
SQL> alter table target.fjj_tab1 modify c2 not null;
alter table target.fjj_tab1 modify c2 not null
*
ERROR at line 1:
ORA-02296: cannot enable (TARGET.) - null values found
SQL> delete target.fjj_tab1;
1 row deleted.
SQL> commit;
Commit complete.
SQL> alter table target.fjj_tab1 modify c2 not null;
Table altered.
SQL> update source.fjj_tab1 set c1='20200513-2' where id=1;
1 row updated.
SQL>
SQL> commit;
Commit complete.
GGSCI (testa as ggs@testa) 52> info all
Program Status Group Lag at Chkpt Time Since Chkpt
MANAGER RUNNING
EXTRACT RUNNING E_TEST3 00:00:00 00:00:06
REPLICAT ABENDED R_TEST3 00:00:00 00:00:43
2020-05-13 10:04:44 WARNING OGG-00869 Aborting BATCHSQL transaction. Detected inconsistent result: executed 1 operations in batch, resultin
g in 0 affected rows.
2020-05-13 10:04:44 WARNING OGG-01137 BATCHSQL suspended, continuing in normal mode.
2020-05-13 10:04:44 WARNING OGG-01003 Repositioning to rba 2308 in seqno 1.
2020-05-13 10:04:44 WARNING OGG-01004 Aborted grouped transaction on TARGET.FJJ_TAB1, Database error 1400 (OCI Error ORA-01400: cannot inse
rt NULL into ("TARGET"."FJJ_TAB1"."C2") (status = 1400), SQL <INSERT INTO "TARGET"."FJJ_TAB1" ("ID","C1") VALUES (:a0,:a1)>).
2020-05-13 10:04:44 WARNING OGG-01003 Repositioning to rba 2308 in seqno 1.
2020-05-13 10:04:44 WARNING OGG-01154 SQL error 1400 mapping SOURCE.FJJ_TAB1 to TARGET.FJJ_TAB1 OCI Error ORA-01400: cannot insert NULL int
o ("TARGET"."FJJ_TAB1"."C2") (status = 1400), SQL <INSERT INTO "TARGET"."FJJ_TAB1" ("ID","C1") VALUES (:a0,:a1)>.
Source Context :
SourceModule : [er.replicat.errors]
SourceID : [/scratch/aime/adestore/views/aime_adc00jza/oggcore/OpenSys/src/app/er/replicat/reperrors.cpp]
SourceMethod : [repError]
SourceLine : [1680]
ThreadBacktrace : [15] elements
: [_ZN3ggs5gglib14MultiThreading6Thread9RunThreadEPNS2_10ThreadArgsE]
: [/home/oracle/ggs/replicat(ggs::gglib::MultiThreading::Thread::RunThread(ggs::gglib::MultiThreading::Thread::Thre
adArgs*))]
...skipping one line
]
: [/home/oracle/ggs/replicat(ggs::er::ReplicatContext::repError(short, int, char const*, extr_ptr_def*, ggs::gglib:
:gglcr::CommonLCR const*, std_rec_hdr_def*, char*, ObjectMetadata*, bool))]
: [/home/oracle/ggs/replicat()]
: [/home/oracle/ggs/replicat(ggs::er::ReplicatContext::processRecord(ggs::gglib::gglcr::CommonLCR const*, ggs::ggli
b::gglcr::CommonLCR*, extr_ptr_def*&, extr_ptr_def*&, bool&, int&, bool, RepCsn&))]
: [/home/oracle/ggs/replicat(ggs::gglib::MultiThreading::MainThread::Run(int, char**))]
: [/lib64/libc.so.6(__libc_start_main)]
: [/home/oracle/ggs/replicat()]
: [/home/oracle/ggs/replicat(ggs::gglib::MultiThreading::MainThread::Run(int, char**))]
: [/home/oracle/ggs/replicat(ggs::gglib::MultiThreading::Thread::RunThread(ggs::gglib::MultiThreading::Thread::Thre
adArgs*))]
: [/home/oracle/ggs/replicat(ggs::gglib::MultiThreading::MainThread::Run(int, char**))]
: [/home/oracle/ggs/replicat()]
: [/lib64/libc.so.6(__libc_start_main)]
: [/home/oracle/ggs/replicat()]
2020-05-13 10:04:44 ERROR OGG-01296 Error mapping from SOURCE.FJJ_TAB1 to TARGET.FJJ_TAB1.
Reading /home/oracle/ggs/dirdat/e3000000001, current RBA 2437, 4 records, m_file_seqno = 1, m_file_rba = 2437
Report at 2020-05-13 10:04:44 (activity since 2020-05-13 09:58:03)
问题分析
2020-05-13 10:04:44 WARNING OGG-01154 SQL error 1400 mapping SOURCE.FJJ_TAB1 to TARGET.FJJ_TAB1 OCI Error ORA-01400: cannot insert NULL int
o (“TARGET”.“FJJ_TAB1”.“C2”) (status = 1400), SQL <INSERT INTO “TARGET”.“FJJ_TAB1” (“ID”,“C1”) VALUES (:a0,:a1)>.
1、源目标表结构相同，NOT NULL的列相同
2、源表，目标表为3列，其中ID为主键，C2 NOT NULL，为什么产生了INSERT (“ID”,“C1”)两列的INSERT
3、logdump trail报错记录
Logdump 1 >open /home/oracle/ggs/dirdat/e3000000001
Current LogTrail is /home/oracle/ggs/dirdat/e3000000001
Logdump 2 >detail on
Logdump 3 >ghdr on
Logdump 4 >pos 2437
Reading forward from RBA 2437
Logdump 5 >n
Hdr-Ind : E (x45) Partition : . (x0c)
UndoFlag : . (x00) BeforeAfter: A (x41)
RecLength : 27 (x001b) IO Time : 2020/05/13 10:04:41.000.000
IOType : 15 (x0f) OrigNode : 255 (xff)
TransInd : . (x02) FormatType : R (x52)
SyskeyLen : 0 (x00) Incomplete : . (x00)
AuditRBA : 64 AuditPos : 5940240
Continued : N (x00) RecCount : 1 (x01)
2020/05/13 10:04:41.000.000 FieldComp Len 27 RBA 2437 <<<<记录类型为FieldComp
Name: SOURCE.FJJ_TAB1 (TDR Index: 1)
After Image: Partition 12 G e
0000 0005 0000 0001 3100 0100 0e00 0000 0a32 3032 | …1…202
3030 3531 332d 32 | 00513-2
Column 0 (x0000), Len 5 (x0005)
Column 1 (x0001), Len 14 (x000e) <<<<源库有3列，trail文件中2列。
**该问题是由于update的记录，目标不存在（根据保留周期已清理，或其它原因),
当replicate配置了HandleCollisions,UPDATE的目标记录不存在时，会转换为INSERT,但trail中只主键及更新列的数据，导致了ORA-01400: cannot insert NULL
**
临时解决，跑过报错记录
SQL> insert into source.fjj_tab1 values (2,'d1','d1');
1 row created.
SQL> commit;
Commit complete.
Logdump 6 >n
___________________________________________________________________
Hdr-Ind : E (x45) Partition : . (x0c)
UndoFlag : . (x00) BeforeAfter: A (x41)
RecLength : 29 (x001d) IO Time : 2020/05/13 10:11:02.000.000
IOType : 5 (x05) OrigNode : 255 (xff)
TransInd : . (x03) FormatType : R (x52)
SyskeyLen : 0 (x00) Incomplete : . (x00)
AuditRBA : 64 AuditPos : 6178832
Continued : N (x00) RecCount : 1 (x01)
2020/05/13 10:11:02.000.000 Insert Len 29 RBA 2544
Name: SOURCE.FJJ_TAB1 (TDR Index: 1)
After Image: Partition 12 G s
0000 0005 0000 0001 3200 0100 0600 0000 0264 3100 | ........2........d1.
0200 0600 0000 0264 31 | .......d1
Column 0 (x0000), Len 5 (x0005)
Column 1 (x0001), Len 6 (x0006)
Column 2 (x0002), Len 6 (x0006)
GGSCI (testa as ggs@testa) 64> alter R_TEST3,EXTSEQNO 1, EXTRBA 2544
2020-05-13 10:12:34 INFO OGG-06594 Replicat R_TEST3 has been altered. Even the start up position might be updated, duplicate suppression remains active in next startup. To override duplicate suppression, start R_TEST3 with NOFILTERDUPTRANSACTIONS option.
REPLICAT altered.
GGSCI (testa as ggs@testa) 65> info all
Program Status Group Lag at Chkpt Time Since Chkpt
MANAGER RUNNING
EXTRACT RUNNING E_TEST3 00:00:00 00:00:06
REPLICAT STOPPED R_TEST3 00:00:00 00:00:39
GGSCI (testa as ggs@testa) 66> start R_TEST3
Sending START request to MANAGER ...
REPLICAT R_TEST3 starting
GGSCI (testa as ggs@testa) 68> stats R_TEST3
Sending STATS request to REPLICAT R_TEST3 ...
Start of Statistics at 2020-05-13 10:13:35.
Replicating from SOURCE.FJJ_TAB1 to TARGET.FJJ_TAB1:
*** Total statistics since 2020-05-13 10:13:22 ***
Total inserts 1.00
Total updates 0.00
Total deletes 0.00
Total discards 0.00
Total operations 1.00
*** Daily statistics since 2020-05-13 10:13:22 ***
Total inserts 1.00
Total updates 0.00
Total deletes 0.00
Total discards 0.00
Total operations 1.00
*** Hourly statistics since 2020-05-13 10:13:22 ***
Total inserts 1.00
Total updates 0.00
Total deletes 0.00
Total discards 0.00
Total operations 1.00
*** Latest statistics since 2020-05-13 10:13:22 ***
Total inserts 1.00
Total updates 0.00
Total deletes 0.00
Total discards 0.00
Total operations 1.00
End of Statistics.
GGSCI (testa as ggs@testa) 69> info all
Program Status Group Lag at Chkpt Time Since Chkpt
MANAGER RUNNING
EXTRACT RUNNING E_TEST3 00:00:00 00:00:06
REPLICAT RUNNING R_TEST3 00:00:00 00:00:07
SQL> select * from target.fjj_tab1;
ID C1 C2
---------- -------------------- --------------------
2 d1 d1
尝试修改参数，解决该问题(未解决)
GGSCI (testa as ggs@testa) 72> stop E_TEST3
Sending STOP request to EXTRACT E_TEST3 ...
Request processed.
extract 参数
FETCHOPTIONS FETCHPKUPDATECOLS
12.2以后应配置为
LOGALLSUPCOLS
UPDATERECORDFORMAT FULL
SQL> update source.fjj_tab1 set c1='20200513-3' where id=1;
1 row updated.
SQL> commit;
Commit complete.
----可以看到UPDATERECORDFORMAT FULL之后，仍然会不能解决
SQL> select * from target.fjj_tab1;
ID C1 C2
---------- -------------------- --------------------
2 d1 d1
GGSCI (testa as ggs@testa) 78> info all
Program Status Group Lag at Chkpt Time Since Chkpt
MANAGER RUNNING
EXTRACT RUNNING E_TEST3 00:00:00 00:00:09
REPLICAT ABENDED R_TEST3 00:00:00 00:00:25
---去掉参数也不能解决
Insertmissingupdates
add supplemental all columns，虽然这样可以解决问题，但如果UPDATE频繁，会明显增加日志量
GGSCI (testa as ggs@testa) 97> stop E_TEST3
Sending STOP request to EXTRACT E_TEST3 …
Request processed.
GGSCI (testa as ggs@testa) 98> delete trandata source.fjj_tab1
2020-05-13 10:25:45 INFO OGG-15142 Logging of supplemental redo log data disabled for table SOURCE.FJJ_TAB1.
2020-05-13 10:25:45 INFO OGG-15139 TRANDATA for scheduling columns has been disabled on table SOURCE.FJJ_TAB1.
GGSCI (testa as ggs@testa) 104> ADD TRANDATA source.fjj_tab1 ALLCOLS
2020-05-13 10:27:27 INFO OGG-15132 Logging of supplemental redo data enabled for table SOURCE.FJJ_TAB1.
2020-05-13 10:27:27 INFO OGG-15133 TRANDATA for scheduling columns has been added on table SOURCE.FJJ_TAB1.
2020-05-13 10:27:27 INFO OGG-15134 TRANDATA for all columns has been added on table SOURCE.FJJ_TAB1.
2020-05-13 10:27:27 INFO OGG-15135 TRANDATA for instantiation CSN has been added on table SOURCE.FJJ_TAB1.
GGSCI (testa as ggs@testa) 105> info TRANDATA source.fjj_tab1
Logging of supplemental redo log data is enabled for table SOURCE.FJJ_TAB1.
All columns supplementally logged for table SOURCE.FJJ_TAB1.
Prepared CSN for table SOURCE.FJJ_TAB1: 1755578
GGSCI (testa as ggs@testa) 107> start E_TEST3
Sending START request to MANAGER …
EXTRACT E_TEST3 starting
SQL> update source.fjj_tab1 set c1=‘20200513-4’ where id=1;
1 row updated.
SQL> commit;
Commit complete.
GGSCI (testa as ggs@testa) 113> alter R_TEST3,EXTSEQNO 3, EXTRBA 0
2020-05-13 10:30:23 INFO OGG-06594 Replicat R_TEST3 has been altered. Even the start up position might be updated, duplicate suppression remains active in next startup. To override duplicate suppression, start R_TEST3 with NOFILTERDUPTRANSACTIONS option.
REPLICAT altered.
GGSCI (testa as ggs@testa) 114>
GGSCI (testa as ggs@testa) 114> start R_TEST3
Sending START request to MANAGER …
REPLICAT R_TEST3 starting
SQL> select * from target.fjj_tab1;
ID C1 C2
2 d1 d1
1 20200513-4 c2 <<<<<可以看到正常复制过来了，update转成了INSERT
REPERROR 1400 DISCARD 跳过错误，解决
----如果想忽略该问题，可以配置跳过，写入DISCARD
REPERROR 1400 DISCARD
OR
REPERROR DEFAULT DISCARD
GGSCI (testa as ggs@testa) 183> stats R_TEST3
Sending STATS request to REPLICAT R_TEST3 ...
Start of Statistics at 2020-05-13 10:53:58.
Replicating from SOURCE.FJJ_TAB1 to TARGET.FJJ_TAB1:
*** Total statistics since 2020-05-13 10:53:47 ***
Total inserts 0.00
Total updates 0.00
Total deletes 0.00
Total discards 1.00 <<<<
Total operations 0.00
[oracle@testa dirrpt]$ cat R_TEST3.dsc
Oracle GoldenGate Delivery for Oracle process started, group R_TEST3 discard file opened: 2020-05-13 10:53:47.415965
Current time: 2020-05-13 10:53:47
OCI Error ORA-01400: cannot insert NULL into ("TARGET"."FJJ_TAB1"."C2") (status = 1400), SQL <INSERT INTO "TARGET"."FJJ_TAB1" ("ID","C1") VALUES (:a2,:a3)> <<<<
Operation failed at seqno 5 rba 1944
Discarding record on action DISCARD on error 1400 <<<
Problem replicating SOURCE.FJJ_TAB1 to TARGET.FJJ_TAB1 <<<<
Mapping problem with unified update record (target format)...
*
ID = 1
000000: 31 |1 |
C1 = 20200513-5
000000: 32 30 32 30 30 35 31 33 2d 35 |20200513-5 |
ID = 1
000000: 31 |1 |
C1 = 20200513-5
000000: 32 30 32 30 30 35 31 33 2d 35 |20200513-5 |
总结
该问题是由于update的记录，目标不存在（根据保留周期已清理，或其它原因),
当replicate配置了HandleCollisions,UPDATE的目标记录不存在时，会转换为INSERT,但trail中只主键及更新列的数据，导致了ORA-01400: cannot insert NULL
解决方法
1、add supplemental all columns，虽然这样可以解决问题，但如果UPDATE频繁，会明显增加日志量
2、如果想忽略该问题，可以配置跳过，写入DISCARD
REPERROR 1400 DISCARD
OR
REPERROR DEFAULT DISCARD
