# Running: pg_createsubscriber --help
[17:10:49.596](0.021s) ok 1 - pg_createsubscriber --help exit code 0
[17:10:49.597](0.001s) ok 2 - pg_createsubscriber --help goes to stdout
[17:10:49.598](0.000s) ok 3 - pg_createsubscriber --help nothing to stderr
[17:10:49.598](0.000s) ok 4 - pg_createsubscriber --help maximum line length
# Running: pg_createsubscriber --version
[17:10:49.604](0.006s) ok 5 - pg_createsubscriber --version exit code 0
[17:10:49.604](0.001s) ok 6 - pg_createsubscriber --version goes to stdout
[17:10:49.605](0.000s) ok 7 - pg_createsubscriber --version nothing to stderr
# Running: pg_createsubscriber --not-a-valid-option
[17:10:49.617](0.012s) ok 8 - pg_createsubscriber with invalid option nonzero exit code
[17:10:49.617](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.
[17:10:49.623](0.006s) ok 10 - no subscriber data directory specified
# Running: pg_createsubscriber --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_ocOa
pg_createsubscriber: error: no publisher connection string specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[17:10:49.662](0.040s) 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_ocOa --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.
[17:10:49.677](0.015s) 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_ocOa --publisher-server port=5432 --database pg1 --database pg1
pg_createsubscriber: error: duplicate database "pg1"
[17:10:49.683](0.005s) ok 13 - duplicate database name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_ocOa --publisher-server port=5432 --publication foo1 --publication foo1 --database pg1 --database pg2
pg_createsubscriber: error: duplicate publication "foo1"
[17:10:49.691](0.008s) ok 14 - duplicate publication name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/tmp_test_ocOa --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).
[17:10:49.710](0.019s) 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_ocOa --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).
[17:10:49.721](0.011s) 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_ocOa --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).
[17:10:49.727](0.006s) ok 17 - wrong number of replication slot names
# Checking port 49751
# Found port 49751
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=49751 host=/tmp/JlJLudBI1E
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_p.log
[17:10:49.731](0.005s) # initializing database system by copying initdb template
# Running: cp -RPp /tmp/cirrus-ci-build/build/tmp_install/initdb-template /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata
# Running: /tmp/cirrus-ci-build/build/src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata
### Starting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/data/t_040_pg_createsubscriber_node_p_data/pgdata -l /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_p.log -o --cluster-name=node_p start
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 21239
# Checking port 49752
# Found port 49752
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=49752 host=/tmp/JlJLudBI1E
Log file: /tmp/cirrus-ci-build/build/testrun/pg_basebackup/040_pg_createsubscriber/log/040_pg_createsubscriber_node_f.log
[17:10:49.930](0.198s) # 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/JlJLudBI1E -p 49751 --checkpoint fast --no-sync
# Backup finished
# Checking port 49753
# Found port 49753
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=49753 host=/tmp/JlJLudBI1E
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 21557
# Checking port 49754
# Found port 49754
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=49754 host=/tmp/JlJLudBI1E
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 21631
### 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=49751 host=/tmp/JlJLudBI1E dbname='pg1' --socket-directory /tmp/JlJLudBI1E --subscriber-port 49754 --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 7364821661409994093 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7364821661409994093 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-05-03 17:10:52.467 UTC [21768][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-05-03 17:10:52.467 UTC [21768][postmaster] LOG:  listening on Unix socket "/tmp/JlJLudBI1E/.s.PGSQL.49754"
2024-05-03 17:10:52.473 UTC [21772][startup] LOG:  database system was shut down at 2024-05-03 17:10:52 UTC
2024-05-03 17:10:52.477 UTC [21768][postmaster] LOG:  database system is ready to accept connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-05-03 17:10:52.560 UTC [21783][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:52.561 UTC [21783][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-05-03 17:10:52.561 UTC [21783][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:52.566 UTC [21783][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-05-03 17:10:52.566 UTC [21783][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-05-03 17:10:52.566 UTC [21783][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.006 user=postgres database=pg1 host=[local]
2024-05-03 17:10:52.569 UTC [21768][postmaster] LOG:  received fast shutdown request
2024-05-03 17:10:52.569 UTC [21768][postmaster] LOG:  aborting any active transactions
2024-05-03 17:10:52.570 UTC [21768][postmaster] LOG:  background worker "logical replication launcher" (PID 21776) exited with exit code 1
2024-05-03 17:10:52.570 UTC [21770][checkpointer] LOG:  shutting down
2024-05-03 17:10:52.570 UTC [21770][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-05-03 17:10:52.572 UTC [21770][checkpointer] LOG:  checkpoint complete: wrote 6 buffers (4.7%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, average=0.000 s; distance=17 kB, estimate=17 kB; lsn=0/30046A0, redo lsn=0/30046A0
2024-05-03 17:10:52.574 UTC [21768][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[17:10:52.677](2.747s) 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=49751 host=/tmp/JlJLudBI1E dbname='pg1' --socket-directory /tmp/JlJLudBI1E --subscriber-port 49753 --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 7364821661409994093 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7364821661409994093 on subscriber
pg_createsubscriber: error: standby is up and running
pg_createsubscriber: hint: Stop the standby and try again.
[17:10:52.701](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=49751 host=/tmp/JlJLudBI1E dbname='pg1' --socket-directory /tmp/JlJLudBI1E --subscriber-port 49752 --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 7364821661409994093 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7364822014391517986 on subscriber
pg_createsubscriber: error: subscriber data directory is not a copy of the source database cluster
[17:10:52.719](0.018s) 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/JlJLudBI1E -p 49753 --checkpoint fast --no-sync
# Backup finished
# Checking port 49755
# Found port 49755
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=49755 host=/tmp/JlJLudBI1E
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=49753 host=/tmp/JlJLudBI1E dbname='pg1' --socket-directory /tmp/JlJLudBI1E --subscriber-port 49755 --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 7364821661409994093 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7364821661409994093 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-05-03 17:10:53.391 UTC [21894][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-05-03 17:10:53.391 UTC [21894][postmaster] LOG:  listening on Unix socket "/tmp/JlJLudBI1E/.s.PGSQL.49755"
2024-05-03 17:10:53.392 UTC [21899][startup] LOG:  database system was interrupted while in recovery at log time 2024-05-03 17:10:51 UTC
2024-05-03 17:10:53.392 UTC [21899][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-05-03 17:10:53.393 UTC [21899][startup] LOG:  starting backup recovery with redo LSN 0/2000028, checkpoint LSN 0/2000080, on timeline ID 1
2024-05-03 17:10:53.393 UTC [21899][startup] LOG:  entering standby mode
2024-05-03 17:10:53.393 UTC [21899][startup] LOG:  redo starts at 0/2000028
2024-05-03 17:10:53.393 UTC [21899][startup] LOG:  completed backup recovery with redo LSN 0/2000028 and end LSN 0/2000120
2024-05-03 17:10:53.393 UTC [21899][startup] LOG:  consistent recovery state reached at 0/3000000
2024-05-03 17:10:53.393 UTC [21894][postmaster] LOG:  database system is ready to accept read-only connections
2024-05-03 17:10:53.396 UTC [21901][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-05-03 17:10:53.460 UTC [21909][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:53.460 UTC [21909][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-05-03 17:10:53.460 UTC [21909][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:53.465 UTC [21909][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-05-03 17:10:53.466 UTC [21909][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:53.466 UTC [21909][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-05-03 17:10:53.469 UTC [21909][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.009 user=postgres database=pg1 host=[local]
pg_createsubscriber: error: primary server cannot be in recovery
2024-05-03 17:10:53.475 UTC [21894][postmaster] LOG:  received fast shutdown request
2024-05-03 17:10:53.475 UTC [21894][postmaster] LOG:  aborting any active transactions
2024-05-03 17:10:53.477 UTC [21901][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-05-03 17:10:53.478 UTC [21897][checkpointer] LOG:  shutting down
2024-05-03 17:10:53.505 UTC [21894][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[17:10:53.580](0.860s) 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 21945
### 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=49751 host=/tmp/JlJLudBI1E dbname='pg1' --socket-directory /tmp/JlJLudBI1E --subscriber-port 49753 --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 7364821661409994093 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7364821661409994093 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-05-03 17:10:54.031 UTC [21986][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-05-03 17:10:54.031 UTC [21986][postmaster] LOG:  listening on Unix socket "/tmp/JlJLudBI1E/.s.PGSQL.49753"
2024-05-03 17:10:54.041 UTC [21995][startup] LOG:  database system was shut down in recovery at 2024-05-03 17:10:53 UTC
2024-05-03 17:10:54.041 UTC [21995][startup] LOG:  entering standby mode
2024-05-03 17:10:54.046 UTC [21995][startup] LOG:  consistent recovery state reached at 0/3000188
2024-05-03 17:10:54.046 UTC [21986][postmaster] LOG:  database system is ready to accept read-only connections
2024-05-03 17:10:54.046 UTC [21995][startup] LOG:  invalid record length at 0/3000188: expected at least 24, got 0
2024-05-03 17:10:54.053 UTC [22003][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-05-03 17:10:54.053 UTC [21995][startup] LOG:  redo starts at 0/3000188
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-05-03 17:10:54.145 UTC [22047][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:54.145 UTC [22047][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-05-03 17:10:54.145 UTC [22047][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:54.163 UTC [22047][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-05-03 17:10:54.164 UTC [22047][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:54.164 UTC [22047][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-05-03 17:10:54.181 UTC [22047][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.035 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-05-03 17:10:54.234 UTC [21986][postmaster] LOG:  received fast shutdown request
2024-05-03 17:10:54.234 UTC [21986][postmaster] LOG:  aborting any active transactions
2024-05-03 17:10:54.246 UTC [22003][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-05-03 17:10:54.249 UTC [21993][checkpointer] LOG:  shutting down
2024-05-03 17:10:54.254 UTC [21986][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[17:10:54.339](0.759s) 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=49751 host=/tmp/JlJLudBI1E dbname='pg1' --socket-directory /tmp/JlJLudBI1E --subscriber-port 49753 --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 7364821661409994093 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7364821661409994093 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-05-03 17:10:54.569 UTC [22082][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-05-03 17:10:54.569 UTC [22082][postmaster] LOG:  listening on Unix socket "/tmp/JlJLudBI1E/.s.PGSQL.49753"
2024-05-03 17:10:54.593 UTC [22086][startup] LOG:  database system was shut down in recovery at 2024-05-03 17:10:54 UTC
2024-05-03 17:10:54.593 UTC [22086][startup] LOG:  entering standby mode
2024-05-03 17:10:54.624 UTC [22086][startup] LOG:  redo starts at 0/3000188
2024-05-03 17:10:54.624 UTC [22086][startup] LOG:  consistent recovery state reached at 0/30046C0
2024-05-03 17:10:54.624 UTC [22082][postmaster] LOG:  database system is ready to accept read-only connections
2024-05-03 17:10:54.635 UTC [22086][startup] LOG:  invalid record length at 0/30046C0: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-05-03 17:10:54.663 UTC [22091][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:54.663 UTC [22091][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-05-03 17:10:54.663 UTC [22091][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:54.670 UTC [22090][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-05-03 17:10:54.678 UTC [22091][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-05-03 17:10:54.688 UTC [22091][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:54.694 UTC [22091][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-05-03 17:10:54.703 UTC [22091][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.039 user=postgres database=pg1 host=[local]
2024-05-03 17:10:54.703 UTC [22082][postmaster] LOG:  received fast shutdown request
2024-05-03 17:10:54.704 UTC [22082][postmaster] LOG:  aborting any active transactions
2024-05-03 17:10:54.704 UTC [22090][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-05-03 17:10:54.710 UTC [22084][checkpointer] LOG:  shutting down
2024-05-03 17:10:54.724 UTC [22082][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[17:10:54.811](0.473s) 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 22103
# 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=49751 host=/tmp/JlJLudBI1E dbname='pg1' --socket-directory /tmp/JlJLudBI1E --subscriber-port 49753 --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 7364821661409994093 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7364821661409994093 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-05-03 17:10:55.252 UTC [22125][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-05-03 17:10:55.252 UTC [22125][postmaster] LOG:  listening on Unix socket "/tmp/JlJLudBI1E/.s.PGSQL.49753"
2024-05-03 17:10:55.268 UTC [22129][startup] LOG:  database system was shut down in recovery at 2024-05-03 17:10:54 UTC
2024-05-03 17:10:55.268 UTC [22129][startup] LOG:  entering standby mode
2024-05-03 17:10:55.320 UTC [22129][startup] LOG:  redo starts at 0/3000188
2024-05-03 17:10:55.321 UTC [22129][startup] LOG:  consistent recovery state reached at 0/30046C0
2024-05-03 17:10:55.321 UTC [22125][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-05-03 17:10:55.327 UTC [22129][startup] LOG:  invalid record length at 0/30046C0: expected at least 24, got 0
2024-05-03 17:10:55.330 UTC [22136][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:55.331 UTC [22136][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-05-03 17:10:55.331 UTC [22136][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:55.335 UTC [22136][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-05-03 17:10:55.338 UTC [22136][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:55.338 UTC [22136][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-05-03 17:10:55.349 UTC [22136][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.018 user=postgres database=pg1 host=[local]
pg_createsubscriber: error: could not obtain replication slot information: got 0 rows, expected 1 row
2024-05-03 17:10:55.365 UTC [22125][postmaster] LOG:  received fast shutdown request
2024-05-03 17:10:55.365 UTC [22125][postmaster] LOG:  aborting any active transactions
2024-05-03 17:10:55.388 UTC [22137][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-05-03 17:10:55.389 UTC [22127][checkpointer] LOG:  shutting down
2024-05-03 17:10:55.415 UTC [22125][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[17:10:55.470](0.659s) not ok 24 - run pg_createsubscriber --dry-run on node S
[17:10:55.472](0.001s) #   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 22165
[17:10:55.665](0.194s) 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=49751 host=/tmp/JlJLudBI1E dbname='pg1' --socket-directory /tmp/JlJLudBI1E --subscriber-port 49753 --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 7364821661409994093 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7364821661409994093 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-05-03 17:10:56.011 UTC [22220][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-05-03 17:10:56.011 UTC [22220][postmaster] LOG:  listening on Unix socket "/tmp/JlJLudBI1E/.s.PGSQL.49753"
2024-05-03 17:10:56.023 UTC [22226][startup] LOG:  database system was shut down in recovery at 2024-05-03 17:10:55 UTC
2024-05-03 17:10:56.023 UTC [22226][startup] LOG:  entering standby mode
2024-05-03 17:10:56.070 UTC [22226][startup] LOG:  redo starts at 0/3004738
2024-05-03 17:10:56.070 UTC [22226][startup] LOG:  consistent recovery state reached at 0/3004770
2024-05-03 17:10:56.070 UTC [22220][postmaster] LOG:  database system is ready to accept read-only connections
2024-05-03 17:10:56.075 UTC [22226][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-05-03 17:10:56.086 UTC [22230][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-05-03 17:10:56.111 UTC [22236][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:56.111 UTC [22236][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-05-03 17:10:56.111 UTC [22236][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:56.117 UTC [22236][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-05-03 17:10:56.120 UTC [22236][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:56.121 UTC [22236][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-05-03 17:10:56.125 UTC [22236][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.013 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-05-03 17:10:56.150 UTC [22220][postmaster] LOG:  received fast shutdown request
2024-05-03 17:10:56.150 UTC [22220][postmaster] LOG:  aborting any active transactions
2024-05-03 17:10:56.150 UTC [22230][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-05-03 17:10:56.156 UTC [22223][checkpointer] LOG:  shutting down
2024-05-03 17:10:56.167 UTC [22220][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: creating publication "pg_createsubscriber_16384_6cb1df81" 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-05-03 17:10:56.298 UTC [22256][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-05-03 17:10:56.298 UTC [22256][postmaster] LOG:  listening on Unix socket "/tmp/JlJLudBI1E/.s.PGSQL.49753"
2024-05-03 17:10:56.309 UTC [22260][startup] LOG:  database system was shut down in recovery at 2024-05-03 17:10:56 UTC
2024-05-03 17:10:56.310 UTC [22260][startup] LOG:  entering standby mode
2024-05-03 17:10:56.316 UTC [22260][startup] LOG:  redo starts at 0/3004738
2024-05-03 17:10:56.316 UTC [22260][startup] LOG:  consistent recovery state reached at 0/3004770
2024-05-03 17:10:56.316 UTC [22256][postmaster] LOG:  database system is ready to accept read-only connections
2024-05-03 17:10:56.316 UTC [22260][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-05-03 17:10:56.329 UTC [22262][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-05-03 17:10:56.405 UTC [22277][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:56.406 UTC [22277][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-05-03 17:10:56.406 UTC [22277][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:56.415 UTC [22277][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-05-03 17:10:56.416 UTC [22277][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:56.416 UTC [22277][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.010 user=postgres database=pg1 host=[local]
pg_createsubscriber: target server reached the consistent state
pg_createsubscriber: hint: If pg_createsubscriber fails after this point, you must recreate the physical replica before continuing.
2024-05-03 17:10:56.418 UTC [22280][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:56.418 UTC [22280][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-05-03 17:10:56.418 UTC [22280][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:56.420 UTC [22280][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_6cb1df81" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_6cb1df81" on database "pg1"
2024-05-03 17:10:56.421 UTC [22280][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_6cb1df81' 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_6cb1df81" on database "pg1"
2024-05-03 17:10:56.428 UTC [22280][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.010 user=postgres database=pg1 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-05-03 17:10:56.450 UTC [22256][postmaster] LOG:  received fast shutdown request
2024-05-03 17:10:56.450 UTC [22256][postmaster] LOG:  aborting any active transactions
2024-05-03 17:10:56.452 UTC [22262][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-05-03 17:10:56.453 UTC [22258][checkpointer] LOG:  shutting down
2024-05-03 17:10:56.459 UTC [22256][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7364822042391312052 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: Done!
[17:10:56.552](0.887s) 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=49751 host=/tmp/JlJLudBI1E dbname='pg1' --socket-directory /tmp/JlJLudBI1E --subscriber-port 49753 --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/JlJLudBI1E port=49751 dbname=pg1
pg_createsubscriber: subscriber(0): subscription: (auto) ; connection string: port=49753 host=/tmp/JlJLudBI1E fallback_application_name=pg_createsubscriber dbname=pg1
pg_createsubscriber: publisher(1): publication: Pub2 ; replication slot: replslot2 ; connection string: host=/tmp/JlJLudBI1E port=49751 dbname=pg2
pg_createsubscriber: subscriber(1): subscription: (auto) ; connection string: port=49753 host=/tmp/JlJLudBI1E fallback_application_name=pg_createsubscriber dbname=pg2
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7364821661409994093 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7364821661409994093 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 49753" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/JlJLudBI1E'"
2024-05-03 17:10:56.606 UTC [22313][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-05-03 17:10:56.606 UTC [22313][postmaster] LOG:  listening on Unix socket "/tmp/JlJLudBI1E/.s.PGSQL.49753"
2024-05-03 17:10:56.611 UTC [22318][startup] LOG:  database system was shut down in recovery at 2024-05-03 17:10:56 UTC
2024-05-03 17:10:56.611 UTC [22318][startup] LOG:  entering standby mode
2024-05-03 17:10:56.635 UTC [22318][startup] LOG:  redo starts at 0/3004738
2024-05-03 17:10:56.635 UTC [22318][startup] LOG:  consistent recovery state reached at 0/3004770
2024-05-03 17:10:56.635 UTC [22313][postmaster] LOG:  database system is ready to accept read-only connections
2024-05-03 17:10:56.636 UTC [22318][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-05-03 17:10:56.639 UTC [22323][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-05-03 17:10:56.704 UTC [22335][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:56.705 UTC [22335][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-05-03 17:10:56.705 UTC [22335][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:56.711 UTC [22335][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-05-03 17:10:56.712 UTC [22335][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:56.714 UTC [22335][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
2024-05-03 17:10:56.724 UTC [22335][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.019 user=postgres database=pg1 host=[local]
pg_createsubscriber: checking settings on publisher
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-05-03 17:10:56.755 UTC [22313][postmaster] LOG:  received fast shutdown request
2024-05-03 17:10:56.755 UTC [22313][postmaster] LOG:  aborting any active transactions
2024-05-03 17:10:56.759 UTC [22323][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-05-03 17:10:56.761 UTC [22316][checkpointer] LOG:  shutting down
2024-05-03 17:10:56.769 UTC [22313][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/JlJLudBI1E'' port=49751 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 49753" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/JlJLudBI1E'"
2024-05-03 17:10:56.987 UTC [22360][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-freebsd, compiled by clang-14.0.5, 64-bit
2024-05-03 17:10:56.987 UTC [22360][postmaster] LOG:  listening on Unix socket "/tmp/JlJLudBI1E/.s.PGSQL.49753"
2024-05-03 17:10:56.989 UTC [22363][startup] LOG:  database system was shut down in recovery at 2024-05-03 17:10:56 UTC
2024-05-03 17:10:56.989 UTC [22363][startup] LOG:  entering standby mode
2024-05-03 17:10:56.989 UTC [22363][startup] LOG:  redo starts at 0/3004738
2024-05-03 17:10:56.989 UTC [22363][startup] LOG:  consistent recovery state reached at 0/3004770
2024-05-03 17:10:56.989 UTC [22360][postmaster] LOG:  database system is ready to accept read-only connections
2024-05-03 17:10:56.989 UTC [22363][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-05-03 17:10:56.997 UTC [22364][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-05-03 17:10:57.084 UTC [22390][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:10:57.089 UTC [22390][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-05-03 17:10:57.089 UTC [22390][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:10:57.095 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-05-03 17:10:57.095 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:57.098 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:10:58.110 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/5:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:58.110 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/6:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:10:59.125 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/7:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:10:59.126 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/8:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:00.128 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/9:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:00.129 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/10:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:01.139 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/11:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:01.139 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/12:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:02.149 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/13:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:02.149 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/14:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:03.158 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/15:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:03.159 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/16:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:04.169 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/17:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:04.169 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/18:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:05.178 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/19:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:05.179 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/20:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:06.196 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/21:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:06.196 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/22:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:07.198 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/23:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:07.199 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/24:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:08.208 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/25:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:08.209 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/26:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:09.219 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/27:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-05-03 17:11:09.219 UTC [22390][client backend] [040_pg_createsubscriber.pl][0/28:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-05-03 17:11:10.005 UTC [22363][startup] LOG:  recovery stopping after WAL location (LSN) "0/30092C0"
2024-05-03 17:11:10.005 UTC [22363][startup] LOG:  redo done at 0/30092C0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 13.01 s
2024-05-03 17:11:10.005 UTC [22363][startup] LOG:  last completed transaction was at log time 2024-05-03 17:10:56.914876+00
2024-05-03 17:11:10.005 UTC [22364][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-05-03 17:11:10.015 UTC [22363][startup] LOG:  selected new timeline ID: 2
2024-05-03 17:11:10.031 UTC [22363][startup] LOG:  archive recovery complete
2024-05-03 17:11:10.031 UTC [22361][checkpointer] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-05-03 17:11:10.032 UTC [22361][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-05-03 17:11:10.034 UTC [22360][postmaster] LOG:  database system is ready to accept connections
2024-05-03 17:11:10.228 UTC [22390][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-05-03 17:11:10.229 UTC [22390][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:13.145 user=postgres database=pg1 host=[local]
2024-05-03 17:11:10.229 UTC [24769][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:11:10.230 UTC [24769][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-05-03 17:11:10.230 UTC [24769][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-05-03 17:11:10.231 UTC [24769][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-05-03 17:11:10.231 UTC [24769][client backend] [040_pg_createsubscriber.pl][1/3:0] LOG:  statement: DROP PUBLICATION "pub1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_d386178f" on database "pg1"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16384_d386178f" CONNECTION 'host=/tmp/JlJLudBI1E port=49751 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-05-03 17:11:10.232 UTC [24769][client backend] [040_pg_createsubscriber.pl][1/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16384_d386178f" CONNECTION 'host=/tmp/JlJLudBI1E port=49751 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-05-03 17:11:10.232 UTC [24769][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-05-03 17:11:10.244 UTC [24769][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_d386178f' 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-05-03 17:11:10.247 UTC [24769][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_d386178f" on database "pg1"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16384_d386178f" ENABLE
2024-05-03 17:11:10.247 UTC [24769][client backend] [040_pg_createsubscriber.pl][1/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16384_d386178f" ENABLE
2024-05-03 17:11:10.247 UTC [24769][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.018 user=postgres database=pg1 host=[local]
2024-05-03 17:11:10.249 UTC [24778][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-05-03 17:11:10.249 UTC [24778][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-05-03 17:11:10.249 UTC [24778][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=040_pg_createsubscriber.pl
2024-05-03 17:11:10.252 UTC [24777][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16384_d386178f" has started
2024-05-03 17:11:10.253 UTC [24778][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-05-03 17:11:10.254 UTC [24778][client backend] [040_pg_createsubscriber.pl][2/3:0] LOG:  statement: DROP PUBLICATION "Pub2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_3d7e4e44" on database "pg2"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16385_3d7e4e44" CONNECTION 'host=/tmp/JlJLudBI1E port=49751 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-05-03 17:11:10.254 UTC [24778][client backend] [040_pg_createsubscriber.pl][2/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16385_3d7e4e44" CONNECTION 'host=/tmp/JlJLudBI1E port=49751 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-05-03 17:11:10.254 UTC [24778][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-05-03 17:11:10.268 UTC [24778][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_3d7e4e44' 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-05-03 17:11:10.270 UTC [24778][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_3d7e4e44" on database "pg2"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16385_3d7e4e44" ENABLE
2024-05-03 17:11:10.271 UTC [24778][client backend] [040_pg_createsubscriber.pl][2/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16385_3d7e4e44" ENABLE
2024-05-03 17:11:10.271 UTC [24778][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.021 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-05-03 17:11:10.276 UTC [22360][postmaster] LOG:  received fast shutdown request
2024-05-03 17:11:10.276 UTC [22360][postmaster] LOG:  aborting any active transactions
2024-05-03 17:11:10.276 UTC [24777][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-05-03 17:11:10.276 UTC [24785][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16385_3d7e4e44" has started
2024-05-03 17:11:10.276 UTC [24785][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-05-03 17:11:10.278 UTC [22360][postmaster] LOG:  background worker "logical replication apply worker" (PID 24785) exited with exit code 1
2024-05-03 17:11:10.278 UTC [22360][postmaster] LOG:  background worker "logical replication apply worker" (PID 24777) exited with exit code 1
2024-05-03 17:11:10.278 UTC [22360][postmaster] LOG:  background worker "logical replication launcher" (PID 24749) exited with exit code 1
2024-05-03 17:11:10.278 UTC [22361][checkpointer] LOG:  shutting down
2024-05-03 17:11:10.278 UTC [22361][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-05-03 17:11:10.279 UTC [22361][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=23 kB, estimate=23 kB; lsn=0/300F1E8, redo lsn=0/300F1E8
2024-05-03 17:11:10.281 UTC [22360][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7364822101808957215 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!
[17:11:10.391](13.839s) ok 27 - run pg_createsubscriber on node S
[17:11:10.404](0.014s) 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 24814
Waiting for all subscriptions in "node_s" to synchronize data
Waiting for replication conn pg_createsubscriber_16384_d386178f'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_3d7e4e44's replay_lsn to pass 0/3009480 on node_p
done
done
[17:11:10.781](0.377s) ok 29 - logical replication works on database pg1
[17:11:10.797](0.016s) ok 30 - logical replication works on database pg2
[17:11:10.818](0.021s) 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"
[17:11:10.930](0.112s) 1..31
[17:11:10.944](0.014s) # Looks like you failed 1 test of 31.