1 repb10进程异常，如下

GGSCI (hostBB) 31> info repb10

REPLICAT repb10 Last Started 2021-03-05 08:39 Status ABENDED

Checkpoint Lag 00:00:04 (updated 15:02:55 ago)

Log Read Checkpoint File ./dirdat/cc149123

2021-03-05 01:43:46.001414 RBA 297156732

2 查看报错信息

2021-03-05 17:14:02 WARNING OGG-00869 OCI Error ORA-01407: cannot update ("fdpuserA"."E_MP_AAA"."ID")

to NULL (status = 1407). UPDATE /*+ RESTRICT_ALL_REF_CONS */ "fdpuserA"."E_MP_AAA" SET "ID" = :a3,"

DATA_DATE" = :a4,"DATA_TYPE" = :a5,"DATA_POINT_FLAG" = :a6,"DATA_WHOLE_FLAG" = :a7,"P1" = :a8,

.....................................

"P83" = :a90,"P84" = :a91,"P85" = :a92,"P86" = :a93,"P87" = :a94,"P88" = :a95,"P89" = :a96,"P90" = :a97,

"P91" = :a98,"P92" = :a99,"P93" = :a100,"P94" = :a101,"P95" = :a102,"P96" = :a103,

"SOURCE_CHANGE_TIME" = :a104,"TARGET_WRITE_TIME" = :a105 WHERE "ID" = :b0 AND

"DATA_DATE" = :b1 AND "DATA_TYPE" = :b2.

2021-03-05 17:14:02 WARNING OGG-01004 Aborted grouped transaction on 'fdpuserA.E_MP_AAA',

Database error 1407 (OCI Error ORA-01407: cannot update ("fdpuserA"."E_MP_AAA"."ID") to NULL (status = 1407).

UPDATE /*+ RESTRICT_ALL_REF_CONS */ "fdpuserA"."E_MP_AAA" SET "ID" = :a3,"DATA_DATE" = :a4,"DATA_TYPE" =

:a5,"DATA_POINT_FLAG" = :a6,"DATA_WHOLE_FLAG" = :a7,"P1" = :a8,"P2" = :a9,"P3" = :a10,"P4" = :a11,"

.。。。。。。。。。。。。。。。。。

P95" = :a102,"P96" = :a103,"SOURCE_CHANGE_TIME" = :a104,"TARGET_WRITE_TIME" = :a105

WHERE "ID" = :b0 AND "DATA_DATE" = :b1 AND "DATA_TYPE" = :b2).

2021-03-05 17:14:02 WARNING OGG-01003 Repositioning to rba 23738948 in seqno 149124.

2021-03-05 17:14:06 WARNING OGG-01154 SQL error 1407 mapping CSMuserB.E_MP_AAA to

fdpuserA.E_MP_AAA OCI Error ORA-01407: cannot update ("fdpuserA"."E_MP_AAA"."ID") to NULL (status = 1407).

UPDATE /*+ RESTRICT_ALL_REF_CONS */ "fdpuserA"."E_MP_AAA" SET "ID" = :a3,"DATA_DATE" = :a4,

"DATA_TYPE" = :a5,"DATA_POINT_FLAG" = :a6,"DATA_WHOLE_FLAG" = :a7,"P1" = :a8,"P2" = :a9,"P3" = :a10,

..................................................................

"P93" = :a100,"P94" = :a101,"P95" = :a102,"P96" = :a103,"SOURCE_CHANGE_TIME" = :a104,

"TARGET_WRITE_TIME" = :a105 WHERE "ID" = :b0 AND "DATA_DATE" = :b1 AND "DATA_TYPE" = :b2.

2021-03-05 17:14:06 WARNING OGG-01003 Repositioning to rba 23738948 in seqno 149124.

Source Context :

SourceModule : [er.errors]

SourceID : [/scratch/pradshar/view_storage/pradshar_pse_15852019/oggcore/OpenSys/src/app/er/errors.cpp]

SourceFunction : [take_rep_err_action]

SourceLine : [623]

ThreadBacktrace : [8] elements

: [/goldengate/libgglog.so(CMessageContext::AddThreadContext()+0x1e) [0x7f388b8d471e]]

: [/goldengate/libgglog.so(CMessageFactory::CreateMessage(CSourceContext*, unsigned int, ...)+0x2cc) [0x7f388b8cd6bc]]

