ogg replicate SQL error 1403错误分析

dai_xuej

1、replicate进程abended
[oracle@SZZFJG ogg]$ ggsci
Oracle GoldenGate Command Interpreter for Oracle
Version 11.1.1.1.2 OGGCORE_11.1.1.1.2_PLATFORMS_111004.2100
Linux, x64, 64bit (optimized), Oracle 11g on Oct  4 2011 23:49:46
Copyright (C) 1995, 2011, Oracle and/or its affiliates. All rights reserved.

GGSCI (SZZFJG) 1> info all
Program     Status      Group       Lag           Time Since Chkpt
MANAGER     RUNNING                                          
REPLICAT    RUNNING     RORA_001    00:00:00      00:00:39   
REPLICAT    ABENDED     RORA_002    00:00:00      24:50:24   
REPLICAT    RUNNING     RORA_003    00:00:00      00:00:35   
REPLICAT    RUNNING     RORA_004    00:00:00      00:00:35   

GGSCI (SZZFJG) 2>

2、view report rora_002

2012-06-07 18:30:41  WARNING OGG-01004  Aborted grouped transaction on 'ZFJGGETER.DJ_SFZ', Database error 1403 ().
2012-06-07 18:30:41  WARNING OGG-01003  Repositioning to rba 1796 in seqno 1.
2012-06-07 18:30:41  WARNING OGG-01154  SQL error 1403 mapping DBO.DJ_SFZ to ZFJGGETER.DJ_SFZ.
2012-06-07 18:30:41  WARNING OGG-01003  Repositioning to rba 1796 in seqno 1.
Source Context :
  SourceModule            : [er.main]
  SourceID                : [/scratch/pradshar/view_storage/pradshar_bugdbrh40_12927937/oggcore/OpenSys/src/app/er/rep.c]
  SourceFunction          : [take_rep_err_action]
  SourceLine              : [16148]
  ThreadBacktrace         : [8] elements
                          : [/home/oracle/ogg/replicat(CMessageContext::AddThreadContext()+0x26) [0x5f2ac6]]
                          : [/home/oracle/ogg/replicat(CMessageFactory::CreateMessage(CSourceContext*, unsigned int, ...)+0x7b2) [0x5e9562]]
                          : [/home/oracle/ogg/replicat(_MSG_ERR_MAP_TO_TANDEM_FAILED(CSourceContext*, DBString<777> const&, DBString<777> const&, CMessageFactory::Mess
ageDisposition)+0x9b) [0x5c79bb]]
                          : [/home/oracle/ogg/replicat [0x832a3a]]
                          : [/home/oracle/ogg/replicat [0x910279]]
                          : [/home/oracle/ogg/replicat(main+0x84b) [0x5081ab]]
                          : [/lib64/libc.so.6(__libc_start_main+0xf4) [0x341f61d994]]
                          : [/home/oracle/ogg/replicat(__gxx_personality_v0+0x1da) [0x4e479a]]
2012-06-07 18:30:41  ERROR   OGG-01296  Error mapping from DBO.DJ_SFZ to ZFJGGETER.DJ_SFZ.
***********************************************************************
*                   ** Run Time Statistics **                         *
***********************************************************************
Reading ./dirdat/t7000001, current RBA 1796, 0 records
Report at 2012-06-07 18:30:41 (activity since 2012-06-07 18:30:41)
From Table DBO.DJ_SFZ to ZFJGGETER.DJ_SFZ:
       #                   inserts:         0
       #                   updates:         0
       #                   deletes:         0
       #                  discards:         1
3、discard文件
Oracle GoldenGate Delivery for Oracle process started, group RORA_002 discard file opened: 2012-06-07 18:30:40
Current time: 2012-06-07 18:30:41
Discarded record from action ABEND on error 1403
Aborting transaction on ./dirdat/t7 beginning at seqno 1 rba 1796
                         error at seqno 1 rba 1796
Problem replicating DBO.DJ_SFZ to ZFJGGETER.DJ_SFZ
Record not found
Mapping problem with compressed update record (target format)...
*
SFZBH = 320503194002232526
ZHAOPIAN = <Raw Data>
*
Process Abending : 2012-06-07 18:30:41

4、edit params rora_002

