# Running: pg_createsubscriber --help
[13:47:41.153](0.041s) ok 1 - pg_createsubscriber --help exit code 0
[13:47:41.187](0.034s) ok 2 - pg_createsubscriber --help goes to stdout
[13:47:41.192](0.005s) ok 3 - pg_createsubscriber --help nothing to stderr
[13:47:41.201](0.009s) ok 4 - pg_createsubscriber --help maximum line length
# Running: pg_createsubscriber --version
[13:47:41.257](0.056s) ok 5 - pg_createsubscriber --version exit code 0
[13:47:41.271](0.014s) ok 6 - pg_createsubscriber --version goes to stdout
[13:47:41.278](0.007s) ok 7 - pg_createsubscriber --version nothing to stderr
# Running: pg_createsubscriber --not-a-valid-option
[13:47:41.363](0.085s) ok 8 - pg_createsubscriber with invalid option nonzero exit code
[13:47:41.365](0.002s) 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.
[13:47:41.417](0.052s) 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_mmmA
pg_createsubscriber: error: no publisher connection string specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[13:47:41.438](0.021s) 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_mmmA --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.
[13:47:41.487](0.049s) 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_mmmA --publisher-server port=5432 --database pg1 --database pg1
pg_createsubscriber: error: duplicate database "pg1"
[13:47:41.505](0.019s) ok 13 - duplicate database name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_mmmA --publisher-server port=5432 --publication foo1 --publication foo1 --database pg1 --database pg2
pg_createsubscriber: error: duplicate publication "foo1"
[13:47:41.556](0.050s) ok 14 - duplicate publication name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_mmmA --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).
[13:47:41.577](0.021s) 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_mmmA --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).
[13:47:41.613](0.036s) 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_mmmA --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).
[13:47:41.633](0.020s) ok 17 - wrong number of replication slot names
# Checking port 53635
# Found port 53635
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=53635 host=/tmp/CmKMYdEyv6
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_p.log
[13:47:41.638](0.005s) # 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 20798
# Checking port 53636
# Found port 53636
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=53636 host=/tmp/CmKMYdEyv6
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_f.log
[13:47:41.858](0.220s) # 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/CmKMYdEyv6 -p 53635 --checkpoint fast --no-sync
# Backup finished
# Checking port 53637
# Found port 53637
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=53637 host=/tmp/CmKMYdEyv6
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 21061
# Checking port 53638
# Found port 53638
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=53638 host=/tmp/CmKMYdEyv6
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 21093
### 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=53635 host=/tmp/CmKMYdEyv6 dbname='pg1' --socket-directory /tmp/CmKMYdEyv6 --subscriber-port 53638 --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 7351039100239992143 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351039100239992143 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 13:47:44.787 UTC [21150][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-27 13:47:44.787 UTC [21150][postmaster] LOG:  listening on Unix socket "/tmp/CmKMYdEyv6/.s.PGSQL.53638"
2024-03-27 13:47:44.794 UTC [21154][startup] LOG:  database system was shut down at 2024-03-27 13:47:44 UTC
2024-03-27 13:47:44.797 UTC [21150][postmaster] LOG:  database system is ready to accept connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-27 13:47:44.890 UTC [21173][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:44.890 UTC [21173][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-27 13:47:44.890 UTC [21173][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:44.895 UTC [21173][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 13:47:44.895 UTC [21173][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-27 13:47:44.896 UTC [21173][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.006 user=postgres database=pg1 host=[local]
2024-03-27 13:47:44.898 UTC [21150][postmaster] LOG:  received fast shutdown request
2024-03-27 13:47:44.898 UTC [21150][postmaster] LOG:  aborting any active transactions
2024-03-27 13:47:44.901 UTC [21150][postmaster] LOG:  background worker "logical replication launcher" (PID 21160) exited with exit code 1
2024-03-27 13:47:44.901 UTC [21152][checkpointer] LOG:  shutting down
2024-03-27 13:47:44.901 UTC [21152][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-03-27 13:47:44.901 UTC [21152][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.001 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-27 13:47:44.909 UTC [21150][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[13:47:45.051](3.193s) 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=53635 host=/tmp/CmKMYdEyv6 dbname='pg1' --socket-directory /tmp/CmKMYdEyv6 --subscriber-port 53637 --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 7351039100239992143 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351039100239992143 on subscriber
pg_createsubscriber: error: standby is up and running
pg_createsubscriber: hint: Stop the standby and try again.
[13:47:45.066](0.015s) 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=53635 host=/tmp/CmKMYdEyv6 dbname='pg1' --socket-directory /tmp/CmKMYdEyv6 --subscriber-port 53636 --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 7351039100239992143 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351039515459776859 on subscriber
pg_createsubscriber: error: subscriber data directory is not a copy of the source database cluster
[13:47:45.081](0.015s) 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/CmKMYdEyv6 -p 53637 --checkpoint fast --no-sync
# Backup finished
# Checking port 53639
# Found port 53639
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=53639 host=/tmp/CmKMYdEyv6
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=53637 host=/tmp/CmKMYdEyv6 dbname='pg1' --socket-directory /tmp/CmKMYdEyv6 --subscriber-port 53639 --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 7351039100239992143 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351039100239992143 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 13:47:45.491 UTC [21288][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-27 13:47:45.492 UTC [21288][postmaster] LOG:  listening on Unix socket "/tmp/CmKMYdEyv6/.s.PGSQL.53639"
2024-03-27 13:47:45.510 UTC [21291][startup] LOG:  database system was interrupted while in recovery at log time 2024-03-27 13:47:43 UTC
2024-03-27 13:47:45.510 UTC [21291][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-27 13:47:45.511 UTC [21291][startup] LOG:  starting backup recovery with redo LSN 0/2000028, checkpoint LSN 0/2000080, on timeline ID 1
2024-03-27 13:47:45.511 UTC [21291][startup] LOG:  entering standby mode
2024-03-27 13:47:45.513 UTC [21291][startup] LOG:  redo starts at 0/2000028
2024-03-27 13:47:45.513 UTC [21291][startup] LOG:  completed backup recovery with redo LSN 0/2000028 and end LSN 0/2000120
2024-03-27 13:47:45.513 UTC [21291][startup] LOG:  consistent recovery state reached at 0/3000000
2024-03-27 13:47:45.513 UTC [21288][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 13:47:45.523 UTC [21293][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-27 13:47:45.591 UTC [21306][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:45.591 UTC [21306][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-27 13:47:45.591 UTC [21306][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:45.597 UTC [21306][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 13:47:45.597 UTC [21306][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:45.597 UTC [21306][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-27 13:47:45.601 UTC [21306][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-27 13:47:45.606 UTC [21288][postmaster] LOG:  received fast shutdown request
2024-03-27 13:47:45.606 UTC [21288][postmaster] LOG:  aborting any active transactions
2024-03-27 13:47:45.608 UTC [21293][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 13:47:45.609 UTC [21289][checkpointer] LOG:  shutting down
2024-03-27 13:47:45.611 UTC [21288][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[13:47:45.782](0.701s) 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 21366
### 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=53635 host=/tmp/CmKMYdEyv6 dbname='pg1' --socket-directory /tmp/CmKMYdEyv6 --subscriber-port 53637 --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 7351039100239992143 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351039100239992143 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 13:47:46.240 UTC [21416][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-27 13:47:46.240 UTC [21416][postmaster] LOG:  listening on Unix socket "/tmp/CmKMYdEyv6/.s.PGSQL.53637"
2024-03-27 13:47:46.242 UTC [21419][startup] LOG:  database system was shut down in recovery at 2024-03-27 13:47:46 UTC
2024-03-27 13:47:46.242 UTC [21419][startup] LOG:  entering standby mode
2024-03-27 13:47:46.262 UTC [21419][startup] LOG:  consistent recovery state reached at 0/3000188
2024-03-27 13:47:46.262 UTC [21419][startup] LOG:  invalid record length at 0/3000188: expected at least 24, got 0
2024-03-27 13:47:46.262 UTC [21416][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 13:47:46.274 UTC [21423][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-27 13:47:46.274 UTC [21419][startup] LOG:  redo starts at 0/3000188
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-27 13:47:46.335 UTC [21429][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:46.342 UTC [21429][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-27 13:47:46.342 UTC [21429][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:46.348 UTC [21429][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 13:47:46.349 UTC [21429][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:46.356 UTC [21429][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-27 13:47:46.361 UTC [21429][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.025 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-27 13:47:46.381 UTC [21416][postmaster] LOG:  received fast shutdown request
2024-03-27 13:47:46.381 UTC [21416][postmaster] LOG:  aborting any active transactions
2024-03-27 13:47:46.381 UTC [21423][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 13:47:46.390 UTC [21417][checkpointer] LOG:  shutting down
2024-03-27 13:47:46.394 UTC [21416][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[13:47:46.516](0.733s) 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=53635 host=/tmp/CmKMYdEyv6 dbname='pg1' --socket-directory /tmp/CmKMYdEyv6 --subscriber-port 53637 --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 7351039100239992143 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351039100239992143 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 13:47:46.607 UTC [21486][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-27 13:47:46.607 UTC [21486][postmaster] LOG:  listening on Unix socket "/tmp/CmKMYdEyv6/.s.PGSQL.53637"
2024-03-27 13:47:46.611 UTC [21491][startup] LOG:  database system was shut down in recovery at 2024-03-27 13:47:46 UTC
2024-03-27 13:47:46.612 UTC [21491][startup] LOG:  entering standby mode
2024-03-27 13:47:46.621 UTC [21491][startup] LOG:  redo starts at 0/3000188
2024-03-27 13:47:46.621 UTC [21491][startup] LOG:  invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3004000, offset 16384
2024-03-27 13:47:46.621 UTC [21491][startup] LOG:  consistent recovery state reached at 0/3002758
2024-03-27 13:47:46.621 UTC [21486][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 13:47:46.621 UTC [21491][startup] LOG:  invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3004000, offset 16384
2024-03-27 13:47:46.626 UTC [21493][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-27 13:47:46.700 UTC [21498][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:46.701 UTC [21498][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-27 13:47:46.701 UTC [21498][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:46.706 UTC [21498][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 13:47:46.707 UTC [21498][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:46.712 UTC [21498][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-27 13:47:46.723 UTC [21498][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.022 user=postgres database=pg1 host=[local]
2024-03-27 13:47:46.724 UTC [21486][postmaster] LOG:  received fast shutdown request
2024-03-27 13:47:46.724 UTC [21486][postmaster] LOG:  aborting any active transactions
2024-03-27 13:47:46.725 UTC [21493][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 13:47:46.726 UTC [21489][checkpointer] LOG:  shutting down
2024-03-27 13:47:46.742 UTC [21486][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[13:47:46.861](0.346s) 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 21530
# 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=53635 host=/tmp/CmKMYdEyv6 dbname='pg1' --socket-directory /tmp/CmKMYdEyv6 --subscriber-port 53637 --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 7351039100239992143 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351039100239992143 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 13:47:47.193 UTC [21566][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-27 13:47:47.193 UTC [21566][postmaster] LOG:  listening on Unix socket "/tmp/CmKMYdEyv6/.s.PGSQL.53637"
2024-03-27 13:47:47.213 UTC [21571][startup] LOG:  database system was shut down in recovery at 2024-03-27 13:47:46 UTC
2024-03-27 13:47:47.213 UTC [21571][startup] LOG:  entering standby mode
2024-03-27 13:47:47.221 UTC [21571][startup] LOG:  redo starts at 0/3000188
2024-03-27 13:47:47.221 UTC [21571][startup] LOG:  consistent recovery state reached at 0/30046C0
2024-03-27 13:47:47.221 UTC [21566][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 13:47:47.222 UTC [21571][startup] LOG:  invalid record length at 0/30046C0: expected at least 24, got 0
2024-03-27 13:47:47.231 UTC [21573][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-27 13:47:47.289 UTC [21580][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:47.289 UTC [21580][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-27 13:47:47.289 UTC [21580][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:47.296 UTC [21580][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 13:47:47.297 UTC [21580][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:47.298 UTC [21580][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-27 13:47:47.301 UTC [21580][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-27 13:47:47.321 UTC [21566][postmaster] LOG:  received fast shutdown request
2024-03-27 13:47:47.321 UTC [21566][postmaster] LOG:  aborting any active transactions
2024-03-27 13:47:47.324 UTC [21573][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 13:47:47.325 UTC [21569][checkpointer] LOG:  shutting down
2024-03-27 13:47:47.325 UTC [21569][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-27 13:47:47.326 UTC [21569][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.001 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-27 13:47:47.326 UTC [21569][checkpointer] LOG:  recovery restart point at 0/30046C0
2024-03-27 13:47:47.360 UTC [21566][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-27 13:47:47.493 UTC [21614][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-27 13:47:47.493 UTC [21614][postmaster] LOG:  listening on Unix socket "/tmp/CmKMYdEyv6/.s.PGSQL.53637"
2024-03-27 13:47:47.503 UTC [21617][startup] LOG:  database system was shut down in recovery at 2024-03-27 13:47:47 UTC
2024-03-27 13:47:47.503 UTC [21617][startup] LOG:  entering standby mode
2024-03-27 13:47:47.515 UTC [21617][startup] LOG:  redo starts at 0/3004738
2024-03-27 13:47:47.515 UTC [21617][startup] LOG:  consistent recovery state reached at 0/3004770
2024-03-27 13:47:47.515 UTC [21614][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 13:47:47.515 UTC [21617][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-03-27 13:47:47.520 UTC [21620][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-27 13:47:47.590 UTC [21627][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:47.591 UTC [21627][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-27 13:47:47.591 UTC [21627][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:47.596 UTC [21627][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 13:47:47.597 UTC [21627][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-27 13:47:47.597 UTC [21627][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.007 user=postgres database=pg1 host=[local]
2024-03-27 13:47:47.599 UTC [21628][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:47.600 UTC [21628][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-27 13:47:47.600 UTC [21628][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:47.600 UTC [21628][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-27 13:47:47.601 UTC [21628][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-27 13:47:47.605 UTC [21628][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.006 user=postgres database=pg1 host=[local]
2024-03-27 13:47:47.607 UTC [21629][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:47.608 UTC [21629][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-27 13:47:47.608 UTC [21629][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:47.615 UTC [21629][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-27 13:47:47.615 UTC [21629][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"
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-27 13:47:47.628 UTC [21629][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.020 user=postgres database=pg2 host=[local]
2024-03-27 13:47:47.629 UTC [21614][postmaster] LOG:  received fast shutdown request
2024-03-27 13:47:47.629 UTC [21614][postmaster] LOG:  aborting any active transactions
2024-03-27 13:47:47.631 UTC [21620][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 13:47:47.632 UTC [21615][checkpointer] LOG:  shutting down
2024-03-27 13:47:47.636 UTC [21614][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7351039540316423214 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: Done!
[13:47:47.830](0.969s) 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 21679
[13:47:48.151](0.321s) 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=53635 host=/tmp/CmKMYdEyv6 dbname='pg1' --socket-directory /tmp/CmKMYdEyv6 --subscriber-port 53637 --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 7351039100239992143 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351039100239992143 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 13:47:48.464 UTC [21729][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-27 13:47:48.464 UTC [21729][postmaster] LOG:  listening on Unix socket "/tmp/CmKMYdEyv6/.s.PGSQL.53637"
2024-03-27 13:47:48.509 UTC [21733][startup] LOG:  database system was shut down in recovery at 2024-03-27 13:47:48 UTC
2024-03-27 13:47:48.509 UTC [21733][startup] LOG:  entering standby mode
2024-03-27 13:47:48.516 UTC [21733][startup] LOG:  redo starts at 0/3004738
2024-03-27 13:47:48.517 UTC [21733][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-03-27 13:47:48.517 UTC [21729][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber:2024-03-27 13:47:48.554 UTC [21733][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
 server was started
pg_createsubscriber: checking settings on subscriber
2024-03-27 13:47:48.581 UTC [21741][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:48.581 UTC [21741][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-27 13:47:48.581 UTC [21741][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:48.587 UTC [21741][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 13:47:48.588 UTC [21741][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:48.588 UTC [21741][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
2024-03-27 13:47:48.593 UTC [21741][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.012 user=postgres database=pg1 host=[local]
pg_createsubscriber: checking settings on publisher
pg_createsubscriber: error: could not obtain replication slot information: got 0 rows, expected 1 row
2024-03-27 13:47:48.620 UTC [21737][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-27 13:47:48.622 UTC [21729][postmaster] LOG:  received fast shutdown request
2024-03-27 13:47:48.622 UTC [21729][postmaster] LOG:  aborting any active transactions
2024-03-27 13:47:48.623 UTC [21737][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 13:47:48.625 UTC [21730][checkpointer] LOG:  shutting down
2024-03-27 13:47:48.633 UTC [21729][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[13:47:48.964](0.812s) not ok 26 - run pg_createsubscriber without --databases
[13:47:48.965](0.001s) #   Failed test 'run pg_createsubscriber without --databases'
#   at /tmp/cirrus-ci-build/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl line 284.
# 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=53635 host=/tmp/CmKMYdEyv6 dbname='pg1' --socket-directory /tmp/CmKMYdEyv6 --subscriber-port 53637 --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/CmKMYdEyv6 port=53635 dbname=pg1
pg_createsubscriber: subscriber(0): subscription: (auto) ; connection string: port=53637 host=/tmp/CmKMYdEyv6 fallback_application_name=pg_createsubscriber dbname=pg1
pg_createsubscriber: publisher(1): publication: Pub2 ; replication slot: replslot2 ; connection string: host=/tmp/CmKMYdEyv6 port=53635 dbname=pg2
pg_createsubscriber: subscriber(1): subscription: (auto) ; connection string: port=53637 host=/tmp/CmKMYdEyv6 fallback_application_name=pg_createsubscriber dbname=pg2
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7351039100239992143 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351039100239992143 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 53637" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/CmKMYdEyv6'"
2024-03-27 13:47:49.064 UTC [21769][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-27 13:47:49.064 UTC [21769][postmaster] LOG:  listening on Unix socket "/tmp/CmKMYdEyv6/.s.PGSQL.53637"
2024-03-27 13:47:49.076 UTC [21774][startup] LOG:  database system was shut down in recovery at 2024-03-27 13:47:48 UTC
2024-03-27 13:47:49.077 UTC [21774][startup] LOG:  entering standby mode
2024-03-27 13:47:49.095 UTC [21774][startup] LOG:  redo starts at 0/3004738
2024-03-27 13:47:49.095 UTC [21774][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-03-27 13:47:49.095 UTC [21769][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 13:47:49.097 UTC [21774][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-03-27 13:47:49.108 UTC [21777][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-27 13:47:49.147 UTC [21779][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:49.148 UTC [21779][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-27 13:47:49.148 UTC [21779][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:49.154 UTC [21779][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 13:47:49.157 UTC [21779][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:49.158 UTC [21779][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-27 13:47:49.161 UTC [21779][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.013 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: 1
pg_createsubscriber: command is: SELECT 1 FROM pg_catalog.pg_replication_slots WHERE active AND slot_name = 'physical_slot'
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: stopping the subscriber
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-27 13:47:49.189 UTC [21769][postmaster] LOG:  received fast shutdown request
2024-03-27 13:47:49.189 UTC [21769][postmaster] LOG:  aborting any active transactions
2024-03-27 13:47:49.190 UTC [21777][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 13:47:49.195 UTC [21772][checkpointer] LOG:  shutting down
2024-03-27 13:47:49.221 UTC [21769][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: creating publication "pub1" on database "pg1"
pg_createsubscriber: command is: CREATE PUBLICATION "pub1" FOR ALL TABLES
pg_createsubscriber: creating the replication slot "replslot1" on database "pg1"
pg_createsubscriber: command is: SELECT lsn FROM pg_catalog.pg_create_logical_replication_slot('replslot1', 'pgoutput', false, false, false)
pg_createsubscriber: create replication slot "replslot1" on publisher
pg_createsubscriber: creating publication "Pub2" on database "pg2"
pg_createsubscriber: command is: CREATE PUBLICATION "Pub2" FOR ALL TABLES
pg_createsubscriber: creating the replication slot "replslot2" on database "pg2"
pg_createsubscriber: command is: SELECT lsn FROM pg_catalog.pg_create_logical_replication_slot('replslot2', 'pgoutput', false, false, false)
pg_createsubscriber: create replication slot "replslot2" on publisher
pg_createsubscriber: recovery parameters:
primary_conninfo = 'user=postgres passfile=''/home/postgres/.pgpass'' channel_binding=prefer host=''/tmp/CmKMYdEyv6'' port=53635 application_name=040_pg_createsubscriber.pl sslmode=prefer sslcompression=0 sslcertmode=allow sslsni=1 ssl_min_protocol_version=TLSv1.2 gssencmode=prefer krbsrvname=postgres gssdelegation=0 target_session_attrs=any load_balance_hosts=disable'
recovery_target = ''
recovery_target_timeline = 'latest'
recovery_target_inclusive = true
recovery_target_action = promote
recovery_target_name = ''
recovery_target_time = ''
recovery_target_xid = ''
recovery_target_lsn = '0/30092C0'
pg_createsubscriber: starting the subscriber
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 53637" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/CmKMYdEyv6'"
2024-03-27 13:47:49.444 UTC [21797][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-27 13:47:49.444 UTC [21797][postmaster] LOG:  listening on Unix socket "/tmp/CmKMYdEyv6/.s.PGSQL.53637"
2024-03-27 13:47:49.471 UTC [21801][startup] LOG:  database system was shut down in recovery at 2024-03-27 13:47:49 UTC
2024-03-27 13:47:49.471 UTC [21801][startup] LOG:  entering standby mode
2024-03-27 13:47:49.478 UTC [21801][startup] LOG:  redo starts at 0/3004738
2024-03-27 13:47:49.478 UTC [21801][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-03-27 13:47:49.478 UTC [21797][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 13:47:49.479 UTC [21801][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-03-27 13:47:49.492 UTC [21802][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-27 13:47:49.541 UTC [21804][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:47:49.541 UTC [21804][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-27 13:47:49.541 UTC [21804][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:47:49.548 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 13:47:49.548 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:49.549 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:50.560 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/5:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:50.560 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/6:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:51.575 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/7:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:51.575 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/8:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:52.586 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/9:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:52.587 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/10:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:53.591 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/11:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:53.591 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/12:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:54.600 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/13:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:54.600 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/14:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:55.610 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/15:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:55.610 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/16:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:56.624 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/17:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:56.625 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/18:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:57.630 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/19:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:57.630 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/20:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:58.640 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/21:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:58.640 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/22:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:47:59.650 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/23:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:47:59.650 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/24:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:48:00.664 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/25:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:48:00.664 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/26:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:48:01.672 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/27:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 13:48:01.672 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/28:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 13:48:02.022 UTC [21801][startup] LOG:  recovery stopping after WAL location (LSN) "0/30092C0"
2024-03-27 13:48:02.022 UTC [21801][startup] LOG:  redo done at 0/30092C0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 12.54 s
2024-03-27 13:48:02.022 UTC [21801][startup] LOG:  last completed transaction was at log time 2024-03-27 13:47:49.406945+00
2024-03-27 13:48:02.022 UTC [21802][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 13:48:02.022 UTC [21801][startup] LOG:  selected new timeline ID: 2
2024-03-27 13:48:02.030 UTC [21801][startup] LOG:  archive recovery complete
2024-03-27 13:48:02.031 UTC [21799][checkpointer] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-03-27 13:48:02.031 UTC [21799][checkpointer] LOG:  checkpoint complete: wrote 16 buffers (12.5%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=19 kB, estimate=19 kB; lsn=0/30092F8, redo lsn=0/30092F8
2024-03-27 13:48:02.034 UTC [21797][postmaster] LOG:  database system is ready to accept connections
2024-03-27 13:48:02.687 UTC [21804][client backend] [040_pg_createsubscriber.pl][0/29: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-27 13:48:02.688 UTC [21804][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:13.147 user=postgres database=pg1 host=[local]
2024-03-27 13:48:02.688 UTC [23504][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:48:02.689 UTC [23504][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-27 13:48:02.689 UTC [23504][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 13:48:02.689 UTC [23504][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: command is: DROP PUBLICATION "pub1"
2024-03-27 13:48:02.690 UTC [23504][client backend] [040_pg_createsubscriber.pl][1/3:0] LOG:  statement: DROP PUBLICATION "pub1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_5d0bb22b" on database "pg1"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16384_5d0bb22b" CONNECTION 'host=/tmp/CmKMYdEyv6 port=53635 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-03-27 13:48:02.691 UTC [23504][client backend] [040_pg_createsubscriber.pl][1/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16384_5d0bb22b" CONNECTION 'host=/tmp/CmKMYdEyv6 port=53635 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-03-27 13:48:02.691 UTC [23504][client backend] [040_pg_createsubscriber.pl][1/4:0] WARNING:  subscriptions created by regression test cases should have names starting with "regress_"
WARNING:  subscriptions created by regression test cases should have names starting with "regress_"
2024-03-27 13:48:02.703 UTC [23504][client backend] [040_pg_createsubscriber.pl][1/5: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_5d0bb22b' AND d.datname = 'pg1'
pg_createsubscriber: setting the replication progress (node name "pg_24588" ; LSN 0/30092C0) on database "pg1"
pg_createsubscriber: command is: SELECT pg_catalog.pg_replication_origin_advance('pg_24588', '0/30092C0')
2024-03-27 13:48:02.706 UTC [23504][client backend] [040_pg_createsubscriber.pl][1/6:0] LOG:  statement: SELECT pg_catalog.pg_replication_origin_advance('pg_24588', '0/30092C0')
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_5d0bb22b" on database "pg1"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16384_5d0bb22b" ENABLE
2024-03-27 13:48:02.706 UTC [23504][client backend] [040_pg_createsubscriber.pl][1/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16384_5d0bb22b" ENABLE
2024-03-27 13:48:02.707 UTC [23504][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.018 user=postgres database=pg1 host=[local]
2024-03-27 13:48:02.707 UTC [23509][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 13:48:02.708 UTC [23509][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-27 13:48:02.708 UTC [23509][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=040_pg_createsubscriber.pl
2024-03-27 13:48:02.712 UTC [23510][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16384_5d0bb22b" has started
2024-03-27 13:48:02.713 UTC [23509][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: command is: DROP PUBLICATION "Pub2"
2024-03-27 13:48:02.713 UTC [23509][client backend] [040_pg_createsubscriber.pl][2/3:0] LOG:  statement: DROP PUBLICATION "Pub2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_5f3e886c" on database "pg2"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16385_5f3e886c" CONNECTION 'host=/tmp/CmKMYdEyv6 port=53635 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-03-27 13:48:02.714 UTC [23509][client backend] [040_pg_createsubscriber.pl][2/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16385_5f3e886c" CONNECTION 'host=/tmp/CmKMYdEyv6 port=53635 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-03-27 13:48:02.714 UTC [23509][client backend] [040_pg_createsubscriber.pl][2/4:0] WARNING:  subscriptions created by regression test cases should have names starting with "regress_"
WARNING:  subscriptions created by regression test cases should have names starting with "regress_"
2024-03-27 13:48:02.729 UTC [23509][client backend] [040_pg_createsubscriber.pl][2/5: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_16385_5f3e886c' AND d.datname = 'pg2'
pg_createsubscriber: setting the replication progress (node name "pg_24589" ; LSN 0/30092C0) on database "pg2"
pg_createsubscriber: command is: SELECT pg_catalog.pg_replication_origin_advance('pg_24589', '0/30092C0')
2024-03-27 13:48:02.732 UTC [23509][client backend] [040_pg_createsubscriber.pl][2/6:0] LOG:  statement: SELECT pg_catalog.pg_replication_origin_advance('pg_24589', '0/30092C0')
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_5f3e886c" on database "pg2"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16385_5f3e886c" ENABLE
2024-03-27 13:48:02.732 UTC [23509][client backend] [040_pg_createsubscriber.pl][2/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16385_5f3e886c" ENABLE
2024-03-27 13:48:02.732 UTC [23509][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.025 user=postgres database=pg2 host=[local]
2024-03-27 13:48:02.738 UTC [23514][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16385_5f3e886c" has started
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: command is: SELECT pg_catalog.pg_drop_replication_slot('physical_slot')
pg_createsubscriber: stopping the subscriber
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-27 13:48:02.744 UTC [21797][postmaster] LOG:  received fast shutdown request
2024-03-27 13:48:02.744 UTC [21797][postmaster] LOG:  aborting any active transactions
2024-03-27 13:48:02.744 UTC [23514][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-03-27 13:48:02.744 UTC [23510][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-03-27 13:48:02.748 UTC [21797][postmaster] LOG:  background worker "logical replication apply worker" (PID 23514) exited with exit code 1
2024-03-27 13:48:02.748 UTC [21797][postmaster] LOG:  background worker "logical replication apply worker" (PID 23510) exited with exit code 1
2024-03-27 13:48:02.748 UTC [21797][postmaster] LOG:  background worker "logical replication launcher" (PID 23381) exited with exit code 1
2024-03-27 13:48:02.748 UTC [21799][checkpointer] LOG:  shutting down
2024-03-27 13:48:02.748 UTC [21799][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-03-27 13:48:02.748 UTC [21799][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.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=14 kB, estimate=18 kB; lsn=0/300CC50, redo lsn=0/300CC50
2024-03-27 13:48:02.750 UTC [21797][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7351039605210920193 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: pg_resetwal command is: "/tmp/cirrus-ci-build/build/tmp_install/usr/local/pgsql/bin/pg_resetwal" -D "/tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_s_data/pgdata" > "/dev/null"
pg_createsubscriber: subscriber successfully changed the system identifier
pg_createsubscriber: Done!
[13:48:02.940](13.975s) ok 27 - run pg_createsubscriber on node S
[13:48:02.952](0.012s) ok 28 - the physical replication slot used as primary_slot_name has been removed
### 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 23562
Waiting for all subscriptions in "node_s" to synchronize data
Waiting for replication conn pg_createsubscriber_16384_5d0bb22b's replay_lsn to pass 0/3009480 on node_p
done
done
Waiting for all subscriptions in "node_s" to synchronize data
Waiting for replication conn pg_createsubscriber_16385_5f3e886c's replay_lsn to pass 0/3009480 on node_p
done
done
[13:48:03.322](0.371s) ok 29 - logical replication works on database pg1
[13:48:03.337](0.014s) ok 30 - logical replication works on database pg2
[13:48:03.362](0.026s) ok 31 - system identifier was changed
### 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"
### 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"
[13:48:03.579](0.216s) 1..31
[13:48:03.587](0.008s) # Looks like you failed 1 test of 31.