: [/goldengate/libgglog.so(_MSG_ERR_MAP_TO_TANDEM_FAILED(CSourceContext*, ggs::gglib::ggapp::CQualDBObjName<(DBObjType)1> const&, ggs::gglib::ggapp::CQualDBObjName<(DBObjType)1> const&, CMessageFactory::MessageDisposition)+0x53) [0x7f388b8c9581]]

: [/goldengate/replicat(take_rep_err_action(short, int, char const*, extr_ptr_def*, __std_rec_hdr*, char*, file_def*, bool)+0xdac) [0x521a80]]

: [/goldengate/replicat(process_extract_loop()+0x2388) [0x53ad18]]

: [/goldengate/replicat(main+0x732) [0x54cbd2]]

: [/lib64/libc.so.6(__libc_start_main+0xf5) [0x7f3885ca63d5]]

: [/goldengate/replicat(__gxx_personality_v0+0x31a) [0x4c0c6a]]

2021-03-05 17:14:07 ERROR OGG-01296 Error mapping from CSMuserB.E_MP_AAA to fdpuserA.E_MP_AAA.

3 根据报错信息，查看执行的SQL

UPDATE /*+ RESTRICT_ALL_REF_CONS */ "fdpuserA"."E_MP_AAA"

SET "ID" = :a3,

"DATA_DATE" = :a4,

"DATA_TYPE" = :a5,

"DATA_POINT_FLAG" = :a6,

"DATA_WHOLE_FLAG" = :a7,

"P1" = :a8,

。。。。。。。。。。。。。。。。。。。。。。。。。。。。。。。。。。。。。。

"P96" = :a103,

"SOURCE_CHANGE_TIME" = :a104,

"TARGET_WRITE_TIME" = :a105

WHERE "ID" = :b0

AND "DATA_DATE" = :b1

AND "DATA_TYPE" = :b2.

4 根据OGG丢弃discard的文件，查看绑定变量的值,会发现一开始ID,DATA_DATE,DATA_TYPE 是有值的，

但紧跟着就没有值了

Current time: 2021-03-05 16:57:47

Discarded record from action ABEND on error 1407

OCI Error ORA-01407: cannot update ("fdpuserA"."E_MP_AAA"."ID") to NULL (status = 1407).

UPDATE /*+ RESTRICT_ALL_REF_CONS */ "fdpuserA"."E_MP_AAA" SET "ID" = :a3,"DATA_DATE" = :a4,

"DATA_TYPE" = :a5,"DATA_POINT_FLAG" = :a6,"DATA_WHOLE_FLAG" = :a7,"P1" = :a8,"P2" = :a9,"P3" = :a10,

".................

Aborting transaction on ./dirdat/cj/yd beginning at seqno 149124 rba 23738948

error at seqno 149124 rba 36180309

Problem replicating CSMuserB.E_MP_AAA to fdpuserA.E_MP_AAA

Mapping problem with compressed key update record (target format)...

*

ID = 49944939 --ID的值为 49944939

DATA_DATE = 2021-03-05 00:00:00

DATA_TYPE = 1

ID = --为什么会再次出现ID值，并且获取不到ID的值

DATA_DATE =

DATA_TYPE =

DATA_POINT_FLAG = NULL

DATA_WHOLE_FLAG = NULL

P1 = NULL

………………………………………………

P96 = NULL

SOURCE_CHANGE_TIME = 2021-03-05 01:43:48

TARGET_WRITE_TIME = 2021-03-05 16:57:47

5 开启trace，发现SQL_ID为2txncyg58q4wk的，ID值无法获取，故为空，

SQL执行同时报错ORA-1407，但where条件的变量值却是可以获取到，如下：

Bind#103

oacdty=01 mxl=32(24) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=1472

kxsbbbfp=7f11c7cd6278 bln=32 avl=08 flg=01

value="49944939"

Bind#104

oacdty=01 mxl=128(57) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=1504

kxsbbbfp=7f11c7cd6298 bln=128 avl=19 flg=01

value="2021-03-05 00:00:00"

Bind#105

oacdty=01 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=1632

kxsbbbfp=7f11c7cd6318 bln=32 avl=01 flg=01

value="1"

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

PARSING IN CURSOR #139714343305896 len=1523 dep=0 uid=108 oct=6 lid=108 tim=1614938748913365 hv=3398112146 ad='2814529cf0' sqlid='2txncyg58q4wk'

UPDATE /*+ RESTRICT_ALL_REF_CONS */ "fdpuserA"."E_MP_AAA" SET "ID" = :a3,"DATA_DATE" = :a4,"DATA_TYPE" = :a5,"DATA_POINT_FLAG" = :a6,