replicat rora_002
setenv (NLS_LANG=AMERICAN_AMERICA.ZHS16GBK)
userid ggs, password ggs
REPORT AT 01:59
REPORTCOUNT EVERY 30 MINUTES, RATE
REPERROR DEFAULT, ABEND
numfiles 5000
CHECKPOINTSECS 40
--assumetargetdefs
sourcedefs ../dirdef/source_001.def
DISCARDFILE ./dirrpt/rept2.dsc, APPEND, MEGABYTES 1024
DISCARDROLLOVER AT 02:30
ALLOWNOOPUPDATES
--HANDLECOLLISIONS
map dbo.da_TaXiangQuanZheng, target ZFJGGETER.DA_TAXIANGQUANZHENG, colmap (USEDEFAULTS, FUJI = "");
map dbo.da_XianZhiQuanLi, target ZFJGGETER.DA_XIANZHIQUANLI, colmap (USEDEFAULTS, FUJI = "");
map dbo.da_ZaiJianGCDY, target ZFJGGETER.DA_ZAIJIANGCDY, colmap (USEDEFAULTS, FUJI = "");
map dbo.dj_SFZ, target ZFJGGETER.DJ_SFZ, colmap (USEDEFAULTS, ZHAOPIAN = "");
map dbo.gg_DengJiYiJian, target ZFJGGETER.GG_DENGJIYIJIAN, colmap (USEDEFAULTS, CHUSHENYIJIAN = "");
map dbo.yw_KeShi, target ZFJGGETER.YW_KESHI, colmap (USEDEFAULTS, BEIZHU = "");


5、表结构情况：

SQL> desc dj_sfz;
Name                                      Null?    Type
----------------------------------------- -------- ----------------------------
BIANHAO                                            NUMBER(38)
SFZBH                                     NOT NULL VARCHAR2(53)
XINGMIN                                            VARCHAR2(158)
XINGBIE                                            VARCHAR2(11)
MINZU                                              VARCHAR2(38)
CHUSHENRIQI                                        DATE
ZHUZHI                                             VARCHAR2(158)
QIANFAJIGUAN                                       VARCHAR2(158)
YOUXIAOQISHI                                       DATE
YOUXIAOQIZHI                                       DATE
ZHUZHI_NEW                                         VARCHAR2(158)
ZHAOPIAN                                           BLOB
SHURURQ                                            DATE
HOSTNAME                                           VARCHAR2(83)
USERNAME                                           VARCHAR2(83)
APPLICATIONNAME                                    VARCHAR2(83)
6、logdump分析：

Logdump 67 >open ./dirdat/t7000001
Logdump 68 >ghdr on
Logdump 69 >detail on
Logdump 70 >detail data
Logdump 71 >usertoken on
Logdump 72 >pos 1796
Reading forward from RBA 1796
Logdump 73 >n
TokenID x47 'G' Record Header    Info x01  Length  146
TokenID x48 'H' GHDR             Info x00  Length   45
TokenID x44 'D' Data             Info x00  Length   38
TokenID x54 'T' GGS Tokens       Info x00  Length   43
TokenID x5a 'Z' Record Trailer   Info x01  Length  146
___________________________________________________________________
Hdr-Ind    :     E  (x45)     Partition  :     .  (x04)  
UndoFlag   :     .  (x00)     BeforeAfter:     A  (x41)  
RecLength  :    38  (x0026)   IO Time    : 2012/06/06 11:51:34.258.599   
IOType     :    15  (x0f)     OrigNode   :   255  (xff)
TransInd   :     .  (x00)     FormatType :     R  (x52)
SyskeyLen  :     0  (x00)     Incomplete :     .  (x00)
AuditRBA   :          6       AuditPos   : 65455301591076
Continued  :     Y  (x01)     RecCount   :     1  (x01)
2012/06/06 11:51:34.258.599 FieldComp            Len    38 RBA 1796
Name: DBO.DJ_SFZ
After  Image:                                             Partition 4   G  b   
0001 0022 0000 001e 3332 3035 3033 3139 3430 3032 | ..."....320503194002  
3233 3235 3236 2020 2020 2020 2020 2020 2020      | 232526              
Column     1 (x0001), Len    34 (x0022)  
0000 001e 3332 3035 3033 3139 3430 3032 3233 3235 | ....3205031940022325  
3236 2020 2020 2020 2020 2020 2020                | 26              
  
GGS tokens:
4c00 0016 3030 3030 3030 3234 3a30 3030 3033 6663 | L...00000024:00003fc  
303a 3030 3635 3600 000d 3030 3030 3a30 3030 3835 | 0:00656...0000:00085  
3830 32                                           | 802

从上面看个人认为问题出在那个blob字段的colmap上：
map dbo.dj_SFZ, target ZFJGGETER.DJ_SFZ, colmap (USEDEFAULTS, ZHAOPIAN = "");

[ 本帖最后由 dai_xuej 于 2012-6-8 15:43 编辑 ]

