BUG #16129: Segfault in tts_virtual_materialize in logical replication worker

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

The following bug has been logged on the website:

Bug reference: 16129
Logged by: Ondrej Jirman
Email address: ienieghapheoghaiwida@xff.cz
PostgreSQL version: 12.1
Operating system: Arch Linux
Description:

Hello,

I've upgraded my main PostgreSQL cluster from 11.5 to 12.1 via pg_dumpall
method and after a while I started getting segfault in logical replication
worker.

My setup is fairly vanilla, non-default options:

shared_buffers = 256MB
work_mem = 512MB
temp_buffers = 64MB
maintenance_work_mem = 4GB
effective_cache_size = 16GB
max_logical_replication_workers = 30
max_replication_slots = 30
max_worker_processes = 30
wal_level = logical

I have several databases that I subscribe to from this database cluster
using logical replication.

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

Hmmm, so it's failing on this memcpy() in tts_virtual_materialize:

else
{
Size data_length = 0;

data = (char *) att_align_nominal(data, att->attalign);
data_length = att_addlength_datum(data_length, att->attlen, val);

memcpy(data, DatumGetPointer(val), data_length);

slot->tts_values[natt] = PointerGetDatum(data);
data += data_length;
}

The question is, which of the pointers is bogus. You seem to already
have a core file, so can you inspect the variables in frame #2? I think
especially

p *slot
p natt
p val
p *att

would be interesting to see.

Also, how does the replicated schema look like? Can we see the table
definitions?

regards

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

Hello,

On Thu, Nov 21, 2019 at 11:39:40AM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

The following bug has been logged on the website:

Bug reference: 16129
Logged by: Ondrej Jirman
Email address: ienieghapheoghaiwida@xff.cz
PostgreSQL version: 12.1
Operating system: Arch Linux
Description:

Hello,

I've upgraded my main PostgreSQL cluster from 11.5 to 12.1 via pg_dumpall
method and after a while I started getting segfault in logical replication
worker.

My setup is fairly vanilla, non-default options:

shared_buffers = 256MB
work_mem = 512MB
temp_buffers = 64MB
maintenance_work_mem = 4GB
effective_cache_size = 16GB
max_logical_replication_workers = 30
max_replication_slots = 30
max_worker_processes = 30
wal_level = logical

I have several databases that I subscribe to from this database cluster
using logical replication.

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

I forgot to add that publisher is still PostgreSQL 11.5.

Hmmm, so it's failing on this memcpy() in tts_virtual_materialize:

else
{
Size data_length = 0;

data = (char *) att_align_nominal(data, att->attalign);
data_length = att_addlength_datum(data_length, att->attlen, val);

memcpy(data, DatumGetPointer(val), data_length);

This is a bytea column in one of the tables on the publisher.

So this looks like it's segfaulting while trying to copy too much bytes
(data_length determined as 620,701,425 bytes):

#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>, __dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34

But maximum length of any bytea valaue in the publisher database is <200kB.

slot->tts_values[natt] = PointerGetDatum(data);
data += data_length;
}

The question is, which of the pointers is bogus. You seem to already
have a core file, so can you inspect the variables in frame #2? I think
especially

p *slot
p natt
p val
p *att

would be interesting to see.

(gdb) p *slot
$1 = {type = T_TupleTableSlot, tts_flags = 20, tts_nvalid = 8, tts_ops = 0x558149ff4da0 <TTSOpsVirtual>, tts_tupleDescriptor = 0x7fcca2ea7548, tts_values = 0x55814adfbc10,
tts_isnull = 0x55814adfbc50, tts_mcxt = 0x55814adfb6e0, tts_tid = {ip_blkid = {bi_hi = 65535, bi_lo = 65535}, ip_posid = 0}, tts_tableOid = 0}
(gdb) p natt
$2 = 2
(gdb) p val
$3 = <optimized out>
(gdb) p slot->tts_values[nat]
No symbol "nat" in current context.
(gdb) p slot->tts_values[natt]
$4 = 94013795319824
(gdb) p *slot->tts_values[natt]
$5 = -1812161596
(gdb) p *att
$6 = {attrelid = 55240, attname = {data = "cover_image", '\000' <repeats 52 times>}, atttypid = 17, attstattarget = -1, attlen = -1, attnum = 3, attndims = 0, attcacheoff = -1, atttypmod = -1,
attbyval = false, attstorage = 120 'x', attalign = 105 'i', attnotnull = true, atthasdef = false, atthasmissing = false, attidentity = 0 '\000', attgenerated = 0 '\000', attisdropped = false,
attislocal = true, attinhcount = 0, attcollation = 0}

Also, how does the replicated schema look like? Can we see the table
definitions?

SET statement_timeout = 0;
SET lock_timeout = 0;
SET idle_in_transaction_session_timeout = 0;
SET client_encoding = 'UTF8';
SET standard_conforming_strings = on;
SELECT pg_catalog.set_config('search_path', '', false);
SET check_function_bodies = false;
SET xmloption = content;
SET client_min_messages = warning;
SET row_security = off;
SET default_tablespace = '';
SET default_table_access_method = heap;
CREATE TABLE public.categories (
id integer NOT NULL,
name text NOT NULL,
description text,
metadata jsonb NOT NULL,
provider integer NOT NULL,
subscribed boolean DEFAULT false NOT NULL,
cover_image bytea
);
CREATE SEQUENCE public.categories_id_seq
START WITH 1
INCREMENT BY 1
NO MINVALUE
NO MAXVALUE
CACHE 1;
ALTER SEQUENCE public.categories_id_seq OWNED BY public.categories.id;
CREATE TABLE public.providers (
id integer NOT NULL,
system_name text NOT NULL,
name text NOT NULL
);
CREATE SEQUENCE public.providers_id_seq
START WITH 1
INCREMENT BY 1
NO MINVALUE
NO MAXVALUE
CACHE 1;
ALTER SEQUENCE public.providers_id_seq OWNED BY public.providers.id;
CREATE TABLE public.videos (
id integer NOT NULL,
title text NOT NULL,
cover_image bytea NOT NULL,
metadata jsonb NOT NULL,
category integer NOT NULL,
published date NOT NULL,
added timestamp without time zone DEFAULT now() NOT NULL,
played boolean DEFAULT false NOT NULL
);
CREATE SEQUENCE public.videos_id_seq
START WITH 1
INCREMENT BY 1
NO MINVALUE
NO MAXVALUE
CACHE 1;
ALTER SEQUENCE public.videos_id_seq OWNED BY public.videos.id;
ALTER TABLE ONLY public.categories ALTER COLUMN id SET DEFAULT nextval('public.categories_id_seq'::regclass);
ALTER TABLE ONLY public.providers ALTER COLUMN id SET DEFAULT nextval('public.providers_id_seq'::regclass);
ALTER TABLE ONLY public.videos ALTER COLUMN id SET DEFAULT nextval('public.videos_id_seq'::regclass);
ALTER TABLE ONLY public.categories
ADD CONSTRAINT categories_pkey PRIMARY KEY (id);
ALTER TABLE ONLY public.providers
ADD CONSTRAINT providers_pkey PRIMARY KEY (id);
ALTER TABLE ONLY public.providers
ADD CONSTRAINT providers_system_name_key UNIQUE (system_name);
ALTER TABLE ONLY public.videos
ADD CONSTRAINT videos_pkey PRIMARY KEY (id);
ALTER TABLE ONLY public.categories
ADD CONSTRAINT categories_provider_fkey FOREIGN KEY (provider) REFERENCES public.providers(id);
ALTER TABLE ONLY public.videos
ADD CONSTRAINT videos_category_fkey FOREIGN KEY (category) REFERENCES public.categories(id);
CREATE SUBSCRIPTION l5_hometv CONNECTION 'host=redacted port=5432 user=redacted password=redacted dbname=hometv' PUBLICATION pub WITH (connect = false, slot_name = 'l5_hometv');

Publisher:

SET statement_timeout = 0;
SET lock_timeout = 0;
SET idle_in_transaction_session_timeout = 0;
SET client_encoding = 'UTF8';
SET standard_conforming_strings = on;
SELECT pg_catalog.set_config('search_path', '', false);
SET check_function_bodies = false;
SET xmloption = content;
SET client_min_messages = warning;
SET row_security = off;
SET default_tablespace = '';
SET default_with_oids = false;
CREATE TABLE public.categories (
id integer NOT NULL,
name text NOT NULL,
description text,
metadata jsonb NOT NULL,
provider integer NOT NULL,
subscribed boolean DEFAULT false NOT NULL,
cover_image bytea
);
CREATE SEQUENCE public.categories_id_seq
START WITH 1
INCREMENT BY 1
NO MINVALUE
NO MAXVALUE
CACHE 1;
ALTER SEQUENCE public.categories_id_seq OWNED BY public.categories.id;
CREATE TABLE public.providers (
id integer NOT NULL,
system_name text NOT NULL,
name text NOT NULL
);
CREATE SEQUENCE public.providers_id_seq
START WITH 1
INCREMENT BY 1
NO MINVALUE
NO MAXVALUE
CACHE 1;
ALTER SEQUENCE public.providers_id_seq OWNED BY public.providers.id;
CREATE TABLE public.videos (
id integer NOT NULL,
title text NOT NULL,
cover_image bytea NOT NULL,
metadata jsonb NOT NULL,
category integer NOT NULL,
published date NOT NULL,
added timestamp without time zone DEFAULT now() NOT NULL,
played boolean DEFAULT false NOT NULL
);
CREATE SEQUENCE public.videos_id_seq
START WITH 1
INCREMENT BY 1
NO MINVALUE
NO MAXVALUE
CACHE 1;
ALTER SEQUENCE public.videos_id_seq OWNED BY public.videos.id;
ALTER TABLE ONLY public.categories ALTER COLUMN id SET DEFAULT nextval('public.categories_id_seq'::regclass);
ALTER TABLE ONLY public.providers ALTER COLUMN id SET DEFAULT nextval('public.providers_id_seq'::regclass);
ALTER TABLE ONLY public.videos ALTER COLUMN id SET DEFAULT nextval('public.videos_id_seq'::regclass);
ALTER TABLE ONLY public.categories
ADD CONSTRAINT categories_pkey PRIMARY KEY (id);
ALTER TABLE ONLY public.providers
ADD CONSTRAINT providers_pkey PRIMARY KEY (id);
ALTER TABLE ONLY public.providers
ADD CONSTRAINT providers_system_name_key UNIQUE (system_name);
ALTER TABLE ONLY public.videos
ADD CONSTRAINT videos_pkey PRIMARY KEY (id);
ALTER TABLE ONLY public.categories
ADD CONSTRAINT categories_provider_fkey FOREIGN KEY (provider) REFERENCES public.providers(id);
ALTER TABLE ONLY public.videos
ADD CONSTRAINT videos_category_fkey FOREIGN KEY (category) REFERENCES public.categories(id);
CREATE PUBLICATION pub FOR ALL TABLES WITH (publish = 'insert, update, delete, truncate');

