# Running: pg_createsubscriber --help
[04:05:43.365](0.027s) ok 1 - pg_createsubscriber --help exit code 0
[04:05:43.366](0.000s) ok 2 - pg_createsubscriber --help goes to stdout
[04:05:43.366](0.000s) ok 3 - pg_createsubscriber --help nothing to stderr
[04:05:43.366](0.000s) ok 4 - pg_createsubscriber --help maximum line length
# Running: pg_createsubscriber --version
[04:05:43.373](0.007s) ok 5 - pg_createsubscriber --version exit code 0
[04:05:43.374](0.001s) ok 6 - pg_createsubscriber --version goes to stdout
[04:05:43.375](0.001s) ok 7 - pg_createsubscriber --version nothing to stderr
# Running: pg_createsubscriber --not-a-valid-option
[04:05:43.383](0.008s) ok 8 - pg_createsubscriber with invalid option nonzero exit code
[04:05:43.383](0.000s) 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.
[04:05:43.394](0.011s) 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_nREV
pg_createsubscriber: error: no publisher connection string specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[04:05:43.419](0.026s) 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_nREV --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.
[04:05:43.471](0.051s) 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_nREV --publisher-server port=5432 --database pg1 --database pg1
pg_createsubscriber: error: duplicate database "pg1"
[04:05:43.501](0.030s) ok 13 - duplicate database name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_nREV --publisher-server port=5432 --publication foo1 --publication foo1 --database pg1 --database pg2
pg_createsubscriber: error: duplicate publication "foo1"
[04:05:43.521](0.020s) ok 14 - duplicate publication name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_nREV --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).
[04:05:43.549](0.028s) 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_nREV --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).
[04:05:43.581](0.032s) 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_nREV --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).
[04:05:43.632](0.051s) ok 17 - wrong number of replication slot names
# Checking port 57707
# Found port 57707
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=57707 host=/tmp/QCvKEwcamq
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_p.log
[04:05:43.659](0.027s) # 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 20687
# Checking port 57708
# Found port 57708
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=57708 host=/tmp/QCvKEwcamq
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_f.log
[04:05:43.900](0.241s) # 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/QCvKEwcamq -p 57707 --checkpoint fast --no-sync
# Backup finished
# Checking port 57709
# Found port 57709
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=57709 host=/tmp/QCvKEwcamq
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 20983
# Checking port 57710
# Found port 57710
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=57710 host=/tmp/QCvKEwcamq
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 21023
### 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=57707 host=/tmp/QCvKEwcamq dbname='pg1' --socket-directory /tmp/QCvKEwcamq --subscriber-port 57710 --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 7349033773678470472 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7349033773678470472 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-22 04:05:47.031 UTC [21114][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-22 04:05:47.031 UTC [21114][postmaster] LOG:  listening on Unix socket "/tmp/QCvKEwcamq/.s.PGSQL.57710"
2024-03-22 04:05:47.039 UTC [21122][startup] LOG:  database system was shut down at 2024-03-22 04:05:46 UTC
2024-03-22 04:05:47.042 UTC [21114][postmaster] LOG:  database system is ready to accept connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-22 04:05:47.124 UTC [21138][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:47.129 UTC [21138][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-22 04:05:47.129 UTC [21138][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:47.137 UTC [21138][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-22 04:05:47.141 UTC [21138][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-22 04:05:47.141 UTC [21138][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.017 user=postgres database=pg1 host=[local]
2024-03-22 04:05:47.144 UTC [21114][postmaster] LOG:  received fast shutdown request
2024-03-22 04:05:47.144 UTC [21114][postmaster] LOG:  aborting any active transactions
2024-03-22 04:05:47.146 UTC [21114][postmaster] LOG:  background worker "logical replication launcher" (PID 21127) exited with exit code 1
2024-03-22 04:05:47.146 UTC [21120][checkpointer] LOG:  shutting down
2024-03-22 04:05:47.146 UTC [21120][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-03-22 04:05:47.147 UTC [21120][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/30046B0, redo lsn=0/30046B0
2024-03-22 04:05:47.157 UTC [21114][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[04:05:47.329](3.429s) 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=57707 host=/tmp/QCvKEwcamq dbname='pg1' --socket-directory /tmp/QCvKEwcamq --subscriber-port 57709 --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 7349033773678470472 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7349033773678470472 on subscriber
pg_createsubscriber: error: standby is up and running
pg_createsubscriber: hint: Stop the standby and try again.
[04:05:47.346](0.017s) 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=57707 host=/tmp/QCvKEwcamq dbname='pg1' --socket-directory /tmp/QCvKEwcamq --subscriber-port 57708 --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 7349033773678470472 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7349034118525825275 on subscriber
pg_createsubscriber: error: subscriber data directory is not a copy of the source database cluster
[04:05:47.361](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/QCvKEwcamq -p 57709 --checkpoint fast --no-sync
# Backup finished
# Checking port 57711
# Found port 57711
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=57711 host=/tmp/QCvKEwcamq
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=57709 host=/tmp/QCvKEwcamq dbname='pg1' --socket-directory /tmp/QCvKEwcamq --subscriber-port 57711 --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 7349033773678470472 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7349033773678470472 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-22 04:05:47.765 UTC [21240][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-22 04:05:47.765 UTC [21240][postmaster] LOG:  listening on Unix socket "/tmp/QCvKEwcamq/.s.PGSQL.57711"
2024-03-22 04:05:47.773 UTC [21245][startup] LOG:  database system was interrupted while in recovery at log time 2024-03-22 04:05:45 UTC
2024-03-22 04:05:47.773 UTC [21245][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-22 04:05:47.773 UTC [21245][startup] LOG:  starting backup recovery with redo LSN 0/2000028, checkpoint LSN 0/2000080, on timeline ID 1
2024-03-22 04:05:47.773 UTC [21245][startup] LOG:  entering standby mode
2024-03-22 04:05:47.774 UTC [21245][startup] LOG:  redo starts at 0/2000028
2024-03-22 04:05:47.774 UTC [21245][startup] LOG:  completed backup recovery with redo LSN 0/2000028 and end LSN 0/2000120
2024-03-22 04:05:47.774 UTC [21245][startup] LOG:  consistent recovery state reached at 0/3000000
2024-03-22 04:05:47.774 UTC [21240][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-22 04:05:47.780 UTC [21246][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-22 04:05:47.862 UTC [21268][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:47.862 UTC [21268][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-22 04:05:47.862 UTC [21268][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:47.867 UTC [21268][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-22 04:05:47.868 UTC [21268][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:47.868 UTC [21268][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-22 04:05:47.875 UTC [21268][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.013 user=postgres database=pg1 host=[local]
pg_createsubscriber: error: primary server cannot be in recovery
2024-03-22 04:05:47.883 UTC [21240][postmaster] LOG:  received fast shutdown request
2024-03-22 04:05:47.883 UTC [21240][postmaster] LOG:  aborting any active transactions
2024-03-22 04:05:47.884 UTC [21246][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-22 04:05:47.885 UTC [21243][checkpointer] LOG:  shutting down
2024-03-22 04:05:47.889 UTC [21240][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[04:05:48.062](0.702s) 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 21333
### 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=57707 host=/tmp/QCvKEwcamq dbname='pg1' --socket-directory /tmp/QCvKEwcamq --subscriber-port 57709 --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 7349033773678470472 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7349033773678470472 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-22 04:05:48.531 UTC [21383][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-22 04:05:48.531 UTC [21383][postmaster] LOG:  listening on Unix socket "/tmp/QCvKEwcamq/.s.PGSQL.57709"
2024-03-22 04:05:48.535 UTC [21388][startup] LOG:  database system was shut down in recovery at 2024-03-22 04:05:48 UTC
2024-03-22 04:05:48.535 UTC [21388][startup] LOG:  entering standby mode
2024-03-22 04:05:48.545 UTC [21388][startup] LOG:  consistent recovery state reached at 0/3000188
2024-03-22 04:05:48.545 UTC [21383][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-22 04:05:48.555 UTC [21388][startup] LOG:  invalid record length at 0/3000188: expected at least 24, got 0
2024-03-22 04:05:48.574 UTC [21389][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-22 04:05:48.576 UTC [21388][startup] LOG:  redo starts at 0/3000188
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-22 04:05:48.622 UTC [21394][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:48.622 UTC [21394][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-22 04:05:48.622 UTC [21394][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:48.629 UTC [21394][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-22 04:05:48.630 UTC [21394][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:48.632 UTC [21394][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-22 04:05:48.637 UTC [21394][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.015 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-22 04:05:48.652 UTC [21383][postmaster] LOG:  received fast shutdown request
2024-03-22 04:05:48.652 UTC [21383][postmaster] LOG:  aborting any active transactions
2024-03-22 04:05:48.657 UTC [21389][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-22 04:05:48.658 UTC [21385][checkpointer] LOG:  shutting down
2024-03-22 04:05:48.661 UTC [21383][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[04:05:48.792](0.730s) 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=57707 host=/tmp/QCvKEwcamq dbname='pg1' --socket-directory /tmp/QCvKEwcamq --subscriber-port 57709 --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 7349033773678470472 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7349033773678470472 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-22 04:05:48.855 UTC [21420][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-22 04:05:48.855 UTC [21420][postmaster] LOG:  listening on Unix socket "/tmp/QCvKEwcamq/.s.PGSQL.57709"
2024-03-22 04:05:48.857 UTC [21424][startup] LOG:  database system was shut down in recovery at 2024-03-22 04:05:48 UTC
2024-03-22 04:05:48.857 UTC [21424][startup] LOG:  entering standby mode
2024-03-22 04:05:48.869 UTC [21424][startup] LOG:  redo starts at 0/3000188
2024-03-22 04:05:48.869 UTC [21424][startup] LOG:  consistent recovery state reached at 0/30001C0
2024-03-22 04:05:48.869 UTC [21420][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-22 04:05:48.877 UTC [21424][startup] LOG:  invalid record length at 0/30001C0: expected at least 24, got 0
2024-03-22 04:05:48.921 UTC [21425][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-22 04:05:48.965 UTC [21434][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:48.965 UTC [21434][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-22 04:05:48.965 UTC [21434][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:48.970 UTC [21434][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-22 04:05:48.971 UTC [21434][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:48.971 UTC [21434][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.
pg_createsubscriber: checking settings on publisher
2024-03-22 04:05:48.978 UTC [21434][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: 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-22 04:05:49.019 UTC [21420][postmaster] LOG:  received fast shutdown request
2024-03-22 04:05:49.019 UTC [21420][postmaster] LOG:  aborting any active transactions
2024-03-22 04:05:49.027 UTC [21425][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-22 04:05:49.028 UTC [21422][checkpointer] LOG:  shutting down
2024-03-22 04:05:49.029 UTC [21420][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[04:05:49.152](0.360s) 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 21491
# 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=57707 host=/tmp/QCvKEwcamq dbname='pg1' --socket-directory /tmp/QCvKEwcamq --subscriber-port 57709 --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 7349033773678470472 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7349033773678470472 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-22 04:05:49.437 UTC [21520][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-22 04:05:49.437 UTC [21520][postmaster] LOG:  listening on Unix socket "/tmp/QCvKEwcamq/.s.PGSQL.57709"
2024-03-22 04:05:49.512 UTC [21523][startup] LOG:  database system was shut down in recovery at 2024-03-22 04:05:49 UTC
2024-03-22 04:05:49.512 UTC [21523][startup] LOG:  entering standby mode
2024-03-22 04:05:49.513 UTC [21523][startup] LOG:  redo starts at 0/3000188
2024-03-22 04:05:49.513 UTC [21523][startup] LOG:  consistent recovery state reached at 0/30046D0
2024-03-22 04:05:49.513 UTC [21520][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-22 04:05:49.513 UTC [21523][startup] LOG:  invalid record length at 0/30046D0: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-22 04:05:49.525 UTC [21530][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:49.526 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-22 04:05:49.526 UTC [21530][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:49.532 UTC [21530][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-22 04:05:49.532 UTC [21530][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:49.535 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: checking settings on publisher
2024-03-22 04:05:49.540 UTC [21530][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.014 user=postgres database=pg1 host=[local]
pg_createsubscriber: error: could not obtain replication slot information: got 0 rows, expected 1 row
2024-03-22 04:05:49.561 UTC [21520][postmaster] LOG:  received fast shutdown request
2024-03-22 04:05:49.561 UTC [21520][postmaster] LOG:  aborting any active transactions
2024-03-22 04:05:49.562 UTC [21527][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-22 04:05:49.564 UTC [21521][checkpointer] LOG:  shutting down
2024-03-22 04:05:49.566 UTC [21520][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[04:05:49.707](0.555s) not ok 24 - run pg_createsubscriber --dry-run on node S
[04:05:49.709](0.002s) #   Failed test 'run pg_createsubscriber --dry-run on node S'
#   at /tmp/cirrus-ci-build/src/bin/pg_basebackup/t/040_pg_createsubscriber.pl line 260.
### 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 21563
[04:05:49.843](0.135s) 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=57707 host=/tmp/QCvKEwcamq dbname='pg1' --socket-directory /tmp/QCvKEwcamq --subscriber-port 57709 --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 7349033773678470472 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7349033773678470472 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-22 04:05:50.014 UTC [21593][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-22 04:05:50.014 UTC [21593][postmaster] LOG:  listening on Unix socket "/tmp/QCvKEwcamq/.s.PGSQL.57709"
2024-03-22 04:05:50.016 UTC [21596][startup] LOG:  database system was shut down in recovery at 2024-03-22 04:05:49 UTC
2024-03-22 04:05:50.016 UTC [21596][startup] LOG:  entering standby mode
2024-03-22 04:05:50.017 UTC [21596][startup] LOG:  redo starts at 0/3004748
2024-03-22 04:05:50.017 UTC [21596][startup] LOG:  consistent recovery state reached at 0/3004780
2024-03-22 04:05:50.017 UTC [21593][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-22 04:05:50.017 UTC [21596][startup] LOG:  invalid record length at 0/3004780: expected at least 24, got 0
2024-03-22 04:05:50.020 UTC [21597][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-22 04:05:50.111 UTC [21612][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:50.112 UTC [21612][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-22 04:05:50.112 UTC [21612][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:50.116 UTC [21612][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-22 04:05:50.117 UTC [21612][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:50.117 UTC [21612][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-22 04:05:50.120 UTC [21612][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.008 user=postgres database=pg1 host=[local]
pg_createsubscriber: checking settings on publisher
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: stopping the subscriber
2024-03-22 04:05:50.135 UTC [21593][postmaster] LOG:  received fast shutdown request
2024-03-22 04:05:50.135 UTC [21593][postmaster] LOG:  aborting any active transactions
2024-03-22 04:05:50.136 UTC [21597][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-22 04:05:50.137 UTC [21594][checkpointer] LOG:  shutting down
2024-03-22 04:05:50.138 UTC [21593][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: creating publication "pg_createsubscriber_16384_3798f2be" 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-22 04:05:50.263 UTC [21646][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-22 04:05:50.263 UTC [21646][postmaster] LOG:  listening on Unix socket "/tmp/QCvKEwcamq/.s.PGSQL.57709"
2024-03-22 04:05:50.266 UTC [21649][startup] LOG:  database system was shut down in recovery at 2024-03-22 04:05:50 UTC
2024-03-22 04:05:50.266 UTC [21649][startup] LOG:  entering standby mode
2024-03-22 04:05:50.285 UTC [21649][startup] LOG:  redo starts at 0/3004748
2024-03-22 04:05:50.287 UTC [21649][startup] LOG:  consistent recovery state reached at 0/3004780
2024-03-22 04:05:50.287 UTC [21646][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-22 04:05:50.288 UTC [21649][startup] LOG:  invalid record length at 0/3004780: expected at least 24, got 0
2024-03-22 04:05:50.292 UTC [21650][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-22 04:05:50.357 UTC [21661][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:50.358 UTC [21661][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-22 04:05:50.358 UTC [21661][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:50.363 UTC [21661][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-22 04:05:50.364 UTC [21661][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-22 04:05:50.364 UTC [21661][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.007 user=postgres database=pg1 host=[local]
2024-03-22 04:05:50.365 UTC [21664][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:50.365 UTC [21664][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-22 04:05:50.365 UTC [21664][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:50.366 UTC [21664][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_3798f2be" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_3798f2be" on database "pg1"
2024-03-22 04:05:50.366 UTC [21664][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_3798f2be' 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_3798f2be" on database "pg1"
2024-03-22 04:05:50.369 UTC [21664][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.004 user=postgres database=pg1 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-22 04:05:50.375 UTC [21646][postmaster] LOG:  received fast shutdown request
2024-03-22 04:05:50.375 UTC [21646][postmaster] LOG:  aborting any active transactions
2024-03-22 04:05:50.376 UTC [21650][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-22 04:05:50.378 UTC [21647][checkpointer] LOG:  shutting down
2024-03-22 04:05:50.380 UTC [21646][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7349034146053936208 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: Done!
[04:05:50.653](0.809s) 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=57707 host=/tmp/QCvKEwcamq dbname='pg1' --socket-directory /tmp/QCvKEwcamq --subscriber-port 57709 --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/QCvKEwcamq port=57707 dbname=pg1
pg_createsubscriber: subscriber(0): subscription: (auto) ; connection string: port=57709 host=/tmp/QCvKEwcamq fallback_application_name=pg_createsubscriber dbname=pg1
pg_createsubscriber: publisher(1): publication: Pub2 ; replication slot: replslot2 ; connection string: host=/tmp/QCvKEwcamq port=57707 dbname=pg2
pg_createsubscriber: subscriber(1): subscription: (auto) ; connection string: port=57709 host=/tmp/QCvKEwcamq fallback_application_name=pg_createsubscriber dbname=pg2
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7349033773678470472 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7349033773678470472 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 57709" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/QCvKEwcamq'"
2024-03-22 04:05:50.696 UTC [21714][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-22 04:05:50.696 UTC [21714][postmaster] LOG:  listening on Unix socket "/tmp/QCvKEwcamq/.s.PGSQL.57709"
2024-03-22 04:05:50.698 UTC [21717][startup] LOG:  database system was shut down in recovery at 2024-03-22 04:05:50 UTC
2024-03-22 04:05:50.698 UTC [21717][startup] LOG:  entering standby mode
2024-03-22 04:05:50.698 UTC [21717][startup] LOG:  redo starts at 0/3004748
2024-03-22 04:05:50.698 UTC [21717][startup] LOG:  consistent recovery state reached at 0/3004780
2024-03-22 04:05:50.698 UTC [21714][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-22 04:05:50.698 UTC [21717][startup] LOG:  invalid record length at 0/3004780: expected at least 24, got 0
2024-03-22 04:05:50.701 UTC [21718][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-22 04:05:50.791 UTC [21746][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:50.791 UTC [21746][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-22 04:05:50.791 UTC [21746][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:50.795 UTC [21746][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-22 04:05:50.796 UTC [21746][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:50.796 UTC [21746][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-22 04:05:50.799 UTC [21746][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.008 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-22 04:05:50.830 UTC [21714][postmaster] LOG:  received fast shutdown request
2024-03-22 04:05:50.830 UTC [21714][postmaster] LOG:  aborting any active transactions
2024-03-22 04:05:50.835 UTC [21718][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-22 04:05:50.837 UTC [21715][checkpointer] LOG:  shutting down
2024-03-22 04:05:50.842 UTC [21714][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/QCvKEwcamq'' port=57707 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/30092E0'
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 57709" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/QCvKEwcamq'"
2024-03-22 04:05:51.019 UTC [21774][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-03-22 04:05:51.019 UTC [21774][postmaster] LOG:  listening on Unix socket "/tmp/QCvKEwcamq/.s.PGSQL.57709"
2024-03-22 04:05:51.024 UTC [21777][startup] LOG:  database system was shut down in recovery at 2024-03-22 04:05:50 UTC
2024-03-22 04:05:51.024 UTC [21777][startup] LOG:  entering standby mode
2024-03-22 04:05:51.025 UTC [21777][startup] LOG:  redo starts at 0/3004748
2024-03-22 04:05:51.025 UTC [21777][startup] LOG:  consistent recovery state reached at 0/3004780
2024-03-22 04:05:51.025 UTC [21774][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-22 04:05:51.025 UTC [21777][startup] LOG:  invalid record length at 0/3004780: expected at least 24, got 0
2024-03-22 04:05:51.037 UTC [21778][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-22 04:05:51.145 UTC [21795][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:05:51.145 UTC [21795][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-22 04:05:51.146 UTC [21795][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:05:51.151 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-22 04:05:51.153 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:51.154 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:05:52.162 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/5:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:52.162 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/6:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:05:53.183 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/7:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:53.184 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/8:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:05:54.194 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/9:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:54.194 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/10:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:05:55.202 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/11:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:55.202 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/12:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:05:56.212 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/13:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:56.212 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/14:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:05:57.236 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/15:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:57.236 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/16:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:05:58.242 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/17:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:58.242 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/18:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:05:59.254 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/19:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:05:59.254 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/20:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:06:00.269 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/21:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:06:00.270 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/22:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:06:01.275 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/23:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:06:01.276 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/24:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:06:02.284 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/25:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:06:02.284 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/26:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:06:03.292 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/27:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:06:03.292 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/28:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:06:04.302 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/29:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-22 04:06:04.302 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/30:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-22 04:06:04.323 UTC [21777][startup] LOG:  recovery stopping after WAL location (LSN) "0/30092E0"
2024-03-22 04:06:04.323 UTC [21777][startup] LOG:  redo done at 0/30092E0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 13.29 s
2024-03-22 04:06:04.323 UTC [21777][startup] LOG:  last completed transaction was at log time 2024-03-22 04:05:50.997398+00
2024-03-22 04:06:04.323 UTC [21778][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-22 04:06:04.327 UTC [21777][startup] LOG:  selected new timeline ID: 2
2024-03-22 04:06:04.334 UTC [21777][startup] LOG:  archive recovery complete
2024-03-22 04:06:04.335 UTC [21775][checkpointer] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-03-22 04:06:04.335 UTC [21775][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/3009318, redo lsn=0/3009318
2024-03-22 04:06:04.337 UTC [21774][postmaster] LOG:  database system is ready to accept connections
2024-03-22 04:06:05.317 UTC [21795][client backend] [040_pg_createsubscriber.pl][0/31: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-22 04:06:05.317 UTC [21795][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:14.172 user=postgres database=pg1 host=[local]
2024-03-22 04:06:05.318 UTC [24534][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:06:05.318 UTC [24534][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-22 04:06:05.318 UTC [24534][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-22 04:06:05.319 UTC [24534][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-22 04:06:05.319 UTC [24534][client backend] [040_pg_createsubscriber.pl][1/3:0] LOG:  statement: DROP PUBLICATION "pub1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_838c2df3" on database "pg1"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16384_838c2df3" CONNECTION 'host=/tmp/QCvKEwcamq port=57707 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-03-22 04:06:05.320 UTC [24534][client backend] [040_pg_createsubscriber.pl][1/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16384_838c2df3" CONNECTION 'host=/tmp/QCvKEwcamq port=57707 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-03-22 04:06:05.320 UTC [24534][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-22 04:06:05.332 UTC [24534][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_838c2df3' AND d.datname = 'pg1'
pg_createsubscriber: setting the replication progress (node name "pg_24588" ; LSN 0/30092E0) on database "pg1"
pg_createsubscriber: command is: SELECT pg_catalog.pg_replication_origin_advance('pg_24588', '0/30092E0')
2024-03-22 04:06:05.335 UTC [24534][client backend] [040_pg_createsubscriber.pl][1/6:0] LOG:  statement: SELECT pg_catalog.pg_replication_origin_advance('pg_24588', '0/30092E0')
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_838c2df3" on database "pg1"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16384_838c2df3" ENABLE
2024-03-22 04:06:05.335 UTC [24534][client backend] [040_pg_createsubscriber.pl][1/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16384_838c2df3" ENABLE
2024-03-22 04:06:05.335 UTC [24534][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.017 user=postgres database=pg1 host=[local]
2024-03-22 04:06:05.341 UTC [24538][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16384_838c2df3" has started
2024-03-22 04:06:05.342 UTC [24541][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-22 04:06:05.342 UTC [24541][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-22 04:06:05.342 UTC [24541][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=040_pg_createsubscriber.pl
2024-03-22 04:06:05.346 UTC [24541][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-22 04:06:05.347 UTC [24541][client backend] [040_pg_createsubscriber.pl][2/3:0] LOG:  statement: DROP PUBLICATION "Pub2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_147ba7d2" on database "pg2"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16385_147ba7d2" CONNECTION 'host=/tmp/QCvKEwcamq port=57707 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-03-22 04:06:05.348 UTC [24541][client backend] [040_pg_createsubscriber.pl][2/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16385_147ba7d2" CONNECTION 'host=/tmp/QCvKEwcamq port=57707 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-03-22 04:06:05.348 UTC [24541][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-22 04:06:05.361 UTC [24541][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_147ba7d2' AND d.datname = 'pg2'
pg_createsubscriber: setting the replication progress (node name "pg_24589" ; LSN 0/30092E0) on database "pg2"
pg_createsubscriber: command is: SELECT pg_catalog.pg_replication_origin_advance('pg_24589', '0/30092E0')
2024-03-22 04:06:05.364 UTC [24541][client backend] [040_pg_createsubscriber.pl][2/6:0] LOG:  statement: SELECT pg_catalog.pg_replication_origin_advance('pg_24589', '0/30092E0')
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_147ba7d2" on database "pg2"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16385_147ba7d2" ENABLE
2024-03-22 04:06:05.364 UTC [24541][client backend] [040_pg_createsubscriber.pl][2/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16385_147ba7d2" ENABLE
2024-03-22 04:06:05.364 UTC [24541][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.022 user=postgres database=pg2 host=[local]
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-22 04:06:05.369 UTC [24549][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16385_147ba7d2" has started
2024-03-22 04:06:05.370 UTC [21774][postmaster] LOG:  received fast shutdown request
2024-03-22 04:06:05.370 UTC [21774][postmaster] LOG:  aborting any active transactions
2024-03-22 04:06:05.370 UTC [24549][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-03-22 04:06:05.371 UTC [24538][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-03-22 04:06:05.372 UTC [21774][postmaster] LOG:  background worker "logical replication apply worker" (PID 24549) exited with exit code 1
2024-03-22 04:06:05.372 UTC [21774][postmaster] LOG:  background worker "logical replication apply worker" (PID 24538) exited with exit code 1
2024-03-22 04:06:05.372 UTC [21774][postmaster] LOG:  background worker "logical replication launcher" (PID 24351) exited with exit code 1
2024-03-22 04:06:05.372 UTC [21775][checkpointer] LOG:  shutting down
2024-03-22 04:06:05.372 UTC [21775][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-03-22 04:06:05.373 UTC [21775][checkpointer] LOG:  checkpoint complete: wrote 10 buffers (7.8%); 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=23 kB, estimate=23 kB; lsn=0/300F228, redo lsn=0/300F228
2024-03-22 04:06:05.375 UTC [21774][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7349034210437874884 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!
[04:06:05.612](14.960s) ok 27 - run pg_createsubscriber on node S
[04:06:05.624](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 24598
Waiting for all subscriptions in "node_s" to synchronize data
Waiting for replication conn pg_createsubscriber_16384_838c2df3's replay_lsn to pass 0/30094A0 on node_p
done
done
Waiting for all subscriptions in "node_s" to synchronize data
Waiting for replication conn pg_createsubscriber_16385_147ba7d2's replay_lsn to pass 0/30094A0 on node_p
done
done
[04:06:05.981](0.357s) ok 29 - logical replication works on database pg1
[04:06:06.007](0.026s) ok 30 - logical replication works on database pg2
[04:06:06.053](0.046s) 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"
[04:06:06.273](0.220s) 1..31
[04:06:06.275](0.002s) # Looks like you failed 1 test of 31.