# Running: pg_createsubscriber --help
[14:36:39.244](0.025s) ok 1 - pg_createsubscriber --help exit code 0
[14:36:39.245](0.001s) ok 2 - pg_createsubscriber --help goes to stdout
[14:36:39.245](0.000s) ok 3 - pg_createsubscriber --help nothing to stderr
[14:36:39.246](0.001s) ok 4 - pg_createsubscriber --help maximum line length
# Running: pg_createsubscriber --version
[14:36:39.255](0.009s) ok 5 - pg_createsubscriber --version exit code 0
[14:36:39.255](0.001s) ok 6 - pg_createsubscriber --version goes to stdout
[14:36:39.255](0.000s) ok 7 - pg_createsubscriber --version nothing to stderr
# Running: pg_createsubscriber --not-a-valid-option
[14:36:39.263](0.008s) ok 8 - pg_createsubscriber with invalid option nonzero exit code
[14:36:39.264](0.001s) ok 9 - pg_createsubscriber with invalid option prints error message
# Running: pg_createsubscriber
pg_createsubscriber: error: no subscriber data directory specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[14:36:39.270](0.006s) ok 10 - no subscriber data directory specified
# Running: pg_createsubscriber --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_68k6
pg_createsubscriber: error: no publisher connection string specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[14:36:39.286](0.016s) ok 11 - no publisher connection string specified
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_68k6 --publisher-server port=5432
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: no database was specified
pg_createsubscriber: error: no database name specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[14:36:39.294](0.008s) ok 12 - no database name specified
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_68k6 --publisher-server port=5432 --database pg1 --database pg1
pg_createsubscriber: error: duplicate database "pg1"
[14:36:39.302](0.007s) ok 13 - duplicate database name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_68k6 --publisher-server port=5432 --publication foo1 --publication foo1 --database pg1 --database pg2
pg_createsubscriber: error: duplicate publication "foo1"
[14:36:39.319](0.018s) ok 14 - duplicate publication name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_68k6 --publisher-server port=5432 --publication foo1 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: error: wrong number of publication names
pg_createsubscriber: hint: Number of publication names (1) must match number of database names (2).
[14:36:39.328](0.008s) ok 15 - wrong number of publication names
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_68k6 --publisher-server port=5432 --publication foo1 --publication foo2 --subscription bar1 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: error: wrong number of subscription names
pg_createsubscriber: hint: Number of subscription names (1) must match number of database names (2).
[14:36:39.350](0.022s) ok 16 - wrong number of subscription names
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_68k6 --publisher-server port=5432 --publication foo1 --publication foo2 --subscription bar1 --subscription bar2 --replication-slot baz1 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: error: wrong number of replication slot names
pg_createsubscriber: hint: Number of replication slot names (1) must match number of database names (2).
[14:36:39.365](0.015s) ok 17 - wrong number of replication slot names
# Checking port 59526
# Found port 59526
Name: node_p
Data directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/archives
Connection string: port=59526 host=/tmp/hnd0DRYYBl
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_p.log
[14:36:39.371](0.007s) # 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/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata
# Running: /tmp/cirrus-ci-build/build/src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata
### Starting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_p.log -o --cluster-name=node_p start
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 20719
# Checking port 59527
# Found port 59527
Name: node_f
Data directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_f_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_f_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_f_data/archives
Connection string: port=59527 host=/tmp/hnd0DRYYBl
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_f.log
[14:36:39.549](0.177s) # initializing database system by running initdb
# Running: initdb -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_f_data/pgdata -A trust -N
The files belonging to this database system will be owned by user "postgres".
This user must also own the server process.

The database cluster will be initialized with this locale configuration:
  locale provider:   libc
  LC_COLLATE:  en_US.UTF-8
  LC_CTYPE:    en_US.UTF-8
  LC_MESSAGES: C
  LC_MONETARY: en_US.UTF-8
  LC_NUMERIC:  en_US.UTF-8
  LC_TIME:     en_US.UTF-8
The default database encoding has accordingly been set to "UTF8".
The default text search configuration will be set to "english".

Data page checksums are disabled.

