# Checking port 53314 # Found port 53314 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=53314 host=/tmp/7MNvflRhQD Log file: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_primary.log # Checking port 53315 # Found port 53315 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=53315 host=/tmp/7MNvflRhQD Log file: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_standby.log # Checking port 53316 # Found port 53316 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=53316 host=/tmp/7MNvflRhQD Log file: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_cascading_standby.log # Checking port 53317 # Found port 53317 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=53317 host=/tmp/7MNvflRhQD Log file: /tmp/cirrus-ci-build/build/testrun/recovery/035_standby_logical_decoding/log/035_standby_logical_decoding_subscriber.log [13:38:54.243](0.022s) # 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=53314 host=/tmp/7MNvflRhQD 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 32139 [13:38:54.737](0.494s) 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/7MNvflRhQD -p 53314 --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 32263 Waiting for replication conn standby's replay_lsn to pass 0/3019E10 on primary done [13:38:55.627](0.890s) # 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 32372 [13:38:56.333](0.706s) ok 2 - behaves_ok_inactiveslot on standby created [13:38:56.516](0.183s) ok 3 - behaves_ok_activeslot on standby created Waiting for replication conn standby's replay_lsn to pass 0/3026718 on primary done [13:38:56.752](0.236s) ok 4 - Decoding produced 14 rows (2 BEGIN/COMMIT and 10 rows) Waiting for replication conn standby's replay_lsn to pass 0/3026848 on primary done [13:38:56.912](0.160s) ok 5 - got expected output from SQL decoding session Waiting for replication conn standby's replay_lsn to pass 0/30273F8 on primary done [13:38:57.098](0.186s) ok 6 - got same expected output from pg_recvlogical decoding session [13:38:57.141](0.043s) ok 7 - pg_recvlogical acknowledged changes Waiting for replication conn standby's replay_lsn to pass 0/3471130 on primary done [13:38:57.392](0.250s) ok 8 - replaying logical slot from another database fails Waiting for replication conn standby's replay_lsn to pass 0/3498968 on primary done Waiting for all subscriptions in "subscriber" to synchronize data Waiting for replication conn tap_sub's replay_lsn to pass 0/34989A0 on standby done done Waiting for replication conn standby's replay_lsn to pass 0/3498F30 on primary done Waiting for replication conn tap_sub's replay_lsn to pass 0/3498F30 on standby done [13:38:58.359](0.968s) 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:38:59.186](0.827s) ok 10 - vacuum_full_inactiveslot on standby created [13:38:59.588](0.402s) 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/34C98D8 on primary done [13:39:00.076](0.488s) ok 12 - inactiveslot slot invalidation is logged with vacuum FULL on pg_class [13:39:00.076](0.000s) ok 13 - activeslot slot invalidation is logged with vacuum FULL on pg_class [13:39:00.117](0.041s) ok 14 - confl_active_logicalslot updated [13:39:00.155](0.038s) ok 15 - vacuum_full_activeslot conflict_reason is rows_removed [13:39:00.181](0.026s) ok 16 - vacuum_full_inactiveslot conflict_reason is rows_removed [13:39:00.216](0.034s) ok 17 - replication slot stats not removed after invalidation [13:39:00.241](0.025s) ok 18 - pg_recvlogical exited non-zero [13:39:00.241](0.000s) 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 33036 [13:39:00.522](0.281s) ok 20 - vacuum_full_activeslot conflict_reason is rows_removed [13:39:00.551](0.029s) 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:39:01.114](0.563s) ok 22 - invalidated logical slots do not lead to retaining WAL [13:39:01.561](0.447s) ok 23 - row_removal_inactiveslot on standby created [13:39:02.017](0.456s) 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: 63.664 MB/s, avg write rate: 136.423 MB/s buffer usage: 79 hits, 7 misses, 15 dirtied WAL usage: 28 records, 15 full page images, 122838 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/403EDB8 on primary [13:42:39.357](217.340s) # poll_query_until timed out executing this query: # SELECT '0/403EDB8' <= 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 32139 ### 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:42:39.463](0.106s) # Tests were run but no plan was declared and done_testing() was not seen. [13:42:39.463](0.000s) # Looks like your test exited with 29 just after 24.