dai_xuej

手动执行这个动作发现
SQL> update dj_sfz set ZHAOPIAN="" where SFZBH='320503194002232526';
ERROR:
ORA-01741: illegal zero-length identifier

dai_xuej

SQL> update dj_sfz_bak set ZHAOPIAN='a' where SFZBH='320503194002232526';

1 row updated.

SQL> update dj_sfz_bak set ZHAOPIAN='' where SFZBH='320503194002232526';

1 row updated.
试着把colmap改成这样：
map dbo.dj_SFZ, target ZFJGGETER.DJ_SFZ, colmap (USEDEFAULTS, ZHAOPIAN = '');
去start replicate
还是abend:
但是报错变了，说明与之前的猜测colmap部分有问题的方向，还是对的。

MAP resolved (entry DBO.DJ_SFZ):
  map DBO.DJ_SFZ, target ZFJGGETER.DJ_SFZ, colmap (USEDEFAULTS, ZHAOPIAN = '');
Using the following default columns with matching names:
  BIANHAO=BianHao, SFZBH=SFZbh, XINGMIN=XingMin, XINGBIE=XingBie, MINZU=MinZu, CHUSHENRIQI=ChuShenRiQi, ZHUZHI=ZhuZhi, QIANFAJIGUAN=QianFaJiGuan, YOUXIAOQISHI=YouXiaoQ
iShi, YOUXIAOQIZHI=YouXiaoQiZhi, ZHUZHI_NEW=ZhuZhi_new, ZHAOPIAN=ZhaoPian, SHURURQ=ShuRuRQ, HOSTNAME=HostName, USERNAME=UserName, APPLICATIONNAME=ApplicationName
...S, ZHAOPIAN = '')...
                 ^
Error in COLMAP clause. Unrecognized clause or element.

Source Context :
  SourceModule            : [er.main]
  SourceID                : [/scratch/pradshar/view_storage/pradshar_bugdbrh40_12927937/oggcore/OpenSys/src/app/er/rep.c]
  SourceFunction          : [get_map_entry]
  SourceLine              : [9126]
  ThreadBacktrace         : [11] elements
                          : [/home/oracle/ogg/replicat(CMessageContext::AddThreadContext()+0x26) [0x5f2ac6]]
                          : [/home/oracle/ogg/replicat(CMessageFactory::CreateMessage(CSourceContext*, unsigned int, ...)+0x7b2) [0x5e9562]]
                          : [/home/oracle/ogg/replicat(_MSG_ERR_DB_CLAUSE_ERROR(CSourceContext*, char const*, CMessageFactory::MessageDisposition)+0x92) [0x5b1352]]
                          : [/home/oracle/ogg/replicat(get_map_entry(char*, int, __wc*, int)+0x1dd6) [0x4fcec6]]
                          : [/home/oracle/ogg/replicat [0x5497e5]]
                          : [/home/oracle/ogg/replicat(WILDCARD_check_table(char const*, char const*, int, unsigned int*, int, unsigned int, DBString<777>*, int)+0x16b
) [0x54b08b]]
                          : [/home/oracle/ogg/replicat(REP_find_source_file_wc(char const*, unsigned int, DBString<777>*, int)+0x350) [0x903d50]]
                          : [/home/oracle/ogg/replicat [0x90bb0d]]
                          : [/home/oracle/ogg/replicat(main+0x84b) [0x5081ab]]
                          : [/lib64/libc.so.6(__libc_start_main+0xf4) [0x341f61d994]]
                          : [/home/oracle/ogg/replicat(__gxx_personality_v0+0x1da) [0x4e479a]]

2012-06-08 16:17:17  ERROR   OGG-00919  Error in COLMAP clause.

dai_xuej

将colmap语句成这样：
map dbo.dj_SFZ, target ZFJGGETER.DJ_SFZ, colmap (USEDEFAULTS, ZHAOPIAN = @binary(ZHAOPIAN));
去启动replicate 进程
报错又返回了之前的sql  error 1403如下：
Opened trail file ./dirdat/t7000001 at 2012-06-08 16:45:59
Processed extract process graceful restart record at seq 1, rba 1734.

MAP resolved (entry DBO.DJ_SFZ):
  map DBO.DJ_SFZ, target ZFJGGETER.DJ_SFZ, colmap (USEDEFAULTS, ZHAOPIAN = @binary(ZHAOPIAN));