creating directory /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_f_data/pgdata ... ok
creating subdirectories ... ok
selecting dynamic shared memory implementation ... posix
selecting default max_connections ... 100
selecting default shared_buffers ... 128MB
selecting default time zone ... UTC
creating configuration files ... ok
running bootstrap script ... ok
performing post-bootstrap initialization ... ok

Sync to disk skipped.
The data directory might become corrupt if the operating system crashes.

Success. You can now start the database server using:

    pg_ctl -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_f_data/pgdata -l logfile start

# Running: /tmp/cirrus-ci-build/build/src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_f_data/pgdata
#### Begin standard error
psql:<stdin>:2: WARNING:  databases created by regression test cases should have names including "regression"
psql:<stdin>:3: WARNING:  databases created by regression test cases should have names including "regression"
#### End standard error
# Taking pg_basebackup backup_1 from node "node_p"
# Running: pg_basebackup -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/backup/backup_1 -h /tmp/hnd0DRYYBl -p 59526 --checkpoint fast --no-sync
# Backup finished
# Checking port 59528
# Found port 59528
Name: node_s
Data directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/archives
Connection string: port=59528 host=/tmp/hnd0DRYYBl
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_s.log
# Initializing node "node_s" from backup "backup_1" of node "node_p"
### Enabling streaming replication for node "node_s"
### Starting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_s.log -o --cluster-name=node_s start
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 21060
# Checking port 59529
# Found port 59529
Name: node_t
Data directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_t_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_t_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_t_data/archives
Connection string: port=59529 host=/tmp/hnd0DRYYBl
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_t.log
# Initializing node "node_t" from backup "backup_1" of node "node_p"
### Enabling streaming replication for node "node_t"
### Starting node "node_t"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_t_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_t.log -o --cluster-name=node_t start
waiting for server to start.... done
server started
# Postmaster PID for node "node_t" is 21091
### Promoting node "node_t"
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_t_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_t.log promote
waiting for server to promote.... done
server promoted
### Stopping node "node_t" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_t_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "node_t"
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_t_data/pgdata --publisher-server port=59526 host=/tmp/hnd0DRYYBl dbname='pg1' --socket-directory /tmp/hnd0DRYYBl --subscriber-port 59529 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_t_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7350680693374330181 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7350680693374330181 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-26 14:36:42.022 UTC [21177][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-26 14:36:42.022 UTC [21177][postmaster] LOG:  listening on Unix socket "/tmp/hnd0DRYYBl/.s.PGSQL.59529"
2024-03-26 14:36:42.039 UTC [21183][startup] LOG:  database system was shut down at 2024-03-26 14:36:41 UTC
2024-03-26 14:36:42.045 UTC [21177][postmaster] LOG:  database system is ready to accept connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-26 14:36:42.118 UTC [21198][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:42.118 UTC [21198][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_t_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:42.118 UTC [21198][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:42.144 UTC [21198][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-26 14:36:42.147 UTC [21198][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
pg_createsubscriber: error: target server must be a standby
2024-03-26 14:36:42.157 UTC [21198][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.039 user=postgres database=pg1 host=[local]
2024-03-26 14:36:42.173 UTC [21177][postmaster] LOG:  received fast shutdown request
2024-03-26 14:36:42.173 UTC [21177][postmaster] LOG:  aborting any active transactions
2024-03-26 14:36:42.193 UTC [21177][postmaster] LOG:  background worker "logical replication launcher" (PID 21191) exited with exit code 1
2024-03-26 14:36:42.193 UTC [21181][checkpointer] LOG:  shutting down
2024-03-26 14:36:42.193 UTC [21181][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-03-26 14:36:42.195 UTC [21181][checkpointer] LOG:  checkpoint complete: wrote 6 buffers (4.7%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s; distance=17 kB, estimate=17 kB; lsn=0/30046A0, redo lsn=0/30046A0
2024-03-26 14:36:42.212 UTC [21177][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[14:36:42.297](2.748s) ok 18 - target server is not in recovery
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=59526 host=/tmp/hnd0DRYYBl dbname='pg1' --socket-directory /tmp/hnd0DRYYBl --subscriber-port 59528 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7350680693374330181 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7350680693374330181 on subscriber
pg_createsubscriber: error: standby is up and running
pg_createsubscriber: hint: Stop the standby and try again.
[14:36:42.345](0.049s) ok 19 - standby is up and running
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_f_data/pgdata --publisher-server port=59526 host=/tmp/hnd0DRYYBl dbname='pg1' --socket-directory /tmp/hnd0DRYYBl --subscriber-port 59527 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_f_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7350680693374330181 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7350681047586758945 on subscriber
pg_createsubscriber: error: subscriber data directory is not a copy of the source database cluster
[14:36:42.431](0.086s) ok 20 - subscriber data directory is not a copy of the source database cluster
# Taking pg_basebackup backup_2 from node "node_s"
# Running: pg_basebackup -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/backup/backup_2 -h /tmp/hnd0DRYYBl -p 59528 --checkpoint fast --no-sync
# Backup finished
# Checking port 59530
# Found port 59530
Name: node_c
Data directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_c_data/pgdata
Backup directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_c_data/backup
Archive directory: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_c_data/archives
Connection string: port=59530 host=/tmp/hnd0DRYYBl
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_c.log
# Initializing node "node_c" from backup "backup_2" of node "node_s"
### Enabling streaming replication for node "node_c"
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_c_data/pgdata --publisher-server port=59528 host=/tmp/hnd0DRYYBl dbname='pg1' --socket-directory /tmp/hnd0DRYYBl --subscriber-port 59530 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_c_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7350680693374330181 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7350680693374330181 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-26 14:36:43.762 UTC [21356][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-26 14:36:43.762 UTC [21356][postmaster] LOG:  listening on Unix socket "/tmp/hnd0DRYYBl/.s.PGSQL.59530"
2024-03-26 14:36:43.764 UTC [21361][startup] LOG:  database system was interrupted while in recovery at log time 2024-03-26 14:36:40 UTC
2024-03-26 14:36:43.764 UTC [21361][startup] HINT:  If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2024-03-26 14:36:43.764 UTC [21361][startup] LOG:  starting backup recovery with redo LSN 0/2000028, checkpoint LSN 0/2000080, on timeline ID 1
2024-03-26 14:36:43.764 UTC [21361][startup] LOG:  entering standby mode
2024-03-26 14:36:43.764 UTC [21361][startup] LOG:  redo starts at 0/2000028
2024-03-26 14:36:43.764 UTC [21361][startup] LOG:  completed backup recovery with redo LSN 0/2000028 and end LSN 0/2000120
2024-03-26 14:36:43.764 UTC [21361][startup] LOG:  consistent recovery state reached at 0/3000000
2024-03-26 14:36:43.764 UTC [21356][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-26 14:36:43.777 UTC [21362][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-26 14:36:43.865 UTC [21385][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:43.865 UTC [21385][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_c_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:43.865 UTC [21385][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:43.871 UTC [21385][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-26 14:36:43.872 UTC [21385][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-26 14:36:43.872 UTC [21385][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-03-26 14:36:43.876 UTC [21385][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.010 user=postgres database=pg1 host=[local]
pg_createsubscriber: error: primary server cannot be in recovery
2024-03-26 14:36:43.889 UTC [21356][postmaster] LOG:  received fast shutdown request
2024-03-26 14:36:43.889 UTC [21356][postmaster] LOG:  aborting any active transactions
2024-03-26 14:36:43.891 UTC [21362][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-26 14:36:43.892 UTC [21359][checkpointer] LOG:  shutting down
2024-03-26 14:36:43.896 UTC [21356][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[14:36:44.053](1.621s) ok 21 - primary server is in recovery
Waiting for replication conn node_s's replay_lsn to pass 0/3000110 on node_p
done
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_p.log restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 21444
### Stopping node "node_s" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "node_s"
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=59526 host=/tmp/hnd0DRYYBl dbname='pg1' --socket-directory /tmp/hnd0DRYYBl --subscriber-port 59528 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7350680693374330181 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7350680693374330181 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-26 14:36:44.474 UTC [21488][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-26 14:36:44.474 UTC [21488][postmaster] LOG:  listening on Unix socket "/tmp/hnd0DRYYBl/.s.PGSQL.59528"
2024-03-26 14:36:44.481 UTC [21491][startup] LOG:  database system was shut down in recovery at 2024-03-26 14:36:44 UTC
2024-03-26 14:36:44.481 UTC [21491][startup] LOG:  entering standby mode
2024-03-26 14:36:44.486 UTC [21491][startup] LOG:  consistent recovery state reached at 0/3000188
2024-03-26 14:36:44.486 UTC [21488][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-26 14:36:44.486 UTC [21491][startup] LOG:  invalid record length at 0/3000188: expected at least 24, got 0
2024-03-26 14:36:44.490 UTC [21492][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-26 14:36:44.490 UTC [21491][startup] LOG:  redo starts at 0/3000188
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-26 14:36:44.574 UTC [21495][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:44.574 UTC [21495][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:44.574 UTC [21495][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:44.584 UTC [21495][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-26 14:36:44.584 UTC [21495][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-26 14:36:44.584 UTC [21495][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-03-26 14:36:44.589 UTC [21495][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.014 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: error: publisher requires wal_level >= "logical"
pg_createsubscriber: error: publisher requires 2 replication slots, but only 0 remain
pg_createsubscriber: hint: Consider increasing max_replication_slots to at least 3.
pg_createsubscriber: error: publisher requires 2 wal sender processes, but only 0 remain
pg_createsubscriber: hint: Consider increasing max_wal_senders to at least 3.
2024-03-26 14:36:44.607 UTC [21488][postmaster] LOG:  received fast shutdown request
2024-03-26 14:36:44.607 UTC [21488][postmaster] LOG:  aborting any active transactions
2024-03-26 14:36:44.609 UTC [21492][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-26 14:36:44.611 UTC [21489][checkpointer] LOG:  shutting down
2024-03-26 14:36:44.612 UTC [21488][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[14:36:44.768](0.716s) ok 22 - primary contains unmet conditions on node P
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=59526 host=/tmp/hnd0DRYYBl dbname='pg1' --socket-directory /tmp/hnd0DRYYBl --subscriber-port 59528 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7350680693374330181 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7350680693374330181 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-26 14:36:44.828 UTC [21518][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-26 14:36:44.828 UTC [21518][postmaster] LOG:  listening on Unix socket "/tmp/hnd0DRYYBl/.s.PGSQL.59528"
2024-03-26 14:36:44.837 UTC [21525][startup] LOG:  database system was shut down in recovery at 2024-03-26 14:36:44 UTC
2024-03-26 14:36:44.837 UTC [21525][startup] LOG:  entering standby mode
2024-03-26 14:36:44.837 UTC [21525][startup] LOG:  redo starts at 0/3000188
2024-03-26 14:36:44.837 UTC [21525][startup] LOG:  invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3004000, offset 16384
2024-03-26 14:36:44.838 UTC [21525][startup] LOG:  consistent recovery state reached at 0/3002758
2024-03-26 14:36:44.838 UTC [21518][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-26 14:36:44.838 UTC [21525][startup] LOG:  invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3004000, offset 16384
2024-03-26 14:36:44.866 UTC [21526][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-26 14:36:44.911 UTC [21530][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:44.912 UTC [21530][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:44.912 UTC [21530][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:44.916 UTC [21530][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-26 14:36:44.916 UTC [21530][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-26 14:36:44.917 UTC [21530][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: error: subscriber requires 2 replication slots, but only 1 remain
pg_createsubscriber: hint: Consider increasing max_replication_slots to at least 2.
pg_createsubscriber: error: subscriber requires 2 logical replication workers, but only 1 remain
pg_createsubscriber: hint: Consider increasing max_logical_replication_workers to at least 2.
pg_createsubscriber: error: subscriber requires 3 worker processes, but only 2 remain
pg_createsubscriber: hint: Consider increasing max_worker_processes to at least 3.
2024-03-26 14:36:44.921 UTC [21518][postmaster] LOG:  received fast shutdown request
2024-03-26 14:36:44.921 UTC [21518][postmaster] LOG:  aborting any active transactions
2024-03-26 14:36:44.923 UTC [21526][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-26 14:36:44.925 UTC [21530][client backend] [040_pg_createsubscriber.pl][0/0:0] FATAL:  terminating connection due to administrator command
2024-03-26 14:36:44.925 UTC [21530][client backend] [040_pg_createsubscriber.pl][0/0:0] LOG:  could not send data to client: Broken pipe
2024-03-26 14:36:44.925 UTC [21530][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.013 user=postgres database=pg1 host=[local]
2024-03-26 14:36:44.926 UTC [21523][checkpointer] LOG:  shutting down
2024-03-26 14:36:44.927 UTC [21518][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[14:36:45.095](0.327s) ok 23 - standby contains unmet conditions on node S
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_p.log restart
waiting for server to shut down.... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 21566
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=59526 host=/tmp/hnd0DRYYBl dbname='pg1' --socket-directory /tmp/hnd0DRYYBl --subscriber-port 59528 --publication pub1 --publication pub2 --subscription sub1 --subscription sub2 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7350680693374330181 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7350680693374330181 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-26 14:36:45.360 UTC [21613][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-26 14:36:45.360 UTC [21613][postmaster] LOG:  listening on Unix socket "/tmp/hnd0DRYYBl/.s.PGSQL.59528"
2024-03-26 14:36:45.365 UTC [21623][startup] LOG:  database system was shut down in recovery at 2024-03-26 14:36:44 UTC
2024-03-26 14:36:45.365 UTC [21623][startup] LOG:  entering standby mode
2024-03-26 14:36:45.372 UTC [21623][startup] LOG:  redo starts at 0/3000188
2024-03-26 14:36:45.372 UTC [21623][startup] LOG:  consistent recovery state reached at 0/30046C0
2024-03-26 14:36:45.372 UTC [21623][startup] LOG:  invalid record length at 0/30046C0: expected at least 24, got 0
2024-03-26 14:36:45.372 UTC [21613][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-26 14:36:45.379 UTC [21628][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-26 14:36:45.470 UTC [21646][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:45.471 UTC [21646][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:45.471 UTC [21646][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:45.478 UTC [21646][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-26 14:36:45.479 UTC [21646][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-26 14:36:45.479 UTC [21646][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-03-26 14:36:45.483 UTC [21646][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.012 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: stopping the subscriber
2024-03-26 14:36:45.502 UTC [21613][postmaster] LOG:  received fast shutdown request
2024-03-26 14:36:45.502 UTC [21613][postmaster] LOG:  aborting any active transactions
2024-03-26 14:36:45.519 UTC [21628][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-26 14:36:45.521 UTC [21621][checkpointer] LOG:  shutting down
2024-03-26 14:36:45.521 UTC [21621][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-26 14:36:45.523 UTC [21621][checkpointer] LOG:  restartpoint complete: wrote 4 buffers (3.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s; distance=17 kB, estimate=17 kB; lsn=0/30046C0, redo lsn=0/30046C0
2024-03-26 14:36:45.523 UTC [21621][checkpointer] LOG:  recovery restart point at 0/30046C0
2024-03-26 14:36:45.531 UTC [21613][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: creating publication "pub1" on database "pg1"
pg_createsubscriber: creating the replication slot "sub1" on database "pg1"
pg_createsubscriber: create replication slot "sub1" on publisher
pg_createsubscriber: creating publication "pub2" on database "pg2"
pg_createsubscriber: creating the replication slot "sub2" on database "pg2"
pg_createsubscriber: create replication slot "sub2" on publisher
pg_createsubscriber: starting the subscriber
2024-03-26 14:36:45.781 UTC [21661][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-26 14:36:45.781 UTC [21661][postmaster] LOG:  listening on Unix socket "/tmp/hnd0DRYYBl/.s.PGSQL.59528"
2024-03-26 14:36:45.844 UTC [21670][startup] LOG:  database system was shut down in recovery at 2024-03-26 14:36:45 UTC
2024-03-26 14:36:45.844 UTC [21670][startup] LOG:  entering standby mode
2024-03-26 14:36:45.845 UTC [21670][startup] LOG:  redo starts at 0/3004738
2024-03-26 14:36:45.845 UTC [21670][startup] LOG:  consistent recovery state reached at 0/3004770
2024-03-26 14:36:45.845 UTC [21661][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-26 14:36:45.845 UTC [21670][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-03-26 14:36:45.860 UTC [21673][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-03-26 14:36:45.913 UTC [21675][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:45.913 UTC [21675][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:45.913 UTC [21675][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:45.917 UTC [21675][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-26 14:36:45.918 UTC [21675][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-26 14:36:45.923 UTC [21675][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.010 user=postgres database=pg1 host=[local]
pg_createsubscriber: target server reached the consistent state
pg_createsubscriber: hint: If pg_createsubscriber fails after this point, you must recreate the physical replica before continuing.
2024-03-26 14:36:45.925 UTC [21679][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:45.925 UTC [21679][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:45.926 UTC [21679][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:45.926 UTC [21679][client backend] [040_pg_createsubscriber.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pub1" on database "pg1"
pg_createsubscriber: creating subscription "sub1" on database "pg1"
2024-03-26 14:36:45.927 UTC [21679][client backend] [040_pg_createsubscriber.pl][1/3:0] LOG:  statement: SELECT s.oid FROM pg_catalog.pg_subscription s INNER JOIN pg_catalog.pg_database d ON (s.subdbid = d.oid) WHERE s.subname = 'sub1' AND d.datname = 'pg1'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "sub1" on database "pg1"
2024-03-26 14:36:45.930 UTC [21679][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.004 user=postgres database=pg1 host=[local]
2024-03-26 14:36:45.931 UTC [21680][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:45.931 UTC [21680][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:45.931 UTC [21680][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:45.936 UTC [21680][client backend] [040_pg_createsubscriber.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pub2" on database "pg2"
pg_createsubscriber: creating subscription "sub2" on database "pg2"
2024-03-26 14:36:45.936 UTC [21680][client backend] [040_pg_createsubscriber.pl][2/3:0] LOG:  statement: SELECT s.oid FROM pg_catalog.pg_subscription s INNER JOIN pg_catalog.pg_database d ON (s.subdbid = d.oid) WHERE s.subname = 'sub2' AND d.datname = 'pg2'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "sub2" on database "pg2"
2024-03-26 14:36:45.939 UTC [21680][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.008 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-26 14:36:45.948 UTC [21661][postmaster] LOG:  received fast shutdown request
2024-03-26 14:36:45.948 UTC [21661][postmaster] LOG:  aborting any active transactions
2024-03-26 14:36:45.950 UTC [21673][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-26 14:36:45.951 UTC [21666][checkpointer] LOG:  shutting down
2024-03-26 14:36:45.952 UTC [21661][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7350681075277485149 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: Done!
[14:36:46.493](1.398s) ok 24 - run pg_createsubscriber --dry-run on node S
### Starting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_s.log -o --cluster-name=node_s start
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 21751
[14:36:46.651](0.157s) ok 25 - standby is in recovery
### Stopping node "node_s" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata -m fast stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "node_s"
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=59526 host=/tmp/hnd0DRYYBl dbname='pg1' --socket-directory /tmp/hnd0DRYYBl --subscriber-port 59528 --replication-slot replslot1
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: no database was specified
pg_createsubscriber: database "pg1" was extracted from the publisher connection string
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7350680693374330181 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7350680693374330181 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-26 14:36:46.948 UTC [21835][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-26 14:36:46.948 UTC [21835][postmaster] LOG:  listening on Unix socket "/tmp/hnd0DRYYBl/.s.PGSQL.59528"
2024-03-26 14:36:46.949 UTC [21839][startup] LOG:  database system was shut down in recovery at 2024-03-26 14:36:46 UTC
2024-03-26 14:36:46.951 UTC [21839][startup] LOG:  entering standby mode
2024-03-26 14:36:46.952 UTC [21839][startup] LOG:  redo starts at 0/3004738
2024-03-26 14:36:46.952 UTC [21839][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-03-26 14:36:46.952 UTC [21835][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-26 14:36:46.952 UTC [21839][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-03-26 14:36:46.958 UTC [21841][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-26 14:36:47.041 UTC [21845][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:47.041 UTC [21845][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:47.041 UTC [21845][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:47.046 UTC [21845][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-26 14:36:47.047 UTC [21845][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-26 14:36:47.050 UTC [21845][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-03-26 14:36:47.054 UTC [21845][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.013 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: stopping the subscriber
2024-03-26 14:36:47.076 UTC [21835][postmaster] LOG:  received fast shutdown request
2024-03-26 14:36:47.076 UTC [21835][postmaster] LOG:  aborting any active transactions
2024-03-26 14:36:47.076 UTC [21841][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-26 14:36:47.084 UTC [21837][checkpointer] LOG:  shutting down
2024-03-26 14:36:47.101 UTC [21835][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: creating publication "pg_createsubscriber_16384_6ff71394" on database "pg1"
pg_createsubscriber: creating the replication slot "replslot1" on database "pg1"
pg_createsubscriber: create replication slot "replslot1" on publisher
pg_createsubscriber: starting the subscriber
2024-03-26 14:36:47.262 UTC [21854][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-26 14:36:47.262 UTC [21854][postmaster] LOG:  listening on Unix socket "/tmp/hnd0DRYYBl/.s.PGSQL.59528"
2024-03-26 14:36:47.266 UTC [21857][startup] LOG:  database system was shut down in recovery at 2024-03-26 14:36:47 UTC
2024-03-26 14:36:47.266 UTC [21857][startup] LOG:  entering standby mode
2024-03-26 14:36:47.267 UTC [21857][startup] LOG:  redo starts at 0/3004738
2024-03-26 14:36:47.267 UTC [21857][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-03-26 14:36:47.267 UTC [21854][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-26 14:36:47.267 UTC [21857][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-03-26 14:36:47.270 UTC [21860][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-03-26 14:36:47.384 UTC [21890][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:47.384 UTC [21890][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:47.384 UTC [21890][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:47.389 UTC [21890][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-26 14:36:47.389 UTC [21890][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
pg_createsubscriber: target server reached the consistent state
pg_createsubscriber: hint: If pg_createsubscriber fails after this point, you must recreate the physical replica before continuing.
2024-03-26 14:36:47.390 UTC [21890][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.006 user=postgres database=pg1 host=[local]
2024-03-26 14:36:47.391 UTC [21892][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:47.391 UTC [21892][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:47.391 UTC [21892][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:47.392 UTC [21892][client backend] [040_pg_createsubscriber.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16384_6ff71394" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_6ff71394" on database "pg1"
2024-03-26 14:36:47.392 UTC [21892][client backend] [040_pg_createsubscriber.pl][1/3:0] LOG:  statement: SELECT s.oid FROM pg_catalog.pg_subscription s INNER JOIN pg_catalog.pg_database d ON (s.subdbid = d.oid) WHERE s.subname = 'pg_createsubscriber_16384_6ff71394' AND d.datname = 'pg1'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_6ff71394" on database "pg1"
2024-03-26 14:36:47.395 UTC [21892][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.003 user=postgres database=pg1 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-26 14:36:47.418 UTC [21854][postmaster] LOG:  received fast shutdown request
2024-03-26 14:36:47.418 UTC [21854][postmaster] LOG:  aborting any active transactions
2024-03-26 14:36:47.419 UTC [21860][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-26 14:36:47.421 UTC [21855][checkpointer] LOG:  shutting down
2024-03-26 14:36:47.422 UTC [21854][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7350681081502766379 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: Done!
[14:36:47.935](1.285s) ok 26 - run pg_createsubscriber without --databases
# Running: pg_createsubscriber --verbose --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=59526 host=/tmp/hnd0DRYYBl dbname='pg1' --socket-directory /tmp/hnd0DRYYBl --subscriber-port 59528 --publication pub1 --publication Pub2 --replication-slot replslot1 --replication-slot replslot2 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: pg_ctl path is:  /tmp/cirrus-ci-build/build/tmp_install/usr/local/pgsql/bin/pg_ctl
pg_createsubscriber: pg_resetwal path is:  /tmp/cirrus-ci-build/build/tmp_install/usr/local/pgsql/bin/pg_resetwal
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: publisher(0): publication: pub1 ; replication slot: replslot1 ; connection string: host=/tmp/hnd0DRYYBl port=59526 dbname=pg1
pg_createsubscriber: subscriber(0): subscription: (auto) ; connection string: port=59528 host=/tmp/hnd0DRYYBl fallback_application_name=pg_createsubscriber dbname=pg1
pg_createsubscriber: publisher(1): publication: Pub2 ; replication slot: replslot2 ; connection string: host=/tmp/hnd0DRYYBl port=59526 dbname=pg2
pg_createsubscriber: subscriber(1): subscription: (auto) ; connection string: port=59528 host=/tmp/hnd0DRYYBl fallback_application_name=pg_createsubscriber dbname=pg2
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7350680693374330181 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7350680693374330181 on subscriber
pg_createsubscriber: starting the standby with command-line options
pg_createsubscriber: pg_ctl command is: "/tmp/cirrus-ci-build/build/tmp_install/usr/local/pgsql/bin/pg_ctl" start -D "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata" -s -o "-p 59528" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/hnd0DRYYBl'"
2024-03-26 14:36:48.111 UTC [22001][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-26 14:36:48.111 UTC [22001][postmaster] LOG:  listening on Unix socket "/tmp/hnd0DRYYBl/.s.PGSQL.59528"
2024-03-26 14:36:48.114 UTC [22008][startup] LOG:  database system was shut down in recovery at 2024-03-26 14:36:47 UTC
2024-03-26 14:36:48.114 UTC [22008][startup] LOG:  entering standby mode
2024-03-26 14:36:48.114 UTC [22008][startup] LOG:  redo starts at 0/3004738
2024-03-26 14:36:48.114 UTC [22008][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-03-26 14:36:48.114 UTC [22001][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-26 14:36:48.114 UTC [22008][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-26 14:36:48.116 UTC [22010][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-26 14:36:48.117 UTC [22010][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-26 14:36:48.117 UTC [22010][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-26 14:36:48.123 UTC [22010][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-26 14:36:48.123 UTC [22010][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-26 14:36:48.124 UTC [22010][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: subscriber: max_logical_replication_workers: 4
pg_createsubscriber: subscriber: max_replication_slots: 10
pg_createsubscriber: subscriber: max_worker_processes: 8
pg_createsubscriber: subscriber: primary_slot_name: physical_slot
pg_createsubscriber: checking settings on publisher
2024-03-26 14:36:48.136 UTC [22010][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.019 user=postgres database=pg1 host=[local]
pg_createsubscriber: publisher: wal_level: logical
pg_createsubscriber: publisher: max_replication_slots: 10
pg_createsubscriber: publisher: current replication slots: 1
pg_createsubscriber: publisher: max_wal_senders: 10
pg_createsubscriber: publisher: current wal senders: 0
pg_createsubscriber: command is: SELECT 1 FROM pg_catalog.pg_replication_slots WHERE active AND slot_name = 'physical_slot'
pg_createsubscriber: error: could not obtain replication slot information: got 0 rows, expected 1 row
pg_createsubscriber: pg_ctl command is: "/tmp/cirrus-ci-build/build/tmp_install/usr/local/pgsql/bin/pg_ctl" stop -D "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata" -s
2024-03-26 14:36:48.141 UTC [22001][postmaster] LOG:  received fast shutdown request
2024-03-26 14:36:48.141 UTC [22001][postmaster] LOG:  aborting any active transactions
2024-03-26 14:36:48.143 UTC [22009][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-26 14:36:48.144 UTC [22006][checkpointer] LOG:  shutting down
2024-03-26 14:36:48.145 UTC [22001][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[14:36:48.285](0.350s) not ok 27 - run pg_createsubscriber on node S
[14:36:48.286](0.001s) #   Failed test 'run pg_createsubscriber on node S'
#   at /tmp/cirrus-ci-build/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl line 297.
[14:36:48.299](0.012s) not ok 28 - the physical replication slot used as primary_slot_name has been removed
[14:36:48.300](0.001s) #   Failed test 'the physical replication slot used as primary_slot_name has been removed'
#   at /tmp/cirrus-ci-build/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl line 318.
[14:36:48.300](0.000s) #          got: '1'
#     expected: '0'
### Starting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_s.log -o --cluster-name=node_s start
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 22051
Waiting for all subscriptions in "node_s" to synchronize data
subscription name must be specified at /tmp/cirrus-ci-build/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl line 337.
# Postmaster PID for node "node_p" is 21566
### Stopping node "node_p" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "node_p"
# No postmaster PID for node "node_f"
# Postmaster PID for node "node_s" is 22051
### Stopping node "node_s" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata -m immediate stop
waiting for server to shut down.... done
server stopped
# No postmaster PID for node "node_s"
# No postmaster PID for node "node_t"
# No postmaster PID for node "node_c"
[14:36:48.758](0.458s) # Tests were run but no plan was declared and done_testing() was not seen.
[14:36:48.759](0.001s) # Looks like your test exited with 29 just after 28.