Re: Logical decoding restart problems

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.

>
>> 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(at)knizhnik:/home/knizhnik/postgres_cluster/contrib/mmts# docker exec
-ti node1 bash
postgres(at)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(at)knizhnik:/home/knizhnik/postgres_cluster/contrib/mmts# docker exec
-ti node2 bash
postgres(at)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(at)knizhnik:/home/knizhnik/postgres_cluster/contrib/mmts# docker exec
-ti node3 bash
postgres(at)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.

--
Konstantin Knizhnik
Postgres Professional: http://www.postgrespro.com
The Russian Postgres Company