Re: [HACKERS] Logical Replication WIP - FailedAssertion, File:"array_typanalyze.c", Line: 340

On 2017-01-19 01:02, Petr Jelinek wrote:

This causes the replica to crash:

#--------------
#!/bin/bash

# 2 instances on 6972 (master) and 6973 (replica)
# initially without publication or subscription

# clean logs
#echo > 
/var/data1/pg_stuff/pg_installations/pgsql.logical_replication/logfile.logical_replication
#echo > 
/var/data1/pg_stuff/pg_installations/pgsql.logical_replication2/logfile.logical_replication2

SLEEP=1
bail=0
pub_count=$( echo "select count(*) from pg_publication" | psql -qtAXp 
6972 )
if  [[ $pub_count -ne 0 ]]
then  echo "pub_count -ne 0 - deleting pub1 & bailing out"  echo "drop publication if exists pub1" | psql -Xp 6972
bail=1
fi
sub_count=$( echo "select count(*) from pg_subscription" | psql -qtAXp 
6973 )
if [[ $sub_count -ne 0 ]] then  echo "sub_count -ne 0 - deleting sub1 & bailing out"  echo "drop subscription if exists
sub1"| psql -Xp 6973  bail=1
 
fi

if [[ $bail -eq 1 ]]
then   exit -1
fi

echo "drop table if exists testt;" | psql -qXap 6972
echo "drop table if exists testt;" | psql -qXap 6973

echo "-- on master  (port 6972):
create table testt(id serial primary key, n integer, c text);
create publication pub1 for all tables; " | psql -qXap 6972

echo "-- on replica (port 6973):
create table testt(id serial primary key, n integer, c text);
create subscription sub1 connection 'port=6972' publication pub1 with 
(disabled);
alter  subscription sub1 enable; "        | psql -qXap 6973

sleep $SLEEP

echo "table testt /*limit 3*/; select current_setting('port'), count(*) 
from testt;" | psql -qXp 6972
echo "table testt /*limit 3*/; select current_setting('port'), count(*) 
from testt;" | psql -qXp 6973

echo "-- now crash:
analyze pg_subscription" | psql -qXp 6973
#--------------



-- log of the replica:

2017-01-19 17:54:09.163 CET 224200 LOG:  starting logical replication 
worker for subscription "sub1"
2017-01-19 17:54:09.166 CET 21166 LOG:  logical replication apply for 
subscription sub1 started
2017-01-19 17:54:09.169 CET 21166 LOG:  starting logical replication 
worker for subscription "sub1"
2017-01-19 17:54:09.172 CET 21171 LOG:  logical replication sync for 
subscription sub1, table testt started
2017-01-19 17:54:09.190 CET 21171 LOG:  logical replication 
synchronization worker finished processing
TRAP: FailedAssertion("!(((array)->elemtype) == extra_data->type_id)", 
File: "array_typanalyze.c", Line: 340)
2017-01-19 17:54:20.110 CET 224190 LOG:  server process (PID 21183) was 
terminated by signal 6: Aborted
2017-01-19 17:54:20.110 CET 224190 DETAIL:  Failed process was running: 
autovacuum: ANALYZE pg_catalog.pg_subscription
2017-01-19 17:54:20.110 CET 224190 LOG:  terminating any other active 
server processes
2017-01-19 17:54:20.110 CET 224198 WARNING:  terminating connection 
because of crash of another server process
2017-01-19 17:54:20.110 CET 224198 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-01-19 17:54:20.110 CET 224198 HINT:  In a moment you should be able 
to reconnect to the database and repeat your command.
2017-01-19 17:54:20.111 CET 224190 LOG:  all server processes 
terminated; reinitializing
2017-01-19 17:54:20.143 CET 21184 LOG:  database system was interrupted; 
last known up at 2017-01-19 17:38:48 CET
2017-01-19 17:54:20.179 CET 21184 LOG:  recovered replication state of 
node 1 to 0/2CEBF08
2017-01-19 17:54:20.179 CET 21184 LOG:  database system was not properly 
shut down; automatic recovery in progress
2017-01-19 17:54:20.181 CET 21184 LOG:  redo starts at 0/2513E88
2017-01-19 17:54:20.184 CET 21184 LOG:  invalid record length at 
0/2546980: wanted 24, got 0
2017-01-19 17:54:20.184 CET 21184 LOG:  redo done at 0/2546918
2017-01-19 17:54:20.184 CET 21184 LOG:  last completed transaction was 
at log time 2017-01-19 17:54:09.191697+01
2017-01-19 17:54:20.191 CET 21184 LOG:  MultiXact member wraparound 
protections are now enabled
2017-01-19 17:54:20.193 CET 224190 LOG:  database system is ready to 
accept connections
2017-01-19 17:54:20.193 CET 21188 LOG:  autovacuum launcher started
2017-01-19 17:54:20.194 CET 21190 LOG:  logical replication launcher 
started
2017-01-19 17:54:20.194 CET 21190 LOG:  starting logical replication 
worker for subscription "sub1"
2017-01-19 17:54:20.202 CET 21191 LOG:  logical replication apply for 
subscription sub1 started



Could probably be whittled down to something shorter but I hope it's 
still easily reproduced.


thanks,

Erik Rijkers





setup of the 2 instances:


#---------------- ./instances.sh
#!/bin/bash
port1=6972
port2=6973
project1=logical_replication
project2=logical_replication2
# pg_stuff_dir=$HOME/pg_stuff  pg_stuff_dir=/var/data1/pg_stuff
PATH1=$pg_stuff_dir/pg_installations/pgsql.$project1/bin:$PATH
PATH2=$pg_stuff_dir/pg_installations/pgsql.$project2/bin:$PATH
server_dir1=$pg_stuff_dir/pg_installations/pgsql.$project1
server_dir2=$pg_stuff_dir/pg_installations/pgsql.$project2
data_dir1=$server_dir1/data
data_dir2=$server_dir2/data
options1="
-c wal_level=logical
-c max_replication_slots=10
-c max_worker_processes=12
-c max_logical_replication_workers=10
-c max_wal_senders=10
-c logging_collector=on
-c log_directory=$server_dir1
-c log_filename=logfile.${project1} "

options2="
-c wal_level=replica
-c max_replication_slots=10
-c max_worker_processes=12
-c max_logical_replication_workers=10
-c max_wal_senders=10
-c logging_collector=on
-c log_directory=$server_dir2
-c log_filename=logfile.${project2} "
which postgres
export PATH=$PATH1; postgres -D $data_dir1 -p $port1 ${options1} &
export PATH=$PATH2; postgres -D $data_dir2 -p $port2 ${options2} &
#---------------- ./instances.sh end