# Checking port 54556
# Found port 54556
Name: primary
Data directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata
Backup directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/backup
Archive directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/archives
Connection string: port=54556 host=/tmp/KGFuiwzImm
Log file: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/log/035_standby_logical_decoding_primary.log
# Checking port 54557
# Found port 54557
Name: standby
Data directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata
Backup directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/backup
Archive directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/archives
Connection string: port=54557 host=/tmp/KGFuiwzImm
Log file: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/log/035_standby_logical_decoding_standby.log
# Checking port 54558
# Found port 54558
Name: cascading_standby
Data directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_cascading_standby_data/pgdata
Backup directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_cascading_standby_data/backup
Archive directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_cascading_standby_data/archives
Connection string: port=54558 host=/tmp/KGFuiwzImm
Log file: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/log/035_standby_logical_decoding_cascading_standby.log
# Checking port 54559
# Found port 54559
Name: subscriber
Data directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_subscriber_data/pgdata
Backup directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_subscriber_data/backup
Archive directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_subscriber_data/archives
Connection string: port=54559 host=/tmp/KGFuiwzImm
Log file: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/log/035_standby_logical_decoding_subscriber.log
[09:36:54.060](0.014s) # initializing database system by copying initdb template
# Running: cp -RPp /src/postgreSQL/postgresql.git/tmp_install/initdb-template /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata
# Running: /src/postgreSQL/postgresql.git/src/test/recovery/../../../src/test/regress/pg_regress --config-auth /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata
### Enabling WAL archiving for node "primary"
Name: primary
Version: 17devel
Data directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata
Backup directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/backup
Archive directory: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/archives
Connection string: port=54556 host=/tmp/KGFuiwzImm
Log file: /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/log/035_standby_logical_decoding_primary.log
### Starting node "primary"
# Running: pg_ctl -w -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/pgdata -l /src/postgreSQL/postgresql.git/src/test/recovery/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 67202
[09:36:54.267](0.207s) ok 1 - Physical slot reports conflict_reason as NULL
# Taking pg_basebackup b1 from node "primary"
# Running: pg_basebackup -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_primary_data/backup/b1 -h /tmp/KGFuiwzImm -p 54556 --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 /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata -l /src/postgreSQL/postgresql.git/src/test/recovery/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 67231
Waiting for replication conn standby's replay_lsn to pass 0/3019928 on primary
done
[09:36:54.582](0.315s) # initializing database system by copying initdb template
# Running: cp -RPp /src/postgreSQL/postgresql.git/tmp_install/initdb-template /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_subscriber_data/pgdata
# Running: /src/postgreSQL/postgresql.git/src/test/recovery/../../../src/test/regress/pg_regress --config-auth /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_subscriber_data/pgdata
### Starting node "subscriber"
# Running: pg_ctl -w -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_subscriber_data/pgdata -l /src/postgreSQL/postgresql.git/src/test/recovery/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 67254
[09:36:54.968](0.386s) ok 2 - behaves_ok_inactiveslot on standby created
[09:36:55.172](0.204s) ok 3 - behaves_ok_activeslot on standby created
Waiting for replication conn standby's replay_lsn to pass 0/30258C8 on primary
done
[09:36:55.204](0.032s) ok 4 - Decoding produced 14 rows (2 BEGIN/COMMIT and 10 rows)
Waiting for replication conn standby's replay_lsn to pass 0/30259F8 on primary
done
[09:36:55.228](0.023s) ok 5 - got expected output from SQL decoding session
Waiting for replication conn standby's replay_lsn to pass 0/30265C0 on primary
done
[09:36:55.256](0.028s) ok 6 - got same expected output from pg_recvlogical decoding session
[09:36:55.269](0.013s) ok 7 - pg_recvlogical acknowledged changes
Waiting for replication conn standby's replay_lsn to pass 0/3457728 on primary
done
[09:36:55.331](0.062s) ok 8 - replaying logical slot from another database fails
Waiting for replication conn standby's replay_lsn to pass 0/347E8F8 on primary
done
Waiting for all subscriptions in "subscriber" to synchronize data
Waiting for replication conn tap_sub's replay_lsn to pass 0/347E930 on standby
done
done
Waiting for replication conn standby's replay_lsn to pass 0/347EEC0 on primary
done
Waiting for replication conn tap_sub's replay_lsn to pass 0/347EEC0 on standby
done
[09:36:55.715](0.384s) 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 /src/postgreSQL/postgresql.git/src/test/recovery/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"


