# Running: pg_createsubscriber --help
[15:56:05.911](0.059s) ok 1 - pg_createsubscriber --help exit code 0
[15:56:05.911](0.000s) ok 2 - pg_createsubscriber --help goes to stdout
[15:56:05.911](0.000s) ok 3 - pg_createsubscriber --help nothing to stderr
[15:56:05.911](0.000s) ok 4 - pg_createsubscriber --help maximum line length
# Running: pg_createsubscriber --version
[15:56:05.933](0.022s) ok 5 - pg_createsubscriber --version exit code 0
[15:56:05.933](0.000s) ok 6 - pg_createsubscriber --version goes to stdout
[15:56:05.933](0.000s) ok 7 - pg_createsubscriber --version nothing to stderr
# Running: pg_createsubscriber --not-a-valid-option
[15:56:05.966](0.032s) ok 8 - pg_createsubscriber with invalid option nonzero exit code
[15:56:05.966](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.
[15:56:06.005](0.039s) ok 10 - no subscriber data directory specified
# Running: pg_createsubscriber --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_wZIU
pg_createsubscriber: error: no publisher connection string specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[15:56:06.023](0.018s) ok 11 - no publisher connection string specified
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_wZIU --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.
[15:56:06.066](0.042s) ok 12 - no database name specified
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_wZIU --publisher-server port=5432 --database pg1 --database pg1
pg_createsubscriber: error: duplicate database "pg1"
[15:56:06.094](0.028s) ok 13 - duplicate database name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_wZIU --publisher-server port=5432 --publication foo1 --publication foo1 --database pg1 --database pg2
pg_createsubscriber: error: duplicate publication "foo1"
[15:56:06.129](0.035s) ok 14 - duplicate publication name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_wZIU --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).
[15:56:06.176](0.046s) ok 15 - wrong number of publication names
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_wZIU --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).
[15:56:06.226](0.050s) ok 16 - wrong number of subscription names
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_wZIU --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).
[15:56:06.251](0.025s) ok 17 - wrong number of replication slot names
# Checking port 57965
# Found port 57965
Name: node_p
Data directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_p_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_p_data/backup
Archive directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_p_data/archives
Connection string: port=57965 host=/tmp/Cb095qtl7B
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/040_pg_createsubscriber_node_p.log
[15:56:06.294](0.043s) # initializing database system by copying initdb template
# Running: cp -RPp /tmp/cirrus-ci-build/tmp_install/initdb-template /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_p_data/pgdata
# Running: /tmp/cirrus-ci-build/src/bin/pg_basebackup/../../../src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_p_data/pgdata
### Starting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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 21693
# Checking port 57966
# Found port 57966
Name: node_f
Data directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_f_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_f_data/backup
Archive directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_f_data/archives
Connection string: port=57966 host=/tmp/Cb095qtl7B
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/040_pg_createsubscriber_node_f.log
[15:56:06.767](0.472s) # initializing database system by running initdb
# Running: initdb -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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:  C.UTF-8
  LC_CTYPE:    C.UTF-8
  LC_MESSAGES: C
  LC_MONETARY: C.UTF-8
  LC_NUMERIC:  C.UTF-8
  LC_TIME:     C.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/src/bin/pg_basebackup/tmp_check/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 ... Etc/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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_f_data/pgdata -l logfile start

