BUG #17802: PGLogical getting Terminated

The following bug has been logged on the website:

Bug reference: 17802
Logged by: Yogesh Pingle
Email address: yp311092(at)gmail(dot)com
PostgreSQL version: 14.1
Operating system: RDS Linux
Description:

Hello Team,

Hope you are doing well !!

I am trying to configure the PGLogical to migrate the data from the
Non-Partition table to the Partition table in RDS DB Version 14.1. Initial
copy is working successfully however whenever I am adding a new row on the
Source then on Target Side the instance is getting terminated with the below
error .

The table Setup is as follows :

Source :
CREATE TABLE partition (
city_id int not null primary key ,
logdate date not null
);
insert into partition values(1,'2023-01-12');
insert into partition values(2,'2023-01-13');

We can INSERT this row once the replication has been started: insert into
partition values(4,'2023-02-11');

Target :

CREATE TABLE partition (
city_id int not null ,
logdate date not null,
PRIMARY KEY (city_id,logdate)
)PARTITION BY RANGE (logdate);

Followed the below Steps :

Source :

CREATE EXTENSION pglogical;
select pglogical.create_node(node_name := 'source_test',dsn := ' port=5432
sslmode=require dbname=partition user= password=);
select
pglogical.replication_set_add_table('default','public.partition',true,
row_filter := ' logdate>=''2023-01-13'' ');

Target :

CREATE EXTENSION pglogical;
select pglogical.create_node('target_test', 'host= port=5432
dbname=partition user= password=);
select pglogical.create_subscription(subscription_name :=
'test_sub',provider_dsn := 'host= port=5432 sslmode=require dbname=partition
user= password=, synchronize_structure := false, synchronize_data :=
true);

Error Source :

'20401', pglogical_apply_pid '907')
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:DEBUG: sending
replication keepalive
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:STATEMENT:
START_REPLICATION SLOT "pgl_postgres_source_test_test_sub" LOGICAL
0/D0004A28 (expected_encoding 'UTF8', min_proto_version '1',
max_proto_version '1', startup_params_format '1',
"binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1',
"binary.basetypes_major_version" '1400', "binary.sizeof_datum" '8',
"binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '0',
"binary.float4_byval" '0', "binary.float8_byval" '1',
"binary.integer_datetimes" '0', "hooks.setup_function"
'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '"all"',
"pglogical.replication_set_names" '"default",default_insert_only,ddl_sql',
"relmeta_cache_size" '-1', pg_version '140006', pglogical_version '2.4.1',
pglogical_version_num '20401', pglogical_apply_pid '907')
2023-02-03 16:16:04 UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:LOG:
could not receive data from client: Connection reset by peer
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:STATEMENT:
START_REPLICATION SLOT "pgl_postgres_source_test_test_sub" LOGICAL
0/D0004A28 (expected_encoding 'UTF8', min_proto_version '1',
max_proto_version '1', startup_params_format '1',
"binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1',
"binary.basetypes_major_version" '1400', "binary.sizeof_datum" '8',
"binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '0',
"binary.float4_byval" '0', "binary.float8_byval" '1',
"binary.integer_datetimes" '0', "hooks.setup_function"
'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '"all"',
"pglogical.replication_set_names" '"default",default_insert_only,ddl_sql',
"relmeta_cache_size" '-1', pg_version '140006', pglogical_version '2.4.1',
pglogical_version_num '20401', pglogical_apply_pid '907')
2023-02-03 16:16:04 UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:LOG:
unexpected EOF on standby connection
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:STATEMENT:
START_REPLICATION SLOT "pgl_postgres_source_test_test_sub" LOGICAL
0/D0004A28 (expected_encoding 'UTF8', min_proto_version '1',
max_proto_version '1', startup_params_format '1',
"binary.want_internal_basetypes" '1', "binary.want_binary_basetypes" '1',
"binary.basetypes_major_version" '1400', "binary.sizeof_datum" '8',
"binary.sizeof_int" '4', "binary.sizeof_long" '8', "binary.bigendian" '0',
"binary.float4_byval" '0', "binary.float8_byval" '1',
"binary.integer_datetimes" '0', "hooks.setup_function"
'pglogical.pglogical_hooks_setup', "pglogical.forward_origins" '"all"',
"pglogical.replication_set_names" '"default",default_insert_only,ddl_sql',
"relmeta_cache_size" '-1', pg_version '140006', pglogical_version '2.4.1',
pglogical_version_num '20401', pglogical_apply_pid '907')
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:DEBUG: shmem_exit(0): 1
before_shmem_exit callbacks to make
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:DEBUG: shmem_exit(0): 8
on_shmem_exit callbacks to make
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:DEBUG: proc_exit(0): 3
callbacks to make
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:DEBUG: exit(0)
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:DEBUG: shmem_exit(-1): 0
before_shmem_exit callbacks to make
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:DEBUG: shmem_exit(-1): 0
on_shmem_exit callbacks to make
2023-02-03 16:16:04
UTC:10.103.90.251(13324):repli_user(at)postgres:[935]:DEBUG: proc_exit(-1): 0
callbacks to make
2023-02-03 16:16:04 UTC::@:[368]:DEBUG: reaping dead processes
2023-02-03 16:16:04 UTC::@:[368]:DEBUG: server process (PID 935) exited
with exit code 0
2023-02-03 16:16:04 UTC::@:[368]:DEBUG: forked new backend, pid=1063
socket=10
2023-02-03 16:16:04
UTC:10.103.90.251(24362):[unknown](at)[unknown]:[1063]:DEBUG: SSL: handshake
start: "before/accept initialization"
2023-02-03 16:16:04
UTC:10.103.90.251(24362):[unknown](at)[unknown]:[1063]:DEBUG: SSL: accept
loop: "before/accept initialization"
2023-02-03 16:16:04
UTC:10.103.90.251(24362):[unknown](at)[unknown]:[1063]:DEBUG: SSL: accept exit
(-1): "SSLv2/v3 read client hello A"
2023-02-03 16:16:04
UTC:10.103.90.251(24362):[unknown](at)[unknown]:[1063]:DEBUG: SSL: accept
loop: "SSLv3 read client hello A"
2023-02-03 16:16:04
UTC:10.103.90.251(24362):[unknown](at)[unknown]:[1063]:DEBUG: SSL: accept
loop: "SSLv3 write server hello A"
2023-02-03 16:16:04
UTC:10.103.90.251(24362):[unknown](at)[unknown]:[1063]:DEBUG: SSL: accept
loop: "SSLv3 write certificate A"
2023-02-03 16:16:04
UTC:10.103.90.251(24362):[unknown](at)[unknown]:[1063]:DEBUG: SSL: accept
loop: "SSLv3 write key exchange A"
2023-02-03 16:16:04
UTC:10.103.90.251(24362):[unknown](at)[unknown]:[1063]:DEBUG: SSL: accept
loop: "SSLv3 write certificate request A"

