Re: crash while decoding INSERT ON CONFLICT

Hi,

On 2018-05-21 12:52:09 -0300, Euler Taveira wrote:
> Hi,
>
> I got the following backtrace in a logical replication setup using 10.3.
>
> Program terminated with signal 11, Segmentation fault.
> #0 ReorderBufferCommit (rb=0xde2a08, xid=<value optimized out>,
> commit_lsn=6211559254952, end_lsn=<value optimized out>,
> commit_time=<value optimized out>, origin_id=<value optimized out>,
> origin_lsn=0) at reorderbuffer.c:1397
> 1397 change->action =
> REORDER_BUFFER_CHANGE_INSERT;
> Missing separate debuginfos, use: debuginfo-install
> glibc-2.12-1.209.el6_9.2.x86_64 libxml2-2.7.6-21.el6_8.1.x86_64
> zlib-1.2.3-29.el6.x86_64
> (gdb) bt
> #0 ReorderBufferCommit (rb=0xde2a08, xid=<value optimized out>,
> commit_lsn=6211559254952, end_lsn=<value optimized out>,
> commit_time=<value optimized out>, origin_id=<value optimized out>,
> origin_lsn=0) at reorderbuffer.c:1397
> #1 0x00000000006bdd58 in DecodeCommit (ctx=0xdbe888, record=<value
> optimized out>) at decode.c:611
> #2 DecodeXactOp (ctx=0xdbe888, record=<value optimized out>) at decode.c:241
> #3 LogicalDecodingProcessRecord (ctx=0xdbe888, record=<value
> optimized out>) at decode.c:113
> #4 0x00000000006d0754 in XLogSendLogical () at walsender.c:2781
> #5 0x00000000006cf782 in WalSndLoop (send_data=0x6d0700
> <XLogSendLogical>) at walsender.c:2149
> #6 0x00000000006d1463 in StartLogicalReplication (cmd_string=<value
> optimized out>) at walsender.c:1102
> #7 exec_replication_command (cmd_string=<value optimized out>) at
> walsender.c:1539
> #8 0x00000000007182b9 in PostgresMain (argc=<value optimized out>,
> argv=<value optimized out>, dbname=0xd368a8 "foo", username=<value
> optimized out>) at postgres.c:4084
> #9 0x00000000006ad27d in BackendRun (argc=<value optimized out>,
> argv=<value optimized out>) at postmaster.c:4405
> #10 BackendStartup (argc=<value optimized out>, argv=<value optimized
> out>) at postmaster.c:4077
> #11 ServerLoop (argc=<value optimized out>, argv=<value optimized
> out>) at postmaster.c:1755
> #12 PostmasterMain (argc=<value optimized out>, argv=<value optimized
> out>) at postmaster.c:1363
> #13 0x000000000062e5b0 in main (argc=3, argv=0xd04540) at main.c:228
> (gdb) p change
> $1 = (ReorderBufferChange *) 0x0
> (gdb) p specinsert
> $2 = (ReorderBufferChange *) 0x0
>
> If my math is correct the lsn 6211559254952 is 5A6/3DC86BA8. The transaction is:
>
> rmgr: Btree len (rec/tot): 3795/ 11731, tx: 144441221, lsn:
> 5A6/3DC80B58, prev 5A6/3DC80B28, desc: SPLIT_R level 0, firstright
> 139, blkref #0: rel 1663/355309/54931968 blk 176078, blkref #1: rel
> 1663/355309/54931968 blk 223615, blkref #2: rel 1663/355309/54931968
> blk 176079 FPW
> rmgr: Btree len (rec/tot): 61/ 4481, tx: 144441221, lsn:
> 5A6/3DC83948, prev 5A6/3DC80B58, desc: INSERT_UPPER off 39, blkref #0:
> rel 1663/355309/54931968 blk 176062 FPW, blkref #1: rel
> 1663/355309/54931968 blk 176078
> rmgr: Btree len (rec/tot): 72/ 72, tx: 144441221, lsn:
> 5A6/3DC84AE8, prev 5A6/3DC83948, desc: INSERT_LEAF off 2, blkref #0:
> rel 1663/355309/57252673 blk 218754
> rmgr: Btree len (rec/tot): 53/ 7613, tx: 144441221, lsn:
> 5A6/3DC84B30, prev 5A6/3DC84AE8, desc: INSERT_LEAF off 129, blkref #0:
> rel 1663/355309/57252674 blk 23008 FPW
> rmgr: Btree len (rec/tot): 64/ 64, tx: 144441221, lsn:
> 5A6/3DC86908, prev 5A6/3DC84B30, desc: INSERT_LEAF off 71, blkref #0:
> rel 1663/355309/57252998 blk 156099
> rmgr: Btree len (rec/tot): 72/ 72, tx: 144441221, lsn:
> 5A6/3DC86948, prev 5A6/3DC86908, desc: INSERT_LEAF off 210, blkref #0:
> rel 1663/355309/57253000 blk 219630
> rmgr: Heap len (rec/tot): 48/ 48, tx: 144441221, lsn:
> 5A6/3DC86990, prev 5A6/3DC86948, desc: HEAP_CONFIRM off 5, blkref #0:
> rel 1663/355309/382872 blk 5520503
> rmgr: Heap len (rec/tot): 54/ 54, tx: 144441221, lsn:
> 5A6/3DC869C0, prev 5A6/3DC86990, desc: LOCK off 8: xid 144441221:
> flags 0 LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/355309/42286702
> blk 0
> rmgr: Heap len (rec/tot): 54/ 54, tx: 144441221, lsn:
> 5A6/3DC869F8, prev 5A6/3DC869C0, desc: LOCK off 1: xid 144441221:
> flags 0 LOCK_ONLY KEYSHR_LOCK , blkref #0: rel 1663/355309/42323652
> blk 0
> rmgr: Heap len (rec/tot): 54/ 54, tx: 144441221, lsn:
> 5A6/3DC86A30, prev 5A6/3DC869F8, desc: LOCK off 23: xid 144441221:
> flags 0 LOCK_ONLY EXCL_LOCK , blkref #0: rel 1663/355309/382874 blk
> 4688787
> rmgr: Heap len (rec/tot): 211/ 211, tx: 144441221, lsn:
> 5A6/3DC86A68, prev 5A6/3DC86A30, desc: HOT_UPDATE off 23 xmax
> 144441221 ; new off 24 xmax 144441221, blkref #0: rel
> 1663/355309/382874 blk 4688787
> rmgr: Heap len (rec/tot): 98/ 98, tx: 144441221, lsn:
> 5A6/3DC86B40, prev 5A6/3DC86A68, desc: HOT_UPDATE off 32 xmax
> 144441221 ; new off 34 xmax 0, blkref #0: rel 1663/355309/39370447 blk
> 6284
> rmgr: Transaction len (rec/tot): 46/ 46, tx: 144441221, lsn:
> 5A6/3DC86BA8, prev 5A6/3DC86B40, desc: COMMIT 2018-05-21
> 10:26:05.830168 -03
>
> which translates into something like:
>
> BEGIN
> INSERT INTO table_a ON CONFLICT
> UPDATE table_b
> UPDATE table_c
> COMMIT
>
> I don't have a test case yet. This is my next step after this report.
> However, it seems to be related to INSERT ON CONFLICT decoding. Ideas?

CC: Peter?

Greetings,

Andres Freund