[09:36:56.221](0.506s) ok 10 - vacuum_full_inactiveslot on standby created
[09:36:56.614](0.393s) ok 11 - vacuum_full_activeslot on standby created
### Reloading node "standby"
# Running: pg_ctl -D /src/postgreSQL/postgresql.git/src/test/recovery/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.00 s.
#### End standard error
Waiting for replication conn standby's replay_lsn to pass 0/34B0090 on primary
done
[09:36:56.769](0.155s) ok 12 - inactiveslot slot invalidation is logged with vacuum FULL on pg_class
[09:36:56.770](0.000s) ok 13 - activeslot slot invalidation is logged with vacuum FULL on pg_class
[09:36:56.884](0.114s) ok 14 - confl_active_logicalslot updated
[09:36:56.893](0.009s) ok 15 - vacuum_full_activeslot conflict_reason is rows_removed
[09:36:56.900](0.007s) ok 16 - vacuum_full_inactiveslot conflict_reason is rows_removed
[09:36:57.001](0.101s) ok 17 - pg_recvlogical exited non-zero
[09:36:57.001](0.000s) ok 18 - slot has been invalidated
### Reloading node "standby"
# Running: pg_ctl -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata reload
server signaled
### Restarting node "standby"
# Running: pg_ctl -w -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata -l /src/postgreSQL/postgresql.git/src/test/recovery/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 67418
[09:36:57.426](0.425s) ok 19 - vacuum_full_activeslot conflict_reason is rows_removed
[09:36:57.435](0.010s) ok 20 - vacuum_full_inactiveslot conflict_reason is rows_removed
Waiting for replication conn standby's replay_lsn to pass 0/40000F8 on primary
done


[09:36:57.968](0.533s) ok 21 - row_removal_inactiveslot on standby created
[09:36:58.469](0.501s) ok 22 - row_removal_activeslot on standby created
### Reloading node "standby"
# Running: pg_ctl -D /src/postgreSQL/postgresql.git/src/test/recovery/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: 72.147 MB/s, avg write rate: 154.601 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.00 s
#### End standard error
Waiting for replication conn standby's replay_lsn to pass 0/403E6A0 on primary
done
[09:36:58.713](0.244s) ok 23 - inactiveslot slot invalidation is logged with vacuum on pg_class
[09:36:58.713](0.000s) ok 24 - activeslot slot invalidation is logged with vacuum on pg_class
[09:36:58.900](0.187s) ok 25 - confl_active_logicalslot updated
[09:36:58.910](0.009s) ok 26 - row_removal_activeslot conflict_reason is rows_removed
[09:36:58.917](0.008s) ok 27 - row_removal_inactiveslot conflict_reason is rows_removed
[09:36:58.998](0.081s) ok 28 - pg_recvlogical exited non-zero
[09:36:58.998](0.000s) ok 29 - slot has been invalidated


[09:36:59.217](0.219s) ok 30 - shared_row_removal_inactiveslot on standby created
[09:36:59.409](0.192s) ok 31 - shared_row_removal_activeslot on standby created
### Reloading node "standby"
# Running: pg_ctl -D /src/postgreSQL/postgresql.git/src/test/recovery/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_authid"
psql:<stdin>:1: INFO:  finished vacuuming "testdb.pg_catalog.pg_authid": index scans: 1
pages: 0 removed, 1 remain, 1 scanned (100.00% of total)
tuples: 1 removed, 15 remain, 0 are dead but not yet removable
removable cutoff: 758, which was 0 XIDs old when operation ended
new relfrozenxid: 758, which is 30 XIDs ahead of previous value
frozen: 0 pages from table (0.00% of total) had 0 tuples frozen
index scan needed: 1 pages from table (100.00% of total) had 1 dead item identifiers removed
index "pg_authid_rolname_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable
index "pg_authid_oid_index": pages: 2 in total, 0 newly deleted, 0 currently deleted, 0 reusable
avg read rate: 54.633 MB/s, avg write rate: 27.316 MB/s
buffer usage: 35 hits, 2 misses, 1 dirtied
WAL usage: 6 records, 1 full page images, 8692 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
psql:<stdin>:1: INFO:  vacuuming "testdb.pg_toast.pg_toast_1260"
psql:<stdin>:1: INFO:  finished vacuuming "testdb.pg_toast.pg_toast_1260": index scans: 0
pages: 0 removed, 0 remain, 0 scanned (100.00% of total)
tuples: 0 removed, 0 remain, 0 are dead but not yet removable
removable cutoff: 758, which was 0 XIDs old when operation ended
new relfrozenxid: 758, which is 30 XIDs ahead of previous value
frozen: 0 pages from table (100.00% of total) had 0 tuples frozen
index scan not needed: 0 pages from table (100.00% of total) had 0 dead item identifiers removed
avg read rate: 63.516 MB/s, avg write rate: 63.516 MB/s
buffer usage: 24 hits, 1 misses, 1 dirtied
WAL usage: 1 records, 0 full page images, 188 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/4041990 on primary
done
[09:36:59.814](0.405s) ok 32 - inactiveslot slot invalidation is logged with vacuum on pg_authid
[09:36:59.814](0.000s) ok 33 - activeslot slot invalidation is logged with vacuum on pg_authid
[09:36:59.958](0.144s) ok 34 - confl_active_logicalslot updated
[09:36:59.966](0.008s) ok 35 - shared_row_removal_activeslot conflict_reason is rows_removed
[09:36:59.972](0.007s) ok 36 - shared_row_removal_inactiveslot conflict_reason is rows_removed
[09:37:00.065](0.093s) ok 37 - pg_recvlogical exited non-zero
[09:37:00.066](0.000s) ok 38 - slot has been invalidated