thank you and regards,
Ondrej

On Thu, Nov 21, 2019 at 12:53:26PM +0100, postgresql wrote:

Hello,

On Thu, Nov 21, 2019 at 11:39:40AM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

I forgot to add that publisher is still PostgreSQL 11.5.

I can also add that I have data checksumming enabled on both ends, and
it did not detect any corruption:

# pg_verify_checksums -D /var/lib/postgres/data
Checksum scan completed
Data checksum version: 1
Files scanned: 1751
Blocks scanned: 86592
Bad checksums: 0

# pg_checksums /var/lib/postgres/data
Checksum operation completed
Files scanned: 22777
Blocks scanned: 3601527
Bad checksums: 0
Data checksum version: 1

WAL log on the publisher is also dumpable to a state hours after the issues
started:

I've put the dump here, if it's of any use: https://megous.com/dl/tmp/wal_dump.txt

Dump ends with:

pg_waldump: FATAL: error in WAL record at 2/BBE0E538: invalid record length at 2/BBE0E5A8: wanted 24, got 0

But that seems normal. I get that error on my other database clusters, too.

I managed to extract the failing logical decoding data from the publisher, if
that helps:

SELECT * FROM pg_logical_slot_peek_binary_changes('l5_hometv', NULL, NULL, 'proto_version', '1', 'publication_names', 'pub');

2/BBD86EA0 | 56395 | \x4200000002bbd880b800023acd790ce5510000dc4b
2/BBD87E90 | 56395 | \x5200004a687075626c696300766964656f73006400080169640000000017ffffffff007469746c650000000019ffffffff00636f7665725f696d6167650000000011ffffffff006d657461646174610000000edafffffff
f0063617465676f72790000000017ffffffff007075626c6973686564000000043affffffff006164646564000000045affffffff00706c617965640000000010ffffffff
2/BBD87E90 | 56395 | \x5500004a684e0008740000000438333933740000005650617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c20627
96c6f206279206ec49b636f20c5a17061746ec49b7574000001397b226964223a20226430313064343430303965323131656162323539616331663662323230656538222c202264617465223a2022323031392d31312d3138222c20226e616d65223a20
2250617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c2062796c6f206279206ec49b636f20c5a17061746ec49b222c2022696d616765223a202
268747470733a2f2f63646e2e7873642e637a2f726573697a652f63353535656239633131353333313632386164666539396237343534353731655f657874726163743d302c302c313931392c313038305f726573697a653d3732302c3430355f2e6a70
673f686173683d6362316362623836336230353361613561333761346666616439303865303431227d7400000003323432740000000a323031392d31312d3138740000001a323031392d31312d31382031323a35303a30312e383136333736740000000
174
2/BBD880E8 | 56395 | \x430000000002bbd880b800000002bbd880e800023acd790ce551

thank you and regards,
o.

On Thu, Nov 21, 2019 at 12:53:26PM +0100, Ondřej Jirman wrote:

Hello,

On Thu, Nov 21, 2019 at 11:39:40AM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

The following bug has been logged on the website:

Bug reference: 16129
Logged by: Ondrej Jirman
Email address: ienieghapheoghaiwida@xff.cz
PostgreSQL version: 12.1
Operating system: Arch Linux
Description:

Hello,

I've upgraded my main PostgreSQL cluster from 11.5 to 12.1 via pg_dumpall
method and after a while I started getting segfault in logical replication
worker.

My setup is fairly vanilla, non-default options:

shared_buffers = 256MB
work_mem = 512MB
temp_buffers = 64MB
maintenance_work_mem = 4GB
effective_cache_size = 16GB
max_logical_replication_workers = 30
max_replication_slots = 30
max_worker_processes = 30
wal_level = logical

I have several databases that I subscribe to from this database cluster
using logical replication.

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

I forgot to add that publisher is still PostgreSQL 11.5.

Hmmm, so it's failing on this memcpy() in tts_virtual_materialize:

else
{
Size data_length = 0;

data = (char *) att_align_nominal(data, att->attalign);
data_length = att_addlength_datum(data_length, att->attlen, val);

memcpy(data, DatumGetPointer(val), data_length);

This is a bytea column in one of the tables on the publisher.

So this looks like it's segfaulting while trying to copy too much bytes
(data_length determined as 620,701,425 bytes):

#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>, __dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34

But maximum length of any bytea valaue in the publisher database is <200kB.

OK. So the public.videos.cover_image column, I suppose?

Anyway, this likely means the pointer bogus, in some way. Maybe it's
pointing to already freed memory, or something like that.

slot->tts_values[natt] = PointerGetDatum(data);
data += data_length;
}

The question is, which of the pointers is bogus. You seem to already
have a core file, so can you inspect the variables in frame #2? I think
especially

p *slot
p natt
p val
p *att

would be interesting to see.

(gdb) p *slot
$1 = {type = T_TupleTableSlot, tts_flags = 20, tts_nvalid = 8, tts_ops = 0x558149ff4da0 <TTSOpsVirtual>, tts_tupleDescriptor = 0x7fcca2ea7548, tts_values = 0x55814adfbc10,
tts_isnull = 0x55814adfbc50, tts_mcxt = 0x55814adfb6e0, tts_tid = {ip_blkid = {bi_hi = 65535, bi_lo = 65535}, ip_posid = 0}, tts_tableOid = 0}
(gdb) p natt
$2 = 2
(gdb) p val
$3 = <optimized out>
(gdb) p slot->tts_values[nat]
No symbol "nat" in current context.
(gdb) p slot->tts_values[natt]
$4 = 94013795319824
(gdb) p *slot->tts_values[natt]
$5 = -1812161596
(gdb) p *att
$6 = {attrelid = 55240, attname = {data = "cover_image", '\000' <repeats 52 times>}, atttypid = 17, attstattarget = -1, attlen = -1, attnum = 3, attndims = 0, attcacheoff = -1, atttypmod = -1,
attbyval = false, attstorage = 120 'x', attalign = 105 'i', attnotnull = true, atthasdef = false, atthasmissing = false, attidentity = 0 '\000', attgenerated = 0 '\000', attisdropped = false,
attislocal = true, attinhcount = 0, attcollation = 0}

OK, nothing obviously bobus here, I think. It's not entirely clear to me
why this works

(gdb) p *slot->tts_values[natt]
$5 = -1812161596

because tts_values[natt] is not a pointer, I think. So I'm not sure how
to interpret the dereference. It would be interesting to see the first
couple of bytes? I think somehing like

(gdb) p ((char*)slot->tts_values[natt])[$n]

for $n between 0 and 3 should do the trick.

Also, how does the replicated schema look like? Can we see the table
definitions?

...
CREATE TABLE public.videos (
id integer NOT NULL,
title text NOT NULL,
cover_image bytea NOT NULL,
metadata jsonb NOT NULL,
category integer NOT NULL,
published date NOT NULL,
added timestamp without time zone DEFAULT now() NOT NULL,
played boolean DEFAULT false NOT NULL
);

OK, so this is the problematic table. Any idea what operation triggers
the issue? Having a small reproducer (say, a single-row insert or so)
would be very helpful.

regards

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

On Thu, Nov 21, 2019 at 01:59:30PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 12:53:26PM +0100, Ondřej Jirman wrote:

Hello,

On Thu, Nov 21, 2019 at 11:39:40AM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

The following bug has been logged on the website:

Bug reference: 16129
Logged by: Ondrej Jirman
Email address: ienieghapheoghaiwida@xff.cz
PostgreSQL version: 12.1
Operating system: Arch Linux
Description:

Hello,

I've upgraded my main PostgreSQL cluster from 11.5 to 12.1 via pg_dumpall
method and after a while I started getting segfault in logical replication
worker.

My setup is fairly vanilla, non-default options:

shared_buffers = 256MB
work_mem = 512MB
temp_buffers = 64MB
maintenance_work_mem = 4GB
effective_cache_size = 16GB
max_logical_replication_workers = 30
max_replication_slots = 30
max_worker_processes = 30
wal_level = logical

I have several databases that I subscribe to from this database cluster
using logical replication.

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

I forgot to add that publisher is still PostgreSQL 11.5.

Hmmm, so it's failing on this memcpy() in tts_virtual_materialize:

else
{
Size data_length = 0;

data = (char *) att_align_nominal(data, att->attalign);
data_length = att_addlength_datum(data_length, att->attlen, val);

memcpy(data, DatumGetPointer(val), data_length);

This is a bytea column in one of the tables on the publisher.

So this looks like it's segfaulting while trying to copy too much bytes
(data_length determined as 620,701,425 bytes):

#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>, __dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34

But maximum length of any bytea valaue in the publisher database is <200kB.

OK. So the public.videos.cover_image column, I suppose?

Anyway, this likely means the pointer bogus, in some way. Maybe it's
pointing to already freed memory, or something like that.

slot->tts_values[natt] = PointerGetDatum(data);
data += data_length;
}

The question is, which of the pointers is bogus. You seem to already
have a core file, so can you inspect the variables in frame #2? I think
especially

p *slot
p natt
p val
p *att

would be interesting to see.

(gdb) p *slot
$1 = {type = T_TupleTableSlot, tts_flags = 20, tts_nvalid = 8, tts_ops = 0x558149ff4da0 <TTSOpsVirtual>, tts_tupleDescriptor = 0x7fcca2ea7548, tts_values = 0x55814adfbc10,
tts_isnull = 0x55814adfbc50, tts_mcxt = 0x55814adfb6e0, tts_tid = {ip_blkid = {bi_hi = 65535, bi_lo = 65535}, ip_posid = 0}, tts_tableOid = 0}
(gdb) p natt
$2 = 2
(gdb) p val
$3 = <optimized out>
(gdb) p slot->tts_values[nat]
No symbol "nat" in current context.
(gdb) p slot->tts_values[natt]
$4 = 94013795319824
(gdb) p *slot->tts_values[natt]
$5 = -1812161596
(gdb) p *att
$6 = {attrelid = 55240, attname = {data = "cover_image", '\000' <repeats 52 times>}, atttypid = 17, attstattarget = -1, attlen = -1, attnum = 3, attndims = 0, attcacheoff = -1, atttypmod = -1,
attbyval = false, attstorage = 120 'x', attalign = 105 'i', attnotnull = true, atthasdef = false, atthasmissing = false, attidentity = 0 '\000', attgenerated = 0 '\000', attisdropped = false,
attislocal = true, attinhcount = 0, attcollation = 0}

