Re: BUG #16125: Crash of PostgreSQL's wal sender during logical replication

Hi,

> Can you create a core dump (see [1]), and print 'change' and 'txn' in
> frame #2? I wonder if some the other fields are bogus too (but it can't
> be entirely true ...), and if the transaction got serialized.
>
> You may need to install debug symbols first, BTW.

I hope that I've understood how to extract correctly those data

(gdb) frame 2
#2 ReorderBufferCommit (rb=0x555713b7b788, xid=xid(at)entry=1667601527, commit_lsn=commit_lsn(at)entry=41707737345720, end_lsn=end_lsn(at)entry=41707737345792, commit_time=commit_time(at)entry=627188499326201,
origin_id=origin_id(at)entry=0, origin_lsn=0) at ./build/../src/backend/replication/logical/reorderbuffer.c:1585
1585 ./build/../src/backend/replication/logical/reorderbuffer.c: No such file or directory.
(gdb) print change
$1 = (ReorderBufferChange *) 0x555713b9a108
(gdb) print *change
$2 = {lsn = 41707737330608, action = REORDER_BUFFER_CHANGE_DELETE, origin_id = 0, data = {tp = {relnode = {spcNode = 1663, dbNode = 13018, relNode = 88964815}, clear_toast_afterwards = 1 '\001', oldtuple = 0x555713cd0d88,
newtuple = 0x0}, msg = {prefix = 0x32da0000067f <error: Cannot access memory at address 0x32da0000067f>, message_size = 4383932111, message = 0x555713cd0d88 "\330-\315\023WU"}, snapshot = 0x32da0000067f,
command_id = 1663, tuplecid = {node = {spcNode = 1663, dbNode = 13018, relNode = 88964815}, tid = {ip_blkid = {bi_hi = 1, bi_lo = 0}, ip_posid = 3464}, cmin = 21847, cmax = 0, combocid = 0}}, node = {
prev = 0x555713b98178, next = 0x555713b98178}}
(gdb) print txn
$3 = (ReorderBufferTXN *) 0x555713b982e8
(gdb) print *txn
$6 = {xid = 1667601527, has_catalog_changes = 0 '\000', is_known_as_subxact = 0 '\000', toplevel_xid = 0, first_lsn = 41707730043960, final_lsn = 41707737345720, end_lsn = 41707737345792, restart_decoding_lsn = 0,
origin_id = 0, origin_lsn = 0, commit_time = 627188499326201, base_snapshot = 0x555713b90408, base_snapshot_lsn = 41707730047464, base_snapshot_node = {prev = 0x555713b7b7a0, next = 0x555713b7b7a0}, nentries = 0,
nentries_mem = 0, serialized = 0 '\000', changes = {head = {prev = 0x555713b98368, next = 0x555713b98368}}, tuplecids = {head = {prev = 0x555713b98378, next = 0x555713b98378}}, ntuplecids = 0, tuplecid_hash = 0x0,
toast_hash = 0x555714ad0fb8, subtxns = {head = {prev = 0x555713b985b0, next = 0x555713b984b8}}, nsubtxns = 4, ninvalidations = 0, invalidations = 0x0, node = {prev = 0x555713b7b790, next = 0x555713b7b790}}

> Do you see it on different PostgreSQL instances? Can you share the
> schema definition?

Unfortunately I can't do it completely, but there are
List of installed extensions
Name | Version | Schema | Description
-----------+---------+------------+--------------------------------
pgcrypto | 1.3 | public | cryptographic functions
pglogical | 2.2.1 | pglogical | PostgreSQL Logical Replication
plpgsql | 1.0 | pg_catalog | PL/pgSQL procedural language

And each table in publication has next structure:
1 jsonb field, and few smallint, integer, bigint fields. No one table has any triggers or special constraints, only primary key and one or two btree indexes.

> Well, if you can create a reproducer, that'd be the best option, because
> then we can investigate locally instead of the ping-ping here.

I will try to do it.

> I'd also like to see the contents of the WAL, particularly for the XID
> triggering this issue. Please run pg_waldump and see how much data is
> there for XID 1667601527. It does commit at 25EE/D6DE6EB8, not sure
> where it starts. It may have subtransactions, so don't do just grep.

Hm, it looks like I do not have wal with start of transaction, but I've found next records using txid and subxacts. I hope it will be useful.