# Running: /tmp/cirrus-ci-build/src/bin/pg_basebackup/../../../src/test/regress/pg_regress --config-auth /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_f_data/pgdata
# Taking pg_basebackup backup_1 from node "node_p"
# Running: pg_basebackup -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_p_data/backup/backup_1 -h /tmp/Cb095qtl7B -p 57965 --checkpoint fast --no-sync
# Backup finished
# Checking port 57967
# Found port 57967
Name: node_s
Data directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/backup
Archive directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/archives
Connection string: port=57967 host=/tmp/Cb095qtl7B
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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 22281
# Checking port 57968
# Found port 57968
Name: node_t
Data directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_t_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_t_data/backup
Archive directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_t_data/archives
Connection string: port=57968 host=/tmp/Cb095qtl7B
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_t_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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 22328
### Promoting node "node_t"
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_t_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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/src/bin/pg_basebackup/tmp_check/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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_t_data/pgdata --publisher-server port=57965 host=/tmp/Cb095qtl7B dbname='pg1' --socket-directory /tmp/Cb095qtl7B --subscriber-port 57968 --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/src/bin/pg_basebackup/tmp_check/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 7351072359928571248 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351072359928571248 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 15:56:12.782 UTC [22390][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-03-27 15:56:12.782 UTC [22390][postmaster] LOG:  listening on Unix socket "/tmp/Cb095qtl7B/.s.PGSQL.57968"
2024-03-27 15:56:12.799 UTC [22398][startup] LOG:  database system was shut down at 2024-03-27 15:56:12 UTC
2024-03-27 15:56:12.811 UTC [22390][postmaster] LOG:  database system is ready to accept connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-27 15:56:12.864 UTC [22409][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:12.865 UTC [22409][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_t_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:12.865 UTC [22409][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:12.901 UTC [22409][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 15:56:12.902 UTC [22409][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
pg_createsubscriber: error: target server must be a standby
2024-03-27 15:56:12.907 UTC [22409][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.045 user=postgres database=pg1 host=[local]
2024-03-27 15:56:12.934 UTC [22390][postmaster] LOG:  received fast shutdown request
2024-03-27 15:56:12.934 UTC [22390][postmaster] LOG:  aborting any active transactions
2024-03-27 15:56:12.938 UTC [22390][postmaster] LOG:  background worker "logical replication launcher" (PID 22401) exited with exit code 1
2024-03-27 15:56:12.939 UTC [22396][checkpointer] LOG:  shutting down
2024-03-27 15:56:12.939 UTC [22396][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-03-27 15:56:12.940 UTC [22396][checkpointer] LOG:  checkpoint complete: wrote 6 buffers (4.7%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=17 kB, estimate=17 kB; lsn=0/30046A0, redo lsn=0/30046A0
2024-03-27 15:56:12.943 UTC [22390][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[15:56:13.318](6.552s) ok 18 - target server is not in recovery
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=57965 host=/tmp/Cb095qtl7B dbname='pg1' --socket-directory /tmp/Cb095qtl7B --subscriber-port 57967 --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/src/bin/pg_basebackup/tmp_check/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 7351072359928571248 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351072359928571248 on subscriber
pg_createsubscriber: error: standby is up and running
pg_createsubscriber: hint: Stop the standby and try again.
[15:56:13.494](0.176s) ok 19 - standby is up and running
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_f_data/pgdata --publisher-server port=57965 host=/tmp/Cb095qtl7B dbname='pg1' --socket-directory /tmp/Cb095qtl7B --subscriber-port 57966 --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/src/bin/pg_basebackup/tmp_check/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 7351072359928571248 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351072609067967738 on subscriber
pg_createsubscriber: error: subscriber data directory is not a copy of the source database cluster
[15:56:13.657](0.163s) 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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/backup/backup_2 -h /tmp/Cb095qtl7B -p 57967 --checkpoint fast --no-sync
# Backup finished
# Checking port 57969
# Found port 57969
Name: node_c
Data directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_c_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_c_data/backup
Archive directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_c_data/archives
Connection string: port=57969 host=/tmp/Cb095qtl7B
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_c_data/pgdata --publisher-server port=57967 host=/tmp/Cb095qtl7B dbname='pg1' --socket-directory /tmp/Cb095qtl7B --subscriber-port 57969 --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/src/bin/pg_basebackup/tmp_check/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 7351072359928571248 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351072359928571248 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 15:56:14.518 UTC [22580][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-03-27 15:56:14.518 UTC [22580][postmaster] LOG:  listening on Unix socket "/tmp/Cb095qtl7B/.s.PGSQL.57969"
2024-03-27 15:56:14.529 UTC [22585][startup] LOG:  database system was interrupted while in recovery at log time 2024-03-27 15:56:10 UTC
2024-03-27 15:56:14.529 UTC [22585][startup] HINT:  If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2024-03-27 15:56:14.530 UTC [22585][startup] LOG:  starting backup recovery with redo LSN 0/2000028, checkpoint LSN 0/2000080, on timeline ID 1
2024-03-27 15:56:14.530 UTC [22585][startup] LOG:  entering standby mode
2024-03-27 15:56:14.531 UTC [22585][startup] LOG:  redo starts at 0/2000028
2024-03-27 15:56:14.531 UTC [22585][startup] LOG:  completed backup recovery with redo LSN 0/2000028 and end LSN 0/2000120
2024-03-27 15:56:14.532 UTC [22585][startup] LOG:  consistent recovery state reached at 0/3000000
2024-03-27 15:56:14.532 UTC [22580][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 15:56:14.544 UTC [22586][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-27 15:56:14.607 UTC [22592][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:14.608 UTC [22592][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_c_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:14.608 UTC [22592][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:14.636 UTC [22592][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 15:56:14.637 UTC [22592][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:14.638 UTC [22592][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-03-27 15:56:14.647 UTC [22592][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.041 user=postgres database=pg1 host=[local]
pg_createsubscriber: error: primary server cannot be in recovery
2024-03-27 15:56:14.689 UTC [22580][postmaster] LOG:  received fast shutdown request
2024-03-27 15:56:14.689 UTC [22580][postmaster] LOG:  aborting any active transactions
2024-03-27 15:56:14.693 UTC [22586][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 15:56:14.701 UTC [22582][checkpointer] LOG:  shutting down
2024-03-27 15:56:14.705 UTC [22580][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[15:56:15.068](1.411s) 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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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 22666
### Stopping node "node_s" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=57965 host=/tmp/Cb095qtl7B dbname='pg1' --socket-directory /tmp/Cb095qtl7B --subscriber-port 57967 --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/src/bin/pg_basebackup/tmp_check/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 7351072359928571248 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351072359928571248 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 15:56:15.650 UTC [22712][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-03-27 15:56:15.650 UTC [22712][postmaster] LOG:  listening on Unix socket "/tmp/Cb095qtl7B/.s.PGSQL.57967"
2024-03-27 15:56:15.683 UTC [22723][startup] LOG:  database system was shut down in recovery at 2024-03-27 15:56:15 UTC
2024-03-27 15:56:15.684 UTC [22723][startup] LOG:  entering standby mode
2024-03-27 15:56:15.685 UTC [22723][startup] LOG:  consistent recovery state reached at 0/3000188
2024-03-27 15:56:15.685 UTC [22723][startup] LOG:  invalid record length at 0/3000188: expected at least 24, got 0
2024-03-27 15:56:15.685 UTC [22712][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-27 15:56:15.717 UTC [22727][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-27 15:56:15.717 UTC [22723][startup] LOG:  redo starts at 0/3000188
2024-03-27 15:56:15.718 UTC [22730][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:15.718 UTC [22730][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:15.718 UTC [22730][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:15.744 UTC [22730][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 15:56:15.744 UTC [22730][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:15.754 UTC [22730][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-03-27 15:56:15.759 UTC [22730][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.041 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: error: publisher requires wal_level >= "logical"
pg_createsubscriber: error: publisher requires 2 replication slots, but only 0 remain
pg_createsubscriber: hint: Consider increasing max_replication_slots to at least 3.
pg_createsubscriber: error: publisher requires 2 wal sender processes, but only 0 remain
pg_createsubscriber: hint: Consider increasing max_wal_senders to at least 3.
2024-03-27 15:56:15.811 UTC [22712][postmaster] LOG:  received fast shutdown request
2024-03-27 15:56:15.811 UTC [22712][postmaster] LOG:  aborting any active transactions
2024-03-27 15:56:15.811 UTC [22727][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 15:56:15.819 UTC [22721][checkpointer] LOG:  shutting down
2024-03-27 15:56:15.823 UTC [22712][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[15:56:16.105](1.037s) ok 22 - primary contains unmet conditions on node P
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=57965 host=/tmp/Cb095qtl7B dbname='pg1' --socket-directory /tmp/Cb095qtl7B --subscriber-port 57967 --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/src/bin/pg_basebackup/tmp_check/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 7351072359928571248 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351072359928571248 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 15:56:16.329 UTC [22772][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-03-27 15:56:16.329 UTC [22772][postmaster] LOG:  listening on Unix socket "/tmp/Cb095qtl7B/.s.PGSQL.57967"
2024-03-27 15:56:16.366 UTC [22779][startup] LOG:  database system was shut down in recovery at 2024-03-27 15:56:15 UTC
2024-03-27 15:56:16.369 UTC [22779][startup] LOG:  entering standby mode
2024-03-27 15:56:16.371 UTC [22779][startup] LOG:  redo starts at 0/3000188
2024-03-27 15:56:16.381 UTC [22779][startup] LOG:  consistent recovery state reached at 0/30046C0
2024-03-27 15:56:16.381 UTC [22779][startup] LOG:  invalid record length at 0/30046C0: expected at least 24, got 0
2024-03-27 15:56:16.381 UTC [22772][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-27 15:56:16.398 UTC [22784][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:16.399 UTC [22784][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:16.399 UTC [22784][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:16.427 UTC [22784][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 15:56:16.428 UTC [22784][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:16.428 UTC [22784][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
2024-03-27 15:56:16.429 UTC [22782][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: error: subscriber requires 2 replication slots, but only 1 remain
pg_createsubscriber: hint: Consider increasing max_replication_slots to at least 2.
pg_createsubscriber: error: subscriber requires 2 logical replication workers, but only 1 remain
pg_createsubscriber: hint: Consider increasing max_logical_replication_workers to at least 2.
pg_createsubscriber: error: subscriber requires 3 worker processes, but only 2 remain
pg_createsubscriber: hint: Consider increasing max_worker_processes to at least 3.
2024-03-27 15:56:16.433 UTC [22784][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.035 user=postgres database=pg1 host=[local]
2024-03-27 15:56:16.451 UTC [22772][postmaster] LOG:  received fast shutdown request
2024-03-27 15:56:16.451 UTC [22772][postmaster] LOG:  aborting any active transactions
2024-03-27 15:56:16.451 UTC [22782][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 15:56:16.457 UTC [22777][checkpointer] LOG:  shutting down
2024-03-27 15:56:16.460 UTC [22772][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[15:56:16.748](0.643s) ok 23 - standby contains unmet conditions on node S
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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 22843
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=57965 host=/tmp/Cb095qtl7B dbname='pg1' --socket-directory /tmp/Cb095qtl7B --subscriber-port 57967 --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/src/bin/pg_basebackup/tmp_check/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 7351072359928571248 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351072359928571248 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 15:56:17.376 UTC [22925][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-03-27 15:56:17.377 UTC [22925][postmaster] LOG:  listening on Unix socket "/tmp/Cb095qtl7B/.s.PGSQL.57967"
2024-03-27 15:56:17.384 UTC [22936][startup] LOG:  database system was shut down in recovery at 2024-03-27 15:56:16 UTC
2024-03-27 15:56:17.385 UTC [22936][startup] LOG:  entering standby mode
2024-03-27 15:56:17.391 UTC [22936][startup] LOG:  redo starts at 0/3000188
2024-03-27 15:56:17.391 UTC [22936][startup] LOG:  consistent recovery state reached at 0/30046C0
2024-03-27 15:56:17.391 UTC [22925][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 15:56:17.391 UTC [22936][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-03-27 15:56:17.405 UTC [22938][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:17.405 UTC [22938][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:17.405 UTC [22938][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:17.423 UTC [22938][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 15:56:17.424 UTC [22938][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:17.425 UTC [22938][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-03-27 15:56:17.437 UTC [22938][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.039 user=postgres database=pg1 host=[local]
pg_createsubscriber: error: could not obtain replication slot information: got 0 rows, expected 1 row
2024-03-27 15:56:17.503 UTC [22925][postmaster] LOG:  received fast shutdown request
2024-03-27 15:56:17.503 UTC [22925][postmaster] LOG:  aborting any active transactions
2024-03-27 15:56:17.503 UTC [22937][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 15:56:17.508 UTC [22934][checkpointer] LOG:  shutting down
2024-03-27 15:56:17.512 UTC [22925][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[15:56:17.619](0.871s) not ok 24 - run pg_createsubscriber --dry-run on node S
[15:56:17.619](0.000s) 
[15:56:17.619](0.000s) #   Failed test 'run pg_createsubscriber --dry-run on node S'
#   at t/040_pg_createsubscriber.pl line 260.
### Starting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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 22956
[15:56:18.014](0.395s) ok 25 - standby is in recovery
### Stopping node "node_s" using mode fast
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=57965 host=/tmp/Cb095qtl7B dbname='pg1' --socket-directory /tmp/Cb095qtl7B --subscriber-port 57967 --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/src/bin/pg_basebackup/tmp_check/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 7351072359928571248 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351072359928571248 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-03-27 15:56:18.466 UTC [23016][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-03-27 15:56:18.466 UTC [23016][postmaster] LOG:  listening on Unix socket "/tmp/Cb095qtl7B/.s.PGSQL.57967"
2024-03-27 15:56:18.479 UTC [23022][startup] LOG:  database system was shut down in recovery at 2024-03-27 15:56:18 UTC
2024-03-27 15:56:18.480 UTC [23022][startup] LOG:  entering standby mode
2024-03-27 15:56:18.481 UTC [23022][startup] LOG:  redo starts at 0/3004738
2024-03-27 15:56:18.481 UTC [23022][startup] LOG:  consistent recovery state reached at 0/3004770
2024-03-27 15:56:18.481 UTC [23022][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-03-27 15:56:18.481 UTC [23016][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-27 15:56:18.507 UTC [23025][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:18.507 UTC [23025][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:18.507 UTC [23025][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:18.523 UTC [23023][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-27 15:56:18.552 UTC [23025][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 15:56:18.555 UTC [23025][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:18.556 UTC [23025][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-03-27 15:56:18.563 UTC [23025][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.057 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: stopping the subscriber
2024-03-27 15:56:18.644 UTC [23016][postmaster] LOG:  received fast shutdown request
2024-03-27 15:56:18.644 UTC [23016][postmaster] LOG:  aborting any active transactions
2024-03-27 15:56:18.644 UTC [23023][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 15:56:18.651 UTC [23020][checkpointer] LOG:  shutting down
2024-03-27 15:56:18.655 UTC [23016][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: creating publication "pg_createsubscriber_16384_ad2261a" on database "pg1"
pg_createsubscriber: creating the replication slot "replslot1" on database "pg1"
pg_createsubscriber: create replication slot "replslot1" on publisher
pg_createsubscriber: starting the subscriber
2024-03-27 15:56:18.927 UTC [23060][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-03-27 15:56:18.927 UTC [23060][postmaster] LOG:  listening on Unix socket "/tmp/Cb095qtl7B/.s.PGSQL.57967"
2024-03-27 15:56:18.947 UTC [23068][startup] LOG:  database system was shut down in recovery at 2024-03-27 15:56:18 UTC
2024-03-27 15:56:18.947 UTC [23068][startup] LOG:  entering standby mode
2024-03-27 15:56:18.951 UTC [23068][startup] LOG:  redo starts at 0/3004738
2024-03-27 15:56:18.951 UTC [23068][startup] LOG:  consistent recovery state reached at 0/3004770
2024-03-27 15:56:18.951 UTC [23068][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-03-27 15:56:18.951 UTC [23060][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 15:56:18.957 UTC [23071][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-03-27 15:56:18.986 UTC [23075][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:18.987 UTC [23075][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:18.987 UTC [23075][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:19.014 UTC [23075][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 15:56:19.016 UTC [23075][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
pg_createsubscriber: target server reached the consistent state
pg_createsubscriber: hint: If pg_createsubscriber fails after this point, you must recreate the physical replica before continuing.
2024-03-27 15:56:19.018 UTC [23075][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.032 user=postgres database=pg1 host=[local]
2024-03-27 15:56:19.029 UTC [23078][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:19.030 UTC [23078][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:19.030 UTC [23078][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:19.032 UTC [23078][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_ad2261a" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_ad2261a" on database "pg1"
2024-03-27 15:56:19.034 UTC [23078][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_ad2261a' 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_ad2261a" on database "pg1"
2024-03-27 15:56:19.040 UTC [23078][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.011 user=postgres database=pg1 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-27 15:56:19.086 UTC [23060][postmaster] LOG:  received fast shutdown request
2024-03-27 15:56:19.086 UTC [23060][postmaster] LOG:  aborting any active transactions
2024-03-27 15:56:19.088 UTC [23071][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 15:56:19.098 UTC [23066][checkpointer] LOG:  shutting down
2024-03-27 15:56:19.102 UTC [23060][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7351072660880255435 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: Done!
[15:56:19.332](1.318s) ok 26 - run pg_createsubscriber without --databases
# Running: pg_createsubscriber --verbose --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata --publisher-server port=57965 host=/tmp/Cb095qtl7B dbname='pg1' --socket-directory /tmp/Cb095qtl7B --subscriber-port 57967 --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/tmp_install/usr/local/pgsql/bin/pg_ctl
pg_createsubscriber: pg_resetwal path is:  /tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_resetwal
pg_createsubscriber: checking if directory "/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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/Cb095qtl7B port=57965 dbname=pg1
pg_createsubscriber: subscriber(0): subscription: (auto) ; connection string: port=57967 host=/tmp/Cb095qtl7B fallback_application_name=pg_createsubscriber dbname=pg1
pg_createsubscriber: publisher(1): publication: Pub2 ; replication slot: replslot2 ; connection string: host=/tmp/Cb095qtl7B port=57965 dbname=pg2
pg_createsubscriber: subscriber(1): subscription: (auto) ; connection string: port=57967 host=/tmp/Cb095qtl7B fallback_application_name=pg_createsubscriber dbname=pg2
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7351072359928571248 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7351072359928571248 on subscriber
pg_createsubscriber: starting the standby with command-line options
pg_createsubscriber: pg_ctl command is: "/tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_ctl" start -D "/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata" -s -o "-p 57967" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/Cb095qtl7B'"
2024-03-27 15:56:19.543 UTC [23139][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-03-27 15:56:19.544 UTC [23139][postmaster] LOG:  listening on Unix socket "/tmp/Cb095qtl7B/.s.PGSQL.57967"
2024-03-27 15:56:19.578 UTC [23144][startup] LOG:  database system was shut down in recovery at 2024-03-27 15:56:19 UTC
2024-03-27 15:56:19.578 UTC [23144][startup] LOG:  entering standby mode
2024-03-27 15:56:19.579 UTC [23144][startup] LOG:  redo starts at 0/3004738
2024-03-27 15:56:19.579 UTC [23144][startup] LOG:  consistent recovery state reached at 0/3004770
2024-03-27 15:56:19.579 UTC [23144][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-03-27 15:56:19.579 UTC [23139][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-27 15:56:19.623 UTC [23151][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:19.624 UTC [23151][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:19.624 UTC [23151][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:19.627 UTC [23148][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-27 15:56:19.681 UTC [23151][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 15:56:19.682 UTC [23151][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:19.682 UTC [23151][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: subscriber: max_logical_replication_workers: 4
pg_createsubscriber: subscriber: max_replication_slots: 10
pg_createsubscriber: subscriber: max_worker_processes: 8
pg_createsubscriber: subscriber: primary_slot_name: physical_slot
pg_createsubscriber: checking settings on publisher
2024-03-27 15:56:19.695 UTC [23151][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.073 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/tmp_install/usr/local/pgsql/bin/pg_ctl" stop -D "/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata" -s
2024-03-27 15:56:19.774 UTC [23139][postmaster] LOG:  received fast shutdown request
2024-03-27 15:56:19.774 UTC [23139][postmaster] LOG:  aborting any active transactions
2024-03-27 15:56:19.774 UTC [23148][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 15:56:19.784 UTC [23142][checkpointer] LOG:  shutting down
2024-03-27 15:56:19.788 UTC [23139][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/Cb095qtl7B'' port=57965 application_name=040_pg_createsubscriber.pl sslmode=prefer sslcompression=0 sslcertmode=allow sslsni=1 ssl_min_protocol_version=TLSv1.2 gssencmode=prefer krbsrvname=postgres gssdelegation=0 target_session_attrs=any load_balance_hosts=disable'
recovery_target = ''
recovery_target_timeline = 'latest'
recovery_target_inclusive = true
recovery_target_action = promote
recovery_target_name = ''
recovery_target_time = ''
recovery_target_xid = ''
recovery_target_lsn = '0/30092C0'
pg_createsubscriber: starting the subscriber
pg_createsubscriber: pg_ctl command is: "/tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_ctl" start -D "/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata" -s -o "-p 57967" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/Cb095qtl7B'"
2024-03-27 15:56:20.152 UTC [23167][postmaster] LOG:  starting PostgreSQL 17devel on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit
2024-03-27 15:56:20.152 UTC [23167][postmaster] LOG:  listening on Unix socket "/tmp/Cb095qtl7B/.s.PGSQL.57967"
2024-03-27 15:56:20.155 UTC [23170][startup] LOG:  database system was shut down in recovery at 2024-03-27 15:56:19 UTC
2024-03-27 15:56:20.155 UTC [23170][startup] LOG:  entering standby mode
2024-03-27 15:56:20.157 UTC [23170][startup] LOG:  redo starts at 0/3004738
2024-03-27 15:56:20.157 UTC [23170][startup] LOG:  consistent recovery state reached at 0/3004770
2024-03-27 15:56:20.157 UTC [23167][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-27 15:56:20.157 UTC [23170][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-03-27 15:56:20.216 UTC [23171][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-03-27 15:56:20.257 UTC [23175][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:20.259 UTC [23175][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:20.259 UTC [23175][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:20.306 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-27 15:56:20.306 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:20.307 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:21.308 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/5:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:21.308 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/6:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:22.308 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/7:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:22.309 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/8:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:23.309 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/9:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:23.314 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/10:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:24.314 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/11:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:24.314 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/12:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:25.315 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/13:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:25.342 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/14:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:26.342 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/15:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:26.342 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/16:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:27.343 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/17:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:27.343 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/18:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:28.344 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/19:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:28.344 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/20:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:29.344 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/21:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:29.345 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/22:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:30.345 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/23:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:30.345 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/24:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:31.346 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/25:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-27 15:56:31.346 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/26:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-03-27 15:56:31.938 UTC [23170][startup] LOG:  recovery stopping after WAL location (LSN) "0/30092C0"
2024-03-27 15:56:31.938 UTC [23170][startup] LOG:  redo done at 0/30092C0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 11.78 s
2024-03-27 15:56:31.938 UTC [23170][startup] LOG:  last completed transaction was at log time 2024-03-27 15:56:19.987768+00
2024-03-27 15:56:31.938 UTC [23171][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-27 15:56:31.947 UTC [23170][startup] LOG:  selected new timeline ID: 2
2024-03-27 15:56:31.967 UTC [23170][startup] LOG:  archive recovery complete
2024-03-27 15:56:31.968 UTC [23168][checkpointer] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-03-27 15:56:31.968 UTC [23168][checkpointer] LOG:  checkpoint complete: wrote 16 buffers (12.5%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=19 kB, estimate=19 kB; lsn=0/30092F8, redo lsn=0/30092F8
2024-03-27 15:56:31.994 UTC [23167][postmaster] LOG:  database system is ready to accept connections
2024-03-27 15:56:32.347 UTC [23175][client backend] [040_pg_createsubscriber.pl][0/27:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
pg_createsubscriber: target server reached the consistent state
pg_createsubscriber: hint: If pg_createsubscriber fails after this point, you must recreate the physical replica before continuing.
2024-03-27 15:56:32.347 UTC [23175][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:12.098 user=postgres database=pg1 host=[local]
2024-03-27 15:56:32.356 UTC [24226][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:32.357 UTC [24226][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:32.357 UTC [24226][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:32.359 UTC [24226][client backend] [040_pg_createsubscriber.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pub1" on database "pg1"
pg_createsubscriber: command is: DROP PUBLICATION "pub1"
2024-03-27 15:56:32.359 UTC [24226][client backend] [040_pg_createsubscriber.pl][1/3:0] LOG:  statement: DROP PUBLICATION "pub1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_d6ea08a0" on database "pg1"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16384_d6ea08a0" CONNECTION 'host=/tmp/Cb095qtl7B port=57965 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-03-27 15:56:32.362 UTC [24226][client backend] [040_pg_createsubscriber.pl][1/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16384_d6ea08a0" CONNECTION 'host=/tmp/Cb095qtl7B port=57965 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-03-27 15:56:32.377 UTC [24226][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_d6ea08a0' AND d.datname = 'pg1'
pg_createsubscriber: setting the replication progress (node name "pg_24588" ; LSN 0/30092C0) on database "pg1"
pg_createsubscriber: command is: SELECT pg_catalog.pg_replication_origin_advance('pg_24588', '0/30092C0')
2024-03-27 15:56:32.382 UTC [24226][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_d6ea08a0" on database "pg1"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16384_d6ea08a0" ENABLE
2024-03-27 15:56:32.383 UTC [24226][client backend] [040_pg_createsubscriber.pl][1/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16384_d6ea08a0" ENABLE
2024-03-27 15:56:32.385 UTC [24226][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.028 user=postgres database=pg1 host=[local]
2024-03-27 15:56:32.387 UTC [24237][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-27 15:56:32.388 UTC [24237][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata/pg_hba.conf:117)
2024-03-27 15:56:32.388 UTC [24237][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=040_pg_createsubscriber.pl
2024-03-27 15:56:32.409 UTC [24239][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16384_d6ea08a0" has started
2024-03-27 15:56:32.411 UTC [24237][client backend] [040_pg_createsubscriber.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "Pub2" on database "pg2"
pg_createsubscriber: command is: DROP PUBLICATION "Pub2"
2024-03-27 15:56:32.412 UTC [24237][client backend] [040_pg_createsubscriber.pl][2/3:0] LOG:  statement: DROP PUBLICATION "Pub2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_e660ef56" on database "pg2"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16385_e660ef56" CONNECTION 'host=/tmp/Cb095qtl7B port=57965 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-03-27 15:56:32.414 UTC [24237][client backend] [040_pg_createsubscriber.pl][2/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16385_e660ef56" CONNECTION 'host=/tmp/Cb095qtl7B port=57965 dbname=pg2' PUBLICATION "Pub2" WITH (create_slot = false, enabled = false, slot_name = 'replslot2', copy_data = false)
2024-03-27 15:56:32.555 UTC [24237][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_e660ef56' AND d.datname = 'pg2'
pg_createsubscriber: setting the replication progress (node name "pg_24589" ; LSN 0/30092C0) on database "pg2"
pg_createsubscriber: command is: SELECT pg_catalog.pg_replication_origin_advance('pg_24589', '0/30092C0')
2024-03-27 15:56:32.559 UTC [24237][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_e660ef56" on database "pg2"
pg_createsubscriber: command is: ALTER SUBSCRIPTION "pg_createsubscriber_16385_e660ef56" ENABLE
2024-03-27 15:56:32.560 UTC [24237][client backend] [040_pg_createsubscriber.pl][2/7:0] LOG:  statement: ALTER SUBSCRIPTION "pg_createsubscriber_16385_e660ef56" ENABLE
2024-03-27 15:56:32.563 UTC [24237][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.175 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/tmp_install/usr/local/pgsql/bin/pg_ctl" stop -D "/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata" -s
2024-03-27 15:56:32.608 UTC [24320][logical replication apply worker] LOG:  logical replication apply worker for subscription "pg_createsubscriber_16385_e660ef56" has started
2024-03-27 15:56:32.621 UTC [23167][postmaster] LOG:  received fast shutdown request
2024-03-27 15:56:32.621 UTC [23167][postmaster] LOG:  aborting any active transactions
2024-03-27 15:56:32.621 UTC [24239][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-03-27 15:56:32.631 UTC [23167][postmaster] LOG:  background worker "logical replication launcher" (PID 24207) exited with exit code 1
2024-03-27 15:56:32.631 UTC [23167][postmaster] LOG:  background worker "logical replication apply worker" (PID 24239) exited with exit code 1
2024-03-27 15:56:32.681 UTC [24320][logical replication apply worker] FATAL:  terminating logical replication worker due to administrator command
2024-03-27 15:56:32.702 UTC [23167][postmaster] LOG:  background worker "logical replication apply worker" (PID 24320) exited with exit code 1
2024-03-27 15:56:32.702 UTC [23168][checkpointer] LOG:  shutting down
2024-03-27 15:56:32.702 UTC [23168][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-03-27 15:56:32.702 UTC [23168][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=23 kB, estimate=23 kB; lsn=0/300F1E8, redo lsn=0/300F1E8
2024-03-27 15:56:32.707 UTC [23167][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7351072719134022215 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: pg_resetwal command is: "/tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_resetwal" -D "/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata" > "/dev/null"
pg_createsubscriber: subscriber successfully changed the system identifier
pg_createsubscriber: Done!
[15:56:33.002](13.670s) ok 27 - run pg_createsubscriber on node S
[15:56:33.098](0.096s) 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/src/bin/pg_basebackup/tmp_check/t_040_pg_createsubscriber_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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 24388
Waiting for all subscriptions in "node_s" to synchronize data
Waiting for replication conn pg_createsubscriber_16384_d6ea08a0'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_e660ef56's replay_lsn to pass 0/3009480 on node_p
done
done
[15:56:34.427](1.329s) ok 29 - logical replication works on database pg1
[15:56:34.496](0.069s) ok 30 - logical replication works on database pg2
[15:56:34.688](0.193s) ok 31 - system identifier was changed
### Stopping node "node_p" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/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/src/bin/pg_basebackup/tmp_check/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"
[15:56:34.858](0.170s) 1..31
[15:56:34.860](0.002s) # Looks like you failed 1 test of 31.