OK, nothing obviously bobus here, I think. It's not entirely clear to me
why this works

(gdb) p *slot->tts_values[natt]
$5 = -1812161596

because tts_values[natt] is not a pointer, I think. So I'm not sure how
to interpret the dereference. It would be interesting to see the first
couple of bytes? I think somehing like

It's probably nothing, the value there just looked big enough be a pointer, so
I dereferenced it in gdb.

(gdb) p ((char*)slot->tts_values[natt])[$n]

for $n between 0 and 3 should do the trick.

(gdb) p ((char*)slot->tts_values[natt])[0]
$7 = -60 '\304'
(gdb) p ((char*)slot->tts_values[natt])[1]
$8 = -101 '\233'
(gdb) p ((char*)slot->tts_values[natt])[2]
$9 = -4 '\374'
(gdb) p ((char*)slot->tts_values[natt])[3]
$10 = -109 '\223'
(gdb) p ((char*)slot->tts_values[natt])[4]
$11 = 0 '\000'
(gdb) p ((char*)slot->tts_values[natt])[5]
$12 = 0 '\000'
(gdb) p ((char*)slot->tts_values[natt])[6]
$13 = -8 '\370'

Also, how does the replicated schema look like? Can we see the table
definitions?

...
CREATE TABLE public.videos (
id integer NOT NULL,
title text NOT NULL,
cover_image bytea NOT NULL,
metadata jsonb NOT NULL,
category integer NOT NULL,
published date NOT NULL,
added timestamp without time zone DEFAULT now() NOT NULL,
played boolean DEFAULT false NOT NULL
);

OK, so this is the problematic table. Any idea what operation triggers
the issue? Having a small reproducer (say, a single-row insert or so)
would be very helpful.

Can something be extracted from the logical decoding data I sent in the other
e-mail? That seems to contain the failing operation, but I don't know how to
decode it off the top of my head from that binary representation.

regards,
o.

On Thu, Nov 21, 2019 at 01:59:13PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 12:53:26PM +0100, postgresql wrote:

Hello,

On Thu, Nov 21, 2019 at 11:39:40AM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

I forgot to add that publisher is still PostgreSQL 11.5.

I can also add that I have data checksumming enabled on both ends, and
it did not detect any corruption:

# pg_verify_checksums -D /var/lib/postgres/data
Checksum scan completed
Data checksum version: 1
Files scanned: 1751
Blocks scanned: 86592
Bad checksums: 0

# pg_checksums /var/lib/postgres/data
Checksum operation completed
Files scanned: 22777
Blocks scanned: 3601527
Bad checksums: 0
Data checksum version: 1

WAL log on the publisher is also dumpable to a state hours after the issues
started:

I've put the dump here, if it's of any use: https://megous.com/dl/tmp/wal_dump.txt

Dump ends with:

pg_waldump: FATAL: error in WAL record at 2/BBE0E538: invalid record length at 2/BBE0E5A8: wanted 24, got 0

But that seems normal. I get that error on my other database clusters, too.

I managed to extract the failing logical decoding data from the publisher, if
that helps:

SELECT * FROM pg_logical_slot_peek_binary_changes('l5_hometv', NULL, NULL, 'proto_version', '1', 'publication_names', 'pub');

2/BBD86EA0 | 56395 | \x4200000002bbd880b800023acd790ce5510000dc4b
2/BBD87E90 | 56395 | \x5200004a687075626c696300766964656f73006400080169640000000017ffffffff007469746c650000000019ffffffff00636f7665725f696d6167650000000011ffffffff006d657461646174610000000edafffffff
f0063617465676f72790000000017ffffffff007075626c6973686564000000043affffffff006164646564000000045affffffff00706c617965640000000010ffffffff
2/BBD87E90 | 56395 | \x5500004a684e0008740000000438333933740000005650617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c20627
96c6f206279206ec49b636f20c5a17061746ec49b7574000001397b226964223a20226430313064343430303965323131656162323539616331663662323230656538222c202264617465223a2022323031392d31312d3138222c20226e616d65223a20
2250617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c2062796c6f206279206ec49b636f20c5a17061746ec49b222c2022696d616765223a202
268747470733a2f2f63646e2e7873642e637a2f726573697a652f63353535656239633131353333313632386164666539396237343534353731655f657874726163743d302c302c313931392c313038305f726573697a653d3732302c3430355f2e6a70
673f686173683d6362316362623836336230353361613561333761346666616439303865303431227d7400000003323432740000000a323031392d31312d3138740000001a323031392d31312d31382031323a35303a30312e383136333736740000000
174
2/BBD880E8 | 56395 | \x430000000002bbd880b800000002bbd880e800023acd790ce551

Can you show the whole transaction? From the WAL dump it seems it just
did a single UPDATE:

rmgr: Heap len (rec/tot): 59/ 4075, tx: 56395, lsn: 2/BBD86EA0, prev 2/BBD86E68, desc: LOCK off 2: xid 56395: flags 0 LOCK_ONLY EXCL_LOCK
blkref #0: rel 1663/19030/19048 fork main blk 415 (FPW); hole: offset: 56, length: 4176
rmgr: Heap len (rec/tot): 523/ 523, tx: 56395, lsn: 2/BBD87E90, prev 2/BBD86EA0, desc: HOT_UPDATE off 2 xmax 56395 ; new off 9 xmax 0
blkref #0: rel 1663/19030/19048 fork main blk 415
rmgr: Transaction len (rec/tot): 46/ 46, tx: 56395, lsn: 2/BBD880B8, prev 2/BBD87E90, desc: COMMIT 2019-11-20 23:28:47.016273 CET

Which fields does it update?

regards

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

On Thu, Nov 21, 2019 at 02:12:02PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 01:59:30PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 12:53:26PM +0100, Ondřej Jirman wrote:

...

OK, so this is the problematic table. Any idea what operation triggers
the issue? Having a small reproducer (say, a single-row insert or so)
would be very helpful.

Can something be extracted from the logical decoding data I sent in the other
e-mail? That seems to contain the failing operation, but I don't know how to
decode it off the top of my head from that binary representation.

Well, why not use pg_logical_slot_peek_changes()? That should be human
readable, I think.

regards

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

On Thu, Nov 21, 2019 at 02:37:14PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 02:12:02PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 01:59:30PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 12:53:26PM +0100, Ondřej Jirman wrote:

...

OK, so this is the problematic table. Any idea what operation triggers
the issue? Having a small reproducer (say, a single-row insert or so)
would be very helpful.

Can something be extracted from the logical decoding data I sent in the other
e-mail? That seems to contain the failing operation, but I don't know how to
decode it off the top of my head from that binary representation.

Well, why not use pg_logical_slot_peek_changes()? That should be human
readable, I think.

I would, but how?

SELECT * FROM pg_logical_slot_peek_changes('l5_hometv', NULL, NULL,
'proto_version', '1', 'publication_names', 'pub');
ERROR: logical decoding output plugin "pgoutput" produces binary output, but
function "pg_logical_slot_peek_changes(name,pg_lsn,integer,text[])" expects
textual data

regards,
o.

On Thu, Nov 21, 2019 at 02:32:37PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:59:13PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 12:53:26PM +0100, postgresql wrote:

Hello,

On Thu, Nov 21, 2019 at 11:39:40AM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

I forgot to add that publisher is still PostgreSQL 11.5.

I can also add that I have data checksumming enabled on both ends, and
it did not detect any corruption:

# pg_verify_checksums -D /var/lib/postgres/data
Checksum scan completed
Data checksum version: 1
Files scanned: 1751
Blocks scanned: 86592
Bad checksums: 0

# pg_checksums /var/lib/postgres/data
Checksum operation completed
Files scanned: 22777
Blocks scanned: 3601527
Bad checksums: 0
Data checksum version: 1

WAL log on the publisher is also dumpable to a state hours after the issues
started:

I've put the dump here, if it's of any use: https://megous.com/dl/tmp/wal_dump.txt

Dump ends with:

pg_waldump: FATAL: error in WAL record at 2/BBE0E538: invalid record length at 2/BBE0E5A8: wanted 24, got 0

But that seems normal. I get that error on my other database clusters, too.

I managed to extract the failing logical decoding data from the publisher, if
that helps:

SELECT * FROM pg_logical_slot_peek_binary_changes('l5_hometv', NULL, NULL, 'proto_version', '1', 'publication_names', 'pub');

2/BBD86EA0 | 56395 | \x4200000002bbd880b800023acd790ce5510000dc4b
2/BBD87E90 | 56395 | \x5200004a687075626c696300766964656f73006400080169640000000017ffffffff007469746c650000000019ffffffff00636f7665725f696d6167650000000011ffffffff006d657461646174610000000edafffffff
f0063617465676f72790000000017ffffffff007075626c6973686564000000043affffffff006164646564000000045affffffff00706c617965640000000010ffffffff
2/BBD87E90 | 56395 | \x5500004a684e0008740000000438333933740000005650617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c20627
96c6f206279206ec49b636f20c5a17061746ec49b7574000001397b226964223a20226430313064343430303965323131656162323539616331663662323230656538222c202264617465223a2022323031392d31312d3138222c20226e616d65223a20
2250617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c2062796c6f206279206ec49b636f20c5a17061746ec49b222c2022696d616765223a202
268747470733a2f2f63646e2e7873642e637a2f726573697a652f63353535656239633131353333313632386164666539396237343534353731655f657874726163743d302c302c313931392c313038305f726573697a653d3732302c3430355f2e6a70
673f686173683d6362316362623836336230353361613561333761346666616439303865303431227d7400000003323432740000000a323031392d31312d3138740000001a323031392d31312d31382031323a35303a30312e383136333736740000000
174
2/BBD880E8 | 56395 | \x430000000002bbd880b800000002bbd880e800023acd790ce551

Can you show the whole transaction? From the WAL dump it seems it just
did a single UPDATE:

I'm not sure what you mean. The above is the whole output I got from that
SELECT.

