# Checking port 64328 # Found port 64328 Name: primary Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/pgdata Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/backup Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/archives Connection string: port=64328 host=/tmp/qHgZ6Ej_7r Log file: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_primary.log # Checking port 64329 # Found port 64329 Name: standby Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_standby_data/pgdata Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_standby_data/backup Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_standby_data/archives Connection string: port=64329 host=/tmp/qHgZ6Ej_7r Log file: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_standby.log # Checking port 64330 # Found port 64330 Name: cascading_standby Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_cascading_standby_data/pgdata Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_cascading_standby_data/backup Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_cascading_standby_data/archives Connection string: port=64330 host=/tmp/qHgZ6Ej_7r Log file: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_cascading_standby.log # Checking port 64331 # Found port 64331 Name: subscriber Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_subscriber_data/pgdata Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_subscriber_data/backup Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_subscriber_data/archives Connection string: port=64331 host=/tmp/qHgZ6Ej_7r Log file: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_subscriber.log [13:36:56.486](0.039s) # initializing database system by copying initdb template # Running: cp -RPp /tmp/cirrus-ci-build/build/tmp_install/initdb-template /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/pgdata # Running: /tmp/cirrus-ci-build/build/src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/pgdata ### Enabling WAL archiving for node "primary" Name: primary Version: 17devel Data directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/pgdata Backup directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/backup Archive directory: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/archives Connection string: port=64328 host=/tmp/qHgZ6Ej_7r Log file: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_primary.log ### Starting node "primary" # Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_primary.log -o --cluster-name=primary start waiting for server to start.... done server started # Postmaster PID for node "primary" is 14620 psql::1: WARNING: databases created by regression test cases should have names including "regression" [13:36:56.746](0.260s) ok 1 - Physical slot reports conflict_reason as NULL # Taking pg_basebackup b1 from node "primary" # Running: pg_basebackup -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/backup/b1 -h /tmp/qHgZ6Ej_7r -p 64328 --checkpoint fast --no-sync # Backup finished # Initializing node "standby" from backup "b1" of node "primary" ### Enabling streaming replication for node "standby" ### Enabling WAL restore for node "standby" ### Starting node "standby" # Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_standby_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_standby.log -o --cluster-name=standby start waiting for server to start.... done server started # Postmaster PID for node "standby" is 14686 Waiting for replication conn standby's replay_lsn to pass 0/3019580 on primary done [13:36:57.202](0.457s) # initializing database system by copying initdb template # Running: cp -RPp /tmp/cirrus-ci-build/build/tmp_install/initdb-template /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_subscriber_data/pgdata # Running: /tmp/cirrus-ci-build/build/src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_subscriber_data/pgdata ### Starting node "subscriber" # Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_subscriber_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_subscriber.log -o --cluster-name=subscriber start waiting for server to start.... done server started # Postmaster PID for node "subscriber" is 14768 [13:36:57.874](0.671s) ok 2 - behaves_ok_inactiveslot on standby created [13:36:58.079](0.206s) ok 3 - behaves_ok_activeslot on standby created Waiting for replication conn standby's replay_lsn to pass 0/3026710 on primary done [13:36:58.167](0.088s) ok 4 - Decoding produced 14 rows (2 BEGIN/COMMIT and 10 rows) Waiting for replication conn standby's replay_lsn to pass 0/3026840 on primary done [13:36:58.231](0.064s) ok 5 - got expected output from SQL decoding session Waiting for replication conn standby's replay_lsn to pass 0/30273F0 on primary done [13:36:58.311](0.081s) ok 6 - got same expected output from pg_recvlogical decoding session [13:36:58.340](0.029s) ok 7 - pg_recvlogical acknowledged changes #### Begin standard error psql::1: WARNING: databases created by regression test cases should have names including "regression" #### End standard error Waiting for replication conn standby's replay_lsn to pass 0/3469230 on primary done [13:36:58.468](0.128s) ok 8 - replaying logical slot from another database fails Waiting for replication conn standby's replay_lsn to pass 0/3490A60 on primary done Waiting for all subscriptions in "subscriber" to synchronize data Waiting for replication conn tap_sub's replay_lsn to pass 0/3490A98 on standby done done Waiting for replication conn standby's replay_lsn to pass 0/3491028 on primary done Waiting for replication conn tap_sub's replay_lsn to pass 0/3491028 on standby done [13:36:59.254](0.786s) ok 9 - check replicated inserts after subscription on standby #### Begin standard error psql::1: NOTICE: dropped replication slot "tap_sub" on publisher #### End standard error ### Stopping node "subscriber" using mode fast # Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_subscriber_data/pgdata -m fast stop waiting for server to shut down.... done server stopped # No postmaster PID for node "subscriber" [13:37:00.020](0.766s) ok 10 - vacuum_full_inactiveslot on standby created [13:37:00.455](0.435s) ok 11 - vacuum_full_activeslot on standby created ### Reloading node "standby" # Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_standby_data/pgdata reload server signaled #### Begin standard error psql::1: INFO: vacuuming "pg_catalog.pg_class" psql::1: INFO: "pg_catalog.pg_class": found 5 removable, 420 nonremovable row versions in 14 pages DETAIL: 0 dead row versions cannot be removed yet. CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s. #### End standard error Waiting for replication conn standby's replay_lsn to pass 0/34C1A10 on primary done [13:37:00.965](0.510s) ok 12 - inactiveslot slot invalidation is logged with vacuum FULL on pg_class [13:37:00.966](0.001s) ok 13 - activeslot slot invalidation is logged with vacuum FULL on pg_class [13:37:00.994](0.028s) ok 14 - confl_active_logicalslot updated [13:37:01.017](0.022s) ok 15 - vacuum_full_activeslot conflict_reason is rows_removed [13:37:01.036](0.019s) ok 16 - vacuum_full_inactiveslot conflict_reason is rows_removed [13:37:01.062](0.026s) ok 17 - replication slot stats not removed after invalidation [13:37:01.075](0.013s) ok 18 - pg_recvlogical exited non-zero [13:37:01.076](0.002s) ok 19 - slot has been invalidated ### Reloading node "standby" # Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_standby_data/pgdata reload server signaled ### Restarting node "standby" # Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_standby_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_standby.log restart waiting for server to shut down.... done server stopped waiting for server to start.... done server started # Postmaster PID for node "standby" is 15279 [13:37:01.469](0.392s) ok 20 - vacuum_full_activeslot conflict_reason is rows_removed [13:37:01.518](0.049s) ok 21 - vacuum_full_inactiveslot conflict_reason is rows_removed Waiting for replication conn standby's replay_lsn to pass 0/40000F8 on primary done [13:37:01.923](0.405s) ok 22 - invalidated logical slots do not lead to retaining WAL [13:37:02.649](0.727s) ok 23 - row_removal_inactiveslot on standby created [13:37:03.118](0.469s) ok 24 - row_removal_activeslot on standby created ### Reloading node "standby" # Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_standby_data/pgdata reload server signaled #### Begin standard error psql::1: INFO: vacuuming "testdb.pg_catalog.pg_class" psql::1: INFO: finished vacuuming "testdb.pg_catalog.pg_class": index scans: 1 pages: 0 removed, 11 remain, 11 scanned (100.00% of total) tuples: 4 removed, 419 remain, 0 are dead but not yet removable removable cutoff: 755, which was 0 XIDs old when operation ended frozen: 0 pages from table (0.00% of total) had 0 tuples frozen index scan needed: 3 pages from table (27.27% of total) had 5 dead item identifiers removed index "pg_class_oid_index": pages: 4 in total, 0 newly deleted, 0 currently deleted, 0 reusable index "pg_class_relname_nsp_index": pages: 5 in total, 0 newly deleted, 0 currently deleted, 0 reusable index "pg_class_tblspc_relfilenode_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable avg read rate: 130.450 MB/s, avg write rate: 246.405 MB/s buffer usage: 125 hits, 9 misses, 17 dirtied WAL usage: 27 records, 15 full page images, 122783 bytes system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s #### End standard error Waiting for replication conn standby's replay_lsn to pass 0/4040930 on primary [13:40:40.168](217.049s) # poll_query_until timed out executing this query: # SELECT '0/4040930' <= replay_lsn AND state = 'streaming' # FROM pg_catalog.pg_stat_replication # WHERE application_name IN ('standby', 'walreceiver') # expecting this output: # t # last actual query output: # # with stderr: timed out waiting for catchup at /tmp/cirrus-ci-build/src/test/recovery/t/035_standby_logical_decoding.pl line 609. # Postmaster PID for node "primary" is 14620 ### Stopping node "primary" using mode immediate # Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/data/t_035_standby_logical_decoding_primary_data/pgdata -m immediate stop waiting for server to shut down.... done server stopped # No postmaster PID for node "primary" # No postmaster PID for node "standby" # No postmaster PID for node "cascading_standby" # No postmaster PID for node "subscriber" [13:40:40.279](0.111s) # Tests were run but no plan was declared and done_testing() was not seen. [13:40:40.279](0.000s) # Looks like your test exited with 29 just after 24.