# Checking port 52732
# Found port 52732
Name: primary
Data directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata
Backup directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/backup
Archive directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/archives
Connection string: port=52732 host=/tmp/w50C45f3_6
Log file: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/log/035_standby_logical_decoding_primary.log
# Checking port 52733
# Found port 52733
Name: standby
Data directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata
Backup directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_standby_data/backup
Archive directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_standby_data/archives
Connection string: port=52733 host=/tmp/w50C45f3_6
Log file: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/log/035_standby_logical_decoding_standby.log
# Checking port 52734
# Found port 52734
Name: cascading_standby
Data directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_cascading_standby_data/pgdata
Backup directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_cascading_standby_data/backup
Archive directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_cascading_standby_data/archives
Connection string: port=52734 host=/tmp/w50C45f3_6
Log file: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/log/035_standby_logical_decoding_cascading_standby.log
# Checking port 52735
# Found port 52735
Name: subscriber
Data directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_subscriber_data/pgdata
Backup directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_subscriber_data/backup
Archive directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_subscriber_data/archives
Connection string: port=52735 host=/tmp/w50C45f3_6
Log file: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/log/035_standby_logical_decoding_subscriber.log
[10:57:19.313](0.418s) # initializing database system by copying initdb template
# Running: cp -RPp /home/vagrant/postgresql/tmp_install/initdb-template /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata
# Running: /home/vagrant/postgresql/src/test/recovery_1/../../../src/test/regress/pg_regress --config-auth /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata
### Enabling WAL archiving for node "primary"
Name: primary
Version: 17devel
Data directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata
Backup directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/backup
Archive directory: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/archives
Connection string: port=52732 host=/tmp/w50C45f3_6
Log file: /home/vagrant/postgresql/src/test/recovery_1/tmp_check/log/035_standby_logical_decoding_primary.log
### Starting node "primary"
# Running: pg_ctl -w -D /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata -l /home/vagrant/postgresql/src/test/recovery_1/tmp_check/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 76092
[10:58:18.461](59.149s) ok 1 - Physical slot reports conflict_reason as NULL
# Taking pg_basebackup b1 from node "primary"
# Running: pg_basebackup -D /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_primary_data/backup/b1 -h /tmp/w50C45f3_6 -p 52732 --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 /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata -l /home/vagrant/postgresql/src/test/recovery_1/tmp_check/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 77018
Waiting for replication conn standby's replay_lsn to pass 0/3019998 on primary
done
[11:00:46.882](148.421s) # initializing database system by copying initdb template
# Running: cp -RPp /home/vagrant/postgresql/tmp_install/initdb-template /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_subscriber_data/pgdata
# Running: /home/vagrant/postgresql/src/test/recovery_1/../../../src/test/regress/pg_regress --config-auth /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_subscriber_data/pgdata
### Starting node "subscriber"
# Running: pg_ctl -w -D /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_subscriber_data/pgdata -l /home/vagrant/postgresql/src/test/recovery_1/tmp_check/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 78629
[11:01:40.137](53.255s) ok 2 - behaves_ok_inactiveslot on standby created
[11:01:41.355](1.219s) ok 3 - behaves_ok_activeslot on standby created
Waiting for replication conn standby's replay_lsn to pass 0/3025970 on primary
done
[11:01:43.213](1.858s) ok 4 - Decoding produced 14 rows (2 BEGIN/COMMIT and 10 rows)
Waiting for replication conn standby's replay_lsn to pass 0/3025AA0 on primary
done
[11:01:44.659](1.446s) ok 5 - got expected output from SQL decoding session
Waiting for replication conn standby's replay_lsn to pass 0/3026668 on primary
done
[11:01:46.507](1.848s) ok 6 - got same expected output from pg_recvlogical decoding session
[11:01:47.269](0.762s) ok 7 - pg_recvlogical acknowledged changes
Waiting for replication conn standby's replay_lsn to pass 0/3458670 on primary
done
[11:02:14.861](27.592s) ok 8 - replaying logical slot from another database fails
Waiting for replication conn standby's replay_lsn to pass 0/347F860 on primary
done
Waiting for all subscriptions in "subscriber" to synchronize data
Waiting for replication conn tap_sub's replay_lsn to pass 0/347F8D0 on standby
done
done
Waiting for replication conn standby's replay_lsn to pass 0/347FE60 on primary
done
Waiting for replication conn tap_sub's replay_lsn to pass 0/347FE60 on standby
done
[11:03:05.167](50.306s) ok 9 - check replicated inserts after subscription on standby
#### Begin standard error
psql:<stdin>:1: NOTICE:  dropped replication slot "tap_sub" on publisher
#### End standard error
### Stopping node "subscriber" using mode fast
# Running: pg_ctl -D /home/vagrant/postgresql/src/test/recovery_1/tmp_check/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"