rmgr: Heap len (rec/tot): 59/ 4075, tx: 56395, lsn: 2/BBD86EA0, prev 2/BBD86E68, desc: LOCK off 2: xid 56395: flags 0 LOCK_ONLY EXCL_LOCK
blkref #0: rel 1663/19030/19048 fork main blk 415 (FPW); hole: offset: 56, length: 4176
rmgr: Heap len (rec/tot): 523/ 523, tx: 56395, lsn: 2/BBD87E90, prev 2/BBD86EA0, desc: HOT_UPDATE off 2 xmax 56395 ; new off 9 xmax 0
blkref #0: rel 1663/19030/19048 fork main blk 415
rmgr: Transaction len (rec/tot): 46/ 46, tx: 56395, lsn: 2/BBD880B8, prev 2/BBD87E90, desc: COMMIT 2019-11-20 23:28:47.016273 CET

Which fields does it update?

The only update that my system does in this database is:

UPDATE videos SET played = TRUE WHERE id = ?

The rest is just inserts:

INSERT INTO categories (name, metadata, cover_image, provider) VALUES (?, ?, ?, (SELECT id FROM providers WHERE system_name = ?))
INSERT INTO videos (title, metadata, cover_image, category, published) VALUES (?, ?, ?, ?, ?)

There are no other data modification statements executed.

There may be updates in other databases in the same cluster, but replication
worker is segfaulting only on the "hometv" database.

regards,
o.

On Thu, Nov 21, 2019 at 02:46:45PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 02:37:14PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 02:12:02PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 01:59:30PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 12:53:26PM +0100, Ondřej Jirman wrote:

...

OK, so this is the problematic table. Any idea what operation triggers
the issue? Having a small reproducer (say, a single-row insert or so)
would be very helpful.

Can something be extracted from the logical decoding data I sent in the other
e-mail? That seems to contain the failing operation, but I don't know how to
decode it off the top of my head from that binary representation.

Well, why not use pg_logical_slot_peek_changes()? That should be human
readable, I think.

I would, but how?

SELECT * FROM pg_logical_slot_peek_changes('l5_hometv', NULL, NULL,
'proto_version', '1', 'publication_names', 'pub');
ERROR: logical decoding output plugin "pgoutput" produces binary output, but
function "pg_logical_slot_peek_changes(name,pg_lsn,integer,text[])" expects
textual data

Ah, right. Sorry, I forgot this is pgoutput.

regards

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

On Thu, Nov 21, 2019 at 02:55:23PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 02:32:37PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:59:13PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 12:53:26PM +0100, postgresql wrote:

Hello,

On Thu, Nov 21, 2019 at 11:39:40AM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

I forgot to add that publisher is still PostgreSQL 11.5.

I can also add that I have data checksumming enabled on both ends, and
it did not detect any corruption:

# pg_verify_checksums -D /var/lib/postgres/data
Checksum scan completed
Data checksum version: 1
Files scanned: 1751
Blocks scanned: 86592
Bad checksums: 0

# pg_checksums /var/lib/postgres/data
Checksum operation completed
Files scanned: 22777
Blocks scanned: 3601527
Bad checksums: 0
Data checksum version: 1

WAL log on the publisher is also dumpable to a state hours after the issues
started:

I've put the dump here, if it's of any use: https://megous.com/dl/tmp/wal_dump.txt

Dump ends with:

pg_waldump: FATAL: error in WAL record at 2/BBE0E538: invalid record length at 2/BBE0E5A8: wanted 24, got 0

But that seems normal. I get that error on my other database clusters, too.

I managed to extract the failing logical decoding data from the publisher, if
that helps:

SELECT * FROM pg_logical_slot_peek_binary_changes('l5_hometv', NULL, NULL, 'proto_version', '1', 'publication_names', 'pub');

2/BBD86EA0 | 56395 | \x4200000002bbd880b800023acd790ce5510000dc4b
2/BBD87E90 | 56395 | \x5200004a687075626c696300766964656f73006400080169640000000017ffffffff007469746c650000000019ffffffff00636f7665725f696d6167650000000011ffffffff006d657461646174610000000edafffffff
f0063617465676f72790000000017ffffffff007075626c6973686564000000043affffffff006164646564000000045affffffff00706c617965640000000010ffffffff
2/BBD87E90 | 56395 | \x5500004a684e0008740000000438333933740000005650617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c20627
96c6f206279206ec49b636f20c5a17061746ec49b7574000001397b226964223a20226430313064343430303965323131656162323539616331663662323230656538222c202264617465223a2022323031392d31312d3138222c20226e616d65223a20
2250617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c2062796c6f206279206ec49b636f20c5a17061746ec49b222c2022696d616765223a202
268747470733a2f2f63646e2e7873642e637a2f726573697a652f63353535656239633131353333313632386164666539396237343534353731655f657874726163743d302c302c313931392c313038305f726573697a653d3732302c3430355f2e6a70
673f686173683d6362316362623836336230353361613561333761346666616439303865303431227d7400000003323432740000000a323031392d31312d3138740000001a323031392d31312d31382031323a35303a30312e383136333736740000000
174
2/BBD880E8 | 56395 | \x430000000002bbd880b800000002bbd880e800023acd790ce551

Can you show the whole transaction? From the WAL dump it seems it just
did a single UPDATE:

I'm not sure what you mean. The above is the whole output I got from that
SELECT.

rmgr: Heap len (rec/tot): 59/ 4075, tx: 56395, lsn: 2/BBD86EA0, prev 2/BBD86E68, desc: LOCK off 2: xid 56395: flags 0 LOCK_ONLY EXCL_LOCK
blkref #0: rel 1663/19030/19048 fork main blk 415 (FPW); hole: offset: 56, length: 4176
rmgr: Heap len (rec/tot): 523/ 523, tx: 56395, lsn: 2/BBD87E90, prev 2/BBD86EA0, desc: HOT_UPDATE off 2 xmax 56395 ; new off 9 xmax 0
blkref #0: rel 1663/19030/19048 fork main blk 415
rmgr: Transaction len (rec/tot): 46/ 46, tx: 56395, lsn: 2/BBD880B8, prev 2/BBD87E90, desc: COMMIT 2019-11-20 23:28:47.016273 CET

Which fields does it update?

The only update that my system does in this database is:

UPDATE videos SET played = TRUE WHERE id = ?

The rest is just inserts:

INSERT INTO categories (name, metadata, cover_image, provider) VALUES (?, ?, ?, (SELECT id FROM providers WHERE system_name = ?))
INSERT INTO videos (title, metadata, cover_image, category, published) VALUES (?, ?, ?, ?, ?)

There are no other data modification statements executed.

Well, this is definitely the updated - both judging by the WAL dump and
also because the backtrace contains apply_handle_update.

Can you show us \d+ on the videos table? What's the replica identity?

regards

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

On Thu, Nov 21, 2019 at 03:35:03PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 02:55:23PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 02:32:37PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:59:13PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 12:53:26PM +0100, postgresql wrote:

Hello,

On Thu, Nov 21, 2019 at 11:39:40AM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

I forgot to add that publisher is still PostgreSQL 11.5.

I can also add that I have data checksumming enabled on both ends, and
it did not detect any corruption:

# pg_verify_checksums -D /var/lib/postgres/data
Checksum scan completed
Data checksum version: 1
Files scanned: 1751
Blocks scanned: 86592
Bad checksums: 0

# pg_checksums /var/lib/postgres/data
Checksum operation completed
Files scanned: 22777
Blocks scanned: 3601527
Bad checksums: 0
Data checksum version: 1

WAL log on the publisher is also dumpable to a state hours after the issues
started:

I've put the dump here, if it's of any use: https://megous.com/dl/tmp/wal_dump.txt

Dump ends with:

pg_waldump: FATAL: error in WAL record at 2/BBE0E538: invalid record length at 2/BBE0E5A8: wanted 24, got 0

But that seems normal. I get that error on my other database clusters, too.

I managed to extract the failing logical decoding data from the publisher, if
that helps:

SELECT * FROM pg_logical_slot_peek_binary_changes('l5_hometv', NULL, NULL, 'proto_version', '1', 'publication_names', 'pub');

2/BBD86EA0 | 56395 | \x4200000002bbd880b800023acd790ce5510000dc4b
2/BBD87E90 | 56395 | \x5200004a687075626c696300766964656f73006400080169640000000017ffffffff007469746c650000000019ffffffff00636f7665725f696d6167650000000011ffffffff006d657461646174610000000edafffffff
f0063617465676f72790000000017ffffffff007075626c6973686564000000043affffffff006164646564000000045affffffff00706c617965640000000010ffffffff
2/BBD87E90 | 56395 | \x5500004a684e0008740000000438333933740000005650617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c20627
96c6f206279206ec49b636f20c5a17061746ec49b7574000001397b226964223a20226430313064343430303965323131656162323539616331663662323230656538222c202264617465223a2022323031392d31312d3138222c20226e616d65223a20
2250617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c2062796c6f206279206ec49b636f20c5a17061746ec49b222c2022696d616765223a202
268747470733a2f2f63646e2e7873642e637a2f726573697a652f63353535656239633131353333313632386164666539396237343534353731655f657874726163743d302c302c313931392c313038305f726573697a653d3732302c3430355f2e6a70
673f686173683d6362316362623836336230353361613561333761346666616439303865303431227d7400000003323432740000000a323031392d31312d3138740000001a323031392d31312d31382031323a35303a30312e383136333736740000000
174
2/BBD880E8 | 56395 | \x430000000002bbd880b800000002bbd880e800023acd790ce551

Can you show the whole transaction? From the WAL dump it seems it just
did a single UPDATE:

I'm not sure what you mean. The above is the whole output I got from that
SELECT.

rmgr: Heap len (rec/tot): 59/ 4075, tx: 56395, lsn: 2/BBD86EA0, prev 2/BBD86E68, desc: LOCK off 2: xid 56395: flags 0 LOCK_ONLY EXCL_LOCK
blkref #0: rel 1663/19030/19048 fork main blk 415 (FPW); hole: offset: 56, length: 4176
rmgr: Heap len (rec/tot): 523/ 523, tx: 56395, lsn: 2/BBD87E90, prev 2/BBD86EA0, desc: HOT_UPDATE off 2 xmax 56395 ; new off 9 xmax 0
blkref #0: rel 1663/19030/19048 fork main blk 415
rmgr: Transaction len (rec/tot): 46/ 46, tx: 56395, lsn: 2/BBD880B8, prev 2/BBD87E90, desc: COMMIT 2019-11-20 23:28:47.016273 CET

Which fields does it update?

The only update that my system does in this database is:

UPDATE videos SET played = TRUE WHERE id = ?

The rest is just inserts:

INSERT INTO categories (name, metadata, cover_image, provider) VALUES (?, ?, ?, (SELECT id FROM providers WHERE system_name = ?))
INSERT INTO videos (title, metadata, cover_image, category, published) VALUES (?, ?, ?, ?, ?)

There are no other data modification statements executed.

Well, this is definitely the updated - both judging by the WAL dump and
also because the backtrace contains apply_handle_update.

I've also managed to get valgrind output on the segfaulting process:

https://megous.com/dl/tmp/valgrind-105524-109020.log

Though it probably doesn't show much new.

Can you show us \d+ on the videos table? What's the replica identity?

Table "public.videos"
Column | Type | Collation | Nullable | Default | Storage | Stats target | Description
-------------+-----------------------------+-----------+----------+------------------------------------+----------+--------------+-------------
id | integer | | not null | nextval('videos_id_seq'::regclass) | plain | |
title | text | | not null | | extended | |
cover_image | bytea | | not null | | extended | |
metadata | jsonb | | not null | | extended | |
category | integer | | not null | | plain | |
published | date | | not null | | plain | |
added | timestamp without time zone | | not null | now() | plain | |
played | boolean | | not null | false | plain | |
Indexes:
"videos_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
"videos_category_fkey" FOREIGN KEY (category) REFERENCES categories(id)
Publications:
"pub"

Table "public.videos"
Column | Type | Collation | Nullable | Default | Storage | Stats target | Description
-------------+-----------------------------+-----------+----------+------------------------------------+----------+--------------+-------------
id | integer | | not null | nextval('videos_id_seq'::regclass) | plain | |
title | text | | not null | | extended | |
cover_image | bytea | | not null | | extended | |
metadata | jsonb | | not null | | extended | |
category | integer | | not null | | plain | |
published | date | | not null | | plain | |
added | timestamp without time zone | | not null | now() | plain | |
played | boolean | | not null | false | plain | |
Indexes:
"videos_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
"videos_category_fkey" FOREIGN KEY (category) REFERENCES categories(id)
Access method: heap

Googling for relica identity, it looks like it should be shown in the \d+
output, but it isn't, for me. Maybe because it's has default value?

regards,
o.

On Thu, Nov 21, 2019 at 04:07:16PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 03:35:03PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 02:55:23PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 02:32:37PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:59:13PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 12:53:26PM +0100, postgresql wrote:

Hello,

On Thu, Nov 21, 2019 at 11:39:40AM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 01:14:18AM +0000, PG Bug reporting form wrote:

Replication of one of my databases (running on ARMv7 machine) started
segfaulting on the subscriber side (x86_64) like this:

#0 0x00007fc259739917 in __memmove_sse2_unaligned_erms () from
/usr/lib/libc.so.6
#1 0x000055d033e93d44 in memcpy (__len=620701425, __src=<optimized out>,
__dest=0x55d0356da804) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55d0356da3b8) at execTuples.c:235
#3 0x000055d033e94d32 in ExecFetchSlotHeapTuple
(slot=slot@entry=0x55d0356da3b8, materialize=materialize@entry=true,
shouldFree=shouldFree@entry=0x7fff0e7cf387) at execTuples.c:1624

I forgot to add that publisher is still PostgreSQL 11.5.

I can also add that I have data checksumming enabled on both ends, and
it did not detect any corruption:

# pg_verify_checksums -D /var/lib/postgres/data
Checksum scan completed
Data checksum version: 1
Files scanned: 1751
Blocks scanned: 86592
Bad checksums: 0

# pg_checksums /var/lib/postgres/data
Checksum operation completed
Files scanned: 22777
Blocks scanned: 3601527
Bad checksums: 0
Data checksum version: 1

WAL log on the publisher is also dumpable to a state hours after the issues
started:

I've put the dump here, if it's of any use: https://megous.com/dl/tmp/wal_dump.txt

Dump ends with:

pg_waldump: FATAL: error in WAL record at 2/BBE0E538: invalid record length at 2/BBE0E5A8: wanted 24, got 0

But that seems normal. I get that error on my other database clusters, too.

I managed to extract the failing logical decoding data from the publisher, if
that helps:

SELECT * FROM pg_logical_slot_peek_binary_changes('l5_hometv', NULL, NULL, 'proto_version', '1', 'publication_names', 'pub');

2/BBD86EA0 | 56395 | \x4200000002bbd880b800023acd790ce5510000dc4b
2/BBD87E90 | 56395 | \x5200004a687075626c696300766964656f73006400080169640000000017ffffffff007469746c650000000019ffffffff00636f7665725f696d6167650000000011ffffffff006d657461646174610000000edafffffff
f0063617465676f72790000000017ffffffff007075626c6973686564000000043affffffff006164646564000000045affffffff00706c617965640000000010ffffffff
2/BBD87E90 | 56395 | \x5500004a684e0008740000000438333933740000005650617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c20627
96c6f206279206ec49b636f20c5a17061746ec49b7574000001397b226964223a20226430313064343430303965323131656162323539616331663662323230656538222c202264617465223a2022323031392d31312d3138222c20226e616d65223a20
2250617a6465726b613a204f206dc3a964696120736520706f7665646520626f6a2e204b64796279206ec3a17320706f6c6974696369206d696c6f76616c692c2062796c6f206279206ec49b636f20c5a17061746ec49b222c2022696d616765223a202
268747470733a2f2f63646e2e7873642e637a2f726573697a652f63353535656239633131353333313632386164666539396237343534353731655f657874726163743d302c302c313931392c313038305f726573697a653d3732302c3430355f2e6a70
673f686173683d6362316362623836336230353361613561333761346666616439303865303431227d7400000003323432740000000a323031392d31312d3138740000001a323031392d31312d31382031323a35303a30312e383136333736740000000
174
2/BBD880E8 | 56395 | \x430000000002bbd880b800000002bbd880e800023acd790ce551

Can you show the whole transaction? From the WAL dump it seems it just
did a single UPDATE:

I'm not sure what you mean. The above is the whole output I got from that
SELECT.

rmgr: Heap len (rec/tot): 59/ 4075, tx: 56395, lsn: 2/BBD86EA0, prev 2/BBD86E68, desc: LOCK off 2: xid 56395: flags 0 LOCK_ONLY EXCL_LOCK
blkref #0: rel 1663/19030/19048 fork main blk 415 (FPW); hole: offset: 56, length: 4176
rmgr: Heap len (rec/tot): 523/ 523, tx: 56395, lsn: 2/BBD87E90, prev 2/BBD86EA0, desc: HOT_UPDATE off 2 xmax 56395 ; new off 9 xmax 0
blkref #0: rel 1663/19030/19048 fork main blk 415
rmgr: Transaction len (rec/tot): 46/ 46, tx: 56395, lsn: 2/BBD880B8, prev 2/BBD87E90, desc: COMMIT 2019-11-20 23:28:47.016273 CET

Which fields does it update?

The only update that my system does in this database is:

UPDATE videos SET played = TRUE WHERE id = ?

The rest is just inserts:

INSERT INTO categories (name, metadata, cover_image, provider) VALUES (?, ?, ?, (SELECT id FROM providers WHERE system_name = ?))
INSERT INTO videos (title, metadata, cover_image, category, published) VALUES (?, ?, ?, ?, ?)

There are no other data modification statements executed.

Well, this is definitely the updated - both judging by the WAL dump and
also because the backtrace contains apply_handle_update.

I've also managed to get valgrind output on the segfaulting process:

https://megous.com/dl/tmp/valgrind-105524-109020.log

Though it probably doesn't show much new.

Is postgres actually compiled with valgrind support? What does pg_config
say?

If you're building the server locally (I don't think there are packages
with valgrind enabled), maybe try adding --enable-cassert option and

CFLAGS"-DRANDOMIZE_ALLOCATED_MEMORY"

which will do more extensive checks at runtime.

Can you show us \d+ on the videos table? What's the replica identity?

Table "public.videos"
Column | Type | Collation | Nullable | Default | Storage | Stats target | Description
-------------+-----------------------------+-----------+----------+------------------------------------+----------+--------------+-------------
id | integer | | not null | nextval('videos_id_seq'::regclass) | plain | |
title | text | | not null | | extended | |
cover_image | bytea | | not null | | extended | |
metadata | jsonb | | not null | | extended | |
category | integer | | not null | | plain | |
published | date | | not null | | plain | |
added | timestamp without time zone | | not null | now() | plain | |
played | boolean | | not null | false | plain | |
Indexes:
"videos_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
"videos_category_fkey" FOREIGN KEY (category) REFERENCES categories(id)
Publications:
"pub"

Table "public.videos"
Column | Type | Collation | Nullable | Default | Storage | Stats target | Description
-------------+-----------------------------+-----------+----------+------------------------------------+----------+--------------+-------------
id | integer | | not null | nextval('videos_id_seq'::regclass) | plain | |
title | text | | not null | | extended | |
cover_image | bytea | | not null | | extended | |
metadata | jsonb | | not null | | extended | |
category | integer | | not null | | plain | |
published | date | | not null | | plain | |
added | timestamp without time zone | | not null | now() | plain | |
played | boolean | | not null | false | plain | |
Indexes:
"videos_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
"videos_category_fkey" FOREIGN KEY (category) REFERENCES categories(id)
Access method: heap

Googling for relica identity, it looks like it should be shown in the \d+
output, but it isn't, for me. Maybe because it's has default value?

Yes, I think it should be listed either for the index, or there should
be an extra section with replica identity. But that depends on psql
version. Aren't you accidentally using an older psql version? That
should be mentioned right after connecting to the server, I think.

regards

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

On Thu, Nov 21, 2019 at 04:27:32PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 04:07:16PM +0100, Ondřej Jirman wrote:

I've also managed to get valgrind output on the segfaulting process:

https://megous.com/dl/tmp/valgrind-105524-109020.log

Though it probably doesn't show much new.

Is postgres actually compiled with valgrind support? What does pg_config
say?

I don't see any valgrind related options in configure --help, I repackaged it
just with CFLAGS set to -ggdb -Og.