"DATA_WHOLE_FLAG" = :a7,"P1" = :a8,"P2" = :a9,"P3" = :a10,"P4" = :a11,"P5" = :a12,"P6" = :a13,"P7" = :a14,"P8" = :a15,"P9" = :a16,"P10" = :a17,

....................

"P88" = :a95,"P89" = :a96,"P90" = :a97,"P91" = :a98,"P92" = :a99,"P93" = :a100,"P94" = :a101,"P95" = :a102,"P96" = :a103,"SOURCE_CHANGE_TIME" = :a104,

"TARGET_WRITE_TIME" = :a105 WHERE "ID" = :b0 AND "DATA_DATE" = :b1 AND "DATA_TYPE" = :b2

END OF STMT

PARSE #139714343305896:c=699,e=699,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1614938748913364

WAIT #139714343305896: nam='library cache lock' ela= 196 handle address=169351999520 lock address=172137777856 100*mode+namespace=12250341945114626 obj#=0 tim=1614938748914409

WAIT #139714343305896: nam='library cache pin' ela= 166 handle address=169351999520 pin address=172137777600 100*mode+namespace=12250341945114626 obj#=0 tim=1614938748914640

BINDS #139714343305896:

Bind#0

oacdty=01 mxl=32(00) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=3984 off=0

kxsbbbfp=7f11c768b210 bln=32 avl=00 flg=05

Bind#1

oacdty=01 mxl=32(00) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=32

kxsbbbfp=7f11c768b230 bln=32 avl=00 flg=01

Bind#2

oacdty=01 mxl=32(00) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=64

kxsbbbfp=7f11c768b250 bln=32 avl=00 flg=01

Bind#3

oacdty=01 mxl=32(00) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=96

kxsbbbfp=7f11c768b270 bln=32 avl=00 flg=01

Bind#4

oacdty=01 mxl=2000(288) mxlc=00 mal=00 scl=00 pre=00

oacflg=03 fl2=1000000 frm=01 csi=873 siz=0 off=128

kxsbbbfp=7f11c768b290 bln=2000 avl=00 flg=01

Bind#5

oacdty=01 mxl=32(00) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=2128

kxsbbbfp=7f11c768ba60 bln=32 avl=00 flg=01

Bind#6

oacdty=01 mxl=32(00) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=2160

kxsbbbfp=7f11c768ba80 bln=32 avl=00 flg=01

………………………………………………

Bind#100

oacdty=01 mxl=32(00) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=1184

kxsbbbfp=7f11c7cd6158 bln=32 avl=00 flg=01

Bind#101

oacdty=01 mxl=128(57) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=1216

kxsbbbfp=7f11c7cd6178 bln=128 avl=19 flg=01

value="2021-03-05 01:43:48"

Bind#102

oacdty=01 mxl=128(57) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=1344

kxsbbbfp=7f11c7cd61f8 bln=128 avl=19 flg=01

value="2021-03-05 18:05:48"

Bind#103

oacdty=01 mxl=32(24) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=1472

kxsbbbfp=7f11c7cd6278 bln=32 avl=08 flg=01

value="49944939"

Bind#104

oacdty=01 mxl=128(57) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=1504

kxsbbbfp=7f11c7cd6298 bln=128 avl=19 flg=01

value="2021-03-05 00:00:00"

Bind#105

oacdty=01 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00

oacflg=21 fl2=1000000 frm=01 csi=873 siz=0 off=1632

kxsbbbfp=7f11c7cd6318 bln=32 avl=01 flg=01

value="1"

WAIT #139714343305896: nam='gc current grant 2-way' ela= 124 p1=1645 p2=379484 p3=33554454 obj#=0 tim=1614938748920783

EXEC #139714343305896:c=7468,e=7829,p=0,cr=4,cu=12,mis=1,r=0,dep=0,og=1,plh=823891787,tim=1614938748921256

ERROR #139714343305896:err=1407 tim=1614938748921279

6 看表的附加日志，附加日志为主键列：

GGSCI (hosta) 4> info trandata CSMuserB.E_MP_AAA

Logging of supplemental redo log data is enabled for table CSMuserB.E_MP_AAA.

Columns supplementally logged for table CSMuserB.E_MP_AAA: DATA_DATE, DATA_TYPE, ID.

查看表的索引