Using the following default columns with matching names:
  BIANHAO=BianHao, SFZBH=SFZbh, XINGMIN=XingMin, XINGBIE=XingBie, MINZU=MinZu, CHUSHENRIQI=ChuShenRiQi, ZHUZHI=ZhuZhi, QIANFAJIGUAN=QianFaJiGuan, YOUXIAOQISHI=YouXiaoQ
iShi, YOUXIAOQIZHI=YouXiaoQiZhi, ZHUZHI_NEW=ZhuZhi_new, ZHAOPIAN=ZhaoPian, SHURURQ=ShuRuRQ, HOSTNAME=HostName, USERNAME=UserName, APPLICATIONNAME=ApplicationName

Using the following key columns for target table ZFJGGETER.DJ_SFZ: SFZBH.


2012-06-08 16:45:59  WARNING OGG-01004  Aborted grouped transaction on 'ZFJGGETER.DJ_SFZ', Database error 1403 ().

2012-06-08 16:45:59  WARNING OGG-01003  Repositioning to rba 1796 in seqno 1.

2012-06-08 16:45:59  WARNING OGG-01154  SQL error 1403 mapping DBO.DJ_SFZ to ZFJGGETER.DJ_SFZ.

2012-06-08 16:45:59  WARNING OGG-01003  Repositioning to rba 1796 in seqno 1.

Source Context :
  SourceModule            : [er.main]
  SourceID                : [/scratch/pradshar/view_storage/pradshar_bugdbrh40_12927937/oggcore/OpenSys/src/app/er/rep.c]
  SourceFunction          : [take_rep_err_action]
  SourceLine              : [16148]
  ThreadBacktrace         : [8] elements
                          : [/home/oracle/ogg/replicat(CMessageContext::AddThreadContext()+0x26) [0x5f2ac6]]
                          : [/home/oracle/ogg/replicat(CMessageFactory::CreateMessage(CSourceContext*, unsigned int, ...)+0x7b2) [0x5e9562]]
                          : [/home/oracle/ogg/replicat(_MSG_ERR_MAP_TO_TANDEM_FAILED(CSourceContext*, DBString<777> const&, DBString<777> const&, CMessageFactory::Mess
ageDisposition)+0x9b) [0x5c79bb]]
                          : [/home/oracle/ogg/replicat [0x832a3a]]
                          : [/home/oracle/ogg/replicat [0x910279]]
                          : [/home/oracle/ogg/replicat(main+0x84b) [0x5081ab]]
                          : [/lib64/libc.so.6(__libc_start_main+0xf4) [0x341f61d994]]
                          : [/home/oracle/ogg/replicat(__gxx_personality_v0+0x1da) [0x4e479a]]

2012-06-08 16:45:59  ERROR   OGG-01296  Error mapping from DBO.DJ_SFZ to ZFJGGETER.DJ_SFZ.
到此问题似呼回到了原地

dai_xuej

When the size of a large object exceeds 4K, Oracle GoldenGate stores the data in segments within the Oracle GoldenGate trail. The first 4K is stored in the base segment, and the rest is stored in a series of 2K segments. Oracle GoldenGate does not support the filtering, column mapping, or manipulation of large objects of this size. Full Oracle GoldenGate functionality can be used for objects that are 4K or smaller.
看来与这个有关系，再看看表中这个照片字段所占的空间：
SQL> select dbms_lob.getlength(zhaopian) from dj_sfz where SFZBH='320503194002232526';

DBMS_LOB.GETLENGTH(ZHAOPIAN)
----------------------------
                       38862
这张照片居然占用了38k多的空间，看来原因出在这儿。到目前为止ogg超过4k的大字段，还不能用字段映射的办法来解决。

dai_xuej

[oracle@SZZFJG ogg]$ cat demo_ora_lob_create.sql
-- Copyright (C) 2002, 2010, Oracle and/or its affiliates. All rights reserved.
--
-- demo_ora_lob_create.sql
--
-- Oracle Tutorial
--
-- Description:
-- Create the TSRSLOB and TTRGVAR tables.After creation of source and target table run stored
-- procedure from sqlplus prompt as
-- exec testing_lobs;
--
-- Note: execute this script from the command line as "sqlplus userid/password @demo_ora_lob_create.sql".
--


DROP TABLE TSRSLOB;
CREATE TABLE TSRSLOB
(  LOB_RECORD_KEY         NUMBER
,  LOB1_CLOB                     CLOB  NULL
,  LOB2_BLOB                   BLOB  NULL
,  CONSTRAINT PK_TSRSLOB
   PRIMARY KEY
   (LOB_RECORD_KEY) USING INDEX
);