2514:rmgr: Transaction len (rec/tot): 38/ 38, tx: 0, lsn: 25EE/D66F0438, prev 25EE/D66F0410, desc: ASSIGNMENT xtop 1667601527: subxacts: 1667601528
2518:rmgr: Heap len (rec/tot): 2063/ 2063, tx: 1667601530, lsn: 25EE/D66F11E8, prev 25EE/D66F0CB0, desc: INSERT off 4, blkref #0: rel 1663/13018/88964795 blk 3125
2520:rmgr: Btree len (rec/tot): 64/ 64, tx: 1667601530, lsn: 25EE/D66F1A38, prev 25EE/D66F19F8, desc: INSERT_LEAF off 256, blkref #0: rel 1663/13018/88964797 blk 15840
2522:rmgr: Heap len (rec/tot): 1341/ 9385, tx: 1667601530, lsn: 25EE/D66F2118, prev 25EE/D66F1A78, desc: INSERT off 7, blkref #0: rel 1663/13018/88964795 blk 3139 FPW
2524:rmgr: Btree len (rec/tot): 64/ 64, tx: 1667601530, lsn: 25EE/D66F54C8, prev 25EE/D66F45E0, desc: INSERT_LEAF off 257, blkref #0: rel 1663/13018/88964797 blk 15840
2525:rmgr: Heap len (rec/tot): 1671/ 1671, tx: 1667601530, lsn: 25EE/D66F5508, prev 25EE/D66F54C8, desc: INSERT off 2, blkref #0: rel 1663/13018/88964792 blk 18475
2527:rmgr: Btree len (rec/tot): 64/ 64, tx: 1667601530, lsn: 25EE/D66F6738, prev 25EE/D66F5B90, desc: INSERT_LEAF off 140, blkref #0: rel 1663/13018/88964798 blk 2058
2530:rmgr: Btree len (rec/tot): 96/ 96, tx: 1667601530, lsn: 25EE/D66F7E40, prev 25EE/D66F7E10, desc: INSERT_LEAF off 28, blkref #0: rel 1663/13018/88964799 blk 5076
2531:rmgr: Btree len (rec/tot): 80/ 80, tx: 1667601530, lsn: 25EE/D66F7EA0, prev 25EE/D66F7E40, desc: INSERT_LEAF off 88, blkref #0: rel 1663/13018/88964800 blk 3412
2532:rmgr: Heap len (rec/tot): 54/ 54, tx: 1667601530, lsn: 25EE/D66F7EF0, prev 25EE/D66F7EA0, desc: DELETE off 2 , blkref #0: rel 1663/13018/88964792 blk 18475
2533:rmgr: Heap len (rec/tot): 54/ 54, tx: 1667601530, lsn: 25EE/D66F7F28, prev 25EE/D66F7EF0, desc: DELETE off 4 , blkref #0: rel 1663/13018/88964795 blk 3125
2534:rmgr: Heap len (rec/tot): 54/ 54, tx: 1667601530, lsn: 25EE/D66F7F60, prev 25EE/D66F7F28, desc: DELETE off 7 , blkref #0: rel 1663/13018/88964795 blk 3139
56346:rmgr: Heap len (rec/tot): 378/ 8198, tx: 1667601537, lsn: 25EE/D6DE33B0, prev 25EE/D6DE1628, desc: DELETE off 6 KEYS_UPDATED , blkref #0: rel 1663/13018/88964815 blk 1938695 FPW
56347:rmgr: Heap len (rec/tot): 54/ 54, tx: 1667601538, lsn: 25EE/D6DE53D0, prev 25EE/D6DE33B0, desc: LOCK off 5: xid 1667601538: flags 0 LOCK_ONLY EXCL_LOCK , blkref #0: rel 1663/13018/88964792 blk 18460
56348:rmgr: Heap len (rec/tot): 6563/ 6563, tx: 1667601538, lsn: 25EE/D6DE5408, prev 25EE/D6DE53D0, desc: UPDATE off 5 xmax 1667601538 ; new off 3 xmax 0, blkref #0: rel 1663/13018/88964792 blk 18499, blkref #1: rel 1663/13018/88964792 blk 18460
56349:rmgr: Btree len (rec/tot): 64/ 64, tx: 1667601538, lsn: 25EE/D6DE6DC8, prev 25EE/D6DE5408, desc: INSERT_LEAF off 140, blkref #0: rel 1663/13018/88964798 blk 2058
56350:rmgr: Btree len (rec/tot): 96/ 96, tx: 1667601538, lsn: 25EE/D6DE6E08, prev 25EE/D6DE6DC8, desc: INSERT_LEAF off 28, blkref #0: rel 1663/13018/88964799 blk 5076
56351:rmgr: Btree len (rec/tot): 80/ 80, tx: 1667601538, lsn: 25EE/D6DE6E68, prev 25EE/D6DE6E08, desc: INSERT_LEAF off 88, blkref #0: rel 1663/13018/88964800 blk 3412
56352:rmgr: Transaction len (rec/tot): 66/ 66, tx: 1667601527, lsn: 25EE/D6DE6EB8, prev 25EE/D6DE6E68, desc: COMMIT 2019-11-16 03:01:39.326201 UTC; subxacts: 1667601528 1667601530 1667601537 1667601538

Regards,
Andrey.