# Running: pg_createsubscriber --help
[16:08:12.170](0.085s) ok 1 - pg_createsubscriber --help exit code 0
[16:08:12.176](0.005s) ok 2 - pg_createsubscriber --help goes to stdout
[16:08:12.176](0.000s) ok 3 - pg_createsubscriber --help nothing to stderr
[16:08:12.176](0.000s) ok 4 - pg_createsubscriber --help maximum line length
# Running: pg_createsubscriber --version
[16:08:12.209](0.033s) ok 5 - pg_createsubscriber --version exit code 0
[16:08:12.219](0.011s) ok 6 - pg_createsubscriber --version goes to stdout
[16:08:12.220](0.000s) ok 7 - pg_createsubscriber --version nothing to stderr
# Running: pg_createsubscriber --not-a-valid-option
[16:08:12.312](0.093s) ok 8 - pg_createsubscriber with invalid option nonzero exit code
[16:08:12.321](0.009s) 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.
[16:08:12.352](0.031s) 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_JWoi
pg_createsubscriber: error: no publisher connection string specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[16:08:12.380](0.027s) 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_JWoi --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.
[16:08:12.403](0.024s) 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_JWoi --publisher-server port=5432 --database pg1 --database pg1
pg_createsubscriber: error: duplicate database "pg1"
[16:08:12.432](0.029s) ok 13 - duplicate database name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_JWoi --publisher-server port=5432 --publication foo1 --publication foo1 --database pg1 --database pg2
pg_createsubscriber: error: duplicate publication "foo1"
[16:08:12.453](0.021s) ok 14 - duplicate publication name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_JWoi --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).
[16:08:12.487](0.034s) 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_JWoi --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).
[16:08:12.506](0.019s) 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_JWoi --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).
[16:08:12.534](0.028s) ok 17 - wrong number of replication slot names
# Checking port 62288
# Found port 62288
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=62288 host=/tmp/asqX9NvlIE
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_p.log
[16:08:12.568](0.034s) # 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 21181
# Checking port 62289
# Found port 62289
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=62289 host=/tmp/asqX9NvlIE
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_f.log
[16:08:12.920](0.352s) # 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/asqX9NvlIE -p 62288 --checkpoint fast --no-sync
# Backup finished
# Checking port 62290
# Found port 62290
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=62290 host=/tmp/asqX9NvlIE
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 21514
# Checking port 62291
# Found port 62291
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=62291 host=/tmp/asqX9NvlIE
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 21584
### 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=62288 host=/tmp/asqX9NvlIE dbname='pg1' --socket-directory /tmp/asqX9NvlIE --subscriber-port 62291 --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 7358868096022095208 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7358868096022095208 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-17 16:08:16.384 UTC [21649][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-04-17 16:08:16.384 UTC [21649][postmaster] LOG:  listening on Unix socket "/tmp/asqX9NvlIE/.s.PGSQL.62291"
2024-04-17 16:08:16.394 UTC [21655][startup] LOG:  database system was shut down at 2024-04-17 16:08:16 UTC
2024-04-17 16:08:16.408 UTC [21649][postmaster] LOG:  database system is ready to accept connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-17 16:08:16.481 UTC [21666][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:16.482 UTC [21666][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-04-17 16:08:16.482 UTC [21666][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:16.488 UTC [21666][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-17 16:08:16.491 UTC [21666][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-04-17 16:08:16.491 UTC [21666][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.010 user=postgres database=pg1 host=[local]
2024-04-17 16:08:16.494 UTC [21649][postmaster] LOG:  received fast shutdown request
2024-04-17 16:08:16.495 UTC [21649][postmaster] LOG:  aborting any active transactions
2024-04-17 16:08:16.501 UTC [21649][postmaster] LOG:  background worker "logical replication launcher" (PID 21658) exited with exit code 1
2024-04-17 16:08:16.502 UTC [21653][checkpointer] LOG:  shutting down
2024-04-17 16:08:16.502 UTC [21653][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-04-17 16:08:16.502 UTC [21653][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-04-17 16:08:16.504 UTC [21649][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:08:16.599](3.679s) 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=62288 host=/tmp/asqX9NvlIE dbname='pg1' --socket-directory /tmp/asqX9NvlIE --subscriber-port 62290 --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 7358868096022095208 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7358868096022095208 on subscriber
pg_createsubscriber: error: standby is up and running
pg_createsubscriber: hint: Stop the standby and try again.
[16:08:16.623](0.024s) 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=62288 host=/tmp/asqX9NvlIE dbname='pg1' --socket-directory /tmp/asqX9NvlIE --subscriber-port 62289 --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 7358868096022095208 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7358868516006060760 on subscriber
pg_createsubscriber: error: subscriber data directory is not a copy of the source database cluster
[16:08:16.650](0.027s) 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/asqX9NvlIE -p 62290 --checkpoint fast --no-sync
# Backup finished
# Checking port 62292
# Found port 62292
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=62292 host=/tmp/asqX9NvlIE
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=62290 host=/tmp/asqX9NvlIE dbname='pg1' --socket-directory /tmp/asqX9NvlIE --subscriber-port 62292 --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 7358868096022095208 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7358868096022095208 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-17 16:08:17.115 UTC [21745][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-04-17 16:08:17.115 UTC [21745][postmaster] LOG:  listening on Unix socket "/tmp/asqX9NvlIE/.s.PGSQL.62292"
2024-04-17 16:08:17.118 UTC [21750][startup] LOG:  database system was interrupted while in recovery at log time 2024-04-17 16:08:15 UTC
2024-04-17 16:08:17.118 UTC [21750][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-04-17 16:08:17.118 UTC [21750][startup] LOG:  starting backup recovery with redo LSN 0/2000028, checkpoint LSN 0/2000080, on timeline ID 1
2024-04-17 16:08:17.118 UTC [21750][startup] LOG:  entering standby mode
2024-04-17 16:08:17.118 UTC [21750][startup] LOG:  redo starts at 0/2000028
2024-04-17 16:08:17.118 UTC [21750][startup] LOG:  completed backup recovery with redo LSN 0/2000028 and end LSN 0/2000120
2024-04-17 16:08:17.119 UTC [21750][startup] LOG:  consistent recovery state reached at 0/3000000
2024-04-17 16:08:17.119 UTC [21745][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-17 16:08:17.125 UTC [21751][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-04-17 16:08:17.211 UTC [21772][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:17.211 UTC [21772][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-04-17 16:08:17.211 UTC [21772][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:17.218 UTC [21772][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-17 16:08:17.219 UTC [21772][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:17.219 UTC [21772][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-04-17 16:08:17.231 UTC [21772][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.020 user=postgres database=pg1 host=[local]
pg_createsubscriber: checking settings on publisher
pg_createsubscriber: error: primary server cannot be in recovery
2024-04-17 16:08:17.240 UTC [21745][postmaster] LOG:  received fast shutdown request
2024-04-17 16:08:17.240 UTC [21745][postmaster] LOG:  aborting any active transactions
2024-04-17 16:08:17.241 UTC [21751][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-17 16:08:17.244 UTC [21748][checkpointer] LOG:  shutting down
2024-04-17 16:08:17.252 UTC [21745][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:08:17.343](0.693s) 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 21831
### 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=62288 host=/tmp/asqX9NvlIE dbname='pg1' --socket-directory /tmp/asqX9NvlIE --subscriber-port 62290 --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 7358868096022095208 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7358868096022095208 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-17 16:08:17.798 UTC [21860][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-04-17 16:08:17.798 UTC [21860][postmaster] LOG:  listening on Unix socket "/tmp/asqX9NvlIE/.s.PGSQL.62290"
2024-04-17 16:08:17.803 UTC [21865][startup] LOG:  database system was shut down in recovery at 2024-04-17 16:08:17 UTC
2024-04-17 16:08:17.803 UTC [21865][startup] LOG:  entering standby mode
2024-04-17 16:08:17.813 UTC [21865][startup] LOG:  consistent recovery state reached at 0/3000188
2024-04-17 16:08:17.813 UTC [21860][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-17 16:08:17.813 UTC [21865][startup] LOG:  invalid record length at 0/3000188: expected at least 24, got 0
2024-04-17 16:08:17.817 UTC [21867][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-04-17 16:08:17.817 UTC [21865][startup] LOG:  redo starts at 0/3000188
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-17 16:08:17.890 UTC [21874][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:17.891 UTC [21874][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-04-17 16:08:17.891 UTC [21874][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:17.897 UTC [21874][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-17 16:08:17.898 UTC [21874][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:17.898 UTC [21874][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-04-17 16:08:17.901 UTC [21874][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.011 user=postgres database=pg1 host=[local]
pg_createsubscriber: checking settings on publisher
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-04-17 16:08:17.923 UTC [21860][postmaster] LOG:  received fast shutdown request
2024-04-17 16:08:17.923 UTC [21860][postmaster] LOG:  aborting any active transactions
2024-04-17 16:08:17.925 UTC [21867][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-17 16:08:17.927 UTC [21863][checkpointer] LOG:  shutting down
2024-04-17 16:08:17.952 UTC [21860][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:08:18.028](0.685s) 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=62288 host=/tmp/asqX9NvlIE dbname='pg1' --socket-directory /tmp/asqX9NvlIE --subscriber-port 62290 --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 7358868096022095208 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7358868096022095208 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-17 16:08:18.065 UTC [21911][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-04-17 16:08:18.065 UTC [21911][postmaster] LOG:  listening on Unix socket "/tmp/asqX9NvlIE/.s.PGSQL.62290"
2024-04-17 16:08:18.067 UTC [21914][startup] LOG:  database system was shut down in recovery at 2024-04-17 16:08:17 UTC
2024-04-17 16:08:18.068 UTC [21914][startup] LOG:  entering standby mode
2024-04-17 16:08:18.069 UTC [21914][startup] LOG:  redo starts at 0/3000188
2024-04-17 16:08:18.069 UTC [21914][startup] LOG:  invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3004000, offset 16384
2024-04-17 16:08:18.069 UTC [21914][startup] LOG:  consistent recovery state reached at 0/3002758
2024-04-17 16:08:18.069 UTC [21911][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-17 16:08:18.069 UTC [21914][startup] LOG:  invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3004000, offset 16384
2024-04-17 16:08:18.072 UTC [21915][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-04-17 16:08:18.162 UTC [21926][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:18.162 UTC [21926][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-04-17 16:08:18.162 UTC [21926][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:18.168 UTC [21926][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-17 16:08:18.168 UTC [21926][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:18.224 UTC [21926][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-04-17 16:08:18.227 UTC [21926][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.065 user=postgres database=pg1 host=[local]
2024-04-17 16:08:18.229 UTC [21911][postmaster] LOG:  received fast shutdown request
2024-04-17 16:08:18.229 UTC [21911][postmaster] LOG:  aborting any active transactions
2024-04-17 16:08:18.231 UTC [21915][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-17 16:08:18.233 UTC [21912][checkpointer] LOG:  shutting down
2024-04-17 16:08:18.236 UTC [21911][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:08:18.335](0.307s) 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 21964
# 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=62288 host=/tmp/asqX9NvlIE dbname='pg1' --socket-directory /tmp/asqX9NvlIE --subscriber-port 62290 --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 7358868096022095208 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7358868096022095208 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-17 16:08:18.613 UTC [22004][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-04-17 16:08:18.613 UTC [22004][postmaster] LOG:  listening on Unix socket "/tmp/asqX9NvlIE/.s.PGSQL.62290"
2024-04-17 16:08:18.616 UTC [22010][startup] LOG:  database system was shut down in recovery at 2024-04-17 16:08:18 UTC
2024-04-17 16:08:18.616 UTC [22010][startup] LOG:  entering standby mode
2024-04-17 16:08:18.618 UTC [22010][startup] LOG:  redo starts at 0/3000188
2024-04-17 16:08:18.618 UTC [22010][startup] LOG:  consistent recovery state reached at 0/30046C0
2024-04-17 16:08:18.618 UTC [22004][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-17 16:08:18.624 UTC [22010][startup] LOG:  invalid record length at 0/30046C0: expected at least 24, got 0
2024-04-17 16:08:18.629 UTC [22013][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-04-17 16:08:18.727 UTC [22025][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:18.728 UTC [22025][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-04-17 16:08:18.728 UTC [22025][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:18.734 UTC [22025][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-17 16:08:18.734 UTC [22025][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:18.734 UTC [22025][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-04-17 16:08:18.738 UTC [22025][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.010 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: stopping the subscriber
2024-04-17 16:08:18.778 UTC [22004][postmaster] LOG:  received fast shutdown request
2024-04-17 16:08:18.778 UTC [22004][postmaster] LOG:  aborting any active transactions
2024-04-17 16:08:18.782 UTC [22013][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-17 16:08:18.783 UTC [22008][checkpointer] LOG:  shutting down
2024-04-17 16:08:18.783 UTC [22008][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-04-17 16:08:18.784 UTC [22008][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-04-17 16:08:18.784 UTC [22008][checkpointer] LOG:  recovery restart point at 0/30046C0
2024-04-17 16:08:18.785 UTC [22004][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-04-17 16:08:19.015 UTC [22073][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-04-17 16:08:19.015 UTC [22073][postmaster] LOG:  listening on Unix socket "/tmp/asqX9NvlIE/.s.PGSQL.62290"
2024-04-17 16:08:19.079 UTC [22076][startup] LOG:  database system was shut down in recovery at 2024-04-17 16:08:18 UTC
2024-04-17 16:08:19.080 UTC [22076][startup] LOG:  entering standby mode
2024-04-17 16:08:19.080 UTC [22076][startup] LOG:  redo starts at 0/3004738
2024-04-17 16:08:19.080 UTC [22076][startup] LOG:  consistent recovery state reached at 0/3004770
2024-04-17 16:08:19.080 UTC [22076][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-04-17 16:08:19.080 UTC [22073][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-04-17 16:08:19.117 UTC [22079][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-04-17 16:08:19.122 UTC [22083][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:19.122 UTC [22083][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-04-17 16:08:19.122 UTC [22083][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:19.129 UTC [22083][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-17 16:08:19.136 UTC [22083][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-04-17 16:08:19.137 UTC [22083][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.015 user=postgres database=pg1 host=[local]
2024-04-17 16:08:19.138 UTC [22089][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:19.138 UTC [22089][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-04-17 16:08:19.138 UTC [22089][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:19.139 UTC [22089][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-04-17 16:08:19.140 UTC [22089][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-04-17 16:08:19.143 UTC [22089][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.005 user=postgres database=pg1 host=[local]
2024-04-17 16:08:19.144 UTC [22090][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:19.144 UTC [22090][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-04-17 16:08:19.144 UTC [22090][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:19.150 UTC [22090][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-04-17 16:08:19.151 UTC [22090][client backend] [040_pg_createsubscriber.pl][2/3:0] LOG:  statement: SELECT s.oid FROM pg_catalog.pg_subscription s INNER JOIN pg_catalog.pg_database d ON (s.subdbid = d.oid) WHERE s.subname = 'sub2' AND d.datname = 'pg2'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "sub2" on database "pg2"
2024-04-17 16:08:19.158 UTC [22090][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.014 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-04-17 16:08:19.164 UTC [22073][postmaster] LOG:  received fast shutdown request
2024-04-17 16:08:19.164 UTC [22073][postmaster] LOG:  aborting any active transactions
2024-04-17 16:08:19.164 UTC [22079][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-17 16:08:19.165 UTC [22074][checkpointer] LOG:  shutting down
2024-04-17 16:08:19.173 UTC [22073][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7358868542252549608 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: Done!
[16:08:19.270](0.935s) 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 22104
[16:08:19.429](0.159s) 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=62288 host=/tmp/asqX9NvlIE dbname='pg1' --socket-directory /tmp/asqX9NvlIE --subscriber-port 62290 --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 7358868096022095208 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7358868096022095208 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-17 16:08:19.772 UTC [22203][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-04-17 16:08:19.772 UTC [22203][postmaster] LOG:  listening on Unix socket "/tmp/asqX9NvlIE/.s.PGSQL.62290"
2024-04-17 16:08:19.791 UTC [22209][startup] LOG:  database system was shut down in recovery at 2024-04-17 16:08:19 UTC
2024-04-17 16:08:19.791 UTC [22209][startup] LOG:  entering standby mode
2024-04-17 16:08:19.808 UTC [22209][startup] LOG:  redo starts at 0/3004738
2024-04-17 16:08:19.808 UTC [22209][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-04-17 16:08:19.808 UTC [22209][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-04-17 16:08:19.808 UTC [22203][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-17 16:08:19.846 UTC [22215][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:19.846 UTC [22215][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-04-17 16:08:19.846 UTC [22215][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:19.865 UTC [22215][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-17 16:08:19.865 UTC [22215][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:19.866 UTC [22215][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-04-17 16:08:19.869 UTC [22215][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.023 user=postgres database=pg1 host=[local]
pg_createsubscriber: error: could not obtain replication slot information: got 0 rows, expected 1 row
2024-04-17 16:08:19.896 UTC [22203][postmaster] LOG:  received fast shutdown request
2024-04-17 16:08:19.896 UTC [22203][postmaster] LOG:  aborting any active transactions
2024-04-17 16:08:19.897 UTC [22211][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-17 16:08:19.898 UTC [22207][checkpointer] LOG:  shutting down
2024-04-17 16:08:19.908 UTC [22203][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:08:20.002](0.574s) not ok 26 - run pg_createsubscriber without --databases
[16:08:20.003](0.000s) #   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=62288 host=/tmp/asqX9NvlIE dbname='pg1' --socket-directory /tmp/asqX9NvlIE --subscriber-port 62290 --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/asqX9NvlIE port=62288 dbname=pg1
pg_createsubscriber: subscriber(0): subscription: (auto) ; connection string: port=62290 host=/tmp/asqX9NvlIE fallback_application_name=pg_createsubscriber dbname=pg1
pg_createsubscriber: publisher(1): publication: Pub2 ; replication slot: replslot2 ; connection string: host=/tmp/asqX9NvlIE port=62288 dbname=pg2
pg_createsubscriber: subscriber(1): subscription: (auto) ; connection string: port=62290 host=/tmp/asqX9NvlIE fallback_application_name=pg_createsubscriber dbname=pg2
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7358868096022095208 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7358868096022095208 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 62290" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/asqX9NvlIE'"
2024-04-17 16:08:20.217 UTC [22252][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-04-17 16:08:20.217 UTC [22252][postmaster] LOG:  listening on Unix socket "/tmp/asqX9NvlIE/.s.PGSQL.62290"
2024-04-17 16:08:20.246 UTC [22258][startup] LOG:  database system was shut down in recovery at 2024-04-17 16:08:19 UTC
2024-04-17 16:08:20.246 UTC [22258][startup] LOG:  entering standby mode
2024-04-17 16:08:20.265 UTC [22258][startup] LOG:  redo starts at 0/3004738
2024-04-17 16:08:20.265 UTC [22258][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-04-17 16:08:20.265 UTC [22258][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-04-17 16:08:20.265 UTC [22252][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-17 16:08:20.297 UTC [22264][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:20.297 UTC [22264][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-04-17 16:08:20.297 UTC [22264][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:20.309 UTC [22260][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-04-17 16:08:20.317 UTC [22264][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-17 16:08:20.320 UTC [22264][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:20.330 UTC [22264][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-04-17 16:08:20.336 UTC [22264][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.039 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-04-17 16:08:20.380 UTC [22252][postmaster] LOG:  received fast shutdown request
2024-04-17 16:08:20.380 UTC [22252][postmaster] LOG:  aborting any active transactions
2024-04-17 16:08:20.387 UTC [22260][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-17 16:08:20.389 UTC [22256][checkpointer] LOG:  shutting down
2024-04-17 16:08:20.404 UTC [22252][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/asqX9NvlIE'' port=62288 application_name=040_pg_createsubscriber.pl sslmode=prefer sslnegotiation=postgres 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 62290" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/asqX9NvlIE'"
2024-04-17 16:08:20.680 UTC [22303][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-04-17 16:08:20.680 UTC [22303][postmaster] LOG:  listening on Unix socket "/tmp/asqX9NvlIE/.s.PGSQL.62290"
2024-04-17 16:08:20.690 UTC [22307][startup] LOG:  database system was shut down in recovery at 2024-04-17 16:08:20 UTC
2024-04-17 16:08:20.690 UTC [22307][startup] LOG:  entering standby mode
2024-04-17 16:08:20.693 UTC [22307][startup] LOG:  redo starts at 0/3004738
2024-04-17 16:08:20.694 UTC [22307][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-04-17 16:08:20.694 UTC [22303][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-17 16:08:20.694 UTC [22307][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-04-17 16:08:20.698 UTC [22308][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-04-17 16:08:20.794 UTC [22319][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:20.795 UTC [22319][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-04-17 16:08:20.795 UTC [22319][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:20.820 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-17 16:08:20.820 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:20.820 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:21.862 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/5:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:21.892 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/6:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:22.901 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/7:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:22.902 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/8:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:23.908 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/9:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:23.909 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/10:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:24.920 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/11:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:24.921 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/12:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:25.932 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/13:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:25.933 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/14:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:26.938 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/15:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:26.939 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/16:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:27.956 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/17:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:27.956 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/18:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:28.968 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/19:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:28.968 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/20:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:29.980 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/21:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:29.980 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/22:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:30.988 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/23:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:30.989 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/24:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:32.008 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/25:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:32.009 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/26:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:33.018 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/27:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-17 16:08:33.019 UTC [22319][client backend] [040_pg_createsubscriber.pl][0/28:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-17 16:08:33.509 UTC [22307][startup] LOG:  recovery stopping after WAL location (LSN) "0/30092C0"
2024-04-17 16:08:33.509 UTC [22307][startup] LOG:  redo done at 0/30092C0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 12.81 s
2024-04-17 16:08:33.509 UTC [22307][startup] LOG:  last completed transaction was at log time 2024-04-17 16:08:20.57839+00
2024-04-17 16:08:33.509 UTC [22308][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-17 16:08:33.515 UTC [22307][startup] LOG:  selected new timeline ID: 2
2024-04-17 16:08:33.524 UTC [22307][startup] LOG:  archive recovery complete
2024-04-17 16:08:33.524 UTC [22305][checkpointer] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-04-17 16:08:33.525 UTC [22305][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-04-17 16:08:33.527 UTC [22303][postmaster] LOG:  database system is ready to accept connections
2024-04-17 16:08:34.035 UTC [22319][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-04-17 16:08:34.035 UTC [22319][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:13.241 user=postgres database=pg1 host=[local]
2024-04-17 16:08:34.036 UTC [24021][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:34.037 UTC [24021][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-04-17 16:08:34.037 UTC [24021][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:34.038 UTC [24021][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-04-17 16:08:34.038 UTC [24021][client backend] [040_pg_createsubscriber.pl][1/3:0] LOG:  statement: DROP PUBLICATION "pub1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_86fbd7a9" on database "pg1"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16384_86fbd7a9" CONNECTION 'host=/tmp/asqX9NvlIE port=62288 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-04-17 16:08:34.040 UTC [24021][client backend] [040_pg_createsubscriber.pl][1/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16384_86fbd7a9" CONNECTION 'host=/tmp/asqX9NvlIE port=62288 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-04-17 16:08:34.040 UTC [24021][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-04-17 16:08:34.056 UTC [24021][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_86fbd7a9' 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-04-17 16:08:34.060 UTC [24021][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_86fbd7a9" on database "pg1"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16384_86fbd7a9" ENABLE
2024-04-17 16:08:34.060 UTC [24021][client backend] [040_pg_createsubscriber.pl][1/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16384_86fbd7a9" ENABLE
2024-04-17 16:08:34.060 UTC [24021][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.024 user=postgres database=pg1 host=[local]
2024-04-17 16:08:34.063 UTC [24033][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-17 16:08:34.063 UTC [24033][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-04-17 16:08:34.063 UTC [24033][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=040_pg_createsubscriber.pl
2024-04-17 16:08:34.067 UTC [24032][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16384_86fbd7a9" has started
2024-04-17 16:08:34.068 UTC [24033][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-04-17 16:08:34.069 UTC [24033][client backend] [040_pg_createsubscriber.pl][2/3:0] LOG:  statement: DROP PUBLICATION "Pub2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_8043fda8" on database "pg2"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16385_8043fda8" CONNECTION 'host=/tmp/asqX9NvlIE port=62288 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-04-17 16:08:34.070 UTC [24033][client backend] [040_pg_createsubscriber.pl][2/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16385_8043fda8" CONNECTION 'host=/tmp/asqX9NvlIE port=62288 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-04-17 16:08:34.070 UTC [24033][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-04-17 16:08:34.087 UTC [24033][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_8043fda8' 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-04-17 16:08:34.090 UTC [24033][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_8043fda8" on database "pg2"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16385_8043fda8" ENABLE
2024-04-17 16:08:34.091 UTC [24033][client backend] [040_pg_createsubscriber.pl][2/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16385_8043fda8" ENABLE
2024-04-17 16:08:34.091 UTC [24033][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.028 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-04-17 16:08:34.098 UTC [22303][postmaster] LOG:  received fast shutdown request
2024-04-17 16:08:34.098 UTC [22303][postmaster] LOG:  aborting any active transactions
2024-04-17 16:08:34.098 UTC [24044][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16385_8043fda8" has started
2024-04-17 16:08:34.098 UTC [24044][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-04-17 16:08:34.099 UTC [24032][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-04-17 16:08:34.103 UTC [22303][postmaster] LOG:  background worker "logical replication apply worker" (PID 24044) exited with exit code 1
2024-04-17 16:08:34.103 UTC [22303][postmaster] LOG:  background worker "logical replication apply worker" (PID 24032) exited with exit code 1
2024-04-17 16:08:34.103 UTC [22303][postmaster] LOG:  background worker "logical replication launcher" (PID 23948) exited with exit code 1
2024-04-17 16:08:34.103 UTC [22305][checkpointer] LOG:  shutting down
2024-04-17 16:08:34.103 UTC [22305][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-04-17 16:08:34.104 UTC [22305][checkpointer] LOG:  checkpoint complete: wrote 5 buffers (3.9%); 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-04-17 16:08:34.106 UTC [22303][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7358868606388877016 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!
[16:08:34.216](14.213s) ok 27 - run pg_createsubscriber on node S
[16:08:34.232](0.017s) 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 24093
Waiting for all subscriptions in "node_s" to synchronize data
Waiting for replication conn pg_createsubscriber_16384_86fbd7a9'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_8043fda8's replay_lsn to pass 0/3009480 on node_p
done
done
[16:08:34.661](0.429s) ok 29 - logical replication works on database pg1
[16:08:34.676](0.015s) ok 30 - logical replication works on database pg2
[16:08:34.703](0.027s) 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"
[16:08:34.824](0.120s) 1..31
[16:08:34.828](0.005s) # Looks like you failed 1 test of 31.