DROP TABLE TTRGVAR;
CREATE TABLE TTRGVAR
(  LOB_RECORD_KEY            NUMBER
,  LOB1_VCHAR0                    VARCHAR2 (1000) NULL
,  LOB1_VCHAR1                    VARCHAR2 (500) NULL
,  LOB1_VCHAR2                    VARCHAR2 (2500) NULL
,  LOB1_VCHAR3                    VARCHAR2 (200) NULL
,  LOB1_VCHAR4                    VARCHAR2 (2000) NULL
,  LOB1_VCHAR5                    VARCHAR2 (2000) NULL
,  LOB1_VCHAR6                    VARCHAR2 (100) NULL
,  LOB1_VCHAR7                    VARCHAR2 (250) NULL
,  LOB1_VCHAR8                    VARCHAR2 (300) NULL
,  LOB1_VCHAR9                    VARCHAR2 (1000) NULL
,  LOB2_VCHAR0                    VARCHAR2 (2000) NULL
,  LOB2_VCHAR1                    VARCHAR2 (1500) NULL
,  LOB2_VCHAR2                    VARCHAR2 (800) NULL
,  LOB2_VCHAR3                    VARCHAR2 (1000) NULL
,  LOB2_VCHAR4                    VARCHAR2 (400) NULL
,  LOB2_VCHAR5                    VARCHAR2 (2000) NULL
,  LOB2_VCHAR6                    VARCHAR2 (1000) NULL
,  LOB2_VCHAR7                    VARCHAR2 (150) NULL
,  LOB2_VCHAR8                    VARCHAR2 (2000) NULL
,  LOB2_VCHAR9                    VARCHAR2 (50) NULL
,  CONSTRAINT PK_TTRGVAR
   PRIMARY KEY
   (LOB_RECORD_KEY) USING INDEX
);

Create or Replace procedure testing_lobs
IS

err_num NUMBER;
position INTEGER;
lang_warn INTEGER;
begin_key INTEGER;
current_key INTEGER;

buf_size BINARY_INTEGER;

var_a_buf varchar2 (9850);
var_b_buf varchar2 (10900);
blob_mem BLOB;

begin
    lang_warn  := 0;
    position := 1;
    buf_size := 10900;

    var_a_buf  := var_a_buf || rpad('a',1000,'a');
    var_a_buf  := var_a_buf || rpad('b',500,'b');
    var_a_buf  := var_a_buf || rpad('c',2500,'c');
    var_a_buf  := var_a_buf || rpad('d',200,'d');
    var_a_buf  := var_a_buf || rpad('e',2000,'e');
    var_a_buf  := var_a_buf || rpad('f',2000,'f');
    var_a_buf  := var_a_buf || rpad('g',100,'g');
    var_a_buf  := var_a_buf || rpad('h',250,'h');
    var_a_buf  := var_a_buf || rpad('i',300,'i');
    var_a_buf  := var_a_buf || rpad('j',1000,'j');

    var_b_buf  := var_b_buf || rpad('h',2000,'h');   
    var_b_buf  := var_b_buf || rpad('i',1500,'i');   
    var_b_buf  := var_b_buf || rpad('j',800,'j');   
    var_b_buf  := var_b_buf || rpad('k',1000,'k');   
    var_b_buf  := var_b_buf || rpad('l',400,'l');   
    var_b_buf  := var_b_buf || rpad('m',2000,'m');   
    var_b_buf  := var_b_buf || rpad('n',1000,'n');   
    var_b_buf  := var_b_buf || rpad('o',150,'o');   
    var_b_buf  := var_b_buf || rpad('p',2000,'p');   
    var_b_buf  := var_b_buf || rpad('q',50,'q');   

    SELECT count (*)
        INTO  begin_key
     FROM   tsrslob;
   
     if begin_key != 0 then
       SELECT max (LOB_RECORD_KEY)
           INTO  begin_key
        FROM   tsrslob;
     end if;
  
     current_key := begin_key + 100;

     INSERT INTO tsrslob VALUES
     (current_key,
      var_a_buf ,
      NULL
     );

     COMMIT;

     SELECT LOB2_BLOB
         INTO  blob_mem
      FROM   tsrslob
      WHERE LOB_RECORD_KEY = current_key
      FOR UPDATE;

     DBMS_LOB.createtemporary(blob_mem, TRUE);
   
     DBMS_LOB.convertToBlob (blob_mem, var_b_buf, buf_size, position , position, 1, lang_warn, lang_warn);

     UPDATE tsrslob set LOB2_BLOB = blob_mem
                   WHERE LOB_RECORD_KEY = current_key;

    commit;
end;
/
quit;