CONFIGURE = '--prefix=/usr' '--mandir=/usr/share/man' '--datadir=/usr/share/postgresql' '--sysconfdir=/etc' '--with-gssapi' '--with-libxml' '--with-openssl' '--with-perl' '--with-python' '--with-tcl' '--with-pam' '--with-system-tzdata=/usr/share/zoneinfo' '--with-uuid=e2fs' '--with-icu' '--with-systemd' '--with-ldap' '--enable-nls' '--enable-thread-safety' '--disable-rpath' 'PYTHON=/usr/bin/python2' 'CFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug' 'LDFLAGS=-Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now' 'CPPFLAGS=-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug'
CC = gcc
CPPFLAGS = -D_FORTIFY_SOURCE=2 -D_GNU_SOURCE -I/usr/include/libxml2
CFLAGS = -Wall -Wmissing-prototypes -Wpointer-arith -Wdeclaration-after-statement -Werror=vla -Wendif-labels -Wmissing-format-attribute -Wformat-security -fno-strict-aliasing -fwrapv -fexcess-precision=standard -Wno-format-truncation -Wno-stringop-truncation -march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug
CFLAGS_SL = -fPIC
LDFLAGS = -Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now -Wl,--as-needed
LDFLAGS_EX =
LDFLAGS_SL =
LIBS = -lpgcommon -lpgport -lpthread -lxml2 -lpam -lssl -lcrypto -lgssapi_krb5 -lz -lreadline -lrt -lcrypt -ldl -lm
VERSION = PostgreSQL 12.1

If you're building the server locally (I don't think there are packages
with valgrind enabled), maybe try adding --enable-cassert option and

CFLAGS"-DRANDOMIZE_ALLOCATED_MEMORY"

which will do more extensive checks at runtime.

Done.

CONFIGURE = '--prefix=/usr' '--mandir=/usr/share/man' '--datadir=/usr/share/postgresql' '--sysconfdir=/etc' '--with-gssapi' '--with-libxml' '--with-openssl' '--with-perl' '--with-python' '--with-tcl' '--with-pam' '--with-system-tzdata=/usr/share/zoneinfo' '--with-uuid=e2fs' '--with-icu' '--with-systemd' '--with-ldap' '--enable-nls' '--enable-thread-safety' '--disable-rpath' '--enable-cassert' 'PYTHON=/usr/bin/python2' 'CFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug -DRANDOMIZE_ALLOCATED_MEMORY' 'LDFLAGS=-Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now' 'CPPFLAGS=-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug'
CC = gcc
CPPFLAGS = -D_FORTIFY_SOURCE=2 -D_GNU_SOURCE -I/usr/include/libxml2
CFLAGS = -Wall -Wmissing-prototypes -Wpointer-arith -Wdeclaration-after-statement -Werror=vla -Wendif-labels -Wmissing-format-attribute -Wformat-security -fno-strict-aliasing -fwrapv -fexcess-precision=standard -Wno-format-truncation -Wno-stringop-truncation -march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug -DRANDOMIZE_ALLOCATED_MEMORY
CFLAGS_SL = -fPIC
LDFLAGS = -Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now -Wl,--as-needed
LDFLAGS_EX =
LDFLAGS_SL =
LIBS = -lpgcommon -lpgport -lpthread -lxml2 -lpam -lssl -lcrypto -lgssapi_krb5 -lz -lreadline -lrt -lcrypt -ldl -lm
VERSION = PostgreSQL 12.1

The difference now is that _len argument value is not stable accross crashes.

one crash...

#0 0x00007fb90c336917 in __memmove_sse2_unaligned_erms () from /usr/lib/libc.so.6
#1 0x000055ff2a7d0e64 in memcpy (__len=972662513, __src=<optimized out>, __dest=0x55ff2cc7dce4) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55ff2cc7d868) at execTuples.c:235
#3 0x000055ff2a7d2a63 in ExecFetchSlotHeapTuple (slot=slot@entry=0x55ff2cc7d868, materialize=materialize@entry=true, shouldFree=shouldFree@entry=0x7ffc80cfc607) at execTuples.c:1624
#4 0x000055ff2a634809 in heapam_tuple_update (relation=0x7fb8f8338100, otid=0x55ff2cc7e138, slot=0x55ff2cc7d868, cid=0, snapshot=<optimized out>, crosscheck=0x0, wait=true, tmfd=0x7ffc80cfc680,
lockmode=0x7ffc80cfc67c, update_indexes=0x7ffc80cfc6d7) at heapam_handler.c:325
#5 0x000055ff2a675d55 in table_tuple_update (update_indexes=0x7ffc80cfc6d7, lockmode=0x7ffc80cfc67c, tmfd=0x7ffc80cfc680, wait=true, crosscheck=0x0, snapshot=0x0, cid=<optimized out>,
slot=0x55ff2cc7d868, otid=0x55ff2cc7e138, rel=0x7fb8f8338100) at ../../../../src/include/access/tableam.h:1261
#6 simple_table_tuple_update (rel=rel@entry=0x7fb8f8338100, otid=otid@entry=0x55ff2cc7e138, slot=slot@entry=0x55ff2cc7d868, snapshot=0x0, update_indexes=update_indexes@entry=0x7ffc80cfc6d7)
at tableam.c:325
#7 0x000055ff2a7cdf08 in ExecSimpleRelationUpdate (estate=estate@entry=0x55ff2ccd02b8, epqstate=epqstate@entry=0x7ffc80cfc730, searchslot=searchslot@entry=0x55ff2cc7e108,
slot=slot@entry=0x55ff2cc7d868) at execReplication.c:493
#8 0x000055ff2a8eb8b2 in apply_handle_update (s=s@entry=0x7ffc80d03d00) at worker.c:750
#9 0x000055ff2a8ebe62 in apply_dispatch (s=s@entry=0x7ffc80d03d00) at worker.c:968
#10 0x000055ff2a8ec5ba in LogicalRepApplyLoop (last_received=11741462160) at worker.c:1176
#11 0x000055ff2a8ecd1a in ApplyWorkerMain (main_arg=<optimized out>) at worker.c:1734
#12 0x000055ff2a8b3927 in StartBackgroundWorker () at bgworker.c:834
#13 0x000055ff2a8c2b6b in do_start_bgworker (rw=rw@entry=0x55ff2cbbf430) at postmaster.c:5770
#14 0x000055ff2a8c2cf7 in maybe_start_bgworkers () at postmaster.c:5996
#15 0x000055ff2a8c3678 in sigusr1_handler (postgres_signal_arg=<optimized out>) at postmaster.c:5167
#16 <signal handler called>
#17 0x00007fb90c384e2a in select () from /usr/lib/libc.so.6
#18 0x000055ff2a8c40f8 in ServerLoop () at postmaster.c:1668
#19 0x000055ff2a8c54fc in PostmasterMain (argc=3, argv=<optimized out>) at postmaster.c:1377
#20 0x000055ff2a81f88a in main (argc=3, argv=0x55ff2cb94260) at main.c:228

and another ...

#0 0x00007f7a1befc917 in __memmove_sse2_unaligned_erms () from /usr/lib/libc.so.6
#1 0x0000559a5439ae64 in memcpy (__len=766338801, __src=<optimized out>, __dest=0x559a55626934) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x559a556264b8) at execTuples.c:235
#3 0x0000559a5439ca63 in ExecFetchSlotHeapTuple (slot=slot@entry=0x559a556264b8, materialize=materialize@entry=true, shouldFree=shouldFree@entry=0x7fff7f2d5787) at execTuples.c:1624
#4 0x0000559a541fe809 in heapam_tuple_update (relation=0x7f7a07efe100, otid=0x559a55626d88, slot=0x559a556264b8, cid=0, snapshot=<optimized out>, crosscheck=0x0, wait=true, tmfd=0x7fff7f2d5800,
lockmode=0x7fff7f2d57fc, update_indexes=0x7fff7f2d5857) at heapam_handler.c:325
#5 0x0000559a5423fd55 in table_tuple_update (update_indexes=0x7fff7f2d5857, lockmode=0x7fff7f2d57fc, tmfd=0x7fff7f2d5800, wait=true, crosscheck=0x0, snapshot=0x0, cid=<optimized out>,
slot=0x559a556264b8, otid=0x559a55626d88, rel=0x7f7a07efe100) at ../../../../src/include/access/tableam.h:1261
#6 simple_table_tuple_update (rel=rel@entry=0x7f7a07efe100, otid=otid@entry=0x559a55626d88, slot=slot@entry=0x559a556264b8, snapshot=0x0, update_indexes=update_indexes@entry=0x7fff7f2d5857)
at tableam.c:325
#7 0x0000559a54397f08 in ExecSimpleRelationUpdate (estate=estate@entry=0x559a55678dc8, epqstate=epqstate@entry=0x7fff7f2d58b0, searchslot=searchslot@entry=0x559a55626d58,
slot=slot@entry=0x559a556264b8) at execReplication.c:493
#8 0x0000559a544b58b2 in apply_handle_update (s=s@entry=0x7fff7f2dce80) at worker.c:750
#9 0x0000559a544b5e62 in apply_dispatch (s=s@entry=0x7fff7f2dce80) at worker.c:968
#10 0x0000559a544b65ba in LogicalRepApplyLoop (last_received=11741462160) at worker.c:1176
#11 0x0000559a544b6d1a in ApplyWorkerMain (main_arg=<optimized out>) at worker.c:1734
#12 0x0000559a5447d927 in StartBackgroundWorker () at bgworker.c:834
#13 0x0000559a5448cb6b in do_start_bgworker (rw=rw@entry=0x559a5558c010) at postmaster.c:5770
#14 0x0000559a5448ccf7 in maybe_start_bgworkers () at postmaster.c:5996
#15 0x0000559a5448d678 in sigusr1_handler (postgres_signal_arg=<optimized out>) at postmaster.c:5167
#16 <signal handler called>
#17 0x00007f7a1bf4ae2a in select () from /usr/lib/libc.so.6
#18 0x0000559a5448e0f8 in ServerLoop () at postmaster.c:1668
#19 0x0000559a5448f4fc in PostmasterMain (argc=3, argv=<optimized out>) at postmaster.c:1377
#20 0x0000559a543e988a in main (argc=3, argv=0x559a55534260) at main.c:228

So it perhaps looks like some memory management issue in the subscribing
postmaster, rather than wal corruption on the publisher.

Can you show us \d+ on the videos table? What's the replica identity?

Table "public.videos"
Column | Type | Collation | Nullable | Default | Storage | Stats target | Description
-------------+-----------------------------+-----------+----------+------------------------------------+----------+--------------+-------------
id | integer | | not null | nextval('videos_id_seq'::regclass) | plain | |
title | text | | not null | | extended | |
cover_image | bytea | | not null | | extended | |
metadata | jsonb | | not null | | extended | |
category | integer | | not null | | plain | |
published | date | | not null | | plain | |
added | timestamp without time zone | | not null | now() | plain | |
played | boolean | | not null | false | plain | |
Indexes:
"videos_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
"videos_category_fkey" FOREIGN KEY (category) REFERENCES categories(id)
Publications:
"pub"