INDEX_OWNER INDEX_NAME TABLE_OWNER TABLE_NAME COLUMN_NAME COLUMN_POSITION STATUS

------------- ---------------------- ------------------ ------------------- ------------ --------------- ------

CSMuserB PK_E_MP_AAA CSMuserB E_MP_AAA ID 1 N/A

CSMuserB PK_E_MP_AAA CSMuserB E_MP_AAA DATA_DATE 2 N/A

CSMuserB PK_E_MP_AAA CSMuserB E_MP_AAA DATA_TYPE 3 N/A

7 使用logdump，查看ID值为49944939 的trail文件，将49944939转换为16进制的值为：2FA196B，

经过查询，总算找到ID值为49944939的数据，发现更新后的主键列确实为空。

Logdump 969 >n

___________________________________________________________________

Hdr-Ind : E (x45) Partition : . (x04)

UndoFlag : . (x00) BeforeAfter: B (x42)

RecLength : 1419 (x058b) IO Time : 2021/03/05 01:43:48.000.033

IOType : 15 (x0f) OrigNode : 255 (xff)

TransInd : . (x01) FormatType : R (x52)

SyskeyLen : 0 (x00) Incomplete : . (x00)

AuditRBA : 473448 AuditPos : 900726448

Continued : N (x00) RecCount : 1 (x01)

2021/03/05 01:43:48.000.033 FieldComp Len 1419 RBA 36178784

Name: CSMuserB.E_MP_AAA

Before Image: Partition 4 G m

0000 000a 0000 0000 0000 02fa 196b 0001 0015 0000 | .............k......

3230 3231 2d30 332d 3035 3a30 303a 3030 3a30 3000 | 2021-03-05:00:00:00.

0200 0a00 0000 0000 0000 0000 0100 0300 0aff ff00 | ....................

0000 0000 0000 0000 0400 04ff ff00 0000 0500 0aff | ....................

ff00 0000 0000 0000 0000 0600 0aff ff00 0000 0000 | ....................

0000 0000 0700 0aff ff00 0000 0000 0000 0000 0800 | ....................

0aff ff00 0000 0000 0000 0000 0900 0aff ff00 0000 | ....................

Column 0 (x0000), Len 10 (x000a)

0000 0000 0000 02fa 196b | .........k

Column 1 (x0001), Len 21 (x0015)

0000 3230 3231 2d30 332d 3035 3a30 303a 3030 3a30 | ..2021-03-05:00:00:0

30 | 0

Column 2 (x0002), Len 10 (x000a)

0000 0000 0000 0000 0001 | ..........

Column 3 (x0003), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

Column 4 (x0004), Len 4 (x0004)

ffff 0000 | ....

Column 5 (x0005), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

Column 6 (x0006), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

…………………………………………………………..

Column 99 (x0063), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

Column 100 (x0064), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

GGS tokens:

TokenID x52 'R' ORAROWID Info x00 Length 20

4141 5050 4d5a 4150 5741 4144 7361 7441 4544 0001 | AAPPMZAPWAADsatAED..

Logdump 970 >n

___________________________________________________________________

Hdr-Ind : E (x45) Partition : . (x04)

UndoFlag : . (x00) BeforeAfter: A (x41)

RecLength : 1474 (x05c2) IO Time : 2021/03/05 01:43:48.001.039

IOType : 115 (x73) OrigNode : 255 (xff)

TransInd : . (x01) FormatType : R (x52)

SyskeyLen : 0 (x00) Incomplete : . (x00)

AuditRBA : 473448 AuditPos : 900726448

Continued : N (x00) RecCount : 1 (x01)

2021/03/05 01:43:48.001.039 GGSPKUpdate Len 1474 RBA 36180309

Name: CSMuserB.E_MP_AAA

After Image: Partition 4 G m

0035 0000 000a 0000 0000 0000 02fa 196b 0001 0015 | .5.............k....

0000 3230 3231 2d30 332d 3035 3a30 303a 3030 3a30 | ..2021-03-05:00:00:0

3000 0200 0a00 0000 0000 0000 0000 0100 0000 0aff | 0...................

ff00 0000 0000 0000 0000 0100 15ff ff31 3930 302d | ...............1900-

3031 2d30 313a 3030 3a30 303a 3030 0002 000a ffff | 01-01:00:00:00......

0000 0000 0000 0000 0003 000a ffff 0000 0000 0000 | ....................

0000 0004 0004 ffff 0000 0005 000a ffff 0000 0000 | ....................