[11:03:45.463](40.296s) ok 10 - vacuum_full_inactiveslot on standby created
[11:03:51.485](6.022s) ok 11 - vacuum_full_activeslot on standby created
### Reloading node "standby"
# Running: pg_ctl -D /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata reload
server signaled

#### Begin standard error
psql:<stdin>:1: INFO:  vacuuming "pg_catalog.pg_class"
psql:<stdin>: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.21 s.
#### End standard error
Waiting for replication conn standby's replay_lsn to pass 0/34CC478 on primary
done
[11:04:19.709](28.223s) ok 12 - inactiveslot slot invalidation is logged with vacuum FULL on pg_class
[11:04:19.712](0.004s) ok 13 - activeslot slot invalidation is logged with vacuum FULL on pg_class
[11:04:22.715](3.003s) ok 14 - confl_active_logicalslot updated
[11:04:24.743](2.028s) ok 15 - vacuum_full_activeslot conflict_reason is rows_removed
[11:04:27.004](2.260s) ok 16 - vacuum_full_inactiveslot conflict_reason is rows_removed
[11:04:29.782](2.778s) ok 17 - pg_recvlogical exited non-zero
[11:04:29.783](0.001s) ok 18 - slot has been invalidated
### Reloading node "standby"
# Running: pg_ctl -D /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata reload
server signaled
### Restarting node "standby"
# Running: pg_ctl -w -D /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata -l /home/vagrant/postgresql/src/test/recovery_1/tmp_check/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 82639
[11:04:45.962](16.179s) ok 19 - vacuum_full_activeslot conflict_reason is rows_removed
[11:04:48.010](2.048s) ok 20 - vacuum_full_inactiveslot conflict_reason is rows_removed
Waiting for replication conn standby's replay_lsn to pass 0/4000130 on primary
done
[11:05:01.528](13.518s) ok 21 - invalidated logical slots do not lead to retaining WAL


[11:05:11.491](9.963s) ok 22 - row_removal_inactiveslot on standby created
[11:05:14.125](2.635s) ok 23 - row_removal_activeslot on standby created
### Reloading node "standby"
# Running: pg_ctl -D /home/vagrant/postgresql/src/test/recovery_1/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata reload
server signaled

#### Begin standard error
psql:<stdin>:1: INFO:  vacuuming "testdb.pg_catalog.pg_class"
psql:<stdin>: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: 754, 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: 0.149 MB/s, avg write rate: 0.319 MB/s
buffer usage: 78 hits, 7 misses, 15 dirtied
WAL usage: 28 records, 15 full page images, 122841 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.36 s
#### End standard error
Waiting for replication conn standby's replay_lsn to pass 0/403E730 on primary
done
[11:05:28.118](13.993s) ok 24 - inactiveslot slot invalidation is logged with vacuum on pg_class
[11:05:28.119](0.001s) not ok 25 - activeslot slot invalidation is logged with vacuum on pg_class
[11:05:28.219](0.100s) 
[11:05:28.325](0.105s) #   Failed test 'activeslot slot invalidation is logged with vacuum on pg_class'
#   at t/035_standby_logical_decoding.pl line 227.
[11:05:31.182](2.857s) ok 26 - confl_active_logicalslot updated
[11:05:34.281](3.099s) not ok 27 - row_removal_activeslot conflict_reason is rows_removed
[11:05:34.282](0.001s) 
[11:05:34.282](0.000s) #   Failed test 'row_removal_activeslot conflict_reason is rows_removed'
#   at t/035_standby_logical_decoding.pl line 183.
[11:05:34.282](0.000s) #          got: ''
#     expected: 'rows_removed'
[11:05:35.102](0.819s) ok 28 - row_removal_inactiveslot conflict_reason is rows_removed
