Date: Thu, 21 Nov 2019 22:41:15 +0100
From: Tomas Vondra <tomas.vondra@2ndquadrant.com>
To: =?utf-8?Q?Ond=C5=99ej?= Jirman <ienieghapheoghaiwida@xff.cz>
Cc: pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #16129: Segfault in tts_virtual_materialize in logical
 replication worker
Message-ID: <20191121214115.3tgefmvkmrzaim74@development>
References: <20191121133237.vgxoilemblaqmstu@development>
 <20191121135523.aybyo7o6yzxxungd@core.my.home>
 <20191121143503.nkdwgjwb7xjopeuq@development>
 <20191121150716.szxqukxrtpjpckm3@core.my.home>
 <20191121152732.hu6y4wzw7nkxpsvk@development>
 <20191121155707.pqkgjphh65o5fapz@core.my.home>
 <20191121161502.xfiy65i3cm6adscr@core.my.home>
 <20191121165752.dffge6bh756xlfdg@development>
 <20191121173555.midj6vp4dmiiqs24@core.my.home>
 <20191121185844.6qsqhwzzuhu3fpsg@core.my.home>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <20191121185844.6qsqhwzzuhu3fpsg@core.my.home>
Precedence: bulk

On Thu, Nov 21, 2019 at 07:58:44PM +0100, Ondřej Jirman wrote:
>On Thu, Nov 21, 2019 at 06:35:55PM +0100, Ondřej Jirman wrote:
>> One missing piece is what exactly is the contents of the outstanding output from
>> pgoutput plugin, that the replica crashes on and doesn't apply. Are there any
>> tools for inspecting the binary output from the pgoutput plugin? Maybe that can
>> provide a clue.
>
>So I've looked at it manually, and the segfaulting transaction doesn't make
>much sense to me. On primary a row with 37880 byte cover_image was inserted,
>but pgoutput plugin sends these records:
>
>B
>R - public.videos  title cover_image metadata,...
>U - new row where cover_image tuple doesn't have any data, just a flag ('u')
>C
>
>Which means 'unchanged toast column' according to logical/proto.c
>
>Yet cover_image is defined as not null.
>
>I guess it's some special handling for VARATT_IS_EXTERNAL_ONDISK.

Actually, no. The second message is 'U' so update, not insert. And we
don't send TOAST values (oversized values, stored aside) that were not
updated. Which is this case, because the cover_image was not updated (as
implied by the 'u' flag).

For the record, the decoded data looks like this:

1) relation structure (8 columns)

R, 19048, public, videos, d, 8,
   (true, id, 23 => int4, 0xffffffff)
   (false, title, 25 => text, 0xffffffff)
   (false, cover_image, 17 => bytea, 0xffffffff)
   (false, metadata, 3802 => jsonb, 0xffffffff)
   (false, category, 23 => int4, 0xffffffff)
   (false, published, 1082 => date, 0xffffffff)
   (false, added, 1114 => timestamp, 0xffffffff)
   (false, played, 16 => uuid, 0xffffffff)

2) update, with the TOAST value undefined/unchanged

U, 19048, N, 8,
   (4, 8393),
   (86, Pazderka: O média se povede boj. Kdyby nás politici milovali, bylo by něco špatně),
   u, /* unchanged bytea */
   (313, {.. json ..}),
   (3, 242),
   (10, 2019-11-18),
   (26, 2019-11-18 12:50:01.816376),
   (1, t)

So it's perfectly well formatted, I think.

>
>To me this looks like this transaction is assuming data for bytea column
>cover_image are already replicated from earlier?
>
>Maybe it is not though? It's certainly breaking some assumption on the
>replica, because this is the precise point where segfault happens.
>

I think this more and more seems like some sort of bug in the apply
code, not resetting a NULL flag and interpreting the bogus value as
a valid pointer. Wouldn't the be the first such bug.

regards

-- 
Tomas Vondra                  http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services