# Checking port 62858
# Found port 62858
Name: node_p
Data directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/backup
Archive directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/archives
Connection string: port=62858 host=/tmp/9Y_XCIGyyw
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log
[04:05:27.788](0.050s) # 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_041_tests_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_041_tests_node_p_data/pgdata
### Starting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log -o --cluster-name=node_p start
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 22891
# Taking pg_basebackup backup_1 from node "node_p"
# Running: pg_basebackup -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/backup/backup_1 -h /tmp/9Y_XCIGyyw -p 62858 --checkpoint fast --no-sync
# Backup finished
# Checking port 62859
# Found port 62859
Name: node_s
Data directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/backup
Archive directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/archives
Connection string: port=62859 host=/tmp/9Y_XCIGyyw
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_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_041_tests_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_s.log -o --cluster-name=node_s start
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 23081
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_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 23094
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:30.269 UTC [23129][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-11 04:05:30.269 UTC [23129][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:30.283 UTC [23136][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:30 UTC
2024-03-11 04:05:30.283 UTC [23136][startup] LOG:  entering standby mode
2024-03-11 04:05:30.284 UTC [23136][startup] LOG:  consistent recovery state reached at 0/30000A0
2024-03-11 04:05:30.284 UTC [23136][startup] LOG:  invalid record length at 0/30000A0: expected at least 24, got 0
2024-03-11 04:05:30.284 UTC [23129][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:30.322 UTC [23139][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:30.322 UTC [23136][startup] LOG:  redo starts at 0/30000A0
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:30.354 UTC [23152][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:30.355 UTC [23152][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:30.355 UTC [23152][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:30.384 UTC [23152][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:30.385 UTC [23152][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:30.385 UTC [23152][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:30.386 UTC [23152][client backend] [041_tests.pl][0/5: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-11 04:05:30.394 UTC [23152][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.044 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: error: publisher requires 3 replication slots, but only 2 remain
pg_createsubscriber: hint: Consider increasing max_replication_slots to at least 4.
[04:05:30.636](2.848s) ok 1 - max_replication_slots are less in number in publisher
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log restart
waiting for server to shut down....2024-03-11 04:05:30.679 UTC [23139][walreceiver] LOG:  replication terminated by primary server
2024-03-11 04:05:30.679 UTC [23139][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3004628.
2024-03-11 04:05:30.679 UTC [23139][walreceiver] FATAL:  could not send end-of-streaming message to primary: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
	no COPY in progress
2024-03-11 04:05:30.682 UTC [23136][startup] LOG:  invalid record length at 0/3004628: expected at least 24, got 0
2024-03-11 04:05:30.698 UTC [23205][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62858" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-11 04:05:30.698 UTC [23136][startup] LOG:  waiting for WAL to become available at 0/3004640
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 23209
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-11 04:05:30.986 UTC [23129][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:30.986 UTC [23129][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:30.993 UTC [23134][checkpointer] LOG:  shutting down
2024-03-11 04:05:30.993 UTC [23134][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-11 04:05:30.993 UTC [23134][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/30045B0, redo lsn=0/30045B0
2024-03-11 04:05:30.993 UTC [23134][checkpointer] LOG:  recovery restart point at 0/30045B0
2024-03-11 04:05:30.997 UTC [23129][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:31.240 UTC [23279][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-11 04:05:31.240 UTC [23279][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:31.260 UTC [23284][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:30 UTC
2024-03-11 04:05:31.260 UTC [23284][startup] LOG:  entering standby mode
2024-03-11 04:05:31.261 UTC [23284][startup] LOG:  consistent recovery state reached at 0/3004628
2024-03-11 04:05:31.261 UTC [23284][startup] LOG:  invalid record length at 0/3004628: expected at least 24, got 0
2024-03-11 04:05:31.261 UTC [23279][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:31.314 UTC [23286][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:31.315 UTC [23291][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:31.315 UTC [23291][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:31.315 UTC [23291][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:31.342 UTC [23291][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:31.343 UTC [23291][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:31.343 UTC [23291][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:31.346 UTC [23291][client backend] [041_tests.pl][0/5: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-11 04:05:31.359 UTC [23291][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.044 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_23233" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_23233" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_23233" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_23233" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-11 04:05:31.501 UTC [23279][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:31.501 UTC [23279][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:31.505 UTC [23286][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:31.509 UTC [23282][checkpointer] LOG:  shutting down
2024-03-11 04:05:31.513 UTC [23279][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-11 04:05:31.673 UTC [23321][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-11 04:05:31.673 UTC [23321][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:31.697 UTC [23324][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:31 UTC
2024-03-11 04:05:31.697 UTC [23324][startup] LOG:  entering standby mode
2024-03-11 04:05:31.698 UTC [23324][startup] LOG:  consistent recovery state reached at 0/3004628
2024-03-11 04:05:31.698 UTC [23324][startup] LOG:  invalid record length at 0/3004628: expected at least 24, got 0
2024-03-11 04:05:31.698 UTC [23321][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-03-11 04:05:31.745 UTC [23327][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:31.746 UTC [23327][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:31.746 UTC [23327][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:31.752 UTC [23325][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:31.752 UTC [23324][startup] LOG:  redo starts at 0/3004628
2024-03-11 04:05:31.768 UTC [23327][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:31.777 UTC [23327][client backend] [041_tests.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-11 04:05:31.779 UTC [23327][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.037 user=postgres database=pg1 host=[local]
2024-03-11 04:05:31.796 UTC [23328][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:31.796 UTC [23328][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:31.796 UTC [23328][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:31.798 UTC [23328][client backend] [041_tests.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_23233" on database "pg1"
2024-03-11 04:05:31.798 UTC [23328][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_23233'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_23233" on database "pg1"
2024-03-11 04:05:31.803 UTC [23328][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.011 user=postgres database=pg1 host=[local]
2024-03-11 04:05:31.812 UTC [23329][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:31.813 UTC [23329][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:31.813 UTC [23329][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-11 04:05:31.834 UTC [23329][client backend] [041_tests.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_23233" on database "pg2"
2024-03-11 04:05:31.838 UTC [23329][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_23233'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_23233" on database "pg2"
2024-03-11 04:05:31.840 UTC [23329][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.030 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-11 04:05:31.889 UTC [23321][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:31.889 UTC [23321][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:31.893 UTC [23325][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:31.896 UTC [23322][checkpointer] LOG:  shutting down
2024-03-11 04:05:31.900 UTC [23321][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344952129613982401 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-11 04:05:32.103 UTC [23341][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-11 04:05:32.103 UTC [23341][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:32.129 UTC [23344][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:31 UTC
2024-03-11 04:05:32.129 UTC [23344][startup] LOG:  entering standby mode
2024-03-11 04:05:32.133 UTC [23344][startup] LOG:  redo starts at 0/3004628
2024-03-11 04:05:32.133 UTC [23344][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-11 04:05:32.133 UTC [23341][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:32.133 UTC [23344][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-11 04:05:32.157 UTC [23345][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: Done!
[04:05:32.483](1.848s) ok 2 - max_replication_slots are accurate on publisher
### Restarting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_s.log restart
waiting for server to shut down....2024-03-11 04:05:32.506 UTC [23341][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:32.506 UTC [23341][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:32.506 UTC [23345][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:32.513 UTC [23342][checkpointer] LOG:  shutting down
2024-03-11 04:05:32.518 UTC [23341][postmaster] LOG:  database system is shut down
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 23390
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:33.144 UTC [23410][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-11 04:05:33.144 UTC [23410][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:33.157 UTC [23413][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:32 UTC
2024-03-11 04:05:33.157 UTC [23413][startup] LOG:  entering standby mode
2024-03-11 04:05:33.159 UTC [23413][startup] LOG:  redo starts at 0/3004628
2024-03-11 04:05:33.160 UTC [23413][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-11 04:05:33.160 UTC [23410][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:33.160 UTC [23413][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-11 04:05:33.199 UTC [23414][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-11 04:05:33.221 UTC [23418][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:33.222 UTC [23418][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:33.222 UTC [23418][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:33.241 UTC [23418][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:33.242 UTC [23418][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:33.243 UTC [23418][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:33.244 UTC [23418][client backend] [041_tests.pl][0/5: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.
2024-03-11 04:05:33.255 UTC [23418][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.042 user=postgres database=pg1 host=[local]
[04:05:33.547](1.064s) ok 3 - max_replication_slots are less in number in subscriber
### Restarting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_s.log restart
waiting for server to shut down....2024-03-11 04:05:33.562 UTC [23410][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:33.562 UTC [23410][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:33.569 UTC [23414][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:33.575 UTC [23411][checkpointer] LOG:  shutting down
2024-03-11 04:05:33.579 UTC [23410][postmaster] LOG:  database system is shut down
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 23422
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:34.269 UTC [23453][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-11 04:05:34.269 UTC [23453][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:34.308 UTC [23456][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:34 UTC
2024-03-11 04:05:34.308 UTC [23456][startup] LOG:  entering standby mode
2024-03-11 04:05:34.310 UTC [23456][startup] LOG:  redo starts at 0/3004628
2024-03-11 04:05:34.310 UTC [23456][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-11 04:05:34.310 UTC [23456][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-11 04:05:34.310 UTC [23453][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:34.355 UTC [23459][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:34.356 UTC [23459][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:34.356 UTC [23459][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:34.360 UTC [23457][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:34.381 UTC [23459][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:34.389 UTC [23459][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:34.390 UTC [23459][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:34.391 UTC [23459][client backend] [041_tests.pl][0/5: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-11 04:05:34.396 UTC [23459][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.052 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_23428" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_23428" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_23428" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_23428" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-11 04:05:34.603 UTC [23453][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:34.603 UTC [23453][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:34.603 UTC [23457][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:34.607 UTC [23454][checkpointer] LOG:  shutting down
2024-03-11 04:05:34.611 UTC [23453][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-11 04:05:34.810 UTC [23479][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-11 04:05:34.810 UTC [23479][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:34.825 UTC [23484][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:34 UTC
2024-03-11 04:05:34.825 UTC [23484][startup] LOG:  entering standby mode
2024-03-11 04:05:34.826 UTC [23484][startup] LOG:  redo starts at 0/3004628
2024-03-11 04:05:34.827 UTC [23484][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-11 04:05:34.827 UTC [23484][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-11 04:05:34.827 UTC [23479][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:34.856 UTC [23485][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-11 04:05:34.945 UTC [23489][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:34.946 UTC [23489][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:34.946 UTC [23489][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:34.982 UTC [23489][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:34.983 UTC [23489][client backend] [041_tests.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-11 04:05:34.984 UTC [23489][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.039 user=postgres database=pg1 host=[local]
2024-03-11 04:05:35.027 UTC [23490][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:35.028 UTC [23490][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:35.028 UTC [23490][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:35.032 UTC [23490][client backend] [041_tests.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_23428" on database "pg1"
2024-03-11 04:05:35.033 UTC [23490][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_23428'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_23428" on database "pg1"
2024-03-11 04:05:35.040 UTC [23490][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.029 user=postgres database=pg1 host=[local]
2024-03-11 04:05:35.046 UTC [23491][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:35.047 UTC [23491][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:35.047 UTC [23491][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-11 04:05:35.082 UTC [23491][client backend] [041_tests.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_23428" on database "pg2"
2024-03-11 04:05:35.091 UTC [23491][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_23428'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_23428" on database "pg2"
2024-03-11 04:05:35.093 UTC [23491][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.048 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-11 04:05:35.143 UTC [23479][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:35.143 UTC [23479][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:35.143 UTC [23485][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:35.151 UTC [23482][checkpointer] LOG:  shutting down
2024-03-11 04:05:35.155 UTC [23479][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344952143388818308 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-11 04:05:35.488 UTC [23537][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-11 04:05:35.489 UTC [23537][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:35.523 UTC [23540][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:35 UTC
2024-03-11 04:05:35.523 UTC [23540][startup] LOG:  entering standby mode
2024-03-11 04:05:35.525 UTC [23540][startup] LOG:  redo starts at 0/3004628
2024-03-11 04:05:35.525 UTC [23540][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-11 04:05:35.525 UTC [23540][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-11 04:05:35.525 UTC [23537][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: Done!
2024-03-11 04:05:35.579 UTC [23541][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
[04:05:36.012](2.465s) ok 4 - max_replication_slots are less in number in subscriber
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log restart
waiting for server to shut down....2024-03-11 04:05:36.063 UTC [23541][walreceiver] LOG:  replication terminated by primary server
2024-03-11 04:05:36.063 UTC [23541][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008BB0.
2024-03-11 04:05:36.063 UTC [23541][walreceiver] FATAL:  could not send end-of-streaming message to primary: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
	no COPY in progress
2024-03-11 04:05:36.066 UTC [23540][startup] LOG:  invalid record length at 0/3008BB0: expected at least 24, got 0
2024-03-11 04:05:36.104 UTC [23563][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62858" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-11 04:05:36.104 UTC [23540][startup] LOG:  waiting for WAL to become available at 0/3008BC8
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 23570
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-11 04:05:36.566 UTC [23537][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:36.566 UTC [23537][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:36.573 UTC [23538][checkpointer] LOG:  shutting down
2024-03-11 04:05:36.573 UTC [23538][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-11 04:05:36.574 UTC [23538][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/3008B38, redo lsn=0/3008B38
2024-03-11 04:05:36.574 UTC [23538][checkpointer] LOG:  recovery restart point at 0/3008B38
2024-03-11 04:05:36.577 UTC [23537][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:36.869 UTC [23614][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-11 04:05:36.870 UTC [23614][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:36.884 UTC [23618][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:36 UTC
2024-03-11 04:05:36.884 UTC [23618][startup] LOG:  entering standby mode
2024-03-11 04:05:36.885 UTC [23618][startup] LOG:  consistent recovery state reached at 0/3008BB0
2024-03-11 04:05:36.885 UTC [23618][startup] LOG:  invalid record length at 0/3008BB0: expected at least 24, got 0
2024-03-11 04:05:36.885 UTC [23614][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:36.928 UTC [23620][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:36.928 UTC [23618][startup] LOG:  redo starts at 0/3008BB0
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:36.996 UTC [23624][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:36.997 UTC [23624][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:36.997 UTC [23624][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:37.040 UTC [23624][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:37.041 UTC [23624][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:37.041 UTC [23624][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:37.059 UTC [23624][client backend] [041_tests.pl][0/5: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-11 04:05:37.065 UTC [23624][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.069 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: error: publisher requires wal_level >= logical
[04:05:37.514](1.502s) ok 5 - wal_level must be logical
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log restart
waiting for server to shut down....2024-03-11 04:05:37.551 UTC [23620][walreceiver] LOG:  replication terminated by primary server
2024-03-11 04:05:37.551 UTC [23620][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008C60.
2024-03-11 04:05:37.551 UTC [23620][walreceiver] FATAL:  could not send end-of-streaming message to primary: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
	no COPY in progress
2024-03-11 04:05:37.555 UTC [23618][startup] LOG:  invalid record length at 0/3008C60: expected at least 24, got 0
2024-03-11 04:05:37.577 UTC [23657][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62858" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-11 04:05:37.577 UTC [23618][startup] LOG:  waiting for WAL to become available at 0/3008C78
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 23660
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-11 04:05:37.890 UTC [23614][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:37.890 UTC [23614][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:37.896 UTC [23616][checkpointer] LOG:  shutting down
2024-03-11 04:05:37.896 UTC [23616][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-11 04:05:37.896 UTC [23616][checkpointer] LOG:  restartpoint complete: wrote 1 buffers (0.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB; lsn=0/3008BE8, redo lsn=0/3008BE8
2024-03-11 04:05:37.896 UTC [23616][checkpointer] LOG:  recovery restart point at 0/3008BE8
2024-03-11 04:05:37.901 UTC [23614][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:38.164 UTC [23706][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-11 04:05:38.164 UTC [23706][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:38.181 UTC [23710][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:37 UTC
2024-03-11 04:05:38.181 UTC [23710][startup] LOG:  entering standby mode
2024-03-11 04:05:38.183 UTC [23710][startup] LOG:  consistent recovery state reached at 0/3008C60
2024-03-11 04:05:38.183 UTC [23710][startup] LOG:  invalid record length at 0/3008C60: expected at least 24, got 0
2024-03-11 04:05:38.183 UTC [23706][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:38.201 UTC [23712][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:38.202 UTC [23712][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:38.202 UTC [23712][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:38.216 UTC [23711][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:38.216 UTC [23710][startup] LOG:  redo starts at 0/3008C60
2024-03-11 04:05:38.247 UTC [23712][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:38.250 UTC [23712][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:38.251 UTC [23712][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:38.252 UTC [23712][client backend] [041_tests.pl][0/5: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-11 04:05:38.263 UTC [23712][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.063 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_23670" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_23670" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_23670" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_23670" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-11 04:05:38.477 UTC [23706][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:38.477 UTC [23706][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:38.481 UTC [23711][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:38.488 UTC [23708][checkpointer] LOG:  shutting down
2024-03-11 04:05:38.493 UTC [23706][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-11 04:05:38.715 UTC [23732][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-11 04:05:38.715 UTC [23732][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:38.730 UTC [23735][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:38 UTC
2024-03-11 04:05:38.731 UTC [23735][startup] LOG:  entering standby mode
2024-03-11 04:05:38.732 UTC [23735][startup] LOG:  redo starts at 0/3008C60
2024-03-11 04:05:38.732 UTC [23735][startup] LOG:  consistent recovery state reached at 0/3008C98
2024-03-11 04:05:38.732 UTC [23735][startup] LOG:  invalid record length at 0/3008C98: expected at least 24, got 0
2024-03-11 04:05:38.732 UTC [23732][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:38.775 UTC [23736][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-11 04:05:38.790 UTC [23738][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:38.791 UTC [23738][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:38.791 UTC [23738][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:38.815 UTC [23738][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:38.818 UTC [23738][client backend] [041_tests.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-11 04:05:38.819 UTC [23738][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.031 user=postgres database=pg1 host=[local]
2024-03-11 04:05:38.829 UTC [23742][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:38.830 UTC [23742][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:38.830 UTC [23742][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:38.834 UTC [23742][client backend] [041_tests.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_23670" on database "pg1"
2024-03-11 04:05:38.834 UTC [23742][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_23670'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_23670" on database "pg1"
2024-03-11 04:05:38.838 UTC [23742][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.009 user=postgres database=pg1 host=[local]
2024-03-11 04:05:38.855 UTC [23744][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:38.856 UTC [23744][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:38.856 UTC [23744][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-11 04:05:38.880 UTC [23744][client backend] [041_tests.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_23670" on database "pg2"
2024-03-11 04:05:38.880 UTC [23744][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_23670'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_23670" on database "pg2"
2024-03-11 04:05:38.891 UTC [23744][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.039 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-11 04:05:38.929 UTC [23732][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:38.929 UTC [23732][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:38.930 UTC [23736][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:38.934 UTC [23733][checkpointer] LOG:  shutting down
2024-03-11 04:05:38.938 UTC [23732][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344952160041864310 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-11 04:05:39.174 UTC [23770][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-11 04:05:39.174 UTC [23770][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:39.193 UTC [23778][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:38 UTC
2024-03-11 04:05:39.193 UTC [23778][startup] LOG:  entering standby mode
2024-03-11 04:05:39.194 UTC [23778][startup] LOG:  redo starts at 0/3008C60
2024-03-11 04:05:39.194 UTC [23778][startup] LOG:  consistent recovery state reached at 0/3008C98
2024-03-11 04:05:39.194 UTC [23778][startup] LOG:  invalid record length at 0/3008C98: expected at least 24, got 0
2024-03-11 04:05:39.195 UTC [23770][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: Done!
2024-03-11 04:05:39.235 UTC [23781][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
[04:05:39.380](1.866s) ok 6 - wal_level is logical
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log restart
waiting for server to shut down....2024-03-11 04:05:39.422 UTC [23781][walreceiver] LOG:  replication terminated by primary server
2024-03-11 04:05:39.422 UTC [23781][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008D10.
2024-03-11 04:05:39.422 UTC [23781][walreceiver] FATAL:  could not send end-of-streaming message to primary: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
	no COPY in progress
2024-03-11 04:05:39.426 UTC [23778][startup] LOG:  invalid record length at 0/3008D10: expected at least 24, got 0
2024-03-11 04:05:39.439 UTC [23802][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62858" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-11 04:05:39.439 UTC [23778][startup] LOG:  waiting for WAL to become available at 0/3008D28
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 23806
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-11 04:05:39.694 UTC [23770][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:39.694 UTC [23770][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:39.701 UTC [23776][checkpointer] LOG:  shutting down
2024-03-11 04:05:39.701 UTC [23776][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-11 04:05:39.702 UTC [23776][checkpointer] LOG:  restartpoint complete: wrote 1 buffers (0.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB; lsn=0/3008C98, redo lsn=0/3008C98
2024-03-11 04:05:39.702 UTC [23776][checkpointer] LOG:  recovery restart point at 0/3008C98
2024-03-11 04:05:39.706 UTC [23770][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:39.925 UTC [23849][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-11 04:05:39.925 UTC [23849][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:39.949 UTC [23864][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:39 UTC
2024-03-11 04:05:39.950 UTC [23864][startup] LOG:  entering standby mode
2024-03-11 04:05:39.952 UTC [23864][startup] LOG:  consistent recovery state reached at 0/3008D10
2024-03-11 04:05:39.952 UTC [23849][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:39.952 UTC [23864][startup] LOG:  invalid record length at 0/3008D10: expected at least 24, got 0
2024-03-11 04:05:39.969 UTC [23867][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:39.970 UTC [23864][startup] LOG:  redo starts at 0/3008D10
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:39.989 UTC [23872][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:39.991 UTC [23872][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:39.991 UTC [23872][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:40.027 UTC [23872][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:40.028 UTC [23872][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:40.030 UTC [23872][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:40.031 UTC [23872][client backend] [041_tests.pl][0/5: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-11 04:05:40.042 UTC [23872][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.054 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: error: publisher requires 2 wal sender processes, but only 1 remain
pg_createsubscriber: hint: Consider increasing max_wal_senders to at least 3.
[04:05:40.251](0.871s) ok 7 - max_wal_senders is not sufficient
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log restart
waiting for server to shut down....2024-03-11 04:05:40.292 UTC [23867][walreceiver] LOG:  replication terminated by primary server
2024-03-11 04:05:40.292 UTC [23867][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008DC0.
2024-03-11 04:05:40.292 UTC [23867][walreceiver] FATAL:  could not send end-of-streaming message to primary: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
	no COPY in progress
2024-03-11 04:05:40.295 UTC [23864][startup] LOG:  invalid record length at 0/3008DC0: expected at least 24, got 0
2024-03-11 04:05:40.313 UTC [23994][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62858" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-11 04:05:40.313 UTC [23864][startup] LOG:  waiting for WAL to become available at 0/3008DD8
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 24005
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-11 04:05:40.724 UTC [23849][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:40.724 UTC [23849][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:40.731 UTC [23858][checkpointer] LOG:  shutting down
2024-03-11 04:05:40.731 UTC [23858][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-11 04:05:40.731 UTC [23858][checkpointer] LOG:  restartpoint complete: wrote 1 buffers (0.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB; lsn=0/3008D48, redo lsn=0/3008D48
2024-03-11 04:05:40.731 UTC [23858][checkpointer] LOG:  recovery restart point at 0/3008D48
2024-03-11 04:05:40.735 UTC [23849][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:41.072 UTC [24077][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-11 04:05:41.072 UTC [24077][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:41.108 UTC [24081][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:40 UTC
2024-03-11 04:05:41.108 UTC [24081][startup] LOG:  entering standby mode
2024-03-11 04:05:41.109 UTC [24081][startup] LOG:  consistent recovery state reached at 0/3008DC0
2024-03-11 04:05:41.109 UTC [24081][startup] LOG:  invalid record length at 0/3008DC0: expected at least 24, got 0
2024-03-11 04:05:41.109 UTC [24077][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:41.160 UTC [24082][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:41.161 UTC [24084][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:41.162 UTC [24084][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:41.162 UTC [24084][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:41.168 UTC [24081][startup] LOG:  redo starts at 0/3008DC0
2024-03-11 04:05:41.219 UTC [24084][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:41.225 UTC [24084][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:41.227 UTC [24084][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:41.229 UTC [24084][client backend] [041_tests.pl][0/5: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-11 04:05:41.247 UTC [24084][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.087 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_24020" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_24020" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_24020" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_24020" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-11 04:05:41.541 UTC [24077][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:41.541 UTC [24077][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:41.541 UTC [24082][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:41.549 UTC [24079][checkpointer] LOG:  shutting down
2024-03-11 04:05:41.554 UTC [24077][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-11 04:05:41.738 UTC [24101][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-11 04:05:41.738 UTC [24101][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:41.762 UTC [24106][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:41 UTC
2024-03-11 04:05:41.762 UTC [24106][startup] LOG:  entering standby mode
2024-03-11 04:05:41.764 UTC [24106][startup] LOG:  redo starts at 0/3008DC0
2024-03-11 04:05:41.764 UTC [24106][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-11 04:05:41.764 UTC [24106][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
2024-03-11 04:05:41.764 UTC [24101][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-03-11 04:05:41.785 UTC [24108][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:41.786 UTC [24108][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:41.786 UTC [24108][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:41.790 UTC [24107][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:41.820 UTC [24108][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:41.820 UTC [24108][client backend] [041_tests.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-11 04:05:41.822 UTC [24108][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.037 user=postgres database=pg1 host=[local]
2024-03-11 04:05:41.828 UTC [24110][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:41.829 UTC [24110][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:41.829 UTC [24110][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:41.835 UTC [24110][client backend] [041_tests.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_24020" on database "pg1"
2024-03-11 04:05:41.835 UTC [24110][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_24020'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_24020" on database "pg1"
2024-03-11 04:05:41.838 UTC [24110][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.010 user=postgres database=pg1 host=[local]
2024-03-11 04:05:41.851 UTC [24111][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:41.851 UTC [24111][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:41.851 UTC [24111][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-11 04:05:41.873 UTC [24111][client backend] [041_tests.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_24020" on database "pg2"
2024-03-11 04:05:41.873 UTC [24111][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_24020'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_24020" on database "pg2"
2024-03-11 04:05:41.878 UTC [24111][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.031 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-11 04:05:41.913 UTC [24101][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:41.913 UTC [24101][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:41.917 UTC [24107][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:41.925 UTC [24104][checkpointer] LOG:  shutting down
2024-03-11 04:05:41.929 UTC [24101][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344952172343324116 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-11 04:05:42.043 UTC [24119][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-11 04:05:42.043 UTC [24119][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:42.060 UTC [24122][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:41 UTC
2024-03-11 04:05:42.061 UTC [24122][startup] LOG:  entering standby mode
2024-03-11 04:05:42.062 UTC [24122][startup] LOG:  redo starts at 0/3008DC0
2024-03-11 04:05:42.062 UTC [24122][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-11 04:05:42.062 UTC [24122][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
2024-03-11 04:05:42.062 UTC [24119][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:42.098 UTC [24123][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: Done!
[04:05:42.128](1.877s) ok 8 - max_wal_senders is sufficient
### Restarting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_s.log restart
2024-03-11 04:05:42.134 UTC [24119][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:42.134 UTC [24119][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:42.134 UTC [24123][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:42.145 UTC [24120][checkpointer] LOG:  shutting down
2024-03-11 04:05:42.149 UTC [24119][postmaster] LOG:  database system is shut down
waiting for server to shut down... done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 24131
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:42.854 UTC [24213][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-11 04:05:42.854 UTC [24213][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:42.899 UTC [24219][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:42 UTC
2024-03-11 04:05:42.899 UTC [24219][startup] LOG:  entering standby mode
2024-03-11 04:05:42.901 UTC [24219][startup] LOG:  redo starts at 0/3008DC0
2024-03-11 04:05:42.901 UTC [24219][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-11 04:05:42.901 UTC [24219][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
2024-03-11 04:05:42.901 UTC [24213][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:42.955 UTC [24222][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:42.956 UTC [24222][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:42.956 UTC [24222][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:42.962 UTC [24220][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:43.035 UTC [24222][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:43.039 UTC [24222][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:43.049 UTC [24222][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:43.052 UTC [24222][client backend] [041_tests.pl][0/5: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 logical replication workers, but only 1 remain
pg_createsubscriber: hint: Consider increasing max_logical_replication_workers to at least 2.
2024-03-11 04:05:43.074 UTC [24222][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.123 user=postgres database=pg1 host=[local]
[04:05:43.397](1.270s) ok 9 - max_logical_replication_workers is not sufficient
### Restarting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_s.log restart
2024-03-11 04:05:43.420 UTC [24213][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:43.420 UTC [24213][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:43.420 UTC [24220][walreceiver] FATAL:  terminating walreceiver process due to administrator command
waiting for server to shut down....2024-03-11 04:05:43.428 UTC [24217][checkpointer] LOG:  shutting down
2024-03-11 04:05:43.432 UTC [24213][postmaster] LOG:  database system is shut down
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 24249
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:44.257 UTC [24286][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-11 04:05:44.257 UTC [24286][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:44.297 UTC [24289][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:43 UTC
2024-03-11 04:05:44.298 UTC [24289][startup] LOG:  entering standby mode
2024-03-11 04:05:44.299 UTC [24289][startup] LOG:  redo starts at 0/3008DC0
2024-03-11 04:05:44.299 UTC [24289][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-11 04:05:44.299 UTC [24289][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
2024-03-11 04:05:44.305 UTC [24286][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:44.344 UTC [24290][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-11 04:05:44.401 UTC [24296][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:44.402 UTC [24296][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:44.402 UTC [24296][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:44.450 UTC [24296][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:44.459 UTC [24296][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:44.460 UTC [24296][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:44.463 UTC [24296][client backend] [041_tests.pl][0/5: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-11 04:05:44.475 UTC [24296][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.075 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_24262" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_24262" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_24262" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_24262" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-11 04:05:44.649 UTC [24286][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:44.649 UTC [24286][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:44.653 UTC [24290][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:44.657 UTC [24287][checkpointer] LOG:  shutting down
2024-03-11 04:05:44.661 UTC [24286][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-11 04:05:44.877 UTC [24319][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-11 04:05:44.877 UTC [24319][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:44.900 UTC [24327][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:44 UTC
2024-03-11 04:05:44.901 UTC [24327][startup] LOG:  entering standby mode
2024-03-11 04:05:44.902 UTC [24327][startup] LOG:  redo starts at 0/3008DC0
2024-03-11 04:05:44.902 UTC [24327][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-11 04:05:44.902 UTC [24327][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
2024-03-11 04:05:44.902 UTC [24319][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:44.933 UTC [24330][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-11 04:05:44.948 UTC [24336][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:44.949 UTC [24336][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:44.949 UTC [24336][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:44.979 UTC [24336][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:44.980 UTC [24336][client backend] [041_tests.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-11 04:05:44.982 UTC [24336][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.038 user=postgres database=pg1 host=[local]
2024-03-11 04:05:44.993 UTC [24338][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:44.994 UTC [24338][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:44.994 UTC [24338][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:44.995 UTC [24338][client backend] [041_tests.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_24262" on database "pg1"
2024-03-11 04:05:44.996 UTC [24338][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_24262'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_24262" on database "pg1"
2024-03-11 04:05:44.998 UTC [24338][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.011 user=postgres database=pg1 host=[local]
2024-03-11 04:05:45.017 UTC [24340][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:45.018 UTC [24340][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:45.018 UTC [24340][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-11 04:05:45.045 UTC [24340][client backend] [041_tests.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_24262" on database "pg2"
2024-03-11 04:05:45.046 UTC [24340][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_24262'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_24262" on database "pg2"
2024-03-11 04:05:45.048 UTC [24340][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.034 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-11 04:05:45.088 UTC [24319][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:45.089 UTC [24319][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:45.089 UTC [24330][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:45.096 UTC [24325][checkpointer] LOG:  shutting down
2024-03-11 04:05:45.101 UTC [24319][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344952186500435654 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-11 04:05:45.318 UTC [24368][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-11 04:05:45.318 UTC [24368][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:45.364 UTC [24372][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:45 UTC
2024-03-11 04:05:45.364 UTC [24372][startup] LOG:  entering standby mode
2024-03-11 04:05:45.365 UTC [24372][startup] LOG:  redo starts at 0/3008DC0
2024-03-11 04:05:45.365 UTC [24372][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-11 04:05:45.365 UTC [24368][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:45.368 UTC [24372][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: Done!
[04:05:45.404](2.007s) ok 10 - max_logical_replication_workers is sufficient
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log restart
2024-03-11 04:05:45.408 UTC [24378][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
waiting for server to shut down....2024-03-11 04:05:45.461 UTC [24378][walreceiver] LOG:  replication terminated by primary server
2024-03-11 04:05:45.461 UTC [24378][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008E70.
2024-03-11 04:05:45.461 UTC [24378][walreceiver] FATAL:  could not send end-of-streaming message to primary: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
	no COPY in progress
2024-03-11 04:05:45.465 UTC [24372][startup] LOG:  invalid record length at 0/3008E70: expected at least 24, got 0
2024-03-11 04:05:45.493 UTC [24390][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62858" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-11 04:05:45.493 UTC [24372][startup] LOG:  waiting for WAL to become available at 0/3008E88
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 24391
2024-03-11 04:05:45.997 UTC [24417][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
### Restarting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_s.log restart
waiting for server to shut down....2024-03-11 04:05:46.753 UTC [24368][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:46.753 UTC [24368][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:46.760 UTC [24417][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:46.763 UTC [24370][checkpointer] LOG:  shutting down
2024-03-11 04:05:46.763 UTC [24370][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-11 04:05:46.764 UTC [24370][checkpointer] LOG:  restartpoint complete: wrote 1 buffers (0.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB; lsn=0/3008DF8, redo lsn=0/3008DF8
2024-03-11 04:05:46.764 UTC [24370][checkpointer] LOG:  recovery restart point at 0/3008DF8
2024-03-11 04:05:46.768 UTC [24368][postmaster] LOG:  database system is shut down
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 24470
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:47.272 UTC [24521][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-11 04:05:47.272 UTC [24521][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:47.288 UTC [24528][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:47 UTC
2024-03-11 04:05:47.288 UTC [24528][startup] LOG:  entering standby mode
2024-03-11 04:05:47.292 UTC [24528][startup] LOG:  redo starts at 0/3008E70
2024-03-11 04:05:47.292 UTC [24528][startup] LOG:  consistent recovery state reached at 0/3008EA8
2024-03-11 04:05:47.292 UTC [24521][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:47.292 UTC [24528][startup] LOG:  invalid record length at 0/3008EA8: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:47.320 UTC [24532][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:47.334 UTC [24535][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:47.335 UTC [24535][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:47.335 UTC [24535][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:47.375 UTC [24535][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:47.380 UTC [24535][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:47.380 UTC [24535][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:47.381 UTC [24535][client backend] [041_tests.pl][0/5: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 3 worker processes, but only 2 remain
pg_createsubscriber: hint: Consider increasing max_worker_processes to at least 3.
2024-03-11 04:05:47.403 UTC [24535][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.078 user=postgres database=pg1 host=[local]
[04:05:47.609](2.205s) ok 11 - max_worker_processes is not sufficient
### Restarting node "node_p"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log restart
waiting for server to shut down....2024-03-11 04:05:47.653 UTC [24532][walreceiver] LOG:  replication terminated by primary server
2024-03-11 04:05:47.653 UTC [24532][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008F20.
2024-03-11 04:05:47.653 UTC [24532][walreceiver] FATAL:  could not send end-of-streaming message to primary: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
	no COPY in progress
2024-03-11 04:05:47.657 UTC [24528][startup] LOG:  invalid record length at 0/3008F20: expected at least 24, got 0
2024-03-11 04:05:47.679 UTC [24568][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62858" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-11 04:05:47.679 UTC [24528][startup] LOG:  waiting for WAL to become available at 0/3008F38
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_p" is 24576
2024-03-11 04:05:48.194 UTC [24613][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:48.195 UTC [24528][startup] WARNING:  hot standby is not possible because of insufficient parameter settings
2024-03-11 04:05:48.195 UTC [24528][startup] DETAIL:  max_worker_processes = 2 is a lower setting than on the primary server, where its value was 3.
2024-03-11 04:05:48.195 UTC [24528][startup] CONTEXT:  WAL redo at 0/3008F20 for XLOG/PARAMETER_CHANGE: max_connections=10 max_worker_processes=3 max_wal_senders=3 max_prepared_xacts=10 max_locks_per_xact=64 wal_level=logical wal_log_hints=on track_commit_timestamp=off
2024-03-11 04:05:48.195 UTC [24528][startup] LOG:  recovery has paused
2024-03-11 04:05:48.195 UTC [24528][startup] DETAIL:  If recovery is unpaused, the server will shut down.
2024-03-11 04:05:48.195 UTC [24528][startup] HINT:  You can then restart the server after making the necessary configuration changes.
2024-03-11 04:05:48.195 UTC [24528][startup] CONTEXT:  WAL redo at 0/3008F20 for XLOG/PARAMETER_CHANGE: max_connections=10 max_worker_processes=3 max_wal_senders=3 max_prepared_xacts=10 max_locks_per_xact=64 wal_level=logical wal_log_hints=on track_commit_timestamp=off
### Restarting node "node_s"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_s.log restart
waiting for server to shut down....2024-03-11 04:05:48.838 UTC [24521][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:48.838 UTC [24521][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:48.838 UTC [24613][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:49.199 UTC [24526][checkpointer] LOG:  shutting down
2024-03-11 04:05:49.200 UTC [24526][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-11 04:05:49.200 UTC [24526][checkpointer] LOG:  restartpoint complete: wrote 1 buffers (0.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB; lsn=0/3008EA8, redo lsn=0/3008EA8
2024-03-11 04:05:49.200 UTC [24526][checkpointer] LOG:  recovery restart point at 0/3008EA8
2024-03-11 04:05:49.204 UTC [24521][postmaster] LOG:  database system is shut down
 done
server stopped
waiting for server to start.... done
server started
# Postmaster PID for node "node_s" is 24757
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:50.119 UTC [24839][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-11 04:05:50.119 UTC [24839][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:50.168 UTC [24856][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:49 UTC
2024-03-11 04:05:50.168 UTC [24856][startup] LOG:  entering standby mode
2024-03-11 04:05:50.170 UTC [24856][startup] LOG:  redo starts at 0/3008F20
2024-03-11 04:05:50.170 UTC [24856][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-11 04:05:50.170 UTC [24856][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-11 04:05:50.170 UTC [24839][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:50.253 UTC [24859][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-11 04:05:50.282 UTC [24862][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:50.282 UTC [24862][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:50.282 UTC [24862][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:50.389 UTC [24862][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:50.390 UTC [24862][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:50.391 UTC [24862][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:50.393 UTC [24862][client backend] [041_tests.pl][0/5: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-11 04:05:50.427 UTC [24862][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.147 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_24780" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_24780" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_24780" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_24780" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-11 04:05:50.763 UTC [24839][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:50.763 UTC [24839][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:50.771 UTC [24859][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:50.774 UTC [24853][checkpointer] LOG:  shutting down
2024-03-11 04:05:50.779 UTC [24839][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-11 04:05:51.185 UTC [24923][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-11 04:05:51.185 UTC [24923][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:51.264 UTC [24935][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:50 UTC
2024-03-11 04:05:51.264 UTC [24935][startup] LOG:  entering standby mode
2024-03-11 04:05:51.265 UTC [24935][startup] LOG:  redo starts at 0/3008F20
2024-03-11 04:05:51.265 UTC [24935][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-11 04:05:51.265 UTC [24935][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-11 04:05:51.265 UTC [24923][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-03-11 04:05:51.337 UTC [24938][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:51.367 UTC [24944][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:51.368 UTC [24944][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:51.368 UTC [24944][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:51.459 UTC [24944][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:51.485 UTC [24944][client backend] [041_tests.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-11 04:05:51.487 UTC [24944][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.123 user=postgres database=pg1 host=[local]
2024-03-11 04:05:51.500 UTC [24957][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:51.501 UTC [24957][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:51.501 UTC [24957][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:51.502 UTC [24957][client backend] [041_tests.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_24780" on database "pg1"
2024-03-11 04:05:51.503 UTC [24957][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_24780'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_24780" on database "pg1"
2024-03-11 04:05:51.519 UTC [24959][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:51.520 UTC [24959][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:51.520 UTC [24959][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-11 04:05:51.529 UTC [24957][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.032 user=postgres database=pg1 host=[local]
2024-03-11 04:05:51.605 UTC [24959][client backend] [041_tests.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_24780" on database "pg2"
2024-03-11 04:05:51.619 UTC [24959][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_24780'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_24780" on database "pg2"
2024-03-11 04:05:51.621 UTC [24959][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.105 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-11 04:05:51.697 UTC [24923][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:51.697 UTC [24923][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:51.701 UTC [24938][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:51.709 UTC [24933][checkpointer] LOG:  shutting down
2024-03-11 04:05:51.714 UTC [24923][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344952214727569612 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-11 04:05:52.071 UTC [24997][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-11 04:05:52.071 UTC [24997][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:52.124 UTC [25010][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:51 UTC
2024-03-11 04:05:52.124 UTC [25010][startup] LOG:  entering standby mode
2024-03-11 04:05:52.143 UTC [25010][startup] LOG:  redo starts at 0/3008F20
2024-03-11 04:05:52.143 UTC [25010][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-11 04:05:52.143 UTC [24997][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:52.144 UTC [25010][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: Done!
2024-03-11 04:05:52.192 UTC [25015][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
[04:05:52.606](4.998s) ok 12 - max_worker_processes is sufficient
# Taking pg_basebackup backup_2 from node "node_s"
# Running: pg_basebackup -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/backup/backup_2 -h /tmp/9Y_XCIGyyw -p 62859 --checkpoint fast --no-sync
2024-03-11 04:05:52.678 UTC [25044][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:52.679 UTC [25044][walsender] [[unknown]][17/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:52.679 UTC [25044][walsender] [[unknown]][17/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-11 04:05:52.689 UTC [25044][walsender] [041_tests.pl][17/0:0] LOG:  received replication command: SHOW data_directory_mode
2024-03-11 04:05:52.689 UTC [25044][walsender] [041_tests.pl][17/0:0] STATEMENT:  SHOW data_directory_mode
2024-03-11 04:05:52.689 UTC [25044][walsender] [041_tests.pl][17/0:0] LOG:  received replication command: SHOW wal_segment_size
2024-03-11 04:05:52.689 UTC [25044][walsender] [041_tests.pl][17/0:0] STATEMENT:  SHOW wal_segment_size
2024-03-11 04:05:52.689 UTC [25044][walsender] [041_tests.pl][17/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:52.689 UTC [25044][walsender] [041_tests.pl][17/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:52.689 UTC [25044][walsender] [041_tests.pl][17/0:0] LOG:  received replication command: BASE_BACKUP ( LABEL 'pg_basebackup base backup',  PROGRESS,  CHECKPOINT 'fast',  WAIT 0,  MANIFEST 'yes',  TARGET 'client')
2024-03-11 04:05:52.689 UTC [25044][walsender] [041_tests.pl][17/0:0] STATEMENT:  BASE_BACKUP ( LABEL 'pg_basebackup base backup',  PROGRESS,  CHECKPOINT 'fast',  WAIT 0,  MANIFEST 'yes',  TARGET 'client')
2024-03-11 04:05:52.736 UTC [25053][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:52.737 UTC [25053][walsender] [[unknown]][18/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:52.737 UTC [25053][walsender] [[unknown]][18/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-11 04:05:52.739 UTC [25053][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: SHOW data_directory_mode
2024-03-11 04:05:52.739 UTC [25053][walsender] [041_tests.pl][18/0:0] STATEMENT:  SHOW data_directory_mode
2024-03-11 04:05:52.739 UTC [25053][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: CREATE_REPLICATION_SLOT "pg_basebackup_25053" TEMPORARY PHYSICAL ( RESERVE_WAL)
2024-03-11 04:05:52.739 UTC [25053][walsender] [041_tests.pl][18/0:0] STATEMENT:  CREATE_REPLICATION_SLOT "pg_basebackup_25053" TEMPORARY PHYSICAL ( RESERVE_WAL)
2024-03-11 04:05:52.739 UTC [25053][walsender] [041_tests.pl][18/0:0] LOG:  released physical replication slot "pg_basebackup_25053"
2024-03-11 04:05:52.739 UTC [25053][walsender] [041_tests.pl][18/0:0] STATEMENT:  CREATE_REPLICATION_SLOT "pg_basebackup_25053" TEMPORARY PHYSICAL ( RESERVE_WAL)
2024-03-11 04:05:52.763 UTC [25053][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:52.763 UTC [25053][walsender] [041_tests.pl][18/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:52.764 UTC [25053][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: START_REPLICATION SLOT "pg_basebackup_25053" 0/3000000 TIMELINE 1
2024-03-11 04:05:52.764 UTC [25053][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "pg_basebackup_25053" 0/3000000 TIMELINE 1
2024-03-11 04:05:52.764 UTC [25053][walsender] [041_tests.pl][18/0:0] LOG:  acquired physical replication slot "pg_basebackup_25053"
2024-03-11 04:05:52.764 UTC [25053][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "pg_basebackup_25053" 0/3000000 TIMELINE 1
2024-03-11 04:05:53.436 UTC [25053][walsender] [041_tests.pl][18/0:0] LOG:  released physical replication slot "pg_basebackup_25053"
2024-03-11 04:05:53.436 UTC [25053][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "pg_basebackup_25053" 0/3000000 TIMELINE 1
2024-03-11 04:05:53.438 UTC [25044][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.761 user=postgres database= host=[local]
2024-03-11 04:05:53.443 UTC [25053][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.707 user=postgres database= host=[local]
# Backup finished
# Checking port 62860
# Found port 62860
Name: node_c
Data directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/pgdata
Backup directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/backup
Archive directory: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/archives
Connection string: port=62860 host=/tmp/9Y_XCIGyyw
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_c.log
# Initializing node "node_c" from backup "backup_2" of node "node_s"
### Enabling streaming replication for node "node_c"
### Starting node "node_c"
# Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_c.log -o --cluster-name=node_c start
waiting for server to start....2024-03-11 04:05:54.572 UTC [25220][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:54.573 UTC [25220][walsender] [[unknown]][19/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:54.573 UTC [25220][walsender] [[unknown]][19/1:0] LOG:  replication connection authorized: user=postgres application_name=node_c
2024-03-11 04:05:54.579 UTC [25220][walsender] [node_c][19/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:54.579 UTC [25220][walsender] [node_c][19/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:54.580 UTC [25220][walsender] [node_c][19/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:54.580 UTC [25220][walsender] [node_c][19/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:54.580 UTC [25220][walsender] [node_c][19/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:54.580 UTC [25220][walsender] [node_c][19/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:54.581 UTC [25220][walsender] [node_c][:0] LOG:  disconnection: session time: 0:00:00.009 user=postgres database= host=[local]
2024-03-11 04:05:54.609 UTC [25226][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:54.610 UTC [25226][walsender] [[unknown]][20/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:54.610 UTC [25226][walsender] [[unknown]][20/1:0] LOG:  replication connection authorized: user=postgres application_name=node_c
2024-03-11 04:05:54.610 UTC [25226][walsender] [node_c][20/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:54.610 UTC [25226][walsender] [node_c][20/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:54.610 UTC [25226][walsender] [node_c][20/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:54.610 UTC [25226][walsender] [node_c][20/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:54.610 UTC [25226][walsender] [node_c][20/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:54.610 UTC [25226][walsender] [node_c][20/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:54.614 UTC [25226][walsender] [node_c][:0] LOG:  disconnection: session time: 0:00:00.007 user=postgres database= host=[local]
 done
server started
# Postmaster PID for node "node_c" is 25211
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62859 --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_041_tests_node_s_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-11 04:05:54.735 UTC [24997][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:54.735 UTC [24997][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:54.742 UTC [25015][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:54.750 UTC [25008][checkpointer] LOG:  shutting down
2024-03-11 04:05:54.754 UTC [24997][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:54.996 UTC [25285][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-11 04:05:54.996 UTC [25285][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:55.034 UTC [25296][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:54 UTC
2024-03-11 04:05:55.034 UTC [25296][startup] LOG:  entering standby mode
2024-03-11 04:05:55.035 UTC [25296][startup] LOG:  redo starts at 0/3008F20
2024-03-11 04:05:55.035 UTC [25296][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-11 04:05:55.035 UTC [25296][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-11 04:05:55.036 UTC [25285][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:55.075 UTC [25298][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:55.085 UTC [25302][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:55.086 UTC [25302][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:55.086 UTC [25302][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:55.119 UTC [25308][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:55.124 UTC [25308][walsender] [[unknown]][17/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:55.124 UTC [25308][walsender] [[unknown]][17/1:0] LOG:  replication connection authorized: user=postgres application_name=node_c
2024-03-11 04:05:55.125 UTC [25308][walsender] [node_c][17/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:55.125 UTC [25308][walsender] [node_c][17/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:55.125 UTC [25308][walsender] [node_c][17/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:55.125 UTC [25308][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:55.125 UTC [25308][walsender] [node_c][17/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:55.125 UTC [25308][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:55.125 UTC [25308][walsender] [node_c][:0] LOG:  disconnection: session time: 0:00:00.009 user=postgres database= host=[local]
2024-03-11 04:05:55.131 UTC [25302][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:55.147 UTC [25302][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:55.148 UTC [25302][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:55.149 UTC [25302][client backend] [041_tests.pl][0/5: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-11 04:05:55.153 UTC [25302][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.069 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_25231" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_25231" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_25231" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_25231" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-11 04:05:55.307 UTC [25285][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:55.307 UTC [25285][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:55.307 UTC [25298][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:55.314 UTC [25294][checkpointer] LOG:  shutting down
2024-03-11 04:05:55.322 UTC [25285][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-11 04:05:55.564 UTC [25345][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-11 04:05:55.564 UTC [25345][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:55.576 UTC [25355][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:55 UTC
2024-03-11 04:05:55.576 UTC [25355][startup] LOG:  entering standby mode
2024-03-11 04:05:55.578 UTC [25355][startup] LOG:  redo starts at 0/3008F20
2024-03-11 04:05:55.578 UTC [25355][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-11 04:05:55.578 UTC [25355][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-11 04:05:55.579 UTC [25345][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-03-11 04:05:55.610 UTC [25357][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:55.611 UTC [25361][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:55.612 UTC [25361][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:55.612 UTC [25361][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:55.631 UTC [25363][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:55.632 UTC [25363][walsender] [[unknown]][17/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:55.632 UTC [25363][walsender] [[unknown]][17/1:0] LOG:  replication connection authorized: user=postgres application_name=node_c
2024-03-11 04:05:55.639 UTC [25363][walsender] [node_c][17/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:55.639 UTC [25363][walsender] [node_c][17/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:55.640 UTC [25363][walsender] [node_c][17/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:55.640 UTC [25363][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:55.640 UTC [25363][walsender] [node_c][17/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:55.640 UTC [25363][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:55.640 UTC [25363][walsender] [node_c][:0] LOG:  disconnection: session time: 0:00:00.016 user=postgres database= host=[local]
2024-03-11 04:05:55.643 UTC [25361][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:55.647 UTC [25361][client backend] [041_tests.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-11 04:05:55.648 UTC [25361][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.044 user=postgres database=pg1 host=[local]
2024-03-11 04:05:55.663 UTC [25366][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:55.664 UTC [25366][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:55.664 UTC [25366][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:55.668 UTC [25366][client backend] [041_tests.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_25231" on database "pg1"
2024-03-11 04:05:55.675 UTC [25366][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_25231'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_25231" on database "pg1"
2024-03-11 04:05:55.679 UTC [25366][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.017 user=postgres database=pg1 host=[local]
2024-03-11 04:05:55.685 UTC [25373][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:55.686 UTC [25373][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:55.686 UTC [25373][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-11 04:05:55.709 UTC [25373][client backend] [041_tests.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_25231" on database "pg2"
2024-03-11 04:05:55.710 UTC [25373][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_25231'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_25231" on database "pg2"
2024-03-11 04:05:55.719 UTC [25373][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.035 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-11 04:05:55.772 UTC [25345][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:55.772 UTC [25345][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:55.772 UTC [25357][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-11 04:05:55.780 UTC [25353][checkpointer] LOG:  shutting down
2024-03-11 04:05:55.784 UTC [25345][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344952232230789775 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-11 04:05:56.060 UTC [25406][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-11 04:05:56.060 UTC [25406][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859"
2024-03-11 04:05:56.088 UTC [25417][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:55 UTC
2024-03-11 04:05:56.088 UTC [25417][startup] LOG:  entering standby mode
2024-03-11 04:05:56.089 UTC [25417][startup] LOG:  redo starts at 0/3008F20
2024-03-11 04:05:56.089 UTC [25417][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-11 04:05:56.089 UTC [25417][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-11 04:05:56.090 UTC [25406][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: Done!
2024-03-11 04:05:56.129 UTC [25421][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-11 04:05:56.131 UTC [25424][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:56.132 UTC [25424][walsender] [[unknown]][17/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:56.132 UTC [25424][walsender] [[unknown]][17/1:0] LOG:  replication connection authorized: user=postgres application_name=node_c
2024-03-11 04:05:56.133 UTC [25424][walsender] [node_c][17/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:56.133 UTC [25424][walsender] [node_c][17/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:56.133 UTC [25424][walsender] [node_c][17/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:56.133 UTC [25424][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:56.133 UTC [25424][walsender] [node_c][17/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:56.133 UTC [25424][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:56.137 UTC [25424][walsender] [node_c][:0] LOG:  disconnection: session time: 0:00:00.013 user=postgres database= host=[local]
[04:05:56.274](3.667s) not ok 13 - standby server is primary to other node
[04:05:56.274](0.000s) 
[04:05:56.274](0.000s) #   Failed test 'standby server is primary to other node'
#   at t/041_tests.pl line 252.
# Running: pg_createsubscriber --verbose --dry-run --pgdata /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/pgdata --publisher-server port=62858 host=/tmp/9Y_XCIGyyw dbname='pg1' --socket-directory /tmp/9Y_XCIGyyw --subscriber-port 62860 --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_041_tests_node_c_data/pgdata" is a cluster data directory
pg_createsubscriber: getting system identifier from publisher
pg_createsubscriber: system identifier is 7344951829458130365 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344951829458130365 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-11 04:05:56.622 UTC [25501][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-11 04:05:56.622 UTC [25501][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62860"
2024-03-11 04:05:56.636 UTC [25515][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:56 UTC
2024-03-11 04:05:56.636 UTC [25515][startup] LOG:  entering standby mode
2024-03-11 04:05:56.637 UTC [25515][startup] LOG:  redo starts at 0/3008F20
2024-03-11 04:05:56.637 UTC [25515][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-11 04:05:56.637 UTC [25515][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-11 04:05:56.638 UTC [25501][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:56.655 UTC [25522][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:56.657 UTC [25522][walsender] [[unknown]][18/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:56.657 UTC [25522][walsender] [[unknown]][18/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-11 04:05:56.658 UTC [25522][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:56.658 UTC [25522][walsender] [041_tests.pl][18/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:56.659 UTC [25522][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:56.659 UTC [25522][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:56.659 UTC [25522][walsender] [041_tests.pl][18/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:56.659 UTC [25522][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:56.659 UTC [25518][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:56.659 UTC [25522][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.003 user=postgres database= host=[local]
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-11 04:05:56.677 UTC [25530][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:56.678 UTC [25530][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:56.678 UTC [25530][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:56.684 UTC [25531][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:56.685 UTC [25531][walsender] [[unknown]][19/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:56.685 UTC [25531][walsender] [[unknown]][19/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-11 04:05:56.688 UTC [25531][walsender] [041_tests.pl][19/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:56.688 UTC [25531][walsender] [041_tests.pl][19/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:56.688 UTC [25531][walsender] [041_tests.pl][19/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:56.688 UTC [25531][walsender] [041_tests.pl][19/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:56.688 UTC [25531][walsender] [041_tests.pl][19/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:56.688 UTC [25531][walsender] [041_tests.pl][19/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:56.689 UTC [25529][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:56.689 UTC [25515][startup] LOG:  waiting for WAL to become available at 0/3002000
2024-03-11 04:05:56.691 UTC [25530][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:56.693 UTC [25531][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.010 user=postgres database= host=[local]
2024-03-11 04:05:56.699 UTC [25530][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-11 04:05:56.700 UTC [25530][client backend] [041_tests.pl][0/4:0] LOG:  statement: SELECT pg_catalog.pg_has_role(current_user, 6304, 'MEMBER'), pg_catalog.has_database_privilege(current_user, 'pg1', 'CREATE'), pg_catalog.has_function_privilege(current_user, 'pg_catalog.pg_replication_origin_advance(text, pg_lsn)', 'EXECUTE')
2024-03-11 04:05:56.701 UTC [25530][client backend] [041_tests.pl][0/5: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-11 04:05:56.705 UTC [25530][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.028 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_25445" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_25445" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_25445" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_25445" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-11 04:05:56.832 UTC [25501][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:56.832 UTC [25501][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:56.836 UTC [25513][checkpointer] LOG:  shutting down
2024-03-11 04:05:56.841 UTC [25501][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-11 04:05:57.102 UTC [25592][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-11 04:05:57.102 UTC [25592][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62860"
2024-03-11 04:05:57.119 UTC [25600][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:56 UTC
2024-03-11 04:05:57.120 UTC [25600][startup] LOG:  entering standby mode
2024-03-11 04:05:57.121 UTC [25600][startup] LOG:  redo starts at 0/3008F20
2024-03-11 04:05:57.122 UTC [25600][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-11 04:05:57.122 UTC [25600][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-11 04:05:57.122 UTC [25592][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-03-11 04:05:57.147 UTC [25602][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:57.148 UTC [25602][client backend] [[unknown]][0/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:57.148 UTC [25602][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:57.157 UTC [25605][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:57.157 UTC [25605][walsender] [[unknown]][20/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:57.157 UTC [25605][walsender] [[unknown]][20/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-11 04:05:57.159 UTC [25605][walsender] [041_tests.pl][20/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:57.159 UTC [25605][walsender] [041_tests.pl][20/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:57.159 UTC [25605][walsender] [041_tests.pl][20/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.159 UTC [25605][walsender] [041_tests.pl][20/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.159 UTC [25605][walsender] [041_tests.pl][20/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:57.159 UTC [25605][walsender] [041_tests.pl][20/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.159 UTC [25601][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:57.161 UTC [25605][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.005 user=postgres database= host=[local]
2024-03-11 04:05:57.194 UTC [25602][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-11 04:05:57.197 UTC [25602][client backend] [041_tests.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-11 04:05:57.198 UTC [25602][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.052 user=postgres database=pg1 host=[local]
2024-03-11 04:05:57.199 UTC [25607][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:57.200 UTC [25607][walsender] [[unknown]][21/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:57.200 UTC [25607][walsender] [[unknown]][21/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-11 04:05:57.200 UTC [25607][walsender] [041_tests.pl][21/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:57.200 UTC [25607][walsender] [041_tests.pl][21/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:57.200 UTC [25607][walsender] [041_tests.pl][21/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.200 UTC [25607][walsender] [041_tests.pl][21/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.200 UTC [25607][walsender] [041_tests.pl][21/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:57.200 UTC [25607][walsender] [041_tests.pl][21/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.200 UTC [25606][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:57.201 UTC [25600][startup] LOG:  waiting for WAL to become available at 0/3002000
2024-03-11 04:05:57.205 UTC [25607][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.013 user=postgres database= host=[local]
2024-03-11 04:05:57.215 UTC [25610][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:57.216 UTC [25610][client backend] [[unknown]][1/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:57.216 UTC [25610][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-11 04:05:57.223 UTC [25610][client backend] [041_tests.pl][1/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16384" on database "pg1"
pg_createsubscriber: creating subscription "pg_createsubscriber_16384_25445" on database "pg1"
2024-03-11 04:05:57.224 UTC [25610][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_25445'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_25445" on database "pg1"
2024-03-11 04:05:57.226 UTC [25610][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.017 user=postgres database=pg1 host=[local]
2024-03-11 04:05:57.239 UTC [25614][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:57.240 UTC [25614][client backend] [[unknown]][2/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/pgdata/pg_hba.conf:117)
2024-03-11 04:05:57.240 UTC [25614][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-11 04:05:57.267 UTC [25614][client backend] [041_tests.pl][2/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
pg_createsubscriber: dropping publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating subscription "pg_createsubscriber_16385_25445" on database "pg2"
2024-03-11 04:05:57.268 UTC [25614][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_25445'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_25445" on database "pg2"
2024-03-11 04:05:57.271 UTC [25614][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.032 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-11 04:05:57.317 UTC [25592][postmaster] LOG:  received fast shutdown request
2024-03-11 04:05:57.318 UTC [25592][postmaster] LOG:  aborting any active transactions
2024-03-11 04:05:57.322 UTC [25598][checkpointer] LOG:  shutting down
2024-03-11 04:05:57.326 UTC [25592][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344952238967628645 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-11 04:05:57.506 UTC [25664][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-11 04:05:57.507 UTC [25664][postmaster] LOG:  listening on Unix socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62860"
2024-03-11 04:05:57.512 UTC [25672][startup] LOG:  database system was shut down in recovery at 2024-03-11 04:05:57 UTC
2024-03-11 04:05:57.512 UTC [25672][startup] LOG:  entering standby mode
2024-03-11 04:05:57.514 UTC [25672][startup] LOG:  redo starts at 0/3008F20
2024-03-11 04:05:57.514 UTC [25672][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-11 04:05:57.514 UTC [25664][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-11 04:05:57.514 UTC [25672][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-11 04:05:57.543 UTC [25678][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:57.545 UTC [25678][walsender] [[unknown]][22/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:57.545 UTC [25678][walsender] [[unknown]][22/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-11 04:05:57.548 UTC [25678][walsender] [041_tests.pl][22/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:57.548 UTC [25678][walsender] [041_tests.pl][22/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:57.551 UTC [25678][walsender] [041_tests.pl][22/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.551 UTC [25678][walsender] [041_tests.pl][22/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.552 UTC [25678][walsender] [041_tests.pl][22/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:57.552 UTC [25678][walsender] [041_tests.pl][22/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.552 UTC [25675][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:57.552 UTC [25678][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.009 user=postgres database= host=[local]
pg_createsubscriber: server was started
pg_createsubscriber: Done!
2024-03-11 04:05:57.567 UTC [25692][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-11 04:05:57.568 UTC [25692][walsender] [[unknown]][23/1:0] LOG:  connection authenticated: user="postgres" method=trust (/tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata/pg_hba.conf:124)
2024-03-11 04:05:57.568 UTC [25692][walsender] [[unknown]][23/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-11 04:05:57.568 UTC [25692][walsender] [041_tests.pl][23/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-11 04:05:57.568 UTC [25692][walsender] [041_tests.pl][23/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-11 04:05:57.569 UTC [25692][walsender] [041_tests.pl][23/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.569 UTC [25692][walsender] [041_tests.pl][23/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.569 UTC [25692][walsender] [041_tests.pl][23/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:57.569 UTC [25692][walsender] [041_tests.pl][23/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-11 04:05:57.569 UTC [25686][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-11 04:05:57.569 UTC [25672][startup] LOG:  waiting for WAL to become available at 0/3002000
2024-03-11 04:05:57.573 UTC [25692][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.005 user=postgres database= host=[local]
[04:05:57.933](1.658s) not ok 14 - standby server is not direct standby of publisher
[04:05:57.933](0.000s) 
[04:05:57.933](0.000s) #   Failed test 'standby server is not direct standby of publisher'
#   at t/041_tests.pl line 267.
### Stopping node "node_p" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_p_data/pgdata -m immediate stop
waiting for server to shut down....2024-03-11 04:05:57.948 UTC [25421][walreceiver] FATAL:  could not receive data from WAL stream: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
2024-03-11 04:05:57.967 UTC [25753][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62858" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-11 04:05:57.967 UTC [25417][startup] LOG:  waiting for WAL to become available at 0/3002000
 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_041_tests_node_s_data/pgdata -m immediate stop
2024-03-11 04:05:58.077 UTC [25406][postmaster] LOG:  received immediate shutdown request
2024-03-11 04:05:58.082 UTC [25406][postmaster] LOG:  database system is shut down
waiting for server to shut down... done
server stopped
# No postmaster PID for node "node_s"
### Stopping node "node_c" using mode immediate
# Running: pg_ctl -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_c_data/pgdata -m immediate stop
2024-03-11 04:05:58.088 UTC [25772][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/9Y_XCIGyyw/.s.PGSQL.62859" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-11 04:05:58.088 UTC [25672][startup] LOG:  waiting for WAL to become available at 0/3002000
2024-03-11 04:05:58.102 UTC [25664][postmaster] LOG:  received immediate shutdown request
2024-03-11 04:05:58.107 UTC [25664][postmaster] LOG:  database system is shut down
waiting for server to shut down... done
server stopped
# No postmaster PID for node "node_c"
[04:05:58.111](0.179s) 1..14
[04:05:58.113](0.001s) # Looks like you failed 2 tests of 14.