Table "public.videos"
Column | Type | Collation | Nullable | Default | Storage | Stats target | Description
-------------+-----------------------------+-----------+----------+------------------------------------+----------+--------------+-------------
id | integer | | not null | nextval('videos_id_seq'::regclass) | plain | |
title | text | | not null | | extended | |
cover_image | bytea | | not null | | extended | |
metadata | jsonb | | not null | | extended | |
category | integer | | not null | | plain | |
published | date | | not null | | plain | |
added | timestamp without time zone | | not null | now() | plain | |
played | boolean | | not null | false | plain | |
Indexes:
"videos_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
"videos_category_fkey" FOREIGN KEY (category) REFERENCES categories(id)
Access method: heap

Googling for relica identity, it looks like it should be shown in the \d+
output, but it isn't, for me. Maybe because it's has default value?

Yes, I think it should be listed either for the index, or there should
be an extra section with replica identity. But that depends on psql
version. Aren't you accidentally using an older psql version? That
should be mentioned right after connecting to the server, I think.

Maybe it has something to do with my upgrade method. I dumped/restored
the replica with pg_dumpall, and then just proceded to enable subscription
and refresh publication with (copy_data=false) for all my subscriptions.

Now, I've tried to start fresh and replicate from the primary "hometv" database
into a new l5_hometv2 on my crashing 12.1 server and it replicates fine, no
crashes. Anyway even in this fresh replicated database, there's no REPLICA
IDENTITY in the \d+ output.

I don't have multiple postgresql installations on the host. There's only
a difference between primary version 11.5 (ARMv7) and replica 12.1 (x86_64).

regards,
o.

On Thu, Nov 21, 2019 at 04:57:07PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 04:27:32PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 04:07:16PM +0100, Ondřej Jirman wrote:

I've also managed to get valgrind output on the segfaulting process:

https://megous.com/dl/tmp/valgrind-105524-109020.log

Though it probably doesn't show much new.

Is postgres actually compiled with valgrind support? What does pg_config
say?

I don't see any valgrind related options in configure --help, I repackaged it
just with CFLAGS set to -ggdb -Og.

You need to use -DUSE_VALGRIND or edit pg_config_manual.h. I usually
just use

CFLAGS="-DRANDOMIZE_ALLOCATED_MEMORY -DUSE_VALGRIND -O0 -ggdb"

which does the trick. Without the USE_VALGRIND defined, we don't include
the valgrind instrumentation, so I suppose the previous results are bogus.

CONFIGURE = '--prefix=/usr' '--mandir=/usr/share/man' '--datadir=/usr/share/postgresql' '--sysconfdir=/etc' '--with-gssapi' '--with-libxml' '--with-openssl' '--with-perl' '--with-python' '--with-tcl' '--with-pam' '--with-system-tzdata=/usr/share/zoneinfo' '--with-uuid=e2fs' '--with-icu' '--with-systemd' '--with-ldap' '--enable-nls' '--enable-thread-safety' '--disable-rpath' 'PYTHON=/usr/bin/python2' 'CFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug' 'LDFLAGS=-Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now' 'CPPFLAGS=-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug'
CC = gcc
CPPFLAGS = -D_FORTIFY_SOURCE=2 -D_GNU_SOURCE -I/usr/include/libxml2
CFLAGS = -Wall -Wmissing-prototypes -Wpointer-arith -Wdeclaration-after-statement -Werror=vla -Wendif-labels -Wmissing-format-attribute -Wformat-security -fno-strict-aliasing -fwrapv -fexcess-precision=standard -Wno-format-truncation -Wno-stringop-truncation -march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug
CFLAGS_SL = -fPIC
LDFLAGS = -Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now -Wl,--as-needed
LDFLAGS_EX =
LDFLAGS_SL =
LIBS = -lpgcommon -lpgport -lpthread -lxml2 -lpam -lssl -lcrypto -lgssapi_krb5 -lz -lreadline -lrt -lcrypt -ldl -lm
VERSION = PostgreSQL 12.1

If you're building the server locally (I don't think there are packages
with valgrind enabled), maybe try adding --enable-cassert option and

CFLAGS"-DRANDOMIZE_ALLOCATED_MEMORY"

which will do more extensive checks at runtime.

Done.

CONFIGURE = '--prefix=/usr' '--mandir=/usr/share/man' '--datadir=/usr/share/postgresql' '--sysconfdir=/etc' '--with-gssapi' '--with-libxml' '--with-openssl' '--with-perl' '--with-python' '--with-tcl' '--with-pam' '--with-system-tzdata=/usr/share/zoneinfo' '--with-uuid=e2fs' '--with-icu' '--with-systemd' '--with-ldap' '--enable-nls' '--enable-thread-safety' '--disable-rpath' '--enable-cassert' 'PYTHON=/usr/bin/python2' 'CFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug -DRANDOMIZE_ALLOCATED_MEMORY' 'LDFLAGS=-Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now' 'CPPFLAGS=-D_FORTIFY_SOURCE=2' 'CXXFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug'
CC = gcc
CPPFLAGS = -D_FORTIFY_SOURCE=2 -D_GNU_SOURCE -I/usr/include/libxml2
CFLAGS = -Wall -Wmissing-prototypes -Wpointer-arith -Wdeclaration-after-statement -Werror=vla -Wendif-labels -Wmissing-format-attribute -Wformat-security -fno-strict-aliasing -fwrapv -fexcess-precision=standard -Wno-format-truncation -Wno-stringop-truncation -march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong -fno-plt -Og -ggdb -fdebug-prefix-map=/workspace/external/pgsql/postgresql-pkg/src=/usr/src/debug -DRANDOMIZE_ALLOCATED_MEMORY
CFLAGS_SL = -fPIC
LDFLAGS = -Wl,-O1,--sort-common,--as-needed,-z,relro,-z,now -Wl,--as-needed
LDFLAGS_EX =
LDFLAGS_SL =
LIBS = -lpgcommon -lpgport -lpthread -lxml2 -lpam -lssl -lcrypto -lgssapi_krb5 -lz -lreadline -lrt -lcrypt -ldl -lm
VERSION = PostgreSQL 12.1

The difference now is that _len argument value is not stable accross crashes.

one crash...

#0 0x00007fb90c336917 in __memmove_sse2_unaligned_erms () from /usr/lib/libc.so.6
#1 0x000055ff2a7d0e64 in memcpy (__len=972662513, __src=<optimized out>, __dest=0x55ff2cc7dce4) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x55ff2cc7d868) at execTuples.c:235
#3 0x000055ff2a7d2a63 in ExecFetchSlotHeapTuple (slot=slot@entry=0x55ff2cc7d868, materialize=materialize@entry=true, shouldFree=shouldFree@entry=0x7ffc80cfc607) at execTuples.c:1624
#4 0x000055ff2a634809 in heapam_tuple_update (relation=0x7fb8f8338100, otid=0x55ff2cc7e138, slot=0x55ff2cc7d868, cid=0, snapshot=<optimized out>, crosscheck=0x0, wait=true, tmfd=0x7ffc80cfc680,
lockmode=0x7ffc80cfc67c, update_indexes=0x7ffc80cfc6d7) at heapam_handler.c:325
#5 0x000055ff2a675d55 in table_tuple_update (update_indexes=0x7ffc80cfc6d7, lockmode=0x7ffc80cfc67c, tmfd=0x7ffc80cfc680, wait=true, crosscheck=0x0, snapshot=0x0, cid=<optimized out>,
slot=0x55ff2cc7d868, otid=0x55ff2cc7e138, rel=0x7fb8f8338100) at ../../../../src/include/access/tableam.h:1261
#6 simple_table_tuple_update (rel=rel@entry=0x7fb8f8338100, otid=otid@entry=0x55ff2cc7e138, slot=slot@entry=0x55ff2cc7d868, snapshot=0x0, update_indexes=update_indexes@entry=0x7ffc80cfc6d7)
at tableam.c:325
#7 0x000055ff2a7cdf08 in ExecSimpleRelationUpdate (estate=estate@entry=0x55ff2ccd02b8, epqstate=epqstate@entry=0x7ffc80cfc730, searchslot=searchslot@entry=0x55ff2cc7e108,
slot=slot@entry=0x55ff2cc7d868) at execReplication.c:493
#8 0x000055ff2a8eb8b2 in apply_handle_update (s=s@entry=0x7ffc80d03d00) at worker.c:750
#9 0x000055ff2a8ebe62 in apply_dispatch (s=s@entry=0x7ffc80d03d00) at worker.c:968
#10 0x000055ff2a8ec5ba in LogicalRepApplyLoop (last_received=11741462160) at worker.c:1176
#11 0x000055ff2a8ecd1a in ApplyWorkerMain (main_arg=<optimized out>) at worker.c:1734
#12 0x000055ff2a8b3927 in StartBackgroundWorker () at bgworker.c:834
#13 0x000055ff2a8c2b6b in do_start_bgworker (rw=rw@entry=0x55ff2cbbf430) at postmaster.c:5770
#14 0x000055ff2a8c2cf7 in maybe_start_bgworkers () at postmaster.c:5996
#15 0x000055ff2a8c3678 in sigusr1_handler (postgres_signal_arg=<optimized out>) at postmaster.c:5167
#16 <signal handler called>
#17 0x00007fb90c384e2a in select () from /usr/lib/libc.so.6
#18 0x000055ff2a8c40f8 in ServerLoop () at postmaster.c:1668
#19 0x000055ff2a8c54fc in PostmasterMain (argc=3, argv=<optimized out>) at postmaster.c:1377
#20 0x000055ff2a81f88a in main (argc=3, argv=0x55ff2cb94260) at main.c:228

and another ...

