Re: Logical decoding restart problems - Mailing list pgsql-hackers

On 19/08/16 18:36, Konstantin Knizhnik wrote:
>
>
> On 19.08.2016 19:06, Petr Jelinek wrote:
>>
>> I don't think this will work correctly, there will be gap between when
>> the new slot starts to decode and the drop of the old one as the new
>> slot first needs to make snapshot.
>>
>> Do I understand correctly that you are not using replication origins?
>
> No, we are using replication origins to prevent recursive replication.
> The gap is not a biggest problem because in multimaster we commit only
> those transaction which are acknowledged by all live nodes.
> So if some transaction falls in the gap... it is unlucky and will be
> aborted.
>

Ah okay, forgot you have sync MM.

>>
>>> The problem is that for some reasons consistent point is not so
>>> consistent and we get partly decoded transactions.
>>> I.e. transaction body consists of two UPDATE but reorder_buffer extracts
>>> only the one (last) update and sent this truncated transaction to
>>> destination causing consistency violation at replica.  I started
>>> investigation of logical decoding code and found several things which I
>>> do not understand.
>>
>> Never seen this happen. Do you have more details about what exactly is
>> happening?
>>
>
> This is transaction at primary node:
>
> root@knizhnik:/home/knizhnik/postgres_cluster/contrib/mmts# docker exec
> -ti node1 bash
> postgres@9a04a0c9f246:/pg$  pg_xlogdump
> data/pg_xlog/000000010000000000000001  | fgrep "tx: 6899"
> rmgr: Heap        len (rec/tot):      7/    53, tx:       6899, lsn:
> 0/019EFBD8, prev 0/019EFB80, desc: LOCK off 12: xid 6899 LOCK_ONLY
> EXCL_LOCK , blkref #0: rel 1663/12407/16421 blk 60
> rmgr: Heap        len (rec/tot):     14/    74, tx:       6899, lsn:
> 0/019EFC10, prev 0/019EFBD8, desc: HOT_UPDATE off 12 xmax 6899 ; new off
> 224 xmax 6899, blkref #0: rel 1663/12407/16421 blk 60
> rmgr: Heap        len (rec/tot):      7/    53, tx:       6899, lsn:
> 0/019EFC60, prev 0/019EFC10, desc: LOCK off 153: xid 6899 LOCK_ONLY
> EXCL_LOCK , blkref #0: rel 1663/12407/16421 blk 49
> rmgr: Heap        len (rec/tot):     14/    82, tx:       6899, lsn:
> 0/019EFC98, prev 0/019EFC60, desc: UPDATE off 153 xmax 6899 ; new off 55
> xmax 6899, blkref #0: rel 1663/12407/16421 blk 62, blkref #1: rel
> 1663/12407/16421 blk 49
> rmgr: Btree       len (rec/tot):      2/    64, tx:       6899, lsn:
> 0/019EFCF0, prev 0/019EFC98, desc: INSERT_LEAF off 294, blkref #0: rel
> 1663/12407/16424 blk 23
> rmgr: Transaction len (rec/tot):    236/   265, tx:       6899, lsn:
> 0/019EFD30, prev 0/019EFCF0, desc: PREPARE
> pg_xlogdump: FATAL:  error in WAL record at 0/1AC0E70: invalid record
> length at 0/1AC0EA8: wanted 24, got 0
>
>
> This is the replicated transaction at other node (it is ont clear from
> the trace, but believe me, it is the same transaction):
>
>
> root@knizhnik:/home/knizhnik/postgres_cluster/contrib/mmts# docker exec
> -ti node2 bash
> postgres@e5b16d82ce06:/pg$ pg_xlogdump
> data/pg_xlog/000000010000000000000001  | fgrep "tx:       6882"
> rmgr: Heap        len (rec/tot):     14/    74, tx:       6882, lsn:
> 0/019F3240, prev 0/019F31F0, desc: HOT_UPDATE off 113 xmax 6882 ; new
> off 219 xmax 0, blkref #0: rel 1663/12407/16421 blk 53
> rmgr: Heap        len (rec/tot):     14/    82, tx:       6882, lsn:
> 0/019F5CB8, prev 0/019F5C60, desc: UPDATE off 163 xmax 6882 ; new off 4
> xmax 0, blkref #0: rel 1663/12407/16421 blk 62, blkref #1: rel
> 1663/12407/16421 blk 51
> rmgr: Btree       len (rec/tot):      2/    64, tx:       6882, lsn:
> 0/019F5D10, prev 0/019F5CB8, desc: INSERT_LEAF off 284, blkref #0: rel
> 1663/12407/16424 blk 23
> rmgr: Transaction len (rec/tot):    248/   274, tx:       6882, lsn:
> 0/019F61F8, prev 0/019F60E8, desc: PREPARE
> pg_xlogdump: FATAL:  error in WAL record at 0/1AD3AD8: invalid record
> length at 0/1AD3B10: wanted 24, got 0
>
>
> And "shorten" version of the same transaction at the third (recovered)
> node:
>
> root@knizhnik:/home/knizhnik/postgres_cluster/contrib/mmts# docker exec
> -ti node3 bash
> postgres@b4066d4211bc:/pg$  pg_xlogdump
> data/pg_xlog/000000010000000000000001  | fgrep "tx: 6893"
> rmgr: Heap        len (rec/tot):      7/    53, tx:       6893, lsn:
> 0/01A29828, prev 0/01A297E0, desc: LOCK off 172: xid 6893 LOCK_ONLY
> EXCL_LOCK , blkref #0: rel 1663/12407/16421 blk 50
> rmgr: Heap        len (rec/tot):     14/    82, tx:       6893, lsn:
> 0/01A29860, prev 0/01A29828, desc: UPDATE+INIT off 172 xmax 6893 ; new
> off 1 xmax 6893, blkref #0: rel 1663/12407/16421 blk 64, blkref #1: rel
> 1663/12407/16421 blk 50
> rmgr: Btree       len (rec/tot):      2/    64, tx:       6893, lsn:
> 0/01A298B8, prev 0/01A29860, desc: INSERT_LEAF off 314, blkref #0: rel
> 1663/12407/16424 blk 23
> rmgr: Transaction len (rec/tot):    236/   265, tx:       6893, lsn:
> 0/01A298F8, prev 0/01A298B8, desc: PREPARE
> pg_xlogdump: FATAL:  error in WAL record at 0/1ACBBF8: invalid record
> length at 0/1ACBC30: wanted 24, got 0
>
> You can see one update instead of two.
>
> Sorry, I have not saved trace  with output of logical decoder. Bu t it
> really decodes just one update!
> What I have done:
>
> DROP_REPLICATION_SLOT "mtm_slot_1";
> CREATE_REPLICATION_SLOT "mtm_slot_1" LOGICAL "multimaster";
> START_REPLICATION SLOT "mtm_slot_1" LOGICAL 0/0 ("startup_params_format"
> '1', "max_proto_version" '1', "min_proto_version" '1',
> "forward_changesets" '1', "mtm_replication_mode" 'recovered');
>
> I have also tried to calculate last origin LSN for this node and
> explicitly specify it in START_REPLICATION.
> But it doesn't help: the same problem persists.
>

Well okay, that says that there was different number of UPDATEs on the 
subscriber, but that does not mean that it's fault of decoding. The 
difference in WAL on downstream can be for example because it didn't 
find matching key for update due to some other desync issue. You'll need 
to check what the output plugin outputs and go from there. If you have 
some reproducible use-case/script I can help debugging it.

--   Petr Jelinek                  http://www.2ndQuadrant.com/  PostgreSQL Development, 24x7 Support, Training &
Services