[09:37:00.374](0.308s) ok 39 - no_conflict_inactiveslot on standby created
[09:37:00.567](0.193s) ok 40 - no_conflict_activeslot on standby created
### Reloading node "standby"
# Running: pg_ctl -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata reload
server signaled

#### Begin standard error
psql:<stdin>:1: INFO:  vacuuming "testdb.public.conflict_test"
psql:<stdin>:1: INFO:  finished vacuuming "testdb.public.conflict_test": index scans: 0
pages: 0 removed, 1 remain, 1 scanned (100.00% of total)
tuples: 4 removed, 4 remain, 0 are dead but not yet removable
removable cutoff: 763, which was 0 XIDs old when operation ended
new relfrozenxid: 761, which is 2 XIDs ahead of previous value
frozen: 0 pages from table (0.00% of total) had 0 tuples frozen
index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed
avg read rate: 71.456 MB/s, avg write rate: 71.456 MB/s
buffer usage: 19 hits, 3 misses, 3 dirtied
WAL usage: 5 records, 3 full page images, 24982 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
psql:<stdin>:1: INFO:  vacuuming "testdb.pg_toast.pg_toast_16418"
psql:<stdin>:1: INFO:  finished vacuuming "testdb.pg_toast.pg_toast_16418": index scans: 0
pages: 0 removed, 0 remain, 0 scanned (100.00% of total)
tuples: 0 removed, 0 remain, 0 are dead but not yet removable
removable cutoff: 763, which was 0 XIDs old when operation ended
new relfrozenxid: 763, which is 4 XIDs ahead of previous value
frozen: 0 pages from table (100.00% of total) had 0 tuples frozen
index scan not needed: 0 pages from table (100.00% of total) had 0 dead item identifiers removed
avg read rate: 77.351 MB/s, avg write rate: 0.000 MB/s
buffer usage: 24 hits, 1 misses, 0 dirtied
WAL usage: 1 records, 0 full page images, 188 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/404BB00 on primary
done
[09:37:00.705](0.139s) ok 41 - inactiveslot slot invalidation is not logged with vacuum on conflict_test
[09:37:00.706](0.000s) ok 42 - activeslot slot invalidation is not logged with vacuum on conflict_test
[09:37:00.710](0.005s) ok 43 - confl_active_logicalslot not updated
[09:37:00.714](0.004s) ok 44 - Logical slots are reported as non conflicting
### Reloading node "standby"
# Running: pg_ctl -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata reload
server signaled
### Restarting node "standby"
# Running: pg_ctl -w -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata -l /src/postgreSQL/postgresql.git/src/test/recovery/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 67603


[09:37:01.366](0.651s) ok 45 - pruning_inactiveslot on standby created
[09:37:01.639](0.273s) ok 46 - pruning_activeslot on standby created
### Reloading node "standby"
# Running: pg_ctl -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata reload
server signaled

Waiting for replication conn standby's replay_lsn to pass 0/4058090 on primary
done
[09:37:16.884](15.246s) ok 47 - inactiveslot slot invalidation is logged with on-access pruning
[09:37:16.885](0.000s) not ok 48 - activeslot slot invalidation is logged with on-access pruning
[09:37:16.885](0.000s) 
[09:37:16.885](0.000s) #   Failed test 'activeslot slot invalidation is logged with on-access pruning'
#   at t/035_standby_logical_decoding.pl line 227.
death by signal at /src/postgreSQL/postgresql.git/src/test/recovery/../../../src/test/perl/PostgreSQL/Test/Cluster.pm line 3169.
# Postmaster PID for node "primary" is 67202
### Stopping node "primary" using mode immediate
# Running: pg_ctl -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/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"
# Postmaster PID for node "standby" is 67603
### Stopping node "standby" using mode immediate
# Running: pg_ctl -D /src/postgreSQL/postgresql.git/src/test/recovery/tmp_check/t_035_standby_logical_decoding_standby_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "standby"
# No postmaster PID for node "cascading_standby"
# No postmaster PID for node "subscriber"
[09:37:24.864](7.979s) # Tests were run but no plan was declared and done_testing() was not seen.
[09:37:24.864](0.000s) # Looks like your test exited with 4 just after 48.
Warning: unable to close filehandle $orig_stderr properly: Broken pipe during global destruction.