#0 0x00007f7a1befc917 in __memmove_sse2_unaligned_erms () from /usr/lib/libc.so.6
#1 0x0000559a5439ae64 in memcpy (__len=766338801, __src=<optimized out>, __dest=0x559a55626934) at /usr/include/bits/string_fortified.h:34
#2 tts_virtual_materialize (slot=0x559a556264b8) at execTuples.c:235
#3 0x0000559a5439ca63 in ExecFetchSlotHeapTuple (slot=slot@entry=0x559a556264b8, materialize=materialize@entry=true, shouldFree=shouldFree@entry=0x7fff7f2d5787) at execTuples.c:1624
#4 0x0000559a541fe809 in heapam_tuple_update (relation=0x7f7a07efe100, otid=0x559a55626d88, slot=0x559a556264b8, cid=0, snapshot=<optimized out>, crosscheck=0x0, wait=true, tmfd=0x7fff7f2d5800,
lockmode=0x7fff7f2d57fc, update_indexes=0x7fff7f2d5857) at heapam_handler.c:325
#5 0x0000559a5423fd55 in table_tuple_update (update_indexes=0x7fff7f2d5857, lockmode=0x7fff7f2d57fc, tmfd=0x7fff7f2d5800, wait=true, crosscheck=0x0, snapshot=0x0, cid=<optimized out>,
slot=0x559a556264b8, otid=0x559a55626d88, rel=0x7f7a07efe100) at ../../../../src/include/access/tableam.h:1261
#6 simple_table_tuple_update (rel=rel@entry=0x7f7a07efe100, otid=otid@entry=0x559a55626d88, slot=slot@entry=0x559a556264b8, snapshot=0x0, update_indexes=update_indexes@entry=0x7fff7f2d5857)
at tableam.c:325
#7 0x0000559a54397f08 in ExecSimpleRelationUpdate (estate=estate@entry=0x559a55678dc8, epqstate=epqstate@entry=0x7fff7f2d58b0, searchslot=searchslot@entry=0x559a55626d58,
slot=slot@entry=0x559a556264b8) at execReplication.c:493
#8 0x0000559a544b58b2 in apply_handle_update (s=s@entry=0x7fff7f2dce80) at worker.c:750
#9 0x0000559a544b5e62 in apply_dispatch (s=s@entry=0x7fff7f2dce80) at worker.c:968
#10 0x0000559a544b65ba in LogicalRepApplyLoop (last_received=11741462160) at worker.c:1176
#11 0x0000559a544b6d1a in ApplyWorkerMain (main_arg=<optimized out>) at worker.c:1734
#12 0x0000559a5447d927 in StartBackgroundWorker () at bgworker.c:834
#13 0x0000559a5448cb6b in do_start_bgworker (rw=rw@entry=0x559a5558c010) at postmaster.c:5770
#14 0x0000559a5448ccf7 in maybe_start_bgworkers () at postmaster.c:5996
#15 0x0000559a5448d678 in sigusr1_handler (postgres_signal_arg=<optimized out>) at postmaster.c:5167
#16 <signal handler called>
#17 0x00007f7a1bf4ae2a in select () from /usr/lib/libc.so.6
#18 0x0000559a5448e0f8 in ServerLoop () at postmaster.c:1668
#19 0x0000559a5448f4fc in PostmasterMain (argc=3, argv=<optimized out>) at postmaster.c:1377
#20 0x0000559a543e988a in main (argc=3, argv=0x559a55534260) at main.c:228

So it perhaps looks like some memory management issue in the subscribing
postmaster, rather than wal corruption on the publisher.

Right, maybe using freed memory, or something like that.

Can you show us \d+ on the videos table? What's the replica identity?

Table "public.videos"
Column | Type | Collation | Nullable | Default | Storage | Stats target | Description
-------------+-----------------------------+-----------+----------+------------------------------------+----------+--------------+-------------
id | integer | | not null | nextval('videos_id_seq'::regclass) | plain | |
title | text | | not null | | extended | |
cover_image | bytea | | not null | | extended | |
metadata | jsonb | | not null | | extended | |
category | integer | | not null | | plain | |
published | date | | not null | | plain | |
added | timestamp without time zone | | not null | now() | plain | |
played | boolean | | not null | false | plain | |
Indexes:
"videos_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
"videos_category_fkey" FOREIGN KEY (category) REFERENCES categories(id)
Publications:
"pub"

Table "public.videos"
Column | Type | Collation | Nullable | Default | Storage | Stats target | Description
-------------+-----------------------------+-----------+----------+------------------------------------+----------+--------------+-------------
id | integer | | not null | nextval('videos_id_seq'::regclass) | plain | |
title | text | | not null | | extended | |
cover_image | bytea | | not null | | extended | |
metadata | jsonb | | not null | | extended | |
category | integer | | not null | | plain | |
published | date | | not null | | plain | |
added | timestamp without time zone | | not null | now() | plain | |
played | boolean | | not null | false | plain | |
Indexes:
"videos_pkey" PRIMARY KEY, btree (id)
Foreign-key constraints:
"videos_category_fkey" FOREIGN KEY (category) REFERENCES categories(id)
Access method: heap

Googling for relica identity, it looks like it should be shown in the \d+
output, but it isn't, for me. Maybe because it's has default value?

Yes, I think it should be listed either for the index, or there should
be an extra section with replica identity. But that depends on psql
version. Aren't you accidentally using an older psql version? That
should be mentioned right after connecting to the server, I think.

Maybe it has something to do with my upgrade method. I dumped/restored
the replica with pg_dumpall, and then just proceded to enable subscription
and refresh publication with (copy_data=false) for all my subscriptions.

Interesting.

Now, I've tried to start fresh and replicate from the primary "hometv" database
into a new l5_hometv2 on my crashing 12.1 server and it replicates fine, no
crashes. Anyway even in this fresh replicated database, there's no REPLICA
IDENTITY in the \d+ output.

I don't have multiple postgresql installations on the host. There's only
a difference between primary version 11.5 (ARMv7) and replica 12.1 (x86_64).

Hmmm, not sure. Have to check the code.

regards

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

On Thu, Nov 21, 2019 at 04:57:07PM +0100, Ondřej Jirman wrote:

Maybe it has something to do with my upgrade method. I dumped/restored
the replica with pg_dumpall, and then just proceded to enable subscription
and refresh publication with (copy_data=false) for all my subscriptions.

OTOH, it may not. There are 2 more databases replicated the same way from
the same database cluster, and they don't crash the replica server, and
continue replicating. The one of the other databases also has bytea columns in
some of the tables.

It really just seems related to the machine restart (a regular one) that I did
on the primary, minutes later replica crashed, and kept crashing ever since
whenever connecting to the primary for the hometv database.

So maybe something's wrong with the replica database (maybe because the
connection got killed by the walsender at unfortunate time), rather than the
original database, because I can replicate the original DB afresh into a new copy
just fine and other databases continue replicating just fine if I disable
the crashing subscription.

regards,
o.

On Thu, Nov 21, 2019 at 05:09:06PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 04:57:07PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 04:27:32PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 04:07:16PM +0100, Ondřej Jirman wrote:

I've also managed to get valgrind output on the segfaulting process:

https://megous.com/dl/tmp/valgrind-105524-109020.log

Though it probably doesn't show much new.

Is postgres actually compiled with valgrind support? What does pg_config
say?

I don't see any valgrind related options in configure --help, I repackaged it
just with CFLAGS set to -ggdb -Og.

You need to use -DUSE_VALGRIND or edit pg_config_manual.h. I usually
just use

CFLAGS="-DRANDOMIZE_ALLOCATED_MEMORY -DUSE_VALGRIND -O0 -ggdb"

which does the trick. Without the USE_VALGRIND defined, we don't include
the valgrind instrumentation, so I suppose the previous results are bogus.

Two new valgrind logs, now with -DUSE_VALGRIND:

https://megous.com/dl/tmp/valgrind-172090.log
https://megous.com/dl/tmp/valgrind-172143.log

A lots of uninitialized 1b accesses around VARATT_IS_EXTERNAL_EXPANDED.

So slot->tts_values[natt] is probably uninitialized.

Which is why the backtrace had a weird value there, I guess.

regards,
o.

On Thu, Nov 21, 2019 at 05:15:02PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 04:57:07PM +0100, Ondřej Jirman wrote:

Maybe it has something to do with my upgrade method. I
dumped/restored the replica with pg_dumpall, and then just proceded
to enable subscription and refresh publication with (copy_data=false)
for all my subscriptions.

OTOH, it may not. There are 2 more databases replicated the same way
from the same database cluster, and they don't crash the replica
server, and continue replicating. The one of the other databases also
has bytea columns in some of the tables.

It really just seems related to the machine restart (a regular one)
that I did on the primary, minutes later replica crashed, and kept
crashing ever since whenever connecting to the primary for the hometv
database.

Hmmm. A restart of the primary certainly should not cause any such
damage, that'd be a bug too. And it'd be a bit strange that it correctly
sends the data and it crashes the replica. How exactly did you restart
the primary? What mode - smart/fast/immediate?

So maybe something's wrong with the replica database (maybe because the
connection got killed by the walsender at unfortunate time), rather
than the original database, because I can replicate the original DB
afresh into a new copy just fine and other databases continue
replicating just fine if I disable the crashing subscription.

Possibly, but what would be the damaged bit? The only thing I can think
of is the replication slot info (i.e. snapshot), and I know there were
some timing issues in the serialization.

How far is the change from the restart point of the slot (visible in
pg_replication_slots)? If there are many changes since then, that'd mean
the corrupted snapshot is unlikely.

There's a lot of moving parts in this - you're replicating between major
versions, and from ARM to x86. All of that should work, of course, but
maybe there's a bug somewhere. So it might take time to investigate and
fix. Thanks for you patience ;-)

regards

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

On Thu, Nov 21, 2019 at 05:35:06PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 05:09:06PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 04:57:07PM +0100, Ondřej Jirman wrote:

On Thu, Nov 21, 2019 at 04:27:32PM +0100, Tomas Vondra wrote:

On Thu, Nov 21, 2019 at 04:07:16PM +0100, Ondřej Jirman wrote:

I've also managed to get valgrind output on the segfaulting process:

https://megous.com/dl/tmp/valgrind-105524-109020.log

Though it probably doesn't show much new.

Is postgres actually compiled with valgrind support? What does pg_config
say?

I don't see any valgrind related options in configure --help, I repackaged it
just with CFLAGS set to -ggdb -Og.

You need to use -DUSE_VALGRIND or edit pg_config_manual.h. I usually
just use

CFLAGS="-DRANDOMIZE_ALLOCATED_MEMORY -DUSE_VALGRIND -O0 -ggdb"

which does the trick. Without the USE_VALGRIND defined, we don't include
the valgrind instrumentation, so I suppose the previous results are bogus.

Two new valgrind logs, now with -DUSE_VALGRIND:

https://megous.com/dl/tmp/valgrind-172090.log
https://megous.com/dl/tmp/valgrind-172143.log

Unfortunately, I only get HTTP 403 :-(

A lots of uninitialized 1b accesses around VARATT_IS_EXTERNAL_EXPANDED.

So slot->tts_values[natt] is probably uninitialized.

Which is why the backtrace had a weird value there, I guess.

Possibly. Something is clearly wrong.

regards

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