# Running: pg_createsubscriber --help
[16:10:36.848](0.029s) ok 1 - pg_createsubscriber --help exit code 0
[16:10:36.848](0.000s) ok 2 - pg_createsubscriber --help goes to stdout
[16:10:36.848](0.000s) ok 3 - pg_createsubscriber --help nothing to stderr
[16:10:36.848](0.000s) ok 4 - pg_createsubscriber --help maximum line length
# Running: pg_createsubscriber --version
[16:10:36.870](0.022s) ok 5 - pg_createsubscriber --version exit code 0
[16:10:36.870](0.000s) ok 6 - pg_createsubscriber --version goes to stdout
[16:10:36.870](0.000s) ok 7 - pg_createsubscriber --version nothing to stderr
# Running: pg_createsubscriber --not-a-valid-option
[16:10:36.901](0.031s) ok 8 - pg_createsubscriber with invalid option nonzero exit code
[16:10:36.902](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.
[16:10:36.921](0.019s) ok 10 - no subscriber data directory specified
# Running: pg_createsubscriber --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_nr9F
pg_createsubscriber: error: no publisher connection string specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[16:10:36.941](0.020s) ok 11 - no publisher connection string specified
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_nr9F --publisher-server port=5432
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: no database was specified
pg_createsubscriber: error: no database name specified
pg_createsubscriber: hint: Try "pg_createsubscriber --help" for more information.
[16:10:36.956](0.015s) ok 12 - no database name specified
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_nr9F --publisher-server port=5432 --database pg1 --database pg1
pg_createsubscriber: error: duplicate database "pg1"
[16:10:36.976](0.020s) ok 13 - duplicate database name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_nr9F --publisher-server port=5432 --publication foo1 --publication foo1 --database pg1 --database pg2
pg_createsubscriber: error: duplicate publication "foo1"
[16:10:37.021](0.046s) ok 14 - duplicate publication name
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_nr9F --publisher-server port=5432 --publication foo1 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: error: wrong number of publication names
pg_createsubscriber: hint: Number of publication names (1) must match number of database names (2).
[16:10:37.049](0.027s) ok 15 - wrong number of publication names
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_nr9F --publisher-server port=5432 --publication foo1 --publication foo2 --subscription bar1 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: error: wrong number of subscription names
pg_createsubscriber: hint: Number of subscription names (1) must match number of database names (2).
[16:10:37.091](0.042s) ok 16 - wrong number of subscription names
# Running: pg_createsubscriber --verbose --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/tmp_test_nr9F --publisher-server port=5432 --publication foo1 --publication foo2 --subscription bar1 --subscription bar2 --replication-slot baz1 --database pg1 --database pg2
pg_createsubscriber: validating connection string on publisher
pg_createsubscriber: validating connection string on subscriber
pg_createsubscriber: error: wrong number of replication slot names
pg_createsubscriber: hint: Number of replication slot names (1) must match number of database names (2).
[16:10:37.107](0.016s) ok 17 - wrong number of replication slot names
# Checking port 60713
# Found port 60713
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=60713 host=/tmp/jaOpgBP8Hy
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/040_pg_createsubscriber_node_p.log
[16:10:37.115](0.008s) # 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 26736
# Checking port 60714
# Found port 60714
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=60714 host=/tmp/jaOpgBP8Hy
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/040_pg_createsubscriber_node_f.log
[16:10:37.353](0.238s) # 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/jaOpgBP8Hy -p 60713 --checkpoint fast --no-sync
# Backup finished
# Checking port 60715
# Found port 60715
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=60715 host=/tmp/jaOpgBP8Hy
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 27688
# Checking port 60716
# Found port 60716
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=60716 host=/tmp/jaOpgBP8Hy
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 27793
### 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=60713 host=/tmp/jaOpgBP8Hy dbname='pg1' --socket-directory /tmp/jaOpgBP8Hy --subscriber-port 60716 --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 7354415837656770723 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7354415837656770723 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-05 16:10:41.723 UTC [27909][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-04-05 16:10:41.723 UTC [27909][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60716"
2024-04-05 16:10:41.745 UTC [27915][startup] LOG:  database system was shut down at 2024-04-05 16:10:41 UTC
2024-04-05 16:10:41.754 UTC [27909][postmaster] LOG:  database system is ready to accept connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-05 16:10:41.794 UTC [27924][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:41.795 UTC [27924][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-04-05 16:10:41.795 UTC [27924][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:41.810 UTC [27924][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:41.811 UTC [27924][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
pg_createsubscriber: error: target server must be a standby
2024-04-05 16:10:41.811 UTC [27924][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.017 user=postgres database=pg1 host=[local]
2024-04-05 16:10:41.835 UTC [27909][postmaster] LOG:  received fast shutdown request
2024-04-05 16:10:41.835 UTC [27909][postmaster] LOG:  aborting any active transactions
2024-04-05 16:10:41.844 UTC [27909][postmaster] LOG:  background worker "logical replication launcher" (PID 27921) exited with exit code 1
2024-04-05 16:10:41.847 UTC [27913][checkpointer] LOG:  shutting down
2024-04-05 16:10:41.847 UTC [27913][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-04-05 16:10:41.848 UTC [27913][checkpointer] LOG:  checkpoint complete: wrote 6 buffers (4.7%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=17 kB, estimate=17 kB; lsn=0/30046A0, redo lsn=0/30046A0
2024-04-05 16:10:41.853 UTC [27909][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:10:42.172](4.819s) 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=60713 host=/tmp/jaOpgBP8Hy dbname='pg1' --socket-directory /tmp/jaOpgBP8Hy --subscriber-port 60715 --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 7354415837656770723 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7354415837656770723 on subscriber
pg_createsubscriber: error: standby is up and running
pg_createsubscriber: hint: Stop the standby and try again.
[16:10:42.207](0.036s) 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=60713 host=/tmp/jaOpgBP8Hy dbname='pg1' --socket-directory /tmp/jaOpgBP8Hy --subscriber-port 60714 --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 7354415837656770723 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7354416114018154755 on subscriber
pg_createsubscriber: error: subscriber data directory is not a copy of the source database cluster
[16:10:42.299](0.091s) 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/jaOpgBP8Hy -p 60715 --checkpoint fast --no-sync
# Backup finished
# Checking port 60717
# Found port 60717
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=60717 host=/tmp/jaOpgBP8Hy
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=60715 host=/tmp/jaOpgBP8Hy dbname='pg1' --socket-directory /tmp/jaOpgBP8Hy --subscriber-port 60717 --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 7354415837656770723 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7354415837656770723 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-05 16:10:43.165 UTC [28248][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-04-05 16:10:43.165 UTC [28248][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60717"
2024-04-05 16:10:43.197 UTC [28254][startup] LOG:  database system was interrupted while in recovery at log time 2024-04-05 16:10:40 UTC
2024-04-05 16:10:43.197 UTC [28254][startup] HINT:  If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.
2024-04-05 16:10:43.197 UTC [28254][startup] LOG:  starting backup recovery with redo LSN 0/2000028, checkpoint LSN 0/2000080, on timeline ID 1
2024-04-05 16:10:43.198 UTC [28254][startup] LOG:  entering standby mode
2024-04-05 16:10:43.199 UTC [28254][startup] LOG:  redo starts at 0/2000028
2024-04-05 16:10:43.199 UTC [28254][startup] LOG:  completed backup recovery with redo LSN 0/2000028 and end LSN 0/2000120
2024-04-05 16:10:43.199 UTC [28254][startup] LOG:  consistent recovery state reached at 0/3000000
2024-04-05 16:10:43.199 UTC [28248][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-05 16:10:43.231 UTC [28258][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-05 16:10:43.255 UTC [28265][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:43.256 UTC [28265][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-04-05 16:10:43.256 UTC [28265][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:43.281 UTC [28265][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:43.282 UTC [28265][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:43.282 UTC [28265][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-04-05 16:10:43.288 UTC [28265][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.034 user=postgres database=pg1 host=[local]
pg_createsubscriber: error: primary server cannot be in recovery
2024-04-05 16:10:43.314 UTC [28248][postmaster] LOG:  received fast shutdown request
2024-04-05 16:10:43.314 UTC [28248][postmaster] LOG:  aborting any active transactions
2024-04-05 16:10:43.319 UTC [28258][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-05 16:10:43.329 UTC [28252][checkpointer] LOG:  shutting down
2024-04-05 16:10:43.335 UTC [28248][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:10:43.632](1.333s) 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 28364
### 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=60713 host=/tmp/jaOpgBP8Hy dbname='pg1' --socket-directory /tmp/jaOpgBP8Hy --subscriber-port 60715 --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 7354415837656770723 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7354415837656770723 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-05 16:10:44.335 UTC [28456][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-04-05 16:10:44.335 UTC [28456][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60715"
2024-04-05 16:10:44.342 UTC [28468][startup] LOG:  database system was shut down in recovery at 2024-04-05 16:10:43 UTC
2024-04-05 16:10:44.342 UTC [28468][startup] LOG:  entering standby mode
2024-04-05 16:10:44.343 UTC [28468][startup] LOG:  consistent recovery state reached at 0/3000188
2024-04-05 16:10:44.343 UTC [28456][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-05 16:10:44.344 UTC [28468][startup] LOG:  invalid record length at 0/3000188: expected at least 24, got 0
2024-04-05 16:10:44.373 UTC [28470][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-04-05 16:10:44.374 UTC [28468][startup] LOG:  redo starts at 0/3000188
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-05 16:10:44.413 UTC [28488][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:44.414 UTC [28488][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-04-05 16:10:44.414 UTC [28488][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:44.440 UTC [28488][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:44.441 UTC [28488][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:44.442 UTC [28488][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-04-05 16:10:44.451 UTC [28488][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.045 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-04-05 16:10:44.521 UTC [28456][postmaster] LOG:  received fast shutdown request
2024-04-05 16:10:44.521 UTC [28456][postmaster] LOG:  aborting any active transactions
2024-04-05 16:10:44.521 UTC [28470][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-05 16:10:44.531 UTC [28466][checkpointer] LOG:  shutting down
2024-04-05 16:10:44.538 UTC [28456][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:10:44.752](1.120s) 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=60713 host=/tmp/jaOpgBP8Hy dbname='pg1' --socket-directory /tmp/jaOpgBP8Hy --subscriber-port 60715 --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 7354415837656770723 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7354415837656770723 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-05 16:10:44.882 UTC [28599][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-04-05 16:10:44.882 UTC [28599][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60715"
2024-04-05 16:10:44.892 UTC [28612][startup] LOG:  database system was shut down in recovery at 2024-04-05 16:10:44 UTC
2024-04-05 16:10:44.893 UTC [28612][startup] LOG:  entering standby mode
2024-04-05 16:10:44.901 UTC [28612][startup] LOG:  redo starts at 0/3000188
2024-04-05 16:10:44.901 UTC [28612][startup] LOG:  invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3004000, offset 16384
2024-04-05 16:10:44.901 UTC [28612][startup] LOG:  consistent recovery state reached at 0/3002758
2024-04-05 16:10:44.901 UTC [28599][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-05 16:10:44.901 UTC [28612][startup] LOG:  invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3004000, offset 16384
2024-04-05 16:10:44.914 UTC [28615][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-05 16:10:44.960 UTC [28624][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:44.961 UTC [28624][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-04-05 16:10:44.961 UTC [28624][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:44.976 UTC [28624][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:44.977 UTC [28624][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:44.977 UTC [28624][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: error: subscriber requires 2 replication slots, but only 1 remain
pg_createsubscriber: hint: Consider increasing max_replication_slots to at least 2.
pg_createsubscriber: error: subscriber requires 2 logical replication workers, but only 1 remain
pg_createsubscriber: hint: Consider increasing max_logical_replication_workers to at least 2.
pg_createsubscriber: error: subscriber requires 3 worker processes, but only 2 remain
pg_createsubscriber: hint: Consider increasing max_worker_processes to at least 3.
2024-04-05 16:10:44.982 UTC [28624][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.021 user=postgres database=pg1 host=[local]
2024-04-05 16:10:44.999 UTC [28599][postmaster] LOG:  received fast shutdown request
2024-04-05 16:10:44.999 UTC [28599][postmaster] LOG:  aborting any active transactions
2024-04-05 16:10:45.008 UTC [28615][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-05 16:10:45.012 UTC [28609][checkpointer] LOG:  shutting down
2024-04-05 16:10:45.018 UTC [28599][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:10:45.400](0.648s) 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 28711
# 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=60713 host=/tmp/jaOpgBP8Hy dbname='pg1' --socket-directory /tmp/jaOpgBP8Hy --subscriber-port 60715 --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 7354415837656770723 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7354415837656770723 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-05 16:10:45.735 UTC [28774][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-04-05 16:10:45.735 UTC [28774][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60715"
2024-04-05 16:10:45.749 UTC [28782][startup] LOG:  database system was shut down in recovery at 2024-04-05 16:10:45 UTC
2024-04-05 16:10:45.749 UTC [28782][startup] LOG:  entering standby mode
2024-04-05 16:10:45.751 UTC [28782][startup] LOG:  redo starts at 0/3000188
2024-04-05 16:10:45.751 UTC [28782][startup] LOG:  consistent recovery state reached at 0/30046C0
2024-04-05 16:10:45.751 UTC [28774][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-05 16:10:45.751 UTC [28782][startup] LOG:  invalid record length at 0/30046C0: expected at least 24, got 0
2024-04-05 16:10:45.800 UTC [28783][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-05 16:10:45.848 UTC [28801][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:45.849 UTC [28801][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-04-05 16:10:45.849 UTC [28801][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:45.868 UTC [28801][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:45.869 UTC [28801][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:45.869 UTC [28801][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-04-05 16:10:45.876 UTC [28801][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.038 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: stopping the subscriber
2024-04-05 16:10:45.908 UTC [28774][postmaster] LOG:  received fast shutdown request
2024-04-05 16:10:45.908 UTC [28774][postmaster] LOG:  aborting any active transactions
2024-04-05 16:10:45.916 UTC [28783][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-05 16:10:45.920 UTC [28780][checkpointer] LOG:  shutting down
2024-04-05 16:10:45.920 UTC [28780][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-04-05 16:10:45.920 UTC [28780][checkpointer] LOG:  restartpoint complete: wrote 4 buffers (3.1%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=17 kB, estimate=17 kB; lsn=0/30046C0, redo lsn=0/30046C0
2024-04-05 16:10:45.920 UTC [28780][checkpointer] LOG:  recovery restart point at 0/30046C0
2024-04-05 16:10:45.925 UTC [28774][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: creating publication "pub1" on database "pg1"
pg_createsubscriber: creating the replication slot "sub1" on database "pg1"
pg_createsubscriber: create replication slot "sub1" on publisher
pg_createsubscriber: creating publication "pub2" on database "pg2"
pg_createsubscriber: creating the replication slot "sub2" on database "pg2"
pg_createsubscriber: create replication slot "sub2" on publisher
pg_createsubscriber: starting the subscriber
2024-04-05 16:10:46.216 UTC [28876][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-04-05 16:10:46.216 UTC [28876][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60715"
2024-04-05 16:10:46.231 UTC [28885][startup] LOG:  database system was shut down in recovery at 2024-04-05 16:10:45 UTC
2024-04-05 16:10:46.231 UTC [28885][startup] LOG:  entering standby mode
2024-04-05 16:10:46.233 UTC [28885][startup] LOG:  redo starts at 0/3004738
2024-04-05 16:10:46.233 UTC [28885][startup] LOG:  consistent recovery state reached at 0/3004770
2024-04-05 16:10:46.233 UTC [28876][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-05 16:10:46.237 UTC [28885][startup] LOG:  invalid record length at 0/3004770: expected at least 24, got 0
2024-04-05 16:10:46.265 UTC [28889][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-04-05 16:10:46.276 UTC [28896][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:46.292 UTC [28896][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-04-05 16:10:46.292 UTC [28896][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:46.317 UTC [28896][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:46.323 UTC [28896][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
pg_createsubscriber: target server reached the consistent state
pg_createsubscriber: hint: If pg_createsubscriber fails after this point, you must recreate the physical replica before continuing.
2024-04-05 16:10:46.325 UTC [28896][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.049 user=postgres database=pg1 host=[local]
2024-04-05 16:10:46.330 UTC [28907][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:46.330 UTC [28907][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-04-05 16:10:46.330 UTC [28907][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:46.333 UTC [28907][client backend] [040_pg_createsubscriber.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pub1" on database "pg1"
pg_createsubscriber: creating subscription "sub1" on database "pg1"
2024-04-05 16:10:46.335 UTC [28907][client backend] [040_pg_createsubscriber.pl][1/3:0] LOG:  statement: SELECT s.oid FROM pg_catalog.pg_subscription s INNER JOIN pg_catalog.pg_database d ON (s.subdbid = d.oid) WHERE s.subname = 'sub1' AND d.datname = 'pg1'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "sub1" on database "pg1"
2024-04-05 16:10:46.343 UTC [28907][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.014 user=postgres database=pg1 host=[local]
2024-04-05 16:10:46.350 UTC [28913][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:46.351 UTC [28913][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-04-05 16:10:46.351 UTC [28913][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:46.385 UTC [28913][client backend] [040_pg_createsubscriber.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pub2" on database "pg2"
pg_createsubscriber: creating subscription "sub2" on database "pg2"
2024-04-05 16:10:46.386 UTC [28913][client backend] [040_pg_createsubscriber.pl][2/3:0] LOG:  statement: SELECT s.oid FROM pg_catalog.pg_subscription s INNER JOIN pg_catalog.pg_database d ON (s.subdbid = d.oid) WHERE s.subname = 'sub2' AND d.datname = 'pg2'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "sub2" on database "pg2"
2024-04-05 16:10:46.391 UTC [28913][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.042 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-04-05 16:10:46.410 UTC [28876][postmaster] LOG:  received fast shutdown request
2024-04-05 16:10:46.410 UTC [28876][postmaster] LOG:  aborting any active transactions
2024-04-05 16:10:46.415 UTC [28889][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-05 16:10:46.422 UTC [28883][checkpointer] LOG:  shutting down
2024-04-05 16:10:46.429 UTC [28876][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7354416152560091200 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: Done!
[16:10:46.757](1.356s) ok 24 - run pg_createsubscriber --dry-run on 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 29031
[16:10:46.960](0.203s) 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=60713 host=/tmp/jaOpgBP8Hy dbname='pg1' --socket-directory /tmp/jaOpgBP8Hy --subscriber-port 60715 --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 7354415837656770723 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7354415837656770723 on subscriber
pg_createsubscriber: starting the standby with command-line options
2024-04-05 16:10:47.289 UTC [29116][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-04-05 16:10:47.289 UTC [29116][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60715"
2024-04-05 16:10:47.309 UTC [29126][startup] LOG:  database system was shut down in recovery at 2024-04-05 16:10:46 UTC
2024-04-05 16:10:47.309 UTC [29126][startup] LOG:  entering standby mode
2024-04-05 16:10:47.311 UTC [29126][startup] LOG:  redo starts at 0/3004738
2024-04-05 16:10:47.311 UTC [29126][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-04-05 16:10:47.311 UTC [29116][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-05 16:10:47.321 UTC [29126][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-04-05 16:10:47.346 UTC [29132][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-05 16:10:47.374 UTC [29139][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:47.375 UTC [29139][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-04-05 16:10:47.375 UTC [29139][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:47.396 UTC [29139][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:47.397 UTC [29139][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:47.398 UTC [29139][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: checking settings on publisher
2024-04-05 16:10:47.413 UTC [29139][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.047 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: stopping the subscriber
2024-04-05 16:10:47.479 UTC [29116][postmaster] LOG:  received fast shutdown request
2024-04-05 16:10:47.479 UTC [29116][postmaster] LOG:  aborting any active transactions
2024-04-05 16:10:47.484 UTC [29132][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-05 16:10:47.507 UTC [29124][checkpointer] LOG:  shutting down
2024-04-05 16:10:47.512 UTC [29116][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: creating publication "pg_createsubscriber_16384_6ae2f7c4" 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-04-05 16:10:47.768 UTC [29200][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-04-05 16:10:47.768 UTC [29200][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60715"
2024-04-05 16:10:47.785 UTC [29209][startup] LOG:  database system was shut down in recovery at 2024-04-05 16:10:47 UTC
2024-04-05 16:10:47.785 UTC [29209][startup] LOG:  entering standby mode
2024-04-05 16:10:47.787 UTC [29209][startup] LOG:  redo starts at 0/3004738
2024-04-05 16:10:47.787 UTC [29209][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-04-05 16:10:47.787 UTC [29209][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-04-05 16:10:47.787 UTC [29200][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-04-05 16:10:47.829 UTC [29217][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:47.830 UTC [29217][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-04-05 16:10:47.830 UTC [29217][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:47.845 UTC [29212][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-04-05 16:10:47.865 UTC [29217][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:47.866 UTC [29217][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
pg_createsubscriber: target server reached the consistent state
pg_createsubscriber: hint: If pg_createsubscriber fails after this point, you must recreate the physical replica before continuing.
2024-04-05 16:10:47.867 UTC [29217][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.041 user=postgres database=pg1 host=[local]
2024-04-05 16:10:47.880 UTC [29220][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:47.881 UTC [29220][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-04-05 16:10:47.881 UTC [29220][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:47.883 UTC [29220][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_6ae2f7c4" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_6ae2f7c4" on database "pg1"
2024-04-05 16:10:47.884 UTC [29220][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_6ae2f7c4' 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_6ae2f7c4" on database "pg1"
2024-04-05 16:10:47.889 UTC [29220][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-04-05 16:10:47.904 UTC [29200][postmaster] LOG:  received fast shutdown request
2024-04-05 16:10:47.904 UTC [29200][postmaster] LOG:  aborting any active transactions
2024-04-05 16:10:47.909 UTC [29212][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-05 16:10:47.914 UTC [29206][checkpointer] LOG:  shutting down
2024-04-05 16:10:47.920 UTC [29200][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier of subscriber
pg_createsubscriber: system identifier is 7354416159051489686 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
pg_createsubscriber: Done!
[16:10:48.227](1.267s) 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=60713 host=/tmp/jaOpgBP8Hy dbname='pg1' --socket-directory /tmp/jaOpgBP8Hy --subscriber-port 60715 --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/jaOpgBP8Hy port=60713 dbname=pg1
pg_createsubscriber: subscriber(0): subscription: (auto) ; connection string: port=60715 host=/tmp/jaOpgBP8Hy fallback_application_name=pg_createsubscriber dbname=pg1
pg_createsubscriber: publisher(1): publication: Pub2 ; replication slot: replslot2 ; connection string: host=/tmp/jaOpgBP8Hy port=60713 dbname=pg2
pg_createsubscriber: subscriber(1): subscription: (auto) ; connection string: port=60715 host=/tmp/jaOpgBP8Hy fallback_application_name=pg_createsubscriber dbname=pg2
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7354415837656770723 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7354415837656770723 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 60715" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/jaOpgBP8Hy'"
2024-04-05 16:10:48.437 UTC [29352][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-04-05 16:10:48.438 UTC [29352][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60715"
2024-04-05 16:10:48.449 UTC [29364][startup] LOG:  database system was shut down in recovery at 2024-04-05 16:10:47 UTC
2024-04-05 16:10:48.449 UTC [29364][startup] LOG:  entering standby mode
2024-04-05 16:10:48.451 UTC [29364][startup] LOG:  redo starts at 0/3004738
2024-04-05 16:10:48.451 UTC [29364][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-04-05 16:10:48.451 UTC [29352][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-05 16:10:48.451 UTC [29364][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-04-05 16:10:48.477 UTC [29367][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-04-05 16:10:48.522 UTC [29384][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:48.522 UTC [29384][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-04-05 16:10:48.522 UTC [29384][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:48.536 UTC [29384][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:48.537 UTC [29384][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:48.538 UTC [29384][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT setting FROM pg_catalog.pg_settings WHERE name IN ('max_logical_replication_workers', 'max_replication_slots', 'max_worker_processes', 'primary_slot_name') ORDER BY name
pg_createsubscriber: subscriber: max_logical_replication_workers: 4
pg_createsubscriber: subscriber: max_replication_slots: 10
pg_createsubscriber: subscriber: max_worker_processes: 8
pg_createsubscriber: subscriber: primary_slot_name: physical_slot
pg_createsubscriber: checking settings on publisher
2024-04-05 16:10:48.546 UTC [29384][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.024 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-04-05 16:10:48.619 UTC [29352][postmaster] LOG:  received fast shutdown request
2024-04-05 16:10:48.619 UTC [29352][postmaster] LOG:  aborting any active transactions
2024-04-05 16:10:48.620 UTC [29367][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-05 16:10:48.629 UTC [29361][checkpointer] LOG:  shutting down
2024-04-05 16:10:48.634 UTC [29352][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/jaOpgBP8Hy'' port=60713 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 60715" -o "-c listen_addresses='' -c unix_socket_permissions=0700 -c unix_socket_directories='/tmp/jaOpgBP8Hy'"
2024-04-05 16:10:48.906 UTC [29480][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-04-05 16:10:48.906 UTC [29480][postmaster] LOG:  listening on Unix socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60715"
2024-04-05 16:10:48.920 UTC [29487][startup] LOG:  database system was shut down in recovery at 2024-04-05 16:10:48 UTC
2024-04-05 16:10:48.921 UTC [29487][startup] LOG:  entering standby mode
2024-04-05 16:10:48.922 UTC [29487][startup] LOG:  redo starts at 0/3004738
2024-04-05 16:10:48.923 UTC [29487][startup] LOG:  consistent recovery state reached at 0/3008C70
2024-04-05 16:10:48.923 UTC [29487][startup] LOG:  invalid record length at 0/3008C70: expected at least 24, got 0
2024-04-05 16:10:48.923 UTC [29480][postmaster] LOG:  database system is ready to accept read-only connections
2024-04-05 16:10:48.947 UTC [29489][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-04-05 16:10:48.989 UTC [29505][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:10:48.990 UTC [29505][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-04-05 16:10:48.990 UTC [29505][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:10:49.020 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-04-05 16:10:49.021 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:49.021 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/4:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:50.022 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/5:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:50.023 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/6:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:51.023 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/7:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:51.024 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/8:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:52.024 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/9:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:52.025 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/10:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:53.025 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/11:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:53.026 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/12:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:54.026 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/13:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:54.027 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/14:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:55.027 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/15:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:55.028 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/16:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:56.028 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/17:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:56.029 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/18:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:57.029 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/19:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:57.030 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/20:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:58.034 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/21:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:58.034 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/22:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:10:59.035 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/23:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:10:59.036 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/24:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:11:00.036 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/25:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-04-05 16:11:00.037 UTC [29505][client backend] [040_pg_createsubscriber.pl][0/26:0] LOG:  statement: SELECT 1 FROM pg_catalog.pg_stat_wal_receiver
2024-04-05 16:11:00.623 UTC [29487][startup] LOG:  recovery stopping after WAL location (LSN) "0/30092C0"
2024-04-05 16:11:00.623 UTC [29487][startup] LOG:  redo done at 0/30092C0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 11.70 s
2024-04-05 16:11:00.623 UTC [29487][startup] LOG:  last completed transaction was at log time 2024-04-05 16:10:48.752776+00
2024-04-05 16:11:00.623 UTC [29489][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-04-05 16:11:00.633 UTC [29487][startup] LOG:  selected new timeline ID: 2
2024-04-05 16:11:00.653 UTC [29487][startup] LOG:  archive recovery complete
2024-04-05 16:11:00.654 UTC [29485][checkpointer] LOG:  checkpoint starting: end-of-recovery immediate wait
2024-04-05 16:11:00.655 UTC [29485][checkpointer] LOG:  checkpoint complete: wrote 16 buffers (12.5%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=19 kB, estimate=19 kB; lsn=0/30092F8, redo lsn=0/30092F8
2024-04-05 16:11:00.667 UTC [29480][postmaster] LOG:  database system is ready to accept connections
2024-04-05 16:11:01.037 UTC [29505][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-04-05 16:11:01.038 UTC [29505][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:12.051 user=postgres database=pg1 host=[local]
2024-04-05 16:11:01.049 UTC [31957][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-04-05 16:11:01.050 UTC [31957][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-04-05 16:11:01.050 UTC [31957][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=040_pg_createsubscriber.pl
2024-04-05 16:11:01.054 UTC [31957][client backend] [040_pg_createsubscriber.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pub1" on database "pg1"
pg_createsubscriber: command is: DROP PUBLICATION "pub1"
2024-04-05 16:11:01.054 UTC [31957][client backend] [040_pg_createsubscriber.pl][1/3:0] LOG:  statement: DROP PUBLICATION "pub1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_6b856a8" on database "pg1"
pg_createsubscriber: command is: CREATE SUBSCRIPTION "pg_createsubscriber_16384_6b856a8" CONNECTION 'host=/tmp/jaOpgBP8Hy port=60713 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-04-05 16:11:01.062 UTC [31957][client backend] [040_pg_createsubscriber.pl][1/4:0] LOG:  statement: CREATE SUBSCRIPTION "pg_createsubscriber_16384_6b856a8" CONNECTION 'host=/tmp/jaOpgBP8Hy port=60713 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
2024-04-05 16:11:01.065 UTC [31957][client backend] [040_pg_createsubscriber.pl][1/4:748] ERROR:  could not connect to the publisher: connection to server on socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60713" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-04-05 16:11:01.065 UTC [31957][client backend] [040_pg_createsubscriber.pl][1/4:748] STATEMENT:  CREATE SUBSCRIPTION "pg_createsubscriber_16384_6b856a8" CONNECTION 'host=/tmp/jaOpgBP8Hy port=60713 dbname=pg1' PUBLICATION "pub1" WITH (create_slot = false, enabled = false, slot_name = 'replslot1', copy_data = false)
pg_createsubscriber: error: could not create subscription "pg_createsubscriber_16384_6b856a8" on database "pg1": ERROR:  could not connect to the publisher: connection to server on socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60713" failed: No such file or directory
	Is the server running locally and accepting connections on that socket?
pg_createsubscriber: warning: failed after the end of recovery
pg_createsubscriber: hint: The target server cannot be used as a physical replica anymore.  You must recreate the physical replica before continuing.
pg_createsubscriber: error: connection to database failed: connection to server on socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60713" failed: No such file or directory
	Is the server running locally and accepting connections on that socket?
pg_createsubscriber: warning: publication "pub1" in database "pg1" on primary might be left behind
pg_createsubscriber: hint: Consider dropping this publication before trying again.
pg_createsubscriber: warning: replication slot "replslot1" in database "pg1" on primary might be left behind
pg_createsubscriber: hint: Drop this replication slot soon to avoid retention of WAL files.
pg_createsubscriber: error: connection to database failed: connection to server on socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60713" failed: No such file or directory
	Is the server running locally and accepting connections on that socket?
pg_createsubscriber: warning: publication "Pub2" in database "pg2" on primary might be left behind
pg_createsubscriber: hint: Consider dropping this publication before trying again.
pg_createsubscriber: warning: replication slot "replslot2" in database "pg2" on primary might be left behind
pg_createsubscriber: hint: Drop this replication slot soon to avoid retention of WAL files.
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-04-05 16:11:01.070 UTC [31957][client backend] [040_pg_createsubscriber.pl][:0] LOG:  disconnection: session time: 0:00:00.024 user=postgres database=pg1 host=[local]
2024-04-05 16:11:01.075 UTC [29480][postmaster] LOG:  received fast shutdown request
2024-04-05 16:11:01.075 UTC [29480][postmaster] LOG:  aborting any active transactions
2024-04-05 16:11:01.089 UTC [29480][postmaster] LOG:  background worker "logical replication launcher" (PID 31897) exited with exit code 1
2024-04-05 16:11:01.093 UTC [29485][checkpointer] LOG:  shutting down
2024-04-05 16:11:01.093 UTC [29485][checkpointer] LOG:  checkpoint starting: shutdown immediate
2024-04-05 16:11:01.093 UTC [29485][checkpointer] LOG:  checkpoint complete: wrote 12 buffers (9.4%); 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=1 kB, estimate=17 kB; lsn=0/3009A98, redo lsn=0/3009A98
2024-04-05 16:11:01.102 UTC [29480][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
[16:11:01.403](13.177s) not ok 27 - run pg_createsubscriber on node S
[16:11:01.404](0.000s) 
[16:11:01.404](0.000s) #   Failed test 'run pg_createsubscriber on node S'
#   at t/040_pg_createsubscriber.pl line 297.
connection error: 'psql: error: connection to server on socket "/tmp/jaOpgBP8Hy/.s.PGSQL.60713" failed: No such file or directory
	Is the server running locally and accepting connections on that socket?'
while running 'psql -XAtq -d port=60713 host=/tmp/jaOpgBP8Hy dbname='pg1' -f - -v ON_ERROR_STOP=1' at /tmp/cirrus-ci-build/src/bin/pg_basebackup/../../../src/test/perl/PostgreSQL/Test/Cluster.pm line 2040.
# No postmaster PID for node "node_p"
# No postmaster PID for node "node_f"
# No postmaster PID for node "node_s"
# No postmaster PID for node "node_t"
# No postmaster PID for node "node_c"
[16:11:01.446](0.042s) # Tests were run but no plan was declared and done_testing() was not seen.
[16:11:01.446](0.000s) # Looks like your test exited with 29 just after 27.