Before Image Len 55 (x00000037)

KeyLen 53 (x00000035)

KeyCol 0 (x0000), Len 10 (x000a)

0000 0000 0000 02fa 196b | .........k

KeyCol 1 (x0001), Len 21 (x0015)

0000 3230 3231 2d30 332d 3035 3a30 303a 3030 3a30 | ..2021-03-05:00:00:0

30 | 0

KeyCol 2 (x0002), Len 10 (x000a)

0000 0000 0000 0000 0001 | ..........

After Image Len 1419 (x0000058b)

Column 0 (x0000), Len 10 (x000a)

ffff 0000 0000 0000 0000 | .......... --更新后的值，发现为空，所以OGG报错ORA-1407

Column 1 (x0001), Len 21 (x0015)

ffff 3139 3030 2d30 312d 3031 3a30 303a 3030 3a30 | ..1900-01-01:00:00:0 --仔细看时间，发现时间也不对

30 | 0

Column 2 (x0002), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

Column 3 (x0003), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

Column 4 (x0004), Len 4 (x0004)

ffff 0000 | ....

Column 5 (x0005), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

………………………………………………………………….

Column 99 (x0063), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

Column 100 (x0064), Len 10 (x000a)

ffff 0000 0000 0000 0000 | ..........

GGS tokens:

TokenID x52 'R' ORAROWID Info x00 Length 20

4141 5050 4d5a 4150 5741 4144 7361 7441 4544 0001 | AAPPMZAPWAADsatAED..

8 根据ROWID查询对应的数据，在源端数据是有的，且主键不为空。

SYS@hostA >select * from CSMuserB.E_MP_AAA where rowid='AAPPMZAPWAADsatAED';

49944939 05-MAR-21 1 1 111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111 .0021 .0022 .0036 .0021

.0022 .0022 .0022 .0021 .0022 .0021 .0021 .0021 .0022 .0022 .0022 .0022 .0021 .0022 .0022 .0022 .0022 .0022

.0022 .0022 .0021 .0021 .0021 .0021 .0021 .002 .002 .002 .002 .002 .002 .002 .002 .002 .002 .0021

.0021 .0031 .0015 .0015 .0015 .0046 .0028 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .003 .0015

.0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015

.0015 .0015 .002 .002 .002 .0034 .002 .002 .002 .002 .0021 .0021 .0021 .0021 .0021 .0021 .0021 .0021

.0021 .0021

9 在目标端查询对应的数据：

select * from fdpuserA.E_MP_AAA a where a.id='49944939' and a.data_date=to_date('2021-03-05 00:00:00','yyyy-mm-dd hh24:mi:ss') and a.data_type=1;

SYS@hostB >/

ID DATA_DATE DATA_TYPE DATA_POINT_FLAG

----------------- ------------------ ---------- ---------------

22000087144 04-MAR-21 8 1

SYS@hostB>select * from fdpuserA.E_MP_AAA a where a.id='49944939' and a.data_date=to_date('2021-03-05 00:00:00','yyyy-mm-dd hh24:mi:ss') and a.data_type=1;

49944939 05-MAR-21 1 1 111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111 .0021 .0022 .0036 .0021 .0022 .0022 .0022 .0021 .0022 .0021 .0021 .0021

.0022 .0022 .0022 .0022 .0021 .0022 .0022 .0022 .0022 .0022 .0022 .0022 .0021 .0021 .0021 .0021 .0021 .002 .002 .002 .002 .002 .002 .002 .002 .002 .002

.0021 .0021 .0031 .0015 .0015 .0015 .0046 .0028 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .003 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015

.0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .0015 .002 .002 .002 .0034 .002 .002 .002 .002 .0021 .0021 .0021 .0021 .0021 .0021 .0021

.0021 .0021 .0021 06-MAR-21 06-MAR-21

10 处理方法：OGG忽略此报错将相关事务应用完成后，停止OGG，将目标端的对应数据删除，并从源端将相关数据转换为SQL插入语句，重新插入到目标端。

总结：

根据如上信息，源端有附加日志，且为主键列的值，源端和目标端都有数据，根据OGG的discard文件、追踪文件，trail文件，可以确定，OGG抽取进程将主键列的值，抽取为空，但由于主键列有不为空的约束，故最终导致OGG报ORA-1407错误。根据此信息，认为应该时OGG源端抽取进程抽取的数据异常，导致的ORA-1407错误。

ORA-1407错误分析及追踪