Re: BUG #14758: Segfault with logical replication on a function index

Thank you Masahiko! I've tested and confirmed that this patch fixes the
problem.

On Fri, Jul 28, 2017 at 3:07 AM, Masahiko Sawada <sawada(dot)mshk(at)gmail(dot)com>
wrote:

> On Mon, Jul 24, 2017 at 4:22 PM, <scott(at)deltaex(dot)com> wrote:
> > The following bug has been logged on the website:
> >
> > Bug reference: 14758
> > Logged by: Scott Milliken
> > Email address: scott(at)deltaex(dot)com
> > PostgreSQL version: 10beta2
> > Operating system: Linux 4.10.0-27-generic #30~16.04.2-Ubuntu S
> > Description:
> >
> > I'm testing logical replication on 10beta2, and found a segfault that I
> can
> > reliably reproduce with an index on a not-actually immutable function.
> >
> > Here's the function in question:
> >
> > ```
> > CREATE OR REPLACE FUNCTION public.immutable_random(integer)
> > RETURNS double precision
> > LANGUAGE sql
> > IMMUTABLE
> > AS $function$SELECT random();
> > $function$;
> > ```
> >
> > It's not actually immutable since it's calling random (a hack to get an
> > efficient random sort on a table).
> >
> > (Aside: I'd understand if it errored on creation of the index, but would
> > really prefer to keep using this instead of tablesample because it's
> fast,
> > deterministic, and doesn't have sampling biases like the SYSTEM
> sampling.)
> >
> >
> > Here's full reproduction instructions:
> >
> >
> > Primary:
> > ```
> > mkdir -p /tmp/test-seg0
> > PGPORT=5301 initdb -D /tmp/test-seg0
> > echo "wal_level = logical" >> /tmp/test-seg0/postgresql.conf
> > PGPORT=5301 pg_ctl -D /tmp/test-seg0 start
> > for (( ; ; )); do if pg_isready -d postgres -p 5301; then break; fi;
> sleep
> > 1; done
> > psql -p 5301 postgres -c "CREATE USER test WITH PASSWORD 'test' SUPERUSER
> > CREATEDB CREATEROLE LOGIN REPLICATION BYPASSRLS;"
> > createdb -p 5301 -E utf8 test
> >
> > psql -p 5301 -U test test -c "CREATE TABLE testtbl (id int, name text);"
> > psql -p 5301 -U test test -c "ALTER TABLE testtbl ADD CONSTRAINT
> > testtbl_pkey PRIMARY KEY (id);"
> > psql -p 5301 -U test test -c "CREATE PUBLICATION testpub FOR TABLE
> > testtbl;"
> > psql -p 5301 -U test test -c "INSERT INTO testtbl (id, name) VALUES (1,
> > 'a');"
> > ```
> >
> > Secondary:
> > ```
> > mkdir -p /tmp/test-seg1
> > PGPORT=5302 initdb -D /tmp/test-seg1
> > PGPORT=5302 pg_ctl -D /tmp/test-seg1 start
> > for (( ; ; )); do if pg_isready -d postgres -p 5302; then break; fi;
> sleep
> > 1; done
> > psql -p 5302 postgres -c "CREATE USER test WITH PASSWORD 'test' SUPERUSER
> > CREATEDB CREATEROLE LOGIN REPLICATION BYPASSRLS;"
> > createdb -p 5302 -E utf8 test
> >
> > psql -p 5302 -U test test -c "CREATE TABLE testtbl (id int, name text);"
> > psql -p 5302 -U test test -c "ALTER TABLE testtbl ADD CONSTRAINT
> > testtbl_pkey PRIMARY KEY (id);"
> > psql -p 5302 -U test test -c 'CREATE FUNCTION
> > public.immutable_random(integer) RETURNS double precision LANGUAGE sql
> > IMMUTABLE AS $function$ SELECT random(); $function$'
> > psql -p 5302 -U test test -c "CREATE INDEX ix_testtbl_random ON testtbl
> > USING btree (immutable_random(id));"
> > psql -p 5302 -U test test -c "CREATE SUBSCRIPTION test0_testpub
> CONNECTION
> > 'port=5301 user=test dbname=test' PUBLICATION testpub;"
> > ```
> >
> > The secondary crashes with a segfault:
> >
> > ```
> > 2017-07-23 23:55:37.961 PDT [4823] LOG: logical replication table
> > synchronization worker for subscription "test0_testpub", table "testtbl"
> > has started
> > 2017-07-23 23:55:38.244 PDT [4758] LOG: worker process: logical
> replication
> > worker for subscription 16396 sync 16386 (PID 4823) was terminated by
> signal
> > 11: Segmentation fault
> > 2017-07-23 23:55:38.244 PDT [4758] LOG: terminating any other active
> server
> > processes
> > 2017-07-23 23:55:38.245 PDT [4763] WARNING: terminating connection
> because
> > of crash of another server process
> > 2017-07-23 23:55:38.245 PDT [4763] DETAIL: The postmaster has commanded
> > this server process to roll back the current transaction and exit,
> because
> > another server process exited
> > abnormally and possibly corrupted shared memory.
> > 2017-07-23 23:55:38.245 PDT [4763] HINT: In a moment you should be able
> to
> > reconnect to the database and repeat your command.
> > 2017-07-23 23:55:38.247 PDT [4758] LOG: all server processes terminated;
> > reinitializing
> > 2017-07-23 23:55:38.256 PDT [4826] LOG: database system was interrupted;
> > last known up at 2017-07-23 23:55:36 PDT
> > 2017-07-23 23:55:38.809 PDT [4826] LOG: database system was not properly
> > shut down; automatic recovery in progress
> > 2017-07-23 23:55:38.812 PDT [4826] LOG: redo starts at 0/173AEA0
> > 2017-07-23 23:55:38.815 PDT [4826] LOG: invalid record length at
> 0/17B50B0:
> > wanted 24, got 0
> > 2017-07-23 23:55:38.815 PDT [4826] LOG: redo done at 0/17B5070
> > 2017-07-23 23:55:38.815 PDT [4826] LOG: last completed transaction was
> at
> > log time 2017-07-23 23:55:37.962957-07
> > ```
> >
>
> Thank you for the reporting and precise reproducing steps!
> I could reproduced this issue and it seems to me that the cause of
> this is that the table sync worker didn't get a snapshot before
> starting table copy. Attached patch fixes this problem.
>
> Regards,
>
> --
> Masahiko Sawada
> NIPPON TELEGRAPH AND TELEPHONE CORPORATION
> NTT Open Source Software Center
>