Error Target :

2023-02-03 16:16:06 UTC::@:[368]:DEBUG: starting background worker process
"pglogical supervisor"
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: starting background worker process
"logical replication launcher"
2023-02-03 16:16:06 UTC::@:[368]:LOG: database system is ready to accept
connections
2023-02-03 16:16:06 UTC::@:[1277]:DEBUG: logical replication launcher
started
2023-02-03 16:16:06 UTC::@:[1277]:DEBUG: InitPostgres
2023-02-03 16:16:06 UTC::@:[1277]:DEBUG: my backend ID is 1
2023-02-03 16:16:06 UTC::@:[1277]:DEBUG: StartTransaction(1) name: unnamed;
blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[1277]:DEBUG: CommitTransaction(1) name:
unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[1277]:DEBUG: StartTransaction(1) name: unnamed;
blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[1277]:DEBUG: CommitTransaction(1) name:
unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[1277]:DEBUG: StartTransaction(1) name: unnamed;
blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[1277]:DEBUG: CommitTransaction(1) name:
unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: find_in_dynamic_libpath: trying
"/rdsdbbin/postgres-14.6.R1/lib/pglogical"
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: find_in_dynamic_libpath: trying
"/rdsdbbin/postgres-14.6.R1/lib/pglogical.so"
2023-02-03 16:16:06 UTC::@:[1276]:LOG: starting pglogical supervisor
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: InitPostgres
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: my backend ID is 2
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: StartTransaction(1) name: unnamed;
blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: CommitTransaction(1) name:
unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: StartTransaction(1) name: unnamed;
blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: registering pglogical manager
process for database template1
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: registering background worker
"pglogical manager 1"
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: starting background worker process
"pglogical manager 1"
2023-02-03 16:16:06 UTC::@:[1272]:DEBUG: checkpointer updated shared memory
configuration values
2023-02-03 16:16:06 UTC::@:[1278]:DEBUG: find_in_dynamic_libpath: trying
"/rdsdbbin/postgres-14.6.R1/lib/pglogical"
2023-02-03 16:16:06 UTC::@:[1278]:DEBUG: find_in_dynamic_libpath: trying
"/rdsdbbin/postgres-14.6.R1/lib/pglogical.so"
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1278]:DEBUG: manager worker
[1278] attaching to slot 0 generation 1
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1278]:DEBUG: InitPostgres
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1278]:DEBUG: my backend ID is
3
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1278]:DEBUG:
StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS,
xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: reaping dead processes
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: unregistering background worker
"pglogical manager 1"
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: background worker "pglogical
manager 1" (PID 1278) exited with exit code 0
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: none worker at slot 0 exited
before we noticed it started
2023-02-03 16:16:06 UTC::@:[1276]:DEBUG: registering pglogical manager
process for database postgres
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: registering background worker
"pglogical manager 14717"
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: starting background worker process
"pglogical manager 14717"
2023-02-03 16:16:06 UTC::@:[1279]:DEBUG: find_in_dynamic_libpath: trying
"/rdsdbbin/postgres-14.6.R1/lib/pglogical"
2023-02-03 16:16:06 UTC::@:[1279]:DEBUG: find_in_dynamic_libpath: trying
"/rdsdbbin/postgres-14.6.R1/lib/pglogical.so"
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1279]:DEBUG: manager worker
[1279] attaching to slot 0 generation 2
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1279]:DEBUG: InitPostgres
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1279]:DEBUG: my backend ID is
3
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1279]:DEBUG:
StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS,
xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: registering background worker
"pglogical apply 14717:2769129391"
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: starting background worker process
"pglogical apply 14717:2769129391"
2023-02-03 16:16:06 UTC::@:[1280]:DEBUG: find_in_dynamic_libpath: trying
"/rdsdbbin/postgres-14.6.R1/lib/pglogical"
2023-02-03 16:16:06 UTC::@:[1280]:DEBUG: find_in_dynamic_libpath: trying
"/rdsdbbin/postgres-14.6.R1/lib/pglogical.so"
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1280]:DEBUG: apply worker
[1280] attaching to slot 1 generation 1
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1280]:DEBUG: InitPostgres
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1280]:DEBUG: my backend ID is
4
2023-02-03 16:16:06 UTC::[unknown](at)[unknown]:[1280]:DEBUG:
StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS,
xid/subid/cid: 0/1/0
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: reaping dead processes
2023-02-03 16:16:06 UTC::@:[368]:LOG: background worker "pglogical apply
14717:2769129391" (PID 1280) was terminated by signal 11: Segmentation
fault
2023-02-03 16:16:06 UTC::@:[368]:LOG: terminating any other active server
processes
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: sending SIGQUIT to process 1279
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: sending SIGQUIT to process 1276
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: sending SIGQUIT to process 1277
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: sending SIGQUIT to process 1273
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: sending SIGQUIT to process 1272
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: sending SIGQUIT to process 1274
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: sending SIGQUIT to process 1275
2023-02-03 16:16:06 UTC::@:[1275]:DEBUG: writing stats file
"pg_stat/global.stat"
2023-02-03 16:16:06 UTC::@:[1275]:DEBUG: writing stats file
"pg_stat/db_1.stat"
2023-02-03 16:16:06 UTC::@:[1275]:DEBUG: removing temporary stats file
"/rdsdbdata/db/pg_stat_tmp/db_1.stat"
2023-02-03 16:16:06 UTC::@:[1275]:DEBUG: writing stats file
"pg_stat/db_0.stat"
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: reaping dead processes
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: reaping dead processes
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: reaping dead processes
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: reaping dead processes
2023-02-03 16:16:06 UTC::@:[1275]:DEBUG: removing temporary stats file
"/rdsdbdata/db/pg_stat_tmp/db_0.stat"
2023-02-03 16:16:06 UTC::@:[1275]:DEBUG: shmem_exit(-1): 0
before_shmem_exit callbacks to make
2023-02-03 16:16:06 UTC::@:[1275]:DEBUG: shmem_exit(-1): 0 on_shmem_exit
callbacks to make
2023-02-03 16:16:06 UTC::@:[1275]:DEBUG: proc_exit(-1): 0 callbacks to
make
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: reaping dead processes
2023-02-03 16:16:06 UTC::@:[368]:LOG: all server processes terminated;
reinitializing
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: unregistering background worker
"pglogical apply 14717:2769129391"
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: unregistering background worker
"pglogical manager 14717"
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: shmem_exit(1): 0 before_shmem_exit
callbacks to make
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: shmem_exit(1): 6 on_shmem_exit
callbacks to make
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: cleaning up dynamic shared memory
control segment with ID 541695338
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: invoking
IpcMemoryCreate(size=2182676480)
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: dynamic shared memory system will
support 4494 segments
2023-02-03 16:16:06 UTC::@:[368]:DEBUG: created dynamic shared memory
control segment 2891381378 (179776 bytes)
2023-02-03 16:16:06 UTC::@:[1281]:LOG: database system was interrupted;
last known up at 2023-02-03 16:16:06 UTC
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: removing all temporary WAL
segments
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: checkpoint record is at
0/94004390
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: redo record is at 0/94004390;
shutdown true
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: next transaction ID: 1079; next
OID: 25496
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: next MultiXactId: 1; next
MultiXactOffset: 0
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: oldest unfrozen transaction ID:
727, in database 1
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: oldest MultiXactId: 1, in database
1
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: commit timestamp Xid
oldest/newest: 0/0
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: transaction ID wrap limit is
2147484374, limited by database with OID 1
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: MultiXactId wrap limit is
2147483648, limited by database with OID 1
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: starting up replication slots
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: starting up replication origin
progress state
2023-02-03 16:16:06 UTC::@:[1281]:LOG: recovered replication state of node
1 to 0/D0004A28
2023-02-03 16:16:06 UTC::@:[1281]:LOG: database system was not properly
shut down; automatic recovery in progress
2023-02-03 16:16:06 UTC::@:[1281]:DEBUG: resetting unlogged relations:
cleanup 1 init 0
2023-02-03 16:16:06 UTC::@:[1281]:LOG: invalid record length at 0/94004408:
wanted 24, got 0
2023-02-03 16:16:06 UTC::@:[1281]:LOG: redo is not required
2023-02-03 16:16:06 UTC::@