Troubleshooting Goldengate OGG-02171 and OGG-02191 Pump Extract process ABENDED
最近处理了一起Goldengate Pump Extract进程abended的案例， 进程日志提示ERROR OGG-02171 Error reading LCR from data source和 ERROR OGG-02191 Incompatible record 104 错误，属于trail文件中的事务记录损坏， 通常是跳过文件中的错误记录，重新启动进程，环境是集成模式的goldengate 18.1。
可能发生几种情况：
1) Extract正在写入跟踪，并且记录开头和结尾周围的部分已损坏。 在这种情况下，GoldenGate 丢失了部分数据。
2）两次Extracts错误地写入了同一组trail文件。
3) Extract Pump正在写入跟踪文件， 并且在更新其检查点文件之前以及数据刷新到跟踪之后崩溃。
4) 存储、内存等硬件原因或IO子系统问题，文件写丢失
5）网络问题,TCP/IP 包错误
6) ogg bugs
一些避免的方法：
如果启用了 AsyncIO，Oracle 建议禁用CACHE。测试您的硬件并持续关注任何磁盘或光纤相关的错误。如果使用NAS存储建议使用本地存储观察是否有网络写导致错误。
案例问题现象
GGSCI (anbob2) 1> info all Program Status Group Lag at Chkpt Time Since Chkpt MANAGER RUNNING EXTRACT ABENDED DP_DB 00:00:00 00:41:46 GGSCI (anbob2) 3> info dp_db detail ... GGSCI (anbob2) 14> view report DP_DB ... Source Context : SourceModule : [er.extract.processPumploop] SourceID : [/scratch/jkrath/view_storage/jkrath_ogghp181128vw/oggcore/OpenSys/src/app/er/extract/processPumpLoop.cpp] SourceMethod : [processPumpLoop] SourceLine : [403] 2023-11-27 19:25:43 ERROR OGG-02171 Error reading LCR from data source. Status 509, data source type TrailDataSource. Source Context : SourceModule : [gglib.ggtrail.TrailDataSource] SourceID : [/scratch/jkrath/view_storage/jkrath_ogghp181128vw/oggcore/OpenSys/src/gglib/ggtrail/TrailDataSource.cpp] SourceMethod : [readNextTrailRecord] SourceLine : [2769] 2023-11-27 19:25:43 ERROR OGG-02191 Incompatible record 104 in /OGG_DATA/ogg/dirdat/anbob/et000153846, rba 198,115,192 when getting trail header.
Note：
“Incompatible record”是指在一系列常规记录中遇到不完整的记录。 不完整的记录是指丢失header（实际上应该事务开始的地方），并且从记录的中间开始，该记录被认为已损坏。它可能会导致记录不兼容(Incompatible)。 这些可能是由于某种基顾环境错误而导致的。没有简单且正确的方法可以从此类错误中恢复。最后，您有可能最终会丢失一笔交易，您必须从源头重构该交易并使数据保持一致。
处理思路
如果trail是由Pump写入的，您可以有效地停止目标上的replicat和源库的pump，并更改pump以从失败点开始重新发送来自源的所有文件。或者使用下面提到的ogg 12的新特性Automated Remote Trail File Recovery.这样不会有任何数据丢失，如果源trace就坏了，也可以replicat跳过错误移动下一个，增加参数如下，然后重启replicat
MAXTRANSOPS 1 GROUPTRANSOPS 1
如果还有问题可以使用logdump查找下一个seqno和rba, 指定位置跳过事务
./logdump open ghdr on detail on pos xxx scanforheader ALTER REPLICAT xx, EXTSEQNO xxx ,EXTRBA xxx start replicat
在 OGG 12.2 之前，从 trail文件损坏中恢复需要很多步骤，非常繁琐，如果步骤中的任何一个错误都会导致数据完整性问题，并且复制将会混乱，如下：
1, 如记下目标的上次应用的 SCN 和时间戳;
2, 在源中，扫描此Last Applied SCN 的trail文件;
3, 通过更改Pump Extract来重新提取此 SCN 后的数据;
4, 更改 Replicat 进程以从 New Trail Seq# 中读取;
5, 启动 Pump 和 Replicat 进程;
从 Oracle GoldenGate 12.2 开始，引入了一项名为“Automated Remote Trail File Recovery”的新功能。 对于remote trail file损毁的方法恢复真的很方便，以下是步骤:
1. 首先最重要的是停止源端的Pump进程。
2. 首先从损坏的 seq# 开始删除(or rename)所有跟踪文件。
3. 在源中启动 Pump 进程，现在 Extract Pump可以自动重建丢失的trail文件。
4. 启动Replicat 进程。
如果trail是有extract写入，pump读取时报错，一种是使用extract从事务的开始重新生成trail， 但是找当前事务的开始比较麻烦，因为当前报错的位置是一个事务的中间而且是个bad recored, 很难定位到事务的最开始（TransInd : . (x00)）,并且对于集成模式的extract(因为一些前提条件)不允许修改，从之前的时间重新抽取；另一种是查找到可以read的下一个正常的record事务的开始，跳过中间的错误record, 但是这种会有少量事务的不一致，需要对数据要求严格的环境后期手动对比校验。 这个案例我们处理是跳到下一个正常的extract trail，让pump继续传输。
处理方法
使用logdump工具查找下一条记录postition， 通常需要跳过bad recored当前文件，可能发生在pump或replicat进程.
$ ./logdump Oracle GoldenGate Log File Dump Utility for Oracle Version 18.1.0.0.0 OGGCORE_18.1.0.0.0_PLATFORMS_181128.2000 Copyright (C) 1995, 2018, Oracle and/or its affiliates. All rights reserved. Logdump 437 >open /OGG_DATA/ogg/dirdat/anbob/dv000153846 ghdr on Current LogTrail is /OGG_DATA/ogg/dirdat/anbob/dv000153846 Logdump 438 > Logdump 439 >detail on Logdump 440 >detail data Logdump 441 >ggstoken on Logdump 442 >ggstoken detail Logdump 443 >usertoken on Logdump 444 >usertoken detail Logdump 445 >reclen 5000 Reclen set to 5000 Logdump 446 > count -- COUNT命令可以验证这个trail中是否有corrupted记录 Logdump 506 >pos 198115192 --错误日志中报错的位置 Bad record found at (RBA 396230384, format 5.50 Unknown TokenID 00) 4701 00be 4800 0024 450c 0041 006e 05ff 02f3 314f | G...H..$E..A.n....1O 4434 4940 0000 0000 08b1 3b60 0009 2181 0152 0000 | D4I@......;`..!..R.. 0001 0001 4400 006e 0000 000d 0000 0009 3832 3738 | ....D..n........8278 3737 3534 3700 0100 1000 0000 0c37 3738 4833 5930 | 77547........778H3Y0 3031 3341 3300 0200 1700 0000 1342 435f 5052 4553 | 013A3........BC_PRES 5355 5245 5f53 4554 5f53 5433 0003 0007 0000 0003 | SURE_SET_ST3........ 3030 3100 0400 0500 0000 012d 0005 000a 0000 0000 | 001........-........ 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 | .................... 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 | .................... 0000 0000 0000 0000 0000 | .......... Reading forward from RBA 198115192 Logdump 508 >sfh prev Bad record found at (RBA 198115192, format 5.50 Unknown TokenID 00) 4701 00be 4800 0024 450c 0041 006e 05ff 02f3 314f | G...H..$E..A.n....1O 4434 4940 0000 0000 08b1 3b60 0009 2181 0152 0000 | D4I@......;`..!..R.. 0001 0001 4400 006e 0000 000d 0000 0009 3832 3738 | ....D..n........8278 3737 3534 3700 0100 1000 0000 0c37 3738 4833 5930 | 77547........778H3Y0 3031 3341 3300 0200 1700 0000 1342 435f 5052 4553 | 013A3........BC_PRES 5355 5245 5f53 4554 5f53 5433 0003 0007 0000 0003 | SURE_SET_ST3........ 3030 3100 0400 0500 0000 012d 0005 000a 0000 0000 | 001........-........ 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 | .................... 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 | .................... 0000 0000 0000 0000 0000 | .......... Logdump 491 >pos 198115192 Reading forward from RBA 198115192 Logdump 492 >sfh Bad record found at (RBA 198115192, format 5.50 Unknown TokenID 00) 4701 00be 4800 0024 450c 0041 006e 05ff 02f3 314f | G...H..$E..A.n....1O 4434 4940 0000 0000 08b1 3b60 0009 2181 0152 0000 | D4I@......;`..!..R.. 0001 0001 4400 006e 0000 000d 0000 0009 3832 3738 | ....D..n........8278 3737 3534 3700 0100 1000 0000 0c37 3738 4833 5930 | 77547........778H3Y0 3031 3341 3300 0200 1700 0000 1342 435f 5052 4553 | 013A3........BC_PRES 5355 5245 5f53 4554 5f53 5433 0003 0007 0000 0003 | SURE_SET_ST3........ 3030 3100 0400 0500 0000 012d 0005 000a 0000 0000 | 001........-........ 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 | .................... 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 | .................... 0000 0000 0000 0000 0000
Note：
可见使用sfh查看前后记录的header 都是错误记录。
SCANFORHEADER
Use SCANFORHEADER to go to the next record header. Before using this command, use the GHDR ON command to show record headers (see “GHDR”). SCANFORHEADER can be
shortened to SFH. PREV Displays the previous record header
SCANFORENDTRANS
Use SCANFORENDTRANS to scan for a record that has a transaction indicator of 2 or 3,as shown in the TransInd field of the header. When one of those indicators is found,Logdump displays the first record of the next transaction.The indicators represent the following:
• 2 — last record in the transaction
• 3 — only record in the transaction
SCANFORENDTRANS can be shortened to SFET.
向后手动指定位置
Logdump 493 >pos 198116000 Bad record found at (RBA 198116000, format 5.50 Unknown TokenID 00) Logdump 494 >sfh ___________________________________________________________________ Hdr-Ind : E (x45) Partition : . (x0c) UndoFlag : . (x00) BeforeAfter: A (x41) RecLength : 104 (x0068) IO Time : 2023/11/27 13:45:33.000.000 IOType : 5 (x05) OrigNode : 255 (xff) TransInd : . (x01) FormatType : R (x52) SyskeyLen : 0 (x00) Incomplete : . (x00) AuditRBA : 598401 AuditPos : 145832800 Continued : N (x00) RecCount : 1 (x01) 2023/11/27 13:45:33.000.000 Insert Len 104 RBA 198131791
Note：
手动向后移了一些RBA后可以取到下一个记录head，但是注意TransInd (x01)说明是个事务中间值， 如果修改为这个位置，启动pump会提示如下错误
Transaction Indicator Description:
TransInd : . (x00) First statement in transaction
TransInd : . (x01) Statement in middle of transaction
Translnd : .(x02) last statement in transaction
Translnd : . (x03) Sole statement in transaction
Source Context :
SourceModule : [er.extract.recovery]
SourceID : [/scratch/jkrath/view_storage/jkrath_ogghp181128vw/oggcore/OpenSys/src/app/er/extract/extrecovery.cpp]
SourceMethod : [EXTRECOVERY_shouldWriteTran]
SourceLine : [1218]
2023-11-27 18:19:59 ERROR OGG-01061 Invalid CSN value length(0) from data source during recovery.
Note:
OGG-01061 ,因为pump stopped/abended时的record 是middle of a tansacton,所以会提示上面的错误， 要找到下一个事务的开始位置TransInd:x00 的RBA，然后再启动。 我们继续查找.
Logdump 495 >SCANFORENDTRANS End of Transaction found at RBA 198187887 ___________________________________________________________________ Hdr-Ind : E (x45) Partition : . (x0c) UndoFlag : . (x00) BeforeAfter: A (x41) RecLength : 103 (x0067) IO Time : 2023/11/27 13:45:33.000.000 IOType : 5 (x05) OrigNode : 255 (xff) TransInd : . (x02) FormatType : R (x52) SyskeyLen : 0 (x00) Incomplete : . (x00) AuditRBA : 598401 AuditPos : 146039576 Continued : N (x00) RecCount : 1 (x01) Logdump 496 >n ___________________________________________________________________ Hdr-Ind : E (x45) Partition : . (x0c) UndoFlag : . (x00) BeforeAfter: A (x41) RecLength : 354 (x0162) IO Time : 2023/11/27 13:45:33.000.000 IOType : 5 (x05) OrigNode : 255 (xff) TransInd : . (x00) FormatType : R (x52) SyskeyLen : 0 (x00) Incomplete : . (x00) AuditRBA : 598401 AuditPos : 146080784 Continued : N (x00) RecCount : 1 (x01) 2023/11/27 13:45:33.000.000 Insert Len 354 RBA 198188070
Note:
我们使用SCANFORENDTRANS直接跳到事务结束，然后n取下一条记录.这就是最近的事务开始的RBA位置(trail文件的偏移量). 然后修改pump位置。
GGSCI (anbob2) 7> alter DP_DB extseqno 153846 extrba 198188070
EXTRACT altered.
GGSCI (anbob2) 8> start DP_DB
Sending START request to MANAGER ...
EXTRACT DP_DB starting
GGSCI (anbob2) 14> info DP_DB
EXTRACT DP_DB Last Started 2023-11-27 19:46 Status RUNNING
Checkpoint Lag 05:57:01 (updated 00:00:07 ago)
Process ID 3161
Log Read Checkpoint File /OGG_DATA/ogg/dirdat/anbob/dv000153847
2023-11-27 13:50:07.000000 RBA 135172003
Note：
已经恢复正常。
同样如果尝试向前可以extract的位置，重新extract，也可以手动向前尝试减少几个rba值,如报错是198115192， 我们向前定位到198115152
Logdump 553 >pos 198115152 Bad record found at (RBA 396230344, format 5.50 Unknown TokenID 00) 4701 00be 4800 0024 450c 0041 006e 05ff 02f3 314f | G...H..$E..A.n....1O 4434 4940 0000 0000 08b1 3b60 0009 2181 0152 0000 | D4I@......;`..!..R.. 0001 0001 4400 006e 0000 000d 0000 0009 3832 3738 | ....D..n........8278 3737 3534 3700 0100 1000 0000 0c37 3738 4833 5930 | 77547........778H3Y0 3031 3341 3300 0200 1700 0000 1342 435f 5052 4553 | 013A3........BC_PRES 5355 5245 5f53 4554 5f53 5433 0003 0007 0000 0003 | SURE_SET_ST3........ 3030 3100 0400 0500 0000 012d 0005 000a 0000 0000 | 001........-........ 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 | .................... 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000 | .................... 0000 0000 0000 0000 0000 | .......... Reading forward from RBA 198115152 Logdump 554 >sfh prev ___________________________________________________________________ Hdr-Ind : E (x45) Partition : . (x0c) UndoFlag : . (x00) BeforeAfter: A (x41) RecLength : 104 (x0068) IO Time : 2023/11/27 13:45:33.000.000 IOType : 5 (x05) OrigNode : 255 (xff) TransInd : . (x01) FormatType : R (x52) SyskeyLen : 0 (x00) Incomplete : . (x00) AuditRBA : 598401 AuditPos : 145832800 Continued : N (x00) RecCount : 1 (x01) 2023/11/27 13:45:33.000.000 Insert Len 104 RBA 198115008 Logdump 451 >pos 198000000 Reading forward from RBA 198000000 Logdump 452 >sfh Logdump 461 >SCANFORENDTRANS End of Transaction found at RBA 198052040 ___________________________________________________________________ Hdr-Ind : E (x45) Partition : . (x0c) UndoFlag : . (x00) BeforeAfter: A (x41) RecLength : 99 (x0063) IO Time : 2023/11/27 13:45:33.000.000 IOType : 5 (x05) OrigNode : 255 (xff) TransInd : . (x02) FormatType : R (x52) SyskeyLen : 0 (x00) Incomplete : . (x00) AuditRBA : 598401 AuditPos : 145357168 Continued : N (x00) RecCount : 1 (x01) 2023/11/27 13:45:33.000.000 Insert Len 99 RBA 198052040 Logdump 462 >n ___________________________________________________________________ Hdr-Ind : E (x45) Partition : . (x0c) UndoFlag : . (x00) BeforeAfter: A (x41) RecLength : 352 (x0160) IO Time : 2023/11/27 13:45:33.000.000 IOType : 5 (x05) OrigNode : 255 (xff) TransInd : . (x00) FormatType : R (x52) SyskeyLen : 0 (x00) Incomplete : . (x00) AuditRBA : 598401 AuditPos : 145383440 Continued : N (x00) RecCount : 1 (x01) 2023/11/27 13:45:33.000.000 Insert Len 352 RBA 198052219 ... GGS tokens: TokenID x52 'R' ORAROWID Info x00 Length 20 4141 426a 4b31 4144 3641 4148 6961 4941 4150 0001 | AABjK1AD6AAHiaIAAP.. TokenID x4c 'L' LOGCSN Info x00 Length 14 3133 3936 3531 3935 3431 3036 3039 | 13965195410609 TokenID x36 '6' TRANID Info x00 Length 15 302e 3430 322e 3237 2e38 3333 3331 35 | 0.402.27.833315 TokenID x69 'i' ORATHREADID Info x01 Length 2 0001 | ..
如果我们找到了前一个事务，尝试修改EXTRACT重新生成trail文件。
GGSCI (anbob2) 9> alter EX_db ETROLLOVER 2023-11-27 19:32:23 INFO OGG-01520 Rollover performed. For each affected output trail of Version 10 or higher format, after starting the source extract, issue ALTER EXTSEQNO for that trail's reader (either pump EXTRACT or REPLICAT) to move the reader's scan to the new trail file; it will not happen automatically. EXTRACT altered. GGSCI (anbob2) 10> alter EX_db ,scn 13965195410609 ERROR: Not logged into database, use DBLOGIN. GGSCI (anbob2) 12> dblogin useridalias ggs Successfully logged into database. GGSCI (anbob2 as ggs@anbob2) 14> alter EXTRACT EX_DV , SCN 13965195410609 ERROR: Extract EX_DV can not be positioned to SCN 13965195410609.
Note：
如果提取试图更改 FIRST_SCN 之前的读取检查点，则将报告以上错误，ogg有一个增强请求允许未来版本中的 IE(集成模式抽取进程)定位在 FIRST_SCN 之前，即使存在存档日志，集成的提取也无法 定位读取 FIRST_SCN 之前的旧数据
查找集成提取的first_scn：
select first_scn from dba_capture where capture_name = OGG$CAP_<extract name>
一旦 FIRST_SCN 前进，IE 就无法重新定位到该 SCN 之前。根据 TRANLOGOPTIONS CHECKPOINTRETENTIONTIME 参数提前 FIRST_SCN 值。 GA 版本上此参数的默认值为 60 天。 在最新版本 11.2.1.0.1 上，该时间为 1 天。
总结：
该案例中对于pump extract读取的trace文件损坏，因为是集成模式(IE)，当前模式我们没有办法修改EXTRACT从问题前抽取，也只能修改pump extract跳过trail 中corrupted 记录。 另外因为在尝试extract重新抽取前做了ETROLLOVER，所以记的要手动修改下游的datapump进程指定到新的trail file，否则可能会出现进程一直running停留在ETrollover的配置， 方法如下
ALTER EXTRACT DP_DB EXTSEQNO 153898 EXTRBA 0
微信扫一扫，打赏作者吧～
对不起，这篇文